ci(e2e): stop the WSL2 guest clock stepping backwards during the suite - #451
Conversation
jussielo-amd
left a comment
There was a problem hiding this comment.
Reviewed the clock-settling fix — logic and rationale look solid. One gap worth flagging outside this diff: .github/workflows/nightly.yml's e2e-wsl-nightly job (around line 883) explicitly mirrors e2e-wsl in e2e-selfhosted.yml (its own comments say so directly), boots the same fresh WSL2 guest, but doesn't get this "Settle the clock" step. That's exactly the scenario this PR's root-cause analysis describes (fresh guest, clock still correcting via NTP), so the SystemTime-underflow panic in cucumber's writer is still live there. Might be worth porting the same step over, or intentionally scoping it out if there's a reason nightly doesn't need it.
juhovainio
left a comment
There was a problem hiding this comment.
Reviewed the new "Settle the clock" step. The overall approach (settle both host and guest clocks up front, best-effort, never fail the lane) is well reasoned and clearly explained in the comments and commit message. Two things worth fixing before merge, left inline below:
- The try/catch around the w32tm calls doesn't actually do anything, because
$ErrorActionPreference = 'Continue'on the line above is exactly what prevents a native command's stderr from becoming a terminating error in the first place. So the custom"w32tm /resync: $_"/"w32tm /query: $_"diagnostics are dead code — nothing is silently lost (the raw error still lands in the log via default stderr formatting), but it gives a false impression that failures are being captured and labeled. - The host-side w32tm resync and the guest's bounded (up to 30s) NTP-sync wait run sequentially even though they touch independent clocks and don't depend on each other. Given this lane is already slow (120min budget, ~5min/job just for distro install), overlapping them would shave real time off every run.
Neither is a correctness blocker for the workflow itself, but #1 in particular is misleading since it looks like error handling that isn't actually functioning.
| # Host first: land the correction now rather than have it arrive | ||
| # mid-suite, then report what the service thinks. | ||
| Write-Host "host time before: $((Get-Date).ToUniversalTime().ToString('o'))" | ||
| try { & w32tm /resync /force } catch { Write-Host "w32tm /resync: $_" } |
There was a problem hiding this comment.
This try/catch can't catch anything: $ErrorActionPreference = 'Continue' was just set above, and that's exactly what stops a native command's stderr from being promoted to a terminating error (which is the only thing PowerShell's try/catch intercepts). So when w32tm writes to stderr (no time source configured, service not running, etc.), this catch block never fires and the custom "w32tm /resync: $_" message never prints — the raw stderr still reaches the log via PowerShell's default formatting, but the intended labeled diagnostic is dead code. Same issue on the w32tm /query /status line right below.
There was a problem hiding this comment.
You are right, and it was worse than useless — it read as error handling that works.
Dropped both. $ErrorActionPreference = 'Continue' is what was actually carrying the guarantee all along: a native command's exit code never throws, and under Continueits stderr is not promoted to a terminating error either, so there was nothing for acatchto intercept. The comment now says that explicitly, so the next reader does not re-add a handler on the same reasoning I did. Raww32tm` output still reaches the log.
Fixed in 1946ee1.
There was a problem hiding this comment.
Correction to my previous reply here — I told you the catch "could never fire", and that was wrong.
$ErrorActionPreference governs errors raised by a command that ran; it does not govern command resolution. An unresolvable w32tm raises CommandNotFoundException, which is catchable whatever the preference is set to. I checked against a real interpreter this time instead of reasoning about it:
$ErrorActionPreference = "Continue"
try { & w32tm-does-not-exist /resync } catch { "CAUGHT: $($_.Exception.GetType().Name)" }
CAUGHT: CommandNotFoundException
So your original instinct that this deserved handling was closer to right than my answer was. The two w32tm calls now sit inside the existing try, and the comment states what Continue actually covers ("neither their exit code nor their stderr can fail this step") rather than an absolute that is false.
Your underlying point still stands and is preserved: the labelled per-call diagnostics were dead for the case they named (a machine with no time source), which is what Continue does cover.
One thing I could verify that the automated reviewer flagged as unknown: without any wrapping, execution does continue past an unresolvable command under Continue, so the trailing exit 0 still ran and the step never actually failed the lane. Wrapping makes that unconditional rather than incidental. (Checked on PowerShell 7 on Linux, not Windows PowerShell 5.1, which is what the lane runs.)
Fixed in d468500.
|
|
||
| # See .github/scripts/Invoke-WslBash.ps1. No -PipeFail: the guest script | ||
| # below is a sequence of probes that must each be allowed to fail. | ||
| & "$env:GITHUB_WORKSPACE\.github\scripts\Invoke-WslBash.ps1" -Script @' |
There was a problem hiding this comment.
The host-side w32tm resync above and this guest NTP-sync wait (which can block up to 30s) run strictly sequentially even though they target independent clocks and don't depend on each other. Every WSL2 job pays both costs back-to-back. Running the guest probe concurrently with the host resync (e.g. as a background job) would let them overlap and save time on every run, given this lane's already-tight budget.
There was a problem hiding this comment.
Leaving these sequential, but the ordering is load-bearing rather than incidental, so it is worth the thread.
In WSL2 the guest clock tracks the host. Settling the host first is what gives the guest's own sync an already-correct reference to land on; overlapping them means the guest can sync against a host clock that is still moving, which is the exact condition this step exists to remove. I have added a comment at the call site saying so, because "these are independent, parallelise them" is a reasonable read of the code as it stood.
On the cost: the guest wait short-circuits when NTPSynchronized is already yes, which is the normal case — the 30s is a ceiling for a guest that still owes a correction, not a per-run cost. So the saving is closer to a second than to 30, against a 120-minute budget.
Happy to be overruled if you would still rather have them overlap — leaving this open for you.
|
🔴 Automated review · pr-review-watcher · da8b30a This automation never files a GitHub approval, so no approving review will SummaryAdds one best-effort step to the WSL2 end-to-end job that resyncs the Windows host clock, waits for the in-guest time client to report a completed sync, then disables it — so the suite is not timed across a backwards clock step. Outcome: Needs work — the same lane exists a second time in 🚫 Blocking (must fix before merge)
Related, and cheap to fix alongside: this change adds no test, and an idiomatic one was available. The whole load-bearing property is ordering plus presence, and Non-blocking
|
There was a problem hiding this comment.
🔴 Automated review · pr-review-watcher · da8b30a
This automation never files a GitHub approval, so no approving review will appear here whatever the outcome — the merge decision stays with a human reviewer.
The fix is applied to one of two identical lanes. nightly.yml's e2e-wsl-nightly is a step-for-step twin of the e2e-wsl job edited here: same runner labels, same fresh-distro boot, same step sequence, running the same writers over a longer scenario set. Every condition the diagnosis rests on holds there identically, so that lane keeps dying the same way — and because it carries continue-on-error: true, it dies without even turning the run red. The PR body's "Risk and scope: Low. One added step in one job" reads as a completeness statement, and nothing in the text mentions the twin.
This is a failure mode the repo has already been burned by and built a guard for: xtask/src/workflow_contract.rs's apu_preflight_twins_do_not_drift exists because one nightly lane was left on an older script while its siblings were converted and nothing failed. Either mirror the step into e2e-wsl-nightly at the same position, or say in the PR body why that lane is deliberately left exposed.
Related and cheap to fix alongside: this change adds no test, and an idiomatic one was available. The load-bearing property is ordering plus presence, and workflow_contract.rs already contains both idioms needed — the relative-position assertion used in dependabot_manifest_commit_is_a_guarded_workflow_run_follow_up, and the per-PR/nightly parity loop in apu_preflight_twins_do_not_drift. Roughly ten lines asserting that both WSL jobs contain the settle step and that it precedes their Run E2E tests step would pin exactly what a future step insertion or a copy-paste into the twin can silently break.
The full findings, including five non-blocking items on the guest script's exhausted-wait path and the disabled time client, are in the review comment on this PR.
cucumber measures every scenario's duration with `SystemTime` rather than a monotonic clock and panics when the subtraction underflows (cucumber-0.23.0/src/writer/junit.rs:433, writer/json.rs:218 and :284). A wall clock that steps backwards by any amount between a scenario's start and finish therefore kills the run outright. Worse, the panic is raised inside the writer, which is where cucumber has swapped the panic hook for an empty one, so the job died mid-suite reporting nothing at all. That is what this lane has been doing on most runs for days, the merge queue included. The message was only recovered once the harness began catching the panic at the run boundary (#445): failed to compute duration between SystemTime { tv_sec: 1790582151 } and SystemTime { tv_sec: 1790582185 }: second time provided was later than self The scenario "finished" 33 seconds before it started. Nothing else in the matrix sees this because nothing else runs in a freshly booted guest whose clock is still being corrected underneath it. Land that correction up front, while nothing is timing anything, then stop the clock being stepped again for the rest of the job. Both sides are touched because either can be the one that moves: the guest tracks the Windows host's clock, so a host-side correction lands in the guest too. Every command is best-effort and the step never fails the lane -- a clock that cannot be settled should still run and fail with a real diagnosis rather than a red step here. The step reports what it found on both sides, so if a run still steps, the log says which side was left able to do it. Signed-off-by: Roman Inflianskas <Roman.Inflianskas@amd.com>
Review follow-ups on the "Settle the clock" step. The try/catch around the two `w32tm` calls could never fire. Setting $ErrorActionPreference = 'Continue' is itself what keeps them non-fatal: a native command's exit code never throws, and under 'Continue' its stderr is not promoted to a terminating error either, so there was nothing for a `catch` to intercept. The labelled diagnostics it appeared to provide were dead code, which is worse than no handler because it reads as error handling that works. Drop them; the raw output still reaches the log, and the comment now says which line is actually carrying the guarantee. The Invoke-WslBash.ps1 call is wrapped instead, because that one genuinely can raise a terminating exception -- a missing helper, or `wsl` failing to invoke -- which 'Continue' does not suppress and which would abort the block before the `exit 0` that makes this step non-fatal. That gap contradicted the comment promising it never fails the lane. nightly.yml's e2e-wsl-nightly mirrors e2e-wsl, boots the same fresh guest, and had no clock step, so the hazard was still live there. Port it, with a pointer to the original rather than a second copy of the analysis, and a note that the two are hand-synced until #294 deduplicates the lanes. The host resync and the guest wait stay sequential: in WSL2 the guest clock tracks the host, so settling the host first is what gives the guest's own sync an already-correct reference to land on. Signed-off-by: Roman Inflianskas <Roman.Inflianskas@amd.com>
da8b30a to
1946ee1
Compare
|
Pushed @juhovainio — both points taken, one of them differently than requested:
@jussielo-amd — the What changed underneath this PR#455 landed while this was in review, so this no longer prevents a lane failure — a backward step is now survivable in the harness. The PR description has been rewritten accordingly. What it still does is stop the step at source, so scenario durations are real rather than merely non-fatal: #455's correction necessarily collapses the interval straddling a step to ~0, because the step erased the evidence of how much time actually passed. Worth being explicit about the tradeoff, since #455's author suggested slewing rather than disabling: switching the in-guest client off means the guest clock free-runs for the job, so absolute timestamps drift (bounded, and small over a ~20 minute run) while never moving backwards. A slew-only client — chrony with The WSL2 lane passed on the previous head, which is one data point against a lane that had been failing most runs — not proof, given the failure was intermittent. |
|
🔴 Automated review · pr-review-watcher · d468500 This automation never files a GitHub approval, so no approving review will appear here whatever the outcome — the merge decision stays with a human reviewer. SummaryAdds a best-effort clock-settling step to both WSL2 e2e lanes so cucumber's Prior round1. "the change still ships with no test, and I measured that nothing catches its removal … nothing detects a deletion from either lane, nothing detects the step being moved after the suite." — DISCHARGED. 2. "the comment justifying the removed The prior round's non-blocking items were not restated in the change-request text, so they were not re-checked individually this round. 🚫 Blocking (must fix before merge)None. Non-blocking
|
Withdrawing this change request so it can be replaced by one filed against the current head -- only the newest is operative, and leaving this one standing would obscure which objection is live.
Half of it is genuinely discharged: the twin-mirroring half. The settle step now exists in both WSL2 lanes, in the identical slot (index 5 of 11 in each, after the WSL2 verification step and before the suite step), with byte-identical bodies. That was verified by extracting and comparing the ordered step lists, not taken on trust.
The other half -- that the change ships with no test -- still stands, and is re-filed at the current head together with one new finding.
siloteemu
left a comment
There was a problem hiding this comment.
🔴 Automated review · pr-review-watcher · 1946ee1
Change request filed by automation. The findings below are the blocking half of the round published in the report comment on this pull request; the non-blocking notes stay there. This will be withdrawn once they are addressed — no human needs to clear it.
🚫 Blocking (must fix before merge)
1. xtask/src/workflow_contract.rs — the change still ships with no test, and I measured that nothing catches its removal.
This is the unfinished half of the standing change request. On a scratch copy I deleted the Settle the clock… step from both .github/workflows/e2e-selfhosted.yml and .github/workflows/nightly.yml and re-ran the contract suite: 33 passed, 0 failed — byte-for-byte the same result as with the step present. So today nothing detects a deletion from either lane, nothing detects the step being moved after the suite, and nothing detects the two hand-synced copies drifting. The nightly lane carries job-level continue-on-error: true (.github/workflows/nightly.yml:1094), so a silent regression there would not even turn a run red. The PR's own comment — "Kept in sync by hand until the two lanes are deduplicated" — names exactly the failure mode that an assertion would pin, and the repo already has both idioms: the offset-ordering style in dependabot_manifest_commit_is_a_guarded_workflow_run_follow_up (xtask/src/workflow_contract.rs:559, asserting at :633) and the per-lane parity loop in apu_preflight_twins_do_not_drift (:1021) / nightly_wsl_lane_shares_the_per_pr_pool_labels.
Fix: roughly ten lines looping over [("e2e-selfhosted.yml", "e2e-wsl"), ("nightly.yml", "e2e-wsl-nightly")], using the existing read_workflow (:32) and job_block (:286), asserting for each lane that the step is present and that its offset precedes the suite step's. Search for the exact step line - name: Settle the clock before anything times a scenario rather than a bare substring — a bare substring can be satisfied by a prose mention in a neighbouring comment block, which would make the test pass for the wrong reason, precisely the failure this assertion exists to prevent. Written that way it fails on removal from either lane independently, and fails if the step is moved after the suite.
2. .github/workflows/e2e-selfhosted.yml:1076-1083 (and the identical .github/workflows/nightly.yml:1193-1200) — the comment justifying the removed try/catch states a guarantee PowerShell does not give.
The comment asserts: "a native command's exit code never throws, and under 'Continue' its stderr is not promoted to a terminating error either, so a catch around them could never fire." The first two clauses are right; the conclusion is not. $ErrorActionPreference governs how errors raised by a running command are handled — it does not govern command resolution. If w32tm is not resolvable on PATH, & w32tm /resync /force raises CommandNotFoundException, which is catchable by try/catch irrespective of the preference. So a catch around those two calls demonstrably can fire, and the commit message leans on the same false absolute ("there was nothing for a catch to intercept") as the sole justification for deleting the handler. This blocks not because the scenario is likely — w32tm.exe ships in System32 on every supported Windows — but because a load-bearing, verifiably wrong statement about error semantics is being left in a workflow as documentation, where the next author will copy the rule. I could not exercise whether an unresolvable w32tm would also skip the trailing exit 0 (no PowerShell interpreter available here), which is the one path on which the step's own closing promise — "never fail the lane on a clock it could not settle" — would not hold.
Fix: move the two & w32tm calls inside the existing try block and correct the clause to "under 'Continue', neither their exit code nor their stderr can fail this step". That is a two-line change, it keeps every bit of the current logging and best-effort behaviour, it makes the "never fails the lane" contract unconditional regardless of which statement-termination semantics apply, and it removes the incorrect absolute without weakening anything. (Adversarial check on this fix: wrapping does not suppress any real failure, because the step is best-effort by explicit design and already discards the guest result the same way; and it does not change stderr handling, which 'Continue' still governs.)
…r semantics Two review follow-ups, one of which corrects something I stated wrongly. The step had no test, and removing it was measurably free: deleting it from both workflows left the contract suite green, so nothing detected a deletion, a move after the suite, or the two hand-synced copies drifting -- and on the nightly lane, job-level continue-on-error would have kept a regression from even turning the run red. `both_wsl_lanes_settle_the_clock_before_running_the_suite` pins presence and position in both lanes. It matches the step NAME rather than a substring of the job, because the surrounding comments discuss the clock at length and a substring would stay satisfied by prose after the step was deleted. Verified by mutation: removing the step from either lane independently, and moving it after the suite, each fail it. The comment justifying the removed try/catch was wrong. It claimed a `catch` around the `w32tm` calls "could never fire" under $ErrorActionPreference = 'Continue'. That preference governs errors raised by a command that ran, not command *resolution*: an unresolvable `w32tm` raises CommandNotFoundException, which is catchable whatever the preference is. Confirmed against a real interpreter rather than reasoned about. The calls now sit inside the existing try and the comment states what 'Continue' actually covers, which makes the step's "never fails the lane" promise unconditional instead of resting on which statement happens to terminate. Also noted in place: only the guest side is pinned for the rest of the job -- the host keeps its time service, so a later host-side correction can still propagate inward, and stopping a service on a shared runner is a bigger hammer than this hazard warrants. And why the 30s wait is the right budget. Signed-off-by: Roman Inflianskas <Roman.Inflianskas@amd.com>
|
Pushed The step now has a test, and I measured that it bites
Verified by mutation rather than asserted — each of these fails it independently:
The error-semantics claim was wrong, and I checked it this timeYou are right, and I had stated the opposite to a human reviewer earlier in this PR. The two calls are inside the existing The half you flagged as unverifiable, I could test: without any wrapping, execution continues past an unresolvable command under Non-blocking
|
Both blocking findings are discharged at d468500. The clock-settling step is now pinned by a workflow-contract test, verified by measurement rather than by reading: removing the step from either lane independently reds it, and relocating it after the suite step reds it with the ordering message. The PowerShell comment now states the correct scope, and the unconditional exit sits outside the try/catch so the step's never-fail promise no longer rests on statement-termination semantics. Remaining items are non-blocking and are in the review comment.
juhovainio
left a comment
There was a problem hiding this comment.
The originally-reviewed commit fell out of the branch's history (not a full squash like a previous PR I re-checked, but the object still exists locally so I could diff straight through), so I re-read the diff since my last review plus your reply correcting your own earlier comment, and independently re-verified both points against the current code rather than taking either description at face value.
-
The try/catch around the w32tm calls: fixed. Both
w32tm /resync /forceandw32tm /query /statusnow sit inside the existingtry, and the comment above correctly explains that$ErrorActionPreference = 'Continue'governs errors from a command that ran, not command resolution - an unresolvablew32tmstill raises a catchableCommandNotFoundExceptionregardless of that preference. That matches what you found testing against a real interpreter, and it's a materially different (and more accurate) explanation than either of us originally gave, while the underlying practical concern (the labeled diagnostics being dead for the case they actually named) is still the thing that got fixed. -
The sequential host/guest clock operations: not parallelized, but addressed with a reasoned explanation for why they shouldn't be - a new comment states the guest clock tracks the host under WSL2, so settling the host first is what gives the guest's own NTP sync a correct reference to land on. That's a real constraint, not just a missed optimization, so I'm satisfied with this as a resolution rather than a dodge.
Also noticed the step previously had no test at all - the new both_wsl_lanes_settle_the_clock_before_running_the_suite xtask contract test pins its presence and ordering in both the per-PR and nightly workflows. I pulled it into a disposable worktree and ran it independently: passes.
One caveat: CI currently shows "E2E tests (Strix Halo, Ubuntu)" as failed and "E2E tests (Strix Halo, Windows)" as cancelled alongside it. I checked the Ubuntu failure log - it's a chat-scenario timeout because a previous engine was still holding the GPU (device not drained after 120s, 319 MiB free of a 450 MiB floor), which is shared-runner flakiness unrelated to this diff (this PR only touches the WSL2 lane's clock-settling step). Worth a rerun before merge, but not something I'd hold up the review on.
Approving based on the code and my own verification of both points.
|
The non-blocking items from the review round on this PR, addressed after merge:
|
Summary
mainincluded, until fix(e2e): survive a backward wall-clock step instead of dying silently (EAI-9018) #455 made it survivable.e2e-wsland nightly'se2e-wsl-nightly.report.json,junit.xmland the HTML report trustworthy, rather than silently collapsed to ~0 for whichever scenario straddles a step.The evidence comes from #445, which is what made this failure readable at all.
Root cause
cucumber-0.23.0/src/writer/junit.rs:433:writer/json.rs:218and:284do the same, so either writer can be the one that fires.From the first run that could report it (job 108835275843):
The scenario's
Finishedtimestamp is 33.2 s earlier than itsStartedtimestamp. And because the panic is raised inside the writer, it lands in the window where cucumber has replaced the panic hook with an empty one (runner/basic.rs:929, restored at:1070) — which is why the lane had been failing with no message, no summary and zero-byte reports rather than an error.Every observation fits: WSL2-only (nothing else in the matrix runs in a freshly booted guest whose clock is still being corrected underneath it), a different stop point each run, always early, always fatal, always silent.
The magnitude is incidental. A one-millisecond backwards step is just as fatal as 33 seconds — so the remedy has to be "do not step during the run", not "step less".
What this does
A new best-effort step after the WSL2 check and well before the suite, touching both sides because either can be the one that moves — the guest tracks the Windows host's clock, so a host-side correction lands in the guest too:
w32tm /resync /force, so the correction arrives now instead of mid-suite, thenw32tm /query /statusfor the record.Both sides print their clock before and after, and the guest prints what it found. The step never fails the lane: a clock that could not be settled should still run and fail with a real diagnosis rather than a red step here.
Non-obvious decisions
$ErrorActionPreference = 'Continue'in the host block.shell: powershellruns with'Stop', under which a native command's stderr becomes a terminating error.w32tmwrites there routinely on a machine with no configured time source, which would abort a step whose whole purpose is to be best-effort.-PipeFailon the guest invocation, unlike its siblings in this job: the guest block is a sequence of probes that must each be allowed to fail.Verification, and its limits
This cannot be verified anywhere but the lane, and I want to be plain about that rather than imply more confidence than I have:
bash -nand behaves correctly on the no-timedatectlpath (the branch this takes if the guest has no systemd);cargo test -p xtaskpasses — at the merged commit682afc86, 251 tests (the crate total includes tests from changes merged before this one). That includes the contract test this PR adds,both_wsl_lanes_settle_the_clock_before_running_the_suite, which requires the step in both the per-PR and nightly WSL2 lanes, ahead of the suite. Verified by mutation: removing the step from either lane, independently, or moving it after the suite each fails it. It pins the step's presence and order, not the content of its two hand-copiedrun:bodies.The durable fix is upstream: a duration measured for reporting should come from a monotonic clock, where this cannot happen at all. Worth filing against cucumber regardless of whether this lands; a patched dependency would be the fallback if the lane keeps stepping.
Tradeoff worth confirming
Switching the in-guest client off means the guest clock free-runs for the job: it never moves backwards, but absolute timestamps drift (bounded, and small over a ~20 minute run). A slew-only client — chrony with
makestep 0 0— would keep absolute time correct as well, at the cost of a package install and more moving parts in a lane that is already slow. #455's author suggested slewing; I went with the smaller change because #455 already removes the fatal case, and the remaining goal is only "never step backwards". Say the word and I will swap it.Risk and scope
Low. One added step per WSL2 lane, best-effort throughout, no existing step changed. The worst case is that it does nothing — and even then it leaves a log line saying which clock was still free to move.
The nightly copy is a hand-synced duplicate of the
e2e-wslone, which is the pre-existing condition #294 tracks; it carries a pointer to the original rather than a second copy of the reasoning.