merge master

.travis.yml

@@ -0,0 +1,9 @@
+language: go
+
+go:
+	- 1.0
+	- 1.1
+	- 1.2
+	- 1.3
+	- release
+	- tip

bench_test.go

@@ -85,3 +85,45 @@ func BenchmarkMultiLevelFilter(b *testing.B) {
 		lg.Info("test message")
 	}
 }
+
+func BenchmarkDescendant1(b *testing.B) {
+	lg := New()
+	lg.SetHandler(DiscardHandler())
+	lg = lg.New()
+	for i := 0; i < b.N; i++ {
+		lg.Info("test message")
+	}
+}
+
+func BenchmarkDescendant2(b *testing.B) {
+	lg := New()
+	lg.SetHandler(DiscardHandler())
+	for i := 0; i < 2; i++ {
+		lg = lg.New()
+	}
+	for i := 0; i < b.N; i++ {
+		lg.Info("test message")
+	}
+}
+
+func BenchmarkDescendant4(b *testing.B) {
+	lg := New()
+	lg.SetHandler(DiscardHandler())
+	for i := 0; i < 4; i++ {
+		lg = lg.New()
+	}
+	for i := 0; i < b.N; i++ {
+		lg.Info("test message")
+	}
+}
+
+func BenchmarkDescendant8(b *testing.B) {
+	lg := New()
+	lg.SetHandler(DiscardHandler())
+	for i := 0; i < 8; i++ {
+		lg = lg.New()
+	}
+	for i := 0; i < b.N; i++ {
+		lg.Info("test message")
+	}
+}

ext/handler.go

@@ -1,8 +1,11 @@
 package ext
 
 import (
-	log "gopkg.in/inconshreveable/log15.v2"
 	"sync"
+	"sync/atomic"
+	"unsafe"
+
+	log "gopkg.in/inconshreveable/log15.v2"
 )
 
 // EscalateErrHandler wraps another handler and passes all records through
