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

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

bootstrap/bootstrap-pod.yaml

@@ -16,7 +16,7 @@ spec:
       - "--enable-auto-update=false"
       - "--enable-default-cluster-version=false"
       - "--listen="
-      - "--v=5"
+      - "--v=2"
       - "--kubeconfig=/etc/kubernetes/kubeconfig"
     securityContext:
       privileged: true

install/0000_00_cluster-version-operator_03_deployment.yaml

@@ -33,7 +33,7 @@ spec:
           - "--listen=0.0.0.0:9099"
           - "--serving-cert-file=/etc/tls/serving-cert/tls.crt"
           - "--serving-key-file=/etc/tls/serving-cert/tls.key"
-          - "--v=5"
+          - "--v=2"
         resources:
           requests:
             cpu: 20m

lib/resourceapply/apiext.go

@@ -35,7 +35,7 @@ func ApplyCustomResourceDefinitionv1(ctx context.Context, client apiextclientv1.
 	}
 
 	if reconciling {
-		klog.V(4).Infof("Updating CRD %s due to diff: %v", required.Name, cmp.Diff(existing, required))
+		klog.V(2).Infof("Updating CRD %s due to diff: %v", required.Name, cmp.Diff(existing, required))
 	}
 
 	actual, err := client.CustomResourceDefinitions().Update(ctx, existing, metav1.UpdateOptions{})

lib/resourceapply/apps.go

@@ -35,7 +35,7 @@ func ApplyDeploymentv1(ctx context.Context, client appsclientv1.DeploymentsGette
 		return existing, false, nil
 	}
 	if reconciling {
-		klog.V(4).Infof("Updating Deployment %s/%s due to diff: %v", required.Namespace, required.Name, cmp.Diff(existing, required))
+		klog.V(2).Infof("Updating Deployment %s/%s due to diff: %v", required.Namespace, required.Name, cmp.Diff(existing, required))
 	}
 
 	actual, err := client.Deployments(required.Namespace).Update(ctx, existing, metav1.UpdateOptions{})
@@ -65,7 +65,7 @@ func ApplyDaemonSetv1(ctx context.Context, client appsclientv1.DaemonSetsGetter,
 	}
 
 	if reconciling {
-		klog.V(4).Infof("Updating DaemonSet %s/%s due to diff: %v", required.Namespace, required.Name, cmp.Diff(existing, required))
+		klog.V(2).Infof("Updating DaemonSet %s/%s due to diff: %v", required.Namespace, required.Name, cmp.Diff(existing, required))
 	}
 
 	actual, err := client.DaemonSets(required.Namespace).Update(ctx, existing, metav1.UpdateOptions{})

lib/resourceapply/batch.go

@@ -36,7 +36,7 @@ func ApplyJobv1(ctx context.Context, client batchclientv1.JobsGetter, required *
 	}
 
 	if reconciling {
-		klog.V(4).Infof("Updating Job %s/%s due to diff: %v", required.Namespace, required.Name, cmp.Diff(existing, required))
+		klog.V(2).Infof("Updating Job %s/%s due to diff: %v", required.Namespace, required.Name, cmp.Diff(existing, required))
 	}
 
 	actual, err := client.Jobs(required.Namespace).Update(ctx, existing, metav1.UpdateOptions{})

lib/resourceapply/core.go

@@ -38,7 +38,7 @@ func ApplyNamespacev1(ctx context.Context, client coreclientv1.NamespacesGetter,
 		return existing, false, nil
 	}
 	if reconciling {
-		klog.V(4).Infof("Updating Namespace %s due to diff: %v", required.Name, cmp.Diff(existing, required))
+		klog.V(2).Infof("Updating Namespace %s due to diff: %v", required.Name, cmp.Diff(existing, required))
 	}
 
 	actual, err := client.Namespaces().Update(ctx, existing, metav1.UpdateOptions{})
@@ -75,7 +75,7 @@ func ApplyServicev1(ctx context.Context, client coreclientv1.ServicesGetter, req
 	existing.Spec.Selector = required.Spec.Selector
 
 	if reconciling {
-		klog.V(4).Infof("Updating Service %s/%s due to diff: %v", required.Namespace, required.Name, cmp.Diff(existing, required))
+		klog.V(2).Infof("Updating Service %s/%s due to diff: %v", required.Namespace, required.Name, cmp.Diff(existing, required))
 	}
 
 	actual, err := client.Services(required.Namespace).Update(ctx, existing, metav1.UpdateOptions{})
@@ -105,7 +105,7 @@ func ApplyServiceAccountv1(ctx context.Context, client coreclientv1.ServiceAccou
 	}
 
 	if reconciling {
-		klog.V(4).Infof("Updating ServiceAccount %s/%s due to diff: %v", required.Namespace, required.Name, cmp.Diff(existing, required))
+		klog.V(2).Infof("Updating ServiceAccount %s/%s due to diff: %v", required.Namespace, required.Name, cmp.Diff(existing, required))
 	}
 
 	actual, err := client.ServiceAccounts(required.Namespace).Update(ctx, existing, metav1.UpdateOptions{})
@@ -135,7 +135,7 @@ func ApplyConfigMapv1(ctx context.Context, client coreclientv1.ConfigMapsGetter,
 	}
 
 	if reconciling {
-		klog.V(4).Infof("Updating ConfigMap %s/%s due to diff: %v", required.Namespace, required.Name, cmp.Diff(existing, required))
+		klog.V(2).Infof("Updating ConfigMap %s/%s due to diff: %v", required.Namespace, required.Name, cmp.Diff(existing, required))
 	}
 
 	actual, err := client.ConfigMaps(required.Namespace).Update(ctx, existing, metav1.UpdateOptions{})

lib/resourceapply/cv.go

@@ -36,7 +36,7 @@ func ApplyClusterVersionFromCache(ctx context.Context, lister configlistersv1.Cl
 		return existing, false, nil
 	}
 
-	klog.V(4).Infof("Updating ClusterVersion %s due to diff: %v", required.Name, cmp.Diff(existing, required))
+	klog.V(2).Infof("Updating ClusterVersion %s due to diff: %v", required.Name, cmp.Diff(existing, required))
 
 	actual, err := client.ClusterVersions().Update(ctx, existing, metav1.UpdateOptions{})
 	return actual, true, err

lib/resourceapply/imagestream.go

@@ -34,7 +34,7 @@ func ApplyImageStreamv1(ctx context.Context, client imageclientv1.ImageStreamsGe
 	}
 
 	if reconciling {
-		klog.V(4).Infof("Updating Namespace %s due to diff: %v", required.Name, cmp.Diff(existing, required))
+		klog.V(2).Infof("Updating Namespace %s due to diff: %v", required.Name, cmp.Diff(existing, required))
 	}
 	actual, err := client.ImageStreams(required.Namespace).Update(ctx, existing, metav1.UpdateOptions{})
 	return actual, true, err

lib/resourceapply/rbac.go

@@ -35,7 +35,7 @@ func ApplyClusterRoleBindingv1(ctx context.Context, client rbacclientv1.ClusterR
 		return existing, false, nil
 	}
 	if reconciling {
-		klog.V(4).Infof("Updating ClusterRoleBinding %s due to diff: %v", required.Name, cmp.Diff(existing, required))
+		klog.V(2).Infof("Updating ClusterRoleBinding %s due to diff: %v", required.Name, cmp.Diff(existing, required))
 	}
 
 	actual, err := client.ClusterRoleBindings().Update(ctx, existing, metav1.UpdateOptions{})
@@ -64,7 +64,7 @@ func ApplyClusterRolev1(ctx context.Context, client rbacclientv1.ClusterRolesGet
 		return existing, false, nil
 	}
 	if reconciling {
-		klog.V(4).Infof("Updating ClusterRole %s due to diff: %v", required.Name, cmp.Diff(existing, required))
+		klog.V(2).Infof("Updating ClusterRole %s due to diff: %v", required.Name, cmp.Diff(existing, required))
 	}
 
 	actual, err := client.ClusterRoles().Update(ctx, existing, metav1.UpdateOptions{})
@@ -93,7 +93,7 @@ func ApplyRoleBindingv1(ctx context.Context, client rbacclientv1.RoleBindingsGet
 		return existing, false, nil
 	}
 	if reconciling {
-		klog.V(4).Infof("Updating RoleBinding %s/%s due to diff: %v", required.Namespace, required.Name, cmp.Diff(existing, required))
+		klog.V(2).Infof("Updating RoleBinding %s/%s due to diff: %v", required.Namespace, required.Name, cmp.Diff(existing, required))
 	}
 
 	actual, err := client.RoleBindings(required.Namespace).Update(ctx, existing, metav1.UpdateOptions{})
@@ -122,7 +122,7 @@ func ApplyRolev1(ctx context.Context, client rbacclientv1.RolesGetter, required
 		return existing, false, nil
 	}
 	if reconciling {
-		klog.V(4).Infof("Updating Role %s/%s due to diff: %v", required.Namespace, required.Name, cmp.Diff(existing, required))
+		klog.V(2).Infof("Updating Role %s/%s due to diff: %v", required.Namespace, required.Name, cmp.Diff(existing, required))
 	}
 
 	actual, err := client.Roles(required.Namespace).Update(ctx, existing, metav1.UpdateOptions{})

lib/resourceapply/security.go

@@ -36,7 +36,7 @@ func ApplySecurityContextConstraintsv1(ctx context.Context, client securityclien
 	}
 
 	if reconciling {
-		klog.V(4).Infof("Updating SCC %s due to diff: %v", required.Name, cmp.Diff(existing, required))
+		klog.V(2).Infof("Updating SCC %s due to diff: %v", required.Name, cmp.Diff(existing, required))
 	}
 
 	actual, err := client.SecurityContextConstraints().Update(ctx, existing, metav1.UpdateOptions{})

lib/resourcebuilder/batch.go

@@ -19,7 +19,7 @@ func WaitForJobCompletion(ctx context.Context, client batchclientv1.JobsGetter,
 			klog.Error(err)
 			return false, nil
 		} else if !done {
-			klog.V(4).Infof("Job %s in namespace %s is not ready, continuing to wait.", job.ObjectMeta.Name, job.ObjectMeta.Namespace)
+			klog.V(2).Infof("Job %s in namespace %s is not ready, continuing to wait.", job.ObjectMeta.Name, job.ObjectMeta.Namespace)
 			return false, nil
 		}
 		return true, nil
@@ -50,7 +50,7 @@ func checkJobHealth(ctx context.Context, client batchclientv1.JobsGetter, job *b
 	// the Job will 'Active == 0' if and only if it exceeds the deadline or if the update image could not be pulled.
 	// Failed jobs will be recreated in the next run.
 	if j.Status.Active == 0 {
-		klog.V(4).Infof("No active pods for job %s in namespace %s", job.Name, job.Namespace)
+		klog.V(2).Infof("No active pods for job %s in namespace %s", job.Name, job.Namespace)
 		failed, reason, message := hasJobFailed(job)
 		// If there is more than one failed job pod then get the cause for failure
 		if j.Status.Failed > 0 {
@@ -68,7 +68,7 @@ func checkJobHealth(ctx context.Context, client batchclientv1.JobsGetter, job *b
 			if reason == "DeadlineExceeded" {
 				return false, fmt.Errorf("deadline exceeded, reason: %q, message: %q", reason, message)
 			} else {
-				klog.V(4).Infof("Ignoring job %s in namespace %s with condition Failed=True because %s: %s", job.Name, job.Namespace, reason, message)
+				klog.V(2).Infof("Ignoring job %s in namespace %s with condition Failed=True because %s: %s", job.Name, job.Namespace, reason, message)
 			}
 		}
 	}

lib/resourcedelete/helper.go

@@ -62,7 +62,7 @@ func SetDeleteRequested(obj metav1.Object, resource Resource) {
 	deletedResources.lock.Lock()
 	deletedResources.m[resource] = times
 	deletedResources.lock.Unlock()
-	klog.V(4).Infof("Delete requested for %s.", resource)
+	klog.V(2).Infof("Delete requested for %s.", resource)
 }
 
 // SetDeleteVerified updates map entry to indicate resource deletion has been completed.
@@ -73,7 +73,7 @@ func SetDeleteVerified(resource Resource) {
 	deletedResources.lock.Lock()
 	deletedResources.m[resource] = times
 	deletedResources.lock.Unlock()
-	klog.V(4).Infof("Delete of %s completed.", resource)
+	klog.V(2).Infof("Delete of %s completed.", resource)
 }
 
 // getDeleteTimes returns map entry for given resource.
@@ -111,9 +111,9 @@ func GetDeleteProgress(resource Resource, getError error) (bool, error) {
 				SetDeleteVerified(resource)
 			} else {
 				if deletionTimes.Expected != nil {
-					klog.V(4).Infof("Delete of %s is expected by %s.", resource, deletionTimes.Expected.String())
+					klog.V(2).Infof("Delete of %s is expected by %s.", resource, deletionTimes.Expected.String())
 				} else {
-					klog.V(4).Infof("Delete of %s has already been requested.", resource)
+					klog.V(2).Infof("Delete of %s has already been requested.", resource)
 				}
 			}
 		}

pkg/autoupdate/autoupdate.go

@@ -153,9 +153,9 @@ func (ctrl *Controller) handleErr(err error, key interface{}) {
 
 func (ctrl *Controller) sync(ctx context.Context, key string) error {
 	startTime := time.Now()
-	klog.V(4).Infof("Started syncing auto-updates %q (%v)", key, startTime)
+	klog.V(2).Infof("Started syncing auto-updates %q (%v)", key, startTime)
 	defer func() {
-		klog.V(4).Infof("Finished syncing auto-updates %q (%v)", key, time.Since(startTime))
+		klog.V(2).Infof("Finished syncing auto-updates %q (%v)", key, time.Since(startTime))
 	}()
 
 	clusterversion, err := ctrl.cvLister.Get(ctrl.name)

pkg/cincinnati/cincinnati.go

@@ -80,16 +80,16 @@ func (c Client) GetUpdates(ctx context.Context, uri *url.URL, arch string, chann
 	req.Header.Add("Accept", GraphMediaType)
 	if c.transport != nil && c.transport.TLSClientConfig != nil {
 		if c.transport.TLSClientConfig.ClientCAs == nil {
-			klog.V(5).Infof("Using a root CA pool with 0 root CA subjects to request updates from %s", uri)
+			klog.V(2).Infof("Using a root CA pool with 0 root CA subjects to request updates from %s", uri)
 		} else {
-			klog.V(5).Infof("Using a root CA pool with %n root CA subjects to request updates from %s", len(c.transport.TLSClientConfig.RootCAs.Subjects()), uri)
+			klog.V(2).Infof("Using a root CA pool with %n root CA subjects to request updates from %s", len(c.transport.TLSClientConfig.RootCAs.Subjects()), uri)
 		}
 	}
 
 	if c.transport != nil && c.transport.Proxy != nil {
 		proxy, err := c.transport.Proxy(req)
 		if err == nil && proxy != nil {
-			klog.V(5).Infof("Using proxy %s to request updates from %s", proxy.Host, uri)
+			klog.V(2).Infof("Using proxy %s to request updates from %s", proxy.Host, uri)
 		}
 	}