feature(test runner): capture error and pending calls when timing out (#7193)

src/client/channelOwner.ts

@@ -74,11 +74,11 @@ export abstract class ChannelOwner<T extends channels.Channel = channels.Channel
     const channel = new Proxy(base, {
       get: (obj: any, prop) => {
         if (prop === 'debugScopeState')
-          return (params: any) => this._connection.sendMessageToServer(this._guid, prop, params, apiName);
+          return (params: any) => this._connection.sendMessageToServer(this, prop, params, apiName);
         if (typeof prop === 'string') {
           const validator = scheme[paramsName(this._type, prop)];
           if (validator)
-            return (params: any) => this._connection.sendMessageToServer(this._guid, prop, validator(params, ''), apiName);
+            return (params: any) => this._connection.sendMessageToServer(this, prop, validator(params, ''), apiName);
         }
         return obj[prop];
       },
@@ -103,15 +103,15 @@ export abstract class ChannelOwner<T extends channels.Channel = channels.Channel
   }
 
   _waitForEventInfoBefore(waitId: string, apiName: string) {
-    this._connection.sendMessageToServer(this._guid, 'waitForEventInfo', { info: { apiName, waitId, phase: 'before' } }, undefined).catch(() => {});
+    this._connection.sendMessageToServer(this, 'waitForEventInfo', { info: { apiName, waitId, phase: 'before' } }, undefined).catch(() => {});
   }
 
   _waitForEventInfoAfter(waitId: string, error?: string) {
-    this._connection.sendMessageToServer(this._guid, 'waitForEventInfo', { info: { waitId, phase: 'after', error } }, undefined).catch(() => {});
+    this._connection.sendMessageToServer(this, 'waitForEventInfo', { info: { waitId, phase: 'after', error } }, undefined).catch(() => {});
   }
 
   _waitForEventInfoLog(waitId: string, message: string) {
-    this._connection.sendMessageToServer(this._guid, 'waitForEventInfo', { info: { waitId, phase: 'log', message } }, undefined).catch(() => {});
+    this._connection.sendMessageToServer(this, 'waitForEventInfo', { info: { waitId, phase: 'log', message } }, undefined).catch(() => {});
   }
 
   private toJSON() {

src/client/connection.ts

@@ -52,7 +52,7 @@ export class Connection extends EventEmitter {
   private _waitingForObject = new Map<string, any>();
   onmessage = (message: object): void => {};
   private _lastId = 0;
-  private _callbacks = new Map<number, { resolve: (a: any) => void, reject: (a: Error) => void }>();
+  private _callbacks = new Map<number, { resolve: (a: any) => void, reject: (a: Error) => void, metadata: channels.Metadata }>();
   private _rootObject: ChannelOwner;
   private _disconnectedErrorMessage: string | undefined;
   private _onClose?: () => void;
@@ -69,21 +69,27 @@ export class Connection extends EventEmitter {
     return new Promise(f => this._waitingForObject.set(guid, f));
   }
 
+  pendingProtocolCalls(): channels.Metadata[] {
+    return Array.from(this._callbacks.values()).map(callback => callback.metadata);
+  }
+
   getObjectWithKnownName(guid: string): any {
     return this._objects.get(guid)!;
   }
 
-  async sendMessageToServer(guid: string, method: string, params: any, apiName: string | undefined): Promise<any> {
+  async sendMessageToServer(object: ChannelOwner, method: string, params: any, apiName: string | undefined): Promise<any> {
+    const guid = object._guid;
     const { stack, frames } = captureStackTrace();
     const id = ++this._lastId;
     const converted = { id, guid, method, params };
     // Do not include metadata in debug logs to avoid noise.
     debugLogger.log('channel:command', converted);
-    this.onmessage({ ...converted, metadata: { stack: frames, apiName } });
+    const metadata: channels.Metadata = { stack: frames, apiName };
+    this.onmessage({ ...converted, metadata });
     try {
       if (this._disconnectedErrorMessage)
         throw new Error(this._disconnectedErrorMessage);
-      return await new Promise((resolve, reject) => this._callbacks.set(id, { resolve, reject }));
+      return await new Promise((resolve, reject) => this._callbacks.set(id, { resolve, reject, metadata }));
     } catch (e) {
       const innerStack = ((process.env.PWDEBUGIMPL || isUnderTest()) && e.stack) ? e.stack.substring(e.stack.indexOf(e.message) + e.message.length) : '';
       e.stack = e.message + innerStack + '\n' + stack;

src/test/index.ts

@@ -17,8 +17,8 @@
 import * as fs from 'fs';
 import * as path from 'path';
 import * as os from 'os';
-import type { LaunchOptions, BrowserContextOptions, Page, ViewportSize } from '../../types/types';
-import type { TestType, PlaywrightTestArgs, PlaywrightTestOptions, PlaywrightWorkerArgs, PlaywrightWorkerOptions } from '../../types/test';
+import type { LaunchOptions, BrowserContextOptions, Page, BrowserContext } from '../../types/types';
+import type { TestType, PlaywrightTestArgs, PlaywrightTestOptions, PlaywrightWorkerArgs, PlaywrightWorkerOptions, FullConfig, TestInfo } from '../../types/test';
 import { rootTestType } from './testType';
 import { createGuid, removeFolders } from '../utils/utils';
 export { expect } from './expect';
@@ -167,7 +167,18 @@ export const test = _baseTest.extend<PlaywrightTestArgs & PlaywrightTestOptions,
         return page.screenshot({ timeout: 5000, path: screenshotPath }).catch(e => {});
       }));
     }
+
+    const prependToError = testInfo.status ===  'timedOut' ? formatPendingCalls((context as any)._connection.pendingProtocolCalls(), testInfo) : '';
     await context.close();
+    if (prependToError) {
+      if (!testInfo.error) {
+        testInfo.error = { value: prependToError };
+      } else if (testInfo.error.message) {
+        testInfo.error.message = prependToError + testInfo.error.message;
+        if (testInfo.error.stack)
+          testInfo.error.stack = prependToError + testInfo.error.stack;
+      }
+    }
 
     const preserveVideo = captureVideo && (videoMode === 'on' || (testFailed && videoMode === 'retain-on-failure') || (videoMode === 'on-first-retry' && testInfo.retry === 1));
     if (preserveVideo) {
@@ -191,3 +202,29 @@ export const test = _baseTest.extend<PlaywrightTestArgs & PlaywrightTestOptions,
   },
 });
 export default test;
+
+function formatPendingCalls(calls: ProtocolCall[], testInfo: TestInfo) {
+  if (!calls.length)
+    return '';
+  return 'Pending operations:\n' + calls.map(call => {
+    const frame = call.stack && call.stack[0] ? formatStackFrame(testInfo.config, call.stack[0]) : '<unknown>';
+    return `  - ${call.apiName} at ${frame}\n`;
+  }).join('') + '\n';
+}
+
+function formatStackFrame(config: FullConfig, frame: StackFrame) {
+  const file = path.relative(config.rootDir, frame.file) || path.basename(frame.file);
+  return `${file}:${frame.line || 1}:${frame.column || 1}`;
+}
+
+type StackFrame = {
+  file: string,
+  line?: number,
+  column?: number,
+  function?: string,
+};
+
+type ProtocolCall = {
+  stack?: StackFrame[],
+  apiName?: string,
+};

src/test/reporters/base.ts

@@ -185,6 +185,8 @@ function formatFailedResult(test: Test, result: TestResult): string {
   if (result.status === 'timedOut') {
     tokens.push('');
     tokens.push(indent(colors.red(`Timeout of ${test.timeout}ms exceeded.`), '    '));
+    if (result.error !== undefined)
+      tokens.push(indent(formatError(result.error, test.spec.file), '    '));
   } else {
     tokens.push(indent(formatError(result.error!, test.spec.file), '    '));
   }

src/test/workerRunner.ts

@@ -331,11 +331,12 @@ export class WorkerRunner extends EventEmitter {
           testInfo.status = 'skipped';
       } else {
         // We might fail after the timeout, e.g. due to fixture teardown.
-        // Do not overwrite the timeout status with this error.
-        if (testInfo.status === 'passed') {
+        // Do not overwrite the timeout status.
+        if (testInfo.status === 'passed')
           testInfo.status = 'failed';
+        // Keep the error even in the case of timeout, if there was no error before.
+        if (!('error' in  testInfo))
           testInfo.error = serializeError(error);
-        }
       }
     }
   }
@@ -344,21 +345,23 @@ export class WorkerRunner extends EventEmitter {
     try {
       await this._runHooks(test.spec.parent!, 'afterEach', testInfo);
     } catch (error) {
-      // Do not overwrite test failure error.
-      if (!(error instanceof SkipError) && testInfo.status === 'passed') {
-        testInfo.status = 'failed';
-        testInfo.error = serializeError(error);
+      if (!(error instanceof SkipError)) {
+        if (testInfo.status === 'passed')
+          testInfo.status = 'failed';
+        // Do not overwrite test failure error.
+        if (!('error' in  testInfo))
+          testInfo.error = serializeError(error);
         // Continue running even after the failure.
       }
     }
     try {
       await this._fixtureRunner.teardownScope('test');
     } catch (error) {
-      // Do not overwrite test failure error.
-      if (testInfo.status === 'passed') {
+      if (testInfo.status === 'passed')
         testInfo.status = 'failed';
+      // Do not overwrite test failure error.
+      if (!('error' in  testInfo))
         testInfo.error = serializeError(error);
-      }
     }
   }
 

src/utils/stackTrace.ts

@@ -59,10 +59,10 @@ export function captureStackTrace(): { stack: string, frames: StackFrame[] } {
     const fileName = path.resolve(process.cwd(), frame.file);
     if (PW_LIB_DIRS.some(libDir => fileName.includes(libDir)))
       continue;
-    // for tests.
-    if (isUnderTest() && fileName.includes(path.join('playwright', 'src')))
+    const isTesting = process.env.PWTEST_CLI_ALLOW_TEST_COMMAND || isUnderTest();
+    if (isTesting && fileName.includes(path.join('playwright', 'src')))
       continue;
-    if (isUnderTest() && fileName.includes(path.join('playwright', 'tests', 'config', 'coverage.js')))
+    if (isTesting && fileName.includes(path.join('playwright', 'tests', 'config', 'coverage.js')))
       continue;
     frames.push({
       file: fileName,

tests/playwright-test/playwright.spec.ts

@@ -14,7 +14,7 @@
  * limitations under the License.
  */
 
-import { test, expect } from './playwright-test-fixtures';
+import { test, expect, stripAscii } from './playwright-test-fixtures';
 import fs from 'fs';
 import path from 'path';
 import { spawnSync } from 'child_process';
@@ -122,6 +122,30 @@ test('should complain with projects and --browser', async ({ runInlineTest }) =>
   expect(result.output).toContain('Cannot use --browser option when configuration file defines projects');
 });
 
+test('should report error and pending operations on timeout', async ({ runInlineTest }, testInfo) => {
+  const result = await runInlineTest({
+    'a.test.ts': `
+      const { test } = pwt;
+      test('timedout', async ({ page }) => {
+        await page.setContent('<div>Click me</div>');
+        await Promise.all([
+          page.click('text=Missing'),
+          page.textContent('text=More missing'),
+        ]);
+      });
+    `,
+  }, { workers: 1, timeout: 2000 });
+
+  expect(result.exitCode).toBe(1);
+  expect(result.passed).toBe(0);
+  expect(result.failed).toBe(1);
+  expect(result.output).toContain('Pending operations:');
+  expect(result.output).toContain('- page.click at a.test.ts:9:16');
+  expect(result.output).toContain('- page.textContent at a.test.ts:10:16');
+  expect(result.output).toContain('retrieving textContent from "text=More missing"');
+  expect(stripAscii(result.output)).toContain(`10 |           page.textContent('text=More missing'),`);
+});
+
 test('should work with screenshot: only-on-failure', async ({ runInlineTest }, testInfo) => {
   const result = await runInlineTest({
     'playwright.config.ts': `