Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix: go-kit/log-slog adapter fixes #9943

Conversation

tjhop
Copy link

@tjhop tjhop commented Nov 18, 2024

Changes included:

  • log/slog always includes timestamps by default; they are now included in the go-kit/log output. We make no attempts to adjust/remove any other timestamp keys (such as the often used ts kv pair in go-kit/log implementations).
  • a new function to handle properly appending/nesting our kv pairs for the logger
  • proper handling of nested grouping
  • introduction of a preformatted field on the goKitHandler struct to cache previously added kv pairs containing log values. helpful to maintain the ordering of kv pairs added via multiple/nested/chained calls to a logger's .With() or .WithGroup() methods.
  • WithGroup() now returns a new handler struct, as opposed to updating itself (as recommended by slog implementation docs).

Not addressed:

  • tests still need to be updated. they currently use a mock logger, and the log lines have timestamps included. Since timestamps aren't deterministic, they're not easy to mock. I refrained from creating a wrapper interface to mock the time just for sake of testing; I used pattern matching with regexs when implementing slog tests for prometheus/common's promslog pkg.
  • I haven't found a good way to (programmatically) address call depth when getting source caller info. Using a call depth of 6 (see code snippet) seems to properly unwind back to the originating .Info() etc method call, but I haven't checked other options.

Example output, after shimming the following logging calls into the existing handler test suite:

gkadapterLogger := SlogFromGoKit(log.With(log.NewLogfmtLogger(os.Stderr), "caller", log.Caller(6)))
gkadapterLogger.Info("go-kit/log adapter output")
gkadapterLogger.WithGroup("g1").WithGroup("g2").Info("test1", "hello", "world")
gkadapterLogger.WithGroup("g1").With("hello", "world").Info("test2", "hello", "world")
gkadapterLogger.WithGroup("g1").With("hello", "world").WithGroup("g2").Info("test3", "hello", "world")
gkadapterLogger.With("hello", "world").With("hello", "world").Info("test4", "hello", "world")
// Output:
// level=info caller=slogadapter_test.go:26 time=2024-11-18T13:09:59.674350655-05:00 msg=test1 g1.g2.hello=world
// level=info caller=slogadapter_test.go:27 time=2024-11-18T13:09:59.674376383-05:00 msg=test2 g1.hello=world g1.hello=world
// level=info caller=slogadapter_test.go:28 time=2024-11-18T13:09:59.674392598-05:00 msg=test3 g1.hello=world g1.g2.hello=world
// level=info caller=slogadapter_test.go:29 time=2024-11-18T13:09:59.674419421-05:00 msg=test4 hello=world hello=world hello=world

What this PR does

Which issue(s) this PR fixes or relates to

Fixes #

Checklist

  • Tests updated.
  • Documentation added.
  • CHANGELOG.md updated - the order of entries should be [CHANGE], [FEATURE], [ENHANCEMENT], [BUGFIX].
  • about-versioning.md updated with experimental features.

@tjhop tjhop requested a review from a team as a code owner November 18, 2024 18:17
@CLAassistant
Copy link

CLAassistant commented Nov 18, 2024

CLA assistant check
All committers have signed the CLA.

aknuds1
aknuds1 previously approved these changes Nov 18, 2024
Copy link
Contributor

@aknuds1 aknuds1 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, thanks

@aknuds1 aknuds1 dismissed their stale review November 18, 2024 19:14

Tests are failing.

Copy link
Contributor

@aknuds1 aknuds1 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you fix failing tests?

@aknuds1 aknuds1 force-pushed the arve/upgrade-mimir-prometheus branch from 78797ed to d920e20 Compare November 19, 2024 08:48
@aknuds1 aknuds1 requested review from stevesg, grafanabot and a team as code owners November 19, 2024 08:49
Copy link
Contributor

@dimitarvdimitrov dimitarvdimitrov left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

can you explain why we need so many changes to the libraries
Screenshot 2024-11-19 at 11 18 30

Screenshot 2024-11-19 at 11 18 47

I'm especially concerned about the prometheus vendoring. Is this pulling in v3 changes?

@aknuds1
Copy link
Contributor

aknuds1 commented Nov 19, 2024

@dimitarvdimitrov this is a PR against my PR :)

@dimitarvdimitrov dimitarvdimitrov dismissed their stale review November 19, 2024 09:23

it's all good, I thought we're merging against main here. whew

Changes included:
- log/slog always includes timestamps by default; they are now included
  in the go-kit/log output. We make no attempts to adjust/remove any
other timestamp keys (such as the often used `ts` kv pair in go-kit/log
implementations).
- a new function to handle properly appending/nesting our kv pairs for
  the logger
- proper handling of nested grouping
- introduction of a `preformatted` field on the goKitHandler struct to
  cache previously added kv pairs containing log values. helpful to
maintain the ordering of kv pairs added via multiple/nested/chained
calls to a logger's `.With()` or `.WithGroup()` methods.
- WithGroup() now returns a new handler struct, as opposed to updating
  itself (as recommended by slog implementation docs).
- Update test suite to allow stripping timestamps from logs to prevent
  non-deterministic output
- Update test suite mock setup to validate correct log formatting, now
  that kv pairs for logs follow the pattern `group1.group2.key=value`

Not addressed:
- I haven't found a good way to (programmatically) address call depth
  when getting source caller info. Using a call depth of 6 (see code
snippet) seems to properly unwind back to the originating `.Info()` etc
method call, but I haven't checked other options.

Example output, after shimming the following logging calls into the
existing handler test suite:

```go
gkadapterLogger := SlogFromGoKit(log.With(log.NewLogfmtLogger(os.Stderr), "caller", log.Caller(6)))
gkadapterLogger.Info("go-kit/log adapter output")
gkadapterLogger.WithGroup("g1").WithGroup("g2").Info("test1", "hello", "world")
gkadapterLogger.WithGroup("g1").With("hello", "world").Info("test2", "hello", "world")
gkadapterLogger.WithGroup("g1").With("hello", "world").WithGroup("g2").Info("test3", "hello", "world")
gkadapterLogger.With("hello", "world").With("hello", "world").Info("test4", "hello", "world")
// Output:
// level=info caller=slogadapter_test.go:26 time=2024-11-18T13:09:59.674350655-05:00 msg=test1 g1.g2.hello=world
// level=info caller=slogadapter_test.go:27 time=2024-11-18T13:09:59.674376383-05:00 msg=test2 g1.hello=world g1.hello=world
// level=info caller=slogadapter_test.go:28 time=2024-11-18T13:09:59.674392598-05:00 msg=test3 g1.hello=world g1.g2.hello=world
// level=info caller=slogadapter_test.go:29 time=2024-11-18T13:09:59.674419421-05:00 msg=test4 hello=world hello=world hello=world
```

Signed-off-by: TJ Hoplock <[email protected]>
@tjhop
Copy link
Author

tjhop commented Nov 19, 2024

@dimitarvdimitrov I rebased on @aknuds1's PR, the change set is now accurate (and much more reasonably sized 🙃 )

@dimitarvdimitrov
Copy link
Contributor

i'll leave the reviews to @aknuds1 since he's already involved

@aknuds1 aknuds1 force-pushed the arve/upgrade-mimir-prometheus branch from 1e5912c to e414b00 Compare November 20, 2024 07:58
@tjhop tjhop closed this Nov 27, 2024
@tjhop
Copy link
Author

tjhop commented Nov 27, 2024

Closing this PR in favor of library adoption in the parent PR

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants