From f76e8e4ddffb6a8b799eaad668548eee717a57c1 Mon Sep 17 00:00:00 2001 From: Daniel Price Date: Thu, 13 Jul 2023 17:14:46 +0000 Subject: [PATCH] Allow callers to pass go context through to hooks Add Ctx(context.Context) to Event and Context, allowing log.Info().Ctx(ctx).Msg("hello"). Registered hooks can retrieve the context from Event.GetCtx(). Facilitates writing hooks which fetch tracing context from the go context. --- README.md | 56 +++++++++++++++++++++++++++++++++++------------ benchmark_test.go | 9 ++++++++ context.go | 10 +++++++++ event.go | 30 ++++++++++++++++++++++--- hook_test.go | 34 ++++++++++++++++++++++++++++ log.go | 6 +++-- log_test.go | 6 ++++- 7 files changed, 131 insertions(+), 20 deletions(-) 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)