log/slog: structured, leveled logging

[jba]

We propose a new package providing structured logging with levels. Structured logging adds key-value pairs to a human-readable output message to enable fast, accurate processing of large amounts of log data.

See the design doc for details.

[jba]

I thought the CLs are publicly visible. What happens when you click that link?

[fsouza]

I thought the CLs are publicly visible. What happens when you click that link?

Sorry when I first commented it was missing the link, my bad

[jba]

I had to submit the issue to get a number to name the design doc to mail the CL. (!)

[mpx]

This is a huge API surface without any real production testing (AIUI). Perhaps it might be better to land it under golang.org/x for some time? Eg, like context, xerrors changes.

[seankhliao]

It's available under golang.org/x/exp/slog

[mpx]

It's available under golang.org/x/exp/slog

True, but it is unlikely to see much production testing under exp.

[deefdragon]

I love most of what this does, but I don't support its addition as it stands. Specifically, I have issues with the option to use inline key-value pairs in the log calls. I believe the attributes system alone is fine. Logging does not need the breakage that key-value args like that allow.

The complexity in the documentation around Log should be a warning sign.

... The attribute arguments are processed as follows:

• If an argument is an Attr, it is used as is.
• If an argument is a string and this is not the last argument, the following argument is treated as the value and the two are combined into an Attr.
• Otherwise, the argument is treated as a value with key "!BADKEY".

The suggestion was that potential problems with key-value misalignment will all be solved by vet checks. As I mentioned in this thread of the discussion, relying on vet should be viewed a warning as to potential problems with the design, not a part of the design itself. Vet should not be a catch-all, and we should do what we can to avoid requiring vet warnings to safely develop go.

An accidentally deleted/missed or added/extra argument in key value logging would offset the keys and values after it. That could easily bog down a logging system trying to index all the new "keys" it is getting. It could also lead to data being exposed in a way that it should not be.

I acknowledge that neither of these examples are all that likely in a well defined system, or somewhere with good practices around code reviewing etc.. But they are possible.

[hherman1]

@deefdragon Doesn't this concern apply to Printf as well? Is the difference the dependency on these logs by external systems..?

[prochac]

Based on that the Go standard library is very often being recommended as source of idiomatic code, and this package aspires to be merged as part of it, I would like you explain to me the involvement of context package.

If some object uses logger, isn't it its dependency? Shouldn't we make the dependencies explicit? Isn't this logger smuggling bad practice? If passing the logger by context is idiomatic, is *sql.DB too?

Why has the logger stored context? It violates the most famous sentence from the documentation for context

Contexts should not be stored inside a struct type, but instead passed to each function that needs it.

Logger in context containing its own context inside ...

Frankly, I'm a bit confused.

[deefdragon]

@hherman1 The same concern does apply to printf, tho it's not as bad compared to logging. With printf, most statements are consumed as a single chunk, and only consumed locally by the programmer. Being misaligned is easy enough for a human to notice, parse, and correct.

In the case of Sprintf, where it might not be consumed by the programmer, and instead be used as an argument to something, the "testing" during development that is making sure the program starts would likely catch most misalignment.

Being off by one in a log is much harder to catch as it has no real impact in the program's execution. You only notice there is an issue when you have to go through your logs.

[mminklet]

I think I share some of @prochac 's concerns regarding context. Maybe I'm being a bit of a luddite, but recommending that the logger is passed around inside context rather than via explicit dependency injection, smells a bit funny to me. Context, from what I have always followed, is for request-scoped information, rather than dependencies. And the more clarity surfacing dependencies the better. IE just assuming the right logger is in context, and getting the default one because it's still getting some logger

[v3n]

Maybe I'm being a bit of a luddite, but recommending that the logger is passed around inside context rather than via explicit dependency injection, smells a bit funny to me. Context, from what I have always followed, is for request-scoped information, rather than dependencies.

I think there are two approaches here:

• For long-lived process (think the kind of thing that you would pass context.Background() to); I would absolutely recommend dependency injected loggers. This would include situations where a context logger might be available, but may use fan-in/singleflight to demux requests. For these cases, the logged is frequently implemented as a 'child logger', which in some frameworks allows you to adjust the log level per-child.

