Add model and generation time to LLM gist reports

tests/ai_explainer/test_output.py

@@ -12,6 +12,8 @@
     format_explanation_line,
 )
 from utils.llm.base import LLMError, LLMProvider, LLMUsage
+from utils.llm.fallback import FallbackProvider
+from utils.llm.report import ReportContext
 
 
 class TestStructuredOutput(unittest.TestCase):
@@ -219,7 +221,7 @@ def test_spill_failure_still_returns_alert_line(self, _mock_mkdir: MagicMock, _m
 
 class TestTextRefineDetailBudget(unittest.TestCase):
     def test_immediate_pass_keeps_detail_without_extra_call(self) -> None:
-        provider = MagicMock()
+        provider = MagicMock(model_name="test")
         provider.supports_structured_output = False
         provider.complete.side_effect = [
             "TLDR: original. LOW.\n\nDETAIL:\nOriginal analysis.",
@@ -231,7 +233,7 @@ def test_immediate_pass_keeps_detail_without_extra_call(self) -> None:
         self.assertIn("original. LOW", result.summary)
 
     def test_multiple_revisions_regenerate_detail_once(self) -> None:
-        provider = MagicMock()
+        provider = MagicMock(model_name="test")
         provider.supports_structured_output = False
         provider.complete.side_effect = [
             "TLDR: original. LOW.\n\nDETAIL:\nOriginal analysis.",
@@ -248,7 +250,7 @@ def test_multiple_revisions_regenerate_detail_once(self) -> None:
 
     def test_expansion_failure_keeps_revised_summary_discards_stale_detail(self) -> None:
 
-        provider = MagicMock()
+        provider = MagicMock(model_name="test")
         provider.supports_structured_output = False
         provider.complete.side_effect = [
             "TLDR: original. LOW.\n\nDETAIL:\nOriginal analysis.",
@@ -264,10 +266,11 @@ def test_expansion_failure_keeps_revised_summary_discards_stale_detail(self) ->
 class _UsageProvider(LLMProvider):
     """A text provider that reports a fixed usage per call, like a real provider; fails after ``fail_after`` calls."""
 
-    def __init__(self, responses: list[str], fail_after: int | None = None) -> None:
+    def __init__(self, responses: list[str], fail_after: int | None = None, *, model_name: str = "test") -> None:
         self.responses = responses
         self.fail_after = fail_after
         self.calls = 0
+        self._model_name = model_name
 
     def complete(self, prompt: str, system_prompt: str = "") -> str:
         if self.fail_after is not None and self.calls >= self.fail_after:
@@ -278,7 +281,7 @@ def complete(self, prompt: str, system_prompt: str = "") -> str:
 
     @property
     def model_name(self) -> str:
-        return "test"
+        return self._model_name
 
 
 class TestStageUsage(unittest.TestCase):
@@ -300,6 +303,7 @@ def test_summary_critique_rounds_and_detail_are_recorded(self) -> None:
         )
         self.assertEqual(explanation.stages[1].summary, "Pauses the vault and blocks deposits. MEDIUM")
         self.assertEqual([s.usage.input_tokens for s in explanation.stages if s.usage], [1000, 2000, 3000, 4000])
+        self.assertEqual([s.model_name for s in explanation.stages], ["test"] * 4)
 
     def test_failed_call_reports_no_usage(self) -> None:
         provider = _UsageProvider(["TLDR: Pauses the vault. LOW\nDETAIL: d"], fail_after=1)
@@ -309,6 +313,76 @@ def test_failed_call_reports_no_usage(self) -> None:
         )
         # The failed call keeps no usage: the provider's last_usage still belongs to the summary call.
         self.assertIsNone(explanation.stages[1].usage)
+        self.assertEqual(explanation.stages[1].model_name, "test")
+
+
+class TestGenerationMetadata(unittest.TestCase):
+    """Published reports identify all answering models and total generation time."""
+
+    def test_empty_structured_summary_model_is_omitted_but_usage_is_retained(self) -> None:
+        cli = MagicMock(spec=LLMProvider, model_name="empty-cli", supports_structured_output=True)
+        cli.complete_structured.return_value = {"summary": "", "risk_tag": "LOW"}
+        cli.complete.side_effect = LLMError("text unavailable")
+        cli.last_usage = LLMUsage(2000, 900, None, 100, 0.5)
+        api = _UsageProvider(["TLDR: Pauses the vault. LOW", "Detailed analysis."], model_name="api")
+        provider = FallbackProvider([cli, api])
+
+        explanation = _generate_explanation(provider, "p", report_ctx=ReportContext(chain_id=1))
+
+        self.assertIn("- **Model:** api\n", explanation.report)
+        self.assertNotIn("empty-cli", explanation.report)
+        self.assertEqual(explanation.stages[0].outcome, "empty")
+        self.assertEqual(explanation.stages[0].model_name, "empty-cli")
+        self.assertEqual(explanation.stages[0].usage, cli.last_usage)
+
+    @patch("utils.llm.ai_explainer.perf_counter")
+    def test_generation_time_is_logged_for_successful_and_empty_summaries(self, clock: MagicMock) -> None:
+        for response in ("TLDR: Pauses the vault. LOW\nDETAIL: Detail.", "   "):
+            with self.subTest(response=response):
+                clock.return_value = 100.0
+
+                def complete(prompt: str, system_prompt: str = "") -> str:
+                    clock.return_value = 110.0
+                    return response
+
+                provider = MagicMock(
+                    spec=LLMProvider, model_name="api", supports_structured_output=False, last_usage=None
+                )
+                provider.complete.side_effect = complete
+                with self.assertLogs("utils.llm.ai_explainer", level="INFO") as logs:
+                    explanation = _generate_explanation(provider, "p", report_ctx=ReportContext(chain_id=1))
+                self.assertIn("generation time=10.0s", "\n".join(logs.output))
+                if explanation.summary:
+                    self.assertIn("- **Time:** 10.0s", explanation.report)
+
+    @patch("utils.llm.ai_explainer.upload_to_gist", return_value="https://gist.wavey.info/abc123")
+    def test_fallback_models_and_total_time_reach_gist(self, gist: MagicMock) -> None:
+        primary = _UsageProvider(
+            ["TLDR: Pauses the vault. LOW\nDETAIL: Initial detail."], fail_after=1, model_name="primary"
+        )
+        fallback = _UsageProvider(
+            ["TLDR: Pauses the vault and blocks deposits. MEDIUM", "PASS", "Final detail."], model_name="fallback"
+        )
+        unused = _UsageProvider([], model_name="unused")
+        provider = FallbackProvider([primary, fallback, unused])
+
+        with self.assertLogs("utils.llm.ai_explainer", level="INFO") as logs:
+            explanation = _generate_explanation(provider, "prompt", refine=True, report_ctx=ReportContext(chain_id=1))
+        format_explanation_line(explanation)
+
+        body = gist.call_args.args[0]
+        self.assertIn("- **Chain:** Mainnet (chain id 1)", body)
+        self.assertIn("- **Risk:** MEDIUM\n- **Model:** primary / fallback\n- **Time:**", body)
+        self.assertRegex(body, r"- \*\*Time:\*\* \d+\.\ds")
+        self.assertNotIn("unused", body)
+        self.assertIn("Final detail.", body)
+        self.assertEqual([stage.model_name for stage in explanation.stages], ["primary"] + ["fallback"] * 3)
+        output = "\n".join(logs.output)
+        self.assertIn("summary ok model=primary in=1000 cached=900 out=100", output)
+        self.assertIn("critique-1 revised model=fallback in=1000 cached=900 out=100", output)
+        self.assertIn("generation time=", output)
+        self.assertEqual(sum("LLM usage:" in line for line in logs.output), 1)
+        self.assertNotIn("LLM stage=", output)
 
 
 class TestEmptyCritique(unittest.TestCase):

tests/test_llm_cli.py

@@ -11,7 +11,7 @@
 from typing import Any
 from unittest.mock import MagicMock, patch
 
-from utils.llm.base import LLMError, LLMProvider, LLMUnavailableError
+from utils.llm.base import LLMError, LLMProvider, LLMUnavailableError, LLMUsage
 from utils.llm.cli_provider import ClaudeCLIProvider, CodexCLIProvider, _cli_environment, _run_cli
 from utils.llm.factory import get_llm_provider, reset_provider
 from utils.llm.fallback import FallbackProvider
@@ -32,8 +32,10 @@ def _events(*items: dict[str, Any]) -> str:
 CODEX_SUCCESS = _events({"type": "thread.started"}, {"type": "turn.completed"})
 
 
-def _claude_result(**fields: Any) -> str:
-    return _events({"type": "system", "subtype": "init"}, {"type": "result", "is_error": False, **fields})
+def _claude_result(model: str | None = None, **fields: Any) -> str:
+    return _events(
+        {"type": "system", "subtype": "init", "model": model}, {"type": "result", "is_error": False, **fields}
+    )
 
 
 def _arg_after(args: list[str], flag: str) -> str:
@@ -313,6 +315,48 @@ def fake_run(label: str, args: list[str], *rest: Any) -> MagicMock:
 class TestClaudeCLIProvider(unittest.TestCase):
     """Tests for ClaudeCLIProvider."""
 
+    @patch("utils.llm.cli_provider._run_cli")
+    def test_default_model_is_read_from_init_metadata(self, mock_run: MagicMock) -> None:
+        mock_run.return_value = _completed([], stdout=_claude_result(model="claude-opus-5-5", result="OK"))
+        provider = ClaudeCLIProvider(binary="claude")
+        provider.complete("p")
+        self.assertEqual(provider.model_name, "claude-cli:claude-opus-5-5")
+
+    @patch("utils.llm.cli_provider._run_cli")
+    def test_answering_model_overrides_init_model_and_configured_alias(self, mock_run: MagicMock) -> None:
+        mock_run.return_value = _completed(
+            [],
+            stdout=_events(
+                {"type": "system", "subtype": "init", "model": "initial-model"},
+                {"type": "assistant", "message": {"model": "first-model", "content": []}},
+                {"type": "assistant", "message": {"model": "answering-model", "content": []}},
+                {"type": "result", "is_error": False, "result": "OK"},
+            ),
+        )
+        provider = ClaudeCLIProvider(binary="claude", model="opus")
+        provider.complete("p")
+        self.assertEqual(provider.model_name, "claude-cli:answering-model")
+
+    @patch("utils.llm.cli_provider._run_cli")
+    def test_missing_or_invalid_metadata_does_not_reuse_previous_model(self, mock_run: MagicMock) -> None:
+        for configured in ("", "opus"):
+            for model in (None, " ", "<synthetic>"):
+                with self.subTest(configured=configured, model=model):
+                    mock_run.side_effect = [
+                        _completed([], stdout=_claude_result(model="previous-model", result="OK")),
+                        _completed(
+                            [],
+                            stdout=_events(
+                                {"type": "assistant", "message": {"model": model}},
+                                {"type": "result", "is_error": False, "result": "OK"},
+                            ),
+                        ),
+                    ]
+                    provider = ClaudeCLIProvider(binary="claude", model=configured)
+                    provider.complete("previous")
+                    provider.complete("current")
+                    self.assertEqual(provider.model_name, f"claude-cli:{configured}" if configured else "claude-cli")
+
     @patch("utils.llm.cli_provider._run_cli")
     def test_complete_disables_builtins_and_mcp(self, mock_run: MagicMock) -> None:
         seen_system: list[str] = []
@@ -348,14 +392,22 @@ def test_complete_structured_reads_structured_output(self, mock_run: MagicMock)
         mock_run.side_effect = lambda label, args, *rest: _completed(
             args,
             stdout=_events(
-                {"type": "assistant", "message": {"content": [{"type": "tool_use", "name": "StructuredOutput"}]}},
+                {
+                    "type": "assistant",
+                    "message": {
+                        "model": "claude-opus-5-5",
+                        "content": [{"type": "tool_use", "name": "StructuredOutput"}],
+                    },
+                },
                 {"type": "result", "is_error": False, "result": "", "structured_output": {"summary": "ok"}},
             ),
         )
 
-        result = ClaudeCLIProvider(binary="claude").complete_structured("p", SCHEMA)
+        provider = ClaudeCLIProvider(binary="claude", model="opus")
+        result = provider.complete_structured("p", SCHEMA)
 
         self.assertEqual(result, {"summary": "ok"})
+        self.assertEqual(provider.model_name, "claude-cli:claude-opus-5-5")
         self.assertEqual(json.loads(_arg_after(mock_run.call_args.args[1], "--json-schema")), SCHEMA)
 
     @patch("utils.llm.cli_provider._run_cli")
@@ -439,10 +491,42 @@ def model_name(self) -> str:
 class TestFallbackProvider(unittest.TestCase):
     """Tests for FallbackProvider."""
 
+    def test_api_fallback_preserves_usage_for_both_completion_formats(self) -> None:
+        for structured in (False, True):
+            with self.subTest(structured=structured):
+                cli = _StubProvider("cli", [LLMUnavailableError("offline")])
+                api = _StubProvider("api", [{"summary": "ok"}] if structured else ["ok"])
+                api.last_usage = LLMUsage(1000, 900, 25, 100, 0.5)
+                chain = FallbackProvider([cli, api])
+                if structured:
+                    chain.complete_structured("p", SCHEMA)
+                else:
+                    chain.complete("p")
+                self.assertEqual(chain.last_usage, api.last_usage)
+
+    def test_usage_and_model_reset_when_provider_changes_or_all_fail(self) -> None:
+        cli = _StubProvider("cli", [LLMError("try API"), "ok", LLMError("failed")])
+        api = _StubProvider("api", ["ok", LLMError("failed")])
+        api.last_usage = LLMUsage(1000, 900, None, 100, 0.5)
+        chain = FallbackProvider([cli, api])
+        chain.complete("p")
+        self.assertIsNotNone(chain.last_usage)
+        chain.complete("p")
+        self.assertIsNone(chain.last_usage)
+        self.assertEqual(chain.model_name, "cli")
+
+        with self.assertRaises(LLMError):
+            chain.complete("p")
+        self.assertIsNone(chain.last_usage)
+        self.assertEqual(chain.model_name, "")
+
     def test_first_success_wins(self) -> None:
         first, second = _StubProvider("a", ["from a"]), _StubProvider("b", ["from b"])
         chain = FallbackProvider([first, second])
-        self.assertEqual(chain.complete("p"), "from a")
+        with self.assertLogs("utils.llm.fallback", level="DEBUG") as logs:
+            self.assertEqual(chain.complete("p"), "from a")
+        self.assertTrue(any("LLM attempt: provider=_StubProvider operation=complete" in line for line in logs.output))
+        self.assertFalse(any("model=" in line for line in logs.output))
         self.assertEqual(second.calls, 0)
         self.assertEqual(chain.model_name, "a")
 

tests/test_llm_report.py

@@ -469,11 +469,30 @@ def test_metadata_header(self) -> None:
         )
         self.assertIn("- **Chain:** Mainnet (chain id 1)", report)
         self.assertIn("- **Risk:** HIGH", report)
+        self.assertNotIn("**Model:**", report)
+        self.assertNotIn("**Time:**", report)
 
     def test_contract_unlinked_without_label_address(self) -> None:
         report = build_report("Summary.", "Analysis.", _add_farms_ctx())
         self.assertIn("- **Contract:** Infinifi Shorttimelock\n", report)
 
+    def test_model_metadata_is_plain_text(self) -> None:
+        report = build_report(
+            "Summary.",
+            "Analysis.",
+            _add_farms_ctx(),
+            model_names=("model_[link](https://example.com)<b>*`\\\n- injected",),
+        )
+        self.assertIn(
+            r"- **Model:** model\_\[link\](https://example.com)&lt;b&gt;\*\`\\ - injected",
+            report,
+        )
+        self.assertNotIn("\n- injected", report)
+
+    def test_zero_generation_time_is_shown(self) -> None:
+        report = build_report("Summary.", "Analysis.", _add_farms_ctx(), elapsed_s=0)
+        self.assertIn("- **Time:** 0.0s", report)
+
     def test_contract_unlinked_on_chain_without_explorer(self) -> None:
         ctx = _add_farms_ctx(chain_id=999999, label_address=TIMELOCK)
         self.assertIn("- **Contract:** Infinifi Shorttimelock\n", build_report("S.", "A.", ctx))