diff --git a/cli.py b/cli.py index 66d63321aeac6..fa0cab6ca90c6 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,45 @@ 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. + + 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. + """ + 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. @@ -20553,8 +20607,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 +20772,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 0000000000000..be4c554641ff6 --- /dev/null +++ b/tests/cli/test_exit_summary_before_cleanup_ordering.py @@ -0,0 +1,148 @@ +"""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 pytest + +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() + + 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 + (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, from_signal=True) diff --git a/tests/cli/test_exit_watchdog_signal_arm.py b/tests/cli/test_exit_watchdog_signal_arm.py index cb7a05ea178d4..cbe5b32bb5d52 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")