diff --git a/README.md b/README.md index 312b3b1e..3fc0dc4a 100644 --- a/README.md +++ b/README.md @@ -513,25 +513,53 @@ stdlog.Print("hello world") ### context.Context integration -The `Logger` instance could be attached to `context.Context` values with `logger.WithContext(ctx)` -and extracted from it using `zerolog.Ctx(ctx)`. +Go contexts are commonly passed throughout Go code, and this can help you pass +your Logger into places it might otherwise be hard to inject. The `Logger` +instance may be attached to Go context (`context.Context`) using +`Logger.WithContext(ctx)` and extracted from it using `zerolog.Ctx(ctx)`. +For example: -Example to add logger to context: ```go -// this code attach logger instance to context fields -ctx := context.Background() -logger := zerolog.New(os.Stdout) -ctx = logger.WithContext(ctx) -someFunc(ctx) +func f() { + logger := zerolog.New(os.Stdout) + ctx := context.Background() + + // Attach the Logger to the context.Context + ctx = logger.WithContext(ctx) + someFunc(ctx) +} + +func someFunc(ctx context.Context) { + // Get Logger from the go Context. if it's nil, then + // `zerolog.DefaultContextLogger` is returned, if + // `DefaultContextLogger` is nil, then a disabled logger is returned. + logger := zerolog.Ctx(ctx) + logger.Info().Msg("Hello") +} ``` -Extracting logger from context: +A second form of `context.Context` integration allows you to pass the current +context.Context into the logged event, and retrieve it from hooks. This can be +useful to log trace and span IDs or other information stored in the go context, +and facilitates the unification of logging and tracing in some systems: + ```go -func someFunc(ctx context.Context) { - // get logger from context. if it's nill, then `zerolog.DefaultContextLogger` is returned, - // if `DefaultContextLogger` is nil, then disabled logger returned. - logger := zerolog.Ctx(ctx) - logger.Info().Msg("Hello") +type TracingHook struct{} + +func (h TracingHook) Run(e *zerolog.Event, level zerolog.Level, msg string) { + ctx := e.Ctx() + spanId := getSpanIdFromContext(ctx) // as per your tracing framework + e.Str("span-id", spanId) +} + +func f() { + // Setup the logger + logger := zerolog.New(os.Stdout) + logger = logger.Hook(TracingHook{}) + + ctx := context.Background() + // Use the Ctx function to make the context available to the hook + logger.Info().Ctx(ctx).Msg("Hello") } ``` diff --git a/benchmark_test.go b/benchmark_test.go index 9aa41008..b2bb79a3 100644 --- a/benchmark_test.go +++ b/benchmark_test.go @@ -1,6 +1,7 @@ package zerolog import ( + "context" "errors" "io/ioutil" "net" @@ -160,6 +161,7 @@ func BenchmarkLogFieldType(b *testing.B) { {"a", "a", 0}, } errs := []error{errors.New("a"), errors.New("b"), errors.New("c"), errors.New("d"), errors.New("e")} + ctx := context.Background() types := map[string]func(e *Event) *Event{ "Bool": func(e *Event) *Event { return e.Bool("k", bools[0]) @@ -191,6 +193,9 @@ func BenchmarkLogFieldType(b *testing.B) { "Errs": func(e *Event) *Event { return e.Errs("k", errs) }, + "Ctx": func(e *Event) *Event { + return e.Ctx(ctx) + }, "Time": func(e *Event) *Event { return e.Time("k", times[0]) }, @@ -284,6 +289,7 @@ func BenchmarkContextFieldType(b *testing.B) { {"a", "a", 0}, } errs := []error{errors.New("a"), errors.New("b"), errors.New("c"), errors.New("d"), errors.New("e")} + ctx := context.Background() types := map[string]func(c Context) Context{ "Bool": func(c Context) Context { return c.Bool("k", bools[0]) @@ -318,6 +324,9 @@ func BenchmarkContextFieldType(b *testing.B) { "Errs": func(c Context) Context { return c.Errs("k", errs) }, + "Ctx": func(c Context) Context { + return c.Ctx(ctx) + }, "Time": func(c Context) Context { return c.Time("k", times[0]) }, diff --git a/context.go b/context.go index 39397d9c..9d860e50 100644 --- a/context.go +++ b/context.go @@ -1,6 +1,7 @@ package zerolog import ( + "context" "fmt" "io/ioutil" "math" @@ -165,6 +166,15 @@ func (c Context) Err(err error) Context { return c.AnErr(ErrorFieldName, err) } +// Ctx adds the context.Context to the logger context. The context.Context is +// not rendered in the error message, but is made available for hooks to use. +// A typical use case is to extract tracing information from the +// context.Context. +func (c Context) Ctx(ctx context.Context) Context { + c.l.ctx = ctx + return c +} + // Bool adds the field key with val as a bool to the logger context. func (c Context) Bool(key string, b bool) Context { c.l.context = enc.AppendBool(enc.AppendKey(c.l.context, key), b) diff --git a/event.go b/event.go index 5fb46536..2a5d3b08 100644 --- a/event.go +++ b/event.go @@ -1,6 +1,7 @@ package zerolog import ( + "context" "fmt" "net" "os" @@ -24,9 +25,10 @@ type Event struct { w LevelWriter level Level done func(msg string) - stack bool // enable error stack trace - ch []Hook // hooks from context - skipFrame int // The number of additional frames to skip when printing the caller. + stack bool // enable error stack trace + ch []Hook // hooks from context + skipFrame int // The number of additional frames to skip when printing the caller. + ctx context.Context // Optional Go context for event } func putEvent(e *Event) { @@ -417,6 +419,28 @@ func (e *Event) Stack() *Event { return e } +// Ctx adds the Go Context to the *Event context. The context is not rendered +// in the output message, but is available to hooks and to Func() calls via the +// GetCtx() accessor. A typical use case is to extract tracing information from +// the Go Ctx. +func (e *Event) Ctx(ctx context.Context) *Event { + if e != nil { + e.ctx = ctx + } + return e +} + +// GetCtx retrieves the Go context.Context which is optionally stored in the +// Event. This allows Hooks and functions passed to Func() to retrieve values +// which are stored in the context.Context. This can be useful in tracing, +// where span information is commonly propagated in the context.Context. +func (e *Event) GetCtx() context.Context { + if e == nil || e.ctx == nil { + return context.Background() + } + return e.ctx +} + // Bool adds the field key with val as a bool to the *Event context. func (e *Event) Bool(key string, b bool) *Event { if e == nil { diff --git a/hook_test.go b/hook_test.go index 19bde9d4..e9f5b9ee 100644 --- a/hook_test.go +++ b/hook_test.go @@ -2,10 +2,15 @@ package zerolog import ( "bytes" + "context" "io/ioutil" "testing" ) +type contextKeyType int + +var contextKey contextKeyType + var ( levelNameHook = HookFunc(func(e *Event, level Level, msg string) { levelName := level.String() @@ -31,6 +36,12 @@ var ( discardHook = HookFunc(func(e *Event, level Level, message string) { e.Discard() }) + contextHook = HookFunc(func(e *Event, level Level, message string) { + contextData, ok := e.GetCtx().Value(contextKey).(string) + if ok { + e.Str("context-data", contextData) + } + }) ) func TestHook(t *testing.T) { @@ -120,6 +131,29 @@ func TestHook(t *testing.T) { log = log.Hook(discardHook) log.Log().Msg("test message") }}, + {"Context/Background", `{"level":"info","message":"test message"}` + "\n", func(log Logger) { + log = log.Hook(contextHook) + log.Info().Ctx(context.Background()).Msg("test message") + }}, + {"Context/nil", `{"level":"info","message":"test message"}` + "\n", func(log Logger) { + // passing `nil` where a context is wanted is against + // the rules, but people still do it. + log = log.Hook(contextHook) + log.Info().Ctx(nil).Msg("test message") // nolint + }}, + {"Context/valid", `{"level":"info","context-data":"12345abcdef","message":"test message"}` + "\n", func(log Logger) { + ctx := context.Background() + ctx = context.WithValue(ctx, contextKey, "12345abcdef") + log = log.Hook(contextHook) + log.Info().Ctx(ctx).Msg("test message") + }}, + {"Context/With/valid", `{"level":"info","context-data":"12345abcdef","message":"test message"}` + "\n", func(log Logger) { + ctx := context.Background() + ctx = context.WithValue(ctx, contextKey, "12345abcdef") + log = log.Hook(contextHook) + log = log.With().Ctx(ctx).Logger() + log.Info().Msg("test message") + }}, {"None", `{"level":"error"}` + "\n", func(log Logger) { log.Error().Msg("") }}, diff --git a/log.go b/log.go index e6f6f7c0..7c7c6a20 100644 --- a/log.go +++ b/log.go @@ -82,8 +82,7 @@ // log.Warn().Msg("") // // Output: {"level":"warn","severity":"warn"} // -// -// Caveats +// # Caveats // // There is no fields deduplication out-of-the-box. // Using the same key multiple times creates new key in final JSON each time. @@ -99,6 +98,7 @@ package zerolog import ( + "context" "errors" "fmt" "io" @@ -218,6 +218,7 @@ type Logger struct { context []byte hooks []Hook stack bool + ctx context.Context } // New creates a root logger with given output writer. If the output writer implements @@ -455,6 +456,7 @@ func (l *Logger) newEvent(level Level, done func(string)) *Event { e := newEvent(l.w, level) e.done = done e.ch = l.hooks + e.ctx = l.ctx if level != NoLevel && LevelFieldName != "" { e.Str(LevelFieldName, LevelFieldMarshalFunc(level)) } diff --git a/log_test.go b/log_test.go index 0e64c494..4d0d93b1 100644 --- a/log_test.go +++ b/log_test.go @@ -2,6 +2,7 @@ package zerolog import ( "bytes" + "context" "errors" "fmt" "net" @@ -119,7 +120,8 @@ func TestWith(t *testing.T) { Uint64("uint64", 10). Float32("float32", 11.101). Float64("float64", 12.30303). - Time("time", time.Time{}) + Time("time", time.Time{}). + Ctx(context.Background()) _, file, line, _ := runtime.Caller(0) caller := fmt.Sprintf("%s:%d", file, line+3) log := ctx.Caller().Logger() @@ -344,6 +346,7 @@ func TestFields(t *testing.T) { Dur("dur", 1*time.Second). Time("time", time.Time{}). TimeDiff("diff", now, now.Add(-10*time.Second)). + Ctx(context.Background()). Msg("") if got, want := decodeIfBinaryToString(out.Bytes()), `{"caller":"`+caller+`","string":"foo","stringer":"127.0.0.1","stringer_nil":null,"bytes":"bar","hex":"12ef","json":{"some":"json"},"cbor":"data:application/cbor;base64,gwGCAgOCBAU=","func":"func_output","error":"some error","bool":true,"int":1,"int8":2,"int16":3,"int32":4,"int64":5,"uint":6,"uint8":7,"uint16":8,"uint32":9,"uint64":10,"IPv4":"192.168.0.100","IPv6":"2001:db8:85a3::8a2e:370:7334","Mac":"00:14:22:01:23:45","Prefix":"192.168.0.100/24","float32":11.1234,"float64":12.321321321,"dur":1000,"time":"0001-01-01T00:00:00Z","diff":10000}`+"\n"; got != want { t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want) @@ -462,6 +465,7 @@ func TestFieldsDisabled(t *testing.T) { Dur("dur", 1*time.Second). Time("time", time.Time{}). TimeDiff("diff", now, now.Add(-10*time.Second)). + Ctx(context.Background()). Msg("") if got, want := decodeIfBinaryToString(out.Bytes()), ""; got != want { t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)