Skip to content

Powershell debugger hangs stepping over a script invocation #2742

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
johndog opened this issue Jun 3, 2020 · 27 comments
Closed

Powershell debugger hangs stepping over a script invocation #2742

johndog opened this issue Jun 3, 2020 · 27 comments
Assignees
Labels
Area-Debugging Issue-Bug A bug to squash. Resolution-Fixed Will close automatically.

Comments

@johndog
Copy link

johndog commented Jun 3, 2020

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%
@ghost ghost added the Needs: Triage Maintainer attention needed! label Jun 3, 2020
@PrzemyslawKlys
Copy link
Contributor

Can you reproduce it with Preview version?

@SydneyhSmith SydneyhSmith added Needs-Repro-Info and removed Needs: Triage Maintainer attention needed! labels Jun 4, 2020
@SydneyhSmith
Copy link
Collaborator

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
Copy link
Author

johndog commented Jun 4, 2020

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.

@ghost ghost added the Needs: Maintainer Attention Maintainer attention needed! label Jun 4, 2020
@PrzemyslawKlys
Copy link
Contributor

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
Copy link
Author

johndog commented Jun 5, 2020

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
Copy link
Author

johndog commented Jun 5, 2020

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
Copy link
Contributor

rjmholt commented Jun 5, 2020

@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
Copy link
Author

johndog commented Jun 5, 2020

@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
Copy link
Contributor

rjmholt commented Jun 5, 2020

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

@SydneyhSmith SydneyhSmith removed the Needs: Maintainer Attention Maintainer attention needed! label Jun 9, 2020
@ghost
Copy link

ghost commented Jun 24, 2020

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

@ghost ghost added the Resolution-Inactive Will close automatically. label Jun 24, 2020
@ghost ghost closed this as completed Jun 24, 2020
@johndog
Copy link
Author

johndog commented Aug 27, 2020

@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: #2742 (comment)

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

@ghost ghost added the Needs: Maintainer Attention Maintainer attention needed! label Aug 27, 2020
@johndog
Copy link
Author

johndog commented Aug 27, 2020

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 SydneyhSmith reopened this Sep 1, 2020
@SydneyhSmith
Copy link
Collaborator

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

@SydneyhSmith SydneyhSmith added Area-Debugging Issue-Bug A bug to squash. and removed Needs: Maintainer Attention Maintainer attention needed! Needs-Repro-Info Resolution-Inactive Will close automatically. labels Sep 8, 2020
@jeanph01
Copy link

$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..

@ghost ghost added the Needs: Maintainer Attention Maintainer attention needed! label Oct 27, 2020
@SydneyhSmith SydneyhSmith removed the Needs: Maintainer Attention Maintainer attention needed! label Oct 27, 2020
@oliverroer
Copy link

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:
image

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. 😄

@ghost ghost added the Needs: Maintainer Attention Maintainer attention needed! label Dec 15, 2020
@SydneyhSmith SydneyhSmith removed the Needs: Maintainer Attention Maintainer attention needed! label Jan 12, 2021
@grzegorz-silarski
Copy link

I had something similar while using interactive debugging. Debugger works but interactive terminal hangs and I can't type any word in it. It's basically dead. The connection with this thread is the $ErrorActionPreference variable as this happens whenever it's set to $ErrorActionPreference = [System.Management.Automation.ActionPreference]::Stop.

OS:
MacOS 11.4

Logs from Editor Services:

2021-07-15 11:14:20.648 +02:00 [INF] PowerShell Version: 7.1.3, Edition: Core
2021-07-15 11:14:20.778 +02:00 [WRN] Tried to send request or notification before initialization was completed and will be sent later {"Method":"powerShell/executionStatusChanged","Params":{"ExecutionOptions":{"WriteOutputToHost":false,"WriteErrorsToHost":false,"AddToHistory":false,"InterruptCommandPrompt":false,"WriteInputToHost":false,"InputString":null,"UseNewScope":false,"$type":"ExecutionOptions"},"ExecutionStatus":"Running","HadErrors":false,"$type":"ExecutionStatusChangedEventArgs"},"TraceParent":null,"TraceState":null,"$type":"OutgoingNotification"}
2021-07-15 11:14:20.802 +02:00 [WRN] Tried to send request or notification before initialization was completed and will be sent later {"Method":"powerShell/executionStatusChanged","Params":{"ExecutionOptions":{"WriteOutputToHost":false,"WriteErrorsToHost":true,"AddToHistory":false,"InterruptCommandPrompt":false,"WriteInputToHost":false,"InputString":null,"UseNewScope":false,"$type":"ExecutionOptions"},"ExecutionStatus":"Running","HadErrors":false,"$type":"ExecutionStatusChangedEventArgs"},"TraceParent":null,"TraceState":null,"$type":"OutgoingNotification"}
2021-07-15 11:14:20.826 +02:00 [INF] highlight handler loaded
2021-07-15 11:14:20.940 +02:00 [ERR] Execution of the following command(s) completed with errors:

    Import-Module /Users/grzeg/.vscode/extensions/ms-vscode.powershell-2021.6.2/modules/PowerShellEditorServices/Commands/PowerShellEditorServices.Commands.psd1


2021-07-15 11:14:20.943 +02:00 [WRN] Tried to send request or notification before initialization was completed and will be sent later {"Method":"powerShell/executionStatusChanged","Params":{"ExecutionOptions":{"WriteOutputToHost":false,"WriteErrorsToHost":false,"AddToHistory":false,"InterruptCommandPrompt":false,"WriteInputToHost":false,"InputString":null,"UseNewScope":false,"$type":"ExecutionOptions"},"ExecutionStatus":"Completed","HadErrors":true,"$type":"ExecutionStatusChangedEventArgs"},"TraceParent":null,"TraceState":null,"$type":"OutgoingNotification"}
2021-07-15 11:14:20.962 +02:00 [WRN] Tried to send request or notification before initialization was completed and will be sent later {"Method":"powerShell/executionStatusChanged","Params":{"ExecutionOptions":{"WriteOutputToHost":false,"WriteErrorsToHost":true,"AddToHistory":false,"InterruptCommandPrompt":false,"WriteInputToHost":false,"InputString":null,"UseNewScope":false,"$type":"ExecutionOptions"},"ExecutionStatus":"Completed","HadErrors":false,"$type":"ExecutionStatusChangedEventArgs"},"TraceParent":null,"TraceState":null,"$type":"OutgoingNotification"}
2021-07-15 11:14:21.424 +02:00 [WRN] No ConfigurationItems have been defined, configuration won't surface any configuration from the client!
2021-07-15 11:14:22.204 +02:00 [INF] Unable to find PSSA settings file at '/Users/grzeg/Repos/powershell-practice/PSScriptAnalyzerSettings.psd1'. Loading default rules.
2021-07-15 11:14:22.206 +02:00 [INF] PSScriptAnalyzer settings file not found. Falling back to default rules
2021-07-15 11:20:01.544 +02:00 [ERR] Execution of the following command(s) completed with errors:

    $keys[$i]


2021-07-15 11:20:01.544 +02:00 [WRN] Runtime exception occurred while executing command

$PSVersionTable:

Name                           Value
----                           -----
PSVersion                      7.1.3
PSEdition                      Core
GitCommitId                    7.1.3
OS                             Darwin 20.5.0 Darwin Kernel Version 20.5.0: Sat May  8 05:10:33 PDT 2021; root:xnu-7195.121.3~9/RELEASE_X86_64
Platform                       Unix
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0…}
PSRemotingProtocolVersion      2.3
SerializationVersion           1.1.0.1
WSManStackVersion              3.0

VS Code:
Version: 1.58.1

ms-vscode.powershell:
v2021.6.2

@ghost ghost added the Needs: Maintainer Attention Maintainer attention needed! label Jul 15, 2021
@grzegorz-silarski
Copy link

An update. The issue is with watches like in @oliverroer post.

I'm getting:

2021-07-15 11:37:22.491 +02:00 [INF] PowerShell Version: 7.1.3, Edition: Core
2021-07-15 11:37:22.666 +02:00 [WRN] Tried to send request or notification before initialization was completed and will be sent later {"Method":"powerShell/executionStatusChanged","Params":{"ExecutionOptions":{"WriteOutputToHost":false,"WriteErrorsToHost":false,"AddToHistory":false,"InterruptCommandPrompt":false,"WriteInputToHost":false,"InputString":null,"UseNewScope":false,"$type":"ExecutionOptions"},"ExecutionStatus":"Running","HadErrors":false,"$type":"ExecutionStatusChangedEventArgs"},"TraceParent":null,"TraceState":null,"$type":"OutgoingNotification"}
2021-07-15 11:37:22.695 +02:00 [WRN] Tried to send request or notification before initialization was completed and will be sent later {"Method":"powerShell/executionStatusChanged","Params":{"ExecutionOptions":{"WriteOutputToHost":false,"WriteErrorsToHost":true,"AddToHistory":false,"InterruptCommandPrompt":false,"WriteInputToHost":false,"InputString":null,"UseNewScope":false,"$type":"ExecutionOptions"},"ExecutionStatus":"Running","HadErrors":false,"$type":"ExecutionStatusChangedEventArgs"},"TraceParent":null,"TraceState":null,"$type":"OutgoingNotification"}
2021-07-15 11:37:22.727 +02:00 [INF] highlight handler loaded
2021-07-15 11:37:22.833 +02:00 [ERR] Execution of the following command(s) completed with errors:

    Import-Module /Users/grzeg/.vscode/extensions/ms-vscode.powershell-2021.6.2/modules/PowerShellEditorServices/Commands/PowerShellEditorServices.Commands.psd1


2021-07-15 11:37:22.837 +02:00 [WRN] Tried to send request or notification before initialization was completed and will be sent later {"Method":"powerShell/executionStatusChanged","Params":{"ExecutionOptions":{"WriteOutputToHost":false,"WriteErrorsToHost":false,"AddToHistory":false,"InterruptCommandPrompt":false,"WriteInputToHost":false,"InputString":null,"UseNewScope":false,"$type":"ExecutionOptions"},"ExecutionStatus":"Completed","HadErrors":true,"$type":"ExecutionStatusChangedEventArgs"},"TraceParent":null,"TraceState":null,"$type":"OutgoingNotification"}
2021-07-15 11:37:22.852 +02:00 [WRN] Tried to send request or notification before initialization was completed and will be sent later {"Method":"powerShell/executionStatusChanged","Params":{"ExecutionOptions":{"WriteOutputToHost":false,"WriteErrorsToHost":true,"AddToHistory":false,"InterruptCommandPrompt":false,"WriteInputToHost":false,"InputString":null,"UseNewScope":false,"$type":"ExecutionOptions"},"ExecutionStatus":"Completed","HadErrors":false,"$type":"ExecutionStatusChangedEventArgs"},"TraceParent":null,"TraceState":null,"$type":"OutgoingNotification"}
2021-07-15 11:37:23.350 +02:00 [WRN] No ConfigurationItems have been defined, configuration won't surface any configuration from the client!
2021-07-15 11:37:24.132 +02:00 [INF] Unable to find PSSA settings file at '/Users/grzeg/Repos/powershell-practice/PSScriptAnalyzerSettings.psd1'. Loading default rules.
2021-07-15 11:37:24.135 +02:00 [INF] PSScriptAnalyzer settings file not found. Falling back to default rules
2021-07-15 11:37:46.082 +02:00 [ERR] Execution of the following command(s) completed with errors:

    $keys[$i]

Error #1:
Cannot index into a null array.
ScriptStackTrace:
at <ScriptBlock>, /Users/grzeg/Repos/powershell-practice/scripts/ListAllAzDoProjectsWithDetails.ps1: line 15
at <ScriptBlock>, <No file>: line 1
Exception:
   System.Management.Automation.RuntimeException: Cannot index into a null array.
   at CallSite.Target(Closure , CallSite , Object , Object )
   at System.Dynamic.UpdateDelegates.UpdateAndExecute2[T0,T1,TRet](CallSite site, T0 arg0, T1 arg1)
   at System.Management.Automation.Interpreter.DynamicInstruction`3.Run(InterpretedFrame frame)
   at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)
2021-07-15 11:37:46.100 +02:00 [ERR] Execution of the following command(s) completed with errors:

    $ceny[$keys[$i]]

Error #1:
Cannot index into a null array.
ScriptStackTrace:
at <ScriptBlock>, /Users/grzeg/Repos/powershell-practice/scripts/ListAllAzDoProjectsWithDetails.ps1: line 15
at <ScriptBlock>, <No file>: line 1
Exception:
   System.Management.Automation.RuntimeException: Cannot index into a null array.
   at CallSite.Target(Closure , CallSite , Object , Object )
   at System.Dynamic.UpdateDelegates.UpdateAndExecute2[T0,T1,TRet](CallSite site, T0 arg0, T1 arg1)
   at System.Management.Automation.Interpreter.DynamicInstruction`3.Run(InterpretedFrame frame)
   at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)
