Flaky test: TestHandleUsage_LedgerBackedModelSeriesDisclosesWhatItLeavesOut races the cost-ledger writer goroutine
Nobody has claimed this yet.
- Dominant language
- Go
- Stars
- 13
- Forks
- 40
- Avg merge
- 12h 17m
- Merged PRs (30d)
- 156
Description
Summary
TestHandleUsage_LedgerBackedModelSeriesDisclosesWhatItLeavesOut (authbridge/authlib/sessionapi/usage_test.go:779) fails intermittently. It failed on a PR that changes no authlib code, and passed on re-run with no change.
Observed once so far, in run 35380183842, job "Go CI (authlib)":
usage_test.go:809: Totals.CostMicros = 100000, want 350000 — both rows are real spend:
{"window":"today","bucketSeconds":66446,"group":"model","buckets":[{...
"costMicros":100000,"pricedRequests":1,"priceableRequests":1,
"series":{"opus":{...,"costMicros":100000,...}}}],
"totals":{"requests":1,...,"costMicros":100000,...},"priced":true}
The test records two rows in the same minute — $0.10 with an Inference extension, $0.25 gateway-priced with none — and asserts both reach the response (350000 micros). Only the first arrived: requests is 1, not 2, so the second row was absent from the day file, not mis-attributed.
Root cause: a missing write barrier, not a clock
The two rows take different paths through costledger.Writer:
ledgerWithOneCostedMinuterecords row 1 and callsFlush(), which advancesflushedThroughpast that minute.- The test then records row 2 into that already-flushed minute.
Writer.add(costledger/writer.go:573) takes the!minute.After(w.flushedThrough)branch — "straight to the writer rather than back into memory" — so the row goes toenqueue, which is explicitly "outside the lock, and never blocking" (writer.go:596). - The test's second
Flush()does not cover it.Flushonly submits its own in-memory batch (writer.go:988-993); row 2 is already in the asyncw.opsqueue. - The HTTP read then hits the day file before the writer goroutine has written row 2.
The codebase already names this hazard — sync() at writer.go:995:
syncblocks until every batch enqueued before this call has been written. A test barrier, and only that. It exists becauseRecordreturns before its IO has happened, so a test that records and then reads the day files would be asserting against a race rather than against behaviour.
sync() is unexported, so sessionapi tests cannot call it. grep -c 'sync()' sessionapi/usage_test.go → 0, while costledger's own tests call it in five places. The barrier exists and is unreachable from the package that needs it.
This also explains why it is rare: the window is one goroutine scheduling delay wide, and -race (which CI uses) perturbs exactly that timing.
Ruled out
- Not the PR under test. #1052 changes four files, all under
cmd/abctl;git diff origin/main..HEAD -- authbridge/authlib/is empty.Go CI (authbridge abctl)passed in the same run. - Not a real regression. Re-running the same job with no code change passed. #1056, with byte-identical
authlib, passed 4 minutes later. - Not timezone. Passes under
TZ=UTC,America/New_York,Europe/London. - Not the midnight clamp. This was my first hypothesis, given
insideTodayAt's comment about 00:00:30, but the failure was at 18:27 UTC (bucketSeconds: 66446= 18:27:26 exactly), and modelling the clamp shows it keeps rows inside the window at every hour. - Not
Trust()/admission.costevent.Event.Trust()(costevent.go:379) is pure — no clock, no environment — so the $0.25 row's pricedness is deterministic. Passes 20× locally under-race.
Suggested fix
Give sessionapi tests the barrier costledger tests already have — an exported Sync(), or an export_test.go alias, called after the second Record. That closes the race at the assertion rather than by widening a timeout.
Worth a look at the other 13 callers of insideToday(t, …) in the same file for the same "record after Flush, then read the file" shape. Only this one has bitten so far.
Reproducing
I could not reproduce it on demand — 20 iterations under -race across three timezones all pass. The evidence above is from the CI log plus reading the write path. A deliberate reproduction would inject a delay in the writer goroutine between enqueue and the file write.
Found while reviewing CI on #1052; not caused by it.
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Start with authbridge/authlib/sessionapi/usage_test.go:779 and costledger/writer.go, especially add, Flush, and sync. Trace the second Record after the first Flush, then add a test-accessible barrier and use it before the HTTP read; verify the flaky test and the related insideToday callers under -race.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go
- Domain
- testing-qa
- Issue type
- Bug
- Difficulty
- 3/5
- Estimated time
- 1-2 days
- Activity status
- Active
- Clarity
- Clearly specified
- Newbie friendliness
- 75/100