fix(test runner): update timeout error messages (#15117)

Some of the current timeout error messages are confusing, because they do not suggest that the issue is most likely a slow test. This PR updates timeout messages as follows:
- Test timeout of 30000ms exceeded.
- Test timeout of 30000ms exceeded while setting up "browser".
- Test timeout of 30000ms exceeded while tearing down "context".
- Test timeout of 30000ms exceeded while setting up "playwright configuration".
- Test timeout of 30000ms exceeded while running "beforeEach" hook.
- Test timeout of 30000ms exceeded while running "afterEach" hook.
- "beforeAll" hook timeout of 30000ms exceeded.
- "afterAll" hook timeout of 30000ms exceeded.
- Worker teardown timeout of 30000ms exceeded.
- "skip" modifier timeout of 30000ms exceeded.
- Fixture "myCustomFixture" timeout of 5000ms exceeded.
This commit is contained in:
Dmitry Gozman 2022-06-30 17:05:08 -07:00 committed by GitHub
parent dc1d8dc3da
commit b86926e691
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
15 changed files with 69 additions and 57 deletions

View file

@ -66,8 +66,9 @@ class Fixture {
this.runner = runner;
this.registration = registration;
this.value = null;
const title = this.registration.customTitle || this.registration.name;
this._runnableDescription = {
title: `fixture "${this.registration.customTitle || this.registration.name}" setup`,
title: this.registration.timeout !== undefined ? `Fixture "${title}"` : `setting up "${title}"`,
location: registration.location,
slot: this.registration.timeout === undefined ? undefined : {
timeout: this.registration.timeout,
@ -139,7 +140,8 @@ class Fixture {
}
if (this._useFuncFinished) {
debugTest(`teardown ${this.registration.name}`);
this._runnableDescription.title = `fixture "${this.registration.customTitle || this.registration.name}" teardown`;
const title = this.registration.customTitle || this.registration.name;
this._runnableDescription.title = this.registration.timeout !== undefined ? `Fixture "${title}"` : `tearing down "${title}"`;
timeoutManager.setCurrentFixture(this._runnableDescription);
this._useFuncFinished.resolve();
await this._selfTeardownComplete;

View file

@ -84,7 +84,7 @@ export const test = _baseTest.extend<TestFixtures, WorkerFixtures>({
});
if (dir)
await removeFolders([dir]);
}, { scope: 'worker', _title: 'built-in playwright configuration' } as any],
}, { scope: 'worker', _title: 'playwright configuration' } as any],
_browserOptions: [async ({ playwright, headless, channel, launchOptions }, use) => {
const options: LaunchOptions = {
@ -452,7 +452,7 @@ export const test = _baseTest.extend<TestFixtures, WorkerFixtures>({
else
await fs.promises.unlink(file).catch(() => {});
}));
}, { auto: 'all-hooks-included', _title: 'built-in playwright configuration' } as any],
}, { auto: 'all-hooks-included', _title: 'playwright configuration' } as any],
_contextFactory: [async ({ browser, video, _artifactsDir }, use, testInfo) => {
const videoMode = normalizeVideoMode(video);

View file

@ -104,29 +104,35 @@ export class TimeoutManager {
}
private _createTimeoutError(): TestError {
let suffix = '';
let message = '';
const timeout = this._currentSlot().timeout;
switch (this._runnable.type) {
case 'test':
suffix = ''; break;
case 'beforeAll':
case 'beforeEach':
case 'afterAll':
const fixtureSuffix = this._fixture ? ` while ${this._fixture.title}` : '';
message = `Test timeout of ${timeout}ms exceeded${fixtureSuffix}.`;
break;
case 'afterEach':
suffix = ` in ${this._runnable.type} hook`; break;
case 'beforeEach':
message = `Test timeout of ${timeout}ms exceeded while running "${this._runnable.type}" hook.`;
break;
case 'beforeAll':
case 'afterAll':
message = `"${this._runnable.type}" hook timeout of ${timeout}ms exceeded.`;
break;
case 'teardown':
suffix = ` in fixtures teardown`; break;
message = `Worker teardown timeout of ${timeout}ms exceeded.`;
break;
case 'skip':
case 'slow':
case 'fixme':
case 'fail':
suffix = ` in ${this._runnable.type} modifier`; break;
message = `"${this._runnable.type}" modifier timeout of ${timeout}ms exceeded.`;
break;
}
const fixtureWithSlot = this._fixture?.slot ? this._fixture : undefined;
if (fixtureWithSlot)
suffix = ` by ${fixtureWithSlot.title}`;
else if (this._fixture)
suffix = ` while running ${this._fixture.title}`;
const message = colors.red(`Timeout of ${this._currentSlot().timeout}ms exceeded${suffix}.`);
message = `${fixtureWithSlot.title} timeout of ${timeout}ms exceeded.`;
message = colors.red(message);
const location = (fixtureWithSlot || this._runnable).location;
return {
message,

View file

@ -418,8 +418,9 @@ export class WorkerRunner extends EventEmitter {
}
}
// Teardown test-scoped fixtures.
testInfo._timeoutManager.setCurrentRunnable({ type: 'teardown', slot: afterHooksSlot });
// Teardown test-scoped fixtures. Attribute to 'test' so that users understand
// they should probably increate the test timeout to fix this issue.
testInfo._timeoutManager.setCurrentRunnable({ type: 'test', slot: afterHooksSlot });
const testScopeError = await testInfo._runFn(() => this._fixtureRunner.teardownScope('test', testInfo._timeoutManager));
firstAfterHooksError = firstAfterHooksError || testScopeError;
});
@ -439,9 +440,12 @@ export class WorkerRunner extends EventEmitter {
firstAfterHooksError = firstAfterHooksError || afterAllError;
}
const teardownSlot = { timeout: this._project.timeout, elapsed: 0 };
testInfo._timeoutManager.setCurrentRunnable({ type: 'teardown', slot: teardownSlot });
// Attribute to 'test' so that users understand they should probably increate the test timeout to fix this issue.
testInfo._timeoutManager.setCurrentRunnable({ type: 'test', slot: teardownSlot });
const testScopeError = await testInfo._runFn(() => this._fixtureRunner.teardownScope('test', testInfo._timeoutManager));
firstAfterHooksError = firstAfterHooksError || testScopeError;
// Attribute to 'teardown' because worker fixtures are not perceived as a part of a test.
testInfo._timeoutManager.setCurrentRunnable({ type: 'teardown', slot: teardownSlot });
const workerScopeError = await testInfo._runFn(() => this._fixtureRunner.teardownScope('worker', testInfo._timeoutManager));
firstAfterHooksError = firstAfterHooksError || workerScopeError;
});

