Enhanced Logging

README.md

@@ -87,7 +87,7 @@ $command = @(
         "-HostName 'My Client'",
         "-HostProfileId 'myclient'",
         "-HostVersion 1.0.0",
-        "-LogLevel Diagnostic"
+        "-LogLevel Trace"
 ) -join " "
 
 $pwsh_arguments = "-NoLogo -NoProfile -Command $command"

src/PowerShellEditorServices.Hosting/Commands/StartEditorServicesCommand.cs

@@ -138,7 +138,7 @@ public StartEditorServicesCommand()
         /// The minimum log level that should be emitted.
         /// </summary>
         [Parameter]
-        public PsesLogLevel LogLevel { get; set; } = PsesLogLevel.Normal;
+        public string LogLevel { get; set; } = PsesLogLevel.Warning.ToString();
 
         /// <summary>
         /// Paths to additional PowerShell modules to be imported at startup.
@@ -195,6 +195,11 @@ public StartEditorServicesCommand()
         [Parameter]
         public string StartupBanner { get; set; }
 
+        /// <summary>
+        /// Compatibility to store the currently supported PSESLogLevel Enum Value
+        /// </summary>
+        private PsesLogLevel _psesLogLevel = PsesLogLevel.Warning;
+
 #pragma warning disable IDE0022
         protected override void BeginProcessing()
         {
@@ -218,7 +223,7 @@ protected override void BeginProcessing()
         [System.Diagnostics.CodeAnalysis.SuppressMessage("Usage", "VSTHRD002:Avoid problematic synchronous waits", Justification = "We have to wait here, it's the whole program.")]
         protected override void EndProcessing()
         {
-            _logger.Log(PsesLogLevel.Diagnostic, "Beginning EndProcessing block");
+            _logger.Log(PsesLogLevel.Trace, "Beginning EndProcessing block");
             try
             {
                 // First try to remove PSReadLine to decomplicate startup
@@ -229,7 +234,7 @@ protected override void EndProcessing()
                 EditorServicesConfig editorServicesConfig = CreateConfigObject();
 
                 using EditorServicesLoader psesLoader = EditorServicesLoader.Create(_logger, editorServicesConfig, SessionDetailsPath, _loggerUnsubscribers);
-                _logger.Log(PsesLogLevel.Verbose, "Loading EditorServices");
+                _logger.Log(PsesLogLevel.Debug, "Loading EditorServices");
                 // Synchronously start editor services and wait here until it shuts down.
                 psesLoader.LoadAndRunEditorServicesAsync().GetAwaiter().GetResult();
             }
@@ -257,7 +262,25 @@ protected override void EndProcessing()
 
         private void StartLogging()
         {
-            _logger = new HostLogger(LogLevel);
+            bool isLegacyPsesLogLevel = false;
+            if (!Enum.TryParse(LogLevel, true, out _psesLogLevel))
+            {
+                // PSES used to have log levels that didn't match MEL levels, this is an adapter for those types and may eventually be removed once people migrate their settings.
+                isLegacyPsesLogLevel = true;
+                _psesLogLevel = LogLevel switch
+                {
+                    "Diagnostic" => PsesLogLevel.Trace,
+                    "Verbose" => PsesLogLevel.Debug,
+                    "Normal" => PsesLogLevel.Information,
+                    _ => PsesLogLevel.Trace
+                };
+            }
+
+            _logger = new HostLogger(_psesLogLevel);
+            if (isLegacyPsesLogLevel)
+            {
+                _logger.Log(PsesLogLevel.Warning, $"The log level '{LogLevel}' is deprecated and will be removed in a future release. Please update your settings or command line options to use one of the following options: 'Trace', 'Debug', 'Information', 'Warning', 'Error', 'Critical'.");
+            }
 
             // We need to not write log messages to Stdio
             // if it's being used as a protocol transport
@@ -281,7 +304,7 @@ private void StartLogging()
             IDisposable fileLoggerUnsubscriber = _logger.Subscribe(fileLogger);
             fileLogger.AddUnsubscriber(fileLoggerUnsubscriber);
             _loggerUnsubscribers.Add(fileLoggerUnsubscriber);
-            _logger.Log(PsesLogLevel.Diagnostic, "Logging started");
+            _logger.Log(PsesLogLevel.Trace, "Logging started");
         }
 
         // Sanitizes user input and ensures the directory is created.
@@ -299,7 +322,7 @@ private string GetLogDirPath()
 
         private void RemovePSReadLineForStartup()
         {
-            _logger.Log(PsesLogLevel.Verbose, "Removing PSReadLine");
+            _logger.Log(PsesLogLevel.Debug, "Removing PSReadLine");
             using SMA.PowerShell pwsh = SMA.PowerShell.Create(RunspaceMode.CurrentRunspace);
             bool hasPSReadLine = pwsh.AddCommand(new CmdletInfo(@"Microsoft.PowerShell.Core\Get-Module", typeof(GetModuleCommand)))
                 .AddParameter("Name", "PSReadLine")
@@ -314,13 +337,13 @@ private void RemovePSReadLineForStartup()
                     .AddParameter("Name", "PSReadLine")
                     .AddParameter("ErrorAction", "SilentlyContinue");
 
-                _logger.Log(PsesLogLevel.Verbose, "Removed PSReadLine");
+                _logger.Log(PsesLogLevel.Debug, "Removed PSReadLine");
             }
         }
 
         private EditorServicesConfig CreateConfigObject()
         {
-            _logger.Log(PsesLogLevel.Diagnostic, "Creating host configuration");
+            _logger.Log(PsesLogLevel.Trace, "Creating host configuration");
 
             string bundledModulesPath = BundledModulesPath;
             if (!Path.IsPathRooted(bundledModulesPath))
@@ -349,7 +372,7 @@ private EditorServicesConfig CreateConfigObject()
                 LogPath)
             {
                 FeatureFlags = FeatureFlags,
-                LogLevel = LogLevel,
+                LogLevel = _psesLogLevel,
                 ConsoleRepl = GetReplKind(),
                 UseNullPSHostUI = Stdio, // If Stdio is used we can't write anything else out
                 AdditionalModules = AdditionalModules,
@@ -399,31 +422,31 @@ private string GetProfilePathFromProfileObject(PSObject profileObject, ProfileUs
         // * On Linux or macOS on any version greater than or equal to 7
         private ConsoleReplKind GetReplKind()
         {
-            _logger.Log(PsesLogLevel.Diagnostic, "Determining REPL kind");
+            _logger.Log(PsesLogLevel.Trace, "Determining REPL kind");
 
             if (Stdio || !EnableConsoleRepl)
             {
-                _logger.Log(PsesLogLevel.Diagnostic, "REPL configured as None");
+                _logger.Log(PsesLogLevel.Trace, "REPL configured as None");
                 return ConsoleReplKind.None;
             }
 
             if (UseLegacyReadLine)
             {
-                _logger.Log(PsesLogLevel.Diagnostic, "REPL configured as Legacy");
+                _logger.Log(PsesLogLevel.Trace, "REPL configured as Legacy");
                 return ConsoleReplKind.LegacyReadLine;
             }
 
-            _logger.Log(PsesLogLevel.Diagnostic, "REPL configured as PSReadLine");
+            _logger.Log(PsesLogLevel.Trace, "REPL configured as PSReadLine");
             return ConsoleReplKind.PSReadLine;
         }
 
         private ITransportConfig GetLanguageServiceTransport()
         {
-            _logger.Log(PsesLogLevel.Diagnostic, "Configuring LSP transport");
+            _logger.Log(PsesLogLevel.Trace, "Configuring LSP transport");
 
             if (DebugServiceOnly)
             {
-                _logger.Log(PsesLogLevel.Diagnostic, "No LSP transport: PSES is debug only");
+                _logger.Log(PsesLogLevel.Trace, "No LSP transport: PSES is debug only");
                 return null;
             }
 
@@ -447,11 +470,11 @@ private ITransportConfig GetLanguageServiceTransport()
 
         private ITransportConfig GetDebugServiceTransport()
         {
-            _logger.Log(PsesLogLevel.Diagnostic, "Configuring debug transport");
+            _logger.Log(PsesLogLevel.Trace, "Configuring debug transport");
 
             if (LanguageServiceOnly)
             {
-                _logger.Log(PsesLogLevel.Diagnostic, "No Debug transport: PSES is language service only");
+                _logger.Log(PsesLogLevel.Trace, "No Debug transport: PSES is language service only");
                 return null;
             }
 
@@ -462,7 +485,7 @@ private ITransportConfig GetDebugServiceTransport()
                     return new StdioTransportConfig(_logger);
                 }
 
-                _logger.Log(PsesLogLevel.Diagnostic, "No debug transport: Transport is Stdio with debug disabled");
+                _logger.Log(PsesLogLevel.Trace, "No debug transport: Transport is Stdio with debug disabled");
                 return null;
             }
 

src/PowerShellEditorServices.Hosting/Configuration/EditorServicesConfig.cs

@@ -90,14 +90,14 @@ public EditorServicesConfig(
         public ConsoleReplKind ConsoleRepl { get; set; } = ConsoleReplKind.None;
 
         /// <summary>
-        /// Will suppress messages to PSHost (to prevent Stdio clobbering)        
+        /// Will suppress messages to PSHost (to prevent Stdio clobbering)
         /// </summary>
         public bool UseNullPSHostUI { get; set; }
 
         /// <summary>
-        /// The minimum log level to log events with.
+        /// The minimum log level to log events with. Defaults to warning but is usually overriden by the startup process.
         /// </summary>
-        public PsesLogLevel LogLevel { get; set; } = PsesLogLevel.Normal;
+        public PsesLogLevel LogLevel { get; set; } = PsesLogLevel.Warning;
 
         /// <summary>
         /// Configuration for the language server protocol transport to use.

src/PowerShellEditorServices.Hosting/Configuration/HostLogger.cs

@@ -12,20 +12,51 @@
 namespace Microsoft.PowerShell.EditorServices.Hosting
 {
     /// <summary>
-    /// User-facing log level for editor services configuration.
+    /// Log Level for HostLogger. This is a direct copy of LogLevel from Microsoft.Extensions.Logging, and will map to
+    /// MEL.LogLevel once MEL is bootstrapped, but we don't want to load any MEL assemblies until the Assembly Load
+    /// Context is set up.
     /// </summary>
-    /// <remarks>
-    /// The underlying values of this enum attempt to align to
-    /// <see cref="Microsoft.Extensions.Logging.LogLevel" />
-    /// </remarks>
     public enum PsesLogLevel
     {
-        Diagnostic = 0,
-        Verbose = 1,
-        Normal = 2,
+        /// <summary>
+        /// Logs that contain the most detailed messages. These messages may contain sensitive application data.
+        /// These messages are disabled by default and should never be enabled in a production environment.
+        /// </summary>
+        Trace = 0,
+
+        /// <summary>
+        /// Logs that are used for interactive investigation during development.  These logs should primarily contain
+        /// information useful for debugging and have no long-term value.
+        /// </summary>
+        Debug = 1,
+
+        /// <summary>
+        /// Logs that track the general flow of the application. These logs should have long-term value.
+        /// </summary>
+        Information = 2,
+
+        /// <summary>
+        /// Logs that highlight an abnormal or unexpected event in the application flow, but do not otherwise cause the
+        /// application execution to stop.
+        /// </summary>
         Warning = 3,
+
+        /// <summary>
+        /// Logs that highlight when the current flow of execution is stopped due to a failure. These should indicate a
+        /// failure in the current activity, not an application-wide failure.
+        /// </summary>
         Error = 4,
-        None = 5
+
+        /// <summary>
+        /// Logs that describe an unrecoverable application or system crash, or a catastrophic failure that requires
+        /// immediate attention.
+        /// </summary>
+        Critical = 5,
+
+        /// <summary>
+        /// Not used for writing log messages. Specifies that a logging category should not write any messages.
+        /// </summary>
+        None = 6,
     }
 
     /// <summary>
@@ -180,15 +211,9 @@ public void LogException(
     /// Since it's likely that the process will end when PSES shuts down,
     /// there's no good reason to need objects rather than writing directly to the host.
     /// </remarks>
-    internal class PSHostLogger : IObserver<(PsesLogLevel logLevel, string message)>
+    /// <param name="ui">The PowerShell host user interface object to log output to.</param>
+    internal class PSHostLogger(PSHostUserInterface ui) : IObserver<(PsesLogLevel logLevel, string message)>
     {
-        private readonly PSHostUserInterface _ui;
-
-        /// <summary>
-        /// Create a new PowerShell host logger.
-        /// </summary>
-        /// <param name="ui">The PowerShell host user interface object to log output to.</param>
-        public PSHostLogger(PSHostUserInterface ui) => _ui = ui;
 
         public void OnCompleted()
         {
@@ -200,35 +225,35 @@ public void OnCompleted()
 
         public void OnNext((PsesLogLevel logLevel, string message) value)
         {
-            switch (value.logLevel)
+            (PsesLogLevel logLevel, string message) = value;
+            switch (logLevel)
             {
-                case PsesLogLevel.Diagnostic:
-                    _ui.WriteDebugLine(value.message);
-                    return;
-
-                case PsesLogLevel.Verbose:
-                    _ui.WriteVerboseLine(value.message);
-                    return;
-
-                case PsesLogLevel.Normal:
-                    _ui.WriteLine(value.message);
-                    return;
-
+                case PsesLogLevel.Trace:
+                    ui.WriteDebugLine("[Trace] " + message);
+                    break;
+                case PsesLogLevel.Debug:
+                    ui.WriteDebugLine(message);
+                    break;
+                case PsesLogLevel.Information:
+                    ui.WriteVerboseLine(message);
+                    break;
                 case PsesLogLevel.Warning:
-                    _ui.WriteWarningLine(value.message);
-                    return;
-
+                    ui.WriteWarningLine(message);
+                    break;
                 case PsesLogLevel.Error:
-                    _ui.WriteErrorLine(value.message);
-                    return;
-
+                case PsesLogLevel.Critical:
+                    ui.WriteErrorLine(message);
+                    break;
                 default:
-                    _ui.WriteLine(value.message);
-                    return;
+                    ui.WriteDebugLine("UNKNOWN:" + message);
+                    break;
             }
         }
     }
 
+    /// <summary>
+    /// A simple log sink that logs to a stream, typically used to log to a file.
+    /// </summary>
     internal class StreamLogger : IObserver<(PsesLogLevel logLevel, string message)>, IDisposable
     {
         public static StreamLogger CreateWithNewFile(string path)
@@ -283,9 +308,7 @@ public void OnCompleted()
             }
 
             _cancellationSource.Cancel();
-
             _writerThread.Join();
-
             _unsubscriber.Dispose();
             _fileWriter.Flush();
             _fileWriter.Close();
@@ -298,29 +321,17 @@ public void OnCompleted()
 
         public void OnNext((PsesLogLevel logLevel, string message) value)
         {
-            string message = null;
-            switch (value.logLevel)
+            string message = value.logLevel switch
             {
-                case PsesLogLevel.Diagnostic:
-                    message = $"[DBG]: {value.message}";
-                    break;
-
-                case PsesLogLevel.Verbose:
-                    message = $"[VRB]: {value.message}";
-                    break;
-
-                case PsesLogLevel.Normal:
-                    message = $"[INF]: {value.message}";
-                    break;
-
-                case PsesLogLevel.Warning:
-                    message = $"[WRN]: {value.message}";
-                    break;
-
-                case PsesLogLevel.Error:
-                    message = $"[ERR]: {value.message}";
-                    break;
-            }
+                // String interpolation often considered a logging sin is OK here because our filtering happens before.
+                PsesLogLevel.Trace => $"[TRC]: {value.message}",
+                PsesLogLevel.Debug => $"[DBG]: {value.message}",
+                PsesLogLevel.Information => $"[INF]: {value.message}",
+                PsesLogLevel.Warning => $"[WRN]: {value.message}",
+                PsesLogLevel.Error => $"[ERR]: {value.message}",
+                PsesLogLevel.Critical => $"[CRT]: {value.message}",
+                _ => value.message,
+            };
 
             _messageQueue.Add(message);
         }