feat(inspector): render params and durations in log (#5489)

src/dispatchers/dispatcher.ts

@@ -219,6 +219,7 @@ export class DispatcherConnection {
         rewriteErrorMessage(e, e.message + formatLogRecording(callMetadata.log) + kLoggingNote);
       this.onmessage({ id, error: serializeError(e) });
     } finally {
+      callMetadata.endTime = monotonicTime();
       if (sdkObject)
         await sdkObject.instrumentation.onAfterCall(sdkObject, callMetadata);
     }

src/server/instrumentation.ts

@@ -34,6 +34,8 @@ export type CallMetadata = {
   id: number;
   startTime: number;
   endTime: number;
+  pauseStartTime?: number;
+  pauseEndTime?: number;
   type: string;
   method: string;
   params: any;

src/server/progress.ts

@@ -109,7 +109,6 @@ export class ProgressController {
       throw e;
     } finally {
       clearTimeout(timer);
-      this.metadata.endTime = monotonicTime();
     }
   }
 

src/server/supplements/inspectorController.ts

@@ -72,12 +72,15 @@ export class InspectorController implements InstrumentationListener {
       const info = metadata.params.info;
       switch (info.phase) {
         case 'before':
+          metadata.endTime = 0;
           // Fall through.
         case 'log':
           return;
         case 'after':
-          metadata = this._waitOperations.get(info.waitId)!;
+          const originalMetadata = this._waitOperations.get(info.waitId)!;
+          originalMetadata.endTime = metadata.endTime;
           this._waitOperations.delete(info.waitId);
+          metadata = originalMetadata;
           break;
       }
     }

src/server/supplements/recorder/recorderTypes.ts

@@ -36,6 +36,11 @@ export type CallLog = {
   status: 'in-progress' | 'done' | 'error' | 'paused';
   error?: string;
   reveal?: boolean;
+  duration?: number;
+  params: {
+    url?: string,
+    selector?: string,
+  };
 };
 
 export type SourceHighlight = {

src/server/supplements/recorderSupplement.ts

@@ -31,7 +31,7 @@ import { RecorderApp } from './recorder/recorderApp';
 import { CallMetadata, internalCallMetadata, SdkObject } from '../instrumentation';
 import { Point } from '../../common/types';
 import { CallLog, EventData, Mode, Source, UIState } from './recorder/recorderTypes';
-import { isUnderTest } from '../../utils/utils';
+import { isUnderTest, monotonicTime } from '../../utils/utils';
 
 type BindingSource = { frame: Frame, page: Page };
 
@@ -210,6 +210,7 @@ export class RecorderSupplement {
       this._pausedCallsMetadata.set(metadata, f);
     });
     this._recorderApp!.setPaused(true);
+    metadata.pauseStartTime = monotonicTime();
     this._updateUserSources();
     this.updateCallLog([metadata]);
     return result;
@@ -219,8 +220,11 @@ export class RecorderSupplement {
     this._pauseOnNextStatement = step;
     this._recorderApp?.setPaused(false);
 
-    for (const callback of this._pausedCallsMetadata.values())
+    const endTime = monotonicTime();
+    for (const [metadata, callback] of this._pausedCallsMetadata) {
+      metadata.pauseEndTime = endTime;
       callback();
+    }
     this._pausedCallsMetadata.clear();
 
     this._updateUserSources();
@@ -418,7 +422,21 @@ export class RecorderSupplement {
         status = 'paused';
       if (metadata.error)
         status = 'error';
-      logs.push({ id: metadata.id, messages: metadata.log, title, status, error: metadata.error });
+      const params = {
+        url: metadata.params?.url,
+        selector: metadata.params?.selector,
+      };
+      let duration = metadata.endTime ? metadata.endTime - metadata.startTime : undefined;
+      if (duration && metadata.pauseStartTime && metadata.pauseEndTime)
+        duration -= (metadata.pauseEndTime - metadata.pauseStartTime);
+      logs.push({
+        id: metadata.id,
+        messages: metadata.log,
+        title, status,
+        error: metadata.error,
+        params,
+        duration
+      });
     }
     this._recorderApp?.updateCallLogs(logs);
   }

src/web/recorder/callLog.css

@@ -76,3 +76,16 @@
 .call-log .codicon-error {
   color: red;
 }
+
+.call-log-url {
+  color: var(--blue);
+}
+
+.call-log-selector {
+  color: var(--orange);
+}
+
+.call-log-time {
+  margin-left: 4px;
+  color: var(--gray);
+}

src/web/recorder/callLog.example.ts

@@ -22,7 +22,9 @@ export function exampleCallLog(): CallLog[] {
       'id': 3,
       'messages': [],
       'title': 'newPage',
-      'status': 'done'
+      'status': 'done',
+      'duration': 100,
+      'params': {}
     },
     {
       'id': 4,
@@ -30,7 +32,11 @@ export function exampleCallLog(): CallLog[] {
         'navigating to "https://github.com/microsoft", waiting until "load"',
       ],
       'title': 'goto',
-      'status': 'done'
+      'status': 'done',
+      'params': {
+        'url': 'https://github.com/microsoft'
+      },
+      'duration': 1100,
     },
     {
       'id': 5,
@@ -47,7 +53,10 @@ export function exampleCallLog(): CallLog[] {
         '  performing click action'
       ],
       'title': 'click',
-      'status': 'paused'
+      'status': 'paused',
+      'params': {
+        'selector': 'input[aria-label="Find a repository…"]'
+      },
     },
     {
       'id': 6,
@@ -56,7 +65,9 @@ export function exampleCallLog(): CallLog[] {
       ],
       'error': 'Error occured',
       'title': 'error',
-      'status': 'error'
+      'status': 'error',
+      'params': {
+      },
     },
   ];
 }

