Skip to content

fix(plugins): isolate policy hook dispatch - #820

Closed
Kyzcreig wants to merge 2 commits into
mainfrom
fix/pre-tool-hook-dispatch-starvation
Closed

Kyzcreig wants to merge 2 commits into
mainfrom
fix/pre-tool-hook-dispatch-starvation

Conversation

@Kyzcreig

Copy link
Copy Markdown
Collaborator

Summary

  • run fail-closed pre_tool_call callbacks on a dedicated 4-worker daemon executor instead of creating an unpooled thread per invocation
  • measure the callback timeout from callback start, not submission, so dispatch queue delay is not misclassified as a slow policy hook
  • apply the 60-second suppression window only after callback runtime exceeds its budget; a callback canceled before start does not poison subsequent tool calls
  • log queue_wait and run_time separately on both dispatch and callback-runtime timeouts

Root cause

The live incident report suspected asyncio's shared default executor. Current fork/main had already moved bounded hooks to per-callback daemon threads, so shared-pool saturation was not the direct current path. The remaining failure was equivalent: done.wait(timeout) began immediately after Thread.start(), charging thread dispatch / GIL scheduling delay to callback runtime. That false runtime timeout installed the same 60-second fail-closed suppression window.

Tests

RED before implementation:

  • delayed dispatch was treated as a successful immediate callback rather than a separately classified dispatch timeout, and there was no suppression-state contract
  • runtime timeout logs lacked queue/run split

GREEN after implementation:

  • scripts/run_tests.sh tests/agent/test_shell_hooks.py tests/hermes_cli/test_plugins.py -q — 128 passed under host load 49
  • /opt/homebrew/bin/ruff check hermes_cli/plugins.py tests/hermes_cli/test_plugins.py — clean
  • git diff --check refs/remotes/fork/main...HEAD — clean

The saturated-default-executor regression holds one asyncio default worker busy while a 30 ms policy hook runs on a hermes-policy-hook worker and completes within budget.

Run pre_tool_call callbacks on a dedicated daemon executor, measure timeout from callback start, and reserve suppression for callback runtime breaches. Log queue wait and runtime separately.\n\nVerified: scripts/run_tests.sh tests/agent/test_shell_hooks.py tests/hermes_cli/test_plugins.py -q (128 passed).
@Kyzcreig

Copy link
Copy Markdown
Collaborator Author

🔁 re-enqueue for FleetReview (Apollo): head's terminal record was stamped ERROR by a router restart (release cut 20260921T104203Z / sibling cuts 10:25-10:32Z), not by a review verdict; close/reopen re-submits the unchanged head. No code change.

@Kyzcreig Kyzcreig closed this Sep 21, 2026
@Kyzcreig Kyzcreig reopened this Sep 21, 2026
…he 10:42Z router restart, not a verdict; kanban review APPROVED at 69e71df, tree identical)
@Kyzcreig
Kyzcreig added this pull request to the merge queue Sep 21, 2026
@Kyzcreig
Kyzcreig removed this pull request from the merge queue due to a manual request Sep 21, 2026
@Kyzcreig
Kyzcreig added this pull request to the merge queue Sep 21, 2026
@Kyzcreig
Kyzcreig removed this pull request from the merge queue due to a manual request Sep 21, 2026
@Kyzcreig
Kyzcreig added this pull request to the merge queue Sep 21, 2026
@github-merge-queue
github-merge-queue Bot removed this pull request from the merge queue due to failed status checks Sep 21, 2026
@Kyzcreig
Kyzcreig added this pull request to the merge queue Sep 21, 2026
@github-merge-queue
github-merge-queue Bot removed this pull request from the merge queue due to a conflict with the base branch Sep 21, 2026
@Kyzcreig

Copy link
Copy Markdown
Collaborator Author

Adjudication: SUPERSEDED-BY #819 — and this PR would be a REGRESSION if landed

Closing per the card's adjudication instruction (t_4dbe2f23). This is not a taste
call; both mechanisms were measured against main@post-#819 (846ba492a1) in a
clean worktree, via scripts/run_tests.sh (bare python probe.py from a worktree
executes LIVE-tree code — the trap #819 itself recorded).

Mechanism (b) — "start the timeout clock at callback entry"

Already provided by #819, and the residual is immaterial. main takes
started_at immediately before thread.start() and spawns a fresh daemon thread
per invocation
— there is no queue, so the only non-callback time charged to the
budget is thread-spawn latency. Measured under 300 live filler threads at host
load ~19-24, 20 invocations:

PRESTART_OVERHEAD_MS p50=0.184 p95=0.202 max=0.212 budget_ms=30000

0.212 ms against a 30 s budget = 0.0007% of budget. There is no starvation to fix.

Mechanism (a) — "dedicated bounded daemon pool for policy hooks"

Not needed on main, and it actively INTRODUCES the starvation this card
describes.
main has no shared pool for policy hooks at all; this PR replaces
per-invocation threads with a bounded 4-worker DaemonThreadPoolExecutor. A
hung policy callback is abandoned, never joined — so it permanently consumes a
worker. Four hung callbacks and the pool is dead for every other session.

Same three probes, both trees, scripts/run_tests.sh, 3 consecutive runs each:

probe main@846ba492a1 this PR @69e71df
fast 30 ms hook w/ saturated asyncio default executor PASS 3/3 PASS 3/3
8 hung policy callbacks must not starve an unrelated session's fast hook PASS 3/3 FAIL 3/3
no suppression armed without a real runtime overrun PASS 3/3 PASS 3/3

Deterministic, not flake (EXIT=0,0,0 vs EXIT=1,1,1; exactly 10
dispatch timed out before start lines on each PR run, 0 on each main run). The
PR's own new log line is the receipt:

Hook 'pre_tool_call' callback fast_hook dispatch timed out before start:
  queue_wait=0.507s run_time=0s budget=0.5s — skipping

An unrelated session's 30 ms hook was refused after never executing — the exact
symptom the card was filed about, manufactured by the fix.

Mechanism (3) — queue-wait/run-time split logging

Meaningful only if a queue exists. main has none, so the split degenerates to
queue_wait≈0.0002s on every line. No residual.

Disposition

No red case on main@post-#819 for any of the three mechanisms → no residual.
Closing as superseded. #819's tests stay green; none of this PR's running-callback
bookkeeping is carried forward.

Note for the record: the card's premise (shared default-executor starvation) was
refuted by #819's measurement — 1,917 pre_tool_call skip lines and ZERO timeout
lines in live logs; the real cause was _hook_running_callbacks keyed
process-wide by (hook_name, id(callback)), so session B took the fail-closed
branch on session A's healthy in-flight callback.

@Kyzcreig

Copy link
Copy Markdown
Collaborator Author

Superseded by #819 — see the adjudication comment above. No residual mechanism survives a red-case test on main@post-#819, and the dedicated bounded pool would regress cross-session isolation.

@Kyzcreig Kyzcreig closed this Sep 21, 2026
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