Skip to content

fix(cli): send a timed-out mocha test's finish that lands after the worker's final flush (SDK-7843) #267

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
AakashHotchandani wants to merge 3 commits into
base: main
Choose a base branch
from
+378 −12
Open

fix(cli): send a timed-out mocha test's finish that lands after the worker's final flush (SDK-7843) #267

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
29ef83d
fix(cli): send a timed-out mocha test's finish that lands after the w…
AakashHotchandani Oct 5, 2026
1a76bfc
chore(changeset): auto-generate from PR template (patch)
github-actions[bot] Oct 5, 2026
6b0453a
fix(cli): close never-finishing tests and wait for late bail cascades…
AakashHotchandani Oct 5, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 5 additions & 0 deletions .changeset/pr-267.md
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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.
126 changes: 125 additions & 1 deletion packages/browserstack-service/src/cli/modules/testHubModule.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -56,6 +66,32 @@ export default class TestHubModule extends BaseModule {
*/
private pendingTestFinishes: Map<string, { args: Record<string, unknown>, 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<string, Record<string, unknown>> = new Map()

/** Late work (an afterTest that started after workerEnding, with its bail cascade). */
private lateWork: Set<Promise<unknown>> = new Set()

/** Finishes sent after workerEnding, which service.after() awaits before teardown. */
private lateFinishSends: Set<Promise<unknown>> = new Set()

/** Tests closed with a synthetic finish; a straggling real TEST/POST for them is dropped. */
private syntheticallyClosed: Set<string> = new Set()

/**
* Create a new TestHubModule
*/
Expand Down Expand Up @@ -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).
Expand All @@ -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<void> | 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<T>(work: Promise<T>): Promise<T> {
if (this.workerEnding) {

@AakashHotchandani AakashHotchandani Oct 5, 2026

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Warning — [CORRECTNESS] A late afterTest that starts before finishWorker() is not tracked, so its bail cascade can still outlive awaitLateTestFinishes

Problem

trackLateWork() adds the afterTest work only if (this.workerEnding). service.afterTest calls it synchronously when it is entered (service.ts:682), so the gate is checked when the timed-out body settles, not when the cascade runs.

If the body settles in the window between the end of the mocha run and finishWorker(), afterTest is entered with workerEnding === false and is never tracked. That window includes the rest of wdio's runner work before the after hooks, and after() itself up to the await drainSkipReports(). This case then plays out as follows:

  • The timed-out test's TEST/POST is still handled: it is either stashed and flushed by finishWorker(), or sent immediately and tracked in lateFinishSends.
  • reportBailSkippedTests then runs untracked. Between the timed-out test's POST and each skipped test's TEST/PRE, openTests and lateFinishSends can both be empty.
  • In the author's live run that gap was about 1.27 s (17:07:22.808 → 17:07:24.082), so a 50 ms poll that lands in it returns.
  • A skipped test whose TestRunStarted is sent after that never gets a finish. It is not in openTests when the synthetic close runs, so it ends in the same ~60-min timeout reap.

When the body settles relative to after() is outside the SDK's control. That is the PR's own premise: the body is "still running when after() starts". The customer timings (late POST 139–150 ms after the flush, with LOG_REPORT/POST in front of it) do not rule out an entry before the flush. The test does not track work registered before the worker is ending (testHubModule.lateFinish.test.ts:171) asserts this gap as intended behaviour.

Suggested Fix

Track unconditionally. trackIn already removes each promise when it settles. wdio awaits every normal afterTest inside the test wrapper, so when after() runs, the only unsettled entries are afterTests of tests mocha abandoned, which are exactly the ones to wait for. The 5 s deadline still bounds the wait.

trackLateWork<T>(work: Promise<T>): Promise<T> {
    // Untracks itself on settle, so only work still running at worker end is waited for.
    this.trackIn(this.lateWork, work)
    return work
}

Change the case at :171 to register work before finishWorker(), release it 120 ms into awaitLateTestFinishes(), and emit a bail-skipped PRE/POST from it. Assert that the skipped test's POST is sent. Keep a separate check that settled pre-ending work returns at once.

Confidence: 🟡 The untracked path is visible in the code and pinned by the unit case at :171. The author's live run measured the cascade gap at 1.27 s. Whether wdio can actually enter a timed-out test's afterTest before after() reaches finishWorker() has not been reproduced: the live run's body settled after the flush.

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<void> {
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])

@AakashHotchandani AakashHotchandani Oct 5, 2026

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Warning — [CORRECTNESS] awaitLateTestFinishes can return while the late test's bail cascade is still emitting skip reports

Problem

The late afterTest emits more than TEST/POST. On the CLI branch, service.afterTest (service.ts:674-676) runs LOG_REPORT/POST, then TEST/POST, then await this.reportBailSkippedTests(test, results). A timed-out test under bail has passed: false and no retry pending, so this calls reportSuiteSkipped from the spec's root suite. Each unrun test then gets INIT_TEST, TEST/PRE (which sends TestRunStarted), LOG_REPORT/POST and TEST/POST.

The wait loop watches only openTestUuids. The timed-out test's uuid is removed inside TestHubModule's TEST/POST observer, but trackEvent(TEST, POST) keeps awaiting the other modules' observers (runHooks → notifyObserver) before reportBailSkippedTests starts. Those observers do real I/O. A 50 ms tick that falls in this gap sees an empty set and leaves the loop.

Promise.all([...this.lateFinishSends]) then takes a snapshot of the sends present at that moment, so skip finishes added later are never awaited. after() goes on to Listener.onWorkerEnd() and teardown while the cascade is still running. A skipped test that has sent TestRunStarted but not TestRunFinished is the same kind of open test_run, and it ends in the same ~60-minute timeout reap.

The PR's repro does not cover this case: the timed-out test is the last test in its spec, so the cascade has nothing to report.

Suggested Fix

Wait for the whole late afterTest, not just its TEST/POST. Once finishWorker() has run, the CLI branch of afterTest should register its own promise with TestHubModule. awaitLateTestFinishes should then loop until open tests, registered late work and lateFinishSends are all empty, or the deadline passes, and re-read lateFinishSends on every pass:

while ((this.openTestUuids.size > 0 || this.lateWork.size > 0 || this.lateFinishSends.size > 0) && Date.now() < deadline) {
    await new Promise((resolve) => setTimeout(resolve, 50))
}
await Promise.all([...this.lateFinishSends])

Add a unit case for this sequence: PRE(timed-out) → finishWorker() → POST(timed-out), then, after an await gap, PRE/POST for a bail-skipped test. Assert that both finishes are sent before awaitLateTestFinishes() resolves.

Confidence: 🟡 Agent analysis of the await ordering across service.afterTest, runHooks and reportBailSkippedTests. It has not been reproduced at runtime, which would need a bail spec where the timed-out test is not the last one.

@AakashHotchandani AakashHotchandani Oct 5, 2026

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Valid, fixed in 6b0453a, and a live run confirmed it isn't only theoretical. service.afterTest now registers its whole CLI branch (LOG_REPORT, TEST/POST and reportBailSkippedTests) through TestHubModule.trackLateWork(), which tracks it only once the worker is ending. awaitLateTestFinishes() loops until open tests, late work and late sends are all empty, re-reading lateFinishSends on every pass.

Live run (chrome/Win11, mocha timeout 10 s + bail, timed-out test in the middle of the spec): the bail-skipped test's TEST/POST landed 1.27 s after the timed-out test's (17:07:24.082 vs 17:07:22.808), still before teardown at .135. The previous loop would have returned about 50 ms after the first finish. Build daoyulfmxsq7w9mcounalwqxqubem2bhf55dygtx from /ext/v1: passed 1, failed 1, skipped 1, unknown 0.

The new unit case (PRE timed-out → finishWorker() → POST, then after a 120 ms gap PRE/POST for a bail-skipped test) fails when I put back the old open-tests-only loop, and passes with the fix.

}

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 }))

@AakashHotchandani AakashHotchandani Oct 5, 2026

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

💡 Suggestion — [RESILIENCE] The synthetic close is a single send with no retry, and an exception on one test stops the rest from being closed

Problem

closeOpenTestsAsIncomplete() calls sendTestFrameworkEvent once. The real late finishes go through flushPendingTestFinishEvent(), which retries 3 times with backoff because, per its own SDK-7265 comment, "a dropped send orphans the test". The synthetic close is the last chance a test gets, so it is the send that most needs the retry.

Separately, the loop has no per-item boundary. If instance.updateMultipleEntries throws for one entry, the exception leaves awaitLateTestFinishes() and after() catches it. The remaining open tests are then not closed, and the sends already queued in lateFinishSends are not awaited before teardown. The classic sweepUnfinished isolates each item (insights-handler.ts per-entry try/catch).

Suggested Fix

Reuse the existing retry path, and isolate each entry:

for (const [uuid, args] of this.openTests) {
    try {
        (args.instance as TestFrameworkInstance).updateMultipleEntries({ /* same fields */ })
        this.syntheticallyClosed.add(uuid)
        this.pendingTestFinishes.set(uuid, { args, uuid })
    } catch (err) {
        this.logger.debug(`closeOpenTestsAsIncomplete: ${uuid}: ${util.format(err)}`)
    }
}
this.openTests.clear()
const send = this.flushPendingTestFinishEvent()   // pinned uuid + 3-attempt retry
if (send) { this.trackIn(this.lateFinishSends, send) }

}
this.openTests.clear()
}

private trackIn(set: Set<Promise<unknown>>, work: Promise<unknown>) {
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
Expand Down
28 changes: 23 additions & 5 deletions packages/browserstack-service/src/service.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
}

Expand Down Expand Up @@ -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)}`)
}
Expand Down Expand Up @@ -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
Expand Down
Loading
Loading