fixed initialize not working correctly, added additional logging

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<long> _action;
+            private readonly Stopwatch _sw;
+
+            public Disposable(IDisposable disposable, Action<long> action)
+            {
+                _disposable = disposable;
+                _action = action;
+                _sw = new Stopwatch();
+                _sw.Start();
+            }
+
+            public void Dispose()
+            {
+                _sw.Stop();
+                _action(_sw.ElapsedMilliseconds);
+                _disposable.Dispose();
+            }
+        }
+
+        /// <summary>
+        /// Times the trace.
+        /// </summary>
+        /// <param name="logger">The logger.</param>
+        /// <param name="message">The message.</param>
+        /// <param name="args">The arguments.</param>
+        /// <returns>IDisposable.</returns>
+        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);
+            });
+        }
+
+        /// <summary>
+        /// Times the debug.
+        /// </summary>
+        /// <param name="logger">The logger.</param>
+        /// <param name="message">The message.</param>
+        /// <param name="args">The arguments.</param>
+        /// <returns>IDisposable.</returns>
+        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);
+            });
+        }
+
+        /// <summary>
+        /// Times the information.
+        /// </summary>
+        /// <param name="logger">The logger.</param>
+        /// <param name="message">The message.</param>
+        /// <param name="args">The arguments.</param>
+        /// <returns>IDisposable.</returns>
+        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);
+            });
+        }
     }
 }

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<long> _action;
+            private readonly Stopwatch _sw;
+
+            public Disposable(IDisposable disposable, Action<long> action)
+            {
+                _disposable = disposable;
+                _action = action;
+                _sw = new Stopwatch();
+                _sw.Start();
+            }
+
+            public void Dispose()
+            {
+                _sw.Stop();
+                _action(_sw.ElapsedMilliseconds);
+                _disposable.Dispose();
+            }
+        }
+
+        /// <summary>
+        /// Times the trace.
+        /// </summary>
+        /// <param name="logger">The logger.</param>
+        /// <param name="message">The message.</param>
+        /// <param name="args">The arguments.</param>
+        /// <returns>IDisposable.</returns>
+        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);
+            });
+        }
+
+        /// <summary>
+        /// Times the debug.
+        /// </summary>
+        /// <param name="logger">The logger.</param>
+        /// <param name="message">The message.</param>
+        /// <param name="args">The arguments.</param>
+        /// <returns>IDisposable.</returns>
+        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);
+            });
+        }
+
+        /// <summary>
+        /// Times the information.
+        /// </summary>
+        /// <param name="logger">The logger.</param>
+        /// <param name="message">The message.</param>
+        /// <param name="args">The arguments.</param>
+        /// <returns>IDisposable.</returns>
+        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);
+            });
+        }
+    }
+}

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<string, string>[] {
+                    new KeyValuePair<string, string>( "Method", notification.Method),
+                    new KeyValuePair<string, string>( "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<ErrorResponse> 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<string, string>[] {
+                    new KeyValuePair<string, string>( "Id", request.Id?.ToString()),
+                    new KeyValuePair<string, string>( "Method", request.Method),
+                    new KeyValuePair<string, string>( "Params", request.Params?.ToString())
+                }))
                 {
-                    var property = typeof(Task<>)
-                        .MakeGenericType(result.GetType().GetTypeInfo().GetGenericArguments()[0]).GetTypeInfo()
-                        .GetProperty(nameof(Task<object>.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<object>.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)

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