microsoft / vscode

Visual Studio Code
https://code.visualstudio.com
MIT License
163.69k stars 29.07k forks source link

Reattached to the wrong terminal #133542

Closed roblourens closed 1 year ago

roblourens commented 3 years ago

I just reloaded a window with my vscode-jupyter repo open, and it attached to a terminal which is already open in my vscode repo, so now this terminal is open in two windows: Sep-21-2021 09-51-02

The right window is the window that originally owned this terminal

One thing about this terminal is that its cwd is some other folder outside of both workspaces, if that matters.

roblourens commented 3 years ago

I reloaded the left window again, and it reattached to the correct terminal.

image

roblourens commented 2 years ago

Just so you know, this happens pretty often. I just reloaded a window and got some random terminal from another window. Let me know if I can collect any other info

JacksonKearl commented 2 years ago

Also hit this, I believe it was after restarting insiders for an update.

Recording 2022-02-01 at 10 36 21

meganrogge commented 2 years ago

I was able to repro once out of many attempts. I wonder if there's a command to reload all windows to simulate what happens on update? Maybe then I'd see it?

Tyriar commented 2 years ago

@meganrogge exiting the application (cmd+q) and reopening it is essentially what happens on update

JacksonKearl commented 2 years ago

Something similar just happened with the most recent insiders update, but now the terminals aren't synced, it's just that the working directory of one window's terminal is set to the other window's root instead of it's own.

image
JacksonKearl commented 2 years ago

