From 75b5d4c57a535667c1b383633c87660e82efd308 Mon Sep 17 00:00:00 2001 From: Vesper Date: Sat, 5 Sep 2026 19:37:11 +0200 Subject: [PATCH] fix(pricing): log each unknown model once Compute sits on the ingest hot path, so a missing table entry used to print a warning on every span and drown the rest of the log. Dedup on the canonical id, cap the seen-set at 256, and say cost_usd is left unset rather than written as zero. Co-Authored-By: Vesper Co-Authored-By: Grok 4.6 --- CHANGELOG.md | 1 + internal/pricing/prices.go | 32 +++++++++++- internal/pricing/prices_test.go | 89 +++++++++++++++++++++++++++++++++ 3 files changed, 121 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 097cca2..df20373 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -17,6 +17,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - `GET /api/v1/history` returns `heatmap_covered_since`. Both heatmaps resolve hour of day, which `daily_usage` does not keep, so they stay raw-only however far back the charts above them now reach. The History page states that window under each one instead of drawing empty cells that read as "no activity" for days that were merely rolled up ### Fixed +- An unknown model no longer prints a warning on every ingested span. `pricing.Compute` sits on the ingest hot path, so one missing table entry used to drown the rest of the log — and the warning claimed `cost_usd` would be 0, which is not what ingest writes: it leaves the column NULL. Each canonical model id is now logged once per process, the message says the column is left unset, and the seen-set is capped at 256 so a client spraying distinct `model` strings cannot grow it without bound - A dated model id resolves to a price. Claude Code sends Haiku 4.5 as `claude-haiku-4-5-20251001`, but the price table is keyed undated and the lookup only stripped the tier suffix (`[1m]`), so every Haiku span was stored with `cost_usd` left NULL behind a `pricing: unknown model` warning — ingest keeps the column unset rather than writing a zero, so the spans were absent from spend totals rather than counted as free. The trailing `-YYYYMMDD` is now stripped after the tier suffix — a real id can carry both — and only when the tail is exactly eight digits, so a version segment (`claude-haiku-4-5`) is not mistaken for a date. The table is unchanged: undated keys stay the one canonical form - `GET /api/v1/overview`'s `users_count` obeyed neither the time window nor the `user_id` filter — it was a bare `SELECT COUNT(DISTINCT user_id) FROM spans`, so the "Users" KPI answered all-time and unscoped next to four KPIs that did not. It now counts the distinct principals active in the selected range, and counts unattributed spans as the single `__anonymous__` principal the users list shows rather than as zero - The Overview's `total_cost_usd` and token KPIs no longer drop spans that carry no `session_id`. They were computed under the same `session_id IS NOT NULL` clause as the session count, so the page's cost total could sit below the Costs page's for the same window diff --git a/internal/pricing/prices.go b/internal/pricing/prices.go index 586adb2..2adad96 100644 --- a/internal/pricing/prices.go +++ b/internal/pricing/prices.go @@ -7,6 +7,7 @@ package pricing import ( "log" "strings" + "sync" ) // ModelPrices holds per-million-token rates for one model tier. @@ -138,7 +139,7 @@ func Compute(model string, inputTokens, outputTokens, cacheReadTokens, cacheWrit p, ok := table[canonicalID(model)] if !ok { if model != "" { - log.Printf("pricing: unknown model %q — cost_usd will be 0 for this span", model) + warnUnknown(model) } return 0 } @@ -148,3 +149,32 @@ func Compute(model string, inputTokens, outputTokens, cacheReadTokens, cacheWrit float64(cacheReadTokens)*p.CacheReadPerMTok + float64(cacheWriteTokens)*p.CacheWritePerMTok) / perM } + +// Ingest is an external boundary: a client can send arbitrarily many distinct +// model strings. Cap the seen-set so a flood cannot grow process memory without bound. +const unknownModelLogCap = 256 + +var ( + unknownMu sync.Mutex + unknownSeen = make(map[string]struct{}) + unknownCapped bool +) + +func warnUnknown(model string) { + id := canonicalID(model) + unknownMu.Lock() + defer unknownMu.Unlock() + if unknownCapped { + return + } + if _, seen := unknownSeen[id]; seen { + return + } + if len(unknownSeen) >= unknownModelLogCap { + unknownCapped = true + log.Printf("pricing: unknown-model warnings suppressed — %d unique models logged, further warnings dropped", unknownModelLogCap) + return + } + unknownSeen[id] = struct{}{} + log.Printf("pricing: unknown model %q — cost_usd left unset for this span", model) +} diff --git a/internal/pricing/prices_test.go b/internal/pricing/prices_test.go index 82a8ca0..58ec9fc 100644 --- a/internal/pricing/prices_test.go +++ b/internal/pricing/prices_test.go @@ -1,7 +1,11 @@ package pricing_test import ( + "bytes" + "fmt" + "log" "math" + "strings" "testing" "github.com/Flopsstuff/cotel/internal/pricing" @@ -150,6 +154,62 @@ func TestComputeOpus5TierSuffixNonZero(t *testing.T) { } } +func TestComputeUnknownModelLogsOnce(t *testing.T) { + prev := log.Writer() + var buf bytes.Buffer + log.SetOutput(&buf) + defer log.SetOutput(prev) + + model := "claude-logonce-alpha" + if got := pricing.Compute(model, 1, 0, 0, 0); got != 0 { + t.Fatalf("unknown model: expected 0, got %v", got) + } + if !strings.Contains(buf.String(), `unknown model "claude-logonce-alpha"`) { + t.Fatalf("first call did not log warning: %q", buf.String()) + } + + buf.Reset() + pricing.Compute(model, 1, 0, 0, 0) + if buf.Len() != 0 { + t.Errorf("repeat call logged: %q", buf.String()) + } + + buf.Reset() + pricing.Compute(model+"-20260315", 1, 0, 0, 0) + if buf.Len() != 0 { + t.Errorf("canonical variant logged: %q", buf.String()) + } +} + +func TestComputeUnknownModelLogsEachCanonicalOnce(t *testing.T) { + prev := log.Writer() + var buf bytes.Buffer + log.SetOutput(&buf) + defer log.SetOutput(prev) + + a := "claude-logonce-bravo" + b := "claude-logonce-charlie" + pricing.Compute(a, 1, 0, 0, 0) + pricing.Compute(b, 1, 0, 0, 0) + out := buf.String() + if !strings.Contains(out, `unknown model "`+a+`"`) { + t.Errorf("missing log for %s: %q", a, out) + } + if !strings.Contains(out, `unknown model "`+b+`"`) { + t.Errorf("missing log for %s: %q", b, out) + } + if n := strings.Count(out, "unknown model"); n != 2 { + t.Errorf("expected 2 unknown-model lines, got %d in %q", n, out) + } + + buf.Reset() + pricing.Compute(a, 1, 0, 0, 0) + pricing.Compute(b, 1, 0, 0, 0) + if buf.Len() != 0 { + t.Errorf("repeat of distinct models logged: %q", buf.String()) + } +} + func TestComputeHaiku45Corrected(t *testing.T) { // claude-haiku-4-5 corrected to $1.00/$5.00 per MTok (was a stale $0.80/$4.00). got := pricing.Compute("claude-haiku-4-5", 1_000_000, 0, 0, 0) @@ -162,3 +222,32 @@ func TestComputeHaiku45Corrected(t *testing.T) { t.Errorf("haiku-4-5 still using stale $0.80 rate") } } + +func TestComputeUnknownModelLogCap(t *testing.T) { + prev := log.Writer() + var buf bytes.Buffer + log.SetOutput(&buf) + defer log.SetOutput(prev) + + // Process-wide set is not reset; fill well past 256 unique canonical IDs. + const n = 300 + for i := 0; i < n; i++ { + pricing.Compute(fmt.Sprintf("claude-logonce-cap-%03d", i), 1, 0, 0, 0) + } + out := buf.String() + if n := strings.Count(out, "unknown-model warnings suppressed"); n != 1 { + t.Fatalf("expected exactly one suppression line, got %d in %q", n, out) + } + if n := strings.Count(out, "unknown model"); n > 256 { + t.Errorf("logged %d unknown-model warnings, cap is 256", n) + } + + buf.Reset() + pricing.Compute("claude-logonce-cap-after", 1, 0, 0, 0) + if buf.Len() != 0 { + t.Errorf("post-cap unique model logged: %q", buf.String()) + } + if got := pricing.Compute("claude-logonce-cap-after-2", 1, 0, 0, 0); got != 0 { + t.Errorf("post-cap unknown still returns 0, got %v", got) + } +}