fix(llm): log raw provider output on JSON failure, raise judge budget to 6000

- complete_json(): log model/max_tokens + raw provider text (1500 cap) when json.loads fails, so a truncated judge reply is diagnosable from the log - complete()/complete_conversation(): log reasoning_content head on empty content (hidden reasoning starves the shared max_tokens cap) - simulator.judge(): max_tokens 2000 -> 6000 (server accepts 8000) - tests: pin judge budget; new test_llm_failure_logging.py pins the logging (autouse fixture restores app.llm logger disabled by alembic fileConfig) 547 passed. Incident #4 (500 char 125).
2026-10-02 22:30:28 +07:00
parent 903602a159
commit 9df2938557
7 changed files with 214 additions and 10 deletions
--- a/backend/app/llm.py
+++ b/backend/app/llm.py
@@ -5,6 +5,7 @@ Mirrors the MiroFish provider-agnostic pattern. Credentials live in .env only.
 from __future__ import annotations

 import json
+import logging
 import re
 import time
 from typing import Any
@@ -18,6 +19,9 @@ class LLMError(Exception):
    pass


+logger = logging.getLogger(__name__)
+
+
 def _strip_thinking_trace(text: str) -> str:
    """Remove ReACT-style chain-of-thought / fences, keep the final JSON text."""
    for fence in ("```json", "```"):
@@ -128,6 +132,17 @@ class LLMClient:
            raise LLMError(f"LLM call failed: {exc}") from exc
        text = (resp.choices[0].message.content or "").strip()
        if not text:
+            # content empty even with budget: the hidden reasoning consumed the
+            # whole max_tokens (it is a shared cap on this llama.cpp endpoint).
+            reasoning = getattr(resp.choices[0].message, "reasoning_content", "") or ""
+            logger.error(
+                "LLM returned empty content (model=%s max_tokens=%d); the hidden "
+                "reasoning (shared cap) likely consumed the whole budget. "
+                "reasoning_content head (first 1500 chars): %s",
+                self.model,
+                max_tokens,
+                reasoning[:1500],
+            )
            raise LLMError("LLM returned empty response")
        return text

@@ -150,7 +165,7 @@ class LLMClient:
        text = _strip_thinking_trace(text)
        try:
            return json.loads(text)
-        except json.JSONDecodeError as exc:
+        except json.JSONDecodeError:
            # Last-ditch: strip leading text before the first { or [
            match = re.search(r"[{\[].*[}\]]", text, re.DOTALL)
            if match:
@@ -158,7 +173,18 @@ class LLMClient:
                    return json.loads(match.group(0))
                except json.JSONDecodeError:
                    pass
-            raise LLMError(f"LLM returned invalid JSON: {exc}") from exc
+            # The raw provider output is the only thing that explains a JSON
+            # failure (truncated mid-string, inline reasoning, code fence) —
+            # log it, capped, so live 500s are debuggable from the server log.
+            snippet = text if len(text) <= 1500 else text[:1500] + "…[truncated]"
+            logger.error(
+                "LLM returned invalid JSON (model=%s max_tokens=%d)\n--- raw output (first %d chars) ---\n%s\n--- end raw output ---",
+                self.model,
+                max_tokens,
+                min(len(text), 1500),
+                snippet,
+            )
+            raise LLMError("LLM returned invalid JSON") from None

    def complete_conversation(
        self,
@@ -196,5 +222,16 @@ class LLMClient:
            raise LLMError(f"LLM call failed: {exc}") from exc
        text = (resp.choices[0].message.content or "").strip()
        if not text:
+            # content empty even with budget: the hidden reasoning consumed the
+            # whole max_tokens (it is a shared cap on this llama.cpp endpoint).
+            reasoning = getattr(resp.choices[0].message, "reasoning_content", "") or ""
+            logger.error(
+                "LLM returned empty content (model=%s max_tokens=%d); the hidden "
+                "reasoning (shared cap) likely consumed the whole budget. "
+                "reasoning_content head (first 1500 chars): %s",
+                self.model,
+                max_tokens,
+                reasoning[:1500],
+            )
            raise LLMError("LLM returned empty response")
        return text
--- a/backend/app/services/simulator.py
+++ b/backend/app/services/simulator.py
@@ -352,8 +352,13 @@ class Simulator:
                state_note = ""
        user_prompt = f"PERSONA:\n{persona_summary}\n\nTRANSCRIPT:\n{transcript}{state_note}"
        try:
+            # 6000 (was 2000): the hidden reasoning counts against the SAME
+            # max_tokens cap (llama.cpp), so a long internal chain leaves little
+            # headroom for the pretty-printed 7-field judge JSON — the live 500
+            # truncated it mid-string at ~char 125 (Unterminated string). 6000
+            # leaves headroom for a long reasoning pass.
            result = self.judge_llm.complete_json(
-                JUDGE_SYSTEM, user_prompt, temperature=0.2, max_tokens=2000
+                JUDGE_SYSTEM, user_prompt, temperature=0.2, max_tokens=6000
            )
        except LLMError as exc:
            raise
--- a/backend/tests/test_llm_budgets.py
+++ b/backend/tests/test_llm_budgets.py
@@ -57,3 +57,16 @@ def test_judge_budget_covers_hidden_reasoning():
        internal={"turns": 1, "misses": 0, "score": 50},
    )
    assert stub.json_kwargs[0]["max_tokens"] >= 1600
+
+
+def test_final_judge_budget_covers_hidden_reasoning():
+    # The FINAL judge (end-of-session verdict) is the fatal path — a truncation
+    # there 500s the whole chat send (the 2026-10-02 live incident: JSON cut off
+    # mid-string at char ~125 because the hidden reasoning consumed the 2000 cap).
+    # 6000 leaves headroom for a long internal chain + the 7-field JSON.
+    stub = _CapturingLLM("")
+    Simulator(stub).judge(
+        persona={"name": "n", "tier": "B", "budget": "b"},
+        messages=[{"role": "seller", "text": "สวัสดี"}, {"role": "customer", "text": "ตกลง"}],
+    )
+    assert stub.json_kwargs[0]["max_tokens"] >= 6000
--- a/backend/tests/test_llm_failure_logging.py
+++ b/backend/tests/test_llm_failure_logging.py
@@ -0,0 +1,83 @@
+"""Failure-path logging: when the LLM returns junk (truncated JSON, empty
+content), the server log must show WHAT the LLM sent — the raw output and/or
+the hidden reasoning head — so live 500s are debuggable from the log alone
+(2026-10-02 incident: 'Unterminated string char 125' with zero raw output in
+the log).
+
+Bypass __init__ (no network / no OpenAI client) and stub _create.
+"""
+from __future__ import annotations
+
+import logging
+
+import pytest
+
+from app.llm import LLMClient, LLMError
+
+
+@pytest.fixture(autouse=True)
+def _logging_capture_restored():
+    # alembic's env.py (run by test_db_schema) does fileConfig(alembic.ini) with
+    # disable_existing_loggers=True — that disables `app.llm`'s logger (and the
+    # root) for the rest of the session, so caplog captures nothing. Restore.
+    def _restore():
+        logging.getLogger("app.llm").disabled = False
+        logging.getLogger().disabled = False
+
+    _restore()
+    yield
+    _restore()
+
+
+def _client_with_content(content: str, reasoning: str = "") -> LLMClient:
+    client = LLMClient.__new__(LLMClient)
+    client.model = "test-model"
+
+    class _Msg:
+        pass
+
+    class _Choice:
+        message = _Msg()
+
+    class _Resp:
+        choices = [_Choice()]
+
+    resp = _Resp()
+    resp.choices[0].message.content = content
+    resp.choices[0].message.reasoning_content = reasoning
+    client._create = lambda **kw: resp
+    return client
+
+
+def test_invalid_json_logs_raw_output(caplog):
+    raw = '{\n  "outcome": "lo'  # truncated mid-string, as in the live incident
+    client = _client_with_content(raw)
+    with caplog.at_level("ERROR"):
+        with pytest.raises(LLMError) as exc:
+            client.complete_json("sys", "user")
+    assert "invalid JSON" in str(exc.value)
+    # The raw output must be visible in the log, capped and delimited.
+    assert "raw output" in caplog.text
+    assert '"outcome": "lo' in caplog.text
+
+
+def test_empty_content_logs_reasoning_head(caplog):
+    client = _client_with_content(
+        "", reasoning="hidden chain-of-thought that consumed the budget"
+    )
+    with caplog.at_level("ERROR"):
+        with pytest.raises(LLMError):
+            client.complete("sys", "user", max_tokens=2000)
+    assert "empty content" in caplog.text
+    assert "hidden chain-of-thought that consumed the budget" in caplog.text
+
+
+def test_empty_conversation_logs_reasoning_head(caplog):
+    client = _client_with_content(
+        "", reasoning="reasoning that ate the whole cap"
+    )
+    with caplog.at_level("ERROR"):
+        with pytest.raises(LLMError):
+            client.complete_conversation([{"role": "seller", "text": "hi"}])
+    assert "empty content" in caplog.text
+    assert "reasoning that ate the whole cap" in caplog.text
--- a/docs/HANDOFF.md
+++ b/docs/HANDOFF.md
@@ -242,6 +242,16 @@ cd backend && uv run python run.py        # Flask :5001
 - `docs/engineering-log/2026-08-15-s4-3-offline-dialect-remediation.md` — offline Alembic dialect finding, test-first fix, verification, and pending review.
 - `docs/engineering-log/2026-08-16-s4-4-importer-errorhandler-commit.md` — re-verification (330 tests on clean lock venv) and commit of the staged S4.4 importer + error-handler hardening increment.

