diff --git a/examples/addsvc/cmd/addsvc/main.go b/examples/addsvc/cmd/addsvc/main.go index f2079f8bc..247a028e5 100644 --- a/examples/addsvc/cmd/addsvc/main.go +++ b/examples/addsvc/cmd/addsvc/main.go @@ -1,4 +1,4 @@ -package main +package main import ( "context" @@ -51,8 +51,8 @@ func main() { var logger log.Logger { logger = log.NewLogfmtLogger(os.Stdout) - logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC) - logger = log.NewContext(logger).With("caller", log.DefaultCaller) + logger = log.With(logger, "ts", log.DefaultTimestampUTC) + logger = log.With(logger, "caller", log.DefaultCaller) } logger.Log("msg", "hello") defer logger.Log("msg", "goodbye") @@ -86,7 +86,7 @@ func main() { var tracer stdopentracing.Tracer { if *zipkinAddr != "" { - logger := log.NewContext(logger).With("tracer", "ZipkinHTTP") + logger := log.With(logger, "tracer", "ZipkinHTTP") logger.Log("addr", *zipkinAddr) // endpoint typically looks like: http://zipkinhost:9411/api/v1/spans @@ -105,7 +105,7 @@ func main() { os.Exit(1) } } else if *zipkinKafkaAddr != "" { - logger := log.NewContext(logger).With("tracer", "ZipkinKafka") + logger := log.With(logger, "tracer", "ZipkinKafka") logger.Log("addr", *zipkinKafkaAddr) collector, err := zipkin.NewKafkaCollector( @@ -126,18 +126,18 @@ func main() { os.Exit(1) } } else if *appdashAddr != "" { - logger := log.NewContext(logger).With("tracer", "Appdash") + logger := log.With(logger, "tracer", "Appdash") logger.Log("addr", *appdashAddr) tracer = appdashot.NewTracer(appdash.NewRemoteCollector(*appdashAddr)) } else if *lightstepToken != "" { - logger := log.NewContext(logger).With("tracer", "LightStep") + logger := log.With(logger, "tracer", "LightStep") logger.Log() // probably don't want to print out the token :) tracer = lightstep.NewTracer(lightstep.Options{ AccessToken: *lightstepToken, }) defer lightstep.FlushLightStepTracer(tracer) } else { - logger := log.NewContext(logger).With("tracer", "none") + logger := log.With(logger, "tracer", "none") logger.Log() tracer = stdopentracing.GlobalTracer() // no-op } @@ -155,7 +155,7 @@ func main() { var sumEndpoint endpoint.Endpoint { sumDuration := duration.With("method", "Sum") - sumLogger := log.NewContext(logger).With("method", "Sum") + sumLogger := log.With(logger, "method", "Sum") sumEndpoint = addsvc.MakeSumEndpoint(service) sumEndpoint = opentracing.TraceServer(tracer, "Sum")(sumEndpoint) @@ -165,7 +165,7 @@ func main() { var concatEndpoint endpoint.Endpoint { concatDuration := duration.With("method", "Concat") - concatLogger := log.NewContext(logger).With("method", "Concat") + concatLogger := log.With(logger, "method", "Concat") concatEndpoint = addsvc.MakeConcatEndpoint(service) concatEndpoint = opentracing.TraceServer(tracer, "Concat")(concatEndpoint) @@ -190,7 +190,7 @@ func main() { // Debug listener. go func() { - logger := log.NewContext(logger).With("transport", "debug") + logger := log.With(logger, "transport", "debug") m := http.NewServeMux() m.Handle("/debug/pprof/", http.HandlerFunc(pprof.Index)) @@ -206,7 +206,7 @@ func main() { // HTTP transport. go func() { - logger := log.NewContext(logger).With("transport", "HTTP") + logger := log.With(logger, "transport", "HTTP") h := addsvc.MakeHTTPHandler(endpoints, tracer, logger) logger.Log("addr", *httpAddr) errc <- http.ListenAndServe(*httpAddr, h) @@ -214,7 +214,7 @@ func main() { // gRPC transport. go func() { - logger := log.NewContext(logger).With("transport", "gRPC") + logger := log.With(logger, "transport", "gRPC") ln, err := net.Listen("tcp", *grpcAddr) if err != nil { @@ -232,7 +232,7 @@ func main() { // Thrift transport. go func() { - logger := log.NewContext(logger).With("transport", "Thrift") + logger := log.With(logger, "transport", "Thrift") var protocolFactory thrift.TProtocolFactory switch *thriftProtocol { diff --git a/examples/apigateway/main.go b/examples/apigateway/main.go index 76aa5f905..bedb368da 100644 --- a/examples/apigateway/main.go +++ b/examples/apigateway/main.go @@ -44,8 +44,8 @@ func main() { var logger log.Logger { logger = log.NewLogfmtLogger(os.Stderr) - logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC) - logger = log.NewContext(logger).With("caller", log.DefaultCaller) + logger = log.With(logger, "ts", log.DefaultTimestampUTC) + logger = log.With(logger, "caller", log.DefaultCaller) } // Service discovery domain. In this example we use Consul. diff --git a/examples/profilesvc/cmd/profilesvc/main.go b/examples/profilesvc/cmd/profilesvc/main.go index 895ebb3b1..58c5cdd47 100644 --- a/examples/profilesvc/cmd/profilesvc/main.go +++ b/examples/profilesvc/cmd/profilesvc/main.go @@ -1,4 +1,4 @@ -package main +package main import ( "flag" @@ -21,8 +21,8 @@ func main() { var logger log.Logger { logger = log.NewLogfmtLogger(os.Stderr) - logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC) - logger = log.NewContext(logger).With("caller", log.DefaultCaller) + logger = log.With(logger, "ts", log.DefaultTimestampUTC) + logger = log.With(logger, "caller", log.DefaultCaller) } var s profilesvc.Service @@ -33,7 +33,7 @@ func main() { var h http.Handler { - h = profilesvc.MakeHTTPHandler(s, log.NewContext(logger).With("component", "HTTP")) + h = profilesvc.MakeHTTPHandler(s, log.With(logger, "component", "HTTP")) } errs := make(chan error) diff --git a/examples/shipping/main.go b/examples/shipping/main.go index 812302810..a4b42f71a 100644 --- a/examples/shipping/main.go +++ b/examples/shipping/main.go @@ -47,7 +47,7 @@ func main() { var logger log.Logger logger = log.NewLogfmtLogger(os.Stderr) logger = &serializedLogger{Logger: logger} - logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC) + logger = log.With(logger, "ts", log.DefaultTimestampUTC) var ( cargos = inmem.NewCargoRepository() @@ -78,7 +78,7 @@ func main() { var bs booking.Service bs = booking.NewService(cargos, locations, handlingEvents, rs) - bs = booking.NewLoggingService(log.NewContext(logger).With("component", "booking"), bs) + bs = booking.NewLoggingService(log.With(logger, "component", "booking"), bs) bs = booking.NewInstrumentingService( kitprometheus.NewCounterFrom(stdprometheus.CounterOpts{ Namespace: "api", @@ -97,7 +97,7 @@ func main() { var ts tracking.Service ts = tracking.NewService(cargos, handlingEvents) - ts = tracking.NewLoggingService(log.NewContext(logger).With("component", "tracking"), ts) + ts = tracking.NewLoggingService(log.With(logger, "component", "tracking"), ts) ts = tracking.NewInstrumentingService( kitprometheus.NewCounterFrom(stdprometheus.CounterOpts{ Namespace: "api", @@ -116,7 +116,7 @@ func main() { var hs handling.Service hs = handling.NewService(handlingEvents, handlingEventFactory, handlingEventHandler) - hs = handling.NewLoggingService(log.NewContext(logger).With("component", "handling"), hs) + hs = handling.NewLoggingService(log.With(logger, "component", "handling"), hs) hs = handling.NewInstrumentingService( kitprometheus.NewCounterFrom(stdprometheus.CounterOpts{ Namespace: "api", @@ -133,7 +133,7 @@ func main() { hs, ) - httpLogger := log.NewContext(logger).With("component", "http") + httpLogger := log.With(logger, "component", "http") mux := http.NewServeMux() diff --git a/examples/stringsvc3/main.go b/examples/stringsvc3/main.go index 86bb1df95..0e2b6b779 100644 --- a/examples/stringsvc3/main.go +++ b/examples/stringsvc3/main.go @@ -22,7 +22,7 @@ func main() { var logger log.Logger logger = log.NewLogfmtLogger(os.Stderr) - logger = log.NewContext(logger).With("listen", *listen).With("caller", log.DefaultCaller) + logger = log.With(logger, "listen", *listen, "caller", log.DefaultCaller) fieldKeys := []string{"method", "error"} requestCount := kitprometheus.NewCounterFrom(stdprometheus.CounterOpts{ diff --git a/log/README.md b/log/README.md index 2763f7f14..7222f8009 100644 --- a/log/README.md +++ b/log/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/log/benchmark_test.go b/log/benchmark_test.go index d3695b834..126bfa5ae 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.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/log/deprecated_levels/levels.go b/log/deprecated_levels/levels.go index da6b681b1..a03421277 100644 --- a/log/deprecated_levels/levels.go +++ b/log/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/log/doc.go b/log/doc.go index ad1128eba..918c0af46 100644 --- a/log/doc.go +++ b/log/doc.go @@ -35,14 +35,15 @@ // 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.NewContext(logger).With("taskID", task.ID) +// logger = log.With(logger, "taskID", task.ID) // logger.Log("event", "starting task") // ... // taskHelper(task.Cmd, logger) @@ -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.) +// 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 Context Values +// Dynamic Contextual 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. +// 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. @@ -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/log/example_test.go b/log/example_test.go index 809593c77..976677489 100644 --- a/log/example_test.go +++ b/log/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 { @@ -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/log/json_logger_test.go b/log/json_logger_test.go index 42df70c1c..00e691005 100644 --- a/log/json_logger_test.go +++ b/log/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/log/level/benchmark_test.go b/log/level/benchmark_test.go index 49ea57eed..4fca6f08f 100644 --- a/log/level/benchmark_test.go +++ b/log/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/log/level/example_test.go b/log/level/example_test.go index e2d357cc2..fed52e512 100644 --- a/log/level/example_test.go +++ b/log/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/log/level/level.go b/log/level/level.go index 9120e6161..6833b0dca 100644 --- a/log/level/level.go +++ b/log/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/log/level/level_test.go b/log/level/level_test.go index 6514af4c7..4d2aca5b8 100644 --- a/log/level/level_test.go +++ b/log/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/log.go b/log/log.go index 97990feff..66a9e2fde 100644 --- a/log/log.go +++ b/log/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,87 +15,22 @@ 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. +// 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. // -// 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. -// -// 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. -func (l *Context) With(keyvals ...interface{}) *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 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 +41,17 @@ 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 { +// 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 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,13 +66,64 @@ 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), } } +// 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/log_test.go b/log/log_test.go index 7c44095b3..1bf29727e 100644 --- a/log/log_test.go +++ b/log/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) } @@ -66,10 +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 or -// whether Context.Log is called via an interface typed variable or a concrete -// typed variable. +// 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)) @@ -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/log/nop_logger_test.go b/log/nop_logger_test.go index 70e69cdfe..908ddd816 100644 --- a/log/nop_logger_test.go +++ b/log/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/log/term/colorlogger_test.go b/log/term/colorlogger_test.go index 7f7b7be66..c27ac596a 100644 --- a/log/term/colorlogger_test.go +++ b/log/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/log/value.go b/log/value.go index a5dc5da33..0ce9b01f4 100644 --- a/log/value.go +++ b/log/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) diff --git a/log/value_test.go b/log/value_test.go index 44e6478af..f67eecece 100644 --- a/log/value_test.go +++ b/log/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++ { diff --git a/sd/consul/integration_test.go b/sd/consul/integration_test.go index 471af4e23..3b5e79f3e 100644 --- a/sd/consul/integration_test.go +++ b/sd/consul/integration_test.go @@ -46,7 +46,7 @@ func TestIntegration(t *testing.T) { subscriber := NewSubscriber( client, factory, - log.NewContext(logger).With("component", "subscriber"), + log.With(logger, "component", "subscriber"), r.Name, r.Tags, true, @@ -64,7 +64,7 @@ func TestIntegration(t *testing.T) { } // Build a registrar for r. - registrar := NewRegistrar(client, r, log.NewContext(logger).With("component", "registrar")) + registrar := NewRegistrar(client, r, log.With(logger, "component", "registrar")) registrar.Register() defer registrar.Deregister() diff --git a/sd/consul/registrar.go b/sd/consul/registrar.go index e89fef696..bf26bd2b8 100644 --- a/sd/consul/registrar.go +++ b/sd/consul/registrar.go @@ -21,7 +21,7 @@ func NewRegistrar(client Client, r *stdconsul.AgentServiceRegistration, logger l return &Registrar{ client: client, registration: r, - logger: log.NewContext(logger).With("service", r.Name, "tags", fmt.Sprint(r.Tags), "address", r.Address), + logger: log.With(logger, "service", r.Name, "tags", fmt.Sprint(r.Tags), "address", r.Address), } } diff --git a/sd/consul/subscriber.go b/sd/consul/subscriber.go index ee3ae34bb..30922e2b2 100644 --- a/sd/consul/subscriber.go +++ b/sd/consul/subscriber.go @@ -36,7 +36,7 @@ func NewSubscriber(client Client, factory sd.Factory, logger log.Logger, service s := &Subscriber{ cache: cache.New(factory, logger), client: client, - logger: log.NewContext(logger).With("service", service, "tags", fmt.Sprint(tags)), + logger: log.With(logger, "service", service, "tags", fmt.Sprint(tags)), service: service, tags: tags, passingOnly: passingOnly, diff --git a/sd/etcd/integration_test.go b/sd/etcd/integration_test.go index 4c7191268..86e1a6d17 100644 --- a/sd/etcd/integration_test.go +++ b/sd/etcd/integration_test.go @@ -49,7 +49,7 @@ func TestIntegration(t *testing.T) { registrar := NewRegistrar(client, Service{ Key: key, Value: value, - }, log.NewContext(log.NewLogfmtLogger(os.Stderr)).With("component", "registrar")) + }, log.With(log.NewLogfmtLogger(os.Stderr), "component", "registrar")) // Register our instance. registrar.Register() @@ -71,7 +71,7 @@ func TestIntegration(t *testing.T) { client, prefix, func(string) (endpoint.Endpoint, io.Closer, error) { return endpoint.Nop, nil, nil }, - log.NewContext(log.NewLogfmtLogger(os.Stderr)).With("component", "subscriber"), + log.With(log.NewLogfmtLogger(os.Stderr), "component", "subscriber"), ) if err != nil { t.Fatalf("NewSubscriber: %v", err) diff --git a/sd/etcd/registrar.go b/sd/etcd/registrar.go index 87b0eccb9..e38643090 100644 --- a/sd/etcd/registrar.go +++ b/sd/etcd/registrar.go @@ -63,10 +63,7 @@ func NewRegistrar(client Client, service Service, logger log.Logger) *Registrar return &Registrar{ client: client, service: service, - logger: log.NewContext(logger).With( - "key", service.Key, - "value", service.Value, - ), + logger: log.With(logger, "key", service.Key, "value", service.Value), } } diff --git a/sd/zk/registrar.go b/sd/zk/registrar.go index dcfae3986..379a4a504 100644 --- a/sd/zk/registrar.go +++ b/sd/zk/registrar.go @@ -24,7 +24,7 @@ func NewRegistrar(client Client, service Service, logger log.Logger) *Registrar return &Registrar{ client: client, service: service, - logger: log.NewContext(logger).With( + logger: log.With(logger, "service", service.Name, "path", service.Path, "data", string(service.Data),