Smoke test driver.exitApplication sometimes does not work (microsoft#157979) (microsoft#158479)

Author: bpasero

src/vs/platform/lifecycle/electron-main/lifecycleMainService.ts

@@ -17,6 +17,7 @@ import { ILogService } from 'vs/platform/log/common/log';
 import { IStateMainService } from 'vs/platform/state/electron-main/state';
 import { ICodeWindow, LoadReason, UnloadReason } from 'vs/platform/window/electron-main/window';
 import { ISingleFolderWorkspaceIdentifier, IWorkspaceIdentifier } from 'vs/platform/workspace/common/workspace';
+import { IEnvironmentMainService } from 'vs/platform/environment/electron-main/environmentMainService';
 
 export const ILifecycleMainService = createDecorator<ILifecycleMainService>('lifecycleMainService');
 
@@ -219,7 +220,8 @@ export class LifecycleMainService extends Disposable implements ILifecycleMainSe
 
 	constructor(
 		@ILogService private readonly logService: ILogService,
-		@IStateMainService private readonly stateMainService: IStateMainService
+		@IStateMainService private readonly stateMainService: IStateMainService,
+		@IEnvironmentMainService private readonly environmentMainService: IEnvironmentMainService
 	) {
 		super();
 
@@ -245,11 +247,11 @@ export class LifecycleMainService extends Disposable implements ILifecycleMainSe
 				return;
 			}
 
-			this.logService.trace('Lifecycle#app.on(before-quit)');
+			this.trace('Lifecycle#app.on(before-quit)');
 			this._quitRequested = true;
 
 			// Emit event to indicate that we are about to shutdown
-			this.logService.trace('Lifecycle#onBeforeShutdown.fire()');
+			this.trace('Lifecycle#onBeforeShutdown.fire()');
 			this._onBeforeShutdown.fire();
 
 			// macOS: can run without any window open. in that case we fire
@@ -265,7 +267,7 @@ export class LifecycleMainService extends Disposable implements ILifecycleMainSe
 		// was closed. We override this event to be in charge if app.quit()
 		// should be called or not.
 		const windowAllClosedListener = () => {
-			this.logService.trace('Lifecycle#app.on(window-all-closed)');
+			this.trace('Lifecycle#app.on(window-all-closed)');
 
 			// Windows/Linux: we quit when all windows have closed
 			// Mac: we only quit when quit was requested
@@ -278,7 +280,7 @@ export class LifecycleMainService extends Disposable implements ILifecycleMainSe
 		// will-quit: an event that is fired after all windows have been
 		// closed, but before actually quitting.
 		app.once('will-quit', e => {
-			this.logService.trace('Lifecycle#app.on(will-quit)');
+			this.trace('Lifecycle#app.on(will-quit)');
 
 			// Prevent the quit until the shutdown promise was resolved
 			e.preventDefault();
@@ -307,7 +309,7 @@ export class LifecycleMainService extends Disposable implements ILifecycleMainSe
 			return this.pendingWillShutdownPromise; // shutdown is already running
 		}
 
-		this.logService.trace('Lifecycle#onWillShutdown.fire()');
+		this.trace('Lifecycle#onWillShutdown.fire()');
 
 		const joiners: Promise<void>[] = [];
 
@@ -348,7 +350,7 @@ export class LifecycleMainService extends Disposable implements ILifecycleMainSe
 			return;
 		}
 
-		this.logService.trace(`lifecycle (main): phase changed (value: ${value})`);
+		this.trace(`lifecycle (main): phase changed (value: ${value})`);
 
 		this._phase = value;
 
@@ -394,7 +396,7 @@ export class LifecycleMainService extends Disposable implements ILifecycleMainSe
 				return;
 			}
 
-			this.logService.trace(`Lifecycle#window.on('close') - window ID ${window.id}`);
+			this.trace(`Lifecycle#window.on('close') - window ID ${window.id}`);
 
 			// Otherwise prevent unload and handle it from window
 			e.preventDefault();
@@ -407,7 +409,7 @@ export class LifecycleMainService extends Disposable implements ILifecycleMainSe
 				this.windowToCloseRequest.add(windowId);
 
 				// Fire onBeforeCloseWindow before actually closing
-				this.logService.trace(`Lifecycle#onBeforeCloseWindow.fire() - window ID ${windowId}`);
+				this.trace(`Lifecycle#onBeforeCloseWindow.fire() - window ID ${windowId}`);
 				this._onBeforeCloseWindow.fire(window);
 
 				// No veto, close window now
@@ -417,7 +419,7 @@ export class LifecycleMainService extends Disposable implements ILifecycleMainSe
 
 		// Window After Closing
 		win.on('closed', () => {
-			this.logService.trace(`Lifecycle#window.on('closed') - window ID ${window.id}`);
+			this.trace(`Lifecycle#window.on('closed') - window ID ${window.id}`);
 
 			// update window count
 			this.windowCounter--;
@@ -467,13 +469,13 @@ export class LifecycleMainService extends Disposable implements ILifecycleMainSe
 			return false;
 		}
 
-		this.logService.trace(`Lifecycle#unload() - window ID ${window.id}`);
+		this.trace(`Lifecycle#unload() - window ID ${window.id}`);
 
 		// first ask the window itself if it vetos the unload
 		const windowUnloadReason = this._quitRequested ? UnloadReason.QUIT : reason;
 		const veto = await this.onBeforeUnloadWindowInRenderer(window, windowUnloadReason);
 		if (veto) {
-			this.logService.trace(`Lifecycle#unload() - veto in renderer (window ID ${window.id})`);
+			this.trace(`Lifecycle#unload() - veto in renderer (window ID ${window.id})`);
 
 			return this.handleWindowUnloadVeto(veto);
 		}
@@ -536,12 +538,14 @@ export class LifecycleMainService extends Disposable implements ILifecycleMainSe
 	}
 
 	quit(willRestart?: boolean): Promise<boolean /* veto */> {
+		this.trace(`Lifecycle#quit() - begin (willRestart: ${willRestart})`);
+
 		if (this.pendingQuitPromise) {
+			this.trace('Lifecycle#quit() - returning pending quit promise');
+
 			return this.pendingQuitPromise;
 		}
 
-		this.logService.trace(`Lifecycle#quit() - will restart: ${willRestart}`);
-
 		// Remember if we are about to restart
 		if (willRestart) {
 			this.stateMainService.setItem(LifecycleMainService.QUIT_AND_RESTART_KEY, true);
@@ -554,15 +558,23 @@ export class LifecycleMainService extends Disposable implements ILifecycleMainSe
 
 			// Calling app.quit() will trigger the close handlers of each opened window
 			// and only if no window vetoed the shutdown, we will get the will-quit event
-			this.logService.trace('Lifecycle#quit() - calling app.quit()');
+			this.trace('Lifecycle#quit() - calling app.quit()');
 			app.quit();
 		});
 
 		return this.pendingQuitPromise;
 	}
 
