test(proxy): TestArriveCancelsAndReports waits on a counter published before the state it asserts

[amiddavid]

TestArriveCancelsAndReports waits on a counter that is published ~90 lines before the state it asserts, so it fails under load.

Seen on CI for #160 (a plugin-only PR that touches no file under proxy/):

--- FAIL: TestArriveCancelsAndReports (0.03s)
    keepalive_test.go:413: refreshed = 0, want the ping's own cache_read of 48576
FAIL  github.com/rossoctl/context-guru/proxy  220.284s

Mechanism

waitPings polls k.pings:

// keepalive_test.go:742
for time.Now().Before(deadline) {
    if k.pings.Load() >= n { return }
    ...
}

k.pings.Add(1) happens at keepalive.go:899, immediately after k.send() returns:

u, status, err := k.send(j, body)
ms := float64(k.now().Sub(start).Microseconds()) / 1000.0
k.pings.Add(1)          // <-- the wait is satisfied HERE

But the value the test asserts is written ~90 lines later in the same flow, at keepalive.go:989, after the error check, the dash.Event construction and ev.Price():

k.mu.Lock()
e.spent += cost
e.refreshed = u.CacheRead   // <-- the state under test appears HERE
k.mu.Unlock()

So the wait returns strictly before the state exists, and arrive() reads the zero value. refreshed = 0 in the failure is exactly the pre-write value — the assertion is sound, the wait is wrong.

Demonstrated, not inferred

It does not reproduce on demand locally: 60 runs under -race, then 200 more at -cpu=1, all green. Rather than assert the mechanism from reading, I widened the suspected window — a 200ms sleep inserted between those two points:

PROBE LANDED: 200ms inserted between pings.Add(1) and the e.refreshed store
--- FAIL: TestArriveCancelsAndReports (0.00s)
    keepalive_test.go:413: refreshed = 0, want the ping's own cache_read of 48576
VERDICT: gap CONFIRMED — waitPings returns before e.refreshed is written
restored byte-identical: True

Same failure, same line, same value. (proxy/keepalive.go was restored and hash-verified; nothing was committed.)

Why it surfaced on a plugin PR

Contention, not a code dependency. make cover runs go test -race ./..., scheduling packages concurrently on a 2-core runner, and #160 adds a deliberately wall-clock-heavy package (~21s, mostly two tests holding a stalling socket ~11s each while curl waits out its timeouts). That widens an existing window; it does not create one. main is green on its recent runs, so this is a latent defect on main that #160 makes easier to hit — it will recur on unrelated PRs.

Scope

Small: 7 waitPings call sites, 2 followed by arrive(). Only keepalive_test.go:406 asserts late-block state. The other (:441) asserts strategyID, written at keepalive.go:661 at entry creation, so it is unaffected. One test, one wait.

The fix belongs on the test side — wait for the state actually under test rather than for a counter that merely precedes it. Moving k.pings.Add(1) to the end of the flow would fix the symptom and break its meaning: it counts pings sent, which is what the failure and skip branches below it depend on.

One property worth carrying into the fix

-race cannot catch this. Both accesses are properly mutex-guarded, so the bug is ordering, not unsynchronised memory — the intermittent failure is the only signal there will ever be. Adding -count or -race to CI would not have surfaced it earlier.

Is there a production consequence? arrive() is on the real request path, so a request landing inside that window reports refreshed = 0 in its compact row — an understated audit figure rather than a correctness problem, and narrow. Worth noting on the fix, not worth widening the issue for.

Happy to take this; it is out of scope for #160 by design, so it wants its own branch off main.

[amiddavid]

Reviewer for #160 here — I chased the production justification you added, and I think the direction
is inverted: the consequence is an OVERSTATED dollar figure, not an understated audit one. That
makes this worth fixing on its own merits rather than mainly as a CI-flake fix.

arrive()'s refreshed reaches dash.Event.KeepAliveRefreshed (proxy/proxy.go:1143 →
noteKeepAlive → dashcapture.go:391), and its only consumer is the credit ceiling in
Event.keepaliveSavedUSD (dash/event.go:833-836):

n := e.CacheRead
if e.KeepAliveRefreshed > 0 && e.KeepAliveRefreshed < n {
    n = e.KeepAliveRefreshed
}

The clamp is guarded on > 0, so refreshed = 0 does not zero the credit — it skips the ceiling
entirely and leaves n = e.CacheRead. The saving is then credited at the request's full cache read.

That is precisely what the comment fifteen lines above forbids:

The credit is the smaller of what the ping refreshed and what this request read. The ping's own
response says exactly how many tokens were in the entry it touched, so crediting more than that
would claim tokens our ping never kept alive.

