log/slog: JSONHandler should deduplicate keys

[veqryn]

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

8edcddd

Does this issue reproduce with the latest release?

yes

What did you do?

	logger := slog.New(slog.NewJSONHandler(os.Stdout))
	logger.LogAttrs(
		context.Background(),
		slog.LevelWarn,
		"fancy message",
		slog.Bool("msg", false),
		slog.String("my attr", "something"),
	)

What did you expect to see?

JSONHandler should be fixed by deduplicating those special keys (time, message, level, and source).
I use "source" as a key in a lot of my code right now, so I'd run into this problem.

Either

{
	"time": "2023-04-01T04:27:46.0959443-06:00",
	"level": "WARN",
	"msg": "fancy message",
	"my attr": "something"
}

Or

{
	"time": "2023-04-01T04:27:46.0959443-06:00",
	"level": "WARN",
	"msg": "fancy message",
	"msg.msg": false,
	"my attr": "something"
}

Or

{
	"time": "2023-04-01T04:27:46.0959443-06:00",
	"level": "WARN",
	"msg": "fancy message",
	"fields": {
		"msg": false,
		"my attr": "something"
	}
}

Or

{
	"time": "2023-04-01T04:27:46.0959443-06:00",
	"level": "WARN",
	"msg": "fancy message",
	"msg#01": false,
	"my attr": "something"
}

What did you see instead?

Invalid json. It would break our log aggregation. Default/Builtin handlers should never create invalid output.

{
	"time": "2023-04-01T04:27:46.0959443-06:00",
	"level": "WARN",
	"msg": "fancy message",
	"msg": false,
	"my attr": "something"
}

@jba

EDIT:
Hey all, I've created a logging handler middleware that will deduplicate attribute keys, before they go to the json logger.
Please check it out: https://github.com/veqryn/slog-dedup

go get github.com/veqryn/slog-dedup

package main

import (
	"log/slog"
	"os"

	slogdedup "github.com/veqryn/slog-dedup"
)

func main() {
	// OverwriteHandler
	overwriter := slogdedup.NewOverwriteHandler(slog.NewJSONHandler(os.Stdout, nil), nil)
	slog.SetDefault(slog.New(overwriter))

	/*
	  {
	    "time": "2023-10-03T01:30:00Z",
	    "level": "INFO",
	    "msg": "this is the dedup overwrite handler",
	    "duplicated": "two"
	  }
	*/
	slog.Info("this is the dedup overwrite handler",
		slog.String("duplicated", "zero"),
		slog.String("duplicated", "one"),
		slog.String("duplicated", "two"),
	)

	// IgnoreHandler
	ignorer := slogdedup.NewIgnoreHandler(slog.NewJSONHandler(os.Stdout, nil), nil)
	slog.SetDefault(slog.New(ignorer))

	/*
	  {
	    "time": "2023-10-03T01:30:00Z",
	    "level": "INFO",
	    "msg": "this is the dedup ignore handler",
	    "duplicated": "zero"
	  }
	*/
	slog.Info("this is the dedup ignore handler",
		slog.String("duplicated", "zero"),
		slog.String("duplicated", "one"),
		slog.String("duplicated", "two"),
	)

	// IncrementHandler
	incrementer := slogdedup.NewIncrementHandler(slog.NewJSONHandler(os.Stdout, nil), nil)
	slog.SetDefault(slog.New(incrementer))

	/*
	  {
	    "time": "2023-10-03T01:30:00Z",
	    "level": "INFO",
	    "msg": "this is the dedup incrementer handler",
	    "duplicated": "zero",
	    "duplicated#01": "one",
	    "duplicated#02": "two"
	  }
	*/
	slog.Info("this is the dedup incrementer handler",
		slog.String("duplicated", "zero"),
		slog.String("duplicated", "one"),
		slog.String("duplicated", "two"),
	)

	// AppendHandler
	appender := slogdedup.NewAppendHandler(slog.NewJSONHandler(os.Stdout, nil), nil)
	slog.SetDefault(slog.New(appender))

	/*
	  {
	    "time": "2023-10-03T01:30:00Z",
	    "level": "INFO",
	    "msg": "this is the dedup appender handler",
	    "duplicated": [
	      "zero",
	      "one",
	      "two"
	    ]
	  }
	*/
	slog.Info("this is the dedup appender handler",
		slog.String("duplicated", "zero"),
		slog.String("duplicated", "one"),
		slog.String("duplicated", "two"),
	)
}

[dsnet]

