Skip to content

test(mcp): measure daemon idle timeout from before the clock starts - #267

Merged
StefanSteiner merged 1 commit into
tableau:mainfrom
StefanSteiner:fix/daemon-idle-timeout-measurement-reference
Sep 6, 2026
Merged

test(mcp): measure daemon idle timeout from before the clock starts#267
StefanSteiner merged 1 commit into
tableau:mainfrom
StefanSteiner:fix/daemon-idle-timeout-measurement-reference

Conversation

@StefanSteiner

Copy link
Copy Markdown
Contributor

What the assertion protects

daemon_idle_timeout_shuts_down_daemon puts a lower and an upper bound on how long the daemon takes to shut itself down once idle:

assert!(elapsed >= Duration::from_secs(2));
assert!(elapsed < Duration::from_secs(4));

The upper bound proves the timeout fired at all. The lower bound proves it did not fire early, and that is the property worth keeping: the daemon owns a hyperd process shared by every connected MCP client, so an idle timeout that fires ahead of schedule tears down a live engine underneath them.

Widening the tolerance to make the failure go away would have discarded exactly the guarantee the test exists for. This PR changes what is measured rather than how much slack it is given.

Root cause

DaemonState::new() starts the idle countdown at construction:

// hyperdb-mcp/src/daemon/health.rs
pub fn new() -> Self {
    Self {
        last_activity: Mutex::new(Instant::now()),
        // ...
    }
}

The test took its own reference instant after that, and after spawning the monitor:

let state = Arc::new(DaemonState::new());  // idle clock starts here
let monitor = std::thread::spawn(/* counts against last_activity */);
let start = Instant::now();                // ...but we measure from here
monitor.join().unwrap();
let elapsed = start.elapsed();

The monitor decides against last_activity, so elapsed under-reports the interval the daemon actually waited by however long this thread spent constructing the state and spawning the monitor. The measured quantity is structurally smaller than the one the 2 s bound describes.

Why it hides on most hosts

The monitor polls on a 100 ms sleep, so it notices the deadline slightly past 2 s, and that overshoot is the only thing holding elapsed above the bound. It is the accumulated slack of twenty sleep(100ms) calls — a property of the host's timer behaviour, not of anything the test controls:

  • ~60 ms on an idle Apple Silicon laptop (measured 45.9–78.5 ms across 25 runs), which masks the defect completely.
  • Collapsing toward zero on a host whose 100 ms sleeps are accurate, because the fire then lands just barely past the boundary.

So the outcome is a race between two unrelated host-dependent quantities — sleep slack versus thread-spawn stall — neither of which has anything to do with the timeout under test. That is why a 3-core macos-14 runner can fail this where a 14-core laptop cannot.

Evidence

Injecting a stall between spawn returning and the reference Instant::now(), and measuring both candidate references in the same process. A preemption and a sleep are indistinguishable to Instant, so the stall is a faithful stand-in for losing the CPU in that window.

parent stall reference after spawn (before) reference before new() (after)
0 ms 0/4 fail 0/4 fail
30 ms 0/4 fail 0/4 fail
55 ms 1/4 fail 0/4 fail
70 ms 3/4 fail 0/4 fail
100 ms 4/4 fail 0/4 fail

At a 100 ms stall the old reference reads 1.967 s — under-reporting by exactly the injected amount — while the new one stays pinned at +69 ms regardless of stall. Under 56 concurrent CPU hogs the setup gap itself was observed widening from ~20 µs to 6.9 ms, confirming that window is genuinely load-sensitive rather than a fixed cost.

On the real test, a 150 ms injected stall reproduces the CI failure exactly:

panicked at hyperdb-mcp/tests/daemon_tests.rs:787:5:
assertion failed: elapsed >= Duration::from_secs(2)

With the new reference that same 150 ms stall passes, and so does 1500 ms. The bound is now a consequence of the monotonic clock rather than a margin: the monitor requests shutdown only once last_activity.elapsed() >= idle_timeout, and the reference is taken at or before last_activity, so elapsed >= idle_timeout holds by construction.

Pre-existing, not a regression from the rc.2 work

Worth stating plainly, since the observed failure landed on the release commit: a direct tree diff across all six recent merges plus the release commit shows hyperdb-mcp/src/daemon/ and hyperdb-mcp/tests/daemon_tests.rs byte-identical — an empty diff. Both the test body and DaemonState::new() trace back to #26, where they were introduced; only the edition-2024 migration has touched the test since.

CI corroborates this independently: the macos-14 job passed on a re-run of the identical commit. Nobody reading the release should suspect the rc.2 changes.

Sibling test

daemon_heartbeat_prevents_idle_shutdown had the same defect behind a larger accidental cushion (~330 ms), measuring from after its heartbeat thread was joined rather than from the last touch(). It now reports the instant taken just before its final touch() and asserts the full idle timeout instead of an arbitrary 500 ms.

Two nearby tests assert upper bounds right after a reset (idle_duration() < 30ms) and are deliberately left alone: an upper bound is inherent to asserting "touch resets the timer", their tolerance is intentional rather than accidental, and they fail under load rather than from a systematic bias. health_protocol_heartbeat_resets_idle is the most exposed of them, because its 30 ms window spans a TCP round-trip — it is the next candidate if it ever flakes.

Limits of this verification

  • The stochastic failure did not reproduce locally. 50 iterations of the full binary under 28 CPU hogs gave 0 failures both before and after the change, so that loop is inconclusive for this defect. Causation rests on the stall injection above, not on the loop.
  • The runner's actual cushion could not be measured, so the stall magnitude that occurred on macos-14 is unknown — only that it exceeded whatever the cushion is there. This PR's own CI run on that runner is the one environment the local loop could not supply.

Worth recording for whoever next audits flake history: re-running a failed job rewrites the run conclusion, so gh run list failure counts are a lower bound. Demonstrated live on the run containing this failure — it now reports success despite having failed the macos-14 leg.

Verification

  • cargo test -p hyperdb-mcp --test daemon_tests52 passed; 0 failed; 8 ignored
  • cargo fmt -p hyperdb-mcp -- --check — clean
  • cargo clippy -p hyperdb-mcp --tests — clean

Test-only, with no public API surface change, so no per-crate changelog entry and no release impact.

`daemon_idle_timeout_shuts_down_daemon` captured its `Instant::now()`
reference after `DaemonState::new()` had already started the idle
countdown, so `elapsed` under-reported the interval the monitor actually
waited by however long this thread took to construct the state and spawn
the monitor. The `elapsed >= 2s` lower bound then rested entirely on the
accumulated overshoot of the monitor's twenty 100ms sleeps — about 60ms
on an idle Apple Silicon host, and a property of the host's timer slack
rather than anything the test controls. A parent stall exceeding that
cushion, which an oversubscribed runner can produce between `spawn`
returning and `Instant::now()`, drives `elapsed` under two seconds and
fails the assertion. Seen once on the macos-14 leg; the same commit
passed on re-run.

Taking the reference before `DaemonState::new()` makes the bound follow
from the monotonic clock instead of a race: the monitor requests
shutdown only once `last_activity.elapsed() >= idle_timeout`, and the
reference is at or before `last_activity`, so `elapsed >= idle_timeout`
always holds. Injecting a 150ms stall after the spawn reproduces the
original failure exactly and passes with the new reference, as does
1500ms.

`daemon_heartbeat_prevents_idle_shutdown` shared the defect behind a
larger accidental cushion, measuring from after its heartbeat thread was
joined rather than from the last `touch()`. It now reports the instant
taken before its final touch and asserts the whole idle timeout instead
of an arbitrary 500ms. Both assertions also gained messages that print
the observed duration, which the original failure did not.
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.

1 participant