From 810b12931f012a0208ec6c337474c6ce3a0a4ce0 Mon Sep 17 00:00:00 2001 From: Benjamin Pasero Date: Wed, 7 Sep 2022 05:54:45 +0200 Subject: [PATCH] smoke - fix log and retry `exitApplication` --- src/vs/workbench/electron-sandbox/window.ts | 8 +++ test/automation/src/application.ts | 10 ++-- test/automation/src/code.ts | 59 +++++++++++++-------- test/automation/src/electron.ts | 4 +- test/automation/src/logger.ts | 6 +-- test/automation/src/playwrightBrowser.ts | 16 +++--- test/automation/src/playwrightDriver.ts | 14 ++--- test/automation/src/playwrightElectron.ts | 6 +-- test/smoke/src/main.ts | 12 ++--- 9 files changed, 79 insertions(+), 56 deletions(-) diff --git a/src/vs/workbench/electron-sandbox/window.ts b/src/vs/workbench/electron-sandbox/window.ts index b3a884353c4a9..3a558cc6b011e 100644 --- a/src/vs/workbench/electron-sandbox/window.ts +++ b/src/vs/workbench/electron-sandbox/window.ts @@ -682,10 +682,18 @@ export class NativeWindow extends Disposable { private setupDriver(): void { const that = this; + let pendingQuit = false; + registerWindowDriver({ async exitApplication(): Promise { + if (pendingQuit) { + that.logService.info('[driver] not handling exitApplication() due to pending quit() call'); + return; + } + that.logService.info('[driver] handling exitApplication()'); + pendingQuit = true; return that.nativeHostService.quit(); } }); diff --git a/test/automation/src/application.ts b/test/automation/src/application.ts index 9a755a142314c..83e7a76ace758 100644 --- a/test/automation/src/application.ts +++ b/test/automation/src/application.ts @@ -69,7 +69,7 @@ export class Application { } async restart(options?: { workspaceOrFolder?: string; extraArgs?: string[] }): Promise { - await measureAndLog((async () => { + await measureAndLog(() => (async () => { await this.stop(); await this._start(options?.workspaceOrFolder, options?.extraArgs); })(), 'Application#restart()', this.logger); @@ -82,7 +82,7 @@ export class Application { const code = await this.startApplication(extraArgs); // ...and make sure the window is ready to interact - await measureAndLog(this.checkWindowReady(code), 'Application#checkWindowReady()', this.logger); + await measureAndLog(() => this.checkWindowReady(code), 'Application#checkWindowReady()', this.logger); } async stop(): Promise { @@ -117,12 +117,12 @@ export class Application { private async checkWindowReady(code: Code): Promise { // We need a rendered workbench - await measureAndLog(code.didFinishLoad(), 'Application#checkWindowReady: wait for navigation to be committed', this.logger); - await measureAndLog(code.waitForElement('.monaco-workbench'), 'Application#checkWindowReady: wait for .monaco-workbench element', this.logger); + await measureAndLog(() => code.didFinishLoad(), 'Application#checkWindowReady: wait for navigation to be committed', this.logger); + await measureAndLog(() => code.waitForElement('.monaco-workbench'), 'Application#checkWindowReady: wait for .monaco-workbench element', this.logger); // Remote but not web: wait for a remote connection state change if (this.remote) { - await measureAndLog(code.waitForTextContent('.monaco-workbench .statusbar-item[id="status.host"]', undefined, statusHostLabel => { + await measureAndLog(() => code.waitForTextContent('.monaco-workbench .statusbar-item[id="status.host"]', undefined, statusHostLabel => { this.logger.log(`checkWindowReady: remote indicator text is ${statusHostLabel}`); // The absence of "Opening Remote" is not a strict diff --git a/test/automation/src/code.ts b/test/automation/src/code.ts index 353cead8e595c..82e80aa89ea71 100644 --- a/test/automation/src/code.ts +++ b/test/automation/src/code.ts @@ -76,11 +76,11 @@ export async function launch(options: LaunchOptions): Promise { throw new Error('Smoke test process has terminated, refusing to spawn Code'); } - await measureAndLog(copyExtension(rootPath, options.extensionsPath, 'vscode-notebook-tests'), 'copyExtension(vscode-notebook-tests)', options.logger); + await measureAndLog(() => copyExtension(rootPath, options.extensionsPath, 'vscode-notebook-tests'), 'copyExtension(vscode-notebook-tests)', options.logger); // Browser smoke tests if (options.web) { - const { serverProcess, driver } = await measureAndLog(launchPlaywrightBrowser(options), 'launch playwright (browser)', options.logger); + const { serverProcess, driver } = await measureAndLog(() => launchPlaywrightBrowser(options), 'launch playwright (browser)', options.logger); registerInstance(serverProcess, options.logger, 'server'); return new Code(driver, options.logger, serverProcess); @@ -88,7 +88,7 @@ export async function launch(options: LaunchOptions): Promise { // Electron smoke tests (playwright) else { - const { electronProcess, driver } = await measureAndLog(launchPlaywrightElectron(options), 'launch playwright (electron)', options.logger); + const { electronProcess, driver } = await measureAndLog(() => launchPlaywrightElectron(options), 'launch playwright (electron)', options.logger); registerInstance(electronProcess, options.logger, 'electron'); return new Code(driver, options.logger, electronProcess); @@ -140,7 +140,7 @@ export class Code { } async exit(): Promise { - return measureAndLog(new Promise(resolve => { + return measureAndLog(() => new Promise(resolve => { const pid = this.mainProcess.pid!; let done = false; @@ -154,18 +154,39 @@ export class Code { while (!done) { retries++; - 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 => { - try { - process.kill(pid, 0); // throws an exception if the process doesn't exist anymore - this.logger.log('Failed to kill Electron process tree:', err?.message); - } catch (error) { - // Expected when process is gone - } - }); + switch (retries) { + + // after 5 / 10 seconds: try to exit gracefully again + case 10: + case 20: { + this.logger.log('Smoke test exit call did not terminate process after 5-10s, gracefully trying to exit the application again...'); + this.driver.exitApplication(); + break; + } + + // after 20 seconds: forcefully kill + case 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 => { + try { + process.kill(pid, 0); // throws an exception if the process doesn't exist anymore + this.logger.log('Failed to kill Electron process tree:', err?.message); + } catch (error) { + // Expected when process is gone + } + }); + + break; + } + + // after 30 seconds: give up + case 60: { + done = true; + this.logger.log('Smoke test exit call did not terminate process after 30s, giving up'); + resolve(); + } } try { @@ -175,12 +196,6 @@ export class Code { done = true; resolve(); } - - if (retries === 60) { - done = true; - this.logger.log('Smoke test exit call did not terminate process after 30s, giving up'); - resolve(); - } } })(); }), 'Code#exit()', this.logger); diff --git a/test/automation/src/electron.ts b/test/automation/src/electron.ts index ffde8728787b9..96f3970c90452 100644 --- a/test/automation/src/electron.ts +++ b/test/automation/src/electron.ts @@ -55,7 +55,7 @@ export async function resolveElectronConfiguration(options: LaunchOptions): Prom if (codePath) { // running against a build: copy the test resolver extension - await measureAndLog(copyExtension(root, extensionsPath, 'vscode-test-resolver'), 'copyExtension(vscode-test-resolver)', logger); + await measureAndLog(() => copyExtension(root, extensionsPath, 'vscode-test-resolver'), 'copyExtension(vscode-test-resolver)', logger); } args.push('--enable-proposed-api=vscode.vscode-test-resolver'); const remoteDataDir = `${userDataDir}-server`; @@ -65,7 +65,7 @@ export async function resolveElectronConfiguration(options: LaunchOptions): Prom // running against a build: copy the test resolver extension into remote extensions dir const remoteExtensionsDir = join(remoteDataDir, 'extensions'); mkdirp.sync(remoteExtensionsDir); - await measureAndLog(copyExtension(root, remoteExtensionsDir, 'vscode-notebook-tests'), 'copyExtension(vscode-notebook-tests)', logger); + await measureAndLog(() => copyExtension(root, remoteExtensionsDir, 'vscode-notebook-tests'), 'copyExtension(vscode-notebook-tests)', logger); } env['TESTRESOLVER_DATA_FOLDER'] = remoteDataDir; diff --git a/test/automation/src/logger.ts b/test/automation/src/logger.ts index 9320bbca7bd9a..28dc9e32c4185 100644 --- a/test/automation/src/logger.ts +++ b/test/automation/src/logger.ts @@ -41,15 +41,15 @@ export class MultiLogger implements Logger { } } -export async function measureAndLog(promise: Promise, name: string, logger: Logger): Promise { +export async function measureAndLog(promiseFactory: () => Promise, name: string, logger: Logger): Promise { const now = Date.now(); - logger.log(`Starting operation '${name}...`); + logger.log(`Starting operation '${name}'...`); let res: T | undefined = undefined; let e: unknown; try { - res = await promise; + res = await promiseFactory(); } catch (error) { e = error; } diff --git a/test/automation/src/playwrightBrowser.ts b/test/automation/src/playwrightBrowser.ts index cfbae17dd005f..808da87137b38 100644 --- a/test/automation/src/playwrightBrowser.ts +++ b/test/automation/src/playwrightBrowser.ts @@ -34,7 +34,7 @@ async function launchServer(options: LaunchOptions) { const { userDataDir, codePath, extensionsPath, logger, logsPath } = options; const codeServerPath = codePath ?? process.env.VSCODE_REMOTE_SERVER_PATH; const agentFolder = userDataDir; - await measureAndLog(mkdirp(agentFolder), `mkdirp(${agentFolder})`, logger); + await measureAndLog(() => mkdirp(agentFolder), `mkdirp(${agentFolder})`, logger); const env = { VSCODE_REMOTE_SERVER_PATH: codeServerPath, @@ -81,28 +81,28 @@ async function launchServer(options: LaunchOptions) { return { serverProcess, - endpoint: await measureAndLog(waitForEndpoint(serverProcess, logger), 'waitForEndpoint(serverProcess)', logger) + endpoint: await measureAndLog(() => waitForEndpoint(serverProcess, logger), 'waitForEndpoint(serverProcess)', logger) }; } async function launchBrowser(options: LaunchOptions, endpoint: string) { const { logger, workspacePath, tracing, headless } = options; - const browser = await measureAndLog(playwright[options.browser ?? 'chromium'].launch({ headless: headless ?? false }), 'playwright#launch', logger); + const browser = await measureAndLog(() => playwright[options.browser ?? 'chromium'].launch({ headless: headless ?? false }), 'playwright#launch', logger); browser.on('disconnected', () => logger.log(`Playwright: browser disconnected`)); - const context = await measureAndLog(browser.newContext(), 'browser.newContext', logger); + const context = await measureAndLog(() => browser.newContext(), 'browser.newContext', logger); if (tracing) { try { - await measureAndLog(context.tracing.start({ screenshots: true, /* remaining options are off for perf reasons */ }), 'context.tracing.start()', logger); + await measureAndLog(() => context.tracing.start({ screenshots: true, /* remaining options are off for perf reasons */ }), 'context.tracing.start()', logger); } catch (error) { logger.log(`Playwright (Browser): Failed to start playwright tracing (${error})`); // do not fail the build when this fails } } - const page = await measureAndLog(context.newPage(), 'context.newPage()', logger); - await measureAndLog(page.setViewportSize({ width: 1200, height: 800 }), 'page.setViewportSize', logger); + const page = await measureAndLog(() => context.newPage(), 'context.newPage()', logger); + await measureAndLog(() => page.setViewportSize({ width: 1200, height: 800 }), 'page.setViewportSize', logger); if (options.verbose) { context.on('page', () => logger.log(`Playwright (Browser): context.on('page')`)); @@ -133,7 +133,7 @@ async function launchBrowser(options: LaunchOptions, endpoint: string) { `["logLevel","${options.verbose ? 'trace' : 'info'}"]` ].join(',')}]`; - await measureAndLog(page.goto(`${endpoint}&${workspacePath.endsWith('.code-workspace') ? 'workspace' : 'folder'}=${URI.file(workspacePath!).path}&payload=${payloadParam}`), 'page.goto()', logger); + await measureAndLog(() => page.goto(`${endpoint}&${workspacePath.endsWith('.code-workspace') ? 'workspace' : 'folder'}=${URI.file(workspacePath!).path}&payload=${payloadParam}`), 'page.goto()', logger); return { browser, context, page }; } diff --git a/test/automation/src/playwrightDriver.ts b/test/automation/src/playwrightDriver.ts index 4eef5d450abfc..3425d11a74c00 100644 --- a/test/automation/src/playwrightDriver.ts +++ b/test/automation/src/playwrightDriver.ts @@ -46,7 +46,7 @@ export class PlaywrightDriver { } try { - await measureAndLog(this.context.tracing.startChunk({ title: name }), `startTracing for ${name}`, this.options.logger); + await measureAndLog(() => this.context.tracing.startChunk({ title: name }), `startTracing for ${name}`, this.options.logger); } catch (error) { // Ignore } @@ -63,7 +63,7 @@ export class PlaywrightDriver { persistPath = join(this.options.logsPath, `playwright-trace-${PlaywrightDriver.traceCounter++}-${name.replace(/\s+/g, '-')}.zip`); } - await measureAndLog(this.context.tracing.stopChunk({ path: persistPath }), `stopTracing for ${name}`, this.options.logger); + await measureAndLog(() => this.context.tracing.stopChunk({ path: persistPath }), `stopTracing for ${name}`, this.options.logger); // To ensure we have a screenshot at the end where // it failed, also trigger one explicitly. Tracing @@ -95,7 +95,7 @@ export class PlaywrightDriver { try { const persistPath = join(this.options.logsPath, `playwright-screenshot-${PlaywrightDriver.screenShotCounter++}-${name.replace(/\s+/g, '-')}.png`); - await measureAndLog(this.page.screenshot({ path: persistPath, type: 'png' }), 'takeScreenshot', this.options.logger); + await measureAndLog(() => this.page.screenshot({ path: persistPath, type: 'png' }), 'takeScreenshot', this.options.logger); } catch (error) { // Ignore } @@ -110,7 +110,7 @@ export class PlaywrightDriver { // Stop tracing try { if (this.options.tracing) { - await measureAndLog(this.context.tracing.stop(), 'stop tracing', this.options.logger); + await measureAndLog(() => this.context.tracing.stop(), 'stop tracing', this.options.logger); } } catch (error) { // Ignore @@ -119,7 +119,7 @@ export class PlaywrightDriver { // Web: exit via `close` method if (this.options.web) { try { - await measureAndLog(this.application.close(), 'playwright.close()', this.options.logger); + await measureAndLog(() => this.application.close(), 'playwright.close()', this.options.logger); } catch (error) { this.options.logger.log(`Error closing appliction (${error})`); } @@ -128,7 +128,7 @@ export class PlaywrightDriver { // Desktop: exit via `driver.exitApplication` else { try { - await measureAndLog(this.evaluateWithDriver(([driver]) => driver.exitApplication()), 'driver.exitApplication()', this.options.logger); + await measureAndLog(() => this.evaluateWithDriver(([driver]) => driver.exitApplication()), 'driver.exitApplication()', this.options.logger); } catch (error) { this.options.logger.log(`Error exiting appliction (${error})`); } @@ -136,7 +136,7 @@ export class PlaywrightDriver { // Server: via `teardown` if (this.serverProcess) { - await measureAndLog(teardown(this.serverProcess, this.options.logger), 'teardown server process', this.options.logger); + await measureAndLog(() => teardown(this.serverProcess!, this.options.logger), 'teardown server process', this.options.logger); } } diff --git a/test/automation/src/playwrightElectron.ts b/test/automation/src/playwrightElectron.ts index 3ad47fbb2ec1d..83ed79e904748 100644 --- a/test/automation/src/playwrightElectron.ts +++ b/test/automation/src/playwrightElectron.ts @@ -29,19 +29,19 @@ export async function launch(options: LaunchOptions): Promise<{ electronProcess: async function launchElectron(configuration: IElectronConfiguration, options: LaunchOptions) { const { logger, tracing } = options; - const electron = await measureAndLog(playwright._electron.launch({ + const electron = await measureAndLog(() => playwright._electron.launch({ executablePath: configuration.electronPath, args: configuration.args, env: configuration.env as { [key: string]: string } }), 'playwright-electron#launch', logger); - const window = await measureAndLog(electron.firstWindow(), 'playwright-electron#firstWindow', logger); + const window = await measureAndLog(() => electron.firstWindow(), 'playwright-electron#firstWindow', logger); const context = window.context(); if (tracing) { try { - await measureAndLog(context.tracing.start({ screenshots: true, /* remaining options are off for perf reasons */ }), 'context.tracing.start()', logger); + await measureAndLog(() => context.tracing.start({ screenshots: true, /* remaining options are off for perf reasons */ }), 'context.tracing.start()', logger); } catch (error) { logger.log(`Playwright (Electron): Failed to start playwright tracing (${error})`); // do not fail the build when this fails } diff --git a/test/smoke/src/main.ts b/test/smoke/src/main.ts index d6b123b32f9e4..e2657a9e4df95 100644 --- a/test/smoke/src/main.ts +++ b/test/smoke/src/main.ts @@ -265,13 +265,13 @@ async function ensureStableCode(): Promise { if (!stableCodePath) { const { major, minor } = parseVersion(version!); const majorMinorVersion = `${major}.${minor - 1}`; - const versionsReq = await retry(() => measureAndLog(fetch('https://update.code.visualstudio.com/api/releases/stable', { headers: { 'x-api-version': '2' } }), 'versionReq', logger), 1000, 20); + const versionsReq = await retry(() => measureAndLog(() => fetch('https://update.code.visualstudio.com/api/releases/stable', { headers: { 'x-api-version': '2' } }), 'versionReq', logger), 1000, 20); if (!versionsReq.ok) { throw new Error('Could not fetch releases from update server'); } - const versions: { version: string }[] = await measureAndLog(versionsReq.json(), 'versionReq.json()', logger); + const versions: { version: string }[] = await measureAndLog(() => versionsReq.json(), 'versionReq.json()', logger); const prefix = `${majorMinorVersion}.`; const previousVersion = versions.find(v => v.version.startsWith(prefix)); @@ -284,7 +284,7 @@ async function ensureStableCode(): Promise { let lastProgressMessage: string | undefined = undefined; let lastProgressReportedAt = 0; const stableCodeDestination = path.join(testDataPath, 's'); - const stableCodeExecutable = await retry(() => measureAndLog(vscodetest.download({ + const stableCodeExecutable = await retry(() => measureAndLog(() => vscodetest.download({ cachePath: stableCodeDestination, version: previousVersion.version, extractSync: true, @@ -339,9 +339,9 @@ async function setup(): Promise { if (!opts.web && !opts.remote && opts.build) { // only enabled when running with --build and not in web or remote - await measureAndLog(ensureStableCode(), 'ensureStableCode', logger); + await measureAndLog(() => ensureStableCode(), 'ensureStableCode', logger); } - await measureAndLog(setupRepository(), 'setupRepository', logger); + await measureAndLog(() => setupRepository(), 'setupRepository', logger); logger.log('Smoketest setup done!\n'); } @@ -375,7 +375,7 @@ before(async function () { after(async function () { try { let deleted = false; - await measureAndLog(Promise.race([ + await measureAndLog(() => Promise.race([ new Promise((resolve, reject) => rimraf(testDataPath, { maxBusyTries: 10 }, error => { if (error) { reject(error);