From 3ff6897420fddf7815becbc102e925f9357a93d5 Mon Sep 17 00:00:00 2001 From: Adam Friedman Date: Sat, 17 Nov 2018 06:36:43 +1100 Subject: [PATCH] Improvements to logging during startup. tintoy/msbuild-project-tools-vscode#42 --- .appveyor.yml | 2 +- CHANGELOG.md | 4 ++++ .../Logging/LanguageServerSink.cs | 7 +++++- src/LanguageServer/LoggingModule.cs | 2 +- src/LanguageServer/Program.cs | 22 ++++++++++++++----- src/LanguageServer/Terminator.cs | 5 +++-- 6 files changed, 32 insertions(+), 10 deletions(-) diff --git a/.appveyor.yml b/.appveyor.yml index c68aae2..c6a271f 100644 --- 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 index bd551ad..31aeb50 100644 --- 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 index 8cfde16..a765e23 100644 --- a/src/LanguageServer.Engine/Logging/LanguageServerSink.cs +++ b/src/LanguageServer.Engine/Logging/LanguageServerSink.cs @@ -66,6 +66,11 @@ public LanguageServerLoggingSink(ILanguageServer languageServer, LoggingLevelSwi } } + /// + /// Can log entries be sent to the language server? + /// + bool CanLog => _languageServer.Server != null && !_hasServerShutDown; + /// /// Emit a log event. /// @@ -74,7 +79,7 @@ public LanguageServerLoggingSink(ILanguageServer languageServer, LoggingLevelSwi /// 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 index 13bd108..47c3113 100644 --- 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 index ad3f667..e922cc2 100644 --- a/src/LanguageServer/Program.cs +++ b/src/LanguageServer/Program.cs @@ -47,6 +47,10 @@ static void Main() { Console.WriteLine(unexpectedError); } + finally + { + Log.CloseAndFlush(); + } } /// @@ -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().ForContext(typeof(Program)); + + log.Debug("Creating language server..."); + var server = container.Resolve(); + 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."); } /// diff --git a/src/LanguageServer/Terminator.cs b/src/LanguageServer/Terminator.cs index c9b56c2..10f6582 100644 --- a/src/LanguageServer/Terminator.cs +++ b/src/LanguageServer/Terminator.cs @@ -50,7 +50,7 @@ public Terminator() /// 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)