fix(cli): record a timed-out mocha test's failure when mocha reports it (SDK-7843)

.changeset/pr-272.md

@@ -0,0 +1,6 @@
+---
+"@wdio/browserstack-service": patch
+---
+
+- Fixed mocha tests that fail by exceeding their timeout being marked "passed" on the Automate / App Automate dashboard, and their builds ending as "timeout" in Test Reporting about an hour after the run. Such tests are now reported as failed, with the timeout error as the reason.
+- Removed the `resolveInstance: unable to resolve/create instance ... LOG POST` error printed when a wdio `before` hook writes to the console.

packages/browserstack-service/src/cli/frameworks/testFramework.ts

@@ -1,3 +1,5 @@
+import type { Frameworks } from '@wdio/types'
+
 import { CLIUtils } from '../cliUtils.js'
 import { eventDispatcher } from '../eventDispatcher.js'
 import { BStackLogger as logger } from '../cliLogger.js'
@@ -84,6 +86,21 @@ export default class TestFramework {
         logger.info(`trackEvent: testFrameworkState=${testFrameworkState}; hookState=${hookState}; args=${args}`)
     }
 
+    /**
+   * Pin a test the reporter's `fail` is about to report to the test run it belongs to, before
+   * that report is queued.
+   * @param {Frameworks.Test} _test
+   */
+    // eslint-disable-next-line @typescript-eslint/no-unused-vars
+    pinFailedAttempt(_test: Frameworks.Test): void {}
+
+    /**
+   * Wait for test finishes that are still being reported. A module calls this before it reads the
+   * final results of the run (session status, the last deferred test finish).
+   * @returns {Promise<void>}
+   */
+    async settleTestFinishes(): Promise<void> {}
+
     /**
    * run test hooks
    * @param {TestFrameworkInstance} instance

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

@@ -87,6 +87,18 @@ async function emitSkipReport({ framework, test, result, suiteTitle }: QueuedSki
     }
 }
 
+/**
+ * Queue a report on the one chain every report wdio may not await goes through, so reports never
+ * interleave on the tracker's per-worker tracked-instance slot. service.after() waits for the chain
+ * through drainSkipReports(). Also used by the reporter's `fail` (SDK-7843).
+ */
+export function enqueueReport(work: () => Promise<void>, what: string): Promise<void> {
+    reportChain = reportChain.then(work).catch((err: unknown) => {
+        BStackLogger.debug(`Failed reporting ${what}: ${err}`)
+    })
+    return reportChain
+}
+
 export function markTestStarted(identifier: string) {
     startedTests.add(identifier)
 }
@@ -128,16 +140,14 @@ export function reportSkippedTest(
     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
+    // awaits — the hook cascade (afterHook) and the bail cascade (afterTest; when the failure was
+    // reported after mocha moved on, from service.after() instead, SDK-7843). 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
+        return enqueueReport(() => emitSkipReport(queued), `skipped test '${identifier}'`)
     }
 
     // The un-awaited `onTestSkip` path: queue it — see the QueuedSkip docs above. Emitting here
@@ -158,7 +168,8 @@ export function reportSkippedTest(
  * 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
+ * `afterHook` and the bail cascade in `afterTest` (or in `after()`, for a failure reported after
+ * mocha moved on, SDK-7843) — 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.
  */

packages/browserstack-service/src/reporter.ts

@@ -4,7 +4,9 @@ import type { SuiteStats, TestStats, RunnerStats, HookStats } from '@wdio/report
 import WDIOReporter from '@wdio/reporter'
 import type { Options, Frameworks } from '@wdio/types'
 import { BrowserstackCLI } from './cli/index.js'
-import { reportSkippedTest, resolveSpecFile } from './cli/skipReporter.js'
+import { enqueueReport, reportSkippedTest, resolveSpecFile } from './cli/skipReporter.js'
+import { TestFrameworkState } from './cli/states/testFrameworkState.js'
+import { HookState } from './cli/states/hookState.js'
 import * as url from 'node:url'
 
 import { v4 as uuidv4 } from 'uuid'
@@ -149,6 +151,42 @@ class _TestReporter extends WDIOReporter {
         }
     }
 
