textmachine/backend/internal/store/requestlog.go

package store

import (
	"context"
	"database/sql"
	"log/slog"

	"textmachine/backend/internal/obs"
)

// RequestLog is one telemetry row (Р7: route, tokens with cache fields, $,
// latency per book/chapter/chunk/stage/role/model). Telemetry is strictly off
// the money path: money lives in spend/checkpoints, and a telemetry-write failure
// is logged and never fails the translation.
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
	// ReasoningInCompletion is the subset of CompletionTokens the provider reported as thinking
	// (llm.Usage.ReasoningInCompletion). nil writes NULL — «the provider reported no such field»,
	// which the column keeps distinct from a measured 0.
	ReasoningInCompletion *int
	CostUSD               float64
	LatencyMS             int
	FinishReason          string
	TMHit                 bool // served from a checkpoint, no call was made
	Degraded              string
	Err                   string
	OK                    bool
	// Estimated marks a row whose CostUSD is a RESERVATION ESTIMATE, not a provider-reported cost (a billed
	// decode failure, or a paid 2xx with zero usage — pack-13 point-9 / research/21 §1.10). DISPLAY-ONLY: it
	// never re-derives money (CostUSD is untouched); it makes the estimated share of spend queryable so an
	// estimate row is not mistaken for a real zero-token call in token-based COGS analytics.
	Estimated bool
	// EstTokens is the DISPLAY-ONLY fertility estimate of the row's output tokens (est_out = 1.20·cjk +
	// 0.39·other over the SOURCE, research/20 — NOT the char/4 EstimateTokens, whose CJK undercount is the
	// «CJK-mine» pack-13 point-9 warns of). Set only on an Estimated row (0 otherwise); it feeds NOTHING on
	// the money path (not the reservation, not CostUSD) — purely a report number so an estimate's magnitude
	// is legible.
	EstTokens int
}

// 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, reasoning_in_completion,
			cost_usd, latency_ms, finish_reason, tm_hit, degraded, err, ok, estimated, est_tokens
		) 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.ReasoningInCompletion,
		rl.CostUSD, rl.LatencyMS, rl.FinishReason, rl.TMHit, rl.Degraded, rl.Err, rl.OK, rl.Estimated, rl.EstTokens)
	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; the golden
// determinism guard reads Chapter/ChunkIdx/RequestHash/Degraded to pin every call's
// request_hash byte-for-byte).
type RequestLogView struct {
	TS                  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
	// ReasoningInCompletion is nil when the row has no answer: a provider that reports no such
	// field, or a row written before the column existed. A measured 0 is a 0.
	ReasoningInCompletion *int
	CostUSD               float64
	LatencyMS             int
	FinishReason          string
	TMHit                 int
	Degraded              string
	Err                   string
	OK                    int
	Estimated             int // 1 = CostUSD is a reservation estimate, not provider-reported (pack-13 point-9)
	EstTokens             int // display-only fertility output-token estimate (pack-13 point-9); 0 unless Estimated
}

// RequestLogRows returns all request_log rows for a book (tmctl report / Phase 0
// acceptance). Materialization under the op timeout and rows.Err() are queryAll's
// guarantees ("context canceled" mid-read / a silently truncated table — acceptance findings).
func (s *Store) RequestLogRows(bookID string) ([]RequestLogView, error) {
	return queryAll(s.r, `
		SELECT ts, chapter, chunk_idx, stage, role, model_requested, model_actual,
		       request_hash, prompt_tokens, cached_tokens,
		       cache_creation_tokens, completion_tokens, reasoning_tokens, reasoning_in_completion,
		       cost_usd, latency_ms, finish_reason, tm_hit, degraded, err, ok, estimated, est_tokens
		FROM request_log WHERE book_id = ? ORDER BY id`,
		func(rows *sql.Rows) (RequestLogView, error) {
			var v RequestLogView
			var ric sql.NullInt64
			err := rows.Scan(&v.TS, &v.Chapter, &v.ChunkIdx, &v.Stage, &v.Role,
				&v.ModelRequested, &v.ModelActual, &v.RequestHash,
				&v.PromptTokens, &v.CachedTokens, &v.CacheCreationTokens,
				&v.CompletionTokens, &v.ReasoningTokens, &ric, &v.CostUSD,
				&v.LatencyMS, &v.FinishReason, &v.TMHit, &v.Degraded, &v.Err, &v.OK, &v.Estimated, &v.EstTokens)
			if ric.Valid {
				n := int(ric.Int64)
				v.ReasoningInCompletion = &n
			}
			return v, err
		}, bookID)
}