Vscode-powershell: Powershell debugger hangs stepping over a script invocation

[johndog]

Issue Type: Bug

1. Open a script with the following contents

Set-StrictMode -Version 5
$ErrorActionPreference = "Stop"
. $PSScriptRoot\test2.ps1
"hello 3"

1. In test2.ps1, put literally anything (e.g. "hello from test2.ps1", or even blank or non-existant).
2. Put a breakpoint on line 3 (test2.ps1 invocation)
3. Hit F5
4. When it breaks hit F10

Result: debugger will never return. You have to stop it and restart the integrated powershell instance.

Note: If either of the first two lines are commented out, i.e. without either Set-StrictMode OR $EAP = "Stop", it seems to work The combination causes fits.

Note 2: If there are no breakpoints, it seems to work then as well.

Extension version: 2020.4.0
VS Code version: Code 1.45.1 (5763d909d5f12fe19f215cbfdd29a91c0fa9208a, 2020-05-14T08:27:35.169Z)
OS version: Windows_NT x64 10.0.19635

System Info

|Item|Value|
|---|---|
|CPUs|Intel(R) Core(TM) i7-8700K CPU @ 3.70GHz (12 x 3696)|
|GPU Status|2d_canvas: enabled
flash_3d: enabled
flash_stage3d: enabled
flash_stage3d_baseline: enabled
gpu_compositing: enabled
multiple_raster_threads: enabled_on
oop_rasterization: disabled_off
protected_video_decode: enabled
rasterization: enabled
skia_renderer: disabled_off_ok
video_decode: enabled
viz_display_compositor: enabled_on
viz_hit_test_surface_layer: disabled_off_ok
webgl: enabled
webgl2: enabled|
|Load (avg)|undefined|
|Memory (System)|31.78GB (15.85GB free)|
|Process Argv|--folder-uri file:///c%3A/repos/devdir|
|Screen Reader|no|
|VM|0%|

[PrzemyslawKlys]

Can you reproduce it with Preview version?

[SydneyhSmith]

Thanks @PrzemyslawKlys that's exactly what I would have asked! The preview extension is here:
https://marketplace.visualstudio.com/items?itemName=ms-vscode.PowerShell-Preview

[johndog]

Yes, I found it in preview initially (most recently on 2020.6.0)... in fact, I think it's been there for several months. I went to production version to see if it was stable enough to not have this issue, so that's why I opened the bug with the release build.

It took me some time to realize it, but I think I started seeing this issue a couple of months ago (preview builds). I was unable to narrow it down at the time, and chalked it up to preview instability. Most of my scripts do both set-strictmode and set ErrorActionPreference to Stop, so I was essentially unable to debug anything. Recently I've been working with more and more Pester scripts which do not apply both of these settings, and when debugging began to work I had thought the debugger was fixed. Once I realized that the bug has more to do with which scripts I'm debugging than which build of the powershell extension, I was able to zero in on a repro and open this issue.

[PrzemyslawKlys]

I actually tried it on my own and couldn't replicate your issue

Set-StrictMode -Version 5
$ErrorActionPreference = "Stop"
. $PSScriptROot\test2.ps1
"hello 3"

Had to use $PSScriptRoot because otherwise it would error.

[johndog]

Had to use $PSScriptRoot because otherwise it would error.

Good point. I assume this wouldn't have been necessary if you did cd $PSScriptRoot first? I'll fix the repro...

Anyway, what's the next step? It reproduces 100% for me.

Would a dump help? Maybe there is a clue in the logs.

[johndog]

This might have something to do with it. From EditorServicesLog:

2020-06-05 09:57:44.897 -07:00 [INF] PowerShell runtime version: 7.1.0, edition: Core
2020-06-05 09:57:45.060 -07:00 [INF] highlight handler loaded
2020-06-05 09:57:46.348 -07:00 [INF] Unable to find PSSA settings file at 'c:\repos\devdir\PSScriptAnalyzerSettings.psd1'. Loading default rules.
2020-06-05 09:57:46.351 -07:00 [INF] PSScriptAnalyzer settings file not found. Falling back to default rules
2020-06-05 09:57:47.201 -07:00 [INF] Adding handlers
2020-06-05 09:57:47.201 -07:00 [INF] Handlers added
2020-06-05 09:57:47.478 -07:00 [ERR] Execution of the following command(s) completed with errors:

    $contextIndex


2020-06-05 09:57:47.486 -07:00 [WRN] Runtime exception occurred while executing command:

