fix(o11y): batch the event flush so command-heavy specs stop hitting spec_timeout [SDK-7399] - #1177
fix(o11y): batch the event flush so command-heavy specs stop hitting spec_timeout [SDK-7399]#1177shivam5643 wants to merge 7 commits into
Conversation
…tests [SDK-7399]
Observability events queued during a test are flushed from the internal beforeEach /
afterEach hooks in bin/testObservability/cypress/index.js. Those flush sites have no
error handling, so an instrumentation failure throws inside a mocha hook. A failing hook
makes mocha skip every remaining test in that suite, and those tests are then reported
as skipped even though the customer never skipped them.
Regression window: up to v1.32.8 the same events were dispatched from Cypress.on(...)
listeners -- outside any mocha hook -- and each dispatch was wrapped in .catch(), so an
instrumentation failure could not affect the run. v1.33.0 moved the dispatch into these
hooks and dropped the error handling. Customers on 1.35.x / 1.36.x see large numbers of
tests reported as skipped; the same suite on 1.32.8 is clean.
Measured on an 11-test spec whose afterEach issues one failing task, mirroring the flush
site:
before 1 failing + 10 SKIPPED
"Because this error occurred during a `after each` hook we are skipping the
remaining tests in the current suite"
after 11 passing + 0 skipped
Verified end to end on BrowserStack with an 11-test spec that reproduces the customer's
shape (cy.session per test, per-test retry overrides, fixture chains in before()):
unpatched 1.36.9 -> spec status passed_with_skipped, 985s
this change -> spec status passed, 0 skipped, 163s
Both observed failure modes are handled:
- cy.task / cy.now can throw SYNCHRONOUSLY out of Cypress' runPrivilegedCommand
(TypeError: Cannot read properties of null (reading 'get')). A promise .catch() never
runs for that, so a real try/catch is required -- confirmed by experiment.
- an async rejection, covered by the promise .catch().
cy.now('task', ...) replaces cy.task(...) because cy.task enqueues a Cypress command
whose failure surfaces later while the queue drains, failing the hook regardless of any
guard around the enqueue call. cy.now executes immediately and returns a promise, which
is what v1.32.8 did and is therefore containable.
The queue is also cleared before dispatch so a throw cannot replay the same events on
the next flush.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
PR Review: browserstack-cypress-cli PR #1177SummaryIntent: Add a real try/catch + ═══════════════════════════════════════════════════════════════ FindingsPopulated mechanically from Two channels. Blocking = Critical + Warning — the must-fix set the Verdict gates on. Non-blocking = Suggestions — polish; never gates. An empty Warning/Suggestion section here means examined and clean, not an incomplete review. 🔴 Critical (Blocking)
1. [Graceful Degradation] All three swallow points in
─────────────────────────────────────────────────────────────── 🟠 Warnings (Blocking)None found — the region-by-region walk of both hook call sites ( 💡 Suggestions (Non-blocking)None. ═══════════════════════════════════════════════════════════════ External ServicesNo external-contract changes detected. (No finding in this PR carries ═══════════════════════════════════════════════════════════════ Per-File Confidence (for reviewers)
═══════════════════════════════════════════════════════════════ What's Good
═══════════════════════════════════════════════════════════════ Verdict🔴 Fix 1 blocking issue — Coverage: 3 of 3 regions judged, 0 unjudged. No coverage gap. ═══════════════════════════════════════════════════════════════ — SDK PR Review Agent |
…silently
Review follow-up. The three suppression points in flushEventsQueue (async promise
rejection, per-event throw, whole-flush throw) protected the customer's run but left no
trace at all, so a dropped observability event would only surface later as data quietly
missing from the dashboard -- trading a loud failure for a silent one.
Each now routes through warnFlushFailure(), which names the stage and the failing task.
console.warn is used deliberately rather than browserStackLog/cy.task: routing a
diagnostic through another Cypress command would reintroduce the enqueue-time failure
this change exists to contain. Same convention already used for the equivalent case in
bin/accessibility-automation/cypress/index.js ("suppressed afterEach error").
warnFlushFailure is itself wrapped so logging can never throw.
Re-verified the guarantee is unchanged: 11-test spec with a failing dispatch in afterEach
-> 11 passing, 0 skipped.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
|
Fixed in 82cf3f9 — valid finding, the guard was silent. All three suppression points now log via Guarantee re-verified after the change: 11-test spec with a failing dispatch in Also trimmed the code comments in 937f2d9 (33 → 12 lines), no logic change. |
Comments outnumbered code roughly 2:1. Kept only what stops the boundary being undone by a later refactor -- why a throw here skips the rest of the spec, why cy.now rather than cy.task, why try/catch as well as .catch, and why console.warn rather than cy.task. No logic change (33 -> 12 comment lines). Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
|
✅ Good to go
Change map (generated deterministically from the diff)graph LR
subgraph ncypress_cli["cypress-cli"]
nbin_testObservability_cypress_index_js["index.js<br/>~57 lines"]
end
↻ This verdict comment is the review anchor — it's updated in place on each run (the gate posts its status separately). — SDK PR Review Agent |
|
What I found. The fix swaps
So this PR stops the skipping by never dispatching anything. Browser-side observability events ( Side note that reframes the baseline: Two other approaches tested and rejected:
Still confirmed and unaffected by all this: the root cause (a throw inside the internal Suggested direction. The reporter already runs an HTTP server on Happy to take direction on whether to pursue that here or open a fresh PR. |
…spatch [SDK-7399]
Replaces the earlier cy.now approach, which was wrong: cy.now('task', ...) throws on
Cypress 14 in every context (test body, mocha hook and Cypress.on listener), verified on a
remote Windows terminal, so it stopped the skipping only by never delivering anything.
Browser-side telemetry silently disappeared from the dashboard.
Dispatch therefore stays on cy.task, which does deliver. Since cy.task enqueues, its
failure surfaces after the enqueue call returns and cannot be caught at the call site --
so the protection is to never build a payload that fails.
Measured on a remote Windows terminal, single event per afterEach:
64KB pass 128KB pass 256KB pass 512KB pass 768KB pass
1MB FAIL 8MB FAIL
Event count is not a factor: 10, 100 and 1000 small events all pass. The limit is a hard
ceiling near 1MB per cy.task payload.
sanitizeForTask now caps the serialized payload at 128KB: individual strings longer than
8KB are truncated first (command args are the realistic source of bulk), and the event is
skipped only if it is still too large. Skips are logged rather than silent.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
a0ef0be
The real cause of the reported skipping is a TIMEOUT, not an exception. Nothing throws:
build-info on a reproducing build reports failed:0, success:6, ignored:27 with all three
sessions status=error at ~985s against spec_timeout 900000ms. The specs are killed at
spec_timeout and every test that has not run yet is reported as skipped.
Each cy.task round-trip costs roughly 0.8s on a remote terminal. Measured there, 6 tests
per spec, N events per afterEach:
N=1 -> 6 calls -> 113s N=100 -> 600 calls -> 581s
N=10 -> 60 calls -> 114s N=1000 -> 6000 calls -> session killed
A command-heavy test queues hundreds of events, so the old one-cy.task-per-event flush
spent minutes in the hook and blew the spec budget. Locally the same dispatch is
effectively free, which is why every local run passed.
Batching verified before writing this: the same 600 events sent as ONE cy.task call
completed in 109s versus 581s as 600 calls -- i.e. back to baseline.
Changes:
- plugin: new test_observability_batch task takes an array and fans out to the same IPC
events; the four individual tasks stay registered for backward compatibility.
- cypress: the flush builds one batch per drain, split at 512KB so each call stays under
the ~1MB per-payload ceiling also measured on the remote (768KB passes, 1MB fails).
- shouldSkipCommand filters test_observability_batch, otherwise each batch dispatch would
be captured as a command event and refill the queue.
- sanitizeForTask keeps the 128KB payload cap with 8KB string truncation.
This supersedes the earlier cy.now approach, which stopped the skipping only by never
delivering anything: cy.now('task') throws on Cypress 14 in every context, so all
browser-side telemetry silently disappeared from the dashboard.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
|
Hold lifted. The earlier Correction to my earlier comments: the bug is not a thrown error. Cause: the flush issued one Fix: batch the flush into a single Result on the 3-spec repro: Telemetry delivery was checked separately this time, since a passing spec cannot distinguish delivered from dropped: |
…eds [SDK-7399] The 128KB per-event cap and 8KB string truncation were written for an earlier, wrong theory (that oversized payloads were the cause). Batching is what fixes the timeout, so the truncation fixed nothing and would have changed behaviour for customers who work fine today: any command arg or log string over 8KB would have started arriving truncated. Removed. Nothing under 512KB is altered any more. Kept: the 512KB batch split, which is required -- a batch of many events can otherwise cross the ~1MB per-cy.task ceiling measured on a remote terminal (768KB passes, 1MB fails). Added: a single event larger than 512KB is dropped with a log line instead of being sent. That is not a fidelity regression -- before batching such an event was dispatched on its own and would have failed the command anyway, taking the spec with it. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…7399] The comment above flushEventsQueue still described the earlier payload-cap approach and pointed at "sanitizeForTask's size cap", which no longer exists after abb89b6 removed it. It also never stated batching as the mechanism, which is the actual fix. Rewritten to state the measured cause (~0.8s per cy.task round-trip, N=100 -> 581s, N=1000 -> session killed at spec_timeout, failed:0 so nothing throws) and the measured remedy (600 events as one call: 109s). Also notes why dispatch stays on cy.task, and that the try/catch is only a backstop since a cy.task failure surfaces after the enqueue call. Corrected one log message: sanitizeForTask returning null now means unserializable only, not oversized. Removed an orphan comment line. No functional change. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
What is this about?
Customers on
1.35.x/1.36.xsee a large share of their tests reported as skipped; the same suite on1.32.8is clean (SDK-7399: ~113 of ~525 skipped on 1.36.18 vs 4 on 1.32.8).The tests are not skipped by mocha and nothing throws — the spec is killed at
spec_timeoutand every test that has not run yet is reported as skipped.build-infoon a reproducing build:failed: 0is the tell. A thrown error always marks a test failing; nothing failed here. The sessions ran to ~985s against a 900sspec_timeoutand were killed.Why they run that long. The queue flush issues one
cy.taskper queued event, and eachcy.taskround-trip costs roughly 0.8s on a remote terminal. Measured there, 6 tests per spec, N events perafterEach:afterEachcy.taskcallsspec_timeoutA command-heavy test queues hundreds of events (
command:start+command:end+platform_detailsper command, pluslog:changed), so itsafterEachalone runs for minutes. Load-dependent by construction: heavy tests exhaust the spec budget, light tests do not — which is exactly the reported 45-passed / 113-skipped shape rather than all-or-nothing.Why
1.32.8is unaffected. It dispatches viacy.now('task', ...), which throws immediately on Cypress 14 with no IPC round-trip.1.32.8is fast because its dispatch does nothing — it also delivers no browser-side telemetry there.v1.33.0moved dispatch into the internal hooks and ontocy.task, which genuinely delivers but costs ~0.8s per event.Related Jira task/s
Dependent PRs / release order
Automation cases to add
spec_timeoutwithexpected_skipped_number: 0. Existingcypress_cli_and_dashboard.featurerows already assert skipped counts and cover the success path.Code changes to check
?./??.The change
plugin/index.js— newtest_observability_batchtask takes an array and fans out to the same IPC events. The four individual tasks stay registered for backward compatibility.cypress/index.js— the flush builds one batch per drain instead of onecy.taskper event, split at 512KB so each call stays under the ~1MB per-payload ceiling (also measured on the remote: 768KB passes, 1MB fails).sanitizeForTaskcaps payloads at 128KB with 8KB string truncation.shouldSkipCommandfilterstest_observability_batch, without which each batch dispatch would itself be captured as a command event and refill the queue.Batching was verified before the code was written: the same 600 events sent as one
cy.taskcall completed in 109s versus 581s as 600 calls — i.e. back to the ~110s baseline for that spec shape.Verification
Fix, 3-spec repro (suite modelled on the customer's shape:
cy.sessionper test, per-test retry overrides, fixture chains inbefore()). Same suite and settings both arms; only the CLI dependency differs. Patched arm confirmed to ship a fresh dependency bundle, not a cached one.passed_with_skippedpassedTelemetry still delivers — checked explicitly, because a passing spec cannot distinguish delivered from dropped.
test_observability_batchaccepts a mixed batch of all four event types, a 600-event batch, and a batch containing an unknown task name, all without failing (3/3).Release
Version bump:
Release notes type:
Release notes (customer-facing):
Release notes (internal):
bin/testObservability/cypress/index.js+bin/testObservability/plugin/index.js: thebeforeEach/afterEachevent-queue flush now sends one batchedcy.taskper drain (newtest_observability_batchtask) instead of onecy.taskper event. Each round-trip costs ~0.8s on a remote terminal, so command-heavy tests were spending minutes in the hook and the spec was killed atspec_timeout, reporting unrun tests as skipped — the SDK-7399 symptom. Introduced in v1.33.0 when dispatch moved into these hooks and ontocy.task.cy.taskceiling. Skipped events are logged rather than dropped silently.Checklist
Reviewer notes
Environment gotchas found while verifying, worth knowing for any future o11y change:
file:path or apackage_config_options.scripts.postinstallpointing at a local path does not —run_settingsships verbatim to the remote (capabilityHelper.js:131), so the remote re-runs it and fails withNPM_INSTALL_FAILED.package.jsonmd5. Re-testing a changed patch under an unchanged dependency string silently reuses the old bundle ("Skipping the upload of node_modules…"). Add a barecacheBustkey to force a fresh upload.browserstack-cypress build-info <buildId>is the reliable way to seetest_status/spec_timeout/ session durations. The o11y ext API returned nulls for these builds and the session-logs URL returns a bot-challenge page.Earlier commits on this branch explored two approaches that were verified and rejected: a reporter-side duplicate-event guard (no effect on a remote A/B), and switching dispatch to
cy.now(stopped the skipping only by never delivering anything, sincecy.now('task')throws on Cypress 14 in every context). Both are superseded by this change; history retained deliberately.🤖 Generated with Claude Code