diff --git a/api/request_logging.py b/api/request_logging.py new file mode 100644 index 00000000..df9df817 --- /dev/null +++ b/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 diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index f3335f98..35cba162 100644 --- a/docs/troubleshooting.md +++ b/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 ` 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. diff --git a/server.py b/server.py index 364d5988..040d80c1 100644 --- a/server.py +++ b/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.""" diff --git a/tests/test_access_log_delivery.py b/tests/test_access_log_delivery.py new file mode 100644 index 00000000..9096d925 --- /dev/null +++ b/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 diff --git a/tests/test_issue2775_log_request.py b/tests/test_issue2775_log_request.py index 687c1830..0bfbb0e2 100644 --- a/tests/test_issue2775_log_request.py +++ b/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"