Hang on startup when awaiting terminal PID

[rjmholt]

Working with current master, I'm getting an occasional (about 50% of the time) hang on startup in Windows PowerShell.

This is again mysterious like the last issue I opened:

However, there's no dispose issue here.

Debugging the progress of this seems to interfere with the possibility of this deadlock occurring.

The log progresses to this point:

2020-02-24 13:57:16.584 -08:00 [DBG] Starting server, deregistering host logger and registering shutdown listener
2020-02-24 13:57:16.842 -08:00 [DBG] Creating LSP transport with endpoint InOut pipe: PSES_lffxipsq.u5q
2020-02-24 13:57:16.848 -08:00 [VRB] Writing session file
2020-02-24 13:57:16.848 -08:00 [VRB] Writing session started
2020-02-24 13:57:16.869 -08:00 [VRB] Assembly resolve event fired for Microsoft.WSMan.Management.resources, Version=3.0.0.0, Culture=en-US, PublicKeyToken=31bf3856ad364e35
2020-02-24 13:57:16.870 -08:00 [VRB] Assembly resolve event fired for Microsoft.WSMan.Management.resources, Version=3.0.0.0, Culture=en-US, PublicKeyToken=31bf3856ad364e35
2020-02-24 13:57:16.906 -08:00 [VRB] Loaded System.Web.Extensions, Version=4.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35
2020-02-24 13:57:16.906 -08:00 [VRB] Loaded System.Web, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a
2020-02-24 13:57:16.920 -08:00 [DBG] Session file written to c:\Users\roholt\Documents\Dev\vscode-PowerShell\sessions\PSES-VSCode-1088-643948 with content:
{"status":"started","languageServiceTransport":"NamedPipe","languageServicePipeName":"\\\\.\\pipe\\PSES_lffxipsq.u5q","debugServiceTransport":"NamedPipe","debugServicePipeName":"\\\\.\\pipe\\PSES_vtetuqus.ss5"}

[rjmholt]

Ok, think this was a stale build from the last issue. Trying to reproduce it isn't working.

[rjmholt]

Right I just got it again...

[rjmholt]

Adding some logging I see this:

2020-02-24 15:04:44.921 -08:00 [DBG] Starting server, deregistering host logger and registering shutdown listener
2020-02-24 15:04:44.925 -08:00 [DBG] Creating LSP transport with endpoint InOut pipe: PSES_ug0cnlp3.eig
2020-02-24 15:04:44.927 -08:00 [VRB] Creating named pipe
2020-02-24 15:04:44.927 -08:00 [VRB] Waiting for named pipe connection
2020-02-24 15:04:44.932 -08:00 [VRB] Writing session file
2020-02-24 15:04:44.932 -08:00 [VRB] Writing session started
2020-02-24 15:04:44.956 -08:00 [VRB] Assembly resolve event fired for Microsoft.WSMan.Management.resources, Version=3.0.0.0, Culture=en-US, PublicKeyToken=31bf3856ad364e35
2020-02-24 15:04:44.956 -08:00 [VRB] Assembly resolve event fired for Microsoft.WSMan.Management.resources, Version=3.0.0.0, Culture=en-US, PublicKeyToken=31bf3856ad364e35
2020-02-24 15:04:44.985 -08:00 [VRB] Loaded System.Web.Extensions, Version=4.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35
2020-02-24 15:04:44.985 -08:00 [VRB] Loaded System.Web, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a
2020-02-24 15:04:45.011 -08:00 [DBG] Session file written to c:\Users\roholt\Documents\Dev\vscode-PowerShell\sessions\PSES-VSCode-1088-415802 with content:
{"status":"started","languageServiceTransport":"NamedPipe","languageServicePipeName":"\\\\.\\pipe\\PSES_ug0cnlp3.eig","debugServiceTransport":"NamedPipe","debugServicePipeName":"\\\\.\\pipe\\PSES_112m3xey.pzc"}
2020-02-24 15:04:45.011 -08:00 [VRB] Waiting on PSES run/shutdown

It seems we are left waiting for the named pipe connection for some reason

[rjmholt]

It seems the backend is working properly here but the client is not connecting to the named pipe...

[rjmholt]

Log points showing we are stuck here:

vscode-powershell/src/process.ts

Line 125 in 17d9a59

const terminalPid = await this.consoleTerminal.processId;

Pausing in the debugger shows us intimers.js...

[TylerLeonhardt]

@rjmholt anything else useful in that pause? Maybe we should bring Danial in since it's terminal related?

[rjmholt]

Unfortunately there's really not much to go on. When I next reproduce it I'll take a full screenshot

[SeeminglyScience]

@rjmholt does it look like this?

I have that every time I open certain workspaces. Maybe related to number of files or number of open editors. Pictured is PowerShell/PowerShell, happens every reload. This is PowerShell 7.

If I Enter-PSHostProcess, there's only one runspace and the Start-EditorCantRememberTheRest cmdlet is what's in the current command processor.

[rjmholt]

I have that every time I open certain workspaces. Maybe related to number of files or number of open editors. Pictured is PowerShell/PowerShell, happens every reload. This is PowerShell 7.

Yeah the terminal looks like that (although I see all the diagnostic logs). I'm also testing it with PowerShell/PowerShell and WinPS + PS7, but only get it occasionally.

As I debug it, the server side seems to be behaving correctly; the reason you're only seeing the single runspace and that cmdlet is because we're still in there waiting for the client to connect. So the terminal prints the banner and then is left waiting for something from the named pipe to progress.

But VSCode isn't connecting, because it seems to be stuck waiting for the terminal PID. It never proceeds to named pipe connection.

[rjmholt]

I wonder if this is actually a symptom of #2377 or at least related to it

[rjmholt]

@Tyriar, just quickly, does #2491 (comment) look at all familiar to you?