diff --git a/src/api.ts b/src/api.ts index 22c2b79d52..a2f0099d28 100644 --- a/src/api.ts +++ b/src/api.ts @@ -22,7 +22,7 @@ export { Dialog } from './dialog'; export { Download } from './download'; export { ElementHandle } from './dom'; export { FileChooser } from './fileChooser'; -export { Logger } from './logger'; +export { Logger } from './types'; export { TimeoutError } from './errors'; export { Frame } from './frames'; export { Keyboard, Mouse } from './input'; diff --git a/src/browser.ts b/src/browser.ts index 55d9d1c375..bdd5d312a9 100644 --- a/src/browser.ts +++ b/src/browser.ts @@ -20,11 +20,11 @@ import { EventEmitter } from 'events'; import { Download } from './download'; import type { BrowserServer } from './server/browserServer'; import { Events } from './events'; -import { InnerLogger } from './logger'; +import { Loggers } from './logger'; import { ProxySettings } from './types'; export type BrowserOptions = { - logger: InnerLogger, + loggers: Loggers, downloadsPath?: string, headful?: boolean, persistent?: PersistentContextOptions, // Undefined means no persistent context. diff --git a/src/browserContext.ts b/src/browserContext.ts index 8c217e0b29..96b624d754 100644 --- a/src/browserContext.ts +++ b/src/browserContext.ts @@ -25,7 +25,7 @@ import * as types from './types'; import { Events } from './events'; import { Download } from './download'; import { BrowserBase } from './browser'; -import { InnerLogger, Logger } from './logger'; +import { Loggers, Logger } from './logger'; import { EventEmitter } from 'events'; import { ProgressController } from './progress'; import { DebugController } from './debug/debugController'; @@ -52,7 +52,7 @@ type CommonContextOptions = { export type PersistentContextOptions = CommonContextOptions; export type BrowserContextOptions = CommonContextOptions & { - logger?: Logger, + logger?: types.Logger, }; export interface BrowserContext { @@ -89,14 +89,15 @@ export abstract class BrowserContextBase extends EventEmitter implements Browser readonly _permissions = new Map(); readonly _downloads = new Set(); readonly _browserBase: BrowserBase; - readonly _logger: InnerLogger; + readonly _apiLogger: Logger; private _debugController: DebugController | undefined; constructor(browserBase: BrowserBase, options: BrowserContextOptions) { super(); this._browserBase = browserBase; this._options = options; - this._logger = options.logger ? new InnerLogger(options.logger) : browserBase._options.logger; + const loggers = options.logger ? new Loggers(options.logger) : browserBase._options.loggers; + this._apiLogger = loggers.api; this._closePromise = new Promise(fulfill => this._closePromiseFulfill = fulfill); } @@ -115,7 +116,7 @@ export abstract class BrowserContextBase extends EventEmitter implements Browser async waitForEvent(event: string, optionsOrPredicate: types.WaitForEventOptions = {}): Promise { const options = typeof optionsOrPredicate === 'function' ? { predicate: optionsOrPredicate } : optionsOrPredicate; - const progressController = new ProgressController(this._logger, this._timeoutSettings.timeout(options)); + const progressController = new ProgressController(this._apiLogger, this._timeoutSettings.timeout(options), 'browserContext.waitForEvent'); if (event !== Events.BrowserContext.Close) this._closePromise.then(error => progressController.abort(error)); return progressController.run(progress => helper.waitForEvent(progress, this, event, options.predicate)); diff --git a/src/chromium/crBrowser.ts b/src/chromium/crBrowser.ts index cec2a2f139..49e1f8496e 100644 --- a/src/chromium/crBrowser.ts +++ b/src/chromium/crBrowser.ts @@ -46,7 +46,7 @@ export class CRBrowser extends BrowserBase { private _tracingClient: CRSession | undefined; static async connect(transport: ConnectionTransport, options: BrowserOptions, devtools?: CRDevTools): Promise { - const connection = new CRConnection(SlowMoTransport.wrap(transport, options.slowMo), options.logger); + const connection = new CRConnection(SlowMoTransport.wrap(transport, options.slowMo), options.loggers); const browser = new CRBrowser(connection, options); browser._devtools = devtools; const session = connection.rootSession; diff --git a/src/chromium/crConnection.ts b/src/chromium/crConnection.ts index bf641674a4..ed05aee9b4 100644 --- a/src/chromium/crConnection.ts +++ b/src/chromium/crConnection.ts @@ -16,10 +16,10 @@ */ import { assert } from '../helper'; -import { ConnectionTransport, ProtocolRequest, ProtocolResponse, protocolLog } from '../transport'; +import { ConnectionTransport, ProtocolRequest, ProtocolResponse } from '../transport'; import { Protocol } from './protocol'; import { EventEmitter } from 'events'; -import { InnerLogger, errorLog } from '../logger'; +import { Loggers, Logger } from '../logger'; import { rewriteErrorMessage } from '../utils/stackTrace'; export const ConnectionEvents = { @@ -36,12 +36,12 @@ export class CRConnection extends EventEmitter { private readonly _sessions = new Map(); readonly rootSession: CRSession; _closed = false; - readonly _logger: InnerLogger; + readonly _logger: Logger; - constructor(transport: ConnectionTransport, logger: InnerLogger) { + constructor(transport: ConnectionTransport, loggers: Loggers) { super(); this._transport = transport; - this._logger = logger; + this._logger = loggers.protocol; this._transport.onmessage = this._onMessage.bind(this); this._transport.onclose = this._onClose.bind(this); this.rootSession = new CRSession(this, '', 'browser', ''); @@ -62,15 +62,15 @@ export class CRConnection extends EventEmitter { const message: ProtocolRequest = { id, method, params }; if (sessionId) message.sessionId = sessionId; - if (this._logger.isLogEnabled(protocolLog)) - this._logger.log(protocolLog, 'SEND ► ' + rewriteInjectedScriptEvaluationLog(message)); + if (this._logger.isEnabled()) + this._logger.info('SEND ► ' + rewriteInjectedScriptEvaluationLog(message)); this._transport.send(message); return id; } async _onMessage(message: ProtocolResponse) { - if (this._logger.isLogEnabled(protocolLog)) - this._logger.log(protocolLog, '◀ RECV ' + JSON.stringify(message)); + if (this._logger.isEnabled()) + this._logger.info('◀ RECV ' + JSON.stringify(message)); if (message.id === kBrowserCloseMessageId) return; if (message.method === 'Target.attachedToTarget') { @@ -166,9 +166,9 @@ export class CRSession extends EventEmitter { } _sendMayFail(method: T, params?: Protocol.CommandParameters[T]): Promise { - return this.send(method, params).catch(error => { + return this.send(method, params).catch((error: Error) => { if (this._connection) - this._connection._logger.log(errorLog, error, []); + this._connection._logger.error(error); }); } diff --git a/src/dom.ts b/src/dom.ts index 67900d864c..bc8ceffe06 100644 --- a/src/dom.ts +++ b/src/dom.ts @@ -28,8 +28,7 @@ import * as js from './javascript'; import { Page } from './page'; import { selectors } from './selectors'; import * as types from './types'; -import { apiLog } from './logger'; -import { Progress, runAbortableTask } from './progress'; +import { Progress, ProgressController } from './progress'; import DebugScript from './debug/injected/debugScript'; export type PointerActionOptions = { @@ -120,6 +119,11 @@ export class ElementHandle extends js.JSHandle { this._initializePreview().catch(e => {}); } + private _runAbortableTask(task: (progress: Progress) => Promise, timeout: number, apiName: string): Promise { + const controller = new ProgressController(this._page._logger, timeout, `elementHandle.${apiName}`); + return controller.run(task); + } + async _initializePreview() { const utility = await this._context.injectedScript(); this._preview = await utility.evaluate((injected, e) => 'JSHandle@' + injected.previewNode(e), this); @@ -268,25 +272,25 @@ export class ElementHandle extends js.JSHandle { async _retryPointerAction(progress: Progress, action: (point: types.Point) => Promise, options: PointerActionOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions): Promise<'notconnected' | 'done'> { let first = true; while (progress.isRunning()) { - progress.log(apiLog, `${first ? 'attempting' : 'retrying'} ${progress.apiName} action`); + progress.logger.info(`${first ? 'attempting' : 'retrying'} ${progress.apiName} action`); const result = await this._performPointerAction(progress, action, options); first = false; if (result === 'notvisible') { if (options.force) throw new Error('Element is not visible'); - progress.log(apiLog, ' element is not visible'); + progress.logger.info(' element is not visible'); continue; } if (result === 'notinviewport') { if (options.force) throw new Error('Element is outside of the viewport'); - progress.log(apiLog, ' element is outside of the viewport'); + progress.logger.info(' element is outside of the viewport'); continue; } if (result === 'nothittarget') { if (options.force) throw new Error('Element does not receive pointer events'); - progress.log(apiLog, ' element does not receive pointer events'); + progress.logger.info(' element does not receive pointer events'); continue; } if (result === 'notconnected') @@ -306,14 +310,14 @@ export class ElementHandle extends js.JSHandle { if ((options as any).__testHookAfterStable) await (options as any).__testHookAfterStable(); - progress.log(apiLog, ' scrolling into view if needed'); + progress.logger.info(' scrolling into view if needed'); progress.throwIfAborted(); // Avoid action that has side-effects. const scrolled = await this._scrollRectIntoViewIfNeeded(position ? { x: position.x, y: position.y, width: 0, height: 0 } : undefined); if (scrolled === 'notvisible') return 'notvisible'; if (scrolled === 'notconnected') return 'notconnected'; - progress.log(apiLog, ' done scrolling'); + progress.logger.info(' done scrolling'); const maybePoint = position ? await this._offsetPoint(position) : await this._clickablePoint(); if (maybePoint === 'notvisible') @@ -325,13 +329,13 @@ export class ElementHandle extends js.JSHandle { if (!force) { if ((options as any).__testHookBeforeHitTarget) await (options as any).__testHookBeforeHitTarget(); - progress.log(apiLog, ` checking that element receives pointer events at (${point.x},${point.y})`); + progress.logger.info(` checking that element receives pointer events at (${point.x},${point.y})`); const hitTargetResult = await this._checkHitTargetAt(point); if (hitTargetResult === 'notconnected') return 'notconnected'; if (hitTargetResult === 'nothittarget') return 'nothittarget'; - progress.log(apiLog, ` element does receive pointer events`); + progress.logger.info(` element does receive pointer events`); } await this._page._frameManager.waitForSignalsCreatedBy(progress, options.noWaitAfter, async () => { @@ -341,24 +345,24 @@ export class ElementHandle extends js.JSHandle { let restoreModifiers: input.Modifier[] | undefined; if (options && options.modifiers) restoreModifiers = await this._page.keyboard._ensureModifiers(options.modifiers); - progress.log(apiLog, ` performing ${progress.apiName} action`); + progress.logger.info(` performing ${progress.apiName} action`); await action(point); - progress.log(apiLog, ` ${progress.apiName} action done`); - progress.log(apiLog, ' waiting for scheduled navigations to finish'); + progress.logger.info(` ${progress.apiName} action done`); + progress.logger.info(' waiting for scheduled navigations to finish'); if ((options as any).__testHookAfterPointerAction) await (options as any).__testHookAfterPointerAction(); if (restoreModifiers) await this._page.keyboard._ensureModifiers(restoreModifiers); }, 'input'); - progress.log(apiLog, ' navigations have finished'); + progress.logger.info(' navigations have finished'); return 'done'; } hover(options: PointerActionOptions & types.PointerActionWaitOptions = {}): Promise { - return runAbortableTask(async progress => { + return this._runAbortableTask(async progress => { throwIfNotConnected(await this._hover(progress, options)); - }, this._page._logger, this._page._timeoutSettings.timeout(options)); + }, this._page._timeoutSettings.timeout(options), 'hover'); } _hover(progress: Progress, options: PointerActionOptions & types.PointerActionWaitOptions): Promise<'notconnected' | 'done'> { @@ -366,9 +370,9 @@ export class ElementHandle extends js.JSHandle { } click(options: ClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}): Promise { - return runAbortableTask(async progress => { + return this._runAbortableTask(async progress => { throwIfNotConnected(await this._click(progress, options)); - }, this._page._logger, this._page._timeoutSettings.timeout(options)); + }, this._page._timeoutSettings.timeout(options), 'click'); } _click(progress: Progress, options: ClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions): Promise<'notconnected' | 'done'> { @@ -376,9 +380,9 @@ export class ElementHandle extends js.JSHandle { } dblclick(options: MultiClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}): Promise { - return runAbortableTask(async progress => { + return this._runAbortableTask(async progress => { throwIfNotConnected(await this._dblclick(progress, options)); - }, this._page._logger, this._page._timeoutSettings.timeout(options)); + }, this._page._timeoutSettings.timeout(options), 'dblclick'); } _dblclick(progress: Progress, options: MultiClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions): Promise<'notconnected' | 'done'> { @@ -386,9 +390,9 @@ export class ElementHandle extends js.JSHandle { } async selectOption(values: string | ElementHandle | types.SelectOption | string[] | ElementHandle[] | types.SelectOption[] | null, options: types.NavigatingActionWaitOptions = {}): Promise { - return runAbortableTask(async progress => { + return this._runAbortableTask(async progress => { return throwIfNotConnected(await this._selectOption(progress, values, options)); - }, this._page._logger, this._page._timeoutSettings.timeout(options)); + }, this._page._timeoutSettings.timeout(options), 'selectOption'); } async _selectOption(progress: Progress, values: string | ElementHandle | types.SelectOption | string[] | ElementHandle[] | types.SelectOption[] | null, options: types.NavigatingActionWaitOptions): Promise { @@ -419,16 +423,16 @@ export class ElementHandle extends js.JSHandle { } async fill(value: string, options: types.NavigatingActionWaitOptions = {}): Promise { - return runAbortableTask(async progress => { + return this._runAbortableTask(async progress => { throwIfNotConnected(await this._fill(progress, value, options)); - }, this._page._logger, this._page._timeoutSettings.timeout(options)); + }, this._page._timeoutSettings.timeout(options), 'fill'); } async _fill(progress: Progress, value: string, options: types.NavigatingActionWaitOptions): Promise<'notconnected' | 'done'> { - progress.log(apiLog, `elementHandle.fill("${value}")`); + progress.logger.info(`elementHandle.fill("${value}")`); assert(helper.isString(value), 'Value must be string. Found value "' + value + '" of type "' + (typeof value) + '"'); return this._page._frameManager.waitForSignalsCreatedBy(progress, options.noWaitAfter, async () => { - progress.log(apiLog, ' waiting for element to be visible, enabled and editable'); + progress.logger.info(' waiting for element to be visible, enabled and editable'); const poll = await this._evaluateHandleInUtility(([injected, node, value]) => { return injected.waitForEnabledAndFill(node, value); }, value); @@ -437,7 +441,7 @@ export class ElementHandle extends js.JSHandle { progress.throwIfAborted(); // Avoid action that has side-effects. if (filled === 'notconnected') return 'notconnected'; - progress.log(apiLog, ' element is visible, enabled and editable'); + progress.logger.info(' element is visible, enabled and editable'); if (filled === 'needsinput') { if (value) await this._page.keyboard.insertText(value); @@ -449,17 +453,17 @@ export class ElementHandle extends js.JSHandle { } async selectText(): Promise { - return runAbortableTask(async progress => { + return this._runAbortableTask(async progress => { progress.throwIfAborted(); // Avoid action that has side-effects. const selected = throwIfError(await this._evaluateInUtility(([injected, node]) => injected.selectText(node), {})); throwIfNotConnected(selected); - }, this._page._logger, 0); + }, 0, 'selectText'); } async setInputFiles(files: string | types.FilePayload | string[] | types.FilePayload[], options: types.NavigatingActionWaitOptions = {}) { - return runAbortableTask(async progress => { + return this._runAbortableTask(async progress => { throwIfNotConnected(await this._setInputFiles(progress, files, options)); - }, this._page._logger, this._page._timeoutSettings.timeout(options)); + }, this._page._timeoutSettings.timeout(options), 'setInputFiles'); } async _setInputFiles(progress: Progress, files: string | types.FilePayload | string[] | types.FilePayload[], options: types.NavigatingActionWaitOptions): Promise<'notconnected' | 'done'> { @@ -500,9 +504,9 @@ export class ElementHandle extends js.JSHandle { } async focus(): Promise { - return runAbortableTask(async progress => { + return this._runAbortableTask(async progress => { throwIfNotConnected(await this._focus(progress)); - }, this._page._logger, 0); + }, 0, 'focus'); } async _focus(progress: Progress): Promise<'notconnected' | 'done'> { @@ -511,13 +515,13 @@ export class ElementHandle extends js.JSHandle { } async type(text: string, options: { delay?: number } & types.NavigatingActionWaitOptions = {}): Promise { - return runAbortableTask(async progress => { + return this._runAbortableTask(async progress => { throwIfNotConnected(await this._type(progress, text, options)); - }, this._page._logger, this._page._timeoutSettings.timeout(options)); + }, this._page._timeoutSettings.timeout(options), 'type'); } async _type(progress: Progress, text: string, options: { delay?: number } & types.NavigatingActionWaitOptions): Promise<'notconnected' | 'done'> { - progress.log(apiLog, `elementHandle.type("${text}")`); + progress.logger.info(`elementHandle.type("${text}")`); return this._page._frameManager.waitForSignalsCreatedBy(progress, options.noWaitAfter, async () => { const focused = await this._focus(progress); if (focused === 'notconnected') @@ -529,13 +533,13 @@ export class ElementHandle extends js.JSHandle { } async press(key: string, options: { delay?: number } & types.NavigatingActionWaitOptions = {}): Promise { - return runAbortableTask(async progress => { + return this._runAbortableTask(async progress => { throwIfNotConnected(await this._press(progress, key, options)); - }, this._page._logger, this._page._timeoutSettings.timeout(options)); + }, this._page._timeoutSettings.timeout(options), 'press'); } async _press(progress: Progress, key: string, options: { delay?: number } & types.NavigatingActionWaitOptions): Promise<'notconnected' | 'done'> { - progress.log(apiLog, `elementHandle.press("${key}")`); + progress.logger.info(`elementHandle.press("${key}")`); return this._page._frameManager.waitForSignalsCreatedBy(progress, options.noWaitAfter, async () => { const focused = await this._focus(progress); if (focused === 'notconnected') @@ -547,11 +551,11 @@ export class ElementHandle extends js.JSHandle { } async check(options: types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}) { - return runAbortableTask(progress => this._setChecked(progress, true, options), this._page._logger, this._page._timeoutSettings.timeout(options)); + return this._runAbortableTask(progress => this._setChecked(progress, true, options), this._page._timeoutSettings.timeout(options), 'check'); } async uncheck(options: types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}) { - return runAbortableTask(progress => this._setChecked(progress, false, options), this._page._logger, this._page._timeoutSettings.timeout(options)); + return this._runAbortableTask(progress => this._setChecked(progress, false, options), this._page._timeoutSettings.timeout(options), 'uncheck'); } async _setChecked(progress: Progress, state: boolean, options: types.PointerActionWaitOptions & types.NavigatingActionWaitOptions) { @@ -599,14 +603,14 @@ export class ElementHandle extends js.JSHandle { } async _waitForDisplayedAtStablePositionAndEnabled(progress: Progress): Promise<'notconnected' | 'done'> { - progress.log(apiLog, ' waiting for element to be visible, enabled and not moving'); + progress.logger.info(' waiting for element to be visible, enabled and not moving'); const rafCount = this._page._delegate.rafCountForStablePosition(); const poll = this._evaluateHandleInUtility(([injected, node, rafCount]) => { return injected.waitForDisplayedAtStablePositionAndEnabled(node, rafCount); }, rafCount); const pollHandler = new InjectedScriptPollHandler(progress, await poll); const result = throwIfError(await pollHandler.finish()); - progress.log(apiLog, ' element is visible, enabled and does not move'); + progress.logger.info(' element is visible, enabled and does not move'); return result; } @@ -651,7 +655,7 @@ export class InjectedScriptPollHandler { return; logs.evaluate(logs => logs.current).catch(e => [] as string[]).then(messages => { for (const message of messages) - this._progress.log(apiLog, message); + this._progress.logger.info(message); }); this._streamLogs(logs.evaluateHandle(logs => logs.next)); }); @@ -683,7 +687,7 @@ export class InjectedScriptPollHandler { // Retrieve all the logs before continuing. const messages = await this._poll.evaluate(poll => poll.takeLastLogs()).catch(e => [] as string[]); for (const message of messages) - this._progress.log(apiLog, message); + this._progress.logger.info(message); } async cancel() { diff --git a/src/firefox/ffBrowser.ts b/src/firefox/ffBrowser.ts index 85b3b211ca..3756f52f28 100644 --- a/src/firefox/ffBrowser.ts +++ b/src/firefox/ffBrowser.ts @@ -35,7 +35,7 @@ export class FFBrowser extends BrowserBase { private _eventListeners: RegisteredListener[]; static async connect(transport: ConnectionTransport, options: BrowserOptions): Promise { - const connection = new FFConnection(SlowMoTransport.wrap(transport, options.slowMo), options.logger); + const connection = new FFConnection(SlowMoTransport.wrap(transport, options.slowMo), options.loggers); const browser = new FFBrowser(connection, options); const promises: Promise[] = [ connection.send('Browser.enable', { attachToDefaultContext: !!options.persistent }), diff --git a/src/firefox/ffConnection.ts b/src/firefox/ffConnection.ts index 15a80c338b..53e8a1a7ba 100644 --- a/src/firefox/ffConnection.ts +++ b/src/firefox/ffConnection.ts @@ -17,9 +17,9 @@ import { EventEmitter } from 'events'; import { assert } from '../helper'; -import { ConnectionTransport, ProtocolRequest, ProtocolResponse, protocolLog } from '../transport'; +import { ConnectionTransport, ProtocolRequest, ProtocolResponse } from '../transport'; import { Protocol } from './protocol'; -import { InnerLogger, errorLog } from '../logger'; +import { Loggers, Logger } from '../logger'; import { rewriteErrorMessage } from '../utils/stackTrace'; export const ConnectionEvents = { @@ -34,7 +34,7 @@ export class FFConnection extends EventEmitter { private _lastId: number; private _callbacks: Map; private _transport: ConnectionTransport; - readonly _logger: InnerLogger; + readonly _logger: Logger; readonly _sessions: Map; _closed: boolean; @@ -44,10 +44,10 @@ export class FFConnection extends EventEmitter { removeListener: (event: T, listener: (payload: T extends symbol ? any : Protocol.Events[T extends keyof Protocol.Events ? T : never]) => void) => this; once: (event: T, listener: (payload: T extends symbol ? any : Protocol.Events[T extends keyof Protocol.Events ? T : never]) => void) => this; - constructor(transport: ConnectionTransport, logger: InnerLogger) { + constructor(transport: ConnectionTransport, loggers: Loggers) { super(); this._transport = transport; - this._logger = logger; + this._logger = loggers.protocol; this._lastId = 0; this._callbacks = new Map(); @@ -79,14 +79,14 @@ export class FFConnection extends EventEmitter { } _rawSend(message: ProtocolRequest) { - if (this._logger.isLogEnabled(protocolLog)) - this._logger.log(protocolLog, 'SEND ► ' + rewriteInjectedScriptEvaluationLog(message)); + if (this._logger.isEnabled()) + this._logger.info('SEND ► ' + rewriteInjectedScriptEvaluationLog(message)); this._transport.send(message); } async _onMessage(message: ProtocolResponse) { - if (this._logger.isLogEnabled(protocolLog)) - this._logger.log(protocolLog, '◀ RECV ' + JSON.stringify(message)); + if (this._logger.isEnabled()) + this._logger.info('◀ RECV ' + JSON.stringify(message)); if (message.id === kBrowserCloseMessageId) return; if (message.sessionId) { @@ -187,7 +187,7 @@ export class FFSession extends EventEmitter { sendMayFail(method: T, params?: Protocol.CommandParameters[T]): Promise { return this.send(method, params).catch(error => { - this._connection._logger.log(errorLog, error, []); + this._connection._logger.error(error); }); } diff --git a/src/frames.ts b/src/frames.ts index a01425e51e..61f5139fb5 100644 --- a/src/frames.ts +++ b/src/frames.ts @@ -26,10 +26,8 @@ import * as network from './network'; import { Page } from './page'; import { selectors } from './selectors'; import * as types from './types'; -import { waitForTimeoutWasUsed } from './hints'; import { BrowserContext } from './browserContext'; -import { Progress, ProgressController, runAbortableTask } from './progress'; -import { apiLog } from './logger'; +import { Progress, ProgressController } from './progress'; type ContextType = 'main' | 'utility'; type ContextData = { @@ -340,11 +338,21 @@ export class Frame { this._parentFrame._childFrames.add(this); } + private _runAbortableTask(task: (progress: Progress) => Promise, timeout: number, apiName: string): Promise { + const controller = new ProgressController(this._page._logger, timeout, this._apiName(apiName)); + return controller.run(task); + } + + private _apiName(method: string) { + const subject = this._page._callingPageAPI ? 'page' : 'frame'; + return `${subject}.${method}`; + } + async goto(url: string, options: GotoOptions = {}): Promise { - const progressController = new ProgressController(this._page._logger, this._page._timeoutSettings.navigationTimeout(options)); + const progressController = new ProgressController(this._page._logger, this._page._timeoutSettings.navigationTimeout(options), this._apiName('goto')); abortProgressOnFrameDetach(progressController, this); return progressController.run(async progress => { - progress.log(apiLog, `navigating to "${url}", waiting until "${options.waitUntil || 'load'}"`); + progress.logger.info(`navigating to "${url}", waiting until "${options.waitUntil || 'load'}"`); const headers = (this._page._state.extraHTTPHeaders || {}); let referer = headers['referer'] || headers['Referer']; if (options.referer !== undefined) { @@ -376,11 +384,11 @@ export class Frame { } async waitForNavigation(options: types.WaitForNavigationOptions = {}): Promise { - const progressController = new ProgressController(this._page._logger, this._page._timeoutSettings.navigationTimeout(options)); + const progressController = new ProgressController(this._page._logger, this._page._timeoutSettings.navigationTimeout(options), this._apiName('waitForNavigation')); abortProgressOnFrameDetach(progressController, this); return progressController.run(async progress => { const toUrl = typeof options.url === 'string' ? ` to "${options.url}"` : ''; - progress.log(apiLog, `waiting for navigation${toUrl} until "${options.waitUntil || 'load'}"`); + progress.logger.info(`waiting for navigation${toUrl} until "${options.waitUntil || 'load'}"`); const frameTask = new FrameTask(this, progress); let documentId: string | undefined; await Promise.race([ @@ -395,7 +403,7 @@ export class Frame { } async waitForLoadState(state: types.LifecycleEvent = 'load', options: types.TimeoutOptions = {}): Promise { - const progressController = new ProgressController(this._page._logger, this._page._timeoutSettings.navigationTimeout(options)); + const progressController = new ProgressController(this._page._logger, this._page._timeoutSettings.navigationTimeout(options), this._apiName('waitForLoadState')); abortProgressOnFrameDetach(progressController, this); return progressController.run(progress => this._waitForLoadState(progress, state)); } @@ -453,8 +461,8 @@ export class Frame { if (!['attached', 'detached', 'visible', 'hidden'].includes(state)) throw new Error(`Unsupported state option "${state}"`); const { world, task } = selectors._waitForSelectorTask(selector, state); - return runAbortableTask(async progress => { - progress.log(apiLog, `waiting for selector "${selector}"${state === 'attached' ? '' : ' to be ' + state}`); + return this._runAbortableTask(async progress => { + progress.logger.info(`waiting for selector "${selector}"${state === 'attached' ? '' : ' to be ' + state}`); const result = await this._scheduleRerunnableTask(progress, world, task); if (!result.asElement()) { result.dispose(); @@ -468,16 +476,16 @@ export class Frame { return adopted; } return handle; - }, this._page._logger, this._page._timeoutSettings.timeout(options)); + }, this._page._timeoutSettings.timeout(options), 'waitForSelector'); } async dispatchEvent(selector: string, type: string, eventInit?: Object, options: types.TimeoutOptions = {}): Promise { const task = selectors._dispatchEventTask(selector, type, eventInit || {}); - return runAbortableTask(async progress => { - progress.log(apiLog, `Dispatching "${type}" event on selector "${selector}"...`); + return this._runAbortableTask(async progress => { + progress.logger.info(`Dispatching "${type}" event on selector "${selector}"...`); const result = await this._scheduleRerunnableTask(progress, 'main', task); result.dispose(); - }, this._page._logger, this._page._timeoutSettings.timeout(options)); + }, this._page._timeoutSettings.timeout(options), 'dispatchEvent'); } async $eval(selector: string, pageFunction: types.FuncOn, arg: Arg): Promise; @@ -519,11 +527,11 @@ export class Frame { } async setContent(html: string, options: types.NavigateOptions = {}): Promise { - const progressController = new ProgressController(this._page._logger, this._page._timeoutSettings.navigationTimeout(options)); + const progressController = new ProgressController(this._page._logger, this._page._timeoutSettings.navigationTimeout(options), this._apiName('setContent')); abortProgressOnFrameDetach(progressController, this); return progressController.run(async progress => { const waitUntil = options.waitUntil === undefined ? 'load' : options.waitUntil; - progress.log(apiLog, `setting frame content, waiting until "${waitUntil}"`); + progress.logger.info(`setting frame content, waiting until "${waitUntil}"`); const tag = `--playwright--set--content--${this._id}--${++this._setContentCounter}--`; const context = await this._utilityContext(); const lifecyclePromise = new Promise((resolve, reject) => { @@ -706,10 +714,11 @@ export class Frame { private async _retryWithSelectorIfNotConnected( selector: string, options: types.TimeoutOptions, - action: (progress: Progress, handle: dom.ElementHandle) => Promise): Promise { - return runAbortableTask(async progress => { + action: (progress: Progress, handle: dom.ElementHandle) => Promise, + apiName: string): Promise { + return this._runAbortableTask(async progress => { while (progress.isRunning()) { - progress.log(apiLog, `waiting for selector "${selector}"`); + progress.logger.info(`waiting for selector "${selector}"`); const { world, task } = selectors._waitForSelectorTask(selector, 'attached'); const handle = await this._scheduleRerunnableTask(progress, world, task); const element = handle.asElement() as dom.ElementHandle; @@ -717,77 +726,76 @@ export class Frame { const result = await action(progress, element); element.dispose(); if (result === 'notconnected') { - progress.log(apiLog, 'element was detached from the DOM, retrying'); + progress.logger.info('element was detached from the DOM, retrying'); continue; } return result; } return undefined as any; - }, this._page._logger, this._page._timeoutSettings.timeout(options)); + }, this._page._timeoutSettings.timeout(options), apiName); } async click(selector: string, options: dom.ClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}) { - await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._click(progress, options)); + await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._click(progress, options), 'click'); } async dblclick(selector: string, options: dom.MultiClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}) { - await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._dblclick(progress, options)); + await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._dblclick(progress, options), 'dblclick'); } async fill(selector: string, value: string, options: types.NavigatingActionWaitOptions = {}) { - await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._fill(progress, value, options)); + await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._fill(progress, value, options), 'fill'); } async focus(selector: string, options: types.TimeoutOptions = {}) { - await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._focus(progress)); + await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._focus(progress), 'focus'); } async textContent(selector: string, options: types.TimeoutOptions = {}): Promise { - return await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle.textContent()); + return await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle.textContent(), 'textContent'); } async innerText(selector: string, options: types.TimeoutOptions = {}): Promise { - return await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle.innerText()); + return await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle.innerText(), 'innerText'); } async innerHTML(selector: string, options: types.TimeoutOptions = {}): Promise { - return await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle.innerHTML()); + return await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle.innerHTML(), 'innerHTML'); } async getAttribute(selector: string, name: string, options: types.TimeoutOptions = {}): Promise { - return await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle.getAttribute(name)); + return await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle.getAttribute(name), 'getAttribute'); } async hover(selector: string, options: dom.PointerActionOptions & types.PointerActionWaitOptions = {}) { - await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._hover(progress, options)); + await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._hover(progress, options), 'hover'); } async selectOption(selector: string, values: string | dom.ElementHandle | types.SelectOption | string[] | dom.ElementHandle[] | types.SelectOption[] | null, options: types.NavigatingActionWaitOptions = {}): Promise { - return this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._selectOption(progress, values, options)); + return this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._selectOption(progress, values, options), 'selectOption'); } async setInputFiles(selector: string, files: string | types.FilePayload | string[] | types.FilePayload[], options: types.NavigatingActionWaitOptions = {}): Promise { - await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._setInputFiles(progress, files, options)); + await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._setInputFiles(progress, files, options), 'setInputFiles'); } async type(selector: string, text: string, options: { delay?: number } & types.NavigatingActionWaitOptions = {}) { - await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._type(progress, text, options)); + await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._type(progress, text, options), 'type'); } async press(selector: string, key: string, options: { delay?: number } & types.NavigatingActionWaitOptions = {}) { - await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._press(progress, key, options)); + await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._press(progress, key, options), 'press'); } async check(selector: string, options: types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}) { - await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._setChecked(progress, true, options)); + await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._setChecked(progress, true, options), 'check'); } async uncheck(selector: string, options: types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}) { - await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._setChecked(progress, false, options)); + await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._setChecked(progress, false, options), 'uncheck'); } async waitForTimeout(timeout: number) { - waitForTimeoutWasUsed(this._page); await new Promise(fulfill => setTimeout(fulfill, timeout)); } @@ -809,9 +817,9 @@ export class Frame { return injectedScript.poll(polling, () => innerPredicate(arg)); }, { injectedScript, predicateBody, polling, arg }); }; - return runAbortableTask( + return this._runAbortableTask( progress => this._scheduleRerunnableTask(progress, 'main', task), - this._page._logger, this._page._timeoutSettings.timeout(options)); + this._page._timeoutSettings.timeout(options), 'waitForFunction'); } async title(): Promise { @@ -999,14 +1007,14 @@ class FrameTask { onSameDocument() { if (this._progress) - this._progress.log(apiLog, `navigated to "${this._frame._url}"`); + this._progress.logger.info(`navigated to "${this._frame._url}"`); if (this._onSameDocument && helper.urlMatches(this._frame.url(), this._onSameDocument.url)) this._onSameDocument.resolve(); } onNewDocument(documentId: string, error?: Error) { if (this._progress && !error) - this._progress.log(apiLog, `navigated to "${this._frame._url}"`); + this._progress.logger.info(`navigated to "${this._frame._url}"`); if (this._onSpecificDocument) { if (documentId === this._onSpecificDocument.expectedDocumentId) { if (error) @@ -1027,7 +1035,7 @@ class FrameTask { onLifecycle(frame: Frame, lifecycleEvent: types.LifecycleEvent) { if (this._progress && frame === this._frame && frame._url !== 'about:blank') - this._progress.log(apiLog, `"${lifecycleEvent}" event fired`); + this._progress.logger.info(`"${lifecycleEvent}" event fired`); if (this._onLifecycle && this._checkLifecycleRecursively(this._frame, this._onLifecycle.waitUntil)) this._onLifecycle.resolve(); } diff --git a/src/hints.ts b/src/hints.ts deleted file mode 100644 index 25107a90ca..0000000000 --- a/src/hints.ts +++ /dev/null @@ -1,33 +0,0 @@ -/** - * 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 { Page } from './page'; -import { Log } from './logger'; - -const hintsLog: Log = { - name: 'hint', - severity: 'warning' -}; - -let waitForTimeoutWasUsedReported = false; -export function waitForTimeoutWasUsed(page: Page) { - if (waitForTimeoutWasUsedReported) - return; - waitForTimeoutWasUsedReported = true; - page._logger.log(hintsLog, `WARNING: page.waitForTimeout(timeout) should only be used for debugging. -Tests using the timer in production are going to be flaky. -Use signals such as network events, selectors becoming visible, etc. instead.`); -} diff --git a/src/logger.ts b/src/logger.ts index 99eb11a2a1..d46ccf1a73 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -15,49 +15,116 @@ */ import * as debug from 'debug'; +import { helper } from './helper'; +import { Logger as LoggerSink, LoggerSeverity } from './types'; -export type LoggerSeverity = 'verbose' | 'info' | 'warning' | 'error'; - -export type Log = { - name: string; - severity?: LoggerSeverity; - color?: string | undefined; -}; - -export interface Logger { - isEnabled(name: string, severity: LoggerSeverity): boolean; - log(name: string, severity: LoggerSeverity, message: string | Error, args: any[], hints: { color?: string }): void; +export function logError(logger: Logger): (error: Error) => void { + return error => logger.error(error); } -export const errorLog: Log = { name: 'generic', severity: 'error' }; -export const apiLog: Log = { name: 'api', color: 'cyan' }; +export class Logger { + private _loggerSink: LoggerSink; + private _name: string; + private _hints: { color?: string; }; + private _scopeName: string | undefined; + private _recording: string[] | undefined; -export function logError(logger: InnerLogger): (error: Error) => void { - return error => logger.log(errorLog, error, []); + constructor(loggerSink: LoggerSink, name: string, hints: { color?: string }, scopeName?: string, record?: boolean) { + this._loggerSink = loggerSink; + this._name = name; + this._hints = hints; + this._scopeName = scopeName; + if (record) + this._recording = []; + } + + isEnabled(severity?: LoggerSeverity): boolean { + return this._loggerSink.isEnabled(this._name, severity || 'info'); + } + + verbose(message: string, ...args: any[]) { + return this._innerLog('verbose', message, args); + } + + info(message: string, ...args: any[]) { + return this._innerLog('info', message, args); + } + + warn(message: string, ...args: any[]) { + return this._innerLog('warning', message, args); + } + + error(message: string | Error, ...args: any[]) { + return this._innerLog('error', message, args); + } + + createScope(scopeName: string, record?: boolean): Logger { + this._loggerSink.log(this._name, 'info', `=> ${scopeName} started`, [], this._hints); + return new Logger(this._loggerSink, this._name, this._hints, scopeName, record); + } + + endScope(status: string) { + this._loggerSink.log(this._name, 'info', `<= ${this._scopeName} ${status}`, [], this._hints); + } + + private _innerLog(severity: LoggerSeverity, message: string | Error, ...args: any[]) { + if (this._recording) + this._recording.push(`[${this._name}] ${message}`); + this._loggerSink.log(this._name, severity, message, args, this._hints); + } + + recording(): string[] { + return this._recording ? this._recording.slice() : []; + } } -export class InnerLogger { - private _userSink: Logger | undefined; - private _debugSink: DebugLogger; +export class Loggers { + readonly api: Logger; + readonly browser: Logger; + readonly protocol: Logger; - constructor(userSink: Logger | undefined) { - this._userSink = userSink; - this._debugSink = new DebugLogger(); + constructor(userSink: LoggerSink | undefined) { + const loggerSink = new MultiplexingLoggerSink(); + if (userSink) + loggerSink.add('user', userSink); + if (helper.isDebugMode()) + loggerSink.add('pwdebug', new PwDebugLoggerSink()); + loggerSink.add('debug', new DebugLoggerSink()); + + this.api = new Logger(loggerSink, 'api', { color: 'cyan' }); + this.browser = new Logger(loggerSink, 'browser', {}); + this.protocol = new Logger(loggerSink, 'protocol', { color: 'green' }); + } +} + +class MultiplexingLoggerSink implements LoggerSink { + private _loggers = new Map(); + + add(id: string, logger: LoggerSink) { + this._loggers.set(id, logger); } - isLogEnabled(log: Log): boolean { - const severity = log.severity || 'info'; - if (this._userSink && this._userSink.isEnabled(log.name, severity)) - return true; - return this._debugSink.isEnabled(log.name, severity); + get(id: string): LoggerSink | undefined { + return this._loggers.get(id); } - log(log: Log, message: string | Error, ...args: any[]) { - const severity = log.severity || 'info'; - const hints = log.color ? { color: log.color } : {}; - if (this._userSink && this._userSink.isEnabled(log.name, severity)) - this._userSink.log(log.name, severity, message, args, hints); - this._debugSink.log(log.name, severity, message, args, hints); + remove(id: string) { + this._loggers.delete(id); + } + + isEnabled(name: string, severity: LoggerSeverity): boolean { + for (const logger of this._loggers.values()) { + if (logger.isEnabled(name, severity)) + return true; + } + return false; + } + + log(name: string, severity: LoggerSeverity, message: string | Error, args: any[], hints: { color?: string }) { + for (const logger of this._loggers.values()) { + if (logger.isEnabled(name, severity)) + logger.log(name, severity, message, args, hints); + } } } @@ -71,7 +138,7 @@ const colorMap = new Map([ ['reset', 0], ]); -class DebugLogger { +class DebugLoggerSink { private _debuggers = new Map(); isEnabled(name: string, severity: LoggerSeverity): boolean { @@ -96,3 +163,12 @@ class DebugLogger { cachedDebugger(message, ...args); } } + +class PwDebugLoggerSink { + isEnabled(name: string, severity: LoggerSeverity): boolean { + return false; + } + + log(name: string, severity: LoggerSeverity, message: string | Error, args: any[], hints: { color?: string }) { + } +} diff --git a/src/page.ts b/src/page.ts index ead67a55f7..4ea0d36e2c 100644 --- a/src/page.ts +++ b/src/page.ts @@ -30,8 +30,8 @@ import { ConsoleMessage, ConsoleMessageLocation } from './console'; import * as accessibility from './accessibility'; import { EventEmitter } from 'events'; import { FileChooser } from './fileChooser'; -import { logError, InnerLogger } from './logger'; -import { ProgressController } from './progress'; +import { logError, Logger } from './logger'; +import { ProgressController, Progress } from './progress'; export interface PageDelegate { readonly rawMouse: input.RawMouse; @@ -100,7 +100,7 @@ export class Page extends EventEmitter { readonly mouse: input.Mouse; readonly _timeoutSettings: TimeoutSettings; readonly _delegate: PageDelegate; - readonly _logger: InnerLogger; + readonly _logger: Logger; readonly _state: PageState; readonly _pageBindings = new Map(); readonly _evaluateOnNewDocumentSources: string[] = []; @@ -112,11 +112,12 @@ export class Page extends EventEmitter { readonly coverage: any; _routes: { url: types.URLMatch, handler: network.RouteHandler }[] = []; _ownedContext: BrowserContext | undefined; + _callingPageAPI = false; constructor(delegate: PageDelegate, browserContext: BrowserContextBase) { super(); this._delegate = delegate; - this._logger = browserContext._logger; + this._logger = browserContext._apiLogger; this._closedCallback = () => {}; this._closedPromise = new Promise(f => this._closedCallback = f); this._disconnectedCallback = () => {}; @@ -139,6 +140,11 @@ export class Page extends EventEmitter { this.coverage = delegate.coverage ? delegate.coverage() : null; } + private _runAbortableTask(task: (progress: Progress) => Promise, timeout: number, apiName: string): Promise { + const controller = new ProgressController(this._logger, timeout, `page.${apiName}`); + return controller.run(task); + } + _didClose() { assert(!this._closed, 'Page closed twice'); this._closed = true; @@ -202,48 +208,48 @@ export class Page extends EventEmitter { } async $(selector: string): Promise | null> { - return this.mainFrame().$(selector); + return this._attributeToPage(() => this.mainFrame().$(selector)); } async waitForSelector(selector: string, options?: types.WaitForElementOptions): Promise | null> { - return this.mainFrame().waitForSelector(selector, options); + return this._attributeToPage(() => this.mainFrame().waitForSelector(selector, options)); } async dispatchEvent(selector: string, type: string, eventInit?: Object, options?: types.TimeoutOptions): Promise { - return this.mainFrame().dispatchEvent(selector, type, eventInit, options); + return this._attributeToPage(() => this.mainFrame().dispatchEvent(selector, type, eventInit, options)); } async evaluateHandle(pageFunction: types.Func1, arg: Arg): Promise>; async evaluateHandle(pageFunction: types.Func1, arg?: any): Promise>; async evaluateHandle(pageFunction: types.Func1, arg: Arg): Promise> { assertMaxArguments(arguments.length, 2); - return this.mainFrame().evaluateHandle(pageFunction, arg); + return this._attributeToPage(() => this.mainFrame().evaluateHandle(pageFunction, arg)); } async $eval(selector: string, pageFunction: types.FuncOn, arg: Arg): Promise; async $eval(selector: string, pageFunction: types.FuncOn, arg?: any): Promise; async $eval(selector: string, pageFunction: types.FuncOn, arg: Arg): Promise { assertMaxArguments(arguments.length, 3); - return this.mainFrame().$eval(selector, pageFunction, arg); + return this._attributeToPage(() => this.mainFrame().$eval(selector, pageFunction, arg)); } async $$eval(selector: string, pageFunction: types.FuncOn, arg: Arg): Promise; async $$eval(selector: string, pageFunction: types.FuncOn, arg?: any): Promise; async $$eval(selector: string, pageFunction: types.FuncOn, arg: Arg): Promise { assertMaxArguments(arguments.length, 3); - return this.mainFrame().$$eval(selector, pageFunction, arg); + return this._attributeToPage(() => this.mainFrame().$$eval(selector, pageFunction, arg)); } async $$(selector: string): Promise[]> { - return this.mainFrame().$$(selector); + return this._attributeToPage(() => this.mainFrame().$$(selector)); } async addScriptTag(options: { url?: string; path?: string; content?: string; type?: string; }): Promise { - return this.mainFrame().addScriptTag(options); + return this._attributeToPage(() => this.mainFrame().addScriptTag(options)); } async addStyleTag(options: { url?: string; path?: string; content?: string; }): Promise { - return this.mainFrame().addStyleTag(options); + return this._attributeToPage(() => this.mainFrame().addStyleTag(options)); } async exposeFunction(name: string, playwrightFunction: Function) { @@ -279,19 +285,19 @@ export class Page extends EventEmitter { } url(): string { - return this.mainFrame().url(); + return this._attributeToPage(() => this.mainFrame().url()); } async content(): Promise { - return this.mainFrame().content(); + return this._attributeToPage(() => this.mainFrame().content()); } async setContent(html: string, options?: types.NavigateOptions): Promise { - return this.mainFrame().setContent(html, options); + return this._attributeToPage(() => this.mainFrame().setContent(html, options)); } async goto(url: string, options?: frames.GotoOptions): Promise { - return this.mainFrame().goto(url, options); + return this._attributeToPage(() => this.mainFrame().goto(url, options)); } async reload(options?: types.NavigateOptions): Promise { @@ -301,11 +307,11 @@ export class Page extends EventEmitter { } async waitForLoadState(state?: types.LifecycleEvent, options?: types.TimeoutOptions): Promise { - return this.mainFrame().waitForLoadState(state, options); + return this._attributeToPage(() => this.mainFrame().waitForLoadState(state, options)); } async waitForNavigation(options?: types.WaitForNavigationOptions): Promise { - return this.mainFrame().waitForNavigation(options); + return this._attributeToPage(() => this.mainFrame().waitForNavigation(options)); } async waitForRequest(urlOrPredicate: string | RegExp | ((r: network.Request) => boolean), options: types.TimeoutOptions = {}): Promise { @@ -328,7 +334,7 @@ export class Page extends EventEmitter { async waitForEvent(event: string, optionsOrPredicate: types.WaitForEventOptions = {}): Promise { const options = typeof optionsOrPredicate === 'function' ? { predicate: optionsOrPredicate } : optionsOrPredicate; - const progressController = new ProgressController(this._logger, this._timeoutSettings.timeout(options)); + const progressController = new ProgressController(this._logger, this._timeoutSettings.timeout(options), 'page.waitForEvent'); this._disconnectedPromise.then(error => progressController.abort(error)); return progressController.run(progress => helper.waitForEvent(progress, this, event, options.predicate)); } @@ -376,7 +382,7 @@ export class Page extends EventEmitter { async evaluate(pageFunction: types.Func1, arg?: any): Promise; async evaluate(pageFunction: types.Func1, arg: Arg): Promise { assertMaxArguments(arguments.length, 2); - return this.mainFrame().evaluate(pageFunction, arg); + return this._attributeToPage(() => this.mainFrame().evaluate(pageFunction, arg)); } async addInitScript(script: Function | string | { path?: string, content?: string }, arg?: any) { @@ -424,7 +430,7 @@ export class Page extends EventEmitter { } async title(): Promise { - return this.mainFrame().title(); + return this._attributeToPage(() => this.mainFrame().title()); } async close(options: { runBeforeUnload: (boolean | undefined); } = {runBeforeUnload: undefined}) { @@ -443,64 +449,73 @@ export class Page extends EventEmitter { return this._closed; } + private _attributeToPage(func: () => T): T { + try { + this._callingPageAPI = true; + return func(); + } finally { + this._callingPageAPI = false; + } + } + async click(selector: string, options?: dom.ClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions) { - return this.mainFrame().click(selector, options); + return this._attributeToPage(() => this.mainFrame().click(selector, options)); } async dblclick(selector: string, options?: dom.MultiClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions) { - return this.mainFrame().dblclick(selector, options); + return this._attributeToPage(() => this.mainFrame().dblclick(selector, options)); } async fill(selector: string, value: string, options?: types.NavigatingActionWaitOptions) { - return this.mainFrame().fill(selector, value, options); + return this._attributeToPage(() => this.mainFrame().fill(selector, value, options)); } async focus(selector: string, options?: types.TimeoutOptions) { - return this.mainFrame().focus(selector, options); + return this._attributeToPage(() => this.mainFrame().focus(selector, options)); } async textContent(selector: string, options?: types.TimeoutOptions): Promise { - return this.mainFrame().textContent(selector, options); + return this._attributeToPage(() => this.mainFrame().textContent(selector, options)); } async innerText(selector: string, options?: types.TimeoutOptions): Promise { - return this.mainFrame().innerText(selector, options); + return this._attributeToPage(() => this.mainFrame().innerText(selector, options)); } async innerHTML(selector: string, options?: types.TimeoutOptions): Promise { - return this.mainFrame().innerHTML(selector, options); + return this._attributeToPage(() => this.mainFrame().innerHTML(selector, options)); } async getAttribute(selector: string, name: string, options?: types.TimeoutOptions): Promise { - return this.mainFrame().getAttribute(selector, name, options); + return this._attributeToPage(() => this.mainFrame().getAttribute(selector, name, options)); } async hover(selector: string, options?: dom.PointerActionOptions & types.PointerActionWaitOptions) { - return this.mainFrame().hover(selector, options); + return this._attributeToPage(() => this.mainFrame().hover(selector, options)); } async selectOption(selector: string, values: string | dom.ElementHandle | types.SelectOption | string[] | dom.ElementHandle[] | types.SelectOption[] | null, options?: types.NavigatingActionWaitOptions): Promise { - return this.mainFrame().selectOption(selector, values, options); + return this._attributeToPage(() => this.mainFrame().selectOption(selector, values, options)); } async setInputFiles(selector: string, files: string | types.FilePayload | string[] | types.FilePayload[], options?: types.NavigatingActionWaitOptions): Promise { - return this.mainFrame().setInputFiles(selector, files, options); + return this._attributeToPage(() => this.mainFrame().setInputFiles(selector, files, options)); } async type(selector: string, text: string, options?: { delay?: number } & types.NavigatingActionWaitOptions) { - return this.mainFrame().type(selector, text, options); + return this._attributeToPage(() => this.mainFrame().type(selector, text, options)); } async press(selector: string, key: string, options?: { delay?: number } & types.NavigatingActionWaitOptions) { - return this.mainFrame().press(selector, key, options); + return this._attributeToPage(() => this.mainFrame().press(selector, key, options)); } async check(selector: string, options?: types.PointerActionWaitOptions & types.NavigatingActionWaitOptions) { - return this.mainFrame().check(selector, options); + return this._attributeToPage(() => this.mainFrame().check(selector, options)); } async uncheck(selector: string, options?: types.PointerActionWaitOptions & types.NavigatingActionWaitOptions) { - return this.mainFrame().uncheck(selector, options); + return this._attributeToPage(() => this.mainFrame().uncheck(selector, options)); } async waitForTimeout(timeout: number) { @@ -510,7 +525,7 @@ export class Page extends EventEmitter { async waitForFunction(pageFunction: types.Func1, arg: Arg, options?: types.WaitForFunctionOptions): Promise>; async waitForFunction(pageFunction: types.Func1, arg?: any, options?: types.WaitForFunctionOptions): Promise>; async waitForFunction(pageFunction: types.Func1, arg: Arg, options?: types.WaitForFunctionOptions): Promise> { - return this.mainFrame().waitForFunction(pageFunction, arg, options); + return this._attributeToPage(() => this.mainFrame().waitForFunction(pageFunction, arg, options)); } workers(): Worker[] { diff --git a/src/progress.ts b/src/progress.ts index 67103cf7c7..3602d45cad 100644 --- a/src/progress.ts +++ b/src/progress.ts @@ -14,18 +14,18 @@ * limitations under the License. */ -import { InnerLogger, Log, apiLog } from './logger'; +import { Logger } from './logger'; import { TimeoutError } from './errors'; import { assert } from './helper'; -import { getCurrentApiCall, rewriteErrorMessage } from './utils/stackTrace'; +import { rewriteErrorMessage } from './utils/stackTrace'; export interface Progress { readonly apiName: string; readonly aborted: Promise; + readonly logger: Logger; timeUntilDeadline(): number; isRunning(): boolean; cleanupWhenAborted(cleanup: () => any): void; - log(log: Log, message: string | Error): void; throwIfAborted(): void; } @@ -35,7 +35,7 @@ export function isRunningTask(): boolean { return !!runningTaskCount; } -export async function runAbortableTask(task: (progress: Progress) => Promise, logger: InnerLogger, timeout: number, apiName?: string): Promise { +export async function runAbortableTask(task: (progress: Progress) => Promise, logger: Logger, timeout: number, apiName: string): Promise { const controller = new ProgressController(logger, timeout, apiName); return controller.run(task); } @@ -54,15 +54,14 @@ export class ProgressController { // Cleanups to be run only in the case of abort. private _cleanups: (() => any)[] = []; - private _logger: InnerLogger; - private _logRecording: string[] = []; + private _logger: Logger; private _state: 'before' | 'running' | 'aborted' | 'finished' = 'before'; private _apiName: string; private _deadline: number; private _timeout: number; - constructor(logger: InnerLogger, timeout: number, apiName?: string) { - this._apiName = apiName || getCurrentApiCall(); + constructor(logger: Logger, timeout: number, apiName: string) { + this._apiName = apiName; this._logger = logger; this._timeout = timeout; @@ -78,9 +77,12 @@ export class ProgressController { this._state = 'running'; ++runningTaskCount; + const loggerScope = this._logger.createScope(this._apiName, true); + const progress: Progress = { apiName: this._apiName, aborted: this._abortedPromise, + logger: loggerScope, timeUntilDeadline: () => this._deadline ? this._deadline - monotonicTime() : 2147483647, // 2^31-1 safe setTimeout in Node. isRunning: () => this._state === 'running', cleanupWhenAborted: (cleanup: () => any) => { @@ -89,20 +91,11 @@ export class ProgressController { else runCleanup(cleanup); }, - log: (log: Log, message: string | Error) => { - if (this._state === 'running') { - this._logRecording.push(`[${log.name}] ${message.toString()}`); - this._logger.log(log, ' ' + message); - } else { - this._logger.log(log, message); - } - }, throwIfAborted: () => { if (this._state === 'aborted') throw new AbortedError(); }, }; - this._logger.log(apiLog, `=> ${this._apiName} started`); const timeoutError = new TimeoutError(`Timeout ${this._timeout}ms exceeded during ${this._apiName}.`); const timer = setTimeout(() => this._forceAbort(timeoutError), progress.timeUntilDeadline()); @@ -111,18 +104,17 @@ export class ProgressController { const result = await Promise.race([promise, this._forceAbortPromise]); clearTimeout(timer); this._state = 'finished'; - this._logger.log(apiLog, `<= ${this._apiName} succeeded`); + loggerScope.endScope('succeeded'); return result; } catch (e) { this._aborted(); - rewriteErrorMessage(e, e.message + formatLogRecording(this._logRecording, this._apiName) + kLoggingNote); + rewriteErrorMessage(e, e.message + formatLogRecording(loggerScope.recording(), this._apiName) + kLoggingNote); clearTimeout(timer); this._state = 'aborted'; - this._logger.log(apiLog, `<= ${this._apiName} failed`); + loggerScope.endScope(`failed`); await Promise.all(this._cleanups.splice(0).map(cleanup => runCleanup(cleanup))); throw e; } finally { - this._logRecording = []; --runningTaskCount; } } diff --git a/src/server/browserType.ts b/src/server/browserType.ts index 5950dc3dda..886d579a7b 100644 --- a/src/server/browserType.ts +++ b/src/server/browserType.ts @@ -21,7 +21,7 @@ import * as util from 'util'; import { BrowserContext, PersistentContextOptions, verifyProxySettings, validateBrowserContextOptions } from '../browserContext'; import { BrowserServer } from './browserServer'; import * as browserPaths from '../install/browserPaths'; -import { Logger, InnerLogger } from '../logger'; +import { Loggers, Logger } from '../logger'; import { ConnectionTransport, WebSocketTransport } from '../transport'; import { BrowserBase, BrowserOptions, Browser } from '../browser'; import { assert, helper } from '../helper'; @@ -29,7 +29,7 @@ import { launchProcess, Env, waitForLine } from './processLauncher'; import { Events } from '../events'; import { PipeTransport } from './pipeTransport'; import { Progress, runAbortableTask } from '../progress'; -import { ProxySettings } from '../types'; +import * as types from '../types'; import { TimeoutSettings } from '../timeoutSettings'; import { WebSocketServer } from './webSocketServer'; @@ -45,18 +45,18 @@ export type LaunchOptionsBase = { handleSIGTERM?: boolean, handleSIGHUP?: boolean, timeout?: number, - logger?: Logger, + logger?: types.Logger, env?: Env, headless?: boolean, devtools?: boolean, - proxy?: ProxySettings, + proxy?: types.ProxySettings, downloadsPath?: string, }; type ConnectOptions = { wsEndpoint: string, slowMo?: number, - logger?: Logger, + logger?: types.Logger, timeout?: number, }; export type LaunchOptions = LaunchOptionsBase & { slowMo?: number }; @@ -105,8 +105,8 @@ export abstract class BrowserTypeBase implements BrowserType { 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.'); options = validateLaunchOptions(options); - const logger = new InnerLogger(options.logger); - const browser = await runAbortableTask(progress => this._innerLaunch(progress, options, logger, undefined), logger, TimeoutSettings.timeout(options)); + const loggers = new Loggers(options.logger); + const browser = await runAbortableTask(progress => this._innerLaunch(progress, options, loggers, undefined), loggers.browser, TimeoutSettings.timeout(options), `browserType.launch`); return browser; } @@ -114,12 +114,12 @@ export abstract class BrowserTypeBase implements BrowserType { assert(!(options as any).port, 'Cannot specify a port without launching as a server.'); options = validateLaunchOptions(options); const persistent = validateBrowserContextOptions(options); - const logger = new InnerLogger(options.logger); - const browser = await runAbortableTask(progress => this._innerLaunch(progress, options, logger, persistent, userDataDir), logger, TimeoutSettings.timeout(options)); + const loggers = new Loggers(options.logger); + const browser = await runAbortableTask(progress => this._innerLaunch(progress, options, loggers, persistent, userDataDir), loggers.browser, TimeoutSettings.timeout(options), 'browserType.launchPersistentContext'); return browser._defaultContext!; } - async _innerLaunch(progress: Progress, options: LaunchOptions, logger: InnerLogger, persistent: PersistentContextOptions | undefined, userDataDir?: string): Promise { + async _innerLaunch(progress: Progress, options: LaunchOptions, logger: Loggers, persistent: PersistentContextOptions | undefined, userDataDir?: string): Promise { options.proxy = options.proxy ? verifyProxySettings(options.proxy) : undefined; const { browserServer, downloadsPath, transport } = await this._launchServer(progress, options, !!persistent, logger, userDataDir); if ((options as any).__testHookBeforeCreateBrowser) @@ -128,7 +128,7 @@ export abstract class BrowserTypeBase implements BrowserType { slowMo: options.slowMo, persistent, headful: !options.headless, - logger, + loggers: logger, downloadsPath, ownedServer: browserServer, proxy: options.proxy, @@ -145,28 +145,28 @@ export abstract class BrowserTypeBase implements BrowserType { async launchServer(options: LaunchServerOptions = {}): Promise { assert(!(options as any).userDataDir, 'userDataDir option is not supported in `browserType.launchServer`. Use `browserType.launchPersistentContext` instead'); options = validateLaunchOptions(options); - const logger = new InnerLogger(options.logger); + const loggers = new Loggers(options.logger); const { port = 0 } = options; return runAbortableTask(async progress => { - const { browserServer, transport } = await this._launchServer(progress, options, false, logger); - browserServer._webSocketServer = this._startWebSocketServer(transport, logger, port); + const { browserServer, transport } = await this._launchServer(progress, options, false, loggers); + browserServer._webSocketServer = this._startWebSocketServer(transport, loggers.browser, port); return browserServer; - }, logger, TimeoutSettings.timeout(options)); + }, loggers.browser, TimeoutSettings.timeout(options), 'browserType.launchServer'); } async connect(options: ConnectOptions): Promise { - const logger = new InnerLogger(options.logger); + const loggers = new Loggers(options.logger); return runAbortableTask(async progress => { const transport = await WebSocketTransport.connect(progress, options.wsEndpoint); progress.cleanupWhenAborted(() => transport.closeAndWait()); if ((options as any).__testHookBeforeCreateBrowser) await (options as any).__testHookBeforeCreateBrowser(); - const browser = await this._connectToTransport(transport, { slowMo: options.slowMo, logger }); + const browser = await this._connectToTransport(transport, { slowMo: options.slowMo, loggers }); return browser; - }, logger, TimeoutSettings.timeout(options)); + }, loggers.browser, TimeoutSettings.timeout(options), 'browserType.connect'); } - private async _launchServer(progress: Progress, options: LaunchServerOptions, isPersistent: boolean, logger: InnerLogger, userDataDir?: string): Promise<{ browserServer: BrowserServer, downloadsPath: string, transport: ConnectionTransport }> { + private async _launchServer(progress: Progress, options: LaunchServerOptions, isPersistent: boolean, loggers: Loggers, userDataDir?: string): Promise<{ browserServer: BrowserServer, downloadsPath: string, transport: ConnectionTransport }> { const { ignoreDefaultArgs = false, args = [], @@ -240,14 +240,14 @@ export abstract class BrowserTypeBase implements BrowserType { 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); + transport = new PipeTransport(stdio[3], stdio[4], loggers.browser); } return { browserServer, downloadsPath, transport }; } abstract _defaultArgs(options: LaunchOptionsBase, isPersistent: boolean, userDataDir: string): string[]; abstract _connectToTransport(transport: ConnectionTransport, options: BrowserOptions): Promise; - abstract _startWebSocketServer(transport: ConnectionTransport, logger: InnerLogger, port: number): WebSocketServer; + abstract _startWebSocketServer(transport: ConnectionTransport, logger: Logger, port: number): WebSocketServer; abstract _amendEnvironment(env: Env, userDataDir: string, executable: string, browserArguments: string[]): Env; abstract _attemptToGracefullyCloseBrowser(transport: ConnectionTransport): void; } diff --git a/src/server/chromium.ts b/src/server/chromium.ts index 603f08acff..79c61bc675 100644 --- a/src/server/chromium.ts +++ b/src/server/chromium.ts @@ -23,7 +23,7 @@ import { Env } from './processLauncher'; import { kBrowserCloseMessageId } from '../chromium/crConnection'; import { LaunchOptionsBase, BrowserTypeBase } from './browserType'; import { ConnectionTransport, ProtocolRequest, ProtocolResponse } from '../transport'; -import { InnerLogger } from '../logger'; +import { Logger } from '../logger'; import { BrowserDescriptor } from '../install/browserPaths'; import { CRDevTools } from '../chromium/crDevTools'; import { BrowserOptions } from '../browser'; @@ -72,7 +72,7 @@ export class Chromium extends BrowserTypeBase { transport.send(message); } - _startWebSocketServer(transport: ConnectionTransport, logger: InnerLogger, port: number): WebSocketServer { + _startWebSocketServer(transport: ConnectionTransport, logger: Logger, port: number): WebSocketServer { return startWebSocketServer(transport, logger, port); } @@ -130,7 +130,7 @@ type SessionData = { parent?: string, }; -function startWebSocketServer(transport: ConnectionTransport, logger: InnerLogger, port: number): WebSocketServer { +function startWebSocketServer(transport: ConnectionTransport, logger: Logger, port: number): WebSocketServer { const awaitingBrowserTarget = new Map(); const sessionToData = new Map(); const socketToBrowserSession = new Map(); diff --git a/src/server/electron.ts b/src/server/electron.ts index cc61bac125..bb0e1807d1 100644 --- a/src/server/electron.ts +++ b/src/server/electron.ts @@ -20,7 +20,7 @@ import { CRConnection, CRSession } from '../chromium/crConnection'; import { CRExecutionContext } from '../chromium/crExecutionContext'; import { Events } from '../events'; import * as js from '../javascript'; -import { InnerLogger, Logger } from '../logger'; +import { Loggers, Logger } from '../logger'; import { Page } from '../page'; import { TimeoutSettings } from '../timeoutSettings'; import { WebSocketTransport } from '../transport'; @@ -41,7 +41,7 @@ type ElectronLaunchOptions = { handleSIGTERM?: boolean, handleSIGHUP?: boolean, timeout?: number, - logger?: Logger, + logger?: types.Logger, }; export const ElectronEvents = { @@ -57,7 +57,7 @@ interface ElectronPage extends Page { } export class ElectronApplication extends EventEmitter { - private _logger: InnerLogger; + private _apiLogger: Logger; private _browserContext: CRBrowserContext; private _nodeConnection: CRConnection; private _nodeSession: CRSession; @@ -67,9 +67,9 @@ export class ElectronApplication extends EventEmitter { private _lastWindowId = 0; readonly _timeoutSettings = new TimeoutSettings(); - constructor(logger: InnerLogger, browser: CRBrowser, nodeConnection: CRConnection) { + constructor(logger: Loggers, browser: CRBrowser, nodeConnection: CRConnection) { super(); - this._logger = logger; + this._apiLogger = logger.api; this._browserContext = browser._defaultContext as CRBrowserContext; this._browserContext.on(Events.BrowserContext.Close, () => this.emit(ElectronEvents.ElectronApplication.Close)); this._browserContext.on(Events.BrowserContext.Page, event => this._onPage(event)); @@ -131,7 +131,7 @@ export class ElectronApplication extends EventEmitter { async waitForEvent(event: string, optionsOrPredicate: types.WaitForEventOptions = {}): Promise { const options = typeof optionsOrPredicate === 'function' ? { predicate: optionsOrPredicate } : optionsOrPredicate; - const progressController = new ProgressController(this._logger, this._timeoutSettings.timeout(options)); + const progressController = new ProgressController(this._apiLogger, this._timeoutSettings.timeout(options), 'electron.waitForEvent'); if (event !== ElectronEvents.ElectronApplication.Close) this._browserContext._closePromise.then(error => progressController.abort(error)); return progressController.run(progress => helper.waitForEvent(progress, this, event, options.predicate)); @@ -172,7 +172,7 @@ export class Electron { handleSIGTERM = true, handleSIGHUP = true, } = options; - const logger = new InnerLogger(options.logger); + const loggers = new Loggers(options.logger); return runAbortableTask(async progress => { let app: ElectronApplication | undefined = undefined; const electronArguments = ['--inspect=0', '--remote-debugging-port=0', '--require', path.join(__dirname, 'electronLoader.js'), ...args]; @@ -196,15 +196,15 @@ export class Electron { 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 nodeConnection = new CRConnection(nodeTransport, loggers); 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); + const browser = await CRBrowser.connect(chromeTransport, { headful: true, loggers, persistent: { viewport: null }, ownedServer: browserServer }); + app = new ElectronApplication(loggers, browser, nodeConnection); await app._init(); return app; - }, logger, TimeoutSettings.timeout(options)); + }, loggers.browser, TimeoutSettings.timeout(options), 'electron.launch'); } } diff --git a/src/server/firefox.ts b/src/server/firefox.ts index 8d85dd9250..a9d2762716 100644 --- a/src/server/firefox.ts +++ b/src/server/firefox.ts @@ -24,7 +24,7 @@ import { kBrowserCloseMessageId } from '../firefox/ffConnection'; import { LaunchOptionsBase, BrowserTypeBase, FirefoxUserPrefsOptions } from './browserType'; import { Env } from './processLauncher'; import { ConnectionTransport, ProtocolResponse, ProtocolRequest } from '../transport'; -import { InnerLogger } from '../logger'; +import { Logger } from '../logger'; import { BrowserOptions } from '../browser'; import { BrowserDescriptor } from '../install/browserPaths'; import { WebSocketServer } from './webSocketServer'; @@ -52,7 +52,7 @@ export class Firefox extends BrowserTypeBase { transport.send(message); } - _startWebSocketServer(transport: ConnectionTransport, logger: InnerLogger, port: number): WebSocketServer { + _startWebSocketServer(transport: ConnectionTransport, logger: Logger, port: number): WebSocketServer { return startWebSocketServer(transport, logger, port); } @@ -110,7 +110,7 @@ type SessionData = { socket: ws, }; -function startWebSocketServer(transport: ConnectionTransport, logger: InnerLogger, port: number): WebSocketServer { +function startWebSocketServer(transport: ConnectionTransport, logger: Logger, port: number): WebSocketServer { const pendingBrowserContextCreations = new Set(); const pendingBrowserContextDeletions = new Map(); const browserContextIds = new Map(); diff --git a/src/server/pipeTransport.ts b/src/server/pipeTransport.ts index 3d875b3be5..47876f142a 100644 --- a/src/server/pipeTransport.ts +++ b/src/server/pipeTransport.ts @@ -17,7 +17,7 @@ import { helper, RegisteredListener } from '../helper'; import { ConnectionTransport, ProtocolRequest, ProtocolResponse } from '../transport'; -import { logError, InnerLogger } from '../logger'; +import { logError, Logger } from '../logger'; export class PipeTransport implements ConnectionTransport { private _pipeWrite: NodeJS.WritableStream; @@ -29,7 +29,7 @@ export class PipeTransport implements ConnectionTransport { onmessage?: (message: ProtocolResponse) => void; onclose?: () => void; - constructor(pipeWrite: NodeJS.WritableStream, pipeRead: NodeJS.ReadableStream, logger: InnerLogger) { + constructor(pipeWrite: NodeJS.WritableStream, pipeRead: NodeJS.ReadableStream, logger: Logger) { this._pipeWrite = pipeWrite; this._eventListeners = [ helper.addEventListener(pipeRead, 'data', buffer => this._dispatch(buffer)), diff --git a/src/server/processLauncher.ts b/src/server/processLauncher.ts index e38b27a983..d323d1bb4f 100644 --- a/src/server/processLauncher.ts +++ b/src/server/processLauncher.ts @@ -16,26 +16,12 @@ */ import * as childProcess from 'child_process'; -import { Log } from '../logger'; import * as readline from 'readline'; import * as removeFolder from 'rimraf'; import * as stream from 'stream'; import { helper } from '../helper'; import { Progress } from '../progress'; -export const browserLog: Log = { - name: 'browser', -}; - -const browserStdOutLog: Log = { - name: 'browser:out', -}; - -const browserStdErrLog: Log = { - name: 'browser:err', - severity: 'warning' -}; - export type Env = {[key: string]: string | number | boolean | undefined}; export type LaunchProcessOptions = { @@ -68,7 +54,7 @@ export async function launchProcess(options: LaunchProcessOptions): Promise ${options.executablePath} ${options.args.join(' ')}`); + progress.logger.info(` ${options.executablePath} ${options.args.join(' ')}`); const spawnedProcess = childProcess.spawn( options.executablePath, options.args, @@ -90,16 +76,16 @@ export async function launchProcess(options: LaunchProcessOptions): Promise failedPromise).then(e => Promise.reject(e)); } - progress.log(browserLog, ` pid=${spawnedProcess.pid}`); + progress.logger.info(` pid=${spawnedProcess.pid}`); const stdout = readline.createInterface({ input: spawnedProcess.stdout }); stdout.on('line', (data: string) => { - progress.log(browserStdOutLog, data); + progress.logger.info(data); }); const stderr = readline.createInterface({ input: spawnedProcess.stderr }); stderr.on('line', (data: string) => { - progress.log(browserStdErrLog, data); + progress.logger.warn(data); }); let processClosed = false; @@ -108,7 +94,7 @@ export async function launchProcess(options: LaunchProcessOptions): Promise {}; const waitForCleanup = new Promise(f => fulfillCleanup = f); spawnedProcess.once('exit', (exitCode, signal) => { - progress.log(browserLog, ``); + progress.logger.info(``); processClosed = true; helper.removeEventListeners(listeners); options.onExit(exitCode, signal); @@ -135,21 +121,21 @@ export async function launchProcess(options: LaunchProcessOptions): Promise`); + progress.logger.info(``); killProcess(); await waitForClose; // Ensure the process is dead and we called options.onkill. return; } gracefullyClosing = true; - progress.log(browserLog, ``); + progress.logger.info(``); await options.attemptToGracefullyClose().catch(() => killProcess()); await waitForCleanup; // Ensure the process is dead and we have cleaned up. - progress.log(browserLog, ``); + progress.logger.info(``); } // This method has to be sync to be used as 'exit' event handler. function killProcess() { - progress.log(browserLog, ``); + progress.logger.info(``); helper.removeEventListeners(listeners); if (spawnedProcess.pid && !spawnedProcess.killed && !processClosed) { // Force kill the browser. diff --git a/src/server/webSocketServer.ts b/src/server/webSocketServer.ts index 3b20fb90eb..00f185e01f 100644 --- a/src/server/webSocketServer.ts +++ b/src/server/webSocketServer.ts @@ -17,7 +17,7 @@ import { IncomingMessage } from 'http'; import * as ws from 'ws'; import { helper } from '../helper'; -import { InnerLogger, logError } from '../logger'; +import { logError, Logger } from '../logger'; import { ConnectionTransport, ProtocolRequest, ProtocolResponse } from '../transport'; export interface WebSocketServerDelegate { @@ -30,7 +30,7 @@ export interface WebSocketServerDelegate { export class WebSocketServer { private _transport: ConnectionTransport; - private _logger: InnerLogger; + private _logger: Logger; private _server: ws.Server; private _guid: string; readonly wsEndpoint: string; @@ -40,7 +40,7 @@ export class WebSocketServer { private _sockets = new Set(); private _pendingRequests = new Map(); - constructor(transport: ConnectionTransport, logger: InnerLogger, port: number, delegate: WebSocketServerDelegate) { + constructor(transport: ConnectionTransport, logger: Logger, port: number, delegate: WebSocketServerDelegate) { this._guid = helper.guid(); this._transport = transport; this._logger = logger; diff --git a/src/server/webkit.ts b/src/server/webkit.ts index 303a949caf..4b9df8895b 100644 --- a/src/server/webkit.ts +++ b/src/server/webkit.ts @@ -22,7 +22,7 @@ import { kBrowserCloseMessageId } from '../webkit/wkConnection'; import { LaunchOptionsBase, BrowserTypeBase } from './browserType'; import { ConnectionTransport, ProtocolResponse, ProtocolRequest } from '../transport'; import * as ws from 'ws'; -import { InnerLogger } from '../logger'; +import { Logger } from '../logger'; import { BrowserOptions } from '../browser'; import { BrowserDescriptor } from '../install/browserPaths'; import { WebSocketServer } from './webSocketServer'; @@ -45,7 +45,7 @@ export class WebKit extends BrowserTypeBase { transport.send({method: 'Playwright.close', params: {}, id: kBrowserCloseMessageId}); } - _startWebSocketServer(transport: ConnectionTransport, logger: InnerLogger, port: number): WebSocketServer { + _startWebSocketServer(transport: ConnectionTransport, logger: Logger, port: number): WebSocketServer { return startWebSocketServer(transport, logger, port); } @@ -87,7 +87,7 @@ export class WebKit extends BrowserTypeBase { } } -function startWebSocketServer(transport: ConnectionTransport, logger: InnerLogger, port: number): WebSocketServer { +function startWebSocketServer(transport: ConnectionTransport, logger: Logger, port: number): WebSocketServer { const pendingBrowserContextCreations = new Set(); const pendingBrowserContextDeletions = new Map(); const browserContextIds = new Map(); diff --git a/src/transport.ts b/src/transport.ts index af7e6e34cc..a19ba01f62 100644 --- a/src/transport.ts +++ b/src/transport.ts @@ -17,9 +17,7 @@ import * as WebSocket from 'ws'; import { helper } from './helper'; -import { Log } from './logger'; import { Progress } from './progress'; -import { browserLog } from './server/processLauncher'; export type ProtocolRequest = { id: number; @@ -128,7 +126,7 @@ export class WebSocketTransport implements ConnectionTransport { onclose?: () => void; static async connect(progress: Progress, url: string): Promise { - progress.log(browserLog, ` ${url}`); + progress.logger.info(` ${url}`); const transport = new WebSocketTransport(progress, url); let success = false; progress.aborted.then(() => { @@ -137,11 +135,11 @@ export class WebSocketTransport implements ConnectionTransport { }); await new Promise((fulfill, reject) => { transport._ws.addEventListener('open', async () => { - progress.log(browserLog, ` ${url}`); + progress.logger.info(` ${url}`); fulfill(transport); }); transport._ws.addEventListener('error', event => { - progress.log(browserLog, ` ${url} ${event.message}`); + progress.logger.info(` ${url} ${event.message}`); reject(new Error('WebSocket error: ' + event.message)); transport._ws.close(); }); @@ -171,7 +169,7 @@ export class WebSocketTransport implements ConnectionTransport { }); this._ws.addEventListener('close', event => { - this._progress && this._progress.log(browserLog, ` ${url}`); + this._progress && this._progress.logger.info(` ${url}`); if (this.onclose) this.onclose.call(null); }); @@ -184,7 +182,7 @@ export class WebSocketTransport implements ConnectionTransport { } close() { - this._progress && this._progress.log(browserLog, ` ${this._ws.url}`); + this._progress && this._progress.logger.info(` ${this._ws.url}`); this._ws.close(); } @@ -229,9 +227,3 @@ export class InterceptingTransport implements ConnectionTransport { this._delegate.close(); } } - -export const protocolLog: Log = { - name: 'protocol', - severity: 'verbose', - color: 'green' -}; diff --git a/src/types.ts b/src/types.ts index 149e470d49..d4a00d7251 100644 --- a/src/types.ts +++ b/src/types.ts @@ -177,4 +177,11 @@ export type ProxySettings = { password?: string }; +export type LoggerSeverity = 'verbose' | 'info' | 'warning' | 'error'; + +export interface Logger { + isEnabled(name: string, severity: LoggerSeverity): boolean; + log(name: string, severity: LoggerSeverity, message: string | Error, args: any[], hints: { color?: string }): void; +} + export type WaitForEventOptions = Function | { predicate?: Function, timeout?: number }; diff --git a/src/utils/stackTrace.ts b/src/utils/stackTrace.ts index 0eba24fc7f..45fe0190d8 100644 --- a/src/utils/stackTrace.ts +++ b/src/utils/stackTrace.ts @@ -18,7 +18,6 @@ import * as path from 'path'; // NOTE: update this to point to playwright/lib when moving this file. const PLAYWRIGHT_LIB_PATH = path.normalize(path.join(__dirname, '..')); -const APICOVERAGE = path.normalize(path.join(__dirname, '..', '..', 'test', 'apicoverage')); type ParsedStackFrame = { filePath: string, functionName: string }; @@ -61,26 +60,6 @@ export function getCallerFilePath(ignorePrefix = PLAYWRIGHT_LIB_PATH): string | return null; } -export function getCurrentApiCall(prefix = PLAYWRIGHT_LIB_PATH): string { - const error = new Error(); - const stackFrames = (error.stack || '').split('\n').slice(1); - // Find last stackframe that points to prefix - that should be the api call. - let apiName: string = ''; - for (const frame of stackFrames) { - const parsed = parseStackFrame(frame); - if (!parsed || (!parsed.filePath.startsWith(prefix) && !parsed.filePath.startsWith(APICOVERAGE) && parsed.filePath !== __filename)) - break; - apiName = parsed.functionName; - } - const parts = apiName.split('.'); - if (parts.length && parts[0].length) { - parts[0] = parts[0][0].toLowerCase() + parts[0].substring(1); - if (parts[0] === 'webKit') - parts[0] = 'webkit'; - } - return parts.join('.'); -} - export function rewriteErrorMessage(e: Error, newMessage: string): Error { if (e.stack) { const index = e.stack.indexOf(e.message); diff --git a/src/webkit/wkBrowser.ts b/src/webkit/wkBrowser.ts index 63902fcb95..f4adfaa5f3 100644 --- a/src/webkit/wkBrowser.ts +++ b/src/webkit/wkBrowser.ts @@ -51,7 +51,7 @@ export class WKBrowser extends BrowserBase { constructor(transport: ConnectionTransport, options: BrowserOptions) { super(options); - this._connection = new WKConnection(transport, options.logger, this._onDisconnect.bind(this)); + this._connection = new WKConnection(transport, options.loggers, this._onDisconnect.bind(this)); this._browserSession = this._connection.browserSession; this._eventListeners = [ helper.addEventListener(this._browserSession, 'Playwright.pageProxyCreated', this._onPageProxyCreated.bind(this)), diff --git a/src/webkit/wkConnection.ts b/src/webkit/wkConnection.ts index 7a548a2d38..0554c0d180 100644 --- a/src/webkit/wkConnection.ts +++ b/src/webkit/wkConnection.ts @@ -17,9 +17,9 @@ import { EventEmitter } from 'events'; import { assert } from '../helper'; -import { ConnectionTransport, ProtocolRequest, ProtocolResponse, protocolLog } from '../transport'; +import { ConnectionTransport, ProtocolRequest, ProtocolResponse } from '../transport'; import { Protocol } from './protocol'; -import { InnerLogger, errorLog } from '../logger'; +import { Loggers, Logger } from '../logger'; import { rewriteErrorMessage } from '../utils/stackTrace'; // WKPlaywright uses this special id to issue Browser.close command which we @@ -37,11 +37,11 @@ export class WKConnection { private _lastId = 0; private _closed = false; readonly browserSession: WKSession; - readonly _logger: InnerLogger; + readonly _logger: Logger; - constructor(transport: ConnectionTransport, logger: InnerLogger, onDisconnect: () => void) { + constructor(transport: ConnectionTransport, loggers: Loggers, onDisconnect: () => void) { this._transport = transport; - this._logger = logger; + this._logger = loggers.protocol; this._transport.onmessage = this._dispatchMessage.bind(this); this._transport.onclose = this._onClose.bind(this); this._onDisconnect = onDisconnect; @@ -55,14 +55,14 @@ export class WKConnection { } rawSend(message: ProtocolRequest) { - if (this._logger.isLogEnabled(protocolLog)) - this._logger.log(protocolLog, 'SEND ► ' + rewriteInjectedScriptEvaluationLog(message)); + if (this._logger.isEnabled()) + this._logger.info('SEND ► ' + rewriteInjectedScriptEvaluationLog(message)); this._transport.send(message); } private _dispatchMessage(message: ProtocolResponse) { - if (this._logger.isLogEnabled(protocolLog)) - this._logger.log(protocolLog, '◀ RECV ' + JSON.stringify(message)); + if (this._logger.isEnabled()) + this._logger.info('◀ RECV ' + JSON.stringify(message)); if (message.id === kBrowserCloseMessageId) return; if (message.pageProxyId) { @@ -139,7 +139,7 @@ export class WKSession extends EventEmitter { sendMayFail(method: T, params?: Protocol.CommandParameters[T]): Promise { return this.send(method, params).catch(error => { - this.connection._logger.log(errorLog, error, []); + this.connection._logger.error(error); }); } diff --git a/test/defaultbrowsercontext.spec.js b/test/defaultbrowsercontext.spec.js index 1027e36e88..01d0f01eda 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(`Timeout 5000ms exceeded during ${browserType.name()}.launchPersistentContext.`); + expect(error.message).toContain(`Timeout 5000ms exceeded during browserType.launchPersistentContext.`); await removeUserDataDir(userDataDir); }); it('should handle exception', async({browserType, defaultBrowserOptions}) => { diff --git a/test/fixtures.spec.js b/test/fixtures.spec.js index edcf19cfe2..81136a4810 100644 --- a/test/fixtures.spec.js +++ b/test/fixtures.spec.js @@ -187,10 +187,4 @@ describe('StackTrace', () => { }); expect(filePath).toBe(__filename); }); - it('api call', async state => { - const stackTrace = require(path.join(state.playwrightPath, 'lib', 'utils', 'stackTrace')); - const callme = require('./fixtures/callback'); - const apiCall = callme(stackTrace.getCurrentApiCall.bind(stackTrace, path.join(__dirname, 'fixtures') + path.sep)); - expect(apiCall).toBe('callme'); - }); }); diff --git a/test/launcher.spec.js b/test/launcher.spec.js index b1aa1e45fa..08f4a8ed4a 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(`Timeout 5000ms exceeded during ${browserType.name()}.launch.`); + expect(error.message).toContain(`Timeout 5000ms exceeded during browserType.launch.`); expect(error.message).toContain(`[browser] `); expect(error.message).toContain(`[browser] pid=`); });