proposal: log/slog: option to print msg key last

[ekkagra]

Proposal Details

Consider the output of slog Text or JSON handler log outputs for below code

	logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
	logger.Info("hello", "count", 3)

	logger2 := logger.With("app", "alpha")
	logger3 := logger.With("app", "beta ")
	loggerGrp := logger3.WithGroup("grp1")

	logger2.Info("short msg", "id", 1)
	logger3.Info("long long long long abc def abc msg", "count", 100)
	loggerGrp.Info("asd asd asd asd asd", "code", "ok")
	loggerGrp.Warn("not found", "id", 1000)
	logger2.Info("short msg", "id", 1)
	logger3.Info("long long long long abc def abc msg", "count", 100)
	loggerGrp.Info("asd asd asd asd asd", "code", "ok")
	loggerGrp.Warn("not found", "id", 1000)

Output - JSONHandler

{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"hello","count":3}
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"short msg","app":"alpha","id":1}
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"long long long long abc def abc msg","app":"beta ","count":100}
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"asd asd asd asd asd","app":"beta ","grp1":{"code":"ok"}}
{"time":"2009-11-10T23:00:00Z","level":"WARN","msg":"not found","app":"beta ","grp1":{"id":1000}}
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"short msg","app":"alpha","id":1}
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"long long long long abc def abc msg","app":"beta ","count":100}
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"asd asd asd asd asd","app":"beta ","grp1":{"code":"ok"}}
{"time":"2009-11-10T23:00:00Z","level":"WARN","msg":"not found","app":"beta ","grp1":{"id":1000}}

Although, this is easily machine parsable, but this doesn't look very human readable from one aspect.
When reading logs, the Attr added using With or WithGroup are added in end. This makes it difficult to navigate and find next line of interest.
The value for msg key is variable in length. As humans normally read from left to right, it takes effort to find the next common key attribute. E.g. in above case, the common key attribute is app which could be either alpha or beta.

If msg is added last, all Attr added via With and WithGroup will be better visually aligned. It will be easy to jump to next log for say "app": "alpha".

{"time":"2009-11-10T23:00:00Z","level":"INFO","count":3,"msg":"hello"}
{"time":"2009-11-10T23:00:00Z","level":"INFO","count":3,"msg":"hello"}
{"time":"2009-11-10T23:00:00Z","level":"INFO","app":"alpha","id":1,"msg":"short msg"}
{"time":"2009-11-10T23:00:00Z","level":"INFO","app":"beta ","count":100,"msg":"long long long long abc def abc msg"}
{"time":"2009-11-10T23:00:00Z","level":"INFO","app":"beta ","grp1":{"code":"ok"},"msg":"asd asd asd asd asd"}
{"time":"2009-11-10T23:00:00Z","level":"WARN","app":"beta ","grp1":{"id":1000},"msg":"not found"}
{"time":"2009-11-10T23:00:00Z","level":"INFO","app":"alpha","id":1,"msg":"short msg"}
{"time":"2009-11-10T23:00:00Z","level":"INFO","app":"beta ","count":100,"msg":"long long long long abc def abc msg"}
{"time":"2009-11-10T23:00:00Z","level":"INFO","app":"beta ","grp1":{"code":"ok"},"msg":"asd asd asd asd asd"}
{"time":"2009-11-10T23:00:00Z","level":"WARN","app":"beta ","grp1":{"id":1000},"msg":"not found"}

If some flag in HandlerOptions is added like AddMsgInLast, it will make reading logs easier for cases like

1. loggers grouped into some heirarchy using With/WithGroup
2. multiple go programs running in same container but having common key attributes like "app": "alpha", "app": "beta " for differentiation.

[gabyhelp]

Related Issues and Documentation

• log/slog: JSONHandler should deduplicate keys #59365
• log/slog: inconsistent handling of empty groups #61067 (closed)

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[ianlancetaylor]

CC @jba

I think the pain of making a change like this at this point outweighs the benefit. It would break too many working tests.

[jba]

As usual, the answer here is to write your own slog.Handler.
Also, the JSON format isn't really for people. Use slog.TextHandler, or view the JSON logs with some sort of formatter. You can probably write a jq expression to get what you want.

[seankhliao]

afaik most other structured loggers also put the message first since it contains the most important information. as mentioned above, filtering should be done with other tools if necessary

[ekkagra]

I agree that JSONHandler isn't for people. But TextHandler output also brings up the same issue.

Filtering logs may not always be feasible. Sometimes the log has to be read as is for establishing event timings from multiple goroutines or applications. Filtering logs will not give the complete picture.

Say some container is running multiple go applications along with some non-go app which doesn't follow any logging pattern.
If logs are filtered for {"app": "alpha"}, it will be difficult to compare timing of events against logs from other applications.

Also, creating loggers using With effectively adds a sort of identifier to each log output. As log identifiers for stacked up right in end of log, one has to scan each line to see if the line was of interest.

My point is that:
For a machine or log parser, the presence of "msg" key is enough irrespective of its location, but for human it helps having identifiers placed early on in the log output.

[gopherbot]

Change https://go.dev/cl/619795 mentions this issue: log/slog: Add MessageLast option in slog HandlerOptions