src/web/recorder/callLog.tsx

@@ -17,6 +17,7 @@
 import './callLog.css';
 import * as React from 'react';
 import type { CallLog } from '../../server/supplements/recorder/recorderTypes';
+import { msToString } from '../uiUtils';
 
 export interface CallLogProps {
   log: CallLog[]
@@ -46,7 +47,10 @@ export const CallLogView: React.FC<CallLogProps> = ({
               setExpandOverrides(newOverrides);
             }}></span>
             { callLog.title }
+            { callLog.params.url ? <span>(<span className='call-log-url'>{callLog.params.url}</span>)</span> : undefined }
+            { callLog.params.selector ? <span>(<span className='call-log-selector'>{callLog.params.selector}</span>)</span> : undefined }
             <span className={'codicon ' + iconClass(callLog)}></span>
+            { typeof callLog.duration === 'number' ? <span className='call-log-time'>— {msToString(callLog.duration)}</span> : undefined}
           </div>
           { (isExpanded ? callLog.messages : []).map((message, i) => {
             return <div className='call-log-message' key={i}>

src/web/traceViewer/ui/helpers.tsx

@@ -72,29 +72,3 @@ export const Expandable: React.FunctionComponent<{
     { expanded && <div style={{ display: 'flex', flex: 'auto', margin: '5px 0 5px 20px' }}>{body}</div> }
   </div>;
 };
-
-export function msToString(ms: number): string {
-  if (!isFinite(ms))
-    return '-';
-
-  if (ms === 0)
-    return '0';
-
-  if (ms < 1000)
-    return ms.toFixed(0) + 'ms';
-
-  const seconds = ms / 1000;
-  if (seconds < 60)
-    return seconds.toFixed(1) + 's';
-
-  const minutes = seconds / 60;
-  if (minutes < 60)
-    return minutes.toFixed(1) + 'm';
-
-  const hours = minutes / 60;
-  if (hours < 24)
-    return hours.toFixed(1) + 'h';
-
-  const days = hours / 24;
-  return days.toFixed(1) + 'd';
-}

src/web/traceViewer/ui/snapshotTab.tsx

@@ -18,7 +18,8 @@ import { ActionEntry } from '../../../cli/traceViewer/traceModel';
 import { Boundaries, Size } from '../geometry';
 import './snapshotTab.css';
 import * as React from 'react';
-import { msToString, useMeasure } from './helpers';
+import { useMeasure } from './helpers';
+import { msToString } from '../../uiUtils';
 
 export const SnapshotTab: React.FunctionComponent<{
   actionEntry: ActionEntry | undefined,

src/web/traceViewer/ui/timeline.tsx

@@ -19,7 +19,8 @@ import { ContextEntry, InterestingPageEvent, ActionEntry, trace } from '../../..
 import './timeline.css';
 import { Boundaries } from '../geometry';
 import * as React from 'react';
-import { msToString, useMeasure } from './helpers';
+import { useMeasure } from './helpers';
+import { msToString } from '../../uiUtils';
 
 type TimelineBar = {
   entry?: ActionEntry;

src/web/uiUtils.ts

@@ -0,0 +1,41 @@
+/*
+  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.
+*/
+
+export function msToString(ms: number): string {
+  if (!isFinite(ms))
+    return '-';
+
+  if (ms === 0)
+    return '0';
+
+  if (ms < 1000)
+    return ms.toFixed(0) + 'ms';
+
+  const seconds = ms / 1000;
+  if (seconds < 60)
+    return seconds.toFixed(1) + 's';
+
+  const minutes = seconds / 60;
+  if (minutes < 60)
+    return minutes.toFixed(1) + 'm';
+
+  const hours = minutes / 60;
+  if (hours < 24)
+    return hours.toFixed(1) + 'h';
+
+  const days = hours / 24;
+  return days.toFixed(1) + 'd';
+}

test/pause.spec.ts

@@ -146,8 +146,8 @@ describe('pause', (suite, { mode }) => {
     await recorderPage.click('[title="Resume"]');
     await recorderPage.waitForSelector('.source-line-paused:has-text("page.pause();  // 2")');
     expect(await sanitizeLog(recorderPage)).toEqual([
-      'pause',
-      'click',
+      'pause- XXms',
+      'click(button)- XXms',
       'pause',
     ]);
     await recorderPage.click('[title="Resume"]');
@@ -168,9 +168,9 @@ describe('pause', (suite, { mode }) => {
     await recorderPage.click('[title="Resume"]');
     await recorderPage.waitForSelector('.source-line-paused:has-text("page.pause();  // 2")');
     expect(await sanitizeLog(recorderPage)).toEqual([
-      'pause',
-      'waitForEvent()',
-      'click',
+      'pause- XXms',
+      'waitForEvent(console)- XXms',
+      'click(button)- XXms',
       'pause',
     ]);
     await recorderPage.click('[title="Resume"]');
@@ -187,10 +187,10 @@ describe('pause', (suite, { mode }) => {
     await recorderPage.click('[title="Resume"]');
     await recorderPage.waitForSelector('.source-line-error');
     expect(await sanitizeLog(recorderPage)).toEqual([
-      'pause',
-      'isChecked',
+      'pause- XXms',
+      'isChecked(button)- XXms',
       'checking \"checked\" state of \"button\"',
-      'selector resolved to <button onclick=\"console.log()\">Submit</button>',
+      'selector resolved to <button onclick=\"console.log(1)\">Submit</button>',
       'Not a checkbox or radio button',
     ]);
     const error = await scriptPromise;
@@ -199,10 +199,15 @@ describe('pause', (suite, { mode }) => {
 });
 
 async function sanitizeLog(recorderPage: Page): Promise<string[]> {
-  const text = await recorderPage.innerText('.call-log');
-  return text.split('\n').filter(l => {
-    return l !== 'element is not stable - waiting...';
-  }).map(l => {
-    return l.replace(/\(.*\)/, '()');
-  });
+  const results = [];
+  for (const entry of await recorderPage.$$('.call-log-call')) {
+    const header = await (await (await entry.$('.call-log-call-header')).textContent()).replace(/— \d+(ms|s)/, '- XXms');
+    results.push(header);
+    results.push(...await entry.$$eval('.call-log-message', ee => ee.map(e => e.textContent)));
+    const errorElement = await entry.$('.call-log-error');
+    const error = errorElement ? await errorElement.textContent() : undefined;
+    if (error)
+      results.push(error);
+  }
+  return results;
 }