diff --git a/backend/app/llm.py b/backend/app/llm.py index c58c9c7..2bf33ff 100644 --- 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 diff --git a/backend/app/services/simulator.py b/backend/app/services/simulator.py index 5d842b0..dc284a4 100644 --- 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 diff --git a/backend/tests/test_llm_budgets.py b/backend/tests/test_llm_budgets.py index 4899755..5d848f4 100644 --- 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 diff --git a/backend/tests/test_llm_failure_logging.py b/backend/tests/test_llm_failure_logging.py new file mode 100644 index 0000000..d46a55e --- /dev/null +++ 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 diff --git a/docs/HANDOFF.md b/docs/HANDOFF.md index 6b6e5b3..ee3908a 100644 --- 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//personas//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. diff --git a/docs/engineering-log/2026-10-02-incident4-judge-truncation.md b/docs/engineering-log/2026-10-02-incident4-judge-truncation.md new file mode 100644 index 0000000..4e3860e --- /dev/null +++ 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//personas//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. diff --git a/plan.md b/plan.md index 76e4462..30a6fcd 100644 --- 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.