log/slog: non-top level slog.Value marshals to empty json document

[stevenpelley]

slog.Value always json.marshals to an empty document, "{}", which to me was surprising behavior when using JsonHandler. If a slog.Value is embedded in a logged non-slog.Value, for example a slice, it will effectively omit data. On the other hand any tree of Values and Attrs passed directly to the log functions, without an intervening non-slog.Value object, marshals and logs properly. I expect a slice, or any other non-slog.Value type, containing an slog.Value to marshal to json with the slog.Value's represented value. TextHandler produces the expected logs for the same pattern.

What version of Go are you using (go version)?

go1.21.0 darwin/arm64

Does this issue reproduce with the latest release?

yes

What operating system and processor architecture are you using (go env)?

arm64, darwin (MacOS Ventura 13.5.2)

What did you do?

Original discussion at https://groups.google.com/g/golang-nuts/c/ZvlSL76RNaw/m/N1L_5f0vAQAJ?utm_medium=email&utm_source=footer Demonstration at https://goplay.tools/snippet/H26amsQBiYG There are other, arguably simpler ways to achieve my fundamental goals and I'm not blocked; I still find the behavior below to be surprising.

I logged, using slog and a JsonHandler, values containing types other than slog.Value (e.g., slices) which in turn contain slog.Value. My goal was to use LogValuers to redact object fields by in turn calling LogValue on component objects. The "outer object" has a slice of the inner objects and so the outer object's LogValue returns something resembling AnyValue([]slog.Value).

I additionally directly marshaled slog.Value.

What did you expect to see?

I expected slog to log the json representation of the "outer object" with a field containing the list of "inner objects". I expected json-marshaled slog.Value to produce json representing the value.

Alternatively, the slog documentation (or specifically JsonHandler) could state that no non-slog.Value object passed to a log method may contain an slog.Value, and that LogValuers must maintain this invariant.

What did you see instead?

A list of empty objects: [{}, {}, {}] slog.Value marshals to '{}'

[ianlancetaylor]

CC @jba

[seankhliao]

5901 would be helpful to teach the json encoder about slog.Value

[jba]

I propose adding the following to slog, so that slog.Values marshal as the Go value they represent:

func (v Value) MarshalJSON() ([]byte, error) {
    return json.Marshal(v.Any())
}

@stevenpelley, does that solve your problem? @dsnet, do you have any concerns?

[dsnet]

I don't have any great answers right now, but recursively calling json.Marshal from Value.MarshalJSON can be O(n²) if v.Any can contain nested Value types. This is a known performance flaw with json.Marshaler (and json.Unmarshaler) and has affected other projects like Kubernetes and us at Tailscale.

I'll be presenting next week at GopherCon on a potential new JSON API that would fix this problem, but even then it would take many Go releases before it hits the stdlib (if ever).

That said, if you add MarshalJSON today, you would be able to backwards compatibly add a hypothetical MarshalJSONV2 method in the future without breaking any semantics.

[stevenpelley]

I propose adding the following to slog, so that slog.Values marshal as the Go value they represent:

func (v Value) MarshalJSON() ([]byte, error) {
    return json.Marshal(v.Any())
}

@stevenpelley, does that solve your problem? @dsnet, do you have any concerns?

@jba I believe this provides the behavior I expect (without testing it or understanding the implementations of slog.Value and json.Marshal terribly well).

I don't have any great answers right now, but recursively calling json.Marshal from Value.MarshalJSON can be O(n²) if v.Any can contain nested Value types. This is a known performance flaw with json.Marshaler (and json.Unmarshaler)

@dsnet the concern makes sense. Given that when someone logs with this pattern today their data won't be logged properly I'd argue for first producing the correct result and then waiting for feedback about the performance of JsonHandler and MarshalJson. If I'm the first to report this then maybe it's not that common a pattern. And in practice, for logging, I suspect "n" will be relatively small (obviously with no data and only my personal experience to back this up).

We could also note this performance business about embedded values somewhere around the documentation for func (*JSONHandler) Handle but I think that's discussing the implementation too much.

[dsnet]

I'd argue for first producing the correct result and then waiting for feedback about the performance

Yea, I agree. I'm just saddened we can't do the performant thing today and we'll be adding API that can't be removed when the more performant thing one day arrives. But yes, I don't think we should block this issue for the next year or two on a performance fix.

[AndrewHarrisSPU]

It's already possible to arrive at an invocation of MarshalJSON by going down this branch of encoding logic in JSONHandler. There might be an argument that the risk of O(n²) marshaling cost is already present in the obvious scenario.

At a glance I was skeptical of Value.MarshalJSON but I have persuaded myself that the behaviors have parity with what happens inside TextHandler, or Value.String outside, in less obvious scenarios.