Backup stuck at WaitingForPluginOperations when using CSI & DataMover

[Siradjedd]

What steps did you take and what happened:

i am trying to backup the k8s volumes (longhorn as provider) into minio buckets but the backup job is stuck at WaitingForPluginOperations

What did you expect to happen:
Velero takes volumes backups and store them in minio

The following information will help us better understand what's going on:
velero-values.yaml:

initContainers:
  - name: velero-plugin-for-aws
    image: velero/velero-plugin-for-aws:v1.10.0
    imagePullPolicy: IfNotPresent
    volumeMounts:
      - mountPath: /target
        name: plugins
backupStorageLocation:
  - name: minio
    provider: aws
    bucket: velerobackup
    caCert: <ca.crt>
    prefix: velero
    default:
    accessMode: ReadWrite
    credential:
      name: velero
      key: cloud
    config: 
      region: eu-west-2
      s3ForcePathStyle: true
      s3Url: https://minio.labadeiz.svc.cluster.local:443
defaultBackupStorageLocation: minio
defaultSnapshotMoveData: true
  features: EnableCSI
backupsEnabled: true
snapshotsEnabled: false 
credentials:
  secretContents: 
   cloud: |
     [default]
     aws_access_key_id=<id>
     aws_secret_access_key=<key>

long-volumesnapshotclass:

kind: VolumeSnapshotClass
apiVersion: snapshot.storage.k8s.io/v1
metadata:
  name: longhorn-snapshot-vsc
  labels:
    velero.io/csi-volumesnapshot-class: "true"
driver: driver.longhorn.io
deletionPolicy: Delete
parameters:
  type: snap

Environment:

• Velero version (use velero version): 1.15.0

logs.gz in the minio bucket :

time="2025-01-05T17:23:52Z" level=info msg="Additional Item volumesnapshotcontents.snapshot.storage.k8s.io /snapcontent-9c0bd7fc-ff74-425b-8a61-f06c460389a5 not found in ItemBlock, getting from cluster" backup=velero/csi-b1 logSource="pkg/backup/item_backupper.go:458" name=velero-nginx-pvc-glvtg namespace=nginx resource=volumesnapshots.snapshot.storage.k8s.io
time="2025-01-05T17:23:52Z" level=info msg="Skipping the exclusion checks for this resource" backup=velero/csi-b1 logSource="pkg/backup/item_backupper.go:112" name=snapcontent-9c0bd7fc-ff74-425b-8a61-f06c460389a5 namespace= resource=volumesnapshotcontents.snapshot.storage.k8s.io
time="2025-01-05T17:23:52Z" level=info msg="Backing up item" backup=velero/csi-b1 logSource="pkg/backup/item_backupper.go:184" name=snapcontent-9c0bd7fc-ff74-425b-8a61-f06c460389a5 namespace= resource=volumesnapshotcontents.snapshot.storage.k8s.io
time="2025-01-05T17:23:52Z" level=info msg="Executing custom action" backup=velero/csi-b1 logSource="pkg/backup/item_backupper.go:357" name=snapcontent-9c0bd7fc-ff74-425b-8a61-f06c460389a5 namespace= resource=volumesnapshotcontents.snapshot.storage.k8s.io
time="2025-01-05T17:23:52Z" level=info msg="Executing VolumeSnapshotContentBackupItemAction" backup=velero/csi-b1 cmd=/velero logSource="pkg/backup/actions/csi/volumesnapshotcontent_action.go:63" pluginName=velero
time="2025-01-05T17:23:52Z" level=info msg="Returning from VolumeSnapshotContentBackupItemAction%!(EXTRA string=with %d additionalItems to backup, int=0)" backup=velero/csi-b1 cmd=/velero logSource="pkg/backup/actions/csi/volumesnapshotcontent_action.go:105" pluginName=velero
time="2025-01-05T17:23:52Z" level=info msg="Backed up 16 items out of an estimated total of 16 (estimate will change throughout the backup)" backup=velero/csi-b1 logSource="pkg/backup/backup.go:499" name=velero-nginx-pvc-glvtg namespace=nginx progress= resource=volumesnapshots.snapshot.storage.k8s.io
time="2025-01-05T17:23:52Z" level=info msg="Skipping resource customresourcedefinitions.apiextensions.k8s.io, because it's cluster-scoped and only specific namespaces or namespace scope types are included in the backup." backup=velero/csi-b1 logSource="pkg/util/collections/includes_excludes.go:155"
time="2025-01-05T17:23:52Z" level=info msg="Found associated CRD volumesnapshots.snapshot.storage.k8s.io to add to backup" backup=velero/csi-b1 logSource="pkg/backup/backup.go:795"
time="2025-01-05T17:23:52Z" level=info msg="Backing up item" backup=velero/csi-b1 logSource="pkg/backup/item_backupper.go:184" name=volumesnapshots.snapshot.storage.k8s.io namespace= resource=customresourcedefinitions.apiextensions.k8s.io
time="2025-01-05T17:23:52Z" level=info msg="Executing custom action" backup=velero/csi-b1 logSource="pkg/backup/item_backupper.go:357" name=volumesnapshots.snapshot.storage.k8s.io namespace= resource=customresourcedefinitions.apiextensions.k8s.io
time="2025-01-05T17:23:52Z" level=info msg="Executing RemapCRDVersionAction" backup=velero/csi-b1 cmd=/velero logSource="pkg/backup/actions/remap_crd_version_action.go:61" pluginName=velero
time="2025-01-05T17:23:52Z" level=info msg="Exiting RemapCRDVersionAction, the cluster does not support v1beta1 CRD" backup=velero/csi-b1 cmd=/velero logSource="pkg/backup/actions/remap_crd_version_action.go:88" pluginName=velero
time="2025-01-05T17:23:52Z" level=info msg="Summary for skipped PVs: []" backup=velero/csi-b1 logSource="pkg/backup/backup.go:542"
time="2025-01-05T17:23:52Z" level=info msg="Backed up a total of 17 items" backup=velero/csi-b1 logSource="pkg/backup/backup.go:546" progress=
time="2025-01-05T17:23:52Z" level=info msg="backup SnapshotMoveData is set to true, skip VolumeSnapshot resource persistence." backup=velero/csi-b1 logSource="pkg/backup/snapshots.go:46"

the bundle:
bundle-2025-01-05-20-02-17.tar.gz

update: after horus its PartiallyFailed

[blackpiglet]

You need to install the Velero node-agent DaemonSet to make the CSI snapshot data mover functionality works.

From the bundle, I found the DataUploads are not handled, and no node-agent pods were found.

[Siradjedd]

@blackpiglet could you please clarify the difference between CSI Snapshot with datamover enabled and without it ? i am getting confused.
i enabled the datanodeagent but it still fails after 30mins even thought i am just testing on on an nginx pod & pv ? (it takes long time than file).
Here are the logs of the nodeagent:
time="2025-01-06T08:41:57Z" level=warning msg="Some errors happened during waiting for ready snapshot, errors: [Failed to check and update snapshot content: failed to take snapshot of the volume pvc-4b45a3e1-b46d-4556-9faf-7741c659b862: \"rpc error: code = Internal desc = could not backup to s3, missing [AWS_ACCESS_KEY_ID AWS_SECRET_ACCESS_KEY] in the secret\"]" logSource="pkg/util/csi/volume_snapshot.go:103" owner=nginx-backup-monday-wqr6l 2025-01-06T08:41:57Z ERROR Reconciler error {"controller": "dataupload", "controllerGroup": "velero.io", "controllerKind": "DataUpload", "DataUpload": {"name":"nginx-backup-monday-wqr6l","namespace":"velero"}, "namespace": "velero", "name": "nginx-backup-monday-wqr6l", "reconcileID": "6b75ef3b-582a-4bee-94b5-37ad006041d9", "error": "error wait volume snapshot ready: error to get VolumeSnapshot nginx/velero-nginx-pvc-6dh24: client rate limiter Wait returned an error: rate: Wait(n=1) would exceed context deadline", "errorVerbose": "client rate limiter Wait returned an error: rate: Wait(n=1) would exceed context deadline\nerror to get VolumeSnapshot nginx/velero-nginx-pvc-6dh24\ngithub.com/vmware-tanzu/velero/pkg/util/csi.WaitVolumeSnapshotReady.func1\n\t/go/src/github.com/vmware-tanzu/velero/pkg/util/csi/volume_snapshot.go:71\nk8s.io/apimachinery/pkg/util/wait.loopConditionUntilContext.func2\n\t/go/pkg/mod/k8s.io/apimachinery@v0.29.0/pkg/util/wait/loop.go:87\nk8s.io/apimachinery/pkg/util/wait.loopConditionUntilContext\n\t/go/pkg/mod/k8s.io/apimachinery@v0.29.0/pkg/util/wait/loop.go:88\nk8s.io/apimachinery/pkg/util/wait.PollUntilContextTimeout\n\t/go/pkg/mod/k8s.io/apimachinery@v0.29.0/pkg/util/wait/poll.go:48\ngithub.com/vmware-tanzu/velero/pkg/util/csi.WaitVolumeSnapshotReady\n\t/go/src/github.com/vmware-tanzu/velero/pkg/util/csi/volume_snapshot.go:62\ngithub.com/vmware-tanzu/velero/pkg/exposer.(*csiSnapshotExposer).Expose\n\t/go/src/github.com/vmware-tanzu/velero/pkg/exposer/csi_snapshot.go:109\ngithub.com/vmware-tanzu/velero/pkg/controller.(*DataUploadReconciler).Reconcile\n\t/go/src/github.com/vmware-tanzu/velero/pkg/controller/data_upload_controller.go:214\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Reconcile\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.17.2/pkg/internal/controller/controller.go:119\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.17.2/pkg/internal/controller/controller.go:316\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.17.2/pkg/internal/controller/controller.go:266\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func2.2\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.17.2/pkg/internal/controller/controller.go:227\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1695\nerror wait volume snapshot ready\ngithub.com/vmware-tanzu/velero/pkg/exposer.(*csiSnapshotExposer).Expose\n\t/go/src/github.com/vmware-tanzu/velero/pkg/exposer/csi_snapshot.go:111\ngithub.com/vmware-tanzu/velero/pkg/controller.(*DataUploadReconciler).Reconcile\n\t/go/src/github.com/vmware-tanzu/velero/pkg/controller/data_upload_controller.go:214\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Reconcile\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.17.2/pkg/internal/controller/controller.go:119\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.17.2/pkg/internal/controller/controller.go:316\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.17.2/pkg/internal/controller/controller.go:266\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func2.2\n\t/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.17.2/pkg/internal/controller/controller.go:227\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1695"} sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler

volumeinfo.gz.json in minio bucket:
[ { "pvcName":"nginx-pvc", "pvcNamespace":"nginx", "pvName":"pvc-4b45a3e1-b46d-4556-9faf-7741c659b862", "backupMethod":"CSISnapshot", "snapshotDataMoved":true, "preserveLocalSnapshot":false, "skipped":false, "completionTimestamp":"2025-01-06T08:41:57Z", "result":"failed", "csiSnapshotInfo":{ "snapshotHandle":"unknown", "size":0, "driver":"driver.longhorn.io", "vscName":"unknown", "operationID":"unknown", "ReadyToUse":null }, "snapshotDataMovementInfo":{ "dataMover":"velero", "uploaderType":"kopia", "retainedSnapshot":"velero-nginx-pvc-6dh24", "snapshotHandle":"", "operationID":"du-fd4e5e4a-d2ef-43b8-9d83-7b561a93995d.4b45a3e1-b46d-45578fb2f", "size":0, "Phase":"Failed" }, "pvInfo":{ "reclaimPolicy":"Delete", "labels":null } } ]

[Siradjedd]

@blackpiglet i miss configured the aws_id & aws_secret_id. now i fixet it but still stuck at WaitingForPluginOperations.
and the dataupload is also stuck at Accepted and the job is always pending.

data-agent logs:

