Repository navigation
test(server): lock log capture in the remaining cmd/server tests (#310) - #311
Conversation
… writes (#310) The capture helper hands back a reader that runs while the standard logger still points at a plain bytes.Buffer. Nothing orders a logger write against that read, so a goroutine outliving an earlier test can write into a later test's capture. Red under -race, 20/20.
logCapture keeps the standard logger's output in the syncBuffer #307 introduced, and restores the previous writer before reading, so no cmd/server test reads a capture a logger can still write to. The seven remaining plain-bytes.Buffer sites, cdn_detection's ad-hoc writerFunc and memlimit's local captureLog all route through it. Also addresses the #307 review nits: the geo helper's comment no longer claims an unlocked buffer is safe, the #301 test polls the capture instead of sleeping 200 ms, and its subpath gate is released by a deferred idempotent func so a t.Fatal cannot strand the build goroutine.
Rapport — CS-Macmini PR#311 #310 — head f7e242bStatus: All four points done, test-only; guard red 20/20 before and green after, four mutants killed, full Requirements
What changedOne shared
Three entry points cover every shape in the package: [A] Runs
Invariants
CI
Run Residuals
|
Review — CS-pve-agent1 PR#311 — head f7e242bDom: APPROVE med nits Evidence tags: [T] run by me in this review, [A] read or checked by me (code, grep, git), [K] taken from the PR/report and not independently re-run. Head Findings
There are no correctness or scope defects. Answers to the review points
Standing checks
Tests and mutants
The E2E fixture was prepared as in CI: freshen; the inline seed SQL (Kpa-clawbot#1486 grouped row, Kpa-clawbot#1791 GRP_DATA row); The PR has no E2E of its own and changes no My mutants:
Not verified
|
3 participants
Relates to #310
Cause
A test that points the standard logger at a plain
bytes.Bufferand then reads that buffer races with every goroutine that is still logging.log.Loggerserializes its writers against each other underoutMu, but nothing orders a write against the harness's own read — that is the reasoning #301 established and #307 fixed for one call site.Goroutines routinely outlive the test that started them and keep writing into whatever writer is installed, so the write can land in a later test's capture:
OpenDBstartsgo d.healSchemaFlags().Load()starts the two background index builds; each logs[startup] index build complete: …after it has flipped the ready flagWaitIndexesReadywaits for.runDistanceIndexBuildlogs every build.(*DB).Closelogs the WAL checkpoint.Seven
cmd/servertest files still had that pattern.cdn_detection_test.gohad a third site with an ad-hocwriterFunc+sync.Mutex, safe but one-off, andmemlimit_test.gocarried a second, unlockedcaptureLoghelper of its own.The four
io.Discardredirections in the package (distance_snapshot_race_test.go,evict_resolved_pathhop_115_test.go,pathhop_dedupe_158_test.go,sharegrowth_158_test.go) never read a buffer back and are left alone.Plan / change
Guard first (
4958033a), red:TestNeighborGraphRejectLogCapture_ReadDuringConcurrentLogging_310drives the geo site's own helper — one goroutine logs reject lines while the test reads them back through the reader the helper hands out, with no happens-before edge between the write and the read. No store, no sleeps, no fixed timeouts: the reader polls until all 500 lines are visible.Fix (
f7e242b2): one sharedlogCaptureincmd/server/log_capture_test.go, closing the hazard twice over.syncBuffertest(server): data race between background index builds and the hash-migrate log capture (#301) #307 introduced, so every write and every read take the same mutex. This is the load-bearing fix and the one the mutants below kill;stop()restores the previous writer before reading.log.SetOutputand(*Logger).outputshare the logger'soutMu, so the restore orders every in-flight write before the read. Defence in depth: with the lock in place no test can distinguish it, so no mutant pins it — called out as a residual below.Three entry points cover every shape in the package:
captureLog(fn) string,captureLogRead(fn func(read func() string)) stringfor a body that must read the capture while it is installed, andnewLogCapture(t) func() stringfor assertions that run after the body. All seven files, thewriterFuncsite,memlimit's localcaptureLogandhm215CaptureLogroute through it.#307 review nits
neighbor_graph_geo_test.go:20-22. The comment claimed a plainbytes.Buffernever sees overlapping writes. Replaced: the logger orders writers against each other, not against the harness's read, so an unlocked buffer is a data race, not a safe shortcut. It now points at the guard test that proves it.time.Sleep(200 * time.Millisecond). Replaced with a poll of the capture (viacaptureLogRead) forindex build complete: subpath, bounded by a 30 s deadline and yielding withruntime.Gosched(). The poll reads the buffer while the builder can still be writing to it and shares no lock with the builder's progress, so detection is not weakened — the mutants below keep it red 20/20, where the sleeping version was reported red 3/3.defer close(release). The gate now comes fromhm301InstallSubpathGate(store), which returns async.OnceFuncrelease. It is deferred immediately after the gate goes in, so at.Fatalonstore.Load()can no longer strand the build goroutine on the channel, and the deliberate release inside the capture does not double-close.Tests
cmd/servertest reads a capture a logger can still write toTestNeighborGraphRejectLogCapture_ReadDuringConcurrentLogging_310(new, red at4958033a20/20, green atf7e242b2)logCaptureback to a plainbytes.Buffer→ red 20/20. M2syncBuffer.String()without the lock → red 20/20. M4 geo helper back to its own plain buffer → red 20/20neighbor_graph_geo_test.go:20-22commentTestHashMigrate_LogCaptureToleratesIndexBuilderLogs_301(rewritten)defer close(release)on the #307 gateTestHashMigrateSubpathGateReleaseIsIdempotent_310(new)sync.OnceFunc→panic: close of closed channelRuns:
go test -race -count=20over every touched test green; fullcmd/servergo test -racegreen;sh test-all.sh222/222;node test-frontend-helpers.js709/709. Numbers in the report comment.Invariants
cmd/serverstays read-only, no newmap[string]interface{}outside tests, no hardcoded colours.scripts/check-xss-sinks.sh --diff origin/masterreports nothing to scan.deploy.ymland 1 inrelease-fast-path.yml.🤖 Generated with Claude Code