Skip to content
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: structured, leveled logging #56345

Closed
jba opened this issue Oct 20, 2022 · 841 comments
Closed

log/slog: structured, leveled logging #56345

jba opened this issue Oct 20, 2022 · 841 comments

Comments

@jba
Copy link
Contributor

jba commented Oct 20, 2022

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 jba added the Proposal label Oct 20, 2022
@gopherbot gopherbot added this to the Proposal milestone Oct 20, 2022
@jba

This comment was marked as resolved.

@fsouza

This comment was marked as resolved.

@jba

This comment was marked as resolved.

@mpx
Copy link
Contributor

mpx commented Oct 22, 2022

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
Copy link
Member

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

@mpx

This comment was marked as resolved.

@deefdragon
Copy link

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
Copy link

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

@prochac
Copy link

prochac commented Oct 24, 2022

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
Copy link

@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
Copy link

mminklet commented Oct 25, 2022

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
Copy link

v3n commented Oct 25, 2022

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
Copy link

mminklet commented Oct 25, 2022

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
Copy link
Member

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
Copy link
Contributor Author

jba commented Oct 25, 2022

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

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

@jba
Copy link
Contributor Author

jba commented Oct 25, 2022

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
Copy link
Contributor Author

jba commented Oct 25, 2022

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
Copy link
Contributor Author

jba commented Oct 25, 2022

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
Copy link

amnonbc commented Oct 25, 2022

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

@deefdragon
Copy link

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
Copy link
Contributor

fsouza commented Oct 25, 2022

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
Copy link
Contributor Author

jba commented Oct 25, 2022

can you do a video talk on this.

Done.

@AndrewHarrisSPU
Copy link

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
Copy link

amnonbc commented Oct 26, 2022

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
Copy link
Contributor Author

jba commented Oct 26, 2022

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
Copy link
Contributor

rsc commented Oct 26, 2022

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
Copy link

rabbbit commented Oct 26, 2022

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 #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
Copy link

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.

eric pushed a commit to fancybits/go that referenced this issue Sep 7, 2023
Add a package for testing that a slog.Handler implementation
satisfies that interface's documented requirements.

Code copied from x/exp/slog/slogtest.

Updates golang#56345.

Change-Id: I89e94d93bfbe58e3c524758f7ac3c3fba2a2ea96
Reviewed-on: https://go-review.googlesource.com/c/go/+/487895
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Jonathan Amsterdam <jba@google.com>
Reviewed-by: Alan Donovan <adonovan@google.com>
eric pushed a commit to fancybits/go that referenced this issue Sep 7, 2023
The slog structured logging package.

This code was copied from the slog directory of the x/exp repo
at commit 642cacee5cc05231f45555a333d07f1005ffc287, with the
following changes:

- Change import paths.
- Delete unused files list.go, list_test.go.
- Rename example_depth_test.go to example_wrap_test.go and
  adjust example output.
- Change the tag safe_values to safe_slog_values.
- Make captureHandler goroutine-safe to fix a race condition
  in benchmarks.
- Other small changes as suggested in review comments.

Also, add dependencies to go/build/deps_test.go.

Also, add new API for the API checker.

Updates golang#56345.

Change-Id: Id8d720967571ced5c5f32c84a8dd9584943cd7df
Reviewed-on: https://go-review.googlesource.com/c/go/+/477295
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
Run-TryBot: Jonathan Amsterdam <jba@google.com>
Reviewed-by: Alan Donovan <adonovan@google.com>
eric pushed a commit to fancybits/go that referenced this issue Sep 7, 2023
Use the new functions in 1.20 (unsafe.StringData, etc.) instead
of StringHeader and StructHeader from the reflect package.

Updates golang#56345.

Change-Id: I84d0db7b203aeffe45ce8b06beb7b4ee17e19949
Reviewed-on: https://go-review.googlesource.com/c/go/+/478055
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Alan Donovan <adonovan@google.com>
Run-TryBot: Jonathan Amsterdam <jba@google.com>
Reviewed-by: Ian Lance Taylor <iant@google.com>
eric pushed a commit to fancybits/go that referenced this issue Sep 7, 2023
Make it clear that "qualified by the given name" doesn't imply
any particular implementation, but depends on how the Handler
treats groups.

Updates golang#56345.

Change-Id: Idf52553108bc1a7d2091a06cc4fc4cc0fc52cc14
Reviewed-on: https://go-review.googlesource.com/c/go/+/478056
Reviewed-by: Alan Donovan <adonovan@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Jonathan Amsterdam <jba@google.com>
eric pushed a commit to fancybits/go that referenced this issue Sep 7, 2023
- Remove the norace_test.go files, moving their contents elsewhere.

- Rename the internal/testutil package to internal/slogtest.

- Remove value_unsafe.go, moving its contents to value.go.

Updates golang#56345.

Change-Id: I2a24ace5aea47f7a3067cd671f606c4fb279d744
Reviewed-on: https://go-review.googlesource.com/c/go/+/478197
Run-TryBot: Jonathan Amsterdam <jba@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@google.com>
eric pushed a commit to fancybits/go that referenced this issue Sep 7, 2023
Bench log file is created non-portably, only works on system where
"/tmp" existed and "/" is path separator.

Fixing this by using portable methods from std lib.

Updates golang#56345

Change-Id: I1f6b6b97b913ca56a6053beca7025652618ecbf3
Reviewed-on: https://go-review.googlesource.com/c/go/+/478355
Run-TryBot: Ian Lance Taylor <iant@google.com>
Reviewed-by: Ian Lance Taylor <iant@google.com>
Auto-Submit: Ian Lance Taylor <iant@google.com>
Reviewed-by: Jonathan Amsterdam <jba@google.com>
Run-TryBot: Cuong Manh Le <cuong.manhle.vn@gmail.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
eric pushed a commit to fancybits/go that referenced this issue Sep 7, 2023
Delete the set of bytes that need quoting in TextHandler, because it
is almost identical to the set for JSON. Use JSONHandler's safeSet
with a few exceptions.

Updates golang#56345.

Change-Id: Iff6d309c067affef2e5ecfcebd6e1bb8f00f95b9
Reviewed-on: https://go-review.googlesource.com/c/go/+/478198
Reviewed-by: Ian Lance Taylor <iant@google.com>
Run-TryBot: Jonathan Amsterdam <jba@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
eric pushed a commit to fancybits/go that referenced this issue Sep 7, 2023
Give an example illustrating the problem with dots inside groups
or keys. Clarify that to fix it in general, you need to do more
than escape the keys, since that won't distinguish the group "a.b"
from the two groups "a" and "b".

Updates golang#56345.

Change-Id: Ide301899c548d50b0a1f18e93e93d6e11ad485cf
Reviewed-on: https://go-review.googlesource.com/c/go/+/478199
Reviewed-by: Alan Donovan <adonovan@google.com>
Run-TryBot: Jonathan Amsterdam <jba@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
eric pushed a commit to fancybits/go that referenced this issue Sep 7, 2023
Add a suite of benchmarks for the LogAttrs method, which is intended
to be fast.

Updates golang#56345.

Change-Id: If43f9f250bd588247c539bed87f81be7f5428c6d
Reviewed-on: https://go-review.googlesource.com/c/go/+/478200
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Jonathan Amsterdam <jba@google.com>
Reviewed-by: Alan Donovan <adonovan@google.com>
eric pushed a commit to fancybits/go that referenced this issue Sep 7, 2023
Format Group values like a []Attr, rather than a *Attr.

Also, use fmt.Append in Value.append.

Updates golang#56345.

Change-Id: I9db1a8ec47f8e99c1ac3225d78e152013116bff3
Reviewed-on: https://go-review.googlesource.com/c/go/+/479515
Run-TryBot: Jonathan Amsterdam <jba@google.com>
Reviewed-by: Alan Donovan <adonovan@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
eric pushed a commit to fancybits/go that referenced this issue Sep 7, 2023
Comparing two Values with == is sensitive to the internal
representation of Values, and may not correspond to
equality on the Go values they represent. For example,

    StringValue("X") != StringValue(strings.ToUpper("x"))

because Go ends up doing a pointer comparison on the data
stored in the Values.

So make Values non-comparable by adding a non-comparable field.

Updates golang#56345.

Change-Id: Ieedbf454e631cda10bc6fcf470b57d3f1d2182cc
Reviewed-on: https://go-review.googlesource.com/c/go/+/479516
Run-TryBot: Jonathan Amsterdam <jba@google.com>
Reviewed-by: Alan Donovan <adonovan@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
eric pushed a commit to fancybits/go that referenced this issue Sep 7, 2023
Add a package for testing that a slog.Handler implementation
satisfies that interface's documented requirements.

Code copied from x/exp/slog/slogtest.

Updates golang#56345.

Change-Id: I89e94d93bfbe58e3c524758f7ac3c3fba2a2ea96
Reviewed-on: https://go-review.googlesource.com/c/go/+/487895
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Jonathan Amsterdam <jba@google.com>
Reviewed-by: Alan Donovan <adonovan@google.com>
@tzq0301
Copy link

tzq0301 commented Nov 16, 2023

It seems that NewContext(...) and FromContext(...), are not in Go 1.21, which are in the discussion. But I think that they're really useful. I wonder that will they be supported in the future?

@jba
Copy link
Contributor Author

jba commented Nov 16, 2023

They were very controversial. I don't see that changing.

@pohly
Copy link

pohly commented Nov 17, 2023

https://pkg.go.dev/github.com/go-logr/logr has NewContext and FromContext. In 1.3.0 (released last month) I added support for slog (see "slog interoperability" in the README and https://pkg.go.dev/github.com/go-logr/logr@v1.3.0/slogr), so now you can do:

var logger *slog.Logger
logger = slog.New(slogr.NewSlogHandler(logr.FromContextOrDiscard(ctx)))
logger = logger.With("answer", 42)
ctx = logr.NewContext(ctx, slogr.NewLogr(logger.Handler()))

Storing and retrieving a slog.Logger is not ideal because storing it must convert to logr.Logger and retrieving must undo that, which causes additional memory allocations. I have an idea how that could be avoided, but for that the main logr package must depend on slog, which is something that @thockin and I wanted to avoid until there is specific demand for it.

@veqryn
Copy link
Contributor

veqryn commented Nov 18, 2023

github.com/veqryn/slog-context has support for two different workflows for using slog and context: storing and retrieving the logger from Context and/or storing and retrieving attributes and values from Context. (These workflows can be used individually or together at the same time.)

Attributes Extracted from Context Workflow:

Using the slogctx.Handler lets you Prepend and Append attributes to log lines, even when a logger is not passed into a function or in code we don't control. This is done without storing the logger in the context; instead the attributes are stored in the context and the Handler picks them up later whenever a new log line is written.

In that same workflow, the HandlerOptions and AttrExtractor types let you extract any custom values from a context and have them automatically be prepended or appended to all log lines using that context.
For example, the slogotel.ExtractTraceSpanID extractor will automatically extract the OTEL (OpenTelemetry) TraceID and SpanID, and add them to the log record, while also annotating the Span with an error code if the log is at error level.

Logger in Context Workflow:

Using NewCtx and FromCtx let you store the logger itself within a context, and get it back out again. Wrapper methods With/WithGroup/Debug/Info/Warn/Error/Log/LogAttrs let you work directly with a logger residing with the context (or the default logger if no logger is stored in the context).

@tzq0301 @andviro @lpar @pohly

@pohly
Copy link

pohly commented Nov 18, 2023

Using the slogcontext.Handler lets you Prepend and Append attributes to log lines, even when a logger is not passed into a function or in code we don't control. This is done without storing the logger in the context; instead the attributes are stored in the context and the Handler picks them up later whenever a new log line is written.

