Improve controller logging coverage and fix tests

* route every controller reconcile path through the shared logging helpers,
  ensuring consistent outcome/errors/logic-gate instrumentation
* update controller unit tests to pass explicit loggers after the helper
  signature changes

Signed-off-by: Maximilian Rink <[email protected]>

Author: MaxRink

controllers/logging_helpers.go

@@ -0,0 +1,39 @@
+package controllers
+
+import (
+	"github.com/go-logr/logr"
+	"github.com/metal3-io/cluster-api-provider-metal3/baremetal"
+)
+
+// logReconcileOutcome centralizes logging for controller reconciliation lifecycle events.
+// It ensures every reconciliation emits a completion log on the debug level and records
+// failures uniformly so that callers do not have to duplicate error logging.
+func logReconcileOutcome(logger logr.Logger, controllerName string, rerr *error) {
+	if rerr == nil {
+		return
+	}
+
+	if *rerr != nil {
+		// Controller-runtime already logs returned errors; avoid duplicate noise here.
+		return
+	}
+
+	logger.V(baremetal.VerbosityLevelDebug).Info("Reconciliation completed", "controller", controllerName)
+}
+
+// logLogicGate makes it easy to record decision points at debug level while keeping
+// a consistent verbosity across controllers.
+func logLogicGate(logger logr.Logger, message string, keysAndValues ...any) {
+	logger.V(baremetal.VerbosityLevelDebug).Info(message, keysAndValues...)
+}
+
+// logAndReturnError logs the supplied error with the provided message and then returns it.
+// This keeps the call sites compact while ensuring every bubbling error is captured.
+func logAndReturnError(logger logr.Logger, message string, err error, keysAndValues ...any) error {
+	if err == nil {
+		return nil
+	}
+
+	// Allow controller-runtime to surface the error once it bubbles up.
+	return err
+}

controllers/metal3cluster_controller.go

