fix(browserstack-service): close orphaned cucumber hooks that inflate build duration (SDK-7167)

.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.

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,16 +524,16 @@ 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
         }
 
         for (const fullTitle of Object.keys(this._tests)) {
             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'))
     }

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) {

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<number> {
             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)

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).

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', () => {