chore: move progress log into the metadata (#5411)

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) });

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,27 +53,22 @@ export class SdkObject extends EventEmitter {
   }
 }
 
-export type ActionResult = {
-  logs: string[],
-  startTime: number,
-  endTime: number,
-  error?: Error,
-};
-
 export interface Instrumentation {
   onContextCreated(context: BrowserContext): Promise<void>;
   onContextWillDestroy(context: BrowserContext): Promise<void>;
   onContextDidDestroy(context: BrowserContext): Promise<void>;
   onActionCheckpoint(name: string, sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
-  onAfterAction(result: ActionResult, sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
+  onAfterAction(sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
+  onLog(logName: string, message: string, sdkObject: SdkObject, metadata: CallMetadata): void;
 }
 
 export interface InstrumentationListener {
   onContextCreated?(context: BrowserContext): Promise<void>;
   onContextWillDestroy?(context: BrowserContext): Promise<void>;
   onContextDidDestroy?(context: BrowserContext): Promise<void>;
   onActionCheckpoint?(name: string, sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
-  onAfterAction?(result: ActionResult, sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
+  onAfterAction?(sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
+  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: [],
   };
 }

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;
     }
   }

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<void> {
@@ -28,4 +29,8 @@ export class InspectorController implements InstrumentationListener {
       });
     }
   }
+
+  onLog(logName: string, message: string): void {
+    debugLogger.log(logName as any, message);
+  }
 }

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<void> {
-    this._contextTracers.get(sdkObject.attribution.context!)?.onAfterAction(result, sdkObject, metadata);
+  async onAfterAction(sdkObject: SdkObject, metadata: CallMetadata): Promise<void> {
+    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<void> {
+  async onAfterAction(sdkObject: SdkObject, metadata: CallMetadata): Promise<void> {
     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);

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/'] = [