search

openebs / velero-plugin

Velero plugin for backup/restore of OpenEBS cStor volumes
https://docs.openebs.io
Apache License 2.0
63 stars 32 forks source link

Cannot restore backups of zfs-localpv PVs to encrypted ZFS pools #145

Closed artw closed 3 years ago

artw commented 3 years ago

Can't get velero to restore PV backups from snapshot it creates, please help me debug this.

Backs it up like a champ

$ velero backup create --include-namespaces redis-test redis-test
Backup request "redis-test" submitted successfully.
Run `velero backup describe redis-test` or `velero backup logs redis-test` for more details.

$ velero backup describe redis-test --details
Name:         redis-test
Namespace:    velero
Labels:       velero.io/storage-location=default
Annotations:  velero.io/source-cluster-k8s-gitversion=v1.20.2+k3s1
              velero.io/source-cluster-k8s-major-version=1
              velero.io/source-cluster-k8s-minor-version=20

Phase:  Completed

Errors:    0
Warnings:  0

Namespaces:
  Included:  redis-test
  Excluded:  <none>

Resources:
  Included:        *
  Excluded:        <none>
  Cluster-scoped:  auto

Label selector:  <none>

Storage Location:  default

Velero-Native Snapshot PVs:  auto

TTL:  720h0m0s

Hooks:  <none>

Backup Format Version:  1.1.0

Started:    2021-02-05 10:16:18 +0200 EET
Completed:  2021-02-05 10:16:32 +0200 EET

Expiration:  2021-03-07 10:16:18 +0200 EET

Total items to be backed up:  25
Items backed up:              25

Resource List:
  apps/v1/ControllerRevision:
    - redis-test/redis-745597d796
  apps/v1/StatefulSet:
    - redis-test/redis
  discovery.k8s.io/v1beta1/EndpointSlice:
    - redis-test/redis-qlfmj
    - redis-test/redis-t7hsx
  v1/ConfigMap:
    - redis-test/kube-root-ca.crt
    - redis-test/redis-config
  v1/Endpoints:
    - redis-test/redis
  v1/Event:
    - redis-test/redis-0.1660cbfef6e8b1e3
    - redis-test/redis-0.1660cbff2f156fe0
    - redis-test/redis-0.1660cbff6cd7a348
    - redis-test/redis-0.1660cbff70a70c30
    - redis-test/redis-0.1660cbff77e06f00
    - redis-test/redis-storage-redis-0.1660cbfeb681af2d
    - redis-test/redis-storage-redis-0.1660cbfeba9f91cf
    - redis-test/redis-storage-redis-0.1660cbfebaec74eb
    - redis-test/redis-storage-redis-0.1660cbfece7abbb0
    - redis-test/redis.1660cbfeb6195847
    - redis-test/redis.1660cbfeb89a7981
  v1/Namespace:
    - redis-test
  v1/PersistentVolume:
    - pvc-51791429-c865-4439-8c76-387d335c8cd3
  v1/PersistentVolumeClaim:
    - redis-test/redis-storage-redis-0
  v1/Pod:
    - redis-test/redis-0
  v1/Secret:
    - redis-test/default-token-sv8cj
  v1/Service:
    - redis-test/redis
  v1/ServiceAccount:
    - redis-test/default

Velero-Native Snapshots:
  pvc-51791429-c865-4439-8c76-387d335c8cd3:
    Snapshot ID:        pvc-51791429-c865-4439-8c76-387d335c8cd3..redis-test
    Type:               zfs-localpv
    Availability Zone:
    IOPS:               <N/A>

Backups are really there, and the snapshot is a working one. I even tested it by importing it with zfs recv

$ mcli ls cube/velero-con/backups/redis-test
[2021-02-05 10:16:32 EET]    29B redis-test-csi-volumesnapshotcontents.json.gz
[2021-02-05 10:16:32 EET]    29B redis-test-csi-volumesnapshots.json.gz
[2021-02-05 10:16:32 EET] 3.8KiB redis-test-logs.gz
[2021-02-05 10:16:32 EET]    29B redis-test-podvolumebackups.json.gz
[2021-02-05 10:16:32 EET]   403B redis-test-resource-list.json.gz
[2021-02-05 10:16:32 EET]   240B redis-test-volumesnapshots.json.gz
[2021-02-05 10:16:32 EET]  10KiB redis-test.tar.gz
[2021-02-05 10:16:32 EET] 2.1KiB velero-backup.json
[2021-02-05 10:16:26 EET]  46KiB zfs-pvc-51791429-c865-4439-8c76-387d335c8cd3-redis-test
[2021-02-05 10:16:20 EET]   806B zfs-pvc-51791429-c865-4439-8c76-387d335c8cd3-redis-test.zfsvol

$ mcli cp cube/velero-con/backups/redis-test/zfs-pvc-51791429-c865-4439-8c76-387d335c8cd3-redis-test /tmp/ 
...-8c76-387d335c8cd3-redis-test:  46.20 KiB / 46.20 KiB ┃▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓┃ 1.18 MiB/s 0s
$ file /tmp/zfs-pvc-51791429-c865-4439-8c76-387d335c8cd3-redis-test
/tmp/zfs-pvc-51791429-c865-4439-8c76-387d335c8cd3-redis-test: ZFS shapshot (little-endian machine), version 33554449, type: ZFS, destination GUID: FA 8C 94 12 7F 4D 8D 67, name: 'data/k3s/pv/pvc-51791429-c865-4439-8c76-387d335c8cd3@redis-test'

Now I delete the namespace, wait a bit, make sure that no PV and zfs volume is gone.

$ kubectl delete namespace redis-test
namespace "redis-test" deleted

When I restore it, everything is ok apart from the PV

$ velero restore create --from-backup redis-test
Restore request "redis-test-20210205104711" submitted successfully.
Run `velero restore describe redis-test-20210205104711` or `velero restore logs redis-test-20210205104711` for more details.

$ velero restore describe redis-test-20210205104711                                                                            
Name:         redis-test-20210205104711
Namespace:    velero
Labels:       <none>
Annotations:  <none>

Phase:  PartiallyFailed (run 'velero restore logs redis-test-20210205104711' for more information)

Started:    2021-02-05 10:47:12 +0200 EET
Completed:  2021-02-05 10:47:24 +0200 EET

Errors:
  Velero:     <none>
  Cluster:  error executing PVAction for persistentvolumes/pvc-51791429-c865-4439-8c76-387d335c8cd3: rpc error: code = Unknown desc = zfs: error in restoring pvc-51791429-c865-4439-8c76-387d335c8cd3.redis-test, status:{Failed}
  Namespaces: <none>

Backup:  redis-test

Namespaces:
  Included:  all namespaces found in the backup
  Excluded:  <none>

Resources:
  Included:        *
  Excluded:        nodes, events, events.events.k8s.io, backups.velero.io, restores.velero.io, resticrepositories.velero.io
  Cluster-scoped:  auto

Namespace mappings:  <none>

Label selector:  <none>

Restore PVs:  auto

Judging by the logs, velero downloads the snap successfully, but fails to "CreateVolumeFromSnapshot"

$ velero restore logs redis-test-20210205104711
time="2021-02-05T08:47:12Z" level=info msg="starting restore" logSource="pkg/controller/restore_controller.go:467" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:12Z" level=info msg="Starting restore of backup velero/redis-test" logSource="pkg/restore/restore.go:363" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:12Z" level=info msg="Restoring cluster level resource 'persistentvolumes'" logSource="pkg/restore/restore.go:726" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:12Z" level=info msg="Getting client for /v1, Kind=PersistentVolume" logSource="pkg/restore/restore.go:768" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:12Z" level=info msg="Restoring persistent volume from snapshot." logSource="pkg/restore/restore.go:922" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:12Z" level=info msg="zfs: Initializing velero plugin for ZFS-LocalPV" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/zfs/snapshot/snap.go:36" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:12Z" level=info msg="Reading from {backups/redis-test/zfs-pvc-51791429-c865-4439-8c76-387d335c8cd3-redis-test.zfsvol} with provider{aws} to bucket{velero-con}" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/clouduploader/operation.go:138" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:12Z" level=info msg="successfully read object{backups/redis-test/zfs-pvc-51791429-c865-4439-8c76-387d335c8cd3-redis-test.zfsvol} to {aws}" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/clouduploader/operation.go:146" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:17Z" level=info msg="Client{1} operation completed.. completed count{0}" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/clouduploader/server_utils.go:178" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:22Z" level=error msg="zfs: restore failed vol pvc-51791429-c865-4439-8c76-387d335c8cd3 snap redis-test err: zfs: error in restoring pvc-51791429-c865-4439-8c76-387d335c8cd3.redis-test, status:{Failed}" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/zfs/plugin/restore.go:280" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:22Z" level=info msg="Transfer done.. closing the server" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/clouduploader/server.go:311" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:22Z" level=info msg="successfully restored object{backups/redis-test/zfs-pvc-51791429-c865-4439-8c76-387d335c8cd3-redis-test} from {aws}" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/clouduploader/operation.go:106" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:22Z" level=error msg="zfs: error doRestore returning snap pvc-51791429-c865-4439-8c76-387d335c8cd3..redis-test err zfs: error in restoring pvc-51791429-c865-4439-8c76-387d335c8cd3.redis-test, status:{Failed}" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/zfs/plugin/restore.go:359" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:22Z" level=error msg="zfs: error CreateVolumeFromSnapshot returning snap pvc-51791429-c865-4439-8c76-387d335c8cd3..redis-test err zfs: error in restoring pvc-51791429-c865-4439-8c76-387d335c8cd3.redis-test, status:{Failed}" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/zfs/plugin/zfs.go:133" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Restoring resource 'persistentvolumeclaims' into namespace 'redis-test'" logSource="pkg/restore/restore.go:724" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Getting client for /v1, Kind=PersistentVolumeClaim" logSource="pkg/restore/restore.go:768" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Executing item action for persistentvolumeclaims" logSource="pkg/restore/restore.go:1002" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Executing AddPVFromPVCAction" cmd=/velero logSource="pkg/restore/add_pv_from_pvc_action.go:44" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Adding PV pvc-51791429-c865-4439-8c76-387d335c8cd3 as an additional item to restore" cmd=/velero logSource="pkg/restore/add_pv_from_pvc_action.go:66" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Skipping persistentvolumes/pvc-51791429-c865-4439-8c76-387d335c8cd3 because it's already been restored." logSource="pkg/restore/restore.go:866" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Executing item action for persistentvolumeclaims" logSource="pkg/restore/restore.go:1002" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Executing ChangePVCNodeSelectorAction" cmd=/velero logSource="pkg/restore/change_pvc_node_selector.go:65" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Done executing ChangePVCNodeSelectorAction" cmd=/velero logSource="pkg/restore/change_pvc_node_selector.go:128" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Executing item action for persistentvolumeclaims" logSource="pkg/restore/restore.go:1002" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Executing ChangeStorageClassAction" cmd=/velero logSource="pkg/restore/change_storageclass_action.go:65" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Done executing ChangeStorageClassAction" cmd=/velero logSource="pkg/restore/change_storageclass_action.go:76" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Attempting to restore PersistentVolumeClaim: redis-storage-redis-0" logSource="pkg/restore/restore.go:1107" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Restoring resource 'secrets' into namespace 'redis-test'" logSource="pkg/restore/restore.go:724" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Getting client for /v1, Kind=Secret" logSource="pkg/restore/restore.go:768" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Attempting to restore Secret: default-token-sv8cj" logSource="pkg/restore/restore.go:1107" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Restoring resource 'configmaps' into namespace 'redis-test'" logSource="pkg/restore/restore.go:724" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Getting client for /v1, Kind=ConfigMap" logSource="pkg/restore/restore.go:768" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Attempting to restore ConfigMap: kube-root-ca.crt" logSource="pkg/restore/restore.go:1107" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Restore of ConfigMap, kube-root-ca.crt skipped: it already exists in the cluster and is the same as the backed up version" logSource="pkg/restore/restore.go:1164" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Attempting to restore ConfigMap: redis-config" logSource="pkg/restore/restore.go:1107" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Restoring resource 'serviceaccounts' into namespace 'redis-test'" logSource="pkg/restore/restore.go:724" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Getting client for /v1, Kind=ServiceAccount" logSource="pkg/restore/restore.go:768" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Executing item action for serviceaccounts" logSource="pkg/restore/restore.go:1002" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Executing ServiceAccountAction" cmd=/velero logSource="pkg/restore/service_account_action.go:47" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Done executing ServiceAccountAction" cmd=/velero logSource="pkg/restore/service_account_action.go:78" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Attempting to restore ServiceAccount: default" logSource="pkg/restore/restore.go:1107" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Restoring resource 'pods' into namespace 'redis-test'" logSource="pkg/restore/restore.go:724" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Getting client for /v1, Kind=Pod" logSource="pkg/restore/restore.go:768" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Executing item action for pods" logSource="pkg/restore/restore.go:1002" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Executing AddPVCFromPodAction" cmd=/velero logSource="pkg/restore/add_pvc_from_pod_action.go:44" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Adding PVC redis-test/redis-storage-redis-0 as an additional item to restore" cmd=/velero logSource="pkg/restore/add_pvc_from_pod_action.go:58" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Skipping persistentvolumeclaims/redis-test/redis-storage-redis-0 because it's already been restored." logSource="pkg/restore/restore.go:866" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Executing item action for pods" logSource="pkg/restore/restore.go:1002" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Executing InitRestoreHookPodAction" cmd=/velero logSource="pkg/restore/init_restorehook_pod_action.go:49" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Pod redis-test/redis-0 has no init.hook.restore.velero.io/container-image annotation, no initRestoreHook in annotation" cmd=/velero logSource="internal/hook/item_hook_handler.go:350" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Handling InitRestoreHooks from RestoreSpec" cmd=/velero logSource="internal/hook/item_hook_handler.go:138" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Returning pod redis-test/redis-0 with 0 init container(s)" cmd=/velero logSource="internal/hook/item_hook_handler.go:157" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Executing item action for pods" logSource="pkg/restore/restore.go:1002" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Returning from InitRestoreHookPodAction" cmd=/velero logSource="pkg/restore/init_restorehook_pod_action.go:57" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Executing item action for pods" logSource="pkg/restore/restore.go:1002" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Executing ResticRestoreAction" cmd=/velero logSource="pkg/restore/restic_restore_action.go:71" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Done executing ResticRestoreAction" cmd=/velero logSource="pkg/restore/restic_restore_action.go:94" pluginName=velero restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Attempting to restore Pod: redis-0" logSource="pkg/restore/restore.go:1107" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Restoring resource 'controllerrevisions.apps' into namespace 'redis-test'" logSource="pkg/restore/restore.go:724" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Getting client for apps/v1, Kind=ControllerRevision" logSource="pkg/restore/restore.go:768" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Attempting to restore ControllerRevision: redis-745597d796" logSource="pkg/restore/restore.go:1107" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Restoring resource 'endpoints' into namespace 'redis-test'" logSource="pkg/restore/restore.go:724" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Getting client for /v1, Kind=Endpoints" logSource="pkg/restore/restore.go:768" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Attempting to restore Endpoints: redis" logSource="pkg/restore/restore.go:1107" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Restoring resource 'endpointslices.discovery.k8s.io' into namespace 'redis-test'" logSource="pkg/restore/restore.go:724" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Getting client for discovery.k8s.io/v1beta1, Kind=EndpointSlice" logSource="pkg/restore/restore.go:768" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Attempting to restore EndpointSlice: redis-qlfmj" logSource="pkg/restore/restore.go:1107" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Attempting to restore EndpointSlice: redis-t7hsx" logSource="pkg/restore/restore.go:1107" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Skipping restore of resource because the restore spec excludes it" logSource="pkg/restore/restore.go:416" resource=events restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Restoring resource 'services' into namespace 'redis-test'" logSource="pkg/restore/restore.go:724" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Getting client for /v1, Kind=Service" logSource="pkg/restore/restore.go:768" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Executing item action for services" logSource="pkg/restore/restore.go:1002" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Attempting to restore Service: redis" logSource="pkg/restore/restore.go:1107" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Restoring resource 'statefulsets.apps' into namespace 'redis-test'" logSource="pkg/restore/restore.go:724" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Getting client for apps/v1, Kind=StatefulSet" logSource="pkg/restore/restore.go:768" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Attempting to restore StatefulSet: redis" logSource="pkg/restore/restore.go:1107" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Waiting for all restic restores to complete" logSource="pkg/restore/restore.go:488" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Done waiting for all restic restores to complete" logSource="pkg/restore/restore.go:504" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Waiting for all post-restore-exec hooks to complete" logSource="pkg/restore/restore.go:508" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="Done waiting for all post-restore exec hooks to complete" logSource="pkg/restore/restore.go:516" restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:23Z" level=info msg="restore completed" logSource="pkg/controller/restore_controller.go:482" restore=velero/redis-test-20210205104711

