Skip to content

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

Open
osho-20 wants to merge 3 commits into
mainfrom
fix/sdk-7167-cucumber-hook-duration
Open

fix(browserstack-service): close orphaned cucumber hooks that inflate build duration (SDK-7167)#120
osho-20 wants to merge 3 commits into
mainfrom
fix/sdk-7167-cucumber-hook-duration

Conversation

@osho-20

@osho-20 osho-20 commented Aug 4, 2026

Copy link
Copy Markdown
Collaborator

What is this about?

Fixes incorrect (inflated) build durations on the new Test Observability dashboard for WebdriverIO + Cucumber runs ([Aya] customer report: build showed 4h 35m on the new dashboard vs 2h 42m on the old one).

Root cause: some Cucumber AFTER_EACH hooks emit HookRunStarted but their HookRunFinished is never sent. The backend holds the hook open until the project's hook timeout (2h) and the build watchdog inflates the reported duration. Customer SDK debug logs prove the drop is client-side: hookEvents { started: 525, finished: 521 } with zero upload failures — 4 finish events were never created.

Three complementary fixes:

  1. Teardown sweep now covers Cucumber (was mocha-only; the code documented Cucumber as a known gap). Cucumber hook meta is tagged with kind/name/hookType/testRunId at start, scenario meta is tagged in beforeScenario and stamped finished in afterScenario, and sweepUnfinished() emits a terminal HookRunFinished / TestRunFinished for any started-but-unfinished entity before the worker's event queue shuts down.
  2. Open hook runs are journaled like open test runs, so when the worker is killed outright mid-hook (Ctrl-C / CI cancellation) the detached exit cleanup finalizes the orphaned hook with a HookRunFinished (hook_run envelope). Previously only orphaned test runs were finalized.
  3. Hardening: the cucumber hook after path skips (with a warning) when no start was recorded instead of emitting an unmatched finish / throwing a TypeError, and in-flight step state is reset at scenario start so an aborted step can no longer silently drop every later AFTER_EACH hook's events for the rest of the worker.

End-to-end verification on Automate (minimal WDIO 9 + Cucumber project, run interrupted via SIGINT while the After hook sleeps):

End-to-end verification on Automate — graceful-completion path (no SIGINT; per review 4875326601: adapter-level fault drops the hook's after callback while the worker completes normally; one registered global After hook shared by 2 scenarios, same fault active in both runs; service artifact stock):

Unit tests: 9 new tests (cucumber sweep, hook journaling/finalization, after-path guard, step-state reset). Full vitest suite shows the identical 70 pre-existing environmental failures as clean main — zero regressions. Build + eslint clean.

Related Jira task/s

Release (mandatory for every PR — required for the ready-for-review label)

Version bump: (required — tick exactly one)

  • minor (backwards-compatible feature)
  • patch (bug fix or other small change)

Release notes type: (optional)

  • New Feature
  • Bug Fix
  • Other Improvement

Release notes (customer-facing): (optional but encouraged)

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

Release notes (internal): (required — engineer-facing; what actually changed / why)

  • Extended the mocha-only sweepUnfinished() teardown safety net to Cucumber: hook/scenario meta is tagged with kind + identity at start, afterScenario stamps finishedAt, and the sweep emits terminal HookRunFinished/TestRunFinished for started-but-unfinished cucumber entities (SDK-7167 — orphaned AFTER_EACH starts held hooks open until the 2h backend hook timeout, inflating build duration on the new dashboard).
  • listener.hookStarted/hookFinished now record/clear the open-runs journal, and finalizeOrphanedRuns() emits HookRunFinished (hook_run envelope) for journaled hook entries — so a worker killed outright mid-hook gets its hook finalized by the exit cleanup, not just its test run.
  • Cucumber hook after events with no recorded start are skipped with a warning (no unmatched finish, no TypeError); _cucumberData.steps is reset per scenario so a stuck in-flight step can't misclassify later AFTER_EACH hooks as step-level and silently drop their events.

Checklist

  • Ready to review
  • Has it been tested locally?

PR Validations

Run Tests: Comment RUN_TESTS to trigger sanity tests.

🤖 Generated with Claude Code

… 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 <noreply@anthropic.com>
@osho-20
osho-20 requested a review from a team as a code owner August 4, 2026 20:03
@osho-20 osho-20 added bug Something isn't working ready-for-review labels Aug 4, 2026
@github-actions

github-actions Bot commented Aug 4, 2026

Copy link
Copy Markdown
Contributor

🔴 SDK PR Review gate is red. Pending:

  • The SDK PR Review Agent has not reviewed the current head commit yet — run the SDK PR Review Agent.

It turns green once the latest SDK PR Review Agent run reports GTG on the current head commit. A native reviewer approval is separately required by branch protection before merge.

1 similar comment
@github-actions

github-actions Bot commented Aug 5, 2026

Copy link
Copy Markdown
Contributor

🔴 SDK PR Review gate is red. Pending:

  • The SDK PR Review Agent has not reviewed the current head commit yet — run the SDK PR Review Agent.

It turns green once the latest SDK PR Review Agent run reports GTG on the current head commit. A native reviewer approval is separately required by branch protection before merge.

@anish353

anish353 commented Aug 5, 2026

Copy link
Copy Markdown
Collaborator

RUN_TESTS

@anish353
anish353 requested review from AakashHotchandani and harshit-browserstack and removed request for Dalwin-Barnard and kamal-kaur04 August 5, 2026 13:17
@minionhelperappqa

Copy link
Copy Markdown

[SDK Wdio Test] TRA build state: passed | Stability 100% — verdict: success. Passed: 85, Failed: 0, Aggregate: 85. TRA: https://observability.browserstack.com/builds/mfeml8mrmwyavljudzogob3embvcioqxixiijywg

@harshit-browserstack harshit-browserstack left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

SDK PR Review — 🔴 2 blocking issues

Scope reviewed: 6 files · Risk: Medium · 1 critical, 1 warning, 0 suggestions

Intent as understood: Fixes SDK-7167 — inflated build durations on the TRA dashboard for WebdriverIO + Cucumber. Some Cucumber AFTER_EACH hooks emit HookRunStarted but their HookRunFinished never arrives, so the backend holds the hook in-progress until its 2h timeout and the build watchdog folds that into the reported duration. Three changes: extend the mocha-only sweepUnfinished() teardown net to Cucumber, journal open Cucumber hook runs so a hard-killed worker's exit-cleanup can finalize them, and harden processCucumberHook's after path against a missing before.


🔴 Critical — the cited E2E verification exercises a different code path than the fix it's offered as proof for

packages/browserstack-service/tests/insights-handler.test.ts · describe('sweepUnfinished - cucumber')

The PR body's "End-to-end verification on Automate" runs a minimal WDIO 9 + Cucumber project and interrupts it via SIGINT while the After hook sleeps, showing "Finalized 2 orphaned test/hook run(s)" on the fixed branch vs 1 on unfixed.

But a SIGINT'd process only reaches finalizeOrphanedRuns() — the detached exit-cleanup / next-launch recovery path (cleanup.ts:78, launcher.ts:631). It can never reach sweepUnfinished() (service.ts:657), which runs only from the worker's own in-process, graceful after() completion. A hard-killed process doesn't reach its own graceful after() hook at all. These are two disjoint code paths triggered by two disjoint failure modes.

This matters because the reported symptom — hookEvents { started: 525, finished: 521 }, zero upload failures, on a build that otherwise completed normally — looks much more like the graceful-completion failure mode (sweepUnfinished's target: a hook's own after callback never firing while the worker runs to completion) than the hard-kill mode. If that read is right, the flagship E2E proof demonstrates the secondary journal-based fix, not the primary sweepUnfinished-based one the root-cause narrative centers on.

Separately, none of the 9 new unit tests simulate two sequential hook invocations sharing one hookId — every sweepUnfinished - cucumber test manually seeds a single pre-existing _tests[key] entry. That proves the sweep works for one tracked entry; it can't prove a second orphaned occurrence of the same hookId survives to be swept.

Suggested fix

  1. Add or re-cite an E2E build exercising the graceful path — an After() hook whose body fails in a way that lets the framework continue without ever firing the hook's after callback, rather than a SIGINT — so the worker actually reaches after()sweepUnfinished(). Compare against an unfixed-branch build under that same scenario.
  2. Add a unit test firing two before events for the same hookId with no intervening after, asserting whether the first (now-overwritten) occurrence is still recoverable. That single test also resolves the open question below.

🟠 Warning (needs confirmation) — _tests[hookId] unconditional overwrite may silently discard an earlier orphan

packages/browserstack-service/src/insights-handler.ts · _InsightsHandler.processCucumberHook

In the before branch, this._tests[hookId] = hookMetaData has no guard against clobbering an existing still-open entry at that key. The two identity schemes this PR relies on aren't symmetric:

  • Scenario keygetUniqueIdentifierForCucumber(world) = pickle.uri + '_' + pickle.astNodeIds.join(','). Provably unique per scenario occurrence. ✅
  • Hook keygetCucumberHookUniqueId(hookType, hook) = hook.hookId, forwarded as-is from @wdio/cucumber-framework. Its per-invocation uniqueness can't be established from this repo's source.

If hook.hookId is assigned once per hook registration (Cucumber.js's conventional message-protocol behavior — a Hook's id set at Before()/After() definition time and reused by every scenario invoking it) rather than fresh per invocation, then: scenario N's AFTER_EACH orphans, scenario N+1's before for the same registered hook overwrites _tests[hookId], and N's orphan is gone before sweepUnfinished() — which runs once, at worker teardown — ever inspects it.

The reported build dropped 4 finishes out of 525 starts. If 2+ land on the same registered global hook within one worker, this fix would recover at most the last of them.

The disk-journal path (recordOpenRun/clearOpenRun, keyed by a fresh per-invocation uuid in separate files) is not affected — only the in-process sweepUnfinished() net.

Suggested fix — key _tests for BEFORE_EACH/AFTER_EACH on a composite identifier that's unique regardless of hookId's external semantics, using data already in scope:

const hookKey = `${hookId}_${InsightsHandler.currentTest.uuid}`
this._tests[hookKey] = hookMetaData

(mirroring the same composite key in the after branch's lookup/guard). Alternatively, guard the overwrite itself: before replacing, check whether the existing entry is started-but-unfinished and eagerly emit its terminal HookRunFinished first, mirroring sweepUnfinished()'s own synthetic-finish logic.

Honest confidence note: the overwrite mechanism is provable by reading this repo's code. The external fact the claim hinges on — whether @wdio/cucumber-framework's hook.hookId is per-registration or per-invocation — is not verifiable from this checkout, since the framework isn't vendored here. Two independent review passes pulled the framework's public source and both read it as registration-scoped (cucumberFormatter.ts's onTestStepStarted resolves via this._hookEvent.find(h => h.id === teststep.hookId)), but that's external-library evidence. Flagging it as needs-confirmation rather than asserting it.


Per-file confidence

File Status Reason
src/insights-handler.ts 🔴 Fix 1 hookId keying concern — needs independent confirmation
tests/insights-handler.test.ts 🔴 Fix 1 E2E verification path mismatch — objectively verifiable
src/testOps/listener.ts Reviewed, clean
src/testOps/openRunsJournal.ts Reviewed, clean
src/types.ts Reviewed, clean
tests/testOps/openRunsJournal.test.ts Reviewed, clean

External services

No external-contract shape changes detected — only when existing event types fire. One sub-threshold observation not promoted to a finding: whether the collector accepts HookRunFinished / hook_run payloads batched under the pre-existing 'ORPHANED_TEST_RUN_FINALIZATION' label. Cheap sanity check if you want extra confidence; not blocking.

What's good

  • sweepUnfinished()'s framework guard stays scoped to mocha + cucumber rather than broadening, keeping blast radius tight.
  • The new after-path guard and the afterScenario/uuid checks correctly avoid crashes and unmatched-finish emissions, consistent with the file's existing defensive style.
  • Nine new unit tests give solid breadth across the provably-safe paths (hook tagging, the guard, single-entry sweep for both hook and scenario, step-state reset), backed by real before/after Automate build links.

Open questions

  1. Can you confirm — from @wdio/cucumber-framework / @cucumber/cucumber docs, or a quick instrumented log — whether hook.hookId is the same across two scenarios invoking the same registered Before()/After(), or unique per invocation? This one fact decides whether the warning above is a real gap or a non-issue.
  2. Can the E2E verification be re-run for the graceful-completion path (no SIGINT), to match the customer's actual symptom signature?

Posted as a recommendation, not a merge decision — the review deliberately does not submit an approve/request-changes verdict.

…ation (SDK-7167)

cucumber's hookId is assigned at Before()/After() registration time, so every
scenario invoking the same registered hook shares one _tests key — a still-open
entry orphaned in an earlier scenario was clobbered by the next invocation
before sweepUnfinished() could close it. Suffix the key with the current
scenario's run uuid so each invocation is tracked independently; this also
stops a dropped 'before' from matching a previous scenario's closed entry and
re-emitting its uuid.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
@github-actions

github-actions Bot commented Aug 6, 2026

Copy link
Copy Markdown
Contributor

🔴 SDK PR Review gate is red. Pending:

  • The SDK PR Review Agent has not reviewed the current head commit yet — run the SDK PR Review Agent.

It turns green once the latest SDK PR Review Agent run reports GTG on the current head commit. A native reviewer approval is separately required by branch protection before merge.

@anish353

anish353 commented Aug 6, 2026

Copy link
Copy Markdown
Collaborator

Re: review — both findings verified against primary sources; the warning is a real gap and is now fixed in 88ccf6f.

🟠 Warning — _tests[hookId] overwrite → confirmed and fixed

The open question is settled: hook.hookId is registration-scoped. In @wdio/cucumber-framework's cucumberFormatter.ts, hook steps resolve via this._hookEvent.find(h => h.id === teststep.hookId), and _hookEvent accumulates one Hook envelope per registered Before()/After() (onHook push). Two scenarios invoking the same registered hook therefore share one hookId, and scenario N+1's before clobbered scenario N's still-open orphan before the once-per-worker sweep ran.

FixgetCucumberHookUniqueId now returns `${hookId}_${InsightsHandler.currentTest.uuid}` for BEFORE_EACH/AFTER_EACH (single derivation point, so the before/after branches stay symmetric; currentTest.uuid is set in beforeScenario and stable across a hook's before/after pair). *_ALL hooks keep the feature-scoped key.

This also fixes a latent second defect on the same key: with a registration-scoped key, a dropped before in scenario N+1 made the after branch find scenario N's closed entry and re-emit HookRunFinished with that stale uuid — a duplicate finish. With the composite key the no-start guard now fires correctly.

🔴 Critical — verification gaps → unit-test half closed; graceful-path E2E still open

Added the requested test plus two companions (cucumber hooks sharing one registered hookId across scenarios):

  1. two before events sharing one hookId, no intervening afterboth orphans survive and are swept (this is the test that fails on the previous head);
  2. two full before/after pairs → each after matches its own invocation's uuid, sweep finds nothing;
  3. dropped before in a later scenario → no stale-uuid re-emit.

insights-handler.test.ts 78/78 green; lint + tsc clean; no new failures elsewhere in the suite.

Still open for the PR author: re-run the E2E on the graceful-completion path (no SIGINT — worker reaches after()sweepUnfinished()), matching the customer's symptom signature, and cite before/after builds in the PR body.

@anish353

anish353 commented Aug 6, 2026

Copy link
Copy Markdown
Collaborator

Graceful-path E2E verification (no SIGINT) — closing the remaining critical item from review 4875326601

Setup — minimal WDIO 9 + Cucumber project on Automate (Chrome / Windows 11): 2 scenarios sharing one registered global After hook (so both invocations carry the same registration-scoped hookId — simultaneously exercising the composite-key fix from 88ccf6f). Fault injection lives outside the service, in @wdio/cucumber-framework's wrapStep (env-gated: hooks lose their afterFn dispatch), reproducing exactly the reviewer's requested failure shape — HookRunStarted emitted, the hook's after callback never fires, and the worker runs to graceful completion. The @wdio/browserstack-service artifact is stock in both runs; the identical fault is active in both, so the contrast isolates the fix:

// node_modules/@wdio/cucumber-framework/build/index.js — wrapStep()
const afterFn = process.env.E2E_DROP_HOOK_AFTER === '1' && !isStep ? [] : config.afterHook;

Unfixed (published 9.33.0) — build: https://automation.browserstack.com/builds/qbe0zamxggqm5g5cupde0q0j9cdqjarmpwwpfpuf

hookEvents: {
  started:  { triggeredCount: 2, sentCount: 2, failedCount: 0 },
  finished: { triggeredCount: 0, sentCount: 0, failedCount: 0 }
}

The customer's exact fingerprint (starts > finishes, zero upload failures) on a normally-completing build — both hook runs left open server-side, to be held until the backend hook timeout folds into the build duration.

Fixed (this branch @ 88ccf6f) — build: https://automation.browserstack.com/builds/s6fuyhbqi3icnnsivswvh5nfidsdc8vguqqjryfv

2026-08-06T14:55:52.282Z DEBUG Emitted synthetic HookRunFinished for unfinished 3_dd5323ed-0268-4fea-a297-e0d35abf2734.
2026-08-06T14:55:52.283Z DEBUG Emitted synthetic HookRunFinished for unfinished 3_6a7a9b33-e233-415c-a85e-0df1b894ac48.

hookEvents: {
  started:  { triggeredCount: 2, sentCount: 2, failedCount: 0 },
  finished: { triggeredCount: 2, sentCount: 2, failedCount: 0 }
}

Three things this proves at once:

  1. Right code path: no Finalized N orphaned line anywhere — the journal/exit-cleanup path never ran; these finishes came from sweepUnfinished() on the worker's own graceful after(), matching the customer's symptom signature.
  2. Composite key works live: both synthetic finishes carry the same registered hookId (3) suffixed with two different scenario-run uuids — under the previous bare-hookId keying, scenario 2's before would have clobbered scenario 1's orphan and only one finish could have been recovered.
  3. Fingerprint healed: started == finished == 2, zero upload failures.

O11Y backend state for both builds: terminal, status: passed, 2/2 tests — the delta is confined to hook-run closure, as intended.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

bug Something isn't working ready-for-review

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants