Repository navigation
fix(e2e): survive a backward wall-clock step instead of dying silently (EAI-9018) - #455
Conversation
…y (EAI-9018) The Strix Halo WSL2 lane stops mid-suite and says nothing: the last line is a passing step, then `error: test failed` with no `Caused by:` and no panic message, leaving report.json and junit.xml at 0 bytes and never writing report.html. It has failed this way on most runs for days, on every open PR and on main, landing on a different scenario each time. The cause is the wall clock. Cucumber stamps every event with `SystemTime::now()` and its writers then subtract those stamps, treating the clock as monotonic. It is not. A WSL2 guest under load drifts, and the hypervisor corrects it with a step rather than a slew: 34 s backward mid-scenario, so a Finished stamp landed earlier than its own Started. Both writers this suite tees turn that negative difference into a panic rather than a degraded duration -- `writer::Json` per step, `writer::JUnit` per scenario, with a byte-identical message, so the captured log cannot say which fired. Hardening either one alone would have left the other live, and junit.xml is not even read by anything downstream; report.json is what the HTML report and the xfail reconciliation are built from. So correct the timestamps rather than the writers. MonotonicClock maps each reading onto a non-decreasing timeline: a backward move of at least a second is absorbed into a running offset, which keeps every later interval accurate instead of flattening the rest of the run, and anything smaller is clamped as delivery jitter between concurrent scenarios. Only the pair straddling the step loses its duration, which is unavoidable -- the step erased the evidence of how much time actually passed. The wrapper sits outside `.normalized()`, and that placement is load-bearing. Normalize re-emits events grouped by scenario rather than chronologically, and the suite runs up to 64 at once, so after normalisation a lower timestamp is ordinary; correcting there would fire on healthy runs and destroy the durations this exists to protect. Before it, a backward move means the clock moved. The silence is a separate defect and is not fixed here: cucumber swaps the panic hook for an empty one while a run is in flight, and a panic raised by a writer unwinds past the restore, so only the exit code survives. No Gherkin scenario: this is test-harness plumbing and changes nothing a CLI user can observe -- the rocm binary is untouched. Signed-off-by: Roman Sirokov <roman.sirokov@amd.com>
The WSL2 lane is green, and the run confirms the diagnosis
Comparing step durations against the Those three are the pairs that straddled a clock step. The guest clock stepped three times during this single run; each cost one step's duration and the suite carried on. That is exactly the documented trade-off — the step erases the evidence of how much time passed, so that one pair collapses while every later interval stays accurate. The remaining 576 steps span 0.04 ms to 35 s, so nothing else was flattened. It also independently corroborates the root cause: a host whose clock does not move backward produces no such steps at all, and this one did it repeatedly inside five minutes. On the red check
Everything else is green, including both clippy gates, |
jussielo-amd
left a comment
There was a problem hiding this comment.
Verified: WSL2 lane (the one this fix targets) now passes CI. Code review confirmed `MonotonicClock` corrects the exact timestamp field (`meta.at`) that both `writer::Json` and `writer::JUnit` use in their panicking `duration_since` calls, placement outside `.normalized()` is correct given concurrent-scenario reordering, and unit tests/clippy are clean.
The unrelated `E2E tests (Strix Halo, Ubuntu)` failure is a GPU preflight timeout, not a clock/harness issue — pre-existing flake, not introduced by this change.
Summary
E2E tests (Strix Halo, WSL2)stops mid-suite and says nothing: the last line is a passing step, thenerror: test failedwith noCaused by:and no panic message.report.jsonandjunit.xmlare left at 0 bytes andreport.htmlis never written, so the artifact is empty too. It has failed this way on most runs for days — on every open PR and onmain— landing on a different scenario each run (bench-02,dash-07,dash-15,comfyui-01,chat-02).SystemTime::now()and its writers subtract those stamps, treating the clock as monotonic. A WSL2 guest under load drifts and the hypervisor corrects it with a step, not a slew.This does not fix the lane's silence — that is a separate defect, see below.
Evidence
Captured by #445's instrumentation (
harness-diagnostics.log):A scenario whose Finished stamp is 34 s earlier than its own Started stamp. Correlating the guest's readings against the runner's own clock confirms a genuine backward step rather than mispaired events:
Random resync timing is what makes the abort land on a random scenario.
Why not just harden one writer
Both writers this suite tees carry the identical defect, with a byte-identical message:
writer::Jsonjson.rs:285writer::JUnitjunit.rs:432The captured message cannot distinguish them —
Jsonis teed first, so it panics first whenever both apply. Andjunit.xmlis written and uploaded but never parsed (zero references across.github/,xtask/,scripts/), whereasreport.jsonis what the HTML report, the per-scenario xfail reconciliation and the consolidated report are all built from. Dropping or replacing the JUnit writer would have left the path that actually matters untouched.Non-obvious decisions
.normalized()is load-bearing.Normalizere-emits events grouped by scenario rather than chronologically, andmax_concurrent_scenariosis 64 on the mock lane — so after normalisation a timestamp lower than its predecessor is completely ordinary. Correcting there would fire on healthy runs and destroy the durations this exists to protect. Before it, a backward move means the clock moved. There is a comment at the call site saying so, because inverting it is silently destructive.#[allow(clippy::future_not_send)]onhandle_event:Writerbounds neitherWorldnorSelf::ClibySend, so no implementation of it can produce aSendfuture. Matches the existing use of this allow inrocm-dash-{tui,daemon}/src/transport.rs.Test plan
Regression test built from the exact readings in the captured panic, asserting first that they really are inverted so it cannot pass vacuously, then that
duration_sinceon the corrected pair succeeds — that call is what cucumber turns into a panic. Plus: intervals after a step keep their real length, successive steps each accumulate, a healthy clock is returned byte-identical, sub-threshold jitter is clamped not offset, and an erratic clock never yields a decreasing output.Run on a Linux box (the macOS toolchain cannot build
rocm-engine-lemonadeat all —st_modeisu16there):cargo test --workspace --all-targets— ~3,050 tests, 0 failurescargo clippy --locked -p e2e-cucumber --test e2e -- -D warnings— cleancargo clippy --workspace --all-targets -- -D warnings— cleancargo fmt --all --check— cleanThe wrapper is inert on a healthy clock, which is the risk worth checking. A real suite run writes all three artifacts non-empty and 0 of 53 steps have a zero duration (0.128 ms / 0.788 ms / 274 ms for min / median / max), with
junit.xmltime=attributes populated as before.Not verified in CI: the failure itself cannot be reproduced anywhere but that lane — the clock step is a property of the host. What this changes is the failure mode: a run spanning a step now completes and reports instead of aborting with empty artifacts.
Risk and scope
Low. Nothing outside
tests/e2e-cucumber/changes; therocmbinary is untouched. On a healthy clock the correction is a no-op — the offset stays zero and the clamp only ever absorbs sub-millisecond noise — so ordinary runs report exactly the durations they always did. No new dependencies, soCargo.lockandTHIRD_PARTY_NOTICES.txtare unchanged.No Gherkin scenario: per AGENTS.md §3 this is test-harness plumbing and alters nothing a CLI user can observe.
Related
E2E tests (Strix Halo, Ubuntu), red on the same PRs for the unrelated VRAM-carveout preflight bug (ci(e2e): GPU preflight gates on free VRAM, which is the wrong pool on an APU #438). Independent of this.