contrib/log/slog: fix WithAttrs and WithGroup implementation

[rarguelloF]

What does this PR do?

Fixes #2838

Motivation

Since we were embedding the wrapped slog.Handler, we were using the original implementation of WithAttrs and WithGroup from the original handler, and therefore losing our custom implementation that adds the trace and span ids.

Also, as @shota3506 mentioned in #2839, the tricky part is the Group implementation, since DataDog expected the dd.trace_id and dd.span_id keys to be root level. Hopefully this implementation solves this issue.

In addition, it changes the type used for these fields from slog.Uint64 to slog.String as recommended in the docs.

Reviewer's Checklist

• Changed code has unit tests for its functionality at or near 100% coverage.
• System-Tests covering this feature have been added and enabled with the va.b.c-dev version tag.
• There is a benchmark for any new code, or changes to existing code.
• If this interacts with the agent in a new way, a system test has been added.
• Add an appropriate team label so this PR gets put in the right place for the release notes.
• Non-trivial go.mod changes, e.g. adding new modules, are reviewed by @DataDog/dd-trace-go-guild.

Unsure? Have a question? Request a review!

[pr-commenter]

Benchmarks

Benchmark execution time: 2024-10-18 13:55:16

Comparing candidate commit 221dcff in PR branch rarguelloF/AIDM-326/fix-slog with baseline commit 62ebcc3 in branch main.

Found 0 performance improvements and 0 performance regressions! Performance is the same for 58 metrics, 1 unstable metrics.

[shota3506]

Thank you for addressing the issue. Let me leave one comment.

[shota3506]

It is possible that the same group name appears multiple times.
I think it might be better to keep the attributes by using the depth of groups.
like groupAttrs [][]slog.Attr

[rarguelloF]

@shota3506 you are right, nice catch! 👍

[mtoffl01]

So everytime Handle is invoked, we have to copy over the existing attributes + the new trace attributes, as well as the existing groups?
Is this a performance concern? Is Handle called often?

[rarguelloF]

I think this is definitely gonna have a performance impact. Not sure about slog internals, but I would assume this is called every time a log entry is created (so depends on the application). Sadly, I don't see another way to solve the .Group issue without the performance impact.

However this is a nice call, I will write a benchmark to measure how worse this is 👍

[mtoffl01]

So a call to WithAttrs applies attributes to the most-recently added group. I'm assuming WithAttrs is only ever called when initializing the Handler, like this?

Handler.WithAttrs(<attr1>).WithGroup(<group1>).WithAttrs(<attr2>)

(Where attr1 is applied globally to the handler, and attr2 is applied to group1?)

If you were to use it like this:

handler := Handler.WithGroup(<group1>)
<some other stuff>
handler = handler.WithGroup(<group2>)
<some other stuff>
handler = handler.WithAttrs(<attr1>)

Then it's less obvious that attr1 would be applied to only group2.

So just confirming this is all in-line with how slog is used. 👍

[rarguelloF]

The handler methods are not called directly, these are used through the slog api like:

logger := slog.Default().With("id", systemID).WithGroup("group").With("nested", "attr")

Feel free to check the slog documentation to confirm, but basically what you said is correct 👍

[rarguelloF]

@mtoffl01 Wrote some more benchmarks locally, comparing the previous version BenchmarkHandlerV1, this version BenchmarkHandlerV2 and using the slog json handler without any trace correlation BenchmarkHandlerNoTracing and these are the results:

goos: darwin
goarch: arm64
pkg: gopkg.in/DataDog/dd-trace-go.v1/contrib/log/slog
cpu: Apple M1 Max
BenchmarkHandlerV2
BenchmarkHandlerV2-10           	  901525	      1320 ns/op
BenchmarkHandlerV1
BenchmarkHandlerV1-10           	 2981733	       398.7 ns/op
BenchmarkHandlerNoTracing
BenchmarkHandlerNoTracing-10    	 2982792	       397.8 ns/op
PASS

Since these changes have a notable performance degradation compared to the previous version, I will mark the PR as draft for now to discuss if there's an alternative approach.

[felixge]

I've taken a close look at this and also experimented with some code ideas. My main takeaways are:

1. This is tricky indeed. slog doesn't seem to offer a good way to log an attribute at the root level on a grouped logger. It might be worth raising an upstream issue for this.
2. The performance of the new implementation is okay. We should prioritize being correct over being fast here, and comparing ourselves to a previous baseline that was not working correctly isn't really a very useful way to think about overhead. I also suspect that logging on a pre-grouped or pre-attributed logger isn't happening all that much in practice, so we won't always get the worst-case overhead from this in many cases.

So I think we should go ahead with this.

[rarguelloF]

@felixge great, thanks so much for taking a look!