rossoctl / rossoctl/cortex

Flaky test: TestHandleUsage_LedgerBackedModelSeriesDisclosesWhatItLeavesOut races the cost-ledger writer goroutine

Open
#1,057 0 comments 0 reactions 0 assignees View on GitHub

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:

  1. ledgerWithOneCostedMinute records row 1 and calls Flush(), which advances flushedThrough past that minute.
  2. 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 to enqueue, which is explicitly "outside the lock, and never blocking" (writer.go:596).
  3. The test's second Flush() does not cover it. Flush only submits its own in-memory batch (writer.go:988-993); row 2 is already in the async w.ops queue.
  4. 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:

sync blocks until every batch enqueued before this call has been written. A test barrier, and only that. It exists because Record returns 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.go0, 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

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.