Conversation
…Research#32460) A configured ``pre_tool_call`` hook runs synchronously on the hot path between an LLM response and tool execution. When the hook stalls for the full ``DEFAULT_TIMEOUT_SECONDS = 60`` window it appears to the operator as a silent 50-65s wall-clock gap with no log line at all — only a single ``shell hook timed out`` WARNING fires *after* the timer expires. This is exactly the symptom reported in NousResearch#32460. Spawn the subprocess alongside a daemon watchdog thread that emits a WARNING once the hook crosses ``_SLOW_HOOK_THRESHOLD_SECONDS`` (5s) and repeats every ``_SLOW_HOOK_REPEAT_SECONDS`` (10s) until the hook returns. The warning names the event and command so the operator can identify the offending script without waiting for the full timeout. Cleanup is wired through ``finally`` so the watchdog stops on every exit path — success, timeout, or spawn error.
…search#32460) The agent calls ``get_pre_tool_call_block_message`` for every tool invocation before the tool starts measuring its own duration. A slow plugin or shell hook on that path produces a silent wall-clock gap between an LLM response and the resulting tool execution — the ``tool ... completed (Xs)`` line reports a tiny duration while the real stall happened upstream. Add ``pre_tool_call_block_message_with_latency`` to wrap the call in a ``time.monotonic`` window and emit a single WARNING when the dispatch exceeds ``_PRE_TOOL_DISPATCH_SLOW_THRESHOLD_SECONDS`` (2s). The warning names the tool so the operator can correlate the stall with a specific invocation, and the helper preserves the underlying return value (including block directives) and re-raises exceptions verbatim so it stays purely observational. Threshold lives next to the helper as a module-level constant with a behavioural-pin test so it cannot drift back toward the 60s window that produced the original symptom.
…Research#32460) Sequential + concurrent tool executors, ``invoke_tool`` in the runtime helpers, and the non-skip path in ``model_tools.handle_function_call`` all called ``get_pre_tool_call_block_message`` directly. Swap each site to the latency-aware wrapper so every code path that fires a ``pre_tool_call`` hook contributes to the slow-dispatch WARNING. No behaviour change for fast hooks; slow ones now emit a single WARNING that names the offending tool instead of producing a silent multi-second wall-clock gap.
alt-glitch
added
type/bug
teknium1
reviewed
Jul 13, 2026
teknium1
left a comment
teknium1
left a comment
Collaborator
There was a problem hiding this comment.
Thanks for targeting an otherwise silent hook-stall path. Current main still blocks synchronously in agent/shell_hooks.py:462-474, but this branch predates the current pre-tool approval contract and needs a deliberate salvage.
Problems
agent/tool_dispatch_helpers.py:78wraps deprecatedget_pre_tool_call_block_message(). Current main's dispatch chokepoint isresolve_pre_tool_block()(hermes_cli/plugins.py:2226-2274), which escalatesapprovedirectives and fails closed. The wrapper must preserve that behavior.agent/shell_hooks.py:396says a slow hook stalls every tool dispatch, although_spawn()is used for all hook events;tests/agent/test_shell_hooks.py:402-417exercisespre_llm_call.- #32460 reports terminal-session reuse and only hypothesizes synchronization/readiness polling. It does not establish configured shell hooks as the cause.
Suggested changes
- Time
resolve_pre_tool_block()at the four current dispatch sites and forward the full context metadata. - Test approval denial/error through the instrumented path, and make watchdog messaging event-accurate.
Automated hermes-sweeper review.
|
|
||
| t0 = time.monotonic() | ||
| try: | ||
| return get_pre_tool_call_block_message( |
Collaborator
There was a problem hiding this comment.
Current main makes get_pre_tool_call_block_message() a deprecated block-only shim (hermes_cli/plugins.py:2201-2223); live dispatch uses resolve_pre_tool_block() to enforce approve directives fail-closed. Salvage this wrapper around resolve_pre_tool_block() and forward the full dispatch metadata, otherwise approval directives can be treated as allow.
| logger.warning( | ||
| "shell hook still running after %.1fs " | ||
| "(event=%s command=%s timeout=%ss); " | ||
| "this stalls every tool call dispatch until the hook returns", |
Collaborator
There was a problem hiding this comment.
_spawn() is shared by every shell-hook event, including pre_llm_call, so this wording is inaccurate outside pre_tool_call. Either limit this watchdog to pre-tool hooks or describe the specific event that is currently blocked.
teknium1
added
sweeper:risk-compatibility
Closed
14 tasks
This branch has not been deployed
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
3 participants
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 does this PR do?
Makes the silent 50-65s wall-clock gap reported in #32460 visible in
agent.loginstead of looking like the agent froze.The bug surfaces as a terminal-tool hang on every subsequent call after the first in a CLI/TUI session, while Feishu / gateway sessions run fast. Tool durations in the log show ≤0.5s for trivial commands like
ping/echo, but the wall-clock gap between API call #N completed and tool terminal completed clusters tightly around 50-65s — a textbook fixed-timeout pattern.Root cause:
agent/shell_hooks.pyruns every configuredpre_tool_callhook synchronously on the path between the LLM response and tool execution withDEFAULT_TIMEOUT_SECONDS = 60. When a hook stalls for the full window,subprocess.runwaits silently and the bridge only logs a single shell hook timed out WARNING after the timer expires. The matching tool execution then completes in milliseconds, so the user-visibletool ... completed (Xs)line under-reports the stall and there is nothing in the log that names the offending hook. CLI registers shell hooks by default; the gateway side does not unless they are allow-listed — which explains the CLI-only / Feishu-fast split.Three small additions wired together turn the stall from silent into actionable:
agent/shell_hooks.py— spawn each hook subprocess alongside a daemon watchdog thread. Once the hook has been running for 5 seconds the watchdog emits a WARNING naming the event and command, repeated every 10s until the hook returns. The threshold is well underDEFAULT_TIMEOUT_SECONDS, so a hung hook surfaces immediately instead of after the full 60s window. The watchdog stop signal is wired throughfinallyso success, timeout, and spawn-error paths all clean it up.agent/tool_dispatch_helpers.py— newpre_tool_call_block_message_with_latencywrapsget_pre_tool_call_block_messagein atime.monotonicwindow and logs a WARNING when dispatch exceeds 2s. The warning names the tool so the operator can correlate the stall with a specific invocation regardless of what's blocking (hook, plugin, MCP probe, etc.). The wrapper is purely observational — return value passes through verbatim and exceptions re-raise.agent/tool_executor.py,invoke_toolinagent/agent_runtime_helpers.py, and the non-skip path inmodel_tools.handle_function_callall swap to the new wrapper. Everypre_tool_callinvocation now contributes to the slow-dispatch warning.Related Issue
Fixes #32460
Type of Change
Changes Made
agent/shell_hooks.py— add_SLOW_HOOK_THRESHOLD_SECONDS=5/_SLOW_HOOK_REPEAT_SECONDS=10, new_watch_slow_hookdaemon, wire watchdog aroundsubprocess.runin_spawnwithtry/finallycleanup so the success /TimeoutExpired/ spawn-error paths all stop it.agent/tool_dispatch_helpers.py— newpre_tool_call_block_message_with_latencywrapper +_PRE_TOOL_DISPATCH_SLOW_THRESHOLD_SECONDS=2.agent/tool_executor.py— sequential + concurrent paths route through the wrapper.agent/agent_runtime_helpers.py::invoke_tool— routes through the wrapper.model_tools.py::handle_function_call— non-skip path routes through the wrapper.tests/agent/test_shell_hooks_slow_watchdog.py— 5 new tests pinning fast-hook silence, slow-hook warning content, watchdog stop on success, watchdog stop onTimeoutExpired, and spawn-failure silence.tests/agent/test_pre_tool_dispatch_latency.py— 5 new tests pinning fast-dispatch silence, slow-dispatch warning with tool name + elapsed time, block-message pass-through, exception propagation while still logging, and a production-threshold behavioural pin.Backwards compatible: no public API removed, no schema migration, no new config keys. Hooks that already returned promptly keep behaving identically; the only user-visible change is a WARNING that names the offending hook when it stalls.
How to Test
Behaviour after the fix — agent.log on a hook that stalls 60s:
The 50-65s wall-clock gap is now named, timestamped, attributed to a specific tool, and traceable to a specific hook command — operator can act on it instead of guessing.
Checklist
feat(shell_hooks):,feat(agent):,refactor(dispatch):)xxxigm)test_anthropic_adapter.py::TestRunOauthSetupToken,test_shell_hooks.py::TestCallbackSubprocess::test_timeout_returns_none,test_vision_routing_31179.pyunder contention) confirmed unchanged onupstream/main