diff --git a/src/dispatchers/dispatcher.ts b/src/dispatchers/dispatcher.ts index 6f2c2941ee..84eda62e83 100644 --- a/src/dispatchers/dispatcher.ts +++ b/src/dispatchers/dispatcher.ts @@ -18,10 +18,11 @@ import { EventEmitter } from 'events'; import * as channels from '../protocol/channels'; import { serializeError } from '../protocol/serializers'; import { createScheme, Validator, ValidationError } from '../protocol/validator'; -import { assert, createGuid, debugAssert, isUnderTest } from '../utils/utils'; +import { assert, createGuid, debugAssert, isUnderTest, monotonicTime } from '../utils/utils'; import { tOptional } from '../protocol/validatorPrimitives'; import { kBrowserOrContextClosedError } from '../utils/errors'; import { CallMetadata } from '../server/instrumentation'; +import { StackFrame } from '../common/types'; export const dispatcherSymbol = Symbol('dispatcher'); @@ -124,7 +125,7 @@ export class DispatcherConnection { private _rootDispatcher: Root; onmessage = (message: object) => {}; private _validateParams: (type: string, method: string, params: any) => any; - private _validateMetadata: (metadata: any) => any; + private _validateMetadata: (metadata: any) => { stack?: StackFrame[] }; sendMessageToClient(guid: string, method: string, params: any) { this.onmessage({ guid, method, params: this._replaceDispatchersWithGuids(params) }); @@ -180,9 +181,12 @@ export class DispatcherConnection { throw new Error(`Mismatching dispatcher: "${dispatcher._type}" does not implement "${method}"`); const callMetadata: CallMetadata = { ...this._validateMetadata(metadata), + startTime: monotonicTime(), + endTime: 0, type: dispatcher._type, method, params, + log: [], }; const result = await (dispatcher as any)[method](validated, callMetadata); this.onmessage({ id, result: this._replaceDispatchersWithGuids(result) }); diff --git a/src/server/instrumentation.ts b/src/server/instrumentation.ts index bed754656f..50fbcd77c3 100644 --- a/src/server/instrumentation.ts +++ b/src/server/instrumentation.ts @@ -31,10 +31,14 @@ export type Attribution = { }; export type CallMetadata = { + startTime: number; + endTime: number; type: string; method: string; params: any; stack?: StackFrame[]; + log: string[]; + error?: Error; }; export class SdkObject extends EventEmitter { @@ -49,19 +53,13 @@ export class SdkObject extends EventEmitter { } } -export type ActionResult = { - logs: string[], - startTime: number, - endTime: number, - error?: Error, -}; - export interface Instrumentation { onContextCreated(context: BrowserContext): Promise; onContextWillDestroy(context: BrowserContext): Promise; onContextDidDestroy(context: BrowserContext): Promise; onActionCheckpoint(name: string, sdkObject: SdkObject, metadata: CallMetadata): Promise; - onAfterAction(result: ActionResult, sdkObject: SdkObject, metadata: CallMetadata): Promise; + onAfterAction(sdkObject: SdkObject, metadata: CallMetadata): Promise; + onLog(logName: string, message: string, sdkObject: SdkObject, metadata: CallMetadata): void; } export interface InstrumentationListener { @@ -69,7 +67,8 @@ export interface InstrumentationListener { onContextWillDestroy?(context: BrowserContext): Promise; onContextDidDestroy?(context: BrowserContext): Promise; onActionCheckpoint?(name: string, sdkObject: SdkObject, metadata: CallMetadata): Promise; - onAfterAction?(result: ActionResult, sdkObject: SdkObject, metadata: CallMetadata): Promise; + onAfterAction?(sdkObject: SdkObject, metadata: CallMetadata): Promise; + onLog?(logName: string, message: string, sdkObject: SdkObject, metadata: CallMetadata): void; } export function multiplexInstrumentation(listeners: InstrumentationListener[]): Instrumentation { @@ -87,8 +86,11 @@ export function multiplexInstrumentation(listeners: InstrumentationListener[]): export function internalCallMetadata(): CallMetadata { return { + startTime: 0, + endTime: 0, type: 'Internal', method: '', params: {}, + log: [], }; } diff --git a/src/server/progress.ts b/src/server/progress.ts index bf7802abbc..e2f849c4c7 100644 --- a/src/server/progress.ts +++ b/src/server/progress.ts @@ -17,7 +17,7 @@ import { TimeoutError } from '../utils/errors'; import { assert, monotonicTime } from '../utils/utils'; import { rewriteErrorMessage } from '../utils/stackTrace'; -import { debugLogger, LogName } from '../utils/debugLogger'; +import { LogName } from '../utils/debugLogger'; import { CallMetadata, Instrumentation, SdkObject } from './instrumentation'; export interface Progress { @@ -38,11 +38,10 @@ export class ProgressController { // Cleanups to be run only in the case of abort. private _cleanups: (() => any)[] = []; - private _logName: LogName = 'api'; + private _logName = 'api'; private _state: 'before' | 'running' | 'aborted' | 'finished' = 'before'; private _deadline: number = 0; private _timeout: number = 0; - private _logRecording: string[] = []; readonly metadata: CallMetadata; readonly instrumentation: Instrumentation; readonly sdkObject: SdkObject; @@ -70,9 +69,10 @@ export class ProgressController { const progress: Progress = { log: message => { - if (this._state === 'running') - this._logRecording.push(message); - debugLogger.log(this._logName, message); + if (this._state === 'running') { + this.metadata.log.push(message); + this.instrumentation.onLog(this._logName, message, this.sdkObject, this.metadata); + } }, timeUntilDeadline: () => this._deadline ? this._deadline - monotonicTime() : 2147483647, // 2^31-1 safe setTimeout in Node. isRunning: () => this._state === 'running', @@ -93,34 +93,25 @@ export class ProgressController { const timeoutError = new TimeoutError(`Timeout ${this._timeout}ms exceeded.`); const timer = setTimeout(() => this._forceAbort(timeoutError), progress.timeUntilDeadline()); - const startTime = monotonicTime(); try { const promise = task(progress); const result = await Promise.race([promise, this._forceAbortPromise]); clearTimeout(timer); this._state = 'finished'; - await this.instrumentation.onAfterAction({ - startTime, - endTime: monotonicTime(), - logs: this._logRecording, - }, this.sdkObject, this.metadata); - this._logRecording = []; + this.metadata.endTime = monotonicTime(); + await this.instrumentation.onAfterAction(this.sdkObject, this.metadata); return result; } catch (e) { clearTimeout(timer); this._state = 'aborted'; await Promise.all(this._cleanups.splice(0).map(cleanup => runCleanup(cleanup))); - await this.instrumentation.onAfterAction({ - startTime, - endTime: monotonicTime(), - logs: this._logRecording, - error: e, - }, this.sdkObject, this.metadata); + this.metadata.endTime = monotonicTime(); + this.metadata.error = e; + await this.instrumentation.onAfterAction(this.sdkObject, this.metadata); rewriteErrorMessage(e, e.message + - formatLogRecording(this._logRecording) + + formatLogRecording(this.metadata.log) + kLoggingNote); - this._logRecording = []; throw e; } } diff --git a/src/server/supplements/inspectorController.ts b/src/server/supplements/inspectorController.ts index cdf96f21b5..916fb28713 100644 --- a/src/server/supplements/inspectorController.ts +++ b/src/server/supplements/inspectorController.ts @@ -18,6 +18,7 @@ import { BrowserContext } from '../browserContext'; import { isDebugMode } from '../../utils/utils'; import { RecorderSupplement } from './recorderSupplement'; import { InstrumentationListener } from '../instrumentation'; +import { debugLogger } from '../../utils/debugLogger'; export class InspectorController implements InstrumentationListener { async onContextCreated(context: BrowserContext): Promise { @@ -28,4 +29,8 @@ export class InspectorController implements InstrumentationListener { }); } } + + onLog(logName: string, message: string): void { + debugLogger.log(logName as any, message); + } } diff --git a/src/trace/tracer.ts b/src/trace/tracer.ts index 36b041e7c8..41eee3acff 100644 --- a/src/trace/tracer.ts +++ b/src/trace/tracer.ts @@ -27,7 +27,7 @@ import { helper, RegisteredListener } from '../server/helper'; import { Dialog } from '../server/dialog'; import { Frame, NavigationEvent } from '../server/frames'; import { snapshotScript } from './snapshotterInjected'; -import { ActionResult, CallMetadata, InstrumentationListener, SdkObject } from '../server/instrumentation'; +import { CallMetadata, InstrumentationListener, SdkObject } from '../server/instrumentation'; const fsWriteFileAsync = util.promisify(fs.writeFile.bind(fs)); const fsAppendFileAsync = util.promisify(fs.appendFile.bind(fs)); @@ -59,8 +59,8 @@ export class Tracer implements InstrumentationListener { this._contextTracers.get(sdkObject.attribution.context!)?.onActionCheckpoint(name, sdkObject, metadata); } - async onAfterAction(result: ActionResult, sdkObject: SdkObject, metadata: CallMetadata): Promise { - this._contextTracers.get(sdkObject.attribution.context!)?.onAfterAction(result, sdkObject, metadata); + async onAfterAction(sdkObject: SdkObject, metadata: CallMetadata): Promise { + this._contextTracers.get(sdkObject.attribution.context!)?.onAfterAction(sdkObject, metadata); } } @@ -160,7 +160,7 @@ class ContextTracer implements SnapshotterDelegate { await this._snapshotter.forceSnapshot(sdkObject.attribution.page, snapshotId); } - async onAfterAction(result: ActionResult, sdkObject: SdkObject, metadata: CallMetadata): Promise { + async onAfterAction(sdkObject: SdkObject, metadata: CallMetadata): Promise { if (!sdkObject.attribution.page) return; const event: trace.ActionTraceEvent = { @@ -173,10 +173,10 @@ class ContextTracer implements SnapshotterDelegate { // FIXME: filter out evaluation snippets, binary params: metadata.params, stack: metadata.stack, - startTime: result.startTime, - endTime: result.endTime, - logs: result.logs.slice(), - error: result.error ? result.error.stack : undefined, + startTime: metadata.startTime, + endTime: metadata.endTime, + logs: metadata.log.slice(), + error: metadata.error ? metadata.error.stack : undefined, snapshots: snapshotsForMetadata(metadata), }; this._appendTraceEvent(event); diff --git a/utils/check_deps.js b/utils/check_deps.js index 63cba0215a..d44c4b1dde 100644 --- a/utils/check_deps.js +++ b/utils/check_deps.js @@ -114,7 +114,7 @@ DEPS['src/install/'] = ['src/utils/']; // Client depends on chromium protocol for types. DEPS['src/client/'] = ['src/common/', 'src/utils/', 'src/protocol/', 'src/server/chromium/protocol.ts']; -DEPS['src/dispatchers/'] = ['src/utils/', 'src/protocol/', 'src/server/**']; +DEPS['src/dispatchers/'] = ['src/common/', 'src/utils/', 'src/protocol/', 'src/server/**']; // Generic dependencies for server-side code. DEPS['src/server/'] = [