Skip to content

test(daemon): wait for leasing's held startup write, not 25 ms of real time - #453

Merged
V3RON merged 3 commits into
mainfrom
bug/399
Oct 11, 2026
Merged

V3RON merged 3 commits into
mainfrom
bug/399

Conversation

@V3RON

@V3RON V3RON commented Oct 11, 2026 •

Copy link
Copy Markdown
Contributor

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.

  1. src/daemon/main.test.ts (before this PR, line 681): after it calls startDaemon(...), the test runs await settleRealTime() (setTimeout(resolve, 25), line 535). Then it reads clock.pendingTimerCount and expects 1, the cleanup reaper's tick timer.
  2. That timer is armed in new CleanupReaper(...) (src/daemon/main.ts:299 calls src/core/reaper.ts:66 #armTick()). Before that line, startDaemon awaits real work. loadConfig (main.ts:139). NodeHostInfo.read() (main.ts:158-160, src/ports/host-info.ts:39): the test passes no hostInfo, so on macOS this spawns a real sw_vers process. Then Registry.load (main.ts:198) and loadInstanceId (main.ts:213).
  3. When the box is loaded (the full src/leasing src/core src/daemon src/http run, or parallel agents), the sw_vers spawn alone can take longer than 25 ms. The 25 ms timer then fires before startDaemon reaches main.ts:299. pendingTimerCount is still 0, and you get AssertionError: expected +0 to be 1.

When startup does reach the held write in time, the test is deterministic. convergeStartup (main.ts:384) runs leasing.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 same HoldingFilesystem. It waits await settleRealTime() (25 ms) and then expects started to be false. Startup runs the same real work before it reaches leasing (the sw_vers spawn and the rest). So after 25 ms, started is false whether 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 settleRealTime uses 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.close with no connections emits close on nextTick. A real timer fires only after that work has drained, however loaded the machine is. Evidence shows that one setImmediate is 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.writeFileAtomic resolves a writeReached promise when it starts holding the state.json write. The test awaits Promise.race([writeReached, starting]) before it reads the timer count.

Why the race is gone by construction: when writeReached resolves, startup is inside leasing.settleRequests()'s registry write. In startDaemon, main.ts:299 (reaper constructed, timer armed) comes before daemon.start() → convergeStartup → settleRequests → the write. So the reaper's timer is always armed by then. core.readStartup / core.converge are always held back, because they come after settleRequests returns, which needs the write. The count is 1 on every schedule, however long the steps before main.ts:299 take. The starting arm of the race covers a future startup that never writes state.json. Startup would then finish, and the test would fail on the count assertion, not hang until timeout.

The sibling test gets the same writeReached hook. Its only held write is leasing's Registry.endLeaseAndMarkDeviceMissing (reconciler → src/core/registry.ts:578), so writeReached means 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 the started flag would still read false. 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.converge on the fake driver, announceQueueDepth, the daemon.started emit 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 flipped started. A correct product cannot flip it, because it is parked on the held write. The settleRealTime doc 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 startDaemon a host-info read that takes 100 ms of real time. That stands in for a slow sw_vers spawn 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.

@@ -649,6 +649,12 @@ describe("startDaemon wires core and leasing together", () => {
         dataDirectory: directory,
         drivers: [driver],
         filesystem,
+        hostInfo: {
+          read: async () => {
+            await new Promise((resolve) => setTimeout(resolve, 100));
+            return new FakeHostInfo({ arch: "arm64", os: "macOS", osVersion: "15.5" }).read();
+          },
+        },
         logger: new JsonLinesLogger({ clock, level: "debug", sink: new MemoryLogSink() }),
         statePath,
         version: "1.2.3",

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:

 × finishes leasing's startup before core's convergence re-arms a quarantined device's retry 224ms
AssertionError: expected +0 to be 1 // Object.is equality
 ❯ src/daemon/main.test.ts:695:46
     expect(timersWhileLeasingStartupPending).toBe(1);
 Tests  1 failed | 66 skipped (67)

Same error as in the issue. This PR's code with the same patch:

 Test Files  1 passed (1)
      Tests  1 passed | 66 skipped (67)

The fixed test can still fail for the right reason (testing rule 2). Mutation: in convergeStartup, move await 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.setTimer call 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.

@@ -388,7 +388,6 @@ export async function startDaemon(options: StartDaemonOptions = {}): Promise<Dae
     const read = await core.readStartup();
     const steps = [
       () => core.doctor.reconcile({ read }),
-      () => leasing.reconcile(read),
       () => core.converge(read),
     ];
     for (const step of steps) {
@@ -396,6 +395,7 @@ export async function startDaemon(options: StartDaemonOptions = {}): Promise<Dae
       await step();
     }
     leasing.announceQueueDepth();
+    void leasing.reconcile(read);
   };

Forced slow startup: the same 100 ms hostInfo.read patch as above, applied to this test's options().

Command: pnpm exec vitest run --project unit src/daemon/main.test.ts -t "stays starting until leasing"

New test + break + slow startup:

 × stays starting until leasing has ended the lease whose device is not running, and no longer holds the lease once it is up 253ms
AssertionError: expected true to be false // Object.is equality
 ❯ src/daemon/main.test.ts:766:39
      Tests  1 failed | 66 skipped (67)

Old test (settleRealTime, cc5b11b) + break + slow startup:

      Tests  1 passed | 66 skipped (67)

Old test + break, with no slow patch: also 1 passed. The sw_vers spawn alone outlasts 25 ms here.

New test, break and slow patch both reverted: 1 passed. Waiting only for writeReached, without the setImmediate drain, also passes under the break. That is why the drain is there.

void leasing.reconcile(read) in place of awaiting it in steps is not a usable break. core.converge queues behind the held registry write, so startup stays parked. Old and new tests both pass under it, correctly.

The remaining settleRealTime uses are safe. Each was swapped for a single setImmediate and 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.

  • "holds shutdown open while a release's erase runs": settle no longer awaits leasing.settle() / core.drain(). Result: AssertionError: expected true to be false at :794, with 25 ms and with setImmediate.
  • "cancels the expiry timer…" and "cancels the quarantine retry timer…": dispose skips core.dispose() / leasing.dispose(). Results: expected [] to deeply equal [ Array(1) ] and expected [...] to have a length of 1 but got 2.
  • "probes a leased device again…": this test asserts something happens, so it cannot pass vacuously. It passes with one setImmediate.

Sanity check: pnpm exec vitest run --project unit src/daemon/main.test.ts: 67 passed.

Assumptions

  • Assumption: the four other settleRealTime uses stay as they are, because each is safe (Root cause, Evidence). Swapping them for setImmediate would 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:

  • spec: src/daemon/main.test.ts:693 count read with no macrotask settle after the write is reached, so a mutant passes — not true: making startup run void leasing.settleRequests() fails the test (expected 2 to be 1)
  • claims: src/daemon/main.test.ts:690 a void leasing.settleRequests() mutant arms the retry timer later and passes — not true: that exact mutant fails the test at line 700
  • claims: src/daemon/main.test.ts:533 the line 795 caller relies on settleRealTime during real socket I/O — not blocking: the comment is true, and the line 795 test is unchanged and outside the bug's scope

Closes #399

Written by an agent.

@V3RON

V3RON commented Oct 11, 2026

Copy link
Copy Markdown
Contributor Author

Review notes

Not blocking, not verified. Each is one reviewer's claim.

Written by an agent.

@V3RON
V3RON marked this pull request as ready for review October 11, 2026 13:05
@V3RON
V3RON merged commit d4e3962 into main Oct 11, 2026
25 checks passed
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.

flaky unit: startDaemon 'finishes leasing's startup before core's convergence re-arms a quarantined device's retry' fails under load

1 participant