Skip to content

fix(e2e): survive a backward wall-clock step instead of dying silently (EAI-9018) - #455

Merged
r0x0r merged 1 commit into
mainfrom
eai-9018-monotonic-event-clock
Sep 28, 2026
Merged

r0x0r merged 1 commit into
mainfrom
eai-9018-monotonic-event-clock

Conversation

@r0x0r

@r0x0r r0x0r commented Sep 28, 2026

Copy link
Copy Markdown
Collaborator

Summary

  • E2E tests (Strix Halo, WSL2) 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. report.json and junit.xml are left at 0 bytes and report.html is never written, so the artifact is empty too. It has failed this way on most runs for days — on every open PR and on main — landing on a different scenario each run (bench-02, dash-07, dash-15, comfyui-01, chat-02).
  • The wall clock is the cause. Cucumber stamps every event with 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.
  • Correct the timestamps rather than harden the writers, and do it upstream of normalisation.

This does not fix the lane's silence — that is a separate defect, see below.

Evidence

Captured by #445's instrumentation (harness-diagnostics.log):

=== fatal panic (escaped the cucumber run) ===
message: failed to compute duration between SystemTime { tv_sec: 1790582151, tv_nsec: 969468442 }
         and SystemTime { tv_sec: 1790582185, tv_nsec: 178234361 }:
         second time provided was later than self

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:

guest clock runner clock
scenario Started 07:56:25 ~07:56:25 (in sync)
scenario Finished 07:55:51 ~07:56:26 (34 s behind)
test step ended — 07:56:26

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 site granularity
writer::Json json.rs:285 per step
writer::JUnit junit.rs:432 per scenario

The captured message cannot distinguish them — Json is teed first, so it panics first whenever both apply. And junit.xml is written and uploaded but never parsed (zero references across .github/, xtask/, scripts/), whereas report.json is 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

  • Offset, not clamp. A backward move of ≥ 1 s is absorbed into a running offset, so every later interval stays accurate. A clamp-only correction would flatten every duration for the remainder of the run. The pair straddling the step still collapses to ~0, which is unavoidable: the step erased the evidence of how much time passed.
  • Placement outside .normalized() is load-bearing. Normalize re-emits events grouped by scenario rather than chronologically, and max_concurrent_scenarios is 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.
  • Panic-safety does not depend on the threshold. The non-decreasing clamp covers every case; the threshold only decides whether one pair loses its duration or the rest of the run does. Sub-threshold inversions are treated as delivery jitter between concurrent scenarios rather than adopted as a spurious offset.
  • #[allow(clippy::future_not_send)] on handle_event: Writer bounds neither World nor Self::Cli by Send, so no implementation of it can produce a Send future. Matches the existing use of this allow in rocm-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_since on 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-lemonade at all — st_mode is u16 there):

  • cargo test --workspace --all-targets — ~3,050 tests, 0 failures
  • cargo clippy --locked -p e2e-cucumber --test e2e -- -D warnings — clean
  • cargo clippy --workspace --all-targets -- -D warnings — clean
  • cargo fmt --all --check — clean

The 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.xml time= 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; the rocm binary 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, so Cargo.lock and THIRD_PARTY_NOTICES.txt are unchanged.

No Gherkin scenario: per AGENTS.md §3 this is test-harness plumbing and alters nothing a CLI user can observe.

Related

…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>
@r0x0r
r0x0r requested a review from a team as a code owner September 28, 2026 12:25
@r0x0r

r0x0r commented Sep 28, 2026

Copy link
Copy Markdown
Collaborator Author

The WSL2 lane is green, and the run confirms the diagnosis

E2E tests (Strix Halo, WSL2) passed — its first green run since this started. It completed the full suite and wrote real artifacts instead of aborting:

before (run 36393752400) this run
report.json 0 bytes 130 KB
junit.xml 0 bytes 77 KB
report.html never written 220 KB
artifact total 2.5 KB 70 KB
scenarios aborted at a random one 20 features / 129 scenarios / 579 steps

Comparing step durations against the Strix Halo, Windows lane from the same run — same suite, healthy clock — is what makes this more than "it passed":

Windows: 363 steps, 0 zero-duration (0.00%)
WSL2:    579 steps, 3 zero-duration (0.52%)

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

E2E tests (Strix Halo, Ubuntu) fails here at the GPU preflight (bounded wait for an available GPU) step. That is the VRAM-carveout bug (#438) that #442 fixes — it is red on every open PR and on main, and this branch is cut from main, which does not have that fix yet. Unrelated to this change; nothing in this PR touches the preflight.

Everything else is green, including both clippy gates, commit-signatures, the license header check and third-party notices.

@jussielo-amd jussielo-amd 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.

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.

@r0x0r
r0x0r enabled auto-merge September 28, 2026 12:57
@r0x0r
r0x0r added this pull request to the merge queue Sep 28, 2026
Merged via the queue into main with commit 98df4d7 Sep 28, 2026
27 of 28 checks passed
@r0x0r
r0x0r deleted the eai-9018-monotonic-event-clock branch September 28, 2026 18:27
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants