Enhance logging and error handling in VolumeSnapshotContent deletion process

Signed-off-by: Priyansh Choudhary <im1706@gmail.com>

internal/delete/actions/csi/volumesnapshotcontent_action.go

@@ -71,7 +71,7 @@ func (p *volumeSnapshotContentDeleteItemAction) Execute(
 	// So skip deleting VolumeSnapshotContent not have the backup name
 	// in its labels.
 	if !kubeutil.HasBackupLabel(&snapCont.ObjectMeta, input.Backup.Name) {
-		p.log.Info(
+		p.log.Infof(
 			"VolumeSnapshotContent %s was not taken by backup %s, skipping deletion",
 			snapCont.Name,
 			input.Backup.Name,
@@ -125,6 +125,7 @@ func (p *volumeSnapshotContentDeleteItemAction) Execute(
 	if err := p.crClient.Create(context.TODO(), &snapCont); err != nil {
 		return errors.Wrapf(err, "fail to create VolumeSnapshotContent %s", snapCont.Name)
 	}
+	p.log.Infof("Created temp VolumeSnapshotContent %s with DeletionPolicy=Delete to trigger cloud snapshot cleanup", snapCont.Name)
 
 	// Read resource timeout from backup annotation, if not set, use default value.
 	timeout, err := time.ParseDuration(
@@ -149,20 +150,23 @@ func (p *volumeSnapshotContentDeleteItemAction) Execute(
 		},
 	); err != nil {
 		// Clean up the VSC we created since it can't become ready
+		p.log.WithError(err).Warnf("Temp VolumeSnapshotContent %s did not become ready, cleaning up", snapCont.Name)
 		if deleteErr := p.crClient.Delete(context.TODO(), &snapCont); deleteErr != nil && !apierrors.IsNotFound(deleteErr) {
-			p.log.WithError(deleteErr).Errorf("Failed to clean up VolumeSnapshotContent %s", snapCont.Name)
+			p.log.WithError(deleteErr).Errorf("Failed to clean up temp VolumeSnapshotContent %s", snapCont.Name)
 		}
 		return errors.Wrapf(err, "fail to wait VolumeSnapshotContent %s becomes ready.", snapCont.Name)
 	}
 
+	p.log.Infof("Temp VolumeSnapshotContent %s is ready, deleting to trigger cloud snapshot removal", snapCont.Name)
 	if err := p.crClient.Delete(
 		context.TODO(),
 		&snapCont,
 	); err != nil && !apierrors.IsNotFound(err) {
-		p.log.Infof("VolumeSnapshotContent %s not found", snapCont.Name)
+		p.log.WithError(err).Errorf("Failed to delete temp VolumeSnapshotContent %s", snapCont.Name)
 		return err
 	}
 
+	p.log.Infof("Successfully triggered deletion of VolumeSnapshotContent %s and its cloud snapshot", snapCont.Name)
 	return nil
 }
 
@@ -180,7 +184,7 @@ func (p *volumeSnapshotContentDeleteItemAction) tryDeleteOriginalVSC(
 		if apierrors.IsNotFound(err) {
 			p.log.Debugf("Original VolumeSnapshotContent %s not found in cluster, will use temp VSC flow", vscName)
 		} else {
-			p.log.Debugf("Error looking up original VolumeSnapshotContent %s, will use temp VSC flow", vscName)
+			p.log.WithError(err).Warnf("Error looking up original VolumeSnapshotContent %s, will use temp VSC flow", vscName)
 		}
 		return false
 	}
@@ -192,7 +196,7 @@ func (p *volumeSnapshotContentDeleteItemAction) tryDeleteOriginalVSC(
 		original := existing.DeepCopy()
 		existing.Spec.DeletionPolicy = snapshotv1api.VolumeSnapshotContentDelete
 		if err := p.crClient.Patch(ctx, existing, crclient.MergeFrom(original)); err != nil {
-			p.log.WithError(err).Debugf("Failed to patch DeletionPolicy on original VSC %s, will use temp VSC flow", vscName)
+			p.log.WithError(err).Warnf("Failed to patch DeletionPolicy on original VSC %s, will use temp VSC flow", vscName)
 			return false
 		}
 		p.log.Debugf("Patched DeletionPolicy to Delete on original VolumeSnapshotContent %s", vscName)
@@ -200,10 +204,11 @@ func (p *volumeSnapshotContentDeleteItemAction) tryDeleteOriginalVSC(
 
 	// Delete the original VSC — the CSI driver will clean up the cloud snapshot
 	if err := p.crClient.Delete(ctx, existing); err != nil && !apierrors.IsNotFound(err) {
-		p.log.WithError(err).Debugf("Failed to delete original VolumeSnapshotContent %s, will use temp VSC flow", vscName)
+		p.log.WithError(err).Warnf("Failed to delete original VolumeSnapshotContent %s, will use temp VSC flow", vscName)
 		return false
 	}
 
+	p.log.Infof("Deleted original VolumeSnapshotContent %s with DeletionPolicy=Delete, CSI driver will remove cloud snapshot", vscName)
 	return true
 }
 

internal/delete/actions/csi/volumesnapshotcontent_action_test.go

@@ -39,14 +39,44 @@ import (
 	velerotest "github.com/vmware-tanzu/velero/pkg/test"
 )
 
+// fakeClientWithErrors wraps a real client and injects errors for specific operations.
+type fakeClientWithErrors struct {
+	crclient.Client
+	getError    error
+	patchError  error
+	deleteError error
+}
+
+func (c *fakeClientWithErrors) Get(ctx context.Context, key crclient.ObjectKey, obj crclient.Object, opts ...crclient.GetOption) error {
+	if c.getError != nil {
+		return c.getError
+	}
+	return c.Client.Get(ctx, key, obj, opts...)
+}
+
+func (c *fakeClientWithErrors) Patch(ctx context.Context, obj crclient.Object, patch crclient.Patch, opts ...crclient.PatchOption) error {
+	if c.patchError != nil {
+		return c.patchError
+	}
+	return c.Client.Patch(ctx, obj, patch, opts...)
+}
+
+func (c *fakeClientWithErrors) Delete(ctx context.Context, obj crclient.Object, opts ...crclient.DeleteOption) error {
+	if c.deleteError != nil {
+		return c.deleteError
+	}
+	return c.Client.Delete(ctx, obj, opts...)
+}
+
 func TestVSCExecute(t *testing.T) {
 	snapshotHandleStr := "test"
 	tests := []struct {
-		name     string
-		item     runtime.Unstructured
-		vsc      *snapshotv1api.VolumeSnapshotContent
-		backup   *velerov1api.Backup
-		function func(
+		name           string
+		item           runtime.Unstructured
+		vsc            *snapshotv1api.VolumeSnapshotContent
+		backup         *velerov1api.Backup
+		preExistingVSC *snapshotv1api.VolumeSnapshotContent
+		function       func(
 			ctx context.Context,
 			vsc *snapshotv1api.VolumeSnapshotContent,
 			client crclient.Client,
@@ -96,6 +126,21 @@ func TestVSCExecute(t *testing.T) {
 				return false, errors.Errorf("test error case")
 			},
 		},
+		{
+			name:      "Original VSC exists in cluster, cleaned up directly",
+			vsc:       builder.ForVolumeSnapshotContent("bar").ObjectMeta(builder.WithLabelsMap(map[string]string{velerov1api.BackupNameLabel: "backup"})).Status(&snapshotv1api.VolumeSnapshotContentStatus{SnapshotHandle: &snapshotHandleStr}).Result(),
+			backup:    builder.ForBackup("velero", "backup").Result(),
+			expectErr: false,
+			preExistingVSC: &snapshotv1api.VolumeSnapshotContent{
+				ObjectMeta: metav1.ObjectMeta{Name: "bar"},
+				Spec: snapshotv1api.VolumeSnapshotContentSpec{
+					DeletionPolicy:    snapshotv1api.VolumeSnapshotContentRetain,
+					Driver:            "disk.csi.azure.com",
+					Source:            snapshotv1api.VolumeSnapshotContentSource{SnapshotHandle: stringPtr("snap-123")},
+					VolumeSnapshotRef: corev1api.ObjectReference{Name: "vs-1", Namespace: "default"},
+				},
+			},
+		},
 		{
 			name:      "Error case with CSI error, dangling VSC should be cleaned up",
 			vsc:       builder.ForVolumeSnapshotContent("bar").ObjectMeta(builder.WithLabelsMap(map[string]string{velerov1api.BackupNameLabel: "backup"})).Status(&snapshotv1api.VolumeSnapshotContentStatus{SnapshotHandle: &snapshotHandleStr}).Result(),
@@ -117,6 +162,10 @@ func TestVSCExecute(t *testing.T) {
 			logger := logrus.StandardLogger()
 			checkVSCReadiness = test.function
 
+			if test.preExistingVSC != nil {
+				require.NoError(t, crClient.Create(t.Context(), test.preExistingVSC))
+			}
+
 			p := volumeSnapshotContentDeleteItemAction{log: logger, crClient: crClient}
 
 			if test.vsc != nil {
@@ -321,6 +370,67 @@ func TestTryDeleteOriginalVSC(t *testing.T) {
 			}
 		})
 	}
+
+	// Error injection tests for tryDeleteOriginalVSC
+	t.Run("Get returns non-NotFound error, returns false", func(t *testing.T) {
+		errClient := &fakeClientWithErrors{
+			Client:   velerotest.NewFakeControllerRuntimeClient(t),
+			getError: fmt.Errorf("connection refused"),
+		}
+		p := &volumeSnapshotContentDeleteItemAction{
+			log:      logrus.StandardLogger(),
+			crClient: errClient,
+		}
+		require.False(t, p.tryDeleteOriginalVSC(t.Context(), "some-vsc"))
+	})
+
+	t.Run("Patch fails, returns false", func(t *testing.T) {
+		realClient := velerotest.NewFakeControllerRuntimeClient(t)
+		vsc := &snapshotv1api.VolumeSnapshotContent{
+			ObjectMeta: metav1.ObjectMeta{Name: "patch-fail-vsc"},
+			Spec: snapshotv1api.VolumeSnapshotContentSpec{
+				DeletionPolicy:    snapshotv1api.VolumeSnapshotContentRetain,
+				Driver:            "disk.csi.azure.com",
+				Source:            snapshotv1api.VolumeSnapshotContentSource{SnapshotHandle: stringPtr("snap-789")},
+				VolumeSnapshotRef: corev1api.ObjectReference{Name: "vs-3", Namespace: "default"},
+			},
+		}
+		require.NoError(t, realClient.Create(t.Context(), vsc))
+
+		errClient := &fakeClientWithErrors{
+			Client:     realClient,
+			patchError: fmt.Errorf("patch forbidden"),
+		}
+		p := &volumeSnapshotContentDeleteItemAction{
+			log:      logrus.StandardLogger(),
+			crClient: errClient,
+		}
+		require.False(t, p.tryDeleteOriginalVSC(t.Context(), "patch-fail-vsc"))
+	})
+
+	t.Run("Delete fails, returns false", func(t *testing.T) {
+		realClient := velerotest.NewFakeControllerRuntimeClient(t)
+		vsc := &snapshotv1api.VolumeSnapshotContent{
+			ObjectMeta: metav1.ObjectMeta{Name: "delete-fail-vsc"},
+			Spec: snapshotv1api.VolumeSnapshotContentSpec{
+				DeletionPolicy:    snapshotv1api.VolumeSnapshotContentDelete,
+				Driver:            "disk.csi.azure.com",
+				Source:            snapshotv1api.VolumeSnapshotContentSource{SnapshotHandle: stringPtr("snap-999")},
+				VolumeSnapshotRef: corev1api.ObjectReference{Name: "vs-4", Namespace: "default"},
+			},
+		}
+		require.NoError(t, realClient.Create(t.Context(), vsc))
+
+		errClient := &fakeClientWithErrors{
+			Client:      realClient,
+			deleteError: fmt.Errorf("delete forbidden"),
+		}
+		p := &volumeSnapshotContentDeleteItemAction{
+			log:      logrus.StandardLogger(),
+			crClient: errClient,
+		}
+		require.False(t, p.tryDeleteOriginalVSC(t.Context(), "delete-fail-vsc"))
+	})
 }
 
 func boolPtr(b bool) *bool {