textmachine/backend/internal/store/requestlog.go

package store

import (
	"context"
	"log/slog"

	"textmachine/backend/internal/obs"
)

// RequestLog is one telemetry row (Р7: маршрут, токены с cache-полями, $,
// latency per книга/глава/чанк/стадия/роль/модель). Telemetry is strictly off
// the money path: деньги живут в spend/checkpoints, а сбой записи телеметрии
// логируется и никогда не роняет перевод.
type RequestLog struct {
	TraceID             string
	BookID              string
	Chapter             int
	ChunkIdx            int
	Stage               string
	Role                string
	ModelRequested      string
	ModelActual         string
	RequestHash         string
	PromptTokens        int
	CachedTokens        int
	CacheCreationTokens int
	CompletionTokens    int
	ReasoningTokens     int
	CostUSD             float64
	LatencyMS           int
	FinishReason        string
	TMHit               bool // served from a checkpoint, no call was made
	Degraded            string
	Err                 string
	OK                  bool
}

// InsertRequestLog writes one telemetry row synchronously (a CLI pipeline has
// no answer-latency to protect, unlike vojo's chat path; the async+recover
// pattern returns if this ever sits on a hot path). Errors are the caller's to
// log as WARN — never to fail the pipeline on.
func (s *Store) InsertRequestLog(rl RequestLog) error {
	ctx, cancel := opContext()
	defer cancel()
	_, err := s.w.ExecContext(ctx, `
		INSERT INTO request_log (
			trace_id, book_id, chapter, chunk_idx, stage, role,
			model_requested, model_actual, request_hash,
			prompt_tokens, cached_tokens, cache_creation_tokens,
			completion_tokens, reasoning_tokens,
			cost_usd, latency_ms, finish_reason, tm_hit, degraded, err, ok
		) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)`,
		rl.TraceID, rl.BookID, rl.Chapter, rl.ChunkIdx, rl.Stage, rl.Role,
		rl.ModelRequested, rl.ModelActual, rl.RequestHash,
		rl.PromptTokens, rl.CachedTokens, rl.CacheCreationTokens,
		rl.CompletionTokens, rl.ReasoningTokens,
		rl.CostUSD, rl.LatencyMS, rl.FinishReason, rl.TMHit, rl.Degraded, rl.Err, rl.OK)
	return err
}

// LogRequest is the fire-and-forget wrapper the runner uses: insert, WARN on
// failure, never propagate.
func (s *Store) LogRequest(ctx context.Context, log *slog.Logger, rl RequestLog) {
	if rl.TraceID == "" {
		rl.TraceID = obs.TraceFromContext(ctx)
	}
	if err := s.InsertRequestLog(rl); err != nil && log != nil {
		log.WarnContext(ctx, "request_log insert failed (non-fatal)", "err", err)
	}
}

// FreshCallLatencyMS sums the wall-clock latency of the book's FRESH provider calls (tm_hit=0
// — a checkpoint replay has no answer latency to count) and their count. It is the throughput
// input for the `tmctl status` ETA (D15.3): mean fresh-call latency × remaining work, a
// throughput estimate, never a synthetic time-bar. Pure read, $0.
func (s *Store) FreshCallLatencyMS(bookID string) (totalMS int64, calls int, err error) {
	ctx, cancel := opContext()
	defer cancel()
	err = s.r.QueryRowContext(ctx,
		`SELECT COALESCE(SUM(latency_ms),0), COUNT(*) FROM request_log WHERE book_id = ? AND tm_hit = 0`,
		bookID).Scan(&totalMS, &calls)
	return
}

// 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()
	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()
}