Repository navigation
test(ingestor): make neighbor metrics pruning deterministic - #33
Merged
adminopenclaw8-sketch merged 1 commit intoSep 13, 2026
Merged
Conversation
TestPruneOldNeighborMetrics hardcoded its "recent" fixture to 2026-07-26T12:00:00Z. Once the real date passed 2026-08-25 (30 days later), PruneOldNeighborMetrics(30) started pruning that row too, failing the test's "expected 1 row pruned, got 2" assertion on every run since -- reproduced twice against unmodified origin/master (fda24ca) before this change. This is baseline test nondeterminism, not a production defect: the retention query itself (`WHERE timestamp < cutoff`) is unaffected and unchanged. Fix: pin the test to a fixed reference instant via a new pruneNeighborMetricsNow package-level clock hook (same swap-in-test / restore-in-cleanup pattern already used by readProcSelfIOFn in stats_file.go), instead of a hardcoded calendar date. Production keeps calling time.Now() by default -- only the indirection changes, not the retention behavior, the 30-day window, or any caller. The rewritten test also pins the exact retention boundary explicitly (a row exactly `retentionDays` old is retained, matching the query's strict `<`), proves multiple rows don't influence each other's fate, and proves the fixture's timestamp timezone offset doesn't change the outcome (normalizeReportTS re-stores everything as canonical UTC). Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
This was referenced Sep 13, 2026
dborup
marked this pull request as ready for review
September 13, 2026 10:47
adminopenclaw8-sketch
pushed a commit
that referenced
this pull request
Sep 14, 2026
…rl comments Two review fixes on this PR. 1. CI registration. `test-issue-1890-og-url.js` was only wired into `test-all.sh` (used by `npm test`), not into the JS test step in `.github/workflows/deploy.yml`. CI could not catch a regression of the hardcoded og:url. Added `node test-issue-1890-og-url.js` to that step's existing list, directly before `test-issue-1375-scope-stats- fetch.js` (the test that currently stops the step). test-all.sh is unchanged; the registration there was already correct. 2. Comment accuracy, in `public/index.html` and `test-issue-1890-og-url.js`. The removed tag declared the upstream analyzer instance's own URL as the canonical URL for every self-hosted deployment (Kpa-clawbot#1890) -- correct metadata for upstream, wrong for everyone else. Reworded both comments to say that precisely, and to stop implying things not established: - og:url is metadata, not an HTTP redirect, and does not by itself decide what a viewer's click navigates to. - Per the Open Graph protocol it is a required property, not "optional" -- omitting it leaves the crawled URL as the fallback canonical reference, which is what actually fixes this for every instance. - This change does not refresh previews a consumer has already cached under the old, hardcoded value. No functional assertions changed in test-issue-1890-og-url.js -- only the file-level comment. The `public/index.html` comment change had to avoid writing the literal removed domain: the test's own 4th assertion scans the whole file for that string, and an earlier draft of this comment briefly reintroduced it and failed its own guard before landing on the current wording. Verified on this branch's own base (pre-#51/#33 master) and against a merge into current master: test-issue-1890-og-url.js passes 4/4 on the resulting index.html and still fails 2/4 (og:url present, 00id.net present) against the original hardcoded tag. The merge result's deploy.yml differs from current master by exactly the one added test line; release-fast-path.yml and cmd/server/fork_guard_workflow_test.go are byte-identical to master, and all four #51 repository guards (the five build-and-publish publish steps, release-artifacts, deploy, publish, retag-or-fallback) are present in the merged file. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
This was referenced Sep 14, 2026
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Small, isolated prerequisite fix: makes
TestPruneOldNeighborMetrics(cmd/ingestor) deterministic. This does not touch Go version, Dockerfiles,deploy.yml, production retention behavior, database migrations, or any other test — see "Scope audit" below.Baseline:
origin/masterat mission start / this branch's parent commit —fda24ca575a9e77a3d9acce2aad249284e0d4f2fHead:
1c6a8afca4ffcee85f95a11d598486fe782b921fRelationship to #22: none. #22 (bump Dockerfile base images) is untouched — its branch, head SHA (
207304ea0d93e80feb7e1d5a054caba8e639e63d), and files were re-verified unchanged at the end of this work. This PR does not approve, endorse, or merge #22 and carries no opinion on it. It exists only because independent research surfaced thatTestPruneOldNeighborMetricsfails on both Go 1.22.12 and Go 1.27.1 — baseline nondeterminism, not a Go-version regression — and a Go-only PR should not have to carry an unrelated, already-broken test as noise in its CI run.Root cause
TestPruneOldNeighborMetricshardcoded its "recent" fixture to a fixed calendar date:PruneOldNeighborMetrics(30)computescutoff := time.Now().UTC().AddDate(0, 0, -30)and deletes rows withtimestamp < cutoff. Once real time passed 2026-08-25 (30 days after the fixture date), the "recent" row itself crossed the retention boundary and started getting pruned alongside the intentionally-old row, failing the test's own assertion.Before/after retention arithmetic (reproduced against unmodified
fda24ca5, run at 2026-09-13T09:28:15Z)now(test run time)cutoff= now − 30doldrecentPruneOldNeighborMetricsreturns 2, test asserts 1 →FAIL: expected 1 row pruned, got 2Reproduced twice on the unmodified baseline before any change (both runs:
observer_neighbor_metrics_test.go:128: expected 1 row pruned, got 2).This is baseline test nondeterminism, not a production defect — the retention query itself is correct and is unchanged by this PR.
Fix
The production change is exactly one thing: a clock-hook whose default is
time.Now.PruneOldNeighborMetrics's retention SQL (DELETE FROM observer_neighbor_metrics WHERE timestamp < ?), itsretentionDaysparameter, and the exact-boundary (<, not<=) semantics are byte-for-byte unchanged. The only thing that changed is where "now" is read from:Smallest deterministic correction, following the order of preference given for this task:
PruneOldMetrics,PruneDroppedPackets,PruneOldClientReceptions— all calltime.Now()directly, no seam).TestPruneOldMetrics,TestPruneOldClientReceptions) already avoid hardcoded dates by computing fixtures relative totime.Now()at test-run time. That pattern is safe for "clearly older" / "clearly newer" cases, but not safe for pinning the exact boundary: the test's owntime.Now()call and the production function's internaltime.Now()call happen a few instructions apart, and since storage truncates to RFC3339 (second) precision, an unlucky second-boundary straddle could occasionally flip the boundary row's fate — a real, if rare, source of flakiness that would violate "deterministic regardless of execution speed."readProcSelfIOFninstats_file.go, a package-level function variable swapped in tests and restored viat.Cleanup. This PR adds one narrowly-scoped clock hook,pruneNeighborMetricsNow, following that identical pattern, used only byPruneOldNeighborMetrics.No sleeps, no broadened tolerances, no retention-period changes, no date-relabeling to another future date, and no test skip/quarantine.
Exact-boundary semantics
PruneOldNeighborMetrics's query isWHERE timestamp < cutoff— a strict less-than. So a row exactlyretentionDaysold (timestamp == cutoff) is retained, not pruned. The rewritten test pins this explicitly:nowpkOldpkBoundary<vs<=semantic)pkRecentpkRecentOffsetpkRecent, expressed with a+02:00(Copenhagen) offset instead ofZpkRecent(timezone-invariance:normalizeReportTSre-stores everything as canonical UTC)Each fixture uses a distinct pubkey so the assertions prove the four rows don't influence one another's fate (not just an aggregate count).
Clock-hook safety review
A second review pass specifically re-examined whether the new package-level
pruneNeighborMetricsNowvariable could be read by a background goroutine while a test is overriding or restoring it — absence oft.Parallel()alone is not sufficient evidence, so this traces full ownership/lifecycle, not just that one fact:pruneNeighborMetricsNowis read at exactly one call site (db.go, insidePruneOldNeighborMetrics).PruneOldNeighborMetricsitself is called from exactly three places in the whole repo: two inmain.go(both insidefunc main()'s startup/ticker code, never reachable fromgo test), and one insideTestPruneOldNeighborMetricsitself.OpenStore/OpenStoreWithIntervalschedule two background migrations viaRunAsyncMigration(obs_observer_ts_idx_v1, an index build;tx_last_seen_backfill_v1→backfillTxLastSeen). Read both function bodies: neither callsPruneOldNeighborMetricsor touchespruneNeighborMetricsNow, directly or indirectly.WriterExec/instrumentedExec(the DB call insidePruneOldNeighborMetrics) are fully synchronous — no goroutine is spawned inside the function that could outlive the call and read the hook aftert.Cleanuphas already restored it.t.Fatalfbefore reaching its normal end: the next test observed the hook correctly restored totime.Now.panic()s outright: a side-effecting print placed inside thet.Cleanupcallback fired (proving the cleanup ran) before the test binary's crash from the unrecovered panic — and since an unrecovered panic terminates the whole test process, there is no subsequent test execution window in which a "half-restored" hook could ever be observed.-raceevidence:TestPruneOldNeighborMetricsalone,-race -count=20→ 0 races; fullcmd/ingestorpackage-race(both by this work and independently by a separate reviewer) → 0 race reports ever implicatepruneNeighborMetricsNow,PruneOldNeighborMetrics, orTestPruneOldNeighborMetricsin any run. The races that do exist in the package (below) are structurally unrelated — none of them touch this variable.Two pre-existing, unrelated baseline problems (NOT fixed here — documented, not touched)
These are kept visible, not silenced. This PR does not claim a fully green test suite.
A.
TestBackfillTxLastSeen_ResolvesFromMaxObservationTimestamp— timing/assertion flake (no-raceneeded to see it)cd cmd/ingestor && go test -run '^TestBackfillTxLastSeen_ResolvesFromMaxObservationTimestamp$' -v -count=10 .— toolchain: localgo1.26.0 darwin/arm64(module declaresgo 1.22; behavior is unaffected by Go version — this same test also fails on Go 1.22.12 and 1.27.1 per earlier CI-toolchain research).fda24ca5: 10 isolated single-process runs → 2 FAIL / 8 PASS; a separate 5-run sample → 3 FAIL / 2 PASS. Flake rate is not fixed — it depends on goroutine scheduling.tx_last_seen_backfill_test.go:63: last_seen = 100, want 300 (MAX of 100,300,200).newTestStore/openNeighborsStorecallOpenStore, which unconditionally schedulesbackfillTxLastSeenas an async migration (tx_last_seen_backfill_v1) the instant the store opens. The test also callsbackfillTxLastSeen(context.Background(), store.db)directly and synchronously right after seeding. A captured failing run shows the tell-tale interleaving directly in the log — two"Backfilling transmissions.last_seen..."start lines print before either completion line appears, proving two literally-concurrent executions of the same function against the same DB handle:backfillTxLastSeen's own selection filter isWHERE last_seen = 0 ...(db.go), so whichever of the two concurrent calls'UPDATEruns first "claims" the row — if that happens to land in the brief window between the test'sINSERTof observation100and its laterINSERTs of300/200, the row gets stampedlast_seen = 100and is permanently excluded (last_seen != 0) from ever being recomputed by the test's own later, deliberate call. 10/10 runs (not just the failing ones) show exactly two start/complete pairs of this migration — confirming the double-invocation itself is deterministic; only the exact interleaving/outcome is not.INSERTinside the test's seeding loop the async call'sSELECT/UPDATElands between. The mechanism (two unsynchronized concurrent callers of the same "claim-once" function) is established fact; the microsecond-level interleaving on any one run is not individually traced.dborup/CoreScopeissues (gh issue list --state all, keyword and full-list sweep) and found none covering this; only 4 issues exist in this fork total, none related. Not created without approval.B. Data race between the async backfill migration and a test's own log-buffer capture (
issue1865_test.go) — needs-race, self-contained to one testcd cmd/ingestor && go test -run '^TestHandleNeighborsReportInvalidTimestampLogsEvenWithoutScopeEvidence$' -race -v -count=50 .— same toolchain as above.fda24ca5, running this ONE test completely alone (nothing else in the test binary, ruling out any cross-test leak): 5/50 runs hitWARNING: DATA RACE.openNeighborsStore(t)at that test's own line 719 schedules the asyncbackfillTxLastSeenmigration, and a few lines later (line 731) that same test doeslog.SetOutput(&buf)+ readsbuf.String()without first waiting for its own just-spawned migration goroutine to finish. This is self-contained to one test, not a cross-test leak — confirmed by reproducing it with this test running completely alone, in isolation, with no other test in the binary at all. (This corrects a looser earlier characterization — of a "leaked goroutine colliding with a later test's log capture" — that was proposed before this isolation run; the isolation run shows no other test's involvement is needed or occurs.)log.SetOutput-capture pattern (decode_error_log_test.go,default_scope_bench_test.go,ingest_buffer_test.go,mqtt_reconnect_test.go,mqtt_watchdog_r2_test.go,mqtt_watchdog_1810_test.go,multibyte_persist_helpers_test.go) is equally exposed — each was located by grep but not individually stress-tested for this PR; flagged as a strong "likely, not yet each individually confirmed" candidate for the same class of bug in the proposed follow-up below.Correction re: a third, distinct pre-existing race (found by this review, previously mischaracterized)
While re-verifying B, a full-
cmd/ingestor-package-racerun captured during this PR's own earlier validation work was re-examined stack-trace-by-stack-trace, and turned out to be a third, separate bug, not an instance of B as originally assumed:This is the same class of bug as B (a leaked async goroutine racing a test's own restore of shared state), but a different variable, a different file pair, and — like B — self-contained to one test: reproduced by running
TestStatsFileWriter_SampledAtMatchesProcIOSampledAtalone,-race -count=30, on unmodifiedfda24ca5→ 7/30 race warnings, 4/30 FAIL. Go's race detector attributes a race report to whichever test happens to be executing on the CPU when it fires, which is why an earlier full-package run's race was attributed toTestBackfillTxLastSeen_ResolvesFromMaxObservationTimestamp(problem A's test, which was mid-run at that moment) even though neither of that race's two actual goroutines belongs to that test at all. There are at least three distinct pre-existing bugs in this package's async-migration test infrastructure (A, B, and this one), not one "flake" or two. This one is also not fixed here; also not yet filed as an issue (no duplicate found; not created without approval).Scope audit
cmd/ingestor/db.go(+9/−1: adds thepruneNeighborMetricsNowvar, changes one call site fromtime.Now()topruneNeighborMetricsNow()),cmd/ingestor/observer_neighbor_metrics_test.go(+77/−14: rewritesTestPruneOldNeighborMetrics).go.mod/go.sumare byte-identical toorigin/master).Dockerfile.go, ordeploy.ymlchanged.git diff --check: clean (no whitespace errors) — reconfirmed against exact head1c6a8afc.gofmt -lon both changed files: clean — reconfirmed against exact head1c6a8afc.Repeated-test results
All runs against this branch's exact head (
1c6a8afc),cmd/ingestor, local Go 1.26.0 darwin/arm64 (go.mod declaresgo 1.22, unaffected by this change):TestPruneOldNeighborMetricsalone,-count=25(+ a fresh reconfirm-count=10)TestPruneOldNeighborMetricsalone,-race -count=20(+ a fresh reconfirm-count=10)TestPruneOldNeighborMetricsalone,TZ=UTC,-count=5TestPruneOldNeighborMetricsalone,TZ=Europe/Copenhagen,-count=5TestRecordObserverNeighborMetrics_*,TestHandleNeighborsReport_RecordsSnrHistory)TestPruneOldMetrics,TestPruneOldClientReceptions,TestPruneDroppedPackets)cmd/ingestorsuite, no race,-count=1cmd/ingestorsuite,-race -count=1TestPruneOldNeighborMetricsitself: PASS, 0 races, in every run including this one.cmd/serverfull suite,-count=1cmd/decrypt,cmd/migrate, all 10internal/*modules[no test files]where applicablego build ./...+go vet ./..., all 15 Go modulesThis PR does not claim a fully green suite. Problems A and B (plus the third race documented above) are pre-existing on unmodified
fda24ca5, independent of this change, and are explicitly out of scope here (no race fixes, per this task's boundaries) — see the dedicated section above for reproduction commands, exact stack traces, and what's established fact vs. hypothesis for each.Confirmation
go.mod/go.sum/Dockerfile/deploy.ymldiff anywhere in this branch).pruneNeighborMetricsNowclock-hook indirection described above; it defaults totime.Nowand is never touched outside this one test.🤖 Generated with Claude Code
Actions / CI status (observed only — nothing restarted or approved)
cmd/ingestoris fully green —ok github.com/corescope/ingestor 116.339s coverage: 76.7% of statements, noFAILline for any Go test, andTestBackfillTxLastSeen_ResolvesFromMaxObservationTimestamp(Problem A) did not trigger in this particular run, consistent with it being a probabilistic flake rather than a deterministic failure. The only failing job on this PR is an unrelated frontend JS test —✗ Exactly one 'api('/scope-stats'' call exists (the fixed loader) — found 2(#1375 FAIL) — in a file untouched by this branch; present identically on unmodifiedorigin/mastersince this branch never touches any JS file.codex/port-upstream-1969-...,codex/port-upstream-1957-...,codex/port-upstream-1962-..., etc. — unrelated branches, touching none of the files in this PR) show--- FAIL: TestPruneOldNeighborMetricsand/or--- FAIL: TestBackfillTxLastSeen_ResolvesFromMaxObservationTimestampin their own CI runs from the last few hours (gh run list,gh run view --log-failed). This is real-world confirmation, independent of this PR, that Problem-A-the-hardcoded-fixture-date is now actively red-flagging CI for anyone building onmaster, not just a theoretical/local finding.deploy.yml:on: pull_request: branches: [master]has notypes:key, so per GitHub's default it only listens foropened,synchronize,reopened— notready_for_review. Independently, thedeployjob is separately gatedif: (github.event_name == 'push' || github.event_name == 'workflow_dispatch') && github.ref == 'refs/heads/master', so it cannot run for a pull_request event or a non-master branch regardless. No workflow was restarted or approved as part of this update.Review verification (independent pass on exact head
1c6a8afc)Base
fda24ca5(unchangedorigin/master), isolated checkout, localgo1.27.0 darwin/arm64, all runs sequential. The line counts in the scope audit above were corrected to the actual diff:db.go+9/−1 and the test +77/−14. No code or head change was made.Clock hook: no concrete new risk found
pruneNeighborMetricsNowis read at exactly one place (db.go:2355, insidePruneOldNeighborMetrics). It is written only inTestPruneOldNeighborMetrics: the override at line 148, and the restore viat.Cleanupat line 147, which is registered before the override.PruneOldNeighborMetricsis called in production only insidefunc main(): at startup (main.go:270) and in the 24 h ticker goroutine (main.go:338). No test callsmain(), and no other test calls the function, so no other goroutine can read the hook during the test, independent oft.Parallel().openNeighborsStore→OpenStorestarts twoRunAsyncMigrationgoroutines: theobs_observer_ts_idx_v1index build andbackfillTxLastSeen. Neither reaches the prune function or the hook.Store.Closewaits for them viabackfillWg.Wait(). Cleanups run in reverse order, so the hook is restored before the store closes.PruneOldNeighborMetrics→instrumentedExec→WriterExecis synchronous.t.Cleanupruns on normal completion and ont.Fatal/FailNow. The panic case is covered by the author's empirical check above. A failure before the override only restores the original value.time.Now. Within the function, only thecutoffline differs from master. The SQL (DELETE FROM observer_neighbor_metrics WHERE timestamp < ?), theretentionDaysparameter, the signature and bothmain.gocall sites are unchanged.db.gois the only production file in the diff.RecordObserverNeighborMetricsstoresnormalizeReportTS(ts)=t.UTC().Format(time.RFC3339), the same fixed-width format ascutoff, so the string comparison is chronological. Rows older than the cutoff are deleted, and a row exactly at the cutoff is kept (strict<). Changing<to<=would fail both then != 1and thepkBoundaryassertions. The negative control documented above (boundary fixture moved 1 s past the cutoff → fails) was not repeated.time.FixedZone, so the arithmetic is correct.Fresh results
gofmt -lon both filesgit diff --check fda24ca5..1c6a8afccmd/ingestorgo build+go vet ./...at headTestPruneOldNeighborMetricson master,TZ=UTCandTZ=Europe/Copenhagenexpected 1 row pruned, got 2TZ=UTC,-count=20TZ=Europe/Copenhagen,-count=20TZ=UTC,-race -count=20TZ=Europe/Copenhagen,-race -count=20TestRecordObserverNeighborMetrics_*,TestHandleNeighborsReport_RecordsSnrHistory,TestPruneOldMetrics,TestPruneOldClientReceptions,TestPruneDroppedPackets) at headpruneNeighborMetricsNow/PruneOldNeighborMetricsPre-existing problems this PR does not fix (kept separate)
A. Functional backfill timing failure:
TestBackfillTxLastSeen_ResolvesFromMaxObservationTimestamp, no-raceneeded-count=20: master failed 1/20, this head 4/20. Every failure had the same assertion:last_seen = 100, want 300 (MAX of 100,300,200).backfillTxLastSeennor that test. The author's earlier master samples (2/10 and 3/5) span the same range.cmd/ingestortree equals master's.B. Race-detector data race against the test's log buffer:
TestHandleNeighborsReportInvalidTimestampLogsEvenWithoutScopeEvidence,-race-race -count=50: master had 6 race reports (3 failing iterations), this head 6 race reports (4 failing iterations).log.Println→bytes.(*Buffer).WritefrombackfillTxLastSeen/RunAsyncMigration, racingbytes.(*Buffer).Stringatissue1865_test.go:731.log.SetOutput-capturing tests are equally exposed is not individually verified here.The third race described above (
stats_filewriter vsstats_file_timestamp_test.gocleanup) was not re-run in this pass.CI (observed only; nothing restarted or approved)
1c6a8afc: “Go Build & Test” = failure.✗ Exactly one api('/scope-stats' call exists … found 2(#1375 FAIL). That file is untouched here, and the test also fails on unmodified master locally.set -e, later JS tests and the remaining steps in that job did not run.pull_requesthas notypes:key, soready_for_reviewand body edits do not start runs, and the deploy job requirespush/workflow_dispatchonrefs/heads/master.Not run in this pass
cmd/ingestor/cmd/serversuite (only the targeted runs above).