diff --git a/addsvc/main.go b/addsvc/main.go index 600fb6358..18777169f 100644 --- a/addsvc/main.go +++ b/addsvc/main.go @@ -62,7 +62,7 @@ func main() { // `package log` domain var logger kitlog.Logger logger = kitlog.NewLogfmtLogger(os.Stderr) - logger = kitlog.With(logger, "ts", kitlog.DefaultTimestampUTC) + logger = kitlog.NewContext(logger).With("ts", kitlog.DefaultTimestampUTC) stdlog.SetOutput(kitlog.NewStdlibAdapter(logger)) // redirect stdlib logging to us stdlog.SetFlags(0) // flags are handled in our logger diff --git a/log/benchmark_test.go b/log/benchmark_test.go index 3e4e78fc7..d3695b834 100644 --- a/log/benchmark_test.go +++ b/log/benchmark_test.go @@ -7,15 +7,15 @@ import ( ) func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) { - logger = log.With(logger, "common_key", "common_value") + lc := log.NewContext(logger).With("common_key", "common_value") b.ReportAllocs() b.ResetTimer() for i := 0; i < b.N; i++ { - f(logger) + f(lc) } } var ( baseMessage = func(logger log.Logger) { logger.Log("foo_key", "foo_value") } - withMessage = func(logger log.Logger) { log.With(logger, "a", "b").Log("c", "d") } + withMessage = func(logger log.Logger) { log.NewContext(logger).With("a", "b").Log("c", "d") } ) diff --git a/log/example_test.go b/log/example_test.go new file mode 100644 index 000000000..174161548 --- /dev/null +++ b/log/example_test.go @@ -0,0 +1,23 @@ +package log_test + +import ( + "os" + + "github.com/go-kit/kit/log" +) + +func ExampleContext() { + logger := log.NewLogfmtLogger(os.Stdout) + logger.Log("foo", 123) + ctx := log.NewContext(logger).With("level", "info") + ctx.Log() + ctx = ctx.With("msg", "hello") + ctx.Log() + ctx.With("a", 1).Log("b", 2) + + // Output: + // foo=123 + // level=info + // level=info msg=hello + // level=info msg=hello a=1 b=2 +} diff --git a/log/levels.go b/log/levels.go deleted file mode 100644 index 4c7079bb0..000000000 --- a/log/levels.go +++ /dev/null @@ -1,60 +0,0 @@ -package log - -// Levels provides a default set of leveled loggers. -type Levels struct { - Debug Logger - Info Logger - Error Logger -} - -type levelOptions struct { - levelKey string - debugValue string - infoValue string - errorValue string -} - -// LevelOption sets a parameter for leveled loggers. -type LevelOption func(*levelOptions) - -// LevelKey sets the key for the field used to indicate log level. By default, -// the key is "level". -func LevelKey(key string) LevelOption { - return func(o *levelOptions) { o.levelKey = key } -} - -// DebugLevelValue sets the value for the field used to indicate the debug log -// level. By default, the value is "DEBUG". -func DebugLevelValue(value string) LevelOption { - return func(o *levelOptions) { o.debugValue = value } -} - -// InfoLevelValue sets the value for the field used to indicate the debug log -// level. By default, the value is "INFO". -func InfoLevelValue(value string) LevelOption { - return func(o *levelOptions) { o.infoValue = value } -} - -// ErrorLevelValue sets the value for the field used to indicate the debug log -// level. By default, the value is "ERROR". -func ErrorLevelValue(value string) LevelOption { - return func(o *levelOptions) { o.errorValue = value } -} - -// NewLevels returns a new set of leveled loggers based on the base logger. -func NewLevels(base Logger, options ...LevelOption) Levels { - opts := &levelOptions{ - levelKey: "level", - debugValue: "DEBUG", - infoValue: "INFO", - errorValue: "ERROR", - } - for _, option := range options { - option(opts) - } - return Levels{ - Debug: With(base, opts.levelKey, opts.debugValue), - Info: With(base, opts.levelKey, opts.infoValue), - Error: With(base, opts.levelKey, opts.errorValue), - } -} diff --git a/log/levels/levels.go b/log/levels/levels.go new file mode 100644 index 000000000..92522a4f5 --- /dev/null +++ b/log/levels/levels.go @@ -0,0 +1,127 @@ +package levels + +import "github.com/go-kit/kit/log" + +// Levels provides a leveled logging wrapper around a logger. It has five +// levels: debug, info, warning (warn), error, and critical (crit). If you +// want a different set of levels, you can create your own levels type very +// easily, and you can elide the configuration. +type Levels struct { + ctx log.Context + levelKey string + + // We have a choice between storing level values in string fields or + // making a separate context for each level. When using string fields the + // Log method must combine the base context, the level data, and the + // logged keyvals; but the With method only requires updating one context. + // If we instead keep a separate context for each level the Log method + // must only append the new keyvals; but the With method would have to + // update all five contexts. + + // Roughly speaking, storing multiple contexts breaks even if the ratio of + // Log/With calls is more than the number of levels. We have chosen to + // make the With method cheap and the Log method a bit more costly because + // we do not expect most applications to Log more than five times for each + // call to With. + + debugValue string + infoValue string + warnValue string + errorValue string + critValue string +} + +// New creates a new leveled logger, wrapping the passed logger. +func New(logger log.Logger, options ...Option) Levels { + l := Levels{ + ctx: log.NewContext(logger), + levelKey: "level", + + debugValue: "debug", + infoValue: "info", + warnValue: "warn", + errorValue: "error", + critValue: "crit", + } + for _, option := range options { + option(&l) + } + return l +} + +// With returns a new leveled logger that includes keyvals in all log events. +func (l Levels) With(keyvals ...interface{}) Levels { + return Levels{ + ctx: l.ctx.With(keyvals...), + levelKey: l.levelKey, + debugValue: l.debugValue, + infoValue: l.infoValue, + warnValue: l.warnValue, + errorValue: l.errorValue, + critValue: l.critValue, + } +} + +// Debug logs a debug event along with keyvals. +func (l Levels) Debug(keyvals ...interface{}) error { + return l.ctx.WithPrefix(l.levelKey, l.debugValue).Log(keyvals...) +} + +// Info logs an info event along with keyvals. +func (l Levels) Info(keyvals ...interface{}) error { + return l.ctx.WithPrefix(l.levelKey, l.infoValue).Log(keyvals...) +} + +// Warn logs a warn event along with keyvals. +func (l Levels) Warn(keyvals ...interface{}) error { + return l.ctx.WithPrefix(l.levelKey, l.warnValue).Log(keyvals...) +} + +// Error logs an error event along with keyvals. +func (l Levels) Error(keyvals ...interface{}) error { + return l.ctx.WithPrefix(l.levelKey, l.errorValue).Log(keyvals...) +} + +// Crit logs a crit event along with keyvals. +func (l Levels) Crit(keyvals ...interface{}) error { + return l.ctx.WithPrefix(l.levelKey, l.critValue).Log(keyvals...) +} + +// Option sets a parameter for leveled loggers. +type Option func(*Levels) + +// Key sets the key for the field used to indicate log level. By default, +// the key is "level". +func Key(key string) Option { + return func(l *Levels) { l.levelKey = key } +} + +// DebugValue sets the value for the field used to indicate the debug log +// level. By default, the value is "debug". +func DebugValue(value string) Option { + return func(l *Levels) { l.debugValue = value } +} + +// InfoValue sets the value for the field used to indicate the info log level. +// By default, the value is "info". +func InfoValue(value string) Option { + return func(l *Levels) { l.infoValue = value } +} + +// WarnValue sets the value for the field used to indicate the warning log +// level. By default, the value is "warn". +func WarnValue(value string) Option { + return func(l *Levels) { l.warnValue = value } +} + +// ErrorValue sets the value for the field used to indicate the error log +// level. By default, the value is "error". +func ErrorValue(value string) Option { + return func(l *Levels) { l.errorValue = value } +} + +// CritValue sets the value for the field used to indicate the critical log +// level. By default, the value is "crit". +func CritValue(value string) Option { + return func(l *Levels) { l.critValue = value } +} diff --git a/log/levels/levels_test.go b/log/levels/levels_test.go new file mode 100644 index 000000000..1f4bb4697 --- /dev/null +++ b/log/levels/levels_test.go @@ -0,0 +1,55 @@ +package levels_test + +import ( + "bytes" + "os" + "testing" + + "github.com/go-kit/kit/log" + "github.com/go-kit/kit/log/levels" +) + +func TestDefaultLevels(t *testing.T) { + buf := bytes.Buffer{} + logger := levels.New(log.NewLogfmtLogger(&buf)) + + logger.Debug("msg", "résumé") // of course you'd want to do this + if want, have := "level=debug msg=résumé\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + logger.Info("msg", "Åhus") + if want, have := "level=info msg=Åhus\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + logger.Error("msg", "© violation") + if want, have := "level=error msg=\"© violation\"\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } +} + +func TestModifiedLevels(t *testing.T) { + buf := bytes.Buffer{} + logger := levels.New( + log.NewJSONLogger(&buf), + levels.Key("l"), + levels.DebugValue("dbg"), + ) + logger.With("easter_island", "176°").Debug("msg", "moai") + if want, have := `{"easter_island":"176°","l":"dbg","msg":"moai"}`+"\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } +} + +func ExampleLevels() { + logger := levels.New(log.NewLogfmtLogger(os.Stdout)) + logger.Debug("msg", "hello") + logger.With("context", "foo").Warn("err", "error") + + // Output: + // level=debug msg=hello + // level=warn context=foo err=error +} diff --git a/log/levels_test.go b/log/levels_test.go deleted file mode 100644 index 95333103a..000000000 --- a/log/levels_test.go +++ /dev/null @@ -1,45 +0,0 @@ -package log_test - -import ( - "bytes" - "testing" - - "github.com/go-kit/kit/log" -) - -func TestDefaultLevels(t *testing.T) { - buf := bytes.Buffer{} - levels := log.NewLevels(log.NewLogfmtLogger(&buf)) - - levels.Debug.Log("msg", "👨") // of course you'd want to do this - if want, have := "level=DEBUG msg=👨\n", buf.String(); want != have { - t.Errorf("want %#v, have %#v", want, have) - } - - buf.Reset() - levels.Info.Log("msg", "🚀") - if want, have := "level=INFO msg=🚀\n", buf.String(); want != have { - t.Errorf("want %#v, have %#v", want, have) - } - - buf.Reset() - levels.Error.Log("msg", "🍵") - if want, have := "level=ERROR msg=🍵\n", buf.String(); want != have { - t.Errorf("want %#v, have %#v", want, have) - } -} - -func TestModifiedLevels(t *testing.T) { - buf := bytes.Buffer{} - levels := log.NewLevels( - log.NewJSONLogger(&buf), - log.LevelKey("l"), - log.DebugLevelValue("⛄"), - log.InfoLevelValue("🌜"), - log.ErrorLevelValue("🌊"), - ) - log.With(levels.Debug, "easter_island", "🗿").Log("msg", "💃💃💃") - if want, have := `{"easter_island":"🗿","l":"⛄","msg":"💃💃💃"}`+"\n", buf.String(); want != have { - t.Errorf("want %#v, have %#v", want, have) - } -} diff --git a/log/log.go b/log/log.go index f907713bb..fe7fa5adf 100644 --- a/log/log.go +++ b/log/log.go @@ -6,51 +6,96 @@ package log import "sync/atomic" -// Logger is the fundamental interface for all log operations. Implementations -// must be safe for concurrent use by multiple goroutines. Log creates a log -// event from keyvals, a variadic sequence of alternating keys and values. +// Logger is the fundamental interface for all log operations. Log creates a +// log event from keyvals, a variadic sequence of alternating keys and values. +// Implementations must be safe for concurrent use by multiple goroutines. In +// particular, any implementation of Logger that appends to keyvals or +// modifies any of its elements must make a copy first. type Logger interface { Log(keyvals ...interface{}) error } -// With returns a new Logger that includes keyvals in all log events. The -// returned Logger replaces all value elements (odd indexes) containing a -// Valuer with their generated value for each call to its Log method. -func With(logger Logger, keyvals ...interface{}) Logger { - w, ok := logger.(*withLogger) - if !ok { - w = &withLogger{logger: logger} +// NewContext returns a new Context that logs to logger. +func NewContext(logger Logger) Context { + if c, ok := logger.(Context); ok { + return c } - return w.with(keyvals...) + return Context{logger: logger} } -type withLogger struct { +// A Context wraps a Logger and holds keyvals that it includes in all log +// events. When logging, a Context replaces all value elements (odd indexes) +// containing a Valuer with their generated value for each call to its Log +// method. +type Context struct { logger Logger keyvals []interface{} hasValuer bool } -func (l *withLogger) Log(keyvals ...interface{}) error { +// Log replaces all value elements (odd indexes) containing a Valuer in the +// stored context with their generated value, appends keyvals, and passes the +// result to the wrapped Logger. +func (l Context) Log(keyvals ...interface{}) error { + if len(keyvals)%2 != 0 { + panic("bad keyvals") + } kvs := append(l.keyvals, keyvals...) if l.hasValuer { + // If no keyvals were appended above then we must copy l.keyvals so + // that future log events will reevaluate the stored Valuers. + if len(keyvals) == 0 { + kvs = append([]interface{}{}, l.keyvals...) + } bindValues(kvs[:len(l.keyvals)]) } return l.logger.Log(kvs...) } -func (l *withLogger) with(keyvals ...interface{}) Logger { +// With returns a new Context with keyvals appended to those of the receiver. +func (l Context) With(keyvals ...interface{}) Context { + if len(keyvals) == 0 { + return l + } + if len(keyvals)%2 != 0 { + panic("bad keyvals") + } // Limiting the capacity of the stored keyvals ensures that a new // backing array is created if the slice must grow in Log or With. // Using the extra capacity without copying risks a data race that // would violate the Logger interface contract. n := len(l.keyvals) + len(keyvals) - return &withLogger{ + return Context{ logger: l.logger, keyvals: append(l.keyvals, keyvals...)[:n:n], hasValuer: l.hasValuer || containsValuer(keyvals), } } +// WithPrefix returns a new Context with keyvals prepended to those of the +// receiver. +func (l Context) WithPrefix(keyvals ...interface{}) Context { + if len(keyvals) == 0 { + return l + } + if len(keyvals)%2 != 0 { + panic("bad keyvals") + } + // Limiting the capacity of the stored keyvals ensures that a new + // backing array is created if the slice must grow in Log or With. + // Using the extra capacity without copying risks a data race that + // would violate the Logger interface contract. + n := len(l.keyvals) + len(keyvals) + kvs := make([]interface{}, 0, n) + kvs = append(kvs, keyvals...) + kvs = append(kvs, l.keyvals...) + return Context{ + logger: l.logger, + keyvals: kvs, + hasValuer: l.hasValuer || containsValuer(keyvals), + } +} + // LoggerFunc is an adapter to allow use of ordinary functions as Loggers. If // f is a function with the appropriate signature, LoggerFunc(f) is a Logger // object that calls f. diff --git a/log/log_test.go b/log/log_test.go index 978289a49..fd03f540a 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -10,14 +10,40 @@ import ( var discard = log.Logger(log.LoggerFunc(func(...interface{}) error { return nil })) -func TestWith(t *testing.T) { +func TestContext(t *testing.T) { + buf := &bytes.Buffer{} + logger := log.NewLogfmtLogger(buf) + + kvs := []interface{}{"a", 123} + lc := log.NewContext(logger).With(kvs...) + kvs[1] = 0 // With should copy its key values + + lc = lc.With("b", "c") // With should stack + if err := lc.Log("msg", "message"); err != nil { + t.Fatal(err) + } + if want, have := "a=123 b=c msg=message\n", buf.String(); want != have { + t.Errorf("\nwant: %shave: %s", want, have) + } + + buf.Reset() + lc = lc.WithPrefix("p", "first") + if err := lc.Log("msg", "message"); err != nil { + t.Fatal(err) + } + if want, have := "p=first a=123 b=c msg=message\n", buf.String(); want != have { + t.Errorf("\nwant: %shave: %s", want, have) + } +} + +func TestContextWithPrefix(t *testing.T) { buf := &bytes.Buffer{} kvs := []interface{}{"a", 123} logger := log.NewJSONLogger(buf) - logger = log.With(logger, kvs...) - kvs[1] = 0 // With should copy its key values - logger = log.With(logger, "b", "c") // With should stack - if err := logger.Log("msg", "message"); err != nil { + lc := log.NewContext(logger).With(kvs...) + kvs[1] = 0 // WithPrefix should copy its key values + lc = lc.With("b", "c") // WithPrefix should stack + if err := lc.Log("msg", "message"); err != nil { t.Fatal(err) } if want, have := `{"a":123,"b":"c","msg":"message"}`+"\n", buf.String(); want != have { @@ -45,7 +71,7 @@ func TestWithConcurrent(t *testing.T) { // With must be careful about handling slices that can grow without // copying the underlying array, so give it a challenge. - l := log.With(logger, make([]interface{}, 0, 2)...) + l := log.NewContext(logger).With(make([]interface{}, 0, 2)...) // Start logging concurrently. Each goroutine logs its id so the logger // can bucket the event counts. @@ -80,35 +106,37 @@ func BenchmarkDiscard(b *testing.B) { func BenchmarkOneWith(b *testing.B) { logger := discard - logger = log.With(logger, "k", "v") + lc := log.NewContext(logger).With("k", "v") b.ReportAllocs() b.ResetTimer() for i := 0; i < b.N; i++ { - logger.Log("k", "v") + lc.Log("k", "v") } } func BenchmarkTwoWith(b *testing.B) { logger := discard - for i := 0; i < 2; i++ { - logger = log.With(logger, "k", "v") + lc := log.NewContext(logger).With("k", "v") + for i := 1; i < 2; i++ { + lc = lc.With("k", "v") } b.ReportAllocs() b.ResetTimer() for i := 0; i < b.N; i++ { - logger.Log("k", "v") + lc.Log("k", "v") } } func BenchmarkTenWith(b *testing.B) { logger := discard - for i := 0; i < 10; i++ { - logger = log.With(logger, "k", "v") + lc := log.NewContext(logger).With("k", "v") + for i := 1; i < 10; i++ { + lc = lc.With("k", "v") } b.ReportAllocs() b.ResetTimer() for i := 0; i < b.N; i++ { - logger.Log("k", "v") + lc.Log("k", "v") } } diff --git a/log/stdlib.go b/log/stdlib.go index 2f8f53245..4749b2bf3 100644 --- a/log/stdlib.go +++ b/log/stdlib.go @@ -8,11 +8,11 @@ import ( ) // StdlibWriter implements io.Writer by invoking the stdlib log.Print. It's -// designed to be passed to a gokit logger as the writer, for cases where it's -// necessary to redirect all gokit log output to the stdlib logger. +// designed to be passed to a Go kit logger as the writer, for cases where +// it's necessary to redirect all Go kit log output to the stdlib logger. // // If you have any choice in the matter, you shouldn't use this. Prefer to -// redirect the stdlib log to the gokit logger via NewStdlibAdapter. +// redirect the stdlib log to the Go kit logger via NewStdlibAdapter. type StdlibWriter struct{} // Write implements io.Writer. diff --git a/log/value.go b/log/value.go index a9881ceb3..d0b4daffd 100644 --- a/log/value.go +++ b/log/value.go @@ -6,9 +6,9 @@ import ( "gopkg.in/stack.v1" ) -// A Valuer generates a log value. When passed to With in a value element (odd -// indexes), it represents a dynamic value which is re-evaluated with each log -// event. +// A Valuer generates a log value. When passed to Context.With in a value +// element (odd indexes), it represents a dynamic value which is re-evaluated +// with each log event. type Valuer func() interface{} // bindValues replaces all value elements (odd indexes) containing a Valuer diff --git a/log/value_test.go b/log/value_test.go index 133157975..cee834f31 100644 --- a/log/value_test.go +++ b/log/value_test.go @@ -23,9 +23,9 @@ func TestValueBinding(t *testing.T) { return now } - logger = log.With(logger, "ts", log.Timestamp(mocktime), "caller", log.DefaultCaller) + lc := log.NewContext(logger).With("ts", log.Timestamp(mocktime), "caller", log.DefaultCaller) - logger.Log("foo", "bar") + lc.Log("foo", "bar") timestamp, ok := output[1].(time.Time) if !ok { t.Fatalf("want time.Time, have %T", output[1]) @@ -38,7 +38,7 @@ func TestValueBinding(t *testing.T) { } // A second attempt to confirm the bindings are truly dynamic. - logger.Log("foo", "bar") + lc.Log("foo", "bar") timestamp, ok = output[1].(time.Time) if !ok { t.Fatalf("want time.Time, have %T", output[1]) @@ -51,22 +51,59 @@ func TestValueBinding(t *testing.T) { } } +func TestValueBinding_loggingZeroKeyvals(t *testing.T) { + var output []interface{} + + logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error { + output = keyvals + return nil + })) + + start := time.Date(2015, time.April, 25, 0, 0, 0, 0, time.UTC) + now := start + mocktime := func() time.Time { + now = now.Add(time.Second) + return now + } + + logger = log.NewContext(logger).With("ts", log.Timestamp(mocktime)) + + logger.Log() + timestamp, ok := output[1].(time.Time) + if !ok { + t.Fatalf("want time.Time, have %T", output[1]) + } + if want, have := start.Add(time.Second), timestamp; want != have { + t.Errorf("output[1]: want %v, have %v", want, have) + } + + // A second attempt to confirm the bindings are truly dynamic. + logger.Log() + timestamp, ok = output[1].(time.Time) + if !ok { + t.Fatalf("want time.Time, have %T", output[1]) + } + if want, have := start.Add(2*time.Second), timestamp; want != have { + t.Errorf("output[1]: want %v, have %v", want, have) + } +} + func BenchmarkValueBindingTimestamp(b *testing.B) { logger := discard - logger = log.With(logger, "ts", log.DefaultTimestamp) + lc := log.NewContext(logger).With("ts", log.DefaultTimestamp) b.ReportAllocs() b.ResetTimer() for i := 0; i < b.N; i++ { - logger.Log("k", "v") + lc.Log("k", "v") } } func BenchmarkValueBindingCaller(b *testing.B) { logger := discard - logger = log.With(logger, "caller", log.DefaultCaller) + lc := log.NewContext(logger).With("caller", log.DefaultCaller) b.ReportAllocs() b.ResetTimer() for i := 0; i < b.N; i++ { - logger.Log("k", "v") + lc.Log("k", "v") } }