log/slog: make the current context easily available to loggers #58243

jba · 2023-02-02T13:09:44Z

This issue assumes that the slog proposal will be accepted.

Background

Adding dynamically scoped information to log output greatly aids debugging: it allows logs to be grouped by server request, and gives readers valuable clues about what was happening along the control flow path that led to the log event. One important piece of information is the trace ID, which is added to the context by tracing systems like OpenTelemetry to construct tracing graphs, a valuable performance and debugging tool. If a log event contains a trace ID, it can be used to annotate the trace in the graph, making it easier to see what was going on in the trace. We’ll focus on the trace ID in this issue for concreteness, but whatever solution emerges from this discussion should work for any value in a context.Context.

In OpenTelemetry, trace IDs are contained in spans. A trace is started with a call like

ctx, span := trace.Start(ctx, name, ...)

That call starts a new span, makes it a child of the currently active span (if any), and returns a context containing the span as well as the span itself. It is typically followed by

defer span.End()

which ends the trace. In a server, a typical trace will be an entire request, but nested traces can be established anywhere along the call chain.

The problem

The goal of this issue is to find a good way to convey the context to a slog.Logger, and ultimately to a slog.Handler, so the trace ID and other context values can appear in the output. We’ll assume the programmer has already arranged to pass the context itself around, so that all logging occurs inside a function with a context:

