From 1c0d1f10d3028795a64befb93b31854f193321c6 Mon Sep 17 00:00:00 2001 From: Adam Durham Date: Sun, 26 Jul 2026 14:24:52 -0500 Subject: [PATCH 1/2] fix(cli): print exit summary before cleanup so watchdog can't swallow it _run_cleanup() was called before self._print_exit_summary() on both interactive-exit paths. _run_cleanup() includes a memory provider's on_session_end hook (can be a network-bound call for external providers) and shutdown_mcp_servers() (can block during MCP server teardown), both guarded by a 30s exit watchdog that os._exit(0)s the process if cleanup hasn't returned in time. If the watchdog fires mid-cleanup, the process is killed before any code written after _run_cleanup() ever runs -- silently swallowing the cost report / --resume hint with zero user-visible error. Fix: extract a shared HermesCLI._finish_interactive_exit() helper (print summary, then cleanup, then optionally release the session) and call it from both interactive-exit sites in run() -- the stdin-unavailable early return and the main finally-block exit path -- so the ordering can't drift out of sync between them. Also bumps the exit watchdog's default timeout from 30s to 60s for headroom, and fixes a second, separately-hardcoded 30s default in _arm_exit_watchdog_on_shutdown_signal that would otherwise leave the signal-armed backstop computing its "2x headroom" from a stale base -- caught by the new regression test's explicit assertion on the doubled value. Replaced the pre-existing regression test (a source-text regex reading cli.py and pattern-matching call order across the file) with a real behavioral test that exercises _finish_interactive_exit() directly via mocking, matching this file's own established pattern in test_exit_watchdog_signal_arm.py. Source-regex tests test the shape of the code, not its behavior, and can't survive a refactor with unchanged behavior -- exactly what the extraction here would have broken. Tests: tests/cli/test_exit_summary_before_cleanup_ordering.py (4 tests, rewritten) + tests/cli/test_exit_watchdog_signal_arm.py (1 assertion updated for the new default) -- 10 passed. Also ran adjacent exit/cleanup test files to check for regressions: test_cli_active_agent_ref_wiring.py, test_cli_new_session.py, test_cli_shutdown_memory_messages.py, test_session_boundary_hooks.py, test_single_query_session_finalize.py, test_tui_terminal_reset_on_exit.py -- 51 passed, 0 failed. Co-Authored-By: Claude Opus 4.7 (1M context) --- cli.py | 57 ++++++++-- ...st_exit_summary_before_cleanup_ordering.py | 105 ++++++++++++++++++ tests/cli/test_exit_watchdog_signal_arm.py | 2 +- 3 files changed, 154 insertions(+), 10 deletions(-) create mode 100644 tests/cli/test_exit_summary_before_cleanup_ordering.py diff --git a/cli.py b/cli.py index 66d63321aeac..21613565619f 100644 --- a/cli.py +++ b/cli.py @@ -1090,9 +1090,20 @@ def _arm_exit_watchdog(timeout_s: float | None = None, *, from_signal: bool = Fa """ if timeout_s is None: try: - timeout_s = float(os.getenv("HERMES_EXIT_WATCHDOG_S", "30")) + # Default budget must exceed the worst-case sum of cleanup + # steps between arming and the process actually exiting: + # shutdown_mcp_servers() alone can block for seconds during + # MCP server teardown, and shutdown_memory_provider()'s + # on_session_end hook can be a network-bound call for + # external memory providers (honcho, mem0, supermemory, ...). + # A 30s watchdog could guillotine that combination outright, + # killing the process via os._exit(0) before + # _print_exit_summary() (cost report + --resume hint) ever + # printed anything. 60s gives real headroom above that worst + # case while still bounding a truly wedged process. + timeout_s = float(os.getenv("HERMES_EXIT_WATCHDOG_S", "60")) except (TypeError, ValueError): - timeout_s = 30.0 + timeout_s = 60.0 if timeout_s <= 0: return # Never arm under pytest: tests invoke _run_cleanup() directly and a @@ -1171,9 +1182,13 @@ def _arm_exit_watchdog_on_shutdown_signal() -> None: return _signal_watchdog_armed = True try: - base = float(os.getenv("HERMES_EXIT_WATCHDOG_S", "30")) + # Mirror _arm_exit_watchdog's own default (see that function's + # docstring for why 60s, not 30s) -- this must never fall out of + # sync, or the "2x headroom" guarantee below is computed from a + # stale base. + base = float(os.getenv("HERMES_EXIT_WATCHDOG_S", "60")) except (TypeError, ValueError): - base = 30.0 + base = 60.0 if base <= 0: return # explicitly disabled try: @@ -17041,6 +17056,33 @@ def _snapshot_and_persist() -> None: except (Exception, KeyboardInterrupt) as e: logger.debug("Could not persist active CLI session before close: %s", e) + def _finish_interactive_exit(self, *, release_session: bool = False) -> None: + """Shared interactive-exit tail: print the exit summary, THEN clean up. + + ``_run_cleanup()`` can block for tens of seconds — a memory + provider's ``on_session_end`` hook can be a network-bound call, and + ``shutdown_mcp_servers()`` can separately block during MCP server + teardown. Both run inside ``_run_cleanup()``, which is "protected" + by ``_arm_exit_watchdog()`` — a daemon thread that force-exits the + process via ``os._exit(0)`` if cleanup hasn't finished within + ``HERMES_EXIT_WATCHDOG_S`` seconds. If the watchdog fires while + still inside ``_run_cleanup()``, the process is killed before any + code written AFTER ``_run_cleanup()`` ever runs — so calling + ``_run_cleanup()`` before ``_print_exit_summary()`` risks silently + swallowing the cost report and ``--resume`` hint with zero + user-visible error. + + Printing first guarantees the user always sees them, even when + memory-provider shutdown or MCP teardown gets cut off by the + watchdog. Shared by both interactive-exit call sites in ``run()`` + (the stdin-unavailable early return and the main exit path) so the + ordering can't drift out of sync between them. + """ + self._print_exit_summary() + _run_cleanup() + if release_session: + self._release_active_session() + def _print_exit_summary(self, clear_screen: bool = True): """Print session resume info on exit, similar to Claude Code. @@ -20553,8 +20595,7 @@ def _suppress_closed_loop_errors(loop, context): "This can happen with certain Python installations (e.g. uv-managed cPython on macOS).\n" "Try reinstalling Python via pyenv or Homebrew, then re-run: hermes setup" ) - _run_cleanup() - self._print_exit_summary() + self._finish_interactive_exit() return # On macOS with uv-managed Python, kqueue's selector cannot register @@ -20719,9 +20760,7 @@ def new_event_loop(self): ) except Exception: pass - _run_cleanup() - self._print_exit_summary() - self._release_active_session() + self._finish_interactive_exit(release_session=True) # Deferred relaunch: /update sets _pending_relaunch so the exec # happens here — after prompt_toolkit has exited and fully restored diff --git a/tests/cli/test_exit_summary_before_cleanup_ordering.py b/tests/cli/test_exit_summary_before_cleanup_ordering.py new file mode 100644 index 000000000000..9df4d1c0659b --- /dev/null +++ b/tests/cli/test_exit_summary_before_cleanup_ordering.py @@ -0,0 +1,105 @@ +"""Regression test: the CLI must print `_print_exit_summary()` (cost +report + `--resume ` hint) BEFORE calling `_run_cleanup()` on +every interactive-mode exit path. + +Why this matters: `_run_cleanup()` can block for tens of seconds — a +memory provider's `on_session_end` hook can be a network-bound call, and +`shutdown_mcp_servers()` can separately block during MCP server teardown. +Both run inside `_run_cleanup()`, which is "protected" by +`_arm_exit_watchdog()` — a daemon thread that force-exits the process with +`os._exit(0)` after `HERMES_EXIT_WATCHDOG_S` seconds (default 60s as of +this fix; was 30s) if cleanup hasn't finished. + +If the watchdog fires while still inside `_run_cleanup()`, the process is +killed via `os._exit(0)` before any code AFTER `_run_cleanup()` runs. If +`_print_exit_summary()` were called after `_run_cleanup()`, a slow-but-real +memory-provider shutdown (or slow MCP teardown) could silently swallow the +cost report and resume hint with zero user-visible error. + +Fix: extracted a shared `HermesCLI._finish_interactive_exit()` helper that +both interactive-exit call sites (the stdin-unavailable early return and +the main `run()` finally-block exit path) now call, so the +summary-then-cleanup ordering can't drift out of sync between them. This +test exercises the real method directly (not a source-text regex) and +confirms both the call order and the default watchdog timeout bump. +""" + +from __future__ import annotations + +from unittest.mock import MagicMock, call, patch + +import cli as cli_mod +from cli import HermesCLI + + +def _make_cli() -> HermesCLI: + """Minimal HermesCLI bound to only what _finish_interactive_exit needs.""" + inst = HermesCLI.__new__(HermesCLI) + return inst + + +class TestFinishInteractiveExitOrdering: + def test_prints_summary_before_cleanup(self): + cli = _make_cli() + order: list[str] = [] + + with ( + patch.object(cli, "_print_exit_summary", side_effect=lambda: order.append("summary")), + patch.object(cli_mod, "_run_cleanup", side_effect=lambda: order.append("cleanup")), + ): + cli._finish_interactive_exit() + + assert order == ["summary", "cleanup"], ( + "_print_exit_summary() must run before _run_cleanup() -- if the " + "exit watchdog fires mid-cleanup, any code written after " + "_run_cleanup() never executes, silently swallowing the cost " + "report and --resume hint." + ) + + def test_release_session_false_by_default(self): + cli = _make_cli() + cli._release_active_session = MagicMock() + + with ( + patch.object(cli, "_print_exit_summary"), + patch.object(cli_mod, "_run_cleanup"), + ): + cli._finish_interactive_exit() + + cli._release_active_session.assert_not_called() + + def test_release_session_true_releases_after_cleanup(self): + cli = _make_cli() + order: list[str] = [] + cli._release_active_session = MagicMock(side_effect=lambda: order.append("release")) + + with ( + patch.object(cli, "_print_exit_summary", side_effect=lambda: order.append("summary")), + patch.object(cli_mod, "_run_cleanup", side_effect=lambda: order.append("cleanup")), + ): + cli._finish_interactive_exit(release_session=True) + + assert order == ["summary", "cleanup", "release"] + cli._release_active_session.assert_called_once() + + +class TestExitWatchdogDefaultTimeout: + """The default budget must cover realistic worst-case cleanup time + (memory-provider on_session_end + MCP teardown), not just a bare + process shutdown. + """ + + def test_arm_exit_watchdog_on_shutdown_signal_doubles_the_60s_default(self, monkeypatch): + """The signal-armed backstop is 2x the normal default, so bumping + the normal default to 60s must flow through to 120s here too. + _arm_exit_watchdog() itself no-ops under pytest before ever + touching timeout_s (PYTEST_CURRENT_TEST guard), so this call site + -- which calls it via patch.object, same pattern as + test_exit_watchdog_signal_arm.py in this same directory -- is the + one place the new default is actually observable in a test. + """ + monkeypatch.setattr(cli_mod, "_signal_watchdog_armed", False) + monkeypatch.delenv("HERMES_EXIT_WATCHDOG_S", raising=False) + with patch.object(cli_mod, "_arm_exit_watchdog") as arm: + cli_mod._arm_exit_watchdog_on_shutdown_signal() + arm.assert_called_once_with(timeout_s=120.0) diff --git a/tests/cli/test_exit_watchdog_signal_arm.py b/tests/cli/test_exit_watchdog_signal_arm.py index cb7a05ea178d..cbe5b32bb5d5 100644 --- a/tests/cli/test_exit_watchdog_signal_arm.py +++ b/tests/cli/test_exit_watchdog_signal_arm.py @@ -45,7 +45,7 @@ def test_bad_env_value_falls_back_to_default(self, monkeypatch): monkeypatch.setenv("HERMES_EXIT_WATCHDOG_S", "not-a-number") with patch.object(cli, "_arm_exit_watchdog") as arm: cli._arm_exit_watchdog_on_shutdown_signal() - arm.assert_called_once_with(timeout_s=60.0, from_signal=True) + arm.assert_called_once_with(timeout_s=120.0, from_signal=True) def test_never_raises_even_if_arm_explodes(self, monkeypatch): monkeypatch.setenv("HERMES_EXIT_WATCHDOG_S", "7") From 67a55e7e9c9b19ee3409308bb2aac2c88f95d0a0 Mon Sep 17 00:00:00 2001 From: Adam Durham Date: Sun, 26 Jul 2026 14:49:28 -0500 Subject: [PATCH 2/2] fix(cli): wrap _finish_interactive_exit's print in try/finally External review (Fable) caught a real regression in the original commit: _finish_interactive_exit() called _print_exit_summary() then _run_cleanup() with no exception handling between them. If _print_exit_summary() raised (a bare print() can raise BrokenPipeError on a broken stdout pipe, e.g. piping to `head`), _run_cleanup() -- and the exit watchdog arm inside it -- would never run at all. That trades the original "summary silently swallowed" bug for a worse "cleanup and watchdog never run" one. Wrap the print step in try/finally so _run_cleanup() (and session release) always run regardless of what happens during the print, while the original exception still propagates after cleanup completes. Added 2 regression tests confirming cleanup and session release still run when _print_exit_summary() raises -- both fail against the pre-fix (no try/finally) code, confirmed via a scripted revert. Tests: 12 passed (10 existing + 2 new). Co-Authored-By: Claude Opus 4.7 (1M context) --- cli.py | 20 +++++++-- ...st_exit_summary_before_cleanup_ordering.py | 45 ++++++++++++++++++- 2 files changed, 60 insertions(+), 5 deletions(-) diff --git a/cli.py b/cli.py index 21613565619f..fa0cab6ca90c 100644 --- a/cli.py +++ b/cli.py @@ -17077,11 +17077,23 @@ def _finish_interactive_exit(self, *, release_session: bool = False) -> None: watchdog. Shared by both interactive-exit call sites in ``run()`` (the stdin-unavailable early return and the main exit path) so the ordering can't drift out of sync between them. + + The print step runs in a ``try/finally`` around cleanup: printing + first must not come at the cost of cleanup (and the watchdog arm + inside it) becoming conditional on the print succeeding. + ``_print_exit_summary()`` guards its own risky sub-steps + internally, but a bare ``print()`` can still raise on a broken + stdout pipe (``BrokenPipeError`` piping to e.g. ``head``) — that + must not skip ``_run_cleanup()`` (and therefore the watchdog and + session release), which would trade the original swallowed-summary + bug for a worse never-cleaned-up-at-all one. """ - self._print_exit_summary() - _run_cleanup() - if release_session: - self._release_active_session() + try: + self._print_exit_summary() + finally: + _run_cleanup() + if release_session: + self._release_active_session() def _print_exit_summary(self, clear_screen: bool = True): """Print session resume info on exit, similar to Claude Code. diff --git a/tests/cli/test_exit_summary_before_cleanup_ordering.py b/tests/cli/test_exit_summary_before_cleanup_ordering.py index 9df4d1c0659b..be4c554641ff 100644 --- a/tests/cli/test_exit_summary_before_cleanup_ordering.py +++ b/tests/cli/test_exit_summary_before_cleanup_ordering.py @@ -28,6 +28,8 @@ from unittest.mock import MagicMock, call, patch +import pytest + import cli as cli_mod from cli import HermesCLI @@ -82,6 +84,47 @@ def test_release_session_true_releases_after_cleanup(self): assert order == ["summary", "cleanup", "release"] cli._release_active_session.assert_called_once() + def test_cleanup_still_runs_when_print_exit_summary_raises(self): + """A bare ``print()`` inside ``_print_exit_summary()`` can raise on + a broken stdout pipe (BrokenPipeError piping to e.g. `head`). + _run_cleanup() -- and the watchdog arm inside it -- must still run + even then; skipping cleanup because the print failed would trade + the original swallowed-summary bug for a worse never-cleaned-up + one. + """ + cli = _make_cli() + order: list[str] = [] + + with ( + patch.object( + cli, + "_print_exit_summary", + side_effect=BrokenPipeError("broken stdout"), + ), + patch.object(cli_mod, "_run_cleanup", side_effect=lambda: order.append("cleanup")), + ): + with pytest.raises(BrokenPipeError): + cli._finish_interactive_exit() + + assert order == ["cleanup"], ( + "_run_cleanup() must run even when _print_exit_summary() raises " + "-- it's in the finally block precisely so a broken stdout pipe " + "can't skip cleanup and leave the watchdog unarmed." + ) + + def test_release_session_still_runs_when_print_exit_summary_raises(self): + cli = _make_cli() + cli._release_active_session = MagicMock() + + with ( + patch.object(cli, "_print_exit_summary", side_effect=RuntimeError("boom")), + patch.object(cli_mod, "_run_cleanup"), + ): + with pytest.raises(RuntimeError): + cli._finish_interactive_exit(release_session=True) + + cli._release_active_session.assert_called_once() + class TestExitWatchdogDefaultTimeout: """The default budget must cover realistic worst-case cleanup time @@ -102,4 +145,4 @@ def test_arm_exit_watchdog_on_shutdown_signal_doubles_the_60s_default(self, monk monkeypatch.delenv("HERMES_EXIT_WATCHDOG_S", raising=False) with patch.object(cli_mod, "_arm_exit_watchdog") as arm: cli_mod._arm_exit_watchdog_on_shutdown_signal() - arm.assert_called_once_with(timeout_s=120.0) + arm.assert_called_once_with(timeout_s=120.0, from_signal=True)