Whatever solution is chosen here, I would argue that it should work even if the user explicitly provides duplicate names:

logger.LogAttrs(
	context.Background(),
	slog.LevelWarn,
	"fancy message",
	slog.String("duplicate", "alpha"),
	slog.String("duplicate", "bravo"),
	slog.String("duplicate", "charlie"),
	slog.String("duplicate", "delta"),
	slog.String("duplicate", "echo"),
)

One possible solution is to use a "#%d" scheme similar to how testing.T.Run deduplicates conflicting test names.
For example:

{
	"time": "2023-04-01T04:27:46.0959443-06:00",
	"level": "WARN",
	"msg": "fancy message",
	"duplicate": "alpha",
	"duplicate#01": "bravo",
	"duplicate#02": "charlie",
	"duplicate#03": "delta",
	"duplicate#04": "echo",
}

[seankhliao]

I think the current situation is fine, duplicate keys aren't invalid, just less interoperable.
Changing the key name to deduplicate it seems worse.

As for the original issue, I'll note that option 3 was why WithGroup was added (though this doesn't affect deduplication in general).

[dsnet]

duplicate keys aren't invalid, just less interoperable.

Technically you are correct. Under RFC 8259, section 4, duplicate names are essentially treated as undefined behavior.

In a possible future major version of "encoding/json", we will likely make duplicate keys an explicit error (which is still complaint behavior with RFC 8259) as this lack of checking has been exploited, resulting in severe security vulnerabilities (e.g., CVE-2017-12635). It's unlikely that duplicate names will have such drastic security implications in logging, but strict checking of duplicate names is likely the overall direction that JSON will gradually move towards.

As an aside, Tim Bray, the author of RFC 8259 actually recommends against naïve compliance with RFC 8259, but rather that implementations adhere to RFC 7493 which makes strict decisions on issues that RFC 8259 leaves as undefined.

[jba]

I think it's important to understand whether encoding/json v2 with its currently proposed semantics is likely to be the accepted version. We should probably align slog with those semantics, even if slog appears in Go before encoding/json v2. We're already doing that for formatting NaNs, infinities and, probably, durations (#59345).

For this issue, if we think no dups will be the default for encoding/json v2, then I wouldn't be opposed to making it the default in slog and adding an AllowDuplicateNames option. And we should do the same for TextHandler for consistency.

[dsnet]

whether encoding/json v2 with its currently proposed semantics is likely to be the accepted version

That I can't really answer unfortunately.

We haven't even started the GitHub discussion on anything related to v2 "encoding/json" and may not be ready to do so for some months. A significant piece of work that remains is figuring out the inter-compatibility story between v1 and a hypothetical v2. That's perhaps the hardest part and requires quite a lot of head-scratching.

That said, if there is a v2 "encoding/json", I feel like the security arguments for rejecting duplicate names by default is pretty compelling.

---

The (very) tentative plan for v2 is that v1 "encoding/json" will actually be implemented in terms of v2 with the appropriate number of options specified that makes it behave semantically identically to what v1 "json" does today. Essentially, with the appropriate set of options, you can configure the semantics to be any hybrid mix that is in-between the default behavior of v1 and the default behavior of v2.

Since "log/slog" already depends on the v1 semantics of "encoding/json", you could imagine doing nothing to address this issue for now. I don't think we should block adoption of "slog" on a hypothetical v2 "json". Nor should we overly massage the output of "slog" to match a hypothetical v2 "json".

Supposing v2 "json" one day lands, you could imagine that v2 "json" be integrated into "slog" by exposing something like:

package slog

type HandlerOptions struct {
    // JSONOptions is a list of Option
    // that configures how JSON is marshaled.
    JSONOptions []json.Option
}

To log each message, "slog" would do something like:

// Start with DefaultV1Options since "slog" has historically
// marshaled with mostly v1 semantics by default.
opts := []json.Option{json.DefaultV1Options}
// We have historically specified Encoder.SetEscapeHTML(false).
// By passing a nil escape function, we achieve the same behavior.
opts = append(opts, json.EscapeRune(nil))
// Append any user-specified options,
// which will override any previously set options.
opts = append(opts, h.opts.JSONOptions...)
return json.Marshal(v, opts...)

(You'll note that the options API for "json" above is different than what currently exists in "go-json-experiment/json". I mentioned elsewhere in #59339 that we're considering switching to variadic options as we see it as one of the ways to resolve the v1-to-v2 compatibility tensions).
(Also ignore the performance implications of appending a bunch of options right before calling json.Marshal; we can find ways to to optimize this. Let's focus on semantics.)

Thus, for someone to use v2 "json" with "slog", they would do something like:

slog.HandlerOptions{
    JSONOptions: []json.Option{json.DefaultV2Options},
}.NewJSONHandler(...)

I should also note that DefaultV1Options and DefaultV2Options represent a composite set of options. For example DefaultV1Options includes AllowDuplicateNames(true) while DefaultV2Options includes AllowDuplicateNames(false).

You could also simplify the above by providing NewJSONv2Handler that implicitly inserts json.DefaultV2Options before user-specified options.

One could imagine that "slog" inspects HandlerOptions.JSONOptions and checks AllowDuplicateNames:

• If true, it does what it currently does (i.e., just emits duplicate object members)
• If false, it does automatic name-deduplication similar to what I proposed in log/slog: JSONHandler should deduplicate keys #59365 (comment).

[jba]

Thanks, @dsnet, that makes a lot of sense.

[08d2]

It would be very unexpected if repeated calls to Log with the same key "duplicate" were to produce output like {"duplicate": "alpha", "duplicate#01": "bravo", "duplicate#02": "charlie"}. Among many other reasons, this behavior would make it impossible to reliably assert that a log event emitted with some key K would actually be rendered with that key K in the ultimate output format.

Structured logging defines a concept of a log event which is conceptually above any specific encoding like JSON or logfmt or et cetera. That concept of a log event is well-defined by convention, and that definition doesn't accommodate repeated keys.

[dsnet]

It would be very unexpected if repeated calls to Log with the same key "duplicate" were to produce output like {"duplicate": "alpha", "duplicate#01": "bravo", "duplicate#02": "charlie"}.

Possibly, but there are no good answers when it comes to duplicate names.

It would be nice if the API made it statically impossible to have duplicates,
but I don't see how that can be done without taking in a map[string]any as the input,
which would not be performant.

Given the possibility of runtime duplicates, your options are:

1. Emit the object with all duplicate fields
2. Emit the object, but only keep one of the duplicate fields (e.g., the first occurrence)
3. Rename the duplicate fields to avoid a conflict
4. Report an error
   a. and still do either 1, 2, or 3
   b. or simply reject the message and not log it.

With option 1, you risk the log parser later not being able to read the message entirely or accurately. Duplicate names result in undefined behavior where the parser might ignore duplicates, only use the first one, only use the last one, or use some merged form of all duplicates.

With option 2, you avoid any ambiguities when reading, but are subtly dropping information when writing.

With option 3, you avoid any ambiguities as to the meaning when reading, but are changing the meaning when writing. At least the meaning when reading is consistent across all parsers.

Option 4a is decent as it allows the caller to at least realize that they're possibly holding the API wrong, but I suspect most people will not check the error of logging calls.

Of all the bad options, option 4a with either 1 or 3 is probably the best approach.
Options 2 and 4b discard information, which seems antithetical to the point of a logging library.

[08d2]

Option 2 is pretty clearly the correct choice.

Options 2 and 4b discard information, which seems antithetical to the point of a logging library.

I'm not sure why anyone would expect a structured logging library to never discard information. Emitting multiple structured log events with the same key is pretty clearly going to resolve to a single "winner" for that key, most likely the last event, but really any event would be acceptably valid.

[dsnet]

Option 2 is pretty clearly the correct choice.

That's a matter of opinion. Just as how you find option 3 an odd position, I find option 2 an odd position. Every option has pros and cons.

I'm not sure why anyone would expect a structured logging library to never discard information.

Any value passed to LogAttrs by the programmer carries fairly clear intent that it be logged. Arbitrarily choosing some field to keep, while discarding all others goes against the intent. Thus, my expectation is for a logging library to try hard to never discard information.

[08d2]

Values passed to a structured logging library necessarily include a key which is, by definition, understood as unique within the target log event. So, no: it's definitely not the case that calling a structured logging method like LogAttrs can be assumed to produce any specific log output. Structured logging is, hopefully obviously, not equivalent to log.Printf, or fmt.Printf, or anything like that.

[veqryn]

@dsnet For option 4, how would an error be reported? A separate log line at warning level, or some out-of-band channel or something?

Personally I would have probably expected option 2, where the latest value wins (except that the Message, Time, Level, and Source fields would always win over any Attribute values).

My preferences, would probably be:
option 2 or 4a2
option 3 or 4a3

option 1 would break a lot of log aggregation systems
option 4b would seem like the worst option, as you lose the log line completely, making any error even harder to diagnose