From d980ed7e7ef7c49b298e68cc9d195ddc8cbc1ff2 Mon Sep 17 00:00:00 2001 From: Dmitry Gozman Date: Fri, 29 May 2020 14:39:34 -0700 Subject: [PATCH] chore: introduce Progress concept (#2350) A progress roughly corresponds to an api call. It is used: - to collect logs related to the call; - to handle timeout; - to provide "cancellation token" behavior so that cancelable process can either early-exit with progress.throwIfCanceled() or race against it with progress.race(); - to ensure resources are disposed in the case of a failure with progress.cleanupWhenCanceled(); - (possibly) to log api calls if needed; - (in the future) to augment async stacks. --- src/logger.ts | 36 -------- src/progress.ts | 116 ++++++++++++++++++++++++ src/server/browserServer.ts | 2 +- src/server/browserType.ts | 138 ++++++++++------------------- src/server/electron.ts | 66 +++++++------- src/server/processLauncher.ts | 57 ++++-------- src/timeoutSettings.ts | 2 +- src/transport.ts | 35 +++++--- test/defaultbrowsercontext.spec.js | 2 +- test/launcher.spec.js | 7 +- 10 files changed, 241 insertions(+), 220 deletions(-) create mode 100644 src/progress.ts diff --git a/src/logger.ts b/src/logger.ts index 6df3cd47a7..6e3b33ffd2 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -57,21 +57,6 @@ export class RootLogger implements InnerLogger { if (this._logger.isEnabled(log.name, log.severity || 'info')) this._logger.log(log.name, log.severity || 'info', message, args, log.color ? { color: log.color } : {}); } - - startLaunchRecording() { - this._logger.add(`launch`, new RecordingLogger('browser')); - } - - launchRecording(): string { - const logger = this._logger.get(`launch`) as RecordingLogger; - if (logger) - return logger.recording(); - return ''; - } - - stopLaunchRecording() { - this._logger.remove(`launch`); - } } const colorMap = new Map([ @@ -113,27 +98,6 @@ class MultiplexingLogger implements Logger { } } -export class RecordingLogger implements Logger { - private _prefix: string; - private _recording: string[] = []; - - constructor(prefix: string) { - this._prefix = prefix; - } - - isEnabled(name: string, severity: LoggerSeverity): boolean { - return name.startsWith(this._prefix); - } - - log(name: string, severity: LoggerSeverity, message: string | Error, args: any[], hints: { color?: string }) { - this._recording.push(String(message)); - } - - recording(): string { - return this._recording.join('\n'); - } -} - class DebugLogger implements Logger { private _debuggers = new Map(); diff --git a/src/progress.ts b/src/progress.ts new file mode 100644 index 0000000000..e6f7e7d7d1 --- /dev/null +++ b/src/progress.ts @@ -0,0 +1,116 @@ +/** + * Copyright (c) Microsoft Corporation. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +import { InnerLogger, Log } from './logger'; +import { TimeoutError } from './errors'; +import { helper } from './helper'; +import * as types from './types'; +import { DEFAULT_TIMEOUT, TimeoutSettings } from './timeoutSettings'; +import { getCurrentApiCall, rewriteErrorMessage } from './debug/stackTrace'; + +class AbortError extends Error {} + +export class Progress { + static async runCancelableTask(task: (progress: Progress) => Promise, timeoutOptions: types.TimeoutOptions, logger: InnerLogger, apiName?: string): Promise { + let resolveCancelation = () => {}; + const progress = new Progress(timeoutOptions, logger, new Promise(resolve => resolveCancelation = resolve), apiName); + + const { timeout = DEFAULT_TIMEOUT } = timeoutOptions; + const timeoutError = new TimeoutError(`Timeout ${timeout}ms exceeded during ${progress.apiName}.`); + let rejectWithTimeout: (error: Error) => void; + const timeoutPromise = new Promise((resolve, x) => rejectWithTimeout = x); + const timeoutTimer = setTimeout(() => rejectWithTimeout(timeoutError), helper.timeUntilDeadline(progress.deadline)); + + try { + const promise = task(progress); + const result = await Promise.race([promise, timeoutPromise]); + clearTimeout(timeoutTimer); + progress._running = false; + progress._logRecording = []; + return result; + } catch (e) { + resolveCancelation(); + rewriteErrorMessage(e, e.message + formatLogRecording(progress._logRecording, progress.apiName)); + clearTimeout(timeoutTimer); + progress._running = false; + progress._logRecording = []; + await Promise.all(progress._cleanups.splice(0).map(cleanup => runCleanup(cleanup))); + throw e; + } + } + + readonly apiName: string; + readonly deadline: number; // To be removed? + readonly _canceled: Promise; + + private _logger: InnerLogger; + private _logRecording: string[] = []; + private _cleanups: (() => any)[] = []; + private _running = true; + + constructor(options: types.TimeoutOptions, logger: InnerLogger, canceled: Promise, apiName?: string) { + this.apiName = apiName || getCurrentApiCall(); + this.deadline = TimeoutSettings.computeDeadline(options.timeout); + this._canceled = canceled; + this._logger = logger; + } + + cleanupWhenCanceled(cleanup: () => any) { + if (this._running) + this._cleanups.push(cleanup); + else + runCleanup(cleanup); + } + + throwIfCanceled() { + if (!this._running) + throw new AbortError(); + } + + race(promise: Promise, cleanup?: () => any): Promise { + const canceled = this._canceled.then(async error => { + if (cleanup) + await runCleanup(cleanup); + throw error; + }); + const success = promise.then(result => { + cleanup = undefined; + return result; + }); + return Promise.race([success, canceled]); + } + + log(log: Log, message: string | Error): void { + if (this._running) + this._logRecording.push(message.toString()); + this._logger._log(log, message); + } +} + +async function runCleanup(cleanup: () => any) { + try { + await cleanup(); + } catch (e) { + } +} + +function formatLogRecording(log: string[], name: string): string { + name = ` ${name} logs `; + const headerLength = 60; + const leftLength = (headerLength - name.length) / 2; + const rightLength = headerLength - name.length - leftLength; + return `\n${'='.repeat(leftLength)}${name}${'='.repeat(rightLength)}\n${log.join('\n')}\n${'='.repeat(headerLength)}`; +} diff --git a/src/server/browserServer.ts b/src/server/browserServer.ts index a2e3e866fc..1b0f36ba0b 100644 --- a/src/server/browserServer.ts +++ b/src/server/browserServer.ts @@ -15,8 +15,8 @@ */ import { ChildProcess } from 'child_process'; -import { EventEmitter } from 'events'; import { helper } from '../helper'; +import { EventEmitter } from 'events'; export class WebSocketWrapper { readonly wsEndpoint: string; diff --git a/src/server/browserType.ts b/src/server/browserType.ts index e1efb78982..95a20f4250 100644 --- a/src/server/browserType.ts +++ b/src/server/browserType.ts @@ -24,13 +24,11 @@ import * as browserPaths from '../install/browserPaths'; import { Logger, RootLogger, InnerLogger } from '../logger'; import { ConnectionTransport, WebSocketTransport } from '../transport'; import { BrowserBase, BrowserOptions, Browser } from '../browser'; -import { assert, helper } from '../helper'; -import { TimeoutSettings } from '../timeoutSettings'; +import { assert } from '../helper'; import { launchProcess, Env, waitForLine } from './processLauncher'; import { Events } from '../events'; -import { rewriteErrorMessage } from '../debug/stackTrace'; -import { TimeoutError } from '../errors'; import { PipeTransport } from './pipeTransport'; +import { Progress } from '../progress'; export type BrowserArgOptions = { headless?: boolean, @@ -102,56 +100,36 @@ export abstract class BrowserTypeBase implements BrowserType { async launch(options: LaunchOptions = {}): Promise { assert(!(options as any).userDataDir, 'userDataDir option is not supported in `browserType.launch`. Use `browserType.launchPersistentContext` instead'); assert(!(options as any).port, 'Cannot specify a port without launching as a server.'); - return this._innerLaunch(options, undefined); + const logger = new RootLogger(options.logger); + const browser = await Progress.runCancelableTask(progress => this._innerLaunch(progress, options, logger, undefined), options, logger); + return browser; } async launchPersistentContext(userDataDir: string, options: LaunchOptions & PersistentContextOptions = {}): Promise { assert(!(options as any).port, 'Cannot specify a port without launching as a server.'); const persistent = validatePersistentContextOptions(options); - const browser = await this._innerLaunch(options, persistent, userDataDir); + const logger = new RootLogger(options.logger); + const browser = await Progress.runCancelableTask(progress => this._innerLaunch(progress, options, logger, persistent, userDataDir), options, logger); return browser._defaultContext!; } - async _innerLaunch(options: LaunchOptions, persistent: PersistentContextOptions | undefined, userDataDir?: string): Promise { - const deadline = TimeoutSettings.computeDeadline(options.timeout); - const logger = new RootLogger(options.logger); - logger.startLaunchRecording(); - - let browserServer: BrowserServer | undefined; - try { - const launched = await this._launchServer(options, !!persistent, logger, deadline, userDataDir); - browserServer = launched.browserServer; - const browserOptions: BrowserOptions = { - slowMo: options.slowMo, - persistent, - headful: !processBrowserArgOptions(options).headless, - logger, - downloadsPath: launched.downloadsPath, - ownedServer: browserServer, - }; - copyTestHooks(options, browserOptions); - const hasCustomArguments = !!options.ignoreDefaultArgs && !Array.isArray(options.ignoreDefaultArgs); - const promise = this._innerCreateBrowser(launched.transport, browserOptions, hasCustomArguments); - const browser = await helper.waitWithDeadline(promise, 'the browser to launch', deadline, 'pw:browser*'); - return browser; - } catch (e) { - rewriteErrorMessage(e, e.message + '\n=============== Process output during launch: ===============\n' + - logger.launchRecording() + - '\n============================================================='); - if (browserServer) - await browserServer._closeOrKill(deadline); - throw e; - } finally { - logger.stopLaunchRecording(); - } - } - - async _innerCreateBrowser(transport: ConnectionTransport, browserOptions: BrowserOptions, hasCustomArguments: boolean): Promise { - if ((browserOptions as any).__testHookBeforeCreateBrowser) - await (browserOptions as any).__testHookBeforeCreateBrowser(); + async _innerLaunch(progress: Progress, options: LaunchOptions, logger: RootLogger, persistent: PersistentContextOptions | undefined, userDataDir?: string): Promise { + const { browserServer, downloadsPath, transport } = await this._launchServer(progress, options, !!persistent, logger, userDataDir); + if ((options as any).__testHookBeforeCreateBrowser) + await (options as any).__testHookBeforeCreateBrowser(); + const browserOptions: BrowserOptions = { + slowMo: options.slowMo, + persistent, + headful: !processBrowserArgOptions(options).headless, + logger, + downloadsPath, + ownedServer: browserServer, + }; + copyTestHooks(options, browserOptions); const browser = await this._connectToTransport(transport, browserOptions); // We assume no control when using custom arguments, and do not prepare the default context in that case. - if (browserOptions.persistent && !hasCustomArguments) + const hasCustomArguments = !!options.ignoreDefaultArgs && !Array.isArray(options.ignoreDefaultArgs); + if (persistent && !hasCustomArguments) await browser._defaultContext!._loadDefaultContext(); return browser; } @@ -160,44 +138,26 @@ export abstract class BrowserTypeBase implements BrowserType { assert(!(options as any).userDataDir, 'userDataDir option is not supported in `browserType.launchServer`. Use `browserType.launchPersistentContext` instead'); const { port = 0 } = options; const logger = new RootLogger(options.logger); - const { browserServer, transport } = await this._launchServer(options, false, logger, TimeoutSettings.computeDeadline(options.timeout)); - browserServer._webSocketWrapper = this._wrapTransportWithWebSocket(transport, logger, port); - return browserServer; + return Progress.runCancelableTask(async progress => { + const { browserServer, transport } = await this._launchServer(progress, options, false, logger); + browserServer._webSocketWrapper = this._wrapTransportWithWebSocket(transport, logger, port); + return browserServer; + }, options, logger); } async connect(options: ConnectOptions): Promise { - const deadline = TimeoutSettings.computeDeadline(options.timeout); const logger = new RootLogger(options.logger); - logger.startLaunchRecording(); - - let transport: ConnectionTransport | undefined; - try { - transport = await WebSocketTransport.connect(options.wsEndpoint, logger, deadline); - const browserOptions: BrowserOptions = { - slowMo: options.slowMo, - logger, - }; - copyTestHooks(options, browserOptions); - const promise = this._innerCreateBrowser(transport, browserOptions, false); - const browser = await helper.waitWithDeadline(promise, 'connect to browser', deadline, 'pw:browser*'); - logger.stopLaunchRecording(); + return Progress.runCancelableTask(async progress => { + const transport = await WebSocketTransport.connect(progress, options.wsEndpoint); + progress.cleanupWhenCanceled(() => transport.closeAndWait()); + if ((options as any).__testHookBeforeCreateBrowser) + await (options as any).__testHookBeforeCreateBrowser(); + const browser = await this._connectToTransport(transport, { slowMo: options.slowMo, logger }); return browser; - } catch (e) { - rewriteErrorMessage(e, e.message + '\n=============== Process output during connect: ===============\n' + - logger.launchRecording() + - '\n============================================================='); - try { - if (transport) - transport.close(); - } catch (e) { - } - throw e; - } finally { - logger.stopLaunchRecording(); - } + }, options, logger); } - private async _launchServer(options: LaunchServerOptions, isPersistent: boolean, logger: RootLogger, deadline: number, userDataDir?: string): Promise<{ browserServer: BrowserServer, downloadsPath: string, transport: ConnectionTransport }> { + private async _launchServer(progress: Progress, options: LaunchServerOptions, isPersistent: boolean, logger: RootLogger, userDataDir?: string): Promise<{ browserServer: BrowserServer, downloadsPath: string, transport: ConnectionTransport }> { const { ignoreDefaultArgs = false, args = [], @@ -238,7 +198,7 @@ export abstract class BrowserTypeBase implements BrowserType { handleSIGINT, handleSIGTERM, handleSIGHUP, - logger, + progress, pipe: !this._webSocketRegexNotPipe, tempDirectories, attemptToGracefullyClose: async () => { @@ -254,23 +214,17 @@ export abstract class BrowserTypeBase implements BrowserType { browserServer.emit(Events.BrowserServer.Close, exitCode, signal); }, }); - - try { - if (this._webSocketRegexNotPipe) { - const timeoutError = new TimeoutError(`Timed out while trying to connect to the browser!`); - const match = await waitForLine(launchedProcess, launchedProcess.stdout, this._webSocketRegexNotPipe, helper.timeUntilDeadline(deadline), timeoutError); - const innerEndpoint = match[1]; - transport = await WebSocketTransport.connect(innerEndpoint, logger, deadline); - } else { - const stdio = launchedProcess.stdio as unknown as [NodeJS.ReadableStream, NodeJS.WritableStream, NodeJS.WritableStream, NodeJS.WritableStream, NodeJS.ReadableStream]; - transport = new PipeTransport(stdio[3], stdio[4], logger); - } - } catch (e) { - // If we can't establish a connection, kill the process and exit. - helper.killProcess(launchedProcess); - throw e; - } browserServer = new BrowserServer(launchedProcess, gracefullyClose, kill); + progress.cleanupWhenCanceled(() => browserServer && browserServer._closeOrKill(progress.deadline)); + + if (this._webSocketRegexNotPipe) { + const match = await waitForLine(progress, launchedProcess, launchedProcess.stdout, this._webSocketRegexNotPipe); + const innerEndpoint = match[1]; + transport = await WebSocketTransport.connect(progress, innerEndpoint); + } else { + const stdio = launchedProcess.stdio as unknown as [NodeJS.ReadableStream, NodeJS.WritableStream, NodeJS.WritableStream, NodeJS.WritableStream, NodeJS.ReadableStream]; + transport = new PipeTransport(stdio[3], stdio[4], logger); + } return { browserServer, downloadsPath, transport }; } diff --git a/src/server/electron.ts b/src/server/electron.ts index aa7c4f17b9..a551fdeb0e 100644 --- a/src/server/electron.ts +++ b/src/server/electron.ts @@ -18,10 +18,8 @@ import * as path from 'path'; import { CRBrowser, CRBrowserContext } from '../chromium/crBrowser'; import { CRConnection, CRSession } from '../chromium/crConnection'; import { CRExecutionContext } from '../chromium/crExecutionContext'; -import { TimeoutError } from '../errors'; import { Events } from '../events'; import { ExtendedEventEmitter } from '../extendedEventEmitter'; -import { helper } from '../helper'; import * as js from '../javascript'; import { InnerLogger, Logger, RootLogger } from '../logger'; import { Page } from '../page'; @@ -32,6 +30,7 @@ import { BrowserServer } from './browserServer'; import { launchProcess, waitForLine } from './processLauncher'; import { BrowserContext } from '../browserContext'; import type {BrowserWindow} from 'electron'; +import { Progress } from '../progress'; type ElectronLaunchOptions = { args?: string[], @@ -168,40 +167,39 @@ export class Electron { handleSIGTERM = true, handleSIGHUP = true, } = options; - const deadline = TimeoutSettings.computeDeadline(options.timeout); - let app: ElectronApplication | undefined = undefined; - const logger = new RootLogger(options.logger); - const electronArguments = ['--inspect=0', '--remote-debugging-port=0', '--require', path.join(__dirname, 'electronLoader.js'), ...args]; - const { launchedProcess, gracefullyClose, kill } = await launchProcess({ - executablePath, - args: electronArguments, - env, - handleSIGINT, - handleSIGTERM, - handleSIGHUP, - logger, - pipe: true, - cwd: options.cwd, - tempDirectories: [], - attemptToGracefullyClose: () => app!.close(), - onExit: (exitCode, signal) => { - if (app) - app.emit(ElectronEvents.ElectronApplication.Close, exitCode, signal); - }, - }); + return Progress.runCancelableTask(async progress => { + let app: ElectronApplication | undefined = undefined; + const electronArguments = ['--inspect=0', '--remote-debugging-port=0', '--require', path.join(__dirname, 'electronLoader.js'), ...args]; + const { launchedProcess, gracefullyClose, kill } = await launchProcess({ + executablePath, + args: electronArguments, + env, + handleSIGINT, + handleSIGTERM, + handleSIGHUP, + progress, + pipe: true, + cwd: options.cwd, + tempDirectories: [], + attemptToGracefullyClose: () => app!.close(), + onExit: (exitCode, signal) => { + if (app) + app.emit(ElectronEvents.ElectronApplication.Close, exitCode, signal); + }, + }); - const timeoutError = new TimeoutError(`Timed out while trying to connect to Electron!`); - const nodeMatch = await waitForLine(launchedProcess, launchedProcess.stderr, /^Debugger listening on (ws:\/\/.*)$/, helper.timeUntilDeadline(deadline), timeoutError); - const nodeTransport = await WebSocketTransport.connect(nodeMatch[1], logger, deadline); - const nodeConnection = new CRConnection(nodeTransport, logger); + const nodeMatch = await waitForLine(progress, launchedProcess, launchedProcess.stderr, /^Debugger listening on (ws:\/\/.*)$/); + const nodeTransport = await WebSocketTransport.connect(progress, nodeMatch[1]); + const nodeConnection = new CRConnection(nodeTransport, logger); - const chromeMatch = await waitForLine(launchedProcess, launchedProcess.stderr, /^DevTools listening on (ws:\/\/.*)$/, helper.timeUntilDeadline(deadline), timeoutError); - const chromeTransport = await WebSocketTransport.connect(chromeMatch[1], logger, deadline); - const browserServer = new BrowserServer(launchedProcess, gracefullyClose, kill); - const browser = await CRBrowser.connect(chromeTransport, { headful: true, logger, persistent: { viewport: null }, ownedServer: browserServer }); - app = new ElectronApplication(logger, browser, nodeConnection); - await app._init(); - return app; + const chromeMatch = await waitForLine(progress, launchedProcess, launchedProcess.stderr, /^DevTools listening on (ws:\/\/.*)$/); + const chromeTransport = await WebSocketTransport.connect(progress, chromeMatch[1]); + const browserServer = new BrowserServer(launchedProcess, gracefullyClose, kill); + const browser = await CRBrowser.connect(chromeTransport, { headful: true, logger, persistent: { viewport: null }, ownedServer: browserServer }); + app = new ElectronApplication(logger, browser, nodeConnection); + await app._init(); + return app; + }, options, logger); } } diff --git a/src/server/processLauncher.ts b/src/server/processLauncher.ts index aa9577fb2c..f8553dcc2c 100644 --- a/src/server/processLauncher.ts +++ b/src/server/processLauncher.ts @@ -16,17 +16,17 @@ */ import * as childProcess from 'child_process'; -import { Log, RootLogger } from '../logger'; +import { Log } from '../logger'; import * as readline from 'readline'; import * as removeFolder from 'rimraf'; import * as stream from 'stream'; import * as util from 'util'; -import { TimeoutError } from '../errors'; import { helper } from '../helper'; +import { Progress } from '../progress'; const removeFolderAsync = util.promisify(removeFolder); -const browserLog: Log = { +export const browserLog: Log = { name: 'browser', }; @@ -57,7 +57,7 @@ export type LaunchProcessOptions = { // Note: attemptToGracefullyClose should reject if it does not close the browser. attemptToGracefullyClose: () => Promise, onExit: (exitCode: number | null, signal: string | null) => void, - logger: RootLogger, + progress: Progress, }; type LaunchResult = { @@ -73,9 +73,9 @@ export async function launchProcess(options: LaunchProcessOptions): Promise ${options.executablePath} ${options.args.join(' ')}`); + progress.log(browserLog, ` ${options.executablePath} ${options.args.join(' ')}`); const spawnedProcess = childProcess.spawn( options.executablePath, options.args, @@ -97,16 +97,16 @@ export async function launchProcess(options: LaunchProcessOptions): Promise failedPromise).then(e => Promise.reject(e)); } - logger._log(browserLog, ` pid=${spawnedProcess.pid}`); + progress.log(browserLog, ` pid=${spawnedProcess.pid}`); const stdout = readline.createInterface({ input: spawnedProcess.stdout }); stdout.on('line', (data: string) => { - logger._log(browserStdOutLog, data); + progress.log(browserStdOutLog, data); }); const stderr = readline.createInterface({ input: spawnedProcess.stderr }); stderr.on('line', (data: string) => { - logger._log(browserStdErrLog, data); + progress.log(browserStdErrLog, data); }); let processClosed = false; @@ -115,7 +115,7 @@ export async function launchProcess(options: LaunchProcessOptions): Promise {}; const waitForCleanup = new Promise(f => fulfillCleanup = f); spawnedProcess.once('exit', (exitCode, signal) => { - logger._log(browserLog, ``); + progress.log(browserLog, ``); processClosed = true; helper.removeEventListeners(listeners); options.onExit(exitCode, signal); @@ -142,21 +142,21 @@ export async function launchProcess(options: LaunchProcessOptions): Promise`); + progress.log(browserLog, ``); killProcess(); await waitForClose; // Ensure the process is dead and we called options.onkill. return; } gracefullyClosing = true; - logger._log(browserLog, ``); + progress.log(browserLog, ``); await options.attemptToGracefullyClose().catch(() => killProcess()); await waitForCleanup; // Ensure the process is dead and we have cleaned up. - logger._log(browserLog, ``); + progress.log(browserLog, ``); } // This method has to be sync to be used as 'exit' event handler. function killProcess() { - logger._log(browserLog, ``); + progress.log(browserLog, ``); helper.removeEventListeners(listeners); if (spawnedProcess.pid && !spawnedProcess.killed && !processClosed) { // Force kill the browser. @@ -184,36 +184,19 @@ export async function launchProcess(options: LaunchProcessOptions): Promise { +export function waitForLine(progress: Progress, process: childProcess.ChildProcess, inputStream: stream.Readable, regex: RegExp): Promise { return new Promise((resolve, reject) => { const rl = readline.createInterface({ input: inputStream }); - let stderr = ''; const listeners = [ helper.addEventListener(rl, 'line', onLine), - helper.addEventListener(rl, 'close', () => onClose()), - helper.addEventListener(process, 'exit', () => onClose()), - helper.addEventListener(process, 'error', error => onClose(error)) + helper.addEventListener(rl, 'close', reject), + helper.addEventListener(process, 'exit', reject), + helper.addEventListener(process, 'error', reject) ]; - const timeoutId = timeout ? setTimeout(onTimeout, timeout) : 0; - function onClose(error?: Error) { - cleanup(); - reject(new Error([ - 'Failed to launch browser!' + (error ? ' ' + error.message : ''), - stderr, - '', - 'TROUBLESHOOTING: https://github.com/Microsoft/playwright/blob/master/docs/troubleshooting.md', - '', - ].join('\n'))); - } - - function onTimeout() { - cleanup(); - reject(timeoutError); - } + progress.cleanupWhenCanceled(cleanup); function onLine(line: string) { - stderr += line + '\n'; const match = line.match(regex); if (!match) return; @@ -222,8 +205,6 @@ export function waitForLine(process: childProcess.ChildProcess, inputStream: str } function cleanup() { - if (timeoutId) - clearTimeout(timeoutId); helper.removeEventListeners(listeners); } }); diff --git a/src/timeoutSettings.ts b/src/timeoutSettings.ts index be0c276054..25673510ef 100644 --- a/src/timeoutSettings.ts +++ b/src/timeoutSettings.ts @@ -19,7 +19,7 @@ import { TimeoutOptions } from './types'; import { helper } from './helper'; import * as debugSupport from './debug/debugSupport'; -const DEFAULT_TIMEOUT = debugSupport.isDebugMode() ? 0 : 30000; +export const DEFAULT_TIMEOUT = debugSupport.isDebugMode() ? 0 : 30000; export class TimeoutSettings { private _parent: TimeoutSettings | undefined; diff --git a/src/transport.ts b/src/transport.ts index 92c6e153f3..c663d0bd5d 100644 --- a/src/transport.ts +++ b/src/transport.ts @@ -17,7 +17,9 @@ import * as WebSocket from 'ws'; import { helper } from './helper'; -import { Log, InnerLogger } from './logger'; +import { Log } from './logger'; +import { Progress } from './progress'; +import { browserLog } from './server/processLauncher'; export type ProtocolRequest = { id: number; @@ -120,34 +122,35 @@ export class DeferWriteTransport implements ConnectionTransport { export class WebSocketTransport implements ConnectionTransport { private _ws: WebSocket; - private _logger: InnerLogger; + private _progress: Progress; onmessage?: (message: ProtocolResponse) => void; onclose?: () => void; - static connect(url: string, logger: InnerLogger, deadline: number): Promise { - logger._log({ name: 'browser' }, ` ${url}`); - const transport = new WebSocketTransport(url, logger, deadline); - return new Promise((fulfill, reject) => { + static connect(progress: Progress, url: string): Promise { + progress.log(browserLog, ` ${url}`); + const transport = new WebSocketTransport(progress, url); + const promise = new Promise((fulfill, reject) => { transport._ws.addEventListener('open', async () => { - logger._log({ name: 'browser' }, ` ${url}`); + progress.log(browserLog, ` ${url}`); fulfill(transport); }); transport._ws.addEventListener('error', event => { - logger._log({ name: 'browser' }, ` ${url} ${event.message}`); + progress.log(browserLog, ` ${url} ${event.message}`); reject(new Error('WebSocket error: ' + event.message)); transport._ws.close(); }); }); + return progress.race(promise, () => transport.closeAndWait()); } - constructor(url: string, logger: InnerLogger, deadline: number) { + constructor(progress: Progress, url: string) { this._ws = new WebSocket(url, [], { perMessageDeflate: false, maxPayload: 256 * 1024 * 1024, // 256Mb, - handshakeTimeout: helper.timeUntilDeadline(deadline) + handshakeTimeout: helper.timeUntilDeadline(progress.deadline) }); - this._logger = logger; + this._progress = progress; // The 'ws' module in node sometimes sends us multiple messages in a single task. // In Web, all IO callbacks (e.g. WebSocket callbacks) // are dispatched into separate tasks, so there's no need @@ -162,7 +165,7 @@ export class WebSocketTransport implements ConnectionTransport { }); this._ws.addEventListener('close', event => { - this._logger && this._logger._log({ name: 'browser' }, ` ${url}`); + this._progress && this._progress.log(browserLog, ` ${url}`); if (this.onclose) this.onclose.call(null); }); @@ -175,9 +178,15 @@ export class WebSocketTransport implements ConnectionTransport { } close() { - this._logger && this._logger._log({ name: 'browser' }, ` ${this._ws.url}`); + this._progress && this._progress.log(browserLog, ` ${this._ws.url}`); this._ws.close(); } + + async closeAndWait() { + const promise = new Promise(f => this.onclose = f); + this.close(); + return promise; // Make sure to await the actual disconnect. + } } export class SequenceNumberMixer { diff --git a/test/defaultbrowsercontext.spec.js b/test/defaultbrowsercontext.spec.js index a45d1c6e28..2a68873d09 100644 --- a/test/defaultbrowsercontext.spec.js +++ b/test/defaultbrowsercontext.spec.js @@ -363,7 +363,7 @@ describe('launchPersistentContext()', function() { const userDataDir = await makeUserDataDir(); const options = { ...defaultBrowserOptions, timeout: 5000, __testHookBeforeCreateBrowser: () => new Promise(f => setTimeout(f, 6000)) }; const error = await browserType.launchPersistentContext(userDataDir, options).catch(e => e); - expect(error.message).toContain('Waiting for the browser to launch failed: timeout exceeded. Re-run with the DEBUG=pw:browser* env variable to see the debug log.'); + expect(error.message).toContain(`Timeout 5000ms exceeded during ${browserType.name()}.launchPersistentContext.`); await removeUserDataDir(userDataDir); }); it('should handle exception', async({browserType, defaultBrowserOptions}) => { diff --git a/test/launcher.spec.js b/test/launcher.spec.js index 45f94f7685..39d4083f77 100644 --- a/test/launcher.spec.js +++ b/test/launcher.spec.js @@ -53,7 +53,7 @@ describe('Playwright', function() { it('should handle timeout', async({browserType, defaultBrowserOptions}) => { const options = { ...defaultBrowserOptions, timeout: 5000, __testHookBeforeCreateBrowser: () => new Promise(f => setTimeout(f, 6000)) }; const error = await browserType.launch(options).catch(e => e); - expect(error.message).toContain('Waiting for the browser to launch failed: timeout exceeded. Re-run with the DEBUG=pw:browser* env variable to see the debug log.'); + expect(error.message).toContain(`Timeout 5000ms exceeded during ${browserType.name()}.launch.`); }); it('should handle exception', async({browserType, defaultBrowserOptions}) => { const e = new Error('Dummy'); @@ -285,11 +285,10 @@ describe('browserType.connect', function() { }); it.slow()('should handle exceptions during connect', async({browserType, defaultBrowserOptions, server}) => { const browserServer = await browserType.launchServer(defaultBrowserOptions); - const e = new Error('Dummy'); - const __testHookBeforeCreateBrowser = () => { throw e }; + const __testHookBeforeCreateBrowser = () => { throw new Error('Dummy') }; const error = await browserType.connect({ wsEndpoint: browserServer.wsEndpoint(), __testHookBeforeCreateBrowser }).catch(e => e); await browserServer._checkLeaks(); await browserServer.close(); - expect(error).toBe(e); + expect(error.message).toContain('Dummy'); }); });