Merge pull request kubernetes#99970 from krzysiekg/structured_logging_pkg_kubelet_kuberuntime

Migrate pkg/kubelet/kuberuntime to structured logging

Author: k8s-ci-robot

pkg/kubelet/kuberuntime/helpers.go

@@ -81,7 +81,7 @@ func toRuntimeProtocol(protocol v1.Protocol) runtimeapi.Protocol {
 		return runtimeapi.Protocol_SCTP
 	}
 
-	klog.Warningf("Unknown protocol %q: defaulting to TCP", protocol)
+	klog.InfoS("Unknown protocol, defaulting to TCP", "protocol", protocol)
 	return runtimeapi.Protocol_TCP
 }
 

pkg/kubelet/kuberuntime/kuberuntime_container_linux.go

@@ -112,13 +112,13 @@ func GetHugepageLimitsFromResources(resources v1.ResourceRequirements) []*runtim
 
 		pageSize, err := v1helper.HugePageSizeFromResourceName(resourceObj)
 		if err != nil {
-			klog.Warningf("Failed to get hugepage size from resource name: %v", err)
+			klog.InfoS("Failed to get hugepage size from resource", "object", resourceObj, "err", err)
 			continue
 		}
 
 		sizeString, err := v1helper.HugePageUnitSizeFromByteSize(pageSize.Value())
 		if err != nil {
-			klog.Warningf("pageSize is invalid: %v", err)
+			klog.InfoS("Size is invalid", "object", resourceObj, "err", err)
 			continue
 		}
 		requiredHugepageLimits[sizeString] = uint64(amountObj.Value())

pkg/kubelet/kuberuntime/kuberuntime_container_windows.go

