Status bar can dispose commands that are still in use

[sguilliaci]

Type: Bug

The users of our extension do see this error pop-up

It's also present in the console

It happens at random, but can 100% be reproduced by spamming a status bar button that runs a command.

It seems like there is a sleeping bug in the vscode codebase, and our extension is triggering it for some reason.
Note that there isn't an expansion triangle on the pop-up, and that the pop-up does not come from the extension.

The status bar button runs a command that focuses an item in a TreeView. The bug seems to happen only when the tree view is being updated: to reproduce you need to spam the button while the treeview is being refreshed. I'm unsure of the correlation but it's a reliable way to reproduce.

Steps to reproduce

Here are some steps to reproduce, for what it's worth. They're a bit annoying since it requires an account with CircleCI, but all it does is provide a status bar button that we can click.

1. Install https://marketplace.visualstudio.com/items?itemName=circleci.circleci
2. Log in and select a project
3. Re-run a workflow
4. Spam the status bar button ("CircleCI: Running") while the tree view is being updated with the workflow you just re-run
5. Hopefully observe the error pop-up. Otherwise, try again from step 3

If the root cause cannot be identified, could you please provide us with a way for users to not have this error pop-up? Just a console log would be enough.

Relates to #84153

The error comes from here in the vscode codebase:

vscode/src/vs/workbench/api/common/extHostCommands.ts

Line 411 in a8c16a0

return Promise.reject('actual command NOT FOUND');

I cannot attempt to reproduce on insiders because of another pending issue.

VS Code version: Code 1.72.2 (Universal) (d045a5e, 2022-10-12T22:16:30.254Z)
OS version: Darwin arm64 21.4.0
Modes:
Sandboxed: No

System Info

Item	Value
CPUs	Apple M1 Max (10 x 24)
GPU Status	2d_canvas: enabled canvas_oop_rasterization: disabled_off direct_rendering_display_compositor: disabled_off_ok gpu_compositing: enabled metal: disabled_off multiple_raster_threads: enabled_on opengl: enabled_on rasterization: enabled raw_draw: disabled_off_ok skia_renderer: enabled_on video_decode: enabled video_encode: enabled vulkan: disabled_off webgl: enabled webgl2: enabled webgpu: disabled_off
Load (avg)	5, 4, 3
Memory (System)	32.00GB (2.59GB free)
Process Argv	--crash-reporter-id fb2dea6a-4e3a-4679-b6a6-55aae7e25be9
Screen Reader	no
VM	0%

Extensions (8)

Extension	Author (truncated)	Version
Bookmarks	ale	13.3.1
circleci	Cir	1.0.1
vscode-eslint	dba	2.2.6
gitlens	eam	12.2.2
go	gol	0.35.2
remote-ssh	ms-	0.90.1
remote-ssh-edit	ms-	0.84.0
vim	vsc	1.24.2

(1 theme extensions excluded)

A/B Experiments

vsliv368:30146709
vsreu685:30147344
python383cf:30185419
vspor879:30202332
vspor708:30202333
vspor363:30204092
vswsl492:30256859
vslsvsres303:30308271
pythonvspyl392:30443607
vserr242cf:30382550
pythontb:30283811
vsjup518:30340749
pythonptprofiler:30281270
vshan820:30294714
vstes263:30335439
vscoreces:30445986
pythondataviewer:30285071
vscod805cf:30301675
binariesv615:30325510
bridge0708:30335490
bridge0723:30353136
cmake_vspar411:30581797
vsaa593:30376534
pythonvs932:30410667
cppdebug:30492333
vsclangdf:30486550
c4g48928:30535728
dsvsc012cf:30540253
azure-dev_surveyone:30548225
pyindex848cf:30577861
nodejswelcome1:30587005
fc301958:30595537
2e4cg342:30596373

[jrieken]

@bpasero @alexr00 These errors occur when disposing a extension host side command too early, when they are still used in the renderer

[bpasero]

These errors occur when disposing a extension host side command too early, when they are still used in the renderer

Do we know which command is disposed here that triggers the error? Can we print the ID of the command?

[jrieken]

Unfortunately not - it's one command for all (complex) EH side command

[jrieken]

