diff --git a/.changeset/pr-129.md b/.changeset/pr-129.md new file mode 100644 index 0000000..778b45a --- /dev/null +++ b/.changeset/pr-129.md @@ -0,0 +1,5 @@ +--- +"@wdio/browserstack-service": patch +--- + +- Fixed WebdriverIO (Mocha) builds occasionally being reported as timed out even though the test run finished successfully. diff --git a/packages/browserstack-service/src/cli/modules/testHubModule.ts b/packages/browserstack-service/src/cli/modules/testHubModule.ts index 1d8d33d..859b6da 100644 --- a/packages/browserstack-service/src/cli/modules/testHubModule.ts +++ b/packages/browserstack-service/src/cli/modules/testHubModule.ts @@ -146,10 +146,28 @@ export default class TestHubModule extends BaseModule { const { args } = this.pendingTestFinish this.pendingTestFinish = null this.logger.debug('flushPendingTestFinishEvent: sending deferred TEST/POST event') - return this.sendTestFrameworkEvent(args, { testFrameworkState: 'TEST', testHookState: 'POST' }) + // 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. + const maxAttempts = 3 + const attempt = (n: number): Promise => + 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((resolve) => setTimeout(resolve, 200 * n)).then(() => attempt(n + 1)) + }) + return attempt(1) } - async sendTestFrameworkEvent(args: Record, stateOverride?: { testFrameworkState: string, testHookState: string }) { + async sendTestFrameworkEvent(args: Record, stateOverride?: { testFrameworkState: string, testHookState: string }): Promise { try { const testArgs = args as { test: Frameworks.Test, instance: TestFrameworkInstance } const instance = testArgs.instance as TestFrameworkInstance @@ -185,8 +203,10 @@ export default class TestHubModule extends BaseModule { this.logger.debug(`sendTestFrameworkEvent payload: ${JSON.stringify(payload)}`) await GrpcClient.getInstance().testFrameworkEvent(payload) this.logger.debug(`sendTestFrameworkEvent complete for testState: ${testFrameworkState} hookState: ${testHookState}`) + return true } catch (error) { this.logger.error(`Error in sendTestFrameworkEvent: ${util.format(error)}`) + return false } } diff --git a/packages/browserstack-service/tests/cli/modules/testHubModule.deferredFinish.test.ts b/packages/browserstack-service/tests/cli/modules/testHubModule.deferredFinish.test.ts new file mode 100644 index 0000000..0a8a551 --- /dev/null +++ b/packages/browserstack-service/tests/cli/modules/testHubModule.deferredFinish.test.ts @@ -0,0 +1,195 @@ +import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest' +import TestHubModule from '../../../src/cli/modules/testHubModule.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 { GrpcClient } from '../../../src/cli/grpcClient.js' +import { TestFrameworkConstants } from '../../../src/cli/frameworks/constants/testFrameworkConstants.js' +import type { Frameworks } from '@wdio/types' + +vi.mock('../../../src/cli/frameworks/testFramework.js', () => ({ + default: { + registerObserver: vi.fn(), + getTrackedInstance: vi.fn(), + getState: vi.fn(), + setState: vi.fn(), + hasState: vi.fn() + } +})) + +vi.mock('../../../src/cli/frameworks/automationFramework.js', () => ({ + default: { getTrackedInstance: vi.fn(), getState: vi.fn(), getDriver: vi.fn() } +})) + +vi.mock('../../../src/cli/grpcClient.js', () => ({ + GrpcClient: { getInstance: vi.fn() } +})) + +vi.mock('../../../src/cli/frameworks/wdioMochaTestFramework.js', () => ({ + default: { getLogEntries: vi.fn(), clearLogs: vi.fn() } +})) + +vi.mock('../../../src/cli/cliLogger.js', () => ({ + BStackLogger: { debug: vi.fn(), info: vi.fn(), error: vi.fn(), warn: vi.fn() } +})) + +// Build a mock TestFrameworkInstance sitting at mocha TEST/POST (a finished test whose +// TestRunFinished the module defers past the after-each window). +function makeMochaTestInstance(uuid: string) { + return { + __uuid: uuid, + getContext: () => ({ + getId: () => 'ctx', + getThreadId: () => 'thread-1', + getProcessId: () => 'proc-1' + }), + getAllData: () => new Map([ + [TestFrameworkConstants.KEY_TEST_FRAMEWORK_NAME, 'WebdriverIO-mocha'], + [TestFrameworkConstants.KEY_TEST_FRAMEWORK_VERSION, '9.33.1'], + [TestFrameworkConstants.KEY_TEST_STARTED_AT, '2026-08-10T20:53:00Z'], + [TestFrameworkConstants.KEY_TEST_ENDED_AT, '2026-08-10T20:53:02Z'] + ]), + getRef: () => `ref-${uuid}`, + getCurrentTestState: () => TestFrameworkState.TEST, + getCurrentHookState: () => HookState.POST + } +} + +describe('TestHubModule — deferred last-test-finish delivery (SDK-7265)', () => { + let testHubModule: TestHubModule + let mockGrpcClient: { testFrameworkEvent: ReturnType } + + beforeEach(() => { + vi.clearAllMocks() + process.env.WDIO_WORKER_ID = '0-1' + + mockGrpcClient = { testFrameworkEvent: vi.fn().mockResolvedValue({ success: true }) } + vi.mocked(GrpcClient.getInstance).mockReturnValue(mockGrpcClient as never) + + // KEY_TEST_RESULT_AT present (so onAllTestEvents does not take the "no results" path); + // framework name resolves to mocha; uuid echoes the instance. + vi.mocked(TestFramework.hasState).mockReturnValue(true) + vi.mocked(TestFramework.getState).mockImplementation((instance: any, key: unknown) => { + if (key === TestFrameworkConstants.KEY_TEST_FRAMEWORK_NAME) { + return 'WebdriverIO-mocha' + } + if (key === TestFrameworkConstants.KEY_TEST_DEFERRED) { + return false + } + if (key === TestFrameworkConstants.KEY_TEST_UUID) { + return instance?.__uuid + } + return '' + }) + + testHubModule = new TestHubModule({ enabled: true, hubUrl: 'https://hub.browserstack.com' }) + Object.defineProperty(testHubModule, 'config', { + value: { hubUrl: 'https://hub.browserstack.com' }, + writable: true + }) + }) + + afterEach(() => { + vi.resetAllMocks() + delete process.env.WDIO_WORKER_ID + }) + + it('defers a mocha TEST/POST instead of sending it immediately', () => { + const inst = makeMochaTestInstance('t1') + testHubModule.onAllTestEvents({ instance: inst, test: { title: 't1' } as Frameworks.Test }) + // Held for the after-each window — not yet on the wire. + expect(mockGrpcClient.testFrameworkEvent).not.toHaveBeenCalled() + }) + + it('delivers the deferred finish when the flush send succeeds', async () => { + const inst = makeMochaTestInstance('t1') + testHubModule.onAllTestEvents({ instance: inst, test: { title: 't1' } as Frameworks.Test }) + + await testHubModule.flushPendingTestFinishEvent() + + expect(mockGrpcClient.testFrameworkEvent).toHaveBeenCalledTimes(1) + expect(mockGrpcClient.testFrameworkEvent).toHaveBeenCalledWith( + expect.objectContaining({ testFrameworkState: 'TEST', testHookState: 'POST', uuid: 't1' }) + ) + }) + + // REPRODUCTION: the worker's last test relies on this single best-effort flush (service.after()). + // A transient gRPC failure was swallowed with no retry, so the TestRunFinished never reached the + // binary/backend. The test then stays "in progress" and is reaped by Test Hub's ~60-min per-test + // timeout (TEST_TIMED_OUT_WITH_BUILD_SUCCESS), which stamps the whole build `timeout`. + it('does not drop the last-test finish on a transient send failure — retries the SAME finish until delivered', async () => { + const inst = makeMochaTestInstance('last') + testHubModule.onAllTestEvents({ instance: inst, test: { title: 'last' } as Frameworks.Test }) + + // First attempt fails transiently, second succeeds. + mockGrpcClient.testFrameworkEvent + .mockRejectedValueOnce(new Error('transient gRPC failure')) + .mockResolvedValueOnce({ success: true }) + + await testHubModule.flushPendingTestFinishEvent() + + // Retried (not a single fixed attempt) AND every attempt re-sends the same test's finish — + // distinguishes a real retry-until-delivered from a regressed single-shot send. + expect(mockGrpcClient.testFrameworkEvent).toHaveBeenCalledTimes(2) + for (const call of mockGrpcClient.testFrameworkEvent.mock.calls) { + expect(call[0]).toMatchObject({ uuid: 'last', testFrameworkState: 'TEST', testHookState: 'POST' }) + } + }) + + it('drives the retry budget to exhaustion on sustained failure, then gives up cleanly without re-stashing', async () => { + const inst = makeMochaTestInstance('exhaust') + testHubModule.onAllTestEvents({ instance: inst, test: { title: 'exhaust' } as Frameworks.Test }) + + mockGrpcClient.testFrameworkEvent.mockRejectedValue(new Error('sustained gRPC outage')) + + await expect(testHubModule.flushPendingTestFinishEvent()).resolves.toBeUndefined() + + // All three attempts ran, each re-sending the same finish. + expect(mockGrpcClient.testFrameworkEvent).toHaveBeenCalledTimes(3) + for (const call of mockGrpcClient.testFrameworkEvent.mock.calls) { + expect(call[0]).toMatchObject({ uuid: 'exhaust' }) + } + // An exhausted event must NOT be re-stashed into the shared slot — re-stashing races the + // fire-and-forget flush call sites and can drop a newer test's finish (SDK-7265 review #1). + expect((testHubModule as unknown as { pendingTestFinish: unknown }).pendingTestFinish).toBeNull() + expect(testHubModule.logger.error).toHaveBeenCalledWith( + expect.stringContaining('failed after all retries') + ) + }) + + it('concurrent flushes each deliver their own finish — a retrying older flush never drops a newer test', async () => { + let aAttempts = 0 + mockGrpcClient.testFrameworkEvent.mockImplementation((payload: { uuid: string }) => { + if (payload.uuid === 'A') { + aAttempts += 1 + if (aAttempts === 1) { + return Promise.reject(new Error('transient on A')) + } + } + return Promise.resolve({ success: true }) + }) + + // Test A finishes, is deferred, then flushed fire-and-forget (as the next-test boundary does). + testHubModule.onAllTestEvents({ instance: makeMochaTestInstance('A'), test: { title: 'A' } as Frameworks.Test }) + const flushA = testHubModule.flushPendingTestFinishEvent() // not awaited — A is retrying + + // While A retries, test B finishes, is deferred and flushed. + testHubModule.onAllTestEvents({ instance: makeMochaTestInstance('B'), test: { title: 'B' } as Frameworks.Test }) + await testHubModule.flushPendingTestFinishEvent() // B + await flushA + + const sent = mockGrpcClient.testFrameworkEvent.mock.calls.map((c: unknown[]) => (c[0] as { uuid: string }).uuid) + expect(sent.filter((u) => u === 'A').length).toBe(2) // 1 transient fail + 1 retry success + expect(sent.filter((u) => u === 'B').length).toBe(1) // delivered once, never dropped + }) + + it('clears the pending finish after a flush so it is never sent twice', async () => { + const inst = makeMochaTestInstance('t1') + testHubModule.onAllTestEvents({ instance: inst, test: { title: 't1' } as Frameworks.Test }) + + await testHubModule.flushPendingTestFinishEvent() + await testHubModule.flushPendingTestFinishEvent() // second flush is a no-op + + expect(mockGrpcClient.testFrameworkEvent).toHaveBeenCalledTimes(1) + }) +})