From 516b15ac4e512c22f1f173bb8fc955e0028bcb73 Mon Sep 17 00:00:00 2001 From: Andrew Schwartzmeyer Date: Mon, 10 May 2021 16:05:02 -0700 Subject: [PATCH 1/5] Markup `PowerShellEditorServices/Hosting` As opposed to `PowerShellEditorServices.Hosting`. Same namespace, different assembly. --- .../Hosting/EditorServicesLoading.cs | 2 +- .../Hosting/EditorServicesServerFactory.cs | 77 ++++++++++++++++--- .../Hosting/HostStartupInfo.cs | 19 ++++- .../Logging/PsesTelemetryEvent.cs | 2 +- 4 files changed, 84 insertions(+), 16 deletions(-) diff --git a/src/PowerShellEditorServices/Hosting/EditorServicesLoading.cs b/src/PowerShellEditorServices/Hosting/EditorServicesLoading.cs index b8276652b..f4b4d386d 100644 --- a/src/PowerShellEditorServices/Hosting/EditorServicesLoading.cs +++ b/src/PowerShellEditorServices/Hosting/EditorServicesLoading.cs @@ -11,7 +11,7 @@ internal static class EditorServicesLoading { internal static void LoadEditorServicesForHost() { - // No op that forces loading this assembly + // No-op that forces loading this assembly } } } diff --git a/src/PowerShellEditorServices/Hosting/EditorServicesServerFactory.cs b/src/PowerShellEditorServices/Hosting/EditorServicesServerFactory.cs index b2b96d4d1..82fe5214a 100644 --- a/src/PowerShellEditorServices/Hosting/EditorServicesServerFactory.cs +++ b/src/PowerShellEditorServices/Hosting/EditorServicesServerFactory.cs @@ -21,16 +21,25 @@ namespace Microsoft.PowerShell.EditorServices.Hosting { /// /// Factory class for hiding dependencies of Editor Services. - /// In particular, dependency injection and logging are wrapped by factory methods on this class - /// so that the host assembly can construct the LSP and debug servers - /// without taking logging or dependency injection dependencies directly. /// + /// + /// Dependency injection and logging are wrapped by factory methods on this class so that the + /// host assembly can construct the LSP and debug servers without directly depending on and . + /// internal class EditorServicesServerFactory : IDisposable { /// - /// Create a new Editor Services factory. - /// This method will instantiate logging. + /// Create a new Editor Services factory. This method will instantiate logging. /// + /// + /// This can only be called once because it sets global state (the logger) and that call is + /// in . + /// + /// TODO: Why is this a static function wrapping a constructor instead of just a + /// constructor? In the end it returns an instance (albeit a "singleton"). + /// /// The path of the log file to use. /// The minimum log level to use. /// @@ -54,6 +63,9 @@ public static EditorServicesServerFactory Create(string logPath, int minimumLogL return new EditorServicesServerFactory(loggerFactory, (LogLevel)minimumLogLevel); } + // TODO: Can we somehow refactor this member so the language and debug servers can be + // instantiated using their constructors instead of tying them to this factory with `Create` + // methods? private readonly ILoggerFactory _loggerFactory; private readonly Microsoft.Extensions.Logging.ILogger _logger; @@ -70,9 +82,13 @@ private EditorServicesServerFactory(ILoggerFactory loggerFactory, LogLevel minim /// /// Create the LSP server. /// + /// + /// This is only called once and that's in . + /// /// The protocol transport input stream. /// The protocol transport output stream. - /// The host details configuration for Editor Services instantation. + /// The host details configuration for Editor Services + /// instantation. /// A new, unstarted language server instance. public PsesLanguageServer CreateLanguageServer( Stream inputStream, @@ -85,25 +101,51 @@ public PsesLanguageServer CreateLanguageServer( /// /// Create the debug server given a language server instance. /// + /// + /// This is only called once and that's in . + /// /// The protocol transport input stream. /// The protocol transport output stream. /// /// A new, unstarted debug server instance. - public PsesDebugServer CreateDebugServerWithLanguageServer(Stream inputStream, Stream outputStream, PsesLanguageServer languageServer, bool usePSReadLine) + public PsesDebugServer CreateDebugServerWithLanguageServer( + Stream inputStream, + Stream outputStream, + PsesLanguageServer languageServer, + bool usePSReadLine) { - return new PsesDebugServer(_loggerFactory, inputStream, outputStream, languageServer.LanguageServer.Services, useTempSession: false, usePSReadLine); + return new PsesDebugServer( + _loggerFactory, + inputStream, + outputStream, + languageServer.LanguageServer.Services, + useTempSession: false, + usePSReadLine); } /// /// Create a new debug server based on an old one in an ended session. /// + /// + /// This is only called once and that's in . + /// /// The protocol transport input stream. /// The protocol transport output stream. /// The old debug server to recreate. /// - public PsesDebugServer RecreateDebugServer(Stream inputStream, Stream outputStream, PsesDebugServer debugServer, bool usePSReadLine) + public PsesDebugServer RecreateDebugServer( + Stream inputStream, + Stream outputStream, + PsesDebugServer debugServer, + bool usePSReadLine) { - return new PsesDebugServer(_loggerFactory, inputStream, outputStream, debugServer.ServiceProvider, useTempSession: false, usePSReadLine); + return new PsesDebugServer( + _loggerFactory, + inputStream, + outputStream, + debugServer.ServiceProvider, + useTempSession: false, + usePSReadLine); } /// @@ -113,13 +155,16 @@ public PsesDebugServer RecreateDebugServer(Stream inputStream, Stream outputStre /// The protocol transport output stream. /// The host startup configuration to create the server session with. /// - public PsesDebugServer CreateDebugServerForTempSession(Stream inputStream, Stream outputStream, HostStartupInfo hostStartupInfo) + public PsesDebugServer CreateDebugServerForTempSession( + Stream inputStream, + Stream outputStream, + HostStartupInfo hostStartupInfo) { var serviceProvider = new ServiceCollection() .AddLogging(builder => builder .ClearProviders() .AddSerilog() - .SetMinimumLevel(LogLevel.Trace)) + .SetMinimumLevel(LogLevel.Trace)) // TODO: Why randomly set to trace? .AddSingleton(provider => null) .AddPsesLanguageServices(hostStartupInfo) // For a Temp session, there is no LanguageServer so just set it to null @@ -143,6 +188,14 @@ public PsesDebugServer CreateDebugServerForTempSession(Stream inputStream, Strea usePSReadLine: hostStartupInfo.ConsoleReplEnabled && !hostStartupInfo.UsesLegacyReadLine); } + /// + /// TODO: This class probably should not be as the primary + /// intention of that interface is to provide cleanup of unmanaged resources, which the + /// logger certainly is not. Nor is this class used with a . Instead, + /// this class should call in a finalizer. This + /// could potentially even be done with by passing dispose=true. + /// public void Dispose() { Log.CloseAndFlush(); diff --git a/src/PowerShellEditorServices/Hosting/HostStartupInfo.cs b/src/PowerShellEditorServices/Hosting/HostStartupInfo.cs index d8d631534..5f3ae7647 100644 --- a/src/PowerShellEditorServices/Hosting/HostStartupInfo.cs +++ b/src/PowerShellEditorServices/Hosting/HostStartupInfo.cs @@ -9,9 +9,12 @@ namespace Microsoft.PowerShell.EditorServices.Hosting { /// - /// Contains details about the host as well as any other information - /// needed by Editor Services at startup time. + /// Contains details about the host as well as any other information needed by Editor Services + /// at startup time. /// + /// + /// TODO: Simplify this as a . + /// public sealed class HostStartupInfo { #region Constants @@ -97,6 +100,11 @@ public sealed class HostStartupInfo /// /// The minimum log level of log events to be logged. /// + /// + /// This is cast to all of , , and , hence it is an int. + /// public int LogLevel { get; } #endregion @@ -158,6 +166,13 @@ public HostStartupInfo( #endregion } + /// + /// This is a strange class that is generally null or otherwise just has a single path + /// set. It is eventually parsed one-by-one when setting up the PowerShell runspace. + /// + /// + /// TODO: Simplify this as a . + /// public sealed class ProfilePathInfo { public ProfilePathInfo( diff --git a/src/PowerShellEditorServices/Logging/PsesTelemetryEvent.cs b/src/PowerShellEditorServices/Logging/PsesTelemetryEvent.cs index b62c8042c..d8c2a1d2a 100644 --- a/src/PowerShellEditorServices/Logging/PsesTelemetryEvent.cs +++ b/src/PowerShellEditorServices/Logging/PsesTelemetryEvent.cs @@ -6,7 +6,7 @@ namespace Microsoft.PowerShell.EditorServices.Logging { - // This inheirits from Dictionary so that it can be passed in to SendTelemetryEvent() + // This inherits from Dictionary so that it can be passed in to SendTelemetryEvent() // which takes in an IDictionary // However, I wanted creation to be easy so you can do // new PsesTelemetryEvent { EventName = "eventName", Data = data } From d06d9373f342b9a5a86d60fe1ae2972127f1a9d7 Mon Sep 17 00:00:00 2001 From: Andrew Schwartzmeyer Date: Mon, 10 May 2021 17:57:33 -0700 Subject: [PATCH 2/5] Markup `PowerShellEditorServices/Server` --- .../Server/PsesDebugServer.cs | 1 + .../Server/PsesLanguageServer.cs | 24 ++++++++++++++++--- .../Server/PsesServiceCollectionExtensions.cs | 7 +++++- 3 files changed, 28 insertions(+), 4 deletions(-) diff --git a/src/PowerShellEditorServices/Server/PsesDebugServer.cs b/src/PowerShellEditorServices/Server/PsesDebugServer.cs index b0e4b4b7a..c09a54f14 100644 --- a/src/PowerShellEditorServices/Server/PsesDebugServer.cs +++ b/src/PowerShellEditorServices/Server/PsesDebugServer.cs @@ -99,6 +99,7 @@ public async Task StartAsync() .AddLogging() .AddOptions() .AddPsesDebugServices(ServiceProvider, this, _useTempSession)) + // TODO: Consider replacing all WithHandler with AddSingleton .WithHandler() .WithHandler() .WithHandler() diff --git a/src/PowerShellEditorServices/Server/PsesLanguageServer.cs b/src/PowerShellEditorServices/Server/PsesLanguageServer.cs index 74427fa85..bf74f8bba 100644 --- a/src/PowerShellEditorServices/Server/PsesLanguageServer.cs +++ b/src/PowerShellEditorServices/Server/PsesLanguageServer.cs @@ -32,10 +32,16 @@ internal class PsesLanguageServer /// /// Create a new language server instance. /// + /// + /// This class is only ever instantiated via . It is essentially a + /// singleton. The factory hides the logger. + /// /// Factory to create loggers with. /// Protocol transport input stream. /// Protocol transport output stream. - /// Host configuration to instantiate the server and services with. + /// Host configuration to instantiate the server and services + /// with. public PsesLanguageServer( ILoggerFactory factory, Stream inputStream, @@ -53,6 +59,11 @@ public PsesLanguageServer( /// /// Start the server listening for input. /// + /// + /// For the services (including the + /// context wrapper around PowerShell itself) see . + /// /// A task that completes when the server is ready and listening. public async Task StartAsync() { @@ -62,11 +73,12 @@ public async Task StartAsync() .WithInput(_inputStream) .WithOutput(_outputStream) .WithServices(serviceCollection => serviceCollection - .AddPsesLanguageServices(_hostDetails)) + .AddPsesLanguageServices(_hostDetails)) // NOTE: This adds a lot of services! .ConfigureLogging(builder => builder - .AddSerilog(Log.Logger) + .AddSerilog(Log.Logger) // TODO: Set dispose to true? .AddLanguageProtocolLogging() .SetMinimumLevel(_minimumLogLevel)) + // TODO: Consider replacing all WithHandler with AddSingleton .WithHandler() .WithHandler() .WithHandler() @@ -91,10 +103,15 @@ public async Task StartAsync() .WithHandler() .WithHandler() .WithHandler() + // NOTE: The OnInitialize delegate gets run when we first receive the + // _Initialize_ request: + // https://microsoft.github.io/language-server-protocol/specifications/specification-current/#initialize .OnInitialize( // TODO: Either fix or ignore "method lacks 'await'" warning. async (languageServer, request, cancellationToken) => { + Log.Logger.Debug("Initializing OmniSharp Language Server"); + var serviceProvider = languageServer.Services; var workspaceService = serviceProvider.GetService(); @@ -125,6 +142,7 @@ public async Task StartAsync() /// A task that completes when the server is shut down. public async Task WaitForShutdown() { + Log.Logger.Debug("Shutting down OmniSharp Language Server"); await _serverStart.Task.ConfigureAwait(false); await LanguageServer.WaitForExit.ConfigureAwait(false); } diff --git a/src/PowerShellEditorServices/Server/PsesServiceCollectionExtensions.cs b/src/PowerShellEditorServices/Server/PsesServiceCollectionExtensions.cs index 0ca546453..e0fda77c0 100644 --- a/src/PowerShellEditorServices/Server/PsesServiceCollectionExtensions.cs +++ b/src/PowerShellEditorServices/Server/PsesServiceCollectionExtensions.cs @@ -24,9 +24,13 @@ public static IServiceCollection AddPsesLanguageServices( (provider) => PowerShellContextService.Create( provider.GetService(), + // NOTE: Giving the context service access to the language server this + // early is dangerous because it allows it to start sending + // notifications etc. before it has initialized, potentially resulting + // in deadlocks. We're working on a solution to this. provider.GetService(), hostStartupInfo)) - .AddSingleton() + .AddSingleton() // TODO: What's the difference between this and the TemplateHandler? .AddSingleton() .AddSingleton() .AddSingleton( @@ -34,6 +38,7 @@ public static IServiceCollection AddPsesLanguageServices( { var extensionService = new ExtensionService( provider.GetService(), + // NOTE: See above warning. provider.GetService()); extensionService.InitializeAsync( serviceProvider: provider, From 6728a90b90b4551243eedb0f4102ef58c1476252 Mon Sep 17 00:00:00 2001 From: Andrew Schwartzmeyer Date: Wed, 12 May 2021 17:43:09 -0700 Subject: [PATCH 3/5] Markup `PowerShellEditorServices.Hosting` --- .../BuildInfo.cs | 1 + .../Configuration/HostLogger.cs | 16 +++-- .../EditorServicesLoader.cs | 6 +- .../Internal/EditorServicesRunner.cs | 63 +++++++++++++++++-- 4 files changed, 73 insertions(+), 13 deletions(-) diff --git a/src/PowerShellEditorServices.Hosting/BuildInfo.cs b/src/PowerShellEditorServices.Hosting/BuildInfo.cs index f516c8a8e..54e28024f 100644 --- a/src/PowerShellEditorServices.Hosting/BuildInfo.cs +++ b/src/PowerShellEditorServices.Hosting/BuildInfo.cs @@ -4,6 +4,7 @@ namespace Microsoft.PowerShell.EditorServices.Hosting { public static class BuildInfo { + // TODO: Include a Git commit hash in this. public static readonly string BuildVersion = ""; public static readonly string BuildOrigin = ""; public static readonly System.DateTime? BuildTime = System.DateTime.Parse("2019-12-06T21:43:41", CultureInfo.InvariantCulture.DateTimeFormat); diff --git a/src/PowerShellEditorServices.Hosting/Configuration/HostLogger.cs b/src/PowerShellEditorServices.Hosting/Configuration/HostLogger.cs index af524352c..2a081e7e2 100644 --- a/src/PowerShellEditorServices.Hosting/Configuration/HostLogger.cs +++ b/src/PowerShellEditorServices.Hosting/Configuration/HostLogger.cs @@ -14,9 +14,12 @@ namespace Microsoft.PowerShell.EditorServices.Hosting { /// /// User-facing log level for editor services configuration. - /// The underlying values of this enum align to both Microsoft.Logging.Extensions.LogLevel - /// and Serilog.Events.LogEventLevel. /// + /// + /// The underlying values of this enum attempt to align to both and . + /// public enum PsesLogLevel { Diagnostic = 0, @@ -27,9 +30,14 @@ public enum PsesLogLevel } /// - /// A logging front-end for host startup allowing handover to the backend - /// and decoupling from the host's particular logging sink. + /// A logging front-end for host startup allowing handover to the backend and decoupling from + /// the host's particular logging sink. /// + /// + /// This custom logger exists to allow us to log during startup, which is vital information for + /// debugging, but happens before we can load any logger library. This is because startup + /// happens in our isolated assembly environment. See #2292 for more information. + /// public sealed class HostLogger : IObservable<(PsesLogLevel logLevel, string message)>, IObservable<(int logLevel, string message)> diff --git a/src/PowerShellEditorServices.Hosting/EditorServicesLoader.cs b/src/PowerShellEditorServices.Hosting/EditorServicesLoader.cs index 6309adff1..b55d7a70a 100644 --- a/src/PowerShellEditorServices.Hosting/EditorServicesLoader.cs +++ b/src/PowerShellEditorServices.Hosting/EditorServicesLoader.cs @@ -263,11 +263,7 @@ private void UpdatePSModulePath() private void LogHostInformation() { - _logger.Log(PsesLogLevel.Diagnostic, "Logging host information"); - -_logger.Log(PsesLogLevel.Diagnostic, $@" -PID: {System.Diagnostics.Process.GetCurrentProcess().Id} -"); + _logger.Log(PsesLogLevel.Verbose, $"PID: {System.Diagnostics.Process.GetCurrentProcess().Id}"); _logger.Log(PsesLogLevel.Verbose, $@" == Build Details == diff --git a/src/PowerShellEditorServices.Hosting/Internal/EditorServicesRunner.cs b/src/PowerShellEditorServices.Hosting/Internal/EditorServicesRunner.cs index 2b5f70eeb..b4dbf7c63 100644 --- a/src/PowerShellEditorServices.Hosting/Internal/EditorServicesRunner.cs +++ b/src/PowerShellEditorServices.Hosting/Internal/EditorServicesRunner.cs @@ -1,18 +1,23 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. -using Microsoft.PowerShell.EditorServices.Server; using System; using System.Collections.Generic; using System.IO; using System.Threading.Tasks; +using Microsoft.PowerShell.EditorServices.Server; namespace Microsoft.PowerShell.EditorServices.Hosting { /// /// Class to manage the startup of PowerShell Editor Services. - /// This should be called by only after Editor Services has been loaded. /// + /// + /// This should be called by only after Editor Services has + /// been loaded. It relies on to indirectly load and . + /// internal class EditorServicesRunner : IDisposable { private readonly HostLogger _logger; @@ -36,6 +41,7 @@ public EditorServicesRunner( _logger = logger; _config = config; _sessionFileWriter = sessionFileWriter; + // NOTE: This factory helps to isolate `Microsoft.Extensions.Logging/DependencyInjection`. _serverFactory = EditorServicesServerFactory.Create(_config.LogPath, (int)_config.LogLevel, logger); _alreadySubscribedDebug = false; _loggersToUnsubscribe = loggersToUnsubscribe; @@ -44,10 +50,13 @@ public EditorServicesRunner( /// /// Start and run Editor Services and then wait for shutdown. /// + /// + /// TODO: Use "Async" suffix in names of methods that return an awaitable type. + /// /// A task that ends when Editor Services shuts down. public Task RunUntilShutdown() { - // Start Editor Services + // Start Editor Services (see function below) Task runAndAwaitShutdown = CreateEditorServicesAndRunUntilShutdown(); // Now write the session file @@ -59,14 +68,60 @@ public Task RunUntilShutdown() return runAndAwaitShutdown; } + /// + /// TODO: This class probably should not be as the primary + /// intention of that interface is to provide cleanup of unmanaged resources, which the + /// logger certainly is not. Nor is this class used with a . It is + /// only because of the use of that this class is also + /// disposable, and instead that class should be fixed. + /// public void Dispose() { _serverFactory.Dispose(); } /// - /// Master method for instantiating, running and waiting for the LSP and debug servers at the heart of Editor Services. + /// This is the servers' entry point, e.g. main, as it instantiates, runs and waits + /// for the LSP and debug servers at the heart of Editor Services. Uses . /// + /// + /// The logical stack of the program is: + /// + /// + /// Symbol + /// Description + /// + /// + /// + /// + /// The StartEditorServicesCommand PSCmdlet, our PowerShell cmdlet written in C# and + /// shipped in the module. + /// + /// + /// + /// + /// + /// As a cmdlet, this is the end of its "process" block, and it instantiates . + /// + /// + /// + /// + /// + /// Loads isolated dependencies then runs and returns the next task. + /// + /// + /// + /// + /// Task which opens a logfile then returns this task. + /// + /// + /// + /// This task! + /// + /// + /// /// A task that ends when Editor Services shuts down. private async Task CreateEditorServicesAndRunUntilShutdown() { From 43f5e1bd1bce347a4584e1005cb16b20c6035831 Mon Sep 17 00:00:00 2001 From: Andrew Schwartzmeyer Date: Wed, 12 May 2021 18:32:52 -0700 Subject: [PATCH 4/5] Add more logging to `PowerShellContextService.cs` Also change handled exceptions to warning instead of error. --- .../Logging/LoggerExtensions.cs | 2 +- .../PowerShellContextService.cs | 90 ++++++++++--------- 2 files changed, 47 insertions(+), 45 deletions(-) diff --git a/src/PowerShellEditorServices/Logging/LoggerExtensions.cs b/src/PowerShellEditorServices/Logging/LoggerExtensions.cs index 233b12a47..d0098e9ca 100644 --- a/src/PowerShellEditorServices/Logging/LoggerExtensions.cs +++ b/src/PowerShellEditorServices/Logging/LoggerExtensions.cs @@ -28,7 +28,7 @@ public static void LogHandledException( [CallerFilePath] string callerSourceFile = null, [CallerLineNumber] int callerLineNumber = -1) { - logger.LogError(message, exception); + logger.LogWarning(message, exception); } } } diff --git a/src/PowerShellEditorServices/Services/PowerShellContext/PowerShellContextService.cs b/src/PowerShellEditorServices/Services/PowerShellContext/PowerShellContextService.cs index 6d50baa0b..a6ea9ee45 100644 --- a/src/PowerShellEditorServices/Services/PowerShellContext/PowerShellContextService.cs +++ b/src/PowerShellEditorServices/Services/PowerShellContext/PowerShellContextService.cs @@ -174,6 +174,7 @@ public PowerShellContextService( OmniSharp.Extensions.LanguageServer.Protocol.Server.ILanguageServerFacade languageServer, bool isPSReadLineEnabled) { + logger.LogTrace("Instantiating PowerShellContextService and adding event handlers"); _languageServer = languageServer; this.logger = logger; this.isPSReadLineEnabled = isPSReadLineEnabled; @@ -212,9 +213,9 @@ public static PowerShellContextService Create( hostUserInterface, logger); + logger.LogTrace("Creating initial PowerShell runspace"); Runspace initialRunspace = PowerShellContextService.CreateRunspace(psHost, hostStartupInfo.LanguageMode); powerShellContext.Initialize(hostStartupInfo.ProfilePaths, initialRunspace, true, hostUserInterface); - powerShellContext.ImportCommandsModuleAsync(); // TODO: This can be moved to the point after the $psEditor object @@ -325,6 +326,7 @@ public void Initialize( IHostOutput consoleHost) { Validate.IsNotNull("initialRunspace", initialRunspace); + this.logger.LogTrace($"Initializing PowerShell context with runspace {initialRunspace.Name}"); this.ownsInitialRunspace = ownsInitialRunspace; this.SessionState = PowerShellContextState.NotStarted; @@ -351,11 +353,7 @@ public void Initialize( this.CurrentRunspace = this.initialRunspace; // Write out the PowerShell version for tracking purposes - this.logger.LogInformation( - string.Format( - "PowerShell runtime version: {0}, edition: {1}", - this.LocalPowerShellVersion.Version, - this.LocalPowerShellVersion.Edition)); + this.logger.LogInformation($"PowerShell Version: {this.LocalPowerShellVersion.Version}, Edition: {this.LocalPowerShellVersion.Edition}"); Version powerShellVersion = this.LocalPowerShellVersion.Version; if (powerShellVersion >= new Version(5, 0)) @@ -441,6 +439,8 @@ public void Initialize( public Task ImportCommandsModuleAsync(string path) { + this.logger.LogTrace($"Importing PowershellEditorServices commands from {path}"); + PSCommand importCommand = new PSCommand() .AddCommand("Import-Module") .AddArgument(path); @@ -463,6 +463,7 @@ private static bool CheckIfRunspaceNeedsEventHandlers(RunspaceDetails runspaceDe private void ConfigureRunspace(RunspaceDetails runspaceDetails) { + this.logger.LogTrace("Configuring Runspace"); runspaceDetails.Runspace.StateChanged += this.HandleRunspaceStateChanged; if (runspaceDetails.Runspace.Debugger != null) { @@ -475,6 +476,7 @@ private void ConfigureRunspace(RunspaceDetails runspaceDetails) private void CleanupRunspace(RunspaceDetails runspaceDetails) { + this.logger.LogTrace("Cleaning Up Runspace"); runspaceDetails.Runspace.StateChanged -= this.HandleRunspaceStateChanged; if (runspaceDetails.Runspace.Debugger != null) { @@ -596,6 +598,8 @@ public async Task> ExecuteCommandAsync( Validate.IsNotNull(nameof(psCommand), psCommand); Validate.IsNotNull(nameof(executionOptions), executionOptions); + this.logger.LogTrace($"Attempting to execute command(s): {GetStringForPSCommand(psCommand)}"); + // Add history to PSReadLine before cancelling, otherwise it will be restored as the // cancelled prompt when it's called again. if (executionOptions.AddToHistory) @@ -629,7 +633,7 @@ public async Task> ExecuteCommandAsync( this.ShouldExecuteWithEventing(executionOptions) || (PromptNest.IsRemote && executionOptions.IsReadLine))) { - this.logger.LogTrace("Passing command execution to pipeline thread."); + this.logger.LogTrace("Passing command execution to pipeline thread"); if (shouldCancelReadLine && PromptNest.IsReadLineBusy()) { @@ -714,8 +718,7 @@ public async Task> ExecuteCommandAsync( } catch (Exception e) { - logger.LogError( - "Exception occurred while executing debugger command:\r\n\r\n" + e.ToString()); + this.logger.LogException("Exception occurred while executing debugger command", e); } finally { @@ -736,11 +739,7 @@ public async Task> ExecuteCommandAsync( AddToHistory = executionOptions.AddToHistory }; - this.logger.LogTrace( - string.Format( - "Attempting to execute command(s):\r\n\r\n{0}", - GetStringForPSCommand(psCommand))); - + this.logger.LogTrace("Passing to PowerShell"); PowerShell shell = this.PromptNest.GetPowerShell(executionOptions.IsReadLine); @@ -818,29 +817,23 @@ public async Task> ExecuteCommandAsync( } else { - this.logger.LogTrace( - "Execution completed successfully."); + this.logger.LogTrace("Execution completed successfully"); } } } catch (PSRemotingDataStructureException e) { - this.logger.LogError( - "Pipeline stopped while executing command:\r\n\r\n" + e.ToString()); - + this.logger.LogHandledException("Pipeline stopped while executing command", e); errorMessages?.Append(e.Message); } catch (PipelineStoppedException e) { - this.logger.LogError( - "Pipeline stopped while executing command:\r\n\r\n" + e.ToString()); - + this.logger.LogHandledException("Pipeline stopped while executing command", e); errorMessages?.Append(e.Message); } catch (RuntimeException e) { - this.logger.LogWarning( - "Runtime exception occurred while executing command:\r\n\r\n" + e.ToString()); + this.logger.LogHandledException("Runtime exception occurred while executing command", e); hadErrors = true; errorMessages?.Append(e.Message); @@ -1078,8 +1071,7 @@ public async Task ExecuteScriptWithArgsAsync(string script, string arguments = n } catch (System.Management.Automation.DriveNotFoundException e) { - this.logger.LogError( - "Could not determine current filesystem location:\r\n\r\n" + e.ToString()); + this.logger.LogHandledException("Could not determine current filesystem location", e); } var strBld = new StringBuilder(); @@ -1250,9 +1242,7 @@ public void AbortExecution(bool shouldAbortDebugSession) if (this.SessionState == PowerShellContextState.Aborting || this.SessionState == PowerShellContextState.Disposed) { - this.logger.LogTrace( - string.Format( - $"Execution abort requested when already aborted (SessionState = {this.SessionState})")); + this.logger.LogTrace($"Execution abort requested when already aborted (SessionState = {this.SessionState})"); return; } @@ -1539,8 +1529,8 @@ private void CloseRunspace(RunspaceDetails runspaceDetails) if (exitException != null) { - this.logger.LogError( - $"Caught {exitException.GetType().Name} while exiting {runspaceDetails.Location} runspace:\r\n{exitException.ToString()}"); + this.logger.LogHandledException( + $"Caught {exitException.GetType().Name} while exiting {runspaceDetails.Location} runspace", exitException); } } } @@ -1582,6 +1572,8 @@ internal bool IsCurrentRunspaceOutOfProcess() /// internal void EnterNestedPrompt() { + this.logger.LogTrace("Entering nested prompt"); + if (this.IsCurrentRunspaceOutOfProcess()) { throw new NotSupportedException(); @@ -1884,8 +1876,15 @@ private void OnExecutionStatusChanged( hadErrors)); } + /// + /// TODO: This should somehow check if the server has actually started because we are + /// currently sending this notification before it has initialized, which is not allowed. + /// This might be the cause of our deadlock! + /// private void PowerShellContext_RunspaceChangedAsync(object sender, RunspaceChangedEventArgs e) { + this.logger.LogTrace("Sending runspaceChanged notification"); + _languageServer?.SendNotification( "powerShell/runspaceChanged", new MinifiedRunspaceDetails(e.NewRunspace)); @@ -1922,10 +1921,16 @@ public MinifiedRunspaceDetails(RunspaceDetails eventArgs) /// /// Event hook on the PowerShell context to listen for changes in script execution status /// + /// + /// TODO: This should somehow check if the server has actually started because we are + /// currently sending this notification before it has initialized, which is not allowed. + /// /// the PowerShell context sending the execution event /// details of the execution status change private void PowerShellContext_ExecutionStatusChangedAsync(object sender, ExecutionStatusChangedEventArgs e) { + this.logger.LogTrace("Sending executionStatusChanged notification"); + // The cancelling of the prompt (PSReadLine) causes an ExecutionStatus.Aborted to be sent after every // actual execution (ExecutionStatus.Running) on the pipeline. We ignore that event since it's counterintuitive to // the goal of this method which is to send updates when the pipeline is actually running something. @@ -1945,10 +1950,7 @@ private void PowerShellContext_ExecutionStatusChangedAsync(object sender, Execut private IEnumerable ExecuteCommandInDebugger(PSCommand psCommand, bool sendOutputToHost) { - this.logger.LogTrace( - string.Format( - "Attempting to execute command(s) in the debugger:\r\n\r\n{0}", - GetStringForPSCommand(psCommand))); + this.logger.LogTrace($"Attempting to execute command(s)a in the debugger: {GetStringForPSCommand(psCommand)}"); IEnumerable output = this.versionSpecificOperations.ExecuteCommandInDebugger( @@ -2144,6 +2146,8 @@ private static string GetStringForPSCommand(PSCommand psCommand) private void SetExecutionPolicy() { + this.logger.LogTrace("Setting execution policy..."); + // We want to get the list hierarchy of execution policies // Calling the cmdlet is the simplest way to do that IReadOnlyList policies = this.powerShell @@ -2188,7 +2192,7 @@ private void SetExecutionPolicy() } // Finally set the inherited execution policy - this.logger.LogTrace("Setting execution policy to {Policy}", policyToSet); + this.logger.LogTrace($"Setting execution policy to {policyToSet}"); try { this.powerShell @@ -2200,7 +2204,8 @@ private void SetExecutionPolicy() } catch (CmdletInvocationException e) { - this.logger.LogError(e, "Error occurred calling 'Set-ExecutionPolicy -Scope Process -ExecutionPolicy {Policy} -Force'", policyToSet); + this.logger.LogHandledException( + $"Error occurred calling 'Set-ExecutionPolicy -Scope Process -ExecutionPolicy {policyToSet} -Force'", e); } finally { @@ -2221,13 +2226,11 @@ private SessionDetails GetSessionDetails(Func invokeAction) } catch (RuntimeException e) { - this.logger.LogTrace( - "Runtime exception occurred while gathering runspace info:\r\n\r\n" + e.ToString()); + this.logger.LogHandledException("Runtime exception occurred while gathering runspace info", e); } catch (ArgumentNullException) { - this.logger.LogError( - "Could not retrieve session details but no exception was thrown."); + this.logger.LogError("Could not retrieve session details but no exception was thrown."); } // TODO: Return a harmless object if necessary @@ -2320,9 +2323,7 @@ private void SetProfileVariableInCurrentRunspace(ProfilePathInfo profilePaths) profilePaths.CurrentUserCurrentHost)); this.logger.LogTrace( - string.Format( - "Setting $profile variable in runspace. Current user host profile path: {0}", - profilePaths.CurrentUserCurrentHost)); + $"Setting $profile variable in runspace. Current user host profile path: {profilePaths.CurrentUserCurrentHost}"); // Set the variable in the runspace this.powerShell.Commands.Clear(); @@ -2545,6 +2546,7 @@ private void OnDebuggerStop(object sender, DebuggerStopEventArgs e) else { // TODO: How to handle this? + this.logger.LogError($"Unhandled TaskIndex: {taskIndex}"); } } From 14352c5ed01a7a75c3acfce9fc36485316af3ba4 Mon Sep 17 00:00:00 2001 From: Andrew Schwartzmeyer Date: Tue, 18 May 2021 18:28:10 -0700 Subject: [PATCH 5/5] Add more logging to `ConfigurationHandler.cs` --- .../Workspace/Handlers/ConfigurationHandler.cs | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/src/PowerShellEditorServices/Services/Workspace/Handlers/ConfigurationHandler.cs b/src/PowerShellEditorServices/Services/Workspace/Handlers/ConfigurationHandler.cs index b21294338..073c176cb 100644 --- a/src/PowerShellEditorServices/Services/Workspace/Handlers/ConfigurationHandler.cs +++ b/src/PowerShellEditorServices/Services/Workspace/Handlers/ConfigurationHandler.cs @@ -50,8 +50,10 @@ public PsesConfigurationHandler( public override async Task Handle(DidChangeConfigurationParams request, CancellationToken cancellationToken) { LanguageServerSettingsWrapper incomingSettings = request.Settings.ToObject(); - if(incomingSettings == null) + this._logger.LogTrace("Handling DidChangeConfiguration"); + if (incomingSettings == null) { + this._logger.LogTrace("Incoming settings were null"); return await Unit.Task.ConfigureAwait(false); } @@ -73,6 +75,7 @@ public override async Task Handle(DidChangeConfigurationParams request, Ca if (!string.IsNullOrEmpty(_configurationService.CurrentSettings.Cwd) && Directory.Exists(_configurationService.CurrentSettings.Cwd)) { + this._logger.LogTrace($"Setting CWD (from config) to {_configurationService.CurrentSettings.Cwd}"); await _powerShellContextService.SetWorkingDirectoryAsync( _configurationService.CurrentSettings.Cwd, isPathAlreadyEscaped: false).ConfigureAwait(false); @@ -80,9 +83,12 @@ await _powerShellContextService.SetWorkingDirectoryAsync( } else if (_workspaceService.WorkspacePath != null && Directory.Exists(_workspaceService.WorkspacePath)) { + this._logger.LogTrace($"Setting CWD (from workspace) to {_workspaceService.WorkspacePath}"); await _powerShellContextService.SetWorkingDirectoryAsync( _workspaceService.WorkspacePath, isPathAlreadyEscaped: false).ConfigureAwait(false); + } else { + this._logger.LogTrace("Tried to set CWD but in bad state"); } this._cwdSet = true; @@ -95,8 +101,10 @@ await _powerShellContextService.SetWorkingDirectoryAsync( if (_configurationService.CurrentSettings.EnableProfileLoading && (!this._profilesLoaded || !profileLoadingPreviouslyEnabled)) { + this._logger.LogTrace("Loading profiles..."); await _powerShellContextService.LoadHostProfilesAsync().ConfigureAwait(false); this._profilesLoaded = true; + this._logger.LogTrace("Loaded!"); } // Wait until after profiles are loaded (or not, if that's the @@ -104,11 +112,13 @@ await _powerShellContextService.SetWorkingDirectoryAsync( if (!this._consoleReplStarted) { // Start the interactive terminal + this._logger.LogTrace("Starting command loop"); _powerShellContextService.ConsoleReader.StartCommandLoop(); this._consoleReplStarted = true; } // Run any events subscribed to configuration updates + this._logger.LogTrace("Running configuration update event handlers"); ConfigurationUpdated(this, _configurationService.CurrentSettings); // Convert the editor file glob patterns into an array for the Workspace