From 7357eae7cf97042fd267b6de47db9e621ea72a65 Mon Sep 17 00:00:00 2001 From: Rogee Date: Sat, 10 Oct 2026 11:42:26 +0800 Subject: [PATCH] test: synchronize log capture with asynchronous HTTP logging --- internal/logging/logging_test.go | 63 +++++++++++++++++++++++++++++++- 1 file changed, 61 insertions(+), 2 deletions(-) diff --git a/internal/logging/logging_test.go b/internal/logging/logging_test.go index d4d2a91..ac2e148 100644 --- a/internal/logging/logging_test.go +++ b/internal/logging/logging_test.go @@ -7,18 +7,77 @@ import ( "log" "log/slog" "strings" + "sync" "testing" ) -func installTestLogger(t *testing.T, debug bool) *bytes.Buffer { +// HTTP transports can finish logging request bodies asynchronously. Every +// writer and snapshot reader must synchronize on the same capture lock. +// Bytes returns a copy so callers cannot mutate the buffer after unlocking. +type testLogCapture struct { + mu sync.Mutex + buffer bytes.Buffer +} + +func (b *testLogCapture) Write(p []byte) (int, error) { + b.mu.Lock() + defer b.mu.Unlock() + return b.buffer.Write(p) +} + +func (b *testLogCapture) String() string { + b.mu.Lock() + defer b.mu.Unlock() + return b.buffer.String() +} + +func (b *testLogCapture) Bytes() []byte { + b.mu.Lock() + defer b.mu.Unlock() + return bytes.Clone(b.buffer.Bytes()) +} + +func installTestLogger(t *testing.T, debug bool) *testLogCapture { t.Helper() previous := slog.Default() - out := new(bytes.Buffer) + out := new(testLogCapture) Configure("dispatcher", debug, out) t.Cleanup(func() { slog.SetDefault(previous) }) return out } +func TestLogCaptureConcurrentSnapshots(t *testing.T) { + out := installTestLogger(t, false) + started := make(chan struct{}) + done := make(chan error, 1) + go func() { + close(started) + for i := 0; i < 1000; i++ { + if _, err := out.Write([]byte("record\n")); err != nil { + done <- err + return + } + } + done <- nil + }() + <-started + for i := 0; i < 1000; i++ { + _ = out.String() + _ = out.Bytes() + } + if err := <-done; err != nil { + t.Fatal(err) + } + if count := strings.Count(out.String(), "record\n"); count != 1000 { + t.Fatalf("captured %d records, want 1000", count) + } + copyOfCapture := out.Bytes() + copyOfCapture[0] = 'X' + if strings.HasPrefix(out.String(), "X") { + t.Fatal("snapshot exposes the live capture buffer") + } +} + func TestLogrusModesIncludeWorkflowButOnlyDebugIncludesBody(t *testing.T) { for _, debug := range []bool{false, true} { t.Run(map[bool]string{false: "normal", true: "debug"}[debug], func(t *testing.T) {