`logs[labadeiz-longhorn-backup-datamover-lthkx/d6edd1a9-af36-46e9-ad42-c0dc7291b5ed]***************************
time="2025-01-07T08:09:54Z" level=info msg="Completed to collect data mover pod log for labadeiz-longhorn-backup-datamover-lthkx" controller=dataupload dataupload=velero/labadeiz-longhorn-backup-datamover-lthkx logSource="pkg/datapath/micro_service_watcher.go:424"

time="2025-01-07T08:09:54Z" level=info msg="Calling callback on data path pod termination" controller=dataupload data path pod=labadeiz-longhorn-backup-datamover-lthkx dataupload=velero/labadeiz-longhorn-backup-datamover-lthkx logSource="pkg/datapath/micro_service_watcher.go:319"
time="2025-01-07T08:09:54Z" level=info msg="Async fs backup data path completed" dataupload=labadeiz-longhorn-backup-datamover-lthkx logSource="pkg/controller/data_upload_controller.go:408"

time="2025-01-07T08:09:56Z" level=info msg="Data upload completed" dataupload=labadeiz-longhorn-backup-datamover-lthkx logSource="pkg/controller/data_upload_controller.go:442"

time="2025-01-07T08:09:56Z" level=info msg="Complete callback on data path pod termination" controller=dataupload data path pod=labadeiz-longhorn-backup-datamover-lthkx dataupload=velero/labadeiz-longhorn-backup-datamover-lthkx logSource="pkg/datapath/micro_service_watcher.go:331"

time="2025-01-07T08:09:56Z" level=info msg="Reconcile labadeiz-longhorn-backup-datamover-lthkx" controller=dataupload dataupload=velero/labadeiz-longhorn-backup-datamover-lthkx logSource="pkg/controller/data_upload_controller.go:131"

time="2025-01-07T08:09:56Z" level=info msg="Reconcile labadeiz-longhorn-backup-datamover-lthkx" controller=dataupload dataupload=velero/labadeiz-longhorn-backup-datamover-lthkx logSource="pkg/controller/data_upload_controller.go:131"

time="2025-01-07T08:10:15Z" level=info msg="Reconcile labadeiz-longhorn-backup-datamover-96dqv" controller=dataupload dataupload=velero/labadeiz-longhorn-backup-datamover-96dqv logSource="pkg/controller/data_upload_controller.go:131"`

velero-backup-logs.gz:

