test: integration: nrt: dump logs on failure

Some tests want to look into pod events to learn about the
scheduler decision. Add dump of events on failure to help
troubleshooting the flakes.

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

Author: ffromani

test/integration/noderesourcetopology_cache_test.go

@@ -338,8 +338,8 @@ func TestTopologyCachePluginWithoutUpdates(t *testing.T) {
 						string(corev1.ResourceCPU):    "16",
 						string(corev1.ResourceMemory): "24Gi",
 					},
-					expectedNode:  "fake-node-cache-1",
 					schedulerName: discardReservedSchedulerName,
+					expectedNode:  "fake-node-cache-1",
 				},
 				{
 					podName:      "nrt-pod-2000",
@@ -508,7 +508,7 @@ func TestTopologyCachePluginWithoutUpdates(t *testing.T) {
 
 			defer func() {
 				cleanupTest(t, testCtx)
-				klog.Infof("test environment cleaned up")
+				klog.Infof("test environment %q cleaned up", tt.name)
 			}()
 
 			if err := createNodesFromNodeResourceTopologies(cs, testCtx.Ctx, tt.nodeResourceTopologies); err != nil {
@@ -554,8 +554,10 @@ func TestTopologyCachePluginWithoutUpdates(t *testing.T) {
 				if p.isDelete {
 					var err error
 					klog.Infof("Waiting before to delete Pod %q", p.podName)
-					err = podIsScheduled(1*time.Second, 20, cs, ns, p.podName)
+					updatedPod, err := podIsScheduled(1*time.Second, 20, cs, ns, p.podName)
 					if err != nil {
+						// we need more context, but we don't want to clutter the logs
+						t.Logf("%s: pod %s/%s to be scheduled, error: %v\nstatus=%s", tt.name, p.pod.Namespace, p.pod.Name, err, formatObject(updatedPod.Status))
 						t.Errorf("Pod %q to be scheduled, error: %v", p.pod.Name, err)
 					}
 
@@ -579,15 +581,17 @@ func TestTopologyCachePluginWithoutUpdates(t *testing.T) {
 				}
 
 				var action string = "scheduled"
-				var checkPod func(interval time.Duration, times int, cs clientset.Interface, podNamespace, podName string) error = podIsScheduled
+				var checkPod func(interval time.Duration, times int, cs clientset.Interface, podNamespace, podName string) (*corev1.Pod, error) = podIsScheduled
 				if p.expectedNode == "" {
 					action = "kept pending"
 					checkPod = podIsPending
 				}
 
-				err = checkPod(1*time.Second, 20, cs, p.pod.Namespace, p.pod.Name)
+				updatedPod, err := checkPod(1*time.Second, 20, cs, p.pod.Namespace, p.pod.Name)
 				if err != nil {
-					t.Errorf("Pod %q to be %s, error: %v", p.pod.Name, action, err)
+					// we need more context, but we don't want to clutter the logs
+					t.Logf("%s: pod %s/%s to be %s, error: %v\nstatus=%s", tt.name, p.pod.Namespace, p.pod.Name, action, err, formatObject(updatedPod.Status))
+					t.Errorf("Pod %s/%s to be %s, error: %v", p.pod.Namespace, p.pod.Name, action, err)
 				}
 				klog.Infof("Pod %v %s", p.pod.Name, action)
 			}
@@ -604,7 +608,7 @@ func TestTopologyCachePluginWithoutUpdates(t *testing.T) {
 				}
 
 				if !podMatchesExpectedNode(p.pod.Namespace, p.pod.Name, nodeName, p.expectedNode) {
-					t.Errorf("misplaced pod: %q", p.pod.Name)
+					t.Errorf("misplaced pod: %q got %q expected %q", p.pod.Name, nodeName, p.expectedNode)
 				}
 			}
 

test/integration/noderesourcetopology_test.go

@@ -18,14 +18,14 @@ package integration
 
 import (
 	"context"
-	"encoding/json"
 	"fmt"
 	"strings"
 	"testing"
 	"time"
 
 	v1 "k8s.io/api/core/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"k8s.io/apimachinery/pkg/fields"
 	"k8s.io/apimachinery/pkg/util/uuid"
 	"k8s.io/apimachinery/pkg/util/wait"
 	"k8s.io/client-go/dynamic"
@@ -1994,21 +1994,26 @@ func TestTopologyMatchPlugin(t *testing.T) {
 					// if tt.expectedNodes == 0 we don't expect the pod to get scheduled
 				} else {
 					// wait for the pod scheduling to failed.
+					var err error
+					var events []v1.Event
 					if err := wait.Poll(5*time.Second, 20*time.Second, func() (bool, error) {
-						events, err := podFailedScheduling(cs, ns, p.Name)
+						events, err = getPodEvents(cs, ns, p.Name)
 						if err != nil {
 							// This could be a connection error, so we want to retry.
 							klog.ErrorS(err, "Failed check pod scheduling status for pod", "pod", klog.KRef(ns, p.Name))
 							return false, nil
 						}
-						for _, e := range events {
-							if strings.Contains(e.Message, tt.errMsg) {
+						candidateEvents := filterPodFailedSchedulingEvents(events)
+						for _, ce := range candidateEvents {
+							if strings.Contains(ce.Message, tt.errMsg) {
 								return true, nil
 							}
-							klog.Warningf("Pod failed but error message does not contain substring: %q; got %q instead", tt.errMsg, e.Message)
+							klog.Warningf("Pod failed but error message does not contain substring: %q; got %q instead", tt.errMsg, ce.Message)
 						}
 						return false, nil
 					}); err != nil {
+						// we need more context to troubleshoot, but let's not clutter the actual error
+						t.Logf("pod %q scheduling should failed with error: %v got %v events:\n%s", p.Name, tt.errMsg, err, formatEvents(events))
 						t.Errorf("pod %q scheduling should failed, error: %v", p.Name, err)
 					}
 				}
@@ -2146,29 +2151,42 @@ func parseTestUserEntry(entries []nrtTestUserEntry, ns string) []nrtTestEntry {
 	return teList
 }
 
-func podFailedScheduling(c clientset.Interface, podNamespace, podName string) ([]v1.Event, error) {
-	var failedSchedulingEvents []v1.Event
-	opt := metav1.ListOptions{
-		FieldSelector: fmt.Sprintf("involvedObject.name=%s", podName),
-		TypeMeta:      metav1.TypeMeta{Kind: "Pod"},
+func getPodEvents(c clientset.Interface, podNamespace, podName string) ([]v1.Event, error) {
+	opts := metav1.ListOptions{
+		FieldSelector: fields.SelectorFromSet(map[string]string{
+			"involvedObject.name":      podName,
+			"involvedObject.namespace": podNamespace,
+			// TODO: use uid
+		}).String(),
+		TypeMeta: metav1.TypeMeta{Kind: "Pod"},
 	}
-	events, err := c.CoreV1().Events(podNamespace).List(context.TODO(), opt)
+	evs, err := c.CoreV1().Events(podNamespace).List(context.TODO(), opts)
 	if err != nil {
-		return failedSchedulingEvents, err
+		return nil, err
 	}
+	return evs.Items, nil
+}
 
-	for _, e := range events.Items {
-		if e.Reason == "FailedScheduling" {
-			failedSchedulingEvents = append(failedSchedulingEvents, e)
+func filterPodFailedSchedulingEvents(events []v1.Event) []v1.Event {
+	var failedSchedulingEvents []v1.Event
+	for _, ev := range events {
+		if ev.Reason == "FailedScheduling" {
+			failedSchedulingEvents = append(failedSchedulingEvents, ev)
 		}
 	}
-	return failedSchedulingEvents, nil
+	return failedSchedulingEvents
 }
 
-func formatObject(obj interface{}) string {
-	bytes, err := json.Marshal(obj)
-	if err != nil {
-		return fmt.Sprintf("<ERROR: %s>", err)
+func formatEvents(events []v1.Event) string {
+	var sb strings.Builder
+	for idx, ev := range events {
+		fmt.Fprintf(&sb, "%02d - %s\n", idx, eventToString(ev))
 	}
-	return string(bytes)
+	return sb.String()
+}
+
+func eventToString(ev v1.Event) string {
+	return fmt.Sprintf("type=%q action=%q message=%q reason=%q reportedBy={%s/%s}",
+		ev.Type, ev.Action, ev.Message, ev.Reason, ev.ReportingController, ev.ReportingInstance,
+	)
 }

test/integration/nrtutils.go

@@ -18,6 +18,7 @@ package integration
 
 import (
 	"context"
+	"encoding/json"
 	"fmt"
 	"sort"
 	"strings"
@@ -202,31 +203,35 @@ func (n *nrtWrapper) Obj() *topologyv1alpha2.NodeResourceTopology {
 	return &n.nrt
 }
 
-func podIsScheduled(interval time.Duration, times int, cs clientset.Interface, podNamespace, podName string) error {
-	return wait.Poll(interval, time.Duration(times)*interval, func() (bool, error) {
-		return podScheduled(cs, podNamespace, podName), nil
+func podIsScheduled(interval time.Duration, times int, cs clientset.Interface, podNamespace, podName string) (*corev1.Pod, error) {
+	var err error
+	var pod *corev1.Pod
+	waitErr := wait.Poll(interval, time.Duration(times)*interval, func() (bool, error) {
+		pod, err = cs.CoreV1().Pods(podNamespace).Get(context.TODO(), podName, metav1.GetOptions{})
+		if err != nil {
+			// This could be a connection error so we want to retry.
+			klog.ErrorS(err, "Failed to get pod", "pod", klog.KRef(podNamespace, podName))
+			return false, err
+		}
+		return pod.Spec.NodeName != "", nil
 	})
+	return pod, waitErr
 }
 
-func podIsPending(interval time.Duration, times int, cs clientset.Interface, podNamespace, podName string) error {
+func podIsPending(interval time.Duration, times int, cs clientset.Interface, podNamespace, podName string) (*corev1.Pod, error) {
+	var err error
+	var pod *corev1.Pod
 	for attempt := 0; attempt < times; attempt++ {
-		if !podPending(cs, podNamespace, podName) {
-			return fmt.Errorf("pod %s/%s not pending", podNamespace, podName)
+		pod, err = cs.CoreV1().Pods(podNamespace).Get(context.TODO(), podName, metav1.GetOptions{})
+		if err != nil {
+			return pod, fmt.Errorf("pod %s/%s not pending: %w", podNamespace, podName, err)
+		}
+		if pod.Spec.NodeName != "" {
+			return pod, fmt.Errorf("pod %s/%s not pending: bound to %q", podNamespace, podName, pod.Spec.NodeName)
 		}
 		time.Sleep(interval)
 	}
-	return nil
-}
-
-// podPending returns true if a node is not assigned to the given pod.
-func podPending(c clientset.Interface, podNamespace, podName string) bool {
-	pod, err := c.CoreV1().Pods(podNamespace).Get(context.TODO(), podName, metav1.GetOptions{})
-	if err != nil {
-		// This could be a connection error so we want to retry.
-		klog.ErrorS(err, "Failed to get pod", "pod", klog.KRef(podNamespace, podName))
-		return false
-	}
-	return pod.Spec.NodeName == ""
+	return pod, nil
 }
 
 func accumulateResourcesToCapacity(nrt topologyv1alpha2.NodeResourceTopology) corev1.ResourceList {
@@ -301,3 +306,11 @@ func makeTestFullyAvailableNRTs() []*topologyv1alpha2.NodeResourceTopology {
 				}).Obj(),
 	)
 }
+
+func formatObject(obj interface{}) string {
+	bytes, err := json.Marshal(obj)
+	if err != nil {
+		return fmt.Sprintf("<ERROR: %s>", err)
+	}
+	return string(bytes)
+}