From 4958033a1be31c1b95f8e10b963bf8dd08715b0e Mon Sep 17 00:00:00 2001 From: dborup Date: Tue, 6 Oct 2026 10:45:14 +0200 Subject: [PATCH 1/2] test(server): guard the neighbor-graph log capture against concurrent 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. --- cmd/server/log_capture_race_310_test.go | 55 +++++++++++++++++++++++++ 1 file changed, 55 insertions(+) create mode 100644 cmd/server/log_capture_race_310_test.go diff --git a/cmd/server/log_capture_race_310_test.go b/cmd/server/log_capture_race_310_test.go new file mode 100644 index 000000000..0f3b928ce --- /dev/null +++ b/cmd/server/log_capture_race_310_test.go @@ -0,0 +1,55 @@ +package main + +import ( + "log" + "testing" + "time" +) + +// Issue #310 (follow-up to #301 / #307): a guard for the neighbor-graph geo +// capture, one of the seven cmd/server sites that redirected the standard +// logger into a plain bytes.Buffer. +// +// captureNeighborGraphRejectLog installs the capture for the whole test and +// hands back a reader the test calls while the logger still points at that +// buffer. log.Logger orders its writers against each other under outMu, but +// nothing orders a write against the harness's own read. Plenty of goroutines +// log at moments the test does not control -- OpenDB's healSchemaFlags, the +// two background index builds Load() starts, runDistanceIndexBuild, +// (*DB).Close's WAL checkpoint, the recomputers -- and one left over from an +// earlier test can write into a later test's capture. +// +// The hazard is reproduced here without a store: one goroutine logs reject +// lines while the test reads them back, with no happens-before edge between +// the write and the read. Red under -race while the capture buffer is +// unlocked, green once every access takes the capture's mutex. +func TestNeighborGraphRejectLogCapture_ReadDuringConcurrentLogging_310(t *testing.T) { + read := captureNeighborGraphRejectLog(t) + + const lines = 500 + started := make(chan struct{}) + done := make(chan struct{}) + go func() { + defer close(done) + // Do not race ahead of the reader: the overlap is the point. + <-started + for i := 0; i < lines; i++ { + log.Printf("[neighbor-graph] reject geo-far edge marker-310 %d", i) + } + }() + + deadline := time.Now().Add(30 * time.Second) + got := read() + close(started) + for len(got) < lines { + if time.Now().After(deadline) { + t.Fatalf("captured %d of %d reject lines before the deadline", len(got), lines) + } + got = read() + } + <-done + + if n := len(read()); n != lines { + t.Fatalf("captured %d reject lines, want %d", n, lines) + } +} From f7e242b2a28b728a81fb0338e7c30c1e3d62a9a9 Mon Sep 17 00:00:00 2001 From: dborup Date: Tue, 6 Oct 2026 10:54:30 +0200 Subject: [PATCH 2/2] test(server): one locked log capture for every cmd/server test (#310) 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. --- cmd/server/cdn_detection_test.go | 124 ++++++++---------- cmd/server/hash_migrate_log_race_301_test.go | 68 ++++++++-- cmd/server/hash_migrate_readonly_215_test.go | 13 +- cmd/server/issue199_node_not_found_test.go | 51 ++++--- cmd/server/log_capture_test.go | 95 ++++++++++++++ cmd/server/memlimit_test.go | 21 +-- cmd/server/neighbor_graph_geo_test.go | 31 ++--- .../nodes_pagination_postfilter_test.go | 45 +++---- .../ping_score_history_production_test.go | 20 +-- .../schema_degradation_per_store_test.go | 28 ++-- 10 files changed, 284 insertions(+), 212 deletions(-) create mode 100644 cmd/server/log_capture_test.go diff --git a/cmd/server/cdn_detection_test.go b/cmd/server/cdn_detection_test.go index ffbd47f5c..9a7816c28 100644 --- a/cmd/server/cdn_detection_test.go +++ b/cmd/server/cdn_detection_test.go @@ -18,8 +18,6 @@ package main // next.ServeHTTP. import ( - "bytes" - "log" "net/http" "net/http/httptest" "strings" @@ -40,22 +38,21 @@ func resetCDNDetectionOnce() { // the middleware did not silently drop the request. func runWithCDNMiddleware(t *testing.T, req *http.Request) (string, bool) { t.Helper() - var buf bytes.Buffer - prev := log.Writer() - log.SetOutput(&buf) - defer log.SetOutput(prev) - nextCalled := false - h := cdnDetectionMiddleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - nextCalled = true - w.WriteHeader(http.StatusOK) - })) - w := httptest.NewRecorder() - h.ServeHTTP(w, req) - if w.Code != http.StatusOK { - t.Fatalf("middleware must not block request; got status %d", w.Code) - } - return buf.String(), nextCalled + // The capture is locked (#310): goroutines from earlier tests keep + // logging into whatever writer is installed. + out := captureLog(func() { + h := cdnDetectionMiddleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + nextCalled = true + w.WriteHeader(http.StatusOK) + })) + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + if w.Code != http.StatusOK { + t.Fatalf("middleware must not block request; got status %d", w.Code) + } + }) + return out, nextCalled } func TestCDNDetection_LogsOnCFRayHeader(t *testing.T) { @@ -145,30 +142,29 @@ func TestCDNDetection_LogsWhenCDNHeaderAccompaniesProxyHeaders(t *testing.T) { func TestCDNDetection_LogsOnlyOnce(t *testing.T) { resetCDNDetectionOnce() - var buf bytes.Buffer - prev := log.Writer() - log.SetOutput(&buf) - defer log.SetOutput(prev) - nextCalled := 0 - h := cdnDetectionMiddleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - nextCalled++ - w.WriteHeader(http.StatusOK) - })) - - for i := 0; i < 3; i++ { - req := httptest.NewRequest("GET", "/api/observers", nil) - req.Header.Set("CF-Ray", "abc123") - w := httptest.NewRecorder() - h.ServeHTTP(w, req) - } + // The capture is locked (#310): goroutines from earlier tests keep + // logging into whatever writer is installed. + out := captureLog(func() { + h := cdnDetectionMiddleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + nextCalled++ + w.WriteHeader(http.StatusOK) + })) + + for i := 0; i < 3; i++ { + req := httptest.NewRequest("GET", "/api/observers", nil) + req.Header.Set("CF-Ray", "abc123") + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + } + }) if nextCalled != 3 { t.Fatalf("middleware must call next on every request; got %d calls, want 3", nextCalled) } - got := strings.Count(buf.String(), "detected request via CDN") + got := strings.Count(out, "detected request via CDN") if got != 1 { - t.Errorf("expected CDN warning exactly once across multiple requests; got %d in output: %q", got, buf.String()) + t.Errorf("expected CDN warning exactly once across multiple requests; got %d in output: %q", got, out) } } @@ -206,56 +202,40 @@ func TestCDNDetection_RecognizesAllCommonCDNHeaders(t *testing.T) { func TestCDNDetectionMiddlewareConcurrentFirstRequestLogsOnce(t *testing.T) { resetCDNDetectionOnce() - var buf bytes.Buffer - var bufMu sync.Mutex - prev := log.Writer() - // log.Printf can be called concurrently; serialize writes to buf - // so we never race the test's own assertion read. - log.SetOutput(writerFunc(func(p []byte) (int, error) { - bufMu.Lock() - defer bufMu.Unlock() - return buf.Write(p) - })) - defer log.SetOutput(prev) - var nextCalls int64 - h := cdnDetectionMiddleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - atomic.AddInt64(&nextCalls, 1) - w.WriteHeader(http.StatusOK) - })) - const n = 50 - var wg sync.WaitGroup - wg.Add(n) - for i := 0; i < n; i++ { - go func() { - defer wg.Done() - req := httptest.NewRequest("GET", "/api/observers", nil) - req.Header.Set("CF-Ray", "abc123-LAX") - w := httptest.NewRecorder() - h.ServeHTTP(w, req) - }() - } - wg.Wait() + // log.Printf is called concurrently here; the shared capture is locked + // (#310), so this no longer needs a buffer and mutex of its own. + out := captureLog(func() { + h := cdnDetectionMiddleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + atomic.AddInt64(&nextCalls, 1) + w.WriteHeader(http.StatusOK) + })) + + var wg sync.WaitGroup + wg.Add(n) + for i := 0; i < n; i++ { + go func() { + defer wg.Done() + req := httptest.NewRequest("GET", "/api/observers", nil) + req.Header.Set("CF-Ray", "abc123-LAX") + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + }() + } + wg.Wait() + }) if got := atomic.LoadInt64(&nextCalls); got != n { t.Fatalf("middleware must call next on every concurrent request; got %d, want %d", got, n) } - bufMu.Lock() - out := buf.String() - bufMu.Unlock() got := strings.Count(out, "detected request via CDN") if got != 1 { t.Errorf("expected sync.Once to admit exactly ONE warning under %d concurrent first-requests; got %d. Output:\n%s", n, got, out) } } -// writerFunc adapts a function to io.Writer. -type writerFunc func(p []byte) (int, error) - -func (f writerFunc) Write(p []byte) (int, error) { return f(p) } - // Round-2 MAJOR finding: sync.Once only short-circuits the log.Printf, // not the per-request header scan. firstCDNHeader still iterates 4 // http.Header.Get lookups on every /api request after warning fires. diff --git a/cmd/server/hash_migrate_log_race_301_test.go b/cmd/server/hash_migrate_log_race_301_test.go index c485adcd9..8191cd40d 100644 --- a/cmd/server/hash_migrate_log_race_301_test.go +++ b/cmd/server/hash_migrate_log_race_301_test.go @@ -1,11 +1,47 @@ package main import ( + "runtime" "strings" + "sync" "testing" "time" ) +// hm301InstallSubpathGate holds the subpath index build until the returned +// release runs. release is idempotent, so the caller can defer it right after +// the gate goes in and still release it on purpose later: without that +// deferred net a t.Fatal between the two (store.Load returning an error, say) +// would leave the build goroutine blocked on the channel for the rest of the +// run (#310, nit 3 of the #307 review). +func hm301InstallSubpathGate(store *PacketStore) (release func()) { + gate := make(chan struct{}) + store.subpathBuildGate = func() { <-gate } + return sync.OnceFunc(func() { close(gate) }) +} + +// The deferred net and the deliberate release are the same func, so releasing +// twice must be a no-op rather than a "close of closed channel" panic. +func TestHashMigrateSubpathGateReleaseIsIdempotent_310(t *testing.T) { + store := &PacketStore{} + release := hm301InstallSubpathGate(store) + + blocked := make(chan struct{}) + go func() { + defer close(blocked) + store.subpathBuildGate() + }() + + release() + release() + + select { + case <-blocked: + case <-time.After(30 * time.Second): + t.Fatal("the gated build goroutine was never released") + } +} + // Issue #301: Load() starts the two background index builds, and each builder // logs one more line ("index build complete") AFTER it has flipped its ready // flag. WaitIndexesReady returning therefore does not mean the builders are @@ -13,8 +49,7 @@ import ( // The log capture of the hash-migrate harness must take those writes without a // data race: here the subpath builder is released inside the capture, so its // last line lands in the captured output while nothing orders it before the -// read at the end of the capture. Red under -race with an unsynchronized -// buffer. +// harness's reads. Red under -race with an unsynchronized buffer. func TestHashMigrate_LogCaptureToleratesIndexBuilderLogs_301(t *testing.T) { d := hm215Create(t) d.ballast(t) @@ -24,23 +59,36 @@ func TestHashMigrate_LogCaptureToleratesIndexBuilderLogs_301(t *testing.T) { } t.Cleanup(func() { db.conn.Close() }) store := NewPacketStore(db, &PacketStoreConfig{}) - release := make(chan struct{}) - store.subpathBuildGate = func() { <-release } + release := hm301InstallSubpathGate(store) + defer release() // a t.Fatal below must not strand the build goroutine if err := store.Load(); err != nil { t.Fatal(err) } - out := hm215CaptureLog(func() { - close(release) + const want = "index build complete: subpath" + out := captureLogRead(func(read func() string) { + release() if !store.WaitIndexesReady(30 * time.Second) { t.Error("background index builds did not finish") + return } // The builder logs its completion line after the ready flag that - // woke us; give it time to land in the capture. Sleeping orders - // nothing, so the race detector still sees the two accesses. - time.Sleep(200 * time.Millisecond) + // woke us. Poll the capture for it rather than sleeping a fixed + // 200 ms (#310, nit 2 of the #307 review): the poll reads the + // buffer while the builder can still be writing to it and shares + // no lock with the builder's own progress, so an unsynchronized + // capture is still a race the detector reports — proven by the + // mutant in the PR report. + deadline := time.Now().Add(30 * time.Second) + for !strings.Contains(read(), want) { + if time.Now().After(deadline) { + t.Error("the subpath builder's last line did not arrive") + return + } + runtime.Gosched() + } }) - if !strings.Contains(out, "index build complete: subpath") { + if !strings.Contains(out, want) { t.Fatalf("the subpath builder's last line was not captured:\n%s", out) } } diff --git a/cmd/server/hash_migrate_readonly_215_test.go b/cmd/server/hash_migrate_readonly_215_test.go index 12c9ecf86..003ce537c 100644 --- a/cmd/server/hash_migrate_readonly_215_test.go +++ b/cmd/server/hash_migrate_readonly_215_test.go @@ -5,7 +5,6 @@ import ( "database/sql" "database/sql/driver" "fmt" - "log" "os" "path/filepath" "reflect" @@ -239,15 +238,9 @@ func hm215Migrate(s *PacketStore, batch int) string { // hm215CaptureLog returns what the standard logger printed while fn ran. The // buffer is locked: the index builders that Load() starts log their last line // after the ready flag WaitIndexesReady waits for, so one can still be writing -// when the capture is read (#301). -func hm215CaptureLog(fn func()) string { - buf := newSyncBuffer() - prev := log.Writer() - log.SetOutput(buf) - defer log.SetOutput(prev) - fn() - return buf.String() -} +// when the capture is read (#301). Since #310 every cmd/server capture shares +// that one helper. +func hm215CaptureLog(fn func()) string { return captureLog(fn) } // stmtLog records every statement a connection prepares or every transaction it // begins. database/sql falls back to Prepare/Begin for a driver connection that diff --git a/cmd/server/issue199_node_not_found_test.go b/cmd/server/issue199_node_not_found_test.go index b3c83329b..daa4609de 100644 --- a/cmd/server/issue199_node_not_found_test.go +++ b/cmd/server/issue199_node_not_found_test.go @@ -1,10 +1,8 @@ package main import ( - "bytes" "context" "encoding/json" - "log" "net/http/httptest" "strings" "testing" @@ -167,18 +165,16 @@ func TestNodeDetail404LookupErrorIsLoggedOnce(t *testing.T) { if _, err := srv.db.conn.Exec(`CREATE TABLE inactive_nodes (public_key TEXT PRIMARY KEY, name TEXT)`); err != nil { t.Fatal(err) } - var buf bytes.Buffer - prev := log.Writer() - log.SetOutput(&buf) - defer log.SetOutput(prev) - - for i := 0; i < 3; i++ { - code, body := issue199Get(t, router, issue199Unknown) - if code != 404 || len(body) != 1 || body["error"] == nil { - t.Fatalf("request %d: status=%d body=%v, want the bare 404", i, code, body) + // The capture is locked (#310): the server's background goroutines keep + // logging into whatever writer is installed. + out := captureLog(func() { + for i := 0; i < 3; i++ { + code, body := issue199Get(t, router, issue199Unknown) + if code != 404 || len(body) != 1 || body["error"] == nil { + t.Fatalf("request %d: status=%d body=%v, want the bare 404", i, code, body) + } } - } - out := buf.String() + }) if n := strings.Count(out, "missing-node lookup failed"); n != 1 { t.Fatalf("logged %d lookup failures for 3 requests, want 1; log:\n%s", n, out) } @@ -193,21 +189,20 @@ func TestNodeDetail404LookupErrorIsLoggedOnce(t *testing.T) { // A request cancelled by its client is not a broken lookup: nothing logged. func TestNodeDetail404CancelledLookupIsNotLogged(t *testing.T) { srv, _ := setupTestServer(t) - var buf bytes.Buffer - prev := log.Writer() - log.SetOutput(&buf) - defer log.SetOutput(prev) - - ctx, cancel := context.WithCancel(context.Background()) - cancel() - req := httptest.NewRequest("GET", "/api/nodes/"+issue199Unknown, nil).WithContext(ctx) - w := httptest.NewRecorder() - srv.writeNodeNotFound(w, req, issue199Unknown) - if w.Code != 404 { - t.Fatalf("status=%d, want 404", w.Code) - } - if strings.Contains(buf.String(), "missing-node lookup failed") { - t.Errorf("cancelled request logged as a lookup failure: %s", buf.String()) + // The capture is locked (#310): the server's background goroutines keep + // logging into whatever writer is installed. + out := captureLog(func() { + ctx, cancel := context.WithCancel(context.Background()) + cancel() + req := httptest.NewRequest("GET", "/api/nodes/"+issue199Unknown, nil).WithContext(ctx) + w := httptest.NewRecorder() + srv.writeNodeNotFound(w, req, issue199Unknown) + if w.Code != 404 { + t.Fatalf("status=%d, want 404", w.Code) + } + }) + if strings.Contains(out, "missing-node lookup failed") { + t.Errorf("cancelled request logged as a lookup failure: %s", out) } } diff --git a/cmd/server/log_capture_test.go b/cmd/server/log_capture_test.go new file mode 100644 index 000000000..f8a9f2b38 --- /dev/null +++ b/cmd/server/log_capture_test.go @@ -0,0 +1,95 @@ +package main + +import ( + "io" + "log" + "sync" + "testing" +) + +// Issue #310 (follow-up to #301 / #307): a test that points the standard +// logger at a plain bytes.Buffer and then reads that buffer races with every +// goroutine that is still logging. log.Logger serializes its writers against +// each other under outMu, but nothing orders a write against the harness's +// own read -- and goroutines routinely outlive the test that started them: +// OpenDB's healSchemaFlags, the two background index builds Load() starts, +// runDistanceIndexBuild, (*DB).Close's WAL checkpoint, the recomputers. Such +// a goroutine can land in a *later* test's capture. +// +// logCapture closes the hazard twice over: +// +// 1. the buffer is a syncBuffer (#307), so every write and every read take +// the same mutex. This is the load-bearing fix and the one the guard +// tests kill mutants on; +// 2. stop restores the previous writer *before* reading. log.SetOutput and +// (*Logger).output share the logger's outMu, so the restore orders every +// in-flight write before the read. Defence in depth: with (1) in place no +// test can distinguish it, so no mutant pins it. +type logCapture struct { + buf *syncBuffer + prev io.Writer + flags int + prefix string + once sync.Once +} + +// startLogCapture redirects the standard logger into a locked buffer and +// records the writer, flags and prefix to put back. A caller that wants +// log.SetFlags(0) sets it after this returns; restoreWriter undoes it. +func startLogCapture() *logCapture { + c := &logCapture{ + buf: newSyncBuffer(), + prev: log.Writer(), + flags: log.Flags(), + prefix: log.Prefix(), + } + log.SetOutput(c.buf) + return c +} + +// read returns everything captured so far. Safe to call while the logger +// still points at the capture. +func (c *logCapture) read() string { return c.buf.String() } + +// restoreWriter puts the previous writer, flags and prefix back. Idempotent, +// so it can be deferred and still be followed by stop. +func (c *logCapture) restoreWriter() { + c.once.Do(func() { + log.SetOutput(c.prev) + log.SetFlags(c.flags) + log.SetPrefix(c.prefix) + }) +} + +// stop restores the previous writer and then returns the captured output. +func (c *logCapture) stop() string { + c.restoreWriter() + return c.buf.String() +} + +// captureLog returns what the standard logger printed while fn ran. The +// writer is restored even if fn calls t.Fatal or panics. +func captureLog(fn func()) string { + return captureLogRead(func(func() string) { fn() }) +} + +// captureLogRead is captureLog for a body that has to read the capture while +// the logger is still pointing at it -- polling for a line a background +// goroutine is about to write, say. read is safe to call concurrently with +// any logger write. +func captureLogRead(fn func(read func() string)) string { + c := startLogCapture() + defer c.restoreWriter() + fn(c.read) + return c.stop() +} + +// newLogCapture installs a capture for the rest of the test and returns a +// locked reader. Use it where the assertions have to see the log while the +// capture is still installed; captureLog is the simpler choice otherwise. +func newLogCapture(t testing.TB) func() string { + t.Helper() + c := startLogCapture() + t.Cleanup(c.restoreWriter) + return c.read +} diff --git a/cmd/server/memlimit_test.go b/cmd/server/memlimit_test.go index 881816b55..ce8afc58a 100644 --- a/cmd/server/memlimit_test.go +++ b/cmd/server/memlimit_test.go @@ -1,8 +1,6 @@ package main import ( - "bytes" - "log" "runtime/debug" "strings" "testing" @@ -61,11 +59,11 @@ func TestMemlimitUnderprovisioned(t *testing.T) { effective, cgroup int64 want bool }{ - {512, 1536, true}, // 512*2=1024 < 1536 → underprovisioned - {768, 1536, false}, // 768*2=1536 == 1536 → not under (boundary) + {512, 1536, true}, // 512*2=1024 < 1536 → underprovisioned + {768, 1536, false}, // 768*2=1536 == 1536 → not under (boundary) {1024, 1536, false}, - {0, 1536, false}, // no effective limit → skip - {512, 0, false}, // no cgroup info → skip + {0, 1536, false}, // no effective limit → skip + {512, 0, false}, // no cgroup info → skip } for _, c := range cases { got := memlimitUnderprovisioned(c.effective, c.cgroup) @@ -75,17 +73,6 @@ func TestMemlimitUnderprovisioned(t *testing.T) { } } -// captureLog redirects the default logger to a buffer for the duration of f, -// then restores the previous writer. Returns captured output. -func captureLog(f func()) string { - var buf bytes.Buffer - prev := log.Writer() - log.SetOutput(&buf) - defer log.SetOutput(prev) - f() - return buf.String() -} - // TestWarnIfMemlimitUnderprovisioned_EmitsWarning verifies the warning IS // logged when the injected cgroup reader reports a container limit more than // 2x larger than the effective GOMEMLIMIT. diff --git a/cmd/server/neighbor_graph_geo_test.go b/cmd/server/neighbor_graph_geo_test.go index 3c67408ea..2cb417489 100644 --- a/cmd/server/neighbor_graph_geo_test.go +++ b/cmd/server/neighbor_graph_geo_test.go @@ -1,8 +1,6 @@ package main import ( - "bytes" - "log" "strings" "sync" "sync/atomic" @@ -10,31 +8,24 @@ import ( "time" ) -// captureNeighborGraphRejectLog redirects the global logger to a buffer for -// the life of the test (restored via t.Cleanup, matching this package's -// existing log.SetOutput test convention — see schema_degradation_per_store_test.go) -// and returns a function that extracts just the +// captureNeighborGraphRejectLog redirects the global logger into the shared +// locked capture for the life of the test (restored via t.Cleanup) and +// returns a function that extracts just the // "[neighbor-graph] reject geo-far edge" lines, so incidental log output // from elsewhere in the build doesn't make callers flaky. // -// Safe under concurrent log.Printf callers: the standard logger serializes -// each Output() call (format + single Write) behind its own mutex, so a -// plain bytes.Buffer never sees overlapping writes. +// The capture must be locked (#301, #310): callers read it while the logger +// still points at it. The standard logger serializes each Output() call +// against the other writers, but it does not order a write against this +// read, and goroutines from an earlier test keep logging into whatever +// buffer is installed. A plain bytes.Buffer is therefore a data race, not a +// safe shortcut -- see TestNeighborGraphRejectLogCapture_ReadDuringConcurrentLogging_310. func captureNeighborGraphRejectLog(t *testing.T) func() []string { t.Helper() - var buf bytes.Buffer - prevOut := log.Writer() - prevFlags := log.Flags() - prevPrefix := log.Prefix() - log.SetOutput(&buf) - t.Cleanup(func() { - log.SetOutput(prevOut) - log.SetFlags(prevFlags) - log.SetPrefix(prevPrefix) - }) + read := newLogCapture(t) return func() []string { var lines []string - for _, l := range strings.Split(buf.String(), "\n") { + for _, l := range strings.Split(read(), "\n") { if strings.Contains(l, "[neighbor-graph] reject geo-far edge") { lines = append(lines, l) } diff --git a/cmd/server/nodes_pagination_postfilter_test.go b/cmd/server/nodes_pagination_postfilter_test.go index 7711d42f3..48ce77c25 100644 --- a/cmd/server/nodes_pagination_postfilter_test.go +++ b/cmd/server/nodes_pagination_postfilter_test.go @@ -1,10 +1,8 @@ package main import ( - "bytes" "encoding/json" "fmt" - "log" "net/http/httptest" "strings" "testing" @@ -151,27 +149,26 @@ func TestHandleNodes_PostFilterCompensationLoopLogsOnExhaustion(t *testing.T) { } srv.cfg.SetHiddenNamePrefixes([]string{"🚫"}) - var buf bytes.Buffer - prev := log.Writer() - log.SetOutput(&buf) - defer log.SetOutput(prev) - - req := httptest.NewRequest("GET", "/api/nodes?limit=1&offset=0", nil) - w := httptest.NewRecorder() - router.ServeHTTP(w, req) - if w.Code != 200 { - t.Fatalf("status=%d body=%s", w.Code, w.Body.String()) - } - var resp struct { - Nodes []map[string]interface{} `json:"nodes"` - } - if err := json.Unmarshal(w.Body.Bytes(), &resp); err != nil { - t.Fatalf("decode: %v body=%s", err, w.Body.String()) - } - if len(resp.Nodes) != 0 { - t.Errorf("expected 0 nodes (RealNode is beyond the 50-iteration cap), got %d: %+v", len(resp.Nodes), resp.Nodes) - } - if !strings.Contains(buf.String(), "maxIterations") { - t.Errorf("expected a log breadcrumb mentioning maxIterations when the compensation loop is exhausted, got log output: %q", buf.String()) + // The capture is locked (#310): the store's background goroutines keep + // logging into whatever writer is installed. + out := captureLog(func() { + req := httptest.NewRequest("GET", "/api/nodes?limit=1&offset=0", nil) + w := httptest.NewRecorder() + router.ServeHTTP(w, req) + if w.Code != 200 { + t.Fatalf("status=%d body=%s", w.Code, w.Body.String()) + } + var resp struct { + Nodes []map[string]interface{} `json:"nodes"` + } + if err := json.Unmarshal(w.Body.Bytes(), &resp); err != nil { + t.Fatalf("decode: %v body=%s", err, w.Body.String()) + } + if len(resp.Nodes) != 0 { + t.Errorf("expected 0 nodes (RealNode is beyond the 50-iteration cap), got %d: %+v", len(resp.Nodes), resp.Nodes) + } + }) + if !strings.Contains(out, "maxIterations") { + t.Errorf("expected a log breadcrumb mentioning maxIterations when the compensation loop is exhausted, got log output: %q", out) } } diff --git a/cmd/server/ping_score_history_production_test.go b/cmd/server/ping_score_history_production_test.go index ac0cf9f4b..f416ccacd 100644 --- a/cmd/server/ping_score_history_production_test.go +++ b/cmd/server/ping_score_history_production_test.go @@ -1,7 +1,6 @@ package main import ( - "bytes" "context" "errors" "log" @@ -635,19 +634,12 @@ func TestPingScoreHistoryRealPublisher_StoresIntoServerPingScoresCache(t *testin // et al.) and structurally by pingScoreHistorySetStatus's own signature, // which has no error parameter to leak through in the first place. func TestPingScoreHistoryRealReportError_LogsWithStablePrefix(t *testing.T) { - var buf bytes.Buffer - orig := log.Writer() - origFlags := log.Flags() - log.SetOutput(&buf) - log.SetFlags(0) - defer func() { - log.SetOutput(orig) - log.SetFlags(origFlags) - }() - - pingScoreHistoryRealReportError("cycle_failed", errors.New("secret detail: /var/lib/corescope/meshcore.db")) - - got := buf.String() + // The capture is locked (#310): goroutines from earlier tests keep + // logging into whatever writer is installed. + got := captureLog(func() { + log.SetFlags(0) + pingScoreHistoryRealReportError("cycle_failed", errors.New("secret detail: /var/lib/corescope/meshcore.db")) + }) if !strings.Contains(got, "[ping-scores-history] cycle_failed:") { t.Errorf("log output = %q, want the stable [ping-scores-history] : prefix", got) } diff --git a/cmd/server/schema_degradation_per_store_test.go b/cmd/server/schema_degradation_per_store_test.go index f8f67eab8..98af788a4 100644 --- a/cmd/server/schema_degradation_per_store_test.go +++ b/cmd/server/schema_degradation_per_store_test.go @@ -1,7 +1,6 @@ package main import ( - "bytes" "log" "strings" "testing" @@ -17,27 +16,22 @@ import ( // package-level sentinel. GREEN follow-up moves the sentinel to a // PacketStore field so each instance has a fresh dedupe set. func TestSchemaDegradationLogIsPerStore(t *testing.T) { - var buf bytes.Buffer - prev := log.Writer() - prevFlags := log.Flags() - log.SetOutput(&buf) - log.SetFlags(0) - t.Cleanup(func() { - log.SetOutput(prev) - log.SetFlags(prevFlags) - }) - const msg = "test-schema-degradation-marker-1199" - s1 := &PacketStore{} - s2 := &PacketStore{} - s1.logSchemaDegradationOnce(msg) - s2.logSchemaDegradationOnce(msg) + // The capture is locked (#310): goroutines from earlier tests keep + // logging into whatever writer is installed. + out := captureLog(func() { + log.SetFlags(0) + s1 := &PacketStore{} + s2 := &PacketStore{} + s1.logSchemaDegradationOnce(msg) + s2.logSchemaDegradationOnce(msg) + }) - hits := strings.Count(buf.String(), msg) + hits := strings.Count(out, msg) if hits != 2 { t.Fatalf("expected 2 log emissions (one per PacketStore), got %d. "+ "package-level sentinel pollutes across instances — move to a "+ - "struct field. log buffer:\n%s", hits, buf.String()) + "struct field. log buffer:\n%s", hits, out) } }