feat(tui): debug-pane audit logging surface (v0.10.0)

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.
2026-05-25 01:36:35 -07:00
parent 139771c8d8
commit 209427ab23
4 changed files with 321 additions and 5 deletions
@@ -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.