🤔 wait... maybe I can add some debug info here

[reduckted]

I don't know how useful this information will be, but I've started seeing this error in TypeScript workspaces after upgrading to 1.73. It seems to mostly occur after applying a suggestion from the "lightbulb" menu, but I haven't been able to work out how to reproduce it reliably yet.

[jrieken]

#165805 makes the error message better - but the programming mistake is the same. We dispose a "cached" EH command even though it is still used (referenced) in the UI

[sguilliaci]

@jrieken This is what it looks like after your commit

• circleci.statusBarClick is the command that is executed when clicking on the status bar item
• circleci.statusBarClick is not declared in the package.json
• I don't know about the /28 suffix

[bpasero]

@sguilliaci what does "spam the status bar button" mean?

[sguilliaci]

@bpasero By spamming I mean clicking on it multiple times in a row as fast as possible until the problem reproduces

It is possible that the status bar item command is updated every time we click on it

[bpasero]

@sguilliaci that is possible if running the command updates the status bar entry...

[sguillia]

@bpasero Some users of our extension do randomly see the error message while using the extension normally.

Spamming the status bar item that updates its own command is one way to reliably reproduce the issue, but this is just a way to reproduce and is not the core of this bug report.

Since the message comes from VS Code itself, there aren't many options available to us so that our users do not to see the message again. It is not known whether some status bar item clicks are ignored (do not execute the desired command).

[bpasero]

Why do the commands need the /number suffix and change all the time?

[sguilliaci]

@bpasero If the question is for me, I don't know. Our extension is not suffixing the commands.

Regarding the info-needed label, do you need more information from me?

[bpasero]

After a 1on1 with Jo, we found that this command disposal might run too early before the UI was updated:

vscode/src/vs/workbench/api/common/extHostStatusBar.ts

Line 165 in 59f5d55

this._internalCommandRegistration.clear();

Because the update runs with a setTimeout:

vscode/src/vs/workbench/api/common/extHostStatusBar.ts

Line 206 in 59f5d55

this._timeoutHandle = setTimeout(() => {

However I think there is more to it because updating the UI needs to communicate with the renderer process which is async by nature. So I think a better way of disposing the command is when we truly know that it is not used anymore from the renderer.

@sguillia @sguilliaci is it possible that the command that you register with the status bar itself modifies the status bar entry immediately, i.e. sets the command again to the entry?

[sguilliaci]

@bpasero It is possible. At the very least I know we update the status bar frequently

Thanks for investigating

[bpasero]

@sguilliaci we will need a simple hello world snippet to reproduce. I tried this but cannot trigger this, at least on macOS:

export function activate(context: vscode.ExtensionContext) {

	let s: vscode.StatusBarItem;
	let b = false;

	vscode.commands.registerCommand('test-ts.helloWorld', () => {
		if (!s) {
			s = vscode.window.createStatusBarItem();
			s.text = `Command`;
			s.show();
		}

		s.text = `Command`;
		s.command = `test-ts.helloWorld2`;
	});

	vscode.commands.registerCommand('test-ts.helloWorld2', () => {
		s.command = `test-ts.helloWorld`;
		s.text = `Command Changed`;
	});
}

export function deactivate() { }

Can you provide a small snippet that reproduces? My snippet above sets the command each time you click.

[sguilliaci]

@bpasero I can't reproduce using the snippet above either. But with my extension it's easily reproducible. I'm on macOS too.

Do you really need a small snippet, or would a VSIX with a kind of self-reproducing issue do the job?

Meanwhile, the issue can still be reproduced by repeatedly clicking on the status bar item immediatly after re-running or cancelling a workflow with the CircleCI extension

Enregistrement.de.l.ecran.2022-11-25.a.14.28.21.mov

[bpasero]

A standalone snippet would speed this up if you are interested in a fast turnaround. Also I am on macOS, not sure that makes an impact, could be harder to reproduce on macOS.

[VSCodeTriageBot]

This issue has been closed automatically because it needs more information and has not had recent activity. See also our issue reporting guidelines.

Happy Coding!

[sguilliaci]

Creating a standalone snippet will take some time. My colleagues or I will do it at some point. You can park this ticket for now. Thanks for investigating