fix(leak): don't mutate logger, just make events from it (#69)

* fix: don't race poking logger variable, just make events from it

fixes: #68

* fix: need a concurrent buffer to run the current logging test

* fix: correct a data race

logger.go

@@ -76,8 +76,9 @@ func SetLogger(opts ...Option) gin.HandlerFunc {
 		Timestamp().
 		Logger()
 	return func(c *gin.Context) {
+		rl := l
 		if cfg.logger != nil {
-			l = cfg.logger(c, l)
+			rl = cfg.logger(c, l)
 		}
 
 		start := time.Now()
@@ -112,43 +113,33 @@ func SetLogger(opts ...Option) gin.HandlerFunc {
 			}
 			latency := end.Sub(start)
 
-			l = l.With().
-				Int("status", c.Writer.Status()).
-				Str("method", c.Request.Method).
-				Str("path", path).
-				Str("ip", c.ClientIP()).
-				Dur("latency", latency).
-				Str("user_agent", c.Request.UserAgent()).
-				Int("body_size", c.Writer.Size()).
-				Logger()
-
 			msg := "Request"
 			if len(c.Errors) > 0 {
 				msg = c.Errors.String()
 			}
 
+			var evt *zerolog.Event
 			level, hasLevel := cfg.pathLevels[path]
 
 			switch {
 			case c.Writer.Status() >= http.StatusBadRequest && c.Writer.Status() < http.StatusInternalServerError:
-				{
-					l.WithLevel(cfg.clientErrorLevel).
-						Msg(msg)
-				}
+				evt = rl.WithLevel(cfg.clientErrorLevel)
 			case c.Writer.Status() >= http.StatusInternalServerError:
-				{
-					l.WithLevel(cfg.serverErrorLevel).
-						Msg(msg)
-				}
+				evt = rl.WithLevel(cfg.serverErrorLevel)
 			case hasLevel:
-				{
-					l.WithLevel(level).
-						Msg(msg)
-				}
+				evt = rl.WithLevel(level)
 			default:
-				l.WithLevel(cfg.defaultLevel).
-					Msg(msg)
+				evt = rl.WithLevel(cfg.defaultLevel)
 			}
+			evt.
+				Int("status", c.Writer.Status()).
+				Str("method", c.Request.Method).
+				Str("path", path).
+				Str("ip", c.ClientIP()).
+				Dur("latency", latency).
+				Str("user_agent", c.Request.UserAgent()).
+				Int("body_size", c.Writer.Size()).
+				Msg(msg)
 		}
 	}
 }

logger_test.go

@@ -3,9 +3,12 @@ package logger
 import (
 	"bytes"
 	"context"
+	"fmt"
 	"net/http"
 	"net/http/httptest"
 	"regexp"
+	"strings"
+	"sync"
 	"testing"
 
 	"github.com/gin-gonic/gin"
@@ -151,6 +154,52 @@ func TestLoggerWithLevels(t *testing.T) {
 	assert.Contains(t, buffer.String(), "FTL")
 }
 
+type concurrentBuffer struct {
+	mu sync.Mutex
+	b  bytes.Buffer
+}
+
+func (b *concurrentBuffer) Write(p []byte) (n int, err error) {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	return b.b.Write(p)
+}
+
+func TestCustomLoggerIssue68(t *testing.T) {
+	buffer := new(concurrentBuffer)
+	gin.SetMode(gin.ReleaseMode)
+	r := gin.New()
+	l := zerolog.New(buffer)
+	r.Use(SetLogger(
+		WithLogger(func(*gin.Context, zerolog.Logger) zerolog.Logger { return l }),
+		WithDefaultLevel(zerolog.DebugLevel),
+		WithClientErrorLevel(zerolog.ErrorLevel),
+		WithServerErrorLevel(zerolog.FatalLevel),
+	))
+	r.GET("/example", func(c *gin.Context) {})
+
+	// concurrent requests should only have their info logged once
+	var wg sync.WaitGroup
+	for i := 0; i < 10; i++ {
+		wg.Add(1)
+		req := fmt.Sprintf("/example?a=%d", i)
+		go func() {
+			defer wg.Done()
+			performRequest(r, "GET", req)
+		}()
+	}
+	wg.Wait()
+
+	bs := buffer.b.String()
+	for i := 0; i < 10; i++ {
+		// should contain each request log exactly once
+		msg := fmt.Sprintf("/example?a=%d", i)
+		if assert.Contains(t, bs, msg) {
+			assert.Equal(t, strings.Index(bs, msg), strings.LastIndex(bs, msg))
+		}
+	}
+}
+
 func TestLoggerParseLevel(t *testing.T) {
 	type args struct {
 		levelStr string