From 61ac6a7a32d62dd64abe8e4b807fb7f12d28c802 Mon Sep 17 00:00:00 2001 From: YASH JAIN Date: Wed, 5 Aug 2026 01:33:24 +0530 Subject: [PATCH 1/2] fix(browserstack-service): close orphaned cucumber hooks that inflate build duration (SDK-7167) A cucumber hook (typically AFTER_EACH) that emitted HookRunStarted but never its HookRunFinished stayed open on the Test Observability backend until the project's hook timeout (2h), inflating the build duration shown on the new dashboard (customer saw 4h35m for a 2h42m build). Customer SDK debug logs confirmed the drop is client-side: 525 hook starts vs 521 finishes triggered, zero upload failures. Three complementary fixes: - Extend the teardown sweep (previously mocha-only, documented known gap) to cucumber: hook meta is tagged kind/name/hookType/testRunId at start, scenario meta is tagged in beforeScenario and stamped finished in afterScenario, and sweepUnfinished now emits terminal HookRunFinished / TestRunFinished for any started-but-unfinished cucumber entity before the worker's event queue shuts down. - Journal open hook runs like open test runs, so when the worker is killed outright mid-hook (Ctrl-C / CI cancellation) the exit cleanup finalizes the orphaned hook with a HookRunFinished (hook_run envelope) instead of only finalizing the test run. - Guard the cucumber hook 'after' path against a missing start record (skip with a warning instead of emitting an unmatched finish / TypeError), and reset in-flight step state at scenario start so an aborted step can no longer silently drop every later AFTER_EACH hook's events. Verified end-to-end on Automate: interrupting a run mid-After-hook with the published 9.33.0 leaves the hook open (only the test run is finalized); with this fix the exit cleanup finalizes both ("Finalized 2 orphaned test/hook run(s)"). Co-Authored-By: Claude Fable 5 --- .../src/insights-handler.ts | 60 ++++++-- .../src/testOps/listener.ts | 5 + .../src/testOps/openRunsJournal.ts | 45 +++--- packages/browserstack-service/src/types.ts | 3 +- .../tests/insights-handler.test.ts | 128 ++++++++++++++++++ .../tests/testOps/openRunsJournal.test.ts | 19 +++ 6 files changed, 230 insertions(+), 30 deletions(-) diff --git a/packages/browserstack-service/src/insights-handler.ts b/packages/browserstack-service/src/insights-handler.ts index 2fa77c7..1811000 100644 --- a/packages/browserstack-service/src/insights-handler.ts +++ b/packages/browserstack-service/src/insights-handler.ts @@ -254,16 +254,31 @@ class _InsightsHandler { } if (event === 'before') { this.setCurrentHook({ uuid: hookUUID }) - const hookMetaData = { + const hookMetaData: TestMeta = { uuid: hookUUID, startedAt: (new Date()).toISOString(), testRunId: InsightsHandler.currentTest.uuid, - hookType: hookType + hookType: hookType, + // Tag as a hook and stash identity so the teardown sweep can synthesise a + // terminal HookRunFinished if this hook's 'after' event never arrives — + // an orphaned start otherwise holds the hook open until the backend hook + // timeout and inflates the build duration on the dashboard (SDK-7167). + kind: 'hook', + name: this.getCucumberHookName(hookType), + scopes: [this._cucumberData.feature?.name || ''], + fileName: this._cucumberData.uri } this._tests[hookId] = hookMetaData this.listener.hookStarted(this.getHookRunDataForCucumber(hookMetaData, 'HookRunStarted')) } else { + if (!this._tests[hookId]) { + // No stashed start for this hook id: its 'before' event was dropped (e.g. + // classified as a step-level hook then). Emitting a finish the backend cannot + // match to a start would orphan it — skip, mirroring the mocha-path guard. + BStackLogger.warn(`Skipping HookRunFinished for cucumber hook '${hookId}' — no matching HookRunStarted was recorded.`) + return + } this._tests[hookId].finishedAt = (new Date()).toISOString() this.setCurrentHook({ uuid: this._tests[hookId].uuid, finished: true }) this.listener.hookFinished(this.getHookRunDataForCucumber(this._tests[hookId], 'HookRunFinished', result)) @@ -497,9 +512,10 @@ class _InsightsHandler { * test/hook so the backend closes the entity instead of leaving it in_progress and * letting the build watchdog inflate the duration. * - * Scoped to mocha. Cucumber hooks are keyed differently (getCucumberHookUniqueId) and - * their lifecycle differs, so they are intentionally left out here — closing them safely - * would need cucumber-specific keying and is a known gap for a follow-up. + * Covers mocha and cucumber. Cucumber entries are keyed by hook-definition id / scenario + * unique id rather than title, but both stash kind + identity at start time, so the same + * kind-tag scan closes them (SDK-7167: an AFTER_EACH hook whose finish was never emitted + * held the hook open until the backend's 2h hook timeout, inflating the build duration). * * Each entry was tagged with kind at start time so we emit HookRunFinished for hooks and * TestRunFinished for tests without re-deriving the kind from the title. Entries without a @@ -508,7 +524,7 @@ class _InsightsHandler { * entity lands in a terminal state rather than pending. */ public async sweepUnfinished() { - if (this._framework !== 'mocha') { + if (this._framework !== 'mocha' && this._framework !== 'cucumber') { return } @@ -516,8 +532,8 @@ class _InsightsHandler { const meta = this._tests[fullTitle] // Already finished, or no kind tag — nothing to sweep. // - // Kind-less entries are CLI/gRPC-path tests seeded by setTestData (cucumber/legacy - // entries are also kind-less and skipped for the same reason). A CLI-path test's + // Kind-less entries are CLI/gRPC-path tests seeded by setTestData (legacy entries + // are also kind-less and skipped for the same reason). A CLI-path test's // test_run lifecycle is owned by the binary (trackEvent -> gRPC -> stopBinSession), NOT // the JS listener pipeline this sweep emits on. Sweeping them would double-emit a finish // on a transport that never opened them, so they are correctly skipped here. Any genuine @@ -597,7 +613,14 @@ class _InsightsHandler { } if (meta.kind === 'hook') { - testData.hook_type = meta.name ? getHookType(meta.name.toLowerCase()) : 'undefined' + // Cucumber hook meta stashes the classified hookType directly; mocha hook meta + // only has the title-derived name, so fall back to parsing it. + testData.hook_type = meta.hookType || (meta.name ? getHookType(meta.name.toLowerCase()) : 'undefined') + // Cucumber hooks carry the owning test-run id — keep it so the backend can + // attribute the synthetic finish to the right scenario. + if (meta.testRunId) { + testData.test_run_id = meta.testRunId + } } return testData @@ -621,13 +644,24 @@ class _InsightsHandler { this._cucumberData.scenario = world.pickle this._cucumberData.scenariosStarted = true this._cucumberData.stepsStarted = false + // No step can be in flight at scenario start. A step whose afterStep never fired + // (aborted/killed mid-step) would otherwise leave a stale entry here for the rest of + // the worker, misclassifying every later scenario's AFTER_EACH hooks as step-level + // and silently dropping their events. + this._cucumberData.steps = [] const pickleData = world.pickle const gherkinDocument = world.gherkinDocument const featureData = gherkinDocument.feature const uniqueId = getUniqueIdentifierForCucumber(world) const testMetaData: TestMeta = { uuid: uuid, - startedAt: (new Date()).toISOString() + startedAt: (new Date()).toISOString(), + // Tag as a test and stash identity so the teardown sweep can synthesise a terminal + // TestRunFinished if this scenario never reaches afterScenario (SDK-7167). + kind: 'test', + name: pickleData?.name, + scopes: [featureData?.name || ''], + fileName: gherkinDocument?.uri } if (pickleData) { @@ -650,6 +684,12 @@ class _InsightsHandler { async afterScenario (world: ITestCaseHookParameter) { this._cucumberData.scenario = undefined + // Stamp the finish on the stashed meta so the teardown sweep recognises this scenario + // as closed and does not double-emit a synthetic TestRunFinished for it. + const uniqueId = getUniqueIdentifierForCucumber(world) + if (this._tests[uniqueId]) { + this._tests[uniqueId].finishedAt = (new Date()).toISOString() + } this.flushCBTDataQueue() this.listener.testFinished(this.getTestRunDataForCucumber(world, 'TestRunFinished')) } diff --git a/packages/browserstack-service/src/testOps/listener.ts b/packages/browserstack-service/src/testOps/listener.ts index 29ec61e..699ae7b 100644 --- a/packages/browserstack-service/src/testOps/listener.ts +++ b/packages/browserstack-service/src/testOps/listener.ts @@ -79,6 +79,10 @@ class Listener { if (!shouldProcessEventForTesthub('HookRunStarted')) { return } + // Journal the open hook (same as testStarted) so an interrupted run's exit + // cleanup can finalize it — an orphaned HookRunStarted otherwise stays open + // until the backend hook timeout and inflates the build duration (SDK-7167). + recordOpenRun(hookData) this.hookStartedStats.triggered() this.sendBatchEvents(this.getEventForHook('HookRunStarted', hookData)) } catch (e) { @@ -92,6 +96,7 @@ class Listener { if (!shouldProcessEventForTesthub('HookRunFinished')) { return } + clearOpenRun(hookData.uuid) this.hookFinishedStats.triggered(hookData.result) this.sendBatchEvents(this.getEventForHook('HookRunFinished', hookData)) } catch (e) { diff --git a/packages/browserstack-service/src/testOps/openRunsJournal.ts b/packages/browserstack-service/src/testOps/openRunsJournal.ts index b4119e8..9d2f62c 100644 --- a/packages/browserstack-service/src/testOps/openRunsJournal.ts +++ b/packages/browserstack-service/src/testOps/openRunsJournal.ts @@ -7,11 +7,14 @@ import { DATA_BATCH_ENDPOINT } from '../constants.js' import { BStackLogger } from '../bstackLogger.js' /** - * Crash-resilient journal of test runs that have sent TestRunStarted but not yet - * TestRunFinished. Each open run is persisted as a small file so that if the worker - * (or the whole wdio process tree) is killed mid-test, the launcher's shutdown path - * or the detached exit cleanup can still send a synthetic TestRunFinished — otherwise - * the test case stays "in progress" on the Test Reporting & Analytics dashboard forever. + * Crash-resilient journal of test and hook runs that have sent TestRunStarted / + * HookRunStarted but not yet the matching finish. Each open run is persisted as a small + * file so that if the worker (or the whole wdio process tree) is killed mid-test or + * mid-hook, the launcher's shutdown path or the detached exit cleanup can still send a + * synthetic TestRunFinished / HookRunFinished — otherwise the entity stays "in progress" + * on the Test Reporting & Analytics dashboard until the backend watchdog times it out, + * inflating the reported build duration (SDK-7167: an orphaned AFTER_EACH cucumber hook + * added its 2h hook timeout to the build's duration on the new dashboard). */ const OPEN_RUNS_DIR = path.join(process.cwd(), 'logs', 'bstack_open_runs') @@ -72,23 +75,27 @@ export async function finalizeOrphanedRuns(): Promise { return 0 } const finishedAt = new Date().toISOString() - const events: UploadType[] = orphans.map((testData) => { - const startedAtMs = testData.started_at ? new Date(testData.started_at).getTime() : NaN - return { - event_type: 'TestRunFinished', - test_run: { - ...testData, - finished_at: finishedAt, - result: 'failed', - duration_in_ms: Number.isNaN(startedAtMs) ? undefined : Math.max(0, Date.now() - startedAtMs), - failure: [{ backtrace: [ORPHAN_FAILURE_REASON] }], - failure_reason: ORPHAN_FAILURE_REASON, - failure_type: 'UnhandledError' - } + const events: UploadType[] = orphans.map((runData) => { + const startedAtMs = runData.started_at ? new Date(runData.started_at).getTime() : NaN + const finishedRun = { + ...runData, + finished_at: finishedAt, + result: 'failed', + duration_in_ms: Number.isNaN(startedAtMs) ? undefined : Math.max(0, Date.now() - startedAtMs), + failure: [{ backtrace: [ORPHAN_FAILURE_REASON] }], + failure_reason: ORPHAN_FAILURE_REASON, + failure_type: 'UnhandledError' } + // Hook payloads carry type 'hook' (same discriminator the listener uses to pick + // the hook_run/test_run envelope key) — finalize them as HookRunFinished so the + // backend closes the hook instead of dropping an unknown test_run uuid. + if (runData.type === 'hook') { + return { event_type: 'HookRunFinished', hook_run: finishedRun } + } + return { event_type: 'TestRunFinished', test_run: finishedRun } }) await batchAndPostEvents(DATA_BATCH_ENDPOINT, 'ORPHANED_TEST_RUN_FINALIZATION', events) - BStackLogger.info(`Finalized ${events.length} orphaned test run(s) left behind by an interrupted run`) + BStackLogger.info(`Finalized ${events.length} orphaned test/hook run(s) left behind by an interrupted run`) return events.length } catch (e) { BStackLogger.debug('openRunsJournal: failed to finalize orphaned runs: ' + e) diff --git a/packages/browserstack-service/src/types.ts b/packages/browserstack-service/src/types.ts index d01b9d8..daa9a28 100644 --- a/packages/browserstack-service/src/types.ts +++ b/packages/browserstack-service/src/types.ts @@ -256,7 +256,8 @@ export interface TestMeta { testRunId?: string, // Explicitly records whether this entry is a hook or a test so a teardown sweep can emit the // correct synthetic finish event without re-deriving the kind from the title. Tagged at - // beforeHook/beforeTest time. Only used for the mocha never-finished sweep. + // beforeHook/beforeTest/processCucumberHook/beforeScenario time. Only used for the + // never-finished sweep (mocha and cucumber). kind?: 'hook' | 'test', // Identity captured at start time so the sweep can build a terminal finish payload without the // live framework test object (which is gone by teardown). diff --git a/packages/browserstack-service/tests/insights-handler.test.ts b/packages/browserstack-service/tests/insights-handler.test.ts index 521c9ea..9dfe28a 100644 --- a/packages/browserstack-service/tests/insights-handler.test.ts +++ b/packages/browserstack-service/tests/insights-handler.test.ts @@ -140,6 +140,8 @@ describe('afterScenario', () => { insightsHandler.afterScenario({ pickle: { name: 'pickle-name', + uri: 'uri', + astNodeIds: ['1'], tags: [] }, gherkinDocument: { @@ -152,6 +154,16 @@ describe('afterScenario', () => { } as any) expect(insightsHandler['getTestRunDataForCucumber']).toBeCalledTimes(1) }) + + it('stamps finishedAt on the stashed scenario meta so the teardown sweep skips it', () => { + vi.spyOn(utils, 'getUniqueIdentifierForCucumber').mockReturnValue('scenario-unique-id') + insightsHandler['_tests']['scenario-unique-id'] = { uuid: 'uuid1', startedAt: '2020-01-01T00:00:00.000Z', kind: 'test' } + insightsHandler.afterScenario({ + pickle: { name: 'pickle-name', uri: 'uri', astNodeIds: ['1'], tags: [] }, + gherkinDocument: { uri: '', feature: { name: 'feature-name', description: '' } } + } as any) + expect(insightsHandler['_tests']['scenario-unique-id'].finishedAt).toBeTruthy() + }) }) describe('beforeStep', () => { @@ -855,6 +867,122 @@ describe('processCucumberHook', function () { insightsHandler['processCucumberHook'](undefined, { event: 'after' }, resultObj as any) expect(sendHookRunEventSpy).toBeCalledWith(hookObj, 'HookRunFinished', resultObj) }) + + it('tags the stashed meta as a hook (with identity) on the before event so the sweep can close it', function () { + cucumberHookTypeSpy.mockReturnValue('AFTER_EACH') + cucumberHookUniqueIdSpy.mockReturnValue('hook_unique_id') + InsightsHandler['currentTest'].uuid = 'test_uuid' + insightsHandler['processCucumberHook']({ id: '1', hookId: 'hook_unique_id' } as any, { event: 'before', hookUUID: 'hook_uuid' }) + const meta = insightsHandler['_tests']['hook_unique_id'] + expect(meta.kind).toBe('hook') + expect(meta.hookType).toBe('AFTER_EACH') + expect(meta.uuid).toBe('hook_uuid') + expect(meta.startedAt).toBeTruthy() + }) + + it('skips the after event (no unmatched finish) when no start was recorded for the hook id', function () { + cucumberHookTypeSpy.mockReturnValue('AFTER_EACH') + cucumberHookUniqueIdSpy.mockReturnValue('unseen_hook_id') + const hookFinishedSpy = vi.spyOn(insightsHandler['listener'], 'hookFinished').mockImplementation(() => {}) + insightsHandler['processCucumberHook']({ id: '1', hookId: 'unseen_hook_id' } as any, { event: 'after' }, { passed: true } as any) + expect(hookFinishedSpy).toBeCalledTimes(0) + hookFinishedSpy.mockRestore() + }) +}) + +describe('sweepUnfinished - cucumber', function () { + let handler: InsightsHandler + let hookFinishedSpy, testFinishedSpy + + beforeEach(() => { + handler = new InsightsHandler(browser, 'cucumber') + hookFinishedSpy = vi.spyOn(handler['listener'], 'hookFinished').mockImplementation(() => {}) + testFinishedSpy = vi.spyOn(handler['listener'], 'testFinished').mockImplementation(() => {}) + }) + + afterEach(() => { + hookFinishedSpy.mockRestore() + testFinishedSpy.mockRestore() + }) + + it('emits a terminal HookRunFinished for a started-but-unfinished cucumber hook', async () => { + handler['_tests']['cucumber-hook-def-id'] = { + uuid: 'hook-uuid-1', + startedAt: '2020-01-01T00:00:00.000Z', + kind: 'hook', + hookType: 'AFTER_EACH', + name: 'AFTER_EACH for my scenario', + testRunId: 'test-run-uuid-1', + scopes: ['my feature'], + fileName: 'features/my.feature' + } + await handler.sweepUnfinished() + expect(hookFinishedSpy).toBeCalledTimes(1) + const payload = hookFinishedSpy.mock.calls[0][0] as any + expect(payload.uuid).toBe('hook-uuid-1') + expect(payload.type).toBe('hook') + expect(payload.result).toBe('failed') + expect(payload.hook_type).toBe('AFTER_EACH') + expect(payload.test_run_id).toBe('test-run-uuid-1') + expect(payload.finished_at).toBeTruthy() + // marked finished so a second sweep pass will not re-emit + expect(handler['_tests']['cucumber-hook-def-id'].finishedAt).toBeTruthy() + }) + + it('does not sweep a cucumber hook that finished normally', async () => { + handler['_tests']['cucumber-hook-def-id'] = { + uuid: 'hook-uuid-1', + startedAt: '2020-01-01T00:00:00.000Z', + finishedAt: '2020-01-01T00:00:01.000Z', + kind: 'hook', + hookType: 'AFTER_EACH' + } + await handler.sweepUnfinished() + expect(hookFinishedSpy).toBeCalledTimes(0) + }) + + it('emits a terminal TestRunFinished for a started-but-unfinished scenario', async () => { + handler['_tests']['scenario-unique-id'] = { + uuid: 'scenario-uuid-1', + startedAt: '2020-01-01T00:00:00.000Z', + kind: 'test', + name: 'my scenario', + scopes: ['my feature'], + fileName: 'features/my.feature' + } + await handler.sweepUnfinished() + expect(testFinishedSpy).toBeCalledTimes(1) + const payload = testFinishedSpy.mock.calls[0][0] as any + expect(payload.uuid).toBe('scenario-uuid-1') + expect(payload.type).toBe('test') + expect(payload.result).toBe('failed') + }) + + it('skips kind-less legacy entries', async () => { + handler['_tests']['legacy-entry'] = { + uuid: 'legacy-uuid', + startedAt: '2020-01-01T00:00:00.000Z' + } + await handler.sweepUnfinished() + expect(hookFinishedSpy).toBeCalledTimes(0) + expect(testFinishedSpy).toBeCalledTimes(0) + }) +}) + +describe('beforeScenario resets in-flight step state', function () { + it('clears stale steps left by an aborted step so hook classification stays correct', async () => { + const handler = new InsightsHandler(browser, 'cucumber') + vi.spyOn(utils, 'getUniqueIdentifierForCucumber').mockReturnValue('scenario-unique-id') + handler['getTestRunDataForCucumber'] = vi.fn() as any + handler['_cucumberData'].steps = [{ id: 'stale-step' } as any] + await handler.beforeScenario({ + pickle: { name: 'pickle-name', uri: 'uri', astNodeIds: ['1'], tags: [] }, + gherkinDocument: { uri: 'features/my.feature', feature: { name: 'feature-name', description: '' } } + } as any) + expect(handler['_cucumberData'].steps).toEqual([]) + const meta = handler['_tests']['scenario-unique-id'] + expect(meta.kind).toBe('test') + }) }) describe('sendCBTInfo', () => { diff --git a/packages/browserstack-service/tests/testOps/openRunsJournal.test.ts b/packages/browserstack-service/tests/testOps/openRunsJournal.test.ts index d7b2dfa..2da8ab0 100644 --- a/packages/browserstack-service/tests/testOps/openRunsJournal.test.ts +++ b/packages/browserstack-service/tests/testOps/openRunsJournal.test.ts @@ -113,6 +113,25 @@ describe('openRunsJournal', () => { expect(event.test_run.duration_in_ms).toBeGreaterThanOrEqual(5000) }) + it('posts a failed HookRunFinished (hook_run envelope) for an orphaned hook', async () => { + const startedAt = new Date(Date.now() - 5000).toISOString() + mockFs.existsSync.mockReturnValueOnce(true) + mockFs.readdirSync.mockReturnValueOnce(['open-run-h.json'] as any) + mockFs.readFileSync.mockReturnValueOnce(JSON.stringify({ uuid: 'h', type: 'hook', hook_type: 'AFTER_EACH', name: 'AFTER_EACH for scenario', started_at: startedAt })) + const batchSpy = vi.spyOn(utils, 'batchAndPostEvents').mockResolvedValueOnce(undefined as any) + + expect(await OpenRunsJournal.finalizeOrphanedRuns()).toBe(1) + + const [, , events] = batchSpy.mock.calls[0] + const event = (events as any)[0] + expect(event.event_type).toBe('HookRunFinished') + expect(event.test_run).toBeUndefined() + expect(event.hook_run.uuid).toBe('h') + expect(event.hook_run.hook_type).toBe('AFTER_EACH') + expect(event.hook_run.result).toBe('failed') + expect(event.hook_run.finished_at).toBeTruthy() + }) + it('swallows upload failures and returns 0', async () => { mockFs.existsSync.mockReturnValueOnce(true) mockFs.readdirSync.mockReturnValueOnce(['open-run-a.json'] as any) From 69ede2a1554f11bc030bc944e89bed1dd53e54d6 Mon Sep 17 00:00:00 2001 From: "github-actions[bot]" <41898282+github-actions[bot]@users.noreply.github.com> Date: Tue, 4 Aug 2026 20:04:08 +0000 Subject: [PATCH 2/2] chore(changeset): auto-generate from PR template (patch) --- .changeset/pr-120.md | 5 +++++ 1 file changed, 5 insertions(+) create mode 100644 .changeset/pr-120.md diff --git a/.changeset/pr-120.md b/.changeset/pr-120.md new file mode 100644 index 0000000..e9eb15c --- /dev/null +++ b/.changeset/pr-120.md @@ -0,0 +1,5 @@ +--- +"@wdio/browserstack-service": patch +--- + +- Fixed inflated build durations on the Test Observability dashboard for WebdriverIO + Cucumber runs: hooks interrupted mid-run are now closed instead of staying "in progress" until the hook timeout.