NOTES:
  - All commands are prepended with a `date -u` for ease of correlation with the logs
  - Executed on a v1.17 kubernetes vagrant based cluster
  - csi-snapshotter logs are presented at the end

==== Create the snapshot ====
$ date -u; ./k create -f ./ceph-csi/examples/rbd/snapshot.yaml 
Mon 17 Feb 2020 11:55:26 PM UTC
volumesnapshot.snapshot.storage.k8s.io/rbd-pvc-snapshot created

==== Examine VolumeSnapshot and VolumeSnapshotContent objects ====

$ date -u; ./k get volumesnapshot -o yaml
Mon 17 Feb 2020 11:55:39 PM UTC
apiVersion: v1
items:
- apiVersion: snapshot.storage.k8s.io/v1beta1
  kind: VolumeSnapshot
  metadata:
    creationTimestamp: "2020-02-17T23:55:26Z"
    finalizers:
    - snapshot.storage.kubernetes.io/volumesnapshot-as-source-protection
    - snapshot.storage.kubernetes.io/volumesnapshot-bound-protection
    generation: 1
    name: rbd-pvc-snapshot
    namespace: default
    resourceVersion: "221386"
    selfLink: /apis/snapshot.storage.k8s.io/v1beta1/namespaces/default/volumesnapshots/rbd-pvc-snapshot
    uid: 64842a16-3d8e-4b84-90de-87f54db5d9da
  spec:
    source:
      persistentVolumeClaimName: rbd-pvc
    volumeSnapshotClassName: csi-rbdplugin-snapclass
  status:
    boundVolumeSnapshotContentName: snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da
    readyToUse: false
kind: List
metadata:
  resourceVersion: ""
  selfLink: ""

$ date -u; ./k get volumesnapshotcontent -o yaml
Mon 17 Feb 2020 11:55:43 PM UTC
apiVersion: v1
items:
- apiVersion: snapshot.storage.k8s.io/v1beta1
  kind: VolumeSnapshotContent
  metadata:
    annotations:
      snapshot.storage.kubernetes.io/deletion-secret-name: rook-csi-rbd-provisioner
      snapshot.storage.kubernetes.io/deletion-secret-namespace: rook-ceph
    creationTimestamp: "2020-02-17T23:55:26Z"
    finalizers:
    - snapshot.storage.kubernetes.io/volumesnapshotcontent-bound-protection
    generation: 1
    name: snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da
    resourceVersion: "221384"
    selfLink: /apis/snapshot.storage.k8s.io/v1beta1/volumesnapshotcontents/snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da
    uid: 85a2671c-e52a-49e6-b378-b50d9045dc7c
  spec:
    deletionPolicy: Delete
    driver: rbd.csi.ceph.com
    source:
      volumeHandle: 0001-0009-rook-ceph-0000000000000001-e9de23c1-51e0-11ea-9324-a228f17c8258
    volumeSnapshotClassName: csi-rbdplugin-snapclass
    volumeSnapshotRef:
      apiVersion: snapshot.storage.k8s.io/v1beta1
      kind: VolumeSnapshot
      name: rbd-pvc-snapshot
      namespace: default
      resourceVersion: "221380"
      uid: 64842a16-3d8e-4b84-90de-87f54db5d9da
kind: List
metadata:
  resourceVersion: ""
  selfLink: ""

==== Delete above requested/created VolumeSnapshot object ====

$ date -u ; ./k delete -f ./ceph-csi/examples/rbd/snapshot.yaml 
Mon 17 Feb 2020 11:56:18 PM UTC
volumesnapshot.snapshot.storage.k8s.io "rbd-pvc-snapshot" deleted


==== Verify state of objects post deletion ====

$ date -u; ./k get volumesnapshot -o yaml
Mon 17 Feb 2020 11:56:41 PM UTC
apiVersion: v1
items: []
kind: List
metadata:
  resourceVersion: ""
  selfLink: ""

$ date -u; ./k get volumesnapshotcontent -o yaml
Mon 17 Feb 2020 11:56:45 PM UTC
apiVersion: v1
items: []
kind: List
metadata:
  resourceVersion: ""
  selfLink: ""

$ date -u; kubectl get pvc -o yaml
Mon 17 Feb 2020 11:59:18 PM UTC
apiVersion: v1
items:
- apiVersion: v1
  kind: PersistentVolumeClaim
  metadata:
    annotations:
      pv.kubernetes.io/bind-completed: "yes"
      pv.kubernetes.io/bound-by-controller: "yes"
      volume.beta.kubernetes.io/storage-provisioner: rbd.csi.ceph.com
    creationTimestamp: "2020-02-17T23:55:02Z"
    finalizers:
    - kubernetes.io/pvc-protection
    - snapshot.storage.kubernetes.io/pvc-as-source-protection
    name: rbd-pvc
    namespace: default
    resourceVersion: "221382"
    selfLink: /api/v1/namespaces/default/persistentvolumeclaims/rbd-pvc
    uid: 2720d8fd-53ad-412f-8370-537e2bb9576a
  spec:
    accessModes:
    - ReadWriteOnce
    resources:
      requests:
        storage: 1Gi
    storageClassName: csi-rbd-sc
    volumeMode: Filesystem
    volumeName: pvc-2720d8fd-53ad-412f-8370-537e2bb9576a
  status:
    accessModes:
    - ReadWriteOnce
    capacity:
      storage: 1Gi
    phase: Bound
kind: List
metadata:
  resourceVersion: ""
  selfLink: ""

=========== csi-snapshotter sidecar logs ===========

I0217 23:55:26.969768       1 snapshot_controller_base.go:144] enqueued "snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da" for sync
I0217 23:55:26.969816       1 snapshot_controller_base.go:159] contentWorker[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:55:26.969861       1 util.go:119] storeObjectUpdate: adding content "snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da", version 221383
I0217 23:55:26.969890       1 snapshot_controller.go:56] synchronizing VolumeSnapshotContent[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:55:26.969903       1 snapshot_controller.go:543] Check if VolumeSnapshotContent[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da] should be deleted.
I0217 23:55:26.969914       1 snapshot_controller.go:77] syncContent: Call CreateSnapshot for content snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da
I0217 23:55:26.969924       1 snapshot_controller.go:133] createSnapshot for content [snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]: started
I0217 23:55:26.969935       1 snapshot_controller.go:112] scheduleOperation[create-snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:55:26.970003       1 snapshot_controller.go:296] createSnapshotOperation: Creating snapshot for content snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da through the plugin ...
I0217 23:55:26.970023       1 snapshot_controller.go:220] getCSISnapshotInput for content [snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:55:26.970028       1 snapshot_controller.go:451] getSnapshotClass: VolumeSnapshotClassName [csi-rbdplugin-snapclass]
I0217 23:55:26.978588       1 snapshotter.go:56] CSI CreateSnapshot: snapshot-64842a16-3d8e-4b84-90de-87f54db5d9da
I0217 23:55:26.978625       1 connection.go:182] GRPC call: /csi.v1.Identity/GetPluginInfo
I0217 23:55:26.978636       1 connection.go:183] GRPC request: {}
I0217 23:55:26.979690       1 snapshot_controller_base.go:144] enqueued "snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da" for sync
I0217 23:55:26.979725       1 snapshot_controller_base.go:159] contentWorker[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:55:26.979744       1 util.go:147] storeObjectUpdate updating content "snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da" with version 221384
I0217 23:55:26.979759       1 snapshot_controller.go:56] synchronizing VolumeSnapshotContent[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:55:26.979770       1 snapshot_controller.go:543] Check if VolumeSnapshotContent[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da] should be deleted.
I0217 23:55:26.979779       1 snapshot_controller.go:77] syncContent: Call CreateSnapshot for content snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da
I0217 23:55:26.979787       1 snapshot_controller.go:133] createSnapshot for content [snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]: started
I0217 23:55:26.979796       1 snapshot_controller.go:112] scheduleOperation[create-snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:55:26.979805       1 snapshot_controller.go:118] operation "create-snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da" is already running, skipping
I0217 23:55:26.983441       1 connection.go:185] GRPC response: {"name":"rbd.csi.ceph.com","vendor_version":"canary"}
I0217 23:55:26.984585       1 connection.go:186] GRPC error: <nil>

====> Initial call to plugin to Create requested snapshot <====
I0217 23:55:26.984603       1 connection.go:182] GRPC call: /csi.v1.Controller/CreateSnapshot
I0217 23:55:26.984613       1 connection.go:183] GRPC request: {"name":"snapshot-64842a16-3d8e-4b84-90de-87f54db5d9da","parameters":{"clusterID":"rook-ceph"},"secrets":"***stripped***","source_volume_id":"0001-0009-rook-ceph-0000000000000001-e9de23c1-51e0-11ea-9324-a228f17c8258"}

I0217 23:56:00.612464       1 reflector.go:278] github.com/kubernetes-csi/external-snapshotter/pkg/client/informers/externalversions/factory.go:117: forcing resync
I0217 23:56:00.612614       1 snapshot_controller_base.go:144] enqueued "snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da" for sync
I0217 23:56:00.612776       1 snapshot_controller_base.go:159] contentWorker[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:56:00.612854       1 util.go:147] storeObjectUpdate updating content "snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da" with version 221384
I0217 23:56:00.612916       1 snapshot_controller.go:56] synchronizing VolumeSnapshotContent[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:56:00.612937       1 snapshot_controller.go:543] Check if VolumeSnapshotContent[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da] should be deleted.
I0217 23:56:00.612959       1 snapshot_controller.go:77] syncContent: Call CreateSnapshot for content snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da
I0217 23:56:00.613007       1 snapshot_controller.go:133] createSnapshot for content [snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]: started
I0217 23:56:00.613030       1 snapshot_controller.go:112] scheduleOperation[create-snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:56:00.613051       1 snapshot_controller.go:118] operation "create-snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da" is already running, skipping

====> Initial call times out <====
I0217 23:56:11.979195       1 connection.go:185] GRPC response: {}
I0217 23:56:11.983541       1 connection.go:186] GRPC error: rpc error: code = DeadlineExceeded desc = context deadline exceeded

I0217 23:56:11.983717       1 snapshot_controller.go:181] updateContentStatusWithEvent[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:56:12.048104       1 snapshot_controller.go:202] updating VolumeSnapshotContent[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da] error status failed Operation cannot be fulfilled on volumesnapshotcontents.snapshot.storage.k8s.io "snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da": the object has been modified; please apply your changes to the latest version and try again
E0217 23:56:12.048179       1 snapshot_controller.go:139] createSnapshot [create-snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]: error occurred in createSnapshotOperation: failed to take snapshot of the volume, 0001-0009-rook-ceph-0000000000000001-e9de23c1-51e0-11ea-9324-a228f17c8258: "rpc error: code = DeadlineExceeded desc = context deadline exceeded"
E0217 23:56:12.048298       1 goroutinemap.go:150] Operation for "create-snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da" failed. No retries permitted until 2020-02-17 23:56:12.548216266 +0000 UTC m=+92.398685321 (durationBeforeRetry 500ms). Error: "failed to take snapshot of the volume, 0001-0009-rook-ceph-0000000000000001-e9de23c1-51e0-11ea-9324-a228f17c8258: \"rpc error: code = DeadlineExceeded desc = context deadline exceeded\""

====> VolumeSnapshot object deleted approximately around here <====
I0217 23:56:18.337194       1 snapshot_controller_base.go:144] enqueued "snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da" for sync
I0217 23:56:18.337238       1 snapshot_controller_base.go:159] contentWorker[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:56:18.337259       1 util.go:147] storeObjectUpdate updating content "snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da" with version 221605
I0217 23:56:18.337269       1 snapshot_controller.go:56] synchronizing VolumeSnapshotContent[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:56:18.337274       1 snapshot_controller.go:543] Check if VolumeSnapshotContent[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da] should be deleted.
I0217 23:56:18.337279       1 snapshot_controller.go:77] syncContent: Call CreateSnapshot for content snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da
I0217 23:56:18.337284       1 snapshot_controller.go:133] createSnapshot for content [snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]: started
I0217 23:56:18.337289       1 snapshot_controller.go:112] scheduleOperation[create-snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:56:18.337310       1 snapshot_controller.go:296] createSnapshotOperation: Creating snapshot for content snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da through the plugin ...
I0217 23:56:18.337315       1 snapshot_controller.go:220] getCSISnapshotInput for content [snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:56:18.337320       1 snapshot_controller.go:451] getSnapshotClass: VolumeSnapshotClassName [csi-rbdplugin-snapclass]
I0217 23:56:18.356914       1 snapshotter.go:56] CSI CreateSnapshot: snapshot-64842a16-3d8e-4b84-90de-87f54db5d9da
I0217 23:56:18.356939       1 connection.go:182] GRPC call: /csi.v1.Identity/GetPluginInfo
I0217 23:56:18.356947       1 connection.go:183] GRPC request: {}
I0217 23:56:18.358098       1 snapshot_controller_base.go:144] enqueued "snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da" for sync
I0217 23:56:18.358148       1 snapshot_controller_base.go:159] contentWorker[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:56:18.358169       1 util.go:147] storeObjectUpdate updating content "snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da" with version 221607
I0217 23:56:18.358183       1 snapshot_controller.go:56] synchronizing VolumeSnapshotContent[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:56:18.358192       1 snapshot_controller.go:543] Check if VolumeSnapshotContent[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da] should be deleted.
I0217 23:56:18.358202       1 snapshot_controller.go:60] VolumeSnapshotContent[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]: the policy is Delete
I0217 23:56:18.361096       1 connection.go:185] GRPC response: {"name":"rbd.csi.ceph.com","vendor_version":"canary"}
I0217 23:56:18.361684       1 connection.go:186] GRPC error: <nil>

====> Subsequent call to plugin for SnapshotCreate <====
I0217 23:56:18.361696       1 connection.go:182] GRPC call: /csi.v1.Controller/CreateSnapshot
I0217 23:56:18.361701       1 connection.go:183] GRPC request: {"name":"snapshot-64842a16-3d8e-4b84-90de-87f54db5d9da","parameters":{"clusterID":"rook-ceph"},"secrets":"***stripped***","source_volume_id":"0001-0009-rook-ceph-0000000000000001-e9de23c1-51e0-11ea-9324-a228f17c8258"}

I0217 23:56:18.398976       1 snapshot_controller_base.go:144] enqueued "snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da" for sync
I0217 23:56:18.399436       1 snapshot_controller.go:532] Removed protection finalizer from volume snapshot content snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da
I0217 23:56:18.399480       1 util.go:147] storeObjectUpdate updating content "snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da" with version 221607
I0217 23:56:18.399511       1 snapshot_controller_base.go:159] contentWorker[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:56:18.399537       1 snapshot_controller_base.go:258] content "snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da" deleted

====> Plugin response stating operation ABORTED as prior call is still in flight <====
I0217 23:56:19.374067       1 connection.go:185] GRPC response: {}
I0217 23:56:19.374521       1 connection.go:186] GRPC error: rpc error: code = Aborted desc = an operation with the given Volume ID snapshot-64842a16-3d8e-4b84-90de-87f54db5d9da already exists

I0217 23:56:19.374545       1 snapshot_controller.go:181] updateContentStatusWithEvent[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]
I0217 23:56:19.377863       1 snapshot_controller.go:202] updating VolumeSnapshotContent[snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da] error status failed Operation cannot be fulfilled on volumesnapshotcontents.snapshot.storage.k8s.io "snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da": StorageError: invalid object, Code: 4, Key: /registry/snapshot.storage.k8s.io/volumesnapshotcontents/snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da, ResourceVersion: 0, AdditionalErrorMsg: Precondition failed: UID in precondition: 85a2671c-e52a-49e6-b378-b50d9045dc7c, UID in object meta: 
E0217 23:56:19.377887       1 snapshot_controller.go:139] createSnapshot [create-snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da]: error occurred in createSnapshotOperation: failed to take snapshot of the volume, 0001-0009-rook-ceph-0000000000000001-e9de23c1-51e0-11ea-9324-a228f17c8258: "rpc error: code = Aborted desc = an operation with the given Volume ID snapshot-64842a16-3d8e-4b84-90de-87f54db5d9da already exists"
E0217 23:56:19.377928       1 goroutinemap.go:150] Operation for "create-snapcontent-64842a16-3d8e-4b84-90de-87f54db5d9da" failed. No retries permitted until 2020-02-17 23:56:20.377898247 +0000 UTC m=+100.228367219 (durationBeforeRetry 1s). Error: "failed to take snapshot of the volume, 0001-0009-rook-ceph-0000000000000001-e9de23c1-51e0-11ea-9324-a228f17c8258: \"rpc error: code = Aborted desc = an operation with the given Volume ID snapshot-64842a16-3d8e-4b84-90de-87f54db5d9da already exists\""