slog support + logr 1.3.0 update #384

pohly · 2023-09-14T14:42:57Z

What this PR does / why we need it:

Libraries might start to use the new slog/slog API. Support is needed in a logging backend like klog.

When compiled with Go >= 1.21, special support for log/slog gets enabled
automatically:

The formatting of key/value pairs supports slog.Value and slog.LogValuer,
regardless of where those come from.
A slog.GroupValue is formatted as a JSON object.
The logger returned by klog.Background() and the textlogger
support usage as a backend for the slog API, via slogr.NewSlogHandler,
with builtin support for handling a slog.Record. However, -vmodule
does not work when called like that because stack unwinding during
the Enabled check finds the wrong source code.

The klogr package doesn't get updated. It shouldn't be used anymore. To make
that clearer, it gets marked as "deprecated".

Examples demonstrate the resulting output. That output has to be exactly
the same when used as test, so pid and time get set to fixed values.

Special notes for your reviewer:

Key/value pairs still to be given as two values per pair. Using a slog.Attr could be supported (would imply changing logcheck!), but would not be very portable.

Release note:

add slog support

k8s-ci-robot · 2023-09-14T14:43:05Z

This issue is currently awaiting triage.

If klog contributors determine this is a relevant issue, they will accept it by applying the triage/accepted label and provide further guidance.

The triage/accepted label can be added by org members by writing /triage accepted in a comment.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

LogSink.Enabled is sensitive to stack unwinding. logr v1.2.0 got this wrong by calling LogSink.Enabled at different depths for Logger.Info and Logger.Enabled, therefore this test fails with that version. logr v1.3.0 changes the behavior to the more sane "LogSink.Enabled needs to skip one level, regardless where it is called". The Discard log sink implementation changed such that a discard logger doesn't have a sink at all anymore. Go < 1.18 is no longer supported by logr.

mengjiao-liu

I guess the WIP can be removed now?

Check back tomorrow for the rest...

mengjiao-liu · 2023-10-30T10:43:45Z

klogr_test.go

