structured logging for pkg/control

pkg/control/pubcontrol/pub_control.go

@@ -57,7 +57,7 @@ func (c *commonControl) IsPodReady(pod *corev1.Pod) bool {
 func (c *commonControl) IsPodUnavailableChanged(oldPod, newPod *corev1.Pod) bool {
 	// If pod.spec changed, pod will be in unavailable condition
 	if !reflect.DeepEqual(oldPod.Spec, newPod.Spec) {
-		klog.V(3).Infof("pod(%s/%s) specification changed, and maybe cause unavailability", newPod.Namespace, newPod.Name)
+		klog.V(3).InfoS("Pod specification changed, and maybe cause unavailability", "pod", klog.KObj(newPod))
 		return true
 	}
 	// pod add unavailable label
@@ -80,13 +80,13 @@ func (c *commonControl) GetPodsForPub(pub *policyv1alpha1.PodUnavailableBudget)
 		matchedPods, expectedCount, err := c.controllerFinder.GetPodsForRef(ref.APIVersion, ref.Kind, pub.Namespace, ref.Name, true)
 		return matchedPods, expectedCount, err
 	} else if pub.Spec.Selector == nil {
-		klog.Warningf("pub(%s/%s) spec.Selector cannot be empty", pub.Namespace, pub.Name)
+		klog.InfoS("Pub spec.Selector could not be empty", "pub", klog.KObj(pub))
 		return nil, 0, nil
 	}
 	// get pods for selector
 	labelSelector, err := util.ValidatedLabelSelectorAsSelector(pub.Spec.Selector)
 	if err != nil {
-		klog.Warningf("pub(%s/%s) ValidatedLabelSelectorAsSelector failed: %s", pub.Namespace, pub.Name, err.Error())
+		klog.InfoS("Pub ValidatedLabelSelectorAsSelector failed", "pub", klog.KObj(pub), "error", err)
 		return nil, 0, nil
 	}
 	listOptions = &client.ListOptions{Namespace: pub.Namespace, LabelSelector: labelSelector}
@@ -125,7 +125,7 @@ func (c *commonControl) IsPodStateConsistent(pod *corev1.Pod) bool {
 		}
 
 		if !util.IsPodContainerDigestEqual(sets.NewString(container.Name), pod) {
-			klog.V(5).Infof("pod(%s/%s) container(%s) image is inconsistent", pod.Namespace, pod.Name, container.Name)
+			klog.V(5).InfoS("Pod container image was inconsistent", "pod", klog.KObj(pod), "containerName", container.Name)
 			return false
 		}
 	}
