What changed. A usage-log snapshot's fingerprint is now produced by the parse itself: each complete line read is fed into a SHA-256. When a build continues the old snapshot's blocks, it continues the old snapshot's digest too (crypto/sha256's state, kept on the snapshot as `digest`); otherwise the digest starts fresh from byte 0 with the parse. The build's before-read logRecordHash over the whole file is gone. The fingerprint covers the bytes actually parsed (`off`), not info.Size(), so a half line another writer is in the middle of appending is no longer counted as read; the unchanged check, the prefix check and the after-read check all hash `off` bytes. What stays, as #1328's tests require (ggbdpq's analysis on #1357): the unsettled unchanged check, the prefix re-verification on a non-trusted continuation, and the after-read check, which now compares the parse's own digest against the file as it is after the read. A same-tick rewrite is still caught at the build, not at a later read. On the trusted, settled path nothing is re-read, as before; that snapshot now also carries a fingerprint (the continued digest), so a later non-trusted append can verify its prefix instead of rebuilding from byte 0. Test changed: TestUsageRewriteBeforeFingerprintIsNotCached counted logRecordHash calls and rewrote the file at call 1 (after the before-read hash, before the parse) or call 2 (after the read). With the parse being the fingerprint there is no call 1 any more, so the hash=2 case could no longer fire. Its guarantee still holds and is still tested at both boundaries: "before-read" rewrites at the build's first change-time look, after its stat and before it opens and parses; "after-read" rewrites at the after-read fingerprint check. Removing the after-read check makes after-read fail. No other test changed. New tests: - TestUsageAppendReadHashesNoPreReadScan: 20,000-row settled log (2,760,615 bytes), 5 x Append + Summarize(Today), counts the bytes logRecordHash re-reads. origin/main: 7,728,984 bytes per cycle (2.80x the log), FAIL; this commit: 4,968,615 (1.80x), PASS. Wall time per cycle on an M-series Mac, 3 runs each: 3.43-3.52 ms before, 2.28-2.52 ms after (~32% less). The remaining two passes are the prefix check and the after-read check, which the same-tick guarantee needs. - TestUsagePartialLineThenCompletion (settled and unsettled): another writer's half line, a read, then the line completed; the fingerprint covers the parsed bytes only and the completed record is counted. On origin/main it fails on the fingerprint check (it covered the half line). Break checks: no after-read check -> RewriteBeforeFingerprint/after-read fails; no prefix verification on a continuation -> SameSizeAndMtimeRewrite append=true, SameTickRewrite append=true and LogGrowingRewriteThenAppend fail; lines not fed into the digest -> SameTickRewrite fails. Run: go test -tags nogui ./internal/usage/... ./internal/gateway/... (ok, temp HOME, pinned caches, removed after); go test -race ./internal/usage/... (ok); -race -count=10 on the rewrite/append tests (ok); gofmt -l (empty); go vet, GOOS=linux and GOOS=windows go vet -tags nogui ./internal/usage/ (ok). Not tried on Windows or Linux hardware; the change is platform-independent hashing over the same read.
305 lines
9.8 KiB
Go
305 lines
9.8 KiB
Go
package usage
|
|
|
|
import (
|
|
"bytes"
|
|
"fmt"
|
|
"os"
|
|
"testing"
|
|
"time"
|
|
)
|
|
|
|
func TestUsageSameSizeAndMtimeRewrite(t *testing.T) {
|
|
for _, appendAfter := range []bool{false, true} {
|
|
t.Run(fmt.Sprint("append=", appendAfter), func(t *testing.T) {
|
|
pageHome(t)
|
|
now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local))
|
|
historyLog(t, 1034)
|
|
Summarize(All)
|
|
QueryPage(All, Filter{}, 0, 100)
|
|
before, err := os.Stat(Path())
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
data, err := os.ReadFile(Path())
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
edited := bytes.Replace(data, []byte(`"in":10`), []byte(`"in":73`), 1)
|
|
if bytes.Equal(edited, data) || len(edited) != len(data) {
|
|
t.Fatal("fixture must change at the same size")
|
|
}
|
|
if err := os.WriteFile(Path(), edited, 0600); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if err := os.Chtimes(Path(), before.ModTime(), before.ModTime()); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if appendAfter {
|
|
Append(Record{Time: now, Agent: "codex", Provider: "relay", Model: "m", Input: 19})
|
|
}
|
|
got, want := Summarize(All), summarize(All, now, Load(time.Time{}))
|
|
if got.Totals != want.Totals {
|
|
t.Fatalf("same-stat summary stale: got %+v want %+v", got.Totals, want.Totals)
|
|
}
|
|
equalPage(t, QueryPage(All, Filter{}, 0, 100), pageFromLedger(All, Filter{}, 0, 100, LedgerOf(All, Filter{})))
|
|
})
|
|
}
|
|
}
|
|
|
|
func TestUsageSameTickRewriteIsNotCached(t *testing.T) {
|
|
for _, overBudget := range []bool{false, true} {
|
|
for _, appendAfter := range []bool{false, true} {
|
|
for _, afterSettle := range []bool{false, true} {
|
|
t.Run(fmt.Sprintf("uncached=%t/append=%t/after-settle=%t", overBudget, appendAfter, afterSettle), func(t *testing.T) {
|
|
pageHome(t)
|
|
if overBudget {
|
|
cacheBudget(t, 128)
|
|
}
|
|
clock := holdClock(t, time.Now())
|
|
tick := time.Now().Truncate(time.Second)
|
|
holdLogTick(t, tick)
|
|
historyLog(t, 1)
|
|
Summarize(All)
|
|
QueryPage(All, Filter{}, 0, 100)
|
|
warm := logSnapshotFor(true)
|
|
if warm.settled || logSnapshotFor(true) != warm {
|
|
t.Fatal("unchanged same-tick metadata must reuse its fingerprint without becoming settled")
|
|
}
|
|
before, err := statLogFile(Path())
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
data, err := os.ReadFile(Path())
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
edited := bytes.Replace(data, []byte(`"in":10`), []byte(`"in":73`), 1)
|
|
if bytes.Equal(edited, data) || len(edited) != len(data) {
|
|
t.Fatal("fixture must change at the same size")
|
|
}
|
|
if err := os.WriteFile(Path(), edited, 0600); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if err := os.Chtimes(Path(), before.ModTime(), before.ModTime()); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
after, err := statLogFile(Path())
|
|
if err != nil || !sameLogInfo(before, after) {
|
|
t.Fatal("fixture must keep file identity, size, mtime and change stamp", err)
|
|
}
|
|
if appendAfter {
|
|
Append(Record{Time: clock, Agent: "codex", Provider: "relay", Model: "m", Input: 19})
|
|
}
|
|
if afterSettle {
|
|
logIndexNow = func() time.Time { return tick.Add(time.Hour) }
|
|
}
|
|
got, want := Summarize(All), summarize(All, clock, Load(time.Time{}))
|
|
if got.Totals != want.Totals {
|
|
t.Errorf("same-tick summary stale: got %+v want %+v", got.Totals, want.Totals)
|
|
}
|
|
equalPage(t, QueryPage(All, Filter{}, 0, 100), pageFromLedger(All, Filter{}, 0, 100, LedgerOf(All, Filter{})))
|
|
logIndexNow = func() time.Time { return tick.Add(time.Hour) }
|
|
logSnapshotFor(true) // An oversized read publishes a metadata-only copy.
|
|
stable := logSnapshotFor(true)
|
|
for range 3 {
|
|
if logSnapshotFor(true) != stable {
|
|
t.Fatal("settled unchanged metadata was not cached")
|
|
}
|
|
}
|
|
})
|
|
}
|
|
}
|
|
}
|
|
}
|
|
|
|
func holdLogTick(t *testing.T, tick time.Time) {
|
|
t.Helper()
|
|
changeTime, now := logChangeTime, logIndexNow
|
|
logChangeTime = func(info os.FileInfo) time.Time {
|
|
if info == nil {
|
|
return time.Time{}
|
|
}
|
|
return tick
|
|
}
|
|
logIndexNow = func() time.Time { return tick.Add(10 * time.Millisecond) }
|
|
t.Cleanup(func() { logChangeTime, logIndexNow = changeTime, now })
|
|
}
|
|
|
|
// The parse is the fingerprint (#1357), so a rewrite can land before the read
|
|
// (after the stat that decided to read) or between the read and the
|
|
// after-read fingerprint check. Neither may leave the old bytes cached.
|
|
func TestUsageRewriteBeforeFingerprintIsNotCached(t *testing.T) {
|
|
for _, rewriteAt := range []string{"before-read", "after-read"} {
|
|
t.Run(rewriteAt, func(t *testing.T) {
|
|
pageHome(t)
|
|
now := holdClock(t, time.Now())
|
|
tick := time.Now().Truncate(time.Second)
|
|
holdLogTick(t, tick)
|
|
logIndexNow = func() time.Time { return tick.Add(time.Hour) }
|
|
historyLog(t, 1)
|
|
info, err := statLogFile(Path())
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
data, err := os.ReadFile(Path())
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
edited := bytes.Replace(data, []byte(`"in":10`), []byte(`"in":73`), 1)
|
|
if bytes.Equal(edited, data) || len(edited) != len(data) {
|
|
t.Fatal("fixture must change at the same size")
|
|
}
|
|
rewritten := false
|
|
rewrite := func(path string) {
|
|
if rewritten {
|
|
return
|
|
}
|
|
rewritten = true
|
|
if err := os.WriteFile(path, edited, 0600); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if err := os.Chtimes(path, info.ModTime(), info.ModTime()); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
}
|
|
hash, changeTime := logRecordHash, logChangeTime
|
|
if rewriteAt == "before-read" {
|
|
// The build's first look at the change time follows its stat
|
|
// and precedes the open that reads and hashes the lines.
|
|
logChangeTime = func(i os.FileInfo) time.Time {
|
|
rewrite(Path())
|
|
return changeTime(i)
|
|
}
|
|
} else {
|
|
logRecordHash = func(path string, n int64) string {
|
|
rewrite(path)
|
|
return hash(path, n)
|
|
}
|
|
}
|
|
t.Cleanup(func() { logRecordHash, logChangeTime = hash, changeTime })
|
|
Summarize(All)
|
|
if !rewritten {
|
|
t.Fatal("fixture did not rewrite at the read boundary")
|
|
}
|
|
got, want := Summarize(All), summarize(All, now, Load(time.Time{}))
|
|
if got.Totals != want.Totals {
|
|
t.Fatalf("post-read fingerprint hid a rewrite: got %+v want %+v", got.Totals, want.Totals)
|
|
}
|
|
equalPage(t, QueryPage(All, Filter{}, 0, 100), pageFromLedger(All, Filter{}, 0, 100, LedgerOf(All, Filter{})))
|
|
})
|
|
}
|
|
}
|
|
|
|
func cacheBudget(t *testing.T, n int64) {
|
|
t.Helper()
|
|
old := requestCacheBytes
|
|
requestCacheBytes = n
|
|
t.Cleanup(func() { requestCacheBytes = old })
|
|
}
|
|
|
|
func TestUsageRawCacheBudget(t *testing.T) {
|
|
pageHome(t)
|
|
now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local))
|
|
cacheBudget(t, 128)
|
|
historyLog(t, 1034)
|
|
assertFresh := func() {
|
|
t.Helper()
|
|
cold := Load(time.Time{})
|
|
for _, p := range []Period{Today, Week, Month, All} {
|
|
got, want := Summarize(p), summarize(p, now, cold)
|
|
if got.Totals != want.Totals {
|
|
t.Fatalf("uncached %s summary stale: %+v / %+v", p, got.Totals, want.Totals)
|
|
}
|
|
equalPage(t, QueryPage(p, Filter{}, 0, 100), pageFromLedger(p, Filter{}, 0, 100, LedgerOf(p, Filter{})))
|
|
}
|
|
logIndex.Lock()
|
|
retained := len(logIndex.snapshot.blocks)
|
|
logIndex.Unlock()
|
|
if retained != 0 {
|
|
t.Fatalf("retained %d over-budget blocks", retained)
|
|
}
|
|
requestCache.Lock()
|
|
chunks, pages := len(requestCache.chunks)+len(requestCache.gateways), len(requestCache.pages)
|
|
requestCache.Unlock()
|
|
if chunks != 0 || pages != 0 {
|
|
t.Fatalf("uncached raw history retained chunks=%d pages=%d", chunks, pages)
|
|
}
|
|
}
|
|
assertFresh()
|
|
Append(Record{Time: now, Agent: "codex", Provider: "relay", Model: "m", Input: 11})
|
|
assertFresh()
|
|
historyLog(t, 20) // rewrite/truncate after the oversized metadata-only index
|
|
assertFresh()
|
|
}
|
|
|
|
func TestUsageRawAndPricedChunksShareBudget(t *testing.T) {
|
|
pageHome(t)
|
|
holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local))
|
|
historyLog(t, 1034)
|
|
snapshot := readLogSnapshot()
|
|
cacheBudget(t, snapshot.bytes+1)
|
|
equalPage(t, QueryPage(All, Filter{}, 0, 100), pageFromLedger(All, Filter{}, 0, 100, LedgerOf(All, Filter{})))
|
|
requestCache.Lock()
|
|
defer requestCache.Unlock()
|
|
retained := snapshot.bytes
|
|
for _, c := range requestCache.gateways {
|
|
retained += c.Bytes
|
|
}
|
|
for _, c := range requestCache.chunks {
|
|
retained += c.Bytes
|
|
}
|
|
if retained > requestCacheBytes {
|
|
t.Fatalf("raw + priced bytes %d exceed %d", retained, requestCacheBytes)
|
|
}
|
|
}
|
|
|
|
func TestUsageLargeSummaryIsCompleteButNotCached(t *testing.T) {
|
|
pageHome(t)
|
|
for i := 0; i < summaryCacheSessions+1; i++ {
|
|
Append(Record{Time: time.Now(), Agent: "codex", Provider: "relay", Model: "m", Session: fmt.Sprint(i), Input: 1})
|
|
}
|
|
got := Summarize(All)
|
|
if len(got.Sessions) != summaryCacheSessions+1 || got.Calls != summaryCacheSessions+1 {
|
|
t.Fatalf("large summary lost sessions: %d / %d", len(got.Sessions), got.Calls)
|
|
}
|
|
summaries.Lock()
|
|
_, kept := summaries.entries[All]
|
|
summaries.Unlock()
|
|
if kept {
|
|
t.Fatal("oversized Sessions retained in summary cache")
|
|
}
|
|
}
|
|
|
|
// Rebuilding an uncached snapshot with a larger budget keeps its version and
|
|
// page key. The preceding query must leave an initialized page map to write.
|
|
func TestUsagePageCacheAfterUncachedQuery(t *testing.T) {
|
|
pageHome(t)
|
|
settleLogClock(t)
|
|
holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local))
|
|
historyLog(t, 1034)
|
|
normalBudget := requestCacheBytes
|
|
cacheBudget(t, 128)
|
|
QueryPage(All, Filter{}, 0, 100)
|
|
logIndex.Lock()
|
|
uncached := logIndex.snapshot.uncached
|
|
logIndex.Unlock()
|
|
if !uncached {
|
|
t.Fatal("fixture must exceed the tiny budget")
|
|
}
|
|
requestCache.Lock()
|
|
key := requestCache.key
|
|
requestCache.Unlock()
|
|
|
|
requestCacheBytes = normalBudget
|
|
got := QueryPage(All, Filter{}, 0, 100)
|
|
equalPage(t, got, pageFromLedger(All, Filter{}, 0, 100, LedgerOf(All, Filter{})))
|
|
requestCache.Lock()
|
|
defer requestCache.Unlock()
|
|
if requestCache.key != key {
|
|
t.Fatal("page key changed instead of exercising the same cache")
|
|
}
|
|
if _, ok := requestCache.pages[pageKey{All, Filter{}, 0, 100}]; !ok {
|
|
t.Fatal("page not cached after rebuilding within budget")
|
|
}
|
|
}
|