$ kubectl logs -n velero velero-6d56d7bc6-zlcx8 | grep -B 3 error
--
time="2021-02-05T08:47:12Z" level=info msg="Reading from {backups/redis-test/zfs-pvc-51791429-c865-4439-8c76-387d335c8cd3-redis-test.zfsvol} with provider{aws} to bucket{velero-con}" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/clouduploader/operation.go:138" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:12Z" level=info msg="successfully read object{backups/redis-test/zfs-pvc-51791429-c865-4439-8c76-387d335c8cd3-redis-test.zfsvol} to {aws}" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/clouduploader/operation.go:146" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:17Z" level=info msg="Client{1} operation completed.. completed count{0}" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/clouduploader/server_utils.go:178" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:22Z" level=error msg="zfs: restore failed vol pvc-51791429-c865-4439-8c76-387d335c8cd3 snap redis-test err: zfs: error in restoring pvc-51791429-c865-4439-8c76-387d335c8cd3.redis-test, status:{Failed}" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/zfs/plugin/restore.go:280" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:22Z" level=info msg="Transfer done.. closing the server" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/clouduploader/server.go:311" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:22Z" level=info msg="successfully restored object{backups/redis-test/zfs-pvc-51791429-c865-4439-8c76-387d335c8cd3-redis-test} from {aws}" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/clouduploader/operation.go:106" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:22Z" level=error msg="zfs: error doRestore returning snap pvc-51791429-c865-4439-8c76-387d335c8cd3..redis-test err zfs: error in restoring pvc-51791429-c865-4439-8c76-387d335c8cd3.redis-test, status:{Failed}" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/zfs/plugin/restore.go:359" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711
time="2021-02-05T08:47:22Z" level=error msg="zfs: error CreateVolumeFromSnapshot returning snap pvc-51791429-c865-4439-8c76-387d335c8cd3..redis-test err zfs: error in restoring pvc-51791429-c865-4439-8c76-387d335c8cd3.redis-test, status:{Failed}" cmd=/plugins/velero-blockstore-openebs logSource="/go/src/github.com/openebs/velero-plugin/pkg/zfs/plugin/zfs.go:133" pluginName=velero-blockstore-openebs restore=velero/redis-test-20210205104711

Environment:

artw commented 3 years ago

Thanks to @pawanpraka1 we found the root cause of this, discussion there

https://github.com/openebs/zfs-localpv/issues/286

mynktl commented 3 years ago

Closing this issue since it is being tracked at https://github.com/openebs/zfs-localpv/issues/286