fix: preserve access logs during agent stdout capture (#2684)

Own a private stdout descriptor before agent imports and serialize request log writes. Keep logging failures isolated from HTTP responses. Add successful chat/start subprocess delivery regressions and document header-latency semantics and cron ownership.

api/request_logging.py

@@ -0,0 +1,26 @@
+"""Request output independent of agent/tool stdout capture."""
+
+import os
+import threading
+
+
+# Import before agent code. Own the descriptor so replacing or closing Python's
+# sys.stdout cannot capture access/error records intended for the service log.
+try:
+    _STREAM = os.fdopen(
+        os.dup(1), "w", encoding="utf-8", errors="backslashreplace", buffering=1,
+    )
+except OSError:
+    _STREAM = None
+_LOCK = threading.Lock()
+
+
+def emit_request_log(message: str) -> None:
+    """Flush one complete record without letting a broken sink break HTTP."""
+    try:
+        if _STREAM is not None:
+            with _LOCK:
+                _STREAM.write(message + "\n")
+                _STREAM.flush()
+    except Exception:
+        pass

docs/troubleshooting.md

@@ -6,6 +6,26 @@ If your symptom isn't listed and the diagnostics don't narrow it down, file a bu
 
 ---
 
+## Requests succeed but access records disappear during agent work
+
+The server emits `[webui]` JSON access records to its original process stdout,
+using a private duplicate captured before agent imports. This keeps request and
+HTTP error logs visible when an in-process tool redirects or closes `sys.stdout`.
+Logging failures still must not interrupt HTTP responses.
+
+Check the service's captured stdout (for example, `docker logs <container>` or
+the journal for your WebUI unit). Verify successful `POST /api/chat/start` and
+`GET /api/chat/stream` records, not only health probes or rejected requests.
+Records include `method`, `path`, `status`, and `ms`: elapsed time until response
+headers, **not** the lifetime of an SSE stream or the agent turn. A missing record
+before response headers does not distinguish a pending request from a logging
+failure. Keep the launcher's output destination open for the process lifetime.
+
+Scheduled cron execution belongs to the Hermes Agent gateway scheduler, not the
+WebUI HTTP server. Investigate cron outcomes in the gateway's logs and the
+active Hermes home's `cron/executions.db`; WebUI access records show HTTP cron
+management requests, not every scheduled execution.
+
 ## "AIAgent not available -- check that hermes-agent is on sys.path"
 
 **Symptom.** WebUI starts, shows the chat interface, but every chat request fails immediately with this error in the response or the server log. As of v0.51.6 the error includes a diagnostic block with the running Python interpreter, the relevant `sys.path` entries, and the most-common fix; on older versions the message is bare.

server.py

@@ -99,6 +99,7 @@ from urllib.parse import urlparse
 
 logger = logging.getLogger(__name__)
 
+from api.request_logging import emit_request_log
 from api.auth import check_auth, reset_trusted_auth_request_state
 from api.config import HOST, PORT, STATE_DIR, SESSION_DIR, DEFAULT_WORKSPACE
 from api.helpers import (
@@ -338,10 +339,7 @@ class Handler(BaseHTTPRequestHandler):
     @staticmethod
     def _safe_webui_print(message: str) -> None:
         """Emit a request log line without letting logging break responses."""
-        try:
-            print(message, flush=True)
-        except Exception:
-            pass
+        emit_request_log(message)
 
     def log_request(self, code: str='-', size: str='-') -> None:
         """Structured JSON logs for each request."""

tests/test_access_log_delivery.py

@@ -0,0 +1,92 @@
+"""Access records must reach the process output, even during agent capture."""
+
+import json
+import os
+from pathlib import Path
+import subprocess
+import sys
+import textwrap
+
+import pytest
+
+
+@pytest.mark.parametrize("capture", ["redirected", "closed"])
+def test_successful_chat_start_delivers_access_record(tmp_path, capture):
+    # A subprocess tests the delivered fd text, not an internal counter or a
+    # patched print. Keep the real chat route and HTTP response/logging stack;
+    # replace only model discovery and execution with deterministic fixtures.
+    script = textwrap.dedent('''
+        import io
+        import json
+        import sys
+        import threading
+        import time
+        from unittest.mock import patch
+        from server import Handler
+        from api import routes
+        from api.models import Session
+
+        handler = Handler.__new__(Handler)
+        handler.command = "POST"
+        handler.path = "/api/chat/start"
+        handler.requestline = "POST /api/chat/start HTTP/1.1"
+        handler.request_version = "HTTP/1.1"
+        handler.client_address = ("127.0.0.1", 12345)
+        handler.headers = {}
+        handler.wfile = io.BytesIO()
+        handler._req_t0 = time.time()
+        session = Session(session_id="log-delivery", model="fixture")
+        original = sys.stdout
+        captured = io.StringIO()
+        if sys.argv[1] == "closed":
+            captured.close()
+
+        def start_run(session, **kwargs):
+            # Agent tool capture can redirect stdout from another thread before
+            # chat/start writes its acceptance response.
+            def capture_output():
+                sys.stdout = captured
+            worker = threading.Thread(target=capture_output)
+            worker.start()
+            worker.join()
+            return {"stream_id": "log-stream", "session_id": session.session_id}
+
+        try:
+            with (
+                patch.object(routes, "_agent_runtime_barrier_response", return_value=None),
+                patch.object(routes, "_get_or_materialize_session", return_value=session),
+                patch.object(routes, "_resolve_chat_workspace_with_recovery", return_value="/tmp"),
+                patch.object(routes, "_read_profile_model_config", return_value=(None, "fixture", {})),
+                patch.object(routes, "get_config", return_value={}),
+                patch.object(routes, "_resolve_compatible_session_model_state", return_value=("fixture", None, False)),
+                patch.object(routes, "_start_run", side_effect=start_run),
+            ):
+                routes._handle_chat_start(handler, {"session_id": session.session_id, "message": "wake"})
+        finally:
+            sys.stdout = original
+        response = handler.wfile.getvalue()
+        assert b"HTTP/1.1 200" in response, response
+        assert json.loads(response.split(b"\\r\\n\\r\\n", 1)[1])["stream_id"] == "log-stream"
+    ''')
+    env = {
+        "PATH": os.environ["PATH"],
+        "HOME": str(tmp_path),
+        "HERMES_HOME": str(tmp_path / "home"),
+        "HERMES_WEBUI_STATE_DIR": str(tmp_path / "state"),
+        "HERMES_WEBUI_TEST_NETWORK_BLOCK": "1",
+    }
+    result = subprocess.run(
+        [sys.executable, "-c", script, capture],
+        cwd=Path(__file__).resolve().parents[1], env=env,
+        capture_output=True, text=True, timeout=30,
+    )
+    assert result.returncode == 0, result.stderr
+    records = [
+        json.loads(line.removeprefix("[webui] "))
+        for line in result.stdout.splitlines() if line.startswith("[webui] ")
+    ]
+    assert len(records) == 1, f"Successful chat/start lost its access record: {result.stdout!r}"
+    assert records[0]["method"] == "POST"
+    assert records[0]["path"] == "/api/chat/start"
+    assert records[0]["status"] == 200
+    assert records[0]["ms"] >= 0

tests/test_issue2775_log_request.py

@@ -1,16 +1,26 @@
 import json
+import io
+
+import pytest
 
 from server import Handler
 
 
-def test_log_request_handles_malformed_request_without_path(capsys):
+@pytest.fixture
+def log_output(monkeypatch):
+    output = io.StringIO()
+    monkeypatch.setattr("api.request_logging._STREAM", output)
+    return output
+
+
+def test_log_request_handles_malformed_request_without_path(log_output):
     """Malformed request lines can call log_request before path is assigned."""
     handler = Handler.__new__(Handler)
     handler.command = None
 
     Handler.log_request(handler, "400")
 
-    line = capsys.readouterr().out.strip()
+    line = log_output.getvalue().strip()
     assert line.startswith("[webui] ")
     record = json.loads(line.removeprefix("[webui] "))
     assert record["method"] == "-"
@@ -19,7 +29,7 @@ def test_log_request_handles_malformed_request_without_path(capsys):
     assert record["remote"] == "-"
 
 
-def test_log_request_includes_remote_address(capsys):
+def test_log_request_includes_remote_address(log_output):
     handler = Handler.__new__(Handler)
     handler.command = "POST"
     handler.path = "/api/auth/login"
@@ -28,13 +38,13 @@ def test_log_request_includes_remote_address(capsys):
 
     Handler.log_request(handler, "401")
 
-    line = capsys.readouterr().out.strip()
+    line = log_output.getvalue().strip()
     record = json.loads(line.removeprefix("[webui] "))
     assert record["remote"] == "192.0.2.10"
     assert "forwarded_for" not in record
 
 
-def test_log_request_includes_first_forwarded_for_address(capsys):
+def test_log_request_includes_first_forwarded_for_address(log_output):
     class Headers:
         def get(self, key):
             assert key == "X-Forwarded-For"
@@ -48,7 +58,7 @@ def test_log_request_includes_first_forwarded_for_address(capsys):
 
     Handler.log_request(handler, "401")
 
-    line = capsys.readouterr().out.strip()
+    line = log_output.getvalue().strip()
     record = json.loads(line.removeprefix("[webui] "))
     assert record["remote"] == "192.0.2.10"
     assert record["forwarded_for"] == "203.0.113.7"