A volumesnapshotcontent is not removed when volumesnapshot is removed.

[lukshap]

Describe the bug

A volumesnapshotcontent is not removed when relevant volumesnapshot is removed

Environment details

• Image/version of Ceph CSI driver: csi-node-driver-registrar:v1.1.0, csi-provisioner:v1.3.0, csi-snapshotter:v1.2.0, csi-attacher:v1.2.0
• helm chart version: ceph-csi-rbd-0.8.0
• Kubernetes cluster version: v1.15.2
• Logs

Steps to reproduce

Steps to reproduce the behavior:

1. Create secret
2. Create storage class with "Retain policy"
3. Create volumesnapshotclass
4. Create pvc
5. Create volumesnapshot from the pvc above p.4
6. Create pvc from the snapshot above p.5
7. Remove pvc from p.4 (relevant pv will be in the "Released" state, but not removed)
8. Remove volumesnapshot from p.5
9. Remove pv from p7

Actual results

10. Make sure volumesnapshotcontent is not be removed.

Expected behavior

10. Make sure volumesnapshotcontent is be removed.

Additional context

# kubectl get pvc
No resources found.

# kubectl get pv
No resources found.

# kubectl get volumesnapshot
No resources found.

#kubectl get volumesnapshotcontent
NAME                                               AGE
snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35   37m

# kubectl describe volumesnapshotcontent snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35
Name:         snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35
Namespace:    
Labels:       <none>
Annotations:  <none>
API Version:  snapshot.storage.k8s.io/v1alpha1
Kind:         VolumeSnapshotContent
Metadata:
  Creation Timestamp:  2019-08-29T17:50:05Z
  Finalizers:
    snapshot.storage.kubernetes.io/volumesnapshotcontent-protection
  Generation:        1
  Resource Version:  17372103
  Self Link:         /apis/snapshot.storage.k8s.io/v1alpha1/volumesnapshotcontents/snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35
  UID:               2c1af7ac-e1c0-4d4d-ba29-9e5c3dca8760
Spec:
  Csi Volume Snapshot Source:
    Creation Time:    1567101004000000000
    Driver:           rbd.csi.ceph.com
    Restore Size:     1073741824
    Snapshot Handle:  0001-0024-7ef8d74e-670e-464e-9407-895529d93f0a-0000000000000007-6c6ad8fe-ca85-11e9-a6d3-160a63e02676
  Deletion Policy:    Delete
  Persistent Volume Ref:
    API Version:        v1
    Kind:               PersistentVolume
    Name:               pvc-3dba9257-82a2-4d02-b030-2658d939e5f9
    Resource Version:   17340852
    UID:                05d965a0-8cf6-49c6-8362-24ea031bbd3a
  Snapshot Class Name:  csi-rbdplugin-snapclass
  Volume Snapshot Ref:
    API Version:       snapshot.storage.k8s.io/v1alpha1
    Kind:              VolumeSnapshot
    Name:              rbd-pvc-snapshot
    Namespace:         default
    Resource Version:  17372084
    UID:               071a4b93-02fc-42a1-b597-e5496a69ca35
Events:
  Type     Reason               Age                  From                              Message
  ----     ------               ----                 ----                              -------
  Warning  SnapshotDeleteError  43s (x8 over 6m55s)  csi-snapshotter rbd.csi.ceph.com  Failed to delete snapshot
  Warning  SnapshotDeleteError  43s (x8 over 6m55s)  csi-snapshotter rbd.csi.ceph.com  Failed to delete snapshot
  Warning  SnapshotDeleteError  39s (x8 over 6m55s)  csi-snapshotter rbd.csi.ceph.com  Failed to delete snapshot

csi-snapshotter logs:

I0829 18:22:01.229374       1 reflector.go:235] github.com/kubernetes-csi/external-snapshotter/pkg/client/informers/externalversions/factory.go:117: forcing resync
I0829 18:22:01.237587       1 reflector.go:235] github.com/kubernetes-csi/external-snapshotter/pkg/client/informers/externalversions/factory.go:117: forcing resync
I0829 18:22:01.237663       1 snapshot_controller_base.go:195] enqueued "snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35" for sync
I0829 18:22:01.237689       1 snapshot_controller_base.go:275] contentWorker[snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35]
I0829 18:22:01.237729       1 util.go:138] storeObjectUpdate updating content "snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35" with version 17372103
I0829 18:22:01.237745       1 snapshot_controller.go:90] synchronizing VolumeSnapshotContent[snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35]
I0829 18:22:01.237756       1 snapshot_controller.go:116] synchronizing VolumeSnapshotContent[snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35]: content is bound to snapshot default/rbd-pvc-snapshot
I0829 18:22:01.237767       1 snapshot_controller.go:131] synchronizing VolumeSnapshotContent[snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35]: snapshot default/rbd-pvc-snapshot not found
I0829 18:22:01.237776       1 snapshot_controller.go:155] VolumeSnapshotContent[snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35]: policy is Delete
I0829 18:22:01.237786       1 snapshot_controller.go:330] Snapshotter is about to delete volume snapshot content and the operation named delete-snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35[2c1af7ac-e1c0-4d4d-ba29-9e5c3dca8760]
I0829 18:22:01.237799       1 snapshot_controller.go:339] scheduleOperation[delete-snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35[2c1af7ac-e1c0-4d4d-ba29-9e5c3dca8760]]
I0829 18:22:01.237811       1 snapshot_controller.go:347] operation "delete-snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35[2c1af7ac-e1c0-4d4d-ba29-9e5c3dca8760]" postponed due to exponential backoff
I0829 18:23:01.229566       1 reflector.go:235] github.com/kubernetes-csi/external-snapshotter/pkg/client/informers/externalversions/factory.go:117: forcing resync
I0829 18:23:01.237750       1 reflector.go:235] github.com/kubernetes-csi/external-snapshotter/pkg/client/informers/externalversions/factory.go:117: forcing resync
I0829 18:23:01.237816       1 snapshot_controller_base.go:195] enqueued "snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35" for sync
I0829 18:23:01.237841       1 snapshot_controller_base.go:275] contentWorker[snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35]
I0829 18:23:01.237889       1 util.go:138] storeObjectUpdate updating content "snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35" with version 17372103
I0829 18:23:01.237910       1 snapshot_controller.go:90] synchronizing VolumeSnapshotContent[snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35]
I0829 18:23:01.237920       1 snapshot_controller.go:116] synchronizing VolumeSnapshotContent[snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35]: content is bound to snapshot default/rbd-pvc-snapshot
I0829 18:23:01.237929       1 snapshot_controller.go:131] synchronizing VolumeSnapshotContent[snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35]: snapshot default/rbd-pvc-snapshot not found
I0829 18:23:01.237937       1 snapshot_controller.go:155] VolumeSnapshotContent[snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35]: policy is Delete
I0829 18:23:01.237947       1 snapshot_controller.go:330] Snapshotter is about to delete volume snapshot content and the operation named delete-snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35[2c1af7ac-e1c0-4d4d-ba29-9e5c3dca8760]
I0829 18:23:01.237957       1 snapshot_controller.go:339] scheduleOperation[delete-snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35[2c1af7ac-e1c0-4d4d-ba29-9e5c3dca8760]]
I0829 18:23:01.237991       1 snapshot_controller.go:735] deleteSnapshotOperation [snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35] started
I0829 18:23:01.238009       1 util.go:255] GetSecretReference namespaceTemplate kube-system, namespaceParams: map[volumesnapshotcontent.name:snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35], resolved kube-system
I0829 18:23:01.238064       1 util.go:288] GetSecretReference validated Secret: &SecretReference{Name:csi-rbd-secret,Namespace:kube-system,}
I0829 18:23:01.244999       1 connection.go:180] GRPC call: /csi.v1.Controller/DeleteSnapshot
I0829 18:23:01.245016       1 connection.go:181] GRPC request: {"secrets":"***stripped***","snapshot_id":"0001-0024-7ef8d74e-670e-464e-9407-895529d93f0a-0000000000000007-6c6ad8fe-ca85-11e9-a6d3-160a63e02676"}
I0829 18:23:03.822841       1 connection.go:183] GRPC response: {}
I0829 18:23:03.823419       1 connection.go:184] GRPC error: rpc error: code = FailedPrecondition desc = failed to unprotect snapshot: actonic/csi-snap-6c6ad8fe-ca85-11e9-a6d3-160a63e02676 with error: failed to unprotect snapshot, command output: 2019-08-29 18:23:03.761 7fed5deb4700 -1 librbd::SnapshotUnprotectRequest: cannot unprotect: at least 1 child(ren) [317d0cb0fa701] in pool 'actonic'
2019-08-29 18:23:03.761 7fed5deb4700 -1 librbd::SnapshotUnprotectRequest: encountered error: (16) Device or resource busy
2019-08-29 18:23:03.761 7fed5deb4700 -1 librbd::SnapshotUnprotectRequest: 0x563b2fd71980 should_complete_error: ret_val=-16
rbd: unprotecting snap failed: 2019-08-29 18:23:03.785 7fed5deb4700 -1 librbd::SnapshotUnprotectRequest: 0x563b2fd71980 should_complete_error: ret_val=-16
(16) Device or resource busy
: exit status 16
E0829 18:23:03.823528       1 goroutinemap.go:150] Operation for "delete-snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35[2c1af7ac-e1c0-4d4d-ba29-9e5c3dca8760]" failed. No retries permitted until 2019-08-29 18:25:05.823487285 +0000 UTC m=+14525.719961528 (durationBeforeRetry 2m2s). Error: "failed to delete snapshot \"snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35\", err: failed to delete snapshot content snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35: \"rpc error: code = FailedPrecondition desc = failed to unprotect snapshot: actonic/csi-snap-6c6ad8fe-ca85-11e9-a6d3-160a63e02676 with error: failed to unprotect snapshot, command output: 2019-08-29 18:23:03.761 7fed5deb4700 -1 librbd::SnapshotUnprotectRequest: cannot unprotect: at least 1 child(ren) [317d0cb0fa701] in pool 'actonic'\\n2019-08-29 18:23:03.761 7fed5deb4700 -1 librbd::SnapshotUnprotectRequest: encountered error: (16) Device or resource busy\\n2019-08-29 18:23:03.761 7fed5deb4700 -1 librbd::SnapshotUnprotectRequest: 0x563b2fd71980 should_complete_error: ret_val=-16\\nrbd: unprotecting snap failed: 2019-08-29 18:23:03.785 7fed5deb4700 -1 librbd::SnapshotUnprotectRequest: 0x563b2fd71980 should_complete_error: ret_val=-16\\n(16) Device or resource busy\\n: exit status 16\""
I0829 18:23:03.823549       1 event.go:209] Event(v1.ObjectReference{Kind:"VolumeSnapshotContent", Namespace:"", Name:"snapcontent-071a4b93-02fc-42a1-b597-e5496a69ca35", UID:"2c1af7ac-e1c0-4d4d-ba29-9e5c3dca8760", APIVersion:"snapshot.storage.k8s.io/v1alpha1", ResourceVersion:"17372103", FieldPath:""}): type: 'Warning' reason: 'SnapshotDeleteError' Failed to delete snapshot

[Madhu-1]

known issue with snapshot #70 #227 if not, please reopen