Refactor logging in recommender, updater, and target components

Signed-off-by: Omer Aplatony <[email protected]>

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

@@ -121,8 +121,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.")
  }
@@ -223,10 +222,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 traslate 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.Warningf("%v", 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()
  }
  }
@@ -138,7 +138,7 @@ func NewControllerFetcher(config *rest.Config, kubeClient kube_client.Interface,
  if !synced {
  klog.Warningf("Could not sync cache for %s: %v", kind, err)
  } 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", "namespace", key.Namespace, "name", 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", "namespace", key.Namespace, "name", 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", "namespace", podToEvict.Namespace, "name", podToEvict.Name)
  return err
  }
  eventRecorder.Event(podToEvict, apiv1.EventTypeNormal, "EvictedByVPA",
@@ -199,7 +199,7 @@ 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 {
@@ -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, "namespace", creator.Namespace, "name", 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, "namespace", creator.Namespace, "name", creator.Name)
  continue
  }
  }

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

@@ -122,7 +122,7 @@ 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 {
@@ -142,17 +142,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
  }
 
@@ -172,7 +172,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")
@@ -225,7 +225,7 @@ func (u *updater) RunOnce(ctx context.Context) {
  klog.Warningf("evicting pod %s failed: %v", klog.KObj(pod), 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)
@@ -251,7 +251,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 +308,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

@@ -92,7 +92,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.")
@@ -174,7 +174,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

@@ -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)
  continue
  }
  recommendedRequest := vpa_api_util.GetRecommendationForContainer(podContainer.Name, recommendation)