From 7540c378177f473d0f058d8ecea193707ea0e220 Mon Sep 17 00:00:00 2001 From: dborup Date: Tue, 20 Oct 2026 04:55:49 +0000 Subject: [PATCH 1/6] test(server): reproduce retained-history coverage lost to load-time eviction (#509) Retention or memory eviction while the startup load runs, and database retention deleting counted rows before the loader reaches them, leave loadCoverageRatio below 1, so node activity24h, Regions coverage and the #494 analytics coverage stay unknown or load_failed until a restart. Also pin that a row the loader never read keeps coverage unknown, which the current ratio gate certifies. Co-Authored-By: Claude Opus 5.5 --- cmd/server/history_coverage_509_test.go | 286 ++++++++++++++++++++++++ 1 file changed, 286 insertions(+) create mode 100644 cmd/server/history_coverage_509_test.go diff --git a/cmd/server/history_coverage_509_test.go b/cmd/server/history_coverage_509_test.go new file mode 100644 index 000000000..45bc2f54e --- /dev/null +++ b/cmd/server/history_coverage_509_test.go @@ -0,0 +1,286 @@ +package main + +import ( + "database/sql" + "path/filepath" + "testing" + "time" +) + +// #509: retained-history coverage (node activity24h / My Mesh, Regions and the +// #494 analytics coverage) must not turn unknown just because retention or +// eviction removed rows while the startup load was running, and must still +// refuse to claim coverage for rows that were genuinely never loaded. + +const coverage509RetentionHours = 48 + +// coverage509Rows seeds `regular` rows spread over the last 47h (id order = +// FirstSeen order, first_seen == last_seen) after `reheard` long-lived +// transmissions whose FirstSeen is 60h old but whose last_seen falls inside +// the 48h window. The loader selects rows by last_seen, retention evicts by +// FirstSeen: the re-heard rows are loaded and then evicted at the next tick. +func coverage509Rows(t *testing.T, now time.Time, reheard, regular int, reheardLastSeen time.Duration) string { + t.Helper() + dbPath := filepath.Join(t.TempDir(), "coverage509.db") + seedTestDBRows(t, dbPath, reheard+regular, 1, func(i int) (string, int64) { + if i <= reheard { + return now.Add(-60 * time.Hour).Format(time.RFC3339), now.Add(-reheardLastSeen).Unix() + } + step := 47 * time.Hour / time.Duration(regular) + ts := now.Add(-47*time.Hour + time.Duration(i-reheard-1)*step) + return ts.Format(time.RFC3339), ts.Unix() + }) + return dbPath +} + +func openCoverage509Store(t *testing.T, dbPath string, cfg *PacketStoreConfig) *PacketStore { + t.Helper() + db, err := OpenDB(dbPath) + if err != nil { + t.Fatalf("OpenDB: %v", err) + } + t.Cleanup(func() { db.conn.Close() }) + return NewPacketStore(db, cfg) +} + +func coverage509Starts(store *PacketStore, now time.Time) (retained, activity time.Time, analytics NodeAnalyticsCoverage) { + ratio := store.LoadCoverageRatio() + store.mu.RLock() + defer store.mu.RUnlock() + return store.retainedHistoryCoverageStartLocked(now, ratio), + store.nodeActivityCoverageStartLocked(now, ratio), + store.nodeAnalyticsCoverageLocked(2, now) +} + +func assertCoverage509Known(t *testing.T, store *PacketStore, now time.Time) { + t.Helper() + if !store.backgroundLoadDone.Load() || store.backgroundLoadFailed.Load() { + t.Fatalf("load did not finish cleanly: done=%v failed=%v err=%q", + store.backgroundLoadDone.Load(), store.backgroundLoadFailed.Load(), store.BackgroundLoadError()) + } + retained, activity, _ := coverage509Starts(store, now) + floor := now.Add(-coverage509RetentionHours * time.Hour) + if retained.IsZero() || retained.Before(floor) || retained.After(floor.Add(time.Hour)) { + t.Fatalf("retained coverage start=%v, want known near the retention floor %v (ratio=%.4f)", + retained, floor, store.LoadCoverageRatio()) + } + if activity.IsZero() || activity.After(now.Add(-24*time.Hour)) { + t.Fatalf("activity24h coverage start=%v, want known and before %v", activity, now.Add(-24*time.Hour)) + } +} + +// A retention tick between two background chunks evicts the re-heard rows +// the first chunk loaded. They were counted in totalInDB and are gone from +// s.packets, so the old exact-ratio gate stayed unknown until a restart. +func TestCoverage509RetentionEvictionDuringBackgroundLoad(t *testing.T) { + now := time.Now().UTC() + dbPath := coverage509Rows(t, now, 5, 200, 30*time.Hour) + store := openCoverage509Store(t, dbPath, &PacketStoreConfig{RetentionHours: coverage509RetentionHours, HotStartupHours: 12}) + chunks := 0 + store.loadChunkScannedHook = func() { + if chunks++; chunks == 2 { + if n := store.RunEviction(); n != 5 { + t.Errorf("retention tick evicted %d rows, want the 5 re-heard rows", n) + } + } + } + if err := store.RunStartupLoad(50); err != nil { + t.Fatalf("RunStartupLoad: %v", err) + } + if ratio := store.LoadCoverageRatio(); ratio >= 1 { + t.Fatalf("fixture did not reproduce #509: loadCoverageRatio=%.4f", ratio) + } + assertCoverage509Known(t, store, now) + // #494: analytics coverage is not a failed load either, and a retention + // eviction of 60h-old rows must not shrink it to the 12h hot window. + _, _, analytics := coverage509Starts(store, now) + from, err := time.Parse(time.RFC3339Nano, analytics.From) + if err != nil || analytics.Reason != "available_history" || from.After(now.Add(-46*time.Hour)) { + t.Fatalf("analytics coverage=%+v, want available_history from ~47h ago", analytics) + } +} + +// A retention tick right before the background count evicts re-heard rows +// that the hot window loaded; they are still counted in totalInDB. +func TestCoverage509RetentionEvictionAtBackgroundLoadStart(t *testing.T) { + now := time.Now().UTC() + dbPath := coverage509Rows(t, now, 5, 200, time.Hour) + store := openCoverage509Store(t, dbPath, &PacketStoreConfig{RetentionHours: coverage509RetentionHours, HotStartupHours: 12}) + store.bgLoaderEntryHook = func() { store.RunEviction() } + if err := store.RunStartupLoad(50); err != nil { + t.Fatalf("RunStartupLoad: %v", err) + } + if ratio := store.LoadCoverageRatio(); ratio >= 1 { + t.Fatalf("fixture did not reproduce #509: loadCoverageRatio=%.4f", ratio) + } + assertCoverage509Known(t, store, now) +} + +// hotStartupHours=0: the eviction ticker starts at the first chunk, while +// LoadChunked is still loading the rest of the retention window. +func TestCoverage509RetentionEvictionDuringSynchronousLoad(t *testing.T) { + now := time.Now().UTC() + dbPath := coverage509Rows(t, now, 5, 200, 30*time.Hour) + store := openCoverage509Store(t, dbPath, &PacketStoreConfig{RetentionHours: coverage509RetentionHours}) + first := true + store.OnChunkLoaded(func(int, int) { + if first { + first = false + store.RunEviction() + } + }) + if err := store.RunStartupLoad(50); err != nil { + t.Fatalf("RunStartupLoad: %v", err) + } + if ratio := store.LoadCoverageRatio(); ratio >= 1 { + t.Fatalf("fixture did not reproduce #509: loadCoverageRatio=%.4f", ratio) + } + assertCoverage509Known(t, store, now) +} + +// Database retention (the ingestor prunes by first_seen) deletes counted +// rows before the background loader reaches their window. Rows that no +// longer exist are not missing from memory. +func TestCoverage509DatabaseRetentionDuringBackgroundLoad(t *testing.T) { + now := time.Now().UTC() + dbPath := coverage509Rows(t, now, 5, 200, 40*time.Hour) + store := openCoverage509Store(t, dbPath, &PacketStoreConfig{RetentionHours: coverage509RetentionHours, HotStartupHours: 12}) + writer, err := sql.Open("sqlite", dbPath+"?_journal_mode=WAL") + if err != nil { + t.Fatal(err) + } + defer writer.Close() + chunks := 0 + store.loadChunkScannedHook = func() { + if chunks++; chunks == 1 { + // PREFLIGHT: async=true reason="unit-test writer standing in for ingestor retention on an ephemeral DB" + if _, err := writer.Exec(`DELETE FROM observations WHERE transmission_id <= 5`); err != nil { + t.Error(err) + } + // PREFLIGHT: async=true reason="unit-test writer standing in for ingestor retention on an ephemeral DB" + if _, err := writer.Exec(`DELETE FROM transmissions WHERE id <= 5`); err != nil { + t.Error(err) + } + } + } + if err := store.RunStartupLoad(50); err != nil { + t.Fatalf("RunStartupLoad: %v", err) + } + if ratio := store.LoadCoverageRatio(); ratio >= 1 { + t.Fatalf("fixture did not reproduce #509: loadCoverageRatio=%.4f", ratio) + } + assertCoverage509Known(t, store, now) +} + +// A memory-cap eviction during the background load removes rows inside the +// retention window; older chunks merged afterwards put older rows back at +// s.packets[0]. Coverage may only start after the newest evicted row. +func TestCoverage509MemoryEvictionDuringBackgroundLoad(t *testing.T) { + now := time.Now().UTC() + dbPath := coverage509Rows(t, now, 0, 200, 0) + store := openCoverage509Store(t, dbPath, &PacketStoreConfig{RetentionHours: coverage509RetentionHours, HotStartupHours: 12, MaxMemoryMB: 1}) + var lastEvicted time.Time + chunks := 0 + store.loadChunkScannedHook = func() { + if chunks++; chunks != 1 { + return + } + store.mu.Lock() + before := append([]*StoreTx(nil), store.packets...) + tracked := store.trackedBytes + store.trackedBytes = 1 << 30 + store.mu.Unlock() + if store.RunEviction() == 0 { + t.Error("memory eviction did not run") + } + store.mu.Lock() + store.trackedBytes = tracked + for _, tx := range before { + if store.byTxID[tx.ID] == nil { + if at, _ := time.Parse(time.RFC3339, tx.FirstSeen); at.After(lastEvicted) { + lastEvicted = at + } + } + } + store.mu.Unlock() + } + if err := store.RunStartupLoad(50); err != nil { + t.Fatalf("RunStartupLoad: %v", err) + } + if lastEvicted.IsZero() { + t.Fatal("fixture did not record the eviction edge") + } + store.mu.RLock() + first, _ := time.Parse(time.RFC3339, store.packets[0].FirstSeen) + store.mu.RUnlock() + if !first.Before(lastEvicted.Add(-time.Hour)) { + t.Fatalf("fixture did not merge older rows below the eviction edge: first=%v edge=%v", first, lastEvicted) + } + retained, _, _ := coverage509Starts(store, now) + if retained.IsZero() || !retained.After(lastEvicted) { + t.Fatalf("coverage start=%v, want known and after the newest evicted row %v", retained, lastEvicted) + } +} + +// A row inside the window that the loader never read (an un-backfilled +// last_seen=0 row) is genuinely missing: coverage must stay unknown. +func TestCoverage509UnloadedRowKeepsCoverageUnknown(t *testing.T) { + now := time.Now().UTC() + dbPath := filepath.Join(t.TempDir(), "coverage509.db") + seedTestDBRows(t, dbPath, 200, 1, func(i int) (string, int64) { + ts := now.Add(-47*time.Hour + time.Duration(i)*14*time.Minute) + if i == 100 { + return ts.Format(time.RFC3339), 0 + } + return ts.Format(time.RFC3339), ts.Unix() + }) + for _, hot := range []float64{0, 12} { + store := openCoverage509Store(t, dbPath, &PacketStoreConfig{RetentionHours: coverage509RetentionHours, HotStartupHours: hot}) + if err := store.RunStartupLoad(50); err != nil { + t.Fatalf("RunStartupLoad: %v", err) + } + retained, activity, analytics := coverage509Starts(store, now) + if !retained.IsZero() || !activity.IsZero() { + t.Fatalf("hot=%g: unloaded row was certified: retained=%v activity=%v", hot, retained, activity) + } + if hot > 0 && analytics.Reason != "load_failed" { + t.Fatalf("hot=%g: analytics certified an incomplete background load: %+v", hot, analytics) + } + } +} + + +// Eviction ticks and coverage readers run concurrently with the startup +// load, as in production. Run with -race: the verification takes s.mu only +// around the in-memory reads and never across its SQL count (#495). +func TestCoverage509ConcurrentEvictionAndReaders(t *testing.T) { + now := time.Now().UTC() + dbPath := coverage509Rows(t, now, 20, 400, 30*time.Hour) + store := openCoverage509Store(t, dbPath, &PacketStoreConfig{RetentionHours: coverage509RetentionHours, HotStartupHours: 12}) + done := make(chan struct{}) + stopped := make(chan struct{}) + go func() { + defer close(stopped) + for { + select { + case <-done: + return + default: + store.RunEviction() + coverage509Starts(store, now) + } + } + }() + err := store.RunStartupLoad(25) + close(done) + <-stopped + if err != nil { + t.Fatalf("RunStartupLoad: %v", err) + } + // Ticks may land between the two counts often enough to exhaust the + // retries; the result must then be unknown, never an earlier start. + if retained, _, _ := coverage509Starts(store, now); !retained.IsZero() && + retained.Before(now.Add(-coverage509RetentionHours*time.Hour)) { + t.Fatalf("coverage start %v precedes the retention floor", retained) + } +} From 3650261bad316b3baf7dae64c68928caeae1a106 Mon Sep 17 00:00:00 2001 From: dborup Date: Tue, 20 Oct 2026 05:08:29 +0000 Subject: [PATCH 2/6] fix(server): prove retained-history coverage instead of requiring an exact load ratio (#509) Coverage for node activity24h, Regions and the #494 analytics no longer requires loadCoverageRatio == 1. That ratio divides the rows in memory after loading by a count taken before it, so rows that retention or eviction removed meanwhile, or that database retention pruned, read as missing until the next restart. After a successful startup load, verifyRetainedHistory compares the DB count of transmissions with first_seen at or after the edge (and id <= maxTxID) with the in-memory count. The edge is the load floor moved past the newest evicted row, so evicted rows are not part of the claim; pruned rows are no longer counted. A capped or failed load is never verified, and any other mismatch keeps coverage unknown. The SQL count runs without s.mu (#495); an eviction between the two counts repeats the check. The analytics eviction edge now records only the eviction boundary, so one retention eviction of an old re-heard row during the background fill no longer shrinks analytics coverage to the hot window. Co-Authored-By: Claude Opus 5.5 --- cmd/server/chunked_load.go | 1 + cmd/server/history_coverage.go | 119 ++++++++++++++++++++++++ cmd/server/history_coverage_509_test.go | 61 +++++++++++- cmd/server/node_activity_24h.go | 43 ++++----- cmd/server/node_activity_304_test.go | 34 +++---- cmd/server/node_analytics_coverage.go | 18 ++-- cmd/server/regions_observed_test.go | 26 ++++-- cmd/server/repeater_enrich_bulk.go | 6 +- cmd/server/store.go | 24 +++-- docs/api-spec.md | 10 +- 10 files changed, 262 insertions(+), 80 deletions(-) create mode 100644 cmd/server/history_coverage.go diff --git a/cmd/server/chunked_load.go b/cmd/server/chunked_load.go index 6d9c82886..d75d678b6 100644 --- a/cmd/server/chunked_load.go +++ b/cmd/server/chunked_load.go @@ -274,6 +274,7 @@ func (s *PacketStore) RunStartupLoad(chunkSize int) error { s.bgErrMu.Unlock() log.Printf("[store] RunStartupLoad: hotStartupHours=0 — background fill loader SKIPPED (coverage=%.1f%%, loaded=%d, totalInDB=%d)", ratio*100, loadedCount, totalInDB) + s.publishRetainedHistory() s.backgroundLoadDone.Store(true) s.backgroundLoadProgress.Store(100) return nil diff --git a/cmd/server/history_coverage.go b/cmd/server/history_coverage.go new file mode 100644 index 000000000..6560a9399 --- /dev/null +++ b/cmd/server/history_coverage.go @@ -0,0 +1,119 @@ +package main + +import ( + "log" + "sort" + "time" +) + +// retainedHistoryVerifyAttempts bounds the retries when an eviction moves +// the verification edge between the SQL count and the in-memory count. +const retainedHistoryVerifyAttempts = 3 + +// retainedHistoryEdgeLocked returns the instant from which every transmission +// is expected in memory: the load floor, moved past every row an eviction +// (retention or memory cap) removed since the load began, rounded up to a +// whole second. maxID is the highest transmission id the store has reached; +// rows above it are not ingested yet and are no evidence either way. ok is +// false when nothing can be verified: not loaded, empty, capped or failed. +func (s *PacketStore) retainedHistoryEdgeLocked() (from time.Time, maxID int, ok bool) { + h := &s.analyticsHistory + if !s.loaded || len(s.packets) == 0 || h.cap || h.failed { + return time.Time{}, 0, false + } + from, err := time.Parse(time.RFC3339Nano, s.oldestLoaded) + if err != nil { + return time.Time{}, 0, false + } + if h.evictedFrom.After(from) { + from = h.evictedFrom + } + from = from.UTC() + if whole := from.Truncate(time.Second); whole.Before(from) { + from = whole.Add(time.Second) + } + return from, s.maxTxID, true +} + +// countRetainedSinceLocked counts the in-memory transmissions with +// FirstSeen >= bound and ID <= maxID. s.packets is sorted by FirstSeen, so +// they are a suffix; the per-row check keeps an out-of-order row from being +// counted, which could otherwise hide a missing one. +func (s *PacketStore) countRetainedSinceLocked(bound string, maxID int) int { + i := sort.Search(len(s.packets), func(i int) bool { return s.packets[i].FirstSeen >= bound }) + n := 0 + for _, tx := range s.packets[i:] { + if tx.ID <= maxID && tx.FirstSeen >= bound { + n++ + } + } + return n +} + +// verifyRetainedHistory returns the start of the retained history that is +// proven complete, or zero when it cannot be proven (#509). It counts the DB +// rows with first_seen at or after the edge and compares them with the rows +// in memory. The old gate required loadCoverageRatio == 1, which divides the +// rows in memory after loading by a count taken before it: rows that +// retention or eviction removed in between, or that the ingestor pruned from +// the DB, read as missing until the next restart. Here evicted rows lie below +// the edge, and pruned rows are no longer counted. +// +// first_seen is compared as a string on both sides. The bound is the whole +// second formatted without its zone suffix, which sorts at or below every +// canonical UTC stamp of that second ("…:05Z", "…:05.123Z") and above every +// stamp of the second before, so the string test equals the instant test +// (see #351 F6). +// +// The SQL count runs without s.mu (#495). An eviction between the two counts +// moves the edge; the check is then repeated against the new edge. +func (s *PacketStore) verifyRetainedHistory() time.Time { + for attempt := 0; attempt < retainedHistoryVerifyAttempts; attempt++ { + s.mu.RLock() + from, maxID, ok := s.retainedHistoryEdgeLocked() + s.mu.RUnlock() + if !ok { + return time.Time{} + } + bound := from.Format("2006-01-02T15:04:05") + var inDB int + if err := s.db.conn.QueryRow(`SELECT COUNT(*) FROM transmissions WHERE first_seen >= ? AND id <= ?`, + bound, maxID).Scan(&inDB); err != nil { + log.Printf("[store] retained history unverified: count failed: %v", err) + return time.Time{} + } + if s.retainedHistoryCountedHook != nil { + s.retainedHistoryCountedHook() + } + s.mu.RLock() + again, _, ok := s.retainedHistoryEdgeLocked() + inMemory := 0 + if ok && again.Equal(from) { + inMemory = s.countRetainedSinceLocked(bound, maxID) + } + s.mu.RUnlock() + if !ok { + return time.Time{} + } + if !again.Equal(from) { + continue + } + if inMemory != inDB { + log.Printf("[store] retained history unverified: %d of %d transmissions since %s in memory", inMemory, inDB, bound) + return time.Time{} + } + return from + } + log.Printf("[store] retained history unverified: eviction moved the edge %d times", retainedHistoryVerifyAttempts) + return time.Time{} +} + +// publishRetainedHistory verifies the retained history and records the +// result for the coverage readers. It returns whether it was verified. +func (s *PacketStore) publishRetainedHistory() bool { + from := s.verifyRetainedHistory() + s.mu.Lock() + s.retainedHistoryFrom = from + s.mu.Unlock() + return !from.IsZero() +} diff --git a/cmd/server/history_coverage_509_test.go b/cmd/server/history_coverage_509_test.go index 45bc2f54e..0b00658f0 100644 --- a/cmd/server/history_coverage_509_test.go +++ b/cmd/server/history_coverage_509_test.go @@ -44,11 +44,10 @@ func openCoverage509Store(t *testing.T, dbPath string, cfg *PacketStoreConfig) * } func coverage509Starts(store *PacketStore, now time.Time) (retained, activity time.Time, analytics NodeAnalyticsCoverage) { - ratio := store.LoadCoverageRatio() store.mu.RLock() defer store.mu.RUnlock() - return store.retainedHistoryCoverageStartLocked(now, ratio), - store.nodeActivityCoverageStartLocked(now, ratio), + return store.retainedHistoryCoverageStartLocked(now), + store.nodeActivityCoverageStartLocked(now), store.nodeAnalyticsCoverageLocked(2, now) } @@ -249,6 +248,40 @@ func TestCoverage509UnloadedRowKeepsCoverageUnknown(t *testing.T) { } } +// A retention tick between the SQL count and the in-memory count evicts rows +// the SQL count included. The edge moved, so the check is repeated against +// the new edge instead of reporting those rows as missing. +func TestCoverage509EvictionBetweenCountsRetries(t *testing.T) { + now := time.Now().UTC() + dbPath := coverage509Rows(t, now, 0, 200, 0) + store := openCoverage509Store(t, dbPath, &PacketStoreConfig{RetentionHours: coverage509RetentionHours, HotStartupHours: 12}) + counted := 0 + var lastEvicted time.Time + store.retainedHistoryCountedHook = func() { + if counted++; counted == 1 { + // Stand-in for a later tick: the oldest rows aged out. + store.mu.Lock() + evicted := append([]*StoreTx(nil), store.packets[:4]...) + store.invalidateNodeAnalyticsEvictionLocked(evicted) + store.packets = store.packets[4:] + for _, tx := range evicted { + delete(store.byTxID, tx.ID) + } + store.mu.Unlock() + lastEvicted, _ = time.Parse(time.RFC3339, evicted[3].FirstSeen) + } + } + if err := store.RunStartupLoad(50); err != nil { + t.Fatalf("RunStartupLoad: %v", err) + } + if counted < 2 { + t.Fatalf("verification was not repeated after the edge moved (%d counts)", counted) + } + retained, _, _ := coverage509Starts(store, now) + if retained.IsZero() || !retained.After(lastEvicted) || retained.After(lastEvicted.Add(time.Hour)) { + t.Fatalf("coverage start=%v, want known just after the newest evicted row %v", retained, lastEvicted) + } +} // Eviction ticks and coverage readers run concurrently with the startup // load, as in production. Run with -race: the verification takes s.mu only @@ -284,3 +317,25 @@ func TestCoverage509ConcurrentEvictionAndReaders(t *testing.T) { t.Fatalf("coverage start %v precedes the retention floor", retained) } } + +// Capped and failed loads stay unknown however the counts compare: a capped +// load omits rows above the store's highest id, and a failed load is +// reported as failed by the #494 analytics coverage as well. +func TestCoverage509EdgeRefusesCappedOrFailedLoad(t *testing.T) { + now := time.Now().UTC() + s := &PacketStore{loaded: true, maxTxID: 7, oldestLoaded: now.Add(-time.Hour).Format(time.RFC3339Nano), + packets: []*StoreTx{{ID: 7, FirstSeen: now.Format(time.RFC3339)}}} + s.analyticsHistory.evictedFrom = now.Add(-30*time.Minute + time.Nanosecond) + from, maxID, ok := s.retainedHistoryEdgeLocked() + if !ok || maxID != 7 || !from.Equal(now.Add(-30*time.Minute).Truncate(time.Second).Add(time.Second)) { + t.Fatalf("edge=%v maxID=%d ok=%v, want the eviction edge rounded up to a whole second", from, maxID, ok) + } + s.analyticsHistory.cap = true + if _, _, ok := s.retainedHistoryEdgeLocked(); ok { + t.Fatal("capped load must not be verifiable") + } + s.analyticsHistory.cap, s.analyticsHistory.failed = false, true + if _, _, ok := s.retainedHistoryEdgeLocked(); ok { + t.Fatal("failed load must not be verifiable") + } +} diff --git a/cmd/server/node_activity_24h.go b/cmd/server/node_activity_24h.go index e0295f16d..9bdfe9d95 100644 --- a/cmd/server/node_activity_24h.go +++ b/cmd/server/node_activity_24h.go @@ -80,47 +80,36 @@ func (a *NodeActivity24h) add(tx *StoreTx) { } // nodeActivityCoverageStartLocked returns zero unless load and retention -// provide positive evidence of continuous in-memory coverage. A memory cap -// can evict the oldest rows after oldestLoaded was set, so use the current -// first row as the stricter lower bound when it is enabled. -// -// #351 F4: loadCoverage is read by the caller (GetNodeHealth) BEFORE it -// takes s.mu and passed in here, so this function never acquires bgErrMu -// while holding s.mu. bgErrMu exists precisely so its readers need not -// synchronise on s.mu (store.go:530); nesting s.mu → bgErrMu would be the -// first such site in the codebase and would quietly undermine that contract. -func (s *PacketStore) nodeActivityCoverageStartLocked(now time.Time, loadCoverage float64) time.Time { +// provide positive evidence of continuous in-memory coverage. +func (s *PacketStore) nodeActivityCoverageStartLocked(now time.Time) time.Time { // Preserve the existing 24h health contract while other views can expose - // a shorter known interval as partial history. + // a shorter known interval as partial history: unlimited retention with + // a hot window shorter than 24h has no background fill to reach 24h. if (s.retentionHours > 0 && s.retentionHours < 24) || - (loadCoverage < 1 && s.retentionHours <= 0 && s.hotStartupHours < 24) { + (s.retentionHours <= 0 && s.hotStartupHours > 0 && s.hotStartupHours < 24) { return time.Time{} } - return s.retainedHistoryCoverageStartLocked(now, loadCoverage) + return s.retainedHistoryCoverageStartLocked(now) } // retainedHistoryCoverageStartLocked describes the known in-memory history, -// independent of the requested display window. Caller reads loadCoverage -// before taking s.mu; no bgErrMu acquisition is allowed under s.mu. -func (s *PacketStore) retainedHistoryCoverageStartLocked(now time.Time, loadCoverage float64) time.Time { +// independent of the requested display window. +func (s *PacketStore) retainedHistoryCoverageStartLocked(now time.Time) time.Time { if !s.loaded || !s.backgroundLoadDone.Load() || s.backgroundLoadFailed.Load() || len(s.packets) == 0 { return time.Time{} } // The startup "done" gate accepts 90% of DB rows. That is not enough - // to call every empty hour a confirmed zero; require the exact count. - // Unlimited retention with a hot-start window has no background fill and - // leaves loadCoverageRatio at zero. The hot window proves coverage only - // without a memory cap: capped startup can omit newer rows while still - // retaining a much older first row. An old floor alone cannot prove that - // the interval after it was loaded completely. - if loadCoverage < 1 && !(s.retentionHours <= 0 && s.hotStartupHours > 0 && s.maxMemoryMB <= 0) { - return time.Time{} - } - coverage, err := time.Parse(time.RFC3339Nano, s.oldestLoaded) - if err != nil { + // to call every empty hour a confirmed zero: startup must have proven + // the history complete (verifyRetainedHistory, #509). That proof also + // covers a capped load, which can omit newer rows while still retaining + // a much older first row. + coverage := s.retainedHistoryFrom + if coverage.IsZero() { return time.Time{} } + // A memory cap can evict the oldest rows after startup, so use the + // current first row as the stricter lower bound when it is enabled. if s.maxMemoryMB > 0 { first, err := time.Parse(time.RFC3339Nano, s.packets[0].FirstSeen) if err != nil { diff --git a/cmd/server/node_activity_304_test.go b/cmd/server/node_activity_304_test.go index 8820698b5..47205a2b1 100644 --- a/cmd/server/node_activity_304_test.go +++ b/cmd/server/node_activity_304_test.go @@ -62,9 +62,9 @@ func TestNodeHealthActivity24hUsesFullByNodeIndex(t *testing.T) { srv.store.mu.Lock() srv.store.byNode[pubkey] = packets srv.store.loaded = true - srv.store.loadCoverageRatio = 1 srv.store.retentionHours = 168 srv.store.oldestLoaded = start.Add(-time.Hour).Format(time.RFC3339) + srv.store.retainedHistoryFrom = start.Add(-time.Hour) srv.store.packets = []*StoreTx{{ID: 100, FirstSeen: srv.store.oldestLoaded}} srv.store.backgroundLoadDone.Store(true) srv.store.mu.Unlock() @@ -100,49 +100,49 @@ func TestNodeHealthActivity24hUsesFullByNodeIndex(t *testing.T) { func TestNodeActivity24hCoverageRequiresLoadedHistory(t *testing.T) { now := time.Date(2026, 10, 7, 13, 17, 0, 0, time.UTC) start := now.Add(-24 * time.Hour) - s := &PacketStore{loaded: true, loadCoverageRatio: 1, oldestLoaded: start.Add(-time.Hour).Format(time.RFC3339), retentionHours: 168, - packets: []*StoreTx{{FirstSeen: start.Add(-time.Hour).Format(time.RFC3339)}}} + verified := start.Add(-time.Hour) + s := &PacketStore{loaded: true, retainedHistoryFrom: verified, oldestLoaded: verified.Format(time.RFC3339), retentionHours: 168, + packets: []*StoreTx{{FirstSeen: verified.Format(time.RFC3339)}}} s.backgroundLoadDone.Store(true) - if got := s.nodeActivityCoverageStartLocked(now, s.loadCoverageRatio); got.After(start) || got.IsZero() { + if got := s.nodeActivityCoverageStartLocked(now); got.After(start) || got.IsZero() { t.Fatalf("complete load coverage=%v", got) } - s.loadCoverageRatio = 0.90 - if got := s.nodeActivityCoverageStartLocked(now, s.loadCoverageRatio); !got.IsZero() { - t.Fatalf("90%% startup gate is not full coverage, got %v", got) + s.retainedHistoryFrom = time.Time{} // e.g. the 90% startup gate passed without proof + if got := s.nodeActivityCoverageStartLocked(now); !got.IsZero() { + t.Fatalf("unverified history is not full coverage, got %v", got) } + s.retainedHistoryFrom = verified s.retentionHours = 0 s.hotStartupHours = 25 - s.loadCoverageRatio = 0 - if got := s.nodeActivityCoverageStartLocked(now, s.loadCoverageRatio); got.After(start) || got.IsZero() { + if got := s.nodeActivityCoverageStartLocked(now); got.After(start) || got.IsZero() { t.Fatalf("unlimited retention with a fully loaded 25h hot window must be complete, got %v", got) } s.hotStartupHours = 12 - if got := s.nodeActivityCoverageStartLocked(now, s.loadCoverageRatio); !got.IsZero() { + if got := s.nodeActivityCoverageStartLocked(now); !got.IsZero() { t.Fatalf("a 12h hot window cannot prove 24h coverage, got %v", got) } s.hotStartupHours = 0 - s.loadCoverageRatio = 1 // RunStartupLoad sets this after full synchronous loading. - if got := s.nodeActivityCoverageStartLocked(now, s.loadCoverageRatio); got.After(start) || got.IsZero() { + if got := s.nodeActivityCoverageStartLocked(now); got.After(start) || got.IsZero() { t.Fatalf("unlimited retention with no hot window loads full DB, got %v", got) } s.retentionHours = 168 s.maxMemoryMB = 100 s.packets[0].FirstSeen = start.Add(time.Hour).Format(time.RFC3339) - if got := s.nodeActivityCoverageStartLocked(now, s.loadCoverageRatio); !got.After(start) { + if got := s.nodeActivityCoverageStartLocked(now); !got.After(start) { t.Fatalf("memory cap evicted first hour, coverage=%v", got) } s.backgroundLoadFailed.Store(true) - if got := s.nodeActivityCoverageStartLocked(now, s.loadCoverageRatio); !got.IsZero() { + if got := s.nodeActivityCoverageStartLocked(now); !got.IsZero() { t.Fatalf("failed background load must be unknown, coverage=%v", got) } s.backgroundLoadFailed.Store(false) s.retentionHours = 12 - if got := s.nodeActivityCoverageStartLocked(now, s.loadCoverageRatio); !got.IsZero() { + if got := s.nodeActivityCoverageStartLocked(now); !got.IsZero() { t.Fatalf("12h retention cannot cover 24h, coverage=%v", got) } s.retentionHours = 168 s.packets = nil - if got := s.nodeActivityCoverageStartLocked(now, s.loadCoverageRatio); !got.IsZero() { + if got := s.nodeActivityCoverageStartLocked(now); !got.IsZero() { t.Fatalf("empty index cannot prove coverage, coverage=%v", got) } } @@ -289,7 +289,7 @@ func Test351F1StartupCoverageHonoursRetentionWindow(t *testing.T) { "instead of the retained window (finding 1)", store.loadCoverageRatio) } store.mu.RLock() - cov := store.nodeActivityCoverageStartLocked(now, store.loadCoverageRatio) + cov := store.nodeActivityCoverageStartLocked(now) store.mu.RUnlock() if cov.IsZero() || cov.After(windowStart) { t.Fatalf("24h coverage gate must prove completeness when 7+ days of retained "+ diff --git a/cmd/server/node_analytics_coverage.go b/cmd/server/node_analytics_coverage.go index b13edb3bb..d5b8cb7fd 100644 --- a/cmd/server/node_analytics_coverage.go +++ b/cmd/server/node_analytics_coverage.go @@ -29,7 +29,7 @@ type nodeAnalyticsHistory struct { cap bool reason string loadCutoff time.Time - evictedFrom time.Time + evictedFrom time.Time // newest evicted FirstSeen (+1 ns) since the load began observedFrom time.Time lateEvicted int } @@ -181,20 +181,24 @@ func (s *PacketStore) invalidateNodeAnalyticsEvictionLocked(removed []*StoreTx) for _, tx := range removed { edge, ok := parseNodeAnalyticsTime(tx.FirstSeen) if !ok { - h.from = time.Now().UTC() + edge = time.Now().UTC() } else { edge = edge.Add(time.Nanosecond) - if edge.After(h.from) { - h.from = edge - } for _, obs := range tx.Observations { if at, ok := parseNodeAnalyticsTime(obs.Timestamp); ok && !at.Before(edge) { h.lateEvicted++ } } } - if h.from.After(h.evictedFrom) { - h.evictedFrom = h.from + if edge.After(h.from) { + h.from = edge + } + // #509: only the eviction boundary itself. Folding in h.from, the + // provisional hot-window floor while the background fill runs, made + // one retention eviction of an old re-heard row shrink the final + // coverage to the hot window. + if edge.After(h.evictedFrom) { + h.evictedFrom = edge } } if len(removed) > 0 { diff --git a/cmd/server/regions_observed_test.go b/cmd/server/regions_observed_test.go index f52382750..18bfacec2 100644 --- a/cmd/server/regions_observed_test.go +++ b/cmd/server/regions_observed_test.go @@ -21,8 +21,9 @@ func regionsObservedFixture(t testing.TB) (*Server, time.Time, string) { } now := time.Now().UTC().Truncate(time.Second) store := NewPacketStore(db, nil) - store.loaded, store.retentionHours, store.loadCoverageRatio = true, 168, 1 - store.oldestLoaded = now.Add(-8 * 24 * time.Hour).Format(time.RFC3339Nano) + store.loaded, store.retentionHours = true, 168 + store.retainedHistoryFrom = now.Add(-8 * 24 * time.Hour) + store.oldestLoaded = store.retainedHistoryFrom.Format(time.RFC3339Nano) store.packets = []*StoreTx{{FirstSeen: store.oldestLoaded}} store.backgroundLoadDone.Store(true) store.pathHopReady.Store(true) @@ -168,38 +169,43 @@ func TestRetainedHistoryCoverageForRegions(t *testing.T) { srv, now, _ := regionsObservedFixture(t) s := srv.store s.retentionHours = 12 - if floor := s.retainedHistoryCoverageStartLocked(now, 1); !floor.Equal(now.Add(-12 * time.Hour)) { + if floor := s.retainedHistoryCoverageStartLocked(now); !floor.Equal(now.Add(-12 * time.Hour)) { t.Fatalf("known partial floor=%v", floor) } - if floor := s.nodeActivityCoverageStartLocked(now, 1); !floor.IsZero() { + if floor := s.nodeActivityCoverageStartLocked(now); !floor.IsZero() { t.Fatal("existing24h wrapper changed") } s.retentionHours = 168 s.maxMemoryMB = 1 s.packets[0].FirstSeen = now.Add(-2 * time.Hour).Format(time.RFC3339) - if floor := s.retainedHistoryCoverageStartLocked(now, 1); !floor.Equal(now.Add(-2 * time.Hour)) { + if floor := s.retainedHistoryCoverageStartLocked(now); !floor.Equal(now.Add(-2 * time.Hour)) { t.Fatalf("eviction floor=%v", floor) } - if floor := s.retainedHistoryCoverageStartLocked(now, .99); !floor.IsZero() { + verified := s.retainedHistoryFrom + s.retainedHistoryFrom = time.Time{} + if floor := s.retainedHistoryCoverageStartLocked(now); !floor.IsZero() { t.Fatal("partial load must not claim complete coverage") } + s.retainedHistoryFrom = verified s.backgroundLoadFailed.Store(true) - if floor := s.retainedHistoryCoverageStartLocked(now, 1); !floor.IsZero() { + if floor := s.retainedHistoryCoverageStartLocked(now); !floor.IsZero() { t.Fatal("failed load must not claim coverage") } s.backgroundLoadFailed.Store(false) s.backgroundLoadDone.Store(false) - if floor := s.retainedHistoryCoverageStartLocked(now, 1); !floor.IsZero() { + if floor := s.retainedHistoryCoverageStartLocked(now); !floor.IsZero() { t.Fatal("unfinished load must not claim coverage") } s.backgroundLoadDone.Store(true) s.retentionHours, s.hotStartupHours, s.maxMemoryMB = 0, 2, 0 s.oldestLoaded = now.Add(-2 * time.Hour).Format(time.RFC3339) - if floor := s.retainedHistoryCoverageStartLocked(now, 0); !floor.Equal(now.Add(-2 * time.Hour)) { + s.retainedHistoryFrom = now.Add(-2 * time.Hour) + if floor := s.retainedHistoryCoverageStartLocked(now); !floor.Equal(now.Add(-2 * time.Hour)) { t.Fatalf("known hot-window coverage=%v", floor) } s.maxMemoryMB = 1 - if floor := s.retainedHistoryCoverageStartLocked(now, 0); !floor.IsZero() { + s.retainedHistoryFrom = time.Time{} + if floor := s.retainedHistoryCoverageStartLocked(now); !floor.IsZero() { t.Fatalf("capped hot startup without exact row coverage must remain unknown, got %v", floor) } } diff --git a/cmd/server/repeater_enrich_bulk.go b/cmd/server/repeater_enrich_bulk.go index 05241277c..59fd999f5 100644 --- a/cmd/server/repeater_enrich_bulk.go +++ b/cmd/server/repeater_enrich_bulk.go @@ -71,9 +71,7 @@ func (s *PacketStore) computeRepeaterRelayInfoMap(windowHours float64) map[strin } func (s *PacketStore) computeRepeaterRelaySnapshot(windowHours float64) *repeaterRelaySnapshot { - // Read before s.mu: bgErrMu readers intentionally do not wait on the - // packet lock. The same floor/time describes every entry in this result. - loadCoverage := s.LoadCoverageRatio() + // The same floor/time describes every entry in this result. now := time.Now().UTC() // Node metadata (SQL) is read BEFORE s.mu so no query runs under the // packet-store lock (#412/#495). @@ -85,7 +83,7 @@ func (s *PacketStore) computeRepeaterRelaySnapshot(windowHours float64) *repeate s.mu.RLock() snapshot := &repeaterRelaySnapshot{ generatedAt: now, - coverageStart: s.retainedHistoryCoverageStartLocked(now, loadCoverage), + coverageStart: s.retainedHistoryCoverageStartLocked(now), loading: !s.loaded || (!s.backgroundLoadDone.Load() && !s.backgroundLoadFailed.Load()), } pm := metadata.pm diff --git a/cmd/server/store.go b/cmd/server/store.go index f9b6622a7..f38d9d3c5 100644 --- a/cmd/server/store.go +++ b/cmd/server/store.go @@ -219,6 +219,11 @@ type PacketStore struct { totalObs int insertCount int64 queryCount int64 + + // retainedHistoryFrom is the start of the retained history that startup + // proved complete (verifyRetainedHistory, #509); zero = unknown. Guarded by mu. + retainedHistoryFrom time.Time + // Response caches (separate mutex to avoid contention with store RWMutex) cacheMu sync.RWMutex rfCache map[string]*cachedResult // region → cached RF result @@ -640,6 +645,10 @@ type PacketStore struct { // scanned into local maps and before it is merged into the store. // Test-only (#89 route_mask refresh race). loadChunkScannedHook func() + // retainedHistoryCountedHook, if non-nil, runs in verifyRetainedHistory + // between the SQL count and the in-memory count, without s.mu. + // Test-only (#509 edge-moved retry). + retainedHistoryCountedHook func() // loadScannedRowHook, if non-nil, runs once in Load / LoadChunked right // after the first transmission row is read, then is cleared. It runs // while s.mu is held, so it must not call anything that takes s.mu @@ -1748,6 +1757,7 @@ func (s *PacketStore) loadBackgroundChunks() { s.mu.Lock() s.analyticsHistory.loading = false s.mu.Unlock() + s.publishRetainedHistory() s.backgroundLoadDone.Store(true) return } @@ -1868,6 +1878,10 @@ func (s *PacketStore) loadBackgroundChunks() { s.mu.RLock() loadedCount := int64(len(s.packets)) s.mu.RUnlock() + // #509: whether the retained history is complete is proven by + // verifyRetainedHistory, not by this ratio. Rows that retention or + // eviction removed while loading lower the ratio without being missing. + verified := chunkErrors == 0 && totalInDB >= 0 && s.publishRetainedHistory() var ratio float64 if totalInDB > 0 { @@ -1891,7 +1905,7 @@ func (s *PacketStore) loadBackgroundChunks() { bgErr := s.backgroundLoadErr s.bgErrMu.Unlock() s.mu.Lock() - s.analyticsHistory.failed = s.analyticsHistory.failed || chunkErrors > 0 || totalInDB < 0 || (totalInDB > 0 && loadedCount < totalInDB) + s.analyticsHistory.failed = s.analyticsHistory.failed || chunkErrors > 0 || totalInDB < 0 || (totalInDB > 0 && !verified) s.finishNodeAnalyticsLoadLocked(target, false, false) s.mu.Unlock() @@ -10746,12 +10760,6 @@ func (s *PacketStore) GetNodeHealth(pubkey string, now time.Time) (map[string]in } } - // #351 F4: snapshot the bgErrMu-guarded coverage ratio BEFORE taking - // s.mu so this reader honours bgErrMu's "no s.mu needed" contract - // (store.go:530) instead of being the first site to nest s.mu → bgErrMu. - s.bgErrMu.RLock() - loadCoverage := s.loadCoverageRatio - s.bgErrMu.RUnlock() _, pm := s.getCachedNodesAndPM() nonRelaySet := map[string]struct{}{} seenSet := map[string]struct{}{} @@ -10775,7 +10783,7 @@ func (s *PacketStore) GetNodeHealth(pubkey string, now time.Time) (map[string]in packets := s.byNode[pubkey] activityKey := strings.ToLower(pubkey) todayStart := now.UTC().Truncate(24 * time.Hour).Format(time.RFC3339) - activity := newNodeActivity24h(now, s.nodeActivityCoverageStartLocked(now, loadCoverage)) + activity := newNodeActivity24h(now, s.nodeActivityCoverageStartLocked(now)) var packetsToday int var totalHops, hopCount int diff --git a/docs/api-spec.md b/docs/api-spec.md index d49e7e10a..f2336afcc 100644 --- a/docs/api-spec.md +++ b/docs/api-spec.md @@ -929,10 +929,12 @@ observations of one transmission count once. Association can come from node identity or a resolved path; it does not prove that a repeater forwarded the packet. Bucket boundaries are half-open `[start, end)` and move with request time rather than aligning to clock hours. A malformed `first_seen` is ignored. -`complete` is true only when successful loading reports 100% of the retained -transmissions in memory and the retention/index bounds cover the whole 24-hour -window. The server's general background-load “done” threshold of 90% is not -enough for this field. If `complete` is false, zero-count +`complete` is true only when successful loading has proven that every retained +transmission since the coverage start is in memory and the retention/index +bounds cover the whole 24-hour window. Rows that retention or eviction removed +while loading lie before the coverage start and do not count as missing. The +server's general background-load “done” threshold of 90% is not enough for +this field. If `complete` is false, zero-count buckets before `coverageStart` represent unknown history rather than confirmed silence. A null `coverageStart` means coverage cannot be established (for example during startup or after a failed load). From 5b0619739f869b69db9da93bc4a5eae5ec59a726 Mon Sep 17 00:00:00 2001 From: dborup Date: Tue, 20 Oct 2026 06:57:38 +0000 Subject: [PATCH 3/6] test(server): reproduce sync-path coverage lost to DB rows below the retention floor (#509) With hotStartupHours=0 the load floor is s.packets[0].FirstSeen. A loaded re-heard row (old first_seen, recent last_seen) pulls it below the retention floor, so the verification counts DB rows that were never meant to be loaded and coverage stays unknown although every retained row is in memory. No retention tick is needed; this is the default-config case (#351 F1). The second test adds concurrent ingest during the load and between the two counts, and rows on both sides of the retention floor. Co-Authored-By: Claude Opus 5.5 --- cmd/server/history_coverage_509_test.go | 131 ++++++++++++++++++++++++ 1 file changed, 131 insertions(+) diff --git a/cmd/server/history_coverage_509_test.go b/cmd/server/history_coverage_509_test.go index 0b00658f0..eca9e5f94 100644 --- a/cmd/server/history_coverage_509_test.go +++ b/cmd/server/history_coverage_509_test.go @@ -2,6 +2,7 @@ package main import ( "database/sql" + "fmt" "path/filepath" "testing" "time" @@ -339,3 +340,133 @@ func TestCoverage509EdgeRefusesCappedOrFailedLoad(t *testing.T) { t.Fatal("failed load must not be verifiable") } } + +// coverage509BelowFloorRows seeds the default-config shape (#351 F1): the DB +// keeps more history than the server's retentionHours. `reheard` long-lived +// transmissions have a 60h-old first_seen and a last_seen 30h ago, `plain` +// rows at 55h ago and `edge` rows two minutes either side of the 48h +// retention floor sit in the DB, followed by `regular` rows over the last +// 47h. Only rows with last_seen inside the window are loaded. +func coverage509BelowFloorRows(t *testing.T, now time.Time, reheard, plain, edge, regular int) string { + t.Helper() + dbPath := filepath.Join(t.TempDir(), "coverage509.db") + floor := now.Add(-coverage509RetentionHours * time.Hour) + seedTestDBRows(t, dbPath, reheard+plain+2*edge+regular, 1, func(i int) (string, int64) { + var ts time.Time + switch { + case i <= reheard: + return now.Add(-60 * time.Hour).Format(time.RFC3339), now.Add(-30 * time.Hour).Unix() + case i <= reheard+plain: + ts = now.Add(-55 * time.Hour) + case i <= reheard+plain+edge: + ts = floor.Add(-2 * time.Minute) + case i <= reheard+plain+2*edge: + ts = floor.Add(2 * time.Minute) + default: + ts = now.Add(-47*time.Hour + time.Duration(i-reheard-plain-2*edge-1)*14*time.Minute) + } + return ts.Format(time.RFC3339), ts.Unix() + }) + return dbPath +} + +// coverage509InsertTx stands in for the ingestor writing a new transmission +// while the server is starting. +func coverage509InsertTx(t *testing.T, writer *sql.DB, id int, at time.Time) { + t.Helper() + // PREFLIGHT: async=true reason="unit-test writer standing in for the ingestor on an ephemeral DB" + if _, err := writer.Exec(`INSERT INTO transmissions (id, raw_hex, hash, first_seen, route_type, payload_type, payload_version, decoded_json, last_seen) VALUES (?, 'aabb', ?, ?, 0, 4, 1, '{}', ?)`, + id, fmt.Sprintf("live%06d", id), at.Format(time.RFC3339), at.Unix()); err != nil { + t.Error(err) + } + // PREFLIGHT: async=true reason="unit-test writer standing in for the ingestor on an ephemeral DB" + if _, err := writer.Exec(`INSERT INTO observations (id, transmission_id, observer_id, observer_name, direction, snr, rssi, score, path_json, timestamp) VALUES (?, ?, 'obs1', 'Obs1', 'RX', -10.0, -80.0, 5, '[]', ?)`, + 1000000+id, id, at.Format(time.RFC3339)); err != nil { + t.Error(err) + } +} + +// With hotStartupHours=0 the load floor is s.packets[0].FirstSeen, which a +// loaded re-heard row pulls below the retention floor. DB rows between it +// and the floor were never meant to be loaded (their last_seen is outside +// the window) and must not count as missing. No retention tick runs during +// the load, the common case for a fast startup. +func TestCoverage509DBRowsBelowRetentionFloorNoTick(t *testing.T) { + for _, hot := range []float64{0, 12} { + now := time.Now().UTC() + dbPath := coverage509BelowFloorRows(t, now, 5, 3, 0, 200) + store := openCoverage509Store(t, dbPath, &PacketStoreConfig{RetentionHours: coverage509RetentionHours, HotStartupHours: hot}) + if err := store.RunStartupLoad(50); err != nil { + t.Fatalf("hot=%g: RunStartupLoad: %v", hot, err) + } + t.Logf("hot=%g: loadCoverageRatio=%.4f", hot, store.LoadCoverageRatio()) + assertCoverage509Known(t, store, now) + } +} + +// The ingestor keeps writing while the server starts and the poller ingests +// concurrently with the load and with the verification, while DB rows sit +// on both sides of the retention floor. Rows the ingestor wrote after the +// store's highest id are not yet evidence either way: in the DB (not polled +// yet) or in memory (polled between the two counts), they must not turn a +// complete history into a mismatch. Rows just below the floor were never +// loaded and must not count as missing; rows just above it were. +func TestCoverage509ConcurrentIngestAtRetentionEdge(t *testing.T) { + for _, hot := range []float64{0, 12} { + now := time.Now().UTC() + const reheard, plain, edge, regular = 5, 3, 4, 200 + dbPath := coverage509BelowFloorRows(t, now, reheard, plain, edge, regular) + store := openCoverage509Store(t, dbPath, &PacketStoreConfig{RetentionHours: coverage509RetentionHours, HotStartupHours: hot}) + writer, err := sql.Open("sqlite", dbPath+"?_journal_mode=WAL") + if err != nil { + t.Fatal(err) + } + nextID := reheard + plain + 2*edge + regular + insertDuringLoad := func() { + for i := 0; i < 3; i++ { + nextID++ + coverage509InsertTx(t, writer, nextID, time.Now().UTC()) + } + } + // The background fill only reads windows older than the hot + // window, so rows written during it stay above the store's + // highest id until the poller picks them up. + if hot > 0 { + chunks := 0 + store.loadChunkScannedHook = func() { + if chunks++; chunks == 1 { + insertDuringLoad() + } + } + } else { + first := true + store.OnChunkLoaded(func(int, int) { + if first { + first = false + insertDuringLoad() + } + }) + } + polled := 0 + store.retainedHistoryCountedHook = func() { + if polled++; polled != 1 { + return + } + nextID++ + coverage509InsertTx(t, writer, nextID, time.Now().UTC()) + // Poller tick between the SQL and the in-memory count. + if _, newMax := store.IngestNewFromDB(store.MaxTransmissionID(), 100); newMax != nextID { + t.Errorf("hot=%g: poller reached id %d, want %d", hot, newMax, nextID) + } + } + if err := store.RunStartupLoad(50); err != nil { + t.Fatalf("hot=%g: RunStartupLoad: %v", hot, err) + } + writer.Close() + if polled == 0 { + t.Fatalf("hot=%g: verification never reached the poller tick", hot) + } + t.Logf("hot=%g: loadCoverageRatio=%.4f", hot, store.LoadCoverageRatio()) + assertCoverage509Known(t, store, now) + } +} From 9f2d9ff0ebf8cbc495a9b5efb8df7d02b9f654ff Mon Sep 17 00:00:00 2001 From: dborup Date: Tue, 20 Oct 2026 07:03:40 +0000 Subject: [PATCH 4/6] fix(server): floor the retained-history edge at the retention floor (#509) Review F1 on #511. With hotStartupHours=0 the load floor is s.packets[0].FirstSeen; a loaded re-heard row puts it below the retention floor, and the verification then counted DB rows that were never meant to be loaded. Coverage stayed unknown until a restart, although every retained row was in memory. retainedHistoryEdgeLocked now takes now and raises the edge to the retention floor when retentionHours > 0. A row with first_seen at or after the floor has last_seen after it too, so the load (whose cutoff was taken earlier) selected it. verifyRetainedHistory takes now once, so only an eviction moves the edge between the two reads. Also pins the id <= maxID bounds on both counts (review F2) through the concurrent-ingest test, and adds an edge unit test for the floor. Co-Authored-By: Claude Opus 5.5 --- cmd/server/history_coverage.go | 31 ++++++++++++++++++------- cmd/server/history_coverage_509_test.go | 31 ++++++++++++++++++++++--- 2 files changed, 51 insertions(+), 11 deletions(-) diff --git a/cmd/server/history_coverage.go b/cmd/server/history_coverage.go index 6560a9399..3b3ac69b9 100644 --- a/cmd/server/history_coverage.go +++ b/cmd/server/history_coverage.go @@ -12,11 +12,19 @@ const retainedHistoryVerifyAttempts = 3 // retainedHistoryEdgeLocked returns the instant from which every transmission // is expected in memory: the load floor, moved past every row an eviction -// (retention or memory cap) removed since the load began, rounded up to a -// whole second. maxID is the highest transmission id the store has reached; -// rows above it are not ingested yet and are no evidence either way. ok is -// false when nothing can be verified: not loaded, empty, capped or failed. -func (s *PacketStore) retainedHistoryEdgeLocked() (from time.Time, maxID int, ok bool) { +// (retention or memory cap) removed since the load began and up to the +// retention floor at now, rounded up to a whole second. maxID is the highest +// transmission id the store has reached; rows above it are not ingested yet +// and are no evidence either way. ok is false when nothing can be verified: +// not loaded, empty, capped or failed. +// +// The retention floor matters with hotStartupHours=0, where the load floor +// is s.packets[0].FirstSeen: a loaded re-heard row (old first_seen, recent +// last_seen) puts it below the floor, and the DB rows between the two were +// never meant to be loaded. A row with first_seen at or after the floor has +// last_seen after it too, so the load (whose cutoff was taken earlier) +// selected it. +func (s *PacketStore) retainedHistoryEdgeLocked(now time.Time) (from time.Time, maxID int, ok bool) { h := &s.analyticsHistory if !s.loaded || len(s.packets) == 0 || h.cap || h.failed { return time.Time{}, 0, false @@ -28,6 +36,11 @@ func (s *PacketStore) retainedHistoryEdgeLocked() (from time.Time, maxID int, ok if h.evictedFrom.After(from) { from = h.evictedFrom } + if s.retentionHours > 0 { + if floor := now.Add(-time.Duration(s.retentionHours * float64(time.Hour))); floor.After(from) { + from = floor + } + } from = from.UTC() if whole := from.Truncate(time.Second); whole.Before(from) { from = whole.Add(time.Second) @@ -66,11 +79,13 @@ func (s *PacketStore) countRetainedSinceLocked(bound string, maxID int) int { // (see #351 F6). // // The SQL count runs without s.mu (#495). An eviction between the two counts -// moves the edge; the check is then repeated against the new edge. +// moves the edge; the check is then repeated against the new edge. now is +// taken once, so only an eviction moves the edge between the two reads. func (s *PacketStore) verifyRetainedHistory() time.Time { + now := time.Now().UTC() for attempt := 0; attempt < retainedHistoryVerifyAttempts; attempt++ { s.mu.RLock() - from, maxID, ok := s.retainedHistoryEdgeLocked() + from, maxID, ok := s.retainedHistoryEdgeLocked(now) s.mu.RUnlock() if !ok { return time.Time{} @@ -86,7 +101,7 @@ func (s *PacketStore) verifyRetainedHistory() time.Time { s.retainedHistoryCountedHook() } s.mu.RLock() - again, _, ok := s.retainedHistoryEdgeLocked() + again, _, ok := s.retainedHistoryEdgeLocked(now) inMemory := 0 if ok && again.Equal(from) { inMemory = s.countRetainedSinceLocked(bound, maxID) diff --git a/cmd/server/history_coverage_509_test.go b/cmd/server/history_coverage_509_test.go index eca9e5f94..3da095828 100644 --- a/cmd/server/history_coverage_509_test.go +++ b/cmd/server/history_coverage_509_test.go @@ -327,16 +327,16 @@ func TestCoverage509EdgeRefusesCappedOrFailedLoad(t *testing.T) { s := &PacketStore{loaded: true, maxTxID: 7, oldestLoaded: now.Add(-time.Hour).Format(time.RFC3339Nano), packets: []*StoreTx{{ID: 7, FirstSeen: now.Format(time.RFC3339)}}} s.analyticsHistory.evictedFrom = now.Add(-30*time.Minute + time.Nanosecond) - from, maxID, ok := s.retainedHistoryEdgeLocked() + from, maxID, ok := s.retainedHistoryEdgeLocked(now) if !ok || maxID != 7 || !from.Equal(now.Add(-30*time.Minute).Truncate(time.Second).Add(time.Second)) { t.Fatalf("edge=%v maxID=%d ok=%v, want the eviction edge rounded up to a whole second", from, maxID, ok) } s.analyticsHistory.cap = true - if _, _, ok := s.retainedHistoryEdgeLocked(); ok { + if _, _, ok := s.retainedHistoryEdgeLocked(now); ok { t.Fatal("capped load must not be verifiable") } s.analyticsHistory.cap, s.analyticsHistory.failed = false, true - if _, _, ok := s.retainedHistoryEdgeLocked(); ok { + if _, _, ok := s.retainedHistoryEdgeLocked(now); ok { t.Fatal("failed load must not be verifiable") } } @@ -470,3 +470,28 @@ func TestCoverage509ConcurrentIngestAtRetentionEdge(t *testing.T) { assertCoverage509Known(t, store, now) } } + +// The edge never sits below the retention floor: every row with first_seen +// at or after the floor has last_seen after it too and was selected by the +// load, while older rows were never meant to be in memory. +func TestCoverage509EdgeFlooredAtRetention(t *testing.T) { + now := time.Date(2026, 10, 20, 12, 0, 0, 500, time.UTC) + s := &PacketStore{loaded: true, maxTxID: 7, retentionHours: 48, + oldestLoaded: now.Add(-60 * time.Hour).Format(time.RFC3339Nano), + packets: []*StoreTx{{ID: 7, FirstSeen: now.Format(time.RFC3339)}}} + floor := now.Add(-48 * time.Hour) + from, _, ok := s.retainedHistoryEdgeLocked(now) + if !ok || !from.Equal(floor.Truncate(time.Second).Add(time.Second)) { + t.Fatalf("edge=%v ok=%v, want the retention floor %v rounded up", from, ok, floor) + } + // An eviction edge above the floor still wins. + s.analyticsHistory.evictedFrom = now.Add(-47 * time.Hour) + if from, _, _ := s.retainedHistoryEdgeLocked(now); !from.Equal(now.Add(-47 * time.Hour).Truncate(time.Second).Add(time.Second)) { + t.Fatalf("edge=%v, want the eviction edge above the floor", from) + } + // Unlimited retention has no floor. + s.retentionHours, s.analyticsHistory.evictedFrom = 0, time.Time{} + if from, _, _ := s.retainedHistoryEdgeLocked(now); !from.Equal(now.Add(-60 * time.Hour).Truncate(time.Second).Add(time.Second)) { + t.Fatalf("edge=%v, want the load floor with unlimited retention", from) + } +} From 3294f958e08d6f33778fd558a34d33a2d14f8070 Mon Sep 17 00:00:00 2001 From: dborup Date: Tue, 20 Oct 2026 09:24:16 +0000 Subject: [PATCH 5/6] test(server): reproduce staging coverage lost to rows re-heard during the background load (#509) Staging shape: retentionHours 48, hotStartupHours 6, a memory cap and the background fill, with retention and memory-cap ticks, the poller and new ingest during the load. The control without re-hearing proves the retained history; with transmissions re-heard before their window is read, the ingestor moves last_seen to now, out of every window still to be read, and the poller skips their observations. The proof then fails ("1871 of 1875"), so coverage stays unknown at ratio 0.997. Also pins the retention floor on the background path (round-2 N1, mutant R2): rows pruned from the DB in the sliver between the background floor and the verification floor must not count as surplus. Co-Authored-By: Claude Opus 5.5 --- cmd/server/history_coverage_509_test.go | 207 ++++++++++++++++++++++++ 1 file changed, 207 insertions(+) diff --git a/cmd/server/history_coverage_509_test.go b/cmd/server/history_coverage_509_test.go index 3da095828..2a56c8e83 100644 --- a/cmd/server/history_coverage_509_test.go +++ b/cmd/server/history_coverage_509_test.go @@ -495,3 +495,210 @@ func TestCoverage509EdgeFlooredAtRetention(t *testing.T) { t.Fatalf("edge=%v, want the load floor with unlimited retention", from) } } + +// coverage509Reheard stands in for the ingestor hearing an existing +// transmission again: a new observation row, then the last_seen bump +// (ingestor InsertTransmission, #1690). last_seen moves to `at`, out of any +// background window that has not been read yet. +func coverage509Reheard(t *testing.T, writer *sql.DB, txID, obsID int, at time.Time) { + t.Helper() + // PREFLIGHT: async=true reason="unit-test writer standing in for the ingestor on an ephemeral DB" + if _, err := writer.Exec(`INSERT INTO observations (id, transmission_id, observer_id, observer_name, direction, snr, rssi, score, path_json, timestamp) VALUES (?, ?, 'obs2', 'Obs2', 'RX', -9.0, -79.0, 5, '[]', ?)`, + obsID, txID, at.Format(time.RFC3339)); err != nil { + t.Error(err) + } + // PREFLIGHT: async=true reason="unit-test writer standing in for the ingestor on an ephemeral DB" + if _, err := writer.Exec(`UPDATE transmissions SET last_seen = ? WHERE id = ? AND last_seen < ?`, at.Unix(), txID, at.Unix()); err != nil { + t.Error(err) + } +} + +// The staging configuration (#509 round 3): retentionHours 48, +// hotStartupHours 6, a memory cap and the background fill, while the +// ingestor keeps writing. Retention evicts the re-heard rows the hot window +// loaded, a memory-cap tick evicts the oldest rows mid-load, the poller +// runs, and new transmissions arrive. With reheard, the ingestor also hears +// transmissions again whose last_seen sat in a window not read yet: one +// after the hot cursor passed it, three before the second background +// window. Their last_seen moves to now, out of every window the loader +// will still read, and the poller skips observations of transmissions that +// are not in memory. They must still end up in memory, and coverage must be +// known. The control (no re-hearing) isolates the remaining gates: +// eviction, retention, oldestLoaded at the background start and the 90% +// done gate. +func TestCoverage509StagingShapeBackgroundLoad(t *testing.T) { + for _, reheard := range []bool{false, true} { + t.Run(fmt.Sprintf("reheard=%v", reheard), func(t *testing.T) { + now := time.Now().UTC() + const reheardOld, regular = 5, 2000 + dbPath := coverage509Rows(t, now, reheardOld, regular, time.Hour) + store := openCoverage509Store(t, dbPath, &PacketStoreConfig{ + RetentionHours: coverage509RetentionHours, HotStartupHours: 6, MaxMemoryMB: 1}) + writer, err := sql.Open("sqlite", dbPath+"?_journal_mode=WAL") + if err != nil { + t.Fatal(err) + } + defer writer.Close() + // Regular row i has first_seen == last_seen ≈ now − 47h + (i−6)·step. + rowAt := func(hoursAgo float64) int { + return reheardOld + 1 + int((47-hoursAgo)/47*regular) + } + var hearAgain []int + nextID, nextObs := reheardOld+regular, 5000000 + hear := func(id int) { + nextObs++ + coverage509Reheard(t, writer, id, nextObs, time.Now().UTC()) + hearAgain = append(hearAgain, id) + } + first := true + store.OnChunkLoaded(func(int, int) { + if first && reheard { + first = false + hear(rowAt(20)) // first background window, behind the hot cursor + } + }) + var lastEvicted time.Time + sinceObs := store.MaxObservationID() + chunks := 0 + store.loadChunkScannedHook = func() { + // [now−30h, now−6h) scanned, [now−48h, now−30h) not read yet. + if chunks++; chunks != 1 { + return + } + if reheard { + for _, ago := range []float64{40, 38, 33} { + hear(rowAt(ago)) + } + } + for i := 0; i < 3; i++ { + nextID++ + coverage509InsertTx(t, writer, nextID, time.Now().UTC()) + } + if n := store.RunEviction(); n != reheardOld { + t.Errorf("retention tick evicted %d rows, want the %d re-heard rows", n, reheardOld) + } + // Poller tick: observations of transmissions that are not in + // memory are skipped. + store.IngestNewFromDB(store.MaxTransmissionID(), 100) + store.IngestNewObservations(sinceObs, 500) + } + // A memory-cap tick once the oldest window is merged, when the + // store is fullest: it lands between the two counts, so the + // check also repeats against the moved edge. + counted := 0 + store.retainedHistoryCountedHook = func() { + if counted++; counted != 1 { + return + } + store.mu.Lock() + before := append([]*StoreTx(nil), store.packets...) + tracked := store.trackedBytes + store.trackedBytes = int64(store.maxMemoryMB)*1048576 + 1 + store.mu.Unlock() + if store.RunEviction() == 0 { + t.Error("memory eviction did not run") + } + store.mu.Lock() + store.trackedBytes = tracked + for _, tx := range before { + if store.byTxID[tx.ID] == nil { + if at, _ := time.Parse(time.RFC3339, tx.FirstSeen); at.After(lastEvicted) { + lastEvicted = at + } + } + } + store.mu.Unlock() + } + if err := store.RunStartupLoad(100); err != nil { + t.Fatalf("RunStartupLoad: %v", err) + } + t.Logf("loadCoverageRatio=%.4f lastEvicted=%v", store.LoadCoverageRatio(), lastEvicted) + if !store.backgroundLoadDone.Load() || store.backgroundLoadFailed.Load() { + t.Fatalf("load did not finish cleanly: err=%q", store.BackgroundLoadError()) + } + floor := now.Add(-coverage509RetentionHours * time.Hour) + if lastEvicted.Before(floor) || lastEvicted.After(now.Add(-25*time.Hour)) { + t.Fatalf("fixture: memory eviction edge %v, want inside the window and before 25h ago", lastEvicted) + } + store.mu.RLock() + for _, id := range hearAgain { + if store.byTxID[id] == nil { + t.Errorf("re-heard transmission %d is not in memory", id) + } + } + store.mu.RUnlock() + retained, activity, analytics := coverage509Starts(store, now) + if retained.IsZero() || !retained.After(lastEvicted) || retained.After(lastEvicted.Add(time.Hour)) { + t.Fatalf("retained coverage start=%v, want known just after the memory eviction edge %v", retained, lastEvicted) + } + if activity.IsZero() || activity.After(now.Add(-24*time.Hour)) { + t.Fatalf("activity24h coverage start=%v, want known and before %v", activity, now.Add(-24*time.Hour)) + } + if analytics.Reason == "load_failed" { + t.Fatalf("analytics coverage=%+v, want a verified load", analytics) + } + }) + } +} + +// N1 (round 2): the retention floor also bounds the edge on the background +// path. There oldestLoaded ends at the retention floor taken when the +// background fill started, which is just below the floor at verification. +// The ingestor prunes by first_seen, so it can delete rows in that sliver +// while they are still in memory, before a server tick evicts them. They +// were never meant to be covered and must not count as surplus. +func TestCoverage509BackgroundEdgeFlooredAtRetention(t *testing.T) { + now := time.Now().UTC() + const regular, sliver = 200, 3 + dbPath := coverage509Rows(t, now, 0, regular, 0) + store := openCoverage509Store(t, dbPath, &PacketStoreConfig{RetentionHours: coverage509RetentionHours, HotStartupHours: 12}) + writer, err := sql.Open("sqlite", dbPath+"?_journal_mode=WAL") + if err != nil { + t.Fatal(err) + } + defer writer.Close() + var sliverAt time.Time + store.bgLoaderEntryHook = func() { + // Start early in a second, so the background floor taken next is + // in the same second; the sliver rows sit one second above it. + if frac := time.Duration(time.Now().Nanosecond()); frac > 500*time.Millisecond { + time.Sleep(time.Second - frac) + } + sliverAt = time.Now().UTC().Truncate(time.Second).Add(time.Second - coverage509RetentionHours*time.Hour) + for i := 1; i <= sliver; i++ { + // PREFLIGHT: async=true reason="unit-test writer standing in for the ingestor on an ephemeral DB" + if _, err := writer.Exec(`INSERT INTO transmissions (id, raw_hex, hash, first_seen, route_type, payload_type, payload_version, decoded_json, last_seen) VALUES (?, 'aabb', ?, ?, 0, 4, 1, '{}', ?)`, + regular+i, fmt.Sprintf("sliver%d", i), sliverAt.Format(time.RFC3339), sliverAt.Unix()); err != nil { + t.Error(err) + } + } + } + chunks := 0 + store.loadChunkScannedHook = func() { + if chunks++; chunks != 2 { // the oldest window, sliver rows scanned + return + } + // Wait until the retention floor has passed the sliver, then let the + // ingestor prune it; the scanned rows are still merged. + for !time.Now().UTC().Add(-coverage509RetentionHours * time.Hour).After(sliverAt) { + time.Sleep(20 * time.Millisecond) + } + // PREFLIGHT: async=true reason="unit-test writer standing in for ingestor retention on an ephemeral DB" + if _, err := writer.Exec(`DELETE FROM transmissions WHERE id > ?`, regular); err != nil { + t.Error(err) + } + } + if err := store.RunStartupLoad(50); err != nil { + t.Fatalf("RunStartupLoad: %v", err) + } + store.mu.RLock() + inMemory := store.byTxID[regular+1] != nil + store.mu.RUnlock() + if !inMemory || chunks < 2 { + t.Fatalf("fixture: sliver row in memory=%v after %d chunks", inMemory, chunks) + } + retained, _, _ := coverage509Starts(store, now) + if retained.IsZero() || !retained.After(sliverAt) { + t.Fatalf("retained coverage start=%v, want known and above the pruned sliver at %v", retained, sliverAt) + } +} From afc27e918e00decac18ed443edf151ca14d70bd5 Mon Sep 17 00:00:00 2001 From: dborup Date: Tue, 20 Oct 2026 09:46:17 +0000 Subject: [PATCH 6/6] fix(server): load transmissions re-heard during the background load (#509) The startup windows select by last_seen, and the ingestor moves last_seen to the time of each new observation. A transmission heard again before its background window was read, or after the hot cursor passed it, fell out of every window still to be read, and the poller skips observations of transmissions that are not in memory. It stayed missing until the next restart, so the retained-history proof refused coverage on every background-fill startup with live traffic. LoadChunked records the highest observation id when the load begins. After the last background window, loadReheardTransmissions loads the transmissions observed since then (id <= maxTxID) that are not in memory, through the window loader's merge (loadChunk is split into loadChunkWhere). Ids above maxTxID stay with the poller, which still ingests and broadcasts them as new. Errors only leave rows missing, which the proof reports as unknown. The SQL runs without s.mu (#495). Co-Authored-By: Claude Opus 5.5 --- cmd/server/chunked_load.go | 7 +++ cmd/server/history_coverage.go | 76 +++++++++++++++++++++++++ cmd/server/history_coverage_509_test.go | 12 +++- cmd/server/store.go | 48 +++++++++------- 4 files changed, 122 insertions(+), 21 deletions(-) diff --git a/cmd/server/chunked_load.go b/cmd/server/chunked_load.go index d75d678b6..32075d559 100644 --- a/cmd/server/chunked_load.go +++ b/cmd/server/chunked_load.go @@ -367,6 +367,13 @@ func (s *PacketStore) LoadChunked(chunkSize int) error { s.beginNodeAnalyticsLoadLocked(hotCutoffStr) s.mu.Unlock() + // #509: observations after this id re-hear transmissions while the + // load runs; the background fill loads those that no window picked up. + s.loadStartObsID = -1 + if err := s.db.conn.QueryRow(`SELECT COALESCE(MAX(id), 0) FROM observations`).Scan(&s.loadStartObsID); err != nil { + s.loadStartObsID = -1 + } + // COUNT honours the same retention/hot-startup filter the chunk // loop applies, so the logged "DB total" matches the rows the // loop will actually walk. Use a `t2` alias to share the WHERE diff --git a/cmd/server/history_coverage.go b/cmd/server/history_coverage.go index 3b3ac69b9..2b3a79629 100644 --- a/cmd/server/history_coverage.go +++ b/cmd/server/history_coverage.go @@ -1,8 +1,10 @@ package main import ( + "fmt" "log" "sort" + "strings" "time" ) @@ -132,3 +134,77 @@ func (s *PacketStore) publishRetainedHistory() bool { s.mu.Unlock() return !from.IsZero() } + +// loadReheardTransmissionsBatch bounds the ids in one loadChunkWhere query. +const loadReheardTransmissionsBatch = 500 + +// loadReheardTransmissions loads the transmissions that the ingestor heard +// again while the startup load ran and that no window picked up (#509). The +// windows select by last_seen, and the ingestor moves last_seen to the time +// of the new observation: a transmission re-heard before its background +// window was read, or after the hot cursor passed it, falls out of every +// window still to be read, and the poller skips observations of +// transmissions that are not in memory. It would then stay missing until +// the next restart, and the retained history could never be proven. +// +// Every re-hearing writes an observation first, so the candidates are the +// transmissions observed after sinceObsID (the highest observation id when +// the load began). Ids above the store's highest id are new transmissions, +// which the poller ingests. The rest are loaded when they are not in +// memory; nothing else loads an id at or below maxTxID that the load +// skipped, so they cannot be merged twice. Errors only leave rows missing, +// which verifyRetainedHistory then reports as unknown. +func (s *PacketStore) loadReheardTransmissions(sinceObsID int64) { + if sinceObsID < 0 { + return + } + s.mu.RLock() + maxID := s.maxTxID + s.mu.RUnlock() + rows, err := s.db.conn.Query(`SELECT DISTINCT transmission_id FROM observations WHERE id > ? AND transmission_id <= ?`, + sinceObsID, maxID) + if err != nil { + log.Printf("[store] re-heard transmissions: query failed: %v", err) + return + } + var heard []int + for rows.Next() { + var id int + if err := rows.Scan(&id); err != nil { + rows.Close() + log.Printf("[store] re-heard transmissions: scan failed: %v", err) + return + } + heard = append(heard, id) + } + err = rows.Err() + rows.Close() + if err != nil { + log.Printf("[store] re-heard transmissions: %v", err) + return + } + s.mu.RLock() + missing := heard[:0] + for _, id := range heard { + if s.byTxID[id] == nil { + missing = append(missing, id) + } + } + s.mu.RUnlock() + for len(missing) > 0 { + batch := missing + if len(batch) > loadReheardTransmissionsBatch { + batch = batch[:loadReheardTransmissionsBatch] + } + missing = missing[len(batch):] + args := make([]interface{}, len(batch)) + for i, id := range batch { + args[i] = id + } + where := "t.id IN (?" + strings.Repeat(", ?", len(batch)-1) + ")" + if err := s.loadChunkWhere(where, args, fmt.Sprintf("(%d re-heard)", len(batch))); err != nil { + log.Printf("[store] re-heard transmissions: load failed: %v", err) + return + } + } +} diff --git a/cmd/server/history_coverage_509_test.go b/cmd/server/history_coverage_509_test.go index 2a56c8e83..56d4f81f2 100644 --- a/cmd/server/history_coverage_509_test.go +++ b/cmd/server/history_coverage_509_test.go @@ -581,6 +581,9 @@ func TestCoverage509StagingShapeBackgroundLoad(t *testing.T) { // memory are skipped. store.IngestNewFromDB(store.MaxTransmissionID(), 100) store.IngestNewObservations(sinceObs, 500) + // Written after the poller tick: the poller's, not the load's. + nextID++ + coverage509InsertTx(t, writer, nextID, time.Now().UTC()) } // A memory-cap tick once the oldest window is merged, when the // store is fullest: it lands between the two counts, so the @@ -622,11 +625,16 @@ func TestCoverage509StagingShapeBackgroundLoad(t *testing.T) { } store.mu.RLock() for _, id := range hearAgain { - if store.byTxID[id] == nil { - t.Errorf("re-heard transmission %d is not in memory", id) + if tx := store.byTxID[id]; tx == nil || tx.ObservationCount != 2 { + t.Errorf("re-heard transmission %d is not in memory with both observations: %+v", id, tx) } } store.mu.RUnlock() + // The newest row is still the poller's: it ingests and + // broadcasts it as new. + if got, _ := store.IngestNewFromDB(nextID-1, 100); len(got) != 1 { + t.Errorf("poller ingested %d new transmissions after the load, want the 1 written after its tick", len(got)) + } retained, activity, analytics := coverage509Starts(store, now) if retained.IsZero() || !retained.After(lastEvicted) || retained.After(lastEvicted.Add(time.Hour)) { t.Fatalf("retained coverage start=%v, want known just after the memory eviction edge %v", retained, lastEvicted) diff --git a/cmd/server/store.go b/cmd/server/store.go index f38d9d3c5..576d6c284 100644 --- a/cmd/server/store.go +++ b/cmd/server/store.go @@ -585,6 +585,13 @@ type PacketStore struct { // synchronously, then reads this after it returns), so no lock is // needed; no other goroutine touches it. loadWindowTotalInDB int64 + // loadStartObsID: the highest observation id when LoadChunked began; + // -1 when it could not be read or LoadChunked has not run (NewPacketStore + // sets -1, so a direct background fill skips the step). The background + // fill loads the transmissions observed after it that no window picked + // up (#509, loadReheardTransmissions). Same goroutine contract as + // loadWindowTotalInDB. + loadStartObsID int64 // Async hash migration state: set after migrateContentHashesAsync completes. hashMigrationComplete atomic.Bool @@ -850,6 +857,7 @@ func NewPacketStore(db *DB, cfg *PacketStoreConfig, cacheTTLs ...map[string]inte pathHopResolved: make(map[*StoreTx][]uint64), fallbackByNode: make(map[*StoreTx][]string), clockSkew: NewClockSkewEngine(), + loadStartObsID: -1, useResolvedPathIndex: true, areaNodeCache: make(map[string]map[string]bool), areaNodeCacheTimes: make(map[string]time.Time), @@ -1274,12 +1282,26 @@ func accumulateDedup(byTx map[int][]string, seenByTx map[int]map[string]bool, tx func (s *PacketStore) loadChunk(from, to time.Time) error { fromStr := from.UTC().Format(time.RFC3339) toStr := to.UTC().Format(time.RFC3339) - fromUnix := from.UTC().Unix() - toUnix := to.UTC().Unix() - _ = fromStr - _ = toStr - // Build the same SQL as Load() but with a [from, to) window. + // #1690: window on the denormalized last_seen (effective recency) + // rather than first_seen. See chunked_load.go for the full rationale. + // Test/legacy DBs without the column fall back to first_seen. + if s.db.hasLastSeen() { + return s.loadChunkWhere("t.last_seen >= ? AND t.last_seen < ?", + []interface{}{from.UTC().Unix(), to.UTC().Unix()}, "["+fromStr+", "+toStr+")") + } + return s.loadChunkWhere("t.first_seen >= ? AND t.first_seen < ?", + []interface{}{fromStr, toStr}, "["+fromStr+", "+toStr+")") +} + +// loadChunkWhere is loadChunk for any transmissions filter: it loads the +// transmissions matching where (with qArgs) and merges them as loadChunk +// does. label names the chunk in the log. The caller must not select a +// transmission that is already in memory. +func (s *PacketStore) loadChunkWhere(where string, qArgs []interface{}, label string) error { + filterClause := "\n\t\t\tWHERE " + where + + // Build the same SQL as Load() but with the caller's filter. rpCol := "" if s.db.hasResolvedPath() { rpCol = ",\n\t\t\t\to.resolved_path" @@ -1299,19 +1321,6 @@ func (s *PacketStore) loadChunk(from, to time.Time) error { routeMaskCol = ", t.route_mask" } - // #1690: window on the denormalized last_seen (effective recency) - // rather than first_seen. See chunked_load.go for the full rationale. - // Test/legacy DBs without the column fall back to first_seen. - var filterClause string - var qArgs []interface{} - if s.db.hasLastSeen() { - filterClause = "\n\t\t\tWHERE t.last_seen >= ? AND t.last_seen < ?" - qArgs = []interface{}{fromUnix, toUnix} - } else { - filterClause = "\n\t\t\tWHERE t.first_seen >= ? AND t.first_seen < ?" - qArgs = []interface{}{fromStr, toStr} - } - var chunkSQL string if s.db.isV3() { chunkSQL = `SELECT t.id, t.raw_hex, t.hash, t.first_seen, t.route_type, @@ -1674,7 +1683,7 @@ func (s *PacketStore) loadChunk(from, to time.Time) error { } s.mu.Unlock() - log.Printf("[store] background chunk [%s, %s) merged: %d tx, %d obs", fromStr, toStr, len(localPackets), localTotalObs) + log.Printf("[store] background chunk %s merged: %d tx, %d obs", label, len(localPackets), localTotalObs) if coldLoadAmbiguousHopsSkipped > 0 { log.Printf("[store] background chunk: skipped %d ambiguous-prefix relay hops (unique_prefix gate, PR #1643 R1)", coldLoadAmbiguousHopsSkipped) @@ -1846,6 +1855,7 @@ func (s *PacketStore) loadBackgroundChunks() { // best-effort and queries fall back to SQL while it runs. runtime.Gosched() } + s.loadReheardTransmissions(s.loadStartObsID) // Rebuild analytics indexes once after all chunks are merged. s.mu.Lock()