#386: give the stall detector a real-time clock, log the divergence #389

Closed
agent wants to merge 0 commits from worker/t386-clock-bd5b78-4 into main
Member

Fixes #386.

What changed

FleetHealthMonitor's stall check compared two readings of the monotonic clock
(System.nanoTime() by default), which macOS freezes across a host sleep. So a
member that was BUSY for 101 real minutes while the host slept was never flagged
STALL_SUSPECTED, even though the threshold (workingSuspectAfterSeconds) is 600s.

Two changes, exactly the two the ticket names:

  1. The stall check gets a second, wall-clock clock. FleetHealthMonitor now
    takes an additional LongSupplier realtimeClock (existing 8-arg constructor is
    kept, delegating to a default of System.currentTimeMillis() converted to
    nanos, so no caller breaks). Every other decision in the class — readiness
    grace, the snapshot timestamp fed to decide() — stays on the original
    monotonic clock, unchanged.
  2. The divergence is logged once, at WARN, when it's large. Each tick compares
    this tick's monotonic/real-time deltas against the previous tick's. A tick
    cannot run while the process itself is suspended, so an entire sleep lands
    inside exactly one tick's gap — when that gap's divergence exceeds one tick
    interval, it logs one line naming how long the detector could not see.

The two-clock comparison for lastActivityAtNanos

lastActivityAtNanos (SessionManager.java:835) is still written from the
monotonic clock — I did not touch SessionManager. Comparing a wall-clock "now"
directly against that monotonic "then" would be meaningless, so instead: the
monitor accumulates the drift observed between the two clocks tick-to-tick (a
ratchet — it only grows, since the monotonic clock can only lag real time, never
lead it), and adds that accumulated drift into the stall elapsed-time
computation, keeping the comparison in monotonic-nanos units throughout.

Critically, the drift is not accumulated since monitor start — it's
attributed per member, since that member's current BUSY span started: the
monitor records the accumulated-drift value at the moment it first observes a
given lastActivityAtNanos on a BUSY session, and only adds drift accrued
after that point. Without this, a single old sleep (say, 6 hours, long before
today's session even connected) would otherwise permanently poison every future
BUSY member's stall check, since the raw monotonic elapsed time would never be
enough to offset a always-growing global drift total — every single future BUSY
span would read as instantly stalled. Per-member baselines fix that: a sleep that
happened before a member went busy is never charged to it.

Tests

  • monotonicClockFrozenPastThresholdOnRealClockStillReportsStallSuspected: the
    monotonic clock stands still while the real clock advances past the 600s
    threshold; asserts STALL_SUSPECTED is logged for the member. This is the
    ticket's whole point.
  • clockDivergenceIsLoggedOnceNotOncePerTick: one sleep gap (mono frozen, real
    jumps 700s), then several normal ticks with both clocks advancing 1:1; asserts
    the divergence line appears exactly once.
  • All existing FleetHealthMonitor/FleetHealth tests pass unmodified — none of
    them ticks a BUSY session more than once, so the drift path never engages for
    them (verified: no assertion values changed).

Mutation proof: reverted the stall check to the old
nowNanos - session.lastActivityAtNanos() formula, re-ran
monotonicClockFrozenPastThresholdOnRealClockStillReportsStallSuspected — it
failed (expected: <true> but was: <false>). Restored the fix and reran the full
suite green.

Scope note

The ticket's "how wide this is" section lists 8 more System::nanoTime call
sites (backend quarantine cooldown, backend cool-off window, lead tab scan,
completion resolver, session reaper idle TTL, message service ticket TTL) as
following the same freeze by construction. Per the ticket's explicit decision, I
left all of those untouched — a TTL that pauses with the host is defensible, only
the stall detector was in scope here.

Build

mvn clean install in fleetd/: BUILD SUCCESS,
Tests run: 1463, Failures: 0, Errors: 0, Skipped: 0.

Fixes #386. ## What changed `FleetHealthMonitor`'s stall check compared two readings of the monotonic clock (`System.nanoTime()` by default), which macOS freezes across a host sleep. So a member that was `BUSY` for 101 real minutes while the host slept was never flagged `STALL_SUSPECTED`, even though the threshold (`workingSuspectAfterSeconds`) is 600s. Two changes, exactly the two the ticket names: 1. **The stall check gets a second, wall-clock clock.** `FleetHealthMonitor` now takes an additional `LongSupplier realtimeClock` (existing 8-arg constructor is kept, delegating to a default of `System.currentTimeMillis()` converted to nanos, so no caller breaks). Every other decision in the class — readiness grace, the snapshot timestamp fed to `decide()` — stays on the original monotonic `clock`, unchanged. 2. **The divergence is logged once, at WARN, when it's large.** Each tick compares this tick's monotonic/real-time deltas against the previous tick's. A tick cannot run while the process itself is suspended, so an entire sleep lands inside exactly one tick's gap — when that gap's divergence exceeds one tick interval, it logs one line naming how long the detector could not see. ## The two-clock comparison for `lastActivityAtNanos` `lastActivityAtNanos` (`SessionManager.java:835`) is still written from the monotonic clock — I did not touch `SessionManager`. Comparing a wall-clock "now" directly against that monotonic "then" would be meaningless, so instead: the monitor accumulates the *drift* observed between the two clocks tick-to-tick (a ratchet — it only grows, since the monotonic clock can only lag real time, never lead it), and adds that accumulated drift into the stall elapsed-time computation, keeping the comparison in monotonic-nanos units throughout. Critically, the drift is **not** accumulated since monitor start — it's attributed **per member, since that member's current BUSY span started**: the monitor records the accumulated-drift value at the moment it first observes a given `lastActivityAtNanos` on a `BUSY` session, and only adds drift accrued *after* that point. Without this, a single old sleep (say, 6 hours, long before today's session even connected) would otherwise permanently poison every future `BUSY` member's stall check, since the raw monotonic elapsed time would never be enough to offset a always-growing global drift total — every single future BUSY span would read as instantly stalled. Per-member baselines fix that: a sleep that happened before a member went busy is never charged to it. ## Tests - `monotonicClockFrozenPastThresholdOnRealClockStillReportsStallSuspected`: the monotonic clock stands still while the real clock advances past the 600s threshold; asserts `STALL_SUSPECTED` is logged for the member. This is the ticket's whole point. - `clockDivergenceIsLoggedOnceNotOncePerTick`: one sleep gap (mono frozen, real jumps 700s), then several normal ticks with both clocks advancing 1:1; asserts the divergence line appears exactly once. - All existing `FleetHealthMonitor`/`FleetHealth` tests pass unmodified — none of them ticks a `BUSY` session more than once, so the drift path never engages for them (verified: no assertion values changed). **Mutation proof:** reverted the stall check to the old `nowNanos - session.lastActivityAtNanos()` formula, re-ran `monotonicClockFrozenPastThresholdOnRealClockStillReportsStallSuspected` — it failed (`expected: <true> but was: <false>`). Restored the fix and reran the full suite green. ## Scope note The ticket's "how wide this is" section lists 8 more `System::nanoTime` call sites (backend quarantine cooldown, backend cool-off window, lead tab scan, completion resolver, session reaper idle TTL, message service ticket TTL) as following the same freeze by construction. Per the ticket's explicit decision, I left all of those untouched — a TTL that pauses with the host is defensible, only the stall detector was in scope here. ## Build `mvn clean install` in `fleetd/`: **BUILD SUCCESS**, `Tests run: 1463, Failures: 0, Errors: 0, Skipped: 0`.
agent added 1 commit 2026-09-10 01:54:07 +02:00
#386: give the stall detector a real-time clock, log the divergence
CI / contract (pull_request) Successful in 1m18s
CI / build (pull_request) Successful in 1m26s
769f282408
FleetHealthMonitor.tick's stalled check compared two monotonic-clock
readings (System.nanoTime(), which macOS freezes across a host sleep),
so a member BUSY for 101 real minutes was never flagged.

The monitor now also takes a wall-clock LongSupplier (realtimeClock),
used only inside the stall check. Each tick measures how far the two
clocks moved apart since the previous tick and folds any positive
divergence into a running total; when a single tick's divergence
exceeds one tick interval (the signature of a sleep, since a tick
cannot run while the process itself is suspended) it logs one WARN
naming how long the detector could not see. The correction is applied
per member, keyed to when that member's current lastActivityAtNanos
was first observed BUSY - not since monitor start - so a sleep that
happened before a member went busy is never charged to it.

Every other use of the monitor's clock (readiness grace, snapshot
timestamp) is unchanged. Backend quarantine/cool-off, the lead tab
scan, the completion resolver, the session reaper and the message
service TTLs are untouched, per the ticket's decision.

Existing FleetHealthMonitor/FleetHealth tests pass unmodified (none of
them ticks a BUSY session more than once, so the drift path never
engages for them). Two new tests: a frozen monotonic clock past the
real-time threshold produces STALL_SUSPECTED, and a single sleep gap
logs the divergence exactly once, not once per tick.
ltms closed this pull request 2026-09-10 02:04:25 +02:00
Some checks are pending
CI / contract (pull_request) Successful in 1m18s
CI / build (pull_request) Successful in 1m26s

Pull request closed

Sign in to join this conversation.