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