vscode.executeCodeLensProvider sometimes only contains the range and not title/commands

[DanTup]

I've started seeing intermittent failures in some of my code-lens tests like "command doesn't exist on undefined".

I added some debug logging, and have discovered that sometimes the results from vscode.executeCodeLensProvider contain only a range and no other confirmation.

Here's what my test code looks like:

const cls = await (vs.commands.executeCommand("vscode.executeCodeLensProvider", document.uri, 50) as Thenable<vs.CodeLens[]>);

// TEMP DEBUG
for (const cl of cls) {
	if (!cl.command) {
		throw new Error(`Got code lens without a command! ${JSON.stringify(cl)}`);
	}
}

And it's printing this sometimes:

Error: Got code lens without a command! {"range":[{"line":3,"character":2},{"line":18,"character":4}]}

The ranges match up with what I expect from the provider (and I get the expected count), but there's no way my provider can return ranges without commands - the code looks like this:

return [
	new CodeLens(
		toRange(document, test.offset, test.length),
		{
			arguments: [test],
			command: "_dart.startWithoutDebuggingTestFromOutline",
			title: "Run",
		},
	),
	new CodeLens(
		toRange(document, test.offset, test.length),
		{
			arguments: [test],
			command: "_dart.startDebuggingTestFromOutline",
			title: "Debug",
		},
	),
].concat(runTestTemplates.map((t) => new CodeLens(
	toRange(document, test.offset, test.length),
	{
		arguments: [test, t],
		command: t.template === "run-test" ? "_dart.startWithoutDebuggingTestFromOutline" : "_dart.startDebuggingTestFromOutline",
		title: t.name,
	},
)));

It's not consistent - these results show it failed for 1 of 4 tests on macOS, but passed on Windows and Linux:

I've run the tests repeatedly locally but cannot reproduce (it's on Travis where I see it mostly). It feels like a race condition, but I can't figure out why. I don't use resolve, but I tried passing 50 for the number of items to resolve, but it hasn't helped.

[DanTup]

Oh, seems like this has come up before - though marked as fixed for 1.36 (this is happening in both 1.37.1 and insiders):

#75208

This needs some ugly setTimeout-tricks so that the results are only disposed after.

@jrieken is it expected that there are still races here and this is a bug, or is it known to still have issues?

[vscodebot]

We have a great developer community over on slack where extension authors help each other. This is a great place for you to ask questions and find support.

Happy Coding!

[jrieken]

It depends on itemResolveCount which is 50 in your test and likely not enough

[DanTup]

@jrieken there are only 4 code lens items - why would I need more than 50?

[DanTup]

Actually, that's not quite accurate - there are 28 when I run locally (I filter them to the ones I care about, which is 2-4).

I'll try increasing it to see if the issue goes away - though is it expected that resolve matters here anyway if the provide does not use resolve and always returns the full object?

[jrieken]

Well, that's all I can speculate given the lack of a code sample that reliability reproduces this.

[DanTup]

@jrieken seems it's not that, as I bumped it to 500 and still see the failure. I tweaked the log to include the count as well as the full response.

I appreciate it's hard to debug something that's intermittent, but it seems like there's a bug.

Is there anything more I can do to help track it down?

Got code lens without a command! {
    "range": [
        {
            "line": 3,
            "character": 2
        },
        {
            "line": 18,
            "character": 4
        }
    ]
}


Full response (28 items) was:[
    {
        "range": [
            {
                "line": 3,
                "character": 2
            },
            {
                "line": 18,
                "character": 4
            }
        ]
    },
  // snip

[jrieken]

Is there anything more I can do to help track it down?

Yeah, providing an extension that reproduces this 🤓 The command implementation is pretty simple, calling into provide/resolve which I have confidence that they are working

[DanTup]

Yeah, providing an extension that reproduces this 🤓

Here:

https://github.com/DanTup/vscode-repro-79805

It's a very basic project that creates a code lens provider that returns 30 items with commands. There's a test that runs 20 times that just calls for the code lens, with resolveCount=50, prints the number of results and fails if any of them did not have the command attached.

Here are results on Travis (it's intermittent on Travis, and I haven't seen it at all locally):

https://travis-ci.org/DanTup/vscode-repro-79805/builds/577285247

On attempt 15, got 30 code lens
  ✓ test_code_lens includes run/debug actions for tests (15): 317ms
On attempt 16, got 30 code lens
  1) test_code_lens includes run/debug actions for tests (16)
On attempt 16, got a code lens without any command! {
    "range": [
        {
            "line": 0,
            "character": 0
        },
        {
            "line": 0,
            "character": 1
        }
    ]
}
On attempt 17, got 30 code lens
  ✓ test_code_lens includes run/debug actions for tests (17): 321ms

The command implementation is pretty simple, calling into provide/resolve which I have confidence that they are working

I don't use resolve and the commands are in the original items, so it looks like that code wouldn't do much - I think it might br going wrong elsewhere.

[jrieken]

Thanks. I can reproduce, weirdly when running the unit test as command it always happens on the last run. It never happens when not having arguments to the command, so this is likely an issue with how we cache command arguments

[DanTup]

it always happens on the last run

I'm not sure how it'd know it's the last run, but glad you can repro! Let me know if you need anything more or want me to test a fix.

[jrieken]

This is the backstory: When having code lens with commands with arguments we don't serialise the arguments but we create command-placeholders (using the same UX properties) that behind the scenes invoke the 'real' command. That helps to prevent sending unnecessary data around and helps in cases the data cannot be serialised at all.

The (internal) code lens API manages the lifecycle, e.g. there is CodeLensList#dispose. For instance, the editor-based code lens controller disposes current result whenever it receives and resolves the N+1 list. For the API commands the story is different because the lifecycle is all that clear. The current logic calls dispose in a timeout after returning the result, e.g the result travels back to the extension host and is followed by a message to dispose said result. Now that seems to be happening a little too early, there is another message promise inbetween that seems to mess with those messages.

[jrieken]

Turns out that also executeCommand yields one more time than expected. This gives two chances to receive the release-message before returning the command result

[jrieken]

This isn't very nice but instead of disposing via setTimeout(..., 0) I am pushing a change to dispose only after 100ms. That should give the extension host enough time to process microticks. There is still a theoretical chance of this going back but a 100%-correct fix would mean to send back a message that the command has successfully returned its result etc.

[jrieken]

This is related to/the better fix for #75208

[DanTup]

Thanks for the digging! I just saw a similar failure in code actions in my tests, but looking at your change, I think that had the same issue and now has the same workaround now too?

[CI] TypeError: Cannot read property 'command' of undefined
    at Object.<anonymous> (src/test/dart_only/providers/fix_code_action_provider.test.ts:20:63)
    at Generator.next (<anonymous>)
    at fulfilled (out/src/test/dart_only/providers/fix_code_action_provider.test.js:4:58)

[jrieken]

yeah, very likely the same issue