@@ -95,23 +98,19 @@ func (h *Speculative) Flush() {
 // used to implement the SetHandler method for the default
 // implementation of Logger.
 func HotSwapHandler(h log.Handler) *HotSwap {
-	return &HotSwap{handler: h}
+	hs := new(HotSwap)
+	hs.Swap(h)
+	return hs
 }
 
 type HotSwap struct {
-	mu      sync.RWMutex
-	handler log.Handler
+	handler unsafe.Pointer
 }
 
 func (h *HotSwap) Log(r *log.Record) error {
-	defer h.mu.RUnlock()
-	h.mu.RLock()
-	err := h.handler.Log(r)
-	return err
+	return (*(*log.Handler)(atomic.LoadPointer(&h.handler))).Log(r)
 }
 
 func (h *HotSwap) Swap(newHandler log.Handler) {
-	h.mu.Lock()
-	defer h.mu.Unlock()
-	h.handler = newHandler
+	atomic.StorePointer(&h.handler, unsafe.Pointer(&newHandler))
 }

handler.go

@@ -8,6 +8,8 @@ import (
 	"os"
 	"reflect"
 	"sync"
+	"sync/atomic"
+	"unsafe"
 
 	"gopkg.in/inconshreveable/log15.v2/stack"
 )
@@ -123,7 +125,7 @@ func CallerStackHandler(format string, h Handler) Handler {
 	return FuncHandler(func(r *Record) error {
 		s := stack.Callers().
 			TrimBelow(stack.Call(r.CallPC[0])).
-			TrimAboveName("main.main")
+			TrimRuntime()
 		if len(s) > 0 {
 			buf := &bytes.Buffer{}
 			buf.WriteByte('[')
@@ -277,24 +279,18 @@ func BufferedHandler(bufSize int, h Handler) Handler {
 	return ChannelHandler(recs)
 }
 
-// swapHandler wraps another handler that may swapped out
+// swapHandler wraps another handler that may be swapped out
 // dynamically at runtime in a thread-safe fashion.
 type swapHandler struct {
-	mu      sync.RWMutex
-	handler Handler
+	handler unsafe.Pointer
 }
 
 func (h *swapHandler) Log(r *Record) error {
-	defer h.mu.RUnlock()
-	h.mu.RLock()
-	err := h.handler.Log(r)
-	return err
+	return (*(*Handler)(atomic.LoadPointer(&h.handler))).Log(r)
 }
 
 func (h *swapHandler) Swap(newHandler Handler) {
-	h.mu.Lock()
-	defer h.mu.Unlock()
-	h.handler = newHandler
+	atomic.StorePointer(&h.handler, unsafe.Pointer(&newHandler))
 }
 
 // LazyHandler writes all values to the wrapped handler after evaluating
@@ -316,7 +312,7 @@ func LazyHandler(h Handler) Handler {
 				} else {
 					if cs, ok := v.(stack.Trace); ok {
 						v = cs.TrimBelow(stack.Call(r.CallPC[0])).
-							TrimAboveName("main.main")
+							TrimRuntime()
 					}
 					r.Ctx[i] = v
 				}

log15_test.go

@@ -9,6 +9,7 @@ import (
 	"net"
 	"regexp"
 	"runtime"
+	"sync"
 	"testing"
 	"time"
 )
@@ -446,3 +447,91 @@ func TestCallerFuncHandler(t *testing.T) {
 		t.Fatalf("Wrong context value, got %s expected string matching %s", s, regex)
 	}
 }
+
+// https://github.com/inconshreveable/log15/issues/27
+func TestCallerStackHandler(t *testing.T) {
+	t.Parallel()
+
+	l := New()
+	h, r := testHandler()
+	l.SetHandler(CallerStackHandler("%#v", h))
+
+	lines := []int{}
+
+	func() {
+		l.Info("baz")
+		_, _, line, _ := runtime.Caller(0)
+		lines = append(lines, line-1)
+	}()
+	_, file, line, _ := runtime.Caller(0)
+	lines = append(lines, line-1)
+
+	if len(r.Ctx) != 2 {
+		t.Fatalf("Expected stack in record context. Got length %d, expected %d", len(r.Ctx), 2)
+	}
+
+	const key = "stack"
+
+	if r.Ctx[0] != key {
+		t.Fatalf("Wrong context key, got %s expected %s", r.Ctx[0], key)
+	}
+
+	s, ok := r.Ctx[1].(string)
+	if !ok {
+		t.Fatalf("Wrong context value type, got %T expected string", r.Ctx[1])
+	}
+
+	exp := "["
+	for i, line := range lines {
+		if i > 0 {
+			exp += " "
+		}
+		exp += fmt.Sprint(file, ":", line)
+	}
+	exp += "]"
+
+	if s != exp {
+		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,7 +112,17 @@ func (l *logger) write(msg string, lvl Lvl, ctx []interface{}) {
 }
 
 func (l *logger) New(ctx ...interface{}) Logger {
-	return &logger{append(l.ctx, normalize(ctx)...), &swapHandler{handler: l.h}}
+	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{}) {

root.go

@@ -3,6 +3,7 @@ package log15
 import (
 	"os"
 
+	"github.com/mattn/go-colorable"
 	"gopkg.in/inconshreveable/log15.v2/term"
 )
 
@@ -14,14 +15,15 @@ var (
 
 func init() {
 	if term.IsTty(os.Stdout.Fd()) {
-		StdoutHandler = StreamHandler(os.Stdout, TerminalFormat())
+		StdoutHandler = StreamHandler(colorable.NewColorableStdout(), TerminalFormat())
 	}
 
 	if term.IsTty(os.Stderr.Fd()) {
-		StderrHandler = StreamHandler(os.Stderr, TerminalFormat())
+		StderrHandler = StreamHandler(colorable.NewColorableStderr(), TerminalFormat())
 	}
 
-	root = &logger{[]interface{}{}, &swapHandler{handler: StdoutHandler}}
+	root = &logger{[]interface{}{}, new(swapHandler)}
+	root.SetHandler(StdoutHandler)
 }
 
 // New returns a new logger with the given context.