From 209427ab23ee7e34d059164d0be35c7c22104f35 Mon Sep 17 00:00:00 2001 From: Vuong Hoang Date: Mon, 25 May 2026 01:36:35 -0700 Subject: [PATCH] feat(tui): debug-pane audit logging surface (v0.10.0) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Adds wire-level visibility appropriate for a debugging TUI. Every SSE event arrival now lands as one debug-pane line; token-rate Text and Thinking deltas get aggregated counters surfaced in a per-turn summary instead of per-delta spam. Audit surfaces added (all routed to the debug pane): - per-event arrival: timestamp + event type + sse_id + event-specific summary for WorkerPhase / ToolStart / ToolResult / TextBoundary / Done / Error / Cancelled - turn-summary at terminal events: text_deltas / text_bytes / thinking_deltas / thinking_bytes / elapsed_ms - app-level state-machine transitions via new RatatoskrApp._transition helper (idle → streaming → cancelling → idle, with reason) - worker_spawn line at on_input_submitted with content_len - ctrl_c / ctrl_d audit lines documenting action + exit code - cancel POST lifecycle: _cancel_via_sse takes an optional audit callback and emits issued / ok / failed lines - app_mounted bootstrap line at on_mount (server + agent + session tail + raw + end_user_id) - wire-error exception class + body audit at _stream_turn_worker Helpers: - TuiPresenterState: text_delta_count / text_byte_count / thinking_delta_count / thinking_byte_count / turn_start_ts - module-level _ts() + _audit_line() + RatatoskrApp._audit() / _transition() Tests: 6 new test cases lock in audit-line shape, turn-summary aggregation, cancel-POST lifecycle callback, and the silence of per-Text-delta debug writes. --- pyproject.toml | 2 +- src/ratatoskr/tui.py | 165 ++++++++++++++++++++++++++++++++++++++++++- tests/test_tui.py | 157 ++++++++++++++++++++++++++++++++++++++++ uv.lock | 2 +- 4 files changed, 321 insertions(+), 5 deletions(-) diff --git a/pyproject.toml b/pyproject.toml index 21430c3..29feef0 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "hatchling.build" [project] name = "ratatoskr" -version = "0.9.0" +version = "0.10.0" description = "Worldtree Conversation API debug TUI — multi-pane observability dashboard" readme = "README.md" requires-python = ">=3.12" diff --git a/src/ratatoskr/tui.py b/src/ratatoskr/tui.py index 3906f37..c018f7a 100644 --- a/src/ratatoskr/tui.py +++ b/src/ratatoskr/tui.py @@ -10,7 +10,9 @@ from __future__ import annotations import asyncio import sys +import time as _time from dataclasses import dataclass +from datetime import datetime as _datetime from typing import ClassVar, Literal import httpx @@ -178,6 +180,48 @@ def _plain_label(event: Event) -> str: return f"[unknown_event] {type(event).__name__}" +def _ts() -> str: + """HH:MM:SS.fff wall-clock timestamp for debug-pane log lines.""" + now = _datetime.now() + return now.strftime("%H:%M:%S") + f".{now.microsecond // 1000:03d}" + + +def _audit_line(event: Event) -> str: + """One-line wire-level audit summary for the debug pane. + + v0.10.0: every SSE event arrival lands as one of these in the debug + pane (Text and Thinking deltas are aggregated into the turn summary + instead — token-rate per-delta lines would drown the pane). Shape: + `[HH:MM:SS.fff] event_type sse_id=T:S key=val …`. + """ + sid = getattr(event, "sse_id", None) + sid_str = f"{sid.turn_id}:{sid.seq}" if sid is not None else "-" + kind = type(event).__name__.lower() + if isinstance(event, WorkerPhase): + detail = f"phase={event.phase} turn_id={event.turn_id}" + elif isinstance(event, ToolStart): + detail = f"name={event.name} args={event.arguments!r:.80}" + elif isinstance(event, ToolResult): + detail = f"name={event.name} duration_ms={event.duration_ms}" + elif isinstance(event, TextBoundary): + detail = f"kind={event.kind} char_offset={event.char_offset}" + elif isinstance(event, Done): + detail = ( + f"turn_id={event.sse_id.turn_id} model={event.model} " + f"duration_ms={event.duration_ms}" + ) + elif isinstance(event, Error): + detail = ( + f"turn_id={event.sse_id.turn_id} code={event.error_code} " + f"message={event.message!r:.80}" + ) + elif isinstance(event, Cancelled): + detail = f"turn_id={event.turn_id} reason={event.reason!r}" + else: # Text / Thinking handled by counter path; fallback for safety + detail = "" + return f"[{_ts()}] {kind} sse_id={sid_str} {detail}".rstrip() + + @dataclass(slots=True) class TuiPresenterState: """Per-turn presenter state for TUI mode (issue #12). @@ -202,6 +246,15 @@ class TuiPresenterState: # v0.9.0: reference to the Static widget holding the current turn's # response Markdown Renderable. None between turns. current_response_widget: object = None + # v0.10.0: per-turn counters for the debug-pane turn-summary line. Text + # and Thinking events arrive at token rate; emitting per-delta debug + # lines would drown the pane. Instead we count them and surface + # aggregated totals when the turn closes. + text_delta_count: int = 0 + text_byte_count: int = 0 + thinking_delta_count: int = 0 + thinking_byte_count: int = 0 + turn_start_ts: float = 0.0 def render( self, @@ -240,6 +293,29 @@ class TuiPresenterState: return RichText(s, style=_AU_DEMOTED) try: + # v0.10.0: per-event audit log line to debug pane. Text and + # Thinking arrive at token rate, so we count them rather than + # emit a line per delta — totals are reported in the turn- + # summary on Done/Error/Cancelled. Everything else gets one + # debug-pane line per arrival with timestamp + sse_id + a short + # event-specific summary, giving the operator a wire-level + # timeline of what the server sent. + if isinstance(event, Text): + if self.text_delta_count == 0: + if self.turn_start_ts == 0.0: + self.turn_start_ts = _time.monotonic() + self.text_delta_count += 1 + self.text_byte_count += len(event.content) + elif isinstance(event, Thinking): + if self.thinking_delta_count == 0: + if self.turn_start_ts == 0.0: + self.turn_start_ts = _time.monotonic() + self.thinking_delta_count += 1 + self.thinking_byte_count += len(event.content) + else: + if self.turn_start_ts == 0.0: + self.turn_start_ts = _time.monotonic() + debug_log.write(_dim(_audit_line(event))) # v0.7.1: Thinking deltas coalesce by newline before flushing. # Worldtree emits Thinking events at token granularity; per-delta # RichLog writes produce one visual line per token (per-token-per- @@ -315,6 +391,28 @@ class TuiPresenterState: transcript.scroll_end(animate=False) return if isinstance(event, (Done, Error, Cancelled)): + # v0.10.0: emit turn-summary to debug pane before clearing + # counters. Aggregates the per-event totals (Text + Thinking + # deltas don't get per-event audit lines because they arrive + # at token rate; the summary surfaces what was elided). + elapsed_ms = ( + int((_time.monotonic() - self.turn_start_ts) * 1000) + if self.turn_start_ts + else 0 + ) + turn_id = ( + event.sse_id.turn_id + if hasattr(event, "sse_id") + else getattr(event, "turn_id", "?") + ) + debug_log.write(_dim( + f"[{_ts()}] turn_summary turn_id={turn_id} " + f"text_deltas={self.text_delta_count} " + f"text_bytes={self.text_byte_count} " + f"thinking_deltas={self.thinking_delta_count} " + f"thinking_bytes={self.thinking_byte_count} " + f"elapsed_ms={elapsed_ms}" + )) # Terminal event: finalize the response widget (clear ref so # the next turn mounts a fresh one). The accumulated text is # already rendered as Markdown in the widget — no post-Done @@ -793,6 +891,14 @@ class RatatoskrApp(App[int]): ) self.state = "idle" self._set_hint(self.HINT_IDLE) + # v0.10.0: startup audit so the debug pane carries a complete + # session bootstrap line (server URL, agent, end_user_id, raw flag, + # session tail) before the first turn fires. + self._audit( + f"app_mounted server={self.args.server_url} agent_id={self.agent_id!r} " + f"session={self.session_id[-8:]} raw={self.args.raw} " + f"end_user_id={getattr(self.args, 'end_user_id', None)!r}" + ) def _write_turn_headers(self, turn_id: int) -> None: """v0.6.0: turn-ID headers across every pane for cross-pane @@ -833,6 +939,37 @@ class RatatoskrApp(App[int]): # Widget may be gone during shutdown; ignore. pass + def _audit(self, line: str) -> None: + """Write a timestamped audit line to the debug pane. + + v0.10.0: shared sink for app-level events that don't pass through + the presenter — state transitions, worker spawn/cancel, cancel POST + lifecycle, startup probes. The presenter's per-event audit lives at + `_audit_line()`; this is its app-side counterpart. + """ + try: + from rich.text import Text as RichText + self.query_one("#debug-log", RichLog).write( + RichText(f"[{_ts()}] {line}", style=_AU_DEMOTED) + ) + except Exception: + # Widget may not exist yet (pre-mount) or be tearing down. + pass + + def _transition( + self, new_state: Literal["idle", "streaming", "cancelling"], reason: str + ) -> None: + """Set self.state with debug-pane audit log. + + Every state machine transition flows through here so the debug pane + carries a complete idle→streaming→cancelling→idle timeline with the + triggering reason. Cheap; safe to call from any context. + """ + old = self.state + self.state = new_state + if old != new_state: + self._audit(f"state {old} → {new_state} reason={reason}") + async def on_input_submitted(self, event: Input.Submitted) -> None: """Echo user prompt, spawn stream worker; busy notice if not idle. @@ -863,7 +1000,8 @@ class RatatoskrApp(App[int]): ) transcript.scroll_end(animate=False) event.input.value = "" - self.state = "streaming" + self._transition("streaming", "input_submitted") + self._audit(f"worker_spawn content_len={len(content)}") self._set_hint(self.HINT_STREAMING) self.stream_worker = self.run_worker( self._stream_turn_worker(content), exclusive=True @@ -909,17 +1047,22 @@ class RatatoskrApp(App[int]): if isinstance(event, (Done, Error, Cancelled)): break except SseConnectFailed as exc: + self._audit(f"sse_connect_failed status={exc.status} body={exc.body!r:.120}") _mount_wire_error(f"[sse_connect_failed] status={exc.status} body={exc.body!r}") except SseConnectionDropped as exc: + self._audit(f"connection_dropped last_seen={exc.last_seen_sse_id}") _mount_wire_error(f"[connection_dropped] last_seen={exc.last_seen_sse_id}") except MalformedSseId as exc: + self._audit(f"malformed_sse_id raw={exc.raw!r}") _mount_wire_error(f"[malformed_sse_id] raw={exc.raw!r}") except MalformedSseData as exc: + self._audit(f"malformed_sse_data raw={exc.raw!r:.120}") _mount_wire_error(f"[malformed_sse_data] raw={exc.raw!r}") except TurnIdFlip as exc: + self._audit(f"turn_id_flip expected={exc.established} got={exc.got}") _mount_wire_error(f"[turn_id_flip] expected={exc.established} got={exc.got}") finally: - self.state = "idle" + self._transition("idle", "worker_finally") self.active_turn_id = None self._set_hint(self.HINT_IDLE) @@ -931,29 +1074,35 @@ class RatatoskrApp(App[int]): """Two-stage Ctrl-C state machine per INV-003.""" assert self.state in ("idle", "streaming", "cancelling") if self.state == "idle": + self._audit("ctrl_c state=idle action=exit code=0") self.exit(0) elif self.state == "streaming": if self.active_turn_id is None: + self._audit("ctrl_c state=streaming active_turn_id=None action=force_exit code=3") if self.stream_worker is not None: self.stream_worker.cancel() self.exit(3) return - self.state = "cancelling" + self._audit(f"ctrl_c state=streaming turn_id={self.active_turn_id} action=cancel_post") + self._transition("cancelling", "ctrl_c_cancel_post_issued") self._set_hint(self.HINT_CANCELLING) transcript = self.query_one("#transcript-scroll", VerticalScroll) self.run_worker( _cancel_via_sse( self.client, self.session_id, self.active_turn_id, transcript=transcript, + audit=self._audit, ) ) elif self.state == "cancelling": + self._audit("ctrl_c state=cancelling action=force_exit code=3") if self.stream_worker is not None: self.stream_worker.cancel() self.exit(3) def action_quit(self) -> None: """Ctrl-D — immediate exit regardless of state.""" + self._audit(f"ctrl_d state={self.state} action=exit code=0") if self.stream_worker is not None and not self.stream_worker.is_finished: self.stream_worker.cancel() self.exit(0) @@ -1095,17 +1244,27 @@ async def _cancel_via_sse( turn_id: int, *, transcript: VerticalScroll, + audit: "Callable[[str], None] | None" = None, ) -> None: """Fire-and-forget cancel; never raises (mirrors cli._cancel_and_log; #3 INV-009). v0.9.0: mounts a `[cancel_failed]` Static into the transcript-scroll container on failure (was log.write to RichLog). + v0.10.0: optional `audit` callback (RatatoskrApp._audit) receives one + line on POST issue + one on POST result, so the debug pane carries the + full cancel lifecycle. Defaults to no-op for legacy callers. """ assert client is not None assert isinstance(turn_id, int) and turn_id > 0 + if audit is not None: + audit(f"cancel_post issued session_id={session_id} turn_id={turn_id}") try: await cancel_turn(client, session_id, turn_id) + if audit is not None: + audit(f"cancel_post ok turn_id={turn_id}") except (CancelFailed, CancelTurnNotFound, CancelAlreadyCompleted, httpx.RequestError) as exc: + if audit is not None: + audit(f"cancel_post failed turn_id={turn_id} {type(exc).__name__}: {exc!s:.120}") try: transcript.mount(Static( f"[cancel_failed] {type(exc).__name__}: {exc}", diff --git a/tests/test_tui.py b/tests/test_tui.py index 8aeca06..b08b344 100644 --- a/tests/test_tui.py +++ b/tests/test_tui.py @@ -605,6 +605,122 @@ class TestTuiPresenterState: assert "usage 6756 in → 126 out (6882 total, 0 cached)" in done_line +class TestPresenterAuditLogging: + """v0.10.0 — per-event audit lines + turn-summary in the debug pane. + + The presenter emits one debug-pane line per arriving event (Text and + Thinking are aggregated into the turn-summary instead of per-delta to + avoid drowning the pane at token rate). + """ + + def test_worker_phase_emits_audit_line(self) -> None: + """worker_phase_emits_audit_line: WorkerPhase arrival adds an audit + line to debug_log alongside the existing `· worker_phase:` entry. + Audit line shape: `[HH:MM:SS.fff] workerphase sse_id=N:M …`. + """ + from ratatoskr.tui import TuiPresenterState + + debug_log = MagicMock() + state = TuiPresenterState() + state.render( + WorkerPhase(sse_id=SID, phase="streaming", turn_id=42), + transcript=MagicMock(), + tools_log=MagicMock(), + debug_log=debug_log, + thinking_log=MagicMock(), + raw=False, + ) + # Two writes: audit line + worker_phase telemetry. + assert debug_log.write.call_count == 2 + audit_line = _text_of(debug_log.write.call_args_list[0][0][0]) + assert "workerphase" in audit_line + assert "sse_id=42:5" in audit_line + assert "phase=streaming" in audit_line + + def test_tool_start_emits_audit_line(self) -> None: + """tool_start_emits_audit_line: ToolStart adds one audit line to + debug_log even though the tool event itself routes to tools_log. + """ + from ratatoskr.tui import TuiPresenterState + + debug_log = MagicMock() + state = TuiPresenterState() + state.render( + ToolStart(sse_id=SID, name="read_file", arguments={"path": "/x"}), + transcript=MagicMock(), + tools_log=MagicMock(), + debug_log=debug_log, + thinking_log=MagicMock(), + raw=False, + ) + assert debug_log.write.call_count == 1 + audit_line = _text_of(debug_log.write.call_args[0][0]) + assert "toolstart" in audit_line + assert "sse_id=42:5" in audit_line + assert "name=read_file" in audit_line + + def test_text_delta_counted_not_per_event_audit_line(self) -> None: + """text_delta_counted_not_per_event_audit_line: a Text delta does + NOT emit a per-event audit line (token-rate would drown the pane); + instead it bumps text_delta_count / text_byte_count for the turn- + summary at Done. + """ + from ratatoskr.tui import TuiPresenterState + + debug_log = MagicMock() + state = TuiPresenterState() + state.render( + Text(sse_id=SID, content="hello world"), + transcript=MagicMock(), + tools_log=MagicMock(), + debug_log=debug_log, + thinking_log=MagicMock(), + raw=False, + ) + # No debug-pane writes — text deltas are silent at token rate. + assert not debug_log.write.called + assert state.text_delta_count == 1 + assert state.text_byte_count == len("hello world") + + def test_done_emits_turn_summary_line(self) -> None: + """done_emits_turn_summary_line: when Done arrives the presenter + emits a `turn_summary` line aggregating per-delta Text + Thinking + counters. The shape exposes the totals that per-event audit lines + elided. + """ + from ratatoskr.tui import TuiPresenterState + + debug_log = MagicMock() + state = TuiPresenterState() + # 3 Text deltas + 2 Thinking deltas, then Done. + state.render( + Text(sse_id=SID, content="a"), + transcript=MagicMock(), tools_log=MagicMock(), + debug_log=debug_log, thinking_log=MagicMock(), raw=False, + ) + state.render( + Text(sse_id=SID, content="bc"), + transcript=MagicMock(), tools_log=MagicMock(), + debug_log=debug_log, thinking_log=MagicMock(), raw=False, + ) + state.render( + Thinking(sse_id=SID, content="thought\n"), + transcript=MagicMock(), tools_log=MagicMock(), + debug_log=debug_log, thinking_log=MagicMock(), raw=False, + ) + state.render( + _make_tui_done(), + transcript=MagicMock(), tools_log=MagicMock(), + debug_log=debug_log, thinking_log=MagicMock(), raw=False, + ) + writes = [_text_of(c[0][0]) for c in debug_log.write.call_args_list] + summary = next(w for w in writes if "turn_summary" in w) + assert "text_deltas=2" in summary + assert "text_bytes=3" in summary # "a" + "bc" + assert "thinking_deltas=1" in summary + assert "elapsed_ms=" in summary + + def _text_of(write_arg: object) -> str: """Extract plain text from a RichLog.write() arg (str or rich.text.Text). @@ -715,6 +831,47 @@ class TestCancelViaSse: assert "[cancel_failed]" in line assert "ConnectError" in line + @respx.mock + async def test_audit_callback_records_lifecycle(self) -> None: + """audit_callback_records_lifecycle [v0.10.0]: when the caller passes + an `audit` callback, _cancel_via_sse emits two lines on the happy + path (`cancel_post issued …` + `cancel_post ok …`) and two lines on + the failure path (`issued` + `failed …`). Gives the debug pane a + complete cancel-POST timeline. + """ + respx.post("https://w.example/sessions/s-1/turns/42/cancel").mock( + return_value=httpx.Response(200, json=_CANCEL_OK_RESP) + ) + transcript = MagicMock() + audit_lines: list = [] + async with httpx.AsyncClient(base_url="https://w.example") as client: + await _cancel_via_sse( + client, "s-1", 42, transcript=transcript, audit=audit_lines.append + ) + assert len(audit_lines) == 2 + assert audit_lines[0].startswith("cancel_post issued ") + assert "session_id=s-1" in audit_lines[0] + assert "turn_id=42" in audit_lines[0] + assert audit_lines[1] == "cancel_post ok turn_id=42" + + @respx.mock + async def test_audit_callback_records_failure(self) -> None: + """audit_callback_records_failure [v0.10.0]: failure path emits + `cancel_post issued` then `cancel_post failed …` with exception type. + """ + respx.post("https://w.example/sessions/s-1/turns/42/cancel").mock( + return_value=httpx.Response(500, content=b"boom") + ) + transcript = MagicMock() + audit_lines: list = [] + async with httpx.AsyncClient(base_url="https://w.example") as client: + await _cancel_via_sse( + client, "s-1", 42, transcript=transcript, audit=audit_lines.append + ) + assert len(audit_lines) == 2 + assert audit_lines[0].startswith("cancel_post issued ") + assert audit_lines[1].startswith("cancel_post failed turn_id=42 CancelFailed") + class TestAppMount: """on_mount narrows per issue #6: only identity-widget population. diff --git a/uv.lock b/uv.lock index 930304d..13523bc 100644 --- a/uv.lock +++ b/uv.lock @@ -968,7 +968,7 @@ wheels = [ [[package]] name = "ratatoskr" -version = "0.9.0" +version = "0.10.0" source = { editable = "." } dependencies = [ { name = "httpx" },