Bug 2038936: *: 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

@@ -36,7 +36,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/resourcebuilder/batch.go

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

pkg/autoupdate/autoupdate.go

@@ -149,9 +149,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)
 		}
 	}
 

pkg/cvo/availableupdates.go

@@ -39,7 +39,7 @@ 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 && u.Upstream == upstream && u.Channel == channel && u.RecentlyChanged(optr.minimumUpdateCheckInterval) {
-		klog.V(4).Infof("Available updates were recently retrieved, will try later.")
+		klog.V(2).Infof("Available updates were recently retrieved, will try later.")
 		return nil
 	}
 

pkg/cvo/cvo.go

@@ -478,9 +478,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
@@ -490,11 +490,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
 	}
 
@@ -507,14 +507,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
@@ -549,9 +549,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)
@@ -571,9 +571,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

@@ -4099,7 +4099,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")

pkg/cvo/metrics.go

@@ -323,7 +323,7 @@ func (m *operatorMetrics) Collect(ch chan<- prometheus.Metric) {
 
 		for _, condition := range cv.Status.Conditions {
 			if condition.Status != configv1.ConditionFalse && condition.Status != configv1.ConditionTrue {
-				klog.V(4).Infof("skipping metrics for ClusterVersion condition %s=%s (neither True nor False)", condition.Type, condition.Status)
+				klog.V(2).Infof("skipping metrics for ClusterVersion condition %s=%s (neither True nor False)", condition.Type, condition.Status)
 				continue
 			}
 			g := m.clusterOperatorConditions.WithLabelValues("version", string(condition.Type), string(condition.Reason))
@@ -355,7 +355,7 @@ func (m *operatorMetrics) Collect(ch chan<- prometheus.Metric) {
 			}
 		}
 		if version == "" {
-			klog.V(4).Infof("ClusterOperator %s is not setting the 'operator' version", op.Name)
+			klog.V(2).Infof("ClusterOperator %s is not setting the 'operator' version", op.Name)
 		}
 		g := m.clusterOperatorUp.WithLabelValues(op.Name, version)
 		if resourcemerge.IsOperatorStatusConditionTrue(op.Status.Conditions, configv1.OperatorAvailable) {
@@ -366,7 +366,7 @@ func (m *operatorMetrics) Collect(ch chan<- prometheus.Metric) {
 		ch <- g
 		for _, condition := range op.Status.Conditions {
 			if condition.Status != configv1.ConditionFalse && condition.Status != configv1.ConditionTrue {
-				klog.V(4).Infof("skipping metrics for %s ClusterOperator condition %s=%s (neither True nor False)", op.Name, condition.Type, condition.Status)
+				klog.V(2).Infof("skipping metrics for %s ClusterOperator condition %s=%s (neither True nor False)", op.Name, condition.Type, condition.Status)
 				continue
 			}
 			g := m.clusterOperatorConditions.WithLabelValues(op.Name, string(condition.Type), string(condition.Reason))

pkg/cvo/status.go

@@ -61,7 +61,7 @@ func mergeOperatorHistory(config *configv1.ClusterVersion, desired configv1.Rele
 	}
 
 	if len(config.Status.History) == 0 {
-		klog.V(5).Infof("initialize new history completed=%t desired=%#v", completed, desired)
+		klog.V(2).Infof("initialize new history completed=%t desired=%#v", completed, desired)
 		config.Status.History = append(config.Status.History, configv1.UpdateHistory{
 			Version: desired.Version,
 			Image:   desired.Image,
@@ -78,15 +78,15 @@ func mergeOperatorHistory(config *configv1.ClusterVersion, desired configv1.Rele
 	}
 
 	if mergeEqualVersions(last, desired) {
-		klog.V(5).Infof("merge into existing history completed=%t desired=%#v last=%#v", completed, desired, last)
+		klog.V(2).Infof("merge into existing history completed=%t desired=%#v last=%#v", completed, desired, last)
 		if completed {
 			last.State = configv1.CompletedUpdate
 			if last.CompletionTime == nil {
 				last.CompletionTime = &now
 			}
 		}
 	} else {
-		klog.V(5).Infof("must add a new history entry completed=%t desired=%#v != last=%#v", completed, desired, last)
+		klog.V(2).Infof("must add a new history entry completed=%t desired=%#v != last=%#v", completed, desired, last)
 		if last.CompletionTime == nil {
 			last.CompletionTime = &now
 		}
@@ -115,7 +115,7 @@ func mergeOperatorHistory(config *configv1.ClusterVersion, desired configv1.Rele
 	}
 
 	// leave this here in case we find other future history bugs and need to debug it
-	if klog.V(5).Enabled() && len(config.Status.History) > 1 {
+	if klog.V(2).Enabled() && len(config.Status.History) > 1 {
 		if config.Status.History[0].Image == config.Status.History[1].Image && config.Status.History[0].Version == config.Status.History[1].Version {
 			data, _ := json.MarshalIndent(config.Status.History, "", "  ")
 			panic(fmt.Errorf("tried to update cluster version history to contain duplicate image entries: %s", string(data)))
@@ -158,7 +158,7 @@ const ClusterVersionInvalid configv1.ClusterStatusConditionType = "Invalid"
 // syncStatus calculates the new status of the ClusterVersion based on the current sync state and any
 // validation errors found. We allow the caller to pass the original object to avoid DeepCopying twice.
 func (optr *Operator) syncStatus(ctx context.Context, original, config *configv1.ClusterVersion, status *SyncWorkerStatus, validationErrs field.ErrorList) error {
-	klog.V(5).Infof("Synchronizing errs=%#v status=%#v", validationErrs, status)
+	klog.V(2).Infof("Synchronizing errs=%#v status=%#v", validationErrs, status)
 
 	cvUpdated := false
 	// update the config with the latest available updates