diff --git a/backend/app/llm.py b/backend/app/llm.py index 348c45c..c58c9c7 100644 --- a/backend/app/llm.py +++ b/backend/app/llm.py @@ -106,11 +106,13 @@ class LLMClient: max_tokens: int = 3000, thinking: bool = True, ) -> str: - extra_body = None - if not thinking: - # Qwen3-style thinking models: disable chain-of-thought to cut latency - # (measured 313s -> 44s per persona on the local tabbyAPI server). - extra_body = {"enable_thinking": False} + # Always keep reasoning SEPARATE (llama.cpp: enable_thinking=true puts it in + # reasoning_content, content stays clean). Omitting the field or false makes + # the model write the chain inline into content — which corrupts JSON + # responses ("Unterminated string" live 500) and persona parsing. The + # `thinking` param is retained for API compatibility; on this provider the + # mode is always "separated". + extra_body = {"enable_thinking": True} try: resp = self._create( model=self.model, @@ -181,12 +183,14 @@ class LLMClient: mapped = "user" api_messages.append({"role": mapped, "content": m.get("text") or m.get("content") or ""}) try: + # enable_thinking=true keeps the model's reasoning in reasoning_content + # so the reply text stays clean (see complete()). resp = self._create( model=self.model, temperature=temperature, max_tokens=max_tokens, messages=api_messages, - extra_body=None, + extra_body={"enable_thinking": True}, ) except Exception as exc: raise LLMError(f"LLM call failed: {exc}") from exc diff --git a/backend/app/services/persona_generator.py b/backend/app/services/persona_generator.py index 9b061e3..231c252 100644 --- a/backend/app/services/persona_generator.py +++ b/backend/app/services/persona_generator.py @@ -1,6 +1,6 @@ """Persona generator: builds 15 personas (5 per tier) from a Sales Kit + scenario. -Generation is split into ONE persona per LLM call (thinking disabled) so each call +Generation is split into ONE persona per LLM call (reasoning kept separate) so each call finishes well under the Cloudflare 120s proxy timeout that kills the single 15-persona call. The 15 calls run in a small thread pool (the local LLM tolerates a few concurrent requests) to cut total wall-clock time. diff --git a/backend/app/services/simulator.py b/backend/app/services/simulator.py index 1d30a7a..5d842b0 100644 --- a/backend/app/services/simulator.py +++ b/backend/app/services/simulator.py @@ -248,9 +248,9 @@ class Simulator: "role": "system", "content": "Contract correction: output one JSON object with a non-empty string field named reply. Do not include analysis or extra prose.", }) - # NOTE: the Qwen GGUF reasons internally before answering (the llama.cpp - # endpoint ignores enable_thinking), so the hidden reasoning consumes part - # of the budget — 400 starved it (content=''). 1200 fits reasoning + reply. + # NOTE: the Qwen GGUF reasons internally before answering. We keep that + # reasoning in a separate field (enable_thinking=true), so content stays + # clean — 400 starved the reply (content=''). 1200 fits reply headroom. resp = self.llm.complete_conversation(msgs, temperature=0.7, max_tokens=1200) parsed = self._parse_persona_reply(resp) if parsed is not None: diff --git a/backend/tests/test_llm_budgets.py b/backend/tests/test_llm_budgets.py index f625638..4899755 100644 --- a/backend/tests/test_llm_budgets.py +++ b/backend/tests/test_llm_budgets.py @@ -1,8 +1,8 @@ -"""Budget guard: the Qwen GGUF reasons internally (hidden thinking) before the -visible answer, and llama.cpp's endpoint ignores enable_thinking — so the hidden -reasoning consumes part of the token budget. If a budget is too small, the call -returns HTTP 200 with content='' → LLMError → "LLM service unavailable" (the 2026-10-02 -live incident: persona_reply at 400 tokens, judge JSON at 800). +"""Budget guard: the Qwen GGUF reasons internally (hidden thinking, kept in a +separate field via enable_thinking=true) before the visible answer. If a budget is +too small, the reply has no headroom and the call can return content='' → LLMError +→ "LLM service unavailable" (2026-10-02 live incident: persona_reply at 400 tokens, +judge JSON at 800). These tests pin the budgets so an "optimization" back to the small values fails loudly instead of silently re-breaking chat. diff --git a/backend/tests/test_llm_enable_thinking.py b/backend/tests/test_llm_enable_thinking.py new file mode 100644 index 0000000..ec3fdd3 --- /dev/null +++ b/backend/tests/test_llm_enable_thinking.py @@ -0,0 +1,66 @@ +"""The llama.cpp endpoint writes the model's hidden reasoning INLINE into +`content` UNLESS `enable_thinking` is sent as `true` — which relocates it to the +separate `reasoning_content` field and keeps `content` clean. + +Omitting the field (or sending false) corrupts every JSON response with inline +thinking: the live 2026-10-02 500 was `LLM returned invalid JSON: +Unterminated string` and persona generation was failing for the same reason. + +These tests pin the flag so a future edit that drops it fails loudly. +""" +from __future__ import annotations + +import app.llm as llm_mod +from app.llm import LLMClient + + +def _make_client() -> LLMClient: + c = LLMClient(base_url="http://localhost:9/v1", api_key="test-key", model="m") + c.max_attempts = 1 + c.retry_delay = 0.0 + return c + + +def _resp(content: str = '{"ok": 1}'): + message = type("M", (), {"content": content})() + choice = type("C", (), {"message": message})() + return type("R", (), {"choices": [choice]})() + + +def test_complete_always_sends_enable_thinking_true(monkeypatch): + c = _make_client() + seen: dict = {} + + def spy(**kwargs): + seen["extra_body"] = kwargs.get("extra_body") + return _resp() + + c.client.chat.completions.create = spy + c.complete("sys", "user") + assert seen["extra_body"] == {"enable_thinking": True} + + +def test_complete_json_always_sends_enable_thinking_true(monkeypatch): + c = _make_client() + seen: dict = {} + + def spy(**kwargs): + seen["extra_body"] = kwargs.get("extra_body") + return _resp('{"mood": 1}') + + c.client.chat.completions.create = spy + c.complete_json("sys", "user") + assert seen["extra_body"] == {"enable_thinking": True} + + +def test_complete_conversation_always_sends_enable_thinking_true(monkeypatch): + c = _make_client() + seen: dict = {} + + def spy(**kwargs): + seen["extra_body"] = kwargs.get("extra_body") + return _resp("สวัสดีค่ะ") + + c.client.chat.completions.create = spy + c.complete_conversation([{"role": "seller", "text": "hi"}]) + assert seen["extra_body"] == {"enable_thinking": True} diff --git a/docs/HANDOFF.md b/docs/HANDOFF.md index 6b70397..6b6e5b3 100644 --- a/docs/HANDOFF.md +++ b/docs/HANDOFF.md @@ -242,6 +242,13 @@ 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 #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. +- Fix: `llm.py` always sends `enable_thinking: true` on all three call paths (`complete`/`complete_json`/`complete_conversation`). `tests/test_llm_enable_thinking.py` pins it. **543 passed.** +- Server-side `--reasoning-format none` = speed only now (latency), correctness already fixed. +- Evidence: `docs/engineering-log/2026-10-02-enable-thinking-inline-root-cause.md`. + ## 2026-10-02 live "LLM service unavailable" — root cause + fix in review - Symptom: live chat 500 `LLM service unavailable` while llama.cpp log shows the model generating (two 400-token tasks = the two `persona_reply` attempts, all hidden reasoning). - Root cause (live probes): Qwen3.8-27B GGUF reasons internally; llama.cpp ignores `enable_thinking` → hidden reasoning eats `max_tokens` → HTTP 200 `content=''` → `LLMError`. `persona_reply` (400) crashed the 500; `evaluate_turn` judge (800) silently degraded to `pending` (buying customers never closed the session). diff --git a/docs/engineering-log/2026-10-02-enable-thinking-inline-root-cause.md b/docs/engineering-log/2026-10-02-enable-thinking-inline-root-cause.md new file mode 100644 index 0000000..8baf3e1 --- /dev/null +++ b/docs/engineering-log/2026-10-02-enable-thinking-inline-root-cause.md @@ -0,0 +1,37 @@ +# 2026-10-02 — 500 "invalid JSON: Unterminated string": hidden reasoning inline in content + +## Symptom +After the budget fix (c5553eb): live `POST /api/chat/.../send` → 500 +`LLM returned invalid JSON: Unterminated string starting at: line 5 column 10 (char 143)`. +The budget-raise was whack-a-mole: bigger budget just moves the failure from +`content=''` to `truncated JSON`. + +## Diagnosis (live probes vs pchome.moreminimore.com/v1, model mia-qwen38-3.0bpw) +The llama.cpp endpoint has a hidden-thinking field, and the app must tell it to use it: + +| `enable_thinking` sent | content | reasoning location | +|---|---|---| +| **absent** (what app sent: `extra_body=None`) | `17×24=...408 {"result":408}` | **inline in content** (+ reasoning_content field) | +| `false` | inline in content | inline | +| `true` | `{"result":408}` — clean | `reasoning_content` field | + +Consequences of the inline form (what the app had been living with): +- `complete_json` last-ditch regex grabs a corrupted span → `Unterminated string` → 500 (this incident) +- `persona_generator` (persona JSON) → persona generation fails (the "สร้าง persona ไม่ได้" incident, same root cause) +- persona reply (chat) → reply text bloated with reasoning chain (the 21562-byte 200) + +## Fix (this commit) +`llm.py`: `complete()`, `complete_json()` (via complete), and `complete_conversation()` +**always send `extra_body={"enable_thinking": True}`** — relocates hidden reasoning into +`reasoning_content`, `content` stays clean. The `thinking` param is retained for API +compatibility but is a no-op on this provider (always separated). +`tests/test_llm_enable_thinking.py` pins the flag on all three call paths. + +## Why not just a bigger budget +Budget raises only delay the corruption (empty → truncated → eventually clean); the +inline reasoning format is the actual bug. Separation fixes the judge 500, persona +JSON, and persona reply text at once. + +## Server-side (speed, optional — owner) +`--reasoning-format none` (or no-think template) still removes the reasoning compute +entirely → latency goes back to ~5s. Not required for correctness. diff --git a/plan.md b/plan.md index fb9fd6a..01c1e23 100644 --- a/plan.md +++ b/plan.md @@ -1,16 +1,16 @@ # Sales Trainer — Current Execution Plan ## Status -Complete. Implementation, local verification, and independent review are all closed. No commit, push, deploy, or live-provider testing. +Live-incident fix in independent review. `llm.py` now always sends `enable_thinking: true` so hidden reasoning goes to `reasoning_content` (not inline in content, which was corrupting JSON → 500 + persona failures). 543 passed locally; reviewer verdict pending. ## Current phase / active task -Complete. All implementation, local verification, and independent review closed. Awaiting owner approval for commit/push/deploy (CON-003). +Live-incident #3 (after budget fix c5553eb) — `LLM returned invalid JSON: Unterminated string (char 143)`. Root cause: llama.cpp writes hidden reasoning inline into `content` unless `enable_thinking: true` is sent. Fix: always send the flag on all three call paths. Independent review in progress. ## Last update -2026-10-02. Project requirements reconciled from the latest owner instruction in `project.md`. Legacy architecture and security context reviewed in `docs/plan.md`, `docs/HANDOFF.md`, and `docs/engineering-log/2026-08-24-training-security-review.md`. +2026-10-02. Live incident #3 fix implemented (enable_thinking), 543 tests green, docs updated, independent reviewer dispatched (deleg_a60a1a2e). ## Next action -None in scope. Awaiting owner approval for commit/push/deploy (CON-003). No further implementation work. +Await independent reviewer verdict → commit + push (owner approval per CON-003) → EasyPanel auto-deploy → live verify chat send returns 200 and judge returns real outcomes. ## Blockers None known. Do not commit, push, or deploy. Do not access `.env` or production data.