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: remove calls to Value.Resolve from slog core #59292
Comments
I had a note in my early slog reviews to ask who owns the slice returned by The
It seems to me that a decision is needed for the the primary use case and semantic for I was actually expecting the outcome of the discussion around "deterministic resolution" to go the opposite direction from what it did. As I was implying in #56345 (comment), I still think that the following two code snippets should always produce the same output, even if
|
For my perspective, I can find no beneficial use for a |
That function will run even if the logger is disabled. That's the main advantage. |
How is LogValue insufficiently lazy? Once the enabled check succeeds, what would get in the way of output? The problems with String are that it assumes something about the output, and you can't add any structure. By returning a Value, possibly a Group, you can make sure the Handler outputs something that makes sense for it and can have structure. |
The only case where the value creation is expensive enough that I don't want to do it unless the logger is enabled, I end up needing to add the enabled check outside the log call to avoid the cost of creating a closure anyway, I have yet to find an expensive enough to defer but does not need specific local values case. |
We can always add LogValuer back later. Perhaps removing it for now would make sense. The only way I see to fix the semantics in a reasonable way is for GroupValue and similar things to resolve the values eagerly, before storing them. And then Ian's point is extra true, that callers can do that themselves. What is the compelling reason to keep it? |
I looked back over the discussion. The original motivation was giving type authors the ability to describe how to log their type in a format-agnostic way. You can implement a
So the primary motivation is not performance. But I still think you have to call The other use case, generating a different value on each call, was important to go-kit because it used that for timestamps and (if I recall) stack traces. But I haven't seen any examples of that that would make sense for So I'm in favor of dropping the resolution of values in the slog core, and moving it back to the handlers. That's more error-prone work for the handlers, but the I'll ping the original issue to see if anyone there has more to add. I don't think we need to make a decision right away. |
That's right, Although this feature was primarily motivated by timestamps and caller information, it is a general tool that is not specific to those uses in any way. [1] Outside of the Valuers that go-kit/log provides I have also written the following code a few times for use in tests. I have found that when I care about the timing of log messages in test output it is more useful to have a stopwatch instead of absolute timestamps.
I was able to find one other use case for dynamic values in a private project. It is for logging the current value of a global variable that holds some version information updated asynchronously by polling the contents of a local file. That version information is included in every log message written by the application. I think it's a pretty weird behavior and I don't really like it, but .... 🤷 . [1]: I think it is worth pointing out that the implementation details of |
Currently when using a custom error package that provides stacktraces like pkg/errors, cockroachdb/errors or (ahem) StevenACoffman/simplerr calling The JSONHandler will call:
But TextHandler will call:
|
Thanks for the mention. Is the proposal to drop LogValuer entirely or just to change where/how/when it's called? I don't object to the latter (though I admit I have not taken slog out for a real track day yet). |
It was for one usage of logr.Marshaler (the corresponding feature in go-logr): https://github.com/kubernetes/klog/blob/d7fc50528570f8276de46570f916682257821e22/k8s_references.go#L119-L154 That function captures a slice and only processes it when the slice is about to get logged. That made the handling of log calls that aren't enabled a lot faster. |
I had same question when writing text handler for github actions log handler. Since github actions require specific control how attributes and levels are logged then that usecase illustrates well some limitations of current handler implementation and value resolution. |
I think the proposal should be to keep the |
You can always get the effect of log.Valuer in slog by establishing a convention. If you control both the handler and the log calls, as you would in tests, your handler could look for attribute values of type
Since it's asynchronous, it wouldn't matter if the call happened just after the enabled check, or a microsecond or two later during output. You'd just have to be careful to avoid |
@StevenACoffman, I think the problem there is that |
@thockin, not clear yet, but I also favor the latter. |
@pohly, if we keep LogValuer, the call will definitely happen after the enabled check. |
@mkungla, agreed, and an area of active research. See https://github.com/jba/slog for some ideas. If you want to continue that discussion, let's do so elsewhere, since it's not really on topic for this issue. |
@ianthehat, we added a special Kind to make it harder for handlers to miss. Most will switch on Kind with a default that fails in some way with "unknown kind". That will make forgetting to call LogValue a much easier bug to find. |
Of course. Writing a custom Handler can be the answer to just about anything with slog, just like writing a custom Logger is often the answer for anything with go-kit/log. The question is, are there any cases for which that presents a poor user experience (and there is a way to make a better experience) or integrates badly with other parts of the system and for which slog should provide a solution without requiring everyone to roll their own? The Valuer type in go-kit/log was required to reduce the need for custom Loggers on the front end because those custom loggers would make it too difficult to keep a consistent stack depth which would interact poorly with the desire to provide a mechanism to log source code location data. Once we had that mechanism it also worked nicely for timestamps and other dynamic data that didn't depend on other information in the log event. With slog we might want to be careful about putting all the burden on custom Handlers because it is a four method interface. The friction for implementing a Handler is greater than for simpler interfaces. Take the stopwatch example I gave above. With go-kit/log the implementation is only a few lines and integrates seamlessly with go-kit's With slog it is still possible, but it's a lot more involved. You have to arrange for the stopwatch attribute to get added with a handler middleware (which requires four methods and another handler to forward calls to) and to also zero out the timestamp on the record to avoid it getting written. I don't think it's a critical flaw, but it is an inconvenience by comparison. Possibly more frustrating is that LogValuer looks like it could be used for dynamic values; until you try to use it with I don't know that it's a compelling case, but it's worth considering the developer experience.
Yes, but as I said, that attribute is included with every log message from the app. It is setup in These are not easy design tradeoffs to balance, especially since (not documented that I've seen, but by my observation) slog is prioritizing (potential) performance over simplicity. That's a legitimate tradeoff, but makes other things more difficult. |
From the top post, bullet points 2 ("Copy the []Attr) and 3 ("resolve on the fly") looked more compelling to me. I'd definitely prefer "resolve on the fly". A weaker form of (2) might be a It might be worth noting that |
Removed previous mistaken recollection. I am using |
@ChrisHines: Actually, you don't really need a fully custom handler, only one that doesn't preformat. Turns out I already wrote such a handler. It collects the information from |
Zap's documentation says:
Which is basically what I would say for getting varying values: write a Handler. You can fulfill the stated purpose of a Zap hook by writing a middleware Handler. That is a bit less convenient that registering a hook but keeps the API small. Zerolog hooks are more of a necessity, since it doesn't have configurable backends. |
It seems to me that we have only one genuine example of a non-deterministic LogValuer, and there are other ways to deal with that. My conclusion is that I was mistaken to add calls to Now that the course of action is clear to me, I'm going to change this to a proposal. |
OK, it depends how you define "custom handler". What you wrote fits my definition of a custom handler in the context that I was writing. I guess I should have said "middleware handler". That doesn't change my core point that if the developer is not aware that someone has already written such a thing and it's not in |
Thanks for the careful discussion. Have all concerns about this proposal been addressed? |
I agree with the proposal but would like to know what |
|
I think that is unfortunate. I think that means code that logs arbitrary values or doesn't control or wish to be coupled to the choice of handler cannot use |
This proposal has been added to the active column of the proposals project |
@ChrisHines, Agreed. To achieve the significant performance benefits of preformatting, we are giving up the determinism that you want. |
It would be very surprising if In fact, deferring evaluation in this way can often be unsafe. If a handler lazy-evals logged keys or vals, it assumes those parameters are safe to copy across goroutine boundaries, and are safe to read over time. This isn't something that callers are generally going to assume or provide. For example, it's easy to imagine some code that logs a |
If you pass something to But that is only partly related to when to resolve values. I wouldn't want to require that |
That is also unfortunate. I think it makes the abstraction too leaky. IMHO, the ability to use |
Based on the discussion above, this proposal seems like a likely accept. |
No change in consensus, so accepted. 🎉 |
Change https://go.dev/cl/486375 mentions this issue: |
Remove calls to Value.Resolve from Record.AddAttrs, Record.Add and Logger.With. Handlers must resolve values themselves; document that in Handler. Call Value.Resolve in the built-in handlers. Updates #59292. Change-Id: I00ba2131be0b16e3b1a22741249fd6f81c3efde1 Reviewed-on: https://go-review.googlesource.com/c/go/+/486375 TryBot-Result: Gopher Robot <gobot@golang.org> Run-TryBot: Jonathan Amsterdam <jba@google.com> Reviewed-by: Alan Donovan <adonovan@google.com>
The work on this was completed by the above CL. |
Remove calls to Value.Resolve from Record.AddAttrs, Record.Add and Logger.With. Handlers must resolve values themselves; document that in Handler. Call Value.Resolve in the built-in handlers. Updates golang#59292. Change-Id: I00ba2131be0b16e3b1a22741249fd6f81c3efde1 Reviewed-on: https://go-review.googlesource.com/c/go/+/486375 TryBot-Result: Gopher Robot <gobot@golang.org> Run-TryBot: Jonathan Amsterdam <jba@google.com> Reviewed-by: Alan Donovan <adonovan@google.com>
Remove calls to Value.Resolve from Record.AddAttrs, Record.Add and Logger.With. Handlers must resolve values themselves; document that in Handler. Call Value.Resolve in the built-in handlers. Updates golang#59292. Change-Id: I00ba2131be0b16e3b1a22741249fd6f81c3efde1 Reviewed-on: https://go-review.googlesource.com/c/go/+/486375 TryBot-Result: Gopher Robot <gobot@golang.org> Run-TryBot: Jonathan Amsterdam <jba@google.com> Reviewed-by: Alan Donovan <adonovan@google.com>
The logging methods of
slog
resolve values after they check that they are enabled and before callingHandler.Handle
. This was done soLogValue
methods whose result may vary behave the same way independent of handler implementation.The problem is that resolving values in a Group must either be done in place, inviting aliasing bugs and data races, or be done on a copy of the slice, which can be expensive.
The discussion here shows that there isn't much need for varying LogValue methods. The main use case of
LogValue
is providing a way for type authors to provide structured, format-independent log output, which is deterministic. When varying output is required, all that is needed to make sure it doesn't run afoul of a preformattingHandler.WithAttrs
method is a simple handler wrapper that disables preformatting.So I propose removing the calls to
Value.Resolve
from slog proper and adding them back to the built-in handlers, essentially reverting https://go.dev/cl/464100. Checks for proper calls toResolve
will be added to theslogtest
package.slog proposal: #56345.
Original top post preserved below for posterity.
I'm not sure if this is a bug, or acceptable behavior.
A Group value holds a
[]Attr
. CallingResolve
on the Group value will destructively modify the slice elements with their resolutions.For example, say we have a simple
LogValuer
like this:Then we construct a Group value containing a
replace
:The
replace
is atg.Group()[1].Value
.After calling
g.Resolve()
, the contents ofg.Group()[1].Value
will be modified toIntValue(2)
. You can see this behavior at https://go.dev/play/p/UqjXZ76o78K.The implementation behaves this way to avoid making a copy of the slice when resolving.
Most of the time this behavior won't be noticeable. Code that constructs groups on the fly, like
or
will not observe the modification. But code that retains groups, like
can observe the change. And if
commonAttrs
is shared among multiple goroutines, a data race can happen. Also, the resolution will happen only once, rather than for each log event. That may be fine if the LogValuer's purpose is just to delay an expensive, deterministic computation until it is needed, but it will be wrong if the intent is to generate a value that varies with the log event, like a timestamp.The alternatives I see are:
Leave this behavior as it is, a rare "gotcha" that is forgivable because it improves performance. (Of course, we would document it.)
Copy the
[]Attr
if it contains any LogValuers. This can result in a lot of copying when Group values nest. A Group value containing two other Group values each of which contains a LogValuer will result in three slice copies for each call toResolve
, andResolve
will be called on every log event.This situation arises from our decision to call
Resolve
before calling a handler. We made that choice both for the convenience of handler writers and to make resolution more deterministic. We could revisit it. If a handler performs resolution on the fly, as it is producing output, then it need not copy the group slice.We could say that slog resolves top-level Attrs, but not those inside groups. That is probably too subtle.
slog proposal: #56345.
/cc @ChrisHines, @ianthehat
The text was updated successfully, but these errors were encountered: