fix: race condition if Update on defer

.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.

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.

middleware_test.go

@@ -2,6 +2,8 @@ package logevent
 
 import (
 	"context"
+	"errors"
+	"sync"
 	"testing"
 
 	"github.com/google/go-cmp/cmp"
@@ -18,18 +20,17 @@ 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)
 		}
 	}
 	HandleWithLogEvent(ctx, le, li, h)
 
 	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 +46,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 +69,63 @@ 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()
+	wg := sync.WaitGroup{}
+	wg.Add(1)
+
+	h := func(ctx context.Context) {
+		got = append(got, "handler")
+
+		go func() {
+			defer wg.Done()
+
+			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)
+	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
 }

models.go

@@ -26,9 +26,9 @@ 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
+		mu     sync.Mutex
+		logged bool
+		le     PT
 	}
 )
 
@@ -37,14 +37,24 @@ 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
 }
 
 // Log call the inner logevent.LogEvent to log.
 func (w *wrapperLogEvent[L, T, PT]) Log(ctx context.Context, li L) {
-	w.once.Do(func() {
-		w.le.Log(ctx, li)
-	})
+	w.mu.Lock()
+	defer w.mu.Unlock()
+
+	if w.logged {
+		return
+	}
+
+	w.le.Log(ctx, li)
+	w.logged = true
 }

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)
 		}
 

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)
 		}