usage: refresh caches after same-tick log rewrites (#1328)

* usage: same-tick rewrites refresh cached totals and request pages

Trust change stamps only when they were settled at the snapshot read's
start. Fingerprint recent snapshots and append prefixes, and discard
fingerprint trust when the content changes during a read.

Fixes https://github.com/yetone/magpie/issues/1305

Verified: deterministic old-predicate FAIL/new PASS; usage tests with race;
nogui vet; Linux nogui and Windows builds; usage test cross-compilation for
Windows, Darwin and the unsupported-stamp fallback on FreeBSD.
Full nogui suite exposed the independent sessions TestList empty-session
limit failure. Native Linux GUI vet/build lack pkg-config and GTK/WebKit;
native Windows/NTFS execution was not run.

* usage: keep FILETIME stamp ages valid beyond UnixNano range

Convert whole seconds and the 100ns fraction separately. Checked the epoch, current dates with fractional ticks and year 2500; Windows build and usage test cross-compilation pass. Native Windows execution was not run.

* usage: keep history cached after an append settles

An unchanged log now validates a recent snapshot's nonempty fingerprint
before publishing a settled clone. Preserve its version and sealed blocks
so the summary and page caches stay warm without mutating readers' snapshots.

Follow-up to the review on https://github.com/yetone/magpie/pull/1328,
for https://github.com/yetone/magpie/issues/1305.

On e28e686, the real-clock append/read/settle/read tests fail with a
version bump and 32,428 additional allocations over 4,000 versus 10 rows.
With this change the targeted race run passes, with 165 extra allocations.
The existing performance test now measures this path on the real clock.

Verification uses Go 1.26.8, a temporary HOME and pinned Go caches.
Native Linux GUI checks require missing pkg-config/GTK/WebKit libraries;
native Windows/NTFS execution is not available. No GUI assets change.
Implementation and verification used AI assistance.

Final checks: usage race PASS (421 test results); nogui suite PASS (7,273
test results, 44 packages; 21 skipped tests, 3 packages without tests).
Nogui vet, Linux nogui build, Windows build, and usage test cross-compilation
for Windows amd64, Darwin arm64 and FreeBSD amd64 PASS. Native Linux GUI
vet/build were attempted and failed at the missing pkg-config executable.

internal/usage/cache_bounds_test.go

@@ -46,6 +46,136 @@ func TestUsageSameSizeAndMtimeRewrite(t *testing.T) {
 	}
 }
 
+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 })
+}
+
+func TestUsageRewriteBeforeFingerprintIsNotCached(t *testing.T) {
+	for _, rewriteAt := range []int{1, 2} {
+		t.Run(fmt.Sprint("hash=", 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")
+			}
+			hash := logRecordHash
+			hashCalls := 0
+			rewritten := false
+			logRecordHash = func(path string, n int64) string {
+				hashCalls++
+				if hashCalls == rewriteAt {
+					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)
+					}
+				}
+				return hash(path, n)
+			}
+			t.Cleanup(func() { logRecordHash = hash })
+			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
@@ -130,6 +260,7 @@ func TestUsageLargeSummaryIsCompleteButNotCached(t *testing.T) {
 // 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

internal/usage/incremental_log_test.go

@@ -39,20 +39,40 @@ func historyLog(t testing.TB, n int) {
 	}
 }
 
+// Cache performance tests start after the filesystem's change stamp has settled.
+func settleLogClock(t testing.TB) {
+	t.Helper()
+	old := logIndexNow
+	logIndexNow = func() time.Time { return time.Now().Add(2 * logStampSettle) }
+	t.Cleanup(func() { logIndexNow = old })
+}
+
 func TestUsageOverviewDoesNotReparseHistory(t *testing.T) {
-	pageHome(t)
-	holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local))
-	historyLog(t, 4000)
-	if s := Summarize(Today); s.Calls != 1 {
-		t.Fatal(s.Calls)
+	var allocations [2]float64
+	for i, n := range []int{10, 4000} {
+		pageHome(t)
+		holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local))
+		historyLog(t, n)
+		if s := Summarize(Today); s.Calls != 1 {
+			t.Fatal(s.Calls)
+		}
+		allocations[i] = testing.AllocsPerRun(2, func() {
+			Append(Record{Agent: "codex", Provider: "relay", Model: "m", Input: 1, Status: 200})
+			Summarize(Today)
+			time.Sleep(logStampSettle + 20*time.Millisecond)
+			Summarize(Today)
+		})
 	}
