test(mcp): measure daemon idle timeout from before the clock starts - #267
Merged
StefanSteiner merged 1 commit intoSep 6, 2026
Conversation
`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.
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.
What the assertion protects
daemon_idle_timeout_shuts_down_daemonputs a lower and an upper bound on how long the daemon takes to shut itself down once idle: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
hyperdprocess 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:The test took its own reference instant after that, and after spawning the monitor:
The monitor decides against
last_activity, soelapsedunder-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
elapsedabove the bound. It is the accumulated slack of twentysleep(100ms)calls — a property of the host's timer behaviour, not of anything the test controls: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-14runner can fail this where a 14-core laptop cannot.Evidence
Injecting a stall between
spawnreturning and the referenceInstant::now(), and measuring both candidate references in the same process. A preemption and a sleep are indistinguishable toInstant, so the stall is a faithful stand-in for losing the CPU in that window.new()(after)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:
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 beforelast_activity, soelapsed >= idle_timeoutholds 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/andhyperdb-mcp/tests/daemon_tests.rsbyte-identical — an empty diff. Both the test body andDaemonState::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-14job 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_shutdownhad the same defect behind a larger accidental cushion (~330 ms), measuring from after its heartbeat thread was joined rather than from the lasttouch(). It now reports the instant taken just before its finaltouch()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_idleis 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
macos-14is 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 listfailure counts are a lower bound. Demonstrated live on the run containing this failure — it now reportssuccessdespite having failed themacos-14leg.Verification
cargo test -p hyperdb-mcp --test daemon_tests—52 passed; 0 failed; 8 ignoredcargo fmt -p hyperdb-mcp -- --check— cleancargo clippy -p hyperdb-mcp --tests— cleanTest-only, with no public API surface change, so no per-crate changelog entry and no release impact.