WIP: More logging and notes

Author: andyleejordan

src/PowerShellEditorServices.Hosting/Commands/StartEditorServicesCommand.cs

@@ -402,7 +402,7 @@ private ConsoleReplKind GetReplKind()
 
             if (Stdio || !EnableConsoleRepl)
             {
-                _logger.Log(PsesLogLevel.Diagnostic, "REPL configured as None");
+                _logger.Log(PsesLogLevel.Verbose, "REPL configured as None");
                 return ConsoleReplKind.None;
             }
 
@@ -413,11 +413,11 @@ private ConsoleReplKind GetReplKind()
 
             if (UseLegacyReadLine || (!s_isWindows && majorVersion == 6))
             {
-                _logger.Log(PsesLogLevel.Diagnostic, "REPL configured as Legacy");
+                _logger.Log(PsesLogLevel.Verbose, "REPL configured as Legacy");
                 return ConsoleReplKind.LegacyReadLine;
             }
 
-            _logger.Log(PsesLogLevel.Diagnostic, "REPL configured as PSReadLine");
+            _logger.Log(PsesLogLevel.Verbose, "REPL configured as PSReadLine");
             return ConsoleReplKind.PSReadLine;
         }
 

src/PowerShellEditorServices.Hosting/Configuration/TransportConfig.cs

@@ -108,11 +108,11 @@ private DuplexNamedPipeTransportConfig(HostLogger logger, string pipeName)
 
         public async Task<(Stream inStream, Stream outStream)> ConnectStreamsAsync()
         {
-            _logger.Log(PsesLogLevel.Diagnostic, "Creating named pipe");
+            _logger.Log(PsesLogLevel.Verbose, "Creating named pipe");
             NamedPipeServerStream namedPipe = NamedPipeUtils.CreateNamedPipe(_pipeName, PipeDirection.InOut);
-            _logger.Log(PsesLogLevel.Diagnostic, "Waiting for named pipe connection");
+            _logger.Log(PsesLogLevel.Verbose, "Waiting for named pipe connection");
             await namedPipe.WaitForConnectionAsync().ConfigureAwait(false);
-            _logger.Log(PsesLogLevel.Diagnostic, "Named pipe connected");
+            _logger.Log(PsesLogLevel.Verbose, "Named pipe connected");
             return (namedPipe, namedPipe);
         }
     }

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 ==

src/PowerShellEditorServices.Hosting/Internal/EditorServicesRunner.cs

@@ -1,17 +1,20 @@
 // 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
 {
     /// <summary>
-    /// Class to manage the startup of PowerShell Editor Services.
-    /// This should be called by <see cref="EditorServicesLoader"/> only after Editor Services has been loaded.
+    /// Class to manage the startup of PowerShell Editor Services. This should be called by <see
+    /// cref="EditorServicesLoader"/> only after Editor Services has been loaded. It relies on <see
+    /// cref="EditorServicesServerFactory"/> to indirectly load <see
+    /// cref="Microsoft.Extensions.Logging"/> and <see
+    /// cref="Microsoft.Extensions.DependencyInjection"/>.
     /// </summary>
     internal class EditorServicesRunner : IDisposable
     {
@@ -36,18 +39,21 @@ 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;
         }
 
         /// <summary>
         /// Start and run Editor Services and then wait for shutdown.
+        ///
+        /// TODO: Use "Async" suffix in names of methods that return an awaitable type.
         /// </summary>
         /// <returns>A task that ends when Editor Services shuts down.</returns>
         public Task RunUntilShutdown()
         {
-            // Start Editor Services
+            // Start Editor Services (see function below)
             Task runAndAwaitShutdown = CreateEditorServicesAndRunUntilShutdown();
 
             // Now write the session file
@@ -59,13 +65,23 @@ public Task RunUntilShutdown()
             return runAndAwaitShutdown;
         }
 
+        /// <summary>
+        /// TODO: This class probably should not be <see cref="IDisposable"/> 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 <see langword="using"/>. It is
+        /// only because of the use of <see cref="_serverFactory"/> that this class is also
+        /// disposable, and instead that class should be fixed.
+        /// </summary>
         public void Dispose()
         {
             _serverFactory.Dispose();
         }
 
         /// <summary>
-        /// Master method for instantiating, running and waiting for the LSP and debug servers at the heart of Editor Services.
+        /// Master method for instantiating, running and waiting for the LSP and debug servers at
+        /// the heart of Editor Services. Uses <see cref="HostStartupInfo"/>.
+        ///
+        /// NOTE: This is essentially <c>main</c>.
         /// </summary>
         /// <returns>A task that ends when Editor Services shuts down.</returns>
         private async Task CreateEditorServicesAndRunUntilShutdown()

src/PowerShellEditorServices/Services/PowerShellContext/PowerShellContextService.cs

@@ -351,11 +351,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))
@@ -463,6 +459,7 @@ private static bool CheckIfRunspaceNeedsEventHandlers(RunspaceDetails runspaceDe
 
         private void ConfigureRunspace(RunspaceDetails runspaceDetails)
         {
+            this.logger.LogDebug("Configuring Runspace");
             runspaceDetails.Runspace.StateChanged += this.HandleRunspaceStateChanged;
             if (runspaceDetails.Runspace.Debugger != null)
             {
@@ -475,6 +472,7 @@ private void ConfigureRunspace(RunspaceDetails runspaceDetails)
 
         private void CleanupRunspace(RunspaceDetails runspaceDetails)
         {
+            this.logger.LogDebug("Cleaning Up Runspace");
             runspaceDetails.Runspace.StateChanged -= this.HandleRunspaceStateChanged;
             if (runspaceDetails.Runspace.Debugger != null)
             {
@@ -1933,6 +1931,9 @@ private void PowerShellContext_ExecutionStatusChangedAsync(object sender, Execut
             var options = e?.ExecutionOptions;
             if (options == null || !options.IsReadLine)
             {
+                // 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. We should also figure out exactly _why_ that's happening.
                 _languageServer?.SendNotification(
                     "powerShell/executionStatusChanged",
                     e);
@@ -2144,6 +2145,7 @@ 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<PSObject> policies = this.powerShell
@@ -2571,7 +2573,7 @@ private void ConfigureRunspaceCapabilities(RunspaceDetails runspaceDetails)
 
         private void PushRunspace(RunspaceDetails newRunspaceDetails)
         {
-            this.logger.LogTrace(
+            this.logger.LogDebug(
                 $"Pushing {this.CurrentRunspace.Location} ({this.CurrentRunspace.Context}), new runspace is {newRunspaceDetails.Location} ({newRunspaceDetails.Context}), connection: {newRunspaceDetails.ConnectionString}");
 
             RunspaceDetails previousRunspace = this.CurrentRunspace;