Bug 1879184: Log object updates and show existing/required diff #561

vrutkovs · 2021-05-13T07:51:12Z

Show when object gets created or updated with diff

vrutkovs · 2021-05-13T11:42:25Z

/cc @jottofar

vrutkovs · 2021-05-18T15:46:51Z

/retest

vrutkovs · 2021-05-21T10:35:30Z

/test unit

openshift-ci · 2021-05-31T16:17:48Z

@vrutkovs: This pull request references Bugzilla bug 1879184, which is invalid:

expected the bug to target the "4.8.0" release, but it targets "---" 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 1879184: Log object updates and show existing/required diff

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.

vrutkovs · 2021-05-31T16:23:15Z

/bugzilla refresh

openshift-ci · 2021-05-31T16:23:22Z

@vrutkovs: This pull request references Bugzilla bug 1879184, 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.

3 validation(s) were run on this bug

bug is open, matching expected state (open)
bug target release (4.8.0) matches configured target release for branch (4.8.0)
bug is in the state NEW, which is one of the valid states (NEW, ASSIGNED, ON_DEV, POST, POST)

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.

vrutkovs · 2021-06-03T13:39:20Z

/test unit

wking · 2021-06-03T17:36:03Z

pkg/cvo/internal/generic.go

+	expected := required.DeepCopy()
+	for k, v := range existing.Object {
+		if skipKeys.Has(k) {
+			expected.Object[k] = v


This sort of thing is why I think generically logging diffs is brittle. I'd rather have the Ensure* helpers return a slice of patches instead of the current modified boolean, so we could log the patches "Updating $PROPERTY to $VALUE to clobber $EXISTING_VALUE" instead of having logic about the things we care about clobbering both here and in the Ensure* helpers.

Logging everytime modified is changed may be too verbose. I think we should do that later, on level 4 so that we wouldn't hit master's disks with too much log lines.

if, instead of twiddling *modified, these helpers return []patch, error, we can log any patch we get at one time, before calling the UPDATE. Should be same number of log lines, and we'd only complain about the in-cluster properties we were trying to stomp.

I am in the opinion of moving these to some verbose mode. We do not need the diff for all CVO runs as I think it will impact the performance of CVO a little. But if we change it some mode which can give more details , that would be fine.

This is only required if we want to see not only that we're hot looping but also why. The latter could be dropped and once we know we're hot looping figuring out the why becomes part of the fix process done off line. Choosing one over the other is a question of how often we believe this is going to occur. If rarely then we probably don't need the "why" in the baseline.

CVO can start hotlooping on any non-standard configuration - and its complicated to find out details to fix it.
I'd prefer to include "why" in every run, so that we wouldn't have to request customers to reconfigure CVO to get details.

@vrutkovs What sort of non-standard configs would they have which are managed by the CVO that we'd want to look into?

Users can sideload additional manifests during bootstrap

wking · 2021-06-08T04:04:55Z

/test e2e-agnostic

wking · 2021-06-08T17:32:06Z

Failed to install on Total Regional Cores quota:

/retest

LalatenduMohanty · 2021-06-08T21:25:59Z

pkg/cvo/internal/generic.go

+	expected := required.DeepCopy()
+	for k, v := range existing.Object {
+		if skipKeys.Has(k) {
+			expected.Object[k] = v


I am in the opinion of moving these to some verbose mode. We do not need the diff for all CVO runs as I think it will impact the performance of CVO a little. But if we change it some mode which can give more details , that would be fine.

LalatenduMohanty · 2021-06-08T21:28:06Z

lib/resourceapply/apiext.go

 	}

-	klog.V(2).Infof("Updating CRD %s", required.Name)
+	klog.V(2).Infof("Updating CRD %s due to diff: %v", required.Name, diff.ObjectDiff(existing, required))


IMO we should move these to some higher level of verbosity , what about V4?

I'd rather use the default one, so that we'd see hotloops in CI upgrade jobs. If we move it to v4 we'd have to reconfigure CVO to get them recorded

LalatenduMohanty · 2021-06-09T14:43:12Z

I am wondering if the current PR will have any performance impact or not. If it is not going to have any performance impact then I am fine to merge it as it is.

vrutkovs · 2021-06-09T14:49:50Z

I am wondering if the current PR will have any performance impact or not. If it is not going to have any performance impact then I am fine to merge it as it is.

It improves performance by fixing hotloops in unstructured resources. Additional log lines might be printed during sync periods, but its effect is negligible

LalatenduMohanty

/lgtm

openshift-ci · 2021-06-09T16:33:56Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: LalatenduMohanty, vrutkovs

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~~ [LalatenduMohanty,vrutkovs]

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

openshift-ci · 2021-06-09T19:58:49Z

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

openshift/cluster-version-operator#561

Bugzilla bug 1879184 has been moved to the MODIFIED state.

Details

In response to this:

Bug 1879184: Log object updates and show existing/required diff

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.

vrutkovs · 2021-06-10T08:15:55Z

/cherrypick release-4.7

openshift-cherrypick-robot · 2021-06-10T08:16:34Z

@vrutkovs: new pull request created: #589

Details

In response to this:

/cherrypick release-4.7

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.

Logging of resource diffs was introduced to detect hotlooping in the CVO[1]. But this increases the verbosity of logging during updates when the resources have changed which is not useful. Hence logging of the diffs is more useful in the reconcile mode. Also the diff is generated with ObjectDiff[2] which is deprecated. The ObjectDiff function now just uses cmp.Diff[3] internally and all instances of ObjectDiff have been replaced with cmp.Diff. [1] - openshift#561 [2] - https://github.com/kubernetes/apimachinery/blob/235edae7dd90601011bbe3bcd6f84f7dc857b034/pkg/util/diff/diff.go#L57 [3] - https://pkg.go.dev/github.com/google/go-cmp/cmp#Diff

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

openshift-ci bot added the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label May 13, 2021

openshift-ci bot requested review from smarterclayton and wking May 13, 2021 07:51

openshift-ci bot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label May 13, 2021

vrutkovs force-pushed the verbose-changes-logging branch from 52f3764 to 41a7a6a Compare May 13, 2021 10:25

vrutkovs mentioned this pull request May 13, 2021

Bug 1960339: manifests: add preemptionPolicy for openshift-user-critical openshift/cluster-config-operator#202

Merged

vrutkovs force-pushed the verbose-changes-logging branch 3 times, most recently from 9919448 to 6ab7550 Compare May 13, 2021 11:07

openshift-ci bot requested a review from jottofar May 13, 2021 11:42

vrutkovs force-pushed the verbose-changes-logging branch 2 times, most recently from 2eb9aca to 8c322cb Compare May 14, 2021 07:41

openshift-ci bot added the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label May 16, 2021

vrutkovs force-pushed the verbose-changes-logging branch from 8c322cb to ae8d5fd Compare May 17, 2021 08:06

openshift-ci bot removed the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label May 17, 2021

vrutkovs force-pushed the verbose-changes-logging branch from ae8d5fd to 8809ddb Compare May 18, 2021 07:32

vrutkovs force-pushed the verbose-changes-logging branch 2 times, most recently from 849de5b to bef335b Compare May 21, 2021 08:20

vrutkovs force-pushed the verbose-changes-logging branch from bef335b to dc0f19b Compare May 24, 2021 08:41

vrutkovs force-pushed the verbose-changes-logging branch from dc0f19b to c59a7f8 Compare May 31, 2021 10:22

vrutkovs changed the title ~~WIP Log object updates and show existing/required diff~~ Bug 1879184: Log object updates and show existing/required diff May 31, 2021

openshift-ci bot removed the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label May 31, 2021

openshift-ci bot added bugzilla/severity-medium Referenced Bugzilla bug's severity is medium for the branch this PR is targeting. bugzilla/invalid-bug Indicates that a referenced Bugzilla bug is invalid for the branch this PR is targeting. labels May 31, 2021

wking reviewed Jun 3, 2021

View reviewed changes

timflannagan mentioned this pull request Jun 9, 2021

[release-4.7] Bug 1969320: packageserver CSV: add missing properties operator-framework/operator-lifecycle-manager#2192

Merged

5 tasks

LalatenduMohanty suggested changes Jun 9, 2021

View reviewed changes

LalatenduMohanty approved these changes Jun 9, 2021

View reviewed changes

openshift-ci bot assigned LalatenduMohanty Jun 9, 2021

openshift-ci bot added the lgtm Indicates that a PR is ready to be merged. label Jun 9, 2021

openshift-merge-robot merged commit 4a26c3d into openshift:master Jun 9, 2021

openshift-cherrypick-robot mentioned this pull request Jun 10, 2021

[release-4.7] Bug 1970272: Log object updates and show existing/required diff #589

Merged

openshift-ci bot mentioned this pull request Jun 10, 2021

Bug 1879184: Fixing the log message in rbac.go for clusterrole #588

Merged

arjunrn mentioned this pull request Jul 13, 2021

Bug 1984414: Log resource diffs on update only in reconcile mode #628

Merged

wking mentioned this pull request Jan 4, 2022

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

Merged

jottofar mentioned this pull request Jan 7, 2022

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

Merged

jottofar mentioned this pull request Jan 10, 2022

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

Merged

Bug 1879184: Log object updates and show existing/required diff #561

Bug 1879184: Log object updates and show existing/required diff #561

Uh oh!

Conversation

vrutkovs commented May 13, 2021

Uh oh!

vrutkovs commented May 13, 2021

Uh oh!

vrutkovs commented May 18, 2021

Uh oh!

vrutkovs commented May 21, 2021

Uh oh!

openshift-ci bot commented May 31, 2021

Uh oh!

vrutkovs commented May 31, 2021

Uh oh!

openshift-ci bot commented May 31, 2021

Uh oh!

vrutkovs commented Jun 3, 2021

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

wking commented Jun 8, 2021

Uh oh!

wking commented Jun 8, 2021

Uh oh!

Choose a reason for hiding this comment

Uh oh!

LalatenduMohanty Jun 8, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

LalatenduMohanty commented Jun 9, 2021

Uh oh!

vrutkovs commented Jun 9, 2021

Uh oh!

LalatenduMohanty left a comment

Choose a reason for hiding this comment

Uh oh!

openshift-ci bot commented Jun 9, 2021

Uh oh!

openshift-ci bot commented Jun 9, 2021

Uh oh!

vrutkovs commented Jun 10, 2021

Uh oh!

openshift-cherrypick-robot commented Jun 10, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants

LalatenduMohanty Jun 8, 2021 •

edited

Loading