Skip to content

Commit 43f5e1b

Browse files
andyleejordanandyleejordan
committed
Add more logging to PowerShellContextService.cs
Also change handled exceptions to warning instead of error.
1 parent 6728a90 commit 43f5e1b

File tree

2 files changed

+47
-45
lines changed

2 files changed

+47
-45
lines changed

‎src/PowerShellEditorServices/Logging/LoggerExtensions.cs

+1-1
Original file line numberDiff line numberDiff line change
@@ -28,7 +28,7 @@ public static void LogHandledException(
2828
[CallerFilePath] string callerSourceFile = null,
2929
[CallerLineNumber] int callerLineNumber = -1)
3030
{
31-
logger.LogError(message, exception);
31+
logger.LogWarning(message, exception);
3232
}
3333
}
3434
}

‎src/PowerShellEditorServices/Services/PowerShellContext/PowerShellContextService.cs

+46-44
Original file line numberDiff line numberDiff line change
@@ -174,6 +174,7 @@ public PowerShellContextService(
174174
OmniSharp.Extensions.LanguageServer.Protocol.Server.ILanguageServerFacade languageServer,
175175
bool isPSReadLineEnabled)
176176
{
177+
logger.LogTrace("Instantiating PowerShellContextService and adding event handlers");
177178
_languageServer = languageServer;
178179
this.logger = logger;
179180
this.isPSReadLineEnabled = isPSReadLineEnabled;
@@ -212,9 +213,9 @@ public static PowerShellContextService Create(
212213
hostUserInterface,
213214
logger);
214215

216+
logger.LogTrace("Creating initial PowerShell runspace");
215217
Runspace initialRunspace = PowerShellContextService.CreateRunspace(psHost, hostStartupInfo.LanguageMode);
216218
powerShellContext.Initialize(hostStartupInfo.ProfilePaths, initialRunspace, true, hostUserInterface);
217-
218219
powerShellContext.ImportCommandsModuleAsync();
219220

220221
// TODO: This can be moved to the point after the $psEditor object
@@ -325,6 +326,7 @@ public void Initialize(
325326
IHostOutput consoleHost)
326327
{
327328
Validate.IsNotNull("initialRunspace", initialRunspace);
329+
this.logger.LogTrace($"Initializing PowerShell context with runspace {initialRunspace.Name}");
328330

329331
this.ownsInitialRunspace = ownsInitialRunspace;
330332
this.SessionState = PowerShellContextState.NotStarted;
@@ -351,11 +353,7 @@ public void Initialize(
351353
this.CurrentRunspace = this.initialRunspace;
352354

353355
// Write out the PowerShell version for tracking purposes
354-
this.logger.LogInformation(
355-
string.Format(
356-
"PowerShell runtime version: {0}, edition: {1}",
357-
this.LocalPowerShellVersion.Version,
358-
this.LocalPowerShellVersion.Edition));
356+
this.logger.LogInformation($"PowerShell Version: {this.LocalPowerShellVersion.Version}, Edition: {this.LocalPowerShellVersion.Edition}");
359357

360358
Version powerShellVersion = this.LocalPowerShellVersion.Version;
361359
if (powerShellVersion >= new Version(5, 0))
@@ -441,6 +439,8 @@ public void Initialize(
441439

442440
public Task ImportCommandsModuleAsync(string path)
443441
{
442+
this.logger.LogTrace($"Importing PowershellEditorServices commands from {path}");
443+
444444
PSCommand importCommand = new PSCommand()
445445
.AddCommand("Import-Module")
446446
.AddArgument(path);
@@ -463,6 +463,7 @@ private static bool CheckIfRunspaceNeedsEventHandlers(RunspaceDetails runspaceDe
463463

464464
private void ConfigureRunspace(RunspaceDetails runspaceDetails)
465465
{
466+
this.logger.LogTrace("Configuring Runspace");
466467
runspaceDetails.Runspace.StateChanged += this.HandleRunspaceStateChanged;
467468
if (runspaceDetails.Runspace.Debugger != null)
468469
{
@@ -475,6 +476,7 @@ private void ConfigureRunspace(RunspaceDetails runspaceDetails)
475476

476477
private void CleanupRunspace(RunspaceDetails runspaceDetails)
477478
{
479+
this.logger.LogTrace("Cleaning Up Runspace");
478480
runspaceDetails.Runspace.StateChanged -= this.HandleRunspaceStateChanged;
479481
if (runspaceDetails.Runspace.Debugger != null)
480482
{
@@ -596,6 +598,8 @@ public async Task<IEnumerable<TResult>> ExecuteCommandAsync<TResult>(
596598
Validate.IsNotNull(nameof(psCommand), psCommand);
597599
Validate.IsNotNull(nameof(executionOptions), executionOptions);
598600

601+
this.logger.LogTrace($"Attempting to execute command(s): {GetStringForPSCommand(psCommand)}");
602+
599603
// Add history to PSReadLine before cancelling, otherwise it will be restored as the
600604
// cancelled prompt when it's called again.
601605
if (executionOptions.AddToHistory)
@@ -629,7 +633,7 @@ public async Task<IEnumerable<TResult>> ExecuteCommandAsync<TResult>(
629633
this.ShouldExecuteWithEventing(executionOptions) ||
630634
(PromptNest.IsRemote && executionOptions.IsReadLine)))
631635
{
632-
this.logger.LogTrace("Passing command execution to pipeline thread.");
636+
this.logger.LogTrace("Passing command execution to pipeline thread");
633637

634638
if (shouldCancelReadLine && PromptNest.IsReadLineBusy())
635639
{
@@ -714,8 +718,7 @@ public async Task<IEnumerable<TResult>> ExecuteCommandAsync<TResult>(
714718
}
715719
catch (Exception e)
716720
{
717-
logger.LogError(
718-
"Exception occurred while executing debugger command:\r\n\r\n" + e.ToString());
721+
this.logger.LogException("Exception occurred while executing debugger command", e);
719722
}
720723
finally
721724
{
@@ -736,11 +739,7 @@ public async Task<IEnumerable<TResult>> ExecuteCommandAsync<TResult>(
736739
AddToHistory = executionOptions.AddToHistory
737740
};
738741

739-
this.logger.LogTrace(
740-
string.Format(
741-
"Attempting to execute command(s):\r\n\r\n{0}",
742-
GetStringForPSCommand(psCommand)));
743-
742+
this.logger.LogTrace("Passing to PowerShell");
744743

745744
PowerShell shell = this.PromptNest.GetPowerShell(executionOptions.IsReadLine);
746745

@@ -818,29 +817,23 @@ public async Task<IEnumerable<TResult>> ExecuteCommandAsync<TResult>(
818817
}
819818
else
820819
{
821-
this.logger.LogTrace(
822-
"Execution completed successfully.");
820+
this.logger.LogTrace("Execution completed successfully");
823821
}
824822
}
825823
}
826824
catch (PSRemotingDataStructureException e)
827825
{
828-
this.logger.LogError(
829-
"Pipeline stopped while executing command:\r\n\r\n" + e.ToString());
830-
826+
this.logger.LogHandledException("Pipeline stopped while executing command", e);
831827
errorMessages?.Append(e.Message);
832828
}
833829
catch (PipelineStoppedException e)
834830
{
835-
this.logger.LogError(
836-
"Pipeline stopped while executing command:\r\n\r\n" + e.ToString());
837-
831+
this.logger.LogHandledException("Pipeline stopped while executing command", e);
838832
errorMessages?.Append(e.Message);
839833
}
840834
catch (RuntimeException e)
841835
{
842-
this.logger.LogWarning(
843-
"Runtime exception occurred while executing command:\r\n\r\n" + e.ToString());
836+
this.logger.LogHandledException("Runtime exception occurred while executing command", e);
844837

845838
hadErrors = true;
846839
errorMessages?.Append(e.Message);
@@ -1078,8 +1071,7 @@ public async Task ExecuteScriptWithArgsAsync(string script, string arguments = n
10781071
}
10791072
catch (System.Management.Automation.DriveNotFoundException e)
10801073
{
1081-
this.logger.LogError(
1082-
"Could not determine current filesystem location:\r\n\r\n" + e.ToString());
1074+
this.logger.LogHandledException("Could not determine current filesystem location", e);
10831075
}
10841076

10851077
var strBld = new StringBuilder();
@@ -1250,9 +1242,7 @@ public void AbortExecution(bool shouldAbortDebugSession)
12501242
if (this.SessionState == PowerShellContextState.Aborting
12511243
|| this.SessionState == PowerShellContextState.Disposed)
12521244
{
1253-
this.logger.LogTrace(
1254-
string.Format(
1255-
$"Execution abort requested when already aborted (SessionState = {this.SessionState})"));
1245+
this.logger.LogTrace($"Execution abort requested when already aborted (SessionState = {this.SessionState})");
12561246
return;
12571247
}
12581248

@@ -1539,8 +1529,8 @@ private void CloseRunspace(RunspaceDetails runspaceDetails)
15391529

15401530
if (exitException != null)
15411531
{
1542-
this.logger.LogError(
1543-
$"Caught {exitException.GetType().Name} while exiting {runspaceDetails.Location} runspace:\r\n{exitException.ToString()}");
1532+
this.logger.LogHandledException(
1533+
$"Caught {exitException.GetType().Name} while exiting {runspaceDetails.Location} runspace", exitException);
15441534
}
15451535
}
15461536
}
@@ -1582,6 +1572,8 @@ internal bool IsCurrentRunspaceOutOfProcess()
15821572
/// </summary>
15831573
internal void EnterNestedPrompt()
15841574
{
1575+
this.logger.LogTrace("Entering nested prompt");
1576+
15851577
if (this.IsCurrentRunspaceOutOfProcess())
15861578
{
15871579
throw new NotSupportedException();
@@ -1884,8 +1876,15 @@ private void OnExecutionStatusChanged(
18841876
hadErrors));
18851877
}
18861878

1879+
/// <remarks>
1880+
/// TODO: This should somehow check if the server has actually started because we are
1881+
/// currently sending this notification before it has initialized, which is not allowed.
1882+
/// This might be the cause of our deadlock!
1883+
/// </remarks>
18871884
private void PowerShellContext_RunspaceChangedAsync(object sender, RunspaceChangedEventArgs e)
18881885
{
1886+
this.logger.LogTrace("Sending runspaceChanged notification");
1887+
18891888
_languageServer?.SendNotification(
18901889
"powerShell/runspaceChanged",
18911890
new MinifiedRunspaceDetails(e.NewRunspace));
@@ -1922,10 +1921,16 @@ public MinifiedRunspaceDetails(RunspaceDetails eventArgs)
19221921
/// <summary>
19231922
/// Event hook on the PowerShell context to listen for changes in script execution status
19241923
/// </summary>
1924+
/// <remarks>
1925+
/// TODO: This should somehow check if the server has actually started because we are
1926+
/// currently sending this notification before it has initialized, which is not allowed.
1927+
/// </remarks>
19251928
/// <param name="sender">the PowerShell context sending the execution event</param>
19261929
/// <param name="e">details of the execution status change</param>
19271930
private void PowerShellContext_ExecutionStatusChangedAsync(object sender, ExecutionStatusChangedEventArgs e)
19281931
{
1932+
this.logger.LogTrace("Sending executionStatusChanged notification");
1933+
19291934
// The cancelling of the prompt (PSReadLine) causes an ExecutionStatus.Aborted to be sent after every
19301935
// actual execution (ExecutionStatus.Running) on the pipeline. We ignore that event since it's counterintuitive to
19311936
// the goal of this method which is to send updates when the pipeline is actually running something.
@@ -1945,10 +1950,7 @@ private void PowerShellContext_ExecutionStatusChangedAsync(object sender, Execut
19451950

19461951
private IEnumerable<TResult> ExecuteCommandInDebugger<TResult>(PSCommand psCommand, bool sendOutputToHost)
19471952
{
1948-
this.logger.LogTrace(
1949-
string.Format(
1950-
"Attempting to execute command(s) in the debugger:\r\n\r\n{0}",
1951-
GetStringForPSCommand(psCommand)));
1953+
this.logger.LogTrace($"Attempting to execute command(s)a in the debugger: {GetStringForPSCommand(psCommand)}");
19521954

19531955
IEnumerable<TResult> output =
19541956
this.versionSpecificOperations.ExecuteCommandInDebugger<TResult>(
@@ -2144,6 +2146,8 @@ private static string GetStringForPSCommand(PSCommand psCommand)
21442146

21452147
private void SetExecutionPolicy()
21462148
{
2149+
this.logger.LogTrace("Setting execution policy...");
2150+
21472151
// We want to get the list hierarchy of execution policies
21482152
// Calling the cmdlet is the simplest way to do that
21492153
IReadOnlyList<PSObject> policies = this.powerShell
@@ -2188,7 +2192,7 @@ private void SetExecutionPolicy()
21882192
}
21892193

21902194
// Finally set the inherited execution policy
2191-
this.logger.LogTrace("Setting execution policy to {Policy}", policyToSet);
2195+
this.logger.LogTrace($"Setting execution policy to {policyToSet}");
21922196
try
21932197
{
21942198
this.powerShell
@@ -2200,7 +2204,8 @@ private void SetExecutionPolicy()
22002204
}
22012205
catch (CmdletInvocationException e)
22022206
{
2203-
this.logger.LogError(e, "Error occurred calling 'Set-ExecutionPolicy -Scope Process -ExecutionPolicy {Policy} -Force'", policyToSet);
2207+
this.logger.LogHandledException(
2208+
$"Error occurred calling 'Set-ExecutionPolicy -Scope Process -ExecutionPolicy {policyToSet} -Force'", e);
22042209
}
22052210
finally
22062211
{
@@ -2221,13 +2226,11 @@ private SessionDetails GetSessionDetails(Func<PSCommand, PSObject> invokeAction)
22212226
}
22222227
catch (RuntimeException e)
22232228
{
2224-
this.logger.LogTrace(
2225-
"Runtime exception occurred while gathering runspace info:\r\n\r\n" + e.ToString());
2229+
this.logger.LogHandledException("Runtime exception occurred while gathering runspace info", e);
22262230
}
22272231
catch (ArgumentNullException)
22282232
{
2229-
this.logger.LogError(
2230-
"Could not retrieve session details but no exception was thrown.");
2233+
this.logger.LogError("Could not retrieve session details but no exception was thrown.");
22312234
}
22322235

22332236
// TODO: Return a harmless object if necessary
@@ -2320,9 +2323,7 @@ private void SetProfileVariableInCurrentRunspace(ProfilePathInfo profilePaths)
23202323
profilePaths.CurrentUserCurrentHost));
23212324

23222325
this.logger.LogTrace(
2323-
string.Format(
2324-
"Setting $profile variable in runspace. Current user host profile path: {0}",
2325-
profilePaths.CurrentUserCurrentHost));
2326+
$"Setting $profile variable in runspace. Current user host profile path: {profilePaths.CurrentUserCurrentHost}");
23262327

23272328
// Set the variable in the runspace
23282329
this.powerShell.Commands.Clear();
@@ -2545,6 +2546,7 @@ private void OnDebuggerStop(object sender, DebuggerStopEventArgs e)
25452546
else
25462547
{
25472548
// TODO: How to handle this?
2549+
this.logger.LogError($"Unhandled TaskIndex: {taskIndex}");
25482550
}
25492551
}
25502552

0 commit comments

Comments
 (0)