Confusing behavior with context.Context integration

[bluekeyes]

First, thanks for this library; the API is easy to use and the hlog package is a nice bonus.

We recently started using zerolog.Ctx and (Logger) WithContext and were surprised to find that WithContext modified the context instead of creating a copy of the context with the modified logger. This means that when we set fields in functions that should only be visible to the functions they call, those fields are instead included on all future log message.

This program demonstrates the issue (it happens more naturally in HTTP handlers):

package main

import (
	"context"
	"github.com/rs/zerolog"
	"os"
)

func process(ctx context.Context, id int) {
	log := zerolog.Ctx(ctx).With().Int("id", id).Logger()
	child(log.WithContext(ctx))
}

func child(ctx context.Context) {
	zerolog.Ctx(ctx).Info().Msg("hello from child")
}

func main() {
	ctx := zerolog.New(os.Stdout).WithContext(context.Background())

	zerolog.Ctx(ctx).Info().Msg("processing 1")
	process(ctx, 1)

	zerolog.Ctx(ctx).Info().Msg("processing 2")
	process(ctx, 2)

	zerolog.Ctx(ctx).Info().Msg("done")
}

# expected output
{"level":"info","message":"processing 1"}
{"level":"info","id":1,"message":"hello from child"}
{"level":"info","message":"processing 2"}
{"level":"info","id":2,"message":"hello from child"}
{"level":"info","message":"done"}

# actual output
{"level":"info","message":"processing 1"}
{"level":"info","id":1,"message":"hello from child"}
{"level":"info","id":1,"message":"processing 2"}
{"level":"info","id":1,"id":2,"message":"hello from child"}
{"level":"info","id":1,"id":2,"message":"done"}

I did some digging in the history and it seems like this was added in 6a6144a to support the hlog functions, which are more efficient when they can modify the existing logger and can reasonably expect to exist at the top of the middleware stack.

However, at some later point, all those functions switched to use (*Logger) UpdateContext, which achieves the same thing. It seems like (Logger) WithContext is now only used to set the initial logger.

I think this behavior goes against the expectations of context.Context (modifications are not visible to functions that were not passed the modified context) and makes it difficult to add new logging fields only for sections of a request handler.

Is it possible that (Logger) WithContext could be reverted to always return a copy of the context if the logger is updated?

If not, do you have recommendations on how to work around this behavior? We're currently going to write our own functions to interact with the context, but it would be great if we could stick with the library functions.

[rs]

The rational is that a request context should only have a single instance of the logger so your requests can add fields that are visible to parent middleware for instance. This is particularly useful with the hlog.AccessHandler which can be augmented with request specific fields.

This is also better for performance. Storing a new instance of the logger in the context for each update would end up with a pretty narrow context tree that would impact lookup time for every context.Value calls.

[bluekeyes]

Thanks. I think I understand the reasoning here, but I'm now confused by the difference between (*Logger) UpdateContext and (Logger) WithContext. It seems that UpdateContext also achieves what you describe (fields visible to parent middleware, no new context), so is there a reason to use WithContext instead of calling zerolog.Ctx(ctx).UpdateContext(...) in places that want this behavior?

To give a more concrete example, I have an application that responds to a GitHub webhook and performs an action on every open pull request in the repository. In the handler, I loop over the open PRs and call updatePullRequest(context.Context, *github.PullRequest). This does some logging of its own (and may call other functions that log), so I want to attach the PR number that is being processed to the logger in the context that I pass.

In your view, is it better to pass the modified logger explicitly as an argument or re-add the necessary fields at each level instead of passing a modified context?

[rs]

The (*Logger) UpdateContext will update the context of the logger with no copy of the logger (in place). If the (Logger) WithContext was just storing the pointer without trying to reuse the existing one, it would store the same pointer over and over in the context for each call of WithContext.

What I can do though, is only updating the existing pointer if the currently stored logger is the same as the one you are trying to store. This way, if you copy the logger instead of calling WithContext, it will behave the way you expect.

[rs]

Please review #81.