feat(dashboard): log HTTP access + WebSocket lifecycle to the gui surface - #49003
Open
kshitijk4poor wants to merge 2 commits into
Open
feat(dashboard): log HTTP access + WebSocket lifecycle to the gui surface#49003kshitijk4poor wants to merge 2 commits into
kshitijk4poor wants to merge 2 commits into
Conversation
…face The messaging gateway logs every inbound message to gateway.log, but its dashboard/TUI twin (gui.log) was nearly silent: the dashboard FastAPI app had host-header/auth-gate/auth middlewares but no access log, and 3 of 4 WebSocket endpoints logged nothing at all. Worst of these, /api/pty logged 'pty accepted' on connect but was completely silent on close — a PTY EOF (backend crash), a send failure, or a client drop left no trace, so user-reported 'chat disconnected / TUI froze' was unreproducible. Extend the convention tui_gateway/ws.py::handle_ws already establishes (a structured 'ws closed peer=... reason=... <counters>' line) across the whole surface, at the same INFO granularity as gateway.log, into the gui.log that is already sized for it (10MB x5): - HTTP access-log middleware (registered LIFO-outermost so it captures the final status, including 400/401 from the middlewares above): one INFO line per request with method, path, status, latency, request id, peer. Path only, never the query string (tokens ride in query on some routes). UA/referer at DEBUG (-v). Reads/echoes X-Request-ID for client/proxy correlation. - /api/pty: structured close line covering all exit paths (client_disconnect | pty_eof | send_failed | error) with duration and bytes_in/out counters. - /api/pub + /api/events: accept + structured close (reason/duration/frames) + all reject paths. - /api/ws: reject paths logged; request id threaded into handle_ws and stamped on its accept/close lines so a WS session correlates with the HTTP upgrade. Metadata only — no request/response bodies, no WS frame payloads, no headers/cookies on the INFO lines. Opt-in body capture is a separate change so this stays clear of the debug-share privacy surface. handle_ws gains an optional rid=None arg, backward-compatible with the stdio entry-point (tui_gateway.entry) which calls handle_ws(ws). Tests (behavior-contract style, not frozen strings): HTTP access line shape + query-string redaction + 401-still-logged + X-Request-ID round-trip; WS accept/close lines for /api/pub and /api/events; WS reject logging; rid propagation through handle_ws.
Contributor
🔎 Lint report:
|
| Rule | Count |
|---|---|
unresolved-attribute |
2 |
unsupported-operator |
1 |
First entries
run_agent.py:2971: [unresolved-attribute] unresolved-attribute: Object of type `Self@get_credits_spent_micros` has no attribute `_credits_session_start_micros`
hermes_cli/web_server.py:11203: [unsupported-operator] unsupported-operator: Operator `+=` is not supported between objects of type `str` and `int`
tests/run_agent/test_credits_notices_toggle.py:76: [unresolved-attribute] unresolved-attribute: Unresolved attribute `_credits_session_start_micros` on type `AIAgent`
✅ Fixed issues (1):
| Rule | Count |
|---|---|
invalid-assignment |
1 |
First entries
tests/run_agent/test_credits_notices_toggle.py:76: [invalid-assignment] invalid-assignment: Object of type `None` is not assignable to attribute `_credits_session_start_micros` of type `int`
Unchanged: 5786 pre-existing issues carried over.
Diagnostics are surfaced as warnings — this check never fails the build.
This was referenced Jun 19, 2026
austinpickett
previously approved these changes
Jun 22, 2026
…uded gui_bodies.log Stacked on #49003. That PR added always-on metadata (method/path/status/ latency + WS lifecycle) to the gui surface. This adds the heavy diagnostic tier — actual HTTP request bodies and PTY/WebSocket frames — for the hard dashboard/TUI bugs where metadata alone isn't enough. Body content can carry conversation data, so this is opt-in and built to be structurally incapable of leaking into a shared debug report (see #22016): - New config logging.capture_bodies (default false), surfaced in the dashboard / hermes tools config UI via _SCHEMA_OVERRIDES with a warning description. - When enabled, bodies go to a SEPARATE gui_bodies.log written by a dedicated logger (hermes_body_capture, propagate=False) that is deliberately NOT a member of any COMPONENT_PREFIXES. Four structural guarantees, all tested: 1. not under any component prefix -> never lands in gui.log / agent.log 2. not in hermes_cli/logs.py LOG_FILES -> not tailable via --- ~/.hermes/logs/agent.log (last 50) --- 2026-06-19 18:48:30,316 INFO [20260619_173001_f45949] agent.conversation_loop: API call #4: model=anthropic/claude-opus-4.8 provider=openrouter in=288583 out=529 total=289112 latency=10.6s cache=284912/288583 (99%) 2026-06-19 18:48:30,318 INFO [20260619_173001_f45949] agent.conversation_loop: Turn ended: reason=text_response(finish_reason=stop) model=anthropic/claude-opus-4.8 api_calls=4/16 budget=4/16 tool_turns=110 last_msg_role=assistant response_len=1474 session=20260619_173001_f45949 2026-06-19 18:48:30,325 INFO [20260619_173001_f45949] run_agent: OpenAI client closed (agent_close, shared=True, tcp_force_closed=0) thread=bg-review:6349795328 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:48:30,652 INFO run_agent: OpenAI client closed (stream_request_complete, shared=False, tcp_force_closed=0) thread=Thread-747 (_call):6421311488 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:48:30,653 INFO [20260619_153431_51fd01] agent.conversation_loop: API call #139: model=anthropic/claude-opus-4.8 provider=openrouter in=243960 out=991 total=244951 latency=11.5s cache=242196/243960 (99%) 2026-06-19 18:48:31,348 INFO [20260619_153431_51fd01] agent.tool_executor: tool terminal completed (0.69s, 161 chars) 2026-06-19 18:48:31,384 INFO run_agent: OpenAI client created (chat_completion_stream_request, shared=False) thread=Thread-749 (_call):6421311488 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:48:51,510 INFO run_agent: OpenAI client closed (stream_request_complete, shared=False, tcp_force_closed=0) thread=Thread-749 (_call):6421311488 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:48:51,511 INFO [20260619_153431_51fd01] agent.conversation_loop: API call #140: model=anthropic/claude-opus-4.8 provider=openrouter in=245038 out=1783 total=246821 latency=20.1s cache=243477/245038 (99%) 2026-06-19 18:48:52,215 INFO [20260619_153431_51fd01] agent.tool_executor: tool terminal completed (0.70s, 153 chars) 2026-06-19 18:48:52,245 INFO run_agent: OpenAI client created (chat_completion_stream_request, shared=False) thread=Thread-751 (_call):6421311488 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:48:59,489 INFO run_agent: OpenAI client closed (stream_request_complete, shared=False, tcp_force_closed=0) thread=Thread-751 (_call):6421311488 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:48:59,490 INFO [20260619_153431_51fd01] agent.conversation_loop: API call #141: model=anthropic/claude-opus-4.8 provider=openrouter in=246873 out=493 total=247366 latency=7.3s cache=244127/246873 (99%) 2026-06-19 18:49:13,666 INFO [20260619_153431_51fd01] agent.tool_executor: tool terminal completed (14.17s, 979 chars) 2026-06-19 18:49:13,692 INFO run_agent: OpenAI client created (chat_completion_stream_request, shared=False) thread=Thread-753 (_call):6421311488 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:49:22,930 INFO run_agent: OpenAI client closed (stream_request_complete, shared=False, tcp_force_closed=0) thread=Thread-753 (_call):6421311488 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:49:22,932 INFO [20260619_153431_51fd01] agent.conversation_loop: API call #142: model=anthropic/claude-opus-4.8 provider=openrouter in=247686 out=548 total=248234 latency=9.3s cache=245109/247686 (99%) 2026-06-19 18:49:23,254 INFO [20260619_153431_51fd01] agent.tool_executor: tool patch completed (0.10s, 1394 chars) 2026-06-19 18:49:23,287 INFO run_agent: OpenAI client created (chat_completion_stream_request, shared=False) thread=Thread-762 (_call):6421311488 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:49:26,661 INFO run_agent: OpenAI client closed (stream_request_complete, shared=False, tcp_force_closed=0) thread=Thread-762 (_call):6421311488 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:49:26,662 INFO [20260619_153431_51fd01] agent.conversation_loop: API call #143: model=anthropic/claude-opus-4.8 provider=openrouter in=248814 out=104 total=248918 latency=3.4s cache=246934/248814 (99%) 2026-06-19 18:49:27,958 INFO [20260619_153431_51fd01] agent.tool_executor: tool terminal completed (1.29s, 14487 chars) 2026-06-19 18:49:27,984 INFO run_agent: OpenAI client created (chat_completion_stream_request, shared=False) thread=Thread-764 (_call):6421311488 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:49:43,991 INFO run_agent: OpenAI client closed (stream_request_complete, shared=False, tcp_force_closed=0) thread=Thread-764 (_call):6421311488 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:49:43,992 INFO [20260619_153431_51fd01] agent.conversation_loop: API call #144: model=anthropic/claude-opus-4.8 provider=openrouter in=255375 out=938 total=256313 latency=16.0s cache=247771/255375 (97%) 2026-06-19 18:49:44,087 INFO [20260619_153431_51fd01] agent.conversation_loop: Turn ended: reason=text_response(finish_reason=stop) model=anthropic/claude-opus-4.8 api_calls=36/90 budget=31/90 tool_turns=129 last_msg_role=assistant response_len=2300 session=20260619_153431_51fd01 2026-06-19 18:49:44,112 INFO run_agent: OpenAI client created (agent_init, shared=True) thread=bg-review:6421311488 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:49:44,454 INFO [20260619_153431_51fd01] agent.turn_context: conversation turn: session=20260619_153431_51fd01 model=anthropic/claude-opus-4.8 provider=openrouter platform=cli history=310 msg='Review the conversation above and update the skill library. Be ACTIVE — most ses...' 2026-06-19 18:49:44,573 INFO run_agent: OpenAI client created (chat_completion_stream_request, shared=False) thread=Thread-765 (_call):6150942720 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:49:54,258 INFO run_agent: OpenAI client closed (stream_request_complete, shared=False, tcp_force_closed=0) thread=Thread-765 (_call):6150942720 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:49:54,259 INFO [20260619_153431_51fd01] agent.conversation_loop: API call #1: model=anthropic/claude-opus-4.8 provider=openrouter in=258322 out=423 total=258745 latency=9.8s cache=248822/258322 (96%) 2026-06-19 18:49:54,360 INFO [20260619_153431_51fd01] agent.tool_executor: tool skills_list completed (0.10s, 21152 chars) 2026-06-19 18:49:54,383 INFO run_agent: OpenAI client created (chat_completion_stream_request, shared=False) thread=Thread-766 (_call):6150942720 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:50:02,705 INFO run_agent: OpenAI client closed (stream_request_complete, shared=False, tcp_force_closed=0) thread=Thread-766 (_call):6150942720 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:50:02,706 INFO [20260619_153431_51fd01] agent.conversation_loop: API call #2: model=anthropic/claude-opus-4.8 provider=openrouter in=266258 out=313 total=266571 latency=8.3s cache=258320/266258 (97%) 2026-06-19 18:50:02,814 INFO [20260619_153431_51fd01] agent.tool_executor: tool skill_view completed (0.11s, 111769 chars) 2026-06-19 18:50:02,836 INFO [20260619_153431_51fd01] tools.tool_result_storage: Persisted large tool result: skill_view (toolu_01G7Zvw8ttjsUkomENppFu5T, 111769 chars -> /var/folders/p5/nqn3gs293rv3wtvf01pl9_vr0000gn/T/hermes-results/toolu_01G7Zvw8ttjsUkomENppFu5T.txt) 2026-06-19 18:50:02,861 INFO run_agent: OpenAI client created (chat_completion_stream_request, shared=False) thread=Thread-769 (_call):6150942720 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:50:12,687 INFO run_agent: OpenAI client closed (stream_request_complete, shared=False, tcp_force_closed=0) thread=Thread-769 (_call):6150942720 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:50:12,688 INFO [20260619_153431_51fd01] agent.conversation_loop: API call #3: model=anthropic/claude-opus-4.8 provider=openrouter in=267367 out=386 total=267753 latency=9.8s cache=258694/267367 (97%) 2026-06-19 18:50:12,749 INFO [20260619_153431_51fd01] agent.tool_executor: tool skill_view completed (0.06s, 22856 chars) 2026-06-19 18:50:12,776 INFO run_agent: OpenAI client created (chat_completion_stream_request, shared=False) thread=Thread-770 (_call):6150942720 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:50:18,989 INFO [20260619_153431_51fd01] agent.turn_context: conversation turn: session=20260619_153431_51fd01 model=anthropic/claude-opus-4.8 provider=openrouter platform=cli history=310 msg='yes' 2026-06-19 18:50:19,032 INFO run_agent: OpenAI client created (chat_completion_stream_request, shared=False) thread=Thread-772 (_call):12901707776 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:50:21,530 INFO run_agent: OpenAI client closed (stream_request_complete, shared=False, tcp_force_closed=0) thread=Thread-770 (_call):6150942720 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:50:21,531 INFO [20260619_153431_51fd01] agent.conversation_loop: API call #4: model=anthropic/claude-opus-4.8 provider=openrouter in=276591 out=415 total=277006 latency=8.8s cache=266515/276591 (96%) 2026-06-19 18:50:21,585 WARNING [20260619_153431_51fd01] agent.tool_executor: Tool skill_view returned error (0.05s): {"success": false, "error": "File 'references/stacked-feature-prs.md' not found in skill 'incremental-architecture-refactor'.", "available_files": {}, "hint": "Use one of the available file paths list 2026-06-19 18:50:21,613 INFO run_agent: OpenAI client created (chat_completion_stream_request, shared=False) thread=Thread-773 (_call):6150942720 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:50:36,019 INFO run_agent: OpenAI client closed (stream_request_complete, shared=False, tcp_force_closed=0) thread=Thread-772 (_call):12901707776 provider=openrouter base_url=https://openrouter.ai/api/v1 model=anthropic/claude-opus-4.8 2026-06-19 18:50:36,020 INFO [20260619_153431_51fd01] agent.conversation_loop: API call #145: model=anthropic/claude-opus-4.8 provider=openrouter in=256317 out=997 total=257314 latency=17.0s cache=256311/256317 (100%) 3. not in debug.py _capture_default_log_snapshots() -> NEVER uploaded by⚠️ This will upload the following to a public paste service: • System info (OS, Python version, Hermes version, provider, which API keys are configured — NOT the actual keys) • Recent log lines (agent.log, errors.log, gateway.log, desktop.log — may contain conversation fragments and file paths) • Full agent.log, gateway.log, and desktop.log (up to 512 KB each — likely contains conversation content, tool outputs, and file paths) Pastes auto-delete after 6 hours. Collecting debug report... Uploading... Debug report uploaded: Report https://paste.rs/nnfZj (failed to upload: agent.log: Failed to upload to any paste service: paste.rs: HTTP Error 500: Internal Server Error dpaste.com: <urlopen error [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed: certificate has expired (_ssl.c:1016)>, gateway.log: Failed to upload to any paste service: paste.rs: HTTP Error 500: Internal Server Error dpaste.com: <urlopen error [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed: certificate has expired (_ssl.c:1016)>, desktop.log: Failed to upload to any paste service: paste.rs: HTTP Error 500: Internal Server Error dpaste.com: <urlopen error [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed: certificate has expired (_ssl.c:1016)>) ⏱ Pastes will auto-delete in 6 hours. To delete now: hermes debug delete <url> Share these links with the Hermes team for support. 4. still redacted via RedactingFormatter as defence-in-depth - Disabled state attaches a NullHandler and sets the level above CRITICAL, so _capture_body() is a cheap no-op (single isEnabledFor check) on the hot path. Captured bodies are truncated to 4096 bytes. request.body() is Starlette- cached, so reading it in the access middleware does not consume the stream for downstream handlers. Capture sites: HTTP request body (access middleware), PTY in/out frames. Tests (tests/test_hermes_logging.py::TestBodyCaptureOptIn): disabled-by-default creates no file and captures nothing; enabled writes to gui_bodies.log and the payload is ABSENT from gui.log; large bodies truncate; the body logger is isolated from every component; and the body file is excluded from both LOG_FILES and the debug-share snapshot set.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
The messaging gateway logs every inbound message to
gateway.log, but its dashboard/TUI twin (gui.log) was nearly silent. The dashboard FastAPI app had host-header / auth-gate / auth middlewares but no access log, and 3 of 4 WebSocket endpoints logged nothing at all.The worst case:
/api/ptyloggedpty acceptedon connect but was completely silent on close — a PTY EOF (backend crash), a send failure, or a client drop left no trace. So the common user reports ("chat disconnected", "TUI froze", "dashboard hung") were unreproducible: nothing landed ingui.logfrom the surface that broke.This extends the convention
tui_gateway/ws.py::handle_wsalready establishes — a structuredws closed peer=… reason=… <counters>line — across the whole dashboard surface, at the same INFO granularity asgateway.log, into thegui.logalready sized for it (10MB×5). Pairs with #48981 (which madegui.logshareable viahermes debug share).Changes (
hermes_cli/web_server.py)http method=… path=… status=… dur_ms=… rid=… peer=….-v) only.X-Request-ID(proxy/SPA) or mints one, and echoes it on the response for client-side correlation./api/pty: structured close line across all exit paths —client_disconnect | pty_eof | send_failed | error— withdur_sandbytes_in/outcounters./api/pub+/api/events: accept + structured close (reason/duration/frames) + all reject paths (were silent end-to-end)./api/ws: reject paths logged (were bareclose(code)); request id threaded intohandle_ws.tui_gateway/ws.pyhandle_wsgains an optionalrid=Nonearg, stamped on its existing accept/close lines so a WS session correlates with the HTTP upgrade that opened it. Backward-compatible with the stdio entry-point (tui_gateway.entry), which callshandle_ws(ws).Scope / privacy
Metadata only — no request/response bodies, no WS frame payloads, no headers/cookies on the INFO lines. Opt-in body capture is deliberately a separate change so this stays clear of the
debug shareprivacy surface (#22016).Verbosity
Matches the house convention: everything at INFO to
gui.log(thegateway.loggranularity), noisier fields at DEBUG behind the existing global-v. No new verbosity knob.Test plan
pytest tests/hermes_cli/test_web_server.py tests/test_tui_gateway_ws.py— 310 passedX-Request-IDround-trip + query-string redaction + inbound-rid propagation + 401-is-still-logged (proves outermost ordering)/api/pub+/api/eventsaccept/close lines; reject loggingtui_gateway:ridstamped on accept/close;rid=Nonedefault preservedTestClient: confirmedevents accepted …/events closed peer=… reason=client_disconnect dur_s=…actually fireTestPtyWebSocketround-trip tests fail identically on cleanmainin a sandboxed runner (need a real TTY) — pre-existing, not introduced here (stash-verified againstmain).Follow-up (separate PR)
Opt-in request/response body capture behind a
config.yamlgate +hermes toolstoggle, structurally excluded fromdebug share. Tracked separately so the gating is done right.