func f(ctx context.Context, ...) {

How can we encourage the programmer to include the context in their logging statements?

The key word here is encourage. The slog package already has a way to include the context:

logger.WithContext(ctx).Info(msg)

but programmers are likely to prefer the shorter

logger.Info(msg)

We also need to consider the related problem of how the logger itself is passed around. Although slog has a global logger, that logger will not have attributes that may have been added along the call chain with lines like

logger = logger.With("key", "value")

So programs that care about dynamically scoped data will have to pass the logger down the stack along with the context.

Loggers in contexts

slog's original solution to this problem was to include the logger itself in the context. NewContext would add the logger to the context:

ctx = slog.NewContext(ctx, logger)

FromContext would extract it:

logger := slog.FromContext(ctx)

Callers would still have to write

logger.WithContext(ctx).Info(msg)

but we also included a convenience function, Ctx, that combined FromContext and WithContext:

slog.Ctx(ctx).Info(msg)

Before we reject this solution and look elsewhere, let’s see what’s good about it. It simplifies the code, because instead of passing around both a context and logger, only the context needs to be passed. And it encourages programmers to include the context in their log output, because slog.Ctx(ctx) is a more compact way to obtain a logger than slog.FromContext(ctx).

The author of a tracing system could make it even more likely that log output would contain trace IDs, by modifying the Start method that adds a span to a context. That code could also add the trace ID to the logger in the context:

func Start(ctx context.Context, ...) (context.Context, Span) {
    ...
    logger := slog.FromContext(ctx)
    logger = logger.With("traceID", traceID)
    return slog.NewContext(ctx, logger), span
}

Now the trace information would be logged as long as the programmer retrieved the logger from the context.

Controversy

Some comments on the proposal issue were in favor of including a logger in a context: @v3n, @rliebz, @darkfeline, @neild @dottedmag, @tigrannajaryan 1, 2, 3, @Aneurysm9.

But others were strongly against it: @prochac 1, 2, 3, @mminklet 1, 2, 3, @rabbit, @jellevandenhooff, @ChrisHines.

The main objection is that putting a logger in a context creates a hidden dependency. When you call a function that takes a context, you don’t know whether the context is for logging, cancellation, or both. Context arguments are added to functions just to allow logging. The objectors understand that adding loggers to contexts might make sense for some applications, but oppose adding it to the standard library for fear of creating a precedent that will lead to widespread abuse of contexts.

Because of these concerns, we removed NewContext, FromContext and Ctx from the proposal. So to obtain a logger that may contain dynamically scoped information, a function must take it as an argument somehow, either directly or as a part of another argument, like a receiver field.

Alternatives

If we don’t add loggers to contexts, then how can we encourage programmers to pass contexts to loggers?

We could do nothing to the API, but educate users to write

logger = logger.WithContext(ctx)

at the top of their functions. This might not seem much different than remembering to write logger := slog.FromContext(ctx), but note that previously, FromContext was the only reasonable way to get a logger with dynamic content. Now we assume a logger is already available to the function, so nothing pushes the programmer towards adding the context to it.

Another popular idea is to require each log output method to take a context:

func (*Logger) Info(ctx context.Context, message string, ...)
...

We don’t want to do that, because it goes too far in the other direction, forcing programmers to pass in a context (or at least consider doing so) for every log message.

A related idea is to add context-aware functions to the ones already present:

func (*Logger) Info(message string, ...) // already in the proposal
func (*Logger) InfoCtx(ctx context.Context, message string, ...)
...

We also don’t want to do that, because it greatly increases the size of the API. It’s also not much different from the existing WithContext method, especially if we shortened the name to Ctx:

logger.InfoCtx(ctx, "message")
logger.Ctx(ctx).Info("message")

Another variant of this idea is an adapter type, like @jellevandenhooff’s slogctx package. You would then write

clogger := slogctx.NewLogger(logger)
...
clogger.Info(ctx, "message")

All of these solutions require work in the function doing the logging. What if we could move that work up the call stack? The caller could add the context to the logger whenever the context changed:

// Add a span to the context.
ctx, span := tracer.Start(ctx, ...)
defer span.End()
// Add the context to a logger.
logger = logger.WithContext(ctx)
// Pass the logger down.
f(ctx, logger)

Now f can use the logger directly and still get trace IDs in the output. Since context changes occur relatively infrequently, this convention should reduce the total amount of programmer toil. More importantly, it puts the responsibility in the hands of the programmer who understands the importance of tracing, and how trace IDs are propagated through contexts.

But we can do even better by using an idea first suggested on the proposal issue by @rabbit. If we are willing to mutate a part of the context, we can avoid having to repeatedly incorporate the context into the logger. I sketched an implementation for OpenTelemetry that associates a list of spans with a context key. Starting a new span appends it to the list, and ending a span removes it from the list. Once a logger contains a context with the list, it can be used repeatedly. That means that logger.WithContext needs to be called only for the top-level span. Starting a nested span can be done without updating the logger, since doing so mutates (a part of) the context that the logger already contains.

There is one difference in behavior between the purely functional implementation of adding spans to contexts and the mutating one: if a context is discarded (as by function return) without calling span.End, the functional implementation will drop the span while the mutating one will not. I’m not sure if that’s a bug or a feature.

[Edit: mutating the list of spans in the context does the wrong thing if spans don't follow a stack discipline. It is not recommended for general use.]

Do any of these alternatives adequately ensure that most log events contain trace information? Are there other ideas I’ve missed? Is there anything we can add to or change about slog to help?

The text was updated successfully, but these errors were encountered:

stephenafamo · 2023-02-02T15:19:36Z

While this can work, I personally don't like it because it makes the logger a "request scoped dependency" when it is only a few values in the context that should be.

For example, when writing a web service, I will often have a struct that look like

type Server struct {
    DB     store.DB
    Logger log.Logger // whichever log package I'm using
    // Other dependencies
}

func (s Server) Users(w http.ResponseWriter, r *http.Request) error {
    // .....
    // If I need to log, I will use it like this
    s.Logger.Log(...)
}

With your suggestion, a logger will have to be created at the top of the request tree and passed down.

This means that aside from the context, every function that needs to log also needs to accept a logger since setting it as a one-time dependency is no longer possible.

Personally, I think this is even more cumbersome than doing s.Logger.WithContext(ctx).Log(...).

I much prefer the ergonomics of using the slogctx wrapper and will probably use that (or something else) in cases where I need the context for logging. Which is why I think it will be useful to include it as part of the standard package (or a sub package).

icholy · 2023-02-02T16:02:04Z

What if, instead of passing the whole logger in the context, we only pass the attributes? Then the handler can include them the same way it includes the span info.

tigrannajaryan · 2023-02-02T19:25:34Z

How can we encourage the programmer to include the context in their logging statements?
The key word here is encourage.

Thanks for opening this issue @jba

If I understand your proposal correctly you suggest that the Logger is passed as a parameter to every function that needs to log. Can you please clarify how we will encourage the programmer to accept the Logger as a parameter? Is documentation going to recommend that the Logger is never stored in a struct and is always passed as a parameter, like we already do for Context?

seankhliao · 2023-02-02T19:34:29Z

I don't think spanList will work correctly in the presence of parallel goroutines?

2 goroutines starting their own spans, spun up in parallel from the same parent, will attempt to modify the same list and one of them will be associated with the wrong span.

Additionally, I don't believe we require Handlers to process synchronously, if it delays processing, by the time it gets round to extracting the traceID/spanID (span name in your example), the list may have changed (span ended, new span appended) and the extracted IDs would be wrong

komuw · 2023-02-03T19:31:55Z

slog.Logger has three With* methods; WithGroup, With, WithContext.
Of the three, two of them(WithGroup, & With) call underlying methods on the handler: https://github.com/golang/exp/blob/98cc5a0785f9389a91393b250df90a27725107fc/slog/logger.go#L103-L115
WithContext is the odd one out, it doesn't call any method on the handler.

In order to aid in propagating things like traceID/spanID, I think it would be worthwhile for WithContext to call some underlying handler method.
Assume we expanded the handler interface

type Handler interface {
        .... 
	WithContext(ctx context.Context) context.Context
}

and then logger.WithContext becomes;

func (l *Logger) WithContext(ctx context.Context) *Logger {
	c := l.clone()
	c.ctx = l.handler.WithContext(ctx)
	return c
}

This would enable people to write custom handlers that do things like;

type customHandler struct{ traceID string}
func (c customHandler) WithContext(ctx context.Context) context.Context {
    if vCtx := ctx.Value(myTraceIdCtxKey); vCtx == nil {
       // we got an un-annotated context, let's add traceID to it
       ctx = context.WithValue(ctx, myTraceIdCtxKey, c.traceID)
   }

  return ctx
}

jba · 2023-02-03T20:24:59Z

@stephenafamo, @icholy: one advantage of passing the logger around is the ability to use

logger = logger.With(...)

which may preformat some attributes (depending on the handler; the built-in ones do). That can result in a big speedup.

stephenafamo · 2023-02-03T20:35:11Z

@jba I don't know the internals of slog, so I need to clarify:

In a hypothetical HTTP server, are you saying:

Create a logger for each request and pass it down
May be more performant than
Have a single instance of the logger as a dependency

jba · 2023-02-03T20:35:17Z

If I understand your proposal correctly you suggest that the Logger is passed as a parameter to every function that needs to log. Can you please clarify how we will encourage the programmer to accept the Logger as a parameter? Is documentation going to recommend that the Logger is never stored in a struct and is always passed as a parameter, like we already do for Context?

@tigrannajaryan, I don't have a proposal here. Personally, I think it's fine to put a logger in a context, but we've heard enough serious, thoughtful disagreement about it to start a new issue to consider alternatives. I am hoping to hear from some of the people who don't like loggers in contexts, like @prochac, @mminklet, and others, how they provide access to loggers. @ChrisHines, you wrote "We felt the practice of passing loggers in contexts was harmful enough that we are now undergoing an effort to eliminate it from our code base." What are you doing instead?

jba · 2023-02-03T20:36:09Z

@seankhliao, you're right about both of those points. The mutating implementation is not a good idea.

jellevandenhooff · 2023-02-03T23:13:38Z

Thanks for as always a clear description of the problem @jba.

How can we encourage the programmer to include the context in their logging statements?

I think the answer to this question comes down to some process demanding the programmer includes a context. This could be API-enforcement (like the originally proposed slog.Ctx, or my experimental slogctx.Info), code review, or a linter. I think all are perfectly valid approaches. The more automated and the faster the feedback the more pleasant the experience will be, so I think API-enforcement is preferable over a linter and a linter is preferable over code review.

API-enforcement is tricky because as you describe slog should also work when there is no context available. So making all calls require a context across the board is not an option. In some cases a different API might be helpful and solve the problem. If a program decides to pass a logger in the context, then a getter like the originally proposed slog.Ctx could set a context on the logger as well. An alternative is a wrapper like my slogctx experiment which has a required context argument (and here is a slightly larger example).

As long as there are methods like slog.Info and slog.Default, though, it will always be possible to sidestep the context requirement in an API. Then again, programmers could also go back to log.Println or os.Stderr.Write.

If API is not an option (if you don't want to use a wrapper and don't want to pass around the logger in the context) a linter would be functional and I think quite doable. The linter could detect calls to slog in any function that a context.Context argument (or even a http.Request which has a context on it) and flag logging calls without a matching WithContext calls. With some flow analysis to detect local variables it could even support a single logger := s.logger.WithContext at the start of a function. I think this would be a valuable tool and catch most if not all misuses. The linter can also play double duty and ensure that all logging calls format their key-value attribute arguments pairs appropriately.

Code review as a sanity check will always be helpful (and could, for example, check that people use slog.Ctx or a struct-provided logger instead the global slog.Info. However, because a linter should work, I think relying on code review is not necessary.

I also am a fan of renaming WithContext to Ctx!

AndrewHarrisSPU · 2023-02-05T00:10:44Z

@seankhliao, you're right about both of those points. The mutating implementation is not a good idea.

I found the direction suggested by this mutating implementation appealing, at least. A more narrowly tailored API for managing data that should be logged and should live on a context (as opposed to data that shouldn't be logged but should live on a context, or data that should be logged but shouldn't live on a context) seems useful.

Eventually I wonder if this is related to the third point of #56345 (comment), about when a LogValuer is evaluated. Would it make sense to similarly define when, for a given Record, all observations drawn from a context are evaluated? Along the lines of: invariantly, the first Handler a Record passes through after being created should traverse the Record, evaluate and add attributes based on observing the context. The invariant could be isolated in a Handler that just performs context-related evaluation, or it could be folded into a Handler that does more.

This would be different from other Handlers because it would need to maintain a list of keys to look up. This kind of a handler would have additional behavior and state, like having a WithContextKey in addition to WithGroup and WithAttrs (although a WithContextKey wouldn't be eagerly rendering formatted/encoded text.) But, because this is a proper subtype relationship and a Handler is an interface, we could pass it as a vanilla Handler - it would just be no-ops when there is no context or no keys. This makes sense if only the context given at the time of creating a Record matters and I'm not sure that's true, I just don't see why it wouldn't be.

jba · 2023-02-05T15:02:46Z

@komuw, we want WithContext to be very fast, so we don't want to clone anything. We want people to be able to write logger.WithContext(ctx).Info(msg).

jba · 2023-02-05T15:12:38Z

In a hypothetical HTTP server, are you saying:

Create a logger for each request and pass it down
May be more performant than

Have a single instance of the logger as a dependency

@stephenafamo: Yes, if there are attributes that are common along a call chain.

If you have a fixed logger, you have to add those common attributes in each log call:

func (s *Server) handle(...) {
    commonAttrs := []slog.Attr{...}
    s.part1(commonAttrs)
    s.part2(commonAttrs)
}

func (s *Server) part1(as []slog.Attr) { s.logger.Info(msg, slog.String("func", "part1"), as...) }
func (s *Server) part1(as []slog.Attr) { s.logger.Info(msg, slog.String("func", "part2"), as...) }

The common attrs will be formatted on each call.

If instead you wrote:

func (s *Server) handle(...) {
    logger := s.logger.With(commonAttrs...)
    s.part1(logger)
    s.part2(logger)
}

func (s *Server) part1(l *slog.Logger) { l.Info(msg, slog.String("func", "part1")) }
func (s *Server) part1(l *slog.Logger) { l.Info(msg, slog.String("func", "part2")) }

then the common attrs would be formatted only once, in the logger.With call. (That is true for the built-in handlers, and for any Handler that does a good job of implementing WithAttrs.)

komuw · 2023-02-05T19:20:37Z

@komuw, we want WithContext to be very fast, so we don't want to clone anything. We want people to be able to write logger.WithContext(ctx).Info(msg).

@jba WithContext already clones: https://github.com/golang/exp/blob/98cc5a0785f9389a91393b250df90a27725107fc/slog/logger.go#L123-L124, unless you meant something else.

jba · 2023-02-06T01:39:40Z

@komuw, you're right, it clones the Logger. I was thinking of cloning the Handler. That is typically expensive, but as your example shows, it may not be necessary.

However, I don't really understand your example. Can you give a practical application of Handler.WithContext? Maybe you've given one, but I don't see how the traceID field on your handler gets set.

komuw · 2023-02-06T07:28:13Z

@komuw,
However, I don't really understand your example. Can you give a practical application of Handler.WithContext? Maybe you've given one, but I don't see how the traceID field on your handler gets set.

@jba I took sometime to try and sketch out an implementation and it didn't work out as I had hoped. I take back my suggestion.

komuw · 2023-02-06T07:42:56Z

Thinking about this issue a little more.
It asks two questions;

How can we encourage the programmer to include the context in their logging statements?

I think the answer to this question is easy if you paraphrase the question as follows; How can we encourage the programmer to include the context in their function calls?
The net/http package has two general ways to create a request; NewRequest() & NewRequestWithContext(). How do we normally encourage people to use the latter over the former?
The answer to that is also the answer to the previous question about logging and contexts.

How is the logger itself passed around? Although slog has a global logger ....

The answer to this is; either remove the global logger or document that whoever chooses to use the global logger is opting into that behaviour.

All in all, I feel like the solutions to these questions are; documentation, custom style guides & custom linters.

sagikazarmark · 2023-02-06T11:40:06Z

Personally, I like logger := s.logger.WithContext(ctx) where s is the receiver of a method on a service struct. I generally inject loggers as dependencies to my services and call WithContext whenever I need it.

I wholeheartedly agree with the "hidden dependency" argument.

While I think having a single, idiomatic way to solve a problem is better, having an alternate wrapper around the logger that exposes logger.Info(ctx, ...) methods as a syntactic sugar calling logger.WithContext under the hood is fine IMO.

Lastly, I think the question that needs answering is who is the intended target of any of the solutions being discussed here. Most applications that I consider well-architected have some sort of separate service layer from the transport (HTTP, gRPC, etc) and the first parameter passed to those services is always the context. People who has the discipline to build applications like that will probably use logger.WithContext if it's available and will probably prefer a single solution.

Since a context may not always be present (eg. in main), I'd prefer always writing logger.Info(...) compared to switching between that and logger.Info(ctx, ...) or logger.InfoCtx(ctx, ...).

That leaves logger.WithContext as the winner in my eyes.

rabbbit · 2023-02-07T09:54:18Z

Thanks for splitting this up and a whole write-up @jba!

The author of a tracing system could make it even more likely that log output would contain trace IDs, by modifying the Start method that adds a span to a context. That code could also add the trace ID to the logger in the context:
func Start(ctx context.Context, ...) (context.Context, Span) {
    ...
    logger := slog.FromContext(ctx)
    logger = logger.With("traceID", traceID)
    return slog.NewContext(ctx, logger), span
}
Now the trace information would be logged as long as the programmer retrieved the logger from the context.

This could be perhaps the root of our "disagreement" - the code above would not work in the "style" I, and at least some parts of my corporation, tend to use loggers - loggers are persistent/long-lived/with extra-meta data. Thus to achieve ^ we'd need some kind of "Merge" function that takes two loggers - the long-lived & the per-request part. The same problem applies to logger.WithContext though.

I see how I'm biased/non-representative here, but if we were to assume that loggers are long-lived and contexts carry "...request-scoped values across API boundaries and between processes" then loggers would need to take contexts as any other argument. (I'm personally okay with simply enforcing ctx being present).

Some more random thoughts:

the mutable context idea is indeed not used for spans (and goroutines) but for context back propagation. This is super useful for other reasons (reducing log noise), might not work best here.
we talk about spans/tracing here, but we have plenty of other metadata that we attach to per-request logging too. That data is sometimes, but not always, part of the tracing baggage.
- in this context, I don't right now fully see how logger.WithContext would know which values from context to log. This would mean some global registration of "known context keys", which seems messy.
tangential: we had some internal linting against spurious use of logger.With(... for loggers that were then not logging anything. This turned out to be surprisingly costly for some applications.

stephenafamo · 2023-02-07T13:15:05Z

I have a suggestion. Let the output methods treat context.Context as a special case.

To do this, the slog package will define an internal context key whose values are a slice of slog.Attr. If one of the args given is a context.Context, the output method will retrieve the attached attributes on the context key and append them to the log message.

The slog package can then also include some helper methods to append attributes to this key.

type ctxKey string
const ctxAttrs ctxkey = "attributes"

func AddToContext(ctx context.Context, attrs ...Attr) {
    existing, _ := ctx.Value(ctxAttrs).([]Attr)
    return context.WithValue(ctx, append(existing, attrs...))
}

Using it with open telemetry may then happen like this:

func (s *server) aFunction(ctx context.Context) {
    // the otel package can include the traceID and spanID in the context
    // when creating the new span
    span, ctx := s.tracer.Start(ctx, "span_name") 
    
    // ...... 

    s.Logger.Info("somthing happened", ctx, slog.Int("status", 500))
}

As a bonus, I think this will also remove the need for the awkward context on log records since any values meant to be passed to that record would have been evaluated by the output method.
Logger.WithContext() on the logger may also not be needed anymore since Logger.With() will work as expected with a context argument.

I believe this hits all the goals.

It does not require using a context everywhere
When we do want to use a context, it is very easy to do so since we don't have to resolve the keys and values manually
Things that modify the context, like middlewares or telemetry can add attributes to the context and pass it down. It will also be evaluated once when it is added to the context, not every time a downstream log message is emitted.

jba · 2023-02-07T14:17:00Z

@stephenafamo, nice idea. It does make it a little easier for people to put the context in their logs, but at the cost of adding another special case to key-value args. Also, what would we do for LogAttrs?

We could keep the second idea but not the first by just putting the ctx arg into Record.Context.

You can get the same effect in slog now by wrapping the context in a LogValuer, though it's more cumbersome to use:

type contextLogValuer struct {
	ctx context.Context
}

func (v contextLogValuer) LogValue() slog.Value {
	attrs, _ := v.ctx.Value(ctxAttrs).([]slog.Attr)
	return slog.GroupValue(attrs...)
}

func ContextAttrs(ctx context.Context) slog.LogValuer { return contextLogValuer{ctx} }

func f(ctx context.Context) {
    logger.Info("msg", "", ContextAttrs(ctx), ...)
}

stephenafamo · 2023-02-07T21:34:23Z

@stephenafamo, nice idea. It does make it a little easier for people to put the context in their logs, but at the cost of adding another special case to key-value args. Also, what would we do for LogAttrs?

I think similar to AddToContext, the slog package should include an ContextAttrs function.

func ContextAttrs(ctx context.Context) slog.Attr {
	attrs, _ := v.ctx.Value(ctxAttrs).([]slog.Attr)
        // I'm not sure how slog treats empty group keys. I assume they are flattened
	return slog.Group("", attrs...) 
}

// Then it can be used with LogAttrs like this
slog.Info(msg, slog.ContextAttrs(ctx), slog.Bool("done", true))

We could keep the second idea but not the first by just putting the ctx arg into Record.Context.
.

Records only have one context, what of if the output function is used with multiple contexts. slog.Info("", ctx1, ctx2, ctx3).
Of course, this is not expected, but we would have to decide what happens in such a scenario.

Additionally, if the context is only used to pass request scoped log attributes, for what other reason will the record need to include the context?
Perhaps treating the context as an "Attr carrier" allows us to remove the antipattern of including a context as part of the struct.

You can get the same effect in slog now by wrapping the context in a LogValuer, though it's more cumbersome to use:

type contextLogValuer struct {
	ctx context.Context
}

func (v contextLogValuer) LogValue() slog.Value {
	attrs, _ := v.ctx.Value(ctxAttrs).([]slog.Attr)
	return slog.GroupValue(attrs...)
}

func ContextAttrs(ctx context.Context) slog.LogValuer { return contextLogValuer{ctx} }

func f(ctx context.Context) {
    logger.Info("msg", "", ContextAttrs(ctx), ...)
}

Exactly the problem. While the ingredients already exist, it is quite cumbersome to log values in the context.
I believe this discussion is to find a way to make that easier.

AndrewHarrisSPU · 2023-02-07T23:39:06Z

@stephenafamo
I like the idea of having one symbol in the context holding a segment or table of loggable values. To play nicely, middleware should prefer AddToContext, ContextAttrs, while end users should prefer middleware-provided API, is this the idea?

As far as multiple contexts appearing in a Record ... I feel like the all the smaller problems are significantly easier to reason about if there's at least a documented understanding of a 1:1 Record/Context approach, and anything trickier is off the map (ContextAttrs would be a useful escape hatch, I guess)

@jba

If we don’t add loggers to contexts, then how can we encourage programmers to pass contexts to loggers?

Forgetting WithContext in a line like log.WithContext(ctx).Info("...") seems easy to do. Also, it might not be just "forgetting" ... sometimes it might be hard to reason locally about whether a logger is expecting to be handed a context, or whether it already has one that shouldn't be overwritten. A way to change nothing but suggest an optional style:

func call(ctx context.Context, log func(context.Context) *slog.Logger){
    ...
    log(ctx).Info("...")
    ...
}

func main() {
    ...
    call(ctx, log.WithContext)
    ...
}

The "change something" approach might be:

type Pretext func(context.Context) *Logger

func (l *Logger) Pretext() Pretext {
    // mostly the same implementation as `WithContext`
}

func call(ctx context.Context, log slog.Pretext) { ... }

func main() {
    ...
    call(ctx, log.Pretext())

There are other definitions of Pretext (e.g., type Pretext *slog.Logger) that could work, the idea would be to mask the logger output methods until a later caller has provided a context.

xorkevin · 2023-02-09T20:58:53Z

Hi all! I'm relatively new to participating in forums like this, though I've been using go a long time and care a lot so thought to contribute to the discussion here.

@jba Thanks for being so open to feedback on this! Highly agreed with the concerns that we should not prefer to pass dependencies implicitly.

@stephenafamo, I like a lot of the ideas you're proposing here! I agree that instead of passing loggers implicitly in contexts, we should instead prefer something similar to what you wrote:

type Server struct {
    Logger log.Logger // whichever log package I'm using
    // Other dependencies
}
func (s Server) Users(w http.ResponseWriter, r *http.Request) error {
    // .....
    s.Logger.Log(...)
}

There are a few places where I differ in opinion slightly though.

First is more of an implementation detail, but nevertheless something I think is worth calling out. With regards to the following:

func AddToContext(ctx context.Context, attrs ...Attr) {
    existing, _ := ctx.Value(ctxAttrs).([]Attr)
    return context.WithValue(ctx, append(existing, attrs...))
}

I personally think that instead of increasing allocations with append, I would prefer to keep a pointer to the previous group of attributes, with something like the following (with names up for debate):

https://github.com/xorkevin/klog/blob/140a79471414b705ceefc0e9e431ed8b6650ffe6/klog.go#L271 (a toy logger I've been experimenting with that is not intended for production use yet)

type (
	ctxKeyAttrs struct{}

	ctxAttrs struct {
		attrs  Attr[]
		parent *ctxAttrs
	}
)

func getCtxAttrs(ctx context.Context) *ctxAttrs {
	if ctx == nil {
		return nil
	}
	v := ctx.Value(ctxKeyAttrs{})
	if v == nil {
		return nil
	}
	return v.(*ctxAttrs)
}

func setCtxAttrs(ctx context.Context, fields *ctxAttrs) context.Context {
	return context.WithValue(ctx, ctxKeyAttrs{}, fields)
}

// CtxWithAttrs adds log attrs to context
func CtxWithAttrs(ctx context.Context, attrs ...Attr) context.Context {
	return ExtendCtx(ctx, ctx, attrs...)
}

// ExtendCtx adds log attrs to context
func ExtendCtx(dest, ctx context.Context, attrs ...Attr) context.Context {
	k := &ctxAttrs{
		parent: getCtxAttrs(ctx),
	}
	k.attrs.addAttrs(attrs)
	return setCtxAttrs(dest, k)
}

A log handler may then optionally choose to perform some deduplication if an attribute on a "child" context has the same key as one of its "ancestors".

Next, I agree with the concerns @jba raised here with regards to treating ctx in args ...any differently:

@stephenafamo, nice idea. It does make it a little easier for people to put the context in their logs, but at the cost of adding another special case to key-value args. Also, what would we do for LogAttrs?

I'm currently of the opinion that the handler should be the only "thing" that concerns itself with what values are in a context. For example, with the above ctxAttrs example of mine, I would likely want to write a handler wrapping an slog.Handler which has the responsibility of reading from the context similar to the approach that @jellevandenhooff in slogctx takes (again names up for debate):

type CtxReadingHandler struct {
	inner Handler
}

// implementation of other Handler interface methods

func (h *CtxReadingHandler) Handle(r Record) error {
	for a := getCtxAttrs(r.Context); a != nil; a = a.parent {
		r.AddAttrs(a.attrs...)
	}
	return h.inner.Handle(r)
}

In my view, this also has the added benefit of extending to the "opentelemetry span" use-case quite nicely, because libraries can choose to provide their own wrapping handlers such as:

type OpenTelemetryLogHandler struct {
	inner slog.Handler
}

// implementation of other Handler interface methods

func (h *OpenTelemetryLogHandler) Handle(r slog.Record) error {
	if a := getOpenTelemetryLogAttrs(r.Context); a != nil {
		r.AddAttrs(a...)
	}
	return h.inner.Handle(r)
}

With that in mind, I think either of the following as listed by @jba in the alternatives is preferrable since it does not require the frontend Logger to "know" anything about the context:

logger.InfoCtx(ctx, "message")
logger.Ctx(ctx).Info("message")

Am curious what people think.

stephenafamo · 2023-02-15T06:08:41Z

@AndrewHarrisSPU I struggle to think of a scenario where a static context on the logger will be useful beyond setting static attributes. Please help me understand 🙏🏾

Also, a similar effect can be achieved by doing:

var logger slog.Logger // an existing logger we want to add a static context to
logger = logger.With(slog.Context(ctx)) // added like any other static attribute to the logger

@jba I just noticed that logger.With() takes ...any. While I understand making usage less verbose by having Debug|Warn|Info|Error take key-value pairs, does logger.With have to be the same? I think it would be better to change it to logger.With(...Attr)

AndrewHarrisSPU · 2023-02-15T08:12:02Z

@AndrewHarrisSPU I struggle to think of a scenario where a static context on the logger will be useful beyond setting static attributes. Please help me understand 🙏🏾

I am reviewing LogValuer-related changes in the slog repo to check my assumptions, as the details are in flux and subtle, but ... a subtle implementation detail that I find very interesting is that Records resolve LogValuers when they are added with Record.AddAttrs.

An open question, if adding a LogValuer to a context, when is it resolved? I think at Record time or sort of immediately after is what I might anticipate, at least. If this is the case, one succinct way to define something that gets freshly evaluated each time it's expanded in a Record:

type LogThunk func() slog.Value

func (fn LogThunk) LogValue() slog.Value {
    return fn()
}

One result of pulling a trick like this is, if I store the context instrumented with the LogValuer in the Logger, and pass the Logger to context-unaware API, I still get a dynamic evaluation of the LogValuer each time the context-unaware API logs. It's not ideal, but it's not nothing.

jba · 2023-02-15T08:48:30Z

While I understand making usage less verbose by having Debug|Warn|Info|Error take key-value pairs, does logger.With have to be the same? I think it would be better to change it to logger.With(...Attr)

@stephenafamo, our view is that ...any is the norm; this is the everyday form that most people will use. LogAttrs is an optimization. Optimizing Logger.With isn't as important because we don't expect it to be called as frequently as a log output method.

stephenafamo · 2023-02-15T08:55:12Z

@stephenafamo, our view is that ...any is the norm; this is the everyday form that most people will use. LogAttrs is an optimization. Optimizing Logger.With isn't as important because we don't expect it to be called as frequently as a log output method.

@jba I thought that ...any while the norm, is for convenience.

I am not suggesting ...Attr for optimization, but rather for correctness. As you've said, Logger.With will not be called frequently, so wouldn't it be better to strive for correctness?

No need for "!BADKEY"
No need for treating special cases
No need for special formatting for readability

Perhaps it is better to have this discussion on the original issue instead of here 🤔

jba · 2023-02-15T11:29:37Z

Records resolve LogValuers when they are added with Record.AddAttrs.

@AndrewHarrisSPU, that is a recent change, to make invocations of LogValue more predictable.

An open question, if adding a LogValuer to a context, when is it resolved?

Right now, never. Unless the Handler does it. Are you assuming some change to slog?

if I store the context instrumented with the LogValuer in the Logger, and pass the Logger to context-unaware API, I still get a dynamic evaluation of the LogValuer each time the context-unaware API logs.

Nothing in slog right now will pull that LogValuer out of the context. Can you elaborate on how this works?

jba · 2023-02-15T11:32:03Z

Perhaps it is better to have this discussion on the original issue instead of here

Yes, it would be good for posterity if this suggestion was on the proposal issue. However, we've been down this road before and I don't see anything in your argument that would change my view. I don't think any of the negatives you mention are serious problems in practice.

stephenafamo · 2023-02-15T11:34:03Z

Yes, it would be good for posterity if this suggestion was on the proposal issue. However, we've been down this road before and I don't see anything in your argument that would change my view. I don't think any of the negatives you mention are serious problems in practice.

In that case there's no need

AndrewHarrisSPU · 2023-02-15T20:40:53Z

@jba

An open question, if adding a LogValuer to a context, when is it resolved?

Right now, never. Unless the Handler does it. Are you assuming some change to slog?

if I store the context instrumented with the LogValuer in the Logger, and pass the Logger to context-unaware API, I still get a dynamic evaluation of the LogValuer each time the context-unaware API logs.

Nothing in slog right now will pull that LogValuer out of the context. Can you elaborate on how this works?

I was thinking of some change, along the lines of adding the common/open store for attributes @stephenafamo suggested.

Just a quick PoC to demonstrate (confirm to myself, even...) that I can store a LogValuer that is evaluated per-Record: https://go.dev/play/p/P9ScAjzpiR6

In terms of slogging configuration, this defines a Handler that expands attributes found on a context per-Record, and passes a bigger Record to a JSONHandler. The per-instance state that is added to the the Handler chain is, in this PoC, a list of context keys to observe.

Relative to this PoC, I think the common/open store (one context key or lookup function that Handler authors could expect to use, and pull a number of attributes from) is a great idea - it would be a quality of life improvement and maybe a bit more performant. It would remove the need for state related to context keys on Handlers that just wanted to observe an open store.

jba · 2023-02-17T20:50:20Z

This discussion has been extremely helpful. See my comment on the proposal issue for how I think we should proceed.

suiriass · 2023-03-01T10:08:34Z

Why the LogDepth function is not exported in the new version Does custom calldepth not work properly @jba

jba · 2023-03-01T12:13:26Z

@suiriass, because now you can write it yourself: https://go.googlesource.com/exp/+/refs/heads/master/slog/example_depth_test.go#19.

This PR adds a `context.Context` argument to `weaver.Implements`' `Logger` method: ```go Logger(context.Context) *slog.Logger ``` The returned logger automatically adds "traceid" and "spanid" attributes with any OpenTelemetry trace and span ids present in the provided context. >> Alternatives `slog.Logger` already has methods that receive a `context.Context` (e.g., [DebugContext][], [InfoContext][], [ErrorContext][]). We could modify the `slog.Handler` in the logger returned by `Logger` to extract trace and span ids from these contexts. However, if a programmer forgets to pass a context, which seems easy to do, the log entries will not have tracing data. We also considered putting loggers inside of contexts, with a method to extract a logger (and also embed info from the context into the logger), but this [is frowned upon][log_in_ctx]. [DebugContext]: https://pkg.go.dev/golang.org/x/exp/slog#DebugContext [InfoContext]: https://pkg.go.dev/golang.org/x/exp/slog#InfoContext [ErrorContext]: https://pkg.go.dev/golang.org/x/exp/slog#ErrorContext [log_in_ctx]: golang/go#58243

Automatically add trace and span ids to logs. This PR adds a `context.Context` argument to `weaver.Implements`' `Logger` method: ```go Logger(context.Context) *slog.Logger ``` The returned logger automatically adds "traceid" and "spanid" attributes with any OpenTelemetry trace and span ids present in the provided context. ## Alternatives `slog.Logger` already has methods that receive a `context.Context` (e.g., [DebugContext][], [InfoContext][], [ErrorContext][]). We could modify the `slog.Handler` in the logger returned by `Logger` to extract trace and span ids from these contexts. However, if a programmer forgets to pass a context, which seems easy to do, the log entries will not have tracing data. We also considered putting loggers inside of contexts, with a method to extract a logger (and also embed info from the context into the logger), but this [is frowned upon][log_in_ctx]. [DebugContext]: https://pkg.go.dev/golang.org/x/exp/slog#DebugContext [InfoContext]: https://pkg.go.dev/golang.org/x/exp/slog#InfoContext [ErrorContext]: https://pkg.go.dev/golang.org/x/exp/slog#ErrorContext [log_in_ctx]: golang/go#58243

lictw · 2023-08-11T17:18:41Z

Hello! I can't handle such huge discussion (not native speaker), but I see references on slog.Context(ctx) method as an alternative for something, what is it and why I don't see that in 1.21 slog package? Can release slog version log context values out of box?

jba · 2023-08-11T17:39:23Z

@lictw If you want your handler to get values out of a context, you will have to call it with slog.InfoContext instead of slog.Info, and similarly for Debug, Warn and Error. We got rid of slog.Context a while ago.

lictw · 2023-08-11T17:50:49Z

slog.Context was for the same, so just to pass ctx to handler? Or was it method to transform context values into Attrs?

jba · 2023-08-11T18:39:26Z

Yes, it was a way to pass a context to handlers without defining a bunch of methods that took a context (which is what we eventually did anyway).

There is nothing in slog to transform context values into Attrs. I don't think there is a single way to do that which stands out as the best.

lictw · 2023-08-12T20:12:54Z

But, @jba, if you delete and slog.Context, and handler.WithContext in final, now if I want to pass logger into function and I want that logger has the same context (just to logging, context hold something like session_id) I should or pack logger inside context (and it's the only option to pass via single argument), or pass as two arguments, right? Or have a function like ctxToAttrs() []slog.Attrs and pass single logger using logger.With(), but the first: it's what my handler do (extracting), the second: for what now I have logger.*Context methods, I could use logger.Info("", ctxToAttrs(...)), so, miss of handler.WithContext looks very strange..

jba · 2023-08-13T14:48:49Z

I think it's fine to pass the logger in the context. (Many people disagreed, which is why we left it out.)

If there are specific things you want to get from the context, I think you should write a handler to get them, and use the logger.*Context methods. That is easier than calling ctxToAttrs.

lictw · 2023-08-13T17:11:02Z

If there are specific things you want to get from the context, I think you should write a handler to get them, and use the logger.*Context methods. That is easier than calling ctxToAttrs.

So pass and logger, and context into function is fine for you too? (if not to pass logger with context) I see redundancy in this, it's a pity there is no option how to pass a logger/handler with context, so even if child function will just use WithoutContext methods parent context will be available for handler.

muhlemmer · 2023-08-24T19:42:13Z

Now that I've written my own handler that takes data from the context (most importantly a tracing id) and pass it on to a wrapped logger. There is one pitfall:

If logger.WithGroup() is called and the new logger is used with the context, the attributes end up in that group. At the moment of logging there is no obvious way to get back to the parent group / handler. Perhaps I'm missing something:

package main

import (
	"context"
	"log/slog"
	"os"
)

type idHandler struct {
	slog.Handler
}

func (h *idHandler) Handle(ctx context.Context, record slog.Record) error {
	id, ok := ctx.Value(idKey).(int)
	if ok {
		record.AddAttrs(slog.Int("id", id))
	}
	return h.Handler.Handle(ctx, record)
}

func (h *idHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
	return &idHandler{
		Handler: h.Handler.WithAttrs(attrs),
	}
}

func (h *idHandler) WithGroup(name string) slog.Handler {
	return &idHandler{
		Handler: h.Handler.WithGroup(name),
	}
}

type idKeyType struct{}

var idKey idKeyType

func main() {
	logger := slog.New(&idHandler{slog.NewTextHandler(os.Stdout, nil)})

	ctx := context.WithValue(context.TODO(), idKey, 42)

	logger = logger.With("Hello", "World")
	logger.InfoContext(ctx, "lets log!")

	logger = logger.WithGroup("group").With("foo", "bar")
	logger.InfoContext(ctx, "lets log!")
}

Output:

time=2023-08-24T22:34:36.481+03:00 level=INFO msg="lets log!" Hello=World id=42
time=2023-08-24T22:34:36.481+03:00 level=INFO msg="lets log!" Hello=World group.foo=bar group.id=42

id now became part of the group. Same grouping happens with the JSON handler. I don't think that would make it easy to parse and group these logs based on id.

jba · 2023-08-29T09:52:25Z

@muhlemmer that's unfortunate, but that is a consequence of the design. The final handler, or the processor consuming the logs, will have to recognize that attribute specially.

yysushi · 2023-09-01T10:35:00Z

@muhlemmer @jba

how about this one?

package main

import (
	"context"
	"log/slog"
	"os"
)

type idHandler struct {
	slog.Handler
	group string
}

func (h *idHandler) Handle(ctx context.Context, record slog.Record) error {
	id, ok := ctx.Value(idKey).(int)
	if ok && h.group == "" {
		record.AddAttrs(slog.Int("id", id))
	}
	return h.Handler.Handle(ctx, record)
}

func (h *idHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
	if h.group == "" {
		return &idHandler{
			Handler: h.Handler.WithAttrs(attrs),
		}
	}
	var groupedAttrs []slog.Attr
	for _, attr := range attrs {
		groupedAttrs = append(groupedAttrs, slog.Group(h.group, attr))
	}
	return &idHandler{
		Handler: h.Handler.WithAttrs(groupedAttrs),
		group:   h.group,
	}
}

func (h *idHandler) WithGroup(name string) slog.Handler {
	return &idHandler{
		Handler: h,
		group:   name,
	}
}

type idKeyType struct{}

var idKey idKeyType

func main() {
	logger := slog.New(&idHandler{Handler: slog.NewTextHandler(os.Stdout, nil)})

	ctx := context.WithValue(context.TODO(), idKey, 42)

	logger = logger.With("Hello", "World")
	logger.InfoContext(ctx, "lets log!")

	logger = logger.WithGroup("group").With("foo", "bar")
	logger.InfoContext(ctx, "lets log!")
}

jba · 2023-09-07T12:36:52Z

@yysushi You don't apply the groups from WithGroup to the attrs in the Record. But if you did that and then added the "id" attribute, then I think that would work as long as WithGroup is never called on the handler at the end of the chain.

jba self-assigned this Feb 2, 2023

jba added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Feb 2, 2023

thepudds mentioned this issue Feb 2, 2023

log/slog: structured, leveled logging #56345

Closed

This comment was marked as resolved.

Sign in to view

tigrannajaryan mentioned this issue Feb 7, 2023

Decoupling Event API from Logs API open-telemetry/opentelemetry-specification#3167

Closed

jba closed this as completed Mar 1, 2023

This was referenced Mar 25, 2023

Partial update to latest slog ttys3/slogx#9

Merged

a better wrapper ttys3/slogx#10

Open

mwhittaker mentioned this issue Aug 9, 2023

Automatically add trace and span ids to logs. ServiceWeaver/weaver#512

Merged

aelsabbahy mentioned this issue Sep 11, 2023

Added ctx object to all system struct's constructors goss-org/goss#837

Merged

3 tasks

sgielen mentioned this issue Sep 12, 2023

You should implement .With handler's methods cyrusaf/ctxlog#3

Closed

log/slog: make the current context easily available to loggers #58243

log/slog: make the current context easily available to loggers #58243

Comments

jba commented Feb 2, 2023 • edited

Background

The problem

Loggers in contexts

Controversy

Alternatives

stephenafamo commented Feb 2, 2023

icholy commented Feb 2, 2023

tigrannajaryan commented Feb 2, 2023

seankhliao commented Feb 2, 2023

komuw commented Feb 3, 2023

jba commented Feb 3, 2023

stephenafamo commented Feb 3, 2023

jba commented Feb 3, 2023

jba commented Feb 3, 2023

jellevandenhooff commented Feb 3, 2023

AndrewHarrisSPU commented Feb 5, 2023 • edited

jba commented Feb 5, 2023

jba commented Feb 5, 2023

komuw commented Feb 5, 2023

jba commented Feb 6, 2023

This comment was marked as resolved.

komuw commented Feb 6, 2023

komuw commented Feb 6, 2023 • edited

sagikazarmark commented Feb 6, 2023

This comment was marked as resolved.

rabbbit commented Feb 7, 2023 • edited

stephenafamo commented Feb 7, 2023

jba commented Feb 7, 2023

stephenafamo commented Feb 7, 2023

AndrewHarrisSPU commented Feb 7, 2023 • edited

xorkevin commented Feb 9, 2023

stephenafamo commented Feb 15, 2023

AndrewHarrisSPU commented Feb 15, 2023

jba commented Feb 15, 2023

stephenafamo commented Feb 15, 2023

jba commented Feb 15, 2023

jba commented Feb 15, 2023

stephenafamo commented Feb 15, 2023

AndrewHarrisSPU commented Feb 15, 2023

jba commented Feb 17, 2023

suiriass commented Mar 1, 2023

jba commented Mar 1, 2023

lictw commented Aug 11, 2023 • edited

jba commented Aug 11, 2023

lictw commented Aug 11, 2023

jba commented Aug 11, 2023

lictw commented Aug 12, 2023

jba commented Aug 13, 2023

lictw commented Aug 13, 2023 • edited

muhlemmer commented Aug 24, 2023

jba commented Aug 29, 2023

yysushi commented Sep 1, 2023 • edited

jba commented Sep 7, 2023

jba commented Feb 2, 2023 •

edited

AndrewHarrisSPU commented Feb 5, 2023 •

edited

komuw commented Feb 6, 2023 •

edited

rabbbit commented Feb 7, 2023 •

edited

AndrewHarrisSPU commented Feb 7, 2023 •

edited

lictw commented Aug 11, 2023 •

edited

lictw commented Aug 13, 2023 •

edited

yysushi commented Sep 1, 2023 •

edited