Bug 2038936: *: Use --v=2 logging to drop client-side throttling noise #724

jottofar · 2022-01-10T20:01:21Z

We've been using --v=5 since 88c222c
(install/0000_00_cluster-version-operator_03_deployment: Bump to
--v=5, 2020-08-30, #448). But it leads to large quantities of noise
from client-side throttling 1, and that throttling is V(3):

$ grep -n . vendor/k8s.io/client-go/rest/request.go | grep -B7 -A6 '^597:'
589: switch {
590: case len(retryInfo) > 0:
591: message = fmt.Sprintf("Waited for %v, %s - request: %s:%s", latency, retryInfo, r.verb, r.URL().String())
592: default:
593: message = fmt.Sprintf("Waited for %v due to client-side throttling, not priority and fairness, request: %s:%s", latency, r.verb, r.URL().String())
594: }
596: if latency > longThrottleLatency {
597: klog.V(3).Info(message)
598: }
599: if latency > extraLongThrottleLatency {
600: // If the rate limiter latency is very high, the log message should be printed at a higher log level,
601: // but we use a throttled logger to prevent spamming.
602: globalThrottledLogger.Infof("%s", message)
603: }

Auditing:

$ git --no-pager grep 'klog.V([3-5])' vendor

I don't see much that I'd miss. I liked having
vendor/github.com/openshift/library-go/pkg/verify's logging back when
we made that pivot, but now that that code is old and stable, I'm ok
losing it.

I've shifted the lib/ stuff down to V(2) using:

$ sed -i 's/klog[.]V([3-5])/klog.V(2)/g' $(git grep -l klog.V lib)

It's mostly hotloop-detection since 40d0a4e (Log object updates and
show existing/required diff, 2021-06-03, #561, 2), and isn't all
that noisy since 05e1af7 (Bug 1984414: Log resource diffs on update
only in reconcile mode, 2021-07-22, #628, 3).

I've shifted the pkg/ stuff down to V(2) using:

$ sed -i 's/klog[.]V([3-5])/klog.V(2)/g' $(git grep -l klog.V pkg)

It's mostly fairly core stuff, and low-noise except for the
per-manifest "Running sync for ..." and "Done syncing for ..."
messages 1. The per-manifest messages can be useful to identify
where the CVO is in the sync cycle, so I'm keeping them for now. We
may be able to punt them up to higher levels if we get an alternative
mechanism for identifying sync cycle positions (e.g. events for
task-node completion or task failure).

openshift-ci · 2022-01-10T20:01:27Z

@jottofar: This pull request references Bugzilla bug 2038936, which is invalid:

expected dependent Bugzilla bug 2034493 to target a release in 4.9.0, 4.9.z, but it targets "4.10.0" instead

Comment /bugzilla refresh to re-evaluate validity if changes to the Bugzilla bug are made, or edit the title of this pull request to link to a different bug.

Details

In response to this:

Bug 2038936: *: Use --v=2 logging to drop client-side throttling noise

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.

We've been using --v=5 since 88c222c (install/0000_00_cluster-version-operator_03_deployment: Bump to --v=5, 2020-08-30, openshift#448). But it leads to large quantities of noise from client-side throttling [1], and that throttling is V(3): $ grep -n . vendor/k8s.io/client-go/rest/request.go | grep -B7 -A6 '^597:' 589: switch { 590: case len(retryInfo) > 0: 591: message = fmt.Sprintf("Waited for %v, %s - request: %s:%s", latency, retryInfo, r.verb, r.URL().String()) 592: default: 593: message = fmt.Sprintf("Waited for %v due to client-side throttling, not priority and fairness, request: %s:%s", latency, r.verb, r.URL().String()) 594: } 596: if latency > longThrottleLatency { 597: klog.V(3).Info(message) 598: } 599: if latency > extraLongThrottleLatency { 600: // If the rate limiter latency is very high, the log message should be printed at a higher log level, 601: // but we use a throttled logger to prevent spamming. 602: globalThrottledLogger.Infof("%s", message) 603: } Auditing: $ git --no-pager grep 'klog.V([3-5])' vendor I don't see much that I'd miss. I liked having vendor/github.com/openshift/library-go/pkg/verify's logging back when we made that pivot, but now that that code is old and stable, I'm ok losing it. I've shifted the lib/ stuff down to V(2) using: $ sed -i 's/klog[.]V([3-5])/klog.V(2)/g' $(git grep -l klog.V lib) It's mostly hotloop-detection since 40d0a4e (Log object updates and show existing/required diff, 2021-06-03, openshift#561, [2]), and isn't all that noisy since 05e1af7 (Bug 1984414: Log resource diffs on update only in reconcile mode, 2021-07-22, openshift#628, [3]). I've shifted the pkg/ stuff down to V(2) using: $ sed -i 's/klog[.]V([3-5])/klog.V(2)/g' $(git grep -l klog.V pkg) It's mostly fairly core stuff, and low-noise except for the per-manifest "Running sync for ..." and "Done syncing for ..." messages [1]. The per-manifest messages can be useful to identify where the CVO is in the sync cycle, so I'm keeping them for now. We may be able to punt them up to higher levels if we get an alternative mechanism for identifying sync cycle positions (e.g. events for task-node completion or task failure). [1]: https://bugzilla.redhat.com/show_bug.cgi?id=2034493#c1 [2]: https://bugzilla.redhat.com/show_bug.cgi?id=1879184 [3]: https://bugzilla.redhat.com/show_bug.cgi?id=1984414

jottofar · 2022-01-10T20:05:52Z

/bugzilla refresh

openshift-ci · 2022-01-10T20:06:02Z

@jottofar: This pull request references Bugzilla bug 2038936, which is valid. The bug has been moved to the POST state. The bug has been updated to refer to the pull request using the external bug tracker.

6 validation(s) were run on this bug

bug is open, matching expected state (open)
bug target release (4.8.z) matches configured target release for branch (4.8.z)
bug is in the state ASSIGNED, which is one of the valid states (NEW, ASSIGNED, ON_DEV, POST, POST)
dependent bug Bugzilla bug 2038275 is in the state VERIFIED, which is one of the valid states (VERIFIED, RELEASE_PENDING, CLOSED (ERRATA), CLOSED (CURRENTRELEASE))
dependent Bugzilla bug 2038275 targets the "4.9.z" release, which is one of the valid target releases: 4.9.0, 4.9.z
bug has dependents

Requesting review from QA contact:
/cc @jianlinliu

Details

In response to this:

/bugzilla refresh

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.

wking

/lgtm

openshift-ci · 2022-01-10T20:44:05Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: jottofar, wking

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

The pull request process is described here

Details

Needs approval from an approver in each of these files:

~~OWNERS~~ [jottofar,wking]

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

openshift-bot · 2022-01-10T21:26:07Z

/retest-required

Please review the full test history for this PR and help us cut down flakes.

openshift-bot · 2022-01-10T23:36:06Z

/retest-required

Please review the full test history for this PR and help us cut down flakes.

openshift-ci · 2022-01-11T02:54:34Z

@jottofar: all tests passed!

Full PR test history. Your PR dashboard.

Details

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.

jianlinliu · 2022-01-12T02:46:15Z

/label cherry-pick-approved

openshift-ci · 2022-01-12T02:48:22Z

@jottofar: All pull requests linked via external trackers have merged:

openshift/cluster-version-operator#724

Bugzilla bug 2038936 has been moved to the MODIFIED state.

Details

In response to this:

Bug 2038936: *: Use --v=2 logging to drop client-side throttling noise

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.

openshift-ci bot added the bugzilla/severity-medium Referenced Bugzilla bug's severity is medium for the branch this PR is targeting. label Jan 10, 2022

openshift-ci bot added the bugzilla/invalid-bug Indicates that a referenced Bugzilla bug is invalid for the branch this PR is targeting. label Jan 10, 2022

openshift-ci bot requested review from LalatenduMohanty and sdodson January 10, 2022 20:01

openshift-ci bot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Jan 10, 2022

jottofar force-pushed the bug-2038936 branch from db7938a to 8485e38 Compare January 10, 2022 20:03

openshift-ci bot added bugzilla/valid-bug Indicates that a referenced Bugzilla bug is valid for the branch this PR is targeting. and removed bugzilla/invalid-bug Indicates that a referenced Bugzilla bug is invalid for the branch this PR is targeting. labels Jan 10, 2022

openshift-ci bot requested a review from jianlinliu January 10, 2022 20:06

wking approved these changes Jan 10, 2022

View reviewed changes

openshift-ci bot assigned wking Jan 10, 2022

openshift-ci bot added the lgtm Indicates that a PR is ready to be merged. label Jan 10, 2022

sdodson added the backport-risk-assessed Indicates a PR to a release branch has been evaluated and considered safe to accept. label Jan 11, 2022

openshift-ci bot added the cherry-pick-approved Indicates a cherry-pick PR into a release branch has been approved by the release branch manager. label Jan 12, 2022

openshift-merge-robot merged commit 1b29e92 into openshift:release-4.8 Jan 12, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Bug 2038936: *: Use --v=2 logging to drop client-side throttling noise #724

Bug 2038936: *: Use --v=2 logging to drop client-side throttling noise #724

Uh oh!

jottofar commented Jan 10, 2022

Uh oh!

openshift-ci bot commented Jan 10, 2022

Uh oh!

jottofar commented Jan 10, 2022

Uh oh!

openshift-ci bot commented Jan 10, 2022

Uh oh!

wking left a comment

Uh oh!

openshift-ci bot commented Jan 10, 2022

Uh oh!

openshift-bot commented Jan 10, 2022

Uh oh!

openshift-bot commented Jan 10, 2022

Uh oh!

openshift-ci bot commented Jan 11, 2022

Uh oh!

jianlinliu commented Jan 12, 2022

Uh oh!

openshift-ci bot commented Jan 12, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

Bug 2038936: *: Use --v=2 logging to drop client-side throttling noise #724

Bug 2038936: *: Use --v=2 logging to drop client-side throttling noise #724

Uh oh!

Conversation

jottofar commented Jan 10, 2022

Uh oh!

openshift-ci bot commented Jan 10, 2022

Uh oh!

jottofar commented Jan 10, 2022

Uh oh!

openshift-ci bot commented Jan 10, 2022

Uh oh!

wking left a comment

Choose a reason for hiding this comment

Uh oh!

openshift-ci bot commented Jan 10, 2022

Uh oh!

openshift-bot commented Jan 10, 2022

Uh oh!

openshift-bot commented Jan 10, 2022

Uh oh!

openshift-ci bot commented Jan 11, 2022

Uh oh!

jianlinliu commented Jan 12, 2022

Uh oh!

openshift-ci bot commented Jan 12, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants