klog 2.20.0, logr v1.1.0, zapr v1.1.0 #104103

pohly · 2021-08-03T15:39:14Z

What type of PR is this?

/kind cleanup
/kind api-change

What this PR does / why we need it:

This replaces the experimental logr v0.4 with the stable v1.1.0
release. This is a breaking API change for some users because:

Comparing logr.Logger against nil is not possible anymore:
it's now a struct instead of an interface. Code which
allows a nil logger must switch to *logr.Logger as type.
Logger implementations must be updated in lockstep.

Instead of updating the forked zapr code in json.go, directly using
the original go-logr/zapr is simpler and avoids duplication of effort.

Which issue(s) this PR fixes:

Fixes #104097

Special notes for your reviewer:

The updated zapr supports logging of numeric verbosity. Error messages
don't have a verbosity (= always get logged), so "v" is not getting
added to them anymore.

Source code logging for panic messages got fixed so that it references
the code with the invalid log call, not the json.go implementation.

Finally, zapr includes additional information in its panic
messages ("zap field", "ignored key", "invalid key").

Does this PR introduce a user-facing change?

Users of LogFormatRegistry in component-base must update their code to use the logr v1.0.0 API. The JSON log output now uses the format from go-logr/zapr (no `v` field for error messages, additional information for invalid calls) and has some fixes (correct source code location for warnings about invalid log calls).

pohly · 2021-08-03T15:40:25Z

This is WIP because klog doesn't have a formal release yet and because there are known test failures in staging/src/k8s.io/component-base/logs/json.

pohly · 2021-08-03T17:32:50Z

This is failing because it uses Logger{} to denote an uninitialized logger instead of the former nil, but that then cause nil pointer access because klog does not (and cannot!) detect that such a struct is unusable.

thockin · 2021-08-03T17:50:33Z

Can you use `logr.Discard()` instead, if you need a valid Logger?

…

On Tue, Aug 3, 2021 at 10:33 AM Patrick Ohly ***@***.***> wrote: This is failing because it uses Logger{} to denote an uninitialized logger instead of the former nil, but that then cause nil pointer access because klog does not (and cannot!) detect that such a struct is unusable. — You are receiving this because your review was requested. Reply to this email directly, view it on GitHub, or unsubscribe. Triage notifications on the go with GitHub Mobile for iOS or Android.

fedebongio · 2021-09-02T20:04:12Z

/remove-sig api-machinery

pohly · 2021-09-02T20:49:25Z

@kubernetes/dep-approvers: @serathius finished the technical review, now we need approval for the modified dependencies (external zapr instead of internal fork, updated dependencies).

pohly · 2021-09-09T12:43:32Z

Just noticed some left-over comment and a formatting issue, force-pushed.

This replaces the experimental logr v0.4 with the stable v1.1.0 release. This is a breaking API change for some users because: - Comparing logr.Logger against nil is not possible anymore: it's now a struct instead of an interface. Code which allows a nil logger should switch to *logr.Logger as type. - Logger implementations must be updated in lockstep. Instead of updating the forked zapr code in json.go, directly using the original go-logr/zapr is simpler and avoids duplication of effort. The updated zapr supports logging of numeric verbosity. Error messages don't have a verbosity (= always get logged), so "v" is not getting added to them anymore. Source code logging for panic messages got fixed so that it references the code with the invalid log call, not the json.go implementation. Finally, zapr includes additional information in its panic messages ("zap field", "ignored key", "invalid key").

dims · 2021-09-09T13:50:22Z

/retest

dims · 2021-09-09T13:52:03Z

/approve
/lgtm
/assign @liggitt

logicalhan · 2021-09-09T16:39:15Z

/triage accepted

liggitt · 2021-09-09T18:27:32Z

staging/src/k8s.io/component-base/logs/json/klog_test.go

@@ -149,57 +163,63 @@ func TestKlogIntegration(t *testing.T) {
 			fun: func() {
 				klog.Error("test ", 1)
 			},
-			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1\n","v":0}`,


is it expected that these no longer output "v":0?

Yes, verbosity for error didn't have any semantic meaning. It was always supposed to be equal zero, but we decided to drop it in zapr.

Yes. Only info messages have a verbosity level and are subjected to filtering by verbosity. Error messages are always printed and therefore conceptually don't have verbosity. In other words, V(3).Error is the same as V(0).Error.

liggitt · 2021-09-09T18:32:42Z

are there any benchmarks/performance tests on the structured logging to demonstrate this replumbing didn't noticeably affect resource usage?

liggitt · 2021-09-09T18:33:13Z

dependency mechanics lgtm, just a couple questions

pohly · 2021-09-09T18:51:34Z

are there any benchmarks/performance tests on the structured logging to demonstrate this replumbing didn't noticeably affect resource usage?

I ran the staging/src/k8s.io/component-base/logs/json benchmarks without and with these changes and got:

$ benchstat /tmp/logr04 /tmp/logr10
name               old time/op    new time/op    delta
InfoLoggerInfo-36    1.84µs ± 8%    1.93µs ± 8%     ~     (p=0.246 n=5+5)
ZapLoggerError-36    2.89µs ± 2%    2.87µs ± 4%     ~     (p=0.841 n=5+5)
ZapLoggerV-36        2.23µs ± 2%    2.14µs ± 3%   -3.80%  (p=0.016 n=5+5)

name               old alloc/op   new alloc/op   delta
InfoLoggerInfo-36    1.43kB ± 0%    1.43kB ± 0%     ~     (p=0.111 n=5+5)
ZapLoggerError-36    1.62kB ± 0%    1.56kB ± 0%   -3.93%  (p=0.008 n=5+5)
ZapLoggerV-36        1.45kB ± 0%    1.43kB ± 0%   -1.21%  (p=0.000 n=5+4)

name               old allocs/op  new allocs/op  delta
InfoLoggerInfo-36      7.00 ± 0%      7.00 ± 0%     ~     (all equal)
ZapLoggerError-36      10.0 ± 0%      10.0 ± 0%     ~     (all equal)
ZapLoggerV-36          8.00 ± 0%      7.00 ± 0%  -12.50%  (p=0.008 n=5+5)

So performance gets slightly better.

liggitt · 2021-09-09T18:52:22Z

/lgtm
/approve

k8s-ci-robot · 2021-09-09T18:55:48Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: dims, liggitt, 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~~ [liggitt]
~~staging/src/k8s.io/api/OWNERS~~ [liggitt]
~~staging/src/k8s.io/legacy-cloud-providers/OWNERS~~ [dims,liggitt]

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

serathius · 2021-09-09T19:08:51Z

are there any benchmarks/performance tests on the structured logging to demonstrate this replumbing didn't noticeably affect resource usage?

I ran the staging/src/k8s.io/component-base/logs/json benchmarks without and with these changes and got:

$ benchstat /tmp/logr04 /tmp/logr10
name               old time/op    new time/op    delta
InfoLoggerInfo-36    1.84µs ± 8%    1.93µs ± 8%     ~     (p=0.246 n=5+5)
ZapLoggerError-36    2.89µs ± 2%    2.87µs ± 4%     ~     (p=0.841 n=5+5)
ZapLoggerV-36        2.23µs ± 2%    2.14µs ± 3%   -3.80%  (p=0.016 n=5+5)

name               old alloc/op   new alloc/op   delta
InfoLoggerInfo-36    1.43kB ± 0%    1.43kB ± 0%     ~     (p=0.111 n=5+5)
ZapLoggerError-36    1.62kB ± 0%    1.56kB ± 0%   -3.93%  (p=0.008 n=5+5)
ZapLoggerV-36        1.45kB ± 0%    1.43kB ± 0%   -1.21%  (p=0.000 n=5+4)

name               old allocs/op  new allocs/op  delta
InfoLoggerInfo-36      7.00 ± 0%      7.00 ± 0%     ~     (all equal)
ZapLoggerError-36      10.0 ± 0%      10.0 ± 0%     ~     (all equal)
ZapLoggerV-36          8.00 ± 0%      7.00 ± 0%  -12.50%  (p=0.008 n=5+5)

So performance gets slightly better.

Just a note about using benchstat. You should look at value of p. It represents statistical significance. Lower the better. Result of 0.841 for ZapLoggerError-36 means that number of runs (5 in this example) were not enough to determine if there is improvement (variance is bigger than difference). In this case this doesn't make much differece, but it's usually good to increase number of test runs to make sure p is kept low (<0.1).

For example looks like there is a small regression for InfoLoggerInfo-36, but with p=0.246, benchstat doesn't show delta as there is not enough runs to be sure. I would recommend increasing number of runs to 10.

pohly · 2021-09-09T19:59:13Z

/retest

Unit test flake (k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/util/flowcontrol/fairqueuing/queueset: TestDifferentWidths)

pohly · 2021-09-09T20:24:01Z

/retest

gce test flake (Kubernetes e2e suite: [sig-storage] Downward API volume should update labels on modification)

k8s-ci-robot requested review from alculquicondor, andrewsykim and a team August 3, 2021 15:39

pohly mentioned this pull request Aug 3, 2021

Migrate Json logging format to use zapr #104097

Closed

k8s-ci-robot removed the sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. label Sep 2, 2021

pohly force-pushed the logr-1.0 branch from bab2009 to 7d1597e Compare September 9, 2021 12:43

pohly force-pushed the logr-1.0 branch from 7d1597e to cb6a653 Compare September 9, 2021 12:43

k8s-ci-robot added the sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. label Sep 9, 2021

k8s-ci-robot assigned liggitt and dims Sep 9, 2021

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Sep 9, 2021

k8s-ci-robot added triage/accepted Indicates an issue or PR is ready to be actively worked on. and removed needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. labels Sep 9, 2021

pohly mentioned this pull request Sep 9, 2021

component-base: test and fix JSON output for KObj #104877

Merged

liggitt reviewed Sep 9, 2021

View reviewed changes

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Sep 9, 2021

k8s-ci-robot merged commit 5b49d12 into kubernetes:master Sep 9, 2021

SIG Auth Old automation moved this from Needs Triage to Closed / Done Sep 9, 2021

k8s-ci-robot added this to the v1.23 milestone Sep 9, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

klog 2.20.0, logr v1.1.0, zapr v1.1.0 #104103

klog 2.20.0, logr v1.1.0, zapr v1.1.0 #104103

pohly commented Aug 3, 2021 •

edited

pohly commented Aug 3, 2021

pohly commented Aug 3, 2021

thockin commented Aug 3, 2021 via email

fedebongio commented Sep 2, 2021

pohly commented Sep 2, 2021

pohly commented Sep 9, 2021

dims commented Sep 9, 2021

dims commented Sep 9, 2021

logicalhan commented Sep 9, 2021

liggitt Sep 9, 2021

serathius Sep 9, 2021

pohly Sep 9, 2021

liggitt commented Sep 9, 2021

liggitt commented Sep 9, 2021

pohly commented Sep 9, 2021

liggitt commented Sep 9, 2021

k8s-ci-robot commented Sep 9, 2021

serathius commented Sep 9, 2021 •

edited

pohly commented Sep 9, 2021

pohly commented Sep 9, 2021

klog 2.20.0, logr v1.1.0, zapr v1.1.0 #104103

klog 2.20.0, logr v1.1.0, zapr v1.1.0 #104103

Conversation

pohly commented Aug 3, 2021 • edited

What type of PR is this?

What this PR does / why we need it:

Which issue(s) this PR fixes:

Special notes for your reviewer:

Does this PR introduce a user-facing change?

pohly commented Aug 3, 2021

pohly commented Aug 3, 2021

thockin commented Aug 3, 2021 via email

fedebongio commented Sep 2, 2021

pohly commented Sep 2, 2021

pohly commented Sep 9, 2021

dims commented Sep 9, 2021

dims commented Sep 9, 2021

logicalhan commented Sep 9, 2021

liggitt Sep 9, 2021

Choose a reason for hiding this comment

serathius Sep 9, 2021

Choose a reason for hiding this comment

pohly Sep 9, 2021

Choose a reason for hiding this comment

liggitt commented Sep 9, 2021

liggitt commented Sep 9, 2021

pohly commented Sep 9, 2021

liggitt commented Sep 9, 2021

k8s-ci-robot commented Sep 9, 2021

serathius commented Sep 9, 2021 • edited

pohly commented Sep 9, 2021

pohly commented Sep 9, 2021

pohly commented Aug 3, 2021 •

edited

serathius commented Sep 9, 2021 •

edited