From 26c39cbb277f421490ea883124866795e7efb5d3 Mon Sep 17 00:00:00 2001 From: ethernet Date: Fri, 11 Sep 2026 16:45:38 -0400 Subject: [PATCH] fix(logging): fall back from concurrent-log-handler when portalocker is dead MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A Windows bundle whose venv never processed pywin32.pth (see the launcher fix) fails 'import pywintypes' with ModuleNotFoundError; portalocker 3.x has no msvcrt fallback, so CLH retries lock() 20x and raises 'Cannot acquire lock after 20 attempts' — which handleError suppressed entirely. Result: zero file logging, silently, on every affected install. * probe portalocker once at import (scratch lock/unlock) and fall back to stdlib RotatingFileHandler when it fails; the fallback disables rollover (multi-process appends make Windows renames fail with WinError 32, the #44873 trap CLH exists to avoid) and setup_logging() warns once * the suppressed CLH lock timeout now warns once through the logging system instead of vanishing --- hermes_logging.py | 113 +++++++++++++++++++++++++++++++++-- tests/test_hermes_logging.py | 80 ++++++++++++++++++++++++- 2 files changed, 186 insertions(+), 7 deletions(-) diff --git a/hermes_logging.py b/hermes_logging.py index 68cfbf62ad..5fcad8b700 100644 --- a/hermes_logging.py +++ b/hermes_logging.py @@ -28,9 +28,21 @@ from typing import Optional, Sequence # relies on stdlib's exact ``_open()``/``doRollover()`` lifecycle for the # 0660 chmod and eager file creation; CLH opens lazily and rotates differently. if sys.platform == "win32": - from concurrent_log_handler import ( # noqa: E402 - ConcurrentRotatingFileHandler as RotatingFileHandler, - ) + if _portalocker_probe(): + from concurrent_log_handler import ( # noqa: E402 + ConcurrentRotatingFileHandler as RotatingFileHandler, + ) + else: + # portalocker cannot take a lock on this box (typical cause: a sealed + # bundle whose venv never processed pywin32.pth, so `import pywintypes` + # fails and portalocker's Win32Locker has no msvcrt fallback). CLH + # would silently drop every record through the suppressed lock-timeout + # below; fall back to stdlib rotation instead. Rollover is disabled in + # the fallback: multi-process appends make Windows renames fail with + # WinError 32, the exact #44873 trap CLH exists to avoid. + from logging.handlers import RotatingFileHandler # noqa: E402 + + _WINDOWS_CLH_FALLBACK = True else: from logging.handlers import RotatingFileHandler # noqa: E402 @@ -40,6 +52,50 @@ from hermes_constants import get_config_path, get_hermes_home, mkdir_under_herme # setup_logging() is idempotent: a second call is a no-op unless ``force=True``. _logging_initialized = False +# True only when CLH was rejected at import because portalocker cannot take a +# lock on this Windows box; file handlers then use stdlib rotation (rollover +# disabled — see the module-header comment) and setup_logging() warns once. +_WINDOWS_CLH_FALLBACK = False +_WINDOWS_CLH_FALLBACK_REASON = "" +_fallback_warned = False + + +def _portalocker_probe() -> bool: + """Return True when portalocker can actually take a lock on this box. + + concurrent-log-handler locks every write through portalocker, which on + Windows instantiates Win32Locker and imports pywintypes. Bundled payloads + have shipped with that import broken (the venv's .pth files were never + processed), and portalocker 3.x gives no msvcrt fallback — every emit then + dies with the ImportError, CLH retries 20x, and the suppressed "Cannot + acquire lock" RuntimeError below hides it completely. Probe a scratch file + once at import so we can fall back to stdlib rotation instead of silently + dropping every record. No-op (True) off Windows, where stdlib is in use. + """ + global _WINDOWS_CLH_FALLBACK_REASON + if sys.platform != "win32": + return True + try: + import portalocker + import tempfile + except Exception as exc: + _WINDOWS_CLH_FALLBACK_REASON = repr(exc) + return False + fd, path = tempfile.mkstemp(prefix="hermes-portalocker-") + try: + with os.fdopen(fd, "r+") as stream: + portalocker.lock(stream, portalocker.LOCK_EX) + portalocker.unlock(stream) + except Exception as exc: + _WINDOWS_CLH_FALLBACK_REASON = repr(exc) + return False + finally: + try: + os.unlink(path) + except OSError: + pass + return True + # Thread-local per-conversation session context. _session_context = threading.local() @@ -81,6 +137,33 @@ def _is_windows_concurrent_log_lock_timeout(exc: BaseException | None) -> bool: ) +_windows_lock_timeout_warned = False +_windows_lock_timeout_warn_lock = threading.Lock() + + +def _warn_windows_lock_timeout_once() -> None: + """Report a suppressed CLH lock timeout exactly once per process. + + Every emit after the first failure raises the same RuntimeError, so the + warning must be one-shot or it would spam errors.log as badly as the + stderr noise it replaces. CLH does not chain the underlying cause (the + RuntimeError is raised outside the except, from the retry loop's else + clause), so the message cannot include it; a constantly repeating timeout + means file logging is degraded — the startup portalocker probe in this + module should have caught a dead portalocker and fallen back already. + """ + global _windows_lock_timeout_warned + with _windows_lock_timeout_warn_lock: + if _windows_lock_timeout_warned: + return + _windows_lock_timeout_warned = True + logging.getLogger("hermes_logging").warning( + "concurrent-log-handler timed out acquiring the cross-process log " + "lock; this and later records were dropped (the Desktop slash-worker " + "surface stays clean, but file logging is degraded)." + ) + + # Third-party loggers that are noisy at DEBUG/INFO level. _NOISY_LOGGERS = ( "openai", "openai._base_client", "httpx", "httpcore", "asyncio", "hpack", "hpack.hpack", @@ -177,6 +260,7 @@ def setup_logging( ``gateway.log`` and ``mode="gui"`` adds ``gui.log``. """ global _logging_initialized + global _fallback_warned home = hermes_home or get_hermes_home() log_dir = mkdir_under_hermes_home(home / "logs") cfg_level, cfg_max_size, cfg_backup = _read_logging_config() @@ -206,6 +290,16 @@ def setup_logging( log_filter=_ComponentFilter(COMPONENT_PREFIXES[component]) if component else None, ) + if _WINDOWS_CLH_FALLBACK and not _fallback_warned: + # One-shot, and the file handlers above are already live, so this lands + # in errors.log/agent.log — the fallback must never be invisible again. + _fallback_warned = True + logging.getLogger("hermes_logging").warning( + "concurrent-log-handler unavailable on this Windows install (%s); " + "file logging fell back to stdlib rotation without rollover.", + _WINDOWS_CLH_FALLBACK_REASON or "portalocker probe failed", + ) + if _logging_initialized and not force: return log_dir @@ -322,10 +416,13 @@ class _ManagedRotatingFileHandler(RotatingFileHandler): CLH's ``emit()`` routes that RuntimeError here, so this is the single point to silence it before stdlib prints to stderr (which the Desktop slash-worker - captures into chat output). + captures into chat output). Silencing is not silent: warn once through the + logging system so a wedged lock is visible in the logs instead of a black hole. """ - if not _is_windows_concurrent_log_lock_timeout(sys.exc_info()[1]): - super().handleError(record) + if _is_windows_concurrent_log_lock_timeout(sys.exc_info()[1]): + _warn_windows_lock_timeout_once() + return + super().handleError(record) def _open(self): stream = super()._open() @@ -345,6 +442,10 @@ def _new_file_handler( ) -> "_ManagedRotatingFileHandler": """Create the ``logs/`` directory and a configured ``_ManagedRotatingFileHandler``.""" mkdir_under_hermes_home(path.parent) + if _WINDOWS_CLH_FALLBACK: + # stdlib fallback: no rollover, or the file pins at the size threshold + # and every emit re-triggers the WinError 32 rename failure (#44873). + max_bytes, backup_count = 0, 0 handler = _ManagedRotatingFileHandler( str(path), maxBytes=max_bytes, backupCount=backup_count, encoding="utf-8" ) diff --git a/tests/test_hermes_logging.py b/tests/test_hermes_logging.py index 9c56d08859..3f0c469634 100644 --- a/tests/test_hermes_logging.py +++ b/tests/test_hermes_logging.py @@ -441,7 +441,8 @@ class TestWindowsConcurrentLogLockTimeout: RuntimeError raised in ``_do_lock()`` is caught *inside* CLH and routed to ``handleError`` with the exception live in ``sys.exc_info()``. We invoke ``handleError`` the same way CLH would and assert no traceback - reaches stderr (the slash-worker surface). + reaches stderr (the slash-worker surface) — but the suppression must + still surface once through the logging system, not stay a black hole. Windows-only: the suppression is keyed on the real host, and only on Windows is the base handler CLH at all — the fake platform gave us the @@ -450,19 +451,96 @@ class TestWindowsConcurrentLogLockTimeout: record = logger.makeRecord( logger.name, logging.INFO, __file__, 0, "force rollover", (), None, ) + captured_warnings: list[logging.LogRecord] = [] + + class _Capture(logging.Handler): + def emit(self, record: logging.LogRecord) -> None: + captured_warnings.append(record) + + listener = _Capture() + logging.getLogger("hermes_logging").addHandler(listener) + monkeypatch = pytest.MonkeyPatch() + monkeypatch.setattr(hermes_logging, "_windows_lock_timeout_warned", False) try: try: raise RuntimeError("Cannot acquire lock after 20 attempts") except RuntimeError: handler.handleError(record) + try: + raise RuntimeError("Cannot acquire lock after 20 attempts") + except RuntimeError: + handler.handleError(record) captured = capsys.readouterr() assert "Cannot acquire lock after 20 attempts" not in captured.err assert "--- Logging error ---" not in captured.err + # One-shot warning: the second suppressed emit must not re-warn. + assert len(captured_warnings) == 1 + assert "concurrent-log-handler" in captured_warnings[0].getMessage() finally: + monkeypatch.undo() + logging.getLogger("hermes_logging").removeHandler(listener) logger.removeHandler(handler) handler.close() + def test_lock_timeout_warning_is_one_shot(self, caplog): + """The suppressed-timeout warning is exactly-once per process. + + Every emit after the first CLH lock failure raises the same + RuntimeError, so warn-once is what keeps errors.log from being spammed + as badly as the stderr noise the suppression replaces.""" + monkeypatch = pytest.MonkeyPatch() + monkeypatch.setattr(hermes_logging, "_windows_lock_timeout_warned", False) + try: + with caplog.at_level(logging.WARNING, logger="hermes_logging"): + hermes_logging._warn_windows_lock_timeout_once() + hermes_logging._warn_windows_lock_timeout_once() + finally: + monkeypatch.undo() + warnings = [r for r in caplog.records if r.levelno >= logging.WARNING] + assert len(warnings) == 1 + assert "concurrent-log-handler" in warnings[0].getMessage() + + def test_portalocker_probe_false_when_lock_raises(self, monkeypatch): + """The import-time probe catches a dead portalocker (the sealed-bundle + pywintypes failure) instead of letting CLH drop records silently.""" + + class FakePortalocker: + LOCK_EX = 2 + + @staticmethod + def lock(f, flags): + raise ImportError("pywintypes is required for Win32Locker but not found") + + @staticmethod + def unlock(f): + return None + + monkeypatch.setitem(sys.modules, "portalocker", FakePortalocker) + monkeypatch.setattr(sys, "platform", "win32") + assert hermes_logging._portalocker_probe() is False + assert "pywintypes" in hermes_logging._WINDOWS_CLH_FALLBACK_REASON + + def test_portalocker_probe_true_off_windows(self): + # Off Windows the probe is a no-op: stdlib rotation is already in use. + assert hermes_logging._portalocker_probe() is True + + def test_fallback_handler_disables_rollover(self, tmp_path, monkeypatch): + """The stdlib fallback must not roll over: multi-process append + handles make Windows renames fail with WinError 32, pinning the file + and spamming stderr on every emit (#44873).""" + monkeypatch.setattr(hermes_logging, "_WINDOWS_CLH_FALLBACK", True) + handler = hermes_logging._new_file_handler( + tmp_path / "agent.log", level=logging.INFO, + max_bytes=5 * 1024 * 1024, backup_count=3, + formatter=logging.Formatter("%(message)s"), + ) + try: + assert handler.maxBytes == 0 + assert handler.backupCount == 0 + finally: + handler.close() + class TestReadLoggingConfig: