test(ingestor): stop background work from outliving the test that started it

[dborup]

Separate minimal test-fix, split out of the PR-queue work the way #70 was. It fixes three failing/flaky ingestor tests that have been showing up in the CI of unrelated PRs (#27, #28, #39 name them in their own descriptions as "intermittent" or "fails on master").

Root cause: background work outliving the test that started it

Two independent leaks, both proven by direct evidence from a full go test -race ./... run on master — not inferred.

1. OpenStore starts RunAsyncMigration in the background

That is correct for production (boot must not block), but in a test it races the test's own seeding.

backfillTxLastSeen only selects rows with last_seen = 0. seedTxWithObs inserts the transmission first, then its observations one at a time. If the async migration lands in between, it resolves the row from a partial set and marks it done — and the test's later synchronous backfillTxLastSeen call then skips the row entirely.

That is exactly the intermittent failure:

tx_last_seen_backfill_test.go:63: last_seen = 100, want 300 (MAX of 100,300,200)

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 with .String():

WARNING: DATA RACE
Write at 0x00c0001a8390 by goroutine 1052:
  log.(*Logger).output()
  github.com/corescope/ingestor.(*Store).RunAsyncMigration.func1()
      cmd/ingestor/async_migration.go:124
Previous read at 0x00c0001a8390 by goroutine 1049:
  bytes.(*Buffer).String()
  github.com/corescope/ingestor.TestHandleNeighborsReportInvalidTimestampLogsEvenWithoutScopeEvidence()
      cmd/ingestor/issue1865_test.go:731

Fix: the two store helpers (newTestStore, openNeighborsStore) 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:30 already waits on, with the comment "same synchronization point Close() uses". 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 test binary. From the master run:

[stats-file] write /var/.../TestStatsFileWriter_SampledAtMatchesProcIOSampledAt749730707/001/
  ingestor-stats.json: ... no such file or directory

logged repeatedly during unrelated later tests — the writer was still ticking into a t.TempDir() that had already been removed. It also kept reading the package-level readProcSelfIOFn hook 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.

Measured, before and after

Same machine, same conditions, run back to back. TestBackfillTxLastSeen and TestPruneOldNeighborMetrics without -race (what CI runs for cmd/ingestor); the neighbors test with -race.

test	master 16ffe105	this branch
TestBackfillTxLastSeen_ResolvesFromMaxObservationTimestamp	10 / 40 fail (25%)	0 / 40
TestPruneOldNeighborMetrics	30 / 30 fail	0 / 30
TestHandleNeighborsReport… (-race)	7 / 12 fail, 7 with DATA RACE	0 / 12, 0 with DATA RACE

I was wrong about the second row and am correcting it here. I expected TestPruneOldNeighborMetrics to be an unrelated, environment-specific failure — several PR descriptions in this queue, including #39's, document it as a baseline failure that "already fails on master", and upstream #33 exists to make it deterministic. It is not unrelated: it uses openNeighborsStore, so the same async migration was perturbing it, and waiting on backfillWg fixes it outright.

Scope and what this deliberately does not do

• No assertion was changed, no test skipped, no timeout raised. The tests are fixed by removing the nondeterminism, not by accommodating it.
• The only production change is the stop function on StartStatsFileWriter. It is required — the goroutine is otherwise unstoppable by construction — and it does not alter runtime behaviour, because main.go ignores the returned value and the writer still runs for the process lifetime.
• gofmt flags main_test.go, stats_file_test.go and ~45 other files in this repo under Go 1.26's comment-reformatting rule. That is pre-existing on unmodified master and is left alone.

Note for context: CI runs cmd/server with -race but cmd/ingestor without it (deploy.yml:59 vs :68), so the data races above never failed CI directly. What failed CI was the assertion failure in row 1.

🤖 Generated with Claude Code

[dborup]

Korrektion: mine før/efter-tal i PR-beskrivelsen var målt forkert

Den uafhængige reviewer fandt fejlen, og jeg har verificeret den. Baseline var ikke master.

