Merge fix/sdk-7493-queue-skip-reports-until-drain

.changeset/pr-194.md

@@ -0,0 +1,5 @@
+---
+"@wdio/browserstack-service": patch
+---
+
+- Fixed a skipped test staying stuck on "In Progress" in Test Hub when it sits between two running tests — for example a `it.skip()` in the middle of a spec. Completes the fix shipped in 9.35.3, which only covered skips at the end of a spec. Skipped tests are now reported when the run finishes, so they appear grouped at the end of the build rather than in source order.

packages/browserstack-service/src/cli/modules/testHubModule.ts

@@ -38,8 +38,23 @@ export default class TestHubModule extends BaseModule {
      * slot with a fresh instance for the next test — so it stays valid across tests.
      * Flushed at the next test's first event (INIT_TEST / TEST PRE) or, for the worker's
      * last test, from service.after() via flushPendingTestFinishEvent().
+     *
+     * SDK-7493: keyed by test uuid, NOT a single slot. wdio does not await `onTestSkip`, so a
+     * skip report runs detached and can interleave with a live test — its events land between
+     * the live test's own, on the same per-worker tracked-instance context. With one slot the
+     * second stash silently REPLACED the first (the old guard only flushed when the instance
+     * OBJECT differed, and an interleave can present the same object), so one test's
+     * TestRunFinished was never sent and TRA left it rendering "In Progress" until the ~60-min
+     * idle reap. A map cannot evict: every deferred finish is delivered, each under its own uuid.
+     *
+     * NOTE ON REDUNDANCY: SDK-7493's queue-and-drain (skipReporter) already stops a skip report
+     * running while a test is in flight, so on the normal path that collision can no longer be
+     * triggered and this map is not the primary fix. It is retained deliberately as
+     * defence-in-depth for a reporting path with a real incident history (SDK-7265, SDK-7493,
+     * ~60-min reaps): if any future caller reintroduces an interleave, the worst case degrades
+     * to a late send rather than a silently lost TestRunFinished.
      */
-    private pendingTestFinish: { args: Record<string, unknown> } | null = null
+    private pendingTestFinishes: Map<string, { args: Record<string, unknown>, uuid: string }> = new Map()
 
     /**
      * Create a new TestHubModule
@@ -84,7 +99,7 @@ export default class TestHubModule extends BaseModule {
         // A NEW test is starting (INIT_TEST minted a fresh instance) — the previous test's
         // after-each hook window is definitively over, so flush its deferred finish first
         // (payload build is synchronous, so gRPC send order is preserved).
-        if (this.pendingTestFinish && (testState === TestFrameworkState.INIT_TEST || (testState === TestFrameworkState.TEST && hookState === HookState.PRE))) {
+        if (this.pendingTestFinishes.size > 0 && (testState === TestFrameworkState.INIT_TEST || (testState === TestFrameworkState.TEST && hookState === HookState.PRE))) {
             this.flushPendingTestFinishEvent()
         }
         if (testState === TestFrameworkState.LOG) {
@@ -119,13 +134,16 @@ export default class TestHubModule extends BaseModule {
             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).
-                // If a previous finish is somehow still pending for a DIFFERENT test, flush
-                // it first; a re-stash for the same instance just replaces the stash.
-                if (this.pendingTestFinish && (this.pendingTestFinish.args.instance as TestFrameworkInstance) !== instance) {
-                    this.flushPendingTestFinishEvent()
-                }
-                this.pendingTestFinish = { args }
-                this.logger.debug('onAllTestEvents: deferred TEST/POST send past the after-each hook window')
+                // SDK-7493: key the stash by the test's uuid, captured NOW. Two different tests
+                // can present the same tracked instance when a detached skip report interleaves
+                // with a live test, so keying on the instance object silently dropped one of the
+                // two finishes. Re-stashing the SAME uuid (e.g. the LOG_REPORT/POST recovery
+                // re-entry below) correctly replaces only that test's own entry.
+                const deferUuid = String(
+                    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})`)
             } else {
                 this.sendTestFrameworkEvent(args)
             }
@@ -140,34 +158,45 @@ export default class TestHubModule extends BaseModule {
      * next test's boundary and from service.after() at worker end.
      */
     flushPendingTestFinishEvent(): Promise<void> | undefined {
-        if (!this.pendingTestFinish) {
+        if (this.pendingTestFinishes.size === 0) {
             return undefined
         }
-        const { args } = this.pendingTestFinish
-        this.pendingTestFinish = null
-        this.logger.debug('flushPendingTestFinishEvent: sending deferred TEST/POST event')
+        // Drain every pending finish, not just the newest. Take and clear the whole batch up
+        // front so a concurrent stash (the detached skip chain) starts a fresh entry rather
+        // than being swallowed by this in-flight drain.
+        const batch = [...this.pendingTestFinishes.values()]
+        this.pendingTestFinishes.clear()
+        this.logger.debug(`flushPendingTestFinishEvent: sending ${batch.length} deferred TEST/POST event(s)`)
+
         // SDK-7265: this is the only send of a mocha test's TestRunFinished, and the worker's last
         // test relies on this single flush from service.after(). A dropped send orphans the test →
         // Test Hub reaps it at its ~60-min idle timeout → the passing build is stamped `timeout`.
-        // Retry with backoff. `args` is captured locally and the shared slot is only cleared (never
-        // written back), so concurrent flushes can't clobber one another.
+        // Retry with backoff. Each entry is captured locally, so concurrent flushes can't clobber
+        // one another.
         const maxAttempts = 3
-        const attempt = (n: number): Promise<void> =>
-            this.sendTestFrameworkEvent(args, { testFrameworkState: 'TEST', testHookState: 'POST' }).then((sent) => {
-                if (sent) {
-                    return
-                }
-                this.logger.debug(`flushPendingTestFinishEvent: attempt ${n}/${maxAttempts} failed`)
-                if (n >= maxAttempts) {
-                    this.logger.error('flushPendingTestFinishEvent: deferred TEST/POST send failed after all retries')
-                    return
-                }
-                return new Promise<void>((resolve) => setTimeout(resolve, 200 * n)).then(() => attempt(n + 1))
-            })
-        return attempt(1)
+        const sendOne = ({ args, uuid }: { args: Record<string, unknown>, uuid: string }): Promise<void> => {
+            // SDK-7493: pin the uuid captured at DEFER time. The payload is otherwise serialized
+            // from the instance's live data at send time, and an interleaved skip report can have
+            // rewritten the uuid on that instance since — which would close the wrong test_run and
+            // leave this one open forever.
+            const attempt = (n: number): Promise<void> =>
+                this.sendTestFrameworkEvent(args, { testFrameworkState: 'TEST', testHookState: 'POST', uuid }).then((sent) => {
+                    if (sent) {
+                        return
+                    }
+                    this.logger.debug(`flushPendingTestFinishEvent: uuid=${uuid} attempt ${n}/${maxAttempts} failed`)
+                    if (n >= maxAttempts) {
+                        this.logger.error(`flushPendingTestFinishEvent: deferred TEST/POST send failed after all retries (uuid=${uuid})`)
+                        return
+                    }
+                    return new Promise<void>((resolve) => setTimeout(resolve, 200 * n)).then(() => attempt(n + 1))
+                })
+            return attempt(1)
+        }
+        return Promise.all(batch.map(sendOne)).then(() => undefined)
     }
 
-    async sendTestFrameworkEvent(args: Record<string, unknown>, stateOverride?: { testFrameworkState: string, testHookState: string }): Promise<boolean> {
+    async sendTestFrameworkEvent(args: Record<string, unknown>, stateOverride?: { testFrameworkState: string, testHookState: string, uuid?: string }): Promise<boolean> {
         try {
             const testArgs = args as { test: Frameworks.Test, instance: TestFrameworkInstance }
             const instance = testArgs.instance as TestFrameworkInstance
@@ -182,11 +211,24 @@ export default class TestHubModule extends BaseModule {
 
             this.logger.debug(`sendTestFrameworkEvent for testState: ${testFrameworkState} hookState: ${testHookState}`)
             const platformIndex = process.env.WDIO_WORKER_ID ? parseInt(process.env.WDIO_WORKER_ID.split('-')[0]) : 0
-            const uuid = TestFramework.getState(instance, TestFrameworkConstants.KEY_TEST_UUID) || instance.getRef()
+            // SDK-7493: a deferred flush pins the uuid captured when the finish was stashed;
+            // reading it live here can pick up another test's uuid if an interleaved skip
+            // report rewrote it on this instance in the meantime.
+            const uuid = stateOverride?.uuid || TestFramework.getState(instance, TestFrameworkConstants.KEY_TEST_UUID) || instance.getRef()
             // Nested values such as test_hooks_started/test_hooks_finished are JS Maps, which
             // JSON.stringify would serialise to `{}` and strip the hook data. Convert any Map to
             // a plain object so the binary receives populated hook maps.
-            const eventJson = Buffer.from(JSON.stringify(Object.fromEntries(testData), (_key, value) => value instanceof Map ? Object.fromEntries(value) : value))
+            // SDK-7493: the pinned uuid must go INSIDE event_json too, not just the top-level
+            // field. The binary routes a mocha test_run on the uuid it parses out of this blob —
+            // `webdriverio/index.js` does `const event = JSON.parse(eventJson)` and the mocha
+            // handler builds the test run with `uuid: event.test_uuid` — so a stale `test_uuid`
+            // here would close the wrong run and leave the deferred one open, which is the very
+            // failure the pin exists to prevent. Overriding a copy keeps the instance untouched.
+            const eventData = Object.fromEntries(testData)
+            if (stateOverride?.uuid) {
+                eventData[TestFrameworkConstants.KEY_TEST_UUID] = stateOverride.uuid
+            }
+            const eventJson = Buffer.from(JSON.stringify(eventData, (_key, value) => value instanceof Map ? Object.fromEntries(value) : value))
             const executionContext = { hash: trackedContext.getId(), threadId: trackedContext.getThreadId().toString(), processId: trackedContext.getProcessId().toString() }
             const payload: Omit<TestFrameworkEventRequest, 'binSessionId'> = {
                 platformIndex,

packages/browserstack-service/src/cli/skipReporter.ts

@@ -32,6 +32,61 @@ const reportedSkips = new Set<string>()
 // tracker's single mutable per-worker instance — serialize every report through one chain
 let reportChain: Promise<void> = Promise.resolve()
 
+/**
+ * SDK-7493: skip reports are QUEUED here and only emitted from drainSkipReports(), never at
+ * the moment onTestSkip fires.
+ *
+ * wdio does not await onTestSkip, so emitting inline let a skip's events interleave with a
+ * live test's. Both share one per-worker tracked-instance slot, so the skip's INIT_TEST
+ * repointed that slot mid-test; the live test's afterTest then restored ITS uuid onto the
+ * skip's instance (service.ts `_cliTestUuids`), and from there the two tests' TEST/POSTs
+ * collapsed onto one uuid — one TestRunFinished was lost (test stuck "In Progress" until the
+ * ~60-min reap) and the survivor carried the wrong result. Deferring to the drain removes the
+ * interleave entirely: no test is in flight there, so each skip gets its own instance and uuid.
+ */
+interface QueuedSkip {
+    framework: TestFramework
+    test: Frameworks.Test
+    result: Frameworks.TestResult
+    suiteTitle?: string
+}
+const queuedSkips: QueuedSkip[] = []
+
+/**
+ * Emit one skip's full event sequence, in order.
+ *
+ * Every step is attempted even if an earlier one rejects. TEST/POST is what ultimately
+ * produces the TestRunFinished, and abandoning the sequence on an earlier failure is the
+ * exact outcome this ticket exists to prevent: a test that is started and never finished
+ * sits "In Progress" until Test Hub's ~60-min idle reap. A partial report — worse ordering,
+ * a missing log payload — is strictly better than an unterminated test run.
+ *
+ * The first error is retained and rethrown so the caller still logs a real failure rather
+ * than silently reporting success.
+ */
+async function emitSkipReport({ framework, test, result, suiteTitle }: QueuedSkip): Promise<void> {
+    // LOG_REPORT/POST is what loads the result into the instance (loadTestResult is
+    // gated on it, not on TEST/POST) — same sequence afterTest uses
+    const steps: Array<[State, State, Record<string, unknown>]> = [
+        [TestFrameworkState.INIT_TEST, HookState.PRE, { test }],
+        [TestFrameworkState.TEST, HookState.PRE, { test, suiteTitle }],
+        [TestFrameworkState.LOG_REPORT, HookState.POST, { test, result }],
+        [TestFrameworkState.TEST, HookState.POST, { test, result, suiteTitle }],
+    ]
+
+    let firstError: unknown
+    for (const [state, hook, args] of steps) {
+        try {
+            await framework.trackEvent(state, hook, args)
+        } catch (err: unknown) {
+            firstError ??= err
+        }
+    }
+    if (firstError !== undefined) {
+        throw firstError
+    }
+}
+
 export function markTestStarted(identifier: string) {
     startedTests.add(identifier)
 }
@@ -42,32 +97,70 @@ export function markTestStarted(identifier: string) {
 // so the chain completes while the session is still open. (Hook-skip cascades go via
 // reportSuiteSkipped inside afterHook, which is already awaited, so they were unaffected.)
 export function drainSkipReports(): Promise<void> {
+    // Emit everything queued so far, strictly one at a time. Drains until empty rather than
+    // snapshotting: emitting a skip can enqueue nothing today, but draining a growing queue is
+    // the safe shape. Runs from service.after(), where no test is in flight.
+    reportChain = reportChain.then(async () => {
+        while (queuedSkips.length > 0) {
+            const queued = queuedSkips.shift()!
+            try {
+                await emitSkipReport(queued)
+            } catch (err: unknown) {
+                BStackLogger.debug(`Failed reporting skipped test '${queued.test.title}': ${err}`)
+            }
+        }
+    })
     return reportChain
 }
 
-export function reportSkippedTest(framework: TestFramework, identifier: string, test: Frameworks.Test, suiteTitle?: string): Promise<void> {
+export function reportSkippedTest(
+    framework: TestFramework,
+    identifier: string,
+    test: Frameworks.Test,
+    suiteTitle?: string,
+    options?: { immediate?: boolean }
+): Promise<void> {
     if (startedTests.has(identifier) || reportedSkips.has(identifier)) {
         return reportChain
     }
     reportedSkips.add(identifier)
     const result = { passed: false, skipped: true } as Frameworks.TestResult
-    reportChain = reportChain.then(async () => {
-        // LOG_REPORT/POST is what loads the result into the instance (loadTestResult is
-        // gated on it, not on TEST/POST) — same sequence afterTest uses
-        await framework.trackEvent(TestFrameworkState.INIT_TEST, HookState.PRE, { test })
-        await framework.trackEvent(TestFrameworkState.TEST, HookState.PRE, { test, suiteTitle })
-        await framework.trackEvent(TestFrameworkState.LOG_REPORT, HookState.POST, { test, result })
-        await framework.trackEvent(TestFrameworkState.TEST, HookState.POST, { test, result, suiteTitle })
-    }).catch((err: unknown) => {
-        BStackLogger.debug(`Failed reporting skipped test '${identifier}': ${err}`)
-    })
+    const queued: QueuedSkip = { framework, test, result, suiteTitle }
+
+    // SDK-7493: only the DETACHED caller needs deferring. `immediate` is for callers wdio
+    // awaits — the hook cascade (afterHook) and the bail cascade (afterTest). Those never had
+    // the interleave, because wdio holds the lifecycle open until they resolve, so nothing else
+    // can claim the tracked slot underneath them. Deferring those too would be a behaviour
+    // change for no benefit: their skips would move to end-of-run and their reports would no
+    // longer be part of the hook/test they belong to.
+    if (options?.immediate) {
+        reportChain = reportChain.then(() => emitSkipReport(queued)).catch((err: unknown) => {
+            BStackLogger.debug(`Failed reporting skipped test '${identifier}': ${err}`)
+        })
+        return reportChain
+    }
+
+    // The un-awaited `onTestSkip` path: queue it — see the QueuedSkip docs above. Emitting here
+    // would interleave this skip's events with whatever test is currently running.
+    //
+    // Tradeoff: delivery now depends on service.after() running. If the worker dies before it
+    // (SIGKILL, OOM, a teardown error that skips after()), queued skips are dropped with no
+    // send attempted, where the old inline path would at least have tried. Accepted because
+    // the inline path is the bug being fixed, and an aborted worker already leaves its
+    // in-progress test runs to Test Hub's idle reap regardless.
+    queuedSkips.push(queued)
     return reportChain
 }
 
 /**
  * Port of the legacy insights-handler skip propagation: when a BEFORE_ALL/BEFORE_EACH/
  * AFTER_EACH hook fails (or skips), mocha silently drops the remaining tests in the
  * suite — report each state-undefined test as skipped, recursing into nested describes.
+ *
+ * Reports IMMEDIATELY (SDK-7493): every caller of this — the failed-hook cascade in
+ * `afterHook` and the bail cascade in `afterTest` — is awaited by wdio, so these reports
+ * cannot interleave with a live test the way the un-awaited `onTestSkip` path could. They
+ * belong to the hook/test being reported, so they must not slide to end-of-run.
  */
 export async function reportSuiteSkipped(framework: TestFramework, suite: { tests?: unknown[], suites?: unknown[] }): Promise<void> {
     for (const t of (suite.tests || []) as MochaRuntimeTest[]) {
@@ -86,7 +179,7 @@ export async function reportSuiteSkipped(framework: TestFramework, suite: { test
             file: t.file,
             ctx: { test: { parent: t.parent } }
         } as unknown as Frameworks.Test
-        await reportSkippedTest(framework, identifier, synthetic, parentTitle)
+        await reportSkippedTest(framework, identifier, synthetic, parentTitle, { immediate: true })
     }
     for (const sub of (suite.suites || []) as { tests?: unknown[], suites?: unknown[] }[]) {
         await reportSuiteSkipped(framework, sub)