Clean up logging in PowerShellContextService

I added a bunch more recently that was became less useful and more noisy
after my familiarity improved.

Author: andyleejordan

src/PowerShellEditorServices.Hosting/Internal/EditorServicesRunner.cs

@@ -308,7 +308,7 @@ private void WriteStartupBanner()
 
         private void DebugServer_OnSessionEnded(object sender, EventArgs args)
         {
-            _logger.Log(PsesLogLevel.Verbose, "Debug session ended. Restarting debug service");
+            _logger.Log(PsesLogLevel.Verbose, "Debug session ended, restarting debug service...");
             var oldServer = (PsesDebugServer)sender;
             oldServer.Dispose();
             _alreadySubscribedDebug = false;

src/PowerShellEditorServices/Services/PowerShellContext/PowerShellContextService.cs

@@ -192,7 +192,6 @@ public PowerShellContextService(
             OmniSharp.Extensions.LanguageServer.Protocol.Server.ILanguageServerFacade languageServer,
             bool isPSReadLineEnabled)
         {
-            logger.LogTrace("Instantiating PowerShellContextService and adding event handlers");
             _languageServer = languageServer;
             this.logger = logger;
             this.isPSReadLineEnabled = isPSReadLineEnabled;
@@ -214,7 +213,7 @@ public static PowerShellContextService Create(
             // Respect a user provided bundled module path.
             if (Directory.Exists(hostStartupInfo.BundledModulePath))
             {
-                logger.LogTrace($"Using new bundled module path: {hostStartupInfo.BundledModulePath}");
+                logger.LogDebug($"Using new bundled module path: {hostStartupInfo.BundledModulePath}");
                 s_bundledModulePath = hostStartupInfo.BundledModulePath;
             }
 
@@ -238,7 +237,6 @@ public static PowerShellContextService Create(
                     hostUserInterface,
                     logger);
 
-            logger.LogTrace("Creating initial PowerShell runspace");
             Runspace initialRunspace = PowerShellContextService.CreateRunspace(psHost, hostStartupInfo.InitialSessionState);
             powerShellContext.Initialize(hostStartupInfo.ProfilePaths, initialRunspace, true, hostUserInterface);
             powerShellContext.ImportCommandsModuleAsync();
@@ -327,7 +325,6 @@ public void Initialize(
             IHostOutput consoleHost)
         {
             Validate.IsNotNull("initialRunspace", initialRunspace);
-            this.logger.LogTrace($"Initializing PowerShell context with runspace {initialRunspace.Name}");
 
             this.ownsInitialRunspace = ownsInitialRunspace;
             this.SessionState = PowerShellContextState.NotStarted;
@@ -363,6 +360,7 @@ public void Initialize(
             }
             else
             {
+                // TODO: Also throw for PowerShell 6
                 throw new NotSupportedException(
                     "This computer has an unsupported version of PowerShell installed: " +
                     powerShellVersion.ToString());
@@ -577,10 +575,9 @@ public Task<IEnumerable<TResult>> ExecuteCommandAsync<TResult>(
                     cancellationToken);
         }
 
-
         /// <summary>
         /// Executes a PSCommand against the session's runspace and returns
-        /// a collection of results of the expected type.
+        /// a collection of results of the expected type. This function needs help.
         /// </summary>
         /// <typeparam name="TResult">The expected result type.</typeparam>
         /// <param name="psCommand">The PSCommand to be executed.</param>
@@ -601,8 +598,6 @@ public async Task<IEnumerable<TResult>> ExecuteCommandAsync<TResult>(
             Validate.IsNotNull(nameof(psCommand), psCommand);
             Validate.IsNotNull(nameof(executionOptions), executionOptions);
 
-            this.logger.LogTrace($"Attempting to execute command(s): {GetStringForPSCommand(psCommand)}");
-
             // Add history to PSReadLine before cancelling, otherwise it will be restored as the
             // cancelled prompt when it's called again.
             if (executionOptions.AddToHistory)
@@ -636,8 +631,6 @@ public async Task<IEnumerable<TResult>> ExecuteCommandAsync<TResult>(
                 this.ShouldExecuteWithEventing(executionOptions) ||
                 (PromptNest.IsRemote && executionOptions.IsReadLine)))
             {
-                this.logger.LogTrace("Passing command execution to pipeline thread");
-
                 if (shouldCancelReadLine && PromptNest.IsReadLineBusy())
                 {
                     // If a ReadLine pipeline is running in the debugger then we'll stop responding here
@@ -715,6 +708,7 @@ public async Task<IEnumerable<TResult>> ExecuteCommandAsync<TResult>(
                     }
                     try
                     {
+                        this.logger.LogTrace($"Executing in debugger: {GetStringForPSCommand(psCommand)}");
                         return this.ExecuteCommandInDebugger<TResult>(
                             psCommand,
                             executionOptions.WriteOutputToHost);
@@ -742,8 +736,6 @@ public async Task<IEnumerable<TResult>> ExecuteCommandAsync<TResult>(
                     AddToHistory = executionOptions.AddToHistory
                 };
 
-                this.logger.LogTrace("Passing to PowerShell");
-
                 PowerShell shell = this.PromptNest.GetPowerShell(executionOptions.IsReadLine);
 
                 // Due to the following PowerShell bug, we can't just assign shell.Commands to psCommand
@@ -767,6 +759,8 @@ public async Task<IEnumerable<TResult>> ExecuteCommandAsync<TResult>(
                     : this.CurrentRunspace.Runspace;
                 try
                 {
+                    this.logger.LogDebug($"Invoking: {GetStringForPSCommand(psCommand)}");
+
                     // Nested PowerShell instances can't be invoked asynchronously. This occurs
                     // in nested prompts and pipeline requests from eventing.
                     if (shell.IsNested)
@@ -835,15 +829,11 @@ public async Task<IEnumerable<TResult>> ExecuteCommandAsync<TResult>(
 
                         hadErrors = true;
                     }
-                    else
-                    {
-                        this.logger.LogTrace("Execution completed successfully");
-                    }
                 }
             }
             catch (PSRemotingDataStructureException e)
             {
-                this.logger.LogHandledException("Pipeline stopped while executing command", e);
+                this.logger.LogHandledException("PSRemotingDataStructure exception while executing command", e);
                 errorMessages?.Append(e.Message);
             }
             catch (PipelineStoppedException e)
@@ -1088,7 +1078,7 @@ public async Task ExecuteScriptWithArgsAsync(string script, string arguments = n
                             .FirstOrDefault()
                             .ProviderPath;
 
-                        this.logger.LogTrace($"Prepending working directory {workingDir} to script path {script}");
+                        this.logger.LogDebug($"Prepending working directory {workingDir} to script path {script}");
                         script = Path.Combine(workingDir, script);
                     }
                     catch (System.Management.Automation.DriveNotFoundException e)
@@ -1120,7 +1110,6 @@ public async Task ExecuteScriptWithArgsAsync(string script, string arguments = n
                 strBld.Append(' ').Append(arguments);
 
                 var launchedScript = strBld.ToString();
-                this.logger.LogTrace($"Launch script is: {launchedScript}");
 
                 command.AddScript(launchedScript, false);
             }
@@ -1262,15 +1251,15 @@ public void AbortExecution()
         /// </param>
         public void AbortExecution(bool shouldAbortDebugSession)
         {
+            this.logger.LogTrace("Execution abort requested...");
+
             if (this.SessionState == PowerShellContextState.Aborting
                 || this.SessionState == PowerShellContextState.Disposed)
             {
                 this.logger.LogTrace($"Execution abort requested when already aborted (SessionState = {this.SessionState})");
                 return;
             }
 
-            this.logger.LogTrace("Execution abort requested...");
-
             if (shouldAbortDebugSession)
             {
                 this.ExitAllNestedPrompts();
@@ -1416,7 +1405,7 @@ private void ResumeDebugger(DebuggerResumeAction resumeAction, bool shouldWaitFo
         /// </summary>
         public void Close()
         {
-            logger.LogDebug("Closing PowerShellContextService...");
+            logger.LogTrace("Closing PowerShellContextService...");
             this.PromptNest.Dispose();
             this.SessionState = PowerShellContextState.Disposed;
 
@@ -1854,13 +1843,7 @@ private void OnSessionStateChanged(object sender, SessionStateChangedEventArgs e
         {
             if (this.SessionState != PowerShellContextState.Disposed)
             {
-                this.logger.LogTrace(
-                    string.Format(
-                        "Session state changed --\r\n\r\n    Old state: {0}\r\n    New state: {1}\r\n    Result: {2}",
-                        this.SessionState.ToString(),
-                        e.NewSessionState.ToString(),
-                        e.ExecutionResult));
-
+                this.logger.LogTrace($"Session state was: {SessionState}, is now: {e.NewSessionState}, result: {e.ExecutionResult}");
                 this.SessionState = e.NewSessionState;
                 this.SessionStateChanged?.Invoke(sender, e);
             }
@@ -1906,8 +1889,6 @@ private void OnExecutionStatusChanged(
         /// </remarks>
         private void PowerShellContext_RunspaceChangedAsync(object sender, RunspaceChangedEventArgs e)
         {
-            this.logger.LogTrace("Sending runspaceChanged notification");
-
             _languageServer?.SendNotification(
                 "powerShell/runspaceChanged",
                 new MinifiedRunspaceDetails(e.NewRunspace));
@@ -1952,8 +1933,6 @@ public MinifiedRunspaceDetails(RunspaceDetails eventArgs)
         /// <param name="e">details of the execution status change</param>
         private void PowerShellContext_ExecutionStatusChangedAsync(object sender, ExecutionStatusChangedEventArgs e)
         {
-            this.logger.LogTrace("Sending executionStatusChanged notification");
-
             // The cancelling of the prompt (PSReadLine) causes an ExecutionStatus.Aborted to be sent after every
             // actual execution (ExecutionStatus.Running) on the pipeline. We ignore that event since it's counterintuitive to
             // the goal of this method which is to send updates when the pipeline is actually running something.
@@ -1973,8 +1952,6 @@ private void PowerShellContext_ExecutionStatusChangedAsync(object sender, Execut
 
         private IEnumerable<TResult> ExecuteCommandInDebugger<TResult>(PSCommand psCommand, bool sendOutputToHost)
         {
-            this.logger.LogTrace($"Attempting to execute command(s) in the debugger: {GetStringForPSCommand(psCommand)}");
-
             IEnumerable<TResult> output =
                 this.versionSpecificOperations.ExecuteCommandInDebugger<TResult>(
                     this,