diff --git a/log/format.go b/log/format.go index baf8fddac..765b423d7 100644 --- a/log/format.go +++ b/log/format.go @@ -35,8 +35,16 @@ func PrintOrigins(print bool) { } else { atomic.StoreUint32(&locationEnabled, 0) } + if print { + stackEnabled.Store(true) + } } +// stackEnabled is an atomic flag controlling whether the log handler needs +// to store the callsite stack. This is needed in case any handler wants to +// print locations (locationEnabled), use vmodule, or print full stacks (BacktraceAt). +var stackEnabled atomic.Bool + // locationEnabled is an atomic flag controlling whether the terminal formatter // should append the log locations too when printing entries. var locationEnabled uint32 diff --git a/log/handler_glog.go b/log/handler_glog.go index 9b1d4efaf..a71b1981b 100644 --- a/log/handler_glog.go +++ b/log/handler_glog.go @@ -140,6 +140,10 @@ func (h *GlogHandler) Vmodule(ruleset string) error { h.siteCache = make(map[uintptr]Lvl) atomic.StoreUint32(&h.override, uint32(len(filter))) + // Enable location storage (globally) + if len(h.patterns) > 0 { + stackEnabled.Store(true) + } return nil } @@ -173,6 +177,8 @@ func (h *GlogHandler) BacktraceAt(location string) error { h.location = location atomic.StoreUint32(&h.backtrace, uint32(len(location))) + // Enable location storage (globally) + stackEnabled.Store(true) return nil } diff --git a/log/logger.go b/log/logger.go index 276d6969e..2e66d0841 100644 --- a/log/logger.go +++ b/log/logger.go @@ -131,19 +131,22 @@ type logger struct { } func (l *logger) write(msg string, lvl Lvl, ctx []interface{}, skip int) { - l.h.Log(&Record{ + record := &Record{ Time: time.Now(), Lvl: lvl, Msg: msg, Ctx: newContext(l.ctx, ctx), - Call: stack.Caller(skip), KeyNames: RecordKeyNames{ Time: timeKey, Msg: msgKey, Lvl: lvlKey, Ctx: ctxKey, }, - }) + } + if stackEnabled.Load() { + record.Call = stack.Caller(skip) + } + l.h.Log(record) } func (l *logger) New(ctx ...interface{}) Logger { diff --git a/log/logger_test.go b/log/logger_test.go new file mode 100644 index 000000000..2e59b3fdf --- /dev/null +++ b/log/logger_test.go @@ -0,0 +1,67 @@ +package log + +import ( + "bytes" + "os" + "strings" + "testing" +) + +// TestLoggingWithTrace checks that if BackTraceAt is set, then the +// gloghandler is capable of spitting out a stacktrace +func TestLoggingWithTrace(t *testing.T) { + defer stackEnabled.Store(stackEnabled.Load()) + out := new(bytes.Buffer) + logger := New() + { + glog := NewGlogHandler(StreamHandler(out, TerminalFormat(false))) + glog.Verbosity(LvlTrace) + if err := glog.BacktraceAt("logger_test.go:24"); err != nil { + t.Fatal(err) + } + logger.SetHandler(glog) + } + logger.Trace("a message", "foo", "bar") // Will be bumped to INFO + have := out.String() + if !strings.HasPrefix(have, "INFO") { + t.Fatalf("backtraceat should bump level to info: %s", have) + } + // The timestamp is locale-dependent, so we want to trim that off + // "INFO [01-01|00:00:00.000] a messag ..." -> "a messag..." + have = strings.Split(have, "]")[1] + wantPrefix := " a message\n\ngoroutine" + if !strings.HasPrefix(have, wantPrefix) { + t.Errorf("\nhave: %q\nwant: %q\n", have, wantPrefix) + } +} + +// TestLoggingWithVmodule checks that vmodule works. +func TestLoggingWithVmodule(t *testing.T) { + defer stackEnabled.Store(stackEnabled.Load()) + out := new(bytes.Buffer) + logger := New() + { + glog := NewGlogHandler(StreamHandler(out, TerminalFormat(false))) + glog.Verbosity(LvlCrit) + logger.SetHandler(glog) + logger.Warn("This should not be seen", "ignored", "true") + glog.Vmodule("logger_test.go=5") + } + logger.Trace("a message", "foo", "bar") + have := out.String() + // The timestamp is locale-dependent, so we want to trim that off + // "INFO [01-01|00:00:00.000] a messag ..." -> "a messag..." + have = strings.Split(have, "]")[1] + want := " a message foo=bar\n" + if have != want { + t.Errorf("\nhave: %q\nwant: %q\n", have, want) + } +} + +func BenchmarkTraceLogging(b *testing.B) { + Root().SetHandler(LvlFilterHandler(LvlInfo, StreamHandler(os.Stderr, TerminalFormat(true)))) + b.ResetTimer() + for i := 0; i < b.N; i++ { + Trace("a message", "v", i) + } +}