Vscode: CodeLens error: "actual command NOT FOUND"

[eamodio]

Issue Type: Bug

I just starting seeing this very recently and it only happens sporadically. But when I click on a CodeLens (from GitLens, or references), sometimes instead of running the command I get a notification that says actual command NOT FOUND. But if I try it again it works.

Nothing useful in the console:

VS Code version: Code - Insiders 1.40.0-insider (86405ea23e3937316009fc27c9361deee66ffbf5, 2019-11-06T16:58:49.777Z)
OS version: Windows_NT x64 10.0.19018

System Info

|Item|Value|
|---|---|
|CPUs|Intel(R) Core(TM) i7-6700K CPU @ 4.00GHz (8 x 4008)|
|GPU Status|2d_canvas: enabled
flash_3d: enabled
flash_stage3d: enabled
flash_stage3d_baseline: enabled
gpu_compositing: enabled
metal: disabled_off
multiple_raster_threads: enabled_on
oop_rasterization: disabled_off
protected_video_decode: unavailable_off
rasterization: enabled
skia_renderer: disabled_off
surface_control: disabled_off
surface_synchronization: enabled_on
video_decode: enabled
viz_display_compositor: enabled_on
viz_hit_test_surface_layer: disabled_off
webgl: enabled
webgl2: enabled|
|Load (avg)|undefined|
|Memory (System)|31.93GB (16.71GB free)|
|Process Argv||
|Screen Reader|no|
|VM|0%|

[madig]

The same has been happening for 1.39.x for me I think with the Python plugin, when clicking on the "Run Test | Debug Test" pop-in things above test functions, usually when I save/edit in quick succession.

[jrieken]

This will be tricky without steps or traces... The last changes (I am aware of) happened ~5 months ago when we stopped spying on garbage collection and now manually dispose. What happens is that we create a fake command for UX which triggers the actual command (we do that to avoid serialising command arguments) and those fake command get disposed when code lenses go away. @eamodio Do you you recall if this happened after switching editors (e.g model change) or did this happen after opening an editor or after having typed in it?

[eamodio]

Here are the steps where I've seen it happen (when trying to repro):

1. Open an editor for file A
2. Open an editor for file B and let the code lens load
3. Close the editor for file B
4. Open the editor for file B, and as quickly as you can click on a code lens

[jrieken]

Using workbench-tabs and all in one group I assume, right?

[eamodio]

Yup

[jrieken]

Hm, I was able to produce yet.. I have pushed a commit that adds trace logging to the extension host commands converter. My theory is that there is a sequence like this: create, dispose, execute. Maybe this is when code lenses have been restored from cache and when not yet being refreshed, e.g when clicking a stale lens.

[jrieken]

Ok - this repos easy when delaying all code lens provider by a few seconds, e.g adding await timeout(4000). I believe this is clicking on a code lens that has been restored from cache but for which the command has been disposed already. From the logs

2019-11-08 10:27:32.996] [exthost] [trace] [eamodio.gitlens] provider DONE after 0ms
[2019-11-08 10:27:34.541] [exthost] [trace] [eamodio.gitlens] INVOKE provider 'CodeLensAdapter'
[2019-11-08 10:27:34.541] [exthost] [trace] CommandsConverter#DISPOSE 6
[2019-11-08 10:27:34.541] [exthost] [trace] CommandsConverter#DISPOSE 7
[2019-11-08 10:27:34.541] [exthost] [trace] CommandsConverter#DISPOSE 8
[2019-11-08 10:27:34.541] [exthost] [trace] CommandsConverter#DISPOSE 9
[2019-11-08 10:27:34.541] [exthost] [trace] CommandsConverter#DISPOSE 10
...
...
[2019-11-08 10:27:41.218] [exthost] [trace] CommandsConverter#EXECUTE 9 MISSING
[2019-11-08 10:27:42.982] [exthost] [trace] [eamodio.gitlens] provider DONE after 4005ms
[2019-11-08 10:27:44.454] [exthost] [trace] [eamodio.gitlens] provider DONE after 4010ms
[2019-11-08 10:27:44.709] [exthost] [trace] [eamodio.gitlens] INVOKE provider 'CodeLensAdapter'

