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

.changeset/pr-273.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. Such sessions are now marked 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/frameworks/wdioMochaTestFramework.ts

@@ -13,10 +13,80 @@ import type { Frameworks } from '@wdio/types'
 import { getGitMetaData, getMochaTestHierarchy, getTestTags, getUniqueIdentifier, isUndefined, removeAnsiColors } from '../../util.js'
 import { TEST_ANALYTICS_ID } from '../../constants.js'
 
+/** mocha's live runnable of a test attempt; mocha sets `state` before it emits `fail`. */
+interface MochaRunnable {
+    state?: string
+    timedOut?: boolean
+    duration?: number
+    timeout?: () => number
+}
+
+/** A mocha test attempt that has started (TEST/PRE) and not finished yet (SDK-7843). */
+interface TestAttempt {
+    instance: TestFrameworkInstance
+    test: Frameworks.Test
+    suiteTitle?: unknown
+    runnable?: MochaRunnable
+    /** Who is reporting this attempt's finish: wdio's afterTest, or the reporter's `fail`. */
+    finishingFrom?: 'afterTest' | 'fail'
+    /** Its TEST/POST has been reported. */
+    finished?: boolean
+}
+
+/** The failure mocha recorded on a runnable (it keeps no error object on it). */
+const failureFromRunnable = (runnable: MochaRunnable): Frameworks.TestResult => {
+    const ms = typeof runnable.timeout === 'function' ? runnable.timeout() : undefined
+    const error = new Error(runnable.timedOut && ms ? `Timeout of ${ms}ms exceeded.` : 'Test failed before its afterTest ran.')
+    return { passed: false, error, duration: runnable.duration ?? 0, retries: { attempts: 0, limit: 0 }, exception: error.message, status: 'failed' }
+}
+
 export default class WdioMochaTestFramework extends TestFramework {
     static KEY_HOOK_LAST_STARTED = 'test_hook_last_started'
     static KEY_HOOK_LAST_FINISHED = 'test_hook_last_finished'
 
+    /**
+     * SDK-7843: mocha test attempts that started and have not finished, keyed per attempt.
+     *
+     * wdio runs `afterTest` inside the test's own runnable, after the body. When a test hits
+     * mocha's timeout, mocha fails it (and emits `fail` to reporters) while the body and its
+     * `afterTest` are still pending; mocha then moves on, and with `bail` (or on the worker's last
+     * test) wdio runs `after()` before that `afterTest`. So a test's finish can arrive from the
+     * reporter's `fail`, from a late `afterTest` while another test holds the tracked-instance
+     * slot, or not at all before the session status is marked. Each attempt keeps the instance it
+     * started on, so its finish is reported against its own test run, once.
+     */
+    private openAttempts = new Set<TestAttempt>()
+    /**
+     * The latest attempt started under each `attemptKey`. The key holds only the immediate parent's
+     * title, so two tests in a worker can share it; the later one's TEST/PRE replaces the entry.
+     */
+    private latestAttemptByKey = new Map<string, TestAttempt>()
+    /**
+     * Attempts by the test's body, then by `attemptKey`. wdio hands beforeTest and afterTest
+     * separate copies of the mocha test (`{ ...context.test }`, with no reference to the runnable),
+     * but both carry its `fn`, so afterTest finds its own attempt even when another test with the
+     * same key has started since. Tests can share one body (`it(name, sharedFn)`), hence the key.
+     */
+    private attemptsByFn = new WeakMap<object, Map<string, TestAttempt>>()
+    /** The attempt a source's LOG_REPORT/POST resolved; its TEST/POST passes the same `test` object. */
+    private resolvedFinishes = new WeakMap<object, TestAttempt>()
+
+    /** One attempt of a test: mocha retries a test as a new runnable with `_currentRetry` + 1. */
+    static attemptKey(test: Frameworks.Test): string {
+        const retry = (test as { _currentRetry?: number })._currentRetry
+        const identifier = getUniqueIdentifier(test, 'mocha')
+        return retry ? `${identifier} (retry ${retry})` : identifier
+    }
+
+    private static currentRetry(test: Frameworks.Test): number {
+        return (test as { _currentRetry?: number })._currentRetry ?? 0
+    }
+
+    private static testBody(test: Frameworks.Test): object | undefined {
+        const fn = (test as { fn?: unknown }).fn
+        return typeof fn === 'function' ? fn : undefined
+    }
+
     /**
    * Constructor for the TestFramework
    * @param {Array} testFrameworks - List of Test frameworks
@@ -35,13 +105,35 @@ export default class WdioMochaTestFramework extends TestFramework {
   */
     async trackEvent(testFrameworkState: State, hookState: State, args: Record<string, unknown> = {}) {
         logger.info(`trackEvent: testFrameworkState=${testFrameworkState} hookState=${hookState}`)
+        const attempt = this.resolveTestAttempt(testFrameworkState, hookState, args)
         await super.trackEvent(testFrameworkState, hookState, args)
 
-        const instance = this.resolveInstance(testFrameworkState, hookState, args)
+        // Console output from wdio's `before` hook (after the service has patched console)
+        // arrives before mocha's first hook, so there is no test or hook to attach it to yet and
+        // resolveInstance cannot create one for LOG. The classic path drops such a log silently; do the same instead of
+        // printing an ERROR on every worker (SDK-7843).
+        if (testFrameworkState === TestFrameworkState.LOG && !TestFramework.getTrackedInstance()) {
+            logger.debug(`trackEvent: no test or hook started yet, dropping log for testFrameworkState=${testFrameworkState} hookState=${hookState}`)
+            return
+        }
+
+        if (attempt === null) {
+            return
+        }
+        let instance: TestFrameworkInstance | null
+        if (attempt) {
+            instance = attempt.instance
+            this.updateInstanceState(instance, testFrameworkState, hookState)
+        } else {
+            instance = this.resolveInstance(testFrameworkState, hookState, args)
+        }
         if (instance === null) {
             logger.error(`trackEvent: instance not found for testFrameworkState=${testFrameworkState} hookState=${hookState}`)
             return
         }
+        if (testFrameworkState === TestFrameworkState.TEST && hookState === HookState.PRE && args.test) {
+            this.openTestAttempt(instance, args)
+        }
 
         try {
             // HOOK_REGEX is anchored (^BEFORE_|^AFTER_) — match the short state name; the
@@ -88,6 +180,126 @@ export default class WdioMochaTestFramework extends TestFramework {
         await this.runHooks(instance, testFrameworkState, hookState, args)
     }
 
+    /** TEST/PRE: this attempt's finish is owed from here on, against this instance. */
+    private openTestAttempt(instance: TestFrameworkInstance, args: Record<string, unknown>) {
+        const test = args.test as Frameworks.Test
+        const attempt: TestAttempt = {
+            instance,
+            test,
+            suiteTitle: args.suiteTitle,
+            runnable: test.ctx?.test as MochaRunnable | undefined
+        }
+        this.openAttempts.add(attempt)
+        this.latestAttemptByKey.set(WdioMochaTestFramework.attemptKey(test), attempt)
+        const body = WdioMochaTestFramework.testBody(test)
+        if (body) {
+            const byKey = this.attemptsByFn.get(body) ?? new Map<string, TestAttempt>()
+            byKey.set(WdioMochaTestFramework.attemptKey(test), attempt)
+            this.attemptsByFn.set(body, byKey)
+        }
+    }
+
+    /**
+     * The reporter's `fail`, synchronously in mocha's `fail` event (SDK-7843): pin the failed test
+     * to the attempt mocha just failed, the latest with its key. The finish itself is queued (see
+     * skipReporter's enqueueReport) and may run after mocha has started the next test, which can
+     * share the key.
+     */
+    pinFailedAttempt(test: Frameworks.Test) {
+        const attempt = this.findTestAttempt(test)
+        if (attempt) {
+            this.resolvedFinishes.set(test, attempt)
+        }
+    }
+
+    /**
+     * Whether mocha already failed this attempt. A failure it retries is not marked: mocha clones
+     * the test, emits `retry` instead of `fail` and leaves the attempt's `state` unset. It only
+     * retries a failure, though, so a later attempt of the same test having started means this
+     * one failed.
+     */
+    private mochaFailed(attempt: TestAttempt): boolean {
+        if (attempt.runnable?.state === 'failed') {
+            return true
+        }
+        const body = WdioMochaTestFramework.testBody(attempt.test)
+        const identifier = getUniqueIdentifier(attempt.test, 'mocha')
+        const retry = WdioMochaTestFramework.currentRetry(attempt.test)
+        return [...(body && this.attemptsByFn.get(body)?.values() || [])].some((other) =>
+            getUniqueIdentifier(other.test, 'mocha') === identifier && WdioMochaTestFramework.currentRetry(other.test) > retry)
+    }
+
+    /**
+     * The attempt a finish belongs to. wdio's afterTest carries the test's body, which identifies
+     * it exactly. The reporter's `fail` has only the title and parent: it is pinned (see
+     * pinFailedAttempt) to the latest attempt with that key, which is the one mocha just failed,
+     * so its queued LOG_REPORT and TEST/POST cannot land on a later same-named test.
+     */
+    private findTestAttempt(test: Frameworks.Test): TestAttempt | undefined {
+        const resolved = this.resolvedFinishes.get(test)
+        if (resolved) {
+            return resolved
+        }
+        const body = WdioMochaTestFramework.testBody(test)
+        if (body) {
+            return this.attemptsByFn.get(body)?.get(WdioMochaTestFramework.attemptKey(test))
+        }
+        return this.latestAttemptByKey.get(WdioMochaTestFramework.attemptKey(test))
+    }
+
+    /**
+     * LOG_REPORT/POST and TEST/POST of a mocha test: the attempt to report against. Returns
+     * undefined for any other event, and for a test this framework never saw start (resolved as
+     * before); null to drop the event, when the attempt is already finished or another source is
+     * finishing it.
+     */
+    private resolveTestAttempt(testFrameworkState: State, hookState: State, args: Record<string, unknown>): TestAttempt | null | undefined {
+        const isFinish = hookState === HookState.POST && (testFrameworkState === TestFrameworkState.TEST || testFrameworkState === TestFrameworkState.LOG_REPORT)
+        if (!isFinish || !args.test) {
+            return undefined
+        }
+        const test = args.test as Frameworks.Test
+        const source = args.fromMochaFail ? 'fail' : 'afterTest'
+        const attempt = this.findTestAttempt(test)
+        if (!attempt) {
+            // the reporter's `fail` for a hook, or for a test that never started
+            return source === 'fail' ? null : undefined
+        }
+        if (attempt.finished || (attempt.finishingFrom && attempt.finishingFrom !== source)) {
+            logger.debug(`trackEvent: '${WdioMochaTestFramework.attemptKey(test)}' was already reported, dropping ${testFrameworkState} ${hookState} from ${source}`)
+            return null
+        }
+        attempt.finishingFrom = source
+        this.resolvedFinishes.set(test, attempt)
+        // a timed-out test whose body finished late: wdio's result says only whether the body
+        // threw, not that mocha already failed it
+        if (attempt.runnable && this.mochaFailed(attempt) && (args.result as Frameworks.TestResult | undefined)?.passed) {
+            args.result = failureFromRunnable(attempt.runnable)
+        }
+        if (testFrameworkState === TestFrameworkState.TEST) {
+            attempt.finished = true
+            this.openAttempts.delete(attempt)
+        }
+        return attempt
+    }
+
+    /**
+     * Before the session status is marked and the last test finish is flushed: finish every attempt
+     * mocha already failed (or retried) that nothing reported (no reporter is registered when Test
+     * Reporting, Accessibility and Percy are all off). Runs after drainSkipReports(), which waits
+     * for the finishes the reporter queued.
+     */
+    async settleTestFinishes(): Promise<void> {
+        for (const attempt of [...this.openAttempts]) {
+            if (attempt.runnable && this.mochaFailed(attempt) && !attempt.finishingFrom) {
+                const result = failureFromRunnable(attempt.runnable)
+                this.resolvedFinishes.set(attempt.test, attempt)
+                await this.trackEvent(TestFrameworkState.LOG_REPORT, HookState.POST, { test: attempt.test, result, fromMochaFail: true })
+                await this.trackEvent(TestFrameworkState.TEST, HookState.POST, { test: attempt.test, result, fromMochaFail: true })
+            }
+        }
+    }
+
     /**
    * Resolve instance for the test framework
    * @param {TestFrameworkState} testFrameworkState

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

@@ -32,6 +32,23 @@ const reportedSkips = new Set<string>()
 // tracker's single mutable per-worker instance — serialize every report through one chain
 let reportChain: Promise<void> = Promise.resolve()
 
+/**
+ * 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. 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
+}
+
+/** Wait for every report queued so far; service.after() calls this before marking the session. */
+export function drainSkipReports(): Promise<void> {
+    return reportChain
+}
+
 export function markTestStarted(identifier: string) {
     startedTests.add(identifier)
 }
@@ -42,17 +59,14 @@ export function reportSkippedTest(framework: TestFramework, identifier: string,
     }
     reportedSkips.add(identifier)
     const result = { passed: false, skipped: true } as unknown as Frameworks.TestResult
-    reportChain = reportChain.then(async () => {
+    return enqueueReport(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}`)
-    })
-    return reportChain
+    }, `skipped test '${identifier}'`)
 }
 
 /**

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'
@@ -144,6 +146,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