+	private trace(msg: string): void {
+		if (this.environmentMainService.args['enable-smoke-test-driver']) {
+			this.logService.info(msg); // helps diagnose issues with exiting from smoke tests
+		} else {
+			this.logService.trace(msg);
+		}
+	}
+
 	async relaunch(options?: { addArgs?: string[]; removeArgs?: string[] }): Promise<void> {
-		this.logService.trace('Lifecycle#relaunch()');
+		this.trace('Lifecycle#relaunch()');
 
 		const args = process.argv.slice(1);
 		if (options?.addArgs) {
@@ -595,7 +607,7 @@ export class LifecycleMainService extends Disposable implements ILifecycleMainSe
 			}
 
 			// relaunch after we are sure there is no veto
-			this.logService.trace('Lifecycle#relaunch() - calling app.relaunch()');
+			this.trace('Lifecycle#relaunch() - calling app.relaunch()');
 			app.relaunch({ args });
 		};
 		app.once('quit', quitListener);
@@ -609,7 +621,7 @@ export class LifecycleMainService extends Disposable implements ILifecycleMainSe
 	}
 
 	async kill(code?: number): Promise<void> {
-		this.logService.trace('Lifecycle#kill()');
+		this.trace('Lifecycle#kill()');
 
 		// Give main process participants a chance to orderly shutdown
 		await this.fireOnWillShutdown(ShutdownReason.KILL);

src/vs/workbench/electron-sandbox/window.ts

@@ -660,6 +660,8 @@ export class NativeWindow extends Disposable {
 		const that = this;
 		registerWindowDriver({
 			async exitApplication(): Promise<void> {
+				that.logService.info('[driver] handling exitApplication()');
+
 				return that.nativeHostService.quit();
 			}
 		});

test/automation/src/code.ts

@@ -140,7 +140,7 @@ export class Code {
 	}
 
 	async exit(): Promise<void> {
-		return measureAndLog(new Promise<void>((resolve, reject) => {
+		return measureAndLog(new Promise<void>(resolve => {
 			const pid = this.mainProcess.pid!;
 
 			let done = false;
@@ -154,8 +154,8 @@ export class Code {
 				while (!done) {
 					retries++;
 
-					if (retries === 20) {
-						this.logger.log('Smoke test exit call did not terminate process after 10s, forcefully exiting the application...');
+					if (retries === 40) {
+						this.logger.log('Smoke test exit call did not terminate process after 20s, forcefully exiting the application...');
 
 						// no need to await since we're polling for the process to die anyways
 						treekill(pid, err => {

test/smoke/src/areas/workbench/data-loss.test.ts

@@ -9,18 +9,6 @@ import { createApp, timeout, installDiagnosticsHandler, installAppAfterHandler,
 
 export function setup(ensureStableCode: () => string | undefined, logger: Logger) {
 	describe('Data Loss (insiders -> insiders)', function () {
-
-		// There are cases where `exitApplication` does not actually
-		// stop the application and our attempt then to `kill` the
-		// process tree results in data loss / state loss. All these
-		// tests here rely on state getting persisted properly, so
-		// until we have figured out the root cause, we retry these
-		// tests.
-		// See: https://github.com/microsoft/vscode/issues/157979
-		if (process.platform === 'darwin') {
-			this.retries(2);
-		}
-
 		let app: Application | undefined = undefined;
 
 		// Shared before/after handling
@@ -142,18 +130,6 @@ export function setup(ensureStableCode: () => string | undefined, logger: Logger
 	});
 
 	describe('Data Loss (stable -> insiders)', function () {
-
-		// There are cases where `exitApplication` does not actually
-		// stop the application and our attempt then to `kill` the
-		// process tree results in data loss / state loss. All these
-		// tests here rely on state getting persisted properly, so
-		// until we have figured out the root cause, we retry these
-		// tests.
-		// See: https://github.com/microsoft/vscode/issues/157979
-		if (process.platform === 'darwin') {
-			this.retries(2);
-		}
-
 		let insidersApp: Application | undefined = undefined;
 		let stableApp: Application | undefined = undefined;