[jrieken]

So, the problem is that we cache actual code lenses, shallow copy them, dispose the true result, and later use the shallow copy to reduce flicker when switching back to a previous editor. We can (a) not dispose a model while it's being cached or (b) restore lenses from cache but disable their commands, e.g clicking them will be a no-opt. I tend to go for (a)

[jrieken]

I have not pushed a commit for option (b) as option (a) turned out to be a little more tricky... Now, when restoring lenses from cache we show labels but the commands aren't active, meaning you cannot click them until (re)confirmed from the extension. That means we nicely cleanup garbage and don't get into those "command not found" situations.

Anyways, keeping this open for now. I might come up with an idea for option (a) that actually works and doesn't leak ⛲️

[DanTup]

Sounds like this is already understood/fixed, but FWIW I started seeing it today too, using the test run/debug links in the Dart extension. Clicking to run a test worked fine, then I F12'd into a definition, and came back, and now it gives the error. Seems to fit with the description above.

[jrieken]

and with what version of VS Code does this happen @DanTup

[DanTup]

Current stable. Sorry - I didn't mean to suggest the fix didn't work, was just adding the info I had since I'd come here to open an issue and thought it worth noting :-)

FWIW, I just tested in latest insiders and was unable to repro using the same steps that seemed to repro in stable 👍

[DanTup]

@jrieken I'm trying to track down some flaky integration tests in Dart-Code and I just had this one:

  1) test_code_lens
       includes run/debug actions for tests:
     TypeError: Cannot read property 'title' of undefined
      at D:\a\Dart-Code\Dart-Code\src\test\dart\providers\test_code_lens_provider.test.ts:19:62

I called vscode.executeCodeLensProvider and the returned items were missing their command object entirely. I'm not sure whether it's related to this, or whether it might be https://github.com/microsoft/vscode/issues/45124 again (which you added a workaround for, but I think it's timing-based).

(it was running on GH Actions on Windows - they're not the fastest machines)

[damolina-stripe]

We are seeing this behavior in 1.40.2 (MacOS), when switching quickly to a tab (i.e. not new) and clicking on our CodeLens command _immediately_. We only implement CodeLensProvider.provideCodeLenses with no async work and return a fully resolved CodeLens instance (i.e. with CodeLens.command set). The reason I bring that up is that not setting command and instead follow the pattern the CodeLens sample uses seems to avoid the problem.

From @jrieken comments, it might at we are hitting the transition time between the cached and new instance of the CodeLens. If so, it seems what he mentioned as option b) might be needed when a CodeLens is resolved. Still digging through codelensController.ts to understand better the problem.

As reference, this is the call stack I see:

notificationsAlerts.ts:40 actual command NOT FOUND
onDidNotificationChange @   notificationsAlerts.ts:40
(anonymous) @   notificationsAlerts.ts:26
fire    @   event.ts:580
addNotification @   notifications.ts:171
error   @   notificationService.ts:57
(anonymous) @   codelensController.ts:215
processTicksAndRejections   @   internal/process/task_queues.js:89
Promise.catch (async)       
(anonymous) @   codelensController.ts:215
fire    @   event.ts:580
n.onMouseUp @   codeEditorWidget.ts:1472
emitMouseUp @   viewOutgoingEvents.ts:94
emitMouseUp @   viewController.ts:306
_onMouseUp  @   mouseHandler.ts:208
(anonymous) @   mouseHandler.ts:106
(anonymous) @   editorDom.ts:110

[damolina-stripe]

It seems behavior was fixed on 1.41 and CodeLens is rendered but disabled until loaded again.

[jrieken]

Closing as the fix described above (https://github.com/microsoft/vscode/issues/84153#issuecomment-551584568) seems to be working

[bonaluo]

My vscode version is 1.41.1 but it still warn "actual comand not found",whether the new version can solve this problem