Use per-test logger for more clear logs

We used to log everything using the global logger. This makes the log messy and hard to follow, since we run 5 dr flows concurrently. This will be worse as we add new workloads (e.g. flattened pvcs, cloned pvcs, volsync with block pvc). We use now per-test logger created using the name of the workload (e.g. disapp-deploy-rbd-busybox). Every log message from test flow start with this name. The rest of the log does not specify resources names since we use the same name for all resources (drpc, placement, subscription, etc). Clean up log messages, replacing noisy text with simple description of the event. More work is needed, we still log too much uninteresting details, and do no not log what we wait for, but this is already much easier to follow. Example log with this change: === RUN TestSuites/Exhaustive/Deploy-rbd/Subscr/Enable 2024-10-31T00:37:41.913+0200 INFO subscr-deploy-rbd-busybox Protecting workload 2024-10-31T00:37:41.913+0200 INFO subscr-deploy-cephfs-busybox Protecting workload 2024-10-31T00:37:41.915+0200 INFO appset-deploy-rbd-busybox Workload running on dr2 2024-10-31T00:37:41.915+0200 INFO appset-deploy-rbd-busybox Annotating placement 2024-10-31T00:37:41.917+0200 INFO subscr-deploy-rbd-busybox Workload running on dr2 2024-10-31T00:37:41.917+0200 INFO subscr-deploy-rbd-busybox Annotating placement 2024-10-31T00:37:41.918+0200 INFO subscr-deploy-cephfs-busybox Workload running on dr1 2024-10-31T00:37:41.918+0200 INFO subscr-deploy-cephfs-busybox Annotating placement 2024-10-31T00:37:41.926+0200 INFO appset-deploy-rbd-busybox Creating drpc 2024-10-31T00:37:41.930+0200 INFO subscr-deploy-rbd-busybox Creating drpc 2024-10-31T00:37:41.932+0200 INFO subscr-deploy-cephfs-busybox Creating drpc 2024-10-31T00:38:52.038+0200 INFO appset-deploy-cephfs-busybox drpc is ready Fixes: RamenDR#1597 Signed-off-by: Nir Soffer <[email protected]>
nirs · Oct 30, 2024 · 3da821e · 3da821e
1 parent 866f6ed
commit 3da821e
Show file tree

Hide file tree

