Repository: kubernetes/kubernetes (language: go)

Issue:
[umbrella issue]: poor visibility/observability of the kubelet (cpu,memory,device,topology) managers
### What happened?

The kubelet {cpu, memory, device, topology} manager, collectively known as resource managers, give little to none feedback to their consumers. Once the kubelet is configured with the relevant settings (e.g. cpuManagerPolicy=static or topologyManagerPolicy=restricted, say) and once the workload requests exclusive resources provided by the managers, the implicit contract is that if the pod is admitted, then all the resources are provisioned according to the spec. Similarly, if the kubelet cannot allocate the resources as requested (and as configured) the pod will fail admission with a TopologyAffinityError or similar generic error.

The problem is twofold:
- there's no **explicit** feedback about resource allocation. For example, the system explicitly acknowledges a pod got its image pulled succesfully with a event, yet it does not for resource allocation, even though both are arguably prerequisites to have the pod running, and both could be theoretically inferred from the fact the pod started. The point of this example is to highlight the lack of explicit feedback about allocation.
- on error, there's no way to learn what gone wrong except in most generic term (pod failed with TopologyAffinityError). The only option is to look at kubelet logs, but the kubelet verbosity has to be >= 4 anyway.

### What did you expect to happen?

On success, the system should somehow explcitely acknowledge the resource classes being allocated, for example "CPUs" and that NUMA alignment took place.

On admission failure, the system should give indication of what caused admission failure, like unable to allocate enough memory on the selected NUMA zone, or missing device affine to the selected NUMA zone. But any more information that is presented now is welcome.

In both cases we probably don't want or need to expose the details of the concrete resources, at least not initially.

### How can we reproduce it (as minimally and precisely as possible)?

