Skip to content

Commit 1ebc2b9

Browse files
Daedalusclaude
andcommitted
fix(retention): accumulate late-arriving spans instead of overwriting a rolled-up day
daily_usage was written with INSERT OR REPLACE, which is correct only while a roll-up recomputes a day from complete raw data. A span dated to a day that had already been rolled up and purged — a backfill, or an import of telemetry older than COTEL_RETENTION_RAW_DAYS — made the next cycle see exactly one span for that day, recompute the aggregate from it alone, and REPLACE the correct row. The day's earlier usage was gone, and so were the raw spans that could rebuild it, so historical cost was silently understated. A day's aggregate now accumulates: ON CONFLICT DO UPDATE adds each cycle's sum to the existing row instead of replacing it. This reverses the reasoning recorded in the previous commit, which kept INSERT OR REPLACE because an accumulating upsert would double a day's aggregate on a retry after a crash between the INSERT and the DELETE. That objection was correct and is answered rather than ignored: the accumulate, the raw-span purge and the aggregate purge now run in a single transaction, so the spans a cycle folds in vanish atomically with the addition and a crash rolls both back. The whole-day truncation from that commit still stands — it is what keeps a day from being rolled up in slices in the first place. Accumulation is safe against the trigger it exists for: spans.span_id is a PRIMARY KEY and both ingest and import insert with OR IGNORE, so re-importing a span is a no-op and cannot inflate a total. The COALESCE on the update side covers total_cache_read_tokens and total_cache_write_tokens only, because those are the columns the v7->v8 migration added nullable; the other totals are non-pointer types on every write path and are never NULL. Tests roll up a day, ingest a span dated into that same purged day, and assert the aggregate is the sum of both spans, that the day keeps exactly one row, and that a further cycle does not double-count. Co-Authored-By: Daedalus <daedalus@agents.flopbut.local> Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
1 parent 47e5963 commit 1ebc2b9

4 files changed

Lines changed: 107 additions & 18 deletions

File tree

CHANGELOG.md

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
1414
- No more silent telemetry loss on restart/deploy: the ingest (`:4318`) and dashboard (`:8080`) ports now bind and accept connections **before** the DuckDB open (WAL replay + schema migration), which can take minutes on a large production database. During that window both ports answer a retryable `503` with `Retry-After` instead of resetting the connection, so OTLP exporters retry and spans are delivered once cotel is ready. Previously the ports bound only after the open finished, so every deploy had a multi-minute window where ingest refused connections and dropped spans
1515
- Retention roll-up no longer loses part of a day's usage. The cutoff was a wall-clock instant, so with the worker ticking every 6h (`COTEL_RETENTION_INTERVAL`) a day was rolled up in slices; because `daily_usage` is keyed by day and written with `INSERT OR REPLACE`, each slice overwrote the previous one while its raw spans were already purged. Every day's `span_count`, token totals and `total_cost_usd` were therefore systematically understated — only the last slice survived. The cutoff is now snapped back to UTC midnight — the same boundary the `day` key is bucketed on — so only whole days are ever rolled up and purged. Trade-off: raw spans now live up to one day longer than `COTEL_RETENTION_RAW_DAYS` (default 30). Aggregates already flattened by the old behaviour cannot be recovered — the raw spans are gone
1616
- Retention is now correct on servers that do not run in UTC. A span's `day` is its UTC calendar day, but both retention cutoffs were computed in the server's local zone, so on any host at a non-zero UTC offset — including UTC+1/+2 — the boundary fell inside a day bucket and re-introduced the overwrite above for spans near midnight UTC. Both cutoffs are now computed in UTC, and the retention tests run under a matrix of server timezones so the alignment cannot silently regress
17+
- Retention roll-up no longer overwrites an already-rolled-up day's aggregate when a span dated to that day arrives late — a backfill, or an import of telemetry older than `COTEL_RETENTION_RAW_DAYS`. The day had already been aggregated and its raw spans purged, so the next cycle recomputed the day from the single late span alone and `INSERT OR REPLACE`d the correct total away, silently corrupting historical cost. Late spans now **accumulate** into the existing `daily_usage` row (`ON CONFLICT DO UPDATE`) instead of replacing it; the accumulate and the raw-span purge run in one transaction so a crash between them cannot double-count
1718

1819
### Added
1920
- Startup logging of each phase — `opening db`, `db ready: schema/migrations applied in <duration>`, and `ready: serving live traffic …` — so a slow open is visible instead of a silent container. Plus a Docker `HEALTHCHECK` (`cotel -healthcheck`, which probes the dashboard `/healthz`) so the container reports `health: starting` until the database is open rather than a misleading `Up`; no curl/wget is added to the runtime image

README.md

Lines changed: 12 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -210,10 +210,8 @@ Override with environment variables:
210210

