fix(test runner): timeout in fixture teardown should not prevent other slots (#32157)

When two fixtures have different time slots, timeout in the first one
should not prevent the second one from tearing down.

Similarly, timeout in afterEach hook should not prevent fixture
teardowns.
This commit is contained in:
Dmitry Gozman 2024-08-16 04:25:00 -07:00 committed by GitHub
parent 06ffdd61c9
commit e17d1c498b
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
5 changed files with 154 additions and 66 deletions

View file

@ -17,7 +17,7 @@
import { formatLocation, filterStackFile } from '../util';
import { ManualPromise } from 'playwright-core/lib/utils';
import type { TestInfoImpl } from './testInfo';
import { TimeoutManagerError, type FixtureDescription, type RunnableDescription } from './timeoutManager';
import { type FixtureDescription, type RunnableDescription } from './timeoutManager';
import { fixtureParameterNames, type FixturePool, type FixtureRegistration, type FixtureScope } from '../common/fixtures';
import type { WorkerInfo } from '../../types/test';
import type { Location } from '../../types/testReporter';
@ -125,19 +125,31 @@ class Fixture {
}
async teardown(testInfo: TestInfoImpl, runnable: RunnableDescription) {
try {
const fixtureRunnable = { ...runnable, fixture: this._teardownDescription };
// Do not even start the teardown for a fixture that does not have any
// time remaining in the time slot. This avoids cascading timeouts.
if (!testInfo._timeoutManager.isTimeExhaustedFor(fixtureRunnable)) {
await testInfo._runAsStage({
title: `fixture: ${this.registration.name}`,
runnable: { ...runnable, fixture: this._teardownDescription },
runnable: fixtureRunnable,
stepInfo: this._stepInfo,
}, async () => {
await this._teardownInternal();
});
}
} finally {
// To preserve fixtures integrity, forcefully cleanup fixtures
// that cannnot teardown due to a timeout or an error.
for (const dep of this._deps)
dep._usages.delete(this);
this.runner.instanceForId.delete(this.registration.id);
}
}
private async _teardownInternal() {
if (typeof this.registration.fn !== 'function')
return;
try {
if (this._usages.size !== 0) {
// TODO: replace with assert.
console.error('Internal error: fixture integrity at', this._teardownDescription.title); // eslint-disable-line no-console
@ -148,15 +160,6 @@ class Fixture {
this._useFuncFinished = undefined;
await this._selfTeardownComplete;
}
} finally {
this._cleanupInstance();
}
}
_cleanupInstance() {
for (const dep of this._deps)
dep._usages.delete(this);
this.runner.instanceForId.delete(this.registration.id);
}
_collectFixturesInTeardownOrder(scope: FixtureScope, collector: Set<Fixture>) {
@ -203,27 +206,18 @@ export class FixtureRunner {
const collector = new Set<Fixture>();
for (const fixture of fixtures)
fixture._collectFixturesInTeardownOrder(scope, collector);
try {
let firstError: Error | undefined;
for (const fixture of collector) {
try {
await fixture.teardown(testInfo, runnable);
} catch (error) {
if (error instanceof TimeoutManagerError)
throw error;
firstError = firstError ?? error;
}
}
if (firstError)
throw firstError;
} finally {
// To preserve fixtures integrity, forcefully cleanup fixtures that did not teardown
// due to a timeout in one of them.
for (const fixture of collector)
fixture._cleanupInstance();
if (scope === 'test')
this.testScopeClean = true;
}
if (firstError)
throw firstError;
}
async resolveParametersForFunction(fn: Function, testInfo: TestInfoImpl, autoFixtures: 'worker' | 'test' | 'all-hooks-only', runnable: RunnableDescription): Promise<object | null> {

View file

@ -67,6 +67,12 @@ export class TimeoutManager {
this._running.timeoutPromise.reject(this._createTimeoutError(this._running));
}
isTimeExhaustedFor(runnable: RunnableDescription) {
const slot = runnable.fixture?.slot || runnable.slot || this._defaultSlot;
// Note: the "-1" here matches the +1 in _updateTimeout.
return slot.timeout > 0 && (slot.elapsed >= slot.timeout - 1);
}
async withRunnable<T>(runnable: RunnableDescription | undefined, cb: () => Promise<T>): Promise<T> {
if (!runnable)
return await cb();
@ -104,7 +110,10 @@ export class TimeoutManager {
return;
}
running.deadline = running.start + (running.slot.timeout - running.slot.elapsed);
const timeout = running.deadline - monotonicTime();
// Compensate for Node.js troubles with timeouts that can fire too early.
// We add an extra millisecond which seems to be enough.
// See https://github.com/nodejs/node/issues/26578.
const timeout = running.deadline - monotonicTime() + 1;
if (timeout <= 0)
running.timeoutPromise.reject(this._createTimeoutError(running));
else

View file

@ -31,7 +31,7 @@ import { PoolBuilder } from '../common/poolBuilder';
import type { TestInfoError } from '../../types/test';
import type { Location } from '../../types/testReporter';
import { inheritFixtureNames } from '../common/fixtures';
import { type TimeSlot, TimeoutManagerError } from './timeoutManager';
import { type TimeSlot } from './timeoutManager';
export class WorkerMain extends ProcessRunner {
private _params: WorkerInitParams;
@ -368,36 +368,27 @@ export class WorkerMain extends ProcessRunner {
const afterHooksSlot = { timeout: afterHooksTimeout, elapsed: 0 };
await testInfo._runAsStage({ title: 'After Hooks', stepInfo: { category: 'hook' } }, async () => {
let firstAfterHooksError: Error | undefined;
let didTimeoutInAfterHooks = false;
try {
// Run "immediately upon test function finish" callback.
await testInfo._runAsStage({ title: 'on-test-function-finish', runnable: { type: 'test', slot: afterHooksSlot } }, async () => testInfo._onDidFinishTestFunction?.());
} catch (error) {
if (error instanceof TimeoutManagerError)
didTimeoutInAfterHooks = true;
firstAfterHooksError = firstAfterHooksError ?? error;
}
try {
// Run "afterEach" hooks, unless we failed at beforeAll stage.
if (!didTimeoutInAfterHooks && shouldRunAfterEachHooks)
if (shouldRunAfterEachHooks)
await this._runEachHooksForSuites(reversedSuites, 'afterEach', testInfo, afterHooksSlot);
} catch (error) {
if (error instanceof TimeoutManagerError)
didTimeoutInAfterHooks = true;
firstAfterHooksError = firstAfterHooksError ?? error;
}
try {
if (!didTimeoutInAfterHooks) {
// Teardown test-scoped fixtures. Attribute to 'test' so that users understand
// they should probably increase the test timeout to fix this issue.
await this._fixtureRunner.teardownScope('test', testInfo, { type: 'test', slot: afterHooksSlot });
}
} catch (error) {
if (error instanceof TimeoutManagerError)
didTimeoutInAfterHooks = true;
firstAfterHooksError = firstAfterHooksError ?? error;
}
@ -559,14 +550,16 @@ export class WorkerMain extends ProcessRunner {
let firstError: Error | undefined;
const hooks = suites.map(suite => this._collectHooksAndModifiers(suite, type, testInfo)).flat();
for (const hook of hooks) {
const runnable = { type: hook.type, location: hook.location, slot };
if (testInfo._timeoutManager.isTimeExhaustedFor(runnable)) {
// Do not run hooks that will timeout right away.
continue;
}
try {
await testInfo._runAsStage({ title: hook.title, stepInfo: { category: 'hook', location: hook.location } }, async () => {
const runnable = { type: hook.type, location: hook.location, slot };
await this._fixtureRunner.resolveParametersAndRunFunction(hook.fn, testInfo, 'test', runnable);
});
} catch (error) {
if (error instanceof TimeoutManagerError)
throw error;
firstError = firstError ?? error;
// Skip in modifier prevents others from running.
if (error instanceof SkipError)

View file

@ -625,7 +625,31 @@ test('uncaught error in beforeEach should not be masked by another error', async
expect(result.output).toContain('Received: 1');
});
test('should report error from fixture teardown when beforeAll times out', async ({ runInlineTest }) => {
test('should report error from worker fixture teardown when beforeAll times out', async ({ runInlineTest }) => {
const result = await runInlineTest({
'a.test.js': `
import { test as base, expect } from '@playwright/test';
const test = base.extend({
foo: [async ({}, use) => {
let cb;
await use(new Promise((f, r) => cb = r));
cb(new Error('Oh my!'));
}, { scope: 'worker' }],
});
test.beforeAll(async ({ foo }, testInfo) => {
await foo;
});
test('passing', () => {
});
`,
}, { timeout: 1000 });
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.output).toContain('"beforeAll" hook timeout of 1000ms exceeded.');
expect(result.output).toContain('Error: Oh my!');
});
test('should not report error from test fixture teardown when beforeAll times out', async ({ runInlineTest }) => {
const result = await runInlineTest({
'a.test.js': `
import { test as base, expect } from '@playwright/test';
@ -646,7 +670,7 @@ test('should report error from fixture teardown when beforeAll times out', async
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.output).toContain('"beforeAll" hook timeout of 1000ms exceeded.');
expect(result.output).toContain('Error: Oh my!');
expect(result.output).not.toContain('Error: Oh my!');
});
test('should not hang and report results when worker process suddenly exits during afterAll', async ({ runInlineTest }) => {

View file

@ -559,6 +559,74 @@ test('should allow custom worker fixture timeout longer than force exit cap', as
expect(result.output).toContain(`1 error was not a part of any test, see above for details`);
});
test('should run fixture teardown with custom timeout after test timeout', {
annotation: { type: 'issue', description: 'https://github.com/microsoft/playwright/issues/31537' },
}, async ({ runInlineTest }) => {
const result = await runInlineTest({
'a.spec.ts': `
import { test as base, expect } from '@playwright/test';
const test = base.extend({
foo: [async ({}, use) => {
console.log('\\n%%foo setup');
await use('foo');
console.log('\\n%%foo teardown');
}, { timeout: 2000 }],
});
test('times out', async ({ foo }) => {
console.log('\\n%%test start');
await new Promise(() => {});
console.log('\\n%%test end');
});
`
}, { timeout: 2000 });
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.outputLines).toEqual([
'foo setup',
'test start',
'foo teardown',
]);
});
test('should run fixture teardown with custom timeout after afterEach timeout', async ({ runInlineTest }) => {
const result = await runInlineTest({
'a.spec.ts': `
import { test as base, expect } from '@playwright/test';
let counter = 0;
const test = base.extend({
foo: [async ({}, use) => {
console.log('\\n%%foo setup');
await use('foo' + (++counter));
console.log('\\n%%foo teardown');
}, { timeout: 2000 }],
});
test.afterEach(async () => {
console.log('\\n%%afterEach start');
await new Promise(() => {});
console.log('\\n%%afterEach end');
});
test.afterAll(async ({ foo }) => {
// Note: afterAll should receive a new instance of the "foo" fixture.
console.log('\\n%%afterAll - ' + foo);
});
test('times out', async ({ foo }) => {
console.log('\\n%%test - ' + foo);
});
`
}, { timeout: 2000 });
expect(result.exitCode).toBe(1);
expect(result.failed).toBe(1);
expect(result.outputLines).toEqual([
'foo setup',
'test - foo1',
'afterEach start',
'foo teardown',
'foo setup',
'afterAll - foo2',
'foo teardown',
]);
});
test('test.setTimeout should be able to change custom fixture timeout', async ({ runInlineTest }) => {
const result = await runInlineTest({
'a.spec.ts': `