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/cpumanager/cpu_manager.go b/pkg/kubelet/cm/cpumanager/cpu_manager.go
index 9e72a7cc97aa3..8b59ba6712190 100644
--- a/pkg/kubelet/cm/cpumanager/cpu_manager.go
+++ b/pkg/kubelet/cm/cpumanager/cpu_manager.go
@@ -239,6 +239,8 @@ func (m *manager) Start(activePods ActivePodsFunc, sourcesReady config.SourcesRe
 		return err
 	}
 
+	klog.V(4).InfoS("CPU manager started", "policy", m.policy.Name())
+
 	m.allocatableCPUs = m.policy.GetAllocatableCPUs(m.state)
 
 	if m.policy.Name() == string(PolicyNone) {
@@ -465,7 +467,7 @@ func (m *manager) reconcileState() (success []reconciledContainer, failure []rec
 			cset := m.state.GetCPUSetOrDefault(string(pod.UID), container.Name)
 			if cset.IsEmpty() {
 				// NOTE: This should not happen outside of tests.
-				klog.V(2).InfoS("ReconcileState: skipping container; assigned cpuset is empty", "pod", klog.KObj(pod), "containerName", container.Name)
+				klog.V(2).InfoS("ReconcileState: skipping container; empty cpuset assigned", "pod", klog.KObj(pod), "containerName", container.Name)
 				failure = append(failure, reconciledContainer{pod.Name, container.Name, containerID})
 				continue
 			}
diff --git a/pkg/kubelet/cm/cpumanager/policy_static.go b/pkg/kubelet/cm/cpumanager/policy_static.go
index 26d1fc6d91bef..16a44c5d5829f 100644
--- a/pkg/kubelet/cm/cpumanager/policy_static.go
+++ b/pkg/kubelet/cm/cpumanager/policy_static.go
@@ -388,6 +388,7 @@ func (p *staticPolicy) Allocate(s state.State, pod *v1.Pod, container *v1.Contai
 	p.updateCPUsToReuse(pod, container, cpuset)
 	p.updateMetricsOnAllocate(cpuset)
 
+	klog.V(4).InfoS("Allocated exclusive CPUs", "pod", klog.KObj(pod), "containerName", container.Name, "cpuset", cpuset)
 	return nil
 }
 
@@ -455,7 +456,9 @@ func (p *staticPolicy) allocateCPUs(s state.State, numCPUs int, numaAffinity bit
 }
 
 func (p *staticPolicy) guaranteedCPUs(pod *v1.Pod, container *v1.Container) int {
-	if v1qos.GetPodQOS(pod) != v1.PodQOSGuaranteed {
+	qos := v1qos.GetPodQOS(pod)
+	if qos != v1.PodQOSGuaranteed {
+		klog.V(5).InfoS("Exclusive CPU allocation skipped, pod QoS is not guaranteed", "pod", klog.KObj(pod), "containerName", container.Name, "qos", qos)
 		return 0
 	}
 	cpuQuantity := container.Resources.Requests[v1.ResourceCPU]
@@ -468,7 +471,9 @@ func (p *staticPolicy) guaranteedCPUs(pod *v1.Pod, container *v1.Container) int
 			cpuQuantity = cs.AllocatedResources[v1.ResourceCPU]
 		}
 	}
-	if cpuQuantity.Value()*1000 != cpuQuantity.MilliValue() {
+	cpuValue := cpuQuantity.Value()
+	if cpuValue*1000 != cpuQuantity.MilliValue() {
+		klog.V(5).InfoS("Exclusive CPU allocation skipped, pod requested non-integral CPUs", "pod", klog.KObj(pod), "containerName", container.Name, "cpu", cpuValue)
 		return 0
 	}
 	// Safe downcast to do for all systems with < 2.1 billion CPUs.
diff --git a/pkg/kubelet/cm/cpumanager/state/state_checkpoint.go b/pkg/kubelet/cm/cpumanager/state/state_checkpoint.go
index f6acc7c42ce69..bda90ba1f4ca6 100644
--- a/pkg/kubelet/cm/cpumanager/state/state_checkpoint.go
+++ b/pkg/kubelet/cm/cpumanager/state/state_checkpoint.go
@@ -201,7 +201,7 @@ func (sc *stateCheckpoint) SetCPUSet(podUID string, containerName string, cset c
 	sc.cache.SetCPUSet(podUID, containerName, cset)
 	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)
 	}
 }
 
@@ -212,7 +212,7 @@ func (sc *stateCheckpoint) SetDefaultCPUSet(cset cpuset.CPUSet) {
 	sc.cache.SetDefaultCPUSet(cset)
 	err := sc.storeState()
 	if err != nil {
-		klog.InfoS("Store state to checkpoint error", "err", err)
+		klog.ErrorS(err, "Failed to store state to checkpoint")
 	}
 }
 
@@ -223,7 +223,7 @@ func (sc *stateCheckpoint) SetCPUAssignments(a ContainerCPUAssignments) {
 	sc.cache.SetCPUAssignments(a)
 	err := sc.storeState()
 	if err != nil {
-		klog.InfoS("Store state to checkpoint error", "err", err)
+		klog.ErrorS(err, "Failed to store state to checkpoint")
 	}
 }
 
@@ -234,7 +234,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)
 	}
 }
 
@@ -245,6 +245,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")
 	}
 }


Test patch: