From 3c0749a2e6c85439b918bd6370ffab16fcbc1348 Mon Sep 17 00:00:00 2001 From: Peter Bourgon Date: Fri, 10 Jul 2015 20:31:37 -0600 Subject: [PATCH 01/11] log: first cut of new API, incomplete --- log2/benchmark_test.go | 32 ++++++++++++++++++++++++++++++++ log2/example_test.go | 23 +++++++++++++++++++++++ log2/levels.go | 40 ++++++++++++++++++++++++++++++++++++++++ log2/levels_test.go | 25 +++++++++++++++++++++++++ log2/logfmt.go | 39 +++++++++++++++++++++++++++++++++++++++ log2/logger.go | 34 ++++++++++++++++++++++++++++++++++ log2/value.go | 20 ++++++++++++++++++++ 7 files changed, 213 insertions(+) create mode 100644 log2/benchmark_test.go create mode 100644 log2/example_test.go create mode 100644 log2/levels.go create mode 100644 log2/levels_test.go create mode 100644 log2/logfmt.go create mode 100644 log2/logger.go create mode 100644 log2/value.go diff --git a/log2/benchmark_test.go b/log2/benchmark_test.go new file mode 100644 index 000000000..eb5872a11 --- /dev/null +++ b/log2/benchmark_test.go @@ -0,0 +1,32 @@ +package log_test + +import ( + "io/ioutil" + "testing" + + "github.com/go-kit/kit/log2" +) + +func BenchmarkContextNoMessage(b *testing.B) { + logger := log.NewLogfmtLogger(ioutil.Discard) + ctx := log.NewContext(logger, "module", "benchmark") + for i := 0; i < b.N; i++ { + ctx.Log() + } +} + +func BenchmarkContextOneMessage(b *testing.B) { + logger := log.NewLogfmtLogger(ioutil.Discard) + ctx := log.NewContext(logger, "module", "benchmark") + for i := 0; i < b.N; i++ { + ctx.Log("msg", "hello") + } +} + +func BenchmarkContextWith(b *testing.B) { + logger := log.NewLogfmtLogger(ioutil.Discard) + ctx := log.NewContext(logger, "module", "benchmark") + for i := 0; i < b.N; i++ { + ctx.With("subcontext", 123).Log("msg", "goodbye") + } +} diff --git a/log2/example_test.go b/log2/example_test.go new file mode 100644 index 000000000..8b301c957 --- /dev/null +++ b/log2/example_test.go @@ -0,0 +1,23 @@ +package log_test + +import ( + "os" + + "github.com/go-kit/kit/log2" +) + +func ExampleContext() { + logger := log.NewLogfmtLogger(os.Stdout) + logger.Log("foo", 123) + ctx := log.NewContext(logger, "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/log2/levels.go b/log2/levels.go new file mode 100644 index 000000000..b17ada095 --- /dev/null +++ b/log2/levels.go @@ -0,0 +1,40 @@ +package log + +type Levels interface { + With(...interface{}) Levels + Debug(...interface{}) error + Info(...interface{}) error + Warn(...interface{}) error + Error(...interface{}) error + Crit(...interface{}) error +} + +func NewLevels(logger Logger, keyvals ...interface{}) Levels { + return levels(NewContext(logger, keyvals...)) +} + +type levels Context + +func (l levels) With(keyvals ...interface{}) Levels { + return levels(Context(l).With(keyvals...)) +} + +func (l levels) Debug(keyvals ...interface{}) error { + return NewContext(l.logger).With("level", "debug").With(l.keyvals...).Log(keyvals...) +} + +func (l levels) Info(keyvals ...interface{}) error { + return NewContext(l.logger).With("level", "info").With(l.keyvals...).Log(keyvals...) +} + +func (l levels) Warn(keyvals ...interface{}) error { + return NewContext(l.logger).With("level", "warn").With(l.keyvals...).Log(keyvals...) +} + +func (l levels) Error(keyvals ...interface{}) error { + return NewContext(l.logger).With("level", "error").With(l.keyvals...).Log(keyvals...) +} + +func (l levels) Crit(keyvals ...interface{}) error { + return NewContext(l.logger).With("level", "crit").With(l.keyvals...).Log(keyvals...) +} diff --git a/log2/levels_test.go b/log2/levels_test.go new file mode 100644 index 000000000..a75d5ec19 --- /dev/null +++ b/log2/levels_test.go @@ -0,0 +1,25 @@ +package log_test + +import ( + "io/ioutil" + "os" + "testing" + + "github.com/go-kit/kit/log2" +) + +func ExampleLevels() { + logger := log.NewLevels(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 +} + +func BenchmarkLevels(b *testing.B) { + logger := log.NewLevels(log.NewLogfmtLogger(ioutil.Discard)).With("foo", "bar") + for i := 0; i < b.N; i++ { + logger.Debug("key", "val") + } +} diff --git a/log2/logfmt.go b/log2/logfmt.go new file mode 100644 index 000000000..2dbc60e7e --- /dev/null +++ b/log2/logfmt.go @@ -0,0 +1,39 @@ +package log + +import ( + "io" + + "gopkg.in/logfmt.v0" +) + +type logfmtLogger struct { + w io.Writer +} + +// NewLogfmtLogger returns a logger that encodes keyvals to the Writer in +// logfmt format. The passed Writer must be safe for concurrent use by +// multiple goroutines if the returned Logger will be used concurrently. +func NewLogfmtLogger(w io.Writer) Logger { + return &logfmtLogger{w} +} + +func (l logfmtLogger) Log(keyvals ...interface{}) error { + // The Logger interface requires implementations to be safe for concurrent + // use by multiple goroutines. For this implementation that means making + // only one call to l.w.Write() for each call to Log. We first collect all + // of the bytes into b, and then call l.w.Write(b). + for i := 1; i < len(keyvals); i += 2 { + if valuer, ok := keyvals[i].(Valuer); ok { + keyvals[i] = valuer.Value() + } + } + b, err := logfmt.MarshalKeyvals(keyvals...) + if err != nil { + return err + } + b = append(b, '\n') + if _, err := l.w.Write(b); err != nil { + return err + } + return nil +} diff --git a/log2/logger.go b/log2/logger.go new file mode 100644 index 000000000..7a56d521a --- /dev/null +++ b/log2/logger.go @@ -0,0 +1,34 @@ +package log + +type Logger interface { + Log(keyvals ...interface{}) error +} + +type Context struct { + logger Logger + keyvals []interface{} +} + +func NewContext(logger Logger, keyvals ...interface{}) Context { + if len(keyvals)%2 != 0 { + panic("bad keyvals") + } + return Context{ + logger: logger, + keyvals: keyvals, + } +} + +func (c Context) With(keyvals ...interface{}) Context { + if len(keyvals)%2 != 0 { + panic("bad keyvals") + } + return Context{ + logger: c.logger, + keyvals: append(c.keyvals, keyvals...), + } +} + +func (c Context) Log(keyvals ...interface{}) error { + return c.logger.Log(append(c.keyvals, keyvals...)...) +} diff --git a/log2/value.go b/log2/value.go new file mode 100644 index 000000000..d928d7ef0 --- /dev/null +++ b/log2/value.go @@ -0,0 +1,20 @@ +package log + +import ( + "fmt" + "path/filepath" + "runtime" +) + +type Valuer interface { + Value() interface{} +} + +var Caller = ValuerFunc(func() interface{} { + _, file, line, _ := runtime.Caller(5) + return fmt.Sprintf("%s:%d", filepath.Base(file), line) +}) + +type ValuerFunc func() interface{} + +func (f ValuerFunc) Value() interface{} { return f() } From 85bd2e7e31c66061aafa16b4d3d0d736c32276ed Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Sun, 12 Jul 2015 19:44:39 -0400 Subject: [PATCH 02/11] Rename withLogger to Context and export With method. --- log/benchmark_test.go | 4 ++-- log/levels.go | 6 ++--- log/log.go | 48 +++++++++++++++++++++++++++++----------- log/log_test.go | 27 ++++++++++++----------- log/value_test.go | 51 +++++++++++++++++++++++++++++++++++++------ 5 files changed, 98 insertions(+), 38 deletions(-) diff --git a/log/benchmark_test.go b/log/benchmark_test.go index 3e4e78fc7..126bfa5ae 100644 --- a/log/benchmark_test.go +++ b/log/benchmark_test.go @@ -7,11 +7,11 @@ import ( ) func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) { - logger = log.With(logger, "common_key", "common_value") + lc := log.With(logger, "common_key", "common_value") b.ReportAllocs() b.ResetTimer() for i := 0; i < b.N; i++ { - f(logger) + f(lc) } } diff --git a/log/levels.go b/log/levels.go index 4c7079bb0..1d52a4faa 100644 --- a/log/levels.go +++ b/log/levels.go @@ -2,9 +2,9 @@ package log // Levels provides a default set of leveled loggers. type Levels struct { - Debug Logger - Info Logger - Error Logger + Debug *Context + Info *Context + Error *Context } type levelOptions struct { diff --git a/log/log.go b/log/log.go index f907713bb..0984ea2f7 100644 --- a/log/log.go +++ b/log/log.go @@ -6,45 +6,67 @@ 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 modifies elements of keyvals +// must make a copy and modify the copy. 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 +// With returns a new Context that includes keyvals in all log events. The +// returned Context 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) +func With(logger Logger, keyvals ...interface{}) *Context { + if len(keyvals)%2 != 0 { + panic("bad keyvals") + } + w, ok := logger.(*Context) if !ok { - w = &withLogger{logger: logger} + w = &Context{logger: logger} } - return w.with(keyvals...) + return w.With(keyvals...) } -type withLogger struct { +// A Context wraps a Logger and holds keyvals that it includes in all log +// events. +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 appeneded to those of the receiver. +func (l *Context) With(keyvals ...interface{}) *Context { + 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), diff --git a/log/log_test.go b/log/log_test.go index 978289a49..e07874d89 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -13,11 +13,10 @@ var discard = log.Logger(log.LoggerFunc(func(...interface{}) error { return nil func TestWith(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.With(log.NewJSONLogger(buf), 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 { @@ -80,35 +79,37 @@ func BenchmarkDiscard(b *testing.B) { func BenchmarkOneWith(b *testing.B) { logger := discard - logger = log.With(logger, "k", "v") + lc := log.With(logger, "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.With(logger, "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.With(logger, "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/value_test.go b/log/value_test.go index 133157975..122e4c8bb 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.With(logger, "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.With(logger, "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.With(logger, "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.With(logger, "caller", log.DefaultCaller) b.ReportAllocs() b.ResetTimer() for i := 0; i < b.N; i++ { - logger.Log("k", "v") + lc.Log("k", "v") } } From 45df0a4ba8b90c0f9e65cfd9feca05eba548a50d Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Sun, 12 Jul 2015 20:56:13 -0400 Subject: [PATCH 03/11] Add Context example. --- log/example_test.go | 23 +++++++++++++++++++++++ 1 file changed, 23 insertions(+) create mode 100644 log/example_test.go diff --git a/log/example_test.go b/log/example_test.go new file mode 100644 index 000000000..6ab5cf50e --- /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.With(logger, "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 +} From 352f923ee164e9e91e0883ce6875f409d9eeec3e Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Sun, 12 Jul 2015 21:39:33 -0400 Subject: [PATCH 04/11] Rename log.With to log.NewContext and remove keyvals vargs. --- addsvc/main.go | 2 +- log/benchmark_test.go | 4 ++-- log/example_test.go | 2 +- log/levels.go | 12 ++++++------ log/levels_test.go | 2 +- log/log.go | 30 +++++++++++++----------------- log/log_test.go | 10 +++++----- log/value.go | 6 +++--- log/value_test.go | 8 ++++---- 9 files changed, 36 insertions(+), 40 deletions(-) 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 126bfa5ae..d3695b834 100644 --- a/log/benchmark_test.go +++ b/log/benchmark_test.go @@ -7,7 +7,7 @@ import ( ) func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) { - lc := 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++ { @@ -17,5 +17,5 @@ func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) { 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 index 6ab5cf50e..174161548 100644 --- a/log/example_test.go +++ b/log/example_test.go @@ -9,7 +9,7 @@ import ( func ExampleContext() { logger := log.NewLogfmtLogger(os.Stdout) logger.Log("foo", 123) - ctx := log.With(logger, "level", "info") + ctx := log.NewContext(logger).With("level", "info") ctx.Log() ctx = ctx.With("msg", "hello") ctx.Log() diff --git a/log/levels.go b/log/levels.go index 1d52a4faa..9278a62fd 100644 --- a/log/levels.go +++ b/log/levels.go @@ -2,9 +2,9 @@ package log // Levels provides a default set of leveled loggers. type Levels struct { - Debug *Context - Info *Context - Error *Context + Debug Context + Info Context + Error Context } type levelOptions struct { @@ -53,8 +53,8 @@ func NewLevels(base Logger, options ...LevelOption) Levels { 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), + Debug: NewContext(base).With(opts.levelKey, opts.debugValue), + Info: NewContext(base).With(opts.levelKey, opts.infoValue), + Error: NewContext(base).With(opts.levelKey, opts.errorValue), } } diff --git a/log/levels_test.go b/log/levels_test.go index 95333103a..eee51f04a 100644 --- a/log/levels_test.go +++ b/log/levels_test.go @@ -38,7 +38,7 @@ func TestModifiedLevels(t *testing.T) { log.InfoLevelValue("🌜"), log.ErrorLevelValue("🌊"), ) - log.With(levels.Debug, "easter_island", "🗿").Log("msg", "💃💃💃") + log.NewContext(levels.Debug).With("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 0984ea2f7..f83ac45b5 100644 --- a/log/log.go +++ b/log/log.go @@ -9,28 +9,24 @@ import "sync/atomic" // 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 modifies elements of keyvals -// must make a copy and modify the copy. +// 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 Context that includes keyvals in all log events. The -// returned Context 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{}) *Context { - if len(keyvals)%2 != 0 { - panic("bad keyvals") - } - w, ok := logger.(*Context) - if !ok { - w = &Context{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} } // A Context wraps a Logger and holds keyvals that it includes in all log -// events. +// 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{} @@ -40,7 +36,7 @@ type Context struct { // 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 { +func (l Context) Log(keyvals ...interface{}) error { if len(keyvals)%2 != 0 { panic("bad keyvals") } @@ -57,7 +53,7 @@ func (l *Context) Log(keyvals ...interface{}) error { } // With returns a new Context with keyvals appeneded to those of the receiver. -func (l *Context) With(keyvals ...interface{}) *Context { +func (l Context) With(keyvals ...interface{}) Context { if len(keyvals)%2 != 0 { panic("bad keyvals") } @@ -66,7 +62,7 @@ func (l *Context) With(keyvals ...interface{}) *Context { // Using the extra capacity without copying risks a data race that // would violate the Logger interface contract. n := len(l.keyvals) + len(keyvals) - return &Context{ + return Context{ logger: l.logger, keyvals: append(l.keyvals, keyvals...)[:n:n], hasValuer: l.hasValuer || containsValuer(keyvals), diff --git a/log/log_test.go b/log/log_test.go index e07874d89..ab119cb1d 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -13,7 +13,7 @@ var discard = log.Logger(log.LoggerFunc(func(...interface{}) error { return nil func TestWith(t *testing.T) { buf := &bytes.Buffer{} kvs := []interface{}{"a", 123} - lc := log.With(log.NewJSONLogger(buf), kvs...) + lc := log.NewContext(log.NewJSONLogger(buf)).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 { @@ -44,7 +44,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. @@ -79,7 +79,7 @@ func BenchmarkDiscard(b *testing.B) { func BenchmarkOneWith(b *testing.B) { logger := discard - lc := log.With(logger, "k", "v") + lc := log.NewContext(logger).With("k", "v") b.ReportAllocs() b.ResetTimer() for i := 0; i < b.N; i++ { @@ -89,7 +89,7 @@ func BenchmarkOneWith(b *testing.B) { func BenchmarkTwoWith(b *testing.B) { logger := discard - lc := log.With(logger, "k", "v") + lc := log.NewContext(logger).With("k", "v") for i := 1; i < 2; i++ { lc = lc.With("k", "v") } @@ -102,7 +102,7 @@ func BenchmarkTwoWith(b *testing.B) { func BenchmarkTenWith(b *testing.B) { logger := discard - lc := log.With(logger, "k", "v") + lc := log.NewContext(logger).With("k", "v") for i := 1; i < 10; i++ { lc = lc.With("k", "v") } 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 122e4c8bb..cee834f31 100644 --- a/log/value_test.go +++ b/log/value_test.go @@ -23,7 +23,7 @@ func TestValueBinding(t *testing.T) { return now } - lc := log.With(logger, "ts", log.Timestamp(mocktime), "caller", log.DefaultCaller) + lc := log.NewContext(logger).With("ts", log.Timestamp(mocktime), "caller", log.DefaultCaller) lc.Log("foo", "bar") timestamp, ok := output[1].(time.Time) @@ -66,7 +66,7 @@ func TestValueBinding_loggingZeroKeyvals(t *testing.T) { return now } - logger = log.With(logger, "ts", log.Timestamp(mocktime)) + logger = log.NewContext(logger).With("ts", log.Timestamp(mocktime)) logger.Log() timestamp, ok := output[1].(time.Time) @@ -90,7 +90,7 @@ func TestValueBinding_loggingZeroKeyvals(t *testing.T) { func BenchmarkValueBindingTimestamp(b *testing.B) { logger := discard - lc := 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++ { @@ -100,7 +100,7 @@ func BenchmarkValueBindingTimestamp(b *testing.B) { func BenchmarkValueBindingCaller(b *testing.B) { logger := discard - lc := 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++ { From 1350576efef6ffad7c954e81ba3aa39df2f070c7 Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Sun, 12 Jul 2015 21:41:15 -0400 Subject: [PATCH 05/11] Fix spelling in comment. --- log/log.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/log/log.go b/log/log.go index f83ac45b5..e873ec014 100644 --- a/log/log.go +++ b/log/log.go @@ -52,7 +52,7 @@ func (l Context) Log(keyvals ...interface{}) error { return l.logger.Log(kvs...) } -// With returns a new Context with keyvals appeneded to those of the receiver. +// With returns a new Context with keyvals appended to those of the receiver. func (l Context) With(keyvals ...interface{}) Context { if len(keyvals)%2 != 0 { panic("bad keyvals") From ab4fe883248cf7348f7bf70f4bd8aa6a03458f7e Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Mon, 13 Jul 2015 20:52:27 -0400 Subject: [PATCH 06/11] Move leveled logging into its own package and update API to improve contextual logging. --- log/levels.go | 60 --------------------- log/levels/levels.go | 110 ++++++++++++++++++++++++++++++++++++++ log/levels/levels_test.go | 55 +++++++++++++++++++ log/levels_test.go | 45 ---------------- log/log.go | 27 ++++++++++ log/log_test.go | 33 ++++++++++-- 6 files changed, 222 insertions(+), 108 deletions(-) delete mode 100644 log/levels.go create mode 100644 log/levels/levels.go create mode 100644 log/levels/levels_test.go delete mode 100644 log/levels_test.go diff --git a/log/levels.go b/log/levels.go deleted file mode 100644 index 9278a62fd..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 Context - Info Context - Error Context -} - -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: NewContext(base).With(opts.levelKey, opts.debugValue), - Info: NewContext(base).With(opts.levelKey, opts.infoValue), - Error: NewContext(base).With(opts.levelKey, opts.errorValue), - } -} diff --git a/log/levels/levels.go b/log/levels/levels.go new file mode 100644 index 000000000..fc8425c35 --- /dev/null +++ b/log/levels/levels.go @@ -0,0 +1,110 @@ +package levels + +import "github.com/go-kit/kit/log" + +// Levels provides leveled logging. +type Levels struct { + ctx log.Context + opts *config +} + +// New creates a new leveled logger. +func New(logger log.Logger, options ...Option) Levels { + opts := &config{ + levelKey: "level", + debugValue: "debug", + infoValue: "info", + warnValue: "warn", + errorValue: "error", + critValue: "crit", + } + for _, option := range options { + option(opts) + } + return Levels{ + ctx: log.NewContext(logger), + opts: opts, + } +} + +// 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...), + opts: l.opts, + } +} + +// Debug logs a debug event along with keyvals. +func (l Levels) Debug(keyvals ...interface{}) error { + return l.ctx.WithPrefix(l.opts.levelKey, l.opts.debugValue).Log(keyvals...) +} + +// Info logs an info event along with keyvals. +func (l Levels) Info(keyvals ...interface{}) error { + return l.ctx.WithPrefix(l.opts.levelKey, l.opts.infoValue).Log(keyvals...) +} + +// Warn logs a warn event along with keyvals. +func (l Levels) Warn(keyvals ...interface{}) error { + return l.ctx.WithPrefix(l.opts.levelKey, l.opts.warnValue).Log(keyvals...) +} + +// Error logs an error event along with keyvals. +func (l Levels) Error(keyvals ...interface{}) error { + return l.ctx.WithPrefix(l.opts.levelKey, l.opts.errorValue).Log(keyvals...) +} + +// Crit logs a crit event along with keyvals. +func (l Levels) Crit(keyvals ...interface{}) error { + return l.ctx.WithPrefix(l.opts.levelKey, l.opts.critValue).Log(keyvals...) +} + +type config struct { + levelKey string + + debugValue string + infoValue string + warnValue string + errorValue string + critValue string +} + +// Option sets a parameter for leveled loggers. +type Option func(*config) + +// 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(o *config) { o.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(o *config) { o.debugValue = value } +} + +// InfoValue sets the value for the field used to indicate the debug log +// level. By default, the value is "info". +func InfoValue(value string) Option { + return func(o *config) { o.infoValue = value } +} + +// WarnValue sets the value for the field used to indicate the debug log +// level. By default, the value is "debug". +func WarnValue(value string) Option { + return func(o *config) { o.warnValue = value } +} + +// ErrorValue sets the value for the field used to indicate the debug log +// level. By default, the value is "error". +func ErrorValue(value string) Option { + return func(o *config) { o.errorValue = value } +} + +// CritValue sets the value for the field used to indicate the debug log +// level. By default, the value is "debug". +func CritValue(value string) Option { + return func(o *config) { o.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 eee51f04a..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.NewContext(levels.Debug).With("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 e873ec014..fe7fa5adf 100644 --- a/log/log.go +++ b/log/log.go @@ -54,6 +54,9 @@ func (l Context) Log(keyvals ...interface{}) error { // 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") } @@ -69,6 +72,30 @@ func (l Context) With(keyvals ...interface{}) Context { } } +// 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 ab119cb1d..fd03f540a 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -10,15 +10,42 @@ 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(log.NewJSONLogger(buf)).With(kvs...) - kvs[1] = 0 // With should copy its key values + 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) + 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 { t.Errorf("\nwant: %s\nhave: %s", want, have) } From 30c187f7ffc8e10c6a986229cf6ac4c9f75ef936 Mon Sep 17 00:00:00 2001 From: Peter Bourgon Date: Tue, 14 Jul 2015 09:45:38 +0200 Subject: [PATCH 07/11] log/levels: clean up some comments and var names --- log/levels/levels.go | 59 +++++++++++++++++++++++--------------------- 1 file changed, 31 insertions(+), 28 deletions(-) diff --git a/log/levels/levels.go b/log/levels/levels.go index fc8425c35..d0dadc599 100644 --- a/log/levels/levels.go +++ b/log/levels/levels.go @@ -2,15 +2,18 @@ package levels import "github.com/go-kit/kit/log" -// Levels provides leveled logging. +// 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 - opts *config + ctx log.Context + cfg *config } -// New creates a new leveled logger. +// New creates a new leveled logger, wrapping the passed logger. func New(logger log.Logger, options ...Option) Levels { - opts := &config{ + cfg := &config{ levelKey: "level", debugValue: "debug", infoValue: "info", @@ -19,45 +22,45 @@ func New(logger log.Logger, options ...Option) Levels { critValue: "crit", } for _, option := range options { - option(opts) + option(cfg) } return Levels{ - ctx: log.NewContext(logger), - opts: opts, + ctx: log.NewContext(logger), + cfg: cfg, } } // 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...), - opts: l.opts, + ctx: l.ctx.With(keyvals...), + cfg: l.cfg, } } // Debug logs a debug event along with keyvals. func (l Levels) Debug(keyvals ...interface{}) error { - return l.ctx.WithPrefix(l.opts.levelKey, l.opts.debugValue).Log(keyvals...) + return l.ctx.WithPrefix(l.cfg.levelKey, l.cfg.debugValue).Log(keyvals...) } // Info logs an info event along with keyvals. func (l Levels) Info(keyvals ...interface{}) error { - return l.ctx.WithPrefix(l.opts.levelKey, l.opts.infoValue).Log(keyvals...) + return l.ctx.WithPrefix(l.cfg.levelKey, l.cfg.infoValue).Log(keyvals...) } // Warn logs a warn event along with keyvals. func (l Levels) Warn(keyvals ...interface{}) error { - return l.ctx.WithPrefix(l.opts.levelKey, l.opts.warnValue).Log(keyvals...) + return l.ctx.WithPrefix(l.cfg.levelKey, l.cfg.warnValue).Log(keyvals...) } // Error logs an error event along with keyvals. func (l Levels) Error(keyvals ...interface{}) error { - return l.ctx.WithPrefix(l.opts.levelKey, l.opts.errorValue).Log(keyvals...) + return l.ctx.WithPrefix(l.cfg.levelKey, l.cfg.errorValue).Log(keyvals...) } // Crit logs a crit event along with keyvals. func (l Levels) Crit(keyvals ...interface{}) error { - return l.ctx.WithPrefix(l.opts.levelKey, l.opts.critValue).Log(keyvals...) + return l.ctx.WithPrefix(l.cfg.levelKey, l.cfg.critValue).Log(keyvals...) } type config struct { @@ -76,35 +79,35 @@ type Option func(*config) // 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(o *config) { o.levelKey = key } + return func(c *config) { c.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(o *config) { o.debugValue = value } + return func(c *config) { c.debugValue = value } } -// InfoValue sets the value for the field used to indicate the debug log -// level. By default, the value is "info". +// 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(o *config) { o.infoValue = value } + return func(c *config) { c.infoValue = value } } -// WarnValue sets the value for the field used to indicate the debug log -// level. By default, the value is "debug". +// 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(o *config) { o.warnValue = value } + return func(c *config) { c.warnValue = value } } -// ErrorValue sets the value for the field used to indicate the debug log +// 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(o *config) { o.errorValue = value } + return func(c *config) { c.errorValue = value } } -// CritValue sets the value for the field used to indicate the debug log -// level. By default, the value is "debug". +// 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(o *config) { o.critValue = value } + return func(c *config) { c.critValue = value } } From 3b23396a9a4f2219d74312b22dd84dffd504c914 Mon Sep 17 00:00:00 2001 From: Peter Bourgon Date: Tue, 14 Jul 2015 09:51:22 +0200 Subject: [PATCH 08/11] log2: rm --- log2/benchmark_test.go | 32 -------------------------------- log2/example_test.go | 23 ----------------------- log2/levels.go | 40 ---------------------------------------- log2/levels_test.go | 25 ------------------------- log2/logfmt.go | 39 --------------------------------------- log2/logger.go | 34 ---------------------------------- log2/value.go | 20 -------------------- 7 files changed, 213 deletions(-) delete mode 100644 log2/benchmark_test.go delete mode 100644 log2/example_test.go delete mode 100644 log2/levels.go delete mode 100644 log2/levels_test.go delete mode 100644 log2/logfmt.go delete mode 100644 log2/logger.go delete mode 100644 log2/value.go diff --git a/log2/benchmark_test.go b/log2/benchmark_test.go deleted file mode 100644 index eb5872a11..000000000 --- a/log2/benchmark_test.go +++ /dev/null @@ -1,32 +0,0 @@ -package log_test - -import ( - "io/ioutil" - "testing" - - "github.com/go-kit/kit/log2" -) - -func BenchmarkContextNoMessage(b *testing.B) { - logger := log.NewLogfmtLogger(ioutil.Discard) - ctx := log.NewContext(logger, "module", "benchmark") - for i := 0; i < b.N; i++ { - ctx.Log() - } -} - -func BenchmarkContextOneMessage(b *testing.B) { - logger := log.NewLogfmtLogger(ioutil.Discard) - ctx := log.NewContext(logger, "module", "benchmark") - for i := 0; i < b.N; i++ { - ctx.Log("msg", "hello") - } -} - -func BenchmarkContextWith(b *testing.B) { - logger := log.NewLogfmtLogger(ioutil.Discard) - ctx := log.NewContext(logger, "module", "benchmark") - for i := 0; i < b.N; i++ { - ctx.With("subcontext", 123).Log("msg", "goodbye") - } -} diff --git a/log2/example_test.go b/log2/example_test.go deleted file mode 100644 index 8b301c957..000000000 --- a/log2/example_test.go +++ /dev/null @@ -1,23 +0,0 @@ -package log_test - -import ( - "os" - - "github.com/go-kit/kit/log2" -) - -func ExampleContext() { - logger := log.NewLogfmtLogger(os.Stdout) - logger.Log("foo", 123) - ctx := log.NewContext(logger, "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/log2/levels.go b/log2/levels.go deleted file mode 100644 index b17ada095..000000000 --- a/log2/levels.go +++ /dev/null @@ -1,40 +0,0 @@ -package log - -type Levels interface { - With(...interface{}) Levels - Debug(...interface{}) error - Info(...interface{}) error - Warn(...interface{}) error - Error(...interface{}) error - Crit(...interface{}) error -} - -func NewLevels(logger Logger, keyvals ...interface{}) Levels { - return levels(NewContext(logger, keyvals...)) -} - -type levels Context - -func (l levels) With(keyvals ...interface{}) Levels { - return levels(Context(l).With(keyvals...)) -} - -func (l levels) Debug(keyvals ...interface{}) error { - return NewContext(l.logger).With("level", "debug").With(l.keyvals...).Log(keyvals...) -} - -func (l levels) Info(keyvals ...interface{}) error { - return NewContext(l.logger).With("level", "info").With(l.keyvals...).Log(keyvals...) -} - -func (l levels) Warn(keyvals ...interface{}) error { - return NewContext(l.logger).With("level", "warn").With(l.keyvals...).Log(keyvals...) -} - -func (l levels) Error(keyvals ...interface{}) error { - return NewContext(l.logger).With("level", "error").With(l.keyvals...).Log(keyvals...) -} - -func (l levels) Crit(keyvals ...interface{}) error { - return NewContext(l.logger).With("level", "crit").With(l.keyvals...).Log(keyvals...) -} diff --git a/log2/levels_test.go b/log2/levels_test.go deleted file mode 100644 index a75d5ec19..000000000 --- a/log2/levels_test.go +++ /dev/null @@ -1,25 +0,0 @@ -package log_test - -import ( - "io/ioutil" - "os" - "testing" - - "github.com/go-kit/kit/log2" -) - -func ExampleLevels() { - logger := log.NewLevels(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 -} - -func BenchmarkLevels(b *testing.B) { - logger := log.NewLevels(log.NewLogfmtLogger(ioutil.Discard)).With("foo", "bar") - for i := 0; i < b.N; i++ { - logger.Debug("key", "val") - } -} diff --git a/log2/logfmt.go b/log2/logfmt.go deleted file mode 100644 index 2dbc60e7e..000000000 --- a/log2/logfmt.go +++ /dev/null @@ -1,39 +0,0 @@ -package log - -import ( - "io" - - "gopkg.in/logfmt.v0" -) - -type logfmtLogger struct { - w io.Writer -} - -// NewLogfmtLogger returns a logger that encodes keyvals to the Writer in -// logfmt format. The passed Writer must be safe for concurrent use by -// multiple goroutines if the returned Logger will be used concurrently. -func NewLogfmtLogger(w io.Writer) Logger { - return &logfmtLogger{w} -} - -func (l logfmtLogger) Log(keyvals ...interface{}) error { - // The Logger interface requires implementations to be safe for concurrent - // use by multiple goroutines. For this implementation that means making - // only one call to l.w.Write() for each call to Log. We first collect all - // of the bytes into b, and then call l.w.Write(b). - for i := 1; i < len(keyvals); i += 2 { - if valuer, ok := keyvals[i].(Valuer); ok { - keyvals[i] = valuer.Value() - } - } - b, err := logfmt.MarshalKeyvals(keyvals...) - if err != nil { - return err - } - b = append(b, '\n') - if _, err := l.w.Write(b); err != nil { - return err - } - return nil -} diff --git a/log2/logger.go b/log2/logger.go deleted file mode 100644 index 7a56d521a..000000000 --- a/log2/logger.go +++ /dev/null @@ -1,34 +0,0 @@ -package log - -type Logger interface { - Log(keyvals ...interface{}) error -} - -type Context struct { - logger Logger - keyvals []interface{} -} - -func NewContext(logger Logger, keyvals ...interface{}) Context { - if len(keyvals)%2 != 0 { - panic("bad keyvals") - } - return Context{ - logger: logger, - keyvals: keyvals, - } -} - -func (c Context) With(keyvals ...interface{}) Context { - if len(keyvals)%2 != 0 { - panic("bad keyvals") - } - return Context{ - logger: c.logger, - keyvals: append(c.keyvals, keyvals...), - } -} - -func (c Context) Log(keyvals ...interface{}) error { - return c.logger.Log(append(c.keyvals, keyvals...)...) -} diff --git a/log2/value.go b/log2/value.go deleted file mode 100644 index d928d7ef0..000000000 --- a/log2/value.go +++ /dev/null @@ -1,20 +0,0 @@ -package log - -import ( - "fmt" - "path/filepath" - "runtime" -) - -type Valuer interface { - Value() interface{} -} - -var Caller = ValuerFunc(func() interface{} { - _, file, line, _ := runtime.Caller(5) - return fmt.Sprintf("%s:%d", filepath.Base(file), line) -}) - -type ValuerFunc func() interface{} - -func (f ValuerFunc) Value() interface{} { return f() } From fcff50988fd5fd645e3d5e02f53acf421c51f623 Mon Sep 17 00:00:00 2001 From: Peter Bourgon Date: Tue, 14 Jul 2015 09:53:16 +0200 Subject: [PATCH 09/11] log: fix some comments --- log/stdlib.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) 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. From 375e07e8a6d9e91d44262b8f62d5d13577ca66d5 Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Tue, 14 Jul 2015 19:44:02 -0400 Subject: [PATCH 10/11] Combine config and Levels structs. --- log/levels/levels.go | 66 ++++++++++++++++++++++---------------------- 1 file changed, 33 insertions(+), 33 deletions(-) diff --git a/log/levels/levels.go b/log/levels/levels.go index d0dadc599..415f52bcc 100644 --- a/log/levels/levels.go +++ b/log/levels/levels.go @@ -7,14 +7,22 @@ import "github.com/go-kit/kit/log" // 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 - cfg *config + ctx log.Context + levelKey string + + 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 { - cfg := &config{ - levelKey: "level", + l := Levels{ + ctx: log.NewContext(logger), + levelKey: "level", + debugValue: "debug", infoValue: "info", warnValue: "warn", @@ -22,92 +30,84 @@ func New(logger log.Logger, options ...Option) Levels { critValue: "crit", } for _, option := range options { - option(cfg) - } - return Levels{ - ctx: log.NewContext(logger), - cfg: cfg, + 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...), - cfg: l.cfg, + 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.cfg.levelKey, l.cfg.debugValue).Log(keyvals...) + 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.cfg.levelKey, l.cfg.infoValue).Log(keyvals...) + 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.cfg.levelKey, l.cfg.warnValue).Log(keyvals...) + 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.cfg.levelKey, l.cfg.errorValue).Log(keyvals...) + 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.cfg.levelKey, l.cfg.critValue).Log(keyvals...) -} - -type config struct { - levelKey string - - debugValue string - infoValue string - warnValue string - errorValue string - critValue string + return l.ctx.WithPrefix(l.levelKey, l.critValue).Log(keyvals...) } // Option sets a parameter for leveled loggers. -type Option func(*config) +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(c *config) { c.levelKey = key } + 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(c *config) { c.debugValue = value } + 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(c *config) { c.infoValue = value } + 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(c *config) { c.warnValue = value } + 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(c *config) { c.errorValue = value } + 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(c *config) { c.critValue = value } + return func(l *Levels) { l.critValue = value } } From d15d8f573c7710235973eebd9cbed00f8cfa4c93 Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Wed, 15 Jul 2015 09:11:46 -0400 Subject: [PATCH 11/11] Document implementation tradeoff and reason for choosing to favor a cheap WIth method at the expense of the Log method. --- log/levels/levels.go | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/log/levels/levels.go b/log/levels/levels.go index 415f52bcc..92522a4f5 100644 --- a/log/levels/levels.go +++ b/log/levels/levels.go @@ -10,6 +10,20 @@ 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