1. succesfully run a pod requiring a device, or exclusive access to CPUs, or NUMA alignment. Observe lack of feedback.
2. try to run a pod requiring a device or exclusive access to CPUs, or NUMA alignment. Make it fail admission (e.g. ask for more CPUs than existing on the machine's NUMA zone). Observe the error is a generic "TopologyAffinityError" with lack of indication about the resource failed to be allocated

### Anything else we need to know?

The observability, or lack thereof, of the resource management subsystem was also a [recurring theme in the related Production Readiness Reviews](https://kubernetes.slack.com/archives/CPNHUMN74/p1696357853594279), culminating in a [blocking comment](https://kubernetes.slack.com/archives/CPNHUMN74/p1696518756979339?thread_ts=1696357853.594279&cid=CPNHUMN74) for memory manager GA graduation.

### Kubernetes version

<details>
any since 1.18 (cpumanager introduced, the first of resource managers)
</details>


### Cloud provider

<details>
not relevant
</details>


### OS version

<details>
not relevant
</details>


### Install tools

<details>
not relevant
</details>


### Container runtime (CRI) and version (if applicable)

<details>
any
</details>


### Related plugins (CNI, CSI, ...) and versions (if applicable)

<details>
not relevant
</details>



Discussion / hints:
/assign

I have a PoC in the workings to emit kubernetes events from the Kubelet to provide explicit feedback addressing the cases outlined in the issue description
/sig node
/triage accepted
/priority important-longterm
/remove-kind bug
/kind feature
@ffromani I noticed that we have metrics for CPU,memory,device,topology manager and your PR also adds events for them. do we have a list of other observability improvements ? 
> @ffromani I noticed that we have metrics for CPU,memory,device,topology manager and your PR also adds events for them. do we have a list of other observability improvements ?

Hi! not yet but I'll update this issue. The known gaps are about metrics, events or lack thereof (clearly emerged on PRRs) and log improvements (my own pet peeve).
Regarding log improvements, I believe the best way forward is to improve the resource managers (cpumanager, devicemanager, memorymanager, topologymanager) to make use of contextual logging (see: 
https://kubernetes.io/blog/2020/09/04/kubernetes-1-19-introducing-structured-logs/
https://github.com/kubernetes/enhancements/blob/master/keps/sig-instrumentation/1602-structured-logging/README.md
https://github.com/kubernetes/kubernetes/issues?q=is%3Aissue+is%3Aopen+contextual+logging)
using contextual logging solves most of the problems in logs, maing easier to follow the code flow and having a common experience across the project.
As followup work we can review the logs to check if something else can be improved, like reviewing the verbosiness, adding key=value pairs, improving the messages or anything else, but should be a followup after the move to contextual logging.

Fix patch:
diff --git a/pkg/kubelet/cm/memorymanager/memory_manager.go b/pkg/kubelet/cm/memorymanager/memory_manager.go
index d09a21ad1a20b..448539fc0cd69 100644
--- a/pkg/kubelet/cm/memorymanager/memory_manager.go
+++ b/pkg/kubelet/cm/memorymanager/memory_manager.go
@@ -205,6 +205,7 @@ func (m *manager) Start(activePods ActivePodsFunc, sourcesReady config.SourcesRe
 
 	m.allocatableMemory = m.policy.GetAllocatableMemory(m.state)
 
+	klog.V(4).InfoS("memorymanager started", "policy", m.policy.Name())
 	return nil
 }
 
@@ -248,7 +249,7 @@ func (m *manager) GetMemoryNUMANodes(pod *v1.Pod, container *v1.Container) sets.
 	}
 
 	if numaNodes.Len() == 0 {
-		klog.V(5).InfoS("No allocation is available", "pod", klog.KObj(pod), "containerName", container.Name)
+		klog.V(5).InfoS("NUMA nodes not available for allocation", "pod", klog.KObj(pod), "containerName", container.Name)
 		return nil
 	}
 
@@ -266,7 +267,7 @@ func (m *manager) Allocate(pod *v1.Pod, container *v1.Container) error {
 
 	// Call down into the policy to assign this container memory if required.
 	if err := m.policy.Allocate(m.state, pod, container); err != nil {
-		klog.ErrorS(err, "Allocate error")
+		klog.ErrorS(err, "Allocate error", "pod", klog.KObj(pod), "containerName", container.Name)
 		return err
 	}
 	return nil
@@ -280,7 +281,7 @@ func (m *manager) RemoveContainer(containerID string) error {
 	// if error appears it means container entry already does not exist under the container map
 	podUID, containerName, err := m.containerMap.GetContainerRef(containerID)
 	if err != nil {
-		klog.InfoS("Failed to get container from container map", "containerID", containerID, "err", err)
+		klog.ErrorS(err, "Failed to get container from container map", "containerID", containerID)
 		return nil
 	}
 
@@ -344,7 +345,7 @@ func (m *manager) removeStaleState() {
 	for podUID := range assignments {
 		for containerName := range assignments[podUID] {
 			if _, ok := activeContainers[podUID][containerName]; !ok {
-				klog.InfoS("RemoveStaleState removing state", "podUID", podUID, "containerName", containerName)
+				klog.V(2).InfoS("RemoveStaleState removing state", "podUID", podUID, "containerName", containerName)
 				m.policyRemoveContainerByRef(podUID, containerName)
 			}
 		}
@@ -352,7 +353,7 @@ func (m *manager) removeStaleState() {
 
 	m.containerMap.Visit(func(podUID, containerName, containerID string) {
 		if _, ok := activeContainers[podUID][containerName]; !ok {
-			klog.InfoS("RemoveStaleState removing state", "podUID", podUID, "containerName", containerName)
+			klog.V(2).InfoS("RemoveStaleState removing state", "podUID", podUID, "containerName", containerName)
 			m.policyRemoveContainerByRef(podUID, containerName)
 		}
 	})
diff --git a/pkg/kubelet/cm/memorymanager/policy_static.go b/pkg/kubelet/cm/memorymanager/policy_static.go
index 115e74afa274f..6c6e2d3b881c3 100644
--- a/pkg/kubelet/cm/memorymanager/policy_static.go
+++ b/pkg/kubelet/cm/memorymanager/policy_static.go
@@ -96,7 +96,9 @@ func (p *staticPolicy) Start(s state.State) error {
 // Allocate call is idempotent
 func (p *staticPolicy) Allocate(s state.State, pod *v1.Pod, container *v1.Container) (rerr error) {
 	// allocate the memory only for guaranteed pods
-	if v1qos.GetPodQOS(pod) != v1.PodQOSGuaranteed {
+	qos := v1qos.GetPodQOS(pod)
+	if qos != v1.PodQOSGuaranteed {
+		klog.V(5).InfoS("Exclusive memory allocation skipped, pod QoS is not guaranteed", "pod", klog.KObj(pod), "containerName", container.Name, "qos", qos)
 		return nil
 	}
 
@@ -196,6 +198,7 @@ func (p *staticPolicy) Allocate(s state.State, pod *v1.Pod, container *v1.Contai
 	// TODO: we should refactor our state structs to reflect the amount of the re-used memory
 	p.updateInitContainersMemoryBlocks(s, pod, container, containerBlocks)
 
+	klog.V(4).InfoS("Allocated exclusive memory", "pod", klog.KObj(pod), "containerName", container.Name)
 	return nil
 }
 
@@ -304,24 +307,24 @@ func regenerateHints(pod *v1.Pod, ctn *v1.Container, ctnBlocks []state.Block, re
 	}
 
 	if len(ctnBlocks) != len(reqRsrc) {
-		klog.ErrorS(nil, "The number of requested resources by the container differs from the number of memory blocks", "containerName", ctn.Name)
+		klog.InfoS("The number of requested resources by the container differs from the number of memory blocks", "pod", klog.KObj(pod), "containerName", ctn.Name)
 		return nil
 	}
 
 	for _, b := range ctnBlocks {
 		if _, ok := reqRsrc[b.Type]; !ok {
-			klog.ErrorS(nil, "Container requested resources do not have resource of this type", "containerName", ctn.Name, "type", b.Type)
+			klog.InfoS("Container requested resources but none available of this type", "pod", klog.KObj(pod), "containerName", ctn.Name, "type", b.Type)
 			return nil
 		}
 
 		if b.Size != reqRsrc[b.Type] {
-			klog.ErrorS(nil, "Memory already allocated with different numbers than requested", "podUID", pod.UID, "type", b.Type, "containerName", ctn.Name, "requestedResource", reqRsrc[b.Type], "allocatedSize", b.Size)
+			klog.InfoS("Memory already allocated with different numbers than requested", "pod", klog.KObj(pod), "containerName", ctn.Name, "type", b.Type, "requestedResource", reqRsrc[b.Type], "allocatedSize", b.Size)
 			return nil
 		}
 
 		containerNUMAAffinity, err := bitmask.NewBitMask(b.NUMAAffinity...)
 		if err != nil {
-			klog.ErrorS(err, "Failed to generate NUMA bitmask")
+			klog.ErrorS(err, "Failed to generate NUMA bitmask", "pod", klog.KObj(pod), "containerName", ctn.Name, "type", b.Type)
 			return nil
 		}
 
@@ -654,36 +657,36 @@ func (p *staticPolicy) validateState(s state.State) error {
 
 func areMachineStatesEqual(ms1, ms2 state.NUMANodeMap) bool {
 	if len(ms1) != len(ms2) {
-		klog.ErrorS(nil, "Node states are different", "lengthNode1", len(ms1), "lengthNode2", len(ms2))
+		klog.InfoS("Node states were different", "lengthNode1", len(ms1), "lengthNode2", len(ms2))
 		return false
 	}
 
 	for nodeID, nodeState1 := range ms1 {
 		nodeState2, ok := ms2[nodeID]
 		if !ok {
-			klog.ErrorS(nil, "Node state does not have node ID", "nodeID", nodeID)
+			klog.InfoS("Node state didn't have node ID", "nodeID", nodeID)
 			return false
 		}
 
 		if nodeState1.NumberOfAssignments != nodeState2.NumberOfAssignments {
-			klog.ErrorS(nil, "Node states number of assignments are different", "assignment1", nodeState1.NumberOfAssignments, "assignment2", nodeState2.NumberOfAssignments)
+			klog.InfoS("Node state had a different number of memory assignments.", "assignment1", nodeState1.NumberOfAssignments, "assignment2", nodeState2.NumberOfAssignments)
 			return false
 		}
 
 		if !areGroupsEqual(nodeState1.Cells, nodeState2.Cells) {
-			klog.ErrorS(nil, "Node states groups are different", "stateNode1", nodeState1.Cells, "stateNode2", nodeState2.Cells)
+			klog.InfoS("Node states had different groups", "stateNode1", nodeState1.Cells, "stateNode2", nodeState2.Cells)
 			return false
 		}
 
 		if len(nodeState1.MemoryMap) != len(nodeState2.MemoryMap) {
-			klog.ErrorS(nil, "Node states memory map have different lengths", "lengthNode1", len(nodeState1.MemoryMap), "lengthNode2", len(nodeState2.MemoryMap))
+			klog.InfoS("Node state had memory maps of different lengths", "lengthNode1", len(nodeState1.MemoryMap), "lengthNode2", len(nodeState2.MemoryMap))
 			return false
 		}
 
 		for resourceName, memoryState1 := range nodeState1.MemoryMap {
 			memoryState2, ok := nodeState2.MemoryMap[resourceName]
 			if !ok {
-				klog.ErrorS(nil, "Memory state does not have resource", "resource", resourceName)
+				klog.InfoS("Memory state didn't have resource", "resource", resourceName)
 				return false
 			}
 
@@ -701,11 +704,11 @@ func areMachineStatesEqual(ms1, ms2 state.NUMANodeMap) bool {
 			}
 
 			if tmpState1.Free != tmpState2.Free {
-				klog.InfoS("Memory states for the NUMA node and resource are different", "node", nodeID, "resource", resourceName, "field", "free", "free1", tmpState1.Free, "free2", tmpState2.Free, "memoryState1", *memoryState1, "memoryState2", *memoryState2)
+				klog.InfoS("NUMA node and resource had different memory states", "node", nodeID, "resource", resourceName, "field", "free", "free1", tmpState1.Free, "free2", tmpState2.Free, "memoryState1", *memoryState1, "memoryState2", *memoryState2)
 				return false
 			}
 			if tmpState1.Reserved != tmpState2.Reserved {
-				klog.InfoS("Memory states for the NUMA node and resource are different", "node", nodeID, "resource", resourceName, "field", "reserved", "reserved1", tmpState1.Reserved, "reserved2", tmpState2.Reserved, "memoryState1", *memoryState1, "memoryState2", *memoryState2)
+				klog.InfoS("NUMA node and resource had different memory states", "node", nodeID, "resource", resourceName, "field", "reserved", "reserved1", tmpState1.Reserved, "reserved2", tmpState2.Reserved, "memoryState1", *memoryState1, "memoryState2", *memoryState2)
 				return false
 			}
 		}
@@ -715,17 +718,17 @@ func areMachineStatesEqual(ms1, ms2 state.NUMANodeMap) bool {
 
 func areMemoryStatesEqual(memoryState1, memoryState2 *state.MemoryTable, nodeID int, resourceName v1.ResourceName) bool {
 	if memoryState1.TotalMemSize != memoryState2.TotalMemSize {
-		klog.ErrorS(nil, "Memory states for the NUMA node and resource are different", "node", nodeID, "resource", resourceName, "field", "TotalMemSize", "TotalMemSize1", memoryState1.TotalMemSize, "TotalMemSize2", memoryState2.TotalMemSize, "memoryState1", *memoryState1, "memoryState2", *memoryState2)
+		klog.InfoS("Memory states for the NUMA node and resource are different", "node", nodeID, "resource", resourceName, "field", "TotalMemSize", "TotalMemSize1", memoryState1.TotalMemSize, "TotalMemSize2", memoryState2.TotalMemSize, "memoryState1", *memoryState1, "memoryState2", *memoryState2)
 		return false
 	}
 
 	if memoryState1.SystemReserved != memoryState2.SystemReserved {
-		klog.ErrorS(nil, "Memory states for the NUMA node and resource are different", "node", nodeID, "resource", resourceName, "field", "SystemReserved", "SystemReserved1", memoryState1.SystemReserved, "SystemReserved2", memoryState2.SystemReserved, "memoryState1", *memoryState1, "memoryState2", *memoryState2)
+		klog.InfoS("Memory states for the NUMA node and resource are different", "node", nodeID, "resource", resourceName, "field", "SystemReserved", "SystemReserved1", memoryState1.SystemReserved, "SystemReserved2", memoryState2.SystemReserved, "memoryState1", *memoryState1, "memoryState2", *memoryState2)
 		return false
 	}
 
 	if memoryState1.Allocatable != memoryState2.Allocatable {
-		klog.ErrorS(nil, "Memory states for the NUMA node and resource are different", "node", nodeID, "resource", resourceName, "field", "Allocatable", "Allocatable1", memoryState1.Allocatable, "Allocatable2", memoryState2.Allocatable, "memoryState1", *memoryState1, "memoryState2", *memoryState2)
+		klog.InfoS("Memory states for the NUMA node and resource are different", "node", nodeID, "resource", resourceName, "field", "Allocatable", "Allocatable1", memoryState1.Allocatable, "Allocatable2", memoryState2.Allocatable, "memoryState1", *memoryState1, "memoryState2", *memoryState2)
 		return false
 	}
 	return true
diff --git a/pkg/kubelet/cm/memorymanager/state/state_checkpoint.go b/pkg/kubelet/cm/memorymanager/state/state_checkpoint.go
index 05e32b751a671..dce0bda55a348 100644
--- a/pkg/kubelet/cm/memorymanager/state/state_checkpoint.go
+++ b/pkg/kubelet/cm/memorymanager/state/state_checkpoint.go
@@ -131,7 +131,7 @@ func (sc *stateCheckpoint) SetMachineState(memoryMap NUMANodeMap) {
 	sc.cache.SetMachineState(memoryMap)
 	err := sc.storeState()
 	if err != nil {
-		klog.InfoS("Store state to checkpoint error", "err", err)
+		klog.ErrorS(err, "Failed to store state to checkpoint")
 	}
 }
 
@@ -143,7 +143,7 @@ func (sc *stateCheckpoint) SetMemoryBlocks(podUID string, containerName string,
 	sc.cache.SetMemoryBlocks(podUID, containerName, blocks)
 	err := sc.storeState()
 	if err != nil {
-		klog.InfoS("Store state to checkpoint error", "err", err)
+		klog.ErrorS(err, "Failed to store state to checkpoint", "podUID", podUID, "containerName", containerName)
 	}
 }
 
@@ -155,7 +155,7 @@ func (sc *stateCheckpoint) SetMemoryAssignments(assignments ContainerMemoryAssig
 	sc.cache.SetMemoryAssignments(assignments)
 	err := sc.storeState()
 	if err != nil {
-		klog.InfoS("Store state to checkpoint error", "err", err)
+		klog.ErrorS(err, "Failed to store state to checkpoint")
 	}
 }
 
@@ -167,7 +167,7 @@ func (sc *stateCheckpoint) Delete(podUID string, containerName string) {
 	sc.cache.Delete(podUID, containerName)
 	err := sc.storeState()
 	if err != nil {
-		klog.InfoS("Store state to checkpoint error", "err", err)
+		klog.ErrorS(err, "Failed to store state to checkpoint", "podUID", podUID, "containerName", containerName)
 	}
 }
 
@@ -179,6 +179,6 @@ func (sc *stateCheckpoint) ClearState() {
 	sc.cache.ClearState()
 	err := sc.storeState()
 	if err != nil {
-		klog.InfoS("Store state to checkpoint error", "err", err)
+		klog.ErrorS(err, "Failed to store state to checkpoint")
 	}
 }
diff --git a/pkg/kubelet/cm/memorymanager/state/state_mem.go b/pkg/kubelet/cm/memorymanager/state/state_mem.go
index 7e4da7ab67ce3..19861c6e35a53 100644
--- a/pkg/kubelet/cm/memorymanager/state/state_mem.go
+++ b/pkg/kubelet/cm/memorymanager/state/state_mem.go
@@ -94,6 +94,7 @@ func (s *stateMemory) SetMemoryAssignments(assignments ContainerMemoryAssignment
 	defer s.Unlock()
 
 	s.assignments = assignments.Clone()
+	klog.V(5).InfoS("Updated Memory assignments", "assignments", assignments)
 }
 
 // Delete deletes corresponding Blocks from ContainerMemoryAssignments


Test patch: