chore: Standardized logging with consistent keys and WithValues usage (#968)

* chore: convert fmt.Sprintf logging to structured logging WithValues

* resolved tallaxes comments

* resolved tallaxes comments

* fix: single-use WithValues() changed to direct key value pairs, pricing.go added region WithValues

* fix: WARN messages edited to be V(0) logs with more descriptive messages

* fix: WARN messages have V(-1) level

* fix: WithValues logging removed

* fix: revolsing tallaxes comments

* chore: camelcase for key values for logs

* chore: resourceName key edited to be more specific, Kubernetes resources capitalized, k8s expanded out

* docs: logging guidelines

* docs: more descriptive between V(-1) and Error + formatting

* fix: drop V(-1) for fallback and change to kebab case for instanceType and capacityType

* fix: drop all V(-1) to Info

---------

Co-authored-by: Alex Leites <[email protected]>

Author: alimaazamat

pkg/cache/unavailableofferings.go

@@ -75,12 +75,12 @@ func (u *UnavailableOfferings) MarkSpotUnavailableWithTTL(ctx context.Context, t
 // MarkUnavailableWithTTL allows us to mark an offering unavailable with a custom TTL
 func (u *UnavailableOfferings) MarkUnavailableWithTTL(ctx context.Context, unavailableReason, instanceType, zone, capacityType string, ttl time.Duration) {
 	// even if the key is already in the cache, we still need to call Set to extend the cached entry's TTL
-	log.FromContext(ctx).WithValues(
+	log.FromContext(ctx).V(1).Info("removing offering from offerings",
 		"unavailable", unavailableReason,
 		"instance-type", instanceType,
 		"zone", zone,
 		"capacity-type", capacityType,
-		"ttl", ttl).V(1).Info("removing offering from offerings")
+		"ttl", ttl)
 	u.cache.Set(key(instanceType, zone, capacityType), struct{}{}, ttl)
 	atomic.AddUint64(&u.SeqNum, 1)
 }

pkg/cloudprovider/cloudprovider.go

@@ -190,13 +190,13 @@ func (c *CloudProvider) waitOnPromise(ctx context.Context, promise *instance.Vir
 		vmName := lo.FromPtr(promise.VM.Name)
 		err = c.instanceProvider.Delete(ctx, vmName)
 		if cloudprovider.IgnoreNodeClaimNotFoundError(err) != nil {
-			log.FromContext(ctx).Error(err, fmt.Sprintf("failed to delete VM %s", vmName))
+			log.FromContext(ctx).Error(err, "failed to delete VM", "vmName", vmName)
 		}
 
 		if err = c.kubeClient.Delete(ctx, nodeClaim); err != nil {
 			err = client.IgnoreNotFound(err)
 			if err != nil {
-				log.FromContext(ctx).Error(err, "failed to delete nodeclaim %s, will wait for liveness TTL", nodeClaim.Name)
+				log.FromContext(ctx).Error(err, "failed to delete nodeclaim, will wait for liveness TTL", "NodeClaim", nodeClaim.Name)
 			}
 		}
 		metrics.NodeClaimsDisruptedTotal.Inc(map[string]string{
@@ -259,7 +259,7 @@ func (c *CloudProvider) Get(ctx context.Context, providerID string) (*karpv1.Nod
 	if err != nil {
 		return nil, fmt.Errorf("getting vm name, %w", err)
 	}
-	ctx = log.IntoContext(ctx, log.FromContext(ctx).WithValues("id", vmName))
+	ctx = log.IntoContext(ctx, log.FromContext(ctx).WithValues("vmName", vmName))
 	instance, err := c.instanceProvider.Get(ctx, vmName)
 	if err != nil {
 		return nil, fmt.Errorf("getting instance, %w", err)
@@ -295,8 +295,7 @@ func (c *CloudProvider) GetInstanceTypes(ctx context.Context, nodePool *karpv1.N
 }
 
 func (c *CloudProvider) Delete(ctx context.Context, nodeClaim *karpv1.NodeClaim) error {
-	ctx = log.IntoContext(ctx, log.FromContext(ctx).WithValues("nodeclaim", nodeClaim.Name))
-
+	ctx = log.IntoContext(ctx, log.FromContext(ctx).WithValues("NodeClaim", nodeClaim.Name))
 	vmName, err := utils.GetVMName(nodeClaim.Status.ProviderID)
 	if err != nil {
 		return fmt.Errorf("getting VM name, %w", err)
@@ -446,7 +445,7 @@ func (c *CloudProvider) instanceToNodeClaim(ctx context.Context, vm *armcompute.
 	}
 
 	if zone, err := utils.GetZone(vm); err != nil {
-		log.FromContext(ctx).Info(fmt.Sprintf("WARN: Failed to get zone for VM %s, %v", *vm.Name, err))
+		log.FromContext(ctx).Info("failed to get zone for VM, zone label will be empty", "vmName", *vm.Name, "error", err)
 	} else {
 		labels[corev1.LabelTopologyZone] = zone
 	}

pkg/cloudprovider/drift.go

@@ -88,7 +88,10 @@ func (c *CloudProvider) areStaticFieldsDrifted(ctx context.Context, nodeClaim *k
 	}
 
 	if nodeClassHash != nodeClaimHash {
-		logger.V(1).Info(fmt.Sprintf("drift triggered for %s, as nodeClassHash (%s) != nodeClaimHash (%s)", NodeClassDrift, nodeClassHash, nodeClaimHash))
+		logger.V(1).Info("drift triggered as nodeClassHash != nodeClaimHash",
+			"driftType", NodeClassDrift,
+			"nodeClassHash", nodeClassHash,
+			"nodeClaimHash", nodeClaimHash)
 		return NodeClassDrift, nil
 	}
 
@@ -104,7 +107,7 @@ func (c *CloudProvider) isK8sVersionDrifted(ctx context.Context, nodeClaim *karp
 		// Note: we don't consider this a hard failure for drift if the KubernetesVersion is invalid/not ready to use, so we ignore returning the error here.
 		// We simply ensure the stored version is valid and ready to use, if we are to calculate potential Drift based on it.
 		// TODO (charliedmcb): I'm wondering if we actually want to have these soft-error cases switch to return an error if no-drift condition was found across all of IsDrifted.
-		logger.Info(fmt.Sprintf("WARN: Kubernetes version readiness invalid when checking drift: %s", err))
+		logger.Info("kubernetes version not ready, skipping drift check", "error", err)
 		return "", nil //nolint:nilerr
 	}
 
@@ -115,7 +118,10 @@ func (c *CloudProvider) isK8sVersionDrifted(ctx context.Context, nodeClaim *karp
 
 	nodeK8sVersion := strings.TrimPrefix(node.Status.NodeInfo.KubeletVersion, "v")
 	if nodeK8sVersion != k8sVersion {
-		logger.V(1).Info(fmt.Sprintf("drift triggered for %s, with expected k8s version %s, and actual k8s version %s", K8sVersionDrift, k8sVersion, nodeK8sVersion))
+		logger.V(1).Info("drift triggered due to k8s version mismatch",
+			"driftType", K8sVersionDrift,
+			"expectedKubernetesVersion", k8sVersion,
+			"actualKubernetesVersion", nodeK8sVersion)
 		return K8sVersionDrift, nil
 	}
 	return "", nil
@@ -170,7 +176,7 @@ func (c *CloudProvider) isImageVersionDrifted(
 		// Note: we don't consider this a hard failure for drift if the Images are not ready to use, so we ignore returning the error here.
 		// The stored Images must be ready to use if we are to calculate potential Drift based on them.
 		// TODO (charliedmcb): I'm wondering if we actually want to have these soft-error cases switch to return an error if no-drift condition was found across all of IsDrifted.
-		logger.Info(fmt.Sprintf("WARN: NodeImage readiness invalid when checking drift: %s", err))
+		logger.Info("node image not ready, skipping drift check", "error", err)
 		return "", nil //nolint:nilerr
 	}
 	if len(nodeImages) == 0 {
@@ -185,7 +191,9 @@ func (c *CloudProvider) isImageVersionDrifted(
 		}
 	}
 
-	logger.V(1).Info(fmt.Sprintf("drift triggered for %s, as actual image id %s was not found in the set of currently available node images", ImageDrift, vmImageID))
+	logger.V(1).Info("drift triggered as actual image id was not found in the set of currently available node images",
+		"driftType", ImageDrift,
+		"actualImageID", vmImageID)
 	return ImageDrift, nil
 }
 
@@ -233,12 +241,10 @@ func (c *CloudProvider) isKubeletIdentityDrifted(ctx context.Context, nodeClaim
 	}
 
 	if kubeletIdentityClientID != opts.KubeletIdentityClientID {
-		logger.V(1).Info(
-			fmt.Sprintf("drift triggered for %s, with expected kubelet identity client id %s, and actual kubelet identity client id %s",
-				KubeletIdentityDrift,
-				opts.KubeletIdentityClientID,
-				kubeletIdentityClientID),
-		)
+		logger.V(1).Info("drift triggered due to expected and actual kubelet identity client id mismatch",
+			"driftType", KubeletIdentityDrift,
+			"expectedKubeletIdentityClientID", opts.KubeletIdentityClientID,
+			"actualKubeletIdentityClientID", kubeletIdentityClientID)
 		return KubeletIdentityDrift, nil
 	}
 
@@ -257,7 +263,7 @@ func (c *CloudProvider) getNodeForDrift(ctx context.Context, nodeClaim *karpv1.N
 			return nil, nil
 		}
 		if nodeclaimutils.IsDuplicateNodeError(err) {
-			logger.V(1).Info("WARN: Duplicate node error, invariant violated.")
+			logger.Info("duplicate node error detected, invariant violated")
 		}
 		return nil, err
 	}

pkg/controllers/nodeclaim/garbagecollection/instance_garbagecollection.go

@@ -94,7 +94,7 @@ func (c *VirtualMachine) Reconcile(ctx context.Context) (reconcile.Result, error
 }
 
 func (c *VirtualMachine) garbageCollect(ctx context.Context, nodeClaim *karpv1.NodeClaim, nodeList *v1.NodeList) error {
-	ctx = log.IntoContext(ctx, log.FromContext(ctx).WithValues("provider-id", nodeClaim.Status.ProviderID))
+	ctx = log.IntoContext(ctx, log.FromContext(ctx).WithValues("providerID", nodeClaim.Status.ProviderID))
 	if err := c.cloudProvider.Delete(ctx, nodeClaim); err != nil {
 		return corecloudprovider.IgnoreNodeClaimNotFoundError(err)
 	}
@@ -107,7 +107,7 @@ func (c *VirtualMachine) garbageCollect(ctx context.Context, nodeClaim *karpv1.N
 		if err := c.kubeClient.Delete(ctx, &node); err != nil {
 			return client.IgnoreNotFound(err)
 		}
-		log.FromContext(ctx).WithValues("node", node.Name).V(1).Info("garbage collected node")
+		log.FromContext(ctx).V(1).Info("garbage collected node", "Node", node.Name)
 	}
 	return nil
 }

pkg/controllers/nodeclaim/garbagecollection/nic_garbagecollection.go

@@ -96,7 +96,7 @@ func (c *NetworkInterface) Reconcile(ctx context.Context) (reconcile.Result, err
 				return
 			}
 
-			log.FromContext(ctx).WithValues("nic", nicName).Info("garbage collected NIC")
+			log.FromContext(ctx).Info("garbage collected NIC", "nicName", nicName)
 		}
 	})
 	return reconcile.Result{

pkg/controllers/nodeclaim/inplaceupdate/controller.go

@@ -84,7 +84,7 @@ func (c *Controller) Reconcile(ctx context.Context, nodeClaim *karpv1.NodeClaim)
 	}
 	actualHash := nodeClaim.Annotations[v1beta1.AnnotationInPlaceUpdateHash]
 
-	log.FromContext(ctx).V(1).Info(fmt.Sprintf("goal hash is: %q, actual hash is: %q", goalHash, actualHash))
+	log.FromContext(ctx).V(1).Info("comparing hashes", "goalHash", goalHash, "actualHash", actualHash)
 
 	// If there's no difference from goal state, no need to do anything else
 	if goalHash == actualHash {
@@ -95,6 +95,7 @@ func (c *Controller) Reconcile(ctx context.Context, nodeClaim *karpv1.NodeClaim)
 	if err != nil {
 		return reconcile.Result{}, err
 	}
+	ctx = log.IntoContext(ctx, log.FromContext(ctx).WithValues("vmName", vmName))
 
 	vm, err := c.instanceProvider.Get(ctx, vmName)
 	if err != nil {
@@ -184,6 +185,6 @@ func logVMPatch(ctx context.Context, update *armcompute.VirtualMachineUpdate) {
 			raw, _ := json.Marshal(update)
 			rawStr = string(raw)
 		}
-		log.FromContext(ctx).V(1).Info(fmt.Sprintf("applying patch to Azure VM: %s", rawStr))
+		log.FromContext(ctx).V(1).Info("applying patch to Azure VM", "vmPatch", rawStr)
 	}
 }

pkg/controllers/nodeclass/status/images.go

@@ -161,7 +161,7 @@ func (r *NodeImageReconciler) Reconcile(ctx context.Context, nodeClass *v1beta1.
 
 	// We care about the ordering of the slices here, as it translates to priority during selection, so not treating them as sets
 	if utils.HasChanged(nodeClass.Status.Images, goalImages, &hashstructure.HashOptions{SlicesAsSets: false}) {
-		logger.WithValues("existingImages", nodeClass.Status.Images).WithValues("newImages", goalImages).Info("new available images updated for nodeclass")
+		logger.Info("new available images updated for nodeclass", "existingImages", nodeClass.Status.Images, "newImages", goalImages)
 	}
 	nodeClass.Status.Images = goalImages
 	nodeClass.StatusConditions().SetTrue(v1beta1.ConditionTypeImagesReady)
@@ -203,7 +203,7 @@ func (r *NodeImageReconciler) isMaintenanceWindowOpen(ctx context.Context) (bool
 	// TODO: In the longer run, the maintenance window handling should be factored out into a sharable provider, rather than being contained
 	//     within the image controller itself.
 	if r.cm.HasChanged("nodeclass-maintenancewindowdata", mwConfigMap.Data) {
-		logger.WithValues("maintenanceWindowData", mwConfigMap.Data).Info("new maintenance window data discovered")
+		logger.Info("new maintenance window data discovered", "maintenanceWindowData", mwConfigMap.Data)
 	}
 	if len(mwConfigMap.Data) == 0 {
 		// An empty configmap means there's no maintenance windows defined, and its up to us when to preform maintenance

pkg/controllers/nodeclass/status/kubernetesversion.go

@@ -80,7 +80,7 @@ func (r *KubernetesVersionReconciler) Reconcile(ctx context.Context, nodeClass *
 
 	// Handles case 1: init, update kubernetes status to API server version found
 	if !nodeClass.StatusConditions().Get(v1beta1.ConditionTypeKubernetesVersionReady).IsTrue() || nodeClass.Status.KubernetesVersion == "" {
-		logger.V(1).Info(fmt.Sprintf("init kubernetes version: %s", goalK8sVersion))
+		logger.V(1).Info("init kubernetes version", "goalKubernetesVersion", goalK8sVersion)
 	} else {
 		// Check if there is an upgrade
 		newK8sVersion, err := semver.Parse(goalK8sVersion)
@@ -93,10 +93,10 @@ func (r *KubernetesVersionReconciler) Reconcile(ctx context.Context, nodeClass *
 		}
 		// Handles case 2: Upgrade kubernetes version [Note: we set node image to not ready, since we upgrade node image when there is a kubernetes upgrade]
 		if newK8sVersion.GT(currentK8sVersion) {
-			logger.V(1).Info(fmt.Sprintf("kubernetes upgrade detected: from %s (current), to %s (discovered)", currentK8sVersion.String(), newK8sVersion.String()))
+			logger.V(1).Info("kubernetes upgrade detected", "currentKubernetesVersion", currentK8sVersion.String(), "discoveredKubernetesVersion", newK8sVersion.String())
 			nodeClass.StatusConditions().SetFalse(v1beta1.ConditionTypeImagesReady, "KubernetesUpgrade", "Performing kubernetes upgrade, need to get latest images")
 		} else if newK8sVersion.LT(currentK8sVersion) {
-			logger.Info(fmt.Sprintf("WARN: detected potential kubernetes downgrade: from %s (current), to %s (discovered)", currentK8sVersion.String(), newK8sVersion.String()))
+			logger.Info("detected potential kubernetes downgrade, keeping current version", "currentKubernetesVersion", currentK8sVersion.String(), "discoveredKubernetesVersion", newK8sVersion.String())
 			// We do not currently support downgrading, so keep the kubernetes version the same
 			goalK8sVersion = nodeClass.Status.KubernetesVersion
 		}

pkg/operator/operator.go

@@ -262,20 +262,20 @@ func WaitForCRDs(ctx context.Context, timeout time.Duration, config *rest.Config
 		return fmt.Errorf("creating dynamic rest mapper, %w", err)
 	}
 
-	log.WithValues("timeout", timeout).Info("waiting for required CRDs to be available")
+	log.Info("waiting for required CRDs to be available", "timeout", timeout)
 	ctx, cancel := context.WithTimeout(ctx, timeout)
 	defer cancel()
 
 	for _, gvk := range requiredGVKs {
 		err := wait.PollUntilContextCancel(ctx, 10*time.Second, true, func(ctx context.Context) (bool, error) {
 			if _, err := restMapper.RESTMapping(gvk.GroupKind(), gvk.Version); err != nil {
 				if meta.IsNoMatchError(err) {
-					log.V(1).WithValues("gvk", gvk).Info("waiting for CRD to be available")
+					log.V(1).Info("waiting for CRD to be available", "gvk", gvk)
 					return false, nil
 				}
 				return false, err
 			}
-			log.V(1).WithValues("gvk", gvk).Info("CRD is available")
+			log.V(1).Info("CRD is available", "gvk", gvk)
 			return true, nil
 		})
 		if err != nil {

pkg/providers/imagefamily/resolver.go

@@ -115,7 +115,7 @@ func (r *defaultResolver) Resolve(
 		return nil, err
 	}
 
-	log.FromContext(ctx).Info(fmt.Sprintf("Resolved image %s for instance type %s", imageID, instanceType.Name))
+	log.FromContext(ctx).Info("resolved image", "imageID", imageID, "instance-type", instanceType.Name)
 
 	// TODO: as ProvisionModeBootstrappingClient path develops, we will eventually be able to drop the retrieval of imageDistro here.
 	imageDistro, err := mapToImageDistro(imageID, imageFamily)