Improvements to logging during startup.

tintoy/msbuild-project-tools-vscode#42
tintoy · Nov 16, 2018 · 3ff6897 · 3ff6897
1 parent 89c5b9d
commit 3ff6897
Show file tree

Hide file tree

Showing 6 changed files with 32 additions and 10 deletions.
diff --git a/.appveyor.yml b/.appveyor.yml
@@ -1,4 +1,4 @@
-version: 0.2.46.{build}
+version: 0.2.47.{build}
 image: Visual Studio 2017
 build_script:
 - ps: >-

diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -1,5 +1,9 @@
 # Change Log
 
+## v0.2.47
+
+* Improvements to logging during startup (tintoy/msbuild-project-tools-vscode#42).
+
 ## v0.2.46
 
 * Log configured package sources when initialising a project document (tintoy/msbuild-project-tools-vscode#44).

diff --git a/src/LanguageServer.Engine/Logging/LanguageServerSink.cs b/src/LanguageServer.Engine/Logging/LanguageServerSink.cs
@@ -66,6 +66,11 @@ public LanguageServerLoggingSink(ILanguageServer languageServer, LoggingLevelSwi
             }
         }
 
+        /// <summary>
+        ///     Can log entries be sent to the language server?
+        /// </summary>
+        bool CanLog => _languageServer.Server != null && !_hasServerShutDown;
+
         /// <summary>
         ///     Emit a log event.
         /// </summary>
@@ -74,7 +79,7 @@ public LanguageServerLoggingSink(ILanguageServer languageServer, LoggingLevelSwi
         /// </param>
         public void Emit(LogEvent logEvent)
         {
-            if (_hasServerShutDown)
+            if (!CanLog)
                 return;
 
             if (logEvent.Level < _levelSwitch.MinimumLevel)

diff --git a/src/LanguageServer/LoggingModule.cs b/src/LanguageServer/LoggingModule.cs
@@ -107,7 +107,7 @@ static ILogger CreateLogger(IComponentContext componentContext)
             ILogger logger = loggerConfiguration.CreateLogger();
             Log.Logger = logger;
 
-            Log.Verbose("Logger initialised.");
+            logger.Verbose("Logger initialised.");
 
             return logger;
         }

diff --git a/src/LanguageServer/Program.cs b/src/LanguageServer/Program.cs
@@ -47,6 +47,10 @@ static void Main()
             {
                 Console.WriteLine(unexpectedError);
             }
+            finally
+            {
+                Log.CloseAndFlush();
+            }
         }
 
         /// <summary>
@@ -61,16 +65,26 @@ static async Task AsyncMain()
             using (Terminator terminator = new Terminator())
             using (IContainer container = BuildContainer())
             {
+                // Force initialisation of logging.
+                ILogger log = container.Resolve<ILogger>().ForContext(typeof(Program));
+
+                log.Debug("Creating language server...");
+
                 var server = container.Resolve<LSP.Server.LanguageServer>();
 
+                log.Debug("Waiting for client to initialise language server...");
+
                 await server.Initialize();
+
+                log.Debug("Language server initialised by client.");
+
                 await server.WasShutDown;
 
-                Log.Information("Server is shutting down...");
+                log.Debug("Language server is shutting down...");
 
                 await server.WaitForExit;
 
-                Log.Information("Server has shut down. Preparing to terminate server process...");
+                log.Debug("Server has shut down. Preparing to terminate server process...");
 
                 // AF: Temporary fix for tintoy/msbuild-project-tools-vscode#36
                 //
@@ -79,10 +93,8 @@ static async Task AsyncMain()
                     TimeSpan.FromSeconds(3)
                 );
 
-                // TODO: Terminate immediately if the client process has terminated unexpectedly.
+                log.Debug("Server process is ready to terminate.");
             }
-
-            Log.Information("Server process is ready to terminate.");
         }
 
         /// <summary>

diff --git a/src/LanguageServer/Terminator.cs b/src/LanguageServer/Terminator.cs
@@ -50,7 +50,7 @@ public Terminator()
         /// </param>
         public async void TerminateAfter(TimeSpan timeout)
         {
-            Log.Verbose("Language server process will be forcibly terminated in {Timeout} seconds.", timeout.TotalSeconds);
+            Log.Debug("Language server process will be forcibly terminated in {Timeout} seconds.", timeout.TotalSeconds);
 
             CancellationToken cancellationToken = _cancellation.Token;
             _cancellation.CancelAfter(timeout);
@@ -59,12 +59,13 @@ public async void TerminateAfter(TimeSpan timeout)
             {
                 await Task.Delay(timeout, cancellationToken);
 
-                Log.Warning("Timed out after waiting {Timeout} seconds; the language server process will now be forcibly terminated within {TerminationDelay} second(s).",
+                Log.Debug("Timed out after waiting {Timeout} seconds; the language server process will now be forcibly terminated within {TerminationDelay} second(s).",
                     timeout.TotalSeconds,
                     TerminationDelay.TotalSeconds
                 );
 
                 // Last-ditch effort to flush pending log entries.
+                (Log as IDisposable)?.Dispose();
                 Serilog.Log.CloseAndFlush();
                 await Task.Delay(
                     TimeSpan.FromSeconds(1)