+## 2026-10-02 live 500 #4 — judge JSON truncated (char 125) → raw-output logging + judge budget
+- Symptom: `POST /api/chat/<group>/personas/<persona>/chat/send` → 500 `LLM returned invalid JSON: Unterminated string starting at: line 5 column 10 (char 125)`.
+- Root cause: llama.cpp `enable_thinking: true` puts internal chain in `reasoning_content` (separate field), but reasoning tokens STILL count against the shared `max_tokens`. Judge had 2000; a long chain left <200 for the pretty-printed 7-field judge JSON → truncated mid-string at char 125 → `json.loads` failed → `LLMError` → 500 (judge is fail-closed by design — a fabricated win would close the session wrongly). The old log line carried only the `JSONDecodeError` text — zero raw provider output — so the 500 was undiagnosable from the log.
+- Fix: `backend/app/llm.py` module `logger` — `complete_json()` logs model + max_tokens + raw provider text (capped 1500 chars) on parse failure; `complete()`/`complete_conversation()` log `reasoning_content` head (1500 chars, via `getattr`) on empty content. `simulator.py` `judge()` max_tokens 2000→6000 (server probe 2026-10-02: accepts 8000).
+- Tests: `test_llm_budgets.py` pins judge ≥6000; new `tests/test_llm_failure_logging.py` (3 tests) pins the logging. **547 passed.**
+- Gotcha: `test_db_schema.py` runs alembic → `env.py` `fileConfig(alembic.ini)` → `disable_existing_loggers=True` disables `app.llm`'s logger for the rest of the session → caplog captured nothing. Fix: autouse `_logging_capture_restored` re-enables `app.llm` + root logger around each test.
+- Review: independent diagnosis reviewer REJECT (duplicate `import logging` at line 77; `complete()` empty branch missing the `reasoning_content` head) — both fixed, re-verified, 547 passed.
+- Evidence: `docs/engineering-log/2026-10-02-incident4-judge-truncation.md`.
+- Status: **committed locally**, awaiting owner push approval (CON-003) → EasyPanel auto-deploy.
+
 ## 2026-10-02 live 500 #3 — hidden reasoning written INLINE into content
 - Symptom: `LLM returned invalid JSON: Unterminated string (char 143)` — the budget fix (c5553eb) was whack-a-mole; bigger budget only moves empty→truncated JSON.
 - Root cause (live probes): llama.cpp endpoint writes the model's hidden reasoning INLINE into `content` UNLESS `enable_thinking: true` is sent (which moves it to `reasoning_content`). The app was sending the field absent (`extra_body=None`). Same root cause as the earlier persona-generation failures.
--- a/docs/engineering-log/2026-10-02-incident4-judge-truncation.md
+++ b/docs/engineering-log/2026-10-02-incident4-judge-truncation.md
@@ -0,0 +1,55 @@
+# Incident #4 — 500 judge JSON truncated (char 125) → raw-output logging + judge budget
+
+**Date:** 2026-10-02
+**Trigger:** POST /api/chat/<group>/personas/<persona>/chat/send → 500, server log:
+`LLM returned invalid JSON: Unterminated string starting at: line 5 column 10 (char 125)`
+
+## Root cause
+llama.cpp `enable_thinking=true` puts the internal chain in `reasoning_content`
+(separate field — NOT inline), but reasoning tokens **still count against the same
+`max_tokens` cap**. Judge had `max_tokens=2000`; a long internal chain left <200
+tokens for the pretty-printed 7-field judge JSON → truncated mid-string at char 125
+→ `json.loads` failed → `LLMError` → 500 (judge has no fallback by design: a
+fabricated win would close the session incorrectly).
+
+The old log line carried the `json.JSONDecodeError` message only — **zero raw
+provider output** — so the live 500 was undiagnosable from the log.
+
+## Fix
+1. **`backend/app/llm.py`** — module `logger`.
+   - `complete_json()`: on parse failure → `logger.error` with model, max_tokens,
+     and the RAW provider text (capped 1500 chars) between `--- raw output ---`
+     markers, then `LLMError("LLM returned invalid JSON")`.
+   - `complete()` / `complete_conversation()`: on empty content → `logger.error`
+     with model, max_tokens, and the `reasoning_content` head (first 1500 chars,
+     via `getattr` — it's an extra field on the OpenAI SDK).
+2. **`backend/app/services/simulator.py`** — `judge()` `max_tokens` 2000 → 6000
+   (server probe 2026-10-02: accepts 8000; 6000 leaves headroom for a long
+   reasoning pass + the 7-field JSON).
+3. **Tests**
+   - `tests/test_llm_budgets.py` — `test_final_judge_budget_covers_hidden_reasoning`
+     pins judge `max_tokens >= 6000`.
+   - `tests/test_llm_failure_logging.py` (new) — 3 tests pin the logging behavior:
+     raw output visible on invalid JSON; reasoning head visible on empty content
+     (both `complete` and `complete_conversation`).
+     - Gotcha: `test_db_schema.py` runs alembic, whose `env.py` calls
+       `fileConfig(alembic.ini)` → `disable_existing_loggers=True` **disables
+       `app.llm`'s logger for the rest of the session**, so caplog captured nothing.
+       Fix: autouse `_logging_capture_restored` fixture re-enables `app.llm` and
+       the root logger around each test.
+
+## Review
+Independent diagnosis reviewer: initial REJECT (duplicate `import logging` at
+line 77; `complete()` empty branch missing the `reasoning_content` head). Both
+fixed and verified; 547 passed.
+
+## Verification
+- `backend/.venv/bin/python -m pytest -q` → **547 passed**.
+- `ast.parse` clean on `llm.py`.
+- Server probe: `max_tokens=8000` accepted (2026-10-02).
+
+## Notes
+- No catch added to `sim.judge()` — fail-closed is by design (pinned by
+  `test_final_judge.py`); the fix is budget + observability.
+- `import logging` at `llm.py:8` (module) is the logger; the `import logging`
+  inside `_create` is pre-existing (per-method local) and left as-is.
--- a/plan.md
+++ b/plan.md
@@ -1,19 +1,16 @@
 # Sales Trainer — Current Execution Plan

 ## Status
-Fixed and deployed (`0f34af7`, 2026-10-02). `llm.py` now always sends `enable_thinking: true` so hidden reasoning goes to `reasoning_content` (not inline in content). 543 passed; independent reviewer PASS; live-verified next chat send.
+Incident #4 fix committed locally (`2026-10-02`): raw-output logging in `llm.py` (invalid JSON → raw provider text capped 1500 chars; empty content → `reasoning_content` head), judge `max_tokens` 2000→6000, 4 regression tests. 547 passed; independent reviewer REJECT (2 items) resolved and re-verified. Awaiting owner push approval.

 ## Current phase / active task
-None in scope. Live incident #3 fixed, pushed, auto-deployed. Verify on next live chat send that `POST /api/chat/.../send` returns 200 and the judge returns a real outcome (not the 500 from before).
+Incident #4: fix implemented + reviewed + committed locally. Awaiting owner push approval → EasyPanel auto-deploy (~3 min) → live verify.

 ## Last update
-2026-10-02. Live incident #3 fix implemented, reviewed (PASS), committed `0f34af7`, pushed, EasyPanel auto-deploy in progress.
+2026-10-02. Incident #4 (500 judge JSON truncated, char 125): raw-output logging in llm.py + judge budget 2000→6000 + 4 regression tests. 547 passed. Committed locally, awaiting owner push approval.

 ## Next action
-Live verify: next chat send → 200 + clean persona reply + real judge outcome. If the 500 returns, the new log line (`helpers` internal_error now records the full exc) will name the next cause.
-
-## Blockers
-None known. Do not commit, push, or deploy. Do not access `.env` or production data.
+Owner approves push → EasyPanel auto-deploy (~3 min) → live verify: next chat send → 200 + clean judge outcome. If a JSON 500 returns, the new log line carries the raw provider output (capped 1500 chars) and the model/max_tokens context.

 ## Task breakdown
 - [x] TASK-001 — Trace follow-up/session state machine, progress/polling, one-shot lifecycle, timeout chain, and historic error path. Covers REQ-001–REQ-007; exact historic error remains unverified because local logs/reproduction are unavailable.
@@ -23,6 +20,10 @@ None known. Do not commit, push, or deploy. Do not access `.env` or production d
 - [x] TASK-005 — Increase LLM timeout to 180s, retain finite 30-minute async polling, investigate error from code evidence. Covers REQ-006–REQ-007, AC-003/AC-005.
 - [x] TASK-006 — Full backend/frontend checks and security scan passed; independent reviewer verdict received and verified. Single REJECT finding (gone session reopenable after judge failure) confirmed **stale** — reviewer read a pre-fix `chat_routes.py` snapshot; current tree has the `followup_phase == "gone"` retry branch (chat_routes.py:888) plus both regression tests, which pass. Full suite re-run green post-review (532). No other confirmed blocker. Covers AC-001–AC-005.
 - [x] TASK-007 — Engineering log, handoff, test evidence, and this plan updated with the reviewer verdict. Covers AC-004/AC-005.
+- [x] TASK-008 — Incident #4 (2026-10-02): log raw LLM output on JSON parse failure + reasoning head on empty content (llm.py); judge `max_tokens` 2000→6000 (simulator.py); 4 regression tests (test_llm_budgets.py + new test_llm_failure_logging.py). 547 passed.
+
+## Blockers
+None known. Do not push/deploy without owner approval. Do not access `.env` or production data.

 ## Dependencies
 TASK-002–TASK-005 depend on TASK-001. TASK-006 depends on all implementation tasks; TASK-007 depends on verification results.