From 3bbd5507e8df9d9b7cff14867b6149d766805278 Mon Sep 17 00:00:00 2001 From: Dennis Jakobsen Date: Sun, 20 Sep 2026 22:10:07 +0200 Subject: [PATCH 1/2] test(ingestor): stop background work from outliving the test that started it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two independent leaks let a goroutine from one test keep running into later, unrelated tests. Both were found while reviewing the PR queue; each is proven by direct evidence from a full `go test -race ./...` run on master, not inferred. 1. Async migrations racing the test's own seeding. OpenStore starts RunAsyncMigration in the background so boot is not blocked. In a test that is a race against the test's own setup: backfillTxLastSeen only selects rows with last_seen = 0, so if it lands after seedTxWithObs has inserted the transmission but before all of its observations, it resolves the row from a partial set and marks it done. The test's later synchronous call then skips the row. That is exactly the intermittent tx_last_seen_backfill_test.go:63: last_seen = 100, want 300 (MAX of 100,300,200) reported against TestBackfillTxLastSeen_ResolvesFromMaxObservationTimestamp in the CI of several queue PRs. Measured on master: 10 failures in 40 runs (25%). With this change: 0 in 40. The same goroutine also calls log.Printf, which races TestHandleNeighborsReportInvalidTimestampLogsEvenWithoutScopeEvidence — that test swaps the log sink for its own bytes.Buffer and then reads it. Fix: the two store helpers wait on s.backfillWg before returning. That is the synchronization point Close() already uses (db.go:1470) and the one backfill_default_scope_test.go already waits on. Production is untouched: main.go still never blocks on it. 2. StartStatsFileWriter leaked an unstoppable goroutine. The writer loop was `for range t.C` with no way out, so a writer started by a test ran for the rest of the binary. Evidence from the master run: [stats-file] write /var/.../TestStatsFileWriter_...749730707/001/ ingestor-stats.json: ... no such file or directory logged repeatedly during unrelated later tests, i.e. the writer was still ticking into a t.TempDir() that had already been removed. It also kept reading readProcSelfIOFn every tick, racing the t.Cleanup that restores it. Fix: StartStatsFileWriter returns a stop function that signals the loop and blocks until the goroutine has returned. Stopping asynchronously would not help — the stop has to be ordered before the hook restore, so it waits. Both tests register it with t.Cleanup AFTER the restore, so LIFO ordering runs stop first. main.go calls the function as a statement and is unchanged; the writer still runs for the process lifetime there. No assertion was changed, and no test was skipped or weakened. Co-Authored-By: Claude Opus 5 --- cmd/ingestor/issue1865_test.go | 5 +++++ cmd/ingestor/main_test.go | 10 +++++++++ cmd/ingestor/stats_file.go | 26 +++++++++++++++++++++-- cmd/ingestor/stats_file_test.go | 5 ++++- cmd/ingestor/stats_file_timestamp_test.go | 7 +++++- 5 files changed, 49 insertions(+), 4 deletions(-) diff --git a/cmd/ingestor/issue1865_test.go b/cmd/ingestor/issue1865_test.go index c3f745e10..b35fbb51d 100644 --- a/cmd/ingestor/issue1865_test.go +++ b/cmd/ingestor/issue1865_test.go @@ -115,6 +115,11 @@ func openNeighborsStore(t *testing.T) *Store { if err != nil { t.Fatalf("OpenStore: %v", err) } + // Drain RunAsyncMigration's goroutine before returning. It calls + // log.Printf, and TestHandleNeighborsReportInvalidTimestampLogs... + // swaps the log sink for its own bytes.Buffer and then reads it — the + // two race on that buffer if the migration is still running. + store.backfillWg.Wait() t.Cleanup(func() { store.Close() }) return store } diff --git a/cmd/ingestor/main_test.go b/cmd/ingestor/main_test.go index c3a2e0095..7788688ed 100644 --- a/cmd/ingestor/main_test.go +++ b/cmd/ingestor/main_test.go @@ -125,6 +125,16 @@ func newTestStore(t testing.TB) *Store { if err != nil { t.Fatal(err) } + // OpenStore kicks off RunAsyncMigration in the background so boot is not + // blocked. In a test that is a race against the test's own seeding: + // backfillTxLastSeen only selects rows with last_seen = 0, so if it lands + // after a transmission is inserted but before all of its observations + // are, it resolves the row from a partial set and marks it done — the + // test's later synchronous call then skips the row. That is exactly the + // intermittent `last_seen = 100, want 300 (MAX of 100,300,200)` failure. + // Same synchronization point Close() uses (db.go:1470) and the same one + // backfill_default_scope_test.go already waits on. + s.backfillWg.Wait() t.Cleanup(func() { s.Close() }) return s } diff --git a/cmd/ingestor/stats_file.go b/cmd/ingestor/stats_file.go index 677e5245c..da6f6cde0 100644 --- a/cmd/ingestor/stats_file.go +++ b/cmd/ingestor/stats_file.go @@ -6,6 +6,7 @@ import ( "encoding/json" "log" "os" + "sync" "time" "github.com/meshcore-analyzer/perfio" @@ -236,11 +237,22 @@ func procIORate(prev, cur procIOSnapshot, stamp string) *PerfIOSample { // The stats file path is resolved via statsFilePath() once at writer-loop // start; the env var (CORESCOPE_INGESTOR_STATS) is only re-read on process // restart, not per tick. -func StartStatsFileWriter(s *Store, interval time.Duration) { +// +// Returns a stop function that signals the loop and BLOCKS until the +// goroutine has actually returned. Production (main.go) runs the writer for +// the lifetime of the process and ignores it; tests must call it, because a +// writer that outlives its test keeps calling readProcSelfIOFn every tick — +// which races the t.Cleanup that restores the hook, and gets reported against +// whichever unrelated test happens to run next. Stopping asynchronously would +// not fix that: the stop has to be ordered before the restore, so it waits. +func StartStatsFileWriter(s *Store, interval time.Duration) (stop func()) { if interval <= 0 { interval = time.Second } + quit := make(chan struct{}) + done := make(chan struct{}) go func() { + defer close(done) t := time.NewTicker(interval) defer t.Stop() path := statsFilePath() @@ -253,7 +265,12 @@ func StartStatsFileWriter(s *Store, interval time.Duration) { // The buffer grows once and stays. var buf bytes.Buffer enc := json.NewEncoder(&buf) - for range t.C { + for { + select { + case <-quit: + return + case <-t.C: + } // Capture time.Now() ONCE per tick (Carmack must-fix #5). // Both snapshot.SampledAt and procIO.SampledAt MUST share the // same string so the freshness guard isn't validating one @@ -301,4 +318,9 @@ func StartStatsFileWriter(s *Store, interval time.Duration) { } } }() + var once sync.Once + return func() { + once.Do(func() { close(quit) }) + <-done + } } diff --git a/cmd/ingestor/stats_file_test.go b/cmd/ingestor/stats_file_test.go index 29ba4b22c..e6e9610c9 100644 --- a/cmd/ingestor/stats_file_test.go +++ b/cmd/ingestor/stats_file_test.go @@ -56,7 +56,10 @@ func TestStatsFileWriter_PublishesProcIO(t *testing.T) { } defer store.Close() - StartStatsFileWriter(store, 50*time.Millisecond) + // Stop the writer when the test ends: it writes into t.TempDir() and + // reads the package-level readProcSelfIOFn hook, neither of which may + // outlive the test. + t.Cleanup(StartStatsFileWriter(store, 50*time.Millisecond)) // Wait for at least 2 ticks so the writer has had a chance to populate // procIO rates from a delta. diff --git a/cmd/ingestor/stats_file_timestamp_test.go b/cmd/ingestor/stats_file_timestamp_test.go index 900e65606..2ab308aab 100644 --- a/cmd/ingestor/stats_file_timestamp_test.go +++ b/cmd/ingestor/stats_file_timestamp_test.go @@ -69,7 +69,12 @@ func TestStatsFileWriter_SampledAtMatchesProcIOSampledAt(t *testing.T) { } } - StartStatsFileWriter(store, 50*time.Millisecond) + // Registered AFTER the t.Cleanup that restores readProcSelfIOFn, so LIFO + // ordering stops the writer BEFORE the hook is put back. Without that + // ordering the writer's next tick reads the variable while the cleanup + // writes it — and because the goroutine outlived the test, the race was + // reported against whichever unrelated test ran next. + t.Cleanup(StartStatsFileWriter(store, 50*time.Millisecond)) // Wait for the file to land with a populated procIO block. deadline := time.Now().Add(3 * time.Second) From d39e8079337ea65efcdad381a3cb61bbd346c5c7 Mon Sep 17 00:00:00 2001 From: Dennis Jakobsen Date: Sun, 20 Sep 2026 23:03:56 +0200 Subject: [PATCH 2/2] reviewfix(test): correct a false claim and fix Close/stop ordering MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Independent review found no blocker but two real problems in what I wrote. 1. main_test.go's comment claimed the added backfillWg.Wait() fixes the intermittent `last_seen = 100, want 300` failure in TestBackfillTxLastSeen_ResolvesFromMaxObservationTimestamp. It does not. That test already calls store.WaitForAsyncMigrations() itself on master, with a comment describing the same mechanism — so the migration is already drained at seeding time and the Wait here is redundant for it. What actually fells that test under -race is the leaked stats writer racing the hook restore, i.e. the other half of this change. The Wait still earns its place: it makes a settled database the default for every test using the helper rather than something each new test has to remember, and the same addition in openNeighborsStore is what removes the log-sink race in TestHandleNeighborsReport*. Comment rewritten to say that instead. 2. Both stats tests used `defer store.Close()`. Test defers run BEFORE t.Cleanup, so Close landed before the writer's stop and the writer could tick against a closed Store. Benign today only because the tick body touches atomics and package-level registries and no DB; one DB-backed field in the snapshot would make it use-after-close. Close is now a t.Cleanup registered before the writer's stop, so LIFO ordering runs stop -> hook restore -> Close. Co-Authored-By: Claude Opus 5 --- cmd/ingestor/main_test.go | 17 +++++++++-------- cmd/ingestor/stats_file_test.go | 5 ++++- cmd/ingestor/stats_file_timestamp_test.go | 5 ++++- 3 files changed, 17 insertions(+), 10 deletions(-) diff --git a/cmd/ingestor/main_test.go b/cmd/ingestor/main_test.go index 7788688ed..4c4d8c3e1 100644 --- a/cmd/ingestor/main_test.go +++ b/cmd/ingestor/main_test.go @@ -126,14 +126,15 @@ func newTestStore(t testing.TB) *Store { t.Fatal(err) } // OpenStore kicks off RunAsyncMigration in the background so boot is not - // blocked. In a test that is a race against the test's own seeding: - // backfillTxLastSeen only selects rows with last_seen = 0, so if it lands - // after a transmission is inserted but before all of its observations - // are, it resolves the row from a partial set and marks it done — the - // test's later synchronous call then skips the row. That is exactly the - // intermittent `last_seen = 100, want 300 (MAX of 100,300,200)` failure. - // Same synchronization point Close() uses (db.go:1470) and the same one - // backfill_default_scope_test.go already waits on. + // blocked. Draining it here makes every test that uses this helper start + // from a settled database instead of racing a migration it never asked + // for. Individual tests that already knew to wait (see + // tx_last_seen_backfill_test.go and backfill_default_scope_test.go) keep + // their own call; this makes the guarantee the default rather than + // something each new test has to remember. + // + // Same synchronization point Close() uses (db.go:1470). Production is + // unaffected: main.go still never blocks on it. s.backfillWg.Wait() t.Cleanup(func() { s.Close() }) return s diff --git a/cmd/ingestor/stats_file_test.go b/cmd/ingestor/stats_file_test.go index e6e9610c9..64ab5a757 100644 --- a/cmd/ingestor/stats_file_test.go +++ b/cmd/ingestor/stats_file_test.go @@ -54,7 +54,10 @@ func TestStatsFileWriter_PublishesProcIO(t *testing.T) { if err != nil { t.Fatalf("OpenStore: %v", err) } - defer store.Close() + // Close via t.Cleanup, not defer: test defers run BEFORE cleanups, so a + // deferred Close would let the writer tick against a closed Store. LIFO + // cleanup ordering puts the writer's stop (registered next) ahead of it. + t.Cleanup(func() { store.Close() }) // Stop the writer when the test ends: it writes into t.TempDir() and // reads the package-level readProcSelfIOFn hook, neither of which may diff --git a/cmd/ingestor/stats_file_timestamp_test.go b/cmd/ingestor/stats_file_timestamp_test.go index 2ab308aab..8ae4b8c12 100644 --- a/cmd/ingestor/stats_file_timestamp_test.go +++ b/cmd/ingestor/stats_file_timestamp_test.go @@ -42,7 +42,10 @@ func TestStatsFileWriter_SampledAtMatchesProcIOSampledAt(t *testing.T) { if err != nil { t.Fatalf("OpenStore: %v", err) } - defer store.Close() + // Close via t.Cleanup, not defer: test defers run BEFORE cleanups, so a + // deferred Close would let the writer tick against a closed Store. LIFO + // cleanup ordering puts the writer's stop (registered later) ahead of it. + t.Cleanup(func() { store.Close() }) // Inject a deterministic procIO reader. `at` is pinned far in the // past so any code path that formats the inner SampledAt from