chore: stream trace viewer logs (#27807)

packages/playwright-core/src/server/trace/recorder/tracing.ts

@@ -43,7 +43,7 @@ import { Snapshotter } from './snapshotter';
 import { yazl } from '../../../zipBundle';
 import type { ConsoleMessage } from '../../console';
 
-const version: trace.VERSION = 5;
+const version: trace.VERSION = 6;
 
 export type TracerOptions = {
   name?: string;
@@ -368,6 +368,14 @@ export class Tracing extends SdkObject implements InstrumentationListener, Snaps
     return this._captureSnapshot(event.inputSnapshot, sdkObject, metadata, element);
   }
 
+  onCallLog(sdkObject: SdkObject, metadata: CallMetadata, logName: string, message: string) {
+    if (logName !== 'api')
+      return;
+    const event = createActionLogTraceEvent(metadata, message);
+    if (event)
+      this._appendTraceEvent(event);
+  }
+
   async onAfterCall(sdkObject: SdkObject, metadata: CallMetadata) {
     if (!this._state?.callIds.has(metadata.id))
       return;
@@ -466,7 +474,7 @@ export class Tracing extends SdkObject implements InstrumentationListener, Snaps
   private _appendTraceEvent(event: trace.TraceEvent) {
     const visited = visitTraceEvent(event, this._state!.traceSha1s);
     // Do not flush (console) events, they are too noisy, unless we are in ui mode (live).
-    const flush = this._state!.options.live || (event.type !== 'event' && event.type !== 'console');
+    const flush = this._state!.options.live || (event.type !== 'event' && event.type !== 'console' && event.type !== 'log');
     this._fs.appendFile(this._state!.traceFile, JSON.stringify(visited) + '\n', flush);
   }
 
@@ -531,6 +539,17 @@ function createInputActionTraceEvent(metadata: CallMetadata): trace.InputActionT
   };
 }
 
+function createActionLogTraceEvent(metadata: CallMetadata, message: string): trace.LogTraceEvent | null {
+  if (metadata.internal || metadata.method.startsWith('tracing'))
+    return null;
+  return {
+    type: 'log',
+    callId: metadata.id,
+    time: monotonicTime(),
+    message,
+  };
+}
+
 function createAfterActionTraceEvent(metadata: CallMetadata): trace.AfterActionTraceEvent | null {
   if (metadata.internal || metadata.method.startsWith('tracing'))
     return null;
@@ -538,7 +557,6 @@ function createAfterActionTraceEvent(metadata: CallMetadata): trace.AfterActionT
     type: 'after',
     callId: metadata.id,
     endTime: metadata.endTime,
-    log: metadata.log,
     error: metadata.error?.error,
     result: metadata.result,
   };

packages/playwright/src/worker/testTracing.ts

@@ -130,7 +130,6 @@ export class TestTracing {
       type: 'after',
       callId,
       endTime: monotonicTime(),
-      log: [],
       attachments: serializeAttachments(attachments),
       error,
     });

packages/trace-viewer/src/entries.ts

@@ -33,7 +33,7 @@ export type ContextEntry = {
   options: trace.BrowserContextEventOptions;
   pages: PageEntry[];
   resources: ResourceSnapshot[];
-  actions: trace.ActionTraceEvent[];
+  actions: ActionEntry[];
   events: (trace.EventTraceEvent | trace.ConsoleMessageTraceEvent)[];
   stdio: trace.StdioTraceEvent[];
   hasSource: boolean;
@@ -47,6 +47,11 @@ export type PageEntry = {
     height: number,
   }[];
 };
+
+export type ActionEntry = trace.ActionTraceEvent & {
+  log: { time: number, message: string }[];
+};
+
 export function createEmptyContext(): ContextEntry {
   return {
     isPrimary: false,

packages/trace-viewer/src/traceModel.ts

@@ -17,8 +17,9 @@
 import type * as trace from '@trace/trace';
 import type * as traceV3 from './versions/traceV3';
 import type * as traceV4 from './versions/traceV4';
+import type * as traceV5 from './versions/traceV5';
 import { parseClientSideCallMetadata } from '../../../packages/playwright-core/src/utils/isomorphic/traceUtils';
-import type { ContextEntry, PageEntry } from './entries';
+import type { ActionEntry, ContextEntry, PageEntry } from './entries';
 import { createEmptyContext } from './entries';
 import { SnapshotStorage } from './snapshotStorage';
 
@@ -67,7 +68,7 @@ export class TraceModel {
     let done = 0;
     for (const ordinal of ordinals) {
       const contextEntry = createEmptyContext();
-      const actionMap = new Map<string, trace.ActionTraceEvent>();
+      const actionMap = new Map<string, ActionEntry>();
       contextEntry.traceUrl = backend.traceURL();
       contextEntry.hasSource = hasSource;
 
@@ -150,12 +151,15 @@ export class TraceModel {
     return pageEntry;
   }
 
-  appendEvent(contextEntry: ContextEntry, actionMap: Map<string, trace.ActionTraceEvent>, line: string) {
+  appendEvent(contextEntry: ContextEntry, actionMap: Map<string, ActionEntry>, line: string) {
     if (!line)
       return;
-    const event = this._modernize(JSON.parse(line));
+    const events = this._modernize(JSON.parse(line));
-    if (!event)
+    for (const event of events)
-      return;
+      this._innerAppendEvent(contextEntry, actionMap, event);
+  }
+
+  private _innerAppendEvent(contextEntry: ContextEntry, actionMap: Map<string, ActionEntry>, event: trace.TraceEvent) {
     switch (event.type) {
       case 'context-options': {
         this._version = event.version;
@@ -184,11 +188,18 @@ export class TraceModel {
         existing!.point = event.point;
         break;
       }
+      case 'log': {
+        const existing = actionMap.get(event.callId);
+        existing!.log.push({
+          time: event.time,
+          message: event.message,
+        });
+        break;
+      }
       case 'after': {
         const existing = actionMap.get(event.callId);
         existing!.afterSnapshot = event.afterSnapshot;
         existing!.endTime = event.endTime;
-        existing!.log = event.log;
         existing!.result = event.result;
         existing!.error = event.error;
         existing!.attachments = event.attachments;
@@ -197,7 +208,7 @@ export class TraceModel {
         break;
       }
       case 'action': {
-        actionMap.set(event.callId, event);
+        actionMap.set(event.callId, { ...event, log: [] });
         break;
       }
       case 'event': {
@@ -238,36 +249,40 @@ export class TraceModel {
     }
   }
 
-  private _modernize(event: any): trace.TraceEvent | null {
+  private _modernize(event: any): trace.TraceEvent[] {
     if (this._version === undefined)
-      return event;
+      return [event];
-    const lastVersion: trace.VERSION = 5;
+    const lastVersion: trace.VERSION = 6;
-    for (let version = this._version; version < lastVersion; ++version) {
+    let events = [event];
-      event = (this as any)[`_modernize_${version}_to_${version + 1}`].call(this, event);
+    for (let version = this._version; version < lastVersion; ++version)
-      if (!event)
+      events = (this as any)[`_modernize_${version}_to_${version + 1}`].call(this, events);
-        return null;
+    return events;
-    }
-    return event;
   }
 
-  _modernize_0_to_1(event: any): any {
+  _modernize_0_to_1(events: any[]): any[] {
-    if (event.type === 'action') {
+    for (const event of events) {
+      if (event.type !== 'action')
+        continue;
       if (typeof event.metadata.error === 'string')
         event.metadata.error = { error: { name: 'Error', message: event.metadata.error } };
     }
-    return event;
+    return events;
   }
 
-  _modernize_1_to_2(event: any): any {
+  _modernize_1_to_2(events: any[]): any[] {
-    if (event.type === 'frame-snapshot' && event.snapshot.isMainFrame) {
+    for (const event of events) {
+      if (event.type !== 'frame-snapshot' || !event.snapshot.isMainFrame)
+        continue;
       // Old versions had completely wrong viewport.
       event.snapshot.viewport = this.contextEntries[0]?.options?.viewport || { width: 1280, height: 720 };
     }
-    return event;
+    return events;
   }
 
-  _modernize_2_to_3(event: any): any {
+  _modernize_2_to_3(events: any[]): any[] {
-    if (event.type === 'resource-snapshot' && !event.snapshot.request) {
+    for (const event of events) {
+      if (event.type !== 'resource-snapshot' || event.snapshot.request)
+        continue;
       // Migrate from old ResourceSnapshot to new har entry format.
       const resource = event.snapshot;
       event.snapshot = {
@@ -289,10 +304,20 @@ export class TraceModel {
         _monotonicTime: resource.timestamp,
       };
     }
-    return event;
+    return events;
   }
 
-  _modernize_3_to_4(event: traceV3.TraceEvent): traceV4.TraceEvent | null {
+  _modernize_3_to_4(events: traceV3.TraceEvent[]): traceV4.TraceEvent[] {
+    const result: traceV4.TraceEvent[] = [];
+    for (const event of events) {
+      const e = this._modernize_event_3_to_4(event);
+      if (e)
+        result.push(e);
+    }
+    return result;
+  }
+
+  _modernize_event_3_to_4(event: traceV3.TraceEvent): traceV4.TraceEvent | null {
     if (event.type !== 'action' && event.type !== 'event') {
       return event as traceV3.ContextCreatedTraceEvent |
         traceV3.ScreencastFrameTraceEvent |
@@ -344,7 +369,17 @@ export class TraceModel {
     };
   }
 
-  _modernize_4_to_5(event: traceV4.TraceEvent): trace.TraceEvent | null {
+  _modernize_4_to_5(events: traceV4.TraceEvent[]): traceV5.TraceEvent[] {
+    const result: traceV5.TraceEvent[] = [];
+    for (const event of events) {
+      const e = this._modernize_event_4_to_5(event);
+      if (e)
+        result.push(e);
+    }
+    return result;
+  }
+
+  _modernize_event_4_to_5(event: traceV4.TraceEvent): traceV5.TraceEvent | null {
     if (event.type === 'event' && event.method === '__create__' && event.class === 'JSHandle')
       this._jsHandles.set(event.params.guid, event.params.initializer);
     if (event.type === 'object') {
@@ -384,6 +419,24 @@ export class TraceModel {
     }
     return event;
   }
+
+  _modernize_5_to_6(events: traceV5.TraceEvent[]): trace.TraceEvent[] {
+    const result: trace.TraceEvent[] = [];
+    for (const event of events) {
+      result.push(event);
+      if (event.type !== 'after' || !event.log.length)
+        continue;
+      for (const log of event.log) {
+        result.push({
+          type: 'log',
+          callId: event.callId,
+          message: log,
+          time: -1,
+        });
+      }
+    }
+    return result;
+  }
 }
 
 function stripEncodingFromContentType(contentType: string) {

packages/trace-viewer/src/ui/logTab.tsx

@@ -14,21 +14,21 @@
  * limitations under the License.
  */
 
-import type { ActionTraceEvent } from '@trace/trace';
+import type { ActionTraceEventInContext } from './modelUtil';
 import * as React from 'react';
 import { ListView } from '@web/components/listView';
 import { PlaceholderPanel } from './placeholderPanel';
 
-const LogList = ListView<string>;
+const LogList = ListView<{ message: string, time: number }>;
 
 export const LogTab: React.FunctionComponent<{
-  action: ActionTraceEvent | undefined,
+  action: ActionTraceEventInContext | undefined,
 }> = ({ action }) => {
   if (!action?.log.length)
     return <PlaceholderPanel text='No log entries' />;
   return <LogList
     name='log'
     items={action?.log || []}
-    render={logLine => logLine}
+    render={logLine => logLine.message}
   />;
 };

packages/trace-viewer/src/ui/modelUtil.ts

@@ -38,6 +38,7 @@ export type SourceModel = {
 
 export type ActionTraceEventInContext = ActionTraceEvent & {
   context: ContextEntry;
+  log: { time: number, message: string }[];
 };
 
 export type ActionTreeItem = {

packages/trace-viewer/src/versions/traceV5.ts

@@ -0,0 +1,225 @@
+/**
+ * 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 type { Entry as ResourceSnapshot } from '../../../trace/src/har';
+
+type Language = 'javascript' | 'python' | 'java' | 'csharp' | 'jsonl';
+type Point = { x: number, y: number };
+type Size = { width: number, height: number };
+
+type StackFrame = {
+  file: string,
+  line: number,
+  column: number,
+  function?: string,
+};
+
+type SerializedValue = {
+  n?: number,
+  b?: boolean,
+  s?: string,
+  v?: 'null' | 'undefined' | 'NaN' | 'Infinity' | '-Infinity' | '-0',
+  d?: string,
+  u?: string,
+  bi?: string,
+  m?: SerializedValue,
+  se?: SerializedValue,
+  r?: {
+    p: string,
+    f: string,
+  },
+  a?: SerializedValue[],
+  o?: {
+    k: string,
+    v: SerializedValue,
+  }[],
+  h?: number,
+  id?: number,
+  ref?: number,
+};
+
+type SerializedError = {
+  error?: {
+    message: string,
+    name: string,
+    stack?: string,
+  },
+  value?: SerializedValue,
+};
+
+type NodeSnapshot =
+  // Text node.
+  string |
+  // Subtree reference, "x snapshots ago, node #y". Could point to a text node.
+  // Only nodes that are not references are counted, starting from zero, using post-order traversal.
+  [ [number, number] ] |
+  // Just node name.
+  [ string ] |
+  // Node name, attributes, child nodes.
+  // Unfortunately, we cannot make this type definition recursive, therefore "any".
+  [ string, { [attr: string]: string }, ...any ];
+
+
+type ResourceOverride = {
+  url: string,
+  sha1?: string,
+  ref?: number
+};
+
+type FrameSnapshot = {
+  snapshotName?: string,
+  callId: string,
+  pageId: string,
+  frameId: string,
+  frameUrl: string,
+  timestamp: number,
+  collectionTime: number,
+  doctype?: string,
+  html: NodeSnapshot,
+  resourceOverrides: ResourceOverride[],
+  viewport: { width: number, height: number },
+  isMainFrame: boolean,
+};
+
+export type BrowserContextEventOptions = {
+  viewport?: Size,
+  deviceScaleFactor?: number,
+  isMobile?: boolean,
+  userAgent?: string,
+};
+
+export type ContextCreatedTraceEvent = {
+  version: number,
+  type: 'context-options',
+  browserName: string,
+  channel?: string,
+  platform: string,
+  wallTime: number,
+  title?: string,
+  options: BrowserContextEventOptions,
+  sdkLanguage?: Language,
+  testIdAttributeName?: string,
+};
+
+export type ScreencastFrameTraceEvent = {
+  type: 'screencast-frame',
+  pageId: string,
+  sha1: string,
+  width: number,
+  height: number,
+  timestamp: number,
+};
+
+export type BeforeActionTraceEvent = {
+  type: 'before',
+  callId: string;
+  startTime: number;
+  apiName: string;
+  class: string;
+  method: string;
+  params: Record<string, any>;
+  wallTime: number;
+  beforeSnapshot?: string;
+  stack?: StackFrame[];
+  pageId?: string;
+  parentId?: string;
+};
+
+export type InputActionTraceEvent = {
+  type: 'input',
+  callId: string;
+  inputSnapshot?: string;
+  point?: Point;
+};
+
+export type AfterActionTraceEventAttachment = {
+  name: string;
+  contentType: string;
+  path?: string;
+  sha1?: string;
+  base64?: string;
+};
+
+export type AfterActionTraceEvent = {
+  type: 'after',
+  callId: string;
+  endTime: number;
+  afterSnapshot?: string;
+  log: string[];
+  error?: SerializedError['error'];
+  attachments?: AfterActionTraceEventAttachment[];
+  result?: any;
+};
+
+export type EventTraceEvent = {
+  type: 'event',
+  time: number;
+  class: string;
+  method: string;
+  params: any;
+  pageId?: string;
+};
+
+export type ConsoleMessageTraceEvent = {
+  type: 'console';
+  time: number;
+  pageId?: string;
+  messageType: string,
+  text: string,
+  args?: { preview: string, value: any }[],
+  location: {
+    url: string,
+    lineNumber: number,
+    columnNumber: number,
+  },
+};
+
+export type ResourceSnapshotTraceEvent = {
+  type: 'resource-snapshot',
+  snapshot: ResourceSnapshot,
+};
+
+export type FrameSnapshotTraceEvent = {
+  type: 'frame-snapshot',
+  snapshot: FrameSnapshot,
+};
+
+export type ActionTraceEvent = {
+  type: 'action',
+} & Omit<BeforeActionTraceEvent, 'type'>
+  & Omit<AfterActionTraceEvent, 'type'>
+  & Omit<InputActionTraceEvent, 'type'>;
+
+export type StdioTraceEvent = {
+  type: 'stdout' | 'stderr';
+  timestamp: number;
+  text?: string;
+  base64?: string;
+};
+
+export type TraceEvent =
+    ContextCreatedTraceEvent |
+    ScreencastFrameTraceEvent |
+    ActionTraceEvent |
+    BeforeActionTraceEvent |
+    InputActionTraceEvent |
+    AfterActionTraceEvent |
+    EventTraceEvent |
+    ConsoleMessageTraceEvent |
+    ResourceSnapshotTraceEvent |
+    FrameSnapshotTraceEvent |
+    StdioTraceEvent;

packages/trace/src/trace.ts

@@ -21,7 +21,7 @@ import type { FrameSnapshot, ResourceSnapshot } from './snapshot';
 export type Size = { width: number, height: number };
 
 // Make sure you add _modernize_N_to_N1(event: any) to traceModel.ts.
-export type VERSION = 5;
+export type VERSION = 6;
 
 export type BrowserContextEventOptions = {
   viewport?: Size,
@@ -87,12 +87,18 @@ export type AfterActionTraceEvent = {
   callId: string;
   endTime: number;
   afterSnapshot?: string;
-  log: string[];
   error?: SerializedError['error'];
   attachments?: AfterActionTraceEventAttachment[];
   result?: any;
 };
 
+export type LogTraceEvent = {
+  type: 'log',
+  callId: string;
+  time: number;
+  message: string;
+};
+
 export type EventTraceEvent = {
   type: 'event',
   time: number;
@@ -147,6 +153,7 @@ export type TraceEvent =
     InputActionTraceEvent |
     AfterActionTraceEvent |
     EventTraceEvent |
+    LogTraceEvent |
     ConsoleMessageTraceEvent |
     ResourceSnapshotTraceEvent |
     FrameSnapshotTraceEvent |

tests/config/utils.ts

@@ -115,7 +115,6 @@ export async function parseTraceRaw(file: string): Promise<{ events: any[], reso
             ...event,
             type: 'action',
             endTime: 0,
-            log: []
           };
           actionMap.set(event.callId, action);
         } else if (event.type === 'input') {
@@ -126,7 +125,6 @@ export async function parseTraceRaw(file: string): Promise<{ events: any[], reso
           const existing = actionMap.get(event.callId);
           existing.afterSnapshot = event.afterSnapshot;
           existing.endTime = event.endTime;
-          existing.log = event.log;
           existing.error = event.error;
           existing.result = event.result;
         }