Happened again, accidentally ran a destructive command in the wrong directory :(

cc @Tyriar @meganrogge is there any logging or something I can enable to help you get to the bottom of this?

meganrogge commented 2 years ago

I spent awhile investigating. I don't understand what could be going on here because we store and reconnect to terminals according to the workspaceId. @Tyriar said that he thinks it's a race condition. Setting log level to trace and toggling the shared process would help when it reproes

alexr00 commented 2 years ago

Today I had something new happen:

  1. I had 3 VS Code windows open.
  2. I reloaded window 1.
  3. Window 1 now shares a terminal with window 3! Totally different workspaces.

No other windows were reloaded. No windows were closed. Is there a way I can disable terminal reconnect for local windows? I've also run destructive commands when this happens and I don't want to risk it.

meganrogge commented 2 years ago

Yep, it's not working atm for remote terminals, so:

terminal.integrated.enablePersistentSessions: false
yoyo837 commented 2 years ago

Hello everyone, there is any plan to try to fix it in the nearest milestone?

meganrogge commented 2 years ago

This code that we added for transferring terminals via dnd between windows looks suspicious

https://github.com/microsoft/vscode/blob/d982c14b664f8b6fcd649a31272066f129227306/src/vs/workbench/contrib/terminal/browser/terminalService.ts#L274-L292

meganrogge commented 2 years ago

Has anyone seen this in awhile? I cannot reproduce 😢

roblourens commented 2 years ago

I don't remember seeing it recently

meganrogge commented 2 years ago

Okay pls reopen if you see it again and I'll be happy to debug with anyone that can reproduce it

roblourens commented 2 years ago

Sorry, I cursed myself because this happened again today but I probably won't have consistent repro steps. I reloaded the window with my vscode workspace and got a terminal from this extension sample which is also open in another window, although the terminal panel had not been made visible in that other window's session yet.

I reloaded the window several more times and always got the right terminal after that.

image
meganrogge commented 2 years ago

@roblourens we don't create a terminal until you open the panel, so what do you mean by the terminal had not been made visible yet?

roblourens commented 2 years ago

In case it is important to the issue, I'm just saying that the drop-on-document terminal that was wrongly attached to the vscode window hadn't yet been attached to the drop-on-document window, because it was from some earlier session.

alexr00 commented 2 years ago

I also used to see this periodically but I've had terminal reattach disabled to avoid it. Let me know if it will be helpful and I'll re-enable reattach!

yoyo837 commented 2 years ago

Same as @alexr00

meganrogge commented 2 years ago

Yes it would be very helpful @alexr00. I spent 90 mins yesterday trying to reproduce to no avail. If you could enable trace logging too in case you repro, that might give the insight we need

Tyriar commented 2 years ago

We should review the code around terminal adoption of orphan processes, I suspect the issue is that it's not transactional.

meganrogge commented 2 years ago

it appears we're only doing an orphan check on terminals that are in the workspace as set in the _workspaceLayoutInfos map

Tyriar commented 2 years ago

I think somewhere all unadopted processes get taken by some window? Might not be remembering right though.

Tyriar commented 2 years ago

If you see this again after #152409 lands, please enable trace logging and get the output channel logs for Pty Host and Window.

mjbvz commented 2 years ago

I was seeing this previously on occasion but haven't seen it over the last week so marking as verified

alexr00 commented 2 years ago

+1 on no longer seeing it since re-enabling re-attach a few weeks ago.

alexr00 commented 2 years ago

Just saw this again. The incorrect re-attach occurred on 1 July and I only noticed it today. Pty logs:

[2022-07-01 17:36:53.911] [ptyhost] [warning] Persistent process "2": Process had no disconnect runners but was an orphan
[2022-07-01 17:36:54.202] [ptyhost] [info] Persistent process "2": Replaying 4912 chars and 1 size events
[2022-07-01 17:39:50.808] [ptyhost] [warning] Persistent process "2": Process had no disconnect runners but was an orphan
[2022-07-01 17:39:50.965] [ptyhost] [info] Persistent process "2": Replaying 4861 chars and 1 size events
[2022-07-01 17:40:47.918] [ptyhost] [info] Persistent process "4": The reconnection grace time of 1m has expired, shutting down pid "12472"

Window logs

[2022-07-01 17:38:15.532] [renderer4] [warning] Skipping extension /c:/Users/alros/.vscode-insiders/extensions/ms-vscode.js-debug-1.69.0 in favour of the builtin extension /c:/Program Files/Microsoft VS Code Insiders/resources/app/extensions/ms-vscode.js-debug.
[2022-07-01 17:38:15.533] [renderer4] [warning] Skipping extension /c:/Users/alros/.vscode-insiders/extensions/ms-vscode.vscode-js-profile-table-1.0.1 in favour of the builtin extension /c:/Program Files/Microsoft VS Code Insiders/resources/app/extensions/ms-vscode.vscode-js-profile-table.
[2022-07-01 17:38:15.533] [renderer4] [info] Loading development extension at d:\repos\Microsoft\vscode-pull-request-github
[2022-07-01 17:38:15.534] [renderer4] [critical] Extension 'ms-toolsai.jupyter' wants API proposal 'notebookEditorDecorationType' but that proposal DOES NOT EXIST. Likely, the proposal has been finalized (check 'vscode.d.ts') or was abandoned.
[2022-07-01 17:38:15.561] [renderer4] [warning] [twxs.cmake]: Cannot register 'cmake.cmakePath'. This property is already registered.
[2022-07-01 17:38:15.604] [renderer4] [error] [ms-vscode.vscode-js-profile-flame]: Menu item references a command `extension.js-debug.startProfile` which is not defined in the 'commands' section.
[2022-07-01 17:38:19.034] [renderer4] [error] SyntaxError: Unexpected token A in JSON at position 0
    at JSON.parse (<anonymous>)
    at E.$getPassword (vscode-file://vscode-app/c:/Program%20Files/Microsoft%20VS%20Code%20Insiders/resources/app/out/vs/workbench/workbench.desktop.main.js:1698:49061)
[2022-07-01 17:39:37.770] [renderer4] [error] [Extension Host] You are using the simple (heuristic) fragment matcher, but your queries contain union or interface types. Apollo Client will not be able to accurately map fragments. To make this error go away, use the `IntrospectionFragmentMatcher` as described in the docs: https://www.apollographql.com/docs/react/advanced/fragments.html#fragment-matcher
[2022-07-01 17:39:37.770] [renderer4] [error] [Extension Host] WARNING: heuristic fragment matching going on!
[2022-07-01 17:39:48.684] [renderer4] [warning] Skipping extension /c:/Users/alros/.vscode-insiders/extensions/ms-vscode.js-debug-1.69.0 in favour of the builtin extension /c:/Program Files/Microsoft VS Code Insiders/resources/app/extensions/ms-vscode.js-debug.
[2022-07-01 17:39:48.684] [renderer4] [warning] Skipping extension /c:/Users/alros/.vscode-insiders/extensions/ms-vscode.vscode-js-profile-table-1.0.1 in favour of the builtin extension /c:/Program Files/Microsoft VS Code Insiders/resources/app/extensions/ms-vscode.vscode-js-profile-table.
[2022-07-01 17:39:48.685] [renderer4] [info] Loading development extension at d:\repos\Microsoft\vscode-pull-request-github
[2022-07-01 17:39:48.685] [renderer4] [critical] Extension 'ms-toolsai.jupyter' wants API proposal 'notebookEditorDecorationType' but that proposal DOES NOT EXIST. Likely, the proposal has been finalized (check 'vscode.d.ts') or was abandoned.
[2022-07-01 17:39:48.705] [renderer4] [warning] [twxs.cmake]: Cannot register 'cmake.cmakePath'. This property is already registered.
[2022-07-01 17:39:48.741] [renderer4] [error] [ms-vscode.vscode-js-profile-flame]: Menu item references a command `extension.js-debug.startProfile` which is not defined in the 'commands' section.
[2022-07-01 17:39:51.345] [renderer4] [error] SyntaxError: Unexpected token A in JSON at position 0
    at JSON.parse (<anonymous>)
    at E.$getPassword (vscode-file://vscode-app/c:/Program%20Files/Microsoft%20VS%20Code%20Insiders/resources/app/out/vs/workbench/workbench.desktop.main.js:1698:49061)
[2022-07-04 10:32:16.351] [renderer4] [trace] CommandService#executeCommand setContext
[2022-07-04 10:32:16.352] [renderer4] [trace] [DEBOUNCE: CodeLensProvide] for file:///d%3A/repos/alexr00/playground/test2.js is 250ms
[2022-07-04 10:32:16.592] [renderer4] [trace] [File Watcher (node.js)] [raw] ["change"] globalStorage
[2022-07-04 10:32:16.593] [renderer4] [trace] [File Watcher (node.js)] [CHANGED] c:\Users\alros\AppData\Roaming\Code - Insiders\User\globalStorage
[2022-07-04 10:32:16.593] [renderer4] [trace] [File Watcher (node.js)] [raw] ["change"] globalStorage
[2022-07-04 10:32:16.594] [renderer4] [trace] [File Watcher (node.js)] [CHANGED] c:\Users\alros\AppData\Roaming\Code - Insiders\User\globalStorage
[2022-07-04 10:32:16.647] [renderer4] [trace] [File Watcher (node.js)] >> normalized [CHANGED] c:\Users\alros\AppData\Roaming\Code - Insiders\User\globalStorage
[2022-07-04 10:32:16.649] [renderer4] [debug] User data changed
[2022-07-04 10:32:18.403] [renderer4] [trace] [History stack global-default]: notifyNavigation() (editor: file:///d%3A/repos/alexr00/playground/test2.js, event: user)
[2022-07-04 10:32:18.404] [renderer4] [trace] [History stack global-default]: notifyNavigation() not ignoring (editor: file:///d%3A/repos/alexr00/playground/test2.js, event: user)
[2022-07-04 10:32:18.405] [renderer4] [trace] [History stack global-default]: onSelectionAwareEditorNavigation() (editor: file:///d%3A/repos/alexr00/playground/test2.js, event: user)
[2022-07-04 10:32:18.405] [renderer4] [trace] [History stack global-default]: replace() (editor: file:///d%3A/repos/alexr00/playground/test2.js, event: <none>)
[2022-07-04 10:32:18.406] [renderer4] [trace] [History stack global-default]: index: 2, navigating: false
- group: 0, editor: file:///c%3A/Users/alros/Downloads/schema.docs.graphql, selection: line: 9698-9698, col:  6-6
- group: 0, editor: file:///d%3A/repos/alexr00/playground/test2.js, selection: line: 1-1, col:  1-1
- group: 0, editor: file:///d%3A/repos/alexr00/playground/test2.js, selection: line: 27-27, col:  1-1

[2022-07-04 10:32:19.954] [renderer4] [trace] Started polling file:///c%3A/Users/alros/AppData/Roaming/Code%20-%20Insiders/logs/20220701T173553/output_4_20220701T173948/tasks.log
[2022-07-04 10:32:26.805] [renderer4] [trace] CommandService#executeCommand workbench.output.action.switchBetweenOutputs
[2022-07-04 10:32:26.817] [renderer4] [trace] Stopped polling file:///c%3A/Users/alros/AppData/Roaming/Code%20-%20Insiders/logs/20220701T173553/output_4_20220701T173948/tasks.log
[2022-07-04 10:32:26.834] [renderer4] [trace] Started polling file:///c%3A/Users/alros/AppData/Roaming/Code%20-%20Insiders/logs/20220701T173553/ptyhost.log
[2022-07-04 10:32:31.007] [renderer4] [trace] KeybindingService#dispatch Ctrl+A editor.action.selectAll
[2022-07-04 10:32:31.008] [renderer4] [trace] CommandService#executeCommand editor.action.selectAll
[2022-07-04 10:32:31.008] [renderer4] [trace] Executing Command 'editor.action.selectAll' which has 4 bound.
[2022-07-04 10:32:31.009] [renderer4] [trace] Command 'editor.action.selectAll' was handled by 'code-editor'.
[2022-07-04 10:32:32.080] [renderer4] [trace] KeybindingService#dispatch Ctrl+C editor.action.clipboardCopyAction
[2022-07-04 10:32:32.080] [renderer4] [trace] CommandService#executeCommand editor.action.clipboardCopyAction
[2022-07-04 10:32:32.081] [renderer4] [trace] Executing Command 'editor.action.clipboardCopyAction' which has 6 bound.
[2022-07-04 10:32:32.088] [renderer4] [trace] Command 'editor.action.clipboardCopyAction' was handled by 'code-editor'.
[2022-07-04 10:33:04.166] [renderer4] [trace] KeybindingService#dispatch Shift undefined
[2022-07-04 10:33:04.193] [renderer4] [trace] KeybindingService#dispatch Ctrl undefined
[2022-07-04 10:33:04.193] [renderer4] [trace] KeybindingService#dispatch Shift undefined
[2022-07-04 10:33:04.193] [renderer4] [trace] KeybindingService#dispatch Ctrl undefined
[2022-07-04 10:33:04.198] [renderer4] [trace] KeybindingService#dispatch Shift undefined
[2022-07-04 10:33:04.199] [renderer4] [trace] KeybindingService#dispatch Ctrl undefined
[2022-07-04 10:33:04.208] [renderer4] [trace] [History stack global-default]: notifyNavigation() (editor: file:///d%3A/repos/alexr00/playground/test2.js, event: user)
[2022-07-04 10:33:04.208] [renderer4] [trace] [History stack global-default]: notifyNavigation() not ignoring (editor: file:///d%3A/repos/alexr00/playground/test2.js, event: user)
[2022-07-04 10:33:04.208] [renderer4] [trace] [History stack global-default]: onSelectionAwareEditorNavigation() (editor: file:///d%3A/repos/alexr00/playground/test2.js, event: user)
[2022-07-04 10:33:04.208] [renderer4] [trace] [History stack global-default]: replace() (editor: file:///d%3A/repos/alexr00/playground/test2.js, event: <none>)
[2022-07-04 10:33:04.209] [renderer4] [trace] [History stack global-default]: index: 2, navigating: false
- group: 0, editor: file:///c%3A/Users/alros/Downloads/schema.docs.graphql, selection: line: 9698-9698, col:  6-6
- group: 0, editor: file:///d%3A/repos/alexr00/playground/test2.js, selection: line: 1-1, col:  1-1
- group: 0, editor: file:///d%3A/repos/alexr00/playground/test2.js, selection: line: 24-24, col:  1-1

[2022-07-04 10:33:04.471] [renderer4] [trace] CommandService#executeCommand setContext
[2022-07-04 10:33:04.471] [renderer4] [trace] [DEBOUNCE: CodeLensProvide] for file:///d%3A/repos/alexr00/playground/test2.js is 250ms
[2022-07-04 10:33:12.970] [renderer4] [trace] CommandService#executeCommand workbench.output.action.switchBetweenOutputs
[2022-07-04 10:33:13.001] [renderer4] [trace] Stopped polling file:///c%3A/Users/alros/AppData/Roaming/Code%20-%20Insiders/logs/20220701T173553/ptyhost.log
[2022-07-04 10:33:13.018] [renderer4] [trace] Started polling file:///c%3A/Users/alros/AppData/Roaming/Code%20-%20Insiders/logs/20220701T173553/renderer4.log
lobsterkatie commented 2 years ago

This seemed for a while like it'd stopped happening, but just ran into it again: https://github.com/microsoft/vscode/issues/156207. In my case I'd just reloaded a single window.

alexr00 commented 2 years ago

Just had this happen again, but once again I didn't have trace logging on. I'll try to leave it turned on for next time. Pty Host logs:

[2022-07-26 14:07:06.241] [ptyhost] [warning] Persistent process "1": Process had no disconnect runners but was an orphan
[2022-07-26 14:07:06.570] [ptyhost] [info] Persistent process "1": Replaying 5659 chars and 1 size events
[2022-07-26 14:44:36.944] [ptyhost] [warning] Persistent process "1": Process had no disconnect runners but was an orphan
[2022-07-26 14:44:36.983] [ptyhost] [info] Persistent process "1": Replaying 4909 chars and 1 size events
[2022-07-26 14:44:36.999] [ptyhost] [info] Persistent process "3": Replaying 6314 chars and 1 size events
[2022-07-26 14:44:37.003] [ptyhost] [info] Persistent process "4": Replaying 7534 chars and 1 size events
[2022-07-26 14:45:04.436] [ptyhost] [info] Persistent process "1": Replaying 4909 chars and 1 size events
[2022-07-26 14:45:04.440] [ptyhost] [info] Persistent process "5": Replaying 6408 chars and 1 size events
[2022-07-26 14:45:04.446] [ptyhost] [info] Persistent process "6": Replaying 7534 chars and 1 size events
[2022-07-26 14:45:32.988] [ptyhost] [info] Persistent process "2": The reconnection grace time of 1m has expired, shutting down pid "34528"
[2022-07-26 14:46:43.492] [ptyhost] [info] Persistent process "1": Replaying 4909 chars and 1 size events
[2022-07-26 14:46:43.643] [ptyhost] [info] Persistent process "5": Replaying 6408 chars and 1 size events
[2022-07-26 14:46:43.649] [ptyhost] [info] Persistent process "6": Replaying 7534 chars and 1 size events
[2022-07-26 14:50:59.224] [ptyhost] [info] Persistent process "1": Replaying 4909 chars and 1 size events
[2022-07-26 14:50:59.242] [ptyhost] [info] Persistent process "7": Replaying 10881 chars and 1 size events
[2022-07-26 14:50:59.248] [ptyhost] [info] Persistent process "8": Replaying 9657 chars and 1 size events
[2022-07-26 14:50:59.250] [ptyhost] [info] Persistent process "9": Replaying 2716 chars and 1 size events
[2022-07-26 14:51:44.045] [ptyhost] [info] Persistent process "1": Replaying 4909 chars and 1 size events
[2022-07-26 14:51:44.047] [ptyhost] [info] Persistent process "9": Replaying 2716 chars and 1 size events
[2022-07-26 14:51:44.051] [ptyhost] [info] Persistent process "10": Replaying 10707 chars and 1 size events
[2022-07-26 14:51:44.057] [ptyhost] [info] Persistent process "11": Replaying 9657 chars and 1 size events
[2022-07-26 14:55:55.433] [ptyhost] [info] Persistent process "1": Replaying 4909 chars and 1 size events
[2022-07-26 14:55:55.538] [ptyhost] [info] Persistent process "9": Replaying 2716 chars and 1 size events
[2022-07-26 14:55:55.541] [ptyhost] [info] Persistent process "13": Replaying 4087 chars and 1 size events
[2022-07-26 14:55:55.557] [ptyhost] [info] Persistent process "12": Replaying 3927 chars and 1 size events
[2022-07-26 14:56:41.345] [ptyhost] [info] Persistent process "1": Replaying 4909 chars and 1 size events
[2022-07-26 14:56:41.347] [ptyhost] [info] Persistent process "15": Replaying 0 chars and 1 size events
[2022-07-26 14:58:03.461] [ptyhost] [info] Persistent process "1": Replaying 4909 chars and 1 size events
[2022-07-26 14:58:03.467] [ptyhost] [info] Persistent process "16": Replaying 95 chars and 1 size events
[2022-07-26 15:27:11.370] [ptyhost] [info] Persistent process "21": Replaying 32 chars and 1 size events

Window logs:

[2022-07-26 14:06:58.897] [renderer2] [error] [ms-vscode.remote-repositories]: notebook/cell/executePrimary is a proposed menu identifier. It requires 'package.json#enabledApiProposals: ["notebookEditor"]' and is only available when running out of dev or with the following command line switch: --enable-proposed-api ms-vscode.remote-repositories
[2022-07-26 14:07:03.314] [renderer2] [error] SyntaxError: Unexpected token A in JSON at position 0
    at JSON.parse (<anonymous>)
    at I.$getPassword (vscode-file://vscode-app/c:/Program%20Files/Microsoft%20VS%20Code%20Insiders/resources/app/out/vs/workbench/workbench.desktop.main.js:1705:49637)
[2022-07-26 14:44:13.436] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:44:33.965] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:44:34.923] [renderer2] [error] [ms-vscode.remote-repositories]: notebook/cell/executePrimary is a proposed menu identifier. It requires 'package.json#enabledApiProposals: ["notebookEditor"]' and is only available when running out of dev or with the following command line switch: --enable-proposed-api ms-vscode.remote-repositories
[2022-07-26 14:44:36.434] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:44:36.994] [renderer2] [error] SyntaxError: Unexpected token A in JSON at position 0
    at JSON.parse (<anonymous>)
    at I.$getPassword (vscode-file://vscode-app/c:/Program%20Files/Microsoft%20VS%20Code%20Insiders/resources/app/out/vs/workbench/workbench.desktop.main.js:1705:49637)
[2022-07-26 14:44:38.722] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:44:58.384] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:45:01.227] [renderer2] [error] [ms-vscode.remote-repositories]: notebook/cell/executePrimary is a proposed menu identifier. It requires 'package.json#enabledApiProposals: ["notebookEditor"]' and is only available when running out of dev or with the following command line switch: --enable-proposed-api ms-vscode.remote-repositories
[2022-07-26 14:45:02.502] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:45:03.249] [renderer2] [error] SyntaxError: Unexpected token A in JSON at position 0
    at JSON.parse (<anonymous>)
    at I.$getPassword (vscode-file://vscode-app/c:/Program%20Files/Microsoft%20VS%20Code%20Insiders/resources/app/out/vs/workbench/workbench.desktop.main.js:1705:49637)
[2022-07-26 14:45:03.424] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:45:05.702] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:46:37.505] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:46:40.309] [renderer2] [error] [ms-vscode.remote-repositories]: notebook/cell/executePrimary is a proposed menu identifier. It requires 'package.json#enabledApiProposals: ["notebookEditor"]' and is only available when running out of dev or with the following command line switch: --enable-proposed-api ms-vscode.remote-repositories
[2022-07-26 14:46:41.522] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:46:42.292] [renderer2] [error] SyntaxError: Unexpected token A in JSON at position 0
    at JSON.parse (<anonymous>)
    at I.$getPassword (vscode-file://vscode-app/c:/Program%20Files/Microsoft%20VS%20Code%20Insiders/resources/app/out/vs/workbench/workbench.desktop.main.js:1705:49637)
[2022-07-26 14:46:42.482] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:46:44.951] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:50:52.697] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:50:55.311] [renderer2] [error] [ms-vscode.remote-repositories]: notebook/cell/executePrimary is a proposed menu identifier. It requires 'package.json#enabledApiProposals: ["notebookEditor"]' and is only available when running out of dev or with the following command line switch: --enable-proposed-api ms-vscode.remote-repositories
[2022-07-26 14:50:56.582] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:50:57.630] [renderer2] [error] SyntaxError: Unexpected token A in JSON at position 0
    at JSON.parse (<anonymous>)
    at I.$getPassword (vscode-file://vscode-app/c:/Program%20Files/Microsoft%20VS%20Code%20Insiders/resources/app/out/vs/workbench/workbench.desktop.main.js:1705:49637)
[2022-07-26 14:50:58.169] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:51:00.342] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:51:37.269] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:51:40.340] [renderer2] [error] [ms-vscode.remote-repositories]: notebook/cell/executePrimary is a proposed menu identifier. It requires 'package.json#enabledApiProposals: ["notebookEditor"]' and is only available when running out of dev or with the following command line switch: --enable-proposed-api ms-vscode.remote-repositories
[2022-07-26 14:51:41.614] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:51:42.513] [renderer2] [error] SyntaxError: Unexpected token A in JSON at position 0
    at JSON.parse (<anonymous>)
    at I.$getPassword (vscode-file://vscode-app/c:/Program%20Files/Microsoft%20VS%20Code%20Insiders/resources/app/out/vs/workbench/workbench.desktop.main.js:1705:49637)
[2022-07-26 14:51:43.059] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:51:45.274] [renderer2] [warning] Settings pattern "keyboard.*" doesn't match any settings
[2022-07-26 14:55:51.511] [renderer2] [error] [ms-vscode.remote-repositories]: notebook/cell/executePrimary is a proposed menu identifier. It requires 'package.json#enabledApiProposals: ["notebookEditor"]' and is only available when running out of dev or with the following command line switch: --enable-proposed-api ms-vscode.remote-repositories
[2022-07-26 14:55:54.102] [renderer2] [error] SyntaxError: Unexpected token A in JSON at position 0
    at JSON.parse (<anonymous>)
    at I.$getPassword (vscode-file://vscode-app/c:/Program%20Files/Microsoft%20VS%20Code%20Insiders/resources/app/out/vs/workbench/workbench.desktop.main.js:1705:49637)
[2022-07-26 14:56:37.809] [renderer2] [error] [ms-vscode.remote-repositories]: notebook/cell/executePrimary is a proposed menu identifier. It requires 'package.json#enabledApiProposals: ["notebookEditor"]' and is only available when running out of dev or with the following command line switch: --enable-proposed-api ms-vscode.remote-repositories
[2022-07-26 14:56:40.564] [renderer2] [error] SyntaxError: Unexpected token A in JSON at position 0
    at JSON.parse (<anonymous>)
    at I.$getPassword (vscode-file://vscode-app/c:/Program%20Files/Microsoft%20VS%20Code%20Insiders/resources/app/out/vs/workbench/workbench.desktop.main.js:1705:49637)
[2022-07-26 14:58:01.322] [renderer2] [error] [ms-vscode.remote-repositories]: notebook/cell/executePrimary is a proposed menu identifier. It requires 'package.json#enabledApiProposals: ["notebookEditor"]' and is only available when running out of dev or with the following command line switch: --enable-proposed-api ms-vscode.remote-repositories
[2022-07-26 14:58:03.533] [renderer2] [error] SyntaxError: Unexpected token A in JSON at position 0
    at JSON.parse (<anonymous>)
    at I.$getPassword (vscode-file://vscode-app/c:/Program%20Files/Microsoft%20VS%20Code%20Insiders/resources/app/out/vs/workbench/workbench.desktop.main.js:1705:49637)
[2022-07-26 15:28:22.254] [renderer2] [error] [ms-vscode.remote-repositories]: notebook/cell/executePrimary is a proposed menu identifier. It requires 'package.json#enabledApiProposals: ["notebookEditor"]' and is only available when running out of dev or with the following command line switch: --enable-proposed-api ms-vscode.remote-repositories
[2022-07-26 15:28:22.508] [renderer2] [error] [Extension Host] Extension `ms-python.python` is already registered
[2022-07-26 16:05:38.697] [renderer2] [info] Webgl lost context, disposing of webgl renderer
[2022-07-26 16:05:39.171] [renderer2] [info] Webgl lost context, disposing of webgl renderer
alexdima commented 2 years ago

@Tyriar @meganrogge Could the needed log statement to troubleshoot this on the terminal side be converted to an [info] log. That might help track down this bug sooner.

Tyriar commented 2 years ago

@alexdima they're actually warnings already so they should show up:

[2022-07-26 14:07:06.241] [ptyhost] [warning] Persistent process "1": Process had no disconnect runners but was an orphan

alexdima commented 2 years ago

Just ran into this again. I have the same terminal restored in two distinct windows. I ran into this after restarting to update Insiders on macOS (I had 6 folders opened). The Pty Host log contains the following:

[2022-08-03 21:57:34.961] [ptyhost] [warning] Persistent process "3": Process had no disconnect runners but was an orphan
[2022-08-03 21:57:34.962] [ptyhost] [warning] Persistent process "3": Process had no disconnect runners but was an orphan
[2022-08-03 21:57:35.074] [ptyhost] [info] Persistent process "3": Replaying 937 chars and 1 size events
[2022-08-03 21:57:35.074] [ptyhost] [warning] Persistent process "2": Process had no disconnect runners but was an orphan
[2022-08-03 21:57:35.074] [ptyhost] [warning] Persistent process "4": Process had no disconnect runners but was an orphan
[2022-08-03 21:57:35.144] [ptyhost] [info] Persistent process "3": Replaying 937 chars and 1 size events
[2022-08-03 21:57:35.232] [ptyhost] [info] Persistent process "2": Replaying 154 chars and 1 size events
[2022-08-03 21:57:35.300] [ptyhost] [info] Persistent process "4": Replaying 1653 chars and 1 size events

https://user-images.githubusercontent.com/5047891/182702530-97d5a741-9f64-4a17-aa25-dc4e9f75f957.mp4

Maybe @joaomoreno might know if there's a way to easily simulate a restart caused by an update. Alternatively, maybe you can try changing a setting like "update.mode" which shows the restart prompt. I think this also leads to the terminals attaching incorrectly.

Tyriar commented 2 years ago

Might be related to https://github.com/microsoft/vscode/issues/121926 (maybe not as that's remote only?)

Tyriar commented 2 years ago

I ran into this after restarting to update Insiders on macOS (I had 6 folders opened).

@alexdima this is a little confusing to me. No reconnect is meant to happen on restart, when updating node-pty gets replaced so it can't be running, all processes are torn down and the pty host shuts down with the main process.

Did you see this?

image

Tyriar commented 2 years ago

Changing this to always return isOrphan = true:

https://github.com/microsoft/vscode/blob/49dfe32df2da4db0b43eaf9a2668da5a8133122c/src/vs/platform/terminal/node/ptyService.ts#L399

I can get it to reconnect which is meant to be prevented by one of my other changes.

Tyriar commented 2 years ago

It's a little suspicious that the _revivedPtyIdMap entry doesn't get deleted:

https://github.com/microsoft/vscode/blob/b134ea9ec2b3dbbcc8d56c93c93fec1932432496/src/vs/platform/terminal/node/ptyService.ts#L378-L381

That determines wasRevived here which can bypass the orphan check:

https://github.com/microsoft/vscode/blob/b134ea9ec2b3dbbcc8d56c93c93fec1932432496/src/vs/platform/terminal/node/ptyService.ts#L396-L399

lobsterkatie commented 2 years ago

No reconnect is meant to happen on restart,

I can confirm that within the last two days (both before and after the upgrade to 1.70.0) it has happened to me both on window reload and on full VSCode restart.

alexr00 commented 2 years ago

When I see this it also happen on restart.

Tyriar commented 2 years ago

@lobsterkatie @alexr00 do you see the history restored message when it happens on restart?

alexdima commented 2 years ago

@alexdima this is a little confusing to me. No reconnect is meant to happen on restart, when updating node-pty gets replaced so it can't be running, all processes are torn down and the pty host shuts down with the main process. Did you see this?

Yes, I see this every time when restarting to install a new version (Gear > Restart to Update) or when changing the setting "update.mode":

image
lobsterkatie commented 2 years ago

@lobsterkatie @alexr00 do you see the history restored message when it happens on restart?

I'm 99.9% certain the answer is yes, but I will make sure to notice the next time it happens.

Tyriar commented 2 years ago

Ok, I figured this out. What a journey! Here is the fairly reliable repro:

Note that this is a timing issue and has a chance to not reproduce the problem.


This is what is meant to happen when exiting and restarting the pty host process. Terminal processes are revived (aka. re-created) and their actual pty IDs for this pty host process are mapped to, starting at 1. Notice below how the new IDs start from 1, they just represent the order they are created in which shouldn't matter when reviving.

[2022-08-09 10:37:37.588] [ptyhost] [info] reviveTerminalProcesses', 'terminal id 2 -> newId 1
[2022-08-09 10:37:37.590] [ptyhost] [info] reviveTerminalProcesses', 'terminal id 3 -> newId 2
[2022-08-09 10:37:37.591] [ptyhost] [info] reviveTerminalProcesses', 'terminal id 4 -> newId 3
[2022-08-09 10:37:37.598] [ptyhost] [info] reviveTerminalProcesses', 'terminal id 1 -> newId 4
[2022-08-09 10:37:37.600] [ptyhost] [info] reviveTerminalProcesses', 'terminal id 5 -> newId 5
[2022-08-09 10:37:37.600] [ptyhost] [info] reviveTerminalProcesses', 'terminal id 6 -> newId 6
[2022-08-09 10:37:37.700] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 2 -> revivedPtyId 1
[2022-08-09 10:37:37.700] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 3 -> revivedPtyId 2
[2022-08-09 10:37:37.701] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 4 -> revivedPtyId 3
[2022-08-09 10:37:37.701] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 1 -> revivedPtyId 4
[2022-08-09 10:37:37.701] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 5 -> revivedPtyId 5
[2022-08-09 10:37:37.701] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 6 -> revivedPtyId 6

After that, when reloading windows, terminal processes do not get revived but reconnected to. So an undefined mapping is expected:

[2022-08-09 10:48:20.084] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 1 -> revivedPtyId undefined
[2022-08-09 10:48:20.084] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 2 -> revivedPtyId undefined
[2022-08-09 10:48:20.084] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 3 -> revivedPtyId undefined

What is happening and what is causing this bug as well as a related issue[^1] is that the revived pty ID is cached, so if reloading happens to use a newId that is mapped to a different pty ID in _revivedPtyIdMap, it will reconnect to that one instead:

[2022-08-09 10:40:41.894] [ptyhost] [info] reviveTerminalProcesses', 'terminal id 2 -> newId 1
[2022-08-09 10:40:41.896] [ptyhost] [info] reviveTerminalProcesses', 'terminal id 5 -> newId 2
[2022-08-09 10:40:41.896] [ptyhost] [info] reviveTerminalProcesses', 'terminal id 6 -> newId 3
[2022-08-09 10:40:41.960] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 2 -> revivedPtyId 1
[2022-08-09 10:40:41.960] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 5 -> revivedPtyId 2
[2022-08-09 10:40:41.960] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 6 -> revivedPtyId 3
[2022-08-09 10:40:42.073] [ptyhost] [info] reviveTerminalProcesses', 'terminal id 1 -> newId 4
[2022-08-09 10:40:42.074] [ptyhost] [info] reviveTerminalProcesses', 'terminal id 3 -> newId 5
[2022-08-09 10:40:42.075] [ptyhost] [info] reviveTerminalProcesses', 'terminal id 4 -> newId 6
[2022-08-09 10:40:42.154] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 1 -> revivedPtyId 4
[2022-08-09 10:40:42.154] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 3 -> revivedPtyId 5
[2022-08-09 10:40:42.154] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 4 -> revivedPtyId 6

The above results in:

2 -> 1
5 -> 2
6 -> 3
1 -> 4
3 -> 5
4 -> 6

Then on reload the pty ID mapping occurs instead of being undefined, which causes a reconnect to the wrong pty.

[2022-08-09 10:40:53.471] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 4 -> revivedPtyId 6
[2022-08-09 10:40:53.471] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 5 -> revivedPtyId 2
[2022-08-09 10:40:53.471] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 6 -> revivedPtyId 3
[2022-08-09 10:40:53.507] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 1 -> revivedPtyId 4
[2022-08-09 10:40:53.507] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 2 -> revivedPtyId 1
[2022-08-09 10:40:53.507] [ptyhost] [info] _expandTerminalInstance', 'terminal ID 3 -> revivedPtyId 5

So in the above they get re-mapped, shuffling the order within a window and potentially connecting to a different window's ptys:

2 -> 1 -> 4
5 -> 2 -> 1
6 -> 3 -> 5
1 -> 4 -> 6
3 -> 5 -> 2
4 -> 6 -> 3

image

[^1]: The folder's terminals may not get restored at with the warning "Couldn't get layout info, a terminal was probably disconnected" in the pty host output channel. This started happening due to one of the previous workarounds to prevent 2 windows attaching to the same pty.

lobsterkatie commented 2 years ago

Wow. Nice detective work! Thanks, @Tyriar, looking forward to the fix.

meganrogge commented 1 year ago

Reported here https://github.com/microsoft/vscode/issues/167026

alexr00 commented 1 year ago

I actually saw it again once earlier this week too. It does seem to happen significantly less often than it used to.

alexdima commented 1 year ago

I just ran into this again today. After a restart due to an update, I got a terminal from a folder A showing up by itself in folder B. Here's the only relevant content I found in my logs:

2023-01-03 13:20:22.408 [warning] Persistent process "2": Process had no disconnect runners but was an orphan
2023-01-03 13:20:22.575 [info] Persistent process reconnection "2"
2023-01-03 13:20:23.518 [info] Persistent process "2": Replaying 6148 chars and 1 size events
2023-01-03 13:20:24.340 [warning] Persistent process "2": Process had no disconnect runners but was an orphan
2023-01-03 13:20:24.341 [info] Persistent process reconnection "2"
2023-01-03 13:20:24.392 [info] Persistent process "2": Replaying 6148 chars and 1 size events
2023-01-03 13:20:26.591 [warning] Persistent process "1": Process had no disconnect runners but was an orphan
2023-01-03 13:20:26.591 [info] Persistent process reconnection "1"
2023-01-03 13:20:26.725 [info] Persistent process "1": Replaying 6448 chars and 1 size events
2023-01-03 13:20:28.939 [warning] Persistent process "3": Process had no disconnect runners but was an orphan
2023-01-03 13:20:28.939 [info] Persistent process reconnection "3"
2023-01-03 13:20:29.062 [info] Persistent process "3": Replaying 12539 chars and 1 size events
joaomoreno commented 1 year ago

I hit this today.

Moving this forward to January 2023, since it probably was just lost in the queries by being assigned to August 2022.

alexr00 commented 1 year ago

I've hit this once per day for the past several days. It seems to be occurring more frequently again.

bpasero commented 1 year ago

This would probably be addressed if terminals moved into utility process and there was a message port per terminal: https://github.com/microsoft/vscode/issues/175335