Extension activation reports success before commands get registered

[int19h]

vscode-python/src/client/extension.ts

Lines 54 to 72 in 893b44f

	export async function activate(context: IExtensionContext): Promise<IExtensionApi> {
	let api: IExtensionApi;
	let ready: Promise<void>;
	let serviceContainer: IServiceContainer;
	try {
	[api, ready, serviceContainer] = await activateUnsafe(context, stopWatch, durations);
	} catch (ex) {
	// We want to completely handle the error
	// before notifying VS Code.
	await handleError(ex, durations);
	throw ex; // re-raise
	}
	// Send the "success" telemetry only if activation did not fail.
	// Otherwise Telemetry is send via the error handler.
	sendStartupTelemetry(ready, durations, stopWatch, serviceContainer)
	// Run in the background.
	.ignoreErrors();
	return api;
	}

Note that this code does not await ready. It does await the return value of activateUnsafe(), but that's not the same thing.

The effect is that when activate() returns, our command handlers might not actually be registered yet, and so if something tries to invoke them, it fails. One particular case where this can be consistently observed is our interaction with the Docker extension - in its debug configuration resolver, if the config is for Python, it uses VSCode API to activate vscode-python, and then assumes that it can return ${command:python.interpreterPath} in the config and have it properly expanded. But, because of the race condition, it often ends up as a blank string.

I believe the same is potentially possible with any command that we register under "activationEvents" in our manifest, since VSCode does essentially the same - activate(), then try to locate the command handler and execute it. This might be the root cause of #12072 and similar.

[DonJayamanne]

Most of the activation & command registration happens in activate methods of classes.
Classes that implement IExtensionActivationService or IExtensionSingleActivationService have activate methods, those get executed & we await on them (those were created so we await on those explicity).

I thought we used to await on them, I know we had similar problems in the past wit DS commands..
We might have the same problem in the Jupyter extension. Thanks for identifying this, will fix at our end.

[int19h]

The problem is that the await chain gets broken at the point where there's a (what looks like intentional?) nested promise. Here's how this goes: activate calls and awaits activateUnsafe, which calls and awaits activationComponents:

vscode-python/src/client/extension.ts

Line 106 in 893b44f

const { activationPromise } = await activateComponents(context, serviceManager, serviceContainer);

Note how it awaits on the call itself, but that yields an object that contains another promise. That inner promise corresponds to all those IExtensionActivationService implementations:

vscode-python/src/client/extensionActivation.ts

Lines 165 to 167 in 893b44f

	const manager = serviceContainer.get<IExtensionActivationManager>(IExtensionActivationManager);
	context.subscriptions.push(manager);
	const activationPromise = manager.activate();

vscode-python/src/client/extensionActivation.ts

Line 216 in 893b44f

return { activationPromise };

vscode-python/src/client/activation/activationManager.ts

Lines 53 to 61 in 893b44f

	public async activate(): Promise<void> {
	await this.initialize();
	// Activate all activation services together.
	await Promise.all([
	Promise.all(this.singleActivationServices.map((item) => item.activate())),
	this.activateWorkspace(this.activeResourceService.getActiveResource())
	]);
	await this.autoSelection.autoSelectInterpreter(undefined);
	}

And we do actually await on it, but only in the telemetry codepath that gets spawned from activate(), to measure how long the extension took to load:

vscode-python/src/client/startupTelemetry.ts

Lines 32 to 51 in 893b44f

	export async function sendStartupTelemetry(
	// tslint:disable-next-line:no-any
	activatedPromise: Promise<any>,
	durations: Record<string, number>,
	stopWatch: IStopWatch,
	serviceContainer: IServiceContainer
	) {
	if (isTestExecution()) {
	return;
	}
	try {
	await activatedPromise;
	durations.totalActivateTime = stopWatch.elapsedTime;
	const props = await getActivationTelemetryProps(serviceContainer);
	sendTelemetryEvent(EventName.EDITOR_LOAD, durations, props);
	} catch (ex) {
	traceError('sendStartupTelemetry() failed.', ex);
	}
	}

And activate() explicitly doesn't await telemetry:

vscode-python/src/client/extension.ts

Lines 58 to 71 in 893b44f

	try {
	[api, ready, serviceContainer] = await activateUnsafe(context, stopWatch, durations);
	} catch (ex) {
	// We want to completely handle the error
	// before notifying VS Code.
	await handleError(ex, durations);
	throw ex; // re-raise
	}
	// Send the "success" telemetry only if activation did not fail.
	// Otherwise Telemetry is send via the error handler.
	sendStartupTelemetry(ready, durations, stopWatch, serviceContainer)
	// Run in the background.
	.ignoreErrors();
	return api;

Note that this also means that the comment about exceptions above is wrong, since it's possible for a specific service activate() to fail, and that would be reflected in ready - but the catch handler will never see that, since it never awaits ready directly or indirectly. So we might also not be logging all the errors that are actually happening.

[eleanorjboyd]

fixed the only ones I have seen occur which are the test ones so going to mark this as closed