diff --git a/docs/SPEC-PIN.md b/docs/SPEC-PIN.md index 9980e7d..f037df8 100644 --- a/docs/SPEC-PIN.md +++ b/docs/SPEC-PIN.md @@ -7,17 +7,18 @@ documents the pin, the vendored artifacts, and the bump procedure. | Field | Value | |---|---| -| Worldtree git SHA | `da93ca7cf613f1dc229a7a44d07fc1d7efc78e25` | -| Worldtree HEAD message | `feat(#204): v0.28.0 — persona-state observability surface` | -| Pinned on | 2026-05-25 | -| Pinned by | ratatoskr-dev (bump for #204 affect_update SSE) | -| Worldtree version at pin | `v0.28.0` | +| Worldtree git SHA | `562001af28d752c3a60d449c7ddd09f44fa9dc9a` | +| Worldtree HEAD message | `feat(#201): v0.29.0 — awaiting_llm_first_token SSE heartbeat` | +| Pinned on | 2026-05-26 | +| Pinned by | ratatoskr-dev (bump for #201 awaiting_llm_first_token SSE) | +| Worldtree version at pin | `v0.29.0` | ## Pin history | Date | SHA | Version | Notable deltas consumed | |---|---|---|---| -| 2026-05-25 | `da93ca7` | v0.28.0 | #204 — new SSE event `affect_update` (current/scheduled), new endpoint `GET /agents/{id}/persona_state` (not yet consumed), auth-model doc edits | +| 2026-05-26 | `562001a` | v0.29.0 | #201 — new SSE event `awaiting_llm_first_token` (heartbeat during BuildingPrompt → CallingLLM gap, default 5s interval) | +| 2026-05-25 | `da93ca7` | v0.28.0 | #204 — new SSE event `affect_update` (current/scheduled), new endpoint `GET /agents/{id}/persona_state`, auth-model doc edits | | 2026-05-20 | `55101e9` | v0.19.0 | initial scaffold pin | ## Vendored artifacts diff --git a/docs/conversation-api-spec.md b/docs/conversation-api-spec.md index e5a1f56..1f9db4f 100644 --- a/docs/conversation-api-spec.md +++ b/docs/conversation-api-spec.md @@ -1980,6 +1980,26 @@ Emitted after the post-turn appraisal task has been scheduled (per #177 Phase A' Bootstrap reads available via `GET /agents/{agent_id}/persona_state` (same `snapshot` shape, requires `persona.read` scope). +### awaiting_llm_first_token + +Periodic heartbeat event (issue #201) emitted at a configurable interval during the gap between `worker_phase: phase="BuildingPrompt"` and `worker_phase: phase="CallingLLM"`. Solves the legitimate-slow first-token visibility gap: consumer TUIs can render a "thinking for Ns…" timer rather than a frozen line during heavy-CoT prompt warmup. + +```json +{ + "type": "awaiting_llm_first_token", + "turn_id": 42, + "elapsed_ms_since_building_prompt": 5012.3 +} +``` + +`elapsed_ms_since_building_prompt` is the server-authoritative wall-clock milliseconds since `BuildingPrompt` was emitted. Independent of network latency or clock skew. + +Heartbeats stop the moment the engine produces its first event (the `CallingLLM` marker). They do NOT re-fire during tool-roundtrip `CallingLLM` re-entries — the heartbeat is scoped to the FIRST `BuildingPrompt → CallingLLM` gap only. + +**Configuration:** `conversation_api.awaiting_llm_first_token_heartbeat_s` (default `5.0`). Per-agent override via `agent.conversation.awaiting_llm_first_token_heartbeat_s`. Value `0.0` disables emission entirely. + +Cancellation paths (stall watchdog, user-cancel) also stop the heartbeat — no `awaiting_llm_first_token` event appears after the terminal `cancelled` event. + ### thinking Incremental reasoning/thinking content (from thinking-enabled models). diff --git a/docs/conversation_api.contract.md b/docs/conversation_api.contract.md index 5abe1f7..78098ee 100644 --- a/docs/conversation_api.contract.md +++ b/docs/conversation_api.contract.md @@ -1881,6 +1881,73 @@ SQLite `consumer_agents` table. through `_publish`, so SSE resume / replay handles them with no special case. +## Amendment — AwaitingLLMFirstToken heartbeat (issue #201, INV-201-1..7) + +Adds a periodic SSE heartbeat event during the gap between +`BuildingPrompt` and `CallingLLM` so consumers can distinguish +"engine is thinking" from "engine is wedged" without out-of-band +server inspection. Filed by ratatoskr-dev; ships in v0.29.0. + +- **INV-201-1 (new top-level event type)**: `awaiting_llm_first_token` + is a new top-level SSE event type, sibling to `worker_phase` / + `tool_*` / `text` / `thinking` / `debug` / `done` / `affect_update`. + `_WORKER_PHASE_VOCAB` is NOT extended; INV-053 / INV-054 unchanged. + Same precedent as #204's `affect_update`. + +- **INV-201-2 (config-gated emission)**: Heartbeat emission requires + `awaiting_llm_first_token_heartbeat_s > 0.0`. When the resolved + value is `0.0`, the heartbeat task is never started and zero + `awaiting_llm_first_token` events emit for the turn. When > 0.0, + the task starts immediately after `_publish_phase("BuildingPrompt")` + and emits an event every `interval` seconds until cancelled. + +- **INV-201-3 (defense-in-depth cancellation)**: The heartbeat task + is cancelled at three sites (idempotent via the `_cancel_heartbeat` + helper): (a) immediately before `_publish_phase("CallingLLM")` on + the engine-first-event path; (b) inside the `cancelled`/`error` + handling that wraps `_handle_cancel` (covers stall + user-cancel + paths); (c) in the outer `finally` block alongside + `_clear_stall_timer`. After cancellation, no further + `awaiting_llm_first_token` events emit. + +- **INV-201-4 (wire shape)**: Payload is exactly `{type: + "awaiting_llm_first_token", turn_id: , + elapsed_ms_since_building_prompt: }` plus the composite `id: + ":"` stamped by `_publish`. No additional fields. + `elapsed_ms_since_building_prompt` is `(time.monotonic() - + building_prompt_t) * 1000.0` where `building_prompt_t` is captured + immediately before `BuildingPrompt` is published. + +- **INV-201-5 (first-gap-only scope)**: Heartbeat is scoped to the + FIRST `BuildingPrompt → CallingLLM` gap of the turn. Tool round-trip + `CallingLLM` re-entries (INV-058) emit ZERO + `awaiting_llm_first_token` events. Out-of-scope sub-phases + (`AwaitingToolResult`, `AwaitingNextLLMCall`) would be separate + follow-up features. + +- **INV-201-6 (replay participation)**: Heartbeat events flow through + `_publish → _replay_buffer + queue` per INV-060 — same replay + semantics as worker_phase events. On `Last-Event-ID` reconnect, + prior heartbeats replay identically. + +- **INV-201-7 (config resolution precedence)**: Per-agent + `agent.conversation.awaiting_llm_first_token_heartbeat_s` → + `api_cfg.awaiting_llm_first_token_heartbeat_s` → built-in `5.0`. + Negative values raise `ConfigurationError` at agent load; `0.0` + is valid and means "disabled." Mirrors the `_resolve_stall_timeout_s` + precedence pattern (INV-038). + +### Mechanism note + +The heartbeat task is a separate `asyncio.Task` (NOT `loop.call_later`, +because heartbeats repeat at an interval rather than fire once at a +timeout). An `asyncio.Queue` shared between the heartbeat task and the +generator carries events; the generator uses +`asyncio.wait(return_when=FIRST_COMPLETED)` to race the engine's +`__anext__` against the heartbeat queue's `get` ONLY during the first +iteration. After `CallingLLM` fires, the heartbeat task is cancelled +and subsequent iterations use the original non-race pattern. + ### Storage extension The `consumer_agents` table lives in `core/heimdall/storage/sqlite.py` diff --git a/pyproject.toml b/pyproject.toml index 0fd655a..4193f85 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "hatchling.build" [project] name = "ratatoskr" -version = "0.13.0" +version = "0.14.0" description = "Worldtree Conversation API debug TUI — multi-pane observability dashboard" readme = "README.md" requires-python = ">=3.12" @@ -42,9 +42,9 @@ Repository = "https://gitea.phasefinal.com/vh/ratatoskr" # Ratatoskr is built against Worldtree at this commit; the vendored # spec snapshot in docs/ reflects that SHA. [tool.ratatoskr.spec-pin] -worldtree-spec-rev = "da93ca7cf613f1dc229a7a44d07fc1d7efc78e25" -worldtree-version = "v0.28.0" -pinned-on = "2026-05-25" +worldtree-spec-rev = "562001af28d752c3a60d449c7ddd09f44fa9dc9a" +worldtree-version = "v0.29.0" +pinned-on = "2026-05-26" [tool.hatch.build.targets.wheel] packages = ["src/ratatoskr"] diff --git a/src/ratatoskr/sse_client.py b/src/ratatoskr/sse_client.py index 2ea9cfa..1cd298a 100644 --- a/src/ratatoskr/sse_client.py +++ b/src/ratatoskr/sse_client.py @@ -111,6 +111,31 @@ class Cancelled: partial_message_id: int | None +@dataclass(frozen=True) +class AwaitingLlmFirstToken: + """SSE event `awaiting_llm_first_token`: heartbeat during slow first-token. + + Fires at the configured interval (default 5s) during the gap between + `worker_phase` phase=BuildingPrompt and phase=CallingLLM. Lets clients + render a live "thinking for Ns…" indicator instead of a frozen line + during legitimate-slow first-token latency. Stops the moment CallingLLM + fires (defense-in-depth at three sites); no heartbeat after Cancelled + or stalled terminal events. Tool round-trip re-entries do NOT re-fire + heartbeats — INV-201-5 scopes the mechanism to the FIRST gap only. + + `elapsed_ms_since_building_prompt` is server-authoritative + `time.monotonic()`-based — independent of network latency or clock + skew, monotonically increasing across the heartbeat sequence. + + See docs/conversation-api-spec.md § awaiting_llm_first_token + (Worldtree #201, v0.29.0). + """ + + sse_id: SseId + turn_id: int + elapsed_ms_since_building_prompt: float + + @dataclass(frozen=True) class AffectUpdate: """SSE event `affect_update`: persona-state observability snapshot. @@ -146,6 +171,7 @@ Event = ( | Error | Cancelled | AffectUpdate + | AwaitingLlmFirstToken ) @@ -309,6 +335,15 @@ def _envelope_for_type(body: dict[str, Any], sse_id: SseId) -> Event: reason=body.get("reason"), partial_message_id=body.get("partial_message_id"), ) + if t == "awaiting_llm_first_token": + # Worldtree #201 / v0.29.0: top-level heartbeat during BuildingPrompt + # → CallingLLM gap. Lets clients render live elapsed-time indicators + # instead of frozen lines on legitimate-slow first-token latency. + return AwaitingLlmFirstToken( + sse_id=sse_id, + turn_id=body["turn_id"], + elapsed_ms_since_building_prompt=body["elapsed_ms_since_building_prompt"], + ) if t == "affect_update": # Worldtree #204 / v0.28.0: persona-state observability event. # status="current" carries full snapshot at turn start; diff --git a/src/ratatoskr/tui.py b/src/ratatoskr/tui.py index c92f0f3..efd41a6 100644 --- a/src/ratatoskr/tui.py +++ b/src/ratatoskr/tui.py @@ -46,6 +46,7 @@ from ratatoskr.sessions import ( ) from ratatoskr.sse_client import ( AffectUpdate, + AwaitingLlmFirstToken, CancelAlreadyCompleted, CancelFailed, Cancelled, @@ -295,6 +296,12 @@ def _audit_line(event: Event) -> str: ) elif isinstance(event, Cancelled): detail = f"turn_id={event.turn_id} reason={event.reason!r}" + elif isinstance(event, AwaitingLlmFirstToken): + # Worldtree #201 / v0.29.0. Compact: turn_id + elapsed in seconds + # (the heartbeat itself fires every 5s by default; seconds-rounding + # is the natural unit for operator scanning). + secs = event.elapsed_ms_since_building_prompt / 1000.0 + detail = f"turn_id={event.turn_id} elapsed={secs:.1f}s" elif isinstance(event, AffectUpdate): # Worldtree #204 / v0.28.0. status="current" carries the full # snapshot; surface dominant_emotion + PAD inline so the operator @@ -347,6 +354,13 @@ class TuiPresenterState: thinking_delta_count: int = 0 thinking_byte_count: int = 0 turn_start_ts: float = 0.0 + # v0.14.0: Worldtree #201 heartbeat surface. First + # `awaiting_llm_first_token` mounts a Static; subsequent heartbeats + # update it in place; any non-heartbeat event clears it (the gap + # closed). awaiting_widget is the Static reference (None when + # closed); heartbeat_count tracks emissions for the turn-summary. + awaiting_widget: object = None + heartbeat_count: int = 0 def render( self, @@ -383,6 +397,7 @@ class TuiPresenterState: ( WorkerPhase, Thinking, Text, TextBoundary, ToolStart, ToolResult, Done, Error, Cancelled, AffectUpdate, + AwaitingLlmFirstToken, ), ) from rich.text import Text as RichText @@ -430,6 +445,37 @@ class TuiPresenterState: # the event regardless. pass return + # v0.14.0: AwaitingLlmFirstToken (Worldtree #201) gets the audit + # line (above) plus a live transcript indicator. First heartbeat + # mounts a Static; subsequent heartbeats update it in place. + # Any non-heartbeat event below closes the gap and the indicator + # is removed (the first text/thinking/done arrived). + if isinstance(event, AwaitingLlmFirstToken): + from rich.text import Text as RichText + self.heartbeat_count += 1 + secs = event.elapsed_ms_since_building_prompt / 1000.0 + label = RichText( + f"awaiting first token · {secs:.1f}s", + style=_AU_DEMOTED, + ) + try: + if self.awaiting_widget is None: + self.awaiting_widget = Static(label, classes="awaiting-label") + transcript.mount(self.awaiting_widget) + else: + self.awaiting_widget.update(label) + transcript.scroll_end(animate=False) + except Exception: + pass + return + # Any non-heartbeat event past this point means the gap closed — + # remove the awaiting indicator if it's still mounted. + if self.awaiting_widget is not None: + try: + self.awaiting_widget.remove() + except Exception: + pass + self.awaiting_widget = None # 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- @@ -525,6 +571,7 @@ class TuiPresenterState: f"text_bytes={self.text_byte_count} " f"thinking_deltas={self.thinking_delta_count} " f"thinking_bytes={self.thinking_byte_count} " + f"heartbeats={self.heartbeat_count} " f"elapsed_ms={elapsed_ms}" )) # Terminal event: finalize the response widget (clear ref so @@ -838,6 +885,14 @@ class RatatoskrApp(App[int]): height: auto; padding: 0 1; } + /* v0.14.0: Worldtree #201 — live "awaiting first token · Ns" indicator + in the transcript during the BuildingPrompt → CallingLLM gap. + Demoted styling so it reads as ambient progress, not content. */ + .awaiting-label { + height: auto; + padding: 0 1; + color: $au-dark-60; + } /* v0.8.1: #current-text Static removed. Streaming text now coalesces on `\n` and writes directly to #transcript (same pattern as v0.7.1 thinking fix). Eliminates the dock-bottom-growth-overlap bug. */ diff --git a/tests/test_sse_client.py b/tests/test_sse_client.py index 44a3b69..dc4ef60 100644 --- a/tests/test_sse_client.py +++ b/tests/test_sse_client.py @@ -6,6 +6,7 @@ import respx from ratatoskr.sse_client import ( AffectUpdate, + AwaitingLlmFirstToken, CancelAlreadyCompleted, Cancelled, CancelResult, @@ -955,3 +956,87 @@ class TestAffectUpdate: assert affect.turn_id == 42 assert affect.snapshot is None assert affect.sse_id == SseId(42, 2) + + +class TestAwaitingLlmFirstToken: + """Worldtree #201 / v0.29.0 — `awaiting_llm_first_token` SSE heartbeat. + + Top-level event (not a worker_phase extension) fired during the + BuildingPrompt → CallingLLM gap at the configured interval (default + 5s). Server-authoritative elapsed_ms is time.monotonic()-based and + monotonically increasing across the heartbeat sequence. + + See docs/conversation-api-spec.md § awaiting_llm_first_token. + """ + + @respx.mock + async def test_single_heartbeat_parsed(self) -> None: + """single_heartbeat_parsed [tracer]: type=awaiting_llm_first_token → + AwaitingLlmFirstToken(turn_id, elapsed_ms_since_building_prompt). + """ + stream = _sse_chunk( + "42:1", + { + "type": "awaiting_llm_first_token", + "turn_id": 42, + "elapsed_ms_since_building_prompt": 5012.3, + }, + ) + _sse_chunk("42:2", _DONE_42_6) + respx.post("https://w.example/sessions/s1/messages").mock( + return_value=httpx.Response( + 200, headers={"content-type": "text/event-stream"}, content=stream + ) + ) + async with httpx.AsyncClient(base_url="https://w.example") as client: + events = [e async for e in stream_turn(client, "s1", "hi")] + beat = events[0] + assert isinstance(beat, AwaitingLlmFirstToken) + assert beat.turn_id == 42 + assert beat.elapsed_ms_since_building_prompt == 5012.3 + assert beat.sse_id == SseId(42, 1) + + @respx.mock + async def test_heartbeat_sequence_monotonic(self) -> None: + """heartbeat_sequence_monotonic [scenario]: three consecutive heartbeats + in one turn — elapsed_ms_since_building_prompt monotonically increases, + all carry the same turn_id. + """ + stream = ( + _sse_chunk( + "42:1", + { + "type": "awaiting_llm_first_token", + "turn_id": 42, + "elapsed_ms_since_building_prompt": 5000.0, + }, + ) + + _sse_chunk( + "42:2", + { + "type": "awaiting_llm_first_token", + "turn_id": 42, + "elapsed_ms_since_building_prompt": 10005.4, + }, + ) + + _sse_chunk( + "42:3", + { + "type": "awaiting_llm_first_token", + "turn_id": 42, + "elapsed_ms_since_building_prompt": 15011.8, + }, + ) + + _sse_chunk("42:4", _DONE_42_6) + ) + respx.post("https://w.example/sessions/s1/messages").mock( + return_value=httpx.Response( + 200, headers={"content-type": "text/event-stream"}, content=stream + ) + ) + async with httpx.AsyncClient(base_url="https://w.example") as client: + events = [e async for e in stream_turn(client, "s1", "hi")] + beats = [e for e in events if isinstance(e, AwaitingLlmFirstToken)] + assert len(beats) == 3 + elapsed = [b.elapsed_ms_since_building_prompt for b in beats] + assert elapsed == sorted(elapsed) # monotonically increasing + assert all(b.turn_id == 42 for b in beats) diff --git a/tests/test_tui.py b/tests/test_tui.py index 908391a..6a707cb 100644 --- a/tests/test_tui.py +++ b/tests/test_tui.py @@ -719,6 +719,95 @@ class TestPresenterAuditLogging: assert not tools_log.write.called assert not thinking_log.write.called + def test_awaiting_llm_first_token_mounts_indicator(self) -> None: + """awaiting_llm_first_token_mounts_indicator [v0.14.0]: first heartbeat + mounts a Static into the transcript and bumps heartbeat_count; + debug-pane audit line carries turn_id + elapsed in seconds. + """ + from ratatoskr.sse_client import AwaitingLlmFirstToken + from ratatoskr.tui import TuiPresenterState + + transcript = MagicMock() + debug_log = MagicMock() + state = TuiPresenterState() + state.render( + AwaitingLlmFirstToken( + sse_id=SID, turn_id=42, elapsed_ms_since_building_prompt=5012.3 + ), + transcript=transcript, + tools_log=MagicMock(), + debug_log=debug_log, + thinking_log=MagicMock(), + raw=False, + ) + assert state.heartbeat_count == 1 + assert state.awaiting_widget is not None + assert transcript.mount.call_count == 1 + audit = _text_of(debug_log.write.call_args[0][0]) + assert "awaitingllmfirsttoken" in audit + assert "turn_id=42" in audit + assert "elapsed=5.0s" in audit + + def test_awaiting_subsequent_heartbeats_update_in_place(self) -> None: + """awaiting_subsequent_heartbeats_update_in_place [v0.14.0]: second+ + heartbeats reuse the existing Static (no new mount); heartbeat_count + tracks the total. + """ + from ratatoskr.sse_client import AwaitingLlmFirstToken + from ratatoskr.tui import TuiPresenterState + + transcript = MagicMock() + state = TuiPresenterState() + for elapsed in (5000.0, 10005.4, 15011.8): + state.render( + AwaitingLlmFirstToken( + sse_id=SID, turn_id=42, elapsed_ms_since_building_prompt=elapsed + ), + transcript=transcript, + tools_log=MagicMock(), + debug_log=MagicMock(), + thinking_log=MagicMock(), + raw=False, + ) + assert state.heartbeat_count == 3 + assert transcript.mount.call_count == 1 # mounted once on first + + def test_awaiting_indicator_removed_when_gap_closes(self) -> None: + """awaiting_indicator_removed_when_gap_closes [v0.14.0]: any non- + heartbeat event after one or more heartbeats removes the indicator + and clears the awaiting_widget reference. Text event simulates the + gap closing (CallingLLM fires, text begins). + """ + from ratatoskr.sse_client import AwaitingLlmFirstToken + from ratatoskr.tui import TuiPresenterState + + transcript = MagicMock() + state = TuiPresenterState() + state.render( + AwaitingLlmFirstToken( + sse_id=SID, turn_id=42, elapsed_ms_since_building_prompt=5000.0 + ), + transcript=transcript, + tools_log=MagicMock(), + debug_log=MagicMock(), + thinking_log=MagicMock(), + raw=False, + ) + widget = state.awaiting_widget + assert widget is not None + state.render( + Text(sse_id=SID, content="hello"), + transcript=transcript, + tools_log=MagicMock(), + debug_log=MagicMock(), + thinking_log=MagicMock(), + raw=False, + ) + # State reference cleared (the widget itself is a real Static whose + # .remove() schedules removal — we verify the cleanup intent via + # the state field, which is the contract callers actually observe). + assert state.awaiting_widget is None + def test_affect_update_scheduled_has_no_pad_detail(self) -> None: """affect_update_scheduled_has_no_pad_detail [v0.11.0]: status=scheduled carries no snapshot — the audit line omits dominant_emotion / pad and diff --git a/uv.lock b/uv.lock index 9ae874f..1cf9d32 100644 --- a/uv.lock +++ b/uv.lock @@ -968,7 +968,7 @@ wheels = [ [[package]] name = "ratatoskr" -version = "0.13.0" +version = "0.14.0" source = { editable = "." } dependencies = [ { name = "httpx" },