Skip to content

Commit

Permalink
chore: introduce Progress concept (#2350)
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
dgozman authored May 29, 2020
1 parent 4bd9b30 commit d980ed7
Show file tree
Hide file tree
Showing 10 changed files with 243 additions and 222 deletions.
36 changes: 0 additions & 36 deletions src/logger.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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<string, number>([
Expand Down Expand Up @@ -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<string, debug.IDebugger>();

Expand Down
116 changes: 116 additions & 0 deletions src/progress.ts
Original file line number Diff line number Diff line change
@@ -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<T>(task: (progress: Progress) => Promise<T>, timeoutOptions: types.TimeoutOptions, logger: InnerLogger, apiName?: string): Promise<T> {
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<T>((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<any>;

private _logger: InnerLogger;
private _logRecording: string[] = [];
private _cleanups: (() => any)[] = [];
private _running = true;

constructor(options: types.TimeoutOptions, logger: InnerLogger, canceled: Promise<any>, 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<T>(promise: Promise<T>, cleanup?: () => any): Promise<T> {
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<T>([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)}`;
}
2 changes: 1 addition & 1 deletion src/server/browserServer.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
138 changes: 46 additions & 92 deletions src/server/browserType.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -102,56 +100,36 @@ export abstract class BrowserTypeBase implements BrowserType {
async launch(options: LaunchOptions = {}): Promise<Browser> {
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<BrowserContext> {
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);
return browser._defaultContext!;
}

async _innerLaunch(options: LaunchOptions, persistent: PersistentContextOptions | undefined, userDataDir?: string): Promise<BrowserBase> {
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();
}
const browser = await Progress.runCancelableTask(progress => this._innerLaunch(progress, options, logger, persistent, userDataDir), options, logger);
return browser._defaultContext!;
}

async _innerCreateBrowser(transport: ConnectionTransport, browserOptions: BrowserOptions, hasCustomArguments: boolean): Promise<BrowserBase> {
if ((browserOptions as any).__testHookBeforeCreateBrowser)
await (browserOptions as any).__testHookBeforeCreateBrowser();
async _innerLaunch(progress: Progress, options: LaunchOptions, logger: RootLogger, persistent: PersistentContextOptions | undefined, userDataDir?: string): Promise<BrowserBase> {
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;
}
Expand All @@ -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<Browser> {
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 = [],
Expand Down Expand Up @@ -238,7 +198,7 @@ export abstract class BrowserTypeBase implements BrowserType {
handleSIGINT,
handleSIGTERM,
handleSIGHUP,
logger,
progress,
pipe: !this._webSocketRegexNotPipe,
tempDirectories,
attemptToGracefullyClose: async () => {
Expand All @@ -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 };
}

Expand Down
Loading

0 comments on commit d980ed7

Please sign in to comment.