fleet/fleetd
3
0
Fork 0
Code Issues 73 Pull Requests Actions Packages Projects Releases 1 Wiki Activity

Every fleetd timer freezes while the macOS host sleeps: System.nanoTime() stops, so the stall detector missed a member that was BUSY for 101 minutes #386

New Issue
Closed
opened 2026-09-10 01:26:13 +02:00 by ltms · 1 comment
ltms commented 2026-09-10 01:26:13 +02:00
Owner
Copy Link
Copy Source

Measured on the Mac (fleetd pid 77047, jar built 2026-09-09 13:33:56, HEAD at build 127e683), 2026-09-10.

The measurement

System.nanoTime() on macOS does not advance while the system is asleep. fleetd uses it for every duration it measures. So on a laptop that sleeps, all of fleetd's clocks run slow.

$ ps -o etime= -p 77047
  16:49:01                       # 60,541 s of real time since the daemon started

$ jcmd 77047 VM.uptime
2966.601 s                       # 2,967 s on the monotonic clock

The daemon has been up for 16 h 49 min of real time and has counted 49 minutes.

Control — the clock is not simply broken. Two readings 91 s apart while the host was awake:

T0 wall=1788996195 uptime=2983.247 s
T1 wall=1788996286 uptime=3073.475 s

91 s of real time, 90.2 s of monotonic time. So the clock runs at 1:1 when the host is awake. The whole 57,575 s deficit is sleep time.

What it broke

A sonnet member sat BUSY for 101 minutes and FleetHealthMonitor never flagged it, although the threshold is 10 minutes.

04:30:40  SessionManager - session transitioned terminal=term_65b138e0fa216df ... READY -> BUSY turn=1
06:11:41  SessionManager - releasing session pane=... terminal=term_65b138e0fa216df state=BUSY cause=COMPLETED
  • fleetd.yaml sets workingSuspectAfterSeconds: 600.
  • FleetHealthMonitor.java:135 computes stalled as state == BUSY && nowNanos - session.lastActivityAtNanos() >= workingSuspectAfterNanos, and nowNanos is System::nanoTime (Fleetd.java:588).
  • lastActivityAtNanos is set once, when the member goes BUSY (SessionManager.java:835), and no path refreshes it while BUSY. So the clock, not the bookkeeping, is what kept stalled false.

Denominator. Since the last boot there were 4 BUSY spans. Exactly 1 ran over 600 s of real time (6,060.7 s). It was not flagged. The other 3 were 117 s, 137 s and 147 s, so they should not have been.

Positive control — the monitor was able to look. Its virtual thread is alive and waiting for its next tick:

name: bridge-health- state: TIMED_WAITING virtual: True
    java.base/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(...)

and the same monitor did report stalls in earlier boots, for example:

07:21:47 WARN FleetHealthMonitor - fleet health member=term_65b01ac20cbd5d0 state=STALL_SUSPECTED previous=WORKING

So this is not a dead thread and not a disabled feature. The monitor ran and its clock said 4 minutes had passed.

Why the host slept. pmset -g log shows near-continuous Entering Sleep state due to 'Maintenance Sleep' from 00:31 to 06:10, broken only by ~45 s DarkWakes. The real wake at 06:10:14 is logged as lid ... HID Activity.

#374's guard did not stop it. IdleSleepGuard armed correctly when the member spawned:

04:30:09 DEBUG IdleSleepGuard - idle-sleep guard armed: 1 live member(s)

and the host slept 36 seconds later. CaffeinateSleepAssertionMechanism.java:50 runs caffeinate -i, which asserts against idle sleep. These sleeps are logged as Maintenance Sleep. I have not tested whether another caffeinate flag would hold them off, so treat that as untested, not as ruled out.

How wide this is

System::nanoTime is wired into 8 components in Fleetd.java (lines 219, 225, 260, 330, 474, 569, 588, 674), and SessionReaper.java:79 calls it directly. So the same freeze applies to the backend quarantine cooldown, the backend cool-off window, the lead tab scan interval, the completion resolver, the session reaper's idle TTL and the message service's ticket TTL. I measured the effect only on the health monitor's stall threshold. The others follow from reading the wiring, not from a test.

Is it a bug?

There is a real argument that it is correct: the member process was frozen too, so it did not have 101 minutes of work time. But a lead reasons in real time. It sees a member that has been busy since last night and gets no signal, and a fleet planner sees the slot counted live. The detector and the operator disagree about what "10 minutes" means, and nothing says so.

Suggested direction

Not a full design, just where the seam is:

  1. Give FleetHealthMonitor a real-time clock for its stall threshold, or feed it both clocks and treat a large divergence as its own fact.
  2. When the two clocks diverge by more than a tick interval, log it once. That single line turns "the fleet was quiet" into "the detector was frozen for N minutes", which is the difference between a zero that means nothing happened and a zero that means I could not look.
  3. Decide per timer, not globally. A ticket TTL that pauses with the host may well be what you want; a stall detector that pauses is not.

Related

  • #383 (fleet01 lead) — the per-member health state is detected but never reaches the lead. Different defect, same feature: that one is about surfacing a state, this one is about the state never being computed.
  • #374 — the idle-sleep guard. Armed and did not prevent these sleeps.
Measured on the Mac (`fleetd` pid 77047, jar built 2026-09-09 13:33:56, HEAD at build `127e683`), 2026-09-10. ## The measurement `System.nanoTime()` on macOS does not advance while the system is asleep. fleetd uses it for every duration it measures. So on a laptop that sleeps, all of fleetd's clocks run slow. ``` $ ps -o etime= -p 77047 16:49:01 # 60,541 s of real time since the daemon started $ jcmd 77047 VM.uptime 2966.601 s # 2,967 s on the monotonic clock ``` The daemon has been up for 16 h 49 min of real time and has counted 49 minutes. **Control — the clock is not simply broken.** Two readings 91 s apart while the host was awake: ``` T0 wall=1788996195 uptime=2983.247 s T1 wall=1788996286 uptime=3073.475 s ``` 91 s of real time, 90.2 s of monotonic time. So the clock runs at 1:1 when the host is awake. The whole 57,575 s deficit is sleep time. ## What it broke A `sonnet` member sat BUSY for 101 minutes and `FleetHealthMonitor` never flagged it, although the threshold is 10 minutes. ``` 04:30:40 SessionManager - session transitioned terminal=term_65b138e0fa216df ... READY -> BUSY turn=1 06:11:41 SessionManager - releasing session pane=... terminal=term_65b138e0fa216df state=BUSY cause=COMPLETED ``` - `fleetd.yaml` sets `workingSuspectAfterSeconds: 600`. - `FleetHealthMonitor.java:135` computes `stalled` as `state == BUSY && nowNanos - session.lastActivityAtNanos() >= workingSuspectAfterNanos`, and `nowNanos` is `System::nanoTime` (`Fleetd.java:588`). - `lastActivityAtNanos` is set once, when the member goes BUSY (`SessionManager.java:835`), and no path refreshes it while BUSY. So the clock, not the bookkeeping, is what kept `stalled` false. **Denominator.** Since the last boot there were 4 BUSY spans. Exactly 1 ran over 600 s of real time (6,060.7 s). It was not flagged. The other 3 were 117 s, 137 s and 147 s, so they should not have been. **Positive control — the monitor was able to look.** Its virtual thread is alive and waiting for its next tick: ``` name: bridge-health- state: TIMED_WAITING virtual: True java.base/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(...) ``` and the same monitor did report stalls in earlier boots, for example: ``` 07:21:47 WARN FleetHealthMonitor - fleet health member=term_65b01ac20cbd5d0 state=STALL_SUSPECTED previous=WORKING ``` So this is not a dead thread and not a disabled feature. The monitor ran and its clock said 4 minutes had passed. **Why the host slept.** `pmset -g log` shows near-continuous `Entering Sleep state due to 'Maintenance Sleep'` from 00:31 to 06:10, broken only by ~45 s DarkWakes. The real wake at 06:10:14 is logged as `lid ... HID Activity`. **#374's guard did not stop it.** `IdleSleepGuard` armed correctly when the member spawned: ``` 04:30:09 DEBUG IdleSleepGuard - idle-sleep guard armed: 1 live member(s) ``` and the host slept 36 seconds later. `CaffeinateSleepAssertionMechanism.java:50` runs `caffeinate -i`, which asserts against *idle* sleep. These sleeps are logged as Maintenance Sleep. I have not tested whether another `caffeinate` flag would hold them off, so treat that as untested, not as ruled out. ## How wide this is `System::nanoTime` is wired into 8 components in `Fleetd.java` (lines 219, 225, 260, 330, 474, 569, 588, 674), and `SessionReaper.java:79` calls it directly. So the same freeze applies to the backend quarantine cooldown, the backend cool-off window, the lead tab scan interval, the completion resolver, the session reaper's idle TTL and the message service's ticket TTL. **I measured the effect only on the health monitor's stall threshold.** The others follow from reading the wiring, not from a test. ## Is it a bug? There is a real argument that it is correct: the member process was frozen too, so it did not have 101 minutes of work time. But a lead reasons in real time. It sees a member that has been busy since last night and gets no signal, and a fleet planner sees the slot counted live. The detector and the operator disagree about what "10 minutes" means, and nothing says so. ## Suggested direction Not a full design, just where the seam is: 1. Give `FleetHealthMonitor` a real-time clock for its stall threshold, or feed it both clocks and treat a large divergence as its own fact. 2. When the two clocks diverge by more than a tick interval, log it once. That single line turns "the fleet was quiet" into "the detector was frozen for N minutes", which is the difference between a zero that means *nothing happened* and a zero that means *I could not look*. 3. Decide per timer, not globally. A ticket TTL that pauses with the host may well be what you want; a stall detector that pauses is not. ## Related - #383 (fleet01 lead) — the per-member health state is detected but never reaches the lead. Different defect, same feature: that one is about surfacing a state, this one is about the state never being computed. - #374 — the idle-sleep guard. Armed and did not prevent these sleeps.
ltms commented 2026-09-10 02:00:19 +02:00
Author
Owner
Copy Link
Copy Source

Merged as fd8650c (PR #389), plus a follow-up test in b9d09e0. Verified here.

What landed

FleetHealthMonitor takes a second clock, realtimeClock, used only inside the stall check. Each tick compares this tick's monotonic and real-time deltas against the previous tick's; a positive divergence is added to a running accumulatedDriftNanos ratchet, and the stall check adds that drift back. Readiness grace, the snapshot timestamp and the fault classification all stay on the monotonic clock, as the ticket asked. Fleetd.java passes both clocks. Everything else named in the ticket as out of scope — quarantine cooldown, backend cool-off, lead tab scan, completion resolver, session reaper TTL, ticket TTL — is untouched.

A single WARN names how many seconds the detector could not see. Since the process itself is suspended, one sleep always lands inside exactly one tick's gap, so one sleep gives one line.

Build at the merged HEAD: Tests run: 1466, Failures: 0, Errors: 0, Skipped: 0, BUILD SUCCESS, exit 0. Unpiped, to a file.

The gap I found, and it is the one the worker predicted

The worker did the right thing twice over. It rejected the simple design — one global drift counter — because that counter is a correctness bug, not just a rough edge: drift from a sleep hours before a member connected would be added to that member's very first stall reading, so every future BUSY span would read as instantly stalled forever. It built a per-member baseline instead. Then it wrote in its own report that a reviewer should double-check that logic, because its tests only pin the simple case.

It was right. Both tests it shipped start with the member already BUSY before the sleep. So I mutated the per-member baseline back to the global one it had rejected:

- busyDriftBaselineNanos.put(target, driftBeforeThisTick);
+ busyDriftBaselineNanos.put(target, 0L);

Tests run: 23, Failures: 0, BUILD SUCCESS. Green. The complexity that exists to prevent a correctness bug was not pinned by anything.

This is the pattern again: the worker's proof only covers the line it changed. Its mutation reverted the stall formula and its test caught that. The formula was never the risky part.

The test I added

driftFromASleepBeforeAMemberWentBusyIsNotChargedToThatMember. The ordering is the whole test: the host sleeps 700s while nothing is busy, and only then does a member take a turn with a fresh activity stamp. Its stall clock must start at zero.

Against the mutation:

driftFromASleepBeforeAMemberWentBusyIsNotChargedToThatMember:325
  the member has been busy for 10s, not 710s — the earlier sleep is not its stall
  ==> expected: <0> but was: <1>

Restored, full build green: Tests run: 1467, Failures: 0, Errors: 0, Skipped: 0.

Things I checked and am satisfied with

  • baselineActivity != session.lastActivityAtNanos() compares a boxed Long against a primitive long. lastActivityAtNanos is declared long at MemberSession.java:43, so this unboxes to a value comparison. It is not the reference-equality trap it resembles.
  • A backward clock jump cannot corrupt the ratchet. if (tickDrift > 0) skips it, so an NTP correction that moves real time back is ignored rather than subtracted.
  • Existing tests cannot accidentally engage the drift path. They pass a fake monotonic clock and the real wall clock, so a test that jumps the fake clock by hours produces a large negative tickDrift, which the same guard drops.

Two things left open, deliberately

A large forward jump in System.currentTimeMillis() that is not a sleep — a big NTP correction, or the operator setting the clock — is counted as drift and shortens the effective stall threshold for every BUSY member. The result is a spurious STALL_SUSPECTED, which is a WARN and a health state; terminal() covers only GONE and NEVER_READY, so nothing gets torn down. Loud and wrong beats silent and wrong for a detector, so I am leaving it.

The tick-granularity edge the worker named. If the host wakes and a member goes BUSY before the first tick after the wake, that whole sleep is charged to the new BUSY span. Same blast radius: one spurious warning. Fixing it properly means recording a wall-clock stamp beside lastActivityAtNanos in SessionManager, which is out of this ticket's scope. The worker's choice to err toward over-reporting is the right one for a detector whose entire failure mode was under-reporting.

Not fixed by this ticket

Only the stall threshold is corrected. System::nanoTime is still wired into every other component listed above, so quarantine cooldowns, backend cool-off, ticket TTLs and the idle reaper all still freeze with the host. I measured only the stall threshold, and I did not form a view that any of the others is wrong — a TTL that pauses with the host is defensible. If that changes, it is a new ticket, not this one.

Closing.

Merged as `fd8650c` (PR #389), plus a follow-up test in `b9d09e0`. Verified here. ## What landed `FleetHealthMonitor` takes a second clock, `realtimeClock`, used **only** inside the stall check. Each tick compares this tick's monotonic and real-time deltas against the previous tick's; a positive divergence is added to a running `accumulatedDriftNanos` ratchet, and the stall check adds that drift back. Readiness grace, the snapshot timestamp and the fault classification all stay on the monotonic clock, as the ticket asked. `Fleetd.java` passes both clocks. Everything else named in the ticket as out of scope — quarantine cooldown, backend cool-off, lead tab scan, completion resolver, session reaper TTL, ticket TTL — is untouched. A single WARN names how many seconds the detector could not see. Since the process itself is suspended, one sleep always lands inside exactly one tick's gap, so one sleep gives one line. **Build at the merged HEAD:** `Tests run: 1466, Failures: 0, Errors: 0, Skipped: 0`, `BUILD SUCCESS`, exit 0. Unpiped, to a file. ## The gap I found, and it is the one the worker predicted The worker did the right thing twice over. It rejected the simple design — one global drift counter — because that counter is a **correctness bug**, not just a rough edge: drift from a sleep hours before a member connected would be added to that member's very first stall reading, so every future BUSY span would read as instantly stalled forever. It built a per-member baseline instead. Then it wrote in its own report that a reviewer should double-check that logic, because its tests only pin the simple case. It was right. Both tests it shipped start with the member **already BUSY** before the sleep. So I mutated the per-member baseline back to the global one it had rejected: ```java - busyDriftBaselineNanos.put(target, driftBeforeThisTick); + busyDriftBaselineNanos.put(target, 0L); ``` `Tests run: 23, Failures: 0, BUILD SUCCESS`. Green. The complexity that exists to prevent a correctness bug was not pinned by anything. This is the pattern again: **the worker's proof only covers the line it changed.** Its mutation reverted the stall formula and its test caught that. The formula was never the risky part. ## The test I added `driftFromASleepBeforeAMemberWentBusyIsNotChargedToThatMember`. The ordering is the whole test: the host sleeps 700s **while nothing is busy**, and only then does a member take a turn with a fresh activity stamp. Its stall clock must start at zero. Against the mutation: ``` driftFromASleepBeforeAMemberWentBusyIsNotChargedToThatMember:325 the member has been busy for 10s, not 710s — the earlier sleep is not its stall ==> expected: <0> but was: <1> ``` Restored, full build green: `Tests run: 1467, Failures: 0, Errors: 0, Skipped: 0`. ## Things I checked and am satisfied with - **`baselineActivity != session.lastActivityAtNanos()`** compares a boxed `Long` against a primitive `long`. `lastActivityAtNanos` is declared `long` at `MemberSession.java:43`, so this unboxes to a value comparison. It is not the reference-equality trap it resembles. - **A backward clock jump cannot corrupt the ratchet.** `if (tickDrift > 0)` skips it, so an NTP correction that moves real time back is ignored rather than subtracted. - **Existing tests cannot accidentally engage the drift path.** They pass a fake monotonic clock and the real wall clock, so a test that jumps the fake clock by hours produces a large *negative* `tickDrift`, which the same guard drops. ## Two things left open, deliberately **A large forward jump in `System.currentTimeMillis()` that is not a sleep** — a big NTP correction, or the operator setting the clock — is counted as drift and shortens the effective stall threshold for every BUSY member. The result is a spurious `STALL_SUSPECTED`, which is a WARN and a health state; `terminal()` covers only `GONE` and `NEVER_READY`, so nothing gets torn down. Loud and wrong beats silent and wrong for a detector, so I am leaving it. **The tick-granularity edge the worker named.** If the host wakes and a member goes BUSY before the first tick after the wake, that whole sleep is charged to the new BUSY span. Same blast radius: one spurious warning. Fixing it properly means recording a wall-clock stamp beside `lastActivityAtNanos` in `SessionManager`, which is out of this ticket's scope. The worker's choice to err toward over-reporting is the right one for a detector whose entire failure mode was under-reporting. ## Not fixed by this ticket Only the stall threshold is corrected. `System::nanoTime` is still wired into every other component listed above, so quarantine cooldowns, backend cool-off, ticket TTLs and the idle reaper all still freeze with the host. I measured only the stall threshold, and I did not form a view that any of the others is wrong — a TTL that pauses with the host is defensible. If that changes, it is a new ticket, not this one. Closing.
ltms closed this issue 2026-09-10 02:00:24 +02:00
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels
blocked
Cannot start until something else lands. The body says what.
 needs-live-proof
Merged and green, but never shown working on the running daemon. Not the same as done.
 ready-to-delegate
Scope, files and acceptance criteria are written. A worker can be briefed from the body alone.
 silent-default
A feature that compiles, passes tests, and ships turned off. Nine recurrences and counting.
No Label
Milestone
No items
No Milestone
Projects
Clear projects
No project
Assignees
Clear assignees
agent kevin ltms
No Assignees
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: fleet/fleetd#386
Delete Branch "%!s()"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?