Merge pull request #184 from red-hat-storage/sync_us--main

Syncing latest changes from upstream main for ramen

Author: ShyamsundarR

controllers/drcluster_controller.go

@@ -545,12 +545,12 @@ func (u *drclusterInstance) statusUpdate() error {
 			return fmt.Errorf("failed to update drCluster status (%s/%s)", u.object.Name, u.object.Namespace)
 		}
 
-		u.log.Info(fmt.Sprintf("Updated drCluster Status %+v", u.object.Status))
+		u.log.Info(fmt.Sprintf("Updated drCluster Status (%s/%s)", u.object.Name, u.object.Namespace))
 
 		return nil
 	}
 
-	u.log.Info(fmt.Sprintf("Nothing to update %+v", u.object.Status))
+	u.log.Info(fmt.Sprintf("Nothing to update (%s/%s)", u.object.Name, u.object.Namespace))
 
 	return nil
 }

controllers/drplacementcontrol.go

@@ -126,8 +126,8 @@ func (d *DRPCInstance) RunInitialDeployment() (bool, error) {
 		return !done, err
 	}
 
-	d.log.Info(fmt.Sprintf("Using homeCluster %s for initial deployment, Placement Decision %+v",
-		homeCluster, d.reconciler.getClusterDecision(d.userPlacement)))
+	d.log.Info(fmt.Sprintf("Using homeCluster %s for initial deployment",
+		homeCluster))
 
 	// Check if we already deployed in the homeCluster or elsewhere
 	deployed, clusterName := d.isDeployed(homeCluster)
@@ -804,7 +804,7 @@ func (d *DRPCInstance) RunRelocate() (bool, error) {
 	}
 
 	if d.getLastDRState() != rmn.Relocating && !d.validatePeerReady() {
-		return !done, fmt.Errorf("clean up secondaries is pending (%+v)", d.instance.Status.Conditions)
+		return !done, fmt.Errorf("clean up secondaries is pending, peer is not ready")
 	}
 
 	if curHomeCluster != "" && curHomeCluster != preferredCluster {
@@ -1102,7 +1102,7 @@ func (d *DRPCInstance) isVRGConditionMet(cluster string, conditionType string) b
 		return !ready
 	}
 
-	d.log.Info(fmt.Sprintf("VRG status condition: %+v", condition))
+	d.log.Info(fmt.Sprintf("VRG status condition: %s is %s", conditionType, condition.Status))
 
 	return condition.Status == metav1.ConditionTrue &&
 		condition.ObservedGeneration == vrg.Generation
@@ -1712,7 +1712,7 @@ func (d *DRPCInstance) EnsureCleanup(clusterToSkip string) error {
 		return nil
 	}
 
-	d.log.Info(fmt.Sprintf("PeerReady Condition %v", condition))
+	d.log.Info(fmt.Sprintf("PeerReady Condition is %s, msg: %s", condition.Status, condition.Message))
 
 	// IFF we have VolSync PVCs, then no need to clean up
 	homeCluster := clusterToSkip
@@ -2012,7 +2012,7 @@ func (d *DRPCInstance) ensureVRGDeleted(clusterName string) bool {
 		return false
 	}
 
-	d.log.Info(fmt.Sprintf("VRG not deleted(%v)", vrg.ObjectMeta))
+	d.log.Info(fmt.Sprintf("VRG not deleted(%s)", vrg.Name))
 
 	return false
 }

controllers/drplacementcontrol_controller.go

@@ -1342,8 +1342,6 @@ func getPlacementRule(ctx context.Context, k8sclient client.Client,
 			log.Info("User PlacementRule replica count is not set to 1, reconciliation will only" +
 				" schedule it to a single cluster")
 		}
-
-		log.Info(fmt.Sprintf("PlacementRule Status is: (%+v)", usrPlRule.Status))
 	}
 
 	return usrPlRule, nil
@@ -1702,7 +1700,7 @@ func (r *DRPlacementControlReconciler) updateDRPCStatus(
 		return errorswrapper.Wrap(err, "failed to update DRPC status")
 	}
 
-	log.Info(fmt.Sprintf("Updated DRPC Status %+v", drpc.Status))
+	log.Info("Updated DRPC Status")
 
 	return nil
 }
@@ -1721,7 +1719,7 @@ func (r *DRPlacementControlReconciler) updateResourceCondition(
 	vrg, err := r.MCVGetter.GetVRGFromManagedCluster(drpc.Name, vrgNamespace,
 		clusterName, annotations)
 	if err != nil {
-		log.Info("Failed to get VRG from managed cluster", "errMsg", err)
+		log.Info("Failed to get VRG from managed cluster", "errMsg", err.Error())
 
 		drpc.Status.ResourceConditions = rmn.VRGConditions{}
 	} else {
@@ -1969,7 +1967,7 @@ func (r *DRPlacementControlReconciler) createOrUpdatePlacementDecision(ctx conte
 		return fmt.Errorf("failed to update placementDecision status (%w)", err)
 	}
 
-	r.Log.Info("Created/Updated PlacementDecision", "PlacementDecision", plDecision)
+	r.Log.Info("Created/Updated PlacementDecision", "PlacementDecision", plDecision.Status.Decisions)
 
 	return nil
 }

controllers/drplacementcontrolvolsync.go

@@ -278,7 +278,7 @@ func (d *DRPCInstance) updateVRGSpec(clusterName string, tgtVRG *rmn.VolumeRepli
 		return fmt.Errorf("failed to update MW (%w)", err)
 	}
 
-	d.log.Info(fmt.Sprintf("Updated VRG running in cluster %s. VRG (%+v)", clusterName, vrg))
+	d.log.Info(fmt.Sprintf("Updated VRG running in cluster %s. VRG (%s)", clusterName, vrg.Name))
 
 	return nil
 }

controllers/protectedvolumereplicationgrouplist_controller.go