System.Management.Automation.RuntimeException: The variable '$contextIndex' cannot be retrieved because it has not been set.
   at System.Management.Automation.Runspaces.PipelineBase.Invoke(IEnumerable input)
   at System.Management.Automation.PowerShell.Worker.ConstructPipelineAndDoWork(Runspace rs, Boolean performSyncInvoke)
   at System.Management.Automation.PowerShell.CoreInvokeHelper[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings)
   at System.Management.Automation.PowerShell.CoreInvoke[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings)
   at System.Management.Automation.PowerShell.CoreInvoke[TOutput](IEnumerable input, PSDataCollection`1 output, PSInvocationSettings settings)
   at System.Management.Automation.PowerShell.Invoke[T](IEnumerable input, IList`1 output, PSInvocationSettings settings)
   at System.Management.Automation.PowerShell.Invoke[T](IEnumerable input, PSInvocationSettings settings)
   at Microsoft.PowerShell.EditorServices.Services.PowerShellContextService.ExecuteCommandAsync[TResult](PSCommand psCommand, StringBuilder errorMessages, ExecutionOptions executionOptions) in D:\a\1\s\src\PowerShellEditorServices\Services\PowerShellContext\PowerShellContextService.cs:line 776
   at Microsoft.PowerShell.EditorServices.Services.PowerShellContextService.ExecuteCommandAsync[TResult](PSCommand psCommand, StringBuilder errorMessages, ExecutionOptions executionOptions) in D:\a\1\s\src\PowerShellEditorServices\Services\PowerShellContext\PowerShellContextService.cs:line 825
2020-06-05 09:59:09.647 -07:00 [ERR] Tried to resume debugger with action StepOver but there was no debuggerStoppedTask.

Does the powershell extension use pwsh or powershell?

[rjmholt]

@johndog some next steps:

• Try to see if you can reproduce this with the PowerShell Preview extension
• If so, we need to work out what's happening and why the code isn't progressing. Logs will help with that.

It looks like the log snippet you posted might be involved. It may be that strict mode prevents running something behind the scenes in the debugger.

I did try to reproduce this just now on my Windows (10.0.19041) machine and wasn't able to in PowerShell 7.1, 7 or 5.1, so definitely worth trying the preview extension. Also worth determining if this always happens, or only sometimes.

Does the powershell extension use pwsh or powershell?

It uses whichever of the PowerShells installed on your system you've got it configured to use. From your log snippet, this is currently PS 7.1 on your machine. You can change this by clicking on the little PowerShell icon/version in the lower right-hand corner of the VSCode window.

[johndog]

@rjmholt - As mentioned above (link), I am using the latest extension. I only switched to release to see if it still reproduced. It doesn't seem to make a difference, and it reproduces 100% of the time.

I'm on Windows 19635. Perhaps it regressed on some windows insider build along the way, since 19041.

It uses whichever of the PowerShells installed on your system you've got it configured to use. From your log snippet, this is currently PS 7.1 on your machine. You can change this by clicking on the little PowerShell icon/version in the lower right-hand corner of the VSCode window.

I tried switching from 7.1 to 5.1 and it still reproduces.

I'll follow the steps to collect diagnostic logs.

[rjmholt]

As mentioned above (link), I am using the latest extension.

Ah, sorry, I missed that.

Yeah the logs should help, but if the issue becomes one that only reproduces in certain environments, our next step would be to collect a dump to work out where the code is

[msftbot[bot]]

This issue is being closed as inactive, if this issue is still occurring it will be re-opened

[johndog]

@rjmholt This still reproduces for me.

Version: 1.48.2 (system setup)
Commit: a0479759d6e9ea56afa657e454193f72aef85bd0
Date: 2020-08-25T10:13:11.295Z
Electron: 7.3.2
Chrome: 78.0.3904.130
Node.js: 12.8.1
V8: 7.8.279.23-electron.0
OS: Windows_NT x64 10.0.20197

Log messages pasted here still get printed: https://github.com/PowerShell/vscode-powershell/issues/2742#issuecomment-639632738

Which logs would be useful? What kind of dump would be useful?

[johndog]

These logs seem to be the only relevant ones, so here they are in entirety...

vscode-powershell.log:

