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.

Sign up for GitHub

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

Jump to bottom

klog always logs verbosity 0 with component-base/logs #294

Closed
sbueringer opened this issue Feb 14, 2022 · 5 comments · Fixed by #295
Closed

klog always logs verbosity 0 with component-base/logs #294

sbueringer opened this issue Feb 14, 2022 · 5 comments · Fixed by #295
Assignees
@pohly
Labels
kind/bug Categorizes issue or PR as related to a bug.

Comments

@sbueringer
Copy link
Member

sbueringer commented Feb 14, 2022 •
edited

/kind bug

What steps did you take and what happened:

I'm currently trying to use component-base/logs in combination with controller-runtime in ClusterAPI (kubernetes-sigs/cluster-api#6072).
When using --logging-format=json the log lines contain v: 0 independent of the log level with which the line is actually logged.

What did you expect to happen:
Should log the verbosity with which the log line is logged.

Anything else you would like to add:
When component-base/logs the "log hierarchy" is roughly go-logr.Logger => klog => JSON logger (component-base/logs) => zap:
image

I think the log level get's lost here: https://github.com/kubernetes/klog/blob/main/klogr/klogr.go#L169-L173

To reproduce:
I've created a minimal controller here: https://github.com/sbueringer/cr-klog-issue (with k8s.io/component-base v0.23.3 and k8s.io/klog/v2 v2.40.1)
The issue can be reproduced by running the controller against an arbitrary cluster (with Pods) via:

$  go run main.go --logging-format=json --v=4
...
{"ts":1644841271031.652,"caller":"cr-klog-issue/main.go:92","msg":"controller/pod: Verbosity 0","v":0,"reconciler group":"","reconciler kind":"Pod","name":"capi-kubeadm-control-plane-controller-manager-9769796f6-l8nf2","namespace":"capi-kubeadm-control-plane-system"}
{"ts":1644841271031.67,"caller":"cr-klog-issue/main.go:93","msg":"controller/pod: Verbosity 1","v":0,"reconciler group":"","reconciler kind":"Pod","name":"capi-kubeadm-control-plane-controller-manager-9769796f6-l8nf2","namespace":"capi-kubeadm-control-plane-system"}
{"ts":1644841271031.679,"caller":"cr-klog-issue/main.go:94","msg":"controller/pod: Verbosity 2","v":0,"reconciler group":"","reconciler kind":"Pod","name":"capi-kubeadm-control-plane-controller-manager-9769796f6-l8nf2","namespace":"capi-kubeadm-control-plane-system"}
{"ts":1644841271031.6858,"caller":"cr-klog-issue/main.go:95","msg":"controller/pod: Verbosity 3","v":0,"reconciler group":"","reconciler kind":"Pod","name":"capi-kubeadm-control-plane-controller-manager-9769796f6-l8nf2","namespace":"capi-kubeadm-control-plane-system"}
{"ts":1644841271031.693,"caller":"cr-klog-issue/main.go:96","msg":"controller/pod: Verbosity 4","v":0,"reconciler group":"","reconciler kind":"Pod","name":"capi-kubeadm-control-plane-controller-manager-9769796f6-l8nf2","namespace":"capi-kubeadm-control-plane-system"}

xref: Slack thread: https://kubernetes.slack.com/archives/CG3518SFJ/p1644596428193789
@k8s-ci-robot k8s-ci-robot added the kind/bug Categorizes issue or PR as related to a bug. label Feb 14, 2022
@sbueringer
Copy link
Member Author

cc @dims @pohly

@sbueringer
Copy link
Member Author

cc @fabriziopandini @killianmuldoon

@pohly
Copy link

pohly commented Feb 14, 2022

/assign

I intend to add a unit test to the new "test" package for this and then fix it.

@sbueringer
Copy link
Member Author

sbueringer commented Feb 14, 2022 •
edited

Thx!

Happy to re-test with a branch/PR if it is helpful, but probably not needed as the issue seems to be relatively straightforward.

pohly added a commit to pohly/klog that referenced this issue Feb 14, 2022
@pohly
test: move output test to example, include zapr
fba5a74 
To reproduce the loss of verbosity in
klogr (kubernetes#294) we need a backend which
actually emits the verbosity. zapr does that and also happens to be the logging
implementation used in Kubernetes for JSON, so it makes sense to test with
that.

The expected output mapping may be useful also for testing in Kubernetes,
therefore it gets exported by k8s.io/klog/v2/test.

Because k8s.io/klog/v2 must not depend on zapr, the actual output test gets
moved to the examples. The downside is that "go test ./..." no longer runs it.
One has to remember to enter the "examples" directory. The GitHub action gets
updated to do that.
@pohly pohly mentioned this issue Feb 14, 2022
Merged
pohly added a commit to pohly/klog that referenced this issue Feb 14, 2022
@pohly
test: move output test to example, include zapr
29cae73 
To reproduce the loss of verbosity in
klogr (kubernetes#294) we need a backend which
actually emits the verbosity. zapr does that and also happens to be the logging
implementation used in Kubernetes for JSON, so it makes sense to test with
that.

The expected output mapping may be useful also for testing in Kubernetes,
therefore it gets exported by k8s.io/klog/v2/test.

Because k8s.io/klog/v2 must not depend on zapr, the actual output test gets
moved to the examples. The downside is that "go test ./..." no longer runs it.
One has to remember to enter the "examples" directory. The GitHub action gets
updated to do that.
pohly added a commit to pohly/klog that referenced this issue Feb 14, 2022
@pohly
test: move output test to example, include zapr
139863b 
To reproduce the loss of verbosity in
klogr (kubernetes#294) we need a backend which
actually emits the verbosity. zapr does that and also happens to be the logging
implementation used in Kubernetes for JSON, so it makes sense to test with
that.

The expected output mapping may be useful also for testing in Kubernetes,
therefore it gets exported by k8s.io/klog/v2/test.

Because k8s.io/klog/v2 must not depend on zapr, the actual output test gets
moved to the examples. The downside is that "go test ./..." no longer runs it.
One has to remember to enter the "examples" directory. The GitHub action gets
updated to do that.
pohly added a commit to pohly/klog that referenced this issue Feb 14, 2022
@pohly
test: move output test to example, include zapr
cee11b7 
To reproduce the loss of verbosity in
klogr (kubernetes#294) we need a backend which
actually emits the verbosity. zapr does that and also happens to be the logging
implementation used in Kubernetes for JSON, so it makes sense to test with
that.

The expected output mapping may be useful also for testing in Kubernetes,
therefore it gets exported by k8s.io/klog/v2/test.

Because k8s.io/klog/v2 must not depend on zapr, the actual output test gets
moved to the examples. The downside is that "go test ./..." no longer runs it.
One has to remember to enter the "examples" directory. The GitHub action gets
updated to do that.
pohly added a commit to pohly/klog that referenced this issue Feb 15, 2022
@pohly
test: move output test to example, include zapr
6977d14 
To reproduce the loss of verbosity in
klogr (kubernetes#294) we need a backend which
actually emits the verbosity. zapr does that and also happens to be the logging
implementation used in Kubernetes for JSON, so it makes sense to test with
that.

The expected output mapping may be useful also for testing in Kubernetes,
therefore it gets exported by k8s.io/klog/v2/test.

Because k8s.io/klog/v2 must not depend on zapr, the actual output test gets
moved to the examples. The downside is that "go test ./..." no longer runs it.
One has to remember to enter the "examples" directory. The GitHub action gets
updated to do that.
pohly added a commit to pohly/klog that referenced this issue Feb 15, 2022
@pohly
test: move output test to example, include zapr
bb978b3 
To reproduce the loss of verbosity in
klogr (kubernetes#294) we need a backend which
actually emits the verbosity. zapr does that and also happens to be the logging
implementation used in Kubernetes for JSON, so it makes sense to test with
that.

The expected output mapping may be useful also for testing in Kubernetes,
therefore it gets exported by k8s.io/klog/v2/test.

Because k8s.io/klog/v2 must not depend on zapr, the actual output test gets
moved to the examples. The downside is that "go test ./..." no longer runs it.
One has to remember to enter the "examples" directory. The GitHub action gets
updated to do that.
@sbueringer sbueringer mentioned this issue Feb 16, 2022
Closed
@fabriziopandini
Copy link
Member

Thanks for the quick fix! awesome!

@sbueringer sbueringer mentioned this issue Feb 22, 2022
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@pohly pohly

Labels
kind/bug Categorizes issue or PR as related to a bug.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

klogr verbosity pohly/klog
4 participants
@pohly @sbueringer @fabriziopandini @k8s-ci-robot