Log correct caller information when SpanLogger is used

[charleskorn]

What this PR does:

This PR ensures that correct caller information is logged when SpanLogger is used.

Previously, messages logged with SpanLogger would have caller=spanlogger.go:xxx.

Unfortunately we can't retrieve the existing Caller instance configured in the logger and replace it with another with an increased stack depth, as there's no way to retrieve existing key/value pairs associated with a logger. So instead I've created a spanLoggerAwareCaller that determines the correct stack depth when it is first used.

For similar reasons, this also makes it difficult to only add caller information when the logger is configured to provide caller information, and so SpanLoggers will now unconditionally add caller information to all messages logged. Given all of the applications I checked (Mimir, Loki and Tempo) configure their loggers to include caller information, this doesn't seem to be a big issue, but it did require some changes to some tests that assert on log messages emitted through a SpanLogger.

Which issue(s) this PR fixes:

(none)

Checklist

• Tests updated
• CHANGELOG.md updated - the order of entries should be [CHANGE], [FEATURE], [ENHANCEMENT], [BUGFIX]

[bboreham]

Is there a benchmark for this code?
Particularly interested whether we pay the stack-trace price for logs that are filtered out, eg debug logs.

[aknuds1]

LGTM, excepting @bboreham's question, and please also see my comment about possibly using filepath.Base.

[charleskorn]

Is there a benchmark for this code? Particularly interested whether we pay the stack-trace price for logs that are filtered out, eg debug logs.

I've added one in 273af4f. (The existing BenchmarkSpanLogger benchmark didn't exercise the right behaviour, as the values are never evaluated in that benchmark.)

Results:

goos: darwin
goarch: arm64
pkg: github.com/grafana/dskit/spanlogger
                                                               │  main.txt   │              after.txt              │
                                                               │   sec/op    │   sec/op     vs base                │
SpanLoggerWithRealLogger/info_and_above_allowed/log-10           1.193µ ± 1%   1.995µ ± 3%   +67.18% (p=0.002 n=6)
SpanLoggerWithRealLogger/info_and_above_allowed/level.debug-10   165.8n ± 1%   597.8n ± 4%  +260.66% (p=0.002 n=6)
SpanLoggerWithRealLogger/info_and_above_allowed/debuglog-10      3.837n ± 2%   3.901n ± 3%         ~ (p=0.223 n=6)
SpanLoggerWithRealLogger/all_levels_allowed/log-10               1.227µ ± 4%   1.999µ ± 2%   +62.88% (p=0.002 n=6)
SpanLoggerWithRealLogger/all_levels_allowed/level.debug-10       1.238µ ± 2%   2.054µ ± 1%   +66.02% (p=0.002 n=6)
SpanLoggerWithRealLogger/all_levels_allowed/debuglog-10          1.407µ ± 1%   2.341µ ± 3%   +66.41% (p=0.002 n=6)
geomean                                                          342.7n        595.7n        +73.83%

                                                               │   main.txt    │               after.txt               │
                                                               │     B/op      │     B/op      vs base                 │
SpanLoggerWithRealLogger/info_and_above_allowed/log-10           696.0 ± 15%     1040.0 ± 22%  +49.43% (p=0.002 n=6)
SpanLoggerWithRealLogger/info_and_above_allowed/level.debug-10   400.0 ±  0%      704.0 ±  0%  +76.00% (p=0.002 n=6)
SpanLoggerWithRealLogger/info_and_above_allowed/debuglog-10      0.000 ±  0%      0.000 ±  0%        ~ (p=1.000 n=6) ¹
SpanLoggerWithRealLogger/all_levels_allowed/log-10               696.0 ± 34%     1040.0 ± 22%  +49.43% (p=0.002 n=6)
SpanLoggerWithRealLogger/all_levels_allowed/level.debug-10       968.0 ±  0%     1304.0 ±  0%  +34.71% (p=0.002 n=6)
SpanLoggerWithRealLogger/all_levels_allowed/debuglog-10          904.0 ±  0%     1312.0 ±  0%  +45.13% (p=0.002 n=6)
geomean                                                                      ²                 +40.47%               ²
¹ all samples are equal
² summaries must be >0 to compute geomean

                                                               │   main.txt   │               after.txt               │
                                                               │  allocs/op   │  allocs/op   vs base                  │
SpanLoggerWithRealLogger/info_and_above_allowed/log-10           10.00 ± 0%      15.00 ± 0%   +50.00% (p=0.002 n=6)
SpanLoggerWithRealLogger/info_and_above_allowed/level.debug-10   5.000 ± 0%     10.000 ± 0%  +100.00% (p=0.002 n=6)
SpanLoggerWithRealLogger/info_and_above_allowed/debuglog-10      0.000 ± 0%      0.000 ± 0%         ~ (p=1.000 n=6) ¹
SpanLoggerWithRealLogger/all_levels_allowed/log-10               10.00 ± 0%      15.00 ± 0%   +50.00% (p=0.002 n=6)
SpanLoggerWithRealLogger/all_levels_allowed/level.debug-10       13.00 ± 0%      18.00 ± 0%   +38.46% (p=0.002 n=6)
SpanLoggerWithRealLogger/all_levels_allowed/debuglog-10          12.00 ± 0%      17.00 ± 0%   +41.67% (p=0.002 n=6)
geomean                                                                     ²                 +43.76%               ²
¹ all samples are equal
² summaries must be >0 to compute geomean

The extra cost comes because go-kit/log doesn't recognise that we've overridden the caller field, and so evaluates both the the caller added by SpanLogger, and the original caller added by the application. I'm not sure there's much we can do to avoid this without adding deduplication to go-kit/log that would make the non-SpanLogger logging path slower.

[charleskorn]

@bboreham are you satisfied with the benchmarks above? If you have any ideas on how to make this less costly, I'd love to hear them.

[charleskorn]

Given the approval, I'm going to merge this, but if there is any late feedback, I'd be happy to hear it.