211211
The worker ticks several times a day, but it only ever rolls up and purges
212212
**complete** calendar days: the raw-span cutoff is snapped back to midnight
213-
before use. `daily_usage` is keyed by day and rewritten with `INSERT OR REPLACE`,
214-
so rolling up a day in slices would make each slice overwrite the one before it
215-
while its raw spans were already deleted — permanently understating that day's
216-
`span_count`, tokens and cost.
213+
before use. Rolling up a day in slices would risk a slice's raw spans being
214+
purged before the rest of the day is aggregated.
217215

218216
Those are **UTC** calendar days, and the cutoff is UTC midnight, whatever
219217
timezone the server itself runs in. Aggregates are bucketed by UTC day
@@ -222,6 +220,16 @@ everywhere, so daily figures do not shift with the host's zone.
222220
The practical effect: a raw span survives up to one day longer than
223221
`COTEL_RETENTION_RAW_DAYS` before it is aggregated away.
224222

223+
### Late-arriving spans accumulate
224+
225+
A day's aggregate is built by **accumulation**: each roll-up cycle *adds* its sum
226+
to the existing `daily_usage` row (`ON CONFLICT DO UPDATE`) rather than replacing
227+
it. So a span dated to a day that was already rolled up and purged — a backfill,
228+
or an import (`POST /api/v1/import`) of telemetry older than
229+
`COTEL_RETENTION_RAW_DAYS` — is added to that day's total instead of overwriting
230+
it with itself alone. The accumulate and the raw-span purge run in a single
231+
transaction, so a crash between them cannot double-count.
232+
225233
### Unattributed usage — the `unknown` sentinel
226234

227235
`daily_usage` is keyed by `(day, session_id, model, tool_name)`. A raw span that

internal/storage/retention.go

