diff --git a/.travis.yml b/.travis.yml new file mode 100644 index 0000000..a66c49b --- /dev/null +++ b/.travis.yml @@ -0,0 +1,9 @@ +language: go + +go: + - 1.0 + - 1.1 + - 1.2 + - 1.3 + - release + - tip diff --git a/bench_test.go b/bench_test.go index fc41095..e692e61 100644 --- a/bench_test.go +++ b/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") + } +} diff --git a/ext/handler.go b/ext/handler.go index b9149dd..01feb52 100644 --- a/ext/handler.go +++ b/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)) } diff --git a/handler.go b/handler.go index 0085038..906db43 100644 --- a/handler.go +++ b/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 } diff --git a/log15_test.go b/log15_test.go index 4c3b305..156d83c 100644 --- a/log15_test.go +++ b/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) + } + } +} diff --git a/logger.go b/logger.go index 9543a7f..00d9942 100644 --- a/logger.go +++ b/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{}) { diff --git a/root.go b/root.go index 9fb6a34..f07616a 100644 --- a/root.go +++ b/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. diff --git a/stack/stack.go b/stack/stack.go index d28eb51..ae3021c 100644 --- a/stack/stack.go +++ b/stack/stack.go @@ -4,9 +4,9 @@ package stack import ( "fmt" + "path/filepath" "runtime" "strings" - "sync" ) // Call records a single function invocation from a goroutine stack. It is a @@ -112,6 +112,20 @@ func (pc Call) Format(s fmt.State, c rune) { } } +// Callers returns a Trace for the current goroutine with element 0 +// identifying the calling function. +func Callers() Trace { + pcs := poolBuf() + pcs = pcs[:cap(pcs)] + n := runtime.Callers(2, pcs) + cs := make([]Call, n) + for i, pc := range pcs[:n] { + cs[i] = Call(pc) + } + putPoolBuf(pcs) + return cs +} + // name returns the import path qualified name of the function containing the // call. func (pc Call) name() string { @@ -123,6 +137,16 @@ func (pc Call) name() string { return fn.Name() } +func (pc Call) file() string { + pcFix := uintptr(pc) - 1 // work around for go issue #7690 + fn := runtime.FuncForPC(pcFix) + if fn == nil { + return "???" + } + file, _ := fn.FileLine(pcFix) + return file +} + // Trace records a sequence of function invocations from a goroutine stack. type Trace []Call @@ -140,24 +164,6 @@ func (pcs Trace) Format(s fmt.State, c rune) { s.Write([]byte("]")) } -var pcStackPool = sync.Pool{ - New: func() interface{} { return make([]uintptr, 1000) }, -} - -// Callers returns a Trace for the current goroutine with element 0 -// identifying the calling function. -func Callers() Trace { - pcs := pcStackPool.Get().([]uintptr) - pcs = pcs[:cap(pcs)] - n := runtime.Callers(2, pcs) - cs := make([]Call, n) - for i, pc := range pcs[:n] { - cs[i] = Call(pc) - } - pcStackPool.Put(pcs) - return cs -} - // TrimBelow returns a slice of the Trace with all entries below pc removed. func (pcs Trace) TrimBelow(pc Call) Trace { for len(pcs) > 0 && pcs[0] != pc { @@ -191,3 +197,29 @@ func (pcs Trace) TrimAboveName(name string) Trace { } return pcs } + +var goroot string + +func init() { + goroot = filepath.ToSlash(runtime.GOROOT()) + if runtime.GOOS == "windows" { + goroot = strings.ToLower(goroot) + } +} + +func inGoroot(path string) bool { + if runtime.GOOS == "windows" { + path = strings.ToLower(path) + } + return strings.HasPrefix(path, goroot) +} + +// TrimRuntime returns a slice of the Trace with the topmost entries from the +// go runtime removed. It considers any calls originating from files under +// GOROOT as part of the runtime. +func (pcs Trace) TrimRuntime() Trace { + for len(pcs) > 0 && inGoroot(pcs[len(pcs)-1].file()) { + pcs = pcs[:len(pcs)-1] + } + return pcs +} diff --git a/stack/stack_pool.go b/stack/stack_pool.go new file mode 100644 index 0000000..34f2ca9 --- /dev/null +++ b/stack/stack_pool.go @@ -0,0 +1,19 @@ +// +build go1.3 + +package stack + +import ( + "sync" +) + +var pcStackPool = sync.Pool{ + New: func() interface{} { return make([]uintptr, 1000) }, +} + +func poolBuf() []uintptr { + return pcStackPool.Get().([]uintptr) +} + +func putPoolBuf(p []uintptr) { + pcStackPool.Put(p) +} diff --git a/stack/stack_pool_chan.go b/stack/stack_pool_chan.go new file mode 100644 index 0000000..aa449ed --- /dev/null +++ b/stack/stack_pool_chan.go @@ -0,0 +1,27 @@ +// +build !go1.3 + +package stack + +const ( + stackPoolSize = 64 +) + +var ( + pcStackPool = make(chan []uintptr, stackPoolSize) +) + +func poolBuf() []uintptr { + select { + case p := <-pcStackPool: + return p + default: + return make([]uintptr, 1000) + } +} + +func putPoolBuf(p []uintptr) { + select { + case pcStackPool <- p: + default: + } +}