-	if n := testing.AllocsPerRun(2, func() { Summarize(Today) }); n > 1500 {
-		t.Fatalf("unchanged Today reparsed history: %.0f allocations", n)
+	// Measure what history adds, excluding the append and two queries' fixed cost.
+	t.Logf("append + unsettled + settled summary: %.0f allocations over 4000 rows, %.0f over 10", allocations[1], allocations[0])
+	if grown := allocations[1] - allocations[0]; grown > 1500 {
+		t.Fatalf("append then settle reparsed history: %.0f extra allocations", grown)
 	}
 }
 
 func TestUsageViasSkipsOldHistory(t *testing.T) {
 	pageHome(t)
+	settleLogClock(t)
 	historyLog(t, 4000)
 	since := time.Now().Add(-time.Hour)
 	if v := Vias(since); len(v) != 1 || v["codex|s"][0].Calls != 1 {
@@ -115,6 +135,31 @@ func TestLogAppendReusesSealedBlocks(t *testing.T) {
 	}
 }
 
+func TestLogAppendThenSettleReusesHistory(t *testing.T) {
+	pageHome(t)
+	historyLog(t, 4000)
+	before := readLogSnapshot()
+	Append(Record{Agent: "codex", Provider: "relay", Model: "m", Input: 1, Status: 200})
+	appended := readLogSnapshot()
+	if logChangeStamp(appended.info) == "" {
+		t.Skip("filesystem does not expose change time")
+	}
+	if appended.settled || appended.hash == "" {
+		t.Fatal("append must leave a recent snapshot with a fingerprint")
+	}
+	if appended.blocks[0] != before.blocks[0] {
+		t.Fatal("append rebuilt the sealed history")
+	}
+	time.Sleep(logStampSettle + 20*time.Millisecond)
+	settled := readLogSnapshot()
+	if !settled.settled || settled.version != appended.version || settled.blocks[0] != appended.blocks[0] {
+		t.Fatalf("unchanged settled read rebuilt history: version %d -> %d", appended.version, settled.version)
+	}
+	if appended.settled {
+		t.Fatal("promotion mutated the published snapshot")
+	}
+}
+
 func TestLogPartialLineAndTruncation(t *testing.T) {
 	pageHome(t)
 	now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local))
@@ -161,6 +206,7 @@ func TestCachedSummaryRemainsCallerOwned(t *testing.T) {
 }
 
 func BenchmarkIncrementalUsage(b *testing.B) {
+	settleLogClock(b)
 	// benchmark homes are isolated just as pageHome isolates test homes
 	testenv.SetHome(b, b.TempDir())
 	b.Setenv("XDG_CONFIG_HOME", b.TempDir())

internal/usage/log_change_darwin.go

@@ -1,19 +1,19 @@
 package usage
 
 import (
-	"fmt"
 	"os"
 	"syscall"
+	"time"
 )
 
 // ctime changes even when a writer restores the size and modification time.
-func logChangeStamp(info os.FileInfo) string {
+func nativeLogChangeTime(info os.FileInfo) time.Time {
 	if info == nil {
-		return ""
+		return time.Time{}
 	}
 	stat, ok := info.Sys().(*syscall.Stat_t)
 	if !ok {
-		return ""
+		return time.Time{}
 	}
-	return fmt.Sprintf("%d:%d", stat.Ctimespec.Sec, stat.Ctimespec.Nsec)
+	return time.Unix(stat.Ctimespec.Sec, stat.Ctimespec.Nsec)
 }

internal/usage/log_change_linux.go

@@ -1,19 +1,19 @@
 package usage
 
 import (
-	"fmt"
 	"os"
 	"syscall"
+	"time"
 )
 
 // ctime changes even when a writer restores the size and modification time.
-func logChangeStamp(info os.FileInfo) string {
+func nativeLogChangeTime(info os.FileInfo) time.Time {
 	if info == nil {
-		return ""
+		return time.Time{}
 	}
 	stat, ok := info.Sys().(*syscall.Stat_t)
 	if !ok {
-		return ""
+		return time.Time{}
 	}
-	return fmt.Sprintf("%d:%d", stat.Ctim.Sec, stat.Ctim.Nsec)
+	return time.Unix(stat.Ctim.Sec, stat.Ctim.Nsec)
 }

internal/usage/log_change_other.go

@@ -2,8 +2,11 @@
 
 package usage
 
-import "os"
+import (
+	"os"
+	"time"
+)
 
 // FileInfo exposes no portable change time here. Validate the fingerprint
 // instead, so a same-size rewrite with restored mtime cannot return stale rows.
-func logChangeStamp(os.FileInfo) string { return "" }
+func nativeLogChangeTime(os.FileInfo) time.Time { return time.Time{} }

internal/usage/log_change_windows.go

@@ -3,8 +3,8 @@
 package usage
 
 import (
-	"fmt"
 	"os"
+	"time"
 	"unsafe"
 
 	"golang.org/x/sys/windows"
@@ -91,15 +91,16 @@ func stampLogHandle(f *os.File, info os.FileInfo) os.FileInfo {
 	if raw.ChangeTime == 0 {
 		return info
 	}
-	return logFileInfo{FileInfo: info, stamp: fmt.Sprint(raw.ChangeTime)}
+	changed := time.Unix(raw.ChangeTime/10_000_000-11_644_473_600, raw.ChangeTime%10_000_000*100)
+	return logFileInfo{FileInfo: info, changeTime: changed}
 }
 
-// logChangeStamp extracts the stamp captured at snapshot time. It never
+// nativeLogChangeTime extracts the time captured at snapshot time. It never
 // re-opens or re-stats the path: an old snapshot must keep its old stamp even
 // after the log has been rewritten or appended to.
-func logChangeStamp(info os.FileInfo) string {
+func nativeLogChangeTime(info os.FileInfo) time.Time {
 	if stamped, ok := info.(logFileInfo); ok {
-		return stamped.stamp
+		return stamped.changeTime
 	}
-	return ""
+	return time.Time{}
 }

internal/usage/log_change_windows_test.go

@@ -39,6 +39,10 @@ func requireChangeStamp(t *testing.T, path string) string {
 	if stamp == "" {
 		t.Fatal("ChangeTime is available but the snapshot has no stamp")
 	}
+	want := time.Unix(basic.ChangeTime/10_000_000-11_644_473_600, basic.ChangeTime%10_000_000*100)
+	if got := logChangeTime(info); !got.Equal(want) {
+		t.Fatalf("captured ChangeTime %v != FILETIME %v", got, want)
+	}
 	return stamp
 }
 
@@ -122,6 +126,7 @@ func TestLogChangeSnapshotStampImmutable(t *testing.T) {
 
 func TestLogChangeSnapshotReuseWithoutFingerprint(t *testing.T) {
 	pageHome(t)
+	settleLogClock(t)
 	historyLog(t, 1034)
 	first := readLogSnapshot()
 	requireChangeStamp(t, Path())
@@ -141,6 +146,7 @@ func TestLogChangeSnapshotReuseWithoutFingerprint(t *testing.T) {
 
 func TestLogChangeTrustedAppendReuse(t *testing.T) {
 	pageHome(t)
+	settleLogClock(t)
 	historyLog(t, 1034)
 	before := readLogSnapshot()
 	requireChangeStamp(t, Path())

internal/usage/log_file.go

@@ -1,12 +1,26 @@
 package usage
 
-import "os"
+import (
+	"fmt"
+	"os"
+	"time"
+)
 
 // Keep native file identity alongside a change time captured from the same
 // handle. os.SameFile requires the original os.FileInfo, not this wrapper.
 type logFileInfo struct {
 	os.FileInfo
-	stamp string
+	changeTime time.Time
+}
+
+var logChangeTime = nativeLogChangeTime
+
+func logChangeStamp(info os.FileInfo) string {
+	c := logChangeTime(info)
+	if c.IsZero() {
+		return ""
+	}
+	return fmt.Sprintf("%d:%d", c.Unix(), c.Nanosecond())
 }
 
 func sameLogFile(a, b os.FileInfo) bool {

internal/usage/log_file_test.go

@@ -20,7 +20,7 @@ func TestLogFileInfoPreservesIdentity(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
-	wrapped := logFileInfo{FileInfo: first, stamp: "captured"}
+	wrapped := logFileInfo{FileInfo: first}
 	if !sameLogFile(wrapped, second) || !sameLogFile(second, wrapped) || !sameLogFile(wrapped, logFileInfo{FileInfo: second}) {
 		t.Fatal("wrapped stat lost native file identity")
 	}

internal/usage/log_index.go

@@ -14,7 +14,10 @@ import (
 	"time"
 )
 
-const logBlockRows = 512
+const (
+	logBlockRows   = 512
+	logStampSettle = time.Second
+)
 
 // Raw and priced chunks share the request cache budget. Oversized histories
 // remain queryable but their raw blocks are rebuilt instead of retained.
@@ -22,6 +25,7 @@ const logBlockRows = 512
 type logSnapshot struct {
 	bytes        int64
 	uncached     bool
+	settled      bool
 	path         string
 	info         os.FileInfo
 	off          int64
@@ -38,6 +42,9 @@ var logIndex struct {
 	version  uint64
 }
 
+var logIndexNow = time.Now
+var logRecordHash = recordHash
+
 // File writes must never wait for a historical index rebuild.
 var logAppends struct {
 	sync.Mutex
@@ -53,11 +60,23 @@ func logSnapshotFor(metadataOnly bool) *logSnapshot {
 	logIndex.Lock()
 	defer logIndex.Unlock()
 	path := Path()
+	start := logIndexNow()
 	info, err := statLogFile(path)
+	settled := settledLogStamp(info, start)
 	old := logIndex.snapshot
 	unchanged := old != nil && old.path == path && (err != nil && old.info == nil || err == nil && sameLogInfo(old.info, info))
-	if unchanged && info != nil && logChangeStamp(info) == "" {
-		unchanged = old.hash != "" && recordHash(path, info.Size()) == old.hash
+	if unchanged && info != nil {
+		if logChangeStamp(info) == "" || !old.settled {
+			unchanged = old.hash != "" && logRecordHash(path, info.Size()) == old.hash
+			if unchanged && settled {
+				promoted := *old
+				promoted.info, promoted.settled = info, true
+				old = &promoted
+				logIndex.snapshot = old
+			}
+		} else {
+			unchanged = old.settled && settled
+		}
 	}
 	if unchanged && (!old.uncached || metadataOnly) {
 		return old
@@ -66,7 +85,7 @@ func logSnapshotFor(metadataOnly bool) *logSnapshot {
 		logIndex.version++
 	}
 
-	next := &logSnapshot{path: path, info: info, version: logIndex.version, keyProviders: map[string]bool{}}
+	next := &logSnapshot{path: path, info: info, settled: settled, version: logIndex.version, keyProviders: map[string]bool{}}
 	if err != nil {
 		logIndex.snapshot = next
 		return next
@@ -74,8 +93,8 @@ func logSnapshotFor(metadataOnly bool) *logSnapshot {
 	logAppends.Lock()
 	notePath, noteBase, noteLast := logAppends.path, logAppends.base, logAppends.last
 	logAppends.Unlock()
-	trusted := logChangeStamp(info) != "" && notePath == path && sameLogInfo(oldInfo(old), noteBase) && sameLogInfo(info, noteLast)
-	continued := old != nil && old.path == path && old.info != nil && sameLogFile(old.info, info) && info.Size() > old.info.Size() && (trusted || old.hash != "" && recordHash(path, old.info.Size()) == old.hash)
+	trusted := old != nil && old.settled && logChangeStamp(info) != "" && notePath == path && sameLogInfo(oldInfo(old), noteBase) && sameLogInfo(info, noteLast)
+	continued := old != nil && old.path == path && old.info != nil && sameLogFile(old.info, info) && info.Size() > old.info.Size() && (trusted || old.hash != "" && logRecordHash(path, old.info.Size()) == old.hash)
 	if continued && !old.uncached {
 		next.off, next.first = old.off, old.first
 		next.blocks = slices.Clone(old.blocks)
@@ -89,6 +108,9 @@ func logSnapshotFor(metadataOnly bool) *logSnapshot {
 	if _, err = f.Seek(next.off, 0); err != nil {
 		return next
 	}
+	if !trusted || !settled {
+		next.hash = logRecordHash(path, info.Size())
+	}
 	var tail *rowChunk
 	if n := len(next.blocks); n > 0 && next.blocks[n-1].Count < logBlockRows {
 		tail = next.blocks[n-1].writable()
@@ -123,8 +145,10 @@ func logSnapshotFor(metadataOnly bool) *logSnapshot {
 	if tail != nil {
 		next.blocks = append(next.blocks, tail.freeze())
 	}
-	if !trusted || logChangeStamp(info) == "" {
-		next.hash = recordHash(path, info.Size())
+	// A rewrite during the read must not give old blocks the new content's hash.
+	if (!trusted || !settled) && next.hash != logRecordHash(path, info.Size()) {
+		next.hash = ""
+		next.settled = false
 	}
 	logAppends.Lock()
 	// Preserve writes which arrived while this immutable snapshot was built.
@@ -194,6 +218,14 @@ func oldInfo(s *logSnapshot) os.FileInfo {
 	}
 	return s.info
 }
+
+// A read in the change stamp's clock tick cannot prove that a later equal
+// stamp still names the same bytes. Decide before reading, not at reuse time.
+func settledLogStamp(info os.FileInfo, start time.Time) bool {
+	c := logChangeTime(info)
+	return !c.IsZero() && c.Before(start.Add(-logStampSettle))
+}
+
 func sameLogInfo(a, b os.FileInfo) bool {
 	return a != nil && b != nil && sameLogFile(a, b) && a.Size() == b.Size() && a.ModTime().Equal(b.ModTime()) && logChangeStamp(a) == logChangeStamp(b)
 }

internal/usage/priced_blocks_test.go

@@ -24,6 +24,7 @@ func appendAndQueryAllocs(t *testing.T, n int) float64 {
 }
 
 func TestRequestPageAppendDoesNotRepriceHistory(t *testing.T) {
+	settleLogClock(t)
 	holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local))
 	// A query costs a fixed number of allocations that depends on the
 	// machine (on Windows, provider sign-in lookups read the environment and
@@ -96,6 +97,7 @@ func TestRequestPageInvalidatesLivePrice(t *testing.T) {
 }
 
 func BenchmarkRequestPageAfterAppend(b *testing.B) {
+	settleLogClock(b)
 	testenv.SetHome(b, b.TempDir())
 	b.Setenv("XDG_CONFIG_HOME", b.TempDir())
 	b.Setenv("XDG_CACHE_HOME", b.TempDir())