From 978ce684aee30acb363dc9577ba9702fbb81b3f4 Mon Sep 17 00:00:00 2001 From: David Driscoll Date: Mon, 29 Jan 2018 12:07:27 -0500 Subject: [PATCH 1/2] fixed initialize not working correctly, added additional logging --- src/Client/Logging/LoggerExtensions.cs | 78 +++++++++++++ src/Protocol/TimeLoggerExtensions.cs | 87 ++++++++++++++ src/Server/LspRequestRouter.cs | 154 +++++++++++++++---------- vscode-testextension/src/extension.ts | 3 +- 4 files changed, 257 insertions(+), 65 deletions(-) create mode 100644 src/Protocol/TimeLoggerExtensions.cs diff --git a/src/Client/Logging/LoggerExtensions.cs b/src/Client/Logging/LoggerExtensions.cs index d86a3d91a..7b0bc0d98 100644 --- a/src/Client/Logging/LoggerExtensions.cs +++ b/src/Client/Logging/LoggerExtensions.cs @@ -1,4 +1,6 @@ using System; +using System.Diagnostics; +using System.Linq; using Microsoft.Extensions.Logging; namespace OmniSharp.Extensions.LanguageServer.Client.Logging @@ -35,5 +37,81 @@ public static void LogError(this ILogger logger, Exception exception, string mes logger.LogError(GenericErrorEventId, exception, message, args); } + + class Disposable : IDisposable + { + private readonly IDisposable _disposable; + private readonly Action _action; + private readonly Stopwatch _sw; + + public Disposable(IDisposable disposable, Action action) + { + _disposable = disposable; + _action = action; + _sw = new Stopwatch(); + _sw.Start(); + } + + public void Dispose() + { + _sw.Stop(); + _action(_sw.ElapsedMilliseconds); + _disposable.Dispose(); + } + } + + /// + /// Times the trace. + /// + /// The logger. + /// The message. + /// The arguments. + /// IDisposable. + internal static IDisposable TimeTrace(this ILogger logger, string message, params object[] args) + { + var scope = logger.BeginScope(new { }); + logger.LogTrace($"Starting: {message}", args); + return new Disposable(scope, elapsed => + { + var a = args.Concat(new object[] { elapsed }).ToArray(); + logger.LogTrace($"Finished: {message} in {{ElapsedMilliseconds}}ms", a); + }); + } + + /// + /// Times the debug. + /// + /// The logger. + /// The message. + /// The arguments. + /// IDisposable. + internal static IDisposable TimeDebug(this ILogger logger, string message, params object[] args) + { + var scope = logger.BeginScope(new { }); + logger.LogDebug($"Starting: {message}", args); + return new Disposable(scope, elapsed => + { + var a = args.Concat(new object[] { elapsed }).ToArray(); + logger.LogDebug($"Finished: {message} in {{ElapsedMilliseconds}}ms", a); + }); + } + + /// + /// Times the information. + /// + /// The logger. + /// The message. + /// The arguments. + /// IDisposable. + internal static IDisposable TimeInformation(this ILogger logger, string message, params object[] args) + { + var scope = logger.BeginScope(new { }); + logger.LogInformation($"Starting: {message}", args); + return new Disposable(scope, elapsed => + { + var a = args.Concat(new object[] { elapsed }).ToArray(); + logger.LogInformation($"Finished: {message} in {{ElapsedMilliseconds}}ms", a); + }); + } } } diff --git a/src/Protocol/TimeLoggerExtensions.cs b/src/Protocol/TimeLoggerExtensions.cs new file mode 100644 index 000000000..ac402b1cc --- /dev/null +++ b/src/Protocol/TimeLoggerExtensions.cs @@ -0,0 +1,87 @@ +using System; +using System.Diagnostics; +using System.Linq; +using Microsoft.Extensions.Logging; + +// ReSharper disable once CheckNamespace +namespace Microsoft.Extensions.Logging +{ + internal static class TimeLoggerExtensions + { + class Disposable : IDisposable + { + private readonly IDisposable _disposable; + private readonly Action _action; + private readonly Stopwatch _sw; + + public Disposable(IDisposable disposable, Action action) + { + _disposable = disposable; + _action = action; + _sw = new Stopwatch(); + _sw.Start(); + } + + public void Dispose() + { + _sw.Stop(); + _action(_sw.ElapsedMilliseconds); + _disposable.Dispose(); + } + } + + /// + /// Times the trace. + /// + /// The logger. + /// The message. + /// The arguments. + /// IDisposable. + public static IDisposable TimeTrace(this ILogger logger, string message, params object[] args) + { + var scope = logger.BeginScope(new { }); + logger.LogTrace($"Starting: {message}", args); + return new Disposable(scope, elapsed => + { + var a = args.Concat(new object[] { elapsed }).ToArray(); + logger.LogTrace($"Finished: {message} in {{ElapsedMilliseconds}}ms", a); + }); + } + + /// + /// Times the debug. + /// + /// The logger. + /// The message. + /// The arguments. + /// IDisposable. + public static IDisposable TimeDebug(this ILogger logger, string message, params object[] args) + { + var scope = logger.BeginScope(new { }); + logger.LogDebug($"Starting: {message}", args); + return new Disposable(scope, elapsed => + { + var a = args.Concat(new object[] { elapsed }).ToArray(); + logger.LogDebug($"Finished: {message} in {{ElapsedMilliseconds}}ms", a); + }); + } + + /// + /// Times the information. + /// + /// The logger. + /// The message. + /// The arguments. + /// IDisposable. + public static IDisposable TimeInformation(this ILogger logger, string message, params object[] args) + { + var scope = logger.BeginScope(new { }); + logger.LogInformation($"Starting: {message}", args); + return new Disposable(scope, elapsed => + { + var a = args.Concat(new object[] { elapsed }).ToArray(); + logger.LogInformation($"Finished: {message} in {{ElapsedMilliseconds}}ms", a); + }); + } + } +} diff --git a/src/Server/LspRequestRouter.cs b/src/Server/LspRequestRouter.cs index 694e9f112..a743956df 100644 --- a/src/Server/LspRequestRouter.cs +++ b/src/Server/LspRequestRouter.cs @@ -74,82 +74,104 @@ private ILspHandlerDescriptor FindDescriptor(string method, JToken @params) return _routeMatchers.SelectMany(strat => strat.FindHandler(paramsValue, lspHandlerDescriptors)).FirstOrDefault() ?? descriptor; } - public async Task RouteNotification(IHandlerDescriptor handler, Notification notification) + public async Task RouteNotification(IHandlerDescriptor descriptor, Notification notification) { - try + using (_logger.TimeDebug("Routing Notification {Method}", notification.Method)) { - Task result; - if (handler.Params is null) + using (_logger.BeginScope(new KeyValuePair[] { + new KeyValuePair( "Method", notification.Method), + new KeyValuePair( "Params", notification.Params?.ToString()) + })) { - result = ReflectionRequestHandlers.HandleNotification(handler); + try + { + if (descriptor.Params is null) + { + await ReflectionRequestHandlers.HandleNotification(descriptor); + } + else + { + _logger.LogDebug("Converting params for Notification {Method} to {Type}", notification.Method, descriptor.Params.FullName); + var @params = notification.Params.ToObject(descriptor.Params, _serializer.JsonSerializer); + await ReflectionRequestHandlers.HandleNotification(descriptor, @params); + } + } + catch (Exception e) + { + _logger.LogCritical(Events.UnhandledRequest, e, "Failed to handle request {Method}", notification.Method); + } } - else - { - var @params = notification.Params.ToObject(handler.Params, _serializer.JsonSerializer); - result = ReflectionRequestHandlers.HandleNotification(handler, @params); - } - - await result; - } - catch (Exception e) - { - _logger.LogCritical(Events.UnhandledRequest, e, "Failed to handle request {Method}", notification.Method); } } public async Task RouteRequest(IHandlerDescriptor descriptor, Request request) { - var id = GetId(request.Id); - var cts = new CancellationTokenSource(); - _requests.TryAdd(id, cts); - - // TODO: Try / catch for Internal Error - try + using (_logger.TimeDebug("Routing Request ({Id}) {Method}", request.Id, request.Method)) { - if (descriptor is null) - { - return new MethodNotFound(request.Id, request.Method); - } - - object @params; - try - { - @params = request.Params?.ToObject(descriptor.Params, _serializer.JsonSerializer); - } - catch (Exception cannotDeserializeRequestParams) - { - _logger.LogError(new EventId(-32602), cannotDeserializeRequestParams, "Failed to deserialise request parameters."); - - return new InvalidParams(request.Id); - } - - var result = ReflectionRequestHandlers.HandleRequest(descriptor, @params, cts.Token).ConfigureAwait(false); - await result; - - object responseValue = null; - if (result.GetType().GetTypeInfo().IsGenericType) + using (_logger.BeginScope(new KeyValuePair[] { + new KeyValuePair( "Id", request.Id?.ToString()), + new KeyValuePair( "Method", request.Method), + new KeyValuePair( "Params", request.Params?.ToString()) + })) { - var property = typeof(Task<>) - .MakeGenericType(result.GetType().GetTypeInfo().GetGenericArguments()[0]).GetTypeInfo() - .GetProperty(nameof(Task.Result), BindingFlags.Public | BindingFlags.Instance); - - responseValue = property.GetValue(result); + var id = GetId(request.Id); + var cts = new CancellationTokenSource(); + _requests.TryAdd(id, cts); + + // TODO: Try / catch for Internal Error + try + { + if (descriptor is null) + { + _logger.LogDebug("descriptor not found for Request ({Id}) {Method}", request.Id, request.Method); + return new MethodNotFound(request.Id, request.Method); + } + + object @params; + try + { + _logger.LogDebug("Converting params for Request ({Id}) {Method} to {Type}", request.Id, request.Method, descriptor.Params.FullName); + @params = request.Params?.ToObject(descriptor.Params, _serializer.JsonSerializer); + } + catch (Exception cannotDeserializeRequestParams) + { + _logger.LogError(new EventId(-32602), cannotDeserializeRequestParams, "Failed to deserialise request parameters."); + return new InvalidParams(request.Id); + } + + var result = ReflectionRequestHandlers.HandleRequest(descriptor, @params, cts.Token); + await result; + + _logger.LogDebug("Result was {Type}", result.GetType().FullName); + + object responseValue = null; + if (result.GetType().GetTypeInfo().IsGenericType) + { + var property = typeof(Task<>) + .MakeGenericType(result.GetType().GetTypeInfo().GetGenericArguments()[0]).GetTypeInfo() + .GetProperty(nameof(Task.Result), BindingFlags.Public | BindingFlags.Instance); + + responseValue = property.GetValue(result); + _logger.LogDebug("Response value was {Type}", responseValue?.GetType().FullName); + } + + return new JsonRpc.Client.Response(request.Id, responseValue); + } + catch (TaskCanceledException e) + { + _logger.LogDebug("Request {Id} was cancelled", id); + return new RequestCancelled(); + } + catch (Exception e) + { + _logger.LogCritical(Events.UnhandledRequest, e, "Failed to handle notification {Method}", request.Method); + return new InternalError(id); + } + finally + { + _requests.TryRemove(id, out var _); + } } - - return new JsonRpc.Client.Response(request.Id, responseValue); - } - catch (TaskCanceledException) - { - return new RequestCancelled(); - } - catch (Exception e) - { - _logger.LogCritical(Events.UnhandledRequest, e, "Failed to handle notification {Method}", request.Method); - return new InternalError(id); - } - finally - { - _requests.TryRemove(id, out var _); } } @@ -159,6 +181,10 @@ public void CancelRequest(object id) { cts.Cancel(); } + else + { + _logger.LogDebug("Request {Id} was not found to cancel", id); + } } public IHandlerDescriptor GetDescriptor(Notification notification) diff --git a/vscode-testextension/src/extension.ts b/vscode-testextension/src/extension.ts index 575d340a7..6ef2f8bc8 100644 --- a/vscode-testextension/src/extension.ts +++ b/vscode-testextension/src/extension.ts @@ -13,7 +13,8 @@ import { Trace } from 'vscode-jsonrpc'; export function activate(context: ExtensionContext) { // The server is implemented in node - let serverExe = 'C:/Other/omnisharp-roslyn/bin/Debug/OmniSharp.Stdio/net46/OmniSharp.exe'; + let serverExe = 'C:\\Other\\csharp-language-server-protocol\\sample\\SampleServer\\bin\\Debug\\netcoreapp2.0\\win7-x64\\SampleServer.exe'; + // // let serverExe = 'C:/Other/omnisharp-roslyn/bin/Debug/OmniSharp.Stdio/net46/OmniSharp.exe'; // let serverExe = 'D:/Development/Omnisharp/omnisharp-roslyn/artifacts/publish/OmniSharp.Stdio/win7-x64/OmniSharp.exe'; // let serverExe = context.asAbsolutePath('D:/Development/Omnisharp/omnisharp-roslyn/artifacts/publish/OmniSharp.Stdio/win7-x64/OmniSharp.exe'); // The debug options for the server From 2d46bd8882ab95b693d838f24f04c622593e9627 Mon Sep 17 00:00:00 2001 From: David Driscoll Date: Mon, 29 Jan 2018 12:40:43 -0500 Subject: [PATCH 2/2] remove logging methods from client (inherited by internals) --- src/Client/Logging/LoggerExtensions.cs | 78 -------------------------- 1 file changed, 78 deletions(-) diff --git a/src/Client/Logging/LoggerExtensions.cs b/src/Client/Logging/LoggerExtensions.cs index 7b0bc0d98..d86a3d91a 100644 --- a/src/Client/Logging/LoggerExtensions.cs +++ b/src/Client/Logging/LoggerExtensions.cs @@ -1,6 +1,4 @@ using System; -using System.Diagnostics; -using System.Linq; using Microsoft.Extensions.Logging; namespace OmniSharp.Extensions.LanguageServer.Client.Logging @@ -37,81 +35,5 @@ public static void LogError(this ILogger logger, Exception exception, string mes logger.LogError(GenericErrorEventId, exception, message, args); } - - class Disposable : IDisposable - { - private readonly IDisposable _disposable; - private readonly Action _action; - private readonly Stopwatch _sw; - - public Disposable(IDisposable disposable, Action action) - { - _disposable = disposable; - _action = action; - _sw = new Stopwatch(); - _sw.Start(); - } - - public void Dispose() - { - _sw.Stop(); - _action(_sw.ElapsedMilliseconds); - _disposable.Dispose(); - } - } - - /// - /// Times the trace. - /// - /// The logger. - /// The message. - /// The arguments. - /// IDisposable. - internal static IDisposable TimeTrace(this ILogger logger, string message, params object[] args) - { - var scope = logger.BeginScope(new { }); - logger.LogTrace($"Starting: {message}", args); - return new Disposable(scope, elapsed => - { - var a = args.Concat(new object[] { elapsed }).ToArray(); - logger.LogTrace($"Finished: {message} in {{ElapsedMilliseconds}}ms", a); - }); - } - - /// - /// Times the debug. - /// - /// The logger. - /// The message. - /// The arguments. - /// IDisposable. - internal static IDisposable TimeDebug(this ILogger logger, string message, params object[] args) - { - var scope = logger.BeginScope(new { }); - logger.LogDebug($"Starting: {message}", args); - return new Disposable(scope, elapsed => - { - var a = args.Concat(new object[] { elapsed }).ToArray(); - logger.LogDebug($"Finished: {message} in {{ElapsedMilliseconds}}ms", a); - }); - } - - /// - /// Times the information. - /// - /// The logger. - /// The message. - /// The arguments. - /// IDisposable. - internal static IDisposable TimeInformation(this ILogger logger, string message, params object[] args) - { - var scope = logger.BeginScope(new { }); - logger.LogInformation($"Starting: {message}", args); - return new Disposable(scope, elapsed => - { - var a = args.Concat(new object[] { elapsed }).ToArray(); - logger.LogInformation($"Finished: {message} in {{ElapsedMilliseconds}}ms", a); - }); - } } }