From 56c2f5a61c356d51527f1c0ba661dd7c86858d99 Mon Sep 17 00:00:00 2001
From: "Claude (backend session)" <noreply@anthropic.com>
Date: Sat, 4 Jul 2026 16:56:21 +0300
Subject: [PATCH] Fix tmctl report: materialize request_log rows so they
 outlive the query context that defer-cancel tore down mid-iteration

---
 backend/cmd/tmctl/main.go            | 16 +++-------
 backend/internal/store/requestlog.go | 45 +++++++++++++++++++++++++---
 backend/internal/store/store_test.go | 27 +++++++++++++++++
 docs/PROGRESS.md                     | 29 ++++++++++++++++++
 4 files changed, 101 insertions(+), 16 deletions(-)

diff --git a/backend/cmd/tmctl/main.go b/backend/cmd/tmctl/main.go
index 09f0f9c..ae3785f 100644
--- a/backend/cmd/tmctl/main.go
+++ b/backend/cmd/tmctl/main.go
@@ -109,22 +109,14 @@ func report(cfgPath string) error {
 	if err != nil {
 		return err
 	}
-	defer rows.Close()
 
 	fmt.Printf("%-20s %-8s %-12s %-22s %8s %8s %8s %8s %8s %10s %8s %-8s %-5s %-3s\n",
 		"ts", "stage", "role", "model", "prompt", "cached", "cwrite", "compl", "reason", "cost_usd", "ms", "finish", "tmhit", "ok")
-	for rows.Next() {
-		var ts, stage, role, model, finish string
-		var prompt, cached, cwrite, compl, reason, latency, tmhit, ok int
-		var cost float64
-		if err := rows.Scan(&ts, &stage, &role, &model, &prompt, &cached, &cwrite, &compl, &reason, &cost, &latency, &finish, &tmhit, &ok); err != nil {
-			return err
-		}
+	for _, row := range rows {
 		fmt.Printf("%-20s %-8s %-12s %-22s %8d %8d %8d %8d %8d %10.6f %8d %-8s %-5d %-3d\n",
-			ts, stage, role, model, prompt, cached, cwrite, compl, reason, cost, latency, finish, tmhit, ok)
-	}
-	if err := rows.Err(); err != nil {
-		return err
+			row.TS, row.Stage, row.Role, row.ModelActual, row.PromptTokens, row.CachedTokens,
+			row.CacheCreationTokens, row.CompletionTokens, row.ReasoningTokens, row.CostUSD,
+			row.LatencyMS, row.FinishReason, row.TMHit, row.OK)
 	}
 
 	committed, reserved, err := r.Store.SpentUSD(r.Book.BookID)
diff --git a/backend/internal/store/requestlog.go b/backend/internal/store/requestlog.go
index 13f5119..3a12dc9 100644
--- a/backend/internal/store/requestlog.go
+++ b/backend/internal/store/requestlog.go
@@ -2,7 +2,6 @@ package store
 
 import (
 	"context"
-	"database/sql"
 	"log/slog"
 
 	"textmachine/backend/internal/obs"
@@ -70,13 +69,51 @@ func (s *Store) LogRequest(ctx context.Context, log *slog.Logger, rl RequestLog)
 	}
 }
 
-// RequestLogRows returns rows for inspection (tmctl report / приёмка Фазы 0).
-func (s *Store) RequestLogRows(bookID string) (*sql.Rows, error) {
+// RequestLogView is one request_log row for inspection (tmctl report).
+type RequestLogView struct {
+	TS                  string
+	Stage               string
+	Role                string
+	ModelActual         string
+	PromptTokens        int
+	CachedTokens        int
+	CacheCreationTokens int
+	CompletionTokens    int
+	ReasoningTokens     int
+	CostUSD             float64
+	LatencyMS           int
+	FinishReason        string
+	TMHit               int
+	OK                  int
+}
+
+// RequestLogRows returns all request_log rows for a book (tmctl report / приёмка
+// Фазы 0). Строки МАТЕРИАЛИЗУЮТСЯ под op-таймаутом и возвращаются срезом —
+// отдавать *sql.Rows нельзя: ленивая итерация у вызывающего переживает
+// `defer cancel()` этого метода, и контекст отменяется ПОСРЕДИ чтения
+// («context canceled», обрыв таблицы report — находка реальной приёмки).
+func (s *Store) RequestLogRows(bookID string) ([]RequestLogView, error) {
 	ctx, cancel := opContext()
 	defer cancel()
-	return s.r.QueryContext(ctx, `
+	rows, err := s.r.QueryContext(ctx, `
 		SELECT ts, stage, role, model_actual, prompt_tokens, cached_tokens,
 		       cache_creation_tokens, completion_tokens, reasoning_tokens,
 		       cost_usd, latency_ms, finish_reason, tm_hit, ok
 		FROM request_log WHERE book_id = ? ORDER BY id`, bookID)
+	if err != nil {
+		return nil, err
+	}
+	defer rows.Close()
+	var out []RequestLogView
+	for rows.Next() {
+		var v RequestLogView
+		if err := rows.Scan(&v.TS, &v.Stage, &v.Role, &v.ModelActual,
+			&v.PromptTokens, &v.CachedTokens, &v.CacheCreationTokens,
+			&v.CompletionTokens, &v.ReasoningTokens, &v.CostUSD,
+			&v.LatencyMS, &v.FinishReason, &v.TMHit, &v.OK); err != nil {
+			return nil, err
+		}
+		out = append(out, v)
+	}
+	return out, rows.Err()
 }
diff --git a/backend/internal/store/store_test.go b/backend/internal/store/store_test.go
index ca530b6..7e022ed 100644
--- a/backend/internal/store/store_test.go
+++ b/backend/internal/store/store_test.go
@@ -178,6 +178,33 @@ func TestJobKeepsOriginalSnapshot(t *testing.T) {
 	}
 }
 
+// RequestLogRows обязан вернуть ВСЕ строки, читаемые вызывающим ПОСЛЕ возврата
+// метода: раньше он отдавал *sql.Rows с `defer cancel()`, и контекст отменялся
+// посреди ленивой итерации в tmctl report («context canceled», обрыв таблицы —
+// находка реальной приёмки Фазы 0).
+func TestRequestLogRowsMaterializes(t *testing.T) {
+	s, _ := openTemp(t)
+	for i := 1; i <= 3; i++ {
+		if err := s.InsertRequestLog(RequestLog{BookID: "book", Stage: "draft", PromptTokens: 10 * i, OK: true}); err != nil {
+			t.Fatal(err)
+		}
+	}
+	// Строка другой книги не должна попасть в выборку.
+	if err := s.InsertRequestLog(RequestLog{BookID: "other", Stage: "draft", OK: true}); err != nil {
+		t.Fatal(err)
+	}
+	rows, err := s.RequestLogRows("book")
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(rows) != 3 {
+		t.Fatalf("want 3 materialized rows, got %d (context canceled mid-iteration?)", len(rows))
+	}
+	if rows[0].PromptTokens != 10 || rows[2].PromptTokens != 30 {
+		t.Fatalf("rows not in id order or wrong data: %+v", rows)
+	}
+}
+
 func TestMigrateIsIdempotent(t *testing.T) {
 	path := filepath.Join(t.TempDir(), "test.db")
 	for i := 0; i < 3; i++ {
diff --git a/docs/PROGRESS.md b/docs/PROGRESS.md
index c30ea9c..de26b89 100644
--- a/docs/PROGRESS.md
+++ b/docs/PROGRESS.md
@@ -152,6 +152,34 @@ per-chunk skip+flag вместо падения; структурный запр
 
 Следующее: Фаза 1 (перевод книги целиком) — чанкер, банк памяти v1, гейты (пороги полигона готовы), режим онгоинга.
 
+### Реальная приёмка на живых ключах — PASS (04.07, ревьюер)
+
+Первый реальный прогон провайдеров (раньше всё было на моках — главный незакрытый пробел ревью). `tmctl translate`
+на `example/book.yaml` (draft=deepseek-v4-flash → edit=glm-5, один чанк 264 симв., потолок $1.00):
+- **Деньги сходятся до цента**: draft $0.000219 (453·0.14+556·0.28/1e6 ✓), edit $0.001277 (672·1.0+189·3.2/1e6 ✓);
+  `committed == Σстадий == $0.001496`, `reserved=0`. Порядок величин совпал с прайсингом DeepSeek/z.ai.
+- **Цена по ответившей**: z.ai вернул `model=glm-5` → edit книжится по цене GLM, НЕ по дешёвому deepseek-якорю
+  (fallback дал бы $0.000147 — в 8.7× меньше); `PriceForResponse` подтверждён на реале.
+- **Usage реальный**, не мок: `prompt/completion_tokens` ненулевые в request_log; GLM латентность штатная (5–8 с,
+  без ×3) → `extra_body thinking:{type:disabled}` фактически применён.
+- **Resume**: второй прогон — обе стадии из чекпоинтов за **$0**, ledger неизменен (нет двойной оплаты).
+- **Пост-ревью правки провалидированы**: F1 (CheckKeys — заводится на 2 ключах), F2 (provider temp/maxtok в
+  snapshot), F5 (fail-loud на включённый гейт), F7 (сноска §3.4) — все на месте; Anthropic вычищен из конфигов,
+  висячих ссылок нет (в `BuildClient` ветка `case "anthropic"` осталась, но `kind: anthropic` в models.yaml нет).
+
+**Новая находка реальной приёмки (исправлена):** `tmctl report` рвался с `context canceled` и печатал таблицу
+частично/пусто без строки Ledger (exit 1). Причина — `Store.RequestLogRows` отдавал `*sql.Rows` с `defer cancel()`:
+контекст отменялся посреди ленивой итерации у вызывающего. Данные и деньги в БД были корректны — баг только на
+read-пути `report`. Фикс: строки материализуются под таймаутом и возвращаются срезом `[]RequestLogView`;
+регрессионный тест `TestRequestLogRowsMaterializes`. `go test ./... -race` зелёные.
+
+**Не покрыто реальным прогоном (честно):** (а) DeepSeek cache-hit парсинг — resume короткозамыкает вызов, так что
+реального повторного prefix-хита не было; закрыт только unit-тестом `TestDeepSeekCacheFieldsVariant` (форсить
+реальный хит = лишние траты, не гнал); (б) kill-9 посреди реального провайдерского вызова — инвариант
+`committed==SUM(checkpoints)` доказан unit-тестом `kill9_test.go` (настоящий SIGKILL на SQLite), на реале не
+воспроизводил (деньги/один-чанк дисциплина). (в) Anthropic cache_control/usage-сумма — Anthropic из стека убран,
+проверять больше нечего на этом контуре.
+
 ## Полигон
 (секция параллельной сессии — записи добавлять сюда)
 
@@ -175,6 +203,7 @@ per-chunk skip+flag вместо падения; структурный запр
 
 - **llama.cpp `--n-cpu-moe` для 30b-a3b — перемерено, «Расхождение» с research/06 подтверждено**: потолок генерации на GTX 1070 **~13.5 tok/s** (не 25–30). Таблица конфигов в [03](experiments/03-local-stand.md): ollama 10 → llama.cpp `--cpu-moe` 11.2 → `--n-cpu-moe 33` 13.5 (VRAM 2.9→7.8GB, prefill 105→208). Узкое место — пропускная способность CPU-RAM (DDR4/Pascal), не рантайм; llama.cpp честно лучше ollama (+35% ген., ×2–3 prefill), но 30b-a3b на этом железе — только фоновые роли (~2.5 мин/главу). Скрипт: `eval/llama_moe_bench.sh`.
 - **Замер 4 новых dense-моделей** (ваниль qwen3:8b / qwen3.5:9b / +abliterated / ruadapt) — готово, таблица в [03](experiments/03-local-stand.md). Три вывода: (1) **абляция бесплатна** — qwen3.5 vanilla vs abliterated идентичны по скорости и SFW-качеству → 18+-роль можно на abliterated без штрафа; (2) поколение 3.5>3 умеренно (лучше понимание, −25% токенов, −10% скорости); (3) **RuAdapt: токен-выигрыш подтверждён (−40% ru-токенов), но перевод развалился** (羅生門→«дерево с колокольчиками») → редактор ru-стиля, не переводчик (как и предупреждал research/06). Разрыв с API держится у всех. **Побочная находка для бэкенда:** thinking у Qwen3.5+/GLM/Gemini для роли переводчика обязателен к отключению (иначе пустой/обрезанный вывод — ловилось дважды: эксп. 02 и здесь).
+- **Think-режим (проверка гипотезы владельца «reasoning поднимет качество в разы»)** — [03](experiments/03-local-stand.md), раздел «Влияние thinking». Итог: (а) прежняя «пустота» — артефакт тесного контекста (рассуждения не влезали с ответом), не зависание; (б) с ctx 16k think **завершается и реально чинит реалии** (羅生門: «Радзёмон»→«Рашо-мон»; 朱雀 с китайского чтения на японское) — гипотеза частично подтвердилась; (в) но локально нежизнеспособен: 8,6 мин и ~11k токенов рассуждений на 1400 знаков (вебновелла ≈ 200 ч). **Новый пункт бэклога → оркестратору/бэкенду: проверить think-ON vs OFF по КАЧЕСТВУ на быстром облачном черновике/редакторе (DeepSeek/GLM)** — потенциальный дешёвый рычаг качества, раз reasoning вытаскивает реалии.
 
 ### Следующие шаги полигона
 - [x] Прогон refusal-бенчмарка (SFW/L1/L2-violence часть) — 66/66 ok, пороги в 02; explicit-часть ждёт фрагментов владельца.