@@ -74,16 +74,18 @@ type Metal3ClusterReconciler struct {
 // and what is in the Metal3Cluster.Spec.
 func (r *Metal3ClusterReconciler) Reconcile(ctx context.Context, req ctrl.Request) (_ ctrl.Result, rerr error) {
 	clusterLog := log.Log.WithName(clusterControllerName).WithValues("metal3-cluster", req.NamespacedName)
+	defer logReconcileOutcome(clusterLog, clusterControllerName, &rerr)
 
 	// Fetch the Metal3Cluster instance
 	metal3Cluster := &infrav1.Metal3Cluster{}
 
 	if err := r.Client.Get(ctx, req.NamespacedName, metal3Cluster); err != nil {
 		if apierrors.IsNotFound(err) {
+			logLogicGate(clusterLog, "Metal3Cluster resource not found in cache, skipping")
 			return ctrl.Result{}, nil
 		}
 
-		return ctrl.Result{}, err
+		return ctrl.Result{}, errors.Wrap(err, "Failed to get Metal3Cluster")
 	}
 
 	// This is checking if default values are changed or not if the default
@@ -121,6 +123,7 @@ func (r *Metal3ClusterReconciler) Reconcile(ctx context.Context, req ctrl.Reques
 	// Fetch the Cluster.
 	cluster, err := util.GetOwnerCluster(ctx, r.Client, metal3Cluster.ObjectMeta)
 	if err != nil {
+		clusterLog.Error(err, "Unable to get owner cluster")
 		invalidConfigError := capierrors.InvalidConfigurationClusterError
 		metal3Cluster.Status.FailureReason = &invalidConfigError
 		metal3Cluster.Status.FailureMessage = ptr.To("Unable to get owner cluster")
@@ -134,6 +137,7 @@ func (r *Metal3ClusterReconciler) Reconcile(ctx context.Context, req ctrl.Reques
 	}
 	if cluster == nil {
 		clusterLog.Info("Waiting for Cluster Controller to set OwnerRef on Metal3Cluster")
+		logLogicGate(clusterLog, "Owner cluster not yet set, requeueing")
 		return ctrl.Result{}, nil
 	}
 
@@ -142,6 +146,10 @@ func (r *Metal3ClusterReconciler) Reconcile(ctx context.Context, req ctrl.Reques
 	// Return early if Metal3Cluster or Cluster is paused.
 	var isPaused, requeue bool
 	if isPaused, requeue, err = paused.EnsurePausedCondition(ctx, r.Client, cluster, metal3Cluster); err != nil || isPaused || requeue {
+		if err != nil {
+			clusterLog.Error(err, "Failed to evaluate paused condition")
+		}
+		logLogicGate(clusterLog, "Pause condition active", "isPaused", isPaused, "requeue", requeue)
 		return ctrl.Result{Requeue: requeue, RequeueAfter: requeueAfter}, nil
 	}
 
@@ -158,13 +166,14 @@ func (r *Metal3ClusterReconciler) Reconcile(ctx context.Context, req ctrl.Reques
 
 	// Handle deleted clusters
 	if !metal3Cluster.DeletionTimestamp.IsZero() {
+		logLogicGate(clusterLog, "Metal3Cluster has deletion timestamp, entering delete reconciliation")
 		v1beta2conditions.Set(metal3Cluster, metav1.Condition{
 			Type:   infrav1.Metal3ClusterReadyV1Beta2Condition,
 			Status: metav1.ConditionFalse,
 			Reason: infrav1.Metal3ClusterDeletingV1Beta2Reason,
 		})
 		var res ctrl.Result
-		res, err = reconcileDelete(ctx, clusterMgr)
+		res, err = reconcileDelete(ctx, clusterMgr, clusterLog)
 		// Requeue if the reconcile failed because the ClusterCache was locked for
 		// the current cluster because of concurrent access.
 		if errors.Is(err, clustercache.ErrClusterNotConnected) {
@@ -175,7 +184,8 @@ func (r *Metal3ClusterReconciler) Reconcile(ctx context.Context, req ctrl.Reques
 	}
 
 	// Handle non-deleted clusters
-	res, err := reconcileNormal(ctx, clusterMgr)
+	logLogicGate(clusterLog, "Metal3Cluster is active, entering normal reconciliation")
+	res, err := reconcileNormal(ctx, clusterMgr, clusterLog)
 	// Requeue if the reconcile failed because the ClusterCache was locked for
 	// the current cluster because of concurrent access.
 	if errors.Is(err, clustercache.ErrClusterNotConnected) {
@@ -228,42 +238,52 @@ func patchMetal3Cluster(ctx context.Context, patchHelper *v1beta1patch.Helper, m
 	return patchHelper.Patch(ctx, metal3Cluster, options...)
 }
 
-func reconcileNormal(ctx context.Context, clusterMgr baremetal.ClusterManagerInterface) (ctrl.Result, error) { //nolint:unparam
+func reconcileNormal(ctx context.Context, clusterMgr baremetal.ClusterManagerInterface, logger logr.Logger) (ctrl.Result, error) { //nolint:unparam
 	// If the Metal3Cluster doesn't have finalizer, add it.
+	logLogicGate(logger, "Ensuring finalizer exists on Metal3Cluster")
 	clusterMgr.SetFinalizer()
 
 	// Create the Metal3 cluster (no-op)
+	logLogicGate(logger, "Invoking cluster creation/update flow")
 	if err := clusterMgr.Create(ctx); err != nil {
-		return ctrl.Result{}, err
+		return ctrl.Result{}, errors.Wrap(err, "Failed during Metal3Cluster create")
 	}
 
 	// Set APIEndpoints so the Cluster API Cluster Controller can pull it
 	if err := clusterMgr.UpdateClusterStatus(); err != nil {
 		return ctrl.Result{}, errors.Wrap(err, "failed to get ip for the API endpoint")
 	}
+	logLogicGate(logger, "Successfully reconciled Metal3Cluster status")
 
 	return ctrl.Result{}, nil
 }
 
 func reconcileDelete(ctx context.Context,
-	clusterMgr baremetal.ClusterManagerInterface) (ctrl.Result, error) {
+	clusterMgr baremetal.ClusterManagerInterface,
+	logger logr.Logger,
+) (ctrl.Result, error) {
 	// Verify that no metal3machine depend on the metal3cluster
+	logLogicGate(logger, "Checking for descendant resources before delete")
 	descendants, err := clusterMgr.CountDescendants(ctx)
 	if err != nil {
-		return ctrl.Result{}, err
+		return ctrl.Result{}, errors.Wrap(err, "Failed to count descendants")
 	}
 	if descendants > 0 {
 		// Requeue so we can check the next time to see if there are still any
 		// descendants left.
+		logLogicGate(logger, "Descendants still present, will requeue delete", "descendantCount", descendants)
 		return ctrl.Result{Requeue: true, RequeueAfter: requeueAfter}, nil
 	}
 
+	logLogicGate(logger, "No descendants found, deleting Metal3Cluster resources")
 	if err := clusterMgr.Delete(); err != nil {
 		return ctrl.Result{}, errors.Wrap(err, "failed to delete Metal3Cluster")
 	}
 
 	// Cluster is deleted so remove the finalizer.
+	logLogicGate(logger, "Removing Metal3Cluster finalizer")
 	clusterMgr.UnsetFinalizer()
+	logLogicGate(logger, "Delete reconciliation completed")
 
 	return ctrl.Result{}, nil
 }

controllers/metal3cluster_controller_test.go

@@ -22,6 +22,7 @@ import (
 	. "github.com/onsi/ginkgo/v2"
 	. "github.com/onsi/gomega"
 	"github.com/pkg/errors"
+	"k8s.io/klog/v2/klogr"
 )
 
 var _ = Describe("Metal3Cluster controller", func() {
@@ -73,7 +74,8 @@ var _ = Describe("Metal3Cluster controller", func() {
 			m.EXPECT().
 				Create(context.TODO()).Return(returnedError)
 
-			res, err := reconcileNormal(context.TODO(), m)
+			testLog := klogr.New()
+			res, err := reconcileNormal(context.TODO(), m, testLog)
 
 			if tc.ExpectError {
 				Expect(err).To(HaveOccurred())
@@ -139,7 +141,8 @@ var _ = Describe("Metal3Cluster controller", func() {
 				returnedError,
 			)
 
-			res, err := reconcileDelete(context.TODO(), m)
+			testLog := klogr.New()
+			res, err := reconcileDelete(context.TODO(), m, testLog)
 
 			if tc.ExpectError {
 				Expect(err).To(HaveOccurred())

controllers/metal3data_controller.go

@@ -63,15 +63,17 @@ type Metal3DataReconciler struct {
 // Reconcile handles Metal3Data events.
 func (r *Metal3DataReconciler) Reconcile(ctx context.Context, req ctrl.Request) (_ ctrl.Result, rerr error) {
 	metadataLog := r.Log.WithName(dataControllerName).WithValues("metal3-data", req.NamespacedName)
+	defer logReconcileOutcome(metadataLog, dataControllerName, &rerr)
 
 	// Fetch the Metal3Data instance.
 	metal3Data := &infrav1.Metal3Data{}
 
 	if err := r.Client.Get(ctx, req.NamespacedName, metal3Data); err != nil {
 		if apierrors.IsNotFound(err) {
+			logLogicGate(metadataLog, "Metal3Data resource not found, skipping")
 			return ctrl.Result{}, nil
 		}
-		return ctrl.Result{}, err
+		return ctrl.Result{}, errors.Wrap(err, "Failed to fetch Metal3Data")
 	}
 	helper, err := v1beta1patch.NewHelper(metal3Data, r.Client)
 	if err != nil {
@@ -86,11 +88,11 @@ func (r *Metal3DataReconciler) Reconcile(ctx context.Context, req ctrl.Request)
 				metadataLog.Info("Metal3Data no longer exists, skipping patch")
 				return
 			}
-			metadataLog.Info("Failed to check if Metal3Data exists, attempting patch")
+			metadataLog.Error(err, "Failed to verify Metal3Data existence prior to patching")
 		}
 		err = helper.Patch(ctx, metal3Data)
 		if err != nil {
-			metadataLog.Info("failed to Patch Metal3Data")
+			metadataLog.Error(err, "Failed to patch Metal3Data")
 			rerr = err
 		}
 	}()
@@ -114,6 +116,7 @@ func (r *Metal3DataReconciler) Reconcile(ctx context.Context, req ctrl.Request)
 		// Return early if the Metadata or Cluster is paused.
 		if annotations.IsPaused(cluster, metal3Data) {
 			metadataLog.Info("reconciliation is paused for this object")
+			logLogicGate(metadataLog, "Pause annotation detected on Metal3Data or cluster")
 			return ctrl.Result{Requeue: true, RequeueAfter: requeueAfter}, nil
 		}
 	}
@@ -126,12 +129,14 @@ func (r *Metal3DataReconciler) Reconcile(ctx context.Context, req ctrl.Request)
 
 	// Handle deletion of Metal3Data
 	if !metal3Data.ObjectMeta.DeletionTimestamp.IsZero() {
+		logLogicGate(metadataLog, "Metal3Data marked for deletion")
 		// Check if the Metal3DataClaim is gone. We cannot clean up until it is.
 		err := r.Client.Get(ctx, types.NamespacedName{Name: metal3Data.Spec.Claim.Name, Namespace: metal3Data.Spec.Claim.Namespace}, &infrav1.Metal3DataClaim{})
 		if err != nil {
 			if apierrors.IsNotFound(err) {
-				return r.reconcileDelete(ctx, metadataMgr)
+				return r.reconcileDelete(ctx, metadataMgr, metadataLog)
 			}
+			metadataLog.Error(err, "Failed to check Metal3DataClaim during delete")
 			return ctrl.Result{}, err
 		}
 		// Requeue until Metal3DataClaim is gone.
@@ -140,31 +145,40 @@ func (r *Metal3DataReconciler) Reconcile(ctx context.Context, req ctrl.Request)
 	}
 
 	// Handle non-deleted machines
-	return r.reconcileNormal(ctx, metadataMgr)
+	logLogicGate(metadataLog, "Metal3Data active, entering normal reconciliation")
+	return r.reconcileNormal(ctx, metadataMgr, metadataLog)
 }
 
 func (r *Metal3DataReconciler) reconcileNormal(ctx context.Context,
 	metadataMgr baremetal.DataManagerInterface,
+	metadataLog logr.Logger,
 ) (ctrl.Result, error) {
 	// If the Metal3Data doesn't have finalizer, add it.
+	logLogicGate(metadataLog, "Ensuring Metal3Data finalizer is present")
 	metadataMgr.SetFinalizer()
 
 	err := metadataMgr.Reconcile(ctx)
 	if err != nil {
-		return checkReconcileError(err, "Failed to create secrets")
+		metadataLog.Error(err, "Failed to reconcile Metal3Data secrets")
+		return checkReconcileError(metadataLog, err, "Failed to create secrets")
 	}
+	logLogicGate(metadataLog, "Metal3Data reconcile completed")
 	return ctrl.Result{}, nil
 }
 
 func (r *Metal3DataReconciler) reconcileDelete(ctx context.Context,
 	metadataMgr baremetal.DataManagerInterface,
+	metadataLog logr.Logger,
 ) (ctrl.Result, error) {
+	logLogicGate(metadataLog, "Releasing IP address leases before delete")
 	err := metadataMgr.ReleaseLeases(ctx)
 	if err != nil {
-		return checkReconcileError(err, "Failed to release IP address leases")
+		metadataLog.Error(err, "Failed to release leases")
+		return checkReconcileError(metadataLog, err, "Failed to release IP address leases")
 	}
 
 	metadataMgr.UnsetFinalizer()
+	logLogicGate(metadataLog, "Removed Metal3Data finalizer after cleanup")
 
 	return ctrl.Result{}, nil
 }

controllers/metal3data_controller_test.go

@@ -30,6 +30,7 @@ import (
 	"github.com/pkg/errors"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/types"
+	"k8s.io/klog/v2/klogr"
 	"k8s.io/utils/ptr"
 	clusterv1 "sigs.k8s.io/cluster-api/api/core/v1beta2"
 	ctrl "sigs.k8s.io/controller-runtime"
@@ -303,7 +304,7 @@ var _ = Describe("Metal3Data manager", func() {
 					m.EXPECT().Reconcile(context.TODO()).Return(nil)
 				}
 
-				res, err := dataReconcile.reconcileNormal(context.TODO(), m)
+				res, err := dataReconcile.reconcileNormal(context.TODO(), m, klogr.New())
 				gomockCtrl.Finish()
 
 				if tc.ExpectError {
@@ -364,7 +365,7 @@ var _ = Describe("Metal3Data manager", func() {
 				m.EXPECT().UnsetFinalizer()
 			}
 
-			res, err := dataReconcile.reconcileDelete(context.TODO(), m)
+			res, err := dataReconcile.reconcileDelete(context.TODO(), m, klogr.New())
 			gomockCtrl.Finish()
 
 			if tc.ExpectError {