filter: more granular logging

Add more information, only at high verbosity levels,
about the filter behavior; report the precise
rejection reason, both in logs and in the user-visible record.
The user-visible record (e.g. in pod events) reported
in framework.Status must be concise, so we limit to a single
extra short word, being it the resource name.

Signed-off-by: Francesco Romani <[email protected]>

Author: ffromani

pkg/noderesourcetopology/filter.go

@@ -52,24 +52,24 @@ func singleNUMAContainerLevelHandler(lh logr.Logger, pod *v1.Pod, info *filterIn
 		clh := lh.WithValues(logging.KeyContainer, initContainer.Name, logging.KeyContainerKind, cntKind)
 		clh.V(6).Info("desired resources", stringify.ResourceListToLoggable(initContainer.Resources.Requests)...)
 
-		_, match := resourcesAvailableInAnyNUMANodes(clh, info, initContainer.Resources.Requests)
+		_, match, reason := resourcesAvailableInAnyNUMANodes(clh, info, initContainer.Resources.Requests)
 		if !match {
 			msg := "cannot align " + cntKind + " container"
 			// we can't align init container, so definitely we can't align a pod
-			clh.V(2).Info(msg)
-			return framework.NewStatus(framework.Unschedulable, msg)
+			clh.V(2).Info(msg, "reason", reason)
+			return framework.NewStatus(framework.Unschedulable, msg+": "+reason)
 		}
 	}
 
 	for _, container := range pod.Spec.Containers {
 		clh := lh.WithValues(logging.KeyContainer, container.Name, logging.KeyContainerKind, logging.KindContainerApp)
 		clh.V(6).Info("container requests", stringify.ResourceListToLoggable(container.Resources.Requests)...)
 
-		numaID, match := resourcesAvailableInAnyNUMANodes(clh, info, container.Resources.Requests)
+		numaID, match, reason := resourcesAvailableInAnyNUMANodes(clh, info, container.Resources.Requests)
 		if !match {
 			// we can't align container, so definitely we can't align a pod
-			clh.V(2).Info("cannot align container")
-			return framework.NewStatus(framework.Unschedulable, "cannot align container")
+			clh.V(2).Info("cannot align container", "reason", reason)
+			return framework.NewStatus(framework.Unschedulable, "cannot align container: "+reason)
 		}
 
 		// subtract the resources requested by the container from the given NUMA.
@@ -86,7 +86,7 @@ func singleNUMAContainerLevelHandler(lh logr.Logger, pod *v1.Pod, info *filterIn
 
 // resourcesAvailableInAnyNUMANodes checks for sufficient resource and return the NUMAID that would be selected by Kubelet.
 // this function requires NUMANodeList with properly populated NUMANode, NUMAID should be in range 0-63
-func resourcesAvailableInAnyNUMANodes(lh logr.Logger, info *filterInfo, resources v1.ResourceList) (int, bool) {
+func resourcesAvailableInAnyNUMANodes(lh logr.Logger, info *filterInfo, resources v1.ResourceList) (int, bool, string) {
 	numaID := highestNUMAID
 	bitmask := bm.NewEmptyBitMask()
 	// set all bits, each bit is a NUMA node, if resources couldn't be aligned
@@ -96,50 +96,54 @@ func resourcesAvailableInAnyNUMANodes(lh logr.Logger, info *filterInfo, resource
 	nodeResources := util.ResourceList(info.node.Allocatable)
 
 	for resource, quantity := range resources {
+		clh := lh.WithValues("resource", resource)
 		if quantity.IsZero() {
 			// why bother? everything's fine from the perspective of this resource
-			lh.V(4).Info("ignoring zero-qty resource request", "resource", resource)
+			clh.V(4).Info("ignoring zero-qty resource request")
 			continue
 		}
 
 		if _, ok := nodeResources[resource]; !ok {
 			// some resources may not expose NUMA affinity (device plugins, extended resources), but all resources
 			// must be reported at node level; thus, if they are not present at node level, we can safely assume
 			// we don't have the resource at all.
-			lh.V(2).Info("early verdict: cannot meet request", "resource", resource, "suitable", "false")
-			return numaID, false
+			clh.V(2).Info("early verdict: cannot meet request")
+			return -1, false, string(resource)
 		}
 
 		// for each requested resource, calculate which NUMA slots are good fits, and then AND with the aggregated bitmask, IOW unset appropriate bit if we can't align resources, or set it
 		// obvious, bits which are not in the NUMA id's range would be unset
 		hasNUMAAffinity := false
 		resourceBitmask := bm.NewEmptyBitMask()
 		for _, numaNode := range info.numaNodes {
+			nlh := clh.WithValues("numaCell", numaNode.NUMAID)
 			numaQuantity, ok := numaNode.Resources[resource]
 			if !ok {
+				nlh.V(6).Info("missing")
 				continue
 			}
 
 			hasNUMAAffinity = true
 			if !isResourceSetSuitable(info.qos, resource, quantity, numaQuantity) {
+				nlh.V(6).Info("discarded", "quantity", quantity.String(), "numaQuantity", numaQuantity.String())
 				continue
 			}
 
 			resourceBitmask.Add(numaNode.NUMAID)
-			lh.V(6).Info("feasible", "numaCell", numaNode.NUMAID, "resource", resource)
+			nlh.V(6).Info("feasible")
 		}
 
 		// non-native resources or ephemeral-storage may not expose NUMA affinity,
 		// but since they are available at node level, this is fine
 		if !hasNUMAAffinity && isHostLevelResource(resource) {
-			lh.V(6).Info("resource available at host level (no NUMA affinity)", "resource", resource)
+			clh.V(6).Info("resource available at host level (no NUMA affinity)")
 			continue
 		}
 
 		bitmask.And(resourceBitmask)
 		if bitmask.IsEmpty() {
-			lh.V(2).Info("early verdict", "resource", resource, "suitable", "false")
-			return numaID, false
+			lh.V(2).Info("early verdict: cannot find affinity")
+			return numaID, false, string(resource)
 		}
 	}
 	// according to TopologyManager, the preferred NUMA affinity, is the narrowest one.
@@ -151,7 +155,7 @@ func resourcesAvailableInAnyNUMANodes(lh logr.Logger, info *filterInfo, resource
 	// at least one NUMA node is available
 	ret := !bitmask.IsEmpty()
 	lh.V(2).Info("final verdict", "suitable", ret, "numaCell", numaID)
-	return numaID, ret
+	return numaID, ret, "generic"
 }
 
 func singleNUMAPodLevelHandler(lh logr.Logger, pod *v1.Pod, info *filterInfo) *framework.Status {
@@ -160,10 +164,10 @@ func singleNUMAPodLevelHandler(lh logr.Logger, pod *v1.Pod, info *filterInfo) *f
 	resources := util.GetPodEffectiveRequest(pod)
 	lh.V(6).Info("pod desired resources", stringify.ResourceListToLoggable(resources)...)
 
-	numaID, match := resourcesAvailableInAnyNUMANodes(lh, info, resources)
+	numaID, match, reason := resourcesAvailableInAnyNUMANodes(lh, info, resources)
 	if !match {
-		lh.V(2).Info("cannot align pod", "name", pod.Name)
-		return framework.NewStatus(framework.Unschedulable, "cannot align pod")
+		lh.V(2).Info("cannot align pod", "name", pod.Name, "reason", reason)
+		return framework.NewStatus(framework.Unschedulable, "cannot align pod: "+reason)
 	}
 	lh.V(4).Info("all container placed", "numaCell", numaID)
 	return nil

pkg/noderesourcetopology/filter_test.go

@@ -19,9 +19,10 @@ package noderesourcetopology
 import (
 	"context"
 	"fmt"
-	"reflect"
+	"strings"
 	"testing"
 
+	"github.com/google/go-cmp/cmp"
 	topologyv1alpha2 "github.com/k8stopologyawareschedwg/noderesourcetopology-api/pkg/apis/topology/v1alpha2"
 
 	v1 "k8s.io/api/core/v1"
@@ -696,7 +697,7 @@ func TestNodeResourceTopology(t *testing.T) {
 			}
 			gotStatus := tm.Filter(context.Background(), framework.NewCycleState(), tt.pod, nodeInfo)
 
-			if !reflect.DeepEqual(gotStatus, tt.wantStatus) {
+			if !quasiEqualStatus(gotStatus, tt.wantStatus) {
 				t.Errorf("status does not match: %v, want: %v", gotStatus, tt.wantStatus)
 			}
 		})
@@ -913,7 +914,7 @@ func TestNodeResourceTopologyMultiContainerPodScope(t *testing.T) {
 			}
 			gotStatus := tm.Filter(context.Background(), framework.NewCycleState(), tt.pod, nodeInfo)
 
-			if !reflect.DeepEqual(gotStatus, tt.wantStatus) {
+			if !quasiEqualStatus(gotStatus, tt.wantStatus) {
 				t.Errorf("status does not match: %v, want: %v", gotStatus, tt.wantStatus)
 			}
 		})
@@ -1172,7 +1173,7 @@ func TestNodeResourceTopologyMultiContainerContainerScope(t *testing.T) {
 			nodeInfo.SetNode(nodes[0])
 			gotStatus := tm.Filter(context.Background(), framework.NewCycleState(), tt.pod, nodeInfo)
 
-			if !reflect.DeepEqual(gotStatus, tt.wantStatus) {
+			if !quasiEqualStatus(gotStatus, tt.wantStatus) {
 				t.Errorf("status does not match: %v, want: %v", gotStatus, tt.wantStatus)
 			}
 		})
@@ -1286,3 +1287,18 @@ func parseState(error string) *framework.Status {
 
 	return framework.NewStatus(framework.Unschedulable, error)
 }
+
+func quasiEqualStatus(s, x *framework.Status) bool {
+	if s == nil || x == nil {
+		return s.IsSuccess() && x.IsSuccess()
+	}
+	if s.Code() != x.Code() {
+		return false
+	}
+	sMsg := s.Message()
+	xMsg := x.Message()
+	if !strings.HasPrefix(sMsg, xMsg) {
+		return false
+	}
+	return cmp.Equal(s.Plugin(), x.Plugin())
+}