Merge pull request #100196 from ehashman/remains-of-logs

Migrate remaining logs to structured logging

pkg/kubelet/cm/devicemanager/topology_hints.go

@@ -23,7 +23,6 @@ import (
 	pluginapi "k8s.io/kubelet/pkg/apis/deviceplugin/v1beta1"
 	"k8s.io/kubernetes/pkg/kubelet/cm/topologymanager"
 	"k8s.io/kubernetes/pkg/kubelet/cm/topologymanager/bitmask"
-	"k8s.io/kubernetes/pkg/kubelet/util/format"
 )
 
 // GetTopologyHints implements the TopologyManager HintProvider Interface which
@@ -43,7 +42,7 @@ func (m *ManagerImpl) GetTopologyHints(pod *v1.Pod, container *v1.Container) map
 		if m.isDevicePluginResource(resource) {
 			// Only consider devices that actually container topology information.
 			if aligned := m.deviceHasTopologyAlignment(resource); !aligned {
-				klog.Infof("[devicemanager] Resource '%v' does not have a topology preference", resource)
+				klog.InfoS("Resource does not have a topology preference", "resource", resource)
 				deviceHints[resource] = nil
 				continue
 			}
@@ -54,11 +53,11 @@ func (m *ManagerImpl) GetTopologyHints(pod *v1.Pod, container *v1.Container) map
 			allocated := m.podDevices.containerDevices(string(pod.UID), container.Name, resource)
 			if allocated.Len() > 0 {
 				if allocated.Len() != requested {
-					klog.Errorf("[devicemanager] Resource '%v' already allocated to (pod %v, container %v) with different number than request: requested: %d, allocated: %d", resource, format.Pod(pod), container.Name, requested, allocated.Len())
+					klog.ErrorS(nil, "Resource already allocated to pod with different number than request", "resource", resource, "pod", klog.KObj(pod), "containerName", container.Name, "request", requested, "allocated", allocated.Len())
 					deviceHints[resource] = []topologymanager.TopologyHint{}
 					continue
 				}
-				klog.Infof("[devicemanager] Regenerating TopologyHints for resource '%v' already allocated to (pod %v, container %v)", resource, format.Pod(pod), container.Name)
+				klog.InfoS("Regenerating TopologyHints for resource already allocated to pod", "resource", resource, "pod", klog.KObj(pod), "containerName", container.Name)
 				deviceHints[resource] = m.generateDeviceTopologyHints(resource, allocated, sets.String{}, requested)
 				continue
 			}
@@ -67,7 +66,7 @@ func (m *ManagerImpl) GetTopologyHints(pod *v1.Pod, container *v1.Container) map
 			available := m.getAvailableDevices(resource)
 			reusable := m.devicesToReuse[string(pod.UID)][resource]
 			if available.Union(reusable).Len() < requested {
-				klog.Errorf("[devicemanager] Unable to generate topology hints: requested number of devices unavailable for '%s': requested: %d, available: %d", resource, requested, available.Union(reusable).Len())
+				klog.ErrorS(nil, "Unable to generate topology hints: requested number of devices unavailable", "resource", resource, "request", requested, "available", available.Union(reusable).Len())
 				deviceHints[resource] = []topologymanager.TopologyHint{}
 				continue
 			}
@@ -93,7 +92,7 @@ func (m *ManagerImpl) GetPodTopologyHints(pod *v1.Pod) map[string][]topologymana
 	for resource, requested := range accumulatedResourceRequests {
 		// Only consider devices that actually contain topology information.
 		if aligned := m.deviceHasTopologyAlignment(resource); !aligned {
-			klog.Infof("[devicemanager] Resource '%v' does not have a topology preference", resource)
+			klog.InfoS("Resource does not have a topology preference", "resource", resource)
 			deviceHints[resource] = nil
 			continue
 		}
@@ -104,11 +103,11 @@ func (m *ManagerImpl) GetPodTopologyHints(pod *v1.Pod) map[string][]topologymana
 		allocated := m.podDevices.podDevices(string(pod.UID), resource)
 		if allocated.Len() > 0 {
 			if allocated.Len() != requested {
-				klog.Errorf("[devicemanager] Resource '%v' already allocated to (pod %v) with different number than request: requested: %d, allocated: %d", resource, format.Pod(pod), requested, allocated.Len())
+				klog.ErrorS(nil, "Resource already allocated to pod with different number than request", "resource", resource, "pod", klog.KObj(pod), "request", requested, "allocated", allocated.Len())
 				deviceHints[resource] = []topologymanager.TopologyHint{}
 				continue
 			}
-			klog.Infof("[devicemanager] Regenerating TopologyHints for resource '%v' already allocated to (pod %v)", resource, format.Pod(pod))
+			klog.InfoS("Regenerating TopologyHints for resource already allocated to pod", "resource", resource, "pod", klog.KObj(pod))
 			deviceHints[resource] = m.generateDeviceTopologyHints(resource, allocated, sets.String{}, requested)
 			continue
 		}
@@ -116,7 +115,7 @@ func (m *ManagerImpl) GetPodTopologyHints(pod *v1.Pod) map[string][]topologymana
 		// Get the list of available devices, for which TopologyHints should be generated.
 		available := m.getAvailableDevices(resource)
 		if available.Len() < requested {
-			klog.Errorf("[devicemanager] Unable to generate topology hints: requested number of devices unavailable for '%s': requested: %d, available: %d", resource, requested, available.Len())
+			klog.ErrorS(nil, "Unable to generate topology hints: requested number of devices unavailable", "resource", resource, "request", requested, "available", available.Len())
 			deviceHints[resource] = []topologymanager.TopologyHint{}
 			continue
 		}

pkg/kubelet/images/image_gc_manager.go

@@ -183,7 +183,7 @@ func (im *realImageGCManager) Start() {
 		}
 		_, err := im.detectImages(ts)
 		if err != nil {
-			klog.Warningf("[imageGCManager] Failed to monitor images: %v", err)
+			klog.InfoS("Failed to monitor images", "err", err)
 		} else {
 			im.initialized = true
 		}
@@ -193,7 +193,7 @@ func (im *realImageGCManager) Start() {
 	go wait.Until(func() {
 		images, err := im.runtime.ListImages()
 		if err != nil {
-			klog.Warningf("[imageGCManager] Failed to update image list: %v", err)
+			klog.InfoS("Failed to update image list", "err", err)
 		} else {
 			im.imageCache.set(images)
 		}
@@ -227,7 +227,7 @@ func (im *realImageGCManager) detectImages(detectTime time.Time) (sets.String, e
 	// Make a set of images in use by containers.
 	for _, pod := range pods {
 		for _, container := range pod.Containers {
-			klog.V(5).Infof("Pod %s/%s, container %s uses image %s(%s)", pod.Namespace, pod.Name, container.Name, container.Image, container.ImageID)
+			klog.V(5).InfoS("Container uses image", "pod", klog.KRef(pod.Namespace, pod.Name), "containerName", container.Name, "containerImage", container.Image, "imageID", container.ImageID)
 			imagesInUse.Insert(container.ImageID)
 		}
 	}
@@ -238,12 +238,12 @@ func (im *realImageGCManager) detectImages(detectTime time.Time) (sets.String, e
 	im.imageRecordsLock.Lock()
 	defer im.imageRecordsLock.Unlock()
 	for _, image := range images {
-		klog.V(5).Infof("Adding image ID %s to currentImages", image.ID)
+		klog.V(5).InfoS("Adding image ID to currentImages", "imageID", image.ID)
 		currentImages.Insert(image.ID)
 
 		// New image, set it as detected now.
 		if _, ok := im.imageRecords[image.ID]; !ok {
-			klog.V(5).Infof("Image ID %s is new", image.ID)
+			klog.V(5).InfoS("Image ID is new", "imageID", image.ID)
 			im.imageRecords[image.ID] = &imageRecord{
 				firstDetected: detectTime,
 			}
@@ -251,18 +251,18 @@ func (im *realImageGCManager) detectImages(detectTime time.Time) (sets.String, e
 
 		// Set last used time to now if the image is being used.
 		if isImageUsed(image.ID, imagesInUse) {
-			klog.V(5).Infof("Setting Image ID %s lastUsed to %v", image.ID, now)
+			klog.V(5).InfoS("Setting Image ID lastUsed", "imageID", image.ID, "lastUsed", now)
 			im.imageRecords[image.ID].lastUsed = now
 		}
 
-		klog.V(5).Infof("Image ID %s has size %d", image.ID, image.Size)
+		klog.V(5).InfoS("Image ID has size", "imageID", image.ID, "size", image.Size)
 		im.imageRecords[image.ID].size = image.Size
 	}
 
 	// Remove old images from our records.
 	for image := range im.imageRecords {
 		if !currentImages.Has(image) {
-			klog.V(5).Infof("Image ID %s is no longer present; removing from imageRecords", image)
+			klog.V(5).InfoS("Image ID is no longer present; removing from imageRecords", "imageID", image)
 			delete(im.imageRecords, image)
 		}
 	}
@@ -286,7 +286,7 @@ func (im *realImageGCManager) GarbageCollect() error {
 	}
 
 	if available > capacity {
-		klog.Warningf("available %d is larger than capacity %d", available, capacity)
+		klog.InfoS("Availability is larger than capacity", "available", available, "capacity", capacity)
 		available = capacity
 	}
 
@@ -301,7 +301,7 @@ func (im *realImageGCManager) GarbageCollect() error {
 	usagePercent := 100 - int(available*100/capacity)
 	if usagePercent >= im.policy.HighThresholdPercent {
 		amountToFree := capacity*int64(100-im.policy.LowThresholdPercent)/100 - available
-		klog.Infof("[imageGCManager]: Disk usage on image filesystem is at %d%% which is over the high threshold (%d%%). Trying to free %d bytes down to the low threshold (%d%%).", usagePercent, im.policy.HighThresholdPercent, amountToFree, im.policy.LowThresholdPercent)
+		klog.InfoS("Disk usage on image filesystem is over the high threshold, trying to free bytes down to the low threshold", "usage", usagePercent, "highThreshold", im.policy.HighThresholdPercent, "amountToFree", amountToFree, "lowThreshold", im.policy.LowThresholdPercent)
 		freed, err := im.freeSpace(amountToFree, time.Now())
 		if err != nil {
 			return err
@@ -318,7 +318,7 @@ func (im *realImageGCManager) GarbageCollect() error {
 }
 
 func (im *realImageGCManager) DeleteUnusedImages() error {
-	klog.Infof("attempting to delete unused images")
+	klog.InfoS("Attempting to delete unused images")
 	_, err := im.freeSpace(math.MaxInt64, time.Now())
 	return err
 }
@@ -342,7 +342,7 @@ func (im *realImageGCManager) freeSpace(bytesToFree int64, freeTime time.Time) (
 	images := make([]evictionInfo, 0, len(im.imageRecords))
 	for image, record := range im.imageRecords {
 		if isImageUsed(image, imagesInUse) {
-			klog.V(5).Infof("Image ID %s is being used", image)
+			klog.V(5).InfoS("Image ID is being used", "imageID", image)
 			continue
 		}
 		images = append(images, evictionInfo{
@@ -356,10 +356,10 @@ func (im *realImageGCManager) freeSpace(bytesToFree int64, freeTime time.Time) (
 	var deletionErrors []error
 	spaceFreed := int64(0)
 	for _, image := range images {
-		klog.V(5).Infof("Evaluating image ID %s for possible garbage collection", image.id)
+		klog.V(5).InfoS("Evaluating image ID for possible garbage collection", "imageID", image.id)
 		// Images that are currently in used were given a newer lastUsed.
 		if image.lastUsed.Equal(freeTime) || image.lastUsed.After(freeTime) {
-			klog.V(5).Infof("Image ID %s has lastUsed=%v which is >= freeTime=%v, not eligible for garbage collection", image.id, image.lastUsed, freeTime)
+			klog.V(5).InfoS("Image ID was used too recently, not eligible for garbage collection", "imageID", image.id, "lastUsed", image.lastUsed, "freeTime", freeTime)
 			continue
 		}
 
@@ -367,12 +367,12 @@ func (im *realImageGCManager) freeSpace(bytesToFree int64, freeTime time.Time) (
 		// In such a case, the image may have just been pulled down, and will be used by a container right away.
 
 		if freeTime.Sub(image.firstDetected) < im.policy.MinAge {
-			klog.V(5).Infof("Image ID %s has age %v which is less than the policy's minAge of %v, not eligible for garbage collection", image.id, freeTime.Sub(image.firstDetected), im.policy.MinAge)
+			klog.V(5).InfoS("Image ID's age is less than the policy's minAge, not eligible for garbage collection", "imageID", image.id, "age", freeTime.Sub(image.firstDetected), "minAge", im.policy.MinAge)
 			continue
 		}
 
 		// Remove image. Continue despite errors.
-		klog.Infof("[imageGCManager]: Removing image %q to free %d bytes", image.id, image.size)
+		klog.InfoS("Removing image to free bytes", "imageID", image.id, "size", image.size)
 		err := im.runtime.RemoveImage(container.ImageSpec{Image: image.id})
 		if err != nil {
 			deletionErrors = append(deletionErrors, err)

pkg/kubelet/kuberuntime/kuberuntime_gc.go

@@ -138,12 +138,12 @@ func (cgc *containerGC) removeOldestN(containers []containerGCInfo, toRemove int
 			}
 			message := "Container is in unknown state, try killing it before removal"
 			if err := cgc.manager.killContainer(nil, id, containers[i].name, message, reasonUnknown, nil); err != nil {
-				klog.Errorf("Failed to stop container %q: %v", containers[i].id, err)
+				klog.ErrorS(err, "Failed to stop container", "containerID", containers[i].id)
 				continue
 			}
 		}
 		if err := cgc.manager.removeContainer(containers[i].id); err != nil {
-			klog.Errorf("Failed to remove container %q: %v", containers[i].id, err)
+			klog.ErrorS(err, "Failed to remove container", "containerID", containers[i].id)
 		}
 	}
 
@@ -168,16 +168,16 @@ func (cgc *containerGC) removeOldestNSandboxes(sandboxes []sandboxGCInfo, toRemo
 
 // removeSandbox removes the sandbox by sandboxID.
 func (cgc *containerGC) removeSandbox(sandboxID string) {
-	klog.V(4).Infof("Removing sandbox %q", sandboxID)
+	klog.V(4).InfoS("Removing sandbox", "sandboxID", sandboxID)
 	// In normal cases, kubelet should've already called StopPodSandbox before
 	// GC kicks in. To guard against the rare cases where this is not true, try
 	// stopping the sandbox before removing it.
 	if err := cgc.client.StopPodSandbox(sandboxID); err != nil {
-		klog.Errorf("Failed to stop sandbox %q before removing: %v", sandboxID, err)
+		klog.ErrorS(err, "Failed to stop sandbox before removing", "sandboxID", sandboxID)
 		return
 	}
 	if err := cgc.client.RemovePodSandbox(sandboxID); err != nil {
-		klog.Errorf("Failed to remove sandbox %q: %v", sandboxID, err)
+		klog.ErrorS(err, "Failed to remove sandbox", "sandboxID", sandboxID)
 	}
 }
 
@@ -342,7 +342,7 @@ func (cgc *containerGC) evictPodLogsDirectories(allSourcesReady bool) error {
 			}
 			err := osInterface.RemoveAll(filepath.Join(podLogsRootDirectory, name))
 			if err != nil {
-				klog.Errorf("Failed to remove pod logs directory %q: %v", name, err)
+				klog.ErrorS(err, "Failed to remove pod logs directory", "path", name)
 			}
 		}
 	}
@@ -357,7 +357,7 @@ func (cgc *containerGC) evictPodLogsDirectories(allSourcesReady bool) error {
 				if err != nil {
 					// TODO: we should handle container not found (i.e. container was deleted) case differently
 					// once https://github.com/kubernetes/kubernetes/issues/63336 is resolved
-					klog.Infof("Error getting ContainerStatus for containerID %q: %v", containerID, err)
+					klog.InfoS("Error getting ContainerStatus for containerID", "containerID", containerID, "err", err)
 				} else if status.State != runtimeapi.ContainerState_CONTAINER_EXITED {
 					// Here is how container log rotation works (see containerLogManager#rotateLatestLog):
 					//
@@ -370,17 +370,17 @@ func (cgc *containerGC) evictPodLogsDirectories(allSourcesReady bool) error {
 					// See https://github.com/kubernetes/kubernetes/issues/52172
 					//
 					// We only remove unhealthy symlink for dead containers
-					klog.V(5).Infof("Container %q is still running, not removing symlink %q.", containerID, logSymlink)
+					klog.V(5).InfoS("Container is still running, not removing symlink", "containerID", containerID, "path", logSymlink)
 					continue
 				}
 			} else {
-				klog.V(4).Infof("unable to obtain container Id: %v", err)
+				klog.V(4).InfoS("Unable to obtain container ID", "err", err)
 			}
 			err := osInterface.Remove(logSymlink)
 			if err != nil {
-				klog.Errorf("Failed to remove container log dead symlink %q: %v", logSymlink, err)
+				klog.ErrorS(err, "Failed to remove container log dead symlink", "path", logSymlink)
 			} else {
-				klog.V(4).Infof("removed symlink %s", logSymlink)
+				klog.V(4).InfoS("Removed symlink", "path", logSymlink)
 			}
 		}
 	}