Repository navigation
Conversation
… not 25 ms of real time (#399)
0 failing -> 0 failing
Contributor
Author
Review notesNot blocking, not verified. Each is one reviewer's claim.
Written by an agent. |
V3RON
marked this pull request as ready for review
October 11, 2026 13:05
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Root cause
The test uses 25 ms of real time to wait for the restarted daemon to reach a point in its startup. Nothing makes startup get there in 25 ms.
src/daemon/main.test.ts(before this PR, line 681): after it callsstartDaemon(...), the test runsawait settleRealTime()(setTimeout(resolve, 25), line 535). Then it readsclock.pendingTimerCountand expects1, the cleanup reaper's tick timer.new CleanupReaper(...)(src/daemon/main.ts:299callssrc/core/reaper.ts:66#armTick()). Before that line,startDaemonawaits real work.loadConfig(main.ts:139).NodeHostInfo.read()(main.ts:158-160,src/ports/host-info.ts:39): the test passes nohostInfo, so on macOS this spawns a realsw_versprocess. ThenRegistry.load(main.ts:198) andloadInstanceId(main.ts:213).src/leasing src/core src/daemon src/httprun, or parallel agents), thesw_versspawn alone can take longer than 25 ms. The 25 ms timer then fires beforestartDaemonreaches main.ts:299.pendingTimerCountis still 0, and you getAssertionError: expected +0 to be 1.When startup does reach the held write in time, the test is deterministic.
convergeStartup(main.ts:384) runsleasing.settleRequests()first. That waits on the registry write the test holds (src/leasing/lease-startup.ts:66-68), so core's convergence cannot start. The only race is between the 25 ms sleep and startup reaching the held write. Production code is not involved.The sibling test has the same sync point, and it cannot go red. "stays starting until leasing has ended the lease whose device is not running…" (
src/daemon/main.test.ts:704) restarts the daemon with the sameHoldingFilesystem. It waitsawait settleRealTime()(25 ms) and then expectsstartedto befalse. Startup runs the same real work before it reaches leasing (thesw_versspawn and the rest). So after 25 ms,startedisfalsewhether or not the product waits for leasing. The test passes vacuously (testing rule 2). Under load, or with the forced 100 ms startup delay, the old test passes even with leasing's reconcile moved out of startup (see Evidence); on an idle machine it may go red, so whether it proves anything depends on load.The other
settleRealTimeuses in the file (:795,:820,:836,:847) are safe. In each one, what a broken daemon would still have to do is in-memory work: a stop with no clients, the in-memory filesystem, the fake driver, and timers on the fake clock.net.Server.closewith no connections emitscloseonnextTick. A real timer fires only after that work has drained, however loaded the machine is. Evidence shows that onesetImmediateis already enough for each of them to go red under its break.Fix
The test now waits for the held write itself, not for real time.
HoldingFilesystem.writeFileAtomicresolves awriteReachedpromise when it starts holding thestate.jsonwrite. The test awaitsPromise.race([writeReached, starting])before it reads the timer count.Why the race is gone by construction: when
writeReachedresolves, startup is insideleasing.settleRequests()'s registry write. InstartDaemon, main.ts:299 (reaper constructed, timer armed) comes beforedaemon.start()→convergeStartup→settleRequests→ the write. So the reaper's timer is always armed by then.core.readStartup/core.convergeare always held back, because they come aftersettleRequestsreturns, which needs the write. The count is 1 on every schedule, however long the steps before main.ts:299 take. Thestartingarm of the race covers a future startup that never writesstate.json. Startup would then finish, and the test would fail on the count assertion, not hang until timeout.The sibling test gets the same
writeReachedhook. Its only held write is leasing'sRegistry.endLeaseAndMarkDeviceMissing(reconciler →src/core/registry.ts:578), sowriteReachedmeans startup has got as far as leasing ending the lease. Waiting for the write alone is not enough. A startup that does not wait for leasing reaches the write a few microtasks before it resolves, so thestartedflag would still readfalse. The test therefore drains one macrotask (setImmediate) after the race. From the write on, everything a non-waiting startup still has to do is in memory:core.convergeon the fake driver,announceQueueDepth, thedaemon.startedemit and the log to the memory sink, and the health monitor arming on the fake clock. So that drain is where a broken product has already flippedstarted. A correct product cannot flip it, because it is parked on the held write. ThesettleRealTimedoc comment now says when the helper is sound: only when the remaining work is all in memory.This is the simplest fix: two tests change, and no production code. No timeout is raised; the 25 ms was a guessed duration with nothing in the code behind it.
Evidence
Forcing the interleaving. Temporary patch, not committed: give
startDaemona host-info read that takes 100 ms of real time. That stands in for a slowsw_versspawn on a loaded machine, and it makes startup reach main.ts:299 only after the test's 25 ms timer has fired. The order is fixed: a 25 ms Node timer always fires before a 100 ms one set at almost the same moment.Command:
pnpm exec vitest run --project unit src/daemon/main.test.ts -t "re-arms a quarantined device"Unfixed code (main at 8eb9c87) with the patch:
Same error as in the issue. This PR's code with the same patch:
The fixed test can still fail for the right reason (testing rule 2). Mutation: in
convergeStartup, moveawait leasing.settleRequests()to after the core steps. The fixed test then fails on a named assertion, not a timeout:AssertionError: expected 3 to be 1. The mutation was reverted.I traced every
clock.setTimercall during the restart, to confirm the timer the test counts is the reaper's (main.ts:299 → reaper.ts:175). It is the only timer armed before the held write. The startup read's timeout, quarantine restore, warm-pool tick and health-monitor tick all come after the write is released.The sibling test can now fail for the right reason, and the old one could not. Temporary product break, not committed: startup no longer waits for leasing's reconcile. It runs it in the background after the other steps.
Forced slow startup: the same 100 ms
hostInfo.readpatch as above, applied to this test'soptions().Command:
pnpm exec vitest run --project unit src/daemon/main.test.ts -t "stays starting until leasing"New test + break + slow startup:
Old test (
settleRealTime, cc5b11b) + break + slow startup:Old test + break, with no slow patch: also
1 passed. Thesw_versspawn alone outlasts 25 ms here.New test, break and slow patch both reverted:
1 passed. Waiting only forwriteReached, without thesetImmediatedrain, also passes under the break. That is why the drain is there.void leasing.reconcile(read)in place of awaiting it instepsis not a usable break.core.convergequeues behind the held registry write, so startup stays parked. Old and new tests both pass under it, correctly.The remaining
settleRealTimeuses are safe. Each was swapped for a singlesetImmediateand run under a break of the behaviour it guards. All went red, so what a broken daemon still has to do finishes within one macrotask, and the 25 ms timer comes later than that.settleno longer awaitsleasing.settle()/core.drain(). Result:AssertionError: expected true to be falseat:794, with 25 ms and withsetImmediate.disposeskipscore.dispose()/leasing.dispose(). Results:expected [] to deeply equal [ Array(1) ]andexpected [...] to have a length of 1 but got 2.setImmediate.Sanity check:
pnpm exec vitest run --project unit src/daemon/main.test.ts: 67 passed.Assumptions
settleRealTimeuses stay as they are, because each is safe (Root cause, Evidence). Swapping them forsetImmediatewould change four tests and fix no bug.Review
Spec review: 1 blocking, 0 fixed, 2 notes. Code review: 0 blocking, 0 fixed, 1 notes. Claims review: 0 blocking, 0 fixed, 1 notes. Comment review: 4 blocking, 4 fixed, 0 notes.
Mutate: 0 mutants, 0 alive.
Rejected:
void leasing.settleRequests()fails the test (expected 2 to be 1)void leasing.settleRequests()mutant arms the retry timer later and passes — not true: that exact mutant fails the test at line 700Closes #399
Written by an agent.