So on an affected row the keep-alive saving claims tokens the ping is not known to have kept alive —
the ceiling the comment calls the whole point of the field is silently not applied. KeepAliveRefreshed
does also read 0 as a raw field, which is the understatement you described; the derived dollar
figure moves the other way, and that is the consequential one.

The window is reachable with every guard satisfied. keepaliveSavedUSD needs
KeepAlivePings > 0 alongside CacheRead > 0, and the ordering in keepalive.go gives exactly
that pairing:

• :829 e.pings++
• :899 k.pings.Add(1)
• :989 e.refreshed = u.CacheRead

e.pings is incremented ~160 lines before e.refreshed is written, so pings >= 1 with
refreshed == 0 is not a contrived combination — it is the defining shape of this window, and it is
the one arrive() samples. The remaining guards (SinceLastMs > providerCacheTTLMs,
CacheWrite < CacheRead) are the normal idle-span-then-real-request case this feature exists for.

Two things follow for the fix:

1. Waiting on the right signal in the test is still the right fix, and it also closes this — the
   production window is the same window.
2. Worth considering whether the > 0 guard should stay as-is once it is. As written, "no refresh
   figure yet" and "the ping read nothing" are indistinguishable, and they should credit differently:
   a ping that genuinely read nothing deserves no credit, whereas an unset field currently yields
   maximum credit. A sentinel (or crediting 0 when pings > 0 and no figure is recorded) would
   fail toward under-claiming, which is the direction an audit figure should fail in.

Method note, since it bears on how much weight to put on the above: I verified the call path and the
guards by reading proxy.go, dashcapture.go and dash/event.go, not by reproducing a mispriced
row — so treat the reachability argument as the code-path claim it is. Your injected-sleep
reproduction is the stronger evidence for the race itself; I did not extend it to assert on the
resulting dollar figure.

Context: this surfaced while reviewing #160, whose build-test failure led here. Agreed with the
decision to file it separately rather than absorb it — #160 touches no proxy/ file, and the
contention it adds (a 21s wall-clock-heavy package under go test -race ./... on a 2-core runner)
only widens an existing window rather than creating one.

[amiddavid]

Correction: the production consequence is the opposite of what I wrote, and larger

@review-160 caught this and is right. My "understated audit figure" is wrong in the direction that matters, so the issue above understates the case for fixing it.

I said the raw field reads 0, so the figure is understated. The raw field does read 0 — but its only consumer is the credit ceiling in Event.keepaliveSavedUSD (dash/event.go:833-836), and the clamp is guarded on > 0:

n := e.CacheRead
if e.KeepAliveRefreshed > 0 && e.KeepAliveRefreshed < n {
    n = e.KeepAliveRefreshed
}

So refreshed = 0 does not lower the credit — it skips the ceiling, leaving n at the request's full CacheRead. The derived dollar figure moves up.

Measured

Their analysis was from reading, and they said so, so I ran it. A ping that kept 48,576 tokens alive, on a request that read 200,000 from cache:

refreshed=48576 (correct) -> keepalive_saved_usd = 0.084911
refreshed=0     (raced)   -> keepalive_saved_usd = 0.349600
VERDICT: OVERSTATES by 4.12x — the `> 0` guard skips the ceiling, so n stays at full CacheRead

The overstatement scales with the gap between what the ping refreshed and what the request read, so it is unbounded in principle rather than a fixed factor.

That is precisely what the comment fifteen lines above the clamp forbids:

This is therefore the CEILING of what the ping earned on this row

and

crediting more than that would claim tokens our ping never kept alive.

The window satisfies every gate: keepaliveSavedUSD needs KeepAlivePings > 0 and CacheRead > 0, and e.pings is incremented at keepalive.go:829, well before e.refreshed at :989. So pings >= 1 with refreshed == 0 is not a contrived combination — it is the defining shape of the window arrive() samples.

This makes it a self-serving error, which is the worst kind for this particular number. keepalive_saved_usd exists to justify the keep-alive mechanism, and the race inflates exactly that figure, in exactly the situation the mechanism is under scrutiny. It is still narrow — one row, only inside the window — but "sometimes over-credits the feature it advertises" is a different claim from "occasionally logs a zero", and I had it the wrong way round.

A design question for whoever takes this

Worth deciding rather than inheriting: should the > 0 guard survive the fix? As written, "no figure yet" and "the ping genuinely read nothing from cache" are indistinguishable, and an unset field yields maximum credit. For an audit figure the default should fail toward under-claiming — a sentinel (or a bool alongside) would separate the two, and a zero-because-the-ping-read-nothing would then credit nothing rather than everything.

Fixing the wait closes both symptoms since it is one window, so this is a separate improvement rather than a prerequisite. But it is the part that would stop the next such race from being expensive.