fix(logging): fall back from concurrent-log-handler when portalocker is dead

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

@@ -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"
     )

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: