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

Open
wants to merge 3 commits into
base: arve/upgrade-mimir-prometheus
Choose a base branch
from

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.

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:

```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 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?

Needed to make tests for the slog adapter play nicely with Mock.

Signed-off-by: TJ Hoplock <[email protected]>
- The adapter now uses a `preformatted` keys cache on the handler struct
  to more consistently order keys; msg is always first real key other
than timestamp/level
- as part of fixing group nesting, nested group key value pairs now take
  the form of `group1.group2.key=value`, update mock calls accordingly

Signed-off-by: TJ Hoplock <[email protected]>
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.

3 participants