Merge pull request kubernetes#7294 from omerap12/logging-vpa-routines…

…-updater-target

Refactor logging in recommender, updater, and target components

vertical-pod-autoscaler/pkg/recommender/main.go

@@ -123,8 +123,7 @@ func main() {
 	componentbaseoptions.BindLeaderElectionFlags(&leaderElection, pflag.CommandLine)
 
 	kube_flag.InitFlags()
-	klog.V(1).Infof("Vertical Pod Autoscaler %s Recommender: %v", common.VerticalPodAutoscalerVersion, *recommenderName)
-
+	klog.V(1).InfoS("Vertical Pod Autoscaler Recommender", "version", common.VerticalPodAutoscalerVersion, "recommenderName", *recommenderName)
 	if len(*vpaObjectNamespace) > 0 && len(*ignoredVpaObjectNamespaces) > 0 {
 		klog.Fatalf("--vpa-object-namespace and --ignored-vpa-object-namespaces are mutually exclusive and can't be set together.")
 	}
@@ -225,10 +224,10 @@ func run(healthCheck *metrics.HealthCheck) {
 			resourceMetrics[apiv1.ResourceMemory] = *externalMemoryMetric
 		}
 		externalClientOptions := &input_metrics.ExternalClientOptions{ResourceMetrics: resourceMetrics, ContainerNameLabel: *ctrNameLabel}
-		klog.V(1).Infof("Using External Metrics: %+v", externalClientOptions)
+		klog.V(1).InfoS("Using External Metrics", "options", externalClientOptions)
 		source = input_metrics.NewExternalClient(config, clusterState, *externalClientOptions)
 	} else {
-		klog.V(1).Infof("Using Metrics Server.")
+		klog.V(1).InfoS("Using Metrics Server")
 		source = input_metrics.NewPodMetricsesSource(resourceclient.NewForConfigOrDie(config))
 	}
 

vertical-pod-autoscaler/pkg/recommender/model/cluster.go

@@ -362,19 +362,19 @@ func (cluster *ClusterState) findOrCreateAggregateContainerState(containerID Con
 // 2) The last sample is too old to give meaningful recommendation (>8 days),
 // 3) There are no samples and the aggregate state was created >8 days ago.
 func (cluster *ClusterState) garbageCollectAggregateCollectionStates(ctx context.Context, now time.Time, controllerFetcher controllerfetcher.ControllerFetcher) {
-	klog.V(1).Info("Garbage collection of AggregateCollectionStates triggered")
+	klog.V(1).InfoS("Garbage collection of AggregateCollectionStates triggered")
 	keysToDelete := make([]AggregateStateKey, 0)
 	contributiveKeys := cluster.getContributiveAggregateStateKeys(ctx, controllerFetcher)
 	for key, aggregateContainerState := range cluster.aggregateStateMap {
 		isKeyContributive := contributiveKeys[key]
 		if !isKeyContributive && aggregateContainerState.isEmpty() {
 			keysToDelete = append(keysToDelete, key)
-			klog.V(1).Infof("Removing empty and not contributive AggregateCollectionState for %+v", key)
+			klog.V(1).InfoS("Removing empty and not contributive AggregateCollectionState", "key", key)
 			continue
 		}
 		if aggregateContainerState.isExpired(now) {
 			keysToDelete = append(keysToDelete, key)
-			klog.V(1).Infof("Removing expired AggregateCollectionState for %+v", key)
+			klog.V(1).InfoS("Removing expired AggregateCollectionState", "key", key)
 		}
 	}
 	for _, key := range keysToDelete {

vertical-pod-autoscaler/pkg/recommender/model/types.go

@@ -92,7 +92,7 @@ func ResourcesAsResourceList(resources Resources) apiv1.ResourceList {
 			newKey = apiv1.ResourceMemory
 			quantity = QuantityFromMemoryAmount(resourceAmount)
 		default:
-			klog.Errorf("Cannot translate %v resource name", key)
+			klog.ErrorS(nil, "Cannot translate resource name", "resourceName", key)
 			continue
 		}
 		result[newKey] = quantity
@@ -110,7 +110,7 @@ func ResourceNamesApiToModel(resources []apiv1.ResourceName) *[]ResourceName {
 		case apiv1.ResourceMemory:
 			result = append(result, ResourceMemory)
 		default:
-			klog.Errorf("Cannot translate %v resource name", resource)
+			klog.ErrorS(nil, "Cannot translate resource name", "resourceName", resource)
 			continue
 		}
 	}

vertical-pod-autoscaler/pkg/recommender/routines/capping_post_processor.go

@@ -34,7 +34,7 @@ func (c CappingPostProcessor) Process(vpa *vpa_types.VerticalPodAutoscaler, reco
 	// TODO: maybe rename the vpa_utils.ApplyVPAPolicy to something that mention that it is doing capping only
 	cappedRecommendation, err := vpa_utils.ApplyVPAPolicy(recommendation, vpa.Spec.ResourcePolicy)
 	if err != nil {
-		klog.Errorf("Failed to apply policy for VPA %s: %v", klog.KObj(vpa), err)
+		klog.ErrorS(err, "Failed to apply policy for VPA", "vpa", klog.KObj(vpa))
 		return recommendation
 	}
 	return cappedRecommendation

vertical-pod-autoscaler/pkg/recommender/routines/recommender.go

@@ -109,24 +109,19 @@ func (r *recommender) UpdateVPAs() {
 		if err := r.clusterState.RecordRecommendation(vpa, time.Now()); err != nil {
 			klog.V(0).InfoS("", "err", err)
 			if klog.V(4).Enabled() {
-				klog.Infof("VPA dump")
-				klog.Infof("%+v", vpa)
-				klog.Infof("HasMatchingPods: %v", hasMatchingPods)
-				klog.Infof("PodCount: %v", vpa.PodCount)
 				pods := r.clusterState.GetMatchingPods(vpa)
-				klog.Infof("MatchingPods: %+v", pods)
 				if len(pods) != vpa.PodCount {
-					klog.Errorf("ClusterState pod count and matching pods disagree for VPA %s", klog.KRef(vpa.ID.Namespace, vpa.ID.VpaName))
+					klog.ErrorS(nil, "ClusterState pod count and matching pods disagree for VPA", "vpa", klog.KRef(vpa.ID.Namespace, vpa.ID.VpaName), "podCount", vpa.PodCount, "MatchingPods", pods)
 				}
+				klog.InfoS("VPA dump", "vpa", vpa, "hasMatchingPods", hasMatchingPods, "podCount", vpa.PodCount, "matchingPods", pods)
 			}
 		}
 		cnt.Add(vpa)
 
 		_, err := vpa_utils.UpdateVpaStatusIfNeeded(
 			r.vpaClient.VerticalPodAutoscalers(vpa.ID.Namespace), vpa.ID.VpaName, vpa.AsStatus(), &observedVpa.Status)
 		if err != nil {
-			klog.Errorf(
-				"Cannot update VPA %s object. Reason: %+v", klog.KRef(vpa.ID.Namespace, vpa.ID.VpaName), err)
+			klog.ErrorS(err, "Cannot update VPA", "vpa", klog.KRef(vpa.ID.Namespace, vpa.ID.VpaName))
 		}
 	}
 }
@@ -150,7 +145,7 @@ func (r *recommender) RunOnce() {
 
 	ctx := context.Background()
 
-	klog.V(3).Infof("Recommender Run")
+	klog.V(3).InfoS("Recommender Run")
 
 	r.clusterStateFeeder.LoadVPAs(ctx)
 	timer.ObserveStep("LoadVPAs")
@@ -160,7 +155,7 @@ func (r *recommender) RunOnce() {
 
 	r.clusterStateFeeder.LoadRealTimeMetrics()
 	timer.ObserveStep("LoadMetrics")
-	klog.V(3).Infof("ClusterState is tracking %v PodStates and %v VPAs", len(r.clusterState.Pods), len(r.clusterState.Vpas))
+	klog.V(3).InfoS("ClusterState is tracking", "pods", len(r.clusterState.Pods), "vpas", len(r.clusterState.Vpas))
 
 	r.UpdateVPAs()
 	timer.ObserveStep("UpdateVPAs")
@@ -172,7 +167,7 @@ func (r *recommender) RunOnce() {
 
 	r.clusterState.RateLimitedGarbageCollectAggregateCollectionStates(ctx, time.Now(), r.controllerFetcher)
 	timer.ObserveStep("GarbageCollect")
-	klog.V(3).Infof("ClusterState is tracking %d aggregated container states", r.clusterState.StateMapSize())
+	klog.V(3).InfoS("ClusterState is tracking", "aggregateContainerStates", r.clusterState.StateMapSize())
 }
 
 // RecommenderFactory makes instances of Recommender.
@@ -207,6 +202,6 @@ func (c RecommenderFactory) Make() Recommender {
 		lastAggregateContainerStateGC: time.Now(),
 		lastCheckpointGC:              time.Now(),
 	}
-	klog.V(3).Infof("New Recommender created %+v", recommender)
+	klog.V(3).InfoS("New Recommender created", "recommender", recommender)
 	return recommender
 }

vertical-pod-autoscaler/pkg/target/controller_fetcher/controller_cache_storage.go

@@ -132,7 +132,7 @@ func (cc *controllerCacheStorage) Insert(namespace string, groupResource schema.
 
 // Removes entries which we didn't read in a while from the cache.
 func (cc *controllerCacheStorage) RemoveExpired() {
-	klog.V(5).Info("Removing entries from controllerCacheStorage")
+	klog.V(5).InfoS("Removing entries from controllerCacheStorage")
 	cc.mux.Lock()
 	defer cc.mux.Unlock()
 	now := now()
@@ -143,7 +143,7 @@ func (cc *controllerCacheStorage) RemoveExpired() {
 			delete(cc.cache, k)
 		}
 	}
-	klog.V(5).Infof("Removed %d entries from controllerCacheStorage", removed)
+	klog.V(5).InfoS("Removed entries from controllerCacheStorage", "removed", removed)
 }
 
 // Returns a list of keys for which values need to be refreshed

vertical-pod-autoscaler/pkg/target/controller_fetcher/controller_fetcher.go

@@ -92,12 +92,12 @@ func (f *controllerFetcher) periodicallyRefreshCache(ctx context.Context, period
 			return
 		case <-time.After(period):
 			keysToRefresh := f.scaleSubresourceCacheStorage.GetKeysToRefresh()
-			klog.V(5).Info("Starting to refresh entries in controllerFetchers scaleSubresourceCacheStorage")
+			klog.V(5).InfoS("Starting to refresh entries in controllerFetchers scaleSubresourceCacheStorage")
 			for _, item := range keysToRefresh {
 				scale, err := f.scaleNamespacer.Scales(item.namespace).Get(context.TODO(), item.groupResource, item.name, metav1.GetOptions{})
 				f.scaleSubresourceCacheStorage.Refresh(item.namespace, item.groupResource, item.name, scale, err)
 			}
-			klog.V(5).Infof("Finished refreshing %d entries in controllerFetchers scaleSubresourceCacheStorage", len(keysToRefresh))
+			klog.V(5).InfoS("Finished refreshing entries in controllerFetchers scaleSubresourceCacheStorage", "refreshed", len(keysToRefresh))
 			f.scaleSubresourceCacheStorage.RemoveExpired()
 		}
 	}
@@ -136,9 +136,9 @@ func NewControllerFetcher(config *rest.Config, kubeClient kube_client.Interface,
 		go informer.Run(stopCh)
 		synced := cache.WaitForCacheSync(stopCh, informer.HasSynced)
 		if !synced {
-			klog.Warningf("Could not sync cache for %s: %v", kind, err)
+			klog.V(0).InfoS("Initial sync failed", "kind", kind)
 		} else {
-			klog.Infof("Initial sync of %s completed", kind)
+			klog.InfoS("Initial sync completed", "kind", kind)
 		}
 	}
 
@@ -261,7 +261,7 @@ func (f *controllerFetcher) isWellKnownOrScalable(ctx context.Context, key *Cont
 	//if not well known check if it supports scaling
 	groupKind, err := key.groupKind()
 	if err != nil {
-		klog.Errorf("Could not find groupKind for %s/%s: %v", key.Namespace, key.Name, err)
+		klog.ErrorS(err, "Could not find groupKind", klog.KRef(key.Namespace, key.Name))
 		return false
 	}
 
@@ -271,7 +271,7 @@ func (f *controllerFetcher) isWellKnownOrScalable(ctx context.Context, key *Cont
 
 	mappings, err := f.mapper.RESTMappings(groupKind)
 	if err != nil {
-		klog.Errorf("Could not find mappings for %s: %v", groupKind, err)
+		klog.ErrorS(err, "Could not find mappings", klog.KRef(key.Namespace, key.Name))
 		return false
 	}
 

vertical-pod-autoscaler/pkg/updater/eviction/pods_eviction_restriction.go

@@ -140,7 +140,7 @@ func (e *podsEvictionRestrictionImpl) Evict(podToEvict *apiv1.Pod, eventRecorder
 	}
 	err := e.client.CoreV1().Pods(podToEvict.Namespace).EvictV1(context.TODO(), eviction)
 	if err != nil {
-		klog.Errorf("failed to evict pod %s/%s, error: %v", podToEvict.Namespace, podToEvict.Name, err)
+		klog.ErrorS(err, "Failed to evict pod", klog.KObj(podToEvict))
 		return err
 	}
 	eventRecorder.Event(podToEvict, apiv1.EventTypeNormal, "EvictedByVPA",
@@ -199,11 +199,11 @@ func (f *podsEvictionRestrictionFactoryImpl) NewPodsEvictionRestriction(pods []*
 	for _, pod := range pods {
 		creator, err := getPodReplicaCreator(pod)
 		if err != nil {
-			klog.Errorf("failed to obtain replication info for pod %s: %v", klog.KObj(pod), err)
+			klog.ErrorS(err, "Failed to obtain replication info for pod", "pod", klog.KObj(pod))
 			continue
 		}
 		if creator == nil {
-			klog.Warningf("pod %s not replicated", pod.Name)
+			klog.V(0).InfoS("Pod is not managed by any controller", "pod", klog.KObj(pod))
 			continue
 		}
 		livePods[*creator] = append(livePods[*creator], pod)
@@ -216,15 +216,13 @@ func (f *podsEvictionRestrictionFactoryImpl) NewPodsEvictionRestriction(pods []*
 	required := f.minReplicas
 	if vpa.Spec.UpdatePolicy != nil && vpa.Spec.UpdatePolicy.MinReplicas != nil {
 		required = int(*vpa.Spec.UpdatePolicy.MinReplicas)
-		klog.V(3).Infof("overriding minReplicas from global %v to per-VPA %v for VPA %s",
-			f.minReplicas, required, klog.KObj(vpa))
+		klog.V(3).InfoS("Overriding minReplicas from global to per-VPA value", "globalMinReplicas", f.minReplicas, "vpaMinReplicas", required, "vpa", klog.KObj(vpa))
 	}
 
 	for creator, replicas := range livePods {
 		actual := len(replicas)
 		if actual < required {
-			klog.V(2).Infof("too few replicas for %v %v/%v. Found %v live pods, needs %v (global %v)",
-				creator.Kind, creator.Namespace, creator.Name, actual, required, f.minReplicas)
+			klog.V(2).InfoS("Too few replicas", "kind", creator.Kind, klog.KRef(creator.Namespace, creator.Name), "livePods", actual, "requiredPods", required, "globalMinReplicas", f.minReplicas)
 			continue
 		}
 
@@ -236,8 +234,7 @@ func (f *podsEvictionRestrictionFactoryImpl) NewPodsEvictionRestriction(pods []*
 			var err error
 			configured, err = f.getReplicaCount(creator)
 			if err != nil {
-				klog.Errorf("failed to obtain replication info for %v %v/%v. %v",
-					creator.Kind, creator.Namespace, creator.Name, err)
+				klog.ErrorS(err, "Failed to obtain replication info", "kind", creator.Kind, klog.KRef(creator.Namespace, creator.Name))
 				continue
 			}
 		}

vertical-pod-autoscaler/pkg/updater/logic/updater.go

@@ -122,12 +122,11 @@ func (u *updater) RunOnce(ctx context.Context) {
 	if u.useAdmissionControllerStatus {
 		isValid, err := u.statusValidator.IsStatusValid(ctx, status.AdmissionControllerStatusTimeout)
 		if err != nil {
-			klog.Errorf("Error getting Admission Controller status: %v. Skipping eviction loop", err)
+			klog.ErrorS(err, "Error getting Admission Controller status. Skipping eviction loop")
 			return
 		}
 		if !isValid {
-			klog.Warningf("Admission Controller status has been refreshed more than %v ago. Skipping eviction loop",
-				status.AdmissionControllerStatusTimeout)
+			klog.V(0).InfoS("Admission Controller status is not valid. Skipping eviction loop", "timeout", status.AdmissionControllerStatusTimeout)
 			return
 		}
 	}
@@ -142,17 +141,17 @@ func (u *updater) RunOnce(ctx context.Context) {
 
 	for _, vpa := range vpaList {
 		if slices.Contains(u.ignoredNamespaces, vpa.Namespace) {
-			klog.V(3).Infof("skipping VPA object %s in namespace %s as namespace is ignored", vpa.Name, vpa.Namespace)
+			klog.V(3).InfoS("Skipping VPA object in ignored namespace", "vpa", klog.KObj(vpa), "namespace", vpa.Namespace)
 			continue
 		}
 		if vpa_api_util.GetUpdateMode(vpa) != vpa_types.UpdateModeRecreate &&
 			vpa_api_util.GetUpdateMode(vpa) != vpa_types.UpdateModeAuto {
-			klog.V(3).Infof("skipping VPA object %s because its mode is not \"Recreate\" or \"Auto\"", klog.KObj(vpa))
+			klog.V(3).InfoS("Skipping VPA object because its mode is not \"Recreate\" or \"Auto\"", "vpa", klog.KObj(vpa))
 			continue
 		}
 		selector, err := u.selectorFetcher.Fetch(ctx, vpa)
 		if err != nil {
-			klog.V(3).Infof("skipping VPA object %s because we cannot fetch selector", klog.KObj(vpa))
+			klog.V(3).InfoS("Skipping VPA object because we cannot fetch selector", "vpa", klog.KObj(vpa))
 			continue
 		}
 
@@ -163,7 +162,7 @@ func (u *updater) RunOnce(ctx context.Context) {
 	}
 
 	if len(vpas) == 0 {
-		klog.Warningf("no VPA objects to process")
+		klog.V(0).InfoS("No VPA objects to process")
 		if u.evictionAdmission != nil {
 			u.evictionAdmission.CleanUp()
 		}
@@ -172,7 +171,7 @@ func (u *updater) RunOnce(ctx context.Context) {
 
 	podsList, err := u.podLister.List(labels.Everything())
 	if err != nil {
-		klog.Errorf("failed to get pods list: %v", err)
+		klog.ErrorS(err, "Failed to get pods list")
 		return
 	}
 	timer.ObserveStep("ListPods")
@@ -222,13 +221,13 @@ func (u *updater) RunOnce(ctx context.Context) {
 			}
 			err := u.evictionRateLimiter.Wait(ctx)
 			if err != nil {
-				klog.Warningf("evicting pod %s failed: %v", klog.KObj(pod), err)
+				klog.V(0).InfoS("Eviction rate limiter wait failed", "error", err)
 				return
 			}
-			klog.V(2).Infof("evicting pod %s", klog.KObj(pod))
+			klog.V(2).InfoS("Evicting pod", "pod", klog.KObj(pod))
 			evictErr := evictionLimiter.Evict(pod, u.eventRecorder)
 			if evictErr != nil {
-				klog.Warningf("evicting pod %s failed: %v", klog.KObj(pod), evictErr)
+				klog.V(0).InfoS("Eviction failed", "error", evictErr, "pod", klog.KObj(pod))
 			} else {
 				withEvicted = true
 				metrics_updater.AddEvictedPod(vpaSize)
@@ -251,7 +250,7 @@ func getRateLimiter(evictionRateLimit float64, evictionRateLimitBurst int) *rate
 		// As a special case if the rate is set to rate.Inf, the burst rate is ignored
 		// see https://github.com/golang/time/blob/master/rate/rate.go#L37
 		evictionRateLimiter = rate.NewLimiter(rate.Inf, 0)
-		klog.V(1).Info("Rate limit disabled")
+		klog.V(1).InfoS("Rate limit disabled")
 	} else {
 		evictionRateLimiter = rate.NewLimiter(rate.Limit(evictionRateLimit), evictionRateLimitBurst)
 	}
@@ -308,7 +307,7 @@ func newPodLister(kubeClient kube_client.Interface, namespace string) v1lister.P
 
 func newEventRecorder(kubeClient kube_client.Interface) record.EventRecorder {
 	eventBroadcaster := record.NewBroadcaster()
-	eventBroadcaster.StartLogging(klog.V(4).Infof)
+	eventBroadcaster.StartLogging(klog.V(4).InfoS)
 	if _, isFake := kubeClient.(*fake.Clientset); !isFake {
 		eventBroadcaster.StartRecordingToSink(&clientv1.EventSinkImpl{Interface: clientv1.New(kubeClient.CoreV1().RESTClient()).Events("")})
 	}

vertical-pod-autoscaler/pkg/updater/main.go

@@ -94,7 +94,7 @@ func main() {
 	componentbaseoptions.BindLeaderElectionFlags(&leaderElection, pflag.CommandLine)
 
 	kube_flag.InitFlags()
-	klog.V(1).Infof("Vertical Pod Autoscaler %s Updater", common.VerticalPodAutoscalerVersion)
+	klog.V(1).InfoS("Vertical Pod Autoscaler Updater", "version", common.VerticalPodAutoscalerVersion)
 
 	if len(*vpaObjectNamespace) > 0 && len(*ignoredVpaObjectNamespaces) > 0 {
 		klog.Fatalf("--vpa-object-namespace and --ignored-vpa-object-namespaces are mutually exclusive and can't be set together.")
@@ -177,7 +177,7 @@ func run(healthCheck *metrics.HealthCheck) {
 	var limitRangeCalculator limitrange.LimitRangeCalculator
 	limitRangeCalculator, err := limitrange.NewLimitsRangeCalculator(factory)
 	if err != nil {
-		klog.Errorf("Failed to create limitRangeCalculator, falling back to not checking limits. Error message: %s", err)
+		klog.ErrorS(err, "Failed to create limitRangeCalculator, falling back to not checking limits")
 		limitRangeCalculator = limitrange.NewNoopLimitsCalculator()
 	}
 	admissionControllerStatusNamespace := status.AdmissionControllerStatusNamespace

vertical-pod-autoscaler/pkg/updater/priority/priority_processor.go

@@ -40,7 +40,7 @@ func NewProcessor() PriorityProcessor {
 type defaultPriorityProcessor struct {
 }
 
-func (*defaultPriorityProcessor) GetUpdatePriority(pod *apiv1.Pod, _ *vpa_types.VerticalPodAutoscaler,
+func (*defaultPriorityProcessor) GetUpdatePriority(pod *apiv1.Pod, vpa *vpa_types.VerticalPodAutoscaler,
 	recommendation *vpa_types.RecommendedPodResources) PodPriority {
 	outsideRecommendedRange := false
 	scaleUp := false
@@ -53,8 +53,7 @@ func (*defaultPriorityProcessor) GetUpdatePriority(pod *apiv1.Pod, _ *vpa_types.
 
 	for _, podContainer := range pod.Spec.Containers {
 		if hasObservedContainers && !vpaContainerSet.Has(podContainer.Name) {
-			klog.V(4).Infof("Not listed in %s:%s. Skipping container %s priority calculations",
-				annotations.VpaObservedContainersLabel, pod.GetAnnotations()[annotations.VpaObservedContainersLabel], podContainer.Name)
+			klog.V(4).InfoS("Not listed in VPA observed containers label. Skipping container priority calculations", "label", annotations.VpaObservedContainersLabel, "observedContainers", pod.GetAnnotations()[annotations.VpaObservedContainersLabel], "containerName", podContainer.Name, "vpa", klog.KObj(vpa))
 			continue
 		}
 		recommendedRequest := vpa_api_util.GetRecommendationForContainer(podContainer.Name, recommendation)