@@ -7,6 +7,7 @@ import (
 	"context"
 	"fmt"
 	"strings"
+	"time"
 
 	"github.com/ramendr/ramen/controllers/util"
 	"k8s.io/apimachinery/pkg/runtime"
@@ -50,31 +51,37 @@ type ProtectedVolumeReplicationGroupListInstance struct {
 // - https://pkg.go.dev/sigs.k8s.io/[email protected]/pkg/reconcile
 func (r *ProtectedVolumeReplicationGroupListReconciler) Reconcile(ctx context.Context, req ctrl.Request,
 ) (ctrl.Result, error) {
-	log := ctrl.Log.WithName("controllers").WithName("protectedvolumereplicationgrouplist").
-		WithValues("name", req.NamespacedName.Name)
-
-	log.Info("protectedvolumereplicationgrouplist reconcile start")
-
+	start := time.Now()
 	// save all the commonly used parameters in a struct
 	s := ProtectedVolumeReplicationGroupListInstance{
 		reconciler: r,
 		ctx:        ctx,
-		log:        log,
+		log:        ctrl.Log.WithName("pvrgl").WithValues("name", req.NamespacedName.Name),
 		instance:   &ramendrv1alpha1.ProtectedVolumeReplicationGroupList{},
 	}
 
 	// get ProtectedVolumeReplicationGroupListInstance and save to s.instance
-	if err := r.Client.Get(ctx, req.NamespacedName, s.instance); err != nil {
+	if err := r.Client.Get(s.ctx, req.NamespacedName, s.instance); err != nil {
 		return ctrl.Result{}, client.IgnoreNotFound(fmt.Errorf("get: %w", err))
 	}
 
+	s.log = s.log.WithValues("rid", s.instance.ObjectMeta.UID, "gen", s.instance.ObjectMeta.Generation,
+		"rv", s.instance.ObjectMeta.ResourceVersion)
+	s.ctx = ctrl.LoggerInto(ctx, s.log)
+
+	s.log.Info("reconcile start")
+
+	defer func() {
+		s.log.Info("reconcile end", "time spent", time.Since(start))
+	}()
+
 	if s.instance.Status != nil {
 		return ctrl.Result{}, nil
 	}
 
 	// get target profile from spec
 	s3profileName := s.instance.Spec.S3ProfileName
-	log.Info(fmt.Sprintf("targetProfileName=%s", s3profileName))
+	s.log.Info(fmt.Sprintf("targetProfileName=%s", s3profileName))
 
 	objectStore, _, err := s.reconciler.ObjStoreGetter.ObjectStore(
 		s.ctx, s.reconciler.APIReader, s3profileName, NamespaceName(), s.log)
@@ -100,7 +107,7 @@ func (r *ProtectedVolumeReplicationGroupListReconciler) Reconcile(ctx context.Co
 		return ctrl.Result{}, fmt.Errorf("error during updateStatus: %w", err)
 	}
 
-	log.Info("protectedvolumereplicationgrouplist updated successfully")
+	s.log.Info("updated successfully")
 
 	return ctrl.Result{}, nil
 }

controllers/util/mcv_util.go

@@ -322,8 +322,8 @@ func (m ManagedClusterViewGetterImpl) getOrCreateManagedClusterView(
 			return nil, errorswrapper.Wrap(err, "failed to get ManagedClusterView")
 		}
 
-		logger.Info(fmt.Sprintf("Creating ManagedClusterView %s with scope %+v",
-			key, viewscope))
+		logger.Info(fmt.Sprintf("Creating ManagedClusterView %s with scope %s",
+			key, viewscope.Name))
 
 		if err := m.Create(context.TODO(), mcv); err != nil {
 			return nil, errorswrapper.Wrap(err, "failed to create ManagedClusterView")
@@ -332,8 +332,8 @@ func (m ManagedClusterViewGetterImpl) getOrCreateManagedClusterView(
 
 	if mcv.Spec.Scope != viewscope {
 		// Expected once when uprading ramen if scope format or details have changed.
-		logger.Info(fmt.Sprintf("Updating ManagedClusterView %s scope %+v to %+v",
-			key, mcv.Spec.Scope, viewscope))
+		logger.Info(fmt.Sprintf("Updating ManagedClusterView %s scope %s to %s",
+			key, mcv.Spec.Scope.Name, viewscope.Name))
 
 		mcv.Spec.Scope = viewscope
 		if err := m.Update(context.TODO(), mcv); err != nil {

controllers/util/mw_util.go

@@ -118,9 +118,6 @@ func (mwu *MWUtil) CreateOrUpdateVRGManifestWork(
 	name, namespace, homeCluster string,
 	vrg rmn.VolumeReplicationGroup, annotations map[string]string,
 ) error {
-	mwu.Log.Info(fmt.Sprintf("Create or Update manifestwork %s:%s:%s:%+v",
-		name, namespace, homeCluster, vrg))
-
 	manifestWork, err := mwu.generateVRGManifestWork(name, namespace, homeCluster, vrg, annotations)
 	if err != nil {
 		return err
@@ -157,8 +154,6 @@ func (mwu *MWUtil) CreateOrUpdateMModeManifestWork(
 	name, cluster string,
 	mMode rmn.MaintenanceMode, annotations map[string]string,
 ) error {
-	mwu.Log.Info(fmt.Sprintf("Create or Update manifestwork %s:%s:%+v", name, cluster, mMode))
-
 	manifestWork, err := mwu.generateMModeManifestWork(name, cluster, mMode, annotations)
 	if err != nil {
 		return err
@@ -238,9 +233,6 @@ func (mwu *MWUtil) CreateOrUpdateNFManifestWork(
 	name, namespace, homeCluster string,
 	nf csiaddonsv1alpha1.NetworkFence, annotations map[string]string,
 ) error {
-	mwu.Log.Info(fmt.Sprintf("Create or Update manifestwork %s:%s:%s:%+v",
-		name, namespace, homeCluster, nf))
-
 	manifestWork, err := mwu.generateNFManifestWork(name, namespace, homeCluster, nf, annotations)
 	if err != nil {
 		return err

controllers/volumereplicationgroup_controller.go

@@ -1038,8 +1038,8 @@ func (v *VRGInstance) updateVRGStatus(result ctrl.Result) ctrl.Result {
 	if !reflect.DeepEqual(v.savedInstanceStatus, v.instance.Status) {
 		v.instance.Status.LastUpdateTime = metav1.Now()
 		if err := v.reconciler.Status().Update(v.ctx, v.instance); err != nil {
-			v.log.Info(fmt.Sprintf("Failed to update VRG status (%v/%+v)",
-				err, v.instance.Status))
+			v.log.Info(fmt.Sprintf("Failed to update VRG status (%v/%s)",
+				err, v.instance.Name))
 
 			result.Requeue = true
 

controllers/vrg_recipe.go

@@ -119,7 +119,7 @@ func RecipeParametersExpand(recipe *recipe.Recipe, parameters map[string][]strin
 
 	bytes, err := json.Marshal(*spec)
 	if err != nil {
-		return fmt.Errorf("recipe spec %+v json marshal error: %w", *spec, err)
+		return fmt.Errorf("recipe %s json marshal error: %w", recipe.GetName(), err)
 	}
 
 	s1 := string(bytes)

docs/logging.md

@@ -0,0 +1,101 @@
+# Logging
+
+This document outlines the logging standards and best practices for Ramen.
+
+## General Principles
+
+1. **Consistency**: All controllers should follow the same logging conventions.
+1. **Performance Awareness**: Logging should not significantly impact the
+   performance. Be mindful of the logging levels and the amount of data logged.
+
+## Logger Configuration
+
+- Each controller should create its logger instance with a name specific to the
+  controller for easy identification. For example, if the controller is named
+  `ProtectedVolumeReplicationGroupList`, the logger name could be a shortened
+  form of the controller like `pvrgl`.
+
+  ```go
+  logger := ctrl.Log.WithName("pvrgl")
+  ```
+
+- Loggers should be enriched with key contextual information to make the logs
+  more informative. This includes:
+    - The name of the custom resource.
+    - Then namespace of the custom resource, if applicable.
+    - The UID of the custom resource.
+    - The version of the custom resource.
+
+  ```go
+  logger = logger.WithValues("name", req.NamespacedName.Name, "rid", instance.ObjectMeta.UID, "version", instance.ObjectMeta.ResourceVersion)
+  ```
+
+- The context passed to functions should be augmented with the logger instance:
+
+  ```go
+  ctx = ctrl.LoggerInto(ctx, logger)
+  ```
+
+  This will be useful when we call functions that are outside of the controller
+  scope and the instance.log object is not available to them.
+
+## Log Messages
+
+- Log messages should be concise yet informative. Wherever possible, use
+  structured logging to provide context.
+
+- Start and end of significant operations, like reconciliation, should be logged:
+
+  ```go
+  logger.Info("reconcile start")
+  defer logger.Info("reconcile end", "time spent", time.Since(start))
+  ```
+
+- When logging errors, include the context of the error:
+
+  ```go
+  logger.Error(err, "Error description", "key", "value")
+  ```
+
+- Use key-value pairs instead of concatenating the message and data.
+
+    For example, avoid logging like this:
+
+    ```go
+    log.Info(fmt.Sprintf("Requeuing after %v", duration))
+    ```
+
+    This approach logs everything as one string, making it harder to parse and filter.
+
+    Log additional information as key-value pairs. This method ensures that
+    each piece of information is logged as a separate field, making it easier
+    to search and analyze.
+
+    Example of a well-structured log message:
+
+    ```go
+    s.log.Info("reconcile end", "time spent", time.Since(start))
+    ```
+
+    This will log in the following format, providing clear and structured context:
+
+    ```
+    2024-01-31T14:27:12.726-0500  INFO    pvrgl   reconcile end   {"name": "protectedvrglist-0", "rid": "1e09b0fb-687b-4100-9ab1-a52ba899b37b", "rv": "322", "time spent": 6ms}
+    ```
+
+## Debugging with Logs
+
+The structured logs help debugging. Here's how you can effectively use the logs
+for debugging purposes:
+
+### Filtering Logs for a Specific Resource
+
+To focus on logs related to a specific resource, you can use `grep` with a
+pattern that matches the resource's unique identifiers. For example:
+
+```
+grep -e 'pvrgl.*4db288b5-3f03-441c-bc44-00e356e77f62'
+```
+
+This command filters logs to show entries for the resource with UID
+`4db288b5-3f03-441c-bc44-00e356e77f62`.