8/27/2020 1:55:12 PM [NORMAL] - Language server starting --
8/27/2020 1:55:12 PM [NORMAL] - powershell.exe started.
8/27/2020 1:55:12 PM [NORMAL] -     PowerShell executable: C:\WINDOWS\System32\WindowsPowerShell\v1.0\powershell.exe
8/27/2020 1:55:12 PM [NORMAL] -     PowerShell args: -NoProfile -NonInteractive -ExecutionPolicy Bypass -Command Import-Module 'c:\Users\johndog\.vscode\extensions\ms-vscode.powershell-preview-2020.7.0\modules\PowerShellEditorServices\PowerShellEditorServices.psd1'; Start-EditorServices -HostName 'Visual Studio Code Host' -HostProfileId 'Microsoft.VSCode' -HostVersion '2020.7.0' -AdditionalModules @('PowerShellEditorServices.VSCode') -BundledModulesPath 'c:\Users\johndog\.vscode\extensions\ms-vscode.powershell-preview-2020.7.0\modules' -EnableConsoleRepl -StartupBanner '=====> PowerShell Preview Integrated Console v2020.7.0 <=====
' -LogLevel 'Normal' -LogPath 'c:\Users\johndog\.vscode\extensions\ms-vscode.powershell-preview-2020.7.0\logs\1598561712-28f00211-e22f-49fd-8b32-c91b856ef7071598561710607\EditorServices.log' -SessionDetailsPath 'c:\Users\johndog\.vscode\extensions\ms-vscode.powershell-preview-2020.7.0\sessions\PSES-VSCode-42084-562836' -FeatureFlags @() 
8/27/2020 1:55:12 PM [NORMAL] - Waiting for session file
8/27/2020 1:55:12 PM [NORMAL] -     PowerShell Editor Services args: Import-Module 'c:\Users\johndog\.vscode\extensions\ms-vscode.powershell-preview-2020.7.0\modules\PowerShellEditorServices\PowerShellEditorServices.psd1'; Start-EditorServices -HostName 'Visual Studio Code Host' -HostProfileId 'Microsoft.VSCode' -HostVersion '2020.7.0' -AdditionalModules @('PowerShellEditorServices.VSCode') -BundledModulesPath 'c:\Users\johndog\.vscode\extensions\ms-vscode.powershell-preview-2020.7.0\modules' -EnableConsoleRepl -StartupBanner '=====> PowerShell Preview Integrated Console v2020.7.0 <=====
' -LogLevel 'Normal' -LogPath 'c:\Users\johndog\.vscode\extensions\ms-vscode.powershell-preview-2020.7.0\logs\1598561712-28f00211-e22f-49fd-8b32-c91b856ef7071598561710607\EditorServices.log' -SessionDetailsPath 'c:\Users\johndog\.vscode\extensions\ms-vscode.powershell-preview-2020.7.0\sessions\PSES-VSCode-42084-562836' -FeatureFlags @() 
8/27/2020 1:55:14 PM [NORMAL] - Session file found
8/27/2020 1:55:14 PM [NORMAL] - Registering terminal close callback
8/27/2020 1:55:14 PM [NORMAL] - Registering terminal PID log callback
8/27/2020 1:55:14 PM [NORMAL] - powershell.exe PID: 25032
8/27/2020 1:55:14 PM [NORMAL] - Language server started.
8/27/2020 1:55:14 PM [NORMAL] - {"status":"started","languageServiceTransport":"NamedPipe","languageServicePipeName":"\\\\.\\pipe\\PSES_lordvzlj.jnz","debugServiceTransport":"NamedPipe","debugServicePipeName":"\\\\.\\pipe\\PSES_qmqfquxe.dhc"}
8/27/2020 1:55:14 PM [NORMAL] - Connecting to language service on pipe \\.\pipe\PSES_lordvzlj.jnz...
8/27/2020 1:55:14 PM [NORMAL] - Language service connected.
8/27/2020 1:55:17 PM [WARNING] - Invalid Version: null

EditorServices.log:

2020-08-27 13:55:15.559 -07:00 [INF] PowerShell runtime version: 5.1.20197.1000, edition: Desktop
2020-08-27 13:55:16.236 -07:00 [INF] highlight handler loaded
2020-08-27 13:55:18.157 -07:00 [INF] Unable to find PSSA settings file at 'c:\repos\devdir\PSScriptAnalyzerSettings.psd1'. Loading default rules.
2020-08-27 13:55:18.165 -07:00 [INF] PSScriptAnalyzer settings file not found. Falling back to default rules
2020-08-27 15:32:58.772 -07:00 [INF] Adding handlers
2020-08-27 15:32:58.772 -07:00 [INF] Handlers added
2020-08-27 15:33:00.622 -07:00 [ERR] Exception occurred while executing debugger command:

System.Management.Automation.CommandNotFoundException: The term '__Invoke-ReadLineForEditorServices' is not recognized as the name of a cmdlet, function, script file, or operable program. Check the spelling of the name, or if a path was included, verify that the path is correct and try again.
   at System.Management.Automation.Runspaces.PipelineBase.Invoke(IEnumerable input)
   at System.Management.Automation.PowerShell.Worker.ConstructPipelineAndDoWork(Runspace rs, Boolean performSyncInvoke)
   at System.Management.Automation.PowerShell.CoreInvokeHelper[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings)
   at System.Management.Automation.PowerShell.CoreInvoke[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings)
   at System.Management.Automation.PowerShell.InvokeWithDebugger(IEnumerable`1 input, IList`1 output, PSInvocationSettings settings, Boolean invokeMustRun)
   at System.Management.Automation.ScriptDebugger.ProcessCommand(PSCommand command, PSDataCollection`1 output)
   at Microsoft.PowerShell.EditorServices.Services.PowerShellContext.PowerShell5Operations.ExecuteCommandInDebugger[TResult](PowerShellContextService powerShellContext, Runspace currentRunspace, PSCommand psCommand, Boolean sendOutputToHost, Nullable`1& debuggerResumeAction)
   at Microsoft.PowerShell.EditorServices.Services.PowerShellContextService.ExecuteCommandInDebugger[TResult](PSCommand psCommand, Boolean sendOutputToHost)
   at Microsoft.PowerShell.EditorServices.Services.PowerShellContextService.<ExecuteCommandAsync>d__89`1.MoveNext()
2020-08-27 15:33:00.812 -07:00 [ERR] Execution of the following command(s) completed with errors:

    $contextIndex


2020-08-27 15:33:00.813 -07:00 [WRN] Runtime exception occurred while executing command:

System.Management.Automation.RuntimeException: The variable '$contextIndex' cannot be retrieved because it has not been set.
   at System.Management.Automation.Runspaces.PipelineBase.Invoke(IEnumerable input)
   at System.Management.Automation.PowerShell.Worker.ConstructPipelineAndDoWork(Runspace rs, Boolean performSyncInvoke)
   at System.Management.Automation.PowerShell.CoreInvokeHelper[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings)
   at System.Management.Automation.PowerShell.CoreInvoke[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings)
   at System.Management.Automation.PowerShell.Invoke[T](IEnumerable input, PSInvocationSettings settings)
   at Microsoft.PowerShell.EditorServices.Services.PowerShellContextService.<ExecuteCommandAsync>d__89`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at Microsoft.PowerShell.EditorServices.Services.PowerShellContextService.<ExecuteCommandAsync>d__89`1.MoveNext()
2020-08-27 15:33:02.270 -07:00 [ERR] Tried to resume debugger with action StepOver but there was no debuggerStoppedTask.

[SydneyhSmith]

Thanks @johndog looks like the debugger may be having an issue with StrictMode

[jeanph01]

$ErrorActionPreference being set to "stop" or "inquire" had the strange effect of making the debugger fail. I got this with Powershell and Powershell preview extension and thanks to this thread found this was the problem... really difficult bug to pinpoint because the debugger just stop responding during a debugging session but this code is still in debugging mode..

[oliverroer]

I have had this issue today as well.

After looking at the log, I realized what caused it - at least in my case.

In my case, I had a variable in the watch window, which wasn't initialized.

For example, I can run the following script to produce the issue:

Set-StrictMode -Version 2.0
$ErrorActionPreference = "Stop"

Write-Host "Hello World"

With my watch set like this:

I can set a breakpoint on the first line and step through the script. As soon as I've stepped over the first two lines and try to step to the Write-Host line, the debugger freezes.

StrictMode version 1.0 and onwards lists the following:

Prohibits references to uninitialized variables, except for uninitialized variables in strings.

So I guess setting any version of StrictMode combined with $ErrorActionPreference='Stop' will cause issues when setting a watch on a variable that doesn't exist.

Here's what I saw in my log that helped me spot the issue:

2020-12-15 08:31:32.157 +01:00 [ERR] Execution of the following command(s) completed with errors:

    $Name

Error #1:
The variable '$Name' cannot be retrieved because it has not been set.
ScriptStackTrace:
at <ScriptBlock>, C:\devops\coric-engage-blueprints\freeze.ps1: line 2
Exception:
   System.Management.Automation.RuntimeException: The variable '$Name' cannot be retrieved because it has not been set.
   at System.Management.Automation.VariableOps.GetVariableValue(VariablePath variablePath, ExecutionContext executionContext, VariableExpressionAst varAst)
   at System.Management.Automation.Interpreter.FuncCallInstruction`4.Run(InterpretedFrame frame)
   at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)
2020-12-15 08:31:32.159 +01:00 [VRB] Attempting to execute command(s):

    prompt

It would be nice to have a fix for this. It would be great for the watch to check if the variable exists first, and if not, just write something like $Name: uninitialized or something like that, rather than blindly trying to read it and getting locked up. :smile: