fix(hook): give the callback watchdog the same watched-time rule - #1624
Merged
Merged
Conversation
The stuck-callback watchdog compared the callback's entry time against now every 20 ms and force-exited past 200 ms. Like the lifecycle watchdog before the previous two commits, that charges the callback for time the watchdog thread itself was not running: a callback entered just before the process-wide freeze around a sleep transition would read as stuck the moment the watchdog thawed, even though the tap thread froze with it. The window is the microseconds a callback is entered, so this has not been seen in a log yet; it is the same defect with a smaller target. The decision now lives in a sans-I/O CallbackWatchdog with the lifecycle watchdog's rule: a poll charges the whole gap since the previous one unless kern.sleeptime or kern.waketime moved inside it, in which case at most CALLBACK_OBSERVATION_GAP (5 polls, 100 ms) is charged; an entry is judged on the stall the watchdog was awake to see. The exit log prints stalled_ms next to watched_ms. Normal operation is unchanged: with the thread polling on time, a callback that never returns is still exited on the first poll at or past 200 ms. Refs #952
|
The callback watchdog thread sleeps one poll interval before its first poll, and a watchdog with no previous poll credited that first gap as nothing. A callback that wedged in that window, with the first poll itself delayed past the budget by scheduling, was granted a second 200 ms before the exit (review finding on #1624). The watchdog now starts with the instant it was spawned as its previous poll, so the first gap is charged like every later one; a kernel sleep or wake inside it is discounted as elsewhere.
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.
Summary
The stuck-callback watchdog compared the tap callback's entry time against now every 20 ms and force-exited past 200 ms. Like the lifecycle watchdog before #1282, that charges the callback for time the watchdog thread itself was not running: a callback entered just before the process-wide freeze around a sleep transition would read as stuck the moment the watchdog thawed, even though the tap thread froze with it. The window is the microseconds a callback is entered, so this has not been seen in a log yet; it is the same defect #1282 fixed for the lifecycle watchdog, with a smaller target. Refs #952.
Changes
openlogi-hook: the decision moves out of the poll loop into a sans-I/OCallbackWatchdogwith the lifecycle watchdog's rule. A poll charges the whole gap since the previous one unlesskern.sleeptimeorkern.waketimemoved inside it, in which case at mostCALLBACK_OBSERVATION_GAP(5 polls, 100 ms) is charged; an entry is judged on the stall the watchdog was awake to see.stuck_callbackis gone;CALLBACK_POLL_INTERVALmoves next to the other watchdog constants. The exit log printsstalled_msnext towatched_ms, like the lifecycle exit.crates/openlogi-hook/AGENTS.md: the watched-time rule now names both watchdogs.Normal operation is unchanged: with the thread polling on time, a callback that never returns is still exited on the first poll at or past 200 ms (
callback_timeout_keeps_the_200ms_boundarydrives the real 20 ms cadence and lands at 205 ms).Testing
Run on macOS 26 (arm64) with
RUSTFLAGS="-D warnings", rebased onto master after #1282:cargo fmt --all -- --checkcargo clippy --workspace --all-targets -- -D warningscargo test --workspaceRUSTDOCFLAGS="-D warnings" cargo doc --workspace --no-deps --document-private-items --exclude openlogi-ui --exclude openlogi-desktop --exclude openlogi-overlay --exclude openlogi-agentcargo xtask ci clippy-windowsMutation checks: without the sleep-gated credit cap,
a_frozen_process_is_not_a_stuck_callbackandrepeated_sleep_cycles_still_accumulate_a_stuck_callbackfail;a_callback_gap_with_no_sleep_in_it_is_charged_in_fullpins that a poll delayed by scheduling alone still exits on that poll.Not run:
tests (linux),msrv,cargo-deny(CI). Not runtime-tested on hardware: no reproduction exists for this window, and the change does not alter behaviour outside a gap that contains a kernel sleep or wake.