From 70eca0401d12f3048d59a9194c9ee10847498a45 Mon Sep 17 00:00:00 2001 From: Dmitry Gozman Date: Thu, 19 Aug 2021 17:04:09 -0700 Subject: [PATCH] fix(test runner): avoid internal error for step end without begin (#8327) fix(test runner): avoid internal error for step end without begin Consider the following scenario: - Test finishes and starts tearing down fixtures. - Fixture teardown starts a step S and then times out. - We declare the test finished (with timeout). - Dispatcher shuts down the worker and spins a new one for a retry. Additionally, it clears steps information for the test to be ready for the new retry. Step S information is lost. - Meanwhile, during worker teardown, the step S does actually finish (usually with an error), and we send stepEnd for S. - Dispatcher does not know what to do with step S end and prints an internal error. The fix is to ignore certain messages from the shutting down worker that failed. --- src/test/dispatcher.ts | 36 ++++++++++++++++++++++++++ tests/playwright-test/reporter.spec.ts | 24 ++++++++++++++++- 2 files changed, 59 insertions(+), 1 deletion(-) diff --git a/src/test/dispatcher.ts b/src/test/dispatcher.ts index 2610722c66..3d55c9451e 100644 --- a/src/test/dispatcher.ts +++ b/src/test/dispatcher.ts @@ -124,6 +124,7 @@ export class Dispatcher { // When worker encounters error, we will stop it and create a new one. worker.stop(); + worker.didFail = true; const retryCandidates = new Set(); @@ -255,6 +256,11 @@ export class Dispatcher { _createWorker(testGroup: TestGroup) { const worker = new Worker(this); worker.on('testBegin', (params: TestBeginPayload) => { + if (worker.didFail) { + // Ignore test-related messages from failed workers, because timed out tests/fixtures + // may be triggering unexpected messages. + return; + } if (this._hasReachedMaxFailures()) return; const { test, result: testRun } = this._testById.get(params.testId)!; @@ -263,6 +269,11 @@ export class Dispatcher { this._reporter.onTestBegin?.(test, testRun); }); worker.on('testEnd', (params: TestEndPayload) => { + if (worker.didFail) { + // Ignore test-related messages from failed workers, because timed out tests/fixtures + // may be triggering unexpected messages. + return; + } if (this._hasReachedMaxFailures()) return; const { test, result } = this._testById.get(params.testId)!; @@ -281,6 +292,11 @@ export class Dispatcher { this._reportTestEnd(test, result); }); worker.on('stepBegin', (params: StepBeginPayload) => { + if (worker.didFail) { + // Ignore test-related messages from failed workers, because timed out tests/fixtures + // may be triggering unexpected messages. + return; + } const { test, result, steps, stepStack } = this._testById.get(params.testId)!; const parentStep = [...stepStack].pop(); const step: TestStep = { @@ -301,6 +317,11 @@ export class Dispatcher { this._reporter.onStepBegin?.(test, result, step); }); worker.on('stepEnd', (params: StepEndPayload) => { + if (worker.didFail) { + // Ignore test-related messages from failed workers, because timed out tests/fixtures + // may be triggering unexpected messages. + return; + } const { test, result, steps, stepStack } = this._testById.get(params.testId)!; const step = steps.get(params.stepId); if (!step) { @@ -316,6 +337,13 @@ export class Dispatcher { }); worker.on('stdOut', (params: TestOutputPayload) => { const chunk = chunkFromParams(params); + if (worker.didFail) { + // Note: we keep reading stdout from workers that are currently stopping after failure, + // to debug teardown issues. However, we avoid spoiling the test result from + // the next retry. + this._reporter.onStdOut?.(chunk); + return; + } const pair = params.testId ? this._testById.get(params.testId) : undefined; if (pair) pair.result.stdout.push(chunk); @@ -323,6 +351,13 @@ export class Dispatcher { }); worker.on('stdErr', (params: TestOutputPayload) => { const chunk = chunkFromParams(params); + if (worker.didFail) { + // Note: we keep reading stderr from workers that are currently stopping after failure, + // to debug teardown issues. However, we avoid spoiling the test result from + // the next retry. + this._reporter.onStdErr?.(chunk); + return; + } const pair = params.testId ? this._testById.get(params.testId) : undefined; if (pair) pair.result.stderr.push(chunk); @@ -381,6 +416,7 @@ class Worker extends EventEmitter { hash = ''; index: number; didSendStop = false; + didFail = false; constructor(runner: Dispatcher) { super(); diff --git a/tests/playwright-test/reporter.spec.ts b/tests/playwright-test/reporter.spec.ts index 5c8d137c97..e2b7acda24 100644 --- a/tests/playwright-test/reporter.spec.ts +++ b/tests/playwright-test/reporter.spec.ts @@ -373,6 +373,28 @@ test('should report test.step', async ({ runInlineTest }) => { ]); }); +test('should not have internal error when steps are finished after timeout', async ({ runInlineTest }) => { + const result = await runInlineTest({ + 'a.test.ts': ` + const test = pwt.test.extend({ + page: async ({ page }, use) => { + await use(page); + // Timeout in fixture teardown that will resolve on browser.close. + await page.waitForNavigation(); + }, + }); + test('pass', async ({ page }) => { + // Timeout in the test. + await page.click('foo'); + }); + ` + }, { workers: 1, timeout: 1000, reporter: 'dot', retries: 1 }); + + expect(result.exitCode).toBe(1); + expect(result.failed).toBe(1); + expect(result.output).not.toContain('Internal error'); +}); + test('should report api step hierarchy', async ({ runInlineTest }) => { const expectReporterJS = ` class Reporter { @@ -389,7 +411,7 @@ test('should report api step hierarchy', async ({ runInlineTest }) => { steps: step.steps.length ? step.steps.map(s => this.distillStep(s)) : undefined, }; } - + async onEnd() { const processSuite = (suite: Suite) => { for (const child of suite.suites)