From aa0e3d63d5e9e88c6533d595eeaef0ab9a02b312 Mon Sep 17 00:00:00 2001 From: Wayland Date: Fri, 14 Aug 2026 18:54:04 +0200 Subject: [PATCH 1/2] fix(storage): drop spans.duration_ms so bare equality stops returning nothing duration_ms was a VIRTUAL generated column declared mid-table. It takes a logical slot but no storage slot, so every column after it had a logical index one ahead of its physical index, and `WHERE col = ` on such a column probed an unrelated ART index and matched nothing - a silent wrong answer that reads correctly in review. That is why /api/v1/bash-commands shipped permanently empty. Schema version 10 drops the column and the four queries that read it compute epoch_ms(end_time) - epoch_ms(start_time) instead, aliased back to duration_ms so no response shape or sort key moves. The COALESCE(tool_name, '') workaround goes with it: DuckDB 1.4+ pushes COALESCE into the scan too, so it was on borrowed time. DuckDB refuses to ALTER a table an index depends on, so the migration drops the four secondary indexes first and the existing CREATE INDEX IF NOT EXISTS block rebuilds them. It moves no row data. Verified against a copy of production (108 MB, 34 706 spans): tool_name = 'Bash' counted 0 rows before and 6 440 after, service_name = 'claude-code' 0 before and 34 705 after, span count unchanged; storage.Open went 9.5s -> 9.8s against a cold start dominated by WAL replay, and a later re-apply of schema.sql costs 138 ms. The new upgrade test covers the same path on a seeded v9 database, and the pushdown guard now passes with an empty broken-column list. Co-Authored-By: Wayland Co-Authored-By: Claude Opus 5 --- CHANGELOG.md | 2 + docs/decisions/0001-storage.md | 48 +++++++----- internal/api/handler.go | 18 +---- internal/storage/pushdown_test.go | 119 +++++++++++++++++++++++++----- internal/storage/retention.go | 2 +- internal/storage/schema.sql | 21 +++++- 6 files changed, 154 insertions(+), 56 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index deaf021..2ddee28 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,9 +8,11 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] ### Fixed +- A bare `WHERE col = ` on `spans` returns the matching rows again instead of silently returning none. `duration_ms` was a VIRTUAL generated column declared mid-table: it took a logical slot but no storage slot, so every column after it had a logical index one ahead of its physical index, and an equality on such a column probed an unrelated ART index and found nothing — a wrong result, not an error. Schema version 10 drops the column and computes the duration at the four queries that read it, so logical and physical indexes line up and the trap is gone rather than worked around; the engine-fragile `COALESCE(tool_name, '') = 'Bash'` workaround (DuckDB 1.4+ pushes `COALESCE` down too) goes with it. Verified against a copy of production (108 MB, 34 706 spans): `tool_name = 'Bash'` counted 0 rows before the migration and 6 440 after, `service_name = 'claude-code'` 0 before and 34 705 after, with the span count unchanged ([ADR-0013](docs/decisions/0013-spans-has-no-derived-columns.md)) - A failing `GET /api/v1/bash-commands` no longer renders as the "no command detail in this data" explainer. The Bash section branched on row count alone, so a request that errored looked identical to one that legitimately returned nothing, blaming Claude Code's telemetry for what was actually a server fault. Fetch failures now show the error ### Changed +- Schema version 10 removes `spans.duration_ms`. The migration moves no row data: it drops the four secondary indexes, drops the column (DuckDB refuses to `ALTER` a table an index depends on), and the existing `CREATE INDEX IF NOT EXISTS` block rebuilds them. On the 108 MB production copy the whole upgrade added 0.4 s to a cold start already dominated by WAL replay (9.5 s → 9.8 s), and a later re-apply of `schema.sql` costs 138 ms. No downgrade path: an older binary still starts against a v10 database (`CREATE TABLE IF NOT EXISTS` cannot bring the column back) but every query naming `duration_ms` then errors, so a rollback needs the pre-upgrade database too. Exported CSVs are unaffected — the `duration_ms` column of `spans.csv` was already derived in Go, so the format version does not move - Tools page is flat: the tools table sits directly on the page instead of inside an "All Tools" card. `DataTable` already draws its own bordered surface, so the card put a box inside a box for a heading the page title already gave. Matches the Users page - The Bash commands section no longer vanishes when it has no rows — it always renders and says why it is empty. Claude Code's tool spans carry `tool_name`, `tool_use_id` and `duration_ms` only: which tool ran, not what it ran. No `command` attribute is ever sent (verified against a captured live session, including the enhanced-telemetry beta), so this breakdown stays empty against Claude Code telemetry no matter what — the DuckDB filter-pushdown fix in 0.3.0 was a real bug fix but could not, on its own, put rows in this table. The endpoint is kept for OTLP producers that do send `command` diff --git a/docs/decisions/0001-storage.md b/docs/decisions/0001-storage.md index d4104a4..702373c 100644 --- a/docs/decisions/0001-storage.md +++ b/docs/decisions/0001-storage.md @@ -54,33 +54,41 @@ Reasons: ## Known engine trap: virtual generated columns and secondary indexes -`spans` declares `duration_ms` as a VIRTUAL generated column and carries four -secondary indexes. That combination makes DuckDB answer some constant-equality -predicates — `WHERE tool_name = 'Bash'` — with **zero rows** instead of the -matching ones: a silent wrong result, not an error and not a slowdown. +A table that mixes a VIRTUAL generated column with secondary indexes makes +DuckDB answer some constant-equality predicates — `WHERE tool_name = 'Bash'` — +with **zero rows** instead of the matching ones: a silent wrong result, not an +error and not a slowdown. A virtual generated column takes a logical slot but no storage slot, so every column declared after it has logical index = physical index + 1. A column is answered wrongly exactly when its logical index collides with the *physical* index of an indexed column: the scan concludes an index covers the predicate, -probes that unrelated ART index for the constant, and finds nothing. On the -current layout `service_name` (logical 7) collides with `session_id` (physical -7), and `tool_name` (logical 10) with `user_id` (physical 10). +probes that unrelated ART index for the constant, and finds nothing. -Two consequences for anyone touching this schema: +`spans` used to declare `duration_ms` this way, which put `service_name` +(logical 7) on `session_id` (physical 7) and `tool_name` (logical 10) on +`user_id` (physical 10) — that is how `/api/v1/bash-commands` shipped +permanently empty. Schema version 10 drops the column and computes the duration +where it is read, so logical == physical everywhere and bare equality is correct +again. ADR-0013 records that decision and the rule it establishes: `spans` +carries no derived columns. -- **The affected set is a property of the layout, not of those two columns.** - Adding, reordering, or indexing a column silently moves the collisions. +What remains for anyone touching this schema: + +- **The affected set is a property of the layout, not of any one column.** + Adding, reordering, or indexing a column moves the collisions. `TestSpansEqualityUnderFilterPushdown` in `internal/storage` derives the set - from the live schema on every run and fails in both directions, so a moved - collision is a red build rather than an empty dashboard panel. -- **Wrapping the column keeps the predicate out of the pushdown** - (`COALESCE(col, '') = …`), which is the workaround in use today. It is not - durable: DuckDB 1.4+ pushes `COALESCE` down too, so the same guard test also - asserts the workaround still returns the truth. + from the live schema on every run and fails in both directions, so a + reintroduced hole is a red build rather than an empty dashboard panel. +- **`COALESCE(col, '') = …` keeps a predicate out of the pushdown**, which is + the escape hatch if one is ever needed again. It is not durable: DuckDB 1.4+ + pushes `COALESCE` down too, so the same guard test also asserts it still + returns the truth. +- **DuckDB refuses to `ALTER` a table an index depends on**, so a spans column + change means dropping the four secondary indexes first and letting the + `CREATE INDEX IF NOT EXISTS` block recreate them. Measured at 138 ms on a + 108 MB production copy (34 706 spans). Verified present on DuckDB 1.1.3 (bundled), 1.4.1 and 1.5.5, so upgrading the -engine does not resolve it. Neither does `STORED` — DuckDB rejects stored -generated columns outright. The root-cause fix is to stop declaring -`duration_ms` as a generated column mid-table; that is a schema migration and -is tracked separately. +engine does not resolve it, and `STORED` is rejected outright. Avoiding +generated columns on indexed tables is the only durable fix. diff --git a/internal/api/handler.go b/internal/api/handler.go index 367f9cf..49fbe9a 100644 --- a/internal/api/handler.go +++ b/internal/api/handler.go @@ -601,7 +601,7 @@ func (h *Handler) handleSession(w http.ResponseWriter, _ *http.Request, sessionI rows, _ := h.db.Query(` SELECT start_time, - duration_ms, + CAST(epoch_ms(end_time) - epoch_ms(start_time) AS DOUBLE) AS duration_ms, name, COALESCE(tool_name, ''), COALESCE(model, ''), @@ -805,7 +805,7 @@ parts AS ( SELECT tool_name AS name, COUNT(*) AS calls, - SUM(duration_ms) AS dur_sum, + SUM(CAST(epoch_ms(end_time) - epoch_ms(start_time) AS DOUBLE)) AS dur_sum, COUNT(*) AS dur_calls, COUNT(*) FILTER (WHERE status_code = 2) AS fails, COUNT(*) AS fail_calls @@ -987,16 +987,6 @@ var bashSortExprs = map[string]string{ // handleBashCommands returns per-command breakdown for Bash tool spans. // The command is extracted from the span attributes JSON: direct "command" key first, // then falling back to the "command" field inside a JSON-encoded "tool_input" value. -// -// The tool filter is written as COALESCE(tool_name, '') = 'Bash' rather than the -// plain equality: a bare `spans.tool_name = ` is pushed into the scan as a -// table filter and then matches nothing, so the plain form silently answers with -// an empty breakdown. Wrapping the column keeps the predicate out of the pushdown. -// -// Which columns this hits is a property of the spans layout rather than of -// tool_name — see the trap described in ADR-0001, and the guard test -// TestSpansEqualityUnderFilterPushdown, which fails both when the affected set -// moves and when this workaround stops being enough. func (h *Handler) handleBashCommands(w http.ResponseWriter, r *http.Request) { rangeKey, since := parseRange(r) sort, order := parseSortOrder(r, bashSortExprs, "calls") @@ -1030,10 +1020,10 @@ WITH cmd AS ( attributes->>'command', TRY_CAST(attributes->>'tool_input' AS JSON)->>'command' ) AS command, - duration_ms, + CAST(epoch_ms(end_time) - epoch_ms(start_time) AS DOUBLE) AS duration_ms, status_code FROM spans - WHERE COALESCE(tool_name, '') = 'Bash'` + uidClause + sinceClause + ` + WHERE tool_name = 'Bash'` + uidClause + sinceClause + ` ), cmd_stats AS ( SELECT diff --git a/internal/storage/pushdown_test.go b/internal/storage/pushdown_test.go index c45608e..a873990 100644 --- a/internal/storage/pushdown_test.go +++ b/internal/storage/pushdown_test.go @@ -1,29 +1,27 @@ package storage import ( + "database/sql" "fmt" + "path/filepath" "testing" "time" ) // pushdownBrokenSpanCols are the VARCHAR columns of spans for which the bundled -// DuckDB engine answers a bare `col = ` with zero rows. +// DuckDB engine answers a bare `col = ` with zero rows. Empty since +// spans stopped carrying a generated column (ADR-0013). // -// The trigger is the table shape, not the column: `duration_ms` is a VIRTUAL -// generated column, so it takes a logical slot but no storage slot and every -// column after it has logical index = physical index + 1. A column is answered -// wrongly exactly when its logical index collides with the physical index of an -// indexed column - the scan then probes that unrelated ART index for the -// constant and finds nothing. Today service_name (logical 7) collides with -// session_id (physical 7) and tool_name (logical 10) with user_id (physical 10). +// The trigger is the table shape, not the column: a VIRTUAL generated column +// takes a logical slot but no storage slot, so every column after it has logical +// index = physical index + 1. A column is answered wrongly exactly when its +// logical index collides with the physical index of an indexed column - the scan +// then probes that unrelated ART index for the constant and finds nothing. // // Adding, reordering or indexing a column moves the collisions, which is why // the test below derives the set from the live schema rather than trusting this // list to stay complete. -var pushdownBrokenSpanCols = map[string]bool{ - "service_name": true, - "tool_name": true, -} +var pushdownBrokenSpanCols = map[string]bool{} // spansVarcharCols reads the VARCHAR columns of spans in declaration order. func spansVarcharCols(t *testing.T, r *ReadDB) []string { @@ -134,9 +132,10 @@ func truthCounts(t *testing.T, r *ReadDB, cols []string) (map[string]string, map // pushed into the scan and then match nothing, turning a silently empty answer // into something no reviewer can spot by reading the SQL. // -// It fails in both directions on purpose. A column that starts disagreeing is a -// new place that needs the COALESCE guard; a column in pushdownBrokenSpanCols -// that starts agreeing means the engine was fixed and the workarounds can go. +// It fails in both directions on purpose. A column that starts disagreeing means +// the layout grew a hole again - look for a generated column before reaching for +// a COALESCE workaround; a column in pushdownBrokenSpanCols that starts agreeing +// means the trap is gone and its entry can go. func TestSpansEqualityUnderFilterPushdown(t *testing.T) { db, err := Open(":memory:") if err != nil { @@ -162,7 +161,7 @@ func TestSpansEqualityUnderFilterPushdown(t *testing.T) { bare := count(q+" = ?", probe[c]) if got := count("COALESCE("+q+", '') = ?", probe[c]); got != want[c] { - t.Errorf("COALESCE(%s, '') = %q returned %d rows, want %d: the workaround this codebase relies on no longer returns the truth on %s", + t.Errorf("COALESCE(%s, '') = %q returned %d rows, want %d: the fallback workaround no longer returns the truth on %s", c, probe[c], got, want[c], duckDBVersion(t, ro)) } @@ -171,7 +170,7 @@ func TestSpansEqualityUnderFilterPushdown(t *testing.T) { t.Errorf("%s = %q now returns the correct %d rows on %s: drop %q from pushdownBrokenSpanCols and remove its COALESCE workaround", c, probe[c], want[c], duckDBVersion(t, ro), c) case !broken && bare != want[c]: - t.Errorf("%s = %q returned %d rows, want %d on %s: this column is now silently dropped by filter pushdown and needs the COALESCE workaround", + t.Errorf("%s = %q returned %d rows, want %d on %s: this column is now silently dropped by filter pushdown - check whether spans grew a generated column", c, probe[c], bare, want[c], duckDBVersion(t, ro)) } } @@ -191,6 +190,92 @@ func TestSpansEqualityUnderFilterPushdown(t *testing.T) { } } +// TestUpgradeDropsGeneratedDurationColumn covers the upgrade path the fresh-database +// test cannot: a populated v9 database still carries duration_ms as a generated +// column, and the migration has to remove it without touching the rows around it. +func TestUpgradeDropsGeneratedDurationColumn(t *testing.T) { + path := filepath.Join(t.TempDir(), "v9.duckdb") + + raw, err := sql.Open("duckdb", path) + if err != nil { + t.Fatalf("raw open: %v", err) + } + if _, err := raw.Exec(`CREATE TABLE spans ( + trace_id VARCHAR NOT NULL, span_id VARCHAR NOT NULL PRIMARY KEY, + parent_span_id VARCHAR, name VARCHAR NOT NULL, + start_time TIMESTAMPTZ NOT NULL, end_time TIMESTAMPTZ NOT NULL, + duration_ms DOUBLE GENERATED ALWAYS AS (epoch_ms(end_time) - epoch_ms(start_time)), + service_name VARCHAR, session_id VARCHAR, model VARCHAR, tool_name VARCHAR, + user_id VARCHAR, status_code TINYINT DEFAULT 0, + input_tokens INTEGER, output_tokens INTEGER, + cache_read_tokens INTEGER, cache_write_tokens INTEGER, cost_usd DOUBLE, + attributes JSON, resource_attrs JSON, ingested_at TIMESTAMPTZ DEFAULT now() + )`); err != nil { + t.Fatalf("seed v9 spans: %v", err) + } + for _, idx := range []string{"session_id", "start_time", "name", "user_id"} { + if _, err := raw.Exec(`CREATE INDEX idx_spans_` + idx + ` ON spans(` + idx + `)`); err != nil { + t.Fatalf("seed index on %s: %v", idx, err) + } + } + for i := 0; i < 3; i++ { + if _, err := raw.Exec(` + INSERT INTO spans (trace_id, span_id, name, start_time, end_time, service_name, session_id, model, tool_name, user_id) + VALUES ('t', ?, 'tool.execution', ?, ?, 'claude-code', ?, 'claude-opus-4', 'Bash', ?)`, + fmt.Sprintf("span-%d", i), time.Unix(int64(i), 0), time.Unix(int64(i)+1, 0), + fmt.Sprintf("session-%d", i), fmt.Sprintf("user-%d", i)); err != nil { + t.Fatalf("seed span %d: %v", i, err) + } + } + if err := raw.Close(); err != nil { + t.Fatalf("raw close: %v", err) + } + + db, err := Open(path) + if err != nil { + t.Fatalf("open v9 db: %v", err) + } + defer db.Close() + ro := db.ReadOnly() + + var cols int + if err := ro.QueryRow(` + SELECT COUNT(*) FROM information_schema.columns + WHERE table_name = 'spans' AND column_name = 'duration_ms'`).Scan(&cols); err != nil { + t.Fatalf("read spans columns: %v", err) + } + if cols != 0 { + t.Errorf("duration_ms still declared on spans after upgrade") + } + + var total int + if err := ro.QueryRow(`SELECT COUNT(*) FROM spans`).Scan(&total); err != nil { + t.Fatalf("count spans: %v", err) + } + if total != 3 { + t.Errorf("spans after upgrade = %d, want 3: the migration moved rows", total) + } + + var bash int + if err := ro.QueryRow(`SELECT COUNT(*) FROM spans WHERE tool_name = 'Bash'`).Scan(&bash); err != nil { + t.Fatalf("count Bash spans: %v", err) + } + if bash != 3 { + t.Errorf("tool_name = 'Bash' returned %d rows, want 3 on %s: the upgraded layout still traps bare equality", + bash, duckDBVersion(t, ro)) + } + + var dur float64 + if err := ro.QueryRow(` + SELECT CAST(epoch_ms(end_time) - epoch_ms(start_time) AS DOUBLE) + FROM spans WHERE span_id = 'span-0'`).Scan(&dur); err != nil { + t.Fatalf("read computed duration: %v", err) + } + if dur != 1000 { + t.Errorf("computed duration_ms = %v, want 1000", dur) + } +} + func duckDBVersion(t *testing.T, r *ReadDB) string { t.Helper() var v string diff --git a/internal/storage/retention.go b/internal/storage/retention.go index cef740d..77e6cd5 100644 --- a/internal/storage/retention.go +++ b/internal/storage/retention.go @@ -144,7 +144,7 @@ func (db *DB) rollupAndPurgeAt(cfg RetentionConfig, now time.Time) error { COALESCE(SUM(cache_read_tokens), 0), COALESCE(SUM(cache_write_tokens), 0), COALESCE(SUM(cost_usd), 0), - COALESCE(SUM(duration_ms), 0), + COALESCE(SUM(CAST(epoch_ms(end_time) - epoch_ms(start_time) AS DOUBLE)), 0), COUNT(*) FILTER (WHERE status_code = 2) FROM spans WHERE start_time < ? diff --git a/internal/storage/schema.sql b/internal/storage/schema.sql index c54d15c..da3b6c2 100644 --- a/internal/storage/schema.sql +++ b/internal/storage/schema.sql @@ -1,4 +1,4 @@ --- Schema version: 9 +-- Schema version: 10 -- Versioned; never silently rename columns. CREATE TABLE IF NOT EXISTS schema_version ( @@ -17,9 +17,6 @@ CREATE TABLE IF NOT EXISTS spans ( -- Timing start_time TIMESTAMPTZ NOT NULL, end_time TIMESTAMPTZ NOT NULL, - duration_ms DOUBLE GENERATED ALWAYS AS ( - epoch_ms(end_time) - epoch_ms(start_time) - ), -- Service metadata service_name VARCHAR, @@ -55,6 +52,21 @@ ALTER TABLE spans ADD COLUMN IF NOT EXISTS status_code TINYINT DEFAULT 0; -- Migration v2 → v3: add user_id for multi-user telemetry separation. ALTER TABLE spans ADD COLUMN IF NOT EXISTS user_id VARCHAR; +-- Migration v9 → v10: drop the derived duration_ms column (ADR-0013). As a +-- VIRTUAL generated column it took a logical slot but no storage slot, so every +-- later column's logical index ran one ahead of its physical index and a bare +-- `col = ` probed an unrelated index and matched nothing. Duration is +-- computed where it is read. +-- +-- DuckDB refuses to ALTER a table an index depends on, so the secondary indexes +-- are dropped here and recreated below. Both statements are idempotent, so a +-- re-apply of this file rebuilds the indexes but moves no row data. +DROP INDEX IF EXISTS idx_spans_session_id; +DROP INDEX IF EXISTS idx_spans_start_time; +DROP INDEX IF EXISTS idx_spans_name; +DROP INDEX IF EXISTS idx_spans_user_id; +ALTER TABLE spans DROP COLUMN IF EXISTS duration_ms; + -- Indexes for dashboard hot paths (DuckDB ART indexes). CREATE INDEX IF NOT EXISTS idx_spans_session_id ON spans(session_id); CREATE INDEX IF NOT EXISTS idx_spans_start_time ON spans(start_time); @@ -144,3 +156,4 @@ INSERT INTO schema_version (version) VALUES (6) ON CONFLICT DO NOTHING; INSERT INTO schema_version (version) VALUES (7) ON CONFLICT DO NOTHING; INSERT INTO schema_version (version) VALUES (8) ON CONFLICT DO NOTHING; INSERT INTO schema_version (version) VALUES (9) ON CONFLICT DO NOTHING; +INSERT INTO schema_version (version) VALUES (10) ON CONFLICT DO NOTHING; From aadf9b8c1b8533a6a6c27f3d2522bd261b7fa4e2 Mon Sep 17 00:00:00 2001 From: Wayland Date: Fri, 14 Aug 2026 18:55:55 +0200 Subject: [PATCH 2/2] test(api): assert the session detail duration_ms value, not just row presence handleSession ignores the Scan error, so a projection that no longer scans would have returned zero-valued spans and still passed the len() > 0 check. Pin the computed value instead. Co-Authored-By: Wayland Co-Authored-By: Claude Opus 5 --- internal/api/handler_test.go | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/internal/api/handler_test.go b/internal/api/handler_test.go index cb7ec9c..79ecee4 100644 --- a/internal/api/handler_test.go +++ b/internal/api/handler_test.go @@ -355,7 +355,10 @@ func TestSessionDetail(t *testing.T) { } spans, ok := body["spans"].([]any) if !ok || len(spans) == 0 { - t.Error("expected non-empty spans") + t.Fatal("expected non-empty spans") + } + if got := spans[0].(map[string]any)["duration_ms"].(float64); got != 1000 { + t.Errorf("duration_ms: want 1000 for a 1s span, got %v", got) } }, },