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

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

@@ -34,7 +34,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

@@ -84,16 +84,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)
 		}
 	}
 

pkg/clusterconditions/cache/cache.go

@@ -116,7 +116,7 @@ func (c *Cache) Match(ctx context.Context, condition *configv1.ClusterCondition)
 		if thiefResult, ok := c.MatchResults[thiefKey]; ok {
 			detail = fmt.Sprintf(" (last evaluated on %s)", thiefResult.When)
 		}
-		klog.V(4).Infof("%s is the most stale cached cluster-condition match entry, but it is too fresh%s.  However, we don't have a cached evaluation for %s, so attempt to evaluate that now.", thiefKey, detail, key)
+		klog.V(2).Infof("%s is the most stale cached cluster-condition match entry, but it is too fresh%s.  However, we don't have a cached evaluation for %s, so attempt to evaluate that now.", thiefKey, detail, key)
 	}
 
 	// if we ended up stealing this Match call, log that, to make contention more clear
@@ -127,7 +127,7 @@ func (c *Cache) Match(ctx context.Context, condition *configv1.ClusterCondition)
 		} else {
 			reason = fmt.Sprintf("its last evaluation completed %s ago", now.Sub(thiefResult.When))
 		}
-		klog.V(4).Infof("%s is stealing this cluster-condition match call for %s, because %s", thiefKey, key, reason)
+		klog.V(2).Infof("%s is stealing this cluster-condition match call for %s, because %s", thiefKey, key, reason)
 	}
 
 	match, err := c.Condition.Match(ctx, targetCondition)
@@ -160,7 +160,7 @@ func (c *Cache) expireStaleMatchResults(ctx context.Context, now time.Time) {
 			aspect = "queued request"
 		}
 		if age > c.Expiration {
-			klog.V(4).Infof("pruning %q from the condition cache, as the %s is %s old", key, aspect, age)
+			klog.V(2).Infof("pruning %q from the condition cache, as the %s is %s old", key, aspect, age)
 			delete(c.MatchResults, key)
 		}
 	}

pkg/clusterconditions/clusterconditions.go

@@ -69,7 +69,7 @@ func Match(ctx context.Context, matchingRules []configv1.ClusterCondition) (bool
 	for _, config := range matchingRules {
 		condition, ok := Registry[config.Type]
 		if !ok {
-			klog.V(4).Infof("Skipping unrecognized cluster condition type %q", config.Type)
+			klog.V(2).Infof("Skipping unrecognized cluster condition type %q", config.Type)
 			continue
 		}
 		match, err := condition.Match(ctx, &config)

pkg/clusterconditions/promql/promql.go

@@ -79,7 +79,7 @@ func (p *PromQL) Match(ctx context.Context, condition *configv1.ClusterCondition
 	}
 
 	v1api := prometheusv1.NewAPI(client)
-	klog.V(4).Infof("evaluate %s cluster condition: %q", condition.Type, condition.PromQL.PromQL)
+	klog.V(2).Infof("evaluate %s cluster condition: %q", condition.Type, condition.PromQL.PromQL)
 	result, warnings, err := v1api.Query(ctx, condition.PromQL.PromQL, time.Now())
 	if err != nil {
 		return false, fmt.Errorf("executing PromQL query: %w", err)

pkg/cvo/availableupdates.go

@@ -41,16 +41,16 @@ func (optr *Operator) syncAvailableUpdates(ctx context.Context, config *configv1
 	// updates are only checked at most once per minimumUpdateCheckInterval or if the generation changes
 	u := optr.getAvailableUpdates()
 	if u == nil {
-		klog.V(4).Info("First attempt to retrieve available updates")
+		klog.V(2).Info("First attempt to retrieve available updates")
 	} else if !u.RecentlyChanged(optr.minimumUpdateCheckInterval) {
-		klog.V(4).Infof("Retrieving available updates again, because more than %s has elapsed since %s", optr.minimumUpdateCheckInterval, u.LastAttempt)
+		klog.V(2).Infof("Retrieving available updates again, because more than %s has elapsed since %s", optr.minimumUpdateCheckInterval, u.LastAttempt)
 	} else if channel != u.Channel {
-		klog.V(4).Infof("Retrieving available updates again, because the channel has changed from %q to %q", u.Channel, channel)
+		klog.V(2).Infof("Retrieving available updates again, because the channel has changed from %q to %q", u.Channel, channel)
 	} else if upstream == u.Upstream || (upstream == optr.defaultUpstreamServer && u.Upstream == "") {
-		klog.V(4).Infof("Available updates were recently retrieved, with less than %s elapsed since %s, will try later.", optr.minimumUpdateCheckInterval, u.LastAttempt)
+		klog.V(2).Infof("Available updates were recently retrieved, with less than %s elapsed since %s, will try later.", optr.minimumUpdateCheckInterval, u.LastAttempt)
 		return nil
 	} else {
-		klog.V(4).Infof("Retrieving available updates again, because the upstream has changed from %q to %q", u.Upstream, config.Spec.Upstream)
+		klog.V(2).Infof("Retrieving available updates again, because the upstream has changed from %q to %q", u.Upstream, config.Spec.Upstream)
 	}
 
 	transport, err := optr.getTransport()

pkg/cvo/cvo.go

@@ -511,9 +511,9 @@ func handleErr(ctx context.Context, queue workqueue.RateLimitingInterface, err e
 // It returns an error if it could not update the cluster version object.
 func (optr *Operator) sync(ctx context.Context, key string) error {
 	startTime := time.Now()
-	klog.V(4).Infof("Started syncing cluster version %q (%v)", key, startTime)
+	klog.V(2).Infof("Started syncing cluster version %q (%v)", key, startTime)
 	defer func() {
-		klog.V(4).Infof("Finished syncing cluster version %q (%v)", key, time.Since(startTime))
+		klog.V(2).Infof("Finished syncing cluster version %q (%v)", key, time.Since(startTime))
 	}()
 
 	// ensure the cluster version exists, that the object is valid, and that
@@ -523,11 +523,11 @@ func (optr *Operator) sync(ctx context.Context, key string) error {
 		return err
 	}
 	if changed {
-		klog.V(4).Infof("Cluster version changed, waiting for newer event")
+		klog.V(2).Infof("Cluster version changed, waiting for newer event")
 		return nil
 	}
 	if original == nil {
-		klog.V(4).Infof("No ClusterVersion object and defaulting not enabled, waiting for one")
+		klog.V(2).Infof("No ClusterVersion object and defaulting not enabled, waiting for one")
 		return nil
 	}
 
@@ -542,14 +542,14 @@ func (optr *Operator) sync(ctx context.Context, key string) error {
 	// identify the desired next version
 	desired, ok := findUpdateFromConfig(config)
 	if ok {
-		klog.V(4).Infof("Desired version from spec is %#v", desired)
+		klog.V(2).Infof("Desired version from spec is %#v", desired)
 	} else {
 		currentVersion := optr.currentVersion()
 		desired = configv1.Update{
 			Version: currentVersion.Version,
 			Image:   currentVersion.Image,
 		}
-		klog.V(4).Infof("Desired version from operator is %#v", desired)
+		klog.V(2).Infof("Desired version from operator is %#v", desired)
 	}
 
 	// handle the case of a misconfigured CVO by doing nothing
@@ -584,9 +584,9 @@ func (optr *Operator) sync(ctx context.Context, key string) error {
 // sync available updates. It only modifies cluster version.
 func (optr *Operator) availableUpdatesSync(ctx context.Context, key string) error {
 	startTime := time.Now()
-	klog.V(4).Infof("Started syncing available updates %q (%v)", key, startTime)
+	klog.V(2).Infof("Started syncing available updates %q (%v)", key, startTime)
 	defer func() {
-		klog.V(4).Infof("Finished syncing available updates %q (%v)", key, time.Since(startTime))
+		klog.V(2).Infof("Finished syncing available updates %q (%v)", key, time.Since(startTime))
 	}()
 
 	config, err := optr.cvLister.Get(optr.name)
@@ -603,9 +603,9 @@ func (optr *Operator) availableUpdatesSync(ctx context.Context, key string) erro
 // sync upgradeableCondition. It only modifies cluster version.
 func (optr *Operator) upgradeableSync(ctx context.Context, key string) error {
 	startTime := time.Now()
-	klog.V(4).Infof("Started syncing upgradeable %q (%v)", key, startTime)
+	klog.V(2).Infof("Started syncing upgradeable %q (%v)", key, startTime)
 	defer func() {
-		klog.V(4).Infof("Finished syncing upgradeable %q (%v)", key, time.Since(startTime))
+		klog.V(2).Infof("Finished syncing upgradeable %q (%v)", key, time.Since(startTime))
 	}()
 
 	config, err := optr.cvLister.Get(optr.name)

pkg/cvo/cvo_test.go

@@ -4011,7 +4011,7 @@ func fakeClientsetWithUpdates(obj *configv1.ClusterVersion) *fake.Clientset {
 			obj.Status = update.Status
 			rv, _ := strconv.Atoi(update.ResourceVersion)
 			obj.ResourceVersion = strconv.Itoa(rv + 1)
-			klog.V(5).Infof("updated object to %#v", obj)
+			klog.V(2).Infof("updated object to %#v", obj)
 			return true, obj.DeepCopy(), nil
 		}
 		return false, nil, fmt.Errorf("unrecognized")