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?

[rjmholt]

@sdwheeler

[Tyriar]

Haven't had any reports of processId not resolving on my end.

[sdwheeler]

@rjmholt The workaround build you provided resolved my hang.

[rjmholt]

Fixed in #2498

[rjmholt]

Just to document a bit more, I can reproduce this with the following change from d431617:

diff --git a/src/process.ts b/src/process.ts
index aa957b5..b70966e 100644
--- a/src/process.ts
+++ b/src/process.ts
@@ -128,7 +128,9 @@ export class PowerShellProcess {

         // Log that the PowerShell terminal process has been started
         this.log.write("Registering terminal PID log callback");
-        this.consoleTerminal.processId.then((pid) => this.logTerminalPid(pid, pwshName));
+        const pid = await this.consoleTerminal.processId;
+        this.logTerminalPid(pid, pwshName);
+        // this.consoleTerminal.processId.then((pid) => this.logTerminalPid(pid, pwshName));

         return sessionDetails;
     }

So startup pauses, since the client never opens a named pipe. The debugging the server shows it waiting on a named pipe connection.

In the client, pausing the debugger shows us stopped here:

For whatever reason we are left awaiting the processId value.

I've only seen reports of this on Windows.