diff --git a/README.md b/README.md index 6dec799a5..440150dce 100644 --- a/README.md +++ b/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" diff --git a/src/PowerShellEditorServices.Hosting/Commands/StartEditorServicesCommand.cs b/src/PowerShellEditorServices.Hosting/Commands/StartEditorServicesCommand.cs index e74ca572c..6f2ec8851 100644 --- a/src/PowerShellEditorServices.Hosting/Commands/StartEditorServicesCommand.cs +++ b/src/PowerShellEditorServices.Hosting/Commands/StartEditorServicesCommand.cs @@ -138,7 +138,7 @@ public StartEditorServicesCommand() /// The minimum log level that should be emitted. /// [Parameter] - public PsesLogLevel LogLevel { get; set; } = PsesLogLevel.Normal; + public string LogLevel { get; set; } = PsesLogLevel.Warning.ToString(); /// /// Paths to additional PowerShell modules to be imported at startup. @@ -195,6 +195,11 @@ public StartEditorServicesCommand() [Parameter] public string StartupBanner { get; set; } + /// + /// Compatibility to store the currently supported PSESLogLevel Enum Value + /// + 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; } diff --git a/src/PowerShellEditorServices.Hosting/Configuration/EditorServicesConfig.cs b/src/PowerShellEditorServices.Hosting/Configuration/EditorServicesConfig.cs index b2e683a2f..66bc7b1de 100644 --- a/src/PowerShellEditorServices.Hosting/Configuration/EditorServicesConfig.cs +++ b/src/PowerShellEditorServices.Hosting/Configuration/EditorServicesConfig.cs @@ -90,14 +90,14 @@ public EditorServicesConfig( public ConsoleReplKind ConsoleRepl { get; set; } = ConsoleReplKind.None; /// - /// Will suppress messages to PSHost (to prevent Stdio clobbering) + /// Will suppress messages to PSHost (to prevent Stdio clobbering) /// public bool UseNullPSHostUI { get; set; } /// - /// 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. /// - public PsesLogLevel LogLevel { get; set; } = PsesLogLevel.Normal; + public PsesLogLevel LogLevel { get; set; } = PsesLogLevel.Warning; /// /// Configuration for the language server protocol transport to use. diff --git a/src/PowerShellEditorServices.Hosting/Configuration/HostLogger.cs b/src/PowerShellEditorServices.Hosting/Configuration/HostLogger.cs index 37893bce1..bebb7e2b9 100644 --- a/src/PowerShellEditorServices.Hosting/Configuration/HostLogger.cs +++ b/src/PowerShellEditorServices.Hosting/Configuration/HostLogger.cs @@ -12,20 +12,51 @@ namespace Microsoft.PowerShell.EditorServices.Hosting { /// - /// 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. /// - /// - /// The underlying values of this enum attempt to align to - /// - /// public enum PsesLogLevel { - Diagnostic = 0, - Verbose = 1, - Normal = 2, + /// + /// 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. + /// + Trace = 0, + + /// + /// Logs that are used for interactive investigation during development. These logs should primarily contain + /// information useful for debugging and have no long-term value. + /// + Debug = 1, + + /// + /// Logs that track the general flow of the application. These logs should have long-term value. + /// + Information = 2, + + /// + /// Logs that highlight an abnormal or unexpected event in the application flow, but do not otherwise cause the + /// application execution to stop. + /// Warning = 3, + + /// + /// 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. + /// Error = 4, - None = 5 + + /// + /// Logs that describe an unrecoverable application or system crash, or a catastrophic failure that requires + /// immediate attention. + /// + Critical = 5, + + /// + /// Not used for writing log messages. Specifies that a logging category should not write any messages. + /// + None = 6, } /// @@ -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. /// - internal class PSHostLogger : IObserver<(PsesLogLevel logLevel, string message)> + /// The PowerShell host user interface object to log output to. + internal class PSHostLogger(PSHostUserInterface ui) : IObserver<(PsesLogLevel logLevel, string message)> { - private readonly PSHostUserInterface _ui; - - /// - /// Create a new PowerShell host logger. - /// - /// The PowerShell host user interface object to log output to. - 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; } } } + /// + /// A simple log sink that logs to a stream, typically used to log to a file. + /// 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); } diff --git a/src/PowerShellEditorServices.Hosting/Configuration/SessionFileWriter.cs b/src/PowerShellEditorServices.Hosting/Configuration/SessionFileWriter.cs index c5f351f91..bca1acd5e 100644 --- a/src/PowerShellEditorServices.Hosting/Configuration/SessionFileWriter.cs +++ b/src/PowerShellEditorServices.Hosting/Configuration/SessionFileWriter.cs @@ -63,7 +63,7 @@ public SessionFileWriter(HostLogger logger, string sessionFilePath, Version powe /// The reason for the startup failure. public void WriteSessionFailure(string reason) { - _logger.Log(PsesLogLevel.Diagnostic, "Writing session failure"); + _logger.Log(PsesLogLevel.Trace, "Writing session failure"); Dictionary sessionObject = new() { @@ -81,7 +81,7 @@ public void WriteSessionFailure(string reason) /// The debug adapter transport configuration. public void WriteSessionStarted(ITransportConfig languageServiceTransport, ITransportConfig debugAdapterTransport) { - _logger.Log(PsesLogLevel.Diagnostic, "Writing session started"); + _logger.Log(PsesLogLevel.Trace, "Writing session started"); Dictionary sessionObject = new() { @@ -142,7 +142,7 @@ private void WriteSessionObject(Dictionary sessionObject) File.WriteAllText(_sessionFilePath, content, s_sessionFileEncoding); } - _logger.Log(PsesLogLevel.Verbose, $"Session file written to {_sessionFilePath} with content:\n{content}"); + _logger.Log(PsesLogLevel.Debug, $"Session file written to {_sessionFilePath} with content:\n{content}"); } } } diff --git a/src/PowerShellEditorServices.Hosting/Configuration/TransportConfig.cs b/src/PowerShellEditorServices.Hosting/Configuration/TransportConfig.cs index be763737c..db64a27a7 100644 --- a/src/PowerShellEditorServices.Hosting/Configuration/TransportConfig.cs +++ b/src/PowerShellEditorServices.Hosting/Configuration/TransportConfig.cs @@ -53,7 +53,7 @@ public sealed class StdioTransportConfig : ITransportConfig public Task<(Stream inStream, Stream outStream)> ConnectStreamsAsync() { - _logger.Log(PsesLogLevel.Diagnostic, "Connecting stdio streams"); + _logger.Log(PsesLogLevel.Trace, "Connecting stdio streams"); return Task.FromResult((Console.OpenStandardInput(), Console.OpenStandardOutput())); } } @@ -102,11 +102,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.Trace, "Creating named pipe"); NamedPipeServerStream namedPipe = NamedPipeUtils.CreateNamedPipe(_pipeName, PipeDirection.InOut); - _logger.Log(PsesLogLevel.Diagnostic, "Waiting for named pipe connection"); + _logger.Log(PsesLogLevel.Trace, "Waiting for named pipe connection"); await namedPipe.WaitForConnectionAsync().ConfigureAwait(false); - _logger.Log(PsesLogLevel.Diagnostic, "Named pipe connected"); + _logger.Log(PsesLogLevel.Trace, "Named pipe connected"); return (namedPipe, namedPipe); } } @@ -173,18 +173,18 @@ private SimplexNamedPipeTransportConfig(HostLogger logger, string inPipeName, st public async Task<(Stream inStream, Stream outStream)> ConnectStreamsAsync() { - _logger.Log(PsesLogLevel.Diagnostic, "Starting in pipe connection"); + _logger.Log(PsesLogLevel.Trace, "Starting in pipe connection"); NamedPipeServerStream inPipe = NamedPipeUtils.CreateNamedPipe(_inPipeName, PipeDirection.InOut); Task inPipeConnected = inPipe.WaitForConnectionAsync(); - _logger.Log(PsesLogLevel.Diagnostic, "Starting out pipe connection"); + _logger.Log(PsesLogLevel.Trace, "Starting out pipe connection"); NamedPipeServerStream outPipe = NamedPipeUtils.CreateNamedPipe(_outPipeName, PipeDirection.Out); Task outPipeConnected = outPipe.WaitForConnectionAsync(); - _logger.Log(PsesLogLevel.Diagnostic, "Wating for pipe connections"); + _logger.Log(PsesLogLevel.Trace, "Wating for pipe connections"); await Task.WhenAll(inPipeConnected, outPipeConnected).ConfigureAwait(false); - _logger.Log(PsesLogLevel.Diagnostic, "Simplex named pipe transport connected"); + _logger.Log(PsesLogLevel.Trace, "Simplex named pipe transport connected"); return (inPipe, outPipe); } } diff --git a/src/PowerShellEditorServices.Hosting/EditorServicesLoader.cs b/src/PowerShellEditorServices.Hosting/EditorServicesLoader.cs index cf5c45c75..eea23353c 100644 --- a/src/PowerShellEditorServices.Hosting/EditorServicesLoader.cs +++ b/src/PowerShellEditorServices.Hosting/EditorServicesLoader.cs @@ -70,20 +70,20 @@ public static EditorServicesLoader Create( Version powerShellVersion = GetPSVersion(); SessionFileWriter sessionFileWriter = new(logger, sessionDetailsPath, powerShellVersion); - logger.Log(PsesLogLevel.Diagnostic, "Session file writer created"); + logger.Log(PsesLogLevel.Trace, "Session file writer created"); #if CoreCLR // In .NET Core, we add an event here to redirect dependency loading to the new AssemblyLoadContext we load PSES' dependencies into - logger.Log(PsesLogLevel.Verbose, "Adding AssemblyResolve event handler for new AssemblyLoadContext dependency loading"); + logger.Log(PsesLogLevel.Debug, "Adding AssemblyResolve event handler for new AssemblyLoadContext dependency loading"); PsesLoadContext psesLoadContext = new(s_psesDependencyDirPath); - if (hostConfig.LogLevel == PsesLogLevel.Diagnostic) + if (hostConfig.LogLevel == PsesLogLevel.Trace) { AppDomain.CurrentDomain.AssemblyLoad += (object sender, AssemblyLoadEventArgs args) => { logger.Log( - PsesLogLevel.Diagnostic, + PsesLogLevel.Trace, $"Loaded into load context {AssemblyLoadContext.GetLoadContext(args.LoadedAssembly)}: {args.LoadedAssembly}"); }; } @@ -91,9 +91,9 @@ public static EditorServicesLoader Create( AssemblyLoadContext.Default.Resolving += (AssemblyLoadContext _, AssemblyName asmName) => { #if ASSEMBLY_LOAD_STACKTRACE - logger.Log(PsesLogLevel.Diagnostic, $"Assembly resolve event fired for {asmName}. Stacktrace:\n{new StackTrace()}"); + logger.Log(PsesLogLevel.Trace, $"Assembly resolve event fired for {asmName}. Stacktrace:\n{new StackTrace()}"); #else - logger.Log(PsesLogLevel.Diagnostic, $"Assembly resolve event fired for {asmName}"); + logger.Log(PsesLogLevel.Trace, $"Assembly resolve event fired for {asmName}"); #endif // We only want the Editor Services DLL; the new ALC will lazily load its dependencies automatically @@ -104,15 +104,15 @@ public static EditorServicesLoader Create( string asmPath = Path.Combine(s_psesDependencyDirPath, $"{asmName.Name}.dll"); - logger.Log(PsesLogLevel.Verbose, "Loading PSES DLL using new assembly load context"); + logger.Log(PsesLogLevel.Debug, "Loading PSES DLL using new assembly load context"); return psesLoadContext.LoadFromAssemblyPath(asmPath); }; #else // In .NET Framework we add an event here to redirect dependency loading in the current AppDomain for PSES' dependencies - logger.Log(PsesLogLevel.Verbose, "Adding AssemblyResolve event handler for dependency loading"); + logger.Log(PsesLogLevel.Debug, "Adding AssemblyResolve event handler for dependency loading"); - if (hostConfig.LogLevel == PsesLogLevel.Diagnostic) + if (hostConfig.LogLevel == PsesLogLevel.Trace) { AppDomain.CurrentDomain.AssemblyLoad += (object sender, AssemblyLoadEventArgs args) => { @@ -122,7 +122,7 @@ public static EditorServicesLoader Create( } logger.Log( - PsesLogLevel.Diagnostic, + PsesLogLevel.Trace, $"Loaded '{args.LoadedAssembly.GetName()}' from '{args.LoadedAssembly.Location}'"); }; } @@ -131,9 +131,9 @@ public static EditorServicesLoader Create( AppDomain.CurrentDomain.AssemblyResolve += (object sender, ResolveEventArgs args) => { #if ASSEMBLY_LOAD_STACKTRACE - logger.Log(PsesLogLevel.Diagnostic, $"Assembly resolve event fired for {args.Name}. Stacktrace:\n{new StackTrace()}"); + logger.Log(PsesLogLevel.Trace, $"Assembly resolve event fired for {args.Name}. Stacktrace:\n{new StackTrace()}"); #else - logger.Log(PsesLogLevel.Diagnostic, $"Assembly resolve event fired for {args.Name}"); + logger.Log(PsesLogLevel.Trace, $"Assembly resolve event fired for {args.Name}"); #endif AssemblyName asmName = new(args.Name); @@ -143,7 +143,7 @@ public static EditorServicesLoader Create( string baseDirAsmPath = Path.Combine(s_psesBaseDirPath, dllName); if (File.Exists(baseDirAsmPath)) { - logger.Log(PsesLogLevel.Diagnostic, $"Loading {args.Name} from PSES base dir into LoadFile context"); + logger.Log(PsesLogLevel.Trace, $"Loading {args.Name} from PSES base dir into LoadFile context"); return Assembly.LoadFile(baseDirAsmPath); } @@ -151,7 +151,7 @@ public static EditorServicesLoader Create( string asmPath = Path.Combine(s_psesDependencyDirPath, dllName); if (File.Exists(asmPath)) { - logger.Log(PsesLogLevel.Diagnostic, $"Loading {args.Name} from PSES dependency dir into LoadFile context"); + logger.Log(PsesLogLevel.Trace, $"Loading {args.Name} from PSES dependency dir into LoadFile context"); return Assembly.LoadFile(asmPath); } @@ -212,10 +212,10 @@ public Task LoadAndRunEditorServicesAsync() ValidateConfiguration(); // Method with no implementation that forces the PSES assembly to load, triggering an AssemblyResolve event - _logger.Log(PsesLogLevel.Verbose, "Loading PowerShell Editor Services"); + _logger.Log(PsesLogLevel.Information, "Loading PowerShell Editor Services Assemblies"); LoadEditorServices(); - _logger.Log(PsesLogLevel.Verbose, "Starting EditorServices"); + _logger.Log(PsesLogLevel.Information, "Starting PowerShell Editor Services"); _editorServicesRunner = new EditorServicesRunner(_logger, _hostConfig, _sessionFileWriter, _loggersToUnsubscribe); @@ -225,7 +225,7 @@ public Task LoadAndRunEditorServicesAsync() public void Dispose() { - _logger.Log(PsesLogLevel.Diagnostic, "Loader disposed"); + _logger.Log(PsesLogLevel.Trace, "Loader disposed"); _editorServicesRunner?.Dispose(); // TODO: @@ -242,7 +242,7 @@ private void CheckPowerShellVersion() { PSLanguageMode languageMode = Runspace.DefaultRunspace.SessionStateProxy.LanguageMode; - _logger.Log(PsesLogLevel.Verbose, $@" + _logger.Log(PsesLogLevel.Trace, $@" == PowerShell Details == - PowerShell version: {_powerShellVersion} - Language mode: {languageMode} @@ -261,7 +261,7 @@ private void CheckPowerShellVersion() #if !CoreCLR private void CheckDotNetVersion() { - _logger.Log(PsesLogLevel.Verbose, "Checking that .NET Framework version is at least 4.8"); + _logger.Log(PsesLogLevel.Debug, "Checking that .NET Framework version is at least 4.8"); using RegistryKey key = Registry.LocalMachine.OpenSubKey(@"SOFTWARE\Microsoft\Net Framework Setup\NDP\v4\Full"); object netFxValue = key?.GetValue("Release"); if (netFxValue == null || netFxValue is not int netFxVersion) @@ -269,7 +269,7 @@ private void CheckDotNetVersion() return; } - _logger.Log(PsesLogLevel.Verbose, $".NET registry version: {netFxVersion}"); + _logger.Log(PsesLogLevel.Debug, $".NET registry version: {netFxVersion}"); if (netFxVersion < Net48Version) { @@ -283,26 +283,26 @@ private void UpdatePSModulePath() { if (string.IsNullOrEmpty(_hostConfig.BundledModulePath)) { - _logger.Log(PsesLogLevel.Diagnostic, "BundledModulePath not set, skipping"); + _logger.Log(PsesLogLevel.Trace, "BundledModulePath not set, skipping"); return; } string psModulePath = Environment.GetEnvironmentVariable("PSModulePath").TrimEnd(Path.PathSeparator); if ($"{psModulePath}{Path.PathSeparator}".Contains($"{_hostConfig.BundledModulePath}{Path.PathSeparator}")) { - _logger.Log(PsesLogLevel.Diagnostic, "BundledModulePath already set, skipping"); + _logger.Log(PsesLogLevel.Trace, "BundledModulePath already set, skipping"); return; } psModulePath = $"{psModulePath}{Path.PathSeparator}{_hostConfig.BundledModulePath}"; Environment.SetEnvironmentVariable("PSModulePath", psModulePath); - _logger.Log(PsesLogLevel.Verbose, $"Updated PSModulePath to: '{psModulePath}'"); + _logger.Log(PsesLogLevel.Trace, $"Updated PSModulePath to: '{psModulePath}'"); } private void LogHostInformation() { - _logger.Log(PsesLogLevel.Verbose, $"PID: {System.Diagnostics.Process.GetCurrentProcess().Id}"); + _logger.Log(PsesLogLevel.Trace, $"PID: {System.Diagnostics.Process.GetCurrentProcess().Id}"); - _logger.Log(PsesLogLevel.Verbose, $@" + _logger.Log(PsesLogLevel.Debug, $@" == Build Details == - Editor Services version: {BuildInfo.BuildVersion} - Build origin: {BuildInfo.BuildOrigin} @@ -310,7 +310,7 @@ private void LogHostInformation() - Build time: {BuildInfo.BuildTime} "); - _logger.Log(PsesLogLevel.Verbose, $@" + _logger.Log(PsesLogLevel.Debug, $@" == Host Startup Configuration Details == - Host name: {_hostConfig.HostInfo.Name} - Host version: {_hostConfig.HostInfo.Version} @@ -333,14 +333,14 @@ private void LogHostInformation() + CurrentUserCurrentHost: {_hostConfig.ProfilePaths.CurrentUserCurrentHost ?? ""} "); - _logger.Log(PsesLogLevel.Verbose, $@" + _logger.Log(PsesLogLevel.Debug, $@" == Console Details == - Console input encoding: {Console.InputEncoding.EncodingName} - Console output encoding: {Console.OutputEncoding.EncodingName} - PowerShell output encoding: {GetPSOutputEncoding()} "); - _logger.Log(PsesLogLevel.Verbose, $@" + _logger.Log(PsesLogLevel.Debug, $@" == Environment Details == - OS description: {RuntimeInformation.OSDescription} - OS architecture: {RuntimeInformation.OSArchitecture} @@ -359,7 +359,7 @@ private static string GetPSOutputEncoding() [System.Diagnostics.CodeAnalysis.SuppressMessage("Usage", "CA2208:Instantiate argument exceptions correctly", Justification = "Checking user-defined configuration")] private void ValidateConfiguration() { - _logger.Log(PsesLogLevel.Diagnostic, "Validating configuration"); + _logger.Log(PsesLogLevel.Debug, "Validating configuration"); bool lspUsesStdio = _hostConfig.LanguageServiceTransport is StdioTransportConfig; bool debugUsesStdio = _hostConfig.DebugServiceTransport is StdioTransportConfig; diff --git a/src/PowerShellEditorServices.Hosting/Internal/EditorServicesRunner.cs b/src/PowerShellEditorServices.Hosting/Internal/EditorServicesRunner.cs index 040a9ec78..1c9de268c 100644 --- a/src/PowerShellEditorServices.Hosting/Internal/EditorServicesRunner.cs +++ b/src/PowerShellEditorServices.Hosting/Internal/EditorServicesRunner.cs @@ -60,11 +60,11 @@ public Task RunUntilShutdown() Task runAndAwaitShutdown = CreateEditorServicesAndRunUntilShutdown(); // Now write the session file - _logger.Log(PsesLogLevel.Diagnostic, "Writing session file"); + _logger.Log(PsesLogLevel.Trace, "Writing session file"); _sessionFileWriter.WriteSessionStarted(_config.LanguageServiceTransport, _config.DebugServiceTransport); // Finally, wait for Editor Services to shut down - _logger.Log(PsesLogLevel.Diagnostic, "Waiting on PSES run/shutdown"); + _logger.Log(PsesLogLevel.Debug, "Waiting on PSES run/shutdown"); return runAndAwaitShutdown; } @@ -124,7 +124,7 @@ private async Task CreateEditorServicesAndRunUntilShutdown() { try { - _logger.Log(PsesLogLevel.Diagnostic, "Creating/running editor services"); + _logger.Log(PsesLogLevel.Debug, "Creating/running editor services"); bool creatingLanguageServer = _config.LanguageServiceTransport != null; bool creatingDebugServer = _config.DebugServiceTransport != null; @@ -140,6 +140,9 @@ private async Task CreateEditorServicesAndRunUntilShutdown() return; } + _logger.Log(PsesLogLevel.Information, "PSES Startup Completed. Starting Language Server."); + _logger.Log(PsesLogLevel.Information, "Please check the LSP log file in your client for further messages. In VSCode, this is the 'PowerShell' output pane"); + // We want LSP and maybe debugging // To do that we: // - Create the LSP server @@ -149,7 +152,6 @@ private async Task CreateEditorServicesAndRunUntilShutdown() // - Wait for the LSP server to finish // Unsubscribe the host logger here so that the Extension Terminal is not polluted with input after the first prompt - _logger.Log(PsesLogLevel.Verbose, "Starting server, deregistering host logger and registering shutdown listener"); if (_loggersToUnsubscribe != null) { foreach (IDisposable loggerToUnsubscribe in _loggersToUnsubscribe) @@ -193,11 +195,11 @@ private async Task CreateEditorServicesAndRunUntilShutdown() private async Task RunTempDebugSessionAsync(HostStartupInfo hostDetails) { - _logger.Log(PsesLogLevel.Diagnostic, "Running temp debug session"); + _logger.Log(PsesLogLevel.Information, "Starting temporary debug session"); PsesDebugServer debugServer = await CreateDebugServerForTempSessionAsync(hostDetails).ConfigureAwait(false); - _logger.Log(PsesLogLevel.Verbose, "Debug server created"); + _logger.Log(PsesLogLevel.Debug, "Debug server created"); await debugServer.StartAsync().ConfigureAwait(false); - _logger.Log(PsesLogLevel.Verbose, "Debug server started"); + _logger.Log(PsesLogLevel.Debug, "Debug server started"); await debugServer.WaitForShutdown().ConfigureAwait(false); } @@ -210,47 +212,47 @@ private async Task StartDebugServer(Task debugServerCreation) // To do this, we set an event to allow it to create a new debug server as its session ends if (!_alreadySubscribedDebug) { - _logger.Log(PsesLogLevel.Diagnostic, "Subscribing debug server for session ended event"); + _logger.Log(PsesLogLevel.Trace, "Subscribing debug server for session ended event"); _alreadySubscribedDebug = true; debugServer.SessionEnded += DebugServer_OnSessionEnded; } - _logger.Log(PsesLogLevel.Diagnostic, "Starting debug server"); + _logger.Log(PsesLogLevel.Trace, "Starting debug server"); await debugServer.StartAsync().ConfigureAwait(false); } private Task RestartDebugServerAsync(PsesDebugServer debugServer) { - _logger.Log(PsesLogLevel.Diagnostic, "Restarting debug server"); + _logger.Log(PsesLogLevel.Debug, "Restarting debug server"); Task debugServerCreation = RecreateDebugServerAsync(debugServer); return StartDebugServer(debugServerCreation); } private async Task CreateLanguageServerAsync(HostStartupInfo hostDetails) { - _logger.Log(PsesLogLevel.Verbose, $"Creating LSP transport with endpoint {_config.LanguageServiceTransport.EndpointDetails}"); + _logger.Log(PsesLogLevel.Trace, $"Creating LSP transport with endpoint {_config.LanguageServiceTransport.EndpointDetails}"); (Stream inStream, Stream outStream) = await _config.LanguageServiceTransport.ConnectStreamsAsync().ConfigureAwait(false); - _logger.Log(PsesLogLevel.Diagnostic, "Creating language server"); + _logger.Log(PsesLogLevel.Debug, "Creating language server"); return _serverFactory.CreateLanguageServer(inStream, outStream, hostDetails); } private async Task CreateDebugServerWithLanguageServerAsync(PsesLanguageServer languageServer) { - _logger.Log(PsesLogLevel.Verbose, $"Creating debug adapter transport with endpoint {_config.DebugServiceTransport.EndpointDetails}"); + _logger.Log(PsesLogLevel.Trace, $"Creating debug adapter transport with endpoint {_config.DebugServiceTransport.EndpointDetails}"); (Stream inStream, Stream outStream) = await _config.DebugServiceTransport.ConnectStreamsAsync().ConfigureAwait(false); - _logger.Log(PsesLogLevel.Diagnostic, "Creating debug adapter"); + _logger.Log(PsesLogLevel.Debug, "Creating debug adapter"); return _serverFactory.CreateDebugServerWithLanguageServer(inStream, outStream, languageServer); } private async Task RecreateDebugServerAsync(PsesDebugServer debugServer) { - _logger.Log(PsesLogLevel.Diagnostic, "Recreating debug adapter transport"); + _logger.Log(PsesLogLevel.Debug, "Recreating debug adapter transport"); (Stream inStream, Stream outStream) = await _config.DebugServiceTransport.ConnectStreamsAsync().ConfigureAwait(false); - _logger.Log(PsesLogLevel.Diagnostic, "Recreating debug adapter"); + _logger.Log(PsesLogLevel.Debug, "Recreating debug adapter"); return _serverFactory.RecreateDebugServer(inStream, outStream, debugServer); } @@ -263,7 +265,7 @@ private async Task CreateDebugServerForTempSessionAsync(HostSta private HostStartupInfo CreateHostStartupInfo() { - _logger.Log(PsesLogLevel.Diagnostic, "Creating startup info object"); + _logger.Log(PsesLogLevel.Debug, "Creating startup info object"); ProfilePathInfo profilePaths = null; if (_config.ProfilePaths.AllUsersAllHosts != null @@ -288,7 +290,7 @@ private HostStartupInfo CreateHostStartupInfo() _config.AdditionalModules, _config.InitialSessionState, _config.LogPath, - (int)_config.LogLevel, + (int)_config.LogLevel, //This maps to MEL log levels, we use int so this is easily supplied externally. consoleReplEnabled: _config.ConsoleRepl != ConsoleReplKind.None, useNullPSHostUI: _config.UseNullPSHostUI, usesLegacyReadLine: _config.ConsoleRepl == ConsoleReplKind.LegacyReadLine, @@ -308,7 +310,7 @@ private void WriteStartupBanner() [System.Diagnostics.CodeAnalysis.SuppressMessage("Usage", "VSTHRD110:Observe result of async calls", Justification = "Intentionally fire and forget.")] private void DebugServer_OnSessionEnded(object sender, EventArgs args) { - _logger.Log(PsesLogLevel.Verbose, "Debug session ended, restarting debug service..."); + _logger.Log(PsesLogLevel.Debug, "Debug session ended, restarting debug service..."); PsesDebugServer oldServer = (PsesDebugServer)sender; oldServer.Dispose(); _alreadySubscribedDebug = false; diff --git a/src/PowerShellEditorServices/Logging/HostLoggerAdapter.cs b/src/PowerShellEditorServices/Logging/HostLoggerAdapter.cs index 0c10980dd..9ffe3c950 100644 --- a/src/PowerShellEditorServices/Logging/HostLoggerAdapter.cs +++ b/src/PowerShellEditorServices/Logging/HostLoggerAdapter.cs @@ -13,12 +13,14 @@ internal class HostLoggerAdapter(ILogger logger) : IObserver<(int logLevel, stri { public void OnError(Exception error) => logger.LogError(error, "Error in host logger"); + /// + /// Log the message received from the host into MEL. + /// public void OnNext((int logLevel, string message) value) => logger.Log((LogLevel)value.logLevel, value.message); public void OnCompleted() { // Nothing to do; we simply don't send more log messages } - } } diff --git a/src/PowerShellEditorServices/Logging/LanguageServerLogger.cs b/src/PowerShellEditorServices/Logging/LanguageServerLogger.cs new file mode 100644 index 000000000..0b22ddd95 --- /dev/null +++ b/src/PowerShellEditorServices/Logging/LanguageServerLogger.cs @@ -0,0 +1,185 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. +#nullable enable + +using System; +using System.Collections.Generic; +using System.Linq; +using System.Reactive.Disposables; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; +using Newtonsoft.Json; +using OmniSharp.Extensions.LanguageServer.Protocol.Models; +using OmniSharp.Extensions.LanguageServer.Protocol.Server; +using OmniSharp.Extensions.LanguageServer.Protocol.Window; + +namespace Microsoft.PowerShell.EditorServices.Logging; + +internal class LanguageServerLogger(ILanguageServerFacade responseRouter, string categoryName) : ILogger +{ + public IDisposable? BeginScope(TState state) where TState : notnull => Disposable.Empty; + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log( + LogLevel logLevel, EventId eventId, TState state, Exception? exception, + Func formatter + ) + { + if (responseRouter is null) + { + throw new InvalidOperationException("Log received without a valid responseRouter dependency. This is a bug, please report it."); + } + // Any Omnisharp or trace logs are directly LSP protocol related and we send them to the trace channel + // TODO: Dynamically adjust if SetTrace is reported + // BUG: There is an omnisharp filter incorrectly filtering this. As a workaround we will use logMessage for now. + // https://github.com/OmniSharp/csharp-language-server-protocol/issues/1390 + // + // { + // // Everything with omnisharp goes directly to trace + // string eventMessage = string.Empty; + // string exceptionName = exception?.GetType().Name ?? string.Empty; + // if (eventId.Name is not null) + // { + // eventMessage = eventId.Id == 0 ? eventId.Name : $"{eventId.Name} [{eventId.Id}] "; + // } + + // LogTraceParams trace = new() + // { + // Message = categoryName + ": " + eventMessage + exceptionName, + // Verbose = formatter(state, exception) + // }; + // responseRouter.Client.LogTrace(trace); + // } + + // Drop all omnisharp messages to trace. This isn't a MEL filter because it's specific only to this provider. + if (categoryName.StartsWith("OmniSharp.", StringComparison.OrdinalIgnoreCase)) + { + logLevel = LogLevel.Trace; + } + + (MessageType messageType, string messagePrepend) = GetMessageInfo(logLevel); + + // The vscode-languageserver-node client doesn't support LogOutputChannel as of 2024-11-24 and also doesn't + // provide a way to middleware the incoming log messages, so our output channel has no idea what the logLevel + // is. As a workaround, we send the severity in-line with the message for the client to parse. + // BUG: https://github.com/microsoft/vscode-languageserver-node/issues/1116 + if (responseRouter.Client?.ClientSettings?.ClientInfo?.Name == "Visual Studio Code") + { + messagePrepend = logLevel switch + { + LogLevel.Critical => "CRITICAL: ", + LogLevel.Error => "", + LogLevel.Warning => "", + LogLevel.Information => "", + LogLevel.Debug => "", + LogLevel.Trace => "", + _ => string.Empty + }; + + // The vscode formatter prepends some extra stuff to Info specifically, so we drop Info to Log, but it will get logged correctly on the other side thanks to our inline indicator that our custom parser on the other side will pick up and process. + if (messageType == MessageType.Info) + { + messageType = MessageType.Log; + } + } + + LogMessageParams logMessage = new() + { + Type = messageType, + Message = messagePrepend + categoryName + ": " + formatter(state, exception) + + (exception != null ? " - " + exception : "") + " | " + + //Hopefully this isn't too expensive in the long run + FormatState(state, exception) + }; + responseRouter.Window.Log(logMessage); + } + + /// + /// Formats the state object into a string for logging. + /// + /// + /// This is copied from Omnisharp, we can probably do better. + /// + /// + /// + /// + /// + private static string FormatState(TState state, Exception? exception) + { + return state switch + { + IEnumerable> dict => string.Join(" ", dict.Where(z => z.Key != "{OriginalFormat}").Select(z => $"{z.Key}='{z.Value}'")), + _ => JsonConvert.SerializeObject(state).Replace("\"", "'") + }; + } + + /// + /// Maps MEL log levels to LSP message types + /// + private static (MessageType messageType, string messagePrepend) GetMessageInfo(LogLevel logLevel) + => logLevel switch + { + LogLevel.Critical => (MessageType.Error, "Critical: "), + LogLevel.Error => (MessageType.Error, string.Empty), + LogLevel.Warning => (MessageType.Warning, string.Empty), + LogLevel.Information => (MessageType.Info, string.Empty), + LogLevel.Debug => (MessageType.Log, string.Empty), + LogLevel.Trace => (MessageType.Log, "Trace: "), + _ => throw new ArgumentOutOfRangeException(nameof(logLevel), logLevel, null) + }; +} + +internal class LanguageServerLoggerProvider(ILanguageServerFacade languageServer) : ILoggerProvider +{ + public ILogger CreateLogger(string categoryName) => new LanguageServerLogger(languageServer, categoryName); + + public void Dispose() { } +} + + +public static class LanguageServerLoggerExtensions +{ + /// + /// Adds a custom logger provider for PSES LSP, that provides more granular categorization than the default Omnisharp logger, such as separating Omnisharp and PSES messages to different channels. + /// + public static ILoggingBuilder AddPsesLanguageServerLogging(this ILoggingBuilder builder) + { + builder.Services.AddSingleton(); + return builder; + } + + public static ILoggingBuilder AddLspClientConfigurableMinimumLevel( + this ILoggingBuilder builder, + LogLevel initialLevel = LogLevel.Trace + ) + { + builder.Services.AddOptions(); + builder.Services.AddSingleton(sp => + { + IOptionsMonitor optionsMonitor = sp.GetRequiredService>(); + return new(initialLevel, optionsMonitor); + }); + builder.Services.AddSingleton>(sp => + sp.GetRequiredService()); + + return builder; + } +} + +internal class DynamicLogLevelOptions( + LogLevel initialLevel, + IOptionsMonitor optionsMonitor) : IConfigureOptions +{ + private LogLevel _currentLevel = initialLevel; + private readonly IOptionsMonitor _optionsMonitor = optionsMonitor; + + public void Configure(LoggerFilterOptions options) => options.MinLevel = _currentLevel; + + public void SetLogLevel(LogLevel level) + { + _currentLevel = level; + // Trigger reload of options to apply new log level + _optionsMonitor.CurrentValue.MinLevel = level; + } +} diff --git a/src/PowerShellEditorServices/Server/PsesLanguageServer.cs b/src/PowerShellEditorServices/Server/PsesLanguageServer.cs index b2195cae5..c106d34c6 100644 --- a/src/PowerShellEditorServices/Server/PsesLanguageServer.cs +++ b/src/PowerShellEditorServices/Server/PsesLanguageServer.cs @@ -89,7 +89,7 @@ public async Task StartAsync() }) .ConfigureLogging(builder => builder .ClearProviders() - .AddLanguageProtocolLogging() + .AddPsesLanguageServerLogging() .SetMinimumLevel(_minimumLogLevel)) .WithHandler() .WithHandler()