Lines changed: 36 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -94,12 +94,16 @@ func (db *DB) rollupAndPurgeAt(cfg RetentionConfig, now time.Time) error {
9494
// Roll raw spans older than RawDays into daily_usage before deleting.
9595
//
9696
// The cutoff is snapped back to midnight so a roll-up only ever consumes
97-
// whole days. daily_usage is keyed by day and written with INSERT OR
98-
// REPLACE, so a cutoff landing mid-day would recompute that day from
99-
// whatever raw spans the previous cycle left behind and overwrite the
100-
// earlier slice — whose spans are already deleted. Whole days keep REPLACE
101-
// correct and the whole operation idempotent, at the cost of spans living
102-
// up to one day longer than RawDays.
97+
// whole days: a span survives up to one day longer than RawDays but a day is
98+
// never rolled up in slices.
99+
//
100+
// A day's aggregate accumulates: ON CONFLICT DO UPDATE adds each cycle's sum
101+
// to the existing row rather than replacing it. A span dated to a day that was
102+
// already rolled up and purged — a backfill or an import of old telemetry —
103+
// therefore adds to that day's total instead of overwriting it with itself
104+
// alone. The accumulate and the raw-span DELETE must stay in one transaction:
105+
// the spans a cycle folds in have to be gone atomically with the addition, or
106+
// a crash between them lets a retry count them twice.
103107
//
104108
// That midnight is UTC, never the server's local midnight: the day column
105109
// below comes from CAST(start_time AS TIMESTAMP), which renders the stored
@@ -114,8 +118,16 @@ func (db *DB) rollupAndPurgeAt(cfg RetentionConfig, now time.Time) error {
114118
// normalised values drive the grouping — '' and NULL collapse into one
115119
// 'unknown' bucket rather than two.
116120
rollupCutoff := startOfDayUTC(now.AddDate(0, 0, -cfg.RawDays))
117-
_, err := db.rw.Exec(`
118-
INSERT OR REPLACE INTO daily_usage
121+
aggCutoff := startOfDayUTC(now.AddDate(0, 0, -cfg.AggregateDays))
122+
123+
tx, err := db.rw.Begin()
124+
if err != nil {
125+
return err
126+
}
127+
defer tx.Rollback()
128+
129+
if _, err := tx.Exec(`
130+
INSERT INTO daily_usage
119131
(day, session_id, model, tool_name, user_id,
120132
span_count, total_input_tokens, total_output_tokens,
121133
total_cache_read_tokens, total_cache_write_tokens, total_cost_usd)
@@ -134,21 +146,31 @@ func (db *DB) rollupAndPurgeAt(cfg RetentionConfig, now time.Time) error {
134146
FROM spans
135147
WHERE start_time < ?
136148
GROUP BY 1, 2, 3, 4
137-
`, UnknownSentinel, UnknownSentinel, UnknownSentinel, rollupCutoff)
138-
if err != nil {
149+
ON CONFLICT (day, session_id, model, tool_name) DO UPDATE SET
150+
span_count = daily_usage.span_count + excluded.span_count,
151+
total_input_tokens = daily_usage.total_input_tokens + excluded.total_input_tokens,
152+
total_output_tokens = daily_usage.total_output_tokens + excluded.total_output_tokens,
153+
total_cache_read_tokens = COALESCE(daily_usage.total_cache_read_tokens, 0) + excluded.total_cache_read_tokens,
154+
total_cache_write_tokens = COALESCE(daily_usage.total_cache_write_tokens, 0) + excluded.total_cache_write_tokens,
155+
total_cost_usd = daily_usage.total_cost_usd + excluded.total_cost_usd,
156+
user_id = COALESCE(daily_usage.user_id, excluded.user_id)
157+
`, UnknownSentinel, UnknownSentinel, UnknownSentinel, rollupCutoff); err != nil {
139158
return err
140159
}
141160

142-
// Purge raw spans past RawDays.
143-
if _, err := db.rw.Exec(`DELETE FROM spans WHERE start_time < ?`, rollupCutoff); err != nil {
161+
// Purge raw spans past RawDays — atomic with the accumulate above.
162+
if _, err := tx.Exec(`DELETE FROM spans WHERE start_time < ?`, rollupCutoff); err != nil {
144163
return err
145164
}
146165

147166
// Purge aggregates past AggregateDays. Also UTC-snapped: day is a DATE, so
148167
// a local-zone instant here would round to a different day than the one the
149168
// roll-up wrote and drop (or keep) a day's aggregate a day early or late.
150-
aggCutoff := startOfDayUTC(now.AddDate(0, 0, -cfg.AggregateDays))
151-
if _, err := db.rw.Exec(`DELETE FROM daily_usage WHERE day < ?`, aggCutoff); err != nil {
169+
if _, err := tx.Exec(`DELETE FROM daily_usage WHERE day < ?`, aggCutoff); err != nil {
170+
return err
171+
}
172+
173+
if err := tx.Commit(); err != nil {
152174
return err
153175
}
154176

internal/storage/retention_test.go

Lines changed: 58 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -284,6 +284,64 @@ func TestRollupAndPurge_Idempotent(t *testing.T) {
284284
})
285285
}
286286

287+
// TestRollupAndPurge_LateSpanAccumulates pins the fix for a late-arriving span:
288+
// a span whose day was already rolled up and purged, ingested afterwards (a
289+
// backfill or an import of old telemetry), must be added to that day's existing
290+
// aggregate on the next cycle — not REPLACE it. Before the fix the second
291+
// roll-up recomputed the day from the single late span alone and overwrote the
292+
// correct total, silently corrupting historical cost.
293+
func TestRollupAndPurge_LateSpanAccumulates(t *testing.T) {
294+
db, err := Open(":memory:")
295+
if err != nil {
296+
t.Fatalf("open in-memory db: %v", err)
297+
}
298+
defer db.Close()
299+
300+
day := time.Date(2026, 1, 15, 0, 0, 0, 0, time.Local)
301+
insertBoundarySpan(t, db, "first", day.Add(2*time.Hour), 100, 10, 1000, 200, 0.10)
302+
303+
const rawDays = 30
304+
cfg := RetentionConfig{RawDays: rawDays, AggregateDays: 90}
305+
tick := day.AddDate(0, 0, rawDays+1).Add(8 * time.Hour)
306+
307+
// Roll up the day; its only raw span is aggregated then purged.
308+
if err := db.rollupAndPurgeAt(cfg, tick); err != nil {
309+
t.Fatalf("first roll-up: %v", err)
310+
}
311+
312+
// A late span dated to the same already-rolled-up day arrives afterwards,
313+
// sharing the aggregate's PK (same session/model/tool).
314+
insertBoundarySpan(t, db, "late", day.Add(10*time.Hour), 7, 3, 70, 30, 0.01)
315+
316+
if err := db.rollupAndPurgeAt(cfg, tick); err != nil {
317+
t.Fatalf("second roll-up (late span): %v", err)
318+
}
319+
320+
// The aggregate must be the sum of both spans, not just the late one.
321+
want := dayTotals{spans: 2, input: 107, output: 13, cacheRead: 1070, cacheWrite: 230, cost: 0.11}
322+
if got := accountedFor(t, db, day); got != want {
323+
t.Errorf("late span overwrote the day: accounted %+v, want %+v", got, want)
324+
}
325+
326+
// Accumulation must not fork a second aggregate row for the day.
327+
var rows int64
328+
if err := db.rw.QueryRow(`SELECT COUNT(*) FROM daily_usage WHERE day = CAST(? AS DATE)`,
329+
day.Format("2006-01-02")).Scan(&rows); err != nil {
330+
t.Fatalf("count daily_usage rows for day: %v", err)
331+
}
332+
if rows != 1 {
333+
t.Errorf("daily_usage rows for the day: got %d, want 1", rows)
334+
}
335+
336+
// With the late span now purged, re-running must not double-count it.
337+
if err := db.rollupAndPurgeAt(cfg, tick); err != nil {
338+
t.Fatalf("idempotent re-run: %v", err)
339+
}
340+
if got := accountedFor(t, db, day); got != want {
341+
t.Errorf("re-run changed the aggregate: accounted %+v, want %+v", got, want)
342+
}
343+
}
344+
287345
type dayTotals struct {
288346
spans int64
289347
input, output int64

0 commit comments

Comments
 (0)