Restarting the pty host breaks logging completely

[Tyriar]

Needs #185254 to be fixed to reproduce the issue

Repro:

1. Set log level of "Pty Host" specifically to trace
2. Create a terminal to verify trace logs show up in pty host channel
3. Run the restart pty host command
4. Create a terminal to verify trace logs show up in pty host channel, 🐛 they don't show up

[Tyriar]

@sandy081 some help would be appreciated here. When the process is restarted the logging just stops working completely.

Here's where the utility process environment is created:

vscode/src/vs/platform/terminal/electron-main/electronPtyHostStarter.ts

Lines 79 to 88 in 92921a0

	const config: { [key: string]: string } = {
	...deepClone(process.env),
	VSCODE_LAST_PTY_ID: String(lastPtyId),
	VSCODE_AMD_ENTRYPOINT: 'vs/platform/terminal/node/ptyHostMain',
	VSCODE_PIPE_LOGGING: 'true',
	VSCODE_VERBOSE_LOGGING: 'true', // transmit console logs from server to client,
	VSCODE_RECONNECT_GRACE_TIME: String(this._reconnectConstants.graceTime),
	VSCODE_RECONNECT_SHORT_GRACE_TIME: String(this._reconnectConstants.shortGraceTime),
	VSCODE_RECONNECT_SCROLLBACK: String(this._reconnectConstants.scrollback),
	};

Here's the logger initialization on the pty host proc:

vscode/src/vs/platform/terminal/node/ptyHostMain.ts

Lines 64 to 67 in 92921a0

	const loggerService = new LoggerService(getLogLevel(environmentService), environmentService.logsHome);
	server.registerChannel(TerminalIpcChannels.Logger, new LoggerChannel(loggerService, () => DefaultURITransformer));
	const logger = loggerService.createLogger('ptyhost', { name: localize('ptyHost', "Pty Host") });
	const logService = new LogService(logger, [new ConsoleLogger()]);

If you try repro you'll need this change #185882

[sandy081]

I can reproduce it. 👀

[sandy081]

It seems pty process is creating the log file in a new folder instead in the logs home folder.

It is because a new logsPath folder is getting passed to the pty process from main process. Fixing that would fix this.

[Tyriar]

Weird. Thanks, I'll look into that

[sandy081]

This is causing following regression - only last 5 log sessions are being retained instead of 10. Hence moved it to current milestone and prepared a fix for it.

[meganrogge]

so the logs do show up, but the terminal doesn't seem to get created correctly - I cannot type in it.

EDIT: after restarting the pty host, I cannot type in any of the terminals.

Screen.Recording.2023-06-29.at.11.29.30.AM.mov

2023-06-29 11:29:17.471 [trace] node-pty.IPty#onData �]2;meganrogge@Megans-MacBook-Pro:~/Repos/vscode��]1;~/Repos/vscode�
2023-06-29 11:29:17.471 [trace] node-pty.IPty#onData �]633;D�
2023-06-29 11:29:17.473 [trace] node-pty.IPty#onData �]633;P;Cwd=/Users/meganrogge/Repos/vscode�
2023-06-29 11:29:17.478 [debug] CommandDetectionCapability#handleCommandFinished 0 0 undefined {"commandFinishedMarker":{"line":0,"isDisposed":false,"_disposables":[{"_listeners":[null],"_disposed":false},{},{},{},{}],"_id":151,"_onDispose":{"_listeners":[null],"_disposed":false}}}
2023-06-29 11:29:17.903 [trace] node-pty.IPty#onData 
�[0m�[27m�[24m�[J�]633;A��[01;32m➜  �[36mvscode�[00m �[01;34mgit:(�[31mmerogge/help-dispose�[34m)�[00m �]633;B��[K
2023-06-29 11:29:17.904 [trace] node-pty.IPty#onData �[?1h�=
2023-06-29 11:29:17.904 [trace] node-pty.IPty#onData �[?2004h
2023-06-29 11:29:17.912 [debug] CommandDetectionCapability#handlePromptStart 0 0
2023-06-29 11:29:17.912 [debug] CommandDetectionCapability#handleCommandStart 37 0
2023-06-29 11:29:48.316 [trace] [RPC Request] PtyService#setTerminalLayoutInfo({"workspaceId":"dbca792c1c3bf28acacb2a58cb095ae0","tabs":[{"isActive":true,"activePersistentProcessId":14,"terminals":[{"relativeSize":0.2495075508864084,"terminal":1},{"relativeSize":0.2495075508864084,"terminal":14},{"relativeSize":0.2495075508864084,"terminal":13},{"relativeSize":0.25147734734077476,"terminal":2}]}]})
2023-06-29 11:29:48.316 [trace] [RPC Response] PtyService#setTerminalLayoutInfo undefined

[meganrogge]

the terminal created before the pty host restarted receives input but does not display it. the one created after it restarted does not receive it.

input.mov

[meganrogge]

I don't see this log

vscode/src/vs/workbench/contrib/terminal/electron-sandbox/localTerminalBackend.ts

Line 85 in 1e4479d

this._logService.debug('Starting pty host');

[meganrogge]

I ran it again and now can type in the terminals, but there are no logs happening when I type or create a new terminal

[Tyriar]

As long as the regression @sandy081 fixed in #185875 (comment) is good, this is low priority. Will check it out again in July.

[Tyriar]

Flaky repro, but sometimes a window might not ack the restart. See the bg window correctly shows the restart and relaunches, but the fg doesn't:

Restarting again fixes it, I can't repro any problem with the log not working though.

[Tyriar]

Weird, when this happens data events aren't getting fired for just one window:

[Tyriar]

On input in the broken terminal:

[Tyriar]

The 2 windows are connected to 2 different pty hosts:

[Tyriar]

I'm closing this issue off again as the logging problem was fixed in the linked commit. I investigated the problem @meganrogge hit and created some more targeted issues to fix:

• Restarting the pty host does not kill the old pty host #186772
• Restarting the pty host can permanently break the connection for some windows #186773
• Pty host tracing doesn't log exception responses #186775