diff --git a/.changeset/pr-267.md b/.changeset/pr-267.md new file mode 100644 index 00000000..353d83a6 --- /dev/null +++ b/.changeset/pr-267.md @@ -0,0 +1,5 @@ +--- +"@wdio/browserstack-service": patch +--- + +- Fixed builds ending as "timeout" in Test Reporting, about an hour after the run, when a mocha test failed by exceeding its timeout (especially with `bail`). The timed-out test is now reported as failed, and the build closes when the run ends. diff --git a/packages/browserstack-service/src/cli/modules/testHubModule.ts b/packages/browserstack-service/src/cli/modules/testHubModule.ts index 5026bdaa..5f97c1c0 100644 --- a/packages/browserstack-service/src/cli/modules/testHubModule.ts +++ b/packages/browserstack-service/src/cli/modules/testHubModule.ts @@ -27,6 +27,16 @@ export default class TestHubModule extends BaseModule { name: string static MODULE_NAME = 'TestHubModule' + /** + * SDK-7843: how long service.after() waits for late test finishes to ARRIVE (see + * awaitLateTestFinishes). It does not bound the sends themselves, which keep their own + * retry/backoff in flushPendingTestFinishEvent. + */ + static readonly LATE_TEST_FINISH_WAIT_MS = 5000 + + /** Failure reason on a TestRunFinished synthesised for a test that never reported one. */ + static readonly INCOMPLETE_TEST_REASON = 'Test did not finish before the session ended (incomplete).' + /** * Mocha-only: the TEST/POST (TestRunFinished) send deferred past the after-each hook * window. WDIO fires `afterTest` (which triggers TEST/POST) BEFORE the user's @@ -56,6 +66,32 @@ export default class TestHubModule extends BaseModule { */ private pendingTestFinishes: Map, uuid: string }> = new Map() + /** + * SDK-7843: set by service.after() once it has run the worker's final flush. A mocha test + * that hits its timeout keeps running after mocha moves on, so its `afterTest` (and so its + * TEST/POST) can land AFTER that flush — with `bail` it routinely does. Deferring it then + * strands it: there is no next test and no later flush, the TestRunFinished is never sent, + * and Test Hub reaps the build as `timeout` ~60 min later. Past this point a finish is sent + * immediately instead. + */ + private workerEnding = false + + /** + * Tests whose TEST/PRE was seen but whose TEST/POST has not arrived yet, keyed by uuid, with + * the PRE `args` so a finish can be synthesised for one that never reports (SDK-7843). The + * stored `args.instance` is that test's own object, see pendingTestFinishes. + */ + private openTests: Map> = new Map() + + /** Late work (an afterTest that started after workerEnding, with its bail cascade). */ + private lateWork: Set> = new Set() + + /** Finishes sent after workerEnding, which service.after() awaits before teardown. */ + private lateFinishSends: Set> = new Set() + + /** Tests closed with a synthetic finish; a straggling real TEST/POST for them is dropped. */ + private syntheticallyClosed: Set = new Set() + /** * Create a new TestHubModule */ @@ -131,6 +167,19 @@ export default class TestHubModule extends BaseModule { if (testState === TestFrameworkState.TEST || CLIUtils.matchHookRegex(testState.toString().split('.')[1])) { const frameworkName = String(TestFramework.getState(instance, TestFrameworkConstants.KEY_TEST_FRAMEWORK_NAME) || '') + const testUuid = TestFramework.getState(instance, TestFrameworkConstants.KEY_TEST_UUID) + if (testUuid && testState === TestFrameworkState.TEST) { + if (hookState === HookState.PRE) { + this.openTests.set(String(testUuid), args) + } else if (hookState === HookState.POST) { + if (this.syntheticallyClosed.has(String(testUuid))) { + // Already closed at teardown; a second finish would contradict it. + this.logger.debug(`onAllTestEvents: dropping TEST/POST for a test already closed as incomplete (uuid=${testUuid})`) + return + } + this.openTests.delete(String(testUuid)) + } + } if (testState === TestFrameworkState.TEST && hookState === HookState.POST && frameworkName.toLowerCase().includes('mocha')) { // Defer the TestRunFinished send past the Mocha after-each hook window so // custom tags set in `afterEach` still make the payload (see field docs). @@ -143,13 +192,88 @@ export default class TestHubModule extends BaseModule { TestFramework.getState(instance, TestFrameworkConstants.KEY_TEST_UUID) || instance.getRef() ) this.pendingTestFinishes.set(deferUuid, { args, uuid: deferUuid }) - this.logger.debug(`onAllTestEvents: deferred TEST/POST send past the after-each hook window (uuid=${deferUuid}, pending=${this.pendingTestFinishes.size})`) + if (this.workerEnding) { + // The worker's final flush already ran; nothing would ever send this stash. + this.logger.debug(`onAllTestEvents: TEST/POST arrived after the worker's final flush, sending now (uuid=${deferUuid})`) + const send = this.flushPendingTestFinishEvent() + if (send) { + this.trackIn(this.lateFinishSends, send) + } + } else { + this.logger.debug(`onAllTestEvents: deferred TEST/POST send past the after-each hook window (uuid=${deferUuid}, pending=${this.pendingTestFinishes.size})`) + } } else { this.sendTestFrameworkEvent(args) } } } + /** + * Worker end, step 1 (start of service.after()): flush the deferred finish of the worker's + * last test and switch to sending any later TEST/POST immediately (SDK-7843). + */ + finishWorker(): Promise | undefined { + this.workerEnding = true + return this.flushPendingTestFinishEvent() + } + + /** + * Register work that has to finish before the worker tears down. Only tracked once the + * worker is ending: service.afterTest passes its whole CLI branch, so a late afterTest's + * bail cascade (skip reports after the timed-out test's own TEST/POST) is waited for too. + */ + trackLateWork(work: Promise): Promise { + if (this.workerEnding) { + this.trackIn(this.lateWork, work) + } + return work + } + + /** + * Worker end, step 2 (end of service.after(), before teardown). A test that timed out is + * still running when after() starts; its afterTest (TEST/POST, then any bail cascade) lands + * while after() is in progress. Wait, up to the bound, until every started test has + * reported, late afterTest work has settled and late sends have landed. Any test still open + * after that is closed with a synthetic failed finish, as the classic path's + * sweepUnfinished() does, so the build is not left to Test Hub's ~60-min idle reap. + */ + async awaitLateTestFinishes(waitMs: number = TestHubModule.LATE_TEST_FINISH_WAIT_MS): Promise { + const deadline = Date.now() + waitMs + while ((this.openTests.size > 0 || this.lateWork.size > 0 || this.lateFinishSends.size > 0) && Date.now() < deadline) { + await new Promise((resolve) => setTimeout(resolve, 50)) + } + if (this.openTests.size > 0) { + this.logger.debug(`awaitLateTestFinishes: no TEST/POST within ${waitMs}ms for ${[...this.openTests.keys()].join(', ')}; closing as incomplete`) + this.closeOpenTestsAsIncomplete() + } + await Promise.all([...this.lateFinishSends]) + } + + private closeOpenTestsAsIncomplete() { + const reason = TestHubModule.INCOMPLETE_TEST_REASON + for (const [uuid, args] of this.openTests) { + const instance = args.instance as TestFrameworkInstance + instance.updateMultipleEntries({ + [TestFrameworkConstants.KEY_TEST_RESULT]: 'failed', + [TestFrameworkConstants.KEY_TEST_FAILURE]: [{ backtrace: [reason] }], + [TestFrameworkConstants.KEY_TEST_FAILURE_REASON]: reason, + [TestFrameworkConstants.KEY_TEST_FAILURE_TYPE]: 'UnhandledError', + [TestFrameworkConstants.KEY_TEST_ENDED_AT]: new Date().toISOString() + }) + this.syntheticallyClosed.add(uuid) + this.trackIn(this.lateFinishSends, this.sendTestFrameworkEvent(args, { testFrameworkState: 'TEST', testHookState: 'POST', uuid })) + } + this.openTests.clear() + } + + private trackIn(set: Set>, work: Promise) { + set.add(work) + const untrack = () => { + set.delete(work) + } + work.then(untrack, untrack) + } + /** * Send a deferred TEST/POST (TestRunFinished) event, if one is pending. The instance's * CURRENT state may have moved on (e.g. LOG events during afterEach), so the send uses diff --git a/packages/browserstack-service/src/service.ts b/packages/browserstack-service/src/service.ts index 8854e15c..8222d778 100644 --- a/packages/browserstack-service/src/service.ts +++ b/packages/browserstack-service/src/service.ts @@ -671,9 +671,15 @@ export default class BrowserstackService implements Services.ServiceInstance { this._cliTestUuids.delete(identifier) } } - await BrowserstackCLI.getInstance().getTestFramework()!.trackEvent(TestFrameworkState.LOG_REPORT, HookState.POST, { test, result: results }) - await BrowserstackCLI.getInstance().getTestFramework()!.trackEvent(TestFrameworkState.TEST, HookState.POST, { test, result: results, suiteTitle: this._suiteTitle }) - await this.reportBailSkippedTests(test, results) + const finish = async () => { + await BrowserstackCLI.getInstance().getTestFramework()!.trackEvent(TestFrameworkState.LOG_REPORT, HookState.POST, { test, result: results }) + await BrowserstackCLI.getInstance().getTestFramework()!.trackEvent(TestFrameworkState.TEST, HookState.POST, { test, result: results, suiteTitle: this._suiteTitle }) + await this.reportBailSkippedTests(test, results) + } + // SDK-7843: a timed-out test's afterTest can run while after() is already tearing + // down; register it so after() waits for its finish AND its bail cascade. + const testHubModule = BrowserstackCLI.getInstance().modules?.TestHubModule as TestHubModule | undefined + await (testHubModule ? testHubModule.trackLateWork(finish()) : finish()) return } @@ -766,10 +772,11 @@ export default class BrowserstackService implements Services.ServiceInstance { } // Flush a test-finish event deferred past the after-each hook window — the last // test of the worker has no next-test boundary to trigger the flush. Must run - // before worker teardown so the event isn't dropped. + // before worker teardown so the event isn't dropped. finishWorker() also makes any + // TEST/POST that lands later in after() (a timed-out test) send immediately. try { const testHubModule = BrowserstackCLI.getInstance().modules.TestHubModule as TestHubModule | undefined - await testHubModule?.flushPendingTestFinishEvent() + await testHubModule?.finishWorker() } catch (flushErr) { BStackLogger.debug(`Exception flushing deferred test finish in after(): ${util.format(flushErr)}`) } @@ -850,6 +857,17 @@ export default class BrowserstackService implements Services.ServiceInstance { } catch (sweepErr) { BStackLogger.debug('Exception in sweepUnfinished during after(): ' + util.format(sweepErr)) } + // CLI counterpart (SDK-7843): a mocha test that timed out reports its TEST/POST only + // once its still-running body settles, which is after the finishWorker() flush above. + // Give it a bounded window to land and be sent before the worker tears down. + if (BrowserstackCLI.getInstance().isRunning()) { + try { + const testHubModule = BrowserstackCLI.getInstance().modules.TestHubModule as TestHubModule | undefined + await testHubModule?.awaitLateTestFinishes() + } catch (lateErr) { + BStackLogger.debug(`Exception awaiting late test finishes in after(): ${util.format(lateErr)}`) + } + } // The sweep closes the _tests entries, but the CLI uuid snapshots (_cliTestUuids) are // only drained in afterTest — the callback that never fires for a test the sweep just // handled (e.g. one that timed out). Clear them here at per-worker teardown so stale diff --git a/packages/browserstack-service/tests/cli/modules/testHubModule.lateFinish.test.ts b/packages/browserstack-service/tests/cli/modules/testHubModule.lateFinish.test.ts new file mode 100644 index 00000000..08ac7e21 --- /dev/null +++ b/packages/browserstack-service/tests/cli/modules/testHubModule.lateFinish.test.ts @@ -0,0 +1,205 @@ +import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest' +import TestHubModule from '../../../src/cli/modules/testHubModule.js' +import TestFramework from '../../../src/cli/frameworks/testFramework.js' +import { TestFrameworkState } from '../../../src/cli/states/testFrameworkState.js' +import { HookState } from '../../../src/cli/states/hookState.js' +import { GrpcClient } from '../../../src/cli/grpcClient.js' +import { TestFrameworkConstants } from '../../../src/cli/frameworks/constants/testFrameworkConstants.js' +import type { Frameworks } from '@wdio/types' + +vi.mock('../../../src/cli/frameworks/testFramework.js', () => ({ + default: { + registerObserver: vi.fn(), + getTrackedInstance: vi.fn(), + getState: vi.fn(), + setState: vi.fn(), + hasState: vi.fn() + } +})) + +vi.mock('../../../src/cli/frameworks/automationFramework.js', () => ({ + default: { getTrackedInstance: vi.fn(), getState: vi.fn(), getDriver: vi.fn() } +})) + +vi.mock('../../../src/cli/grpcClient.js', () => ({ + GrpcClient: { getInstance: vi.fn() } +})) + +vi.mock('../../../src/cli/frameworks/wdioMochaTestFramework.js', () => ({ + default: { getLogEntries: vi.fn(), clearLogs: vi.fn() } +})) + +vi.mock('../../../src/cli/cliLogger.js', () => ({ + BStackLogger: { debug: vi.fn(), info: vi.fn(), error: vi.fn(), warn: vi.fn() } +})) + +// A mock mocha TestFrameworkInstance whose TEST state/hook can be moved PRE -> POST. +function makeMochaTestInstance(uuid: string) { + const state = { test: TestFrameworkState.TEST, hook: HookState.PRE } + return { + __uuid: uuid, + getContext: () => ({ + getId: () => 'ctx', + getThreadId: () => 'thread-1', + getProcessId: () => 'proc-1' + }), + getAllData: () => new Map([ + [TestFrameworkConstants.KEY_TEST_FRAMEWORK_NAME, 'WebdriverIO-mocha'], + [TestFrameworkConstants.KEY_TEST_FRAMEWORK_VERSION, '9.33.1'], + [TestFrameworkConstants.KEY_TEST_STARTED_AT, '2026-08-10T20:53:00Z'], + [TestFrameworkConstants.KEY_TEST_ENDED_AT, '2026-08-10T20:53:02Z'] + ]), + getRef: () => `ref-${uuid}`, + updateMultipleEntries: vi.fn(), + getCurrentTestState: () => state.test, + getCurrentHookState: () => state.hook, + state + } +} + +const sendsFor = (grpc: { testFrameworkEvent: ReturnType }, uuid: string, hook: string) => + grpc.testFrameworkEvent.mock.calls.filter(([p]: any[]) => p.uuid === uuid && p.testHookState === hook).length + +describe('TestHubModule — a TEST/POST that lands after the worker\'s final flush (SDK-7843)', () => { + let testHubModule: TestHubModule + let mockGrpcClient: { testFrameworkEvent: ReturnType } + + beforeEach(() => { + vi.clearAllMocks() + process.env.WDIO_WORKER_ID = '0-1' + mockGrpcClient = { testFrameworkEvent: vi.fn().mockResolvedValue({ success: true }) } + vi.mocked(GrpcClient.getInstance).mockReturnValue(mockGrpcClient as never) + vi.mocked(TestFramework.hasState).mockReturnValue(true) + vi.mocked(TestFramework.getState).mockImplementation((instance: any, key: unknown) => { + if (key === TestFrameworkConstants.KEY_TEST_FRAMEWORK_NAME) { + return 'WebdriverIO-mocha' + } + if (key === TestFrameworkConstants.KEY_TEST_DEFERRED) { + return false + } + if (key === TestFrameworkConstants.KEY_TEST_UUID) { + return instance?.__uuid + } + return '' + }) + testHubModule = new TestHubModule({ enabled: true }) + }) + + afterEach(() => { + delete process.env.WDIO_WORKER_ID + }) + + const emit = (instance: ReturnType, hook: State) => { + instance.state.hook = hook + testHubModule.onAllTestEvents({ instance, test: { title: 't' } as Frameworks.Test }) + } + + it('sends a timed-out test\'s finish that arrives after service.after() flushed', async () => { + // A mocha timeout: the test starts, mocha gives up on it and with `bail` the worker's + // after() runs its flush while the test body is still pending... + const timedOut = makeMochaTestInstance('timed-out') + emit(timedOut, HookState.PRE) + await testHubModule.finishWorker() + + // ...and only then does its afterTest fire. Before the fix this was stashed and never sent. + emit(timedOut, HookState.POST) + await testHubModule.awaitLateTestFinishes(1000) + + expect(sendsFor(mockGrpcClient, 'timed-out', 'POST')).toBe(1) + }) + + it('awaitLateTestFinishes waits for a started test whose finish has not arrived yet', async () => { + const timedOut = makeMochaTestInstance('still-running') + emit(timedOut, HookState.PRE) + await testHubModule.finishWorker() + + setTimeout(() => emit(timedOut, HookState.POST), 150) + await testHubModule.awaitLateTestFinishes(2000) + + expect(sendsFor(mockGrpcClient, 'still-running', 'POST')).toBe(1) + }) + + it('closes a test that never finishes with one synthetic failed finish once the bound expires', async () => { + const stuck = makeMochaTestInstance('never-finishes') + emit(stuck, HookState.PRE) + await testHubModule.finishWorker() + + const t0 = Date.now() + await testHubModule.awaitLateTestFinishes(200) + + expect(Date.now() - t0).toBeLessThan(1000) + expect(sendsFor(mockGrpcClient, 'never-finishes', 'POST')).toBe(1) + expect(stuck.updateMultipleEntries).toHaveBeenCalledWith(expect.objectContaining({ + [TestFrameworkConstants.KEY_TEST_RESULT]: 'failed', + [TestFrameworkConstants.KEY_TEST_FAILURE_REASON]: TestHubModule.INCOMPLETE_TEST_REASON + })) + }) + + it('drops a real TEST/POST that straggles in after the synthetic close', async () => { + const stuck = makeMochaTestInstance('straggler') + emit(stuck, HookState.PRE) + await testHubModule.finishWorker() + await testHubModule.awaitLateTestFinishes(100) + + emit(stuck, HookState.POST) + await testHubModule.awaitLateTestFinishes(100) + + expect(sendsFor(mockGrpcClient, 'straggler', 'POST')).toBe(1) + }) + + it('waits for a late afterTest\'s bail cascade, not only the timed-out test\'s own finish', async () => { + const timedOut = makeMochaTestInstance('timed-out-mid-spec') + const bailSkipped = makeMochaTestInstance('bail-skipped') + emit(timedOut, HookState.PRE) + await testHubModule.finishWorker() + + // service.afterTest's CLI branch: TEST/POST, then (after real I/O in other observers) + // the bail cascade reports the spec's unrun tests as skipped. + const lateAfterTest = testHubModule.trackLateWork((async () => { + emit(timedOut, HookState.POST) + await new Promise((resolve) => setTimeout(resolve, 120)) + emit(bailSkipped, HookState.PRE) + emit(bailSkipped, HookState.POST) + })()) + await testHubModule.awaitLateTestFinishes(2000) + + expect(sendsFor(mockGrpcClient, 'timed-out-mid-spec', 'POST')).toBe(1) + expect(sendsFor(mockGrpcClient, 'bail-skipped', 'POST')).toBe(1) + await lateAfterTest + }) + + it('does not track work registered before the worker is ending', async () => { + let release!: () => void + testHubModule.trackLateWork(new Promise((resolve) => { + release = resolve + })) + + await testHubModule.finishWorker() + const t0 = Date.now() + await testHubModule.awaitLateTestFinishes(2000) + + expect(Date.now() - t0).toBeLessThan(500) + release() + }) + + it('still defers a finish during the run, so afterEach custom tags make the payload', () => { + const passing = makeMochaTestInstance('passing') + emit(passing, HookState.PRE) + emit(passing, HookState.POST) + + expect(sendsFor(mockGrpcClient, 'passing', 'POST')).toBe(0) + }) + + it('returns immediately at worker end when every started test has finished', async () => { + const passing = makeMochaTestInstance('done') + emit(passing, HookState.PRE) + emit(passing, HookState.POST) + await testHubModule.finishWorker() + + const t0 = Date.now() + await testHubModule.awaitLateTestFinishes(5000) + + expect(Date.now() - t0).toBeLessThan(500) + expect(sendsFor(mockGrpcClient, 'done', 'POST')).toBe(1) + }) +}) diff --git a/packages/browserstack-service/tests/service.afterSkipOrdering.test.ts b/packages/browserstack-service/tests/service.afterSkipOrdering.test.ts index 828cc0e3..886fc1f7 100644 --- a/packages/browserstack-service/tests/service.afterSkipOrdering.test.ts +++ b/packages/browserstack-service/tests/service.afterSkipOrdering.test.ts @@ -16,8 +16,9 @@ vi.mock('../src/cli/skipReporter.js', () => ({ resolveSpecFile: vi.fn() })) +const onWorkerEnd = vi.hoisted(() => vi.fn().mockResolvedValue(undefined)) vi.mock('../src/testOps/listener.js', () => ({ - default: { getInstance: () => ({ onWorkerEnd: vi.fn().mockResolvedValue(undefined) }) } + default: { getInstance: () => ({ onWorkerEnd }) } })) vi.mock('../src/data-store.js', () => ({ saveWorkerData: vi.fn() })) @@ -34,7 +35,9 @@ vi.mock('../src/instrumentation/performance/performance-tester.js', () => ({ } })) -const flushPendingTestFinishEvent = vi.fn().mockResolvedValue(undefined) +// after() flushes through finishWorker() (SDK-7843), which also arms the immediate-send path. +const finishWorker = vi.fn().mockResolvedValue(undefined) +const awaitLateTestFinishes = vi.fn().mockResolvedValue(undefined) vi.mock('../src/cli/index.js', () => ({ BrowserstackCLI: { @@ -60,7 +63,7 @@ describe('service.after() — skip drain must precede the deferred-finish flush vi.clearAllMocks() vi.mocked(BrowserstackCLI.getInstance).mockReturnValue({ isRunning: () => true, - modules: { TestHubModule: { flushPendingTestFinishEvent } }, + modules: { TestHubModule: { finishWorker, awaitLateTestFinishes } }, getAutomationFramework: () => ({ trackEvent: vi.fn().mockResolvedValue(undefined) }) } as never) }) @@ -86,10 +89,10 @@ describe('service.after() — skip drain must precede the deferred-finish flush await BrowserstackService.prototype.after.call(fakeService() as never, 0) expect(drainSkipReports).toHaveBeenCalledTimes(1) - expect(flushPendingTestFinishEvent).toHaveBeenCalledTimes(1) + expect(finishWorker).toHaveBeenCalledTimes(1) const drainOrder = vi.mocked(drainSkipReports).mock.invocationCallOrder[0] - const flushOrder = flushPendingTestFinishEvent.mock.invocationCallOrder[0] + const flushOrder = finishWorker.mock.invocationCallOrder[0] expect(drainOrder).toBeLessThan(flushOrder) }) @@ -98,6 +101,17 @@ describe('service.after() — skip drain must precede the deferred-finish flush await BrowserstackService.prototype.after.call(fakeService() as never, 0) - expect(flushPendingTestFinishEvent).toHaveBeenCalledTimes(1) + expect(finishWorker).toHaveBeenCalledTimes(1) + }) + + it('waits for late test finishes after the flush and before worker teardown (SDK-7843)', async () => { + await BrowserstackService.prototype.after.call(fakeService() as never, 0) + + expect(awaitLateTestFinishes).toHaveBeenCalledTimes(1) + const flushOrder = finishWorker.mock.invocationCallOrder[0] + const lateOrder = awaitLateTestFinishes.mock.invocationCallOrder[0] + const teardownOrder = onWorkerEnd.mock.invocationCallOrder[0] + expect(flushOrder).toBeLessThan(lateOrder) + expect(lateOrder).toBeLessThan(teardownOrder) }) })