2021-07-15 11:41:30.205 +02:00 [ERR] Execution of the following command(s) completed with errors:

    Microsoft.PowerShell.Core\Get-Command Get-AzDoProjectsList -ErrorAction Ignore


2021-07-15 11:43:24.631 +02:00 [ERR] Execution of the following command(s) completed with errors:

    Microsoft.PowerShell.Core\Get-Command Get-AzDoProjectsList -ErrorAction Ignore


2021-07-15 11:43:26.761 +02:00 [ERR] Execution of the following command(s) completed with errors:

    Microsoft.PowerShell.Core\Get-Command Get-AzDoProjectsList -ErrorAction Ignore


2021-07-15 11:43:40.766 +02:00 [ERR] Execution of the following command(s) completed with errors:

    $keys[$i]


2021-07-15 11:43:40.766 +02:00 [WRN] Runtime exception occurred while executing command

I have 3 watches set that values aren't defined in the script I debug:
image

@andyleejordan andyleejordan removed the Needs: Maintainer Attention Maintainer attention needed! label Jul 20, 2021
@andyleejordan
Copy link
Member

We'll come back to this when the debugger implementation is revamped (in PowerShell/PowerShellEditorServices#1295).

@youngr137
Copy link

I tried to reproduce this which was straight forward. I noticed that the console has a debug prompt. Typing 'c' allowed the script to continue. In this sense it is similar to the issue I raised 'PowerShell debugger hangs using F10 (#3410)'.

@ghost ghost added the Needs: Maintainer Attention Maintainer attention needed! label Jul 30, 2021
@andyleejordan
Copy link
Member

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:
image

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. 😄

This is not a bad idea at all, I'll see what I can do.

@andyleejordan andyleejordan removed the Needs: Maintainer Attention Maintainer attention needed! label Aug 10, 2021
@andyleejordan andyleejordan self-assigned this Aug 10, 2021
@andyleejordan andyleejordan added this to the Consider-vNext milestone Aug 10, 2021
@alvicstep
Copy link

I have been struggling with debugging scripts for some time. This fix saved the day.

@ghost ghost added the Needs: Maintainer Attention Maintainer attention needed! label Jan 5, 2022
@andyleejordan andyleejordan removed the Needs: Maintainer Attention Maintainer attention needed! label Jan 5, 2022
@andyleejordan
Copy link
Member

@alvicstep As the most recent person to encounter this, can I ask you if it reproduces with the Preview extension still?

@alvicstep
Copy link

alvicstep commented Jan 5, 2022 via email

@ghost ghost added the Needs: Maintainer Attention Maintainer attention needed! label Jan 5, 2022
@andyleejordan
Copy link
Member

Could you try the Preview extension?

@alvicstep
Copy link

alvicstep commented Jan 10, 2022 via email

@andyleejordan
Copy link
Member

Fantastic, thank you for the confirmation @alvicstep!

@andyleejordan andyleejordan added Resolution-Fixed Will close automatically. and removed Needs: Maintainer Attention Maintainer attention needed! labels Jan 10, 2022
@ghost ghost closed this as completed Jan 10, 2022
@ghost
Copy link

ghost commented Jan 10, 2022

This issue has been marked as fixed. It has been automatically closed for housekeeping purposes.

This issue was closed.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Area-Debugging Issue-Bug A bug to squash. Resolution-Fixed Will close automatically.
Projects
None yet
Development

No branches or pull requests

10 participants