time="2025-01-06T16:31:54Z" level=info msg="Untrack the PVC labadeiz/data0-myminio-pool-0-0, because it's backed up by CSI BIA." backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/item_backupper.go:407" name=data0-myminio-pool-0-0 namespace=labadeiz resource=persistentvolumeclaims
time="2025-01-06T16:31:54Z" level=info msg="Skipping item because it's already been backed up." backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/item_backupper.go:179" name=data0-myminio-pool-0-0 namespace=labadeiz resource=persistentvolumeclaims
time="2025-01-06T16:31:54Z" level=info msg="Skipping item because it's already been backed up." backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/item_backupper.go:179" name=pvc-0adbf22b-b685-4daf-87f1-0d1e9c13e2e5 namespace= resource=persistentvolumes
time="2025-01-06T16:31:54Z" level=info msg="Backed up 3 items out of an estimated total of 7 (estimate will change throughout the backup)" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/backup.go:499" name=myminio-pool-0-0 namespace=labadeiz progress= resource=pods
time="2025-01-06T16:31:54Z" level=info msg="Processing item" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/backup.go:439" name=labadeiz namespace= progress= resource=namespaces
time="2025-01-06T16:31:54Z" level=info msg="adding namespaces /labadeiz to ItemBlock" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/itemblock.go:63"
time="2025-01-06T16:31:54Z" level=info msg="Backing Up Item Block including namespaces /labadeiz (1 items in block)" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/backup.go:476"
time="2025-01-06T16:31:54Z" level=info msg="Backing up item" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/item_backupper.go:184" name=labadeiz namespace= resource=namespaces
time="2025-01-06T16:31:54Z" level=info msg="Backed up 4 items out of an estimated total of 7 (estimate will change throughout the backup)" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/backup.go:499" name=labadeiz namespace= progress= resource=namespaces
time="2025-01-06T16:31:54Z" level=info msg="Processing item" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/backup.go:439" name=myminio-pool-0 namespace=labadeiz progress= resource=statefulsets.apps
time="2025-01-06T16:31:54Z" level=info msg="adding statefulsets.apps labadeiz/myminio-pool-0 to ItemBlock" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/itemblock.go:63"
time="2025-01-06T16:31:54Z" level=info msg="Backing Up Item Block including statefulsets.apps labadeiz/myminio-pool-0 (1 items in block)" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/backup.go:476"
time="2025-01-06T16:31:54Z" level=info msg="Backing up item" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/item_backupper.go:184" name=myminio-pool-0 namespace=labadeiz resource=statefulsets.apps
time="2025-01-06T16:31:54Z" level=info msg="Backed up 5 items out of an estimated total of 7 (estimate will change throughout the backup)" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/backup.go:499" name=myminio-pool-0 namespace=labadeiz progress= resource=statefulsets.apps
time="2025-01-06T16:31:54Z" level=info msg="Processing item" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/backup.go:439" name=myminio-pool-0-797497599c namespace=labadeiz progress= resource=controllerrevisions.apps
time="2025-01-06T16:31:54Z" level=info msg="adding controllerrevisions.apps labadeiz/myminio-pool-0-797497599c to ItemBlock" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/itemblock.go:63"
time="2025-01-06T16:31:54Z" level=info msg="Backing Up Item Block including controllerrevisions.apps labadeiz/myminio-pool-0-797497599c (1 items in block)" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/backup.go:476"
time="2025-01-06T16:31:54Z" level=info msg="Backing up item" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/item_backupper.go:184" name=myminio-pool-0-797497599c namespace=labadeiz resource=controllerrevisions.apps
time="2025-01-06T16:31:54Z" level=info msg="Backed up 6 items out of an estimated total of 7 (estimate will change throughout the backup)" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/backup.go:499" name=myminio-pool-0-797497599c namespace=labadeiz progress= resource=controllerrevisions.apps
time="2025-01-06T16:31:54Z" level=info msg="Processing item" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/backup.go:439" name=myminio namespace=labadeiz progress= resource=tenants.minio.min.io
time="2025-01-06T16:31:54Z" level=info msg="adding tenants.minio.min.io labadeiz/myminio to ItemBlock" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/itemblock.go:63"
time="2025-01-06T16:31:54Z" level=info msg="Backing Up Item Block including tenants.minio.min.io labadeiz/myminio (1 items in block)" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/backup.go:476"
time="2025-01-06T16:31:54Z" level=info msg="Backing up item" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/item_backupper.go:184" name=myminio namespace=labadeiz resource=tenants.minio.min.io
time="2025-01-06T16:31:54Z" level=info msg="Backed up 7 items out of an estimated total of 7 (estimate will change throughout the backup)" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/backup.go:499" name=myminio namespace=labadeiz progress= resource=tenants.minio.min.io
time="2025-01-06T16:31:54Z" level=info msg="Skipping resource customresourcedefinitions.apiextensions.k8s.io, because it's cluster-scoped and only specific namespaces or namespace scope types are included in the backup." backup=velero/minio-longhorn-backup-datamover logSource="pkg/util/collections/includes_excludes.go:155"
time="2025-01-06T16:31:54Z" level=info msg="Found associated CRD tenants.minio.min.io to add to backup" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/backup.go:795"
time="2025-01-06T16:31:54Z" level=info msg="Backing up item" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/item_backupper.go:184" name=tenants.minio.min.io namespace= resource=customresourcedefinitions.apiextensions.k8s.io
time="2025-01-06T16:31:54Z" level=info msg="Executing custom action" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/item_backupper.go:357" name=tenants.minio.min.io namespace= resource=customresourcedefinitions.apiextensions.k8s.io
time="2025-01-06T16:31:54Z" level=info msg="Executing RemapCRDVersionAction" backup=velero/minio-longhorn-backup-datamover cmd=/velero logSource="pkg/backup/actions/remap_crd_version_action.go:61" pluginName=velero
time="2025-01-06T16:31:54Z" level=info msg="Exiting RemapCRDVersionAction, the cluster does not support v1beta1 CRD" backup=velero/minio-longhorn-backup-datamover cmd=/velero logSource="pkg/backup/actions/remap_crd_version_action.go:88" pluginName=velero
time="2025-01-06T16:31:54Z" level=info msg="Summary for skipped PVs: []" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/backup.go:542"
time="2025-01-06T16:31:54Z" level=info msg="Backed up a total of 8 items" backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/backup.go:546" progress=
time="2025-01-06T16:31:54Z" level=info msg="backup SnapshotMoveData is set to true, skip VolumeSnapshot resource persistence." backup=velero/minio-longhorn-backup-datamover logSource="pkg/backup/snapshots.go:46"

[blackpiglet]

CSI snapshot data movement: https://velero.io/docs/v1.15/csi-snapshot-data-movement/
CSI: https://velero.io/docs/v1.15/csi/

Please refer to these documents for more information.

Could you help collect the debug bundle to investigate?
The command is velero debug.