+	"k8s.io/klog/v2"
+)
+
+func TestVerbosity(t *testing.T) {


Which function is this test function testing against?
for this klog.VDepth(l.callDepth+1, klog.Level(level)).Enabled() ？

Or is it just a missing test before? I don't see the code to be tested in this PR. Is this test any different from the previous behavior? Maybe I'm missing something.

It's a test that was missing before, about handling of the logr.Logger.Enabled call. The behavior of that call changed in 1.3.0 with regards to the call depth.

If you look at the first commit in this PR, then you'll see that textlogger/textlogger.go has a change related to this.

harshanarayana · 2023-10-30T13:41:53Z

contextual_test.go

@@ -56,3 +59,52 @@ func ExampleFlushLogger() {
 	// Output:
 	// flushing...
 }
+
+func BenchmarkPassingLogger(b *testing.B) {
+	b.Run("context", func(b *testing.B) {


Nit:

Suggested change

b.Run("context", func(b *testing.B) {

b.Run("with context", func(b *testing.B) {

might be more readable.

harshanarayana · 2023-10-30T13:42:20Z

contextual_test.go

+		runtime.KeepAlive(finalCtx)
+	})
+
+	b.Run("directly", func(b *testing.B) {


Suggested change

b.Run("directly", func(b *testing.B) {

b.Run("without context", func(b *testing.B) {

nit: May be this might be a bit more readable ?

harshanarayana · 2023-10-30T13:42:34Z

contextual_test.go

+		runtime.KeepAlive(finalLogger)
+	})
+
+	b.Run("directly", func(b *testing.B) {


Same as above.

I've changed to "from context" and removed the "directly" here, because it's the same as the case above (there's no additional work for extraction).

harshanarayana · 2023-10-30T13:47:32Z

internal/buffer/buffer.go

+	if Time != nil {
+		now = *Time
+	}


Is there no way to avoid having to do this? From what I can think of, this is mostly test only use case than anything else. I know go test examples need a strict string match. Is there a way we can work around this somehow ? This is more of a question than something that needs to be fixed before we can get this change in.

This one will add a condition check for each of the Format or Sprint header calls unnecessarily.

This is needed for Example* style unit tests where the output is matched verbatim. There is no workaround for this, upstream Go recommends to make all output of such tests deterministic.

harshanarayana · 2023-10-30T13:48:24Z

internal/serialize/keyvalues_no_slog.go

+// +build !go1.21
+
+/*
+Copyright 2021 The Kubernetes Authors.


Might be a silly question. But don't we need to fix the year on this copyright ?

For new files, as in this case, yes. Will do.

For existing files it's normal to not bump it up, even when adding or modifying content.

internal/serialize/keyvalues_slog.go also had 2021 - fixed as well.

harshanarayana · 2023-10-30T13:57:38Z

internal/sloghandler/sloghandler_slog.go

+	switch {
+	case level >= slog.LevelError:
+		s = severity.ErrorLog
+	case level >= slog.LevelWarn:
+		s = severity.WarningLog
+	}


Might be a good idea to document why this is being done as a comment ?

harshanarayana · 2023-10-30T14:00:37Z

k8s_references_slog.go

+	return slog.AnyValue(ks.MarshalLog())
+}
+
+var _ slog.LogValuer = ObjectRef{}


This is duplicate of line 33 right ? Should this not be

Suggested change

var _ slog.LogValuer = ObjectRef{}

var _ slog.LogValuer = kobjSlice{}

Ooops. Yes, fixed.

harshanarayana · 2023-10-30T14:08:47Z

textlogger/textlogger_slog_test.go

+		"coordinates", coordinates{x: 100, y: 200},
+	)
+
+	// Output:
+	// I1224 12:30:40.000000     123 textlogger_slog_test.go:55] "A debug message"
+	// I1224 12:30:40.000000     123 textlogger_slog_test.go:57] "An info message"
+	// W1224 12:30:40.000000     123 textlogger_slog_test.go:58] "A warning"
+	// E1224 12:30:40.000000     123 textlogger_slog_test.go:59] "An error" err="fake error"
+	// I1224 12:30:40.000000     123 textlogger_slog_test.go:62] "Grouping" top.int=42 top.variables={"a":1,"b":2} top.sub={"str":"abc","bool":true,"bottom":{"coordinates":{"X":-1,"Y":-2}}} top.duration="1s" top.pi=3.12 top.e=2.71 top.moreCoordinates={"X":100,"Y":200}
+	// I1224 12:30:40.000000     123 textlogger_slog_test.go:78] "slog values" variables={"a":1,"b":2} duration="1s" coordinates={"X":100,"Y":200}
+}


Let us say for the sake of discussion, Instead of example based tests, if we turn these into regular tests and capture the data in buffers, can we use regex based validation for the output and avoid having to perform testlogger.FixedTime calls ? If you don't think that is not as user friendly as the current one, I am all right since you have already marked the exposed API as experimental

I prefer the Example* style test because it has additional benefits (shows up in gopkg, gives users a preview what the output will look like).

When compiled with Go >= 1.21, special support for log/slog gets enabled automatically: - The formatting of key/value pairs supports slog.Value and slog.LogValuer, regardless of where those come from. - A slog.GroupValue is formatted as a JSON object. - The logger returned by klog.Background() and the textlogger support usage as a backend for the slog API, via slogr.NewSlogHandler, with builtin support for handling a slog.Record. However, -vmodule does not work when called like that because stack unwinding during the Enabled check finds the wrong source code. - KObj (= ObjectRef) and the type behind KObjSlice support the slog.LogValuer interface and thus get formatted properly by slog backends. The klogr package doesn't get updated. It shouldn't be used anymore. To make that clearer, it gets marked as "deprecated". Examples demonstrate the resulting output. That output has to be exactly the same when used as test, so pid and time get set to fixed values.

pohly · 2023-10-30T14:25:41Z

@harshanarayana: update pushed.

mengjiao-liu · 2023-10-30T14:33:58Z

from my side
/lgtm

wait for @harshanarayana confirm.
Once the PR can be merged, you can cancel the hold at any time
/hold

harshanarayana · 2023-10-31T09:06:45Z

/lgtm
/cc @dims

pohly · 2023-10-31T10:32:23Z

/hold cancel

dims · 2023-10-31T10:40:49Z

/approve

k8s-ci-robot · 2023-10-31T10:40:58Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: dims, harshanarayana, mengjiao-liu, pohly

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [dims]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

[![Mend Renovate](https://app.renovatebot.com/images/banner.svg)](https://renovatebot.com) This PR contains the following updates: | Package | Type | Update | Change | |---|---|---|---| | [k8s.io/klog/v2](https://togithub.com/kubernetes/klog) | require | minor | `v2.100.1` -> `v2.110.1` | --- ### Release Notes <details> <summary>kubernetes/klog (k8s.io/klog/v2)</summary> ### [`v2.110.1`](https://togithub.com/kubernetes/klog/releases/tag/v2.110.1): Prepare klog release for Kubernetes v1.29 (Take 1) [Compare Source](https://togithub.com/kubernetes/klog/compare/v2.100.1...v2.110.1) #### What's Changed - fix: SetLogger via klog.SetLogger will output an unexpected newline by [@aimuz](https://togithub.com/aimuz) in [https://github.com/kubernetes/klog/pull/378](https://togithub.com/kubernetes/klog/pull/378) - resolve comments warning by [@lowang-bh](https://togithub.com/lowang-bh) in [https://github.com/kubernetes/klog/pull/379](https://togithub.com/kubernetes/klog/pull/379) - stderrthreshold: fix flag comment by [@pohly](https://togithub.com/pohly) in [https://github.com/kubernetes/klog/pull/376](https://togithub.com/kubernetes/klog/pull/376) - enable "go vet" checks for parameters by [@pohly](https://togithub.com/pohly) in [https://github.com/kubernetes/klog/pull/390](https://togithub.com/kubernetes/klog/pull/390) - promote experimental code to stable by [@pohly](https://togithub.com/pohly) in [https://github.com/kubernetes/klog/pull/392](https://togithub.com/kubernetes/klog/pull/392) - golangci-lint action by [@pohly](https://togithub.com/pohly) in [https://github.com/kubernetes/klog/pull/380](https://togithub.com/kubernetes/klog/pull/380) - output: handle WithName like zapr does by [@pohly](https://togithub.com/pohly) in [https://github.com/kubernetes/klog/pull/391](https://togithub.com/kubernetes/klog/pull/391) - slog support + logr 1.3.0 update by [@pohly](https://togithub.com/pohly) in [https://github.com/kubernetes/klog/pull/384](https://togithub.com/kubernetes/klog/pull/384) #### New Contributors - [@aimuz](https://togithub.com/aimuz) made their first contribution in [https://github.com/kubernetes/klog/pull/378](https://togithub.com/kubernetes/klog/pull/378) - [@lowang-bh](https://togithub.com/lowang-bh) made their first contribution in [https://github.com/kubernetes/klog/pull/379](https://togithub.com/kubernetes/klog/pull/379) **Full Changelog**: kubernetes/klog@v2.100.1...v2.110.1 </details> --- ### Configuration 📅 **Schedule**: Branch creation - At any time (no schedule defined), Automerge - At any time (no schedule defined). 🚦 **Automerge**: Disabled by config. Please merge this manually once you are satisfied. ♻ **Rebasing**: Whenever PR becomes conflicted, or you tick the rebase/retry checkbox. 🔕 **Ignore**: Close this PR and you won't be reminded about this update again. --- - [ ] If you want to rebase/retry this PR, check this box --- This PR has been generated by [Mend Renovate](https://www.mend.io/free-developer-tools/renovate/). View repository job log [here](https://developer.mend.io/github/hetznercloud/hcloud-cloud-controller-manager).  Co-authored-by: renovate[bot] <29139614+renovate[bot]@users.noreply.github.com>

k8s-ci-robot added do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. labels Sep 14, 2023

k8s-ci-robot requested review from harshanarayana and thockin September 14, 2023 14:43

k8s-ci-robot added the size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. label Sep 14, 2023

pohly force-pushed the slog branch from afd6a48 to c64abe2 Compare September 15, 2023 12:10

pohly force-pushed the slog branch from c64abe2 to 77259d1 Compare October 26, 2023 18:45

pohly force-pushed the slog branch from 77259d1 to 531b368 Compare October 27, 2023 06:04

pohly changed the title ~~WIP: slog support~~ slog support + logr 1.3.0 update Oct 27, 2023

k8s-ci-robot removed the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label Oct 27, 2023

pohly mentioned this pull request Oct 27, 2023

WIP: adapt -vmodule support to logr v1.3.0 #383

Closed

pohly changed the title ~~slog support + logr 1.3.0 update~~ WIP: slog support + logr 1.3.0 update Oct 27, 2023

k8s-ci-robot added the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label Oct 27, 2023

mengjiao-liu reviewed Oct 30, 2023

View reviewed changes

pohly changed the title ~~WIP: slog support + logr 1.3.0 update~~ slog support + logr 1.3.0 update Oct 30, 2023

k8s-ci-robot removed the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label Oct 30, 2023

harshanarayana reviewed Oct 30, 2023

View reviewed changes

pohly force-pushed the slog branch from 531b368 to 44eadc3 Compare October 30, 2023 14:22

k8s-ci-robot added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Oct 30, 2023

k8s-ci-robot assigned mengjiao-liu Oct 30, 2023

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Oct 30, 2023

k8s-ci-robot requested a review from dims October 31, 2023 09:06

k8s-ci-robot assigned harshanarayana Oct 31, 2023

k8s-ci-robot removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Oct 31, 2023

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Oct 31, 2023

k8s-ci-robot merged commit e3f75b8 into kubernetes:main Oct 31, 2023
17 checks passed

platform-engineering-bot mentioned this pull request Mar 16, 2024

Update go updates arcalot/arcaflow-lib-kubernetes-go#15

Closed

1 task

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

slog support + logr 1.3.0 update #384

slog support + logr 1.3.0 update #384

pohly commented Sep 14, 2023 •

edited

Loading

k8s-ci-robot commented Sep 14, 2023

mengjiao-liu left a comment

mengjiao-liu Oct 30, 2023

pohly Oct 30, 2023

harshanarayana Oct 30, 2023

pohly Oct 30, 2023

harshanarayana Oct 30, 2023

pohly Oct 30, 2023

harshanarayana Oct 30, 2023

pohly Oct 30, 2023

harshanarayana Oct 30, 2023

pohly Oct 30, 2023

harshanarayana Oct 30, 2023

pohly Oct 30, 2023

pohly Oct 30, 2023

harshanarayana Oct 30, 2023

pohly Oct 30, 2023

harshanarayana Oct 30, 2023

pohly Oct 30, 2023

harshanarayana Oct 30, 2023

pohly Oct 30, 2023

pohly commented Oct 30, 2023

mengjiao-liu commented Oct 30, 2023

harshanarayana commented Oct 31, 2023

pohly commented Oct 31, 2023

dims commented Oct 31, 2023

k8s-ci-robot commented Oct 31, 2023

	b.Run("context", func(b *testing.B) {
	b.Run("with context", func(b *testing.B) {

	b.Run("directly", func(b *testing.B) {
	b.Run("without context", func(b *testing.B) {

	var _ slog.LogValuer = ObjectRef{}
	var _ slog.LogValuer = kobjSlice{}

slog support + logr 1.3.0 update #384

slog support + logr 1.3.0 update #384

Conversation

pohly commented Sep 14, 2023 • edited Loading

k8s-ci-robot commented Sep 14, 2023

mengjiao-liu left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pohly commented Oct 30, 2023

mengjiao-liu commented Oct 30, 2023

harshanarayana commented Oct 31, 2023

pohly commented Oct 31, 2023

dims commented Oct 31, 2023

k8s-ci-robot commented Oct 31, 2023

pohly commented Sep 14, 2023 •

edited

Loading