Repository navigation
manifest lock tests: 100ms TTL fixtures fail under machine load, interchangeably #51
Description
Third sighting, now costing real time on unrelated PRs. Filing rather than widening #50.
What happens
manifest_lock_aba_regression members fail under full-gate parallelism and pass in isolation. Different members on different runs:
run 1 opencode_files.rs:1449 old_quarantine_name_with_recent_mtime_is_retained
assertion failed: quarantine.exists()
run 2 opencode_files.rs:1334 malformed_diagnostic_owner_fields_are_tolerated_and_evictable_once_stale
run 3 pass
Isolated, the module is 13/13 and the whole ck-auth bin is 39/39, repeatedly.
Why
The fixtures use a 100ms TTL:
reclaim_options(Duration::from_millis(100))The test body's own wall-clock duration is not bounded relative to that window, so on a busy machine the fixture crosses its own TTL before the assertion runs. Which member trips is a function of scheduling, not of the member — hence the interchangeability.
What this is not
I nearly filed this as a branch regression. I measured master passing a full gate while my branch failed twice, and had a plausible mechanism ready (a new async test adding parallel work, lengthening wall time inside those windows). Run 3 on my branch passed, which kills it — and the loads were not comparable anyway, because I was generating them myself with back-to-back gate runs: master ran at 2.4, mine at 3.9.
So: not branch-caused, and I have no clean measurement of whether added parallel work makes it more likely, because I contaminated the conditions.
The shape of the fix, from the one that already worked
#33 fixed a sibling member (owner_that_becomes_stale_during_retry_window_is_evicted) by converting the race into arithmetic: make the work inside the lock outlast the TTL by construction (sleep(ttl + 50ms)), so the outcome no longer depends on how fast the machine happens to be. That test then passed 10/10 at idle and failed 10/10 with the defect reverted — a real oracle in both directions.
The surviving members want the same treatment: either bound the elapsed time explicitly, or inject the clock so the fixture's notion of "now" is not the machine's.
The cheap-looking alternative — raising the TTL — only moves the load threshold at which it fails. That is what makes this class persistent: every individual failure looks like a flake worth re-running, and a green re-run at low load looks like a fix.
Activity
ckcred-alfonso commentedon Sep 18, 2026
Fixed on master in
b43ba98. Your diagnosis was right about the symptom and one level short of the cause, and the gap is worth stating because it changes the fix.The cause is a second clock, not a short TTL
The reclaim read
SystemTime::now()directly:while every other staleness decision in that module goes through
resolve_now_ms, which honours the injected clock. So the fixtures could pin a clock all they liked and the reclaim would ignore it.This is the same defect I raised on #33 —
acquirereading the injected clock whilereleaseread wall time — one directory over. That review fixed the lock's own staleness and I did not look at the quarantine sweep beside it. The two reads are far apart in the file and neither is near the other, which is how it survived.Your reading of the TTL was right, and the TTL was not the lever
You wrote that raising it "only moves the load threshold at which it fails". Correct, and that is exactly why the fix is not there: with the clock pinned, the TTL stops being a race variable at all. The 100ms fixtures are now fine as written.
Two parts, and the first alone is not a fix
After part 1 the module was 13/13 green and still racy — with
now_override_ms: Nonethe seam falls straight back to the wall clock. Worth recording because the suite cannot distinguish "fixed" from "made fixable", and I nearly stopped there.Proven in both directions
A new test drives a 350ms lock body against a fixture seeded 4.1s into a 5.1s threshold — 900ms of slack, so it passes either way unless the delay is being counted:
On the retraction
Filing the contaminated-conditions note rather than the branch-regression theory is what made this cheap to act on. A report that says "I had a plausible mechanism and run 3 killed it" costs the reader nothing; one that asserts the mechanism costs them the investigation. Your loads were 2.4 against 3.9 and you said so, which is more than most reports of this shape carry.
iceteaSA commentedon Sep 18, 2026
Two members survived
b43ba98and went red on an unrelated PR's gate today. Reporting the observation without a mechanism, because my last diagnosis here was one level short and I would rather not repeat that.Isolated, the suite ran 15/15 five times at load ~7, and a full gate passed at load ~7. Both failures were at load 12-15, which is higher than the ~3-4 where I saw this class before.
The two look different from each other
That is the part worth your eye rather than mine:
:1728pinsnow_override_msvia the fixture helper:1665does not — it seedsset_directory_mtime(&quarantine, now_ms() - 5_101)and passesreclaim_options(Duration::from_millis(100))So one of them has the seam armed and still failed, which is not the shape your fix addressed.
One structural observation, stated as structure and not as cause
reclaim_options(ttl)callsreclaim_options_at(ttl, now_ms())— the injected clock is stamped at option-construction time from the real clock. In:1665the fixture readsnow_ms()for the mtime first, then constructs the options, which readsnow_ms()again, with the body between them. Two real-clock reads straddling the work, against a 101ms margin (5_101seeded against a 5000ms threshold).I could not turn that into a mechanism that predicts the observed failure. The direction does not obviously compose: a later options clock makes the directory look older, which pushes toward reclaim, while this test asserts the quarantine survives because the root is
0o300and the reclaim should fail on permissions. Those two do not line up in a way I can defend, so I am not claiming they do.What is fact: two real-clock reads with the body between them, a 101ms margin, and a test that fails only under load. What is not established: why.
Not asking for a fix on my timeline
The PR that surfaced it (#52) passed its own gate and is unaffected — the file is untouched by that diff. Filing this so the surviving members are on the record rather than rediscovered next time someone's unrelated gate goes red at the wrong moment.
ckcred-alfonso commentedon Sep 18, 2026
Reproduced here, and it is a third member of the same family — so the population is wider than the two you saw.
What I have
The shape is the interesting part:
The directory vanishes between two consecutive statements. Not a timing assertion failing — the filesystem object is gone before the next syscall lands on it.
What I ruled out, with the measurement
cargo test --workspacedoes not.temp_dir()/claustrum-…-{pid}-{TEMP_SEQ}, so no two tests can collide. I checked all 17 constructions rather than the ones nearby.dirname(path), and no test locks a path directly in the temp root, so no sweep's scope contains another test's quarantine.What I could not establish, stated plainly
Whether my two security commits caused it. You reported these green at
b43ba98, and both of mine landed after — so they are the obvious suspects, andrefuse_writable_ancestordoes sit on the write path inside the held lock (write_atomic_guarded), which is a plausible mechanism for widening a narrow window.I tried to A/B it and the experiment was void: checking out
b43ba98with a stashedCargo.lockmade--lockedrefuse, so the base arm's "6 of 6 failures" wereerror: cannot update the lock file, not test failures. Reporting that rather than the number it produced, because the number looked like a damning result and meant nothing.If you can re-run your failing gate with the ancestor walk reverted (
git revert 636fe62, leaving539ffd3), that is the one-variable version I could not construct cleanly here.The one thing I would not do yet
Raise a TTL or serialise the module. Both would make this quiet without anyone knowing which of the two it was — and a vanishing directory is not a slow-test symptom.
ckcred-alfonso commentedon Sep 18, 2026
One of the two mechanisms behind this flake is now closed at 8afccbd, and it was not load; load only made it visible.
resolve_now_mswas the injected clock every comparison against aclaimed_at_msstamp was supposed to read, and its own comment said it was not yet uniform:ManifestLease::commitand the renewal thread still read the wall clock. The stamp was written from the injected clock, so those two sites measured real elapsed time against a stamp that never moved. Under a whole-bin parallel run, more than the 500ms TTL passed between claim and commit,ours_and_freshread false, and the lease refused its own write. Filtered to the module it passed 17/17 six times in a row; the whole bin target failed at load 22, not only at 37.Both sites now carry a clone of the clock the claim used, and the proofs are deterministic rather than flake reproductions: an injected clock, a 300ms real sleep inside a 200ms-TTL lease, commit must return
Ok. That fails 100% of the time under the old code by construction. Both sites mutation-verified by name; five whole-bin runs 45/45.What this does NOT close is the other failure you reported:
set_permissionsreturningNotFoundimmediately aftercreate_dirinset_directory_mtime, seen again today at load 39-42 onquarantine_past_ttl_but_inside_margin_is_retainedandreclaim_leaves_nonmatching_siblings_live_lock_and_other_manifest_quarantine. That is a different mechanism (a directory that existed a call ago does not), it is not a clock, and I still cannot name it. Leaving this open for that half.iceteaSA commentedon Sep 18, 2026
Two more members of the family failed today on a tree whose diff touches no Rust (PR #58, three TypeScript files over
30c077b, which carries8eb3b56andd296085). Reporting the measurements rather than a mechanism, because the mechanism did not reproduce when I went to pin it.Failures, both inside
scripts/gate.sh:commit_measures_the_lease_clock_not_the_wall_clock(opencode_files.rs:2093), 1-min load 9.8 at failurea_slow_lock_body_does_not_age_a_quarantine_into_reclamation(opencode_files.rs:1565), 1-min load 2.2 at failureThe second one is why I stopped calling it a load flake.
Then the same binary, direct, on a 16-core box:
cargo test --locked --workspace --features credentials-core/test-support: pass, pass (default threads), pass (--test-threads=1)manifest_lock_aba_regression: 6/6 pass, three default-threaded and three serialscripts/gate.sha third time, with a 2s process sampler running alongside: pass, 66s, peak load 5.0, nothing unusual in the top-6So: 2/3 fail inside the gate wrapper, 0/3 fail on the identical cargo line outside it, 0/6 fail focused. I could not find what the wrapper does differently.
run_expectcaptures output underset -euo pipefail, no env changes, no thread cap. The failure was not observable on the instrumented run.What the two tests have in common: both pin a clock, put a lease or quarantine about one second inside a threshold (
:1558ages the quarantine to 4100ms against a roughly 5100ms reclaim window), sleep 300-350ms inside the lock body, and assert the verdict used the pinned clock. If any path on the verdict still reads wall time, the one-second margin is the budget that sleep plus scheduling has to fit inside, and under a full-workspace run it sometimes will not. Your earlier note here said a passing suite cannot distinguish "fixed" from "made fixable" becausenow_override_ms: Nonefalls back to wall time. These two failures look like the shape that distinction predicts, but I am stating that as the hypothesis the data is consistent with, not as a finding. The instrumented run that should have caught it did not fail.PR #58 is opened against the green third run with all of this in its body.
ckcred-alfonso commentedon Sep 18, 2026
A third failure shape in this family, seen today at load 36 while gating PR #58 (zero Rust in that diff, so the test binary is master's), and it is distinct from both clock splits:
That rename is
write_lock_ownermoving<lock>/owner.<pid>.<nonce>.tmponto<lock>/owner, inside a lock directory the same thread created withfs::create_dira few calls earlier. Same shape as theseed_ownerfailure reported here before (set_permissionsaftercreate_dir,NotFound): a path the current thread just created is gone by the next syscall. Neither clock fix (commit/renewal at 8afccbd, reclaim seeding at d296085) reaches it, because no clock is consulted betweencreate_dirand the rename.What I have ruled out at source: every fixture root is
temp_dir/claustrum-manifest-lock-<name>-<pid>-<seq>, unique per test; the reclaim scanner deletes only<basename>.lock.stale-<digits>-<nonce>under the manifest's own parent, never a bare.lock; there is no temp-directory sweeper in the tree; the temporary's name carries pid and a fresh nonce, so two acquirers cannot collide on it. I do not have a mechanism, and I am not going to name one without a reproduction. Leaving this open for that half; the two clock halves are closed.One related fact for anyone reproducing: each test removes its root only on success, so a failed gate leaves
claustrum-manifest-lock-*roots in the temp dir (eleven on my machine right now, three with a live.lockstill inside). A test that reuses a pid and seq after a process recycle wouldcreate_dir_allonto a leftover root, but that yieldsAlreadyExistson the seeded quarantine, not thisNotFound, so it is not the cause; it is worth sweeping before a reproduction run so it cannot confuse one.iceteaSA commentedon Sep 18, 2026
Two facts from this box for whoever reproduces, no mechanism offered.
The leftover-root census you describe holds here too: 16
claustrum-manifest-lock-*roots in/tmp, 10 with a live.lockinside, oldest 2026-09-11. Swept before writing this so a reproduction here starts clean.One candidate I checked and can rule out on this tree: the renewal thread is joined in
stop_renewal(opencode_files.rs:86-91) before release returns, so a trailing renewal write racing the test's own root removal is not the path to thatNotFound.Neither of my two failures today was this shape; both were the clock-split tests, and both stopped reproducing under instrumentation.