This only works when the code "that you don't control" is careful about always passing the context into any log calls that it invokes, right? So it won't work for e.g. slog.Info, which is what developers who don't care (or don't know) about logging values from context might pick. It also breaks once you need to call code which accepts a Logger, but not a context.

github.com/veqryn/slog-context: [...] storing and retrieving the logger from Context

This won't be interoperable with Kubernetes packages, which use go-logr/logr for this (wrapped by klog, but that's an implementation detail).

My point is: without a convention that is followed by all reusable Go packages, these mechanisms work in scenarios where one controls the entire code base, but not when combining code from different sources.

@antichris
Copy link

@pohly

Maybe it could be worth it adding to slogr something similar to the following:

// NewContext from ctx with a logger that uses [slog.Handler] from the
// provided [slog.Logger].
// An instance of [slog.Logger] using the handler can be retrieved from
// this context using [FromContext].
func NewContext(ctx context.Context, l *slog.Logger) context.Context {
	return logr.NewContext(ctx, NewLogr(l.Handler()))
}

// FromContext returns an [slog.Logger] from the provided context.
func FromContext(ctx context.Context) (l *slog.Logger) {
	return slog.New(NewSlogHandler(logr.FromContextOrDiscard(ctx)))
}

That allocation of a new slog.Logger, 16 bytes on a 64-bit system, on every retrieval is unfortunate, though.

@pohly
Copy link

pohly commented Nov 18, 2023

@antichris: We had considered that and decided against it at the time because it's just syntactic sugar and not necessarily a good solution because of that additional allocation. That constructing a Logger needs an allocation is unfortunate for cases like this where an instance needs to be created frequently. I had suggested to pass slog.Logger by value to avoid it, but that wasn't accepted.

But perhaps that's okay. I think it's fine to simply use the logr.Logger API on top of a slog.Handler via slogr - that's not that different from using slog.Logger as higher-level API. So if someone wants to accept a logger via a context, just use logr? That's what I am proposing for Kubernetes, with some additional support for slog. It avoids further code churn and I just couldn't find a good reason that would have justified switching.

I'm not sure whether this issue is the right place to discuss this, though. I've created go-logr/logr#234 for further discussion and tracking.

@yuseferi
Copy link

yuseferi commented Nov 21, 2023

in the (initial proposal) it was part of the plan but it could cause some performance issue.

There should be a way to consider correlation like, like trace_id, I believe storing the whole logger object is not the best way, maybe just storing fields in the logger could be an option for consideration?

@yuseferi
Copy link

I did a benchmark here on zax and it shows storing fields instead of the whole logger object gives better performance :

BenchmarkLoggingWithZaxV2-10            64324434                56.02 ns/op           72 B/op          2 allocs/op
BenchmarkLoggingWithZaxV2-10            63939517                56.98 ns/op           72 B/op          2 allocs/op
BenchmarkLoggingWithZaxV2-10            63374052                57.60 ns/op           72 B/op          2 allocs/op
BenchmarkLoggingWithZaxV2-10            63417358                57.37 ns/op           72 B/op          2 allocs/op
BenchmarkLoggingWithZaxV2-10            57964246                57.97 ns/op           72 B/op          2 allocs/op
BenchmarkLoggingWithZaxV1-10            54062712                66.40 ns/op          160 B/op          2 allocs/op
BenchmarkLoggingWithZaxV1-10            53155524                65.61 ns/op          160 B/op          2 allocs/op
BenchmarkLoggingWithZaxV1-10            54428521                64.19 ns/op          160 B/op          2 allocs/op
BenchmarkLoggingWithZaxV1-10            55420744                64.28 ns/op          160 B/op          2 allocs/op
BenchmarkLoggingWithZaxV1-10            55199061                64.50 ns/op          160 B/op

@pohly
Copy link

pohly commented Dec 25, 2023

slog as an API already supports "store and extract values":

  • Ensure that all log calls have a context and use the *Ctx variant of the slog.Logger API.
  • Use a slog.Handler which supports extracting the values that you are interested in. Third-party libraries often hide their context key behind their API, so such a handler must be able to call the API of those libraries, or you need to write a wrapper slog.Handler which does this.

Regarding performance: this depends on usage patterns. If all call chains have additional values, then extracting those is going to be faster. If you have many different values and each call chain only has one of those values, then checking for all of them on each log call is probably slower.

@veqryn
Copy link
Contributor

veqryn commented Jan 3, 2024

@pohly and I talked a bit and agreed to coordinate our repos.
So I am happy to announce that github.com/veqryn/slog-context now supports both stdlib slog as well as github.com/go-logr/logr at the same time.

You can use github.com/veqryn/slog-context to:

  • Store a *slog.Logger in the context.Context, and either get it back out again or work with it directly in the ctx.
  • Append or Prepend attributes to the start or end of all log lines that use a Context (useful for adding attributes/baggage to log lines in libraries).
  • Create custom extractors to pull any values out of a Context and add them to all log lines using that context.
  • Automatically add OpenTelemetry TraceID and SpanID to log lines, as well as marking spans as having errored with an error message if appropriate.

@Minoxs
Copy link

Minoxs commented Jan 4, 2024

Hello, everyone! I've been trying out slog and hit some bumps with how the API is designed. Essentially, for my use case I need to check a certain log level and dispatch an alert, and still log normally. A middleware for the default handler basically. Should be something very straight forward, but in the current state, there's no (proper) way to wrap the default handler.

The handlers that slog allows to be constructed don't log in the pretty TIME LEVEL Msg Key=Pair format, essentially forcing me to reimplement the *commonHandler (or a custom one).

Problem

I tried a different approach but hit another roadblock.

type WrapperHandler struct {
	slog.Handler
}

func (w *WrapperHandler) Handle(ctx context.Context, record slog.Record) error {
        doSomething()
	return w.Handler.Handle(ctx, record)
}

func main() {
  wrap := &WrapperHandler{slog.Default().Handler()}
  slog.SetDefault(slog.New(wrap))
  slog.Info("TEST") // <-- Deadlock here!
}

From what I've gathered, it seems to be because of what is being done in SetDefault

func SetDefault(l *Logger) {
	// ...
        // This bit here
	if _, ok := l.Handler().(*defaultHandler); !ok {
		capturePC := log.Flags()&(log.Lshortfile|log.Llongfile) != 0
		log.SetOutput(&handlerWriter{l.Handler(), LevelInfo, capturePC})
		log.SetFlags(0) // we want just the log message, no time or location
	}
}

If I got this right, this was added for compatibility with log but... it smells like bad practice to me. IMO this should NOT be done by SetDefault (a separate function for that), or defaultLogger should be exported. Another option would be a SetDefaultHandler, or a With(slog.Handler)/With(*slog.Logger) similar to how WithGroup works, but for a chain of loggers.

Workaround

If I were to do the following, which feels like a very very bad thing to do, it now works.

type WrapperHandler struct {
	slog.Handler
}

func (w *WrapperHandler) Handle(ctx context.Context, record slog.Record) error {
        doSomething()
	return w.Handler.Handle(ctx, record)
}

func main() {
  wrap := &WrapperHandler(slog.Default().Handler())
  *slog.Default() = *slog.New(wrap) // Bypass SetDefault using pointer hacks (not thread-safe obviously)
  slog.Info("TEST")  // Works just fine
}

Remarks

I'm sorry if these things have been answered already, or if I'm overlooking something, I read the entire documentation and looked through the thread and didn't find this being mentioned. I can't really wrap (pun intended) my head around why extending/wrapping the default logger is so obtuse. I'm aware I could build my own logging package around slog, or use one of the great existing ones, but considering how feature complete slog looks I would rather stick with it as much as possible.

Edit: After some more digging I found this to be related to #62418 and #61892

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
Status: Accepted
Development

No branches or pull requests