From e8b40de31ad8a36ce20a0cd75da6259033f184a1 Mon Sep 17 00:00:00 2001 From: Manuel Doncel Date: Sun, 20 Sep 2026 23:55:14 +0200 Subject: [PATCH 1/3] fix: race condition if Update on defer --- .golangci.yml | 1 + middleware_test.go | 41 ++++++++++++++++++++++++++++++------- mw/grpc/interceptor_test.go | 15 ++++++-------- mw/http/middleware_test.go | 10 ++++----- 4 files changed, 45 insertions(+), 22 deletions(-) diff --git a/.golangci.yml b/.golangci.yml index 36ce525..a22c7b8 100644 --- a/.golangci.yml +++ b/.golangci.yml @@ -39,6 +39,7 @@ linters: - importas # No need of aliasing imports. - inamedparam # Not important. - ireturn # No need for this linter here. + - noinlineerr # I prefer inline error handling. - promlinter # Related to prometheus. - protogetter # Related to protocol buffer. - rowserrcheck # Related to SQL. diff --git a/middleware_test.go b/middleware_test.go index 04d1aab..d120dbf 100644 --- a/middleware_test.go +++ b/middleware_test.go @@ -18,10 +18,9 @@ func TestHandleWithLogEventLogsAfterHandler(t *testing.T) { h := func(ctx context.Context) { got = append(got, "handler") - err := UpdateLogEvent(ctx, func(le *testLogEvent) { + if err := UpdateLogEvent(ctx, func(le *testLogEvent) { le.value = "updated" - }) - if err != nil { + }); err != nil { t.Fatalf("UpdateLogEvent() error = %v", err) } } @@ -29,7 +28,7 @@ func TestHandleWithLogEventLogsAfterHandler(t *testing.T) { want := []string{"handler", "log:updated", "info:updated"} if !cmp.Equal(got, want) { - t.Fatalf("got = %v, want %v", got, want) + t.Fatalf("events = %v, want %v", got, want) } } @@ -45,10 +44,9 @@ func TestHandleWithLogEventLogsAfterPanic(t *testing.T) { h := func(ctx context.Context) { events = append(events, "handler") - err := UpdateLogEvent(ctx, func(le *testLogEvent) { + if err := UpdateLogEvent(ctx, func(le *testLogEvent) { le.value = "panic-update" - }) - if err != nil { + }); err != nil { t.Fatalf("UpdateLogEvent() error = %v", err) } @@ -69,6 +67,35 @@ func TestHandleWithLogEventLogsAfterPanic(t *testing.T) { HandleWithLogEvent(ctx, le, li, h) } +func TestHandleWithLogEventLogsUpdateOnDefer(t *testing.T) { + t.Parallel() + + got := make([]string, 0) + li := testLogInterface{entries: &got} + le := testLogEvent{events: &got} + + ctx := t.Context() + h := func(ctx context.Context) { + got = append(got, "handler") + + go func() { + if err := UpdateLogEvent(ctx, func(le *testLogEvent) { + le.value = "updated" + }); err != nil { + t.Errorf("UpdateLogEvent() error = %v", err) + + return + } + }() + } + HandleWithLogEvent(ctx, le, li, h) + + want := []string{"handler", "log:updated", "info:updated"} + if !cmp.Equal(got, want) { + t.Fatalf("events = %v, want %v", got, want) + } +} + type testLogInterface struct { entries *[]string } diff --git a/mw/grpc/interceptor_test.go b/mw/grpc/interceptor_test.go index abf79a4..37f7f2d 100644 --- a/mw/grpc/interceptor_test.go +++ b/mw/grpc/interceptor_test.go @@ -40,10 +40,9 @@ func TestUnaryServerInterceptorLogsAfterHandler(t *testing.T) { handler := func(ctx context.Context, req any) (any, error) { got = append(got, "handler") - err := logevent.UpdateLogEvent(ctx, func(e *testLogEvent) { + if err := logevent.UpdateLogEvent(ctx, func(e *testLogEvent) { e.value = "updated" - }) - if err != nil { + }); err != nil { t.Fatalf("UpdateLogEvent() error = %v", err) } @@ -79,10 +78,9 @@ func TestUnaryServerInterceptorLogsAfterHandlerError(t *testing.T) { handler := func(ctx context.Context, req any) (any, error) { events = append(events, "handler") - err := logevent.UpdateLogEvent(ctx, func(e *testLogEvent) { + if err := logevent.UpdateLogEvent(ctx, func(e *testLogEvent) { e.value = "error-update" - }) - if err != nil { + }); err != nil { t.Fatalf("UpdateLogEvent() error = %v", err) } @@ -126,10 +124,9 @@ func TestUnaryServerInterceptorEachRequestGetsFreshInstance(t *testing.T) { interceptor := UnaryServerInterceptor(testLogEvent{events: &entries}, li) handler := func(ctx context.Context, req any) (any, error) { - err := logevent.UpdateLogEvent(ctx, func(e *testLogEvent) { + if err := logevent.UpdateLogEvent(ctx, func(e *testLogEvent) { pointers = append(pointers, fmt.Sprintf("%p", e)) - }) - if err != nil { + }); err != nil { t.Fatalf("UpdateLogEvent() error = %v", err) } diff --git a/mw/http/middleware_test.go b/mw/http/middleware_test.go index b6a0abd..6c3d37a 100644 --- a/mw/http/middleware_test.go +++ b/mw/http/middleware_test.go @@ -23,10 +23,9 @@ func TestAddLogEventMiddlewareLogsAfterHandler(t *testing.T) { handler := middleware(nethttp.HandlerFunc(func(w nethttp.ResponseWriter, r *nethttp.Request) { got = append(got, "handler") - err := logevent.UpdateLogEvent(r.Context(), func(le *testLogEvent) { + if err := logevent.UpdateLogEvent(r.Context(), func(le *testLogEvent) { le.value = "updated" - }) - if err != nil { + }); err != nil { t.Fatalf("UpdateLogEvent() error = %v", err) } @@ -58,10 +57,9 @@ func TestAddLogEventMiddlewareLogsAfterPanic(t *testing.T) { handler := middleware(nethttp.HandlerFunc(func(_ nethttp.ResponseWriter, r *nethttp.Request) { events = append(events, "handler") - err := logevent.UpdateLogEvent(r.Context(), func(le *testLogEvent) { + if err := logevent.UpdateLogEvent(r.Context(), func(le *testLogEvent) { le.value = "panic-update" - }) - if err != nil { + }); err != nil { t.Fatalf("UpdateLogEvent() error = %v", err) } From fcc4f7231a2c2c4957367643754394379d9906f2 Mon Sep 17 00:00:00 2001 From: Manuel Doncel Date: Mon, 21 Sep 2026 00:05:10 +0200 Subject: [PATCH 2/3] fix: race condition if Update on defer --- errors.go | 11 ++++++++--- middleware_test.go | 22 ++++++++++++---------- models.go | 15 ++++++++++++--- 3 files changed, 32 insertions(+), 16 deletions(-) diff --git a/errors.go b/errors.go index 8de9ffb..2b31295 100644 --- a/errors.go +++ b/errors.go @@ -8,9 +8,14 @@ import ( var _ error = new(DifferentLogEventTypeError) -// ErrLogEventNotInitialized error returned when adding context to a log event -// but the log event was not initialized. -var ErrLogEventNotInitialized = errors.New("LogEvent not initialized") +var ( + // ErrLogEventNotInitialized error returned when adding context to a log event. + // but the log event was not initialized. + ErrLogEventNotInitialized = errors.New("LogEvent not initialized") + + // ErrUpdatingLoggedEvent error returned when trying to update a log event that has already been logged. + ErrUpdatingLoggedEvent = errors.New("LogEvent already logged") +) type ( // DifferentLogEventTypeError is returned when the log event type is different from the previous one. diff --git a/middleware_test.go b/middleware_test.go index d120dbf..5588ab9 100644 --- a/middleware_test.go +++ b/middleware_test.go @@ -2,6 +2,8 @@ package logevent import ( "context" + "errors" + "sync" "testing" "github.com/google/go-cmp/cmp" @@ -75,25 +77,25 @@ func TestHandleWithLogEventLogsUpdateOnDefer(t *testing.T) { le := testLogEvent{events: &got} ctx := t.Context() + wg := sync.WaitGroup{} + wg.Add(1) + h := func(ctx context.Context) { got = append(got, "handler") go func() { - if err := UpdateLogEvent(ctx, func(le *testLogEvent) { - le.value = "updated" - }); err != nil { - t.Errorf("UpdateLogEvent() error = %v", err) + defer wg.Done() - return + err := UpdateLogEvent(ctx, func(le *testLogEvent) { + le.value = "updated" + }) + if !errors.Is(err, ErrUpdatingLoggedEvent) { + t.Errorf("UpdateLogEvent() error = %v, want %v", err, ErrUpdatingLoggedEvent) } }() } HandleWithLogEvent(ctx, le, li, h) - - want := []string{"handler", "log:updated", "info:updated"} - if !cmp.Equal(got, want) { - t.Fatalf("events = %v, want %v", got, want) - } + wg.Wait() } type testLogInterface struct { diff --git a/models.go b/models.go index 1d2ecee..cee01a1 100644 --- a/models.go +++ b/models.go @@ -26,9 +26,10 @@ type ( // It ensures the Log method is called only once (via [sync.Once]) and protects // concurrent updates to the underlying log event with a mutex. wrapperLogEvent[L Logger, T any, PT PtrLogEvent[L, T]] struct { - once sync.Once - mu sync.Mutex - le PT + once sync.Once + mu sync.Mutex + logged bool + le PT } ) @@ -37,6 +38,10 @@ func (w *wrapperLogEvent[L, T, PT]) Update(f func(t PT)) error { w.mu.Lock() defer w.mu.Unlock() + if w.logged { + return ErrUpdatingLoggedEvent + } + f(w.le) return nil @@ -44,6 +49,10 @@ func (w *wrapperLogEvent[L, T, PT]) Update(f func(t PT)) error { // Log call the inner logevent.LogEvent to log. func (w *wrapperLogEvent[L, T, PT]) Log(ctx context.Context, li L) { + w.mu.Lock() + defer w.mu.Unlock() + + w.logged = true w.once.Do(func() { w.le.Log(ctx, li) }) From d15a03bef176e8eca2e7cfd470a198d62572ad5c Mon Sep 17 00:00:00 2001 From: Manuel Doncel Date: Mon, 21 Sep 2026 00:38:39 +0200 Subject: [PATCH 3/3] fix: race condition if Update on defer --- middleware_test.go | 28 ++++++++++++++++++++++++++++ models.go | 9 +++++---- 2 files changed, 33 insertions(+), 4 deletions(-) diff --git a/middleware_test.go b/middleware_test.go index 5588ab9..2303b41 100644 --- a/middleware_test.go +++ b/middleware_test.go @@ -98,6 +98,34 @@ func TestHandleWithLogEventLogsUpdateOnDefer(t *testing.T) { wg.Wait() } +func TestHandleWithLogEventLogsOnlyOnce(t *testing.T) { + t.Parallel() + + got := make([]string, 0) + li := testLogInterface{entries: &got} + le := testLogEvent{events: &got} + + ctx := t.Context() + _, deferFunc := AddLogEventToContext[testLogInterface, testLogEvent, *testLogEvent](ctx, le) + + const numCalls = 10 + + wg := sync.WaitGroup{} + wg.Add(numCalls) + + for range numCalls { + deferFunc(li) + wg.Done() + } + + wg.Wait() + + want := []string{"log:", "info:"} + if !cmp.Equal(got, want) { + t.Fatalf("events = %v, want %v (Log should have been called exactly once)", got, want) + } +} + type testLogInterface struct { entries *[]string } diff --git a/models.go b/models.go index cee01a1..e61fcb6 100644 --- a/models.go +++ b/models.go @@ -26,7 +26,6 @@ type ( // It ensures the Log method is called only once (via [sync.Once]) and protects // concurrent updates to the underlying log event with a mutex. wrapperLogEvent[L Logger, T any, PT PtrLogEvent[L, T]] struct { - once sync.Once mu sync.Mutex logged bool le PT @@ -52,8 +51,10 @@ func (w *wrapperLogEvent[L, T, PT]) Log(ctx context.Context, li L) { w.mu.Lock() defer w.mu.Unlock() + if w.logged { + return + } + + w.le.Log(ctx, li) w.logged = true - w.once.Do(func() { - w.le.Log(ctx, li) - }) }