Improved error logs

Author: kolluria

pkg/syncer/cnsoperator/controller/cnsunregistervolume/controller.go

@@ -47,8 +47,8 @@ import (
 	"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/logger"
 	k8s "sigs.k8s.io/vsphere-csi-driver/v3/pkg/kubernetes"
 	"sigs.k8s.io/vsphere-csi-driver/v3/pkg/syncer"
-	"sigs.k8s.io/vsphere-csi-driver/v3/pkg/syncer/cnsoperator/util"
 	cnsoptypes "sigs.k8s.io/vsphere-csi-driver/v3/pkg/syncer/cnsoperator/types"
+	"sigs.k8s.io/vsphere-csi-driver/v3/pkg/syncer/cnsoperator/util"
 )
 
 const (
@@ -196,6 +196,9 @@ func (r *Reconciler) Reconcile(ctx context.Context,
 		log.Info("finished reconciling instance")
 	}()
 
+	backoff := getBackoffDuration(ctx, request.NamespacedName)
+	log.Info("backoff duration is ", backoff)
+
 	// Handle deletion of the instance.
 	// The finalizer will be removed only if the volume is unregistered
 	// or if the input parameters are invalid or if the volume is in use.
@@ -204,14 +207,14 @@ func (r *Reconciler) Reconcile(ctx context.Context,
 		err = r.reconcileDelete(ctx, *instance, request)
 		if err != nil {
 			log.Error("failed to reconcile with error ", err)
-			return reconcile.Result{}, err
+			return reconcile.Result{RequeueAfter: backoff}, nil
 		}
 
 		log.Info("removing finalizer and allowing deletion of the instance")
 		err := removeFinalizer(ctx, r.client, instance)
 		if err != nil {
 			log.Error("failed to remove finalizer from the instance with error ", err)
-			return reconcile.Result{}, err
+			return reconcile.Result{RequeueAfter: backoff}, nil
 		}
 
 		deleteBackoffEntry(ctx, request.NamespacedName)
@@ -229,15 +232,15 @@ func (r *Reconciler) Reconcile(ctx context.Context,
 	if err != nil {
 		log.Error("failed to reconcile with error ", err)
 		setInstanceError(ctx, r, instance, err.Error())
-		return reconcile.Result{RequeueAfter: getBackoffDuration(ctx, request.NamespacedName)}, nil
+		return reconcile.Result{RequeueAfter: backoff}, nil
 	}
 
 	msg := "successfully unregistered the volume"
 	err = setInstanceSuccess(ctx, r, instance, msg)
 	if err != nil {
-		log.Warn("failed to set instance to success with error ", err)
-		setInstanceError(ctx, r, instance, "failed to set instance to success")
-		return reconcile.Result{RequeueAfter: getBackoffDuration(ctx, request.NamespacedName)}, nil
+		log.Warn("failed to update status to success with error ", err)
+		setInstanceError(ctx, r, instance, "failed to update status to success")
+		return reconcile.Result{RequeueAfter: backoff}, nil
 	}
 
 	deleteBackoffEntry(ctx, request.NamespacedName)
@@ -343,43 +346,44 @@ func unregisterVolume(ctx context.Context, volMgr volumes.Manager,
 	k8sClient, err := newK8sClient(ctx)
 	if err != nil {
 		log.Error("failed to init K8s client for volume unregistration with error ", err)
-		return err
+		return errors.New("failed to init K8s client for volume unregistration")
 	}
 
 	err = protectPVC(ctx, k8sClient, params.pvcName, params.namespace,
 		cnsoptypes.CNSUnregisterProtectionFinalizer)
 	if err != nil {
-		log.Error("failed to add finalizer on PVC with error ", err)
-		return errors.New("failed to protect PVC")
+		log.Error("failed to protect associated PVC with error ", err)
+		return fmt.Errorf("failed to protect associated PVC %s/%s", params.namespace, params.pvcName)
 	}
 
 	err = deletePVC(ctx, k8sClient, params.pvcName, params.namespace)
 	if err != nil {
-		log.Error("failed to delete PVC with error ", err)
-		return errors.New("failed to delete PVC")
+		log.Error("failed to delete associated PVC with error ", err)
+		return fmt.Errorf("failed to delete associated PVC %s/%s", params.namespace, params.pvcName)
 	}
 
 	err = deletePV(ctx, k8sClient, params.pvName)
 	if err != nil {
-		log.Error("failed to delete PV with error ", err)
-		return errors.New("failed to delete PV")
+		log.Error("failed to delete associated PV with error ", err)
+		return fmt.Errorf("failed to delete associated PV %s", params.pvName)
 	}
 
 	unregDisk := !params.retainFCD // If retainFCD is false, unregister the FCD too.
 	err = volMgr.UnregisterVolume(ctx, params.volumeID, unregDisk)
 	if err != nil {
-		log.Error("failed to unregister volume with error ", err)
-		return errors.New("failed to unregister volume")
+		log.Error("failed to unregister associated volume with error ", err)
+		return fmt.Errorf("failed to unregister associated volume %s", params.volumeID)
 	}
 
 	err = removeFinalizerFromPVC(ctx, k8sClient, params.pvcName, params.namespace,
 		cnsoptypes.CNSUnregisterProtectionFinalizer)
 	if err != nil {
-		log.Error("failed to remove finalizer from PVC with error ", err)
-		return errors.New("failed to remove finalizer from PVC")
+		log.Error("failed to remove finalizer from associated PVC with error ", err)
+		return fmt.Errorf("failed to remove finalizer from associated PVC %s/%s",
+			params.namespace, params.pvcName)
 	}
 
-	log.Infof("successfully unregistered CNS volume %s", params.volumeID)
+	log.Debug("successfully unregistered CNS volume ", params.volumeID)
 	return nil
 }
 
@@ -422,17 +426,12 @@ func recordEvent(ctx context.Context, r *Reconciler,
 	switch eventtype {
 	case v1.EventTypeWarning:
 		// Double backOff duration.
-		backOffDurationMapMutex.Lock()
-		backOffDuration[namespacedName] = min(backOffDuration[namespacedName]*2,
-			cnsoptypes.MaxBackOffDurationForReconciler)
+		doubleBackoffDuration(ctx, namespacedName)
 		r.recorder.Event(instance, v1.EventTypeWarning, "CnsUnregisterVolumeFailed", msg)
-		backOffDurationMapMutex.Unlock()
 	case v1.EventTypeNormal:
 		// Reset backOff duration to one second.
-		backOffDurationMapMutex.Lock()
-		backOffDuration[namespacedName] = time.Second
+		updateBackoffEntry(ctx, namespacedName, time.Second)
 		r.recorder.Event(instance, v1.EventTypeNormal, "CnsUnregisterVolumeSucceeded", msg)
-		backOffDurationMapMutex.Unlock()
 	}
 }
 
@@ -494,18 +493,27 @@ func _getValidatedParams(ctx context.Context, instance v1a1.CnsUnregisterVolume)
 }
 
 func getBackoffDuration(ctx context.Context, name types.NamespacedName) time.Duration {
-	log := logger.GetLogger(ctx).With("name", name)
 	backOffDurationMapMutex.Lock()
 	defer backOffDurationMapMutex.Unlock()
 	if _, exists := backOffDuration[name]; !exists {
-		log.Debug("initializing backoff duration to 1 second")
 		backOffDuration[name] = time.Second
 	}
 
-	log.Infof("backoff duration is %s", backOffDuration[name])
 	return backOffDuration[name]
 }
 
+func doubleBackoffDuration(ctx context.Context, name types.NamespacedName) {
+	d := getBackoffDuration(ctx, name)
+	d = min(d*2, cnsoptypes.MaxBackOffDurationForReconciler)
+	updateBackoffEntry(ctx, name, d)
+}
+
+func updateBackoffEntry(ctx context.Context, name types.NamespacedName, duration time.Duration) {
+	backOffDurationMapMutex.Lock()
+	defer backOffDurationMapMutex.Unlock()
+	backOffDuration[name] = duration
+}
+
 func deleteBackoffEntry(ctx context.Context, name types.NamespacedName) {
 	backOffDurationMapMutex.Lock()
 	defer backOffDurationMapMutex.Unlock()