Jeg kørte "master"-siden af min A/B i hoved-checkoutet /Users/dennisjakobsen/CoreScope, og det står på 651be3e0 — 175 commits bag origin/master (16ffe105). Jeg havde fetch'et, men aldrig opdateret arbejdstræet, og git rev-parse origin/master viste rigtigt, så jeg opdagede det ikke. Alle tre "master"-tal i den oprindelige beskrivelse er derfor målt på et forældet træ og siger intet om den master, denne PR merges ind i.

Konkret hvad det betød:

• TestBackfillTxLastSeen_… (påstået 10/40 på master). Den rigtige master indeholder allerede store.WaitForAsyncMigrations() i netop den test — med en kommentar, der beskriver præcis den mekanisme, jeg troede jeg havde fundet: "OpenStore schedules tx_last_seen_backfill_v1 in the background; if it runs mid-seed it stamps a partial MAX and the direct call skips the row." Mekanismen er altså rigtig, men den var fundet og rettet i forvejen. Revieweren måler testen til 0 fejl på 100 friske processer på rigtig master uden -race.
• TestPruneOldNeighborMetrics (påstået 30/30 på master). Reproducerer slet ikke på rigtig master: 0 fejl over 60 friske processer, 30 in-process-gentagelser, 30 med -race, 3 fulde suiter og 3 fulde -race-suiter. Den påstand trækkes helt tilbage.
• Som følge heraf er s.backfillWg.Wait() i newTestStore redundant for backfill-testen, der allerede venter selv. Den beholdes, fordi den gør garantien til standarden frem for noget, hver ny test skal huske — og fordi den samme tilføjelse i openNeighborsStore er den, der rent faktisk fjerner log-buffer-racen. Kommentaren er omskrevet til at sige dét i stedet for at påstå, at den retter en assertion, den ikke retter.

Hvad der står tilbage — målt mod rigtig master 16ffe105

scenarie	master 16ffe105	denne branch
fuld pakke med -race, ×3	0/3 bestået — 4 races, 4 testfejl	3/3 bestået, 0 races
TestHandleNeighborsReport* -race -count=24	4 races, 2 fejl	0 races, 0 fejl
lækkede StartStatsFileWriter-goroutiner efter stats-testene	1	0
fuld pakke uden -race, ×3	3/3 bestået, 88 s	3/3 bestået, 88–89 s

Master-fejlene, ordret: kørsel 1 TestHandleNeighborsReportInvalidTimestampLogsEvenWithoutScopeEvidence + TestBackfillTxLastSeen_ResolvesFromMaxObservationTimestamp; kørsel 2 TestBackfillTxLastSeen_…; kørsel 3 TestHandleNeighborsReportInvalid…. Branchen: PASS alle tre.

Den rigtige årsagsforklaring: det er del (B) — den lækkede stats-writer, der læser readProcSelfIOFn (stats_file.go:263) og kolliderer med t.Cleanup-gendannelsen (stats_file_timestamp_test.go:52) — der fælder TestBackfillTxLastSeen under -race. Go tilskriver racen den test, der tilfældigvis kører bagefter, og fejlen er testing.go:1712: race detected during execution of test, ikke last_seen = 100, want 300. Del (A) er det, der fjerner racen i TestHandleNeighborsReport*.

Nettoresultatet er uændret og er grunden til at merge: cmd/ingestor går fra aldrig at bestå en fuld -race-kørsel til at bestå den konsekvent. (CI kører i dag cmd/ingestor uden -race, deploy.yml:68, så det har ikke fældet CI direkte — men det betyder også, at ingen -race-dækning af ingestoren er brugbar før dette.)

Rettet i denne runde

• main_test.go: kommentaren påstod at rette en assertion, den ikke retter. Omskrevet til det, den faktisk køber.
• stats_file_test.go / stats_file_timestamp_test.go: defer store.Close() kørte før t.Cleanup(stop) — test-defers kører før cleanups — så writeren kunne ticke mod et lukket Store. Ufarligt i dag, fordi tick-kroppen kun rører atomics og globale registre, men ét DB-baseret felt i snapshottet ville gøre det til use-after-close. Begge steder er Close nu en t.Cleanup registreret før writerens stop, så LIFO giver stop → hook-gendannelse → Close.

Reviewerens øvrige fund, som jeg ikke retter her

