-
Notifications
You must be signed in to change notification settings - Fork 17.6k
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
log/slog: make the current context easily available to loggers #58243
Comments
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 I much prefer the ergonomics of using the |
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. |
Thanks for opening this issue @jba If I understand your proposal correctly you suggest that the |
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 |
In order to aid in propagating things like type Handler interface {
....
WithContext(ctx context.Context) context.Context
} and then 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
} |
@stephenafamo, @icholy: one advantage of passing the logger around is the ability to use
which may preformat some attributes (depending on the handler; the built-in ones do). That can result in a big speedup. |
@jba I don't know the internals of slog, so I need to clarify: In a hypothetical HTTP server, are you saying:
|
@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? |
@seankhliao, you're right about both of those points. The mutating implementation is not a good idea. |
Thanks for as always a clear description of the problem @jba.
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 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 As long as there are methods like 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 Code review as a sanity check will always be helpful (and could, for example, check that people use I also am a fan of renaming WithContext to Ctx! |
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 This would be different from other |
@komuw, we want WithContext to be very fast, so we don't want to clone anything. We want people to be able to write |
@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:
The common attrs will be formatted on each call. If instead you wrote:
then the common attrs would be formatted only once, in the |
@jba |
@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. |
This comment was marked as resolved.
This comment was marked as resolved.
@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. |
Thinking about this issue a little more.
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 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. |
Personally, I like 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 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 Since a context may not always be present (eg. in That leaves |
This comment was marked as resolved.
This comment was marked as resolved.
Thanks for splitting this up and a whole write-up @jba!
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 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:
|
I have a suggestion. Let the output methods treat To do this, the slog package will define an internal context key whose values are a slice of 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. I believe this hits all the goals.
|
@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 We could keep the second idea but not the first by just putting the You can get the same effect in slog now by wrapping the context in a LogValuer, though it's more cumbersome to use:
|
I think similar to 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))
Records only have one context, what of if the output function is used with multiple contexts. 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?
Exactly the problem. While the ingredients already exist, it is quite cumbersome to log values in the context. |
@stephenafamo As far as multiple contexts appearing in a
Forgetting 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 |
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:
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:
I personally think that instead of increasing allocations with 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
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 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
Am curious what people think. |
@stephenafamo, our view is that |
@jba I thought that I am not suggesting
Perhaps it is better to have this discussion on the original issue instead of here 🤔 |
@AndrewHarrisSPU, that is a recent change, to make invocations of
Right now, never. Unless the Handler does it. Are you assuming some change to slog?
Nothing in slog right now will pull that LogValuer out of the context. Can you elaborate on how this works? |
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 |
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 In terms of slogging configuration, this defines a Relative to this PoC, I think the common/open store (one context key or lookup function that |
This discussion has been extremely helpful. See my comment on the proposal issue for how I think we should proceed. |
Why the LogDepth function is not exported in the new version Does custom calldepth not work properly @jba |
@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
Hello! I can't handle such huge discussion (not native speaker), but I see references on |
@lictw If you want your handler to get values out of a context, you will have to call it with |
|
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. |
But, @jba, if you delete and |
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. |
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. |
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 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:
|
@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. |
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!")
} |
@yysushi You don't apply the groups from |
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
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
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:
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:but programmers are likely to prefer the shorter
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 likeSo 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:FromContext
would extract it:Callers would still have to write
but we also included a convenience function,
Ctx
, that combinedFromContext
andWithContext
: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 thanslog.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: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
andCtx
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
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:
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:
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 toCtx
:Another variant of this idea is an adapter type, like @jellevandenhooff’s slogctx package. You would then write
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:
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 thatlogger.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 callingspan.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: