From d4d0b60b27129853b8a8c8792ca7f160c71fcc98 Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Sun, 5 Mar 2017 15:12:49 -0500 Subject: [PATCH 1/2] log: Unexport Context and change With and WithPrefix to top level functions. --- benchmark_test.go | 4 +-- deprecated_levels/levels.go | 16 ++++++------ doc.go | 4 +-- example_test.go | 6 ++--- json_logger_test.go | 2 +- level/benchmark_test.go | 6 ++--- level/example_test.go | 2 +- level/level.go | 8 +++--- level/level_test.go | 4 +-- log.go | 34 +++++++++++++------------ log_test.go | 51 ++++++++++++------------------------- nop_logger_test.go | 2 +- term/colorlogger_test.go | 4 +-- value_test.go | 8 +++--- 14 files changed, 67 insertions(+), 84 deletions(-) diff --git a/benchmark_test.go b/benchmark_test.go index d3695b8..126bfa5 100644 --- a/benchmark_test.go +++ b/benchmark_test.go @@ -7,7 +7,7 @@ import ( ) func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) { - lc := log.NewContext(logger).With("common_key", "common_value") + lc := log.With(logger, "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.NewContext(logger).With("a", "b").Log("c", "d") } + withMessage = func(logger log.Logger) { log.With(logger, "a", "b").Log("c", "d") } ) diff --git a/deprecated_levels/levels.go b/deprecated_levels/levels.go index da6b681..a034212 100644 --- a/deprecated_levels/levels.go +++ b/deprecated_levels/levels.go @@ -7,7 +7,7 @@ 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 + logger log.Logger levelKey string // We have a choice between storing level values in string fields or @@ -34,7 +34,7 @@ type Levels struct { // New creates a new leveled logger, wrapping the passed logger. func New(logger log.Logger, options ...Option) Levels { l := Levels{ - ctx: log.NewContext(logger), + logger: logger, levelKey: "level", debugValue: "debug", @@ -52,7 +52,7 @@ func New(logger log.Logger, options ...Option) Levels { // 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...), + logger: log.With(l.logger, keyvals...), levelKey: l.levelKey, debugValue: l.debugValue, infoValue: l.infoValue, @@ -64,27 +64,27 @@ func (l Levels) With(keyvals ...interface{}) Levels { // Debug returns a debug level logger. func (l Levels) Debug() log.Logger { - return l.ctx.WithPrefix(l.levelKey, l.debugValue) + return log.WithPrefix(l.logger, l.levelKey, l.debugValue) } // Info returns an info level logger. func (l Levels) Info() log.Logger { - return l.ctx.WithPrefix(l.levelKey, l.infoValue) + return log.WithPrefix(l.logger, l.levelKey, l.infoValue) } // Warn returns a warning level logger. func (l Levels) Warn() log.Logger { - return l.ctx.WithPrefix(l.levelKey, l.warnValue) + return log.WithPrefix(l.logger, l.levelKey, l.warnValue) } // Error returns an error level logger. func (l Levels) Error() log.Logger { - return l.ctx.WithPrefix(l.levelKey, l.errorValue) + return log.WithPrefix(l.logger, l.levelKey, l.errorValue) } // Crit returns a critical level logger. func (l Levels) Crit() log.Logger { - return l.ctx.WithPrefix(l.levelKey, l.critValue) + return log.WithPrefix(l.logger, l.levelKey, l.critValue) } // Option sets a parameter for leveled loggers. diff --git a/doc.go b/doc.go index ad1128e..bb92e57 100644 --- a/doc.go +++ b/doc.go @@ -42,7 +42,7 @@ // resulting log output. We can use a context to improve the RunTask example. // // func RunTask(task Task, logger log.Logger) string { -// logger = log.NewContext(logger).With("taskID", task.ID) +// logger = log.With(logger, "taskID", task.ID) // logger.Log("event", "starting task") // ... // taskHelper(task.Cmd, logger) @@ -72,7 +72,7 @@ // entries contain a timestamp and source location looks like this: // // logger := log.NewLogfmtLogger(log.NewSyncWriter(os.Stdout)) -// logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) +// logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) // // Concurrent Safety // diff --git a/example_test.go b/example_test.go index 809593c..99487a6 100644 --- a/example_test.go +++ b/example_test.go @@ -43,7 +43,7 @@ func Example_context() { } RunTask := func(task Task, logger log.Logger) { - logger = log.NewContext(logger).With("taskID", task.ID) + logger = log.With(logger, "taskID", task.ID) logger.Log("event", "starting task") taskHelper(task.Cmd, logger) @@ -68,7 +68,7 @@ func Example_valuer() { return count } - logger = log.NewContext(logger).With("count", log.Valuer(counter)) + logger = log.With(logger, "count", log.Valuer(counter)) logger.Log("call", "first") logger.Log("call", "second") @@ -88,7 +88,7 @@ func Example_debugInfo() { return baseTime } - logger = log.NewContext(logger).With("time", log.Timestamp(mockTime), "caller", log.DefaultCaller) + logger = log.With(logger, "time", log.Timestamp(mockTime), "caller", log.DefaultCaller) logger.Log("call", "first") logger.Log("call", "second") diff --git a/json_logger_test.go b/json_logger_test.go index 42df70c..00e6910 100644 --- a/json_logger_test.go +++ b/json_logger_test.go @@ -13,7 +13,7 @@ func TestJSONLoggerCaller(t *testing.T) { t.Parallel() buf := &bytes.Buffer{} logger := log.NewJSONLogger(buf) - logger = log.NewContext(logger).With("caller", log.DefaultCaller) + logger = log.With(logger, "caller", log.DefaultCaller) if err := logger.Log(); err != nil { t.Fatal(err) diff --git a/level/benchmark_test.go b/level/benchmark_test.go index 49ea57e..4fca6f0 100644 --- a/level/benchmark_test.go +++ b/level/benchmark_test.go @@ -17,13 +17,13 @@ func Benchmark(b *testing.B) { return l }}, {"TimeContext", func(l log.Logger) log.Logger { - return log.NewContext(l).With("time", log.DefaultTimestampUTC) + return log.With(l, "time", log.DefaultTimestampUTC) }}, {"CallerContext", func(l log.Logger) log.Logger { - return log.NewContext(l).With("caller", log.DefaultCaller) + return log.With(l, "caller", log.DefaultCaller) }}, {"TimeCallerReqIDContext", func(l log.Logger) log.Logger { - return log.NewContext(l).With("time", log.DefaultTimestampUTC, "caller", log.DefaultCaller, "reqID", 29) + return log.With(l, "time", log.DefaultTimestampUTC, "caller", log.DefaultCaller, "reqID", 29) }}, } diff --git a/level/example_test.go b/level/example_test.go index e2d357c..fed52e5 100644 --- a/level/example_test.go +++ b/level/example_test.go @@ -12,7 +12,7 @@ func Example_basic() { // setup logger with level filter logger := log.NewLogfmtLogger(os.Stdout) logger = level.NewFilter(logger, level.AllowInfo()) - logger = log.NewContext(logger).With("caller", log.DefaultCaller) + logger = log.With(logger, "caller", log.DefaultCaller) // use level helpers to log at different levels level.Error(logger).Log("err", errors.New("bad data")) diff --git a/level/level.go b/level/level.go index 9120e61..6833b0d 100644 --- a/level/level.go +++ b/level/level.go @@ -4,22 +4,22 @@ import "github.com/go-kit/kit/log" // Error returns a logger that includes a Key/ErrorValue pair. func Error(logger log.Logger) log.Logger { - return log.NewContext(logger).WithPrefix(Key(), ErrorValue()) + return log.WithPrefix(logger, Key(), ErrorValue()) } // Warn returns a logger that includes a Key/WarnValue pair. func Warn(logger log.Logger) log.Logger { - return log.NewContext(logger).WithPrefix(Key(), WarnValue()) + return log.WithPrefix(logger, Key(), WarnValue()) } // Info returns a logger that includes a Key/InfoValue pair. func Info(logger log.Logger) log.Logger { - return log.NewContext(logger).WithPrefix(Key(), InfoValue()) + return log.WithPrefix(logger, Key(), InfoValue()) } // Debug returns a logger that includes a Key/DebugValue pair. func Debug(logger log.Logger) log.Logger { - return log.NewContext(logger).WithPrefix(Key(), DebugValue()) + return log.WithPrefix(logger, Key(), DebugValue()) } // NewFilter wraps next and implements level filtering. See the commentary on diff --git a/level/level_test.go b/level/level_test.go index 6514af4..4d2aca5 100644 --- a/level/level_test.go +++ b/level/level_test.go @@ -144,7 +144,7 @@ func TestLevelContext(t *testing.T) { var logger log.Logger logger = log.NewLogfmtLogger(&buf) logger = level.NewFilter(logger, level.AllowAll()) - logger = log.NewContext(logger).With("caller", log.DefaultCaller) + logger = log.With(logger, "caller", log.DefaultCaller) level.Info(logger).Log("foo", "bar") if want, have := `level=info caller=level_test.go:149 foo=bar`, strings.TrimSpace(buf.String()); want != have { @@ -159,7 +159,7 @@ func TestContextLevel(t *testing.T) { // to specify a higher callstack depth value. var logger log.Logger logger = log.NewLogfmtLogger(&buf) - logger = log.NewContext(logger).With("caller", log.Caller(5)) + logger = log.With(logger, "caller", log.Caller(5)) logger = level.NewFilter(logger, level.AllowAll()) level.Info(logger).Log("foo", "bar") diff --git a/log.go b/log.go index 97990fe..afe42dc 100644 --- a/log.go +++ b/log.go @@ -15,12 +15,12 @@ type Logger interface { // the missing value. var ErrMissingValue = errors.New("(MISSING)") -// NewContext returns a new Context that logs to logger. -func NewContext(logger Logger) *Context { - if c, ok := logger.(*Context); ok { +// newContext returns a new context that logs to logger. +func newContext(logger Logger) *context { + if c, ok := logger.(*context); ok { return c } - return &Context{logger: logger} + return &context{logger: logger} } // Context must always have the same number of stack frames between calls to @@ -57,11 +57,11 @@ func NewContext(logger Logger) *Context { // Context.Log through a variable with type Context. Using pointer receivers // avoids this problem. -// 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) +// 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 { +type context struct { logger Logger keyvals []interface{} hasValuer bool @@ -70,7 +70,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 { kvs := append(l.keyvals, keyvals...) if len(kvs)%2 != 0 { kvs = append(kvs, ErrMissingValue) @@ -86,16 +86,17 @@ func (l *Context) Log(keyvals ...interface{}) error { return l.logger.Log(kvs...) } -// With returns a new Context with keyvals appended to those of the receiver. -func (l *Context) With(keyvals ...interface{}) *Context { +// With returns a new context with keyvals appended to those of the receiver. +func With(logger Logger, keyvals ...interface{}) Logger { if len(keyvals) == 0 { - return l + return logger } + l := newContext(logger) kvs := append(l.keyvals, keyvals...) if len(kvs)%2 != 0 { kvs = append(kvs, ErrMissingValue) } - return &Context{ + return &context{ logger: l.logger, // Limiting the capacity of the stored keyvals ensures that a new // backing array is created if the slice must grow in Log or With. @@ -106,12 +107,13 @@ func (l *Context) With(keyvals ...interface{}) *Context { } } -// WithPrefix returns a new Context with keyvals prepended to those of the +// WithPrefix returns a new context with keyvals prepended to those of the // receiver. -func (l *Context) WithPrefix(keyvals ...interface{}) *Context { +func WithPrefix(logger Logger, keyvals ...interface{}) Logger { if len(keyvals) == 0 { - return l + return logger } + l := newContext(logger) // 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 @@ -126,7 +128,7 @@ func (l *Context) WithPrefix(keyvals ...interface{}) *Context { kvs = append(kvs, ErrMissingValue) } kvs = append(kvs, l.keyvals...) - return &Context{ + return &context{ logger: l.logger, keyvals: kvs, hasValuer: l.hasValuer || containsValuer(keyvals), diff --git a/log_test.go b/log_test.go index 7c44095..55edcbe 100644 --- a/log_test.go +++ b/log_test.go @@ -16,10 +16,10 @@ func TestContext(t *testing.T) { logger := log.NewLogfmtLogger(buf) kvs := []interface{}{"a", 123} - lc := log.NewContext(logger).With(kvs...) + lc := log.With(logger, kvs...) kvs[1] = 0 // With should copy its key values - lc = lc.With("b", "c") // With should stack + lc = log.With(lc, "b", "c") // With should stack if err := lc.Log("msg", "message"); err != nil { t.Fatal(err) } @@ -28,7 +28,7 @@ func TestContext(t *testing.T) { } buf.Reset() - lc = lc.WithPrefix("p", "first") + lc = log.WithPrefix(lc, "p", "first") if err := lc.Log("msg", "message"); err != nil { t.Fatal(err) } @@ -45,17 +45,7 @@ func TestContextMissingValue(t *testing.T) { return nil })) - lc := log.NewContext(logger) - - lc.Log("k") - if want, have := 2, len(output); want != have { - t.Errorf("want len(output) == %v, have %v", want, have) - } - if want, have := log.ErrMissingValue, output[1]; want != have { - t.Errorf("want %#v, have %#v", want, have) - } - - lc.With("k1").WithPrefix("k0").Log("k2") + log.WithPrefix(log.With(logger, "k1"), "k0").Log("k2") if want, have := 6, len(output); want != have { t.Errorf("want len(output) == %v, have %v", want, have) } @@ -67,9 +57,7 @@ func TestContextMissingValue(t *testing.T) { } // Test that Context.Log has a consistent function stack depth when binding -// log.Valuers, regardless of how many times Context.With has been called or -// whether Context.Log is called via an interface typed variable or a concrete -// typed variable. +// log.Valuers, regardless of how many times Context.With has been called. func TestContextStackDepth(t *testing.T) { t.Parallel() fn := fmt.Sprintf("%n", stack.Caller(0)) @@ -91,32 +79,25 @@ func TestContextStackDepth(t *testing.T) { return nil }) - concrete := log.NewContext(logger).With("stack", stackValuer) - var iface log.Logger = concrete + logger = log.With(logger, "stack", stackValuer) // Call through interface to get baseline. - iface.Log("k", "v") + logger.Log("k", "v") want := output[1].(int) for len(output) < 10 { - concrete.Log("k", "v") - if have := output[1]; have != want { - t.Errorf("%d Withs: have %v, want %v", len(output)/2-1, have, want) - } - - iface.Log("k", "v") + logger.Log("k", "v") if have := output[1]; have != want { t.Errorf("%d Withs: have %v, want %v", len(output)/2-1, have, want) } - wrapped := log.NewContext(concrete) + wrapped := log.With(logger) wrapped.Log("k", "v") if have := output[1]; have != want { t.Errorf("%d Withs: have %v, want %v", len(output)/2-1, have, want) } - concrete = concrete.With("k", "v") - iface = concrete + logger = log.With(logger, "k", "v") } } @@ -140,7 +121,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.NewContext(logger).With(make([]interface{}, 0, 2)...) + l := log.With(logger, make([]interface{}, 0, 2)...) // Start logging concurrently. Each goroutine logs its id so the logger // can bucket the event counts. @@ -175,7 +156,7 @@ func BenchmarkDiscard(b *testing.B) { func BenchmarkOneWith(b *testing.B) { logger := log.NewNopLogger() - lc := log.NewContext(logger).With("k", "v") + lc := log.With(logger, "k", "v") b.ReportAllocs() b.ResetTimer() for i := 0; i < b.N; i++ { @@ -185,9 +166,9 @@ func BenchmarkOneWith(b *testing.B) { func BenchmarkTwoWith(b *testing.B) { logger := log.NewNopLogger() - lc := log.NewContext(logger).With("k", "v") + lc := log.With(logger, "k", "v") for i := 1; i < 2; i++ { - lc = lc.With("k", "v") + lc = log.With(lc, "k", "v") } b.ReportAllocs() b.ResetTimer() @@ -198,9 +179,9 @@ func BenchmarkTwoWith(b *testing.B) { func BenchmarkTenWith(b *testing.B) { logger := log.NewNopLogger() - lc := log.NewContext(logger).With("k", "v") + lc := log.With(logger, "k", "v") for i := 1; i < 10; i++ { - lc = lc.With("k", "v") + lc = log.With(lc, "k", "v") } b.ReportAllocs() b.ResetTimer() diff --git a/nop_logger_test.go b/nop_logger_test.go index 70e69cd..908ddd8 100644 --- a/nop_logger_test.go +++ b/nop_logger_test.go @@ -12,7 +12,7 @@ func TestNopLogger(t *testing.T) { if err := logger.Log("abc", 123); err != nil { t.Error(err) } - if err := log.NewContext(logger).With("def", "ghi").Log(); err != nil { + if err := log.With(logger, "def", "ghi").Log(); err != nil { t.Error(err) } } diff --git a/term/colorlogger_test.go b/term/colorlogger_test.go index 7f7b7be..c27ac59 100644 --- a/term/colorlogger_test.go +++ b/term/colorlogger_test.go @@ -56,7 +56,7 @@ func TestColorLoggerConcurrency(t *testing.T) { // copied from log/benchmark_test.go func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) { - lc := log.NewContext(logger).With("common_key", "common_value") + lc := log.With(logger, "common_key", "common_value") b.ReportAllocs() b.ResetTimer() for i := 0; i < b.N; i++ { @@ -66,7 +66,7 @@ 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.NewContext(logger).With("a", "b").Log("c", "d") } + withMessage = func(logger log.Logger) { log.With(logger, "a", "b").Log("c", "d") } ) // copied from log/concurrency_test.go diff --git a/value_test.go b/value_test.go index 44e6478..f67eece 100644 --- a/value_test.go +++ b/value_test.go @@ -24,7 +24,7 @@ func TestValueBinding(t *testing.T) { return now } - lc := log.NewContext(logger).With("ts", log.Timestamp(mocktime), "caller", log.DefaultCaller) + lc := log.With(logger, "ts", log.Timestamp(mocktime), "caller", log.DefaultCaller) lc.Log("foo", "bar") timestamp, ok := output[1].(time.Time) @@ -68,7 +68,7 @@ func TestValueBinding_loggingZeroKeyvals(t *testing.T) { return now } - logger = log.NewContext(logger).With("ts", log.Timestamp(mocktime)) + logger = log.With(logger, "ts", log.Timestamp(mocktime)) logger.Log() timestamp, ok := output[1].(time.Time) @@ -92,7 +92,7 @@ func TestValueBinding_loggingZeroKeyvals(t *testing.T) { func BenchmarkValueBindingTimestamp(b *testing.B) { logger := log.NewNopLogger() - lc := log.NewContext(logger).With("ts", log.DefaultTimestamp) + lc := log.With(logger, "ts", log.DefaultTimestamp) b.ReportAllocs() b.ResetTimer() for i := 0; i < b.N; i++ { @@ -102,7 +102,7 @@ func BenchmarkValueBindingTimestamp(b *testing.B) { func BenchmarkValueBindingCaller(b *testing.B) { logger := log.NewNopLogger() - lc := log.NewContext(logger).With("caller", log.DefaultCaller) + lc := log.With(logger, "caller", log.DefaultCaller) b.ReportAllocs() b.ResetTimer() for i := 0; i < b.N; i++ { From 44aed65f4dc2d4372d8c2656e5d0edb562469aaa Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Sun, 5 Mar 2017 21:46:41 -0500 Subject: [PATCH 2/2] log: Update docs to reflect unexporting context and newContext. This update also contains a few other minor documentation updates. --- README.md | 71 +++++++++++++------------ doc.go | 34 ++++++------ example_test.go | 2 +- log.go | 137 ++++++++++++++++++++++-------------------------- log_test.go | 4 +- value.go | 28 +++++----- 6 files changed, 133 insertions(+), 143 deletions(-) diff --git a/README.md b/README.md index 2763f7f..7222f80 100644 --- a/README.md +++ b/README.md @@ -1,20 +1,22 @@ # package log `package log` provides a minimal interface for structured logging in services. -It may be wrapped to encode conventions, enforce type-safety, provide leveled logging, and so on. -It can be used for both typical application log events, and log-structured data streams. +It may be wrapped to encode conventions, enforce type-safety, provide leveled +logging, and so on. It can be used for both typical application log events, +and log-structured data streams. ## Structured logging -Structured logging is, basically, conceding to the reality that logs are _data_, - and warrant some level of schematic rigor. -Using a stricter, key/value-oriented message format for our logs, - containing contextual and semantic information, - makes it much easier to get insight into the operational activity of the systems we build. -Consequently, `package log` is of the strong belief that - "[the benefits of structured logging outweigh the minimal effort involved](https://www.thoughtworks.com/radar/techniques/structured-logging)". +Structured logging is, basically, conceding to the reality that logs are +_data_, and warrant some level of schematic rigor. Using a stricter, +key/value-oriented message format for our logs, containing contextual and +semantic information, makes it much easier to get insight into the +operational activity of the systems we build. Consequently, `package log` is +of the strong belief that "[the benefits of structured logging outweigh the +minimal effort involved](https://www.thoughtworks.com/radar/techniques/structured-logging)". -Migrating from unstructured to structured logging is probably a lot easier than you'd expect. +Migrating from unstructured to structured logging is probably a lot easier +than you'd expect. ```go // Unstructured @@ -37,17 +39,17 @@ logger.Log("question", "what is the meaning of life?", "answer", 42) // question="what is the meaning of life?" answer=42 ``` -### Log contexts +### Contextual Loggers ```go func main() { var logger log.Logger logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr)) - logger = log.NewContext(logger).With("instance_id", 123) + logger = log.With(logger, "instance_id", 123) logger.Log("msg", "starting") - NewWorker(log.NewContext(logger).With("component", "worker")).Run() - NewSlacker(log.NewContext(logger).With("component", "slacker")).Run() + NewWorker(log.With(logger, "component", "worker")).Run() + NewSlacker(log.With(logger, "component", "slacker")).Run() } // Output: @@ -77,9 +79,8 @@ func main() { // {"msg":"I sure like pie","ts":"2016/01/01 12:34:56"} ``` -Or, if, for legacy reasons, - you need to pipe all of your logging through the stdlib log package, - you can redirect Go kit logger to the stdlib logger. +Or, if, for legacy reasons, you need to pipe all of your logging through the +stdlib log package, you can redirect Go kit logger to the stdlib logger. ```go logger := kitlog.NewLogfmtLogger(kitlog.StdlibWriter{}) @@ -94,7 +95,7 @@ logger.Log("legacy", true, "msg", "at least it's something") ```go var logger log.Logger logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr)) -logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) +logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) logger.Log("msg", "hello") @@ -104,7 +105,7 @@ logger.Log("msg", "hello") ## Supported output formats -- [Logfmt](https://brandur.org/logfmt) +- [Logfmt](https://brandur.org/logfmt) ([see also](https://blog.codeship.com/logfmt-a-log-format-thats-easy-to-read-and-write)) - JSON ## Enhancements @@ -117,27 +118,25 @@ type Logger interface { } ``` -This interface, and its supporting code like [log.Context](https://godoc.org/github.com/go-kit/kit/log#Context), - is the product of much iteration and evaluation. -For more details on the evolution of the Logger interface, - see [The Hunt for a Logger Interface](http://go-talks.appspot.com/github.com/ChrisHines/talks/structured-logging/structured-logging.slide#1), - a talk by [Chris Hines](https://github.com/ChrisHines). +This interface, and its supporting code like is the product of much iteration +and evaluation. For more details on the evolution of the Logger interface, +see [The Hunt for a Logger Interface](http://go-talks.appspot.com/github.com/ChrisHines/talks/structured-logging/structured-logging.slide#1), +a talk by [Chris Hines](https://github.com/ChrisHines). Also, please see - [#63](https://github.com/go-kit/kit/issues/63), - [#76](https://github.com/go-kit/kit/pull/76), - [#131](https://github.com/go-kit/kit/issues/131), - [#157](https://github.com/go-kit/kit/pull/157), - [#164](https://github.com/go-kit/kit/issues/164), and - [#252](https://github.com/go-kit/kit/pull/252) - to review historical conversations about package log and the Logger interface. +[#63](https://github.com/go-kit/kit/issues/63), +[#76](https://github.com/go-kit/kit/pull/76), +[#131](https://github.com/go-kit/kit/issues/131), +[#157](https://github.com/go-kit/kit/pull/157), +[#164](https://github.com/go-kit/kit/issues/164), and +[#252](https://github.com/go-kit/kit/pull/252) +to review historical conversations about package log and the Logger interface. Value-add packages and suggestions, - like improvements to [the leveled logger](https://godoc.org/github.com/go-kit/kit/log/levels), - are of course welcome. -Good proposals should +like improvements to [the leveled logger](https://godoc.org/github.com/go-kit/kit/log/level), +are of course welcome. Good proposals should -- Be composable with [log.Context](https://godoc.org/github.com/go-kit/kit/log#Context), -- Not break the behavior of [log.Caller](https://godoc.org/github.com/go-kit/kit/log#Caller) in any wrapped context, and +- Be composable with [contextual loggers](https://godoc.org/github.com/go-kit/kit/log#With), +- Not break the behavior of [log.Caller](https://godoc.org/github.com/go-kit/kit/log#Caller) in any wrapped contextual loggers, and - Be friendly to packages that accept only an unadorned log.Logger. ## Benchmarks & comparisons diff --git a/doc.go b/doc.go index bb92e57..918c0af 100644 --- a/doc.go +++ b/doc.go @@ -35,11 +35,12 @@ // idea to log simple values without formatting them. This practice allows // the chosen logger to encode values in the most appropriate way. // -// Log Context +// Contextual Loggers // -// A log context stores keyvals that it includes in all log events. Building -// appropriate log contexts reduces repetition and aids consistency in the -// resulting log output. We can use a context to improve the RunTask example. +// A contextual logger stores keyvals that it includes in all log events. +// Building appropriate contextual loggers reduces repetition and aids +// consistency in the resulting log output. With and WithPrefix add context to +// a logger. We can use With to improve the RunTask example. // // func RunTask(task Task, logger log.Logger) string { // logger = log.With(logger, "taskID", task.ID) @@ -51,19 +52,18 @@ // } // // The improved version emits the same log events as the original for the -// first and last calls to Log. The call to taskHelper highlights that a -// context may be passed as a logger to other functions. Each log event -// created by the called function will include the task.ID even though the -// function does not have access to that value. Using log contexts this way -// simplifies producing log output that enables tracing the life cycle of -// individual tasks. (See the Context example for the full code of the -// above snippet.) -// -// Dynamic Context Values -// -// A Valuer function stored in a log context generates a new value each time -// the context logs an event. The Valuer example demonstrates how this -// feature works. +// first and last calls to Log. Passing the contextual logger to taskHelper +// enables each log event created by taskHelper to include the task.ID even +// though taskHelper does not have access to that value. Using contextual +// loggers this way simplifies producing log output that enables tracing the +// life cycle of individual tasks. (See the Contextual example for the full +// code of the above snippet.) +// +// Dynamic Contextual Values +// +// A Valuer function stored in a contextual logger generates a new value each +// time an event is logged. The Valuer example demonstrates how this feature +// works. // // Valuers provide the basis for consistently logging timestamps and source // code location. The log package defines several valuers for that purpose. diff --git a/example_test.go b/example_test.go index 99487a6..9766774 100644 --- a/example_test.go +++ b/example_test.go @@ -29,7 +29,7 @@ func Example_basic() { // taskID=1 event="task complete" } -func Example_context() { +func Example_contextual() { logger := log.NewLogfmtLogger(os.Stdout) type Task struct { diff --git a/log.go b/log.go index afe42dc..66a9e2f 100644 --- a/log.go +++ b/log.go @@ -6,7 +6,7 @@ import "errors" // 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. +// modifies or retains any of its elements must make a copy first. type Logger interface { Log(keyvals ...interface{}) error } @@ -15,78 +15,12 @@ type Logger interface { // the missing value. var ErrMissingValue = errors.New("(MISSING)") -// newContext returns a new context that logs to logger. -func newContext(logger Logger) *context { - if c, ok := logger.(*context); ok { - return c - } - return &context{logger: logger} -} - -// Context must always have the same number of stack frames between calls to -// its Log method and the eventual binding of Valuers to their value. This -// requirement comes from the functional requirement to allow a context to -// resolve application call site information for a log.Caller stored in the -// context. To do this we must be able to predict the number of logging -// functions on the stack when bindValues is called. -// -// Three implementation details provide the needed stack depth consistency. -// The first two of these details also result in better amortized performance, -// and thus make sense even without the requirements regarding stack depth. -// The third detail, however, is subtle and tied to the implementation of the -// Go compiler. -// -// 1. NewContext avoids introducing an additional layer when asked to -// wrap another Context. -// 2. With avoids introducing an additional layer by returning a newly -// constructed Context with a merged keyvals rather than simply -// wrapping the existing Context. -// 3. All of Context's methods take pointer receivers even though they -// do not mutate the Context. +// With returns a new contextual logger with keyvals prepended to those passed +// to calls to Log. If logger is also a contextual logger created by With or +// WithPrefix, keyvals is appended to the existing context. // -// Before explaining the last detail, first some background. The Go compiler -// generates wrapper methods to implement the auto dereferencing behavior when -// calling a value method through a pointer variable. These wrapper methods -// are also used when calling a value method through an interface variable -// because interfaces store a pointer to the underlying concrete value. -// Calling a pointer receiver through an interface does not require generating -// an additional function. -// -// If Context had value methods then calling Context.Log through a variable -// with type Logger would have an extra stack frame compared to calling -// Context.Log through a variable with type Context. Using pointer receivers -// avoids this problem. - -// 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 -} - -// 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 { - kvs := append(l.keyvals, keyvals...) - if len(kvs)%2 != 0 { - kvs = append(kvs, ErrMissingValue) - } - 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...) -} - -// With returns a new context with keyvals appended to those of the receiver. +// 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 { if len(keyvals) == 0 { return logger @@ -107,8 +41,12 @@ func With(logger Logger, keyvals ...interface{}) Logger { } } -// WithPrefix returns a new context with keyvals prepended to those of the -// receiver. +// WithPrefix returns a new contextual logger with keyvals prepended to those +// passed to calls to Log. If logger is also a contextual logger created by +// With or WithPrefix, keyvals is prepended to the existing context. +// +// The returned Logger replaces all value elements (odd indexes) containing a +// Valuer with their generated value for each call to its Log method. func WithPrefix(logger Logger, keyvals ...interface{}) Logger { if len(keyvals) == 0 { return logger @@ -135,6 +73,57 @@ func WithPrefix(logger Logger, keyvals ...interface{}) Logger { } } +// context is the Logger implementation returned by With and WithPrefix. It +// wraps a Logger and holds keyvals that it includes in all log events. Its +// Log method calls bindValues to generate values for each Valuer in the +// context keyvals. +// +// A context must always have the same number of stack frames between calls to +// its Log method and the eventual binding of Valuers to their value. This +// requirement comes from the functional requirement to allow a context to +// resolve application call site information for a Caller stored in the +// context. To do this we must be able to predict the number of logging +// functions on the stack when bindValues is called. +// +// Two implementation details provide the needed stack depth consistency. +// +// 1. newContext avoids introducing an additional layer when asked to +// wrap another context. +// 2. With and WithPrefix avoid introducing an additional layer by +// returning a newly constructed context with a merged keyvals rather +// than simply wrapping the existing context. +type context struct { + logger Logger + keyvals []interface{} + hasValuer bool +} + +func newContext(logger Logger) *context { + if c, ok := logger.(*context); ok { + return c + } + return &context{logger: logger} +} + +// 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 { + kvs := append(l.keyvals, keyvals...) + if len(kvs)%2 != 0 { + kvs = append(kvs, ErrMissingValue) + } + 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...) +} + // 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_test.go b/log_test.go index 55edcbe..1bf2972 100644 --- a/log_test.go +++ b/log_test.go @@ -56,8 +56,8 @@ func TestContextMissingValue(t *testing.T) { } } -// Test that Context.Log has a consistent function stack depth when binding -// log.Valuers, regardless of how many times Context.With has been called. +// Test that context.Log has a consistent function stack depth when binding +// Valuers, regardless of how many times With has been called. func TestContextStackDepth(t *testing.T) { t.Parallel() fn := fmt.Sprintf("%n", stack.Caller(0)) diff --git a/value.go b/value.go index a5dc5da..0ce9b01 100644 --- a/value.go +++ b/value.go @@ -6,9 +6,9 @@ import ( "github.com/go-stack/stack" ) -// 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. +// A Valuer generates a log value. When passed to With or WithPrefix 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 @@ -39,16 +39,6 @@ func Timestamp(t func() time.Time) Valuer { return func() interface{} { return t() } } -var ( - // DefaultTimestamp is a Valuer that returns the current wallclock time, - // respecting time zones, when bound. - DefaultTimestamp Valuer = func() interface{} { return time.Now().Format(time.RFC3339Nano) } - - // DefaultTimestampUTC is a Valuer that returns the current time in UTC - // when bound. - DefaultTimestampUTC Valuer = func() interface{} { return time.Now().UTC().Format(time.RFC3339Nano) } -) - // Caller returns a Valuer that returns a file and line from a specified depth // in the callstack. Users will probably want to use DefaultCaller. func Caller(depth int) Valuer { @@ -56,6 +46,18 @@ func Caller(depth int) Valuer { } var ( + // DefaultTimestamp is a Valuer that returns the current wallclock time, + // respecting time zones, when bound. + DefaultTimestamp = Valuer(func() interface{} { + return time.Now().Format(time.RFC3339Nano) + }) + + // DefaultTimestampUTC is a Valuer that returns the current time in UTC + // when bound. + DefaultTimestampUTC = Valuer(func() interface{} { + return time.Now().UTC().Format(time.RFC3339Nano) + }) + // DefaultCaller is a Valuer that returns the file and line where the Log // method was invoked. It can only be used with log.With. DefaultCaller = Caller(3)