Add debug logging for SLB monitortest cleanup

This test is failing periodically in some cases and we can't see when the problem is occurring to correlate with logs or intervals because the framework doesn't log much of anything.
openshift · Apr 9, 2024 · 79ea7f5 · 79ea7f5
1 parent 856924d
commit 79ea7f5
Show file tree

Hide file tree

Showing 3 changed files with 13 additions and 7 deletions.
diff --git a/pkg/monitortestframework/impl.go b/pkg/monitortestframework/impl.go
@@ -392,8 +392,10 @@ func (r *monitorTestRegistry) Cleanup(ctx context.Context) ([]*junitapi.JUnitTes
 
 	for _, monitorTest := range r.monitorTests {
 		testName := fmt.Sprintf("[Jira:%q] monitor test %v cleanup", monitorTest.jiraComponent, monitorTest.name)
+		log := logrus.WithField("monitorTest", monitorTest.name)
 
 		start := time.Now()
+		log.Info("beginning cleanup")
 		err := cleanupWithPanicProtection(ctx, monitorTest.monitorTest)
 		end := time.Now()
 		duration := end.Sub(start)
@@ -410,6 +412,7 @@ func (r *monitorTestRegistry) Cleanup(ctx context.Context) ([]*junitapi.JUnitTes
 				continue
 			}
 
+			log.WithError(err).Error("failed during cleanup")
 			errs = append(errs, err)
 			junits = append(junits, &junitapi.JUnitTestCase{
 				Name:     testName,

diff --git a/pkg/monitortestframework/panic.go b/pkg/monitortestframework/panic.go
@@ -82,7 +82,7 @@ func cleanupWithPanicProtection(ctx context.Context, monitortest MonitorTest) (e
 	defer func() {
 		if r := recover(); r != nil {
 			err = fmt.Errorf("caught panic: %v", r)
-			logrus.Error("recovering from panic")
+			logrus.WithError(err).Error("recovering from panic")
 			fmt.Print(debug.Stack())
 		}
 	}()

diff --git a/pkg/monitortests/network/disruptionserviceloadbalancer/monitortest.go b/pkg/monitortests/network/disruptionserviceloadbalancer/monitortest.go
@@ -11,10 +11,9 @@ import (
 	"strconv"
 	"time"
 
-	apierrors "k8s.io/apimachinery/pkg/api/errors"
-	"k8s.io/klog/v2"
-
 	"github.com/openshift/origin/pkg/monitortestframework"
+	"github.com/sirupsen/logrus"
+	apierrors "k8s.io/apimachinery/pkg/api/errors"
 
 	configv1 "github.com/openshift/api/config/v1"
 	configclient "github.com/openshift/client-go/config/clientset/versioned"
@@ -282,7 +281,7 @@ func (w *availability) namespaceDeleted(ctx context.Context) (bool, error) {
 	}
 
 	if err != nil {
-		klog.Errorf("Error checking for deleted namespace: %s, %s", w.namespaceName, err.Error())
+		logrus.Errorf("Error checking for deleted namespace: %s, %s", w.namespaceName, err.Error())
 		return false, err
 	}
 
@@ -291,17 +290,21 @@ func (w *availability) namespaceDeleted(ctx context.Context) (bool, error) {
 
 func (w *availability) Cleanup(ctx context.Context) error {
 	if len(w.namespaceName) > 0 && w.kubeClient != nil {
+		log := logrus.WithField("monitorTest", "service-type-load-balancer-availability").WithField("namespace", w.namespaceName)
+		log.Info("deleting namespace")
 		if err := w.kubeClient.CoreV1().Namespaces().Delete(ctx, w.namespaceName, metav1.DeleteOptions{}); err != nil {
+			log.WithError(err).Error("error during namespace deletion")
 			return err
 		}
 
 		startTime := time.Now()
+		log.Info("waiting for namespace deletion to complete")
 		err := wait.PollUntilContextTimeout(ctx, 15*time.Second, 20*time.Minute, true, w.namespaceDeleted)
 		if err != nil {
+			log.WithError(err).Error("error waiting for namespace to delete")
 			return err
 		}
-
-		klog.Infof("Deleting namespace: %s took %.2f seconds", w.namespaceName, time.Now().Sub(startTime).Seconds())
+		log.Infof("namespace deleted in %.2f seconds", time.Now().Sub(startTime).Seconds())
 	}
 
 	return nil