diff --git a/.changeset/pr-273.md b/.changeset/pr-273.md new file mode 100644 index 00000000..73642b05 --- /dev/null +++ b/.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. diff --git a/packages/browserstack-service/src/cli/frameworks/testFramework.ts b/packages/browserstack-service/src/cli/frameworks/testFramework.ts index f291505c..3e9404b2 100644 --- a/packages/browserstack-service/src/cli/frameworks/testFramework.ts +++ b/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} + */ + async settleTestFinishes(): Promise {} + /** * run test hooks * @param {TestFrameworkInstance} instance diff --git a/packages/browserstack-service/src/cli/frameworks/wdioMochaTestFramework.ts b/packages/browserstack-service/src/cli/frameworks/wdioMochaTestFramework.ts index b5706ee2..6a6abd8f 100644 --- a/packages/browserstack-service/src/cli/frameworks/wdioMochaTestFramework.ts +++ b/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() + /** + * 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() + /** + * 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>() + /** The attempt a source's LOG_REPORT/POST resolved; its TEST/POST passes the same `test` object. */ + private resolvedFinishes = new WeakMap() + + /** 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 = {}) { 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) { + 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() + 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): 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 { + 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 diff --git a/packages/browserstack-service/src/cli/skipReporter.ts b/packages/browserstack-service/src/cli/skipReporter.ts index 14bdc562..71a8fc96 100644 --- a/packages/browserstack-service/src/cli/skipReporter.ts +++ b/packages/browserstack-service/src/cli/skipReporter.ts @@ -32,6 +32,23 @@ const reportedSkips = new Set() // tracker's single mutable per-worker instance — serialize every report through one chain let reportChain: Promise = 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, what: string): Promise { + 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 { + 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}'`) } /** diff --git a/packages/browserstack-service/src/reporter.ts b/packages/browserstack-service/src/reporter.ts index d9449827..55cca7e7 100644 --- a/packages/browserstack-service/src/reporter.ts +++ b/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 diff --git a/packages/browserstack-service/src/service.ts b/packages/browserstack-service/src/service.ts index 9c89a4d4..50dc9ae5 100644 --- a/packages/browserstack-service/src/service.ts +++ b/packages/browserstack-service/src/service.ts @@ -36,7 +36,7 @@ import { EVENTS } from './instrumentation/performance/constants.js' import { BrowserstackCLI } from './cli/index.js' import { TestFrameworkState } from './cli/states/testFrameworkState.js' import { HookState } from './cli/states/hookState.js' -import { markTestStarted, reportSuiteSkipped } from './cli/skipReporter.js' +import { drainSkipReports, markTestStarted, reportSuiteSkipped } from './cli/skipReporter.js' import { AutomationFrameworkState } from './cli/states/automationFrameworkState.js' import TestFramework from './cli/frameworks/testFramework.js' import { TestFrameworkConstants } from './cli/frameworks/constants/testFrameworkConstants.js' @@ -541,6 +541,20 @@ export default class BrowserstackService implements Services.ServiceInstance { try { if (BrowserstackCLI.getInstance().isRunning()) { + // SDK-7843: a test that timed out is reported when mocha failed it, and the reporter + // queues that report on the skip-report chain; wait for the chain, then finish a + // failed test nothing reported (no reporter registered), before EXECUTE/POST, where + // the session status is marked from the results recorded so far + try { + await drainSkipReports() + } catch (drainErr) { + BStackLogger.debug(`Exception draining reports in after(): ${util.format(drainErr)}`) + } + try { + await BrowserstackCLI.getInstance().getTestFramework()?.settleTestFinishes() + } catch (settleErr) { + BStackLogger.debug(`Exception settling test finishes in after(): ${util.format(settleErr)}`) + } await BrowserstackCLI.getInstance().getAutomationFramework()!.trackEvent(AutomationFrameworkState.EXECUTE, HookState.POST, {}) } const { preferScenarioName, setSessionName, setSessionStatus } = this._options diff --git a/packages/browserstack-service/tests/cli/wdioMochaTestFramework.test.ts b/packages/browserstack-service/tests/cli/wdioMochaTestFramework.test.ts new file mode 100644 index 00000000..a207957a --- /dev/null +++ b/packages/browserstack-service/tests/cli/wdioMochaTestFramework.test.ts @@ -0,0 +1,302 @@ +import { describe, expect, it, vi, beforeEach, afterEach } from 'vitest' +import * as bstackLogger from '../../src/bstackLogger.js' +import WdioMochaTestFramework from '../../src/cli/frameworks/wdioMochaTestFramework.js' +import TestFramework from '../../src/cli/frameworks/testFramework.js' +import { TestFrameworkState } from '../../src/cli/states/testFrameworkState.js' +import { HookState } from '../../src/cli/states/hookState.js' +import { BStackLogger as cliLogger } from '../../src/cli/cliLogger.js' +import type { Frameworks } from '@wdio/types' +import * as util from '../../src/util.js' +import { TestFrameworkConstants } from '../../src/cli/frameworks/constants/testFrameworkConstants.js' +import type TestFrameworkInstance from '../../src/cli/instances/testFrameworkInstance.js' +import { drainSkipReports, enqueueReport } from '../../src/cli/skipReporter.js' + +vi.spyOn(bstackLogger.BStackLogger, 'logToFile').mockImplementation(() => {}) + +describe('SDK-7843 — a log written before the first mocha hook is dropped quietly', () => { + let framework: WdioMochaTestFramework + let errorSpy: ReturnType + + beforeEach(() => { + framework = new WdioMochaTestFramework(['WebdriverIO', 'mocha'], {}, 'bin-session-id') + errorSpy = vi.spyOn(cliLogger, 'error').mockImplementation(() => {}) + vi.spyOn(cliLogger, 'info').mockImplementation(() => {}) + vi.spyOn(cliLogger, 'debug').mockImplementation(() => {}) + }) + + afterEach(() => { + vi.restoreAllMocks() + }) + + it('does not log an ERROR for console output from wdio\'s `before` hook', async () => { + // wdio's `before` runs before mocha's `before all`, so no instance is tracked yet. + vi.spyOn(TestFramework, 'getTrackedInstance').mockReturnValue(null as any) + const resolveSpy = vi.spyOn(framework, 'resolveInstance') + + await framework.trackEvent(TestFrameworkState.LOG, HookState.POST, { + logEntry: { kind: 'TEST_LOG', message: '[SelfHealer] Installed', level: 'info', timestamp: new Date().toISOString() } + }) + + expect(errorSpy).not.toHaveBeenCalled() + expect(resolveSpy).not.toHaveBeenCalled() + }) + + it('still resolves the instance for a log once a test or hook is tracked', async () => { + vi.spyOn(TestFramework, 'getTrackedInstance').mockReturnValue({} as any) + const resolveSpy = vi.spyOn(framework, 'resolveInstance').mockReturnValue(null) + + await framework.trackEvent(TestFrameworkState.LOG, HookState.POST, { logEntry: {} }) + + expect(resolveSpy).toHaveBeenCalledOnce() + }) + + it('still reports a missing instance for non-log events', async () => { + vi.spyOn(TestFramework, 'getTrackedInstance').mockReturnValue(null as any) + + await framework.trackEvent(TestFrameworkState.TEST, HookState.POST, {}) + + expect(errorSpy).toHaveBeenCalledWith(expect.stringContaining('resolveInstance: unable to resolve/create instance')) + }) +}) + +/** + * SDK-7843 — when a mocha test hits its timeout, mocha fails it (the reporter's `fail`) while its + * body and wdio's afterTest are still pending, and moves on. These drive the real framework in + * that order and record what the product modules (TestHubModule, AutomateModule) would observe. + */ +describe('WdioMochaTestFramework — a test finish is reported once, against its own test run', () => { + let framework: WdioMochaTestFramework + let finishes: string[] + + const runnable = () => ({ state: undefined as string | undefined, timedOut: false, duration: 0, timeout: () => 10000 }) + const makeTest = (title: string, extra: Record = {}) => + ({ title, parent: 'Suite', file: '/spec.js', body: '', ctx: { test: runnable() }, ...extra }) as unknown as Frameworks.Test + const failed = { passed: false, error: new Error('Timeout of 10000ms exceeded.'), duration: 10001, retries: { attempts: 0, limit: 0 }, exception: '', status: 'failed' } as Frameworks.TestResult + const passed = { passed: true, duration: 40000, retries: { attempts: 0, limit: 0 }, exception: '', status: 'passed' } as Frameworks.TestResult + + const start = async (test: Frameworks.Test) => { + await framework.trackEvent(TestFrameworkState.INIT_TEST, HookState.PRE, { test }) + await framework.trackEvent(TestFrameworkState.TEST, HookState.PRE, { test, suiteTitle: 'Suite' }) + return TestFramework.getState(TestFramework.getTrackedInstance(), TestFrameworkConstants.KEY_TEST_UUID) as string + } + const afterTest = async (test: Frameworks.Test, result: Frameworks.TestResult) => { + await framework.trackEvent(TestFrameworkState.LOG_REPORT, HookState.POST, { test, result }) + await framework.trackEvent(TestFrameworkState.TEST, HookState.POST, { test, result, suiteTitle: 'Suite' }) + } + /** What the reporter does in `fail`: pin the test, then queue its finish; wdio does not await it. */ + const reporterFail = (test: Frameworks.Test, result = failed) => { + framework.pinFailedAttempt(test) + void 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 }) + }, test.title) + } + /** service.after(): drain the report chain, then settle. */ + const settle = async () => { + await drainSkipReports() + await framework.settleTestFinishes() + } + + beforeEach(() => { + TestFramework.instances.clear() + framework = new WdioMochaTestFramework(['WebdriverIO-mocha'], { 'WebdriverIO-mocha': '9' }, 'bin-session-id') + finishes = [] + vi.spyOn(util, 'getMochaTestHierarchy').mockReturnValue([]) + vi.spyOn(util, 'getTestTags').mockReturnValue([]) + for (const level of ['info', 'debug', 'error'] as const) { + vi.spyOn(cliLogger, level).mockImplementation(() => {}) + } + // record the TEST/POST each product module would observe, with the test run it closes; + // the modules' gRPC sends take real time, so an instant mock would hide a missing wait + vi.spyOn(framework, 'runHooks').mockImplementation(async (instance: TestFrameworkInstance, state: State, hook: State, args: unknown) => { + if (state === TestFrameworkState.TEST && hook === HookState.POST) { + const { test, result } = args as { test: Frameworks.Test, result: Frameworks.TestResult } + const uuid = TestFramework.getState(instance, TestFrameworkConstants.KEY_TEST_UUID) + await new Promise((resolve) => setTimeout(resolve, 20)) + finishes.push(`${test.title} ${uuid} passed=${result.passed}`) + } + }) + }) + + afterEach(() => { + vi.restoreAllMocks() + TestFramework.instances.clear() + }) + + it('reports a timed-out test from mocha\'s `fail`, and drops its late afterTest', async () => { + const test = makeTest('times out') + const uuid = await start(test) + + reporterFail(test) + await settle() + expect(finishes).toEqual([`times out ${uuid} passed=false`]) + + // the body finished late and succeeded: wdio's afterTest says passed + await afterTest(test, passed) + expect(finishes).toEqual([`times out ${uuid} passed=false`]) + }) + + it('reports a normal failure from afterTest, and drops the `fail` that follows it', async () => { + const test = makeTest('fails') + const uuid = await start(test) + + await afterTest(test, { ...failed, error: new Error('expected 1 to equal 2') }) + reporterFail(test) + await settle() + + expect(finishes).toEqual([`fails ${uuid} passed=false`]) + }) + + it('closes a late afterTest against its own test run while the next test holds the slot', async () => { + const first = makeTest('times out') + const firstUuid = await start(first) + const next = makeTest('next test') + const nextUuid = await start(next) + + await afterTest(first, failed) + + expect(finishes).toEqual([`times out ${firstUuid} passed=false`]) + // the running test keeps its own test run + expect(TestFramework.getState(TestFramework.getTrackedInstance(), TestFrameworkConstants.KEY_TEST_UUID)).toBe(nextUuid) + }) + + it('without a reporter, keeps mocha\'s failure when the late afterTest says passed', async () => { + const test = makeTest('times out then succeeds') + const uuid = await start(test) + + Object.assign(test.ctx!.test as object, { state: 'failed', timedOut: true, duration: 10001 }) + await afterTest(test, passed) + + expect(finishes).toEqual([`times out then succeeds ${uuid} passed=false`]) + }) + + it('without a reporter, settle finishes a test mocha already failed, from its runnable', async () => { + const timedOut = makeTest('times out unreported') + const timedOutUuid = await start(timedOut) + Object.assign(timedOut.ctx!.test as object, { state: 'failed', timedOut: true, duration: 10001 }) + const running = makeTest('still running') + await start(running) + const loadResult = vi.spyOn(framework, 'loadTestResult') + + await settle() + + expect(finishes).toEqual([`times out unreported ${timedOutUuid} passed=false`]) + expect(loadResult).toHaveBeenCalledWith(expect.anything(), expect.objectContaining({ + result: expect.objectContaining({ error: new Error('Timeout of 10000ms exceeded.') }) + })) + }) + + it('keeps each retried attempt on its own test run', async () => { + const attempt0 = makeTest('flaky', { _currentRetry: 0 }) + const uuid0 = await start(attempt0) + const attempt1 = makeTest('flaky', { _currentRetry: 1 }) + const uuid1 = await start(attempt1) + + // attempt 0's late afterTest, then attempt 1 times out too + await afterTest(attempt0, failed) + reporterFail(makeTest('flaky', { _currentRetry: 1 })) + await settle() + + expect(finishes).toEqual([`flaky ${uuid0} passed=false`, `flaky ${uuid1} passed=false`]) + }) + + // mocha retries a timed-out attempt without failing it: it emits `retry`, not `fail`, and + // leaves the attempt's runnable `state` unset + it('without a reporter, settle finishes a retried attempt whose body never returned', async () => { + const fn = () => {} + const attempt0 = makeTest('flaky', { fn, _currentRetry: 0 }) + const uuid0 = await start(attempt0) + Object.assign(attempt0.ctx!.test as object, { timedOut: true, duration: 10001 }) + const attempt1 = makeTest('flaky', { fn, _currentRetry: 1 }) + const uuid1 = await start(attempt1) + await afterTest({ ...attempt1 } as Frameworks.Test, passed) + + await settle() + + expect(finishes).toEqual([`flaky ${uuid1} passed=true`, `flaky ${uuid0} passed=false`]) + }) + + it('keeps a retried attempt failed when its late afterTest says passed', async () => { + const fn = () => {} + const attempt0 = makeTest('flaky', { fn, _currentRetry: 0 }) + const uuid0 = await start(attempt0) + Object.assign(attempt0.ctx!.test as object, { timedOut: true, duration: 10001 }) + await start(makeTest('flaky', { fn, _currentRetry: 1 })) + + await afterTest({ ...attempt0 } as Frameworks.Test, passed) + + expect(finishes).toEqual([`flaky ${uuid0} passed=false`]) + }) + + it('closes a late afterTest by its own test when tests share one body', async () => { + // for (const c of cases) it(c.name, sharedFn) + const fn = () => {} + const first = makeTest('case a', { fn }) + const firstUuid = await start(first) + Object.assign(first.ctx!.test as object, { state: 'failed', timedOut: true, duration: 10001 }) + const second = makeTest('case b', { fn }) + const secondUuid = await start(second) + + await afterTest({ ...first } as Frameworks.Test, passed) + await afterTest({ ...second } as Frameworks.Test, failed) + + expect(finishes).toEqual([`case a ${firstUuid} passed=false`, `case b ${secondUuid} passed=false`]) + }) + + // `attemptKey` holds only the immediate parent's title, so these share `valid - works`: + // describe('login', () => describe('valid', () => it('works'))) and the same under 'signup' + it('reports a later test that shares an earlier finished test\'s key', async () => { + const first = makeTest('works', { parent: 'valid' }) + const firstUuid = await start(first) + await afterTest(first, passed) + const second = makeTest('works', { parent: 'valid' }) + const secondUuid = await start(second) + await afterTest(second, failed) + + expect(finishes).toEqual([`works ${firstUuid} passed=true`, `works ${secondUuid} passed=false`]) + }) + + it('closes a late afterTest by the test\'s body when a same-named test has started since', async () => { + // wdio hands beforeTest and afterTest separate copies of the mocha test; both carry its fn + const first = makeTest('works', { parent: 'valid', fn: () => {} }) + const firstUuid = await start(first) + reporterFail(makeTest('works', { parent: 'valid' })) + await settle() + const second = makeTest('works', { parent: 'valid', fn: () => {} }) + const secondUuid = await start(second) + + // the first test's body finishes late (and succeeds) while the second test is running; the + // second then fails on its own + await afterTest({ ...first } as Frameworks.Test, passed) + await afterTest({ ...second } as Frameworks.Test, failed) + + expect(finishes).toEqual([`works ${firstUuid} passed=false`, `works ${secondUuid} passed=false`]) + }) + + it('keeps the reporter\'s queued finish on the test it pinned, if a same-named test starts in between', async () => { + const first = makeTest('works', { parent: 'valid', fn: () => {} }) + const firstUuid = await start(first) + const failed1 = makeTest('works', { parent: 'valid' }) + // mocha's `fail`: the reporter pins the test now; its queued finish may run after mocha has + // started the next test + framework.pinFailedAttempt(failed1) + const second = makeTest('works', { parent: 'valid', fn: () => {} }) + const secondUuid = await start(second) + await framework.trackEvent(TestFrameworkState.LOG_REPORT, HookState.POST, { test: failed1, result: failed, fromMochaFail: true }) + await framework.trackEvent(TestFrameworkState.TEST, HookState.POST, { test: failed1, result: failed, fromMochaFail: true }) + await afterTest({ ...second } as Frameworks.Test, passed) + + expect(finishes).toEqual([`works ${firstUuid} passed=false`, `works ${secondUuid} passed=true`]) + }) + + it('drops a `fail` for a test that never started (a hook), and still reports afterTest for one it never saw', async () => { + await start(makeTest('runs')) + + reporterFail(makeTest('"before each" hook for runs')) + await settle() + expect(finishes).toEqual([]) + + await afterTest(makeTest('unseen'), passed) + expect(finishes).toHaveLength(1) + }) +}) diff --git a/packages/browserstack-service/tests/reporter.test.ts b/packages/browserstack-service/tests/reporter.test.ts index 2b2a31c3..ed68e6a5 100644 --- a/packages/browserstack-service/tests/reporter.test.ts +++ b/packages/browserstack-service/tests/reporter.test.ts @@ -6,6 +6,11 @@ import type { StdLog } from '../src/index.js' import TestReporter from '../src/reporter.js' import * as utils from '../src/util.js' import * as bstackLogger from '../src/bstackLogger.js' +import { BrowserstackCLI } from '../src/cli/index.js' +import WdioMochaTestFramework from '../src/cli/frameworks/wdioMochaTestFramework.js' +import { TestFrameworkState } from '../src/cli/states/testFrameworkState.js' +import { HookState } from '../src/cli/states/hookState.js' +import { drainSkipReports, reportSkippedTest } from '../src/cli/skipReporter.js' import TestMetadata from '../src/metadata.js' import { BROWSERSTACK_CENTRAL_USER } from '../src/constants.js' @@ -420,3 +425,102 @@ describe('test-reporter', () => { }) }) + +describe('reporter onTestFail — sends mocha\'s failure through the CLI test events (SDK-7843)', () => { + const timeout = new Error('Timeout of 300000ms exceeded. The execution in the test took too long.') + const testStats = { title: 'should navigate via bottom nav', parent: 'Smoke: Home Navigation', error: timeout, _duration: 300004, retries: 0 } + + const makeReporter = (framework: string) => { + const reporter = new TestReporter({}) + ;(reporter as unknown as { _config: unknown })._config = { framework } + return reporter + } + const mockCli = (isRunning: boolean, trackEvent = vi.fn().mockResolvedValue(undefined), pinFailedAttempt = vi.fn()) => { + vi.spyOn(BrowserstackCLI, 'getInstance').mockReturnValue({ isRunning: () => isRunning, getTestFramework: () => ({ trackEvent, pinFailedAttempt }) } as never) + return trackEvent + } + + afterEach(() => { + vi.restoreAllMocks() + }) + + it('sends LOG_REPORT/POST then TEST/POST with mocha\'s result, under the test\'s identity', async () => { + const trackEvent = mockCli(true) + + await makeReporter('mocha').onTestFail(testStats as never) + + const result = expect.objectContaining({ passed: false, error: timeout, duration: 300004, status: 'failed', exception: timeout.message }) + expect(trackEvent.mock.calls.map(([state, hook]) => `${String(state)}/${String(hook)}`)).toEqual([ + `${TestFrameworkState.LOG_REPORT}/${HookState.POST}`, + `${TestFrameworkState.TEST}/${HookState.POST}` + ]) + for (const [, , args] of trackEvent.mock.calls) { + expect(args).toEqual(expect.objectContaining({ result, fromMochaFail: true })) + expect(WdioMochaTestFramework.attemptKey(args.test)).toBe('Smoke: Home Navigation - should navigate via bottom nav') + } + }) + + it('names a retried attempt the way the service\'s afterTest does', async () => { + const trackEvent = mockCli(true) + + await makeReporter('mocha').onTestFail({ ...testStats, retries: 1 } as never) + + expect(WdioMochaTestFramework.attemptKey(trackEvent.mock.calls[0][2].test)).toBe('Smoke: Home Navigation - should navigate via bottom nav (retry 1)') + expect(WdioMochaTestFramework.attemptKey({ title: testStats.title, parent: testStats.parent, _currentRetry: 1 } as never)) + .toBe('Smoke: Home Navigation - should navigate via bottom nav (retry 1)') + }) + + it('pins the test before queueing its finish, and reports that same test object', async () => { + const order: string[] = [] + const pinFailedAttempt = vi.fn(() => { + order.push('pin') + }) + const trackEvent = mockCli(true, vi.fn(async (state: unknown) => { + order.push(String(state)) + }), pinFailedAttempt) + + await makeReporter('mocha').onTestFail(testStats as never) + + expect(order).toEqual(['pin', String(TestFrameworkState.LOG_REPORT), String(TestFrameworkState.TEST)]) + const pinned = pinFailedAttempt.mock.calls[0][0] + expect(trackEvent.mock.calls.map(([, , args]) => args.test)).toEqual([pinned, pinned]) + expect(trackEvent.mock.calls[0][2].test).toBe(pinned) + }) + + it('queues its finish on the skip-report chain, so a queued skip cannot interleave with it', async () => { + const events: string[] = [] + const trackEvent = vi.fn(async (state: unknown, hook: unknown, args: { test: { title: string } }) => { + events.push(`${args.test.title} ${String(state)}/${String(hook)} start`) + await new Promise((resolve) => setTimeout(resolve, 10)) + events.push(`${args.test.title} ${String(state)}/${String(hook)} end`) + }) + mockCli(true, trackEvent) + const framework = { trackEvent } as never + + // wdio does not await either: the fail, then mocha's skip of a later test + void makeReporter('mocha').onTestFail(testStats as never) + void reportSkippedTest(framework, 'Smoke - skipped later', { title: 'skipped later', parent: 'Smoke' } as never, 'Smoke') + await drainSkipReports() + + const failEnd = events.indexOf(`${testStats.title} ${TestFrameworkState.TEST}/${HookState.POST} end`) + const skipStart = events.indexOf(`skipped later ${TestFrameworkState.INIT_TEST}/${HookState.PRE} start`) + expect(failEnd).toBeGreaterThan(-1) + expect(skipStart).toBeGreaterThan(failEnd) + }) + + it('does nothing on the classic flow, which sets the session status from after(result)', async () => { + const trackEvent = mockCli(false) + + await makeReporter('mocha').onTestFail(testStats as never) + + expect(trackEvent).not.toHaveBeenCalled() + }) + + it('does nothing for other frameworks, whose afterTest is not run after after()', async () => { + const trackEvent = mockCli(true) + + await makeReporter('cucumber').onTestFail(testStats as never) + + expect(trackEvent).not.toHaveBeenCalled() + }) +}) diff --git a/packages/browserstack-service/tests/service.test.ts b/packages/browserstack-service/tests/service.test.ts index f25834aa..c32b603e 100644 --- a/packages/browserstack-service/tests/service.test.ts +++ b/packages/browserstack-service/tests/service.test.ts @@ -1,6 +1,7 @@ import path from 'node:path' import { describe, expect, it, vi, beforeEach, afterEach } from 'vitest' +import type { Frameworks } from '@wdio/types' import got from 'got' import logger from '@wdio/logger' @@ -13,6 +14,7 @@ import WdioCucumberTestFramework from '../src/cli/frameworks/wdioCucumberTestFra import { TestFrameworkState } from '../src/cli/states/testFrameworkState.js' import { HookState } from '../src/cli/states/hookState.js' import TestFramework from '../src/cli/frameworks/testFramework.js' +import { AutomationFrameworkState } from '../src/cli/states/automationFrameworkState.js' import { TestFrameworkConstants } from '../src/cli/frameworks/constants/testFrameworkConstants.js' const jasmineSuiteTitle = 'Jasmine__TopLevel__Suite' @@ -2144,3 +2146,76 @@ describe('cucumber CLI dispatch (binary flow)', () => { }) }) + +/** + * SDK-7843 — with a mocha timeout, mocha fails the test (the reporter sends its finish) while its + * body and wdio's afterTest are still pending; with `bail`, wdio then runs after() before that + * afterTest. after() must let that finish land before EXECUTE/POST, where AutomateModule marks the + * session status. + */ +describe('service after() — settles test finishes before the session status is marked (SDK-7843)', () => { + let events: string[] + let settle: ReturnType + let trackEvent: ReturnType + // restored one by one: vi.restoreAllMocks() would also undo this file's module-wide logger spies + let spies: Array<{ mockRestore: () => void }> + + const makeService = () => new BrowserstackService( + { testObservability: false } as never, + [] as never, + { user: 'foo', key: 'bar', framework: 'mocha', mochaOpts: { bail: true } } as never + ) + + beforeEach(() => { + // this file fakes every timer; the finish below is timed with a real setTimeout + vi.useRealTimers() + events = [] + // the reporter's finish is still being sent when after() starts + settle = vi.fn().mockImplementation(async () => { + await new Promise((resolve) => setTimeout(resolve, 30)) + events.push('settleTestFinishes') + }) + trackEvent = vi.fn().mockImplementation(async (state: unknown, hook: unknown) => { + events.push(`${String(state)}/${String(hook)}`) + }) + spies = [] + spies.push(vi.spyOn(BrowserstackCLI, 'getInstance').mockReturnValue({ + isRunning: () => true, + getTestFramework: () => ({ trackEvent, settleTestFinishes: settle }), + getAutomationFramework: () => ({ + trackEvent: vi.fn().mockImplementation(async (state: unknown, hook: unknown) => { + events.push(`${String(state)}/${String(hook)}`) + }) + }) + } as never)) + spies.push(vi.spyOn(TestFramework, 'getTrackedInstance').mockReturnValue({} as never)) + spies.push(vi.spyOn(TestFramework, 'getState').mockReturnValue('uuid-1' as never)) + }) + + afterEach(() => { + spies.forEach((spy) => spy.mockRestore()) + vi.useFakeTimers().setSystemTime(new Date('2020-01-01')) + }) + + it('settles before EXECUTE/POST', async () => { + await makeService().after(1) + + expect(events).toEqual(['settleTestFinishes', `${AutomationFrameworkState.EXECUTE}/${HookState.POST}`]) + }) + + it('leaves the tracked test run alone in afterTest; the CLI framework picks the test\'s own', async () => { + const setState = vi.spyOn(TestFramework, 'setState') + spies.push(setState) + const service = makeService() + const test = { title: 'times out', parent: 'Suite', ctx: { test: {} } } as unknown as Frameworks.Test + + await service.beforeTest(test) + await service.afterTest(test, undefined as never, { passed: false, error: new Error('Timeout'), duration: 1 } as Frameworks.TestResult) + + expect(setState).not.toHaveBeenCalled() + expect(events.filter((e) => e.startsWith(String(TestFrameworkState.TEST)))).toEqual([ + `${TestFrameworkState.TEST}/${HookState.PRE}`, + `${TestFrameworkState.TEST}/${HookState.POST}` + ]) + }) +})