Add more logging and internal documentation

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()
  {
- // Noop 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>()