• However, on the other hand, many APM services have a "log correlation" features (this is even part of the spec for OpenTelemetry). In this situation, you want your context to be propagated by the logger; as the correlation fields would be prebound to the logger and propogated down the stack.

I've used both patterns frequently in high-scale production services; and both have their places. I'd definitely like to see slog promote context-propagated logging as the observability benefits are huge.

[mminklet]

Appreciate your explanation @v3n . I'm still having a slightly hard time understanding the benefit of the logger itself being passed around in context. I understand propagating the log correlation information via context, and we currently use the otelzap implementation that does this sort of thing via ErrorContext(ctx, ...) etc logging methods. I like the WithContext methods proposed here, passing the context to the logger, in similar fashion. It's more the logger itself being passed around inside the context that feels a bit odd to me

The zap and otelzap libraries do allow for the same kind of thing, whereby you can get the logger from context etc (and I'm sure others do), it's just this being in the std library it's more of a recommendation for this kind of pattern

[seankhliao]

I still want a standard handler for testing.TB.Log like https://pkg.go.dev/github.com/go-logr/logr@v1.2.3/testr#New

[jba]

Being off by one in a log is much harder to catch

@deefdragon, we'll have a vet check for that.

[jba]

I still want a standard handler for testing.TB.Log like https://pkg.go.dev/github.com/go-logr/logr@v1.2.3/testr#New

@seankhliao, such a handler seems easy to write, and it's not clear to me yet whether there is enough demand to include it. Let's hold off for now; we can always add it later.

[jba]

Why has the logger stored context? It violates the most famous sentence from the documentation for context

Contexts should not be stored inside a struct type, but instead passed to each function that needs it.

@prochac, that is a design principle, not a hard-and-fast rule. It is there to steer people away from buggy code, but that has to be weighed against other factors. In this case, we knew that passing tracing information to logging was an important feature, but we didn't want to add a context argument to every log output method. This was our solution.

[jba]

Context, from what I have always followed, is for request-scoped information

@mminklet, scoping a logger to a request is a common pattern, and is probably the main application of the ability to add a Logger to a context. It doesn't preclude dependency injection; if that works for you, stick with it.

[amnonbc]

This is a significant proposal. @jba can you do a video talk on this. And, perhaps, a blog post?

[deefdragon]

Being off by one in a log is much harder to catch

@deefdragon, we'll have a vet check for that.

@jba As I said in my original post, I don't think that's a good solution.

relying on vet should be viewed a warning as to potential problems with the design, not a part of the design itself.

[fsouza]

I like this in general. One API nit from an experiment in s3-upload-proxy: it would be good to have a way to convert a string into to the level (say you want to allow users set an environment variable like LOG_LEVEL=debug and have that translated to DebugLevel).

Other libraries (logrus, zerolog, zap) call that function ParseLevel (for zap it's ParseAtomicLevel, but same principle).

[jba]

can you do a video talk on this.

Done.

[AndrewHarrisSPU]

Other libraries (logrus, zerolog, zap) call that function ParseLevel

The additional '+'/'-' terms put a twist on this, I think it'd be nice to have. (I had this laying around: https://go.dev/play/p/Izwzgd8Kmc9)

[amnonbc]

Three comments on the proposal:

One thing which irritated me with zap was the existence of both sugared and attribute log methods. This doubled the API surface, and created a coding style balkanisation of packages that used zap as their logger. In Go there should be one, and preferably only one way of doing things. slog does unfortunately replicate this duplication.

My second observation is that we have 10 Attr constructors, one for each common type we want to log, + any. Could we have used Generics to reduce the API surface here? But if we are going to have explicit Attr constructors, then I would like one which logs an error, one that logs a stringer, and one which logs a []byte as a string.

Finally, I think it is very good (but perhaps overdue) that we are moving towards a canonical production strength logging library in stdlib. Most libraries need some level of logging, if only for debugging. And not having a standard interface of sufficient power meant a lot of pain. If you want to import package foo, you also need to pull in the weird and wonderful logging library that they use, construct a logger of the right type to pass to it, and arrange for the output to somehow be integrated into the logging output and config used by the rest of your system. I have done this myself far too many times and it quickly gets tedious. So great that this will probably soon move into the stdlib, and that new packages will eventually start adopting it. If only we had had it earlier, much aggravation would have been saved.

[jba]

slog does unfortunately replicate this duplication.

I disagree. There is only one Attr-based output method, LogAttrs. It is there as an optimization for those who need it. Most users will be fine with the other five output methods. (And yes, there is also the extra LogAttrsDepth method, but that will be even more rarely used.)

Could we have used Generics to reduce the API surface here?

The answer is, "hopefully." With the current implementation, you can only reduce the API surface at a considerable time penalty. But that may change before this API is frozen. See this item in the discussion.

I would like [an Attr constructor] which logs an error, one that logs a stringer, and one which logs a []byte as a string.

According to my analysis, zap.Stringer uses are 2% of all constructors, and zap.ByteString is at 0.3%. I don't think those numbers warrant more API. (But we can always add them later if I'm wrong.) zap.Error calls are quite common, but we believe that the error argument to Logger.Error will absorb most of those.

[rsc]

This proposal has been added to the active column of the proposals project and will now be reviewed at the weekly proposal review meetings. — rsc for the proposal review group

[rabbbit]

Why has the logger stored context? It violates the most famous sentence from the documentation for context

Contexts should not be stored inside a struct type, but instead passed to each function that needs it.

@prochac, that is a design principle, not a hard-and-fast rule. It is there to steer people away from buggy code, but that has to be weighed against other factors. In this case, we knew that passing tracing information to logging was an important feature, but we didn't want to add a context argument to every log output method. This was our solution.

I'm with @prochac and @mminklet in that passing logger in context seems awkward.

However, I see your point about context propagation and @v3n point:

I'd definitely like to see slog promote context-propagated logging as the observability benefits are huge.

But then context-propagated logging and context-propagated logg**er** are slightly different things.

@jba (apologies if this was already discussed in https://github.com/golang/go/discussions/54763, I tried to & failed to find it there) did you consider something like context-propagated log-context, as opposed to propagating the whole logger?

I frequently wish I could do easily is adding log-context to an already existing logger, like:

logger = slow.WithContext(ctx).With("method", r.Method ...)

.....

err := doSomething(c ctx) err {
   doSomethingElse(c ctx) {
        somethingVeryDeep(c ctx) {
             // do some other work
             slog.AddToContext(ctx, "workResult", ok)
        }
        somethingVeryDeepAgain(c ctx) {
             // do some work
             slog.AddToContext(ctx, "otherWorkResult", ok)
        }
   } ()
} ()
if err != nil {
    logger.Error("requestFailed") // `slog` extract values for me.
}

This would allow me to log once per request/error instead of tens of scattered log-lines which I then need to correlate with request/span ids.

I think this could also support https://go-review.googlesource.com/c/proposal/+/444415/5/design/56345-structured-logging.md#754

ctx, span := tracer.Start(ctx, name, opts)

since tracer.Start could add the context it needs to the log-context on the context.

This would likely require changes to the context package to support this in a performant way, but stdlib wants to support context+logging+tracing natively perhaps context can be adapted too? Maybe changes won't be necessary.

[AndrewHarrisSPU]

There may be a hint of namespace clobbring in ReplaceAttr, where matching on a key string is invoked before group prefixes are applied (example: https://go.dev/play/p/yFNXLz3gklD).

I think it's a reasonable behavior; the version of ReplaceAttr that is attentive to group prefixing doesn't seem like it would be very robust, leading to situations where it's not possible to add a Group downstream without breaking a replacement policy (or update a package because their logger added a Group, etc.). Still I wonder if it's worth noting in documentation.

A version of ReplaceAttr in Handler middleware might offer some flexibility. I really have no opinion on whether that component should be in slog - it's not very hard to implement, and eventually precisely tailoring some more elaborate replacement policies or hooks or whatever seems like it should be written outside of slog.

[prochac]

Why has the logger stored context? It violates the most famous sentence from the documentation for context

Contexts should not be stored inside a struct type, but instead passed to each function that needs it.

@prochac, that is a design principle, not a hard-and-fast rule. It is there to steer people away from buggy code, but that has to be weighed against other factors. In this case, we knew that passing tracing information to logging was an important feature, but we didn't want to add a context argument to every log output method. This was our solution.

Until now, all Go code was using stored context as a cheat to keep backward compatibility to pre-context era code. Totally understandable. Now, it will make a precedent, that you don't have to bother if it's convenient to you. I afraid it can get wild very soon. Maybe not in standard library, but in 3rd party ecosystem for sure.

However, I see your point about context propagation and @v3n point:

I'd definitely like to see slog promote context-propagated logging as the observability benefits are huge.

But then context-propagated logging and context-propagated logg**er** are slightly different things.

Same here. I see a lot of 3rd party libraries using context as some DI container for optional dependencies. Example can be custom http.Client. (Can't find the lib right now, but it was some big SDK.) Now, it will get approval stamp from Go team, that it's totally fine practice. (In the name of comfort) Don't get me wrong, we use context for logging too. But, as mentioned, not for passing the logger, only the fields are being propagated. Funny is, that I'm really considering changing our Logger interface to take the context as first parameter of the logging method. It's being passed to everything else anyway, so I don't see the point why logger should be kept aside from it.

I really get your point of why you want to put it in context. If I needed highly efficient logging, I would go with uber/zap stored in context. But until I don't need that, I will stick with what I consider "correct". Another example of the approach would be usage of valyala/fasthttp, until it's not really necessary, I won't use that.

[mminklet]

It doesn't preclude dependency injection; if that works for you, stick with it.

Yes, I understand that. I don't want to labour the point but my concern is that adding this pattern into the standard library essentially gives a blessing for adding dependencies into the context struct, which to me is a big no-no. I would prefer passing the context into the logging functions to utilise context propagated logging. It might not be pretty but it's clear.

[emilien-puget]

It doesn't preclude dependency injection; if that works for you, stick with it.

Yes, I understand that. I don't want to labour the point but my concern is that adding this pattern into the standard library essentially gives a blessing for adding dependencies into the context struct, which to me is a big no-no. I would prefer passing the context into the logging functions to utilise context propagated logging. It might not be pretty but it's clear.

the opentelemetry work on the logging part agrees with you https://pkg.go.dev/go.opentelemetry.io/otel/baggage

https://opentelemetry.io/docs/concepts/signals/baggage/

[prochac]

It might not be pretty but it's clear.

Sounds like Go to me.

[jba]

@rabbbit, I don't understand how slog.AddToContext works. In particular, both Context and Logger are immutable, but AddToContext seems to be called for effect.

@emilien-puget, as far as I can tell, a Baggage is just another kind of request-scoped value you can add to a context. I don't see how that is for or against adding a context arg to the log functions.

[rabbbit]

@rabbbit, I don't understand how slog.AddToContext works. In particular, both Context and Logger are immutable, but AddToContext seems to be called for effect.

https://go.dev/play/p/GVDrT-mBqCT https://go.dev/play/p/ySq81KLHBJx

Context is immutable, but you can smuggle in mutable request-context (log-context?). We'd need the initial actor to "prepare" the context at the entry point, but that's it - and we're not even breaking anything. If std-lib changes are in-scope, the sky is the limit too :)

[Merovius]

@rabbbit The point of context.Context is to be scoped to the current stack downwards and to be concurrency-safe. Yes, you can make things mutable (and you have to, because almost any logger has side-effects and hence represents mutable state). But semantically, anything you do to it should still adhere to that design principle in general semantics.

[Merovius]

I still want a standard handler for testing.TB.Log like https://pkg.go.dev/github.com/go-logr/logr@v1.2.3/testr#New

@seankhliao, such a handler seems easy to write, and it's not clear to me yet whether there is enough demand to include it. Let's hold off for now; we can always add it later.

I'm not sure how easy it is to write that handler. One notable complication is that if you use t.Log, every function between the call to t.Log and the actual relevant location (which would be the call to Logger.Info etc) has to call t.Helper. I think that kind of contradicts the design as it stands, which allows logging-middleware etc., doesn't it? So ISTM such a handler would need some co-operation from the testing package. Correct me, if I'm wrong, I don't think I fully grasp the design yet.

In terms of demand, IMO the case for such a handler is at least as strong as the case for request-scoped logging, which the API is explicitly designed to support. I want to use t.Log as a logging-handler, so that I see the debug logs specific to a given test if and only if that test fails, to jump in and start debugging ASAP.

[cugu]

Is there an easy way to get coloured logging with slog? logrus, zap, and zerolog have simple ways to get coloured log output.

[Merovius]

@cugu I assume the intent is that someone can implement Handler to output colored logs.

[rabbbit]

@rabbbit The point of context.Context is to be scoped to the current stack downwards and to be concurrency-safe. Yes, you can make things mutable (and you have to, because almost any logger has side-effects and hence represents mutable state). But semantically, anything you do to it should still adhere to that design principle in general semantics.

As long as context stores per-request values it doesn't seem like a major transgression. One could also argue that the "initial actor" registers the storage in context for later use, so it's technically down-the-stack :)

However, I think the core of the discussion is the relationship between loggers and context. I'm in favour of stronger boundaries between the two, even at the cost of passing them (both) explicitly, with some context-extractors. (and the "addToContext" pattern I listed above is just one implementation, even if I personally find it very useful).

[jba]

@rabbbit, it looks like you can do everything you want on top of the existing design. You can initialize your map at the start of the request, and write a handler to extract it from a context. We provide a way for your handler to see the context. That seems like the right division of labor.

[beoran]

If we are going to add a more complex logging packag to the standard library, it would be good to look at what Zerolog is doing. High performance logging without memory allocation.

[jba]

@Merovius, you're right about wrapping a *testing.T, the source line information is off. But it seems that would be a problem for any logging package that makes function calls before invoking its backend. logr deals with that by checking to see if a backend implements a particular interface in its output methods:

package logr

func (l Logger) Info(msg string, keysAndValues ...interface{}) {
    if l.Enabled() {
        if withHelper, ok := l.sink.(CallStackHelperLogSink); ok {
            withHelper.GetCallStackHelper()()
        }
        l.sink.Info(l.level, msg, keysAndValues...)
    }
}

For the testr implementation, GetCallStackHelper returns t.Helper.

That works, but doesn't feel very nice. I don't know what the right solution here is. As you say, probably the testing package needs to be involved.

Whatever the solution, I don't think it should work only for slog, and I don't think it's in scope for this proposal.

[Merovius]

If it's out of scope, then that's that. Just wanted to make clear that for me, personally, it's an adoption blocker. I can say with certainty that I won't use log/slog until there is some solution to this.

[jba]

@Merovius, what do you use now that works for you?

Also, you could write a handler that delegates to a TextHandler and sets HandlerOptions.AddSource to true. That will produce decent source locations, just not as prefixes. You would have to extract them from the middle of the log line.

[jba]

@beoran, we did discuss zerolog. See my comments here and here.

[Merovius]

what do you use now that works for you?

I pass around a Logf matching the Printf signature. For servers, it's a struct-field set to a nop-function on initialization, if nil. For tests I use one server-struct per test and set its Logf field to t.Logf. In prod, I set it to (*log.Logger).Printf. If I need levels, I use multiple fields.

This has drawbacks. I sometimes would like to share server instances between tests, for example (after all, clients are supposed to share it as well). And it doesn't get me request-scoping in production, which would be handy. I considered putting a Logf function into a context, but then the usage is awkward (log.Get(ctx).Logf instead of s.Logf). Ultimately, my apparent priorities are 1. convenience and 2. getting good debugging of tests.

I would like to get the advantages of good context integration and more convenient logging levels, but not at the cost of easy test debugging.

[beoran]

@jba Well I missed that discussion, and it seems you are just arguing you don't like the API. In some large commercial biomedical software we developed before, we found that 30% of our CPU and memory usage was due to logging. And switching to Zerolog mostly fixed that. So I would say that performance comes first for logging due to the potentially huge impact, even if it comes at the cost of a slightly less convenient API.

[jochumdev]

In go-micro "components" may have theier own loggers, for example the registry or grpc can have it's own logger with fixed fields, another Level or even another Handler (fluentd, Loki uvm.).

But cloning a logger With a different level doesn't seem to be straight forward in slog, am I right?

[AndrewHarrisSPU]

Had some success with embedding a testing.TB in a struct that's also a Handler. The idea is to use an encoding handler that, internally, writes to a buffer, and arrange for that buffer to be dumped to test output when testing.TB methods would otherwise emit.

Calling Parallel on this seems unwise, and probably tons of other problems, but it seemed to work out - it also captures a little bit of structure, which is nice.

https://go.dev/play/p/9APBgQuvoo9

[jba]

cloning a logger With a different level doesn't seem to be straight forward in slog

@jochumdev, it's not a one-liner but it is feasible. See my implementation sketch.