@@ -138,14 +138,14 @@ func (c *commonControl) IsPodStateConsistent(pod *corev1.Pod) bool {
 	sidecarSets, sidecars := getSidecarSetsInPod(pod)
 	if sidecarSets.Len() > 0 && sidecars.Len() > 0 {
 		if !sidecarcontrol.IsSidecarContainerUpdateCompleted(pod, sidecarSets, sidecars) {
-			klog.V(5).Infof("PodUnavailableBudget check Pod(%s/%s) is inconsistent", pod.Namespace, pod.Name)
+			klog.V(5).InfoS("PodUnavailableBudget check pod was inconsistent", "pod", klog.KObj(pod))
 			return false
 		}
 	}
 
 	// whether other containers is consistent
 	if err := inplaceupdate.DefaultCheckInPlaceUpdateCompleted(pod); err != nil {
-		klog.V(5).Infof("check pod(%s/%s) InPlaceUpdate failed: %s", pod.Namespace, pod.Name, err.Error())
+		klog.V(5).InfoS("Failed to check pod InPlaceUpdate", "pod", klog.KObj(pod), "error", err)
 		return false
 	}
 
@@ -161,7 +161,7 @@ func (c *commonControl) GetPubForPod(pod *corev1.Pod) (*policyv1alpha1.PodUnavai
 	err := c.Get(context.TODO(), client.ObjectKey{Namespace: pod.Namespace, Name: pubName}, pub)
 	if err != nil {
 		if errors.IsNotFound(err) {
-			klog.Warningf("pod(%s/%s) pub(%s) Is NotFound", pod.Namespace, pod.Name, pubName)
+			klog.InfoS("Pod pub was NotFound", "pod", klog.KObj(pod), "pubName", pubName)
 			return nil, nil
 		}
 		return nil, err

pkg/control/pubcontrol/pub_control_utils.go

@@ -59,15 +59,15 @@ const (
 // 1. allowed(bool) indicates whether to allow this update operation
 // 2. err(error)
 func PodUnavailableBudgetValidatePod(pod *corev1.Pod, operation policyv1alpha1.PubOperation, username string, dryRun bool) (allowed bool, reason string, err error) {
-	klog.V(3).Infof("validating pod(%s/%s) operation(%s) for PodUnavailableBudget", pod.Namespace, pod.Name, operation)
+	klog.V(3).InfoS("Validated pod operation for podUnavailableBudget", "pod", klog.KObj(pod), "operation", operation)
 	// pods that contain annotations[pod.kruise.io/pub-no-protect]="true" will be ignore
 	// and will no longer check the pub quota
 	if pod.Annotations[policyv1alpha1.PodPubNoProtectionAnnotation] == "true" {
-		klog.V(3).Infof("pod(%s/%s) contains annotations[%s]=true, then don't need check pub", pod.Namespace, pod.Name, policyv1alpha1.PodPubNoProtectionAnnotation)
+		klog.V(3).InfoS("Pod contained annotations=true, then didn't need check pub", "pod", klog.KObj(pod), "annotations", policyv1alpha1.PodPubNoProtectionAnnotation)
 		return true, "", nil
 		// If the pod is not ready or state is inconsistent, it doesn't count towards healthy and we should not decrement
 	} else if !PubControl.IsPodReady(pod) || !PubControl.IsPodStateConsistent(pod) {
-		klog.V(3).Infof("pod(%s/%s) is not ready or state is inconsistent, then don't need check pub", pod.Namespace, pod.Name)
+		klog.V(3).InfoS("Pod was not ready or state was inconsistent, then didn't need check pub", "pod", klog.KObj(pod))
 		return true, "", nil
 	}
 
@@ -82,11 +82,11 @@ func PodUnavailableBudgetValidatePod(pod *corev1.Pod, operation policyv1alpha1.P
 	} else if pub.Status.DesiredAvailable == 0 {
 		return true, "", nil
 	} else if !isNeedPubProtection(pub, operation) {
-		klog.V(3).Infof("pod(%s/%s) operation(%s) is not in pub(%s) protection", pod.Namespace, pod.Name, operation, pub.Name)
+		klog.V(3).InfoS("Pod operation was not in pub protection", "pod", klog.KObj(pod), "operation", operation, "pubName", pub.Name)
 		return true, "", nil
 		// pod is in pub.Status.DisruptedPods or pub.Status.UnavailablePods, then don't need check it
 	} else if isPodRecordedInPub(pod.Name, pub) {
-		klog.V(3).Infof("pod(%s/%s) already is recorded in pub(%s/%s)", pod.Namespace, pod.Name, pub.Namespace, pub.Name)
+		klog.V(3).InfoS("Pod was already recorded in pub", "pod", klog.KObj(pod), "pub", klog.KObj(pub))
 		return true, "", nil
 	}
 	// check and decrement pub quota
@@ -103,14 +103,14 @@ func PodUnavailableBudgetValidatePod(pod *corev1.Pod, operation policyv1alpha1.P
 			pubClone, err = kubeClient.GetGenericClient().KruiseClient.PolicyV1alpha1().
 				PodUnavailableBudgets(pub.Namespace).Get(context.TODO(), pub.Name, metav1.GetOptions{})
 			if err != nil {
-				klog.Errorf("Get PodUnavailableBudget(%s/%s) failed form etcd: %s", pub.Namespace, pub.Name, err.Error())
+				klog.ErrorS(err, "Failed to get podUnavailableBudget form etcd", "pub", klog.KObj(pub))
 				return err
 			}
 		} else {
 			// compare local cache and informer cache, then get the newer one
 			item, _, err := util.GlobalCache.Get(pub)
 			if err != nil {
-				klog.Errorf("Get cache failed for PodUnavailableBudget(%s/%s): %s", pub.Namespace, pub.Name, err.Error())
+				klog.ErrorS(err, "Failed to get cache for podUnavailableBudget", "pub", klog.KObj(pub))
 			}
 			if localCached, ok := item.(*policyv1alpha1.PodUnavailableBudget); ok {
 				pubClone = localCached.DeepCopy()
@@ -155,18 +155,18 @@ func PodUnavailableBudgetValidatePod(pod *corev1.Pod, operation policyv1alpha1.P
 
 		// If this is a dry-run, we don't need to go any further than that.
 		if dryRun {
-			klog.V(3).Infof("pod(%s) operation for pub(%s/%s) is a dry run", pod.Name, pubClone.Namespace, pubClone.Name)
+			klog.V(3).InfoS("Pod operation for pub was a dry run", "pod", klog.KObj(pod), "pub", klog.KObj(pubClone))
 			return nil
 		}
-		klog.V(3).Infof("pub(%s/%s) update status(disruptedPods:%d, unavailablePods:%d, expectedCount:%d, desiredAvailable:%d, currentAvailable:%d, unavailableAllowed:%d)",
-			pubClone.Namespace, pubClone.Name, len(pubClone.Status.DisruptedPods), len(pubClone.Status.UnavailablePods),
-			pubClone.Status.TotalReplicas, pubClone.Status.DesiredAvailable, pubClone.Status.CurrentAvailable, pubClone.Status.UnavailableAllowed)
+		klog.V(3).InfoS("Updated pub status", "pub", klog.KObj(pubClone), "disruptedPods", len(pubClone.Status.DisruptedPods),
+			"unavailablePods", len(pubClone.Status.UnavailablePods), "expectedCount", pubClone.Status.TotalReplicas, "desiredAvailable",
+			pubClone.Status.DesiredAvailable, "currentAvailable", pubClone.Status.CurrentAvailable, "unavailableAllowed", pubClone.Status.UnavailableAllowed)
 		start = time.Now()
 		err = kclient.Status().Update(context.TODO(), pubClone)
 		costOfUpdate += time.Since(start)
 		if err == nil {
 			if err = util.GlobalCache.Add(pubClone); err != nil {
-				klog.Errorf("Add cache failed for PodUnavailableBudget(%s/%s): %s", pub.Namespace, pub.Name, err.Error())
+				klog.ErrorS(err, "Failed to add cache for podUnavailableBudget", "pub", klog.KObj(pub))
 			}
 			return nil
 		}
@@ -175,18 +175,20 @@ func PodUnavailableBudgetValidatePod(pod *corev1.Pod, operation policyv1alpha1.P
 		refresh = true
 		return err
 	})
-	klog.V(3).Infof("Webhook cost of pub(%s/%s): conflict times %v, cost of Get %v, cost of Update %v",
-		pub.Namespace, pub.Name, conflictTimes, costOfGet, costOfUpdate)
+	klog.V(3).InfoS("Webhook cost of pub", "pub", klog.KObj(pub),
+		"conflictTimes", conflictTimes, "costOfGet", costOfGet, "costOfUpdate", costOfUpdate)
 	if err != nil && err != wait.ErrWaitTimeout {
-		klog.V(3).Infof("pod(%s/%s) operation(%s) for pub(%s/%s) failed: %s", pod.Namespace, pod.Name, operation, pub.Namespace, pub.Name, err.Error())
+		klog.V(3).InfoS("Pod operation for pub failed", "pod", klog.KObj(pod), "operation", operation,
+			"pub", klog.KObj(pub), "error", err)
 		return false, err.Error(), nil
 	} else if err == wait.ErrWaitTimeout {
 		err = errors.NewTimeoutError(fmt.Sprintf("couldn't update PodUnavailableBudget %s due to conflicts", pub.Name), 10)
-		klog.Errorf("pod(%s/%s) operation(%s) failed: %s", pod.Namespace, pod.Name, operation, err.Error())
+		klog.ErrorS(err, "Pod operation failed", "pod", klog.KObj(pod), "operation", operation)
 		return false, err.Error(), nil
 	}
 
-	klog.V(3).Infof("admit pod(%s/%s) operation(%s) for pub(%s/%s)", pod.Namespace, pod.Name, operation, pub.Namespace, pub.Name)
+	klog.V(3).InfoS("Admitted pod operation for pub", "pod", klog.KObj(pod),
+		"operation", operation, "pub", klog.KObj(pub))
 	return true, "", nil
 }
 
@@ -209,10 +211,10 @@ func checkAndDecrement(podName string, pub *policyv1alpha1.PodUnavailableBudget,
 
 	if operation == policyv1alpha1.PubUpdateOperation {
 		pub.Status.UnavailablePods[podName] = metav1.Time{Time: time.Now()}
-		klog.V(3).Infof("pod(%s) is recorded in pub(%s/%s) UnavailablePods", podName, pub.Namespace, pub.Name)
+		klog.V(3).InfoS("Pod was recorded in pub unavailablePods", "podName", podName, "pub", klog.KObj(pub))
 	} else {
 		pub.Status.DisruptedPods[podName] = metav1.Time{Time: time.Now()}
-		klog.V(3).Infof("pod(%s) is recorded in pub(%s/%s) DisruptedPods", podName, pub.Namespace, pub.Name)
+		klog.V(3).InfoS("Pod was recorded in pub disruptedPods", "podName", podName, "pub", klog.KObj(pub))
 	}
 	return nil
 }

pkg/control/sidecarcontrol/history_control.go

@@ -192,12 +192,12 @@ func (r *realControl) GetHistorySidecarSet(sidecarSet *appsv1alpha1.SidecarSet,
 	clone := sidecarSet.DeepCopy()
 	cloneBytes, err := runtime.Encode(patchCodec, clone)
 	if err != nil {
-		klog.Errorf("Failed to encode sidecarSet(%v), error: %v", sidecarSet.Name, err)
+		klog.ErrorS(err, "Failed to encode sidecarSet", "sidecarSet", klog.KRef("", sidecarSet.Name))
 		return nil, err
 	}
 	patched, err := strategicpatch.StrategicMergePatch(cloneBytes, revision.Data.Raw, clone)
 	if err != nil {
-		klog.Errorf("Failed to merge sidecarSet(%v) and controllerRevision(%v), error: %v", sidecarSet.Name, revision.Name, err)
+		klog.ErrorS(err, "Failed to merge sidecarSet and controllerRevision", "sidecarSet", klog.KRef("", sidecarSet.Name), "controllerRevision", klog.KRef("", revision.Name))
 		return nil, err
 	}
 	// restore history from patch
@@ -224,7 +224,7 @@ func (r *realControl) getControllerRevision(set *appsv1alpha1.SidecarSet, revisi
 			Name:      *revisionInfo.RevisionName,
 		}
 		if err := r.Client.Get(context.TODO(), revisionKey, revision); err != nil {
-			klog.Errorf("Failed to get ControllerRevision %v for SidecarSet(%v), err: %v", *revisionInfo.RevisionName, set.Name, err)
+			klog.ErrorS(err, "Failed to get controllerRevision for sidecarSet", "controllerRevision", klog.KRef("", *revisionInfo.RevisionName), "sidecarSet", klog.KRef("", set.Name))
 			return nil, err
 		}
 		return revision, nil
@@ -237,7 +237,8 @@ func (r *realControl) getControllerRevision(set *appsv1alpha1.SidecarSet, revisi
 		}
 		revisionList := &apps.ControllerRevisionList{}
 		if err := r.Client.List(context.TODO(), revisionList, listOpts...); err != nil {
-			klog.Errorf("Failed to get ControllerRevision for SidecarSet(%v), custom version: %v, err: %v", set.Name, *revisionInfo.CustomVersion, err)
+			klog.ErrorS(err, "Failed to get controllerRevision for sidecarSet", "controllerRevision", klog.KRef("", *revisionInfo.CustomVersion),
+				"sidecarSet", klog.KRef("", set.Name), "customVersion", *revisionInfo.CustomVersion)
 			return nil, err
 		}
 
@@ -253,7 +254,7 @@ func (r *realControl) getControllerRevision(set *appsv1alpha1.SidecarSet, revisi
 		return revisions[len(revisions)-1], nil
 	}
 
-	klog.Error("Failed to get controllerRevision due to both empty RevisionName and CustomVersion")
+	klog.ErrorS(fmt.Errorf("Failed to get controllerRevision due to both empty revisionName and customVersion"), "Failed to get controllerRevision")
 	return nil, nil
 }
 

pkg/control/sidecarcontrol/sidecarset_control.go

@@ -56,7 +56,8 @@ func (c *commonControl) UpgradeSidecarContainer(sidecarContainer *appsv1alpha1.S
 	}
 	container := util.GetContainer(nameToUpgrade, pod)
 	container.Image = sidecarContainer.Image
-	klog.V(3).Infof("upgrade pod(%s/%s) container(%s) Image from(%s) -> to(%s)", pod.Namespace, pod.Name, nameToUpgrade, oldImage, container.Image)
+	klog.V(3).InfoS("Upgraded pod container image", "pod", klog.KObj(pod), "containerName", nameToUpgrade,
+		"oldImage", oldImage, "newImage", container.Image)
 	return container
 }
 
@@ -84,8 +85,8 @@ func (c *commonControl) IsPodReady(pod *v1.Pod) bool {
 	for _, container := range pod.Spec.Containers {
 		// If container is empty container, then its image must be empty image
 		if emptyImage := emptyContainers[container.Name]; emptyImage != "" && container.Image != emptyImage {
-			klog.V(5).Infof("pod(%s/%s) sidecar empty container(%s) Image(%s) isn't Empty Image(%s)",
-				pod.Namespace, pod.Name, container.Name, container.Image, emptyImage)
+			klog.V(5).InfoS("Pod sidecar empty container image wasn't empty image", "pod", klog.KObj(pod),
+				"containerName", container.Name, "containerImage", container.Image, "emptyImage", emptyImage)
 			return false
 		}
 	}
@@ -103,8 +104,8 @@ func (c *commonControl) UpdatePodAnnotationsInUpgrade(changedContainers []string
 	sidecarUpdateStates := make(map[string]*pub.InPlaceUpdateState)
 	if stateStr := pod.Annotations[SidecarsetInplaceUpdateStateKey]; len(stateStr) > 0 {
 		if err := json.Unmarshal([]byte(stateStr), &sidecarUpdateStates); err != nil {
-			klog.Errorf("parse pod(%s/%s) annotations[%s] value(%s) failed: %s",
-				pod.Namespace, pod.Name, SidecarsetInplaceUpdateStateKey, stateStr, err.Error())
+			klog.ErrorS(err, "Failed to parse pod annotations value", "pod", klog.KObj(pod),
+				"annotation", SidecarsetInplaceUpdateStateKey, "value", stateStr)
 		}
 	}
 	inPlaceUpdateState, ok := sidecarUpdateStates[sidecarSet.Name]
@@ -222,8 +223,8 @@ func IsSidecarContainerUpdateCompleted(pod *v1.Pod, sidecarSets, containers sets
 		return true
 		// this won't happen in practice, unless someone manually edit pod annotations
 	} else if err := json.Unmarshal([]byte(stateStr), &sidecarUpdateStates); err != nil {
-		klog.V(5).Infof("parse pod(%s/%s) annotations[%s] value(%s) failed: %s",
-			pod.Namespace, pod.Name, SidecarsetInplaceUpdateStateKey, stateStr, err.Error())
+		klog.V(5).InfoS("Failed to parse pod annotations value", "pod", klog.KObj(pod),
+			"annotation", SidecarsetInplaceUpdateStateKey, "value", stateStr, "error", err)
 		return false
 	}
 
@@ -254,7 +255,8 @@ func IsSidecarContainerUpdateCompleted(pod *v1.Pod, sidecarSets, containers sets
 			// we assume that users should not update workload template with new image
 			// which actually has the same imageID as the old image
 			if oldStatus.ImageID == cs.ImageID && containerImages[cs.Name] != cs.Image {
-				klog.V(5).Infof("pod(%s/%s) container %s status imageID not changed, then inconsistent", pod.Namespace, pod.Name, cs.Name)
+				klog.V(5).InfoS("Pod container status imageID not changed, then inconsistent",
+					"pod", klog.KObj(pod), "containerStatusName", cs.Name)
 				return false
 			}
 		}

pkg/control/sidecarcontrol/util.go

@@ -182,8 +182,8 @@ func GetPodSidecarSetUpgradeSpecInAnnotations(sidecarSetName, annotationKey stri
 
 	sidecarSetHash := make(map[string]SidecarSetUpgradeSpec)
 	if err := json.Unmarshal([]byte(annotations[hashKey]), &sidecarSetHash); err != nil {
-		klog.Errorf("parse pod(%s/%s) annotations[%s] value(%s) failed: %s", pod.GetNamespace(), pod.GetName(), hashKey,
-			annotations[hashKey], err.Error())
+		klog.ErrorS(err, "Failed to parse pod annotations value", "pod", klog.KObj(pod),
+			"annotations", hashKey, "value", annotations[hashKey])
 		// to be compatible with older sidecarSet hash struct, map[string]string
 		olderSidecarSetHash := make(map[string]string)
 		if err = json.Unmarshal([]byte(annotations[hashKey]), &olderSidecarSetHash); err != nil {
@@ -214,7 +214,7 @@ func UpdatePodSidecarSetHash(pod *corev1.Pod, sidecarSet *appsv1alpha1.SidecarSe
 	hashKey := SidecarSetHashAnnotation
 	sidecarSetHash := make(map[string]SidecarSetUpgradeSpec)
 	if err := json.Unmarshal([]byte(pod.Annotations[hashKey]), &sidecarSetHash); err != nil {
-		klog.Errorf("unmarshal pod(%s/%s) annotations[%s] failed: %s", pod.Namespace, pod.Name, hashKey, err.Error())
+		klog.ErrorS(err, "Failed to unmarshal pod annotations", "pod", klog.KObj(pod), "annotations", hashKey)
 
 		// to be compatible with older sidecarSet hash struct, map[string]string
 		olderSidecarSetHash := make(map[string]string)
@@ -346,7 +346,7 @@ func GetInjectedVolumeMountsAndEnvs(control SidecarControl, sidecarContainer *ap
 				// get envVar in container
 				eVar := util.GetContainerEnvVar(&appContainer, envName)
 				if eVar == nil {
-					klog.Warningf("pod(%s/%s) container(%s) get env(%s) is nil", pod.Namespace, pod.Name, appContainer.Name, envName)
+					klog.InfoS("Pod container got nil env", "pod", klog.KObj(pod), "containerName", appContainer.Name, "env", envName)
 					continue
 				}
 				injectedEnvs = append(injectedEnvs, *eVar)
@@ -381,7 +381,8 @@ func GetSidecarTransferEnvs(sidecarContainer *appsv1alpha1.SidecarContainer, pod
 		if tEnv.SourceContainerNameFrom != nil && tEnv.SourceContainerNameFrom.FieldRef != nil {
 			containerName, err := ExtractContainerNameFromFieldPath(tEnv.SourceContainerNameFrom.FieldRef, pod)
 			if err != nil {
-				klog.Errorf("get containerName from pod(%s/%s) annotations or labels[%s] failed: %s", pod.Namespace, pod.Name, tEnv.SourceContainerNameFrom.FieldRef, err.Error())
+				klog.ErrorS(err, "Failed to get containerName from pod annotations or labels",
+					"pod", klog.KObj(pod), "annotationsOrLabels", tEnv.SourceContainerNameFrom.FieldRef)
 				continue
 			}
 			sourceContainerName = containerName
@@ -391,7 +392,7 @@ func GetSidecarTransferEnvs(sidecarContainer *appsv1alpha1.SidecarContainer, pod
 			env, ok := envsInPod[key]
 			if !ok {
 				// if sourceContainerName is empty or not found in pod.spec.containers
-				klog.Warningf("there is no env %v in container %v", tEnv.EnvName, tEnv.SourceContainerName)
+				klog.InfoS("There was no env in container", "envName", tEnv.EnvName, "containerName", tEnv.SourceContainerName)
 				continue
 			}
 			injectedEnvs = append(injectedEnvs, env)