+    /**
+     * SDK-7843: mocha emits `fail` for a timed-out test while its body and wdio's `afterTest` are
+     * still pending, and with `bail` (or on the worker's last test) `after()` runs before that
+     * `afterTest`. On the CLI flow, send the test's finish now, with mocha's own result, so it is
+     * recorded before the session status is marked. The CLI framework reports each test once, so
+     * this is dropped for a normal failure, which afterTest has already reported.
+     */
+    async onTestFail(testStats: TestStats) {
+        if (this._config?.framework !== 'mocha' || !BrowserstackCLI.getInstance().isRunning()) {
+            return
+        }
+        const framework = BrowserstackCLI.getInstance().getTestFramework()
+        if (!framework) {
+            return
+        }
+        // `retries` is this test's retry count so far, i.e. the attempt mocha just failed
+        const attempts = testStats.retries ?? 0
+        const stats = testStats as TestStats & { parent?: string, file?: string }
+        const test = { title: stats.title, parent: stats.parent, fullTitle: stats.fullTitle, file: stats.file, _currentRetry: attempts } as unknown as Frameworks.Test
+        const result: Frameworks.TestResult = {
+            passed: false,
+            error: testStats.error,
+            duration: testStats._duration,
+            retries: { attempts, limit: attempts },
+            exception: testStats.error?.message ?? '',
+            status: 'failed'
+        }
+        // pin now, in mocha's `fail` event: the queued report can run after mocha starts the next test
+        framework.pinFailedAttempt(test)
+        // wdio does not await reporter callbacks: queue it on the skip-report chain, which after() drains
+        await enqueueReport(async () => {
+            await framework.trackEvent(TestFrameworkState.LOG_REPORT, HookState.POST, { test, result, fromMochaFail: true })
+            await framework.trackEvent(TestFrameworkState.TEST, HookState.POST, { test, result, fromMochaFail: true })
+        }, `failed test '${stats.title}'`)
+    }
+
     async onTestEnd(testStats: TestStats) {
         if (!this.needToSendData('test', 'end')) {
             return

packages/browserstack-service/src/service.ts

@@ -70,20 +70,6 @@ export default class BrowserstackService implements Services.ServiceInstance {
     private _specsRan: boolean = false
     private _observability
     private _currentTest?: Frameworks.Test | ITestCaseHookParameter
-    /**
-     * CLI/gRPC path: map of test identity -> the test_uuid minted for it at
-     * INIT_TEST/PRE. The CLI mints a fresh uuid into a SINGLE mutable per-worker tracked instance
-     * (`trackWdioMochaInstance` overwrites `TestFramework.instances[ctxId]` wholesale on every
-     * INIT_TEST), and the gRPC test-finish reads the uuid from that single slot. When a test hangs
-     * past the mocha timeout, the NEXT test's INIT_TEST overwrites the slot before the hung test's
-     * afterTest POST fires, so the POST would carry the wrong (next) test's uuid and the binary
-     * would close the wrong test_run — orphaning the hung one. We snapshot each test's uuid here,
-     * keyed by the same identity the legacy `_tests` map uses, and at afterTest we restore the
-     * finishing test's minted uuid onto the tracked instance before the POST so it closes the
-     * correct test_run. The finishing identity is `originalTest` (already snapshotted pre-await by
-     * the testFnWrapper, so it is the timed-out runnable's own identity, not the next test's).
-     */
-    private _cliTestUuids: Map<string, string> = new Map()
     private _insightsHandler?: InsightsHandler
     private _accessibility
     private _accessibilityHandler?: AccessibilityHandler
@@ -620,17 +606,11 @@ export default class BrowserstackService implements Services.ServiceInstance {
         if (BrowserstackCLI.getInstance().isRunning()) {
             await BrowserstackCLI.getInstance().getTestFramework()!.trackEvent(TestFrameworkState.INIT_TEST, HookState.PRE, { test })
             const uuid = TestFramework.getState(TestFramework.getTrackedInstance(), TestFrameworkConstants.KEY_TEST_UUID)
-            // snapshot this test's freshly-minted uuid keyed by its identity, so a later
-            // afterTest can restore it even after a subsequent INIT_TEST has overwritten the single
-            // mutable tracked-instance slot. Keyed exactly like the legacy `_tests` map.
-            if (this._config.framework === 'mocha' && uuid) {
-                this._cliTestUuids.set(getUniqueIdentifier(test, this._config.framework), uuid as string)
-            }
             // this test reports its own finish (incl. runtime `this.skip()`), so the
             // skip reporter must never re-report it from onTestSkip
             markTestStarted(getUniqueIdentifier(test, this._config.framework))
             this._insightsHandler?.setTestData(test, uuid)
-            await BrowserstackCLI.getInstance().getTestFramework()!.trackEvent(TestFrameworkState.TEST, HookState.PRE, { test, suiteTitle })
+            await BrowserstackCLI.getInstance().getTestFramework()!.trackEvent(TestFrameworkState.TEST, HookState.PRE, { test, suiteTitle, bail: this._mochaBail })
             return
         }
 
@@ -657,27 +637,12 @@ export default class BrowserstackService implements Services.ServiceInstance {
         }
 
         if (BrowserstackCLI.getInstance().isRunning()) {
-            // the CLI test-finish reads test_uuid from the single mutable per-worker
-            // tracked instance, which a later INIT_TEST may have overwritten with the NEXT test's
-            // uuid. `test` is `originalTest` — already the correct (timed-out) identity, snapshotted
-            // pre-await by the testFnWrapper — so restore THAT test's minted uuid onto the tracked
-            // instance so the POST carries it and the binary closes the correct test_run. Without
-            // this, the finish would carry the next test's uuid and orphan the finishing one.
-            if (this._config.framework === 'mocha') {
-                const identifier = getUniqueIdentifier(test, this._config.framework)
-                const resolvedUuid = this._cliTestUuids.get(identifier)
-                if (resolvedUuid) {
-                    const trackedInstance = TestFramework.getTrackedInstance()
-                    if (trackedInstance) {
-                        TestFramework.setState(trackedInstance, TestFrameworkConstants.KEY_TEST_UUID, resolvedUuid)
-                    }
-                    // Clean up so the per-worker map does not grow across the run.
-                    this._cliTestUuids.delete(identifier)
-                }
-            }
+            // `test` is `originalTest`, the timed-out runnable's own identity; the CLI framework
+            // reports the finish against the instance that test started on, even when a later
+            // test has taken the tracked-instance slot, drops it if mocha's `fail` already
+            // reported it, and runs the bail cascade (SDK-7843)
             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)
             return
         }
 
@@ -686,60 +651,6 @@ export default class BrowserstackService implements Services.ServiceInstance {
         await this._percyHandler?.afterTest()
     }
 
-    /**
-     * Whether this failure will be retried, in which case mocha has not dropped anything yet and
-     * the tests after it are still going to run.
-     *
-     * `results.retries` only tracks wdio's spec-file retries — `@wdio/utils` builds it as
-     * `{ attempts: 0, limit: repeatTest }` and `@wdio/mocha-framework` never feeds `mochaOpts.retries`
-     * into it, so under mocha-level retries it stays `{0, 0}` and tells us nothing. Read mocha's own
-     * runnable state for that case, otherwise the cascade fires on the first attempt and reports
-     * tests as skipped that the retry then actually runs.
-     */
-    private hasRetryPending(test: Frameworks.Test, results: Frameworks.TestResult): boolean {
-        const mochaTest = test.ctx?.test as { currentRetry?: () => number, retries?: () => number } | undefined
-        if (typeof mochaTest?.currentRetry === 'function' && typeof mochaTest.retries === 'function') {
-            if (mochaTest.currentRetry() < mochaTest.retries()) {
-                return true
-            }
-        }
-        return Boolean(results.retries && results.retries.attempts < results.retries.limit)
-    }
-
-    /**
-     * mocha's `bail` aborts the run on the first failure, so every test the spec had not reached
-     * yet is dropped without emitting any event and never appears on the dashboard. Report them
-     * as skipped — same cascade the failed-hook path uses, from the spec's root suite so sibling
-     * describes are covered too (bail kills the whole spec, not just the failing describe).
-     *
-     * The root can span more than one file when specs are grouped — `MochaAdapter` adds every spec
-     * it is handed to one mocha instance. Cascading across them is still correct: bail aborts that
-     * whole runner, so those tests do not run either.
-     */
-    private async reportBailSkippedTests(test: Frameworks.Test, results: Frameworks.TestResult) {
-        if (!this._mochaBail || results.passed || results.skipped) {
-            return
-        }
-        try {
-            // inside the boundary: hasRetryPending reaches into mocha's own runnable, which this
-            // SDK does not own
-            if (this.hasRetryPending(test, results)) {
-                return
-            }
-            const framework = BrowserstackCLI.getInstance().getTestFramework()
-            let suite = test.ctx?.test?.parent
-            if (!framework || !suite) {
-                return
-            }
-            while (suite.parent) {
-                suite = suite.parent
-            }
-            await reportSuiteSkipped(framework, suite)
-        } catch (err) {
-            BStackLogger.debug(`Failed reporting bail-skipped tests: ${err}`)
-        }
-    }
-
     @PerformanceTester.Measure(PERFORMANCE_SDK_EVENTS.EVENTS.SDK_HOOK, { hookType: 'after' })
     async after (result: number) {
         try {
@@ -768,6 +679,15 @@ export default class BrowserstackService implements Services.ServiceInstance {
                 } catch (skipDrainErr) {
                     BStackLogger.debug(`Exception draining skip reports in after(): ${util.format(skipDrainErr)}`)
                 }
+                // SDK-7843: the drain above also waits for a timed-out test's finish, which the
+                // reporter's `fail` queues on the same chain. Then finish a failed test nothing
+                // reported (no reporter registered) and run owed bail cascades, before the flush
+                // below and before EXECUTE/POST, where the session status is marked
+                try {
+                    await BrowserstackCLI.getInstance().getTestFramework()?.settleTestFinishes()
+                } catch (settleErr) {
+                    BStackLogger.debug(`Exception settling test finishes in after(): ${util.format(settleErr)}`)
+                }
                 // 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.
@@ -854,12 +774,6 @@ export default class BrowserstackService implements Services.ServiceInstance {
             } catch (sweepErr) {
                 BStackLogger.debug('Exception in sweepUnfinished during after(): ' + util.format(sweepErr))
             }
-            // 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
-            // snapshots cannot leak across the worker. Safe to clear: this runs after the sweep and
-            // no further afterTest will consume them in this worker.
-            this._cliTestUuids.clear()
 
             // Track Listener cleanup
             PerformanceTester.start(EVENTS.SDK_LISTENER_WORKER_END)