• stats_file_test.go:62 (TestStatsFileWriter_PublishesProcIO) skippes på darwin (/proc/self/io), så den nye stop-sti er kun lokalt dækket af timestamp-testen. Den kører i CI på Linux.
• To andre usporede goroutiner findes stadig i cmd/ingestor: mqtt_watchdog.go:676 (maybeForceReconnect spawner uden stop-sti, WaitGroup eller recover) og mqtt_watchdog_1853_test.go:27 (kasserer stop-funktionen fra newAsyncEmit). Revieweren kunne ikke fremtvinge den farlige sammenfald i den første og markerer den som uverificeret. Uden for denne PR's scope — påstanden om at have rettet "problemet" er altså mildt overdrevet, og det siges her frem for at blive stående.
• Et hang, revieweren konstruerede (WaitForAsyncMigrations blokeret af en åben *sql.Rows på den enkelte forbindelse), reproducerer identisk på master og hører til Store.Close() (db.go:1470). Pre-eksisterende; denne PR reducerer faktisk eksponeringen, fordi WaitGroup'en allerede er drænet inden testkroppen.

🤖 Generated with Claude Code

[dborup]

Egen bekræftende måling mod korrekt baseline

Jeg har gentaget A/B'en selv, denne gang med et rent origin/master-worktree som baseline i stedet for det forældede checkout, og efter reviewfix-commit d39e8079:

	master 16ffe105	branch d39e8079
fuld pakke go test -race ./... ×3	1/3 kørsler fejlede, 2 DATA RACE	0/3 fejlede, 0 DATA RACE

Fejlende test på master: TestHandleNeighborsReportInvalidTimestampLogsEvenWithoutScopeEvidence.

Bemærk at min rate (1/3) og reviewerens (3/3, 4 races) ikke er ens. Det er forventeligt for en race og er grunden til, at det er antallet af kørsler uden fejl, der tæller, ikke en enkelt kørsel. Begge målinger viser det samme: master er ikke pålideligt grøn under -race, branchen er.

🤖 Generated with Claude Code

[dborup]

Én rerun af Playwright-jobbet — dokumenteret som urelateret flake

CI-kørsel 35537523535 på d39e8079: Go Build & Test grøn, Playwright fejlede på én test:

=== live multibyte-only E2E against http://localhost:13581 ===
  ✓ navigate to /#/live, toggle exists and defaults OFF
  ✓ turn toggle ON: single-byte packet hidden, multibyte shown
  ✓ turn toggle OFF: previously-hidden single-byte packet appears
  ✗ setting persists across reload: multibyte toggle should restore checked=true from localStorage
--- 3 passed, 1 failed ---

Grundlag for at kalde den urelateret — ikke en antagelse, men filomfang og sammenligning:

• PR'en rører nul frontend-filer. Hele diffen mod master er fem filer, alle under cmd/ingestor/: issue1865_test.go, main_test.go, stats_file.go, stats_file_test.go, stats_file_timestamp_test.go. git diff --name-only origin/master...d39e8079 | grep -cE '\.(js|css|html)$' → 0.
• Den eneste ændring siden den grønne kørsel er tre Go-testfiler. git diff --name-only 3bbd5507 d39e8079 → main_test.go, stats_file_test.go, stats_file_timestamp_test.go. Kørslen på 3bbd5507 havde Playwright success.
• Master har grøn Playwright. Kørsel 35533443876 på 16ffe105: Playwright success.
• Den fejlende test handler om localStorage-persistens hen over reload i live-visningen. Der er ingen sti fra en Go-testhjælper i ingestoren til browserens localStorage.

Derfor én — og kun én — rerun af de fejlede jobs, jf. reglen om at urelaterede flakes må genkøres én gang efter dokumenteret sammenligning med master. Går den ikke grøn, diagnosticerer jeg den i stedet for at genkøre igen.

Sidebemærkning: "Multibyte only"-toggle er i forvejen på min opfølgningsliste fra #41-arbejdet af en anden grund (gaten skjuler replayede pakker). Denne fejl er en anden — persistens hen over reload — men samme flade, så den er værd at kigge på separat.

🤖 Generated with Claude Code