View file

@ -43,7 +43,7 @@ test('should timeout', async ({ runInlineTest }) => {
expect(exitCode).toBe(1);
expect(passed).toBe(0);
expect(failed).toBe(1);
expect(output).toContain('Timeout of 100ms exceeded.');
expect(output).toContain('Test timeout of 100ms exceeded.');
});
test('should succeed', async ({ runInlineTest }) => {

View file

@ -51,7 +51,7 @@ test('should prioritize project timeout', async ({ runInlineTest }) => {
expect(result.exitCode).toBe(1);
expect(result.passed).toBe(1);
expect(result.failed).toBe(1);
expect(result.output).toContain('Timeout of 500ms exceeded.');
expect(result.output).toContain('Test timeout of 500ms exceeded.');
});
test('should prioritize command line timeout over project timeout', async ({ runInlineTest }) => {
@ -69,7 +69,7 @@ test('should prioritize command line timeout over project timeout', async ({ run
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.output).toContain('Timeout of 500ms exceeded.');
expect(result.output).toContain('Test timeout of 500ms exceeded.');
});
test('should read config from --config, resolve relative testDir', async ({ runInlineTest }) => {

View file

@ -36,7 +36,7 @@ test('should handle fixture timeout', async ({ runInlineTest }) => {
`
}, { timeout: 500 });
expect(result.exitCode).toBe(1);
expect(result.output).toContain('Timeout of 500ms');
expect(result.output).toContain('Test timeout of 500ms exceeded while tearing down "timeout".');
expect(result.failed).toBe(2);
});
@ -55,7 +55,7 @@ test('should handle worker fixture timeout', async ({ runInlineTest }) => {
`
}, { timeout: 500 });
expect(result.exitCode).toBe(1);
expect(result.output).toContain('Timeout of 500ms');
expect(result.output).toContain('Worker teardown timeout of 500ms exceeded.');
});
test('should handle worker fixture error', async ({ runInlineTest }) => {
@ -111,7 +111,7 @@ test('should handle worker tear down fixture error after failed test', async ({
`
}, { timeout: 1000 });
expect(result.exitCode).toBe(1);
expect(result.output).toContain('Timeout of 1000ms exceeded.');
expect(result.output).toContain('Test timeout of 1000ms exceeded.');
expect(result.output).toContain('Worker failed');
});
@ -370,7 +370,7 @@ test('should exit with timeout when fixture causes an exception in the test', as
}, { timeout: 500 });
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.output).toContain('Timeout of 500ms exceeded');
expect(result.output).toContain('Test timeout of 500ms exceeded.');
});
test('should error for unsupported scope', async ({ runInlineTest }) => {
@ -408,7 +408,7 @@ test('should give enough time for fixture teardown', async ({ runInlineTest }) =
});
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.output).toContain('Timeout of 1000ms exceeded');
expect(result.output).toContain('Test timeout of 1000ms exceeded while tearing down "fixture".');
expect(result.output.split('\n').filter(line => line.startsWith('%%'))).toEqual([
'%%teardown start',
'%%teardown finished',
@ -431,7 +431,7 @@ test('should not teardown when setup times out', async ({ runInlineTest }) => {
}, { timeout: 1000 });
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.output).toContain('Timeout of 1000ms exceeded');
expect(result.output).toContain('Test timeout of 1000ms exceeded while setting up "fixture".');
expect(result.output.split('\n').filter(line => line.startsWith('%%'))).toEqual([
]);
});
@ -471,10 +471,10 @@ test('should not report fixture teardown timeout twice', async ({ runInlineTest
}, { reporter: 'list', timeout: 1000 });
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.output).toContain('Timeout of 1000ms exceeded while running fixture "fixture" teardown.');
expect(result.output).toContain('Test timeout of 1000ms exceeded while tearing down "fixture".');
expect(stripAnsi(result.output)).not.toContain('pwt.test.extend'); // Should not point to the location.
// TODO: this should be "not.toContain" actually.
expect(result.output).toContain('in fixtures teardown');
expect(result.output).toContain('Worker teardown timeout of 1000ms exceeded.');
});
test('should handle fixture teardown error after test timeout and continue', async ({ runInlineTest }) => {
@ -497,7 +497,7 @@ test('should handle fixture teardown error after test timeout and continue', asy
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.passed).toBe(1);
expect(result.output).toContain('Timeout of 100ms exceeded');
expect(result.output).toContain('Test timeout of 100ms exceeded.');
expect(result.output).toContain('Error: Oh my error');
});
@ -529,6 +529,6 @@ test('should report worker fixture teardown with debug info', async ({ runInline
'a.spec.ts:12:9 good18',
'a.spec.ts:12:9 good19',
'',
'Timeout of 1000ms exceeded while running fixture "fixture" teardown.',
'Worker teardown timeout of 1000ms exceeded.',
].join('\n'));
});

View file

@ -627,7 +627,7 @@ test('should create a new worker for worker fixtures', async ({ runInlineTest })
}, { workers: 1 });
expect(result.output).toContain('foo-a');
expect(result.output).toContain('bar-b');
const baseWorker = +result.output.match(/%%base-(\d)/)[1];
const baseWorker = +result.output.match(/%%base-(\d)/)![1];
expect(result.output).toContain(`%%base-${baseWorker}`);
expect(result.output).toContain(`%%a-${1 - baseWorker}`);
expect(result.output).toContain(`%%b-${baseWorker}`);
@ -709,7 +709,7 @@ test('worker teardown errors reflected in timed-out tests', async ({ runInlineTe
}, { timeout: 1000 });
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.output).toContain('Timeout of 1000ms exceeded.');
expect(result.output).toContain('Test timeout of 1000ms exceeded.');
expect(result.output).toContain('Rejecting!');
});

View file

@ -481,7 +481,7 @@ test('beforeAll timeout should be reported and prevent more tests', async ({ run
'%%beforeAll',
'%%afterAll',
]);
expect(result.output).toContain('Timeout of 1000ms exceeded in beforeAll hook.');
expect(result.output).toContain('"beforeAll" hook timeout of 1000ms exceeded.');
expect(result.output).toContain(`a.test.js:6:12`);
expect(stripAnsi(result.output)).toContain(`> 6 | test.beforeAll(async () => {`);
});
@ -519,7 +519,7 @@ test('afterAll timeout should be reported, run other afterAll hooks, and continu
'%%test2',
'%%afterAll2',
]);
expect(result.output).toContain('Timeout of 1000ms exceeded in afterAll hook.');
expect(result.output).toContain('"afterAll" hook timeout of 1000ms exceeded.');
expect(result.output).toContain(`a.test.js:7:14`);
expect(stripAnsi(result.output)).toContain(`> 7 | test.afterAll(async () => {`);
});
@ -547,7 +547,7 @@ test('beforeAll and afterAll timeouts at the same time should be reported', asyn
'%%beforeAll',
'%%afterAll',
]);
expect(result.output).toContain('Timeout of 1000ms exceeded in beforeAll hook.');
expect(result.output).toContain('"beforeAll" hook timeout of 1000ms exceeded.');
});
test('afterEach should get the test status and duration right away', async ({ runInlineTest }) => {
@ -620,7 +620,7 @@ test('should report error from fixture teardown when beforeAll times out', async
}, { timeout: 1000 });
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(stripAnsi(result.output)).toContain('Timeout of 1000ms exceeded in beforeAll hook.');
expect(stripAnsi(result.output)).toContain('"beforeAll" hook timeout of 1000ms exceeded.');
expect(stripAnsi(result.output)).toContain('Error: Oh my!');
});

View file

@ -87,7 +87,7 @@ test('should allow export default form the config file', async ({ runInlineTest
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.output).toContain('Timeout of 1000ms exceeded.');
expect(result.output).toContain('Test timeout of 1000ms exceeded.');
});
test('should validate configuration object', async ({ runInlineTest }) => {

View file

@ -607,7 +607,7 @@ test('should print expected/received before timeout', async ({ runInlineTest })
expect(result.exitCode).toBe(1);
expect(result.passed).toBe(0);
expect(result.failed).toBe(1);
expect(result.output).toContain('Timeout of 2000ms exceeded.');
expect(result.output).toContain('Test timeout of 2000ms exceeded.');
expect(stripAnsi(result.output)).toContain('Expected string: "Text 2"');
expect(stripAnsi(result.output)).toContain('Received string: "Text content"');
});

View file

@ -389,7 +389,7 @@ test('should report error from beforeAll timeout', async ({ runInlineTest }, tes
expect(result.exitCode).toBe(1);
expect(result.passed).toBe(0);
expect(result.failed).toBe(1);
expect(result.output).toContain('Timeout of 2000ms exceeded in beforeAll hook.');
expect(result.output).toContain('"beforeAll" hook timeout of 2000ms exceeded.');
expect(result.output).toContain('waiting for selector');
expect(stripAnsi(result.output)).toContain(`11 | page.textContent('text=More missing'),`);
});

View file

@ -225,7 +225,7 @@ test('should print flaky timeouts', async ({ runInlineTest }) => {
}, { retries: '1', reporter: 'list', timeout: '1000' });
expect(result.exitCode).toBe(0);
expect(result.flaky).toBe(1);
expect(stripAnsi(result.output)).toContain('Timeout of 1000ms exceeded.');
expect(stripAnsi(result.output)).toContain('Test timeout of 1000ms exceeded.');
});
test('should print stack-less errors', async ({ runInlineTest }) => {

View file

@ -101,7 +101,7 @@ test('test modifiers should work', async ({ runInlineTest }) => {
const expectTest = (title: string, expectedStatus: string, status: string, annotations: any) => {
const spec = result.report.suites[0].specs.find(s => s.title === title) ||
result.report.suites[0].suites.find(s => s.specs[0].title === title).specs[0];
result.report.suites[0].suites!.find(s => s.specs[0].title === title)!.specs[0];
const test = spec.tests[0];
expect(test.expectedStatus).toBe(expectedStatus);
expect(test.results[0].status).toBe(status);
@ -263,8 +263,8 @@ test('test.skip with worker fixtures only should skip before hooks and tests', a
expect(result.passed).toBe(1);
expect(result.skipped).toBe(2);
expect(result.report.suites[0].specs[0].tests[0].annotations).toEqual([]);
expect(result.report.suites[0].suites[0].specs[0].tests[0].annotations).toEqual([{ type: 'skip', description: 'reason' }]);
expect(result.report.suites[0].suites[0].suites[0].specs[0].tests[0].annotations).toEqual([{ type: 'skip', description: 'reason' }]);
expect(result.report.suites[0].suites![0].specs[0].tests[0].annotations).toEqual([{ type: 'skip', description: 'reason' }]);
expect(result.report.suites[0].suites![0].suites![0].specs[0].tests[0].annotations).toEqual([{ type: 'skip', description: 'reason' }]);
expect(result.output.split('\n').filter(line => line.startsWith('%%'))).toEqual([
'%%beforeEach',
'%%passed',
@ -297,7 +297,7 @@ test('test.skip without a callback in describe block should skip hooks', async (
expect(result.exitCode).toBe(0);
expect(result.skipped).toBe(2);
expect(result.report.suites[0].specs[0].tests[0].annotations).toEqual([{ type: 'skip', description: 'reason' }]);
expect(result.report.suites[0].suites[0].specs[0].tests[0].annotations).toEqual([{ type: 'skip', description: 'reason' }]);
expect(result.report.suites[0].suites![0].specs[0].tests[0].annotations).toEqual([{ type: 'skip', description: 'reason' }]);
expect(result.output).not.toContain('%%');
});
@ -330,7 +330,7 @@ test('modifier timeout should be reported', async ({ runInlineTest }) => {
}, { timeout: 2000 });
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.output).toContain('Timeout of 2000ms exceeded in skip modifier.');
expect(result.output).toContain('"skip" modifier timeout of 2000ms exceeded.');
expect(stripAnsi(result.output)).toContain('6 | test.skip(async () => new Promise(() => {}));');
});

View file

@ -65,7 +65,7 @@ test('should respect test.setTimeout', async ({ runInlineTest }) => {
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.passed).toBe(2);
expect(result.output).toContain('Timeout of 1000ms exceeded');
expect(result.output).toContain('Test timeout of 1000ms exceeded.');
});
test('should respect test.setTimeout outside of the test', async ({ runInlineTest }) => {
@ -94,7 +94,7 @@ test('should respect test.setTimeout outside of the test', async ({ runInlineTes
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(2);
expect(result.passed).toBe(2);
expect(result.output).toContain('Timeout of 500ms exceeded');
expect(result.output).toContain('Test timeout of 500ms exceeded.');
});
test('should timeout when calling test.setTimeout too late', async ({ runInlineTest }) => {
@ -111,7 +111,7 @@ test('should timeout when calling test.setTimeout too late', async ({ runInlineT
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.passed).toBe(0);
expect(result.output).toContain('Timeout of 100ms exceeded');
expect(result.output).toContain('Test timeout of 100ms exceeded.');
});
test('should respect test.slow', async ({ runInlineTest }) => {
@ -138,7 +138,7 @@ test('should respect test.slow', async ({ runInlineTest }) => {
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.passed).toBe(2);
expect(result.output).toContain('Timeout of 1000ms exceeded');
expect(result.output).toContain('Test timeout of 1000ms exceeded.');
});
test('should ignore test.setTimeout when debugging', async ({ runInlineTest }) => {
@ -196,8 +196,8 @@ test('should respect fixture timeout', async ({ runInlineTest }) => {
expect(result.exitCode).toBe(1);
expect(result.passed).toBe(1);
expect(result.failed).toBe(2);
expect(result.output).toContain('Timeout of 500ms exceeded by fixture "custom title" setup.');
expect(result.output).toContain('Timeout of 400ms exceeded by fixture "slowTeardown" teardown.');
expect(result.output).toContain('Fixture "custom title" timeout of 500ms exceeded.');
expect(result.output).toContain('Fixture "slowTeardown" timeout of 400ms exceeded.');
expect(stripAnsi(result.output)).toContain('> 5 | const test = pwt.test.extend({');
});
@ -236,8 +236,8 @@ test('should respect test.setTimeout in the worker fixture', async ({ runInlineT
expect(result.exitCode).toBe(1);
expect(result.passed).toBe(2);
expect(result.failed).toBe(1);
expect(result.output).toContain('Timeout of 500ms exceeded by fixture "slowSetup" setup.');
expect(result.output).toContain('Timeout of 400ms exceeded by fixture "custom title" teardown.');
expect(result.output).toContain('Fixture "slowSetup" timeout of 500ms exceeded.');
expect(result.output).toContain('Fixture "custom title" timeout of 400ms exceeded.');
});
test('fixture time in beforeAll hook should not affect test', async ({ runInlineTest }) => {
@ -304,7 +304,7 @@ test('fixture time in beforeEach hook should affect test', async ({ runInlineTes
});
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.output).toContain('Timeout of 1000ms exceeded');
expect(result.output).toContain('Test timeout of 1000ms exceeded.');
});
test('test timeout should still run hooks before fixtures teardown', async ({ runInlineTest }) => {
@ -331,7 +331,7 @@ test('test timeout should still run hooks before fixtures teardown', async ({ ru
});
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.output).toContain('Timeout of 100ms exceeded');
expect(result.output).toContain('Test timeout of 100ms exceeded.');
expect(result.output.split('\n').filter(line => line.startsWith('%%'))).toEqual([
'%%before-auto',
'%%test',