fix(cli): send a timed-out mocha test's finish that lands after the worker's final flush (SDK-7843) - #267
fix(cli): send a timed-out mocha test's finish that lands after the worker's final flush (SDK-7843)#267AakashHotchandani wants to merge 3 commits into
Conversation
…orker's final flush (SDK-7843) The mocha TEST/POST (TestRunFinished) is deferred past the after-each window and flushed at the next test or from service.after(). A test that hits mocha's timeout keeps running after mocha moves on, so its afterTest fires only once the body settles. With `bail` that happens during service.after(), after the final flush has already run against an empty map. The late stash was never sent, Test Hub kept the test_run open, and the build was reaped as `timeout` about 60 minutes later. TestHubModule now: - finishWorker(): called by service.after() in place of the bare flush. It flushes and marks the worker as ending. - sends a TEST/POST immediately, instead of deferring it, once the worker is ending. - awaitLateTestFinishes(): called near the end of service.after(), before teardown. It waits (bounded, 5 s) for every test whose TEST/PRE was seen to report its TEST/POST, then for those sends to land. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
|
Important Review skippedAuto reviews are disabled on this repository. Please check the settings in the CodeRabbit UI or the ⚙️ Run configuration
You can disable this status message by setting the Use the checkbox below for a quick retry:
Comment |
AakashHotchandani
left a comment
AakashHotchandani
left a comment
There was a problem hiding this comment.
Automated SDK PR Review
Verdict: testHubModule.ts:214). Otherwise a test whose body never settles still ends the build as timeout. (2) Make awaitLateTestFinishes wait for the whole late afterTest, including its bail-skip cascade, not only for the timed-out test's TEST/POST (testHubModule.ts:217).
Summary: 0 critical · 2 warnings · 3 suggestions across 4 files reviewed.
Intent: On the CLI flow, TestHubModule holds back a mocha test's TEST/POST (TestRunFinished) until after the after-each window, and sends it at the next test's first event or from service.after(). A test that hits the mocha timeout runs its afterTest only when its pending body settles. With bail, that happens during service.after(), after the final flush has already run, so the finish was never sent. Test Hub then left the test_run open and stamped the build timeout about 60 minutes later (SDK-7843; the CLI path started reaching this customer after #261). The PR adds finishWorker(), which flushes and then sends any later TEST/POST immediately, and awaitLateTestFinishes(), which waits up to 5 s before teardown for every test whose TEST/PRE was seen to report TEST/POST and be sent. Deferral during the run is unchanged. Affected products: Test Reporting (Observability) on the CLI/gRPC path. Affected frameworks: WDIO v9 mocha (the deferral is mocha-only; the open-test wait also covers CLI cucumber). Components: cli/modules/testHubModule.ts, service.ts after(). No proto or binary change.
Risk: Medium
The fix is correct for the failure the customer actually hit, where the late TEST/POST landed within about 1 s of the flush, and it does not regress ordinary runs. The verdict rests on two remaining gaps, and each one still ends in the same ~60-minute timeout reap. First, a timed-out body that never settles within 5 s still gets no TestRunFinished, and the CLI path has no synthetic close equivalent to the classic sweep. Second, the wait can return before a late afterTest's bail-skip cascade has finished sending. Rovo enrichment unavailable — review based on local SDK docs only.
See inline comments below for full Problem and Suggested Fix detail on each finding.
Generated by Automated SDK PR review.
| while (this.openTestUuids.size > 0 && Date.now() < deadline) { | ||
| await new Promise((resolve) => setTimeout(resolve, 50)) | ||
| } | ||
| if (this.openTestUuids.size > 0) { |
There was a problem hiding this comment.
⚠️ Warning — [OBSERVABILITY] A timed-out test whose body never settles within the 5 s bound still gets no TestRunFinished
Problem
awaitLateTestFinishes() only waits. When the bound expires with openTestUuids still non-empty, it logs at debug level (line 215) and returns. Nothing sends a TEST/POST for those uuids, so the TestRunStarted already sent at TEST/PRE has no matching TestRunFinished. Test Hub then reaps the build as timeout about 60 minutes later, which is the SDK-7843 symptom this PR sets out to fix.
The fix depends on the timed-out body settling within 5 s of after() starting. It did in the evidence: the late POST landed 139–150 ms after the flush on customer workers 0-4 and 0-3, and about 1.2 s after it in the repro. Nothing guarantees it, though. Three cases still leave the run open:
- an infinite await;
- a hung driver call, which only wdio's
connectionRetryTimeout(default 120 s) bounds; - a
waitUntil/waitForDisplayedwhose own timeout exceeds the mocha timeout by more than 5 s.
Unit case 3 (gives up after the bound when a test never finishes) asserts 0 sends, so the test suite now locks the gap in.
The classic path does not have this gap. Per the observability docs, openRunsJournal / finalizeOrphanedRuns close "any runs that never received a TestRunFinished event (e.g., due to a test timeout …)", and sweepUnfinished() sends a synthetic finish. That sweep explicitly skips CLI-path tests (insights-handler.ts:543-548: "Any genuine CLI-path orphan is a binary-side concern"). The binary does not close it either: the customer's stop POST returned 200 at 16:34:36, yet finished_at was the 17:34:52 idle reap. So even after this PR, the CLI path has no terminal close for an orphaned test.
Suggested Fix
Send a synthetic terminal TEST/POST for every test still open after the bound. The state this needs is already available. Keep the TEST/PRE args instead of only the uuid. args.instance is that test's own TestFrameworkInstance: INIT_TEST puts a fresh object in the tracked slot, as the pendingTestFinishes docs note, so the stored one stays valid.
private openTests: Map<string, Record<string, unknown>> = new Map()
// TEST/PRE: this.openTests.set(String(testUuid), args)
// TEST/POST: this.openTests.delete(String(testUuid))
// in awaitLateTestFinishes(), after the wait loop:
const reason = 'Test did not report a finish before worker teardown (timed out and never settled)'
const closes = [...this.openTests].map(([uuid, args]) => {
(args.instance as TestFrameworkInstance).updateMultipleEntries({
[TestFrameworkConstants.KEY_TEST_RESULT]: 'failed',
[TestFrameworkConstants.KEY_TEST_FAILURE_REASON]: reason,
[TestFrameworkConstants.KEY_TEST_FAILURE]: [{ backtrace: [reason] }],
[TestFrameworkConstants.KEY_TEST_ENDED_AT]: new Date().toISOString(),
})
this.syntheticallyClosed.add(uuid)
return this.sendTestFrameworkEvent(args, { testFrameworkState: 'TEST', testHookState: 'POST', uuid })
})
this.openTests.clear()
await Promise.all(closes)In the TEST/POST branch, drop any POST whose uuid is in syntheticallyClosed, so a straggler that arrives after the synthetic close is not sent a second time. Then change unit case 3 to expect exactly one failed TEST/POST for never-finishes.
Confidence: 🟢 Grounded in the observability docs (an orphaned run must be closed, and the classic path does this through finalizeOrphanedRuns/sweepUnfinished) and in sdk-anti-pattern #23 (fixing one path but not the parallel one). The missing send can be read directly from the code, and the PR's own unit case 3 asserts it.
There was a problem hiding this comment.
Valid, fixed in 6b0453a. If a test is still open when the bound expires, awaitLateTestFinishes() now closes it with a synthetic failed TEST/POST, using the stored TEST/PRE args (that test's own instance) and its pinned uuid. It sets result: failed with the reason Test did not finish before the session ended (incomplete)., which mirrors the classic sweepUnfinished(). If the real TEST/POST straggles in after that, it is dropped (syntheticallyClosed), so the test is never closed twice. Unit case 3 now expects exactly one failed finish, and a new case covers the straggler drop.
| if (this.openTestUuids.size > 0) { | ||
| this.logger.debug(`awaitLateTestFinishes: no TEST/POST within ${waitMs}ms for ${[...this.openTestUuids].join(', ')}`) | ||
| } | ||
| await Promise.all([...this.lateFinishSends]) |
There was a problem hiding this comment.
⚠️ 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.
There was a problem hiding this comment.
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.
| 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) |
There was a problem hiding this comment.
💡 Suggestion — [TESTING] awaitLateTestFinishes is mocked in the after() ordering test but never asserted
Problem
This mock exists only so after() does not throw. No assertion checks that it is called once, after finishWorker(), and before Listener.onWorkerEnd() and _cliTestUuids.clear(). That position is what lets a late afterTest still restore its snapshotted uuid.
The five new TestHubModule cases call finishWorker() and awaitLateTestFinishes() directly. As the PR description says, they fail trivially on the unfixed source. None of them drives the actual ordering bug: after() starts, the flush runs, a late afterTest arrives, and its finish must be sent before teardown.
No case checks that openTestUuids empties on the skip-reporter drain path either. If it does not, every CLI mocha worker pays the full 5 s.
Suggested Fix
Add three things:
- A call-order assertion:
finishWorker<awaitLateTestFinishes<Listener.onWorkerEnd. - One
after()-level case with the real TestHubModule and a mocked gRPC client. Start a delayed promise beforeafter()that emits the timed-out test's TEST/POST, and assert that the TEST/POST send happens beforeonWorkerEnd. - A case where
drainSkipReports()emits a skip (INIT_TEST/PRE … TEST/POST). Assert thatawaitLateTestFinishes()then returns within a few ms.
There was a problem hiding this comment.
Partly applied in 6b0453a:
- Call order:
service.afterSkipOrdering.test.tsnow assertsfinishWorker<awaitLateTestFinishes<Listener.onWorkerEnd. - New TestHubModule cases: bail cascade (mutation-checked, see the reply above), straggler after synthetic close, and work registered before the worker is ending, which is not waited for.
Not added, and why:
- An
after()-level case with the real TestHubModule. What it would prove (a lateafterTestlanding mid-after()and being sent before teardown) is proven end-to-end by the three real-session builds: stockw6oktdkn…with unknown 1, and fixedkptjob3f…/daoyulfm…with unknown 0. A unit harness would have to fake wdio's timer-drivenafterTestanyway, so it would assert the fake rather than the race. - A skip-drain case.
drainSkipReports()is awaited at the top ofafter(), beforefinishWorker(), and each drained skip emits its TEST/PRE and TEST/POST through the sameonAllTestEventsobserver. SoopenTestsis already balanced whenawaitLateTestFinishes()runs. That is the path the existingreturns immediately at worker end when every started test has finishedcase covers (it returns in under 500 ms against a 5 s bound).
| * instance so late custom-tag merges are included. Called from onAllTestEvents at the | ||
| * next test's boundary and from service.after() at worker end. | ||
| */ | ||
| /** |
There was a problem hiding this comment.
💡 Suggestion — [DOCS] flushPendingTestFinishEvent's JSDoc now sits above finishWorker
Problem
The new methods were inserted between the existing doc block ("Send a deferred TEST/POST (TestRunFinished) event, if one is pending…", lines 187-193) and flushPendingTestFinishEvent() (line 222). Two JSDoc blocks are now stacked above finishWorker(), and flushPendingTestFinishEvent() has none, so IDE hovers and generated docs show the wrong description for both methods.
Suggested Fix
Move lines 187-193 so they sit directly above flushPendingTestFinishEvent(): Promise<void> | undefined {.
There was a problem hiding this comment.
Valid, fixed in 6b0453a. The "Send a deferred TEST/POST…" JSDoc is back directly above flushPendingTestFinishEvent(), and finishWorker(), trackLateWork() and awaitLateTestFinishes() each have only their own block.
| await Promise.all([...this.lateFinishSends]) | ||
| } | ||
|
|
||
| static LATE_TEST_FINISH_WAIT_MS = 5000 |
There was a problem hiding this comment.
💡 Suggestion — [CONFIG] LATE_TEST_FINISH_WAIT_MS is a mutable static declared in the middle of the class
Problem
The bound is a named constant, which is good, but it is a writable static declared between two methods. Any code can reassign it at runtime, and it is hard to find next to MODULE_NAME. It is also not a hard ceiling on after(): the final Promise.all(lateFinishSends) can add up to three gRPC attempts per send, with 200 ms and 400 ms backoff between them.
Suggested Fix
Declare it as static readonly LATE_TEST_FINISH_WAIT_MS = 5000 next to MODULE_NAME (line 28). Update the doc comment to say the 5 s covers only the wait for the finish to arrive, and that the send itself is not included.
There was a problem hiding this comment.
Valid, fixed in 6b0453a. It is now static readonly LATE_TEST_FINISH_WAIT_MS = 5000, declared next to MODULE_NAME. Its doc now says it bounds only the wait for late finishes to arrive, and that the sends keep their own retry/backoff in flushPendingTestFinishEvent. INCOMPLETE_TEST_REASON is also declared there as static readonly.
… at worker end (SDK-7843) Review follow-ups on the late test-finish fix: - Close a test that never reports its finish within the bound with a synthetic failed TEST/POST (reason "Test did not finish before the session ended (incomplete)."). This mirrors the classic path's sweepUnfinished(). A straggling real TEST/POST for it is then dropped. - Wait for the whole late afterTest, not only its TEST/POST: service.afterTest registers its CLI branch via trackLateWork(), so the bail cascade's skip reports are sent before teardown. A live run hit this gap: the cascade's finish landed 1.27 s after the timed-out test's. - LATE_TEST_FINISH_WAIT_MS is now static readonly, next to MODULE_NAME, and its doc says it bounds only the arrival wait. - flushPendingTestFinishEvent's JSDoc is back above it. - Tests: synthetic close, straggler drop, bail-cascade ordering (fails on the previous loop), untracked pre-ending work, and the after() call order finishWorker < awaitLateTestFinishes < onWorkerEnd. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
|
🔴 SDK PR Review gate is red. Pending:
It turns green once the SDK PR Review Agent has run on the current head commit (any verdict — the gate only requires that the review ran). A native reviewer approval is separately required by branch protection before merge. |
AakashHotchandani
left a comment
AakashHotchandani
left a comment
There was a problem hiding this comment.
Automated SDK PR Review (re-review @ 6b0453ab)
Summary
Intent: On the CLI flow, TestHubModule holds back a mocha test's TEST/POST (TestRunFinished) until after the after-each window. It sends it at the next test's first event, or from service.after() for the worker's last test. A test that hits the mocha timeout runs its afterTest only when its pending body settles. With bail, that happens during service.after(), after the final flush, so the finish was never sent. Test Hub then stamped the build timeout about 60 minutes later (SDK-7843). The PR adds three pieces:
finishWorker(): flushes, then sends any later TEST/POST immediately.trackLateWork():service.afterTestregisters its whole CLI branch (LOG_REPORT, TEST/POST, bail cascade) through it once the worker is ending.awaitLateTestFinishes(): before teardown, waits up to 5 s until open tests, late work and late sends are empty. Any test still open is then closed with a synthetic failed TEST/POST ("incomplete"), the CLI counterpart of the classicsweepUnfinished(). A straggling real finish is dropped.
Deferral during the run is unchanged. Affected products: Test Reporting (Observability) on the CLI/gRPC path. Affected frameworks: WDIO v9 mocha; the open-test wait and synthetic close also cover CLI cucumber. Components: cli/modules/testHubModule.ts, service.ts (afterTest, after()). No proto or binary change.
Re-review scope: new head 6b0453ab (prior review at 1a76bfc5). The delta is one commit: fix(cli): close never-finishing tests and wait for late bail cascades….
Risk: Medium
0 critical · 1 warning · 1 suggestion | Files reviewed: 5
Rovo enrichment unavailable — review based on local SDK docs only.
Prior findings status
| # | Prior finding | Status | Evidence at 6b0453ab |
|---|---|---|---|
| W1 🟢 | A test still open after the 5 s bound got no TestRunFinished | RESOLVED | See W1 note below. |
| W2 🟡 | awaitLateTestFinishes could return mid bail-cascade |
PARTIAL | Fixed for the case the review described, an afterTest that starts after finishWorker(). See W2 note below. |
| S1 | Assert call order; add after()-level and drain tests |
DECLINED-ACCEPTABLE (partly applied) | See S1 note below. |
| S2 | flushPendingTestFinishEvent JSDoc misplaced |
RESOLVED | Its doc is at :277-283, directly above :284. finishWorker (:211-215), trackLateWork (:220-225) and awaitLateTestFinishes (:232-240) each have only their own block. |
| S3 | Mutable static mid-class | RESOLVED | static readonly LATE_TEST_FINISH_WAIT_MS = 5000 at :35, next to MODULE_NAME. Its doc now says it bounds only the arrival wait, not the sends. INCOMPLETE_TEST_REASON is static readonly at :38. |
W1 (RESOLVED). closeOpenTestsAsIncomplete() (testHubModule.ts:252-267) uses the stored TEST/PRE args, which hold the test's own instance (openTests, :84, set at :173).
- Fields. It sets result
failed, failure[{backtrace:[reason]}], failure_reason, failure_typeUnhandledErrorand ended_at. These are the same keys the real mocha builder writes (wdioMochaTestFramework.ts:254-259loadTestResult, plus:88-90ended_at). - Parity with the classic path. It matches
sweepUnfinishedexactly:insights-handler.ts:613-614sends resultfailedwithgetFailureObject(new Error('Test/hook did not finish before the session ended (incomplete).')). - Pinned uuid. The uuid is pinned through
stateOverride.uuid, which also overridestest_uuidinsideevent_json(:351-354). - Sent and awaited before teardown. The send is added to
lateFinishSendsand awaited at:249, beforeonWorkerEnd. - No double finish. A straggling real POST is dropped at the single TEST/POST entry point (
:175-179), which runs before both the deferred stash and the immediate send. The flush can therefore never hold a closed uuid. A real POST already in flight has removed its uuid fromopenTests(:180) before it is sent, so it is never also closed synthetically. - Tests. Unit cases
:122and:138cover the close and the straggler drop.
W2 (PARTIAL).
- Fixed.
service.afterTestwraps LOG_REPORT, TEST/POST andreportBailSkippedTestsinfinish()and passes it totrackLateWork(service.ts:674-682). The loop at:242re-readsopenTests,lateWorkandlateFinishSendson every pass. The live rundaoyulfm…saw the cascade's TEST/POST 1.27 s after the timed-out test's, still before teardown. The unit case at:150fails on the old loop: it would exit at about 50 ms, before the 120 ms cascade. - Still open.
trackLateWorkrecords work onlyif (this.workerEnding)(:226). AnafterTestthat started beforefinishWorker()still has an untracked cascade. The test at:171locks this in. See Warning 1.
S1 (DECLINED-ACCEPTABLE, partly applied).
- Added. The call-order assertion
finishWorker < awaitLateTestFinishes < onWorkerEnd(service.afterSkipOrdering.test.ts:107-116), plus the cascade, straggler and pre-ending-work cases. - Declined: the
after()-level case with the real TestHubModule. The author's reason holds. A unit harness would have to fake wdio's timer-drivenafterTest, and three real Automate builds (stockw6oktdkn…with unknown 1; fixedkptjob3f…anddaoyulfm…with unknown 0 and the cascade covered) prove the end-to-end ordering better. - Declined: the drain case.
drainSkipReports()is awaited beforefinishWorker(), and drained skips emit PRE and POST through the same observer, so the existing "returns immediately" case (:193) stands in for it.
Verdict
✅ Good to go: W1, S2 and S3 are resolved, and S1 is acceptably declined.
- The synthetic incomplete close and the late-work wait fix SDK-7843 for the observed timing.
- One non-blocking item is left for human judgment (🟡, timing not reproduced). A late
afterTestthat starts beforefinishWorker()is not tracked, so its bail cascade could outlive the wait (testHubModule.ts:226). Dropping theworkerEndinggate intrackLateWorkis a one-line hardening.
See inline comments below for detail on the non-blocking items.
Generated by Automated SDK PR review.
| * 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) { |
There was a problem hiding this comment.
⚠️ 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 inlateFinishSends. reportBailSkippedTeststhen runs untracked. Between the timed-out test's POST and each skipped test's TEST/PRE,openTestsandlateFinishSendscan 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
openTestswhen the synthetic close runs, so it ends in the same ~60-mintimeoutreap.
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.
| [TestFrameworkConstants.KEY_TEST_ENDED_AT]: new Date().toISOString() | ||
| }) | ||
| this.syntheticallyClosed.add(uuid) | ||
| this.trackIn(this.lateFinishSends, this.sendTestFrameworkEvent(args, { testFrameworkState: 'TEST', testHookState: 'POST', uuid })) |
There was a problem hiding this comment.
💡 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) }1 participant
What is this about?
On the CLI flow, a mocha test that hits mocha's timeout never gets a
TestRunFinished. Test Hub keeps that test_run open, so the build ends astimeoutabout 60 minutes after the run. Test Reporting also shows the timed-out test as unknown rather than failed.A customer hit this (SDK-7843). On 9.36.0–9.39.2, 100% of their WDIO builds ended
finished. Since 9.39.3, 47 of 55 endedtimeout.Why it surfaced only now:
apisblock. Up to 9.39.2 that madeupdateURLSForGRRthrow, and the CLI bootstrap stopped.updateURLSForGRRnull-safe, which was correct. Their workers now run on the CLI path, and that path has this bug.Why it happens.
TestHubModuledefers the mochaTEST/POSTpast the after-each window. The deferred finish is flushed at the next test's first event, or for the worker's last test fromservice.after().On a mocha timeout, mocha gives up on the test while its body is still pending. wdio's
afterTest, which emitsTEST/POST, fires only once that body settles. Withbailthat happens duringservice.after(), after its flush has already run against an empty map. The late stash then has nothing left to send it:after()flush +EXECUTE/POSTTEST/POSTdeferredCustomer binary log for #753: 8
TestRunStartedvs 6TestRunFinished.Timeout of 300000ms exceeded.finished_at= 17:34:52 (the idle reap).The fix, in
TestHubModuleplus two call sites inservice.after():finishWorker()replaces the bareflushPendingTestFinishEvent()call at the start ofafter(). It flushes, then marks the worker as ending. After that, aTEST/POSTis sent immediately instead of deferred, since no later flush exists.trackLateWork():service.afterTestregisters its whole CLI branch through it (LOG_REPORT,TEST/POST, then the bail skip cascade). It is tracked only once the worker is ending.awaitLateTestFinishes()runs near the end ofafter(), next to the classic path'ssweepUnfinished()and before teardown:LATE_TEST_FINISH_WAIT_MS), until every test whoseTEST/PREwas seen has reported, lateafterTestwork has settled, and late sends have landed.TEST/POST(reasonTest did not finish before the session ended (incomplete).), the CLI counterpart ofsweepUnfinished(). A straggling real finish for it is then dropped.Unchanged: a finish during the run is still deferred, so custom tags set in
afterEachstill make it into the payload.Not in v8: the v8 line sends
TEST/POSTinline (no deferral), so it doesn't have this bug. No v8 port is needed.Verification
Real WDIO 9 + mocha runs on Automate (chrome/Win11, CLI flow, Test Reporting on), with
mochaOpts: { timeout: 10000, bail: true }and a test that waits 40 s for a missing element. Each build was read back from/ext/v1/builds/<uuid>/testRuns:w6oktdknrww4qksrmhhwv8rhilwdc6ka4dlf0xi3stock 9.39.2kptjob3frg5grhuomlzrhj2rhihtrjpfwfhklvzrthis PR (1st commit)daoyulfmxsq7w9mcounalwqxqubem2bhf55dygtxthis PR (review fixes)In the third run the bail cascade's
TEST/POSTlanded 1.27 s after the timed-out test's (17:07:24.082 vs 17:07:22.808), still before teardown at .135. Waiting for the whole lateafterTest(review finding) is what covers that.Tests:
tests/cli/modules/testHubModule.lateFinish.test.tshas 8 cases:finishWorker()is sent;tests/service.afterSkipOrdering.test.tsmocksfinishWorker, keeps the SDK-7493 drain-before-flush assertion, and adds the call orderfinishWorker<awaitLateTestFinishes<Listener.onWorkerEnd.Checks:
tests/cli/modules,service*.test.ts,skipReporter*: the same 43 failures with and without this PR, compared by test name. All are pre-existing network-dependentservice.test.tscases; none is new.tests/cli: 4 failed / 414 passed. The 4 are the same pre-existingcliUtilsupdate-CLI andstaleBinaryfailures as onmain.tsc -p tsconfig.prod.json --noEmitandeslintare clean.Related: #264 / #265 (the cosmetic
resolveInstance … LOGERROR from the same ticket).Related Jira task/s
SDK-7843
Release (mandatory for every PR — required for the
ready-for-reviewlabel)Version bump: (required — tick exactly one)
Release notes type: (optional)
Release notes (customer-facing): (optional but encouraged)
bail). The timed-out test is now reported as failed, and the build closes when the run ends.Release notes (internal): (required — engineer-facing; what actually changed / why)
TestHubModule.finishWorker()replaces the bareflushPendingTestFinishEvent()inservice.after(). It flushes and setsworkerEnding, after which a mochaTEST/POSTis sent immediately instead of being stashed. A timed-out test'safterTestfires once its still-pending body settles, which withbailis duringafter(), after the final flush. Its deferred finish was stranded, so the test_run stayed open and the build was reaped astimeout(~60 min).TestHubModule.awaitLateTestFinishes()(bounded 5 s,static readonly LATE_TEST_FINISH_WAIT_MS), called near the end ofafter()before teardown. It waits for open tests (TEST/PRE without TEST/POST), lateafterTestwork registered viatrackLateWork()(including the bail cascade), and late sends. A test still open after the bound gets a synthetic failed TEST/POST ("incomplete"), mirroring the classicsweepUnfinished(); a straggling real finish for it is dropped.updateURLSForGRRbecame null-safe, so the CLI now boots for accounts whose bin-session config has noapis, and those accounts reached the CLI-only deferral path. v8 has no deferral and is unaffected.Checklist
PR Validations
Run Tests: Comment RUN_TESTS to trigger sanity tests.
🤖 Generated with Claude Code