Showing 12 changed files with 164 additions and 136 deletions.
diff --git a/e2e/deployers/applicationset.go b/e2e/deployers/applicationset.go
@@ -13,25 +13,26 @@ type ApplicationSet struct{}
 func (a ApplicationSet) Deploy(w workloads.Workload) error {
 	name := GetCombinedName(a, w)
 	namespace := util.ArgocdNamespace
+	log := util.Ctx.Log.WithName(name)
 
-	util.Ctx.Log.Info("enter Deploy " + name)
+	log.Info("Deploying workload")
 
 	err := CreateManagedClusterSetBinding(McsbName, namespace)
 	if err != nil {
 		return err
 	}
 
-	err = CreatePlacement(name, namespace)
+	err = CreatePlacement(name, namespace, log)
 	if err != nil {
 		return err
 	}
 
-	err = CreatePlacementDecisionConfigMap(name, namespace)
+	err = CreatePlacementDecisionConfigMap(name, namespace, log)
 	if err != nil {
 		return err
 	}
 
-	err = CreateApplicationSet(a, w)
+	err = CreateApplicationSet(a, w, log)
 	if err != nil {
 		return err
 	}
@@ -42,33 +43,34 @@ func (a ApplicationSet) Deploy(w workloads.Workload) error {
 func (a ApplicationSet) Undeploy(w workloads.Workload) error {
 	name := GetCombinedName(a, w)
 	namespace := util.ArgocdNamespace
+	log := util.Ctx.Log.WithName(name)
 
-	util.Ctx.Log.Info("enter Undeploy " + name)
+	log.Info("Undeploying workload")
 
-	err := DeleteApplicationSet(a, w)
+	err := DeleteApplicationSet(a, w, log)
 	if err != nil {
 		return err
 	}
 
-	err = DeleteConfigMap(name, namespace)
+	err = DeleteConfigMap(name, namespace, log)
 	if err != nil {
 		return err
 	}
 
-	err = DeletePlacement(name, namespace)
+	err = DeletePlacement(name, namespace, log)
 	if err != nil {
 		return err
 	}
 
 	// multiple appsets could use the same mcsb in argocd ns.
 	// so delete mcsb if only 1 appset is in argocd ns
-	lastAppset, err := isLastAppsetInArgocdNs(namespace)
+	lastAppset, err := isLastAppsetInArgocdNs(namespace, log)
 	if err != nil {
 		return err
 	}
 
 	if lastAppset {
-		err = DeleteManagedClusterSetBinding(McsbName, namespace)
+		err = DeleteManagedClusterSetBinding(McsbName, namespace, log)
 		if err != nil {
 			return err
 		}

diff --git a/e2e/deployers/crud.go b/e2e/deployers/crud.go
@@ -11,6 +11,7 @@ import (
 	"os/exec"
 	"strings"
 
+	"github.com/go-logr/logr"
 	"github.com/ramendr/ramen/e2e/util"
 	"github.com/ramendr/ramen/e2e/workloads"
 	"k8s.io/apimachinery/pkg/api/errors"
@@ -58,7 +59,7 @@ func CreateManagedClusterSetBinding(name, namespace string) error {
 	return nil
 }
 
-func DeleteManagedClusterSetBinding(name, namespace string) error {
+func DeleteManagedClusterSetBinding(name, namespace string, log logr.Logger) error {
 	mcsb := &ocmv1b2.ManagedClusterSetBinding{
 		ObjectMeta: metav1.ObjectMeta{
 			Name:      name,
@@ -72,13 +73,13 @@ func DeleteManagedClusterSetBinding(name, namespace string) error {
 			return err
 		}
 
-		util.Ctx.Log.Info("managedClusterSetBinding " + name + " not found")
+		log.Info("ManagedClusterSetBinding " + name + " not found")
 	}
 
 	return nil
 }
 
-func CreatePlacement(name, namespace string) error {
+func CreatePlacement(name, namespace string, log logr.Logger) error {
 	labels := make(map[string]string)
 	labels[AppLabelKey] = name
 	clusterSet := []string{ClusterSetName}
@@ -102,13 +103,13 @@ func CreatePlacement(name, namespace string) error {
 			return err
 		}
 
-		util.Ctx.Log.Info("placement " + placement.Name + " already Exists")
+		log.Info("Placement already Exists")
 	}
 
 	return nil
 }
 
-func DeletePlacement(name, namespace string) error {
+func DeletePlacement(name, namespace string, log logr.Logger) error {
 	placement := &ocmv1b1.Placement{
 		ObjectMeta: metav1.ObjectMeta{
 			Name:      name,
@@ -122,13 +123,13 @@ func DeletePlacement(name, namespace string) error {
 			return err
 		}
 
-		util.Ctx.Log.Info("placement " + name + " not found")
+		log.Info("Placement not found")
 	}
 
 	return nil
 }
 
-func CreateSubscription(s Subscription, w workloads.Workload) error {
+func CreateSubscription(s Subscription, w workloads.Workload, log logr.Logger) error {
 	name := GetCombinedName(s, w)
 	namespace := name
 
@@ -173,18 +174,18 @@ func CreateSubscription(s Subscription, w workloads.Workload) error {
 	err := util.Ctx.Hub.CtrlClient.Create(context.Background(), subscription)
 	if err != nil {
 		if !errors.IsAlreadyExists(err) {
-			util.Ctx.Log.Info(fmt.Sprintf("create subscription with error: %v", err))
+			log.Info(fmt.Sprintf("create subscription with error: %v", err))
 
 			return err
 		}
 
-		util.Ctx.Log.Info("subscription " + subscription.Name + " already Exists")
+		log.Info("Subscription already Exists")
 	}
 
 	return nil
 }
 
-func DeleteSubscription(s Subscription, w workloads.Workload) error {
+func DeleteSubscription(s Subscription, w workloads.Workload, log logr.Logger) error {
 	name := GetCombinedName(s, w)
 	namespace := name
 
@@ -201,7 +202,7 @@ func DeleteSubscription(s Subscription, w workloads.Workload) error {
 			return err
 		}
 
-		util.Ctx.Log.Info("subscription " + name + " not found")
+		log.Info("Subscription not found")
 	}
 
 	return nil
@@ -237,7 +238,7 @@ func getSubscription(client client.Client, namespace, name string) (*subscriptio
 	return subscription, nil
 }
 
-func CreatePlacementDecisionConfigMap(cmName string, cmNamespace string) error {
+func CreatePlacementDecisionConfigMap(cmName string, cmNamespace string, log logr.Logger) error {
 	object := metav1.ObjectMeta{Name: cmName, Namespace: cmNamespace}
 
 	data := map[string]string{
@@ -255,13 +256,13 @@ func CreatePlacementDecisionConfigMap(cmName string, cmNamespace string) error {
 			return fmt.Errorf("could not create configMap " + cmName)
 		}
 
-		util.Ctx.Log.Info("configMap " + cmName + " already Exists")
+		log.Info("ConfigMap " + cmName + " already Exists")
 	}
 
 	return nil
 }
 
-func DeleteConfigMap(cmName string, cmNamespace string) error {
+func DeleteConfigMap(cmName string, cmNamespace string, log logr.Logger) error {
 	object := metav1.ObjectMeta{Name: cmName, Namespace: cmNamespace}
 
 	configMap := &corev1.ConfigMap{
@@ -274,14 +275,14 @@ func DeleteConfigMap(cmName string, cmNamespace string) error {
 			return fmt.Errorf("could not delete configMap " + cmName)
 		}
 
-		util.Ctx.Log.Info("configMap " + cmName + " not found")
+		log.Info("ConfigMap " + cmName + " not found")
 	}
 
 	return nil
 }
 
 // nolint:funlen
-func CreateApplicationSet(a ApplicationSet, w workloads.Workload) error {
+func CreateApplicationSet(a ApplicationSet, w workloads.Workload, log logr.Logger) error {
 	var requeueSeconds int64 = 180
 
 	name := GetCombinedName(a, w)
@@ -353,13 +354,13 @@ func CreateApplicationSet(a ApplicationSet, w workloads.Workload) error {
 			return err
 		}
 
-		util.Ctx.Log.Info("applicationset " + appset.Name + " already Exists")
+		log.Info("Applicationset already Exists")
 	}
 
 	return nil
 }
 
-func DeleteApplicationSet(a ApplicationSet, w workloads.Workload) error {
+func DeleteApplicationSet(a ApplicationSet, w workloads.Workload, log logr.Logger) error {
 	name := GetCombinedName(a, w)
 	namespace := util.ArgocdNamespace
 
@@ -376,28 +377,28 @@ func DeleteApplicationSet(a ApplicationSet, w workloads.Workload) error {
 			return err
 		}
 
-		util.Ctx.Log.Info("applicationset " + appset.Name + " not found")
+		log.Info("Applicationset not found")
 	}
 
 	return nil
 }
 
 // check if only the last appset is in the argocd namespace
-func isLastAppsetInArgocdNs(namespace string) (bool, error) {
+func isLastAppsetInArgocdNs(namespace string, log logr.Logger) (bool, error) {
 	appsetList := &argocdv1alpha1hack.ApplicationSetList{}
 
 	err := util.Ctx.Hub.CtrlClient.List(
 		context.Background(), appsetList, client.InNamespace(namespace))
 	if err != nil {
-		util.Ctx.Log.Info("error in getting application sets")
+		log.Info("Failed to get application sets")
 
 		return false, err
 	}
 
 	return len(appsetList.Items) == 1, nil
 }
 
-func DeleteDiscoveredApps(w workloads.Workload, namespace, cluster string) error {
+func DeleteDiscoveredApps(w workloads.Workload, namespace, cluster string, log logr.Logger) error {
 	tempDir, err := os.MkdirTemp("", "ramen-")
 	if err != nil {
 		return err
@@ -415,7 +416,7 @@ func DeleteDiscoveredApps(w workloads.Workload, namespace, cluster string) error
 
 	// Run the command and capture the output
 	if out, err := cmd.Output(); err != nil {
-		util.Ctx.Log.Info(string(out))
+		log.Info(string(out))
 
 		return err
 	}

diff --git a/e2e/deployers/discoveredapps.go b/e2e/deployers/discoveredapps.go
@@ -20,8 +20,9 @@ func (d DiscoveredApps) GetName() string {
 func (d DiscoveredApps) Deploy(w workloads.Workload) error {
 	name := GetCombinedName(d, w)
 	namespace := name
+	log := util.Ctx.Log.WithName(name)
 
-	util.Ctx.Log.Info("enter Deploy " + name)
+	log.Info("Deploying workload")
 
 	// create namespace in both dr clusters
 	if err := util.CreateNamespaceAndAddAnnotation(namespace); err != nil {
@@ -50,58 +51,59 @@ func (d DiscoveredApps) Deploy(w workloads.Workload) error {
 
 	// Run the command and capture the output
 	if out, err := cmd.Output(); err != nil {
-		util.Ctx.Log.Info(string(out))
+		log.Info(string(out))
 
 		return err
 	}
 
-	if err = WaitWorkloadHealth(util.Ctx.C1.CtrlClient, namespace, w); err != nil {
+	if err = WaitWorkloadHealth(util.Ctx.C1.CtrlClient, namespace, w, log); err != nil {
 		return err
 	}
 
-	util.Ctx.Log.Info(name + " is deployed")
+	log.Info("Workload deployed")
 
 	return nil
 }
 
 func (d DiscoveredApps) Undeploy(w workloads.Workload) error {
 	name := GetCombinedName(d, w)
 	namespace := name // this namespace is in dr clusters
+	log := util.Ctx.Log.WithName(name)
 
-	util.Ctx.Log.Info("enter Undeploy " + name)
+	log.Info("Undeploying workload")
 
 	drpolicy, err := util.GetDRPolicy(util.Ctx.Hub.CtrlClient, util.DefaultDRPolicyName)
 	if err != nil {
 		return err
 	}
 
-	util.Ctx.Log.Info("starts to delete discovered apps on " + drpolicy.Spec.DRClusters[0])
+	log.Info("Deleting discovered apps on " + drpolicy.Spec.DRClusters[0])
 
 	// delete app on both clusters
-	if err := DeleteDiscoveredApps(w, namespace, drpolicy.Spec.DRClusters[0]); err != nil {
+	if err := DeleteDiscoveredApps(w, namespace, drpolicy.Spec.DRClusters[0], log); err != nil {
 		return err
 	}
 
-	util.Ctx.Log.Info("starts to delete discovered apps on " + drpolicy.Spec.DRClusters[1])
+	log.Info("Deletting discovered apps on " + drpolicy.Spec.DRClusters[1])
 
-	if err := DeleteDiscoveredApps(w, namespace, drpolicy.Spec.DRClusters[1]); err != nil {
+	if err := DeleteDiscoveredApps(w, namespace, drpolicy.Spec.DRClusters[1], log); err != nil {
 		return err
 	}
 
-	util.Ctx.Log.Info("starts to delete namespace " + namespace + " on " + drpolicy.Spec.DRClusters[0])
+	log.Info("Deleting namespace " + namespace + " on " + drpolicy.Spec.DRClusters[0])
 
 	// delete namespace on both clusters
-	if err := util.DeleteNamespace(util.Ctx.C1.CtrlClient, namespace); err != nil {
+	if err := util.DeleteNamespace(util.Ctx.C1.CtrlClient, namespace, log); err != nil {
 		return err
 	}
 
-	util.Ctx.Log.Info("starts to delete namespace " + namespace + " on " + drpolicy.Spec.DRClusters[1])
+	log.Info("Deleting namespace " + namespace + " on " + drpolicy.Spec.DRClusters[1])
 
-	if err := util.DeleteNamespace(util.Ctx.C2.CtrlClient, namespace); err != nil {
+	if err := util.DeleteNamespace(util.Ctx.C2.CtrlClient, namespace, log); err != nil {
 		return err
 	}
 
-	util.Ctx.Log.Info(name + " is undeployed")
+	log.Info("Workload undeployed")
 
 	return nil
 }