Log every model call's time and tokens

Each call through BudgetedClient emits llm.call: seconds, input,
output and cached tokens, and the answering model when a fallback
answered; a failed call logs how long it ran before it failed.
Usage now carries the server's cached-prompt count on both routes.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01J5Utyfzw7gF7UhjRDEtjTk

nisse-core/tests/test_context.py

@@ -1,6 +1,7 @@
 """The context budget (architecture L6)."""
 
 import io
+import json
 from pathlib import Path
 from typing import Any
 
@@ -25,6 +26,7 @@ from nisse_core.models.context import (
     fit,
     head_and_tail,
 )
+from nisse_core.models.llm import LLMError
 from nisse_core.oplog import OpLog
 from nisse_core.state.store import StateStore
 
@@ -190,7 +192,7 @@ def test_reported_usage_only_ever_raises_the_estimate() -> None:
     assert under_then_over._factors["m"] == 2.0  # never loosened
 
 
-def test_a_request_that_fits_is_sent_whole_and_nothing_is_logged() -> None:
+def test_a_request_that_fits_is_sent_whole_and_no_cut_is_logged() -> None:
     stream = io.StringIO()
     client = BudgetedClient(
         RecordingClient(), lambda m: (100_000, None), oplog=OpLog("t", stream)
@@ -198,7 +200,49 @@ def test_a_request_that_fits_is_sent_whole_and_nothing_is_logged() -> None:
     events = transcript(3, 100)
     client.complete(events, None, "m")
     assert client.last_trim is None
-    assert stream.getvalue() == ""
+    assert "context.trimmed" not in stream.getvalue()
+
+
+def logged(stream: io.StringIO, event: str) -> list[dict[str, Any]]:
+    records = [json.loads(line) for line in stream.getvalue().splitlines()]
+    return [r for r in records if r["event"] == event]
+
+
+def test_every_call_logs_its_time_and_tokens() -> None:
+    # A slow turn should show whether reading or writing took the time (#174).
+    stream = io.StringIO()
+    inner = RecordingClient(reported_input=900)
+    inner.last_usage["cached"] = 800
+    inner.last_model = "fallback-model"
+    client = BudgetedClient(inner, lambda m: (100_000, None), oplog=OpLog("t", stream))
+    client.complete(transcript(1, 10), None, "m")
+    [call] = logged(stream, "llm.call")
+    assert call["cause"] == "answered"
+    assert call["model"] == "m"
+    assert call["answered_by"] == "fallback-model"
+    assert (call["input_tokens"], call["output_tokens"], call["cached_tokens"]) == (
+        900,
+        5,
+        800,
+    )
+    assert isinstance(call["seconds"], float)
+
+
+def test_a_failed_call_logs_how_long_it_ran_and_still_raises() -> None:
+    class TimesOut(RecordingClient):
+        def complete(self, *args, **kwargs):
+            raise LLMError("LLM request returned 408: timed out")
+
+    stream = io.StringIO()
+    client = BudgetedClient(
+        TimesOut(), lambda m: (100_000, None), oplog=OpLog("t", stream)
+    )
+    with pytest.raises(LLMError):
+        client.complete(transcript(1, 10), None, "m")
+    [call] = logged(stream, "llm.call")
+    assert call["cause"] == "failed"
+    assert call["error"] == "LLMError"
+    assert "input_tokens" not in call
 
 
 def test_a_cut_is_recorded_and_logged() -> None: