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

log message verbosity #106978

Merged
merged 1 commit into from Jan 12, 2022
Merged

Conversation

pohly
Copy link
Contributor

@pohly pohly commented Dec 11, 2021

What type of PR is this?

/kind bug

What this PR does / why we need it:

In the following code pattern, the log message will get logged with v=0 in JSON
output although conceptually it has a higher verbosity:

       if klog.V(5).Enabled() {
           klog.Info("hello world")
       }

Having the actual verbosity in the JSON output is relevant, for example for
filtering out only the important info messages. The solution is to use
klog.V(5).Info or something similar.

Whether the outer if is necessary at all depends on how complex the parameters
are. The return value of klog.V can be captured in a variable and be used multiple
times to avoid the overhead for that function call and to avoid repeating
the verbosity level.

Which issue(s) this PR fixes:

Related-to: #102430

Special notes for your reviewer:

git grep 'klog.V([0-9]*).Enabled' cmd/ pkg/ staging can be used to find code locations that may have to be modified.

Does this PR introduce a user-facing change?

Some log messages were logged with `"v":0` in JSON output although they are debug messages with a higher verbosity.

@k8s-ci-robot k8s-ci-robot added release-note Denotes a PR that will be considered when it comes time to generate release notes. kind/bug Categorizes issue or PR as related to a bug. size/L Denotes a PR that changes 100-499 lines, ignoring generated files. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. needs-priority Indicates a PR lacks a `priority/foo` label and requires one. area/apiserver area/cloudprovider area/code-generation area/dependency Issues or PRs related to dependency changes area/kubectl area/kubelet sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. sig/apps Categorizes an issue or PR as relevant to SIG Apps. sig/auth Categorizes an issue or PR as relevant to SIG Auth. sig/cli Categorizes an issue or PR as relevant to SIG CLI. and removed do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. labels Dec 11, 2021
@k8s-ci-robot k8s-ci-robot requested review from ahg-g, andrewsykim and a team December 11, 2021 11:26
@k8s-ci-robot k8s-ci-robot added sig/cloud-provider Categorizes an issue or PR as relevant to SIG Cloud Provider. sig/cluster-lifecycle Categorizes an issue or PR as relevant to SIG Cluster Lifecycle. sig/instrumentation Categorizes an issue or PR as relevant to SIG Instrumentation. sig/node Categorizes an issue or PR as relevant to SIG Node. sig/scheduling Categorizes an issue or PR as relevant to SIG Scheduling. sig/storage Categorizes an issue or PR as relevant to SIG Storage. labels Dec 11, 2021
}
klog.InfoS("Found related ReplicaSets", "replicaSet", klog.KObj(rs), "relatedReplicaSets", relatedNames)
}
klog.V(2).InfoS("Found related ReplicaSets", "replicaSet", klog.KObj(rs), "relatedReplicaSets", klog.KObjs(relatedRSs))
Copy link
Contributor Author

Choose a reason for hiding this comment

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

klog.KObjs does not produce exactly the same output but that should be fine because it works better with JSON.

I am worried that it might cause overhead when the log message is not actually emitted (see #106945).

Therefore here the prior "enabled" check might make sense even when using klog.KObjs.

Copy link
Member

Choose a reason for hiding this comment

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

Seems definitely a valid concern, should we try to prioritize the optimization before we push this out? It definitely could have a large impact in terms of resource consumption

Copy link
Contributor Author

@pohly pohly Dec 13, 2021

Choose a reason for hiding this comment

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

In other places klog.KObjs was used without outer if check. But I myself also lean towards keeping the check until klog.KObj can be shown to not have a performance overhead when called unconditionally.

@pohly
Copy link
Contributor Author

pohly commented Jan 11, 2022

We need @liggitt for approval. https://github.com/kubernetes/kubernetes/blob/master/staging/src/k8s.io/legacy-cloud-providers/OWNERS has a very narrow set of approvers and @thockin's approval wasn't enough.

@dims
Copy link
Member

dims commented Jan 11, 2022

/skip
/approve

@k8s-ci-robot k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Jan 11, 2022
@k8s-ci-robot k8s-ci-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Jan 11, 2022
@pohly
Copy link
Contributor Author

pohly commented Jan 11, 2022

Rebased because of a conflict in pkg/kubelet/pleg/generic.go.

@k8s-ci-robot k8s-ci-robot added the sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. label Jan 11, 2022
@fedebongio
Copy link
Contributor

/remove-sig api-machinery
/triage accepted

@k8s-ci-robot k8s-ci-robot added triage/accepted Indicates an issue or PR is ready to be actively worked on. and removed sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. labels Jan 11, 2022
In the following code pattern, the log message will get logged with v=0 in JSON
output although conceptually it has a higher verbosity:

   if klog.V(5).Enabled() {
       klog.Info("hello world")
   }

Having the actual verbosity in the JSON output is relevant, for example for
filtering out only the important info messages. The solution is to use
klog.V(5).Info or something similar.

Whether the outer if is necessary at all depends on how complex the parameters
are. The return value of klog.V can be captured in a variable and be used
multiple times to avoid the overhead for that function call and to avoid
repeating the verbosity level.
@k8s-ci-robot k8s-ci-robot added the sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. label Jan 12, 2022
@k8s-ci-robot
Copy link
Contributor

k8s-ci-robot commented Jan 12, 2022

@pohly: The following tests failed, say /retest to rerun all failed tests or /retest-required to rerun all mandatory failed tests:

Test name Commit Details Required Rerun command
pull-kubernetes-e2e-gce-iscsi 570fae7a718f88273607dfa698362b2134a9c7ea link false /test pull-kubernetes-e2e-gce-iscsi
pull-kubernetes-e2e-gce-iscsi-serial 570fae7a718f88273607dfa698362b2134a9c7ea link false /test pull-kubernetes-e2e-gce-iscsi-serial
pull-kubernetes-e2e-gce-storage-slow 9eaa2dc link false /test pull-kubernetes-e2e-gce-storage-slow

Full PR test history. Your PR dashboard. Please help us cut down on flakes by linking to an open issue when you hit one in your PR.

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. I understand the commands that are listed here.

@dims
Copy link
Member

dims commented Jan 12, 2022

/skip
/approve
/lgtm

@k8s-ci-robot k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Jan 12, 2022
@k8s-ci-robot
Copy link
Contributor

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: dims, pohly, thockin

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:

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

@dims
Copy link
Member

dims commented Jan 12, 2022

looks like the /hold is for @shivanshu1333 to take a look. please ping me back if you need me to do something

@serathius
Copy link
Contributor

/lgtm

@pohly
Copy link
Contributor Author

pohly commented Jan 12, 2022

/hold cancel

@k8s-ci-robot k8s-ci-robot removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Jan 12, 2022
@k8s-ci-robot k8s-ci-robot merged commit 46c072d into kubernetes:master Jan 12, 2022
SIG Node PR Triage automation moved this from Triage to Done Jan 12, 2022
SIG Auth Old automation moved this from Needs Triage to Closed / Done Jan 12, 2022
@k8s-ci-robot k8s-ci-robot added this to the v1.24 milestone Jan 12, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
approved Indicates a PR has been approved by an approver from all required OWNERS files. area/apiserver area/cloudprovider area/code-generation area/dependency Issues or PRs related to dependency changes area/kubectl area/kubelet cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. kind/bug Categorizes issue or PR as related to a bug. lgtm "Looks good to me", indicates that a PR is ready to be merged. needs-priority Indicates a PR lacks a `priority/foo` label and requires one. release-note Denotes a PR that will be considered when it comes time to generate release notes. sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. sig/apps Categorizes an issue or PR as relevant to SIG Apps. sig/auth Categorizes an issue or PR as relevant to SIG Auth. sig/cli Categorizes an issue or PR as relevant to SIG CLI. sig/cloud-provider Categorizes an issue or PR as relevant to SIG Cloud Provider. sig/cluster-lifecycle Categorizes an issue or PR as relevant to SIG Cluster Lifecycle. sig/instrumentation Categorizes an issue or PR as relevant to SIG Instrumentation. sig/node Categorizes an issue or PR as relevant to SIG Node. sig/scheduling Categorizes an issue or PR as relevant to SIG Scheduling. sig/storage Categorizes an issue or PR as relevant to SIG Storage. size/L Denotes a PR that changes 100-499 lines, ignoring generated files. triage/accepted Indicates an issue or PR is ready to be actively worked on.
Projects
Archived in project
SIG Auth Old
Closed / Done
Development

Successfully merging this pull request may close these issues.

None yet