@@ -97,7 +97,7 @@ func (m *kubeGenericRuntimeManager) generateWindowsContainerConfig(container *v1
 	if wc.Resources.CpuCount > 0 {
 		if wc.Resources.CpuMaximum > 0 {
 			wc.Resources.CpuMaximum = 0
-			klog.Warningf("Mutually exclusive options: CPUCount priority > CPUMaximum priority on Windows Server Containers. CPUMaximum should be ignored")
+			klog.InfoS("Mutually exclusive options: CPUCount priority > CPUMaximum priority on Windows Server Containers. CPUMaximum should be ignored")
 		}
 	}
 

pkg/kubelet/kuberuntime/kuberuntime_image.go

@@ -44,11 +44,11 @@ func (m *kubeGenericRuntimeManager) PullImage(image kubecontainer.ImageSpec, pul
 
 	creds, withCredentials := keyring.Lookup(repoToPull)
 	if !withCredentials {
-		klog.V(3).Infof("Pulling image %q without credentials", img)
+		klog.V(3).InfoS("Pulling image without credentials", "image", img)
 
 		imageRef, err := m.imageService.PullImage(imgSpec, nil, podSandboxConfig)
 		if err != nil {
-			klog.Errorf("Pull image %q failed: %v", img, err)
+			klog.ErrorS(err, "Failed to pull image", "image", img)
 			return "", err
 		}
 
@@ -83,7 +83,7 @@ func (m *kubeGenericRuntimeManager) PullImage(image kubecontainer.ImageSpec, pul
 func (m *kubeGenericRuntimeManager) GetImageRef(image kubecontainer.ImageSpec) (string, error) {
 	status, err := m.imageService.ImageStatus(toRuntimeAPIImageSpec(image))
 	if err != nil {
-		klog.Errorf("ImageStatus for image %q failed: %v", image, err)
+		klog.ErrorS(err, "Failed to get image status", "image", image.Image)
 		return "", err
 	}
 	if status == nil {
@@ -98,7 +98,7 @@ func (m *kubeGenericRuntimeManager) ListImages() ([]kubecontainer.Image, error)
 
 	allImages, err := m.imageService.ListImages(nil)
 	if err != nil {
-		klog.Errorf("ListImages failed: %v", err)
+		klog.ErrorS(err, "Failed to list images")
 		return nil, err
 	}
 
@@ -119,7 +119,7 @@ func (m *kubeGenericRuntimeManager) ListImages() ([]kubecontainer.Image, error)
 func (m *kubeGenericRuntimeManager) RemoveImage(image kubecontainer.ImageSpec) error {
 	err := m.imageService.RemoveImage(&runtimeapi.ImageSpec{Image: image.Image})
 	if err != nil {
-		klog.Errorf("Remove image %q failed: %v", image.Image, err)
+		klog.ErrorS(err, "Failed to remove image", "image", image.Image)
 		return err
 	}
 
@@ -133,7 +133,7 @@ func (m *kubeGenericRuntimeManager) RemoveImage(image kubecontainer.ImageSpec) e
 func (m *kubeGenericRuntimeManager) ImageStats() (*kubecontainer.ImageStats, error) {
 	allImages, err := m.imageService.ListImages(nil)
 	if err != nil {
-		klog.Errorf("ListImages failed: %v", err)
+		klog.ErrorS(err, "Failed to list images")
 		return nil, err
 	}
 	stats := &kubecontainer.ImageStats{}

pkg/kubelet/kuberuntime/kuberuntime_sandbox.go

@@ -37,35 +37,35 @@ import (
 func (m *kubeGenericRuntimeManager) createPodSandbox(pod *v1.Pod, attempt uint32) (string, string, error) {
 	podSandboxConfig, err := m.generatePodSandboxConfig(pod, attempt)
 	if err != nil {
-		message := fmt.Sprintf("GeneratePodSandboxConfig for pod %q failed: %v", format.Pod(pod), err)
-		klog.Error(message)
+		message := fmt.Sprintf("Failed to generate sandbox config for pod %q: %v", format.Pod(pod), err)
+		klog.ErrorS(err, "Failed to generate sandbox config for pod", "pod", klog.KObj(pod))
 		return "", message, err
 	}
 
 	// Create pod logs directory
 	err = m.osInterface.MkdirAll(podSandboxConfig.LogDirectory, 0755)
 	if err != nil {
-		message := fmt.Sprintf("Create pod log directory for pod %q failed: %v", format.Pod(pod), err)
-		klog.Errorf(message)
+		message := fmt.Sprintf("Failed to create log directory for pod %q: %v", format.Pod(pod), err)
+		klog.ErrorS(err, "Failed to create log directory for pod", "pod", klog.KObj(pod))
 		return "", message, err
 	}
 
 	runtimeHandler := ""
 	if m.runtimeClassManager != nil {
 		runtimeHandler, err = m.runtimeClassManager.LookupRuntimeHandler(pod.Spec.RuntimeClassName)
 		if err != nil {
-			message := fmt.Sprintf("CreatePodSandbox for pod %q failed: %v", format.Pod(pod), err)
+			message := fmt.Sprintf("Failed to create sandbox for pod %q: %v", format.Pod(pod), err)
 			return "", message, err
 		}
 		if runtimeHandler != "" {
-			klog.V(2).Infof("Running pod %s with RuntimeHandler %q", format.Pod(pod), runtimeHandler)
+			klog.V(2).InfoS("Running pod with runtime handler", "pod", klog.KObj(pod), "runtimeHandler", runtimeHandler)
 		}
 	}
 
 	podSandBoxID, err := m.runtimeService.RunPodSandbox(podSandboxConfig, runtimeHandler)
 	if err != nil {
-		message := fmt.Sprintf("CreatePodSandbox for pod %q failed: %v", format.Pod(pod), err)
-		klog.Error(message)
+		message := fmt.Sprintf("Failed to create sandbox for pod %q: %v", format.Pod(pod), err)
+		klog.ErrorS(err, "Failed to create sandbox for pod", "pod", klog.KObj(pod))
 		return "", message, err
 	}
 
@@ -220,7 +220,7 @@ func (m *kubeGenericRuntimeManager) getKubeletSandboxes(all bool) ([]*runtimeapi
 
 	resp, err := m.runtimeService.ListPodSandbox(filter)
 	if err != nil {
-		klog.Errorf("ListPodSandbox failed: %v", err)
+		klog.ErrorS(err, "Failed to list pod sandboxes")
 		return nil, err
 	}
 
@@ -231,7 +231,7 @@ func (m *kubeGenericRuntimeManager) getKubeletSandboxes(all bool) ([]*runtimeapi
 func (m *kubeGenericRuntimeManager) determinePodSandboxIPs(podNamespace, podName string, podSandbox *runtimeapi.PodSandboxStatus) []string {
 	podIPs := make([]string, 0)
 	if podSandbox.Network == nil {
-		klog.Warningf("Pod Sandbox status doesn't have network information, cannot report IPs")
+		klog.InfoS("Pod Sandbox status doesn't have network information, cannot report IPs", "pod", klog.KRef(podNamespace, podName))
 		return podIPs
 	}
 
@@ -241,7 +241,7 @@ func (m *kubeGenericRuntimeManager) determinePodSandboxIPs(podNamespace, podName
 	// pick primary IP
 	if len(podSandbox.Network.Ip) != 0 {
 		if net.ParseIP(podSandbox.Network.Ip) == nil {
-			klog.Warningf("Pod Sandbox reported an unparseable IP (Primary) %v", podSandbox.Network.Ip)
+			klog.InfoS("Pod Sandbox reported an unparseable primary IP", "pod", klog.KRef(podNamespace, podName), "IP", podSandbox.Network.Ip)
 			return nil
 		}
 		podIPs = append(podIPs, podSandbox.Network.Ip)
@@ -250,7 +250,7 @@ func (m *kubeGenericRuntimeManager) determinePodSandboxIPs(podNamespace, podName
 	// pick additional ips, if cri reported them
 	for _, podIP := range podSandbox.Network.AdditionalIps {
 		if nil == net.ParseIP(podIP.Ip) {
-			klog.Warningf("Pod Sandbox reported an unparseable IP (additional) %v", podIP.Ip)
+			klog.InfoS("Pod Sandbox reported an unparseable additional IP", "pod", klog.KRef(podNamespace, podName), "IP", podIP.Ip)
 			return nil
 		}
 		podIPs = append(podIPs, podIP.Ip)
@@ -272,7 +272,7 @@ func (m *kubeGenericRuntimeManager) getSandboxIDByPodUID(podUID kubetypes.UID, s
 	}
 	sandboxes, err := m.runtimeService.ListPodSandbox(filter)
 	if err != nil {
-		klog.Errorf("ListPodSandbox with pod UID %q failed: %v", podUID, err)
+		klog.ErrorS(err, "Failed to list sandboxes for pod", "podUID", podUID)
 		return nil, err
 	}
 

pkg/kubelet/kuberuntime/labels.go

@@ -20,12 +20,11 @@ import (
 	"encoding/json"
 	"strconv"
 
-	"k8s.io/api/core/v1"
+	v1 "k8s.io/api/core/v1"
 	kubetypes "k8s.io/apimachinery/pkg/types"
 	"k8s.io/klog/v2"
 	kubecontainer "k8s.io/kubernetes/pkg/kubelet/container"
 	"k8s.io/kubernetes/pkg/kubelet/types"
-	"k8s.io/kubernetes/pkg/kubelet/util/format"
 )
 
 const (
@@ -129,7 +128,7 @@ func newContainerAnnotations(container *v1.Container, pod *v1.Pod, restartCount
 		// Using json encoding so that the PreStop handler object is readable after writing as a label
 		rawPreStop, err := json.Marshal(container.Lifecycle.PreStop)
 		if err != nil {
-			klog.Errorf("Unable to marshal lifecycle PreStop handler for container %q of pod %q: %v", container.Name, format.Pod(pod), err)
+			klog.ErrorS(err, "Unable to marshal lifecycle PreStop handler for container", "containerName", container.Name, "pod", klog.KObj(pod))
 		} else {
 			annotations[containerPreStopHandlerLabel] = string(rawPreStop)
 		}
@@ -138,7 +137,7 @@ func newContainerAnnotations(container *v1.Container, pod *v1.Pod, restartCount
 	if len(container.Ports) > 0 {
 		rawContainerPorts, err := json.Marshal(container.Ports)
 		if err != nil {
-			klog.Errorf("Unable to marshal container ports for container %q for pod %q: %v", container.Name, format.Pod(pod), err)
+			klog.ErrorS(err, "Unable to marshal container ports for container", "containerName", container.Name, "pod", klog.KObj(pod))
 		} else {
 			annotations[containerPortsLabel] = string(rawContainerPorts)
 		}
@@ -192,28 +191,28 @@ func getContainerInfoFromAnnotations(annotations map[string]string) *annotatedCo
 	}
 
 	if containerInfo.Hash, err = getUint64ValueFromLabel(annotations, containerHashLabel); err != nil {
-		klog.Errorf("Unable to get %q from annotations %q: %v", containerHashLabel, annotations, err)
+		klog.ErrorS(err, "Unable to get label value from annotations", "label", containerHashLabel, "annotations", annotations)
 	}
 	if containerInfo.RestartCount, err = getIntValueFromLabel(annotations, containerRestartCountLabel); err != nil {
-		klog.Errorf("Unable to get %q from annotations %q: %v", containerRestartCountLabel, annotations, err)
+		klog.ErrorS(err, "Unable to get label value from annotations", "label", containerRestartCountLabel, "annotations", annotations)
 	}
 	if containerInfo.PodDeletionGracePeriod, err = getInt64PointerFromLabel(annotations, podDeletionGracePeriodLabel); err != nil {
-		klog.Errorf("Unable to get %q from annotations %q: %v", podDeletionGracePeriodLabel, annotations, err)
+		klog.ErrorS(err, "Unable to get label value from annotations", "label", podDeletionGracePeriodLabel, "annotations", annotations)
 	}
 	if containerInfo.PodTerminationGracePeriod, err = getInt64PointerFromLabel(annotations, podTerminationGracePeriodLabel); err != nil {
-		klog.Errorf("Unable to get %q from annotations %q: %v", podTerminationGracePeriodLabel, annotations, err)
+		klog.ErrorS(err, "Unable to get label value from annotations", "label", podTerminationGracePeriodLabel, "annotations", annotations)
 	}
 
 	preStopHandler := &v1.Handler{}
 	if found, err := getJSONObjectFromLabel(annotations, containerPreStopHandlerLabel, preStopHandler); err != nil {
-		klog.Errorf("Unable to get %q from annotations %q: %v", containerPreStopHandlerLabel, annotations, err)
+		klog.ErrorS(err, "Unable to get label value from annotations", "label", containerPreStopHandlerLabel, "annotations", annotations)
 	} else if found {
 		containerInfo.PreStopHandler = preStopHandler
 	}
 
 	containerPorts := []v1.ContainerPort{}
 	if found, err := getJSONObjectFromLabel(annotations, containerPortsLabel, &containerPorts); err != nil {
-		klog.Errorf("Unable to get %q from annotations %q: %v", containerPortsLabel, annotations, err)
+		klog.ErrorS(err, "Unable to get label value from annotations", "label", containerPortsLabel, "annotations", annotations)
 	} else if found {
 		containerInfo.ContainerPorts = containerPorts
 	}
@@ -226,7 +225,7 @@ func getStringValueFromLabel(labels map[string]string, label string) string {
 		return value
 	}
 	// Do not report error, because there should be many old containers without label now.
-	klog.V(3).Infof("Container doesn't have label %s, it may be an old or invalid container", label)
+	klog.V(3).InfoS("Container doesn't have requested label, it may be an old or invalid container", "label", label)
 	// Return empty string "" for these containers, the caller will get value by other ways.
 	return ""
 }
@@ -241,7 +240,7 @@ func getIntValueFromLabel(labels map[string]string, label string) (int, error) {
 		return intValue, nil
 	}
 	// Do not report error, because there should be many old containers without label now.
-	klog.V(3).Infof("Container doesn't have label %s, it may be an old or invalid container", label)
+	klog.V(3).InfoS("Container doesn't have requested label, it may be an old or invalid container", "label", label)
 	// Just set the value to 0
 	return 0, nil
 }
@@ -256,7 +255,7 @@ func getUint64ValueFromLabel(labels map[string]string, label string) (uint64, er
 		return intValue, nil
 	}
 	// Do not report error, because there should be many old containers without label now.
-	klog.V(3).Infof("Container doesn't have label %s, it may be an old or invalid container", label)
+	klog.V(3).InfoS("Container doesn't have requested label, it may be an old or invalid container", "label", label)
 	// Just set the value to 0
 	return 0, nil
 }

pkg/kubelet/kuberuntime/logs/logs.go

@@ -32,7 +32,7 @@ import (
 	"github.com/fsnotify/fsnotify"
 	"k8s.io/klog/v2"
 
-	"k8s.io/api/core/v1"
+	v1 "k8s.io/api/core/v1"
 	internalapi "k8s.io/cri-api/pkg/apis"
 	runtimeapi "k8s.io/cri-api/pkg/apis/runtime/v1alpha2"
 	"k8s.io/kubernetes/pkg/kubelet/types"
@@ -316,7 +316,7 @@ func ReadLogs(ctx context.Context, path, containerID string, opts *LogOptions, r
 	msg := &logMessage{}
 	for {
 		if stop || (limitedMode && limitedNum == 0) {
-			klog.V(2).Infof("Finish parsing log file %q", path)
+			klog.V(2).InfoS("Finished parsing log file", "path", path)
 			return nil
 		}
 		l, err := r.ReadBytes(eol[0])
@@ -363,7 +363,7 @@ func ReadLogs(ctx context.Context, path, containerID string, opts *LogOptions, r
 					}
 					f.Close()
 					if err := watcher.Remove(f.Name()); err != nil && !os.IsNotExist(err) {
-						klog.Errorf("failed to remove file watch %q: %v", f.Name(), err)
+						klog.ErrorS(err, "Failed to remove file watch", "path", f.Name())
 					}
 					f = newF
 					if err := watcher.Add(f.Name()); err != nil {
@@ -379,7 +379,7 @@ func ReadLogs(ctx context.Context, path, containerID string, opts *LogOptions, r
 			if len(l) == 0 {
 				continue
 			}
-			klog.Warningf("Incomplete line in log file %q: %q", path, l)
+			klog.InfoS("Incomplete line in log file", "path", path, "line", l)
 		}
 		if parse == nil {
 			// Initialize the log parsing function.
@@ -391,16 +391,16 @@ func ReadLogs(ctx context.Context, path, containerID string, opts *LogOptions, r
 		// Parse the log line.
 		msg.reset()
 		if err := parse(l, msg); err != nil {
-			klog.Errorf("Failed with err %v when parsing log for log file %q: %q", err, path, l)
+			klog.ErrorS(err, "Failed when parsing line in log file", "path", path, "line", l)
 			continue
 		}
 		// Write the log line into the stream.
 		if err := writer.write(msg); err != nil {
 			if err == errMaximumWrite {
-				klog.V(2).Infof("Finish parsing log file %q, hit bytes limit %d(bytes)", path, opts.bytes)
+				klog.V(2).InfoS("Finished parsing log file, hit bytes limit", "path", path, "limit", opts.bytes)
 				return nil
 			}
-			klog.Errorf("Failed with err %v when writing log for log file %q: %+v", err, path, msg)
+			klog.ErrorS(err, "Failed when writing line to log file", "path", path, "line", msg)
 			return err
 		}
 		if limitedMode {
@@ -417,7 +417,7 @@ func isContainerRunning(id string, r internalapi.RuntimeService) (bool, error) {
 	}
 	// Only keep following container log when it is running.
 	if s.State != runtimeapi.ContainerState_CONTAINER_RUNNING {
-		klog.V(5).Infof("Container %q is not running (state=%q)", id, s.State)
+		klog.V(5).InfoS("Container is not running", "containerId", id, "state", s.State)
 		// Do not return error because it's normal that the container stops
 		// during waiting.
 		return false, nil
@@ -451,10 +451,10 @@ func waitLogs(ctx context.Context, id string, w *fsnotify.Watcher, runtimeServic
 			case fsnotify.Chmod:
 				return true, true, nil
 			default:
-				klog.Errorf("Unexpected fsnotify event: %v, retrying...", e)
+				klog.ErrorS(nil, "Received unexpected fsnotify event, retrying", "event", e)
 			}
 		case err := <-w.Errors:
-			klog.Errorf("Fsnotify watch error: %v, %d error retries remaining", err, errRetry)
+			klog.ErrorS(err, "Received fsnotify watch error, retrying unless no more retries left", "retries", errRetry)
 			if errRetry == 0 {
 				return false, false, err
 			}

pkg/kubelet/kuberuntime/security_context_windows.go

@@ -43,13 +43,15 @@ func verifyRunAsNonRoot(pod *v1.Pod, container *v1.Container, uid *int64, userna
 		return nil
 	}
 	if effectiveSc.RunAsUser != nil {
-		klog.Warningf("Windows container does not support SecurityContext.RunAsUser, please use SecurityContext.WindowsOptions (pod: %q, container: %s)", format.Pod(pod), container.Name)
+		klog.InfoS("Windows container does not support SecurityContext.RunAsUser, please use SecurityContext.WindowsOptions",
+			"pod", klog.KObj(pod), "containerName", container.Name)
 	}
 	if effectiveSc.SELinuxOptions != nil {
-		klog.Warningf("Windows container does not support SecurityContext.SELinuxOptions, please use SecurityContext.WindowsOptions (pod: %q, container: %s)", format.Pod(pod), container.Name)
+		klog.InfoS("Windows container does not support SecurityContext.SELinuxOptions, please use SecurityContext.WindowsOptions",
+			"pod", klog.KObj(pod), "containerName", container.Name)
 	}
 	if effectiveSc.RunAsGroup != nil {
-		klog.Warningf("Windows container does not support SecurityContext.RunAsGroup (pod: %q, container: %s)", format.Pod(pod), container.Name)
+		klog.InfoS("Windows container does not support SecurityContext.RunAsGroup", "pod", klog.KObj(pod), "containerName", container.Name)
 	}
 	if effectiveSc.WindowsOptions != nil {
 		if effectiveSc.WindowsOptions.RunAsUserName != nil {