Merge pull request #1474 from PowerShell/andschwa/comments

Add more logging and internal documentation

Author: andyleejordan

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 = "<development-build>";
         public static readonly string BuildOrigin = "<development>";
         public static readonly System.DateTime? BuildTime = System.DateTime.Parse("2019-12-06T21:43:41", CultureInfo.InvariantCulture.DateTimeFormat);

src/PowerShellEditorServices.Hosting/Configuration/HostLogger.cs

@@ -14,9 +14,12 @@ namespace Microsoft.PowerShell.EditorServices.Hosting
 {
     /// <summary>
     /// 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.
     /// </summary>
+    /// <remarks>
+    /// The underlying values of this enum attempt to align to both <see
+    /// cref="Microsoft.Logging.Extensions.LogLevel"</see> and <see
+    /// cref="Serilog.Events.LogEventLevel"</see>.
+    /// </remarks>
     public enum PsesLogLevel
     {
         Diagnostic = 0,
@@ -27,9 +30,14 @@ public enum PsesLogLevel
     }
 
     /// <summary>
-    /// 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.
     /// </summary>
+    /// <remarks>
+    /// 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.
+    /// </remarks>
     public sealed class HostLogger :
         IObservable<(PsesLogLevel logLevel, string message)>,
         IObservable<(int logLevel, string message)>

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,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
 {
     /// <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.
     /// </summary>
+    /// <remarks>
+    /// 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"/>.
+    /// </remarks>
     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(
         /// <summary>
         /// Start and run Editor Services and then wait for shutdown.
         /// </summary>
+        /// <remarks>
+        /// TODO: Use "Async" suffix in names of methods that return an awaitable type.
+        /// </remarks>
         /// <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,14 +68,60 @@ public Task RunUntilShutdown()
             return runAndAwaitShutdown;
         }
 
+        /// <remarks>
+        /// 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.
+        /// </remarks>
         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.
+        /// This is the servers' entry point, e.g. <c>main</c>, as it instantiates, runs and waits
+        /// for the LSP and debug servers at the heart of Editor Services. Uses <see
+        /// cref="HostStartupInfo"/>.
         /// </summary>
+        /// <remarks>
+        /// The logical stack of the program is:
+        /// <list type="number">
+        /// <listheader>
+        ///     <term>Symbol</term>
+        ///     <description>Description</description>
+        /// </listheader>
+        /// <item>
+        ///     <term><see cref="Microsoft.PowerShell.EditorServices.Commands.StartEditorServicesCommand"/></term>
+        ///     <description>
+        ///     The StartEditorServicesCommand PSCmdlet, our PowerShell cmdlet written in C# and
+        ///     shipped in the module.
+        ///     </description>
+        /// </item>
+        /// <item>
+        ///     <term><see cref="Microsoft.PowerShell.EditorServices.Commands.StartEditorServicesCommand.EndProcessing"/></term>
+        ///     <description>
+        ///     As a cmdlet, this is the end of its "process" block, and it instantiates <see
+        ///     cref="EditorServicesLoader"/>.
+        ///     </description>
+        /// </item>
+        /// <item>
+        ///     <term><see cref="EditorServicesLoader.LoadAndRunEditorServicesAsync"></term>
+        ///     <description>
+        ///     Loads isolated dependencies then runs and returns the next task.
+        ///     </description>
+        /// </item>
+        /// <item>
+        ///     <term><see cref="RunUntilShutdown"></term>
+        ///     <description>Task which opens a logfile then returns this task.</description>
+        /// </item>
+        /// <item>
+        ///     <term><see cref="CreateEditorServicesAndRunUntilShutdown"></term>
+        ///     <description>This task!</description>
+        /// </item>
+        /// </list>
+        /// </remarks>
         /// <returns>A task that ends when Editor Services shuts down.</returns>
         private async Task CreateEditorServicesAndRunUntilShutdown()
         {

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

src/PowerShellEditorServices/Hosting/EditorServicesServerFactory.cs

@@ -21,16 +21,25 @@ namespace Microsoft.PowerShell.EditorServices.Hosting
 {
     /// <summary>
     /// 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.
     /// </summary>
+    /// <remarks>
+    /// 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 <see
+    /// cref="Microsoft.Extensions.Logging"/> and <see
+    /// cref="Microsoft.Extensions.DependencyInjection"/>.
+    /// </remarks>
     internal class EditorServicesServerFactory : IDisposable
     {
         /// <summary>
-        /// Create a new Editor Services factory.
-        /// This method will instantiate logging.
+        /// Create a new Editor Services factory. This method will instantiate logging.
         /// </summary>
+        /// <remarks>
+        /// This can only be called once because it sets global state (the logger) and that call is
+        /// in <see cref="EditorServicesRunner"/>.
+        ///
+        /// 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").
+        /// </remarks>
         /// <param name="logPath">The path of the log file to use.</param>
         /// <param name="minimumLogLevel">The minimum log level to use.</param>
         /// <returns></returns>
@@ -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
         /// <summary>
         /// Create the LSP server.
         /// </summary>
+        /// <remarks>
+        /// This is only called once and that's in <see cref="EditorServicesRunner"/>.
+        /// </remarks>
         /// <param name="inputStream">The protocol transport input stream.</param>
         /// <param name="outputStream">The protocol transport output stream.</param>
-        /// <param name="hostStartupInfo">The host details configuration for Editor Services instantation.</param>
+        /// <param name="hostStartupInfo">The host details configuration for Editor Services
+        /// instantation.</param>
         /// <returns>A new, unstarted language server instance.</returns>
         public PsesLanguageServer CreateLanguageServer(
             Stream inputStream,
@@ -85,25 +101,51 @@ public PsesLanguageServer CreateLanguageServer(
         /// <summary>
         /// Create the debug server given a language server instance.
         /// </summary>
+        /// <remarks>
+        /// This is only called once and that's in <see cref="EditorServicesRunner"/>.
+        /// </remarks>
         /// <param name="inputStream">The protocol transport input stream.</param>
         /// <param name="outputStream">The protocol transport output stream.</param>
         /// <param name="languageServer"></param>
         /// <returns>A new, unstarted debug server instance.</returns>
-        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);
         }
 
         /// <summary>
         /// Create a new debug server based on an old one in an ended session.
         /// </summary>
+        /// <remarks>
+        /// This is only called once and that's in <see cref="EditorServicesRunner"/>.
+        /// </remarks>
         /// <param name="inputStream">The protocol transport input stream.</param>
         /// <param name="outputStream">The protocol transport output stream.</param>
         /// <param name="debugServer">The old debug server to recreate.</param>
         /// <returns></returns>
-        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);
         }
 
         /// <summary>
@@ -113,13 +155,16 @@ public PsesDebugServer RecreateDebugServer(Stream inputStream, Stream outputStre
         /// <param name="outputStream">The protocol transport output stream.</param>
         /// <param name="hostStartupInfo">The host startup configuration to create the server session with.</param>
         /// <returns></returns>
-        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<ILanguageServerFacade>(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);
         }
 
+        /// <remarks>
+        /// 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"/>. Instead,
+        /// this class should call <see cref="Serilog.Log.CloseAndFlush()"/> in a finalizer. This
+        /// could potentially even be done with <see
+        /// cref="SerilogLoggerFactoryExtensions.AddSerilog"</> by passing <c>dispose=true</c>.
+        /// </remarks>
         public void Dispose()
         {
             Log.CloseAndFlush();

src/PowerShellEditorServices/Hosting/HostStartupInfo.cs

@@ -9,9 +9,12 @@
 namespace Microsoft.PowerShell.EditorServices.Hosting
 {
     /// <summary>
-    /// 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.
     /// </summary>
+    /// <remarks>
+    /// TODO: Simplify this as a <see langword="record"/>.
+    /// </remarks>
     public sealed class HostStartupInfo
     {
         #region Constants
@@ -97,6 +100,11 @@ public sealed class HostStartupInfo
         /// <summary>
         /// The minimum log level of log events to be logged.
         /// </summary>
+        /// <remarks>
+        /// This is cast to all of <see cref="PsesLogLevel"/>, <see
+        /// cref="Microsoft.Extensions.Logging.LogLevel"/>, and <see
+        /// cref="Serilog.Events.LogEventLevel"/>, hence it is an <c>int</c>.
+        /// </remarks>
         public int LogLevel { get; }
 
         #endregion
@@ -158,6 +166,13 @@ public HostStartupInfo(
         #endregion
     }
 
+    /// <summary>
+    /// This is a strange class that is generally <c>null</c> or otherwise just has a single path
+    /// set. It is eventually parsed one-by-one when setting up the PowerShell runspace.
+    /// </summary>
+    /// <remarks>
+    /// TODO: Simplify this as a <see langword="record"/>.
+    /// </remarks>
     public sealed class ProfilePathInfo
     {
         public ProfilePathInfo(

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);
         }
     }
 }

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<string, object>
     // However, I wanted creation to be easy so you can do
     // new PsesTelemetryEvent { EventName = "eventName", Data = data }

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<LaunchAndAttachHandler>()
                     .WithHandler<DisconnectHandler>()
                     .WithHandler<BreakpointHandlers>()