merge fixcontext

Author: inconshreveable

log15_test.go

@@ -9,6 +9,7 @@ import (
 	"net"
 	"regexp"
 	"runtime"
+	"sync"
 	"testing"
 	"time"
 )
@@ -493,3 +494,44 @@ func TestCallerStackHandler(t *testing.T) {
 		t.Fatalf("Wrong context value, got %s expected string matching %s", s, exp)
 	}
 }
+
+// tests that when logging concurrently to the same logger
+// from multiple goroutines that the calls are handled independently
+// this test tries to trigger a previous bug where concurrent calls could
+// corrupt each other's context values
+//
+// this test runs N concurrent goroutines each logging a fixed number of
+// records and a handler that buckets them based on the index passed in the context.
+// if the logger is not concurrent-safe then the values in the buckets will not all be the same
+//
+// https://github.com/inconshreveable/log15/pull/30
+func TestConcurrent(t *testing.T) {
+	root := New()
+	// this was the first value that triggered
+	// go to allocate extra capacity in the logger's context slice which
+	// was necessary to trigger the bug
+	const ctxLen = 34
+	l := root.New(make([]interface{}, ctxLen)...)
+	const goroutines = 8
+	var res [goroutines]int
+	l.SetHandler(SyncHandler(FuncHandler(func(r *Record) error {
+		res[r.Ctx[ctxLen+1].(int)]++
+		return nil
+	})))
+	var wg sync.WaitGroup
+	wg.Add(goroutines)
+	for i := 0; i < goroutines; i++ {
+		go func(idx int) {
+			defer wg.Done()
+			for j := 0; j < 10000; j++ {
+				l.Info("test message", "goroutine_idx", idx)
+			}
+		}(i)
+	}
+	wg.Wait()
+	for _, val := range res[:] {
+		if val != 10000 {
+			t.Fatalf("Wrong number of messages for context: %+v", res)
+		}
+	}
+}

logger.go

@@ -100,7 +100,7 @@ func (l *logger) write(msg string, lvl Lvl, ctx []interface{}) {
 		Time: time.Now(),
 		Lvl:  lvl,
 		Msg:  msg,
-		Ctx:  append(l.ctx, normalize(ctx)...),
+		Ctx:  newContext(l.ctx, ctx),
 		KeyNames: RecordKeyNames{
 			Time: timeKey,
 			Msg:  msgKey,
@@ -112,11 +112,19 @@ func (l *logger) write(msg string, lvl Lvl, ctx []interface{}) {
 }
 
 func (l *logger) New(ctx ...interface{}) Logger {
-	child := &logger{append(l.ctx, normalize(ctx)...), new(swapHandler)}
+	child := &logger{newContext(l.ctx, ctx), new(swapHandler)}
 	child.SetHandler(l.h)
 	return child
 }
 
+func newContext(prefix []interface{}, suffix []interface{}) []interface{} {
+	normalizedSuffix := normalize(suffix)
+	newCtx := make([]interface{}, len(prefix)+len(normalizedSuffix))
+	n := copy(newCtx, prefix)
+	copy(newCtx[n:], suffix)
+	return newCtx
+}
+
 func (l *logger) Debug(msg string, ctx ...interface{}) {
 	l.write(msg, LvlDebug, ctx)
 }