$ kubectl describe po busybox
...
Events:
  Type     Reason                  Age              From                                    Message
  ----     ------                  ----             ----                                    -------
  Normal   Scheduled               8s               default-scheduler                       Successfully assigned default/busybox to ip-172-31-16-243.ec2.internal
  Normal   SuccessfulAttachVolume  7s               attachdetach-controller                 AttachVolume.Attach succeeded for volume "pvc-43edb969ce3511e8"
  Warning  FailedMount             1s (x3 over 3s)  kubelet, ip-172-31-16-243.ec2.internal  MountVolume.SetUp failed for volume "pvc-43edb969ce3511e8" : rpc error: code = Unknown desc = executable file not found in $PATH

$ kubectl logs csi-rbdplugin-c2fg2 csi-rbdplugin
...
I1012 15:43:43.842687       1 nodeserver.go:74] rbd image: csi-rbd-43f35474-ce35-11e8-938c-0a7b6b3d3d9a/xfs-pool was successfully mapped at /dev/rbd1
I1012 15:43:43.842696       1 nodeserver.go:81] target /var/lib/kubelet/pods/4a3c555d-ce35-11e8-b182-02ccef257a4a/volumes/kubernetes.io~csi/pvc-43edb969ce3511e8/mount
fstype xfs
device /dev/rbd1
readonly false
attributes map[csiNodePublishSecretNamespace:default imageFormat:2 userid:admin imageFeatures:layering csiProvisionerSecretNamespace:default fsType:xfs monitors:172.31.30.178:6789 172.31.41.151:6789 172.31.84.1:6789 adminid:admin csiNodePublishSecretName:csi-rbd-secret pool:xfs-pool storage.kubernetes.io/csiProvisionerIdentity:1539291186916-8081-csi-rbdplugin csiProvisionerSecretName:csi-rbd-secret]
 mountflags []
I1012 15:43:43.843576       1 mount_linux.go:209] Cannot run systemd-run, assuming non-systemd OS
I1012 15:43:43.843590       1 mount_linux.go:210] systemd-run failed with: exit status 1
I1012 15:43:43.843595       1 mount_linux.go:211] systemd-run output: Failed to create bus connection: No such file or directory
I1012 15:43:43.843604       1 mount_linux.go:471] Checking for issues with fsck on disk: /dev/rbd1
I1012 15:43:43.872778       1 mount_linux.go:484] `fsck` error fsck from util-linux 2.23.2
fsck.ext2: Bad magic number in super-block while trying to open /dev/rbd1
/dev/rbd1: 
The superblock could not be read or does not describe a correct ext2
filesystem.  If the device is valid and it really contains an ext2
filesystem (and not swap or ufs or something else), then the superblock
is corrupt, and you might try running e2fsck with an alternate superblock:
    e2fsck -b 8193 <device>

I1012 15:43:43.872797       1 mount_linux.go:490] Attempting to mount disk: xfs /dev/rbd1 /var/lib/kubelet/pods/4a3c555d-ce35-11e8-b182-02ccef257a4a/volumes/kubernetes.io~csi/pvc-43edb969ce3511e8/mount
I1012 15:43:43.872809       1 mount_linux.go:146] Mounting cmd (mount) with arguments ([-t xfs -o defaults /dev/rbd1 /var/lib/kubelet/pods/4a3c555d-ce35-11e8-b182-02ccef257a4a/volumes/kubernetes.io~csi/pvc-43edb969ce3511e8/mount])
E1012 15:43:43.875501       1 mount_linux.go:151] Mount failed: exit status 32
Mounting command: mount
Mounting arguments: -t xfs -o defaults /dev/rbd1 /var/lib/kubelet/pods/4a3c555d-ce35-11e8-b182-02ccef257a4a/volumes/kubernetes.io~csi/pvc-43edb969ce3511e8/mount
Output: mount: wrong fs type, bad option, bad superblock on /dev/rbd1,
       missing codepage or helper program, or other error

       In some cases useful info is found in syslog - try
       dmesg | tail or so.

I1012 15:43:43.875518       1 mount_linux.go:545] Attempting to determine if disk "/dev/rbd1" is formatted using blkid with args: ([-p -s TYPE -s PTTYPE -o export /dev/rbd1])
I1012 15:43:43.900261       1 mount_linux.go:548] Output: "", err: exit status 2
I1012 15:43:43.900286       1 mount_linux.go:519] Disk "/dev/rbd1" appears to be unformatted, attempting to format as type: "xfs" with options: [/dev/rbd1]
E1012 15:43:43.900334       1 mount_linux.go:526] format of disk "/dev/rbd1" failed: type:("xfs") target:("/var/lib/kubelet/pods/4a3c555d-ce35-11e8-b182-02ccef257a4a/volumes/kubernetes.io~csi/pvc-43edb969ce3511e8/mount") options:(["defaults"])error:(executable file not found in $PATH)
E1012 15:43:43.900351       1 utils.go:100] GRPC error: executable file not found in $PATH

$ kubectl exec csi-rbdplugin-c2fg2 -c csi-rbdplugin ls /usr/sbin | grep mkfs
mkfs
mkfs.cramfs
mkfs.ext2
mkfs.ext3
mkfs.ext4
mkfs.minix

<snip>
STEP: checking the claim
STEP: checking the PV
STEP: checking the created volume is writable and has the PV's mount options
Aug 10 16:23:04.740: INFO: Waiting up to 15m0s for pod "pvc-volume-tester-4rrg8" in namespace "e2e-tests-csi-moc
k-plugin-ktb77" to be "success or failure"
Aug 10 16:23:04.773: INFO: Pod "pvc-volume-tester-4rrg8": Phase="Pending", Reason="", readiness=false. Elapsed:
32.971738ms
<snip>
Aug 10 16:23:33.537: INFO: Pod "pvc-volume-tester-4rrg8": Phase="Succeeded", Reason="", readiness=false. Elapsed
: 28.797109596s
STEP: Saw pod success
Aug 10 16:23:33.537: INFO: Pod "pvc-volume-tester-4rrg8" satisfied condition "success or failure"
STEP: Deleting pod pvc-volume-tester-4rrg8 in namespace e2e-tests-csi-mock-plugin-ktb77
STEP: checking the created volume is readable and retains data
Aug 10 16:23:33.697: INFO: Waiting up to 15m0s for pod "pvc-volume-tester-ldg49" in namespace "e2e-tests-csi-moc
k-plugin-ktb77" to be "success or failure"
Aug 10 16:23:33.751: INFO: Pod "pvc-volume-tester-ldg49": Phase="Pending", Reason="", readiness=false. Elapsed:
53.56882ms
<snip>
Aug 10 16:26:32.882: INFO: Pod "pvc-volume-tester-ldg49": Phase="Pending", Reason="", readiness=false. Elapsed:
2m59.184190378s

# kubectl describe pod pvc-volume-tester-ldg49 -n e2e-tests-csi-mock-plugin-ktb77
<snip>
Events:
  Type     Reason       Age               From                Message
  ----     ------       ----              ----                -------
  Warning  FailedMount  9s (x4 over 58s)  kubelet, 127.0.0.1  MountVolume.SetUp failed for volume "pvc-a7736d229cb911e8" : rpc error: code = DeadlineExceeded desc = context deadline exceeded

I0718 23:43:29.512515       1 identityserver-default.go:32] Using default GetPluginInnfo
I0718 23:43:29.512539       1 utils.go:102] GRPC response: name:"csi-cephfsplugin" vendor_version:"0.2.0"
I0718 23:43:29.521353       1 utils.go:96] GRPC call: /csi.v0.Controller/DeleteVolume
I0718 23:43:29.521424       1 utils.go:97] GRPC request: volume_id:"csi-cephfs-dyn-5ab6b2f6-8ae4-11e8-bb12-0242ac110004" control
ler_delete_secrets:<key:"adminID" value:"admin" > controller_delete_secrets:<key:"adminKey" value:"AQDRrKNVbEevChAAEmRC+pW/KBVHx
a0w/POILA==" >
E0718 23:43:29.984564       1 controllerserver.go:171] failed to delete ceph user csi-user-5ab6b2f6-8ae4-11e8-bb12-0242ac110004:
 cephfs: ceph failed with following error: exit status 1
cephfs: ceph output: 2018-07-18 23:43:29.957718 7f4403592700  0 librados: client.admin authentication error (95) Operation not supported
[errno 95] error connecting to the cluster
I0718 23:43:38.727506       1 utils.go:96] GRPC call: /csi.v0.Identity/GetPluginCapabilities
I0718 23:43:38.727607       1 utils.go:97] GRPC request: 
I0718 23:43:38.727725       1 utils.go:102] GRPC response: capabilities:<service:<type:CONTROLLER_SERVICE > > 
I0718 23:43:38.728846       1 utils.go:96] GRPC call: /csi.v0.Controller/ControllerGetCapabilities
I0718 23:43:38.728904       1 utils.go:97] GRPC request: 
I0718 23:43:38.728991       1 controllerserver-default.go:82] Using default ControllerGetCapabilities
I0718 23:43:38.729007       1 utils.go:102] GRPC response: capabilities:<rpc:<type:CREATE_DELETE_VOLUME > > 
I0718 23:43:38.729940       1 utils.go:96] GRPC call: /csi.v0.Identity/GetPluginInfo
I0718 23:43:38.729974       1 utils.go:97] GRPC request: 
I0718 23:43:38.730034       1 identityserver-default.go:32] Using default GetPluginInnfo
I0718 23:43:38.730046       1 utils.go:102] GRPC response: name:"csi-cephfsplugin" vendor_version:"0.2.0" 
I0718 23:43:38.737483       1 utils.go:96] GRPC call: /csi.v0.Controller/DeleteVolume
I0718 23:43:38.737520       1 utils.go:97] GRPC request: volume_id:"csi-cephfs-dyn-5ab6b2f6-8ae4-11e8-bb12-0242ac110004" controller_delete_secrets:<key:"adminID" value:"admin" > controller_delete_secrets:<key:"adminKey" value:"AQDRrKNVbEevChAAEmRC+pW/KBVHxa0w/POILA==" > 
E0718 23:43:38.749523       1 controllerserver.go:166] failed to delete volume csi-cephfs-dyn-5ab6b2f6-8ae4-11e8-bb12-0242ac110004: cephfs: mount failed with following error: exit status 16
cephfs: mount output: mount error 16 = Device or resource busy
E0718 23:43:38.749679       1 utils.go:100] GRPC error: rpc error: code = Internal desc = cephfs: mount failed with following error: exit status 16
cephfs: mount output: mount error 16 = Device or resource busy

	devicePath, cnt, err := mount.GetDeviceNameFromMount(mounter, targetPath)
	if err != nil {
		return nil, status.Error(codes.Internal, err.Error())
	}

	// Unmounting the image
	err = mounter.Unmount(targetPath)
	if err != nil {
		return nil, status.Error(codes.Internal, err.Error())
	}

	cnt--
	if cnt != 0 {
	 	return &csi.NodeUnpublishVolumeResponse{}, nil
	}

Jan 22 21:29:21 worker2 kubelet: E0122 21:29:21.389261    9198 csi_mounter.go:202] kubernetes.io/csi: mounter.SetupAt failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
Jan 22 21:29:21 worker2 kubelet: E0122 21:29:21.389552    9198 nestedpendingoperations.go:267] Operation for "\"kubernetes.io/csi/csi-rbdplugin^csi-rbd-vol-7e83083f-1e73-11e9-ba2d-0050562c0166\"" failed. No retries permitted until 2019-01-22 21:29:22.389521876 +0300 MSK m=+33400.334588836 (durationBeforeRetry 1s). Error: "MountVolume.SetUp failed for volume \"pvc-7e7d8b001e7311e9\" (UniqueName: \"kubernetes.io/csi/csi-rbdplugin^csi-rbd-vol-7e83083f-1e73-11e9-ba2d-0050562c0166\") pod \"csirbd-demo-pod-2\" (UID: \"8bff42b8-1e73-11e9-907f-0050562c0156\") : rpc error: code = DeadlineExceeded desc = context deadline exceeded"
Jan 22 21:29:22 worker2 kubelet: I0122 21:29:22.420756    9198 operation_generator.go:501] MountVolume.WaitForAttach entering for volume "pvc-7e7d8b001e7311e9" (UniqueName: "kubernetes.io/csi/csi-rbdplugin^csi-rbd-vol-7e83083f-1e73-11e9-ba2d-0050562c0166") pod "csirbd-demo-pod-2" (UID: "8bff42b8-1e73-11e9-907f-0050562c0156") DevicePath "csi-2253bdb6b64f836df4e116574a6ed910aa641146f3ef377603896704803cc1f7"
Jan 22 21:29:22 worker2 kubelet: I0122 21:29:22.424201    9198 operation_generator.go:510] MountVolume.WaitForAttach succeeded for volume "pvc-7e7d8b001e7311e9" (UniqueName: "kubernetes.io/csi/csi-rbdplugin^csi-rbd-vol-7e83083f-1e73-11e9-ba2d-0050562c0166") pod "csirbd-demo-pod-2" (UID: "8bff42b8-1e73-11e9-907f-0050562c0156") DevicePath "csi-2253bdb6b64f836df4e116574a6ed910aa641146f3ef377603896704803cc1f7"
Jan 22 21:29:22 worker2 kubelet: I0122 21:29:22.425384    9198 csi_attacher.go:360] kubernetes.io/csi: attacher.MountDevice STAGE_UNSTAGE_VOLUME capability not set. Skipping MountDevice...
Jan 22 21:29:22 worker2 kubelet: I0122 21:29:22.425409    9198 operation_generator.go:531] MountVolume.MountDevice succeeded for volume "pvc-7e7d8b001e7311e9" (UniqueName: "kubernetes.io/csi/csi-rbdplugin^csi-rbd-vol-7e83083f-1e73-11e9-ba2d-0050562c0166") pod "csirbd-demo-pod-2" (UID: "8bff42b8-1e73-11e9-907f-0050562c0156") device mount path "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-7e7d8b001e7311e9/globalmount"
Jan 22 21:29:37 worker2 kubelet: E0122 21:29:37.425747    9198 csi_mounter.go:202] kubernetes.io/csi: mounter.SetupAt failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
Jan 22 21:29:37 worker2 kubelet: E0122 21:29:37.426114    9198 nestedpendingoperations.go:267] Operation for "\"kubernetes.io/csi/csi-rbdplugin^csi-rbd-vol-7e83083f-1e73-11e9-ba2d-0050562c0166\"" failed. No retries permitted until 2019-01-22 21:29:39.426069178 +0300 MSK m=+33417.371136139 (durationBeforeRetry 2s). Error: "MountVolume.SetUp failed for volume \"pvc-7e7d8b001e7311e9\" (UniqueName: \"kubernetes.io/csi/csi-rbdplugin^csi-rbd-vol-7e83083f-1e73-11e9-ba2d-0050562c0166\") pod \"csirbd-demo-pod-2\" (UID: \"8bff42b8-1e73-11e9-907f-0050562c0156\") : rpc error: code = DeadlineExceeded desc = context deadline exceeded"
Jan 22 21:29:39 worker2 kubelet: I0122 21:29:39.458084    9198 operation_generator.go:501] MountVolume.WaitForAttach entering for volume "pvc-7e7d8b001e7311e9" (UniqueName: "kubernetes.io/csi/csi-rbdplugin^csi-rbd-vol-7e83083f-1e73-11e9-ba2d-0050562c0166") pod "csirbd-demo-pod-2" (UID: "8bff42b8-1e73-11e9-907f-0050562c0156") DevicePath "csi-2253bdb6b64f836df4e116574a6ed910aa641146f3ef377603896704803cc1f7"
Jan 22 21:29:39 worker2 kubelet: I0122 21:29:39.460158    9198 operation_generator.go:510] MountVolume.WaitForAttach succeeded for volume "pvc-7e7d8b001e7311e9" (UniqueName: "kubernetes.io/csi/csi-rbdplugin^csi-rbd-vol-7e83083f-1e73-11e9-ba2d-0050562c0166") pod "csirbd-demo-pod-2" (UID: "8bff42b8-1e73-11e9-907f-0050562c0156") DevicePath "csi-2253bdb6b64f836df4e116574a6ed910aa641146f3ef377603896704803cc1f7"
Jan 22 21:29:39 worker2 kubelet: I0122 21:29:39.461447    9198 csi_attacher.go:360] kubernetes.io/csi: attacher.MountDevice STAGE_UNSTAGE_VOLUME capability not set. Skipping MountDevice...

kubectl describe pod/csirbd-demo-pod-2                                                                                                                                                                                     (autobp/default)
Name:               csirbd-demo-pod-2
Namespace:          default
Priority:           0
PriorityClassName:  <none>
Node:               worker2/10.35.12.25
Start Time:         Tue, 22 Jan 2019 21:28:43 +0300
Labels:             <none>
Annotations:        kubectl.kubernetes.io/last-applied-configuration:
                      {"apiVersion":"v1","kind":"Pod","metadata":{"annotations":{},"name":"csirbd-demo-pod-2","namespace":"default"},"spec":{"containers":[{"ima...
Status:             Pending
IP:                 
Containers:
  web-server:
    Container ID:   
    Image:          nginx
    Image ID:       
    Port:           <none>
    Host Port:      <none>
    State:          Waiting
      Reason:       ContainerCreating
    Ready:          False
    Restart Count:  0
    Environment:    <none>
    Mounts:
      /var/lib/www/html from testpvc (rw)
      /var/run/secrets/kubernetes.io/serviceaccount from default-token-zt594 (ro)
Conditions:
  Type              Status
  Initialized       True 
  Ready             False 
  ContainersReady   False 
  PodScheduled      True 
Volumes:
  testpvc:
    Type:       PersistentVolumeClaim (a reference to a PersistentVolumeClaim in the same namespace)
    ClaimName:  rbd-pvc-ngk
    ReadOnly:   false
  default-token-zt594:
    Type:        Secret (a volume populated by a Secret)
    SecretName:  default-token-zt594
    Optional:    false
QoS Class:       BestEffort
Node-Selectors:  <none>
Tolerations:     node.kubernetes.io/not-ready:NoExecute for 300s
                 node.kubernetes.io/unreachable:NoExecute for 300s
Events:
  Type     Reason                  Age                  From                     Message
  ----     ------                  ----                 ----                     -------
  Normal   Scheduled               4m6s                 default-scheduler        Successfully assigned default/csirbd-demo-pod-2 to worker2
  Normal   SuccessfulAttachVolume  4m6s                 attachdetach-controller  AttachVolume.Attach succeeded for volume "pvc-7e7d8b001e7311e9"
  Warning  FailedMount             2m3s                 kubelet, worker2         Unable to mount volumes for pod "csirbd-demo-pod-2_default(8bff42b8-1e73-11e9-907f-0050562c0156)": timeout expired waiting for volumes to attach or mount for pod "default"/"csirbd-demo-pod-2". list of unmounted volumes=[testpvc]. list of unattached volumes=[testpvc default-token-zt594]
  Warning  FailedMount             55s (x8 over 3m44s)  kubelet, worker2         MountVolume.SetUp failed for volume "pvc-7e7d8b001e7311e9" : rpc error: code = DeadlineExceeded desc = context deadline exceeded

I0125 00:00:36.890803       1 shared_informer.go:123] caches populated
I0125 00:00:36.890860       1 snapshot_controller_base.go:483] controller initialized
I0125 00:01:16.691864       1 snapshot_controller_base.go:169] enqueued "default/rbd-pvc-snapshot" for sync
I0125 00:01:16.691884       1 snapshot_controller_base.go:201] snapshotWorker[default/rbd-pvc-snapshot]
I0125 00:01:16.691889       1 snapshot_controller_base.go:204] snapshotWorker: snapshot namespace [default] name [rbd-pvc-snapshot]
I0125 00:01:16.691896       1 snapshot_controller_base.go:347] checkAndUpdateSnapshotClass [rbd-pvc-snapshot]: VolumeSnapshotClassName [csi-rbdplugin-snapclass]
I0125 00:01:16.691900       1 snapshot_controller.go:769] getSnapshotClass: VolumeSnapshotClassName [csi-rbdplugin-snapclass]
I0125 00:01:16.691905       1 snapshot_controller_base.go:364] VolumeSnapshotClass Snapshotter [csi-rbdplugin] Snapshot Controller snapshotterName [csi-rbdplugin]
I0125 00:01:16.691910       1 snapshot_controller_base.go:215] passed checkAndUpdateSnapshotClass for snapshot "default/rbd-pvc-snapshot"
I0125 00:01:16.691915       1 snapshot_controller_base.go:377] updateSnapshot "default/rbd-pvc-snapshot"
I0125 00:01:16.691939       1 util.go:71] storeObjectUpdate: adding snapshot "default/rbd-pvc-snapshot", version 274434
I0125 00:01:16.691950       1 snapshot_controller.go:140] synchonizing VolumeSnapshot[default/rbd-pvc-snapshot]: bound to: "", Completed: false
I0125 00:01:16.691958       1 snapshot_controller.go:189] syncUnreadySnapshot default/rbd-pvc-snapshot
I0125 00:01:16.691964       1 snapshot_controller.go:260] No VolumeSnapshotContent for VolumeSnapshot default/rbd-pvc-snapshot found
I0125 00:01:16.691968       1 snapshot_controller.go:304] createSnapshot[default/rbd-pvc-snapshot]: started
I0125 00:01:16.691972       1 snapshot_controller.go:279] scheduleOperation[create-default/rbd-pvc-snapshot[56206229-2034-11e9-816a-1062eb3456cc]]
I0125 00:01:16.691993       1 snapshot_controller.go:447] createSnapshot: Creating snapshot default/rbd-pvc-snapshot through the plugin ...
I0125 00:01:16.691999       1 snapshot_controller.go:455] createSnapshotOperation [rbd-pvc-snapshot]: VolumeSnapshotClassName [csi-rbdplugin-snapclass]
I0125 00:01:16.692004       1 snapshot_controller.go:769] getSnapshotClass: VolumeSnapshotClassName [csi-rbdplugin-snapclass]
I0125 00:01:16.703618       1 snapshot_controller.go:738] getVolumeFromVolumeSnapshot: snapshot [rbd-pvc-snapshot] PV name [pvc-9f001a90202c11e9]
I0125 00:01:16.703636       1 util.go:168] GetSecretReference namespaceTemplate default, namespaceParams: map[volumesnapshotcontent.name:snapcontent-56206229-2034-11e9-816a-1062eb3456cc volumesnapshot.namespace:default], resolved default
I0125 00:01:16.703673       1 util.go:201] GetSecretReference validated Secret: &SecretReference{Name:csi-rbd-secret,Namespace:default,}
I0125 00:01:16.706373       1 connection.go:192] CSI CreateSnapshot: snapshot-56206229-2034-11e9-816a-1062eb3456cc
I0125 00:01:16.706387       1 connection.go:259] GRPC call: /csi.v0.Identity/GetPluginInfo
I0125 00:01:16.706774       1 connection.go:261] GRPC response: name:"csi-rbdplugin" vendor_version:"0.3.0" 
I0125 00:01:16.706802       1 connection.go:262] GRPC error: <nil>
I0125 00:01:16.706808       1 connection.go:259] GRPC call: /csi.v0.Controller/CreateSnapshot
I0125 00:01:16.707231       1 connection.go:261] GRPC response: 
I0125 00:01:16.707273       1 connection.go:262] GRPC error: rpc error: code = NotFound desc = Source Volume ID csi-rbd-vol-9f098d01-202c-11e9-b0a2-1062eb3452d7 cannot found
I0125 00:01:16.707298       1 snapshot_controller.go:352] updateSnapshotStatusWithEvent[default/rbd-pvc-snapshot]
I0125 00:01:16.710824       1 snapshot_controller_base.go:169] enqueued "default/rbd-pvc-snapshot" for sync
I0125 00:01:16.710851       1 snapshot_controller_base.go:201] snapshotWorker[default/rbd-pvc-snapshot]
I0125 00:01:16.710858       1 snapshot_controller_base.go:204] snapshotWorker: snapshot namespace [default] name [rbd-pvc-snapshot]
I0125 00:01:16.710867       1 snapshot_controller_base.go:347] checkAndUpdateSnapshotClass [rbd-pvc-snapshot]: VolumeSnapshotClassName [csi-rbdplugin-snapclass]
I0125 00:01:16.710873       1 snapshot_controller.go:769] getSnapshotClass: VolumeSnapshotClassName [csi-rbdplugin-snapclass]
I0125 00:01:16.710881       1 snapshot_controller_base.go:364] VolumeSnapshotClass Snapshotter [csi-rbdplugin] Snapshot Controller snapshotterName [csi-rbdplugin]
I0125 00:01:16.710889       1 snapshot_controller_base.go:215] passed checkAndUpdateSnapshotClass for snapshot "default/rbd-pvc-snapshot"
I0125 00:01:16.710900       1 snapshot_controller_base.go:377] updateSnapshot "default/rbd-pvc-snapshot"
I0125 00:01:16.710925       1 util.go:99] storeObjectUpdate updating snapshot "default/rbd-pvc-snapshot" with version 274435
I0125 00:01:16.710943       1 snapshot_controller.go:140] synchonizing VolumeSnapshot[default/rbd-pvc-snapshot]: bound to: "", Completed: false
I0125 00:01:16.710948       1 snapshot_controller.go:189] syncUnreadySnapshot default/rbd-pvc-snapshot
I0125 00:01:16.710955       1 snapshot_controller.go:260] No VolumeSnapshotContent for VolumeSnapshot default/rbd-pvc-snapshot found
I0125 00:01:16.711085       1 util.go:99] storeObjectUpdate updating snapshot "default/rbd-pvc-snapshot" with version 274435
E0125 00:01:16.711125       1 snapshot_controller.go:310] createSnapshot [create-default/rbd-pvc-snapshot[56206229-2034-11e9-816a-1062eb3456cc]]: error occurred in createSnapshotOperation: failed to take snapshot of the volume, pvc-9f001a90202c11e9: "rpc error: code = NotFound desc = Source Volume ID csi-rbd-vol-9f098d01-202c-11e9-b0a2-1062eb3452d7 cannot found"
E0125 00:01:16.711162       1 goroutinemap.go:150] Operation for "create-default/rbd-pvc-snapshot[56206229-2034-11e9-816a-1062eb3456cc]" failed. No retries permitted until 2019-01-25 00:01:17.211133887 +0000 UTC m=+40.461163804 (durationBeforeRetry 500ms). Error: "failed to take snapshot of the volume, pvc-9f001a90202c11e9: \"rpc error: code = NotFound desc = Source Volume ID csi-rbd-vol-9f098d01-202c-11e9-b0a2-1062eb3452d7 cannot found\""
I0125 00:01:16.711205       1 event.go:221] Event(v1.ObjectReference{Kind:"VolumeSnapshot", Namespace:"default", Name:"rbd-pvc-snapshot", UID:"56206229-2034-11e9-816a-1062eb3456cc", APIVersion:"snapshot.storage.k8s.io/v1alpha1", ResourceVersion:"274435", FieldPath:""}): type: 'Warning' reason: 'SnapshotCreationFailed' Failed to create snapshot: failed to take snapshot of the volume, pvc-9f001a90202c11e9: "rpc error: code = NotFound desc = Source Volume ID csi-rbd-vol-9f098d01-202c-11e9-b0a2-1062eb3452d7 cannot found"

apiVersion: snapshot.storage.k8s.io/v1alpha1
kind: VolumeSnapshotClass
metadata:
  name: csi-rbdplugin-snapclass
snapshotter: csi-rbdplugin
parameters:
  adminid: admin
  imageFormat: "2"
  imageFeatures: layering
  pool: kube
  monitors: 192.168.111.20:6789, 192.168.111.21:6789, 192.168.111.22:6789
  csiSnapshotterSecretName: csi-rbd-secret
  csiSnapshotterSecretNamespace: default

NAMESPACE             NAME                                                          READY   STATUS      RESTARTS   AGE     IP             NODE          NOMINATED NODE   READINESS GATES
default               pod/ceph-8684949c6f-nf728                                     1/1     Running     0          6h16m   10.244.1.88    minas-hv011   <none>           <none>
default               pod/csi-rbdplugin-4brwd                                       2/2     Running     0          57m     192.168.0.27   minas-hv012   <none>           <none>
default               pod/csi-rbdplugin-attacher-0                                  1/1     Running     0          57m     10.244.2.74    minas-hv012   <none>           <none>
default               pod/csi-rbdplugin-knxsg                                       2/2     Running     0          57m     192.168.0.49   minas-hv011   <none>           <none>
default               pod/csi-rbdplugin-p2lw6                                       2/2     Running     0          57m     192.168.0.25   minas-hv010   <none>           <none>
default               pod/csi-rbdplugin-provisioner-0                               1/1     Running     0          57m     10.244.1.113   minas-hv011   <none>           <none>
default               pod/csi-snapshotter-0                                         1/1     Running     0          2m42s   10.244.2.76    minas-hv012   <none>           <none>
default               pod/csirbd-demo-pod                                           1/1     Running     0          18m     10.244.0.66    minas-hv010   <none>           <none>

kubectl get pvc
NAME      STATUS   VOLUME                 CAPACITY   ACCESS MODES   STORAGECLASS   AGE
rbd-pvc   Bound    pvc-9f001a90202c11e9   1Gi        RWO            csi-rbd        57m

kubectl describe volumesnapshot
Name:         rbd-pvc-snapshot
Namespace:    default
Labels:       <none>
Annotations:  <none>
API Version:  snapshot.storage.k8s.io/v1alpha1
Kind:         VolumeSnapshot
Metadata:
  Creation Timestamp:  2019-01-25T00:01:16Z
  Generation:          2
  Resource Version:    274435
  Self Link:           /apis/snapshot.storage.k8s.io/v1alpha1/namespaces/default/volumesnapshots/rbd-pvc-snapshot
  UID:                 56206229-2034-11e9-816a-1062eb3456cc
Spec:
  Snapshot Class Name:    csi-rbdplugin-snapclass
  Snapshot Content Name:  
  Source:
    Kind:  PersistentVolumeClaim
    Name:  rbd-pvc
Status:
  Creation Time:  <nil>
  Error:
    Message:     Failed to create snapshot: failed to take snapshot of the volume, pvc-9f001a90202c11e9: "rpc error: code = NotFound desc = Source Volume ID csi-rbd-vol-9f098d01-202c-11e9-b0a2-1062eb3452d7 cannot found"
    Time:        2019-01-25T00:01:16Z
  Ready:         false
  Restore Size:  <nil>
Events:
  Type     Reason                  Age    From                           Message
  ----     ------                  ----   ----                           -------
  Warning  SnapshotCreationFailed  3m28s  csi-snapshotter csi-rbdplugin  Failed to create snapshot: failed to take snapshot of the volume, pvc-9f001a90202c11e9: "rpc error: code = NotFound desc = Source Volume ID csi-rbd-vol-9f098d01-202c-11e9-b0a2-1062eb3452d7 cannot found"

rbd -p kube ls
pvc-9f001a90202c11e9

rbd -p kube snap ls pvc-9f001a90202c11e9

kubectl version
Client Version: version.Info{Major:"1", Minor:"13", GitVersion:"v1.13.2", GitCommit:"cff46ab41ff0bb44d8584413b598ad8360ec1def", GitTreeState:"clean", BuildDate:"2019-01-10T23:35:51Z", GoVersion:"go1.11.4", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"13", GitVersion:"v1.13.2", GitCommit:"cff46ab41ff0bb44d8584413b598ad8360ec1def", GitTreeState:"clean", BuildDate:"2019-01-10T23:28:14Z", GoVersion:"go1.11.4", Compiler:"gc", Platform:"linux/amd64"}

kube-apiserver
--authorization-mode=Node,RBAC
--feature-gates=VolumeSnapshotDataSource=true
--advertise-address=192.168.0.49
--allow-privileged=true
--client-ca-file=/etc/kubernetes/pki/ca.crt
--enable-admission-plugins=NodeRestriction
--enable-bootstrap-token-auth=true
--etcd-cafile=/etc/kubernetes/pki/etcd/ca.crt
--etcd-certfile=/etc/kubernetes/pki/apiserver-etcd-client.crt
--etcd-keyfile=/etc/kubernetes/pki/apiserver-etcd-client.key
--etcd-servers=https://127.0.0.1:2379
--insecure-port=0
--kubelet-client-certificate=/etc/kubernetes/pki/apiserver-kubelet-client.crt
--kubelet-client-key=/etc/kubernetes/pki/apiserver-kubelet-client.key
--kubelet-preferred-address-types=InternalIP,ExternalIP,Hostname
--proxy-client-cert-file=/etc/kubernetes/pki/front-proxy-client.crt
--proxy-client-key-file=/etc/kubernetes/pki/front-proxy-client.key
--requestheader-allowed-names=front-proxy-client
--requestheader-client-ca-file=/etc/kubernetes/pki/front-proxy-ca.crt
--requestheader-extra-headers-prefix=X-Remote-Extra-
--requestheader-group-headers=X-Remote-Group
--requestheader-username-headers=X-Remote-User
--secure-port=6443
--service-account-key-file=/etc/kubernetes/pki/sa.pub
--service-cluster-ip-range=10.96.0.0/12
--tls-cert-file=/etc/kubernetes/pki/apiserver.crt
--tls-private-key-file=/etc/kubernetes/pki/apiserver.key

// Generating Volume Name and Volume ID, as according to CSI spec they MUST be different

    # Ceph users for operating RBD
    adminid: admin
    userid: kubernetes

kind: Role
apiVersion: rbac.authorization.k8s.io/v1
metadata:
  namespace: default
  name: rbd-configmap-updater
rules:
- apiGroups: [""]
  resources: ["configmaps"]
  verbs: ["create", "update", "patch", "list", "get", "delete"]

---
kind: RoleBinding
apiVersion: rbac.authorization.k8s.io/v1
metadata:
  namespace: default
  name: rbd-node-rb
subjects:
  - kind: ServiceAccount
    name: rbd-cluster-sa
    namespace: default
roleRef:
  kind: Role
  namespace: default
  name: rbd-configmap-updater
  apiGroup: rbac.authorization.k8s.io

warning: ignoring symlink /go/src/github.com/ceph/ceph-csi/vendor/k8s.io/kubernetes/cluster/gce/cos
warning: ignoring symlink /go/src/github.com/ceph/ceph-csi/vendor/k8s.io/kubernetes/cluster/gce/custom
warning: ignoring symlink /go/src/github.com/ceph/ceph-csi/vendor/k8s.io/kubernetes/cluster/gce/ubuntu
package github.com/gman0/ceph-csi/pkg/cephfs: cannot find package "github.com/gman0/ceph-csi/pkg/cephfs" in any of:
        /usr/local/go/src/github.com/gman0/ceph-csi/pkg/cephfs (from $GOROOT)
        /go/src/github.com/gman0/ceph-csi/pkg/cephfs (from $GOPATH)

package github.com/gman0/ceph-csi/pkg/cephfs: cannot find package "github.com/gman0/ceph-csi/pkg/cephfs" in any of:
        /usr/local/go/src/github.com/gman0/ceph-csi/pkg/cephfs (from $GOROOT)
        /go/src/github.com/gman0/ceph-csi/pkg/cephfs (from $GOPATH)

# make rbdplugin-container
if [ ! -d ./vendor ]; then dep ensure; fi
CGO_ENABLED=0 GOOS=linux go build -a -ldflags '-extldflags "-static"' -o  _output/rbdplugin ./rbd
cp _output/rbdplugin  deploy/rbd/docker
docker build -t : deploy/rbd/docker
invalid argument ":" for "-t, --tag" flag: invalid reference format
See 'docker build --help'.
Makefile:34: recipe for target 'rbdplugin-container' failed
make: *** [rbdplugin-container] Error 125

  $ kubectl get pod web-server-76bdb8c758-b9m7d 
  NAME                          READY     STATUS    RESTARTS   AGE
  web-server-76bdb8c758-b9m7d   1/1       Running   0          3m

  $ kubectl exec -it web-server-76bdb8c758-b9m7d bash
  root@web-server-76bdb8c758-b9m7d:/# mount |grep ceph  
  ceph-fuse on /var/lib/www/html type fuse.ceph-fuse (rw,nosuid,nodev,relatime,user_id=0,group_id=0,allow_other)

  (inside pod)
  root@web-server-76bdb8c758-b9m7d:/# touch /var/lib/www/html/test
  root@web-server-76bdb8c758-b9m7d:/# exit

  $ kubectl scale --replicas=2 deployment web-server

  $ kubectl get pod
  web-server-76bdb8c758-b9m7d   1/1       Running             0          25m
  web-server-76bdb8c758-w499x   0/1       ContainerCreating   0          18m

  $  kubectl logs csi-cephfsplugin-4sbnr csi-cephfsplugin
  ...
  ceph-fuse[452]: starting ceph client
  fuse: mountpoint is not empty
  fuse: if you are sure this is safe, use the 'nonempty' mount option
  ceph-fuse[452]: fuse failed to start
  2018-07-31 06:46:31.268 7fd5523cec00 -1 fuse_mount(mountpoint=/var/lib/kubelet/plugins/csi-cephfsplugin/controller/volumes/vol-8f3200c0-948c-11e8-9d90-54e1ad486e52) failed.

    if metadataStore == "k8s_configmap" {
		glog.Infof("cache-perister: using kubernetes configmap as metadata cache persister")
		k8scm := &K8sCMCache{}
		k8scm.Client = NewK8sClient()
		k8scm.Namespace = GetK8sNamespace()
		return k8scm, nil
	} else if metadataStore == "node" {
		glog.Infof("cache-persister: using node as metadata cache persister")
		nc := &NodeCache{}
		nc.BasePath = PluginFolder + "/" + driverName
		return nc, nil
	}
    return nil, errors.New("cache-persister: couldn't parse metadatastorage flag")

i-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty
root       561     1  0 17:51 ?        00:00:00 ceph-fuse /var/lib/kubelet/plugins_registry/csi-cephfsplugin/controller/volumes/root-csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f -c /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty
root       563   561  0 17:51 ?        00:00:00 ceph-fuse /var/lib/kubelet/plugins_registry/csi-cephfsplugin/controller/volumes/root-csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f -c /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty
root       580     1  0 17:51 ?        00:00:00 ceph-fuse /var/lib/kubelet/plugins_registry/csi-cephfsplugin/controller/volumes/root-csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f -c /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty
root       582   580  0 17:51 ?        00:00:00 ceph-fuse /var/lib/kubelet/plugins_registry/csi-cephfsplugin/controller/volumes/root-csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f -c /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty
root       600     1  0 17:52 ?        00:00:00 ceph-fuse /var/lib/kubelet/plugins_registry/csi-cephfsplugin/controller/volumes/root-csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f -c /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty
root       604   600  0 17:52 ?        00:00:00 ceph-fuse /var/lib/kubelet/plugins_registry/csi-cephfsplugin/controller/volumes/root-csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f -c /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty
root       621     1  0 17:52 ?        00:00:00 ceph-fuse /var/lib/kubelet/plugins_registry/csi-cephfsplugin/controller/volumes/root-csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f -c /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty
root       623   621  0 17:52 ?        00:00:00 ceph-fuse /var/lib/kubelet/plugins_registry/csi-cephfsplugin/controller/volumes/root-csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f -c /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty
root       640     1  0 17:53 ?        00:00:00 ceph-fuse /var/lib/kubelet/plugins_registry/csi-cephfsplugin/controller/volumes/root-csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f -c /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty
root       642   640  0 17:53 ?        00:00:00 ceph-fuse /var/lib/kubelet/plugins_registry/csi-cephfsplugin/controller/volumes/root-csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f -c /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty
root       659     1  0 17:53 ?        00:00:00 ceph-fuse /var/lib/kubelet/plugins_registry/csi-cephfsplugin/controller/volumes/root-csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f -c /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty
root       663   659  0 17:53 ?        00:00:00 ceph-fuse /var/lib/kubelet/plugins_registry/csi-cephfsplugin/controller/volumes/root-csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f -c /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty
root       680     1  0 17:53 ?        00:00:00 ceph-fuse /var/lib/kubelet/plugins_registry/csi-cephfsplugin/controller/volumes/root-csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f -c /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty
root       682   680  0 17:53 ?        00:00:00 ceph-fuse /var/lib/kubelet/plugins_registry/csi-cephfsplugin/controller/volumes/root-csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f -c /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty
root       714     1  0 17:53 ?        00:00:00 ceph-fuse /var/lib/kubelet/plugins_registry/csi-cephfsplugin/controller/volumes/root-csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f -c /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty
root       717   714  0 17:53 ?        00:00:00 ceph-fuse /var/lib/kubelet/plugins_registry/csi-cephfsplugin/controller/volumes/root-csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f -c /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.conf -n client.admin --keyring /etc/ceph/ceph.share.csi-cephfs-pvc-279b619c-1e6d-11e9-8331-52540035463f.client.admin.keyring -r / -o nonempty

df: ‘/var/lib/kubelet/pods/d132d662-d1d1-11e8-8297-28d24488ad30/volumes/kubernetes.io~csi/pvc-d123868ad1d111e8/mount’: Transport endpoint is not connected

[root@kube1 /]# rbd snap ls pvc-aa394dc4-207e-11e9-a1e9-52540088830b
SNAPID NAME                                                                                        SIZE TIMESTAMP                
     4 csi-rbd-pvc-aa394dc4-207e-11e9-a1e9-52540088830b-snap-ec0249b2-209a-11e9-98c8-5254005d68f0 1 GiB Fri Jan 25 12:15:37 2019 
     5 csi-rbd-pvc-aa394dc4-207e-11e9-a1e9-52540088830b-snap-028380c1-209b-11e9-98c8-5254005d68f0 1 GiB Fri Jan 25 12:16:14 2019 
     6 csi-rbd-pvc-aa394dc4-207e-11e9-a1e9-52540088830b-snap-17cefbf8-209b-11e9-98c8-5254005d68f0 1 GiB Fri Jan 25 12:16:50 2019 
     7 csi-rbd-pvc-aa394dc4-207e-11e9-a1e9-52540088830b-snap-70d9119f-209e-11e9-98c8-5254005d68f0 1 GiB Fri Jan 25 12:40:49 2019 

0125 12:40:48.168294       1 connection.go:271] GRPC request: {"name":"snapshot-70cc0ba9-209e-11e9-a1e9-52540088830b","parameters":{"csiSnapshotterSecretName":"csi-rbd-secret","csiSnapshotterSecretNamespace":"default","monitors":"rook-ceph-mon-a.rook-ceph.svc.cluster.local:6789","pool":"rbd"},"secrets":"***stripped***","source_volume_id":"csi-rbd-vol-aa48be19-207e-11e9-98c8-5254005d68f0"}
I0125 12:40:49.321851       1 connection.go:273] GRPC response: {"snapshot":{"creation_time":{"seconds":1548420049301024500},"ready_to_use":true,"size_bytes":1073741824,"snapshot_id":"csi-rbd-pvc-aa394dc4-207e-11e9-a1e9-52540088830b-snap-70d9119f-209e-11e9-98c8-5254005d68f0","source_volume_id":"csi-rbd-vol-aa48be19-207e-11e9-98c8-5254005d68f0"}}
I0125 12:40:49.322860       1 connection.go:274] GRPC error: <nil>
I0125 12:40:49.322871       1 connection.go:219] CSI CreateSnapshot: snapshot-70cc0ba9-209e-11e9-a1e9-52540088830b driver name [csi-rbdplugin] snapshot ID [csi-rbd-pvc-aa394dc4-207e-11e9-a1e9-52540088830b-snap-70d9119f-209e-11e9-98c8-5254005d68f0] time stamp [&{1548420049301024459 0 {} [] 0}] size [1073741824] readyToUse [true]
I0125 12:40:49.322941       1 snapshot_controller.go:405] updateSnapshotStatusWithEvent[default/rbd-pvc-snapshot]
I0125 12:40:49.333687       1 util.go:135] storeObjectUpdate updating snapshot "default/rbd-pvc-snapshot" with version 33150
E0125 12:40:49.333760       1 snapshot_controller.go:363] createSnapshot [create-default/rbd-pvc-snapshot[70cc0ba9-209e-11e9-a1e9-52540088830b]]: error occurred in createSnapshotOperation: failed to take snapshot of the volume, pvc-aa394dc4-207e-11e9-a1e9-52540088830b: "timestamp: seconds:1548420049301024459  after 10000-01-01"
E0125 12:40:49.333825       1 goroutinemap.go:150] Operation for "create-default/rbd-pvc-snapshot[70cc0ba9-209e-11e9-a1e9-52540088830b]" failed. No retries permitted until 2019-01-25 12:40:49.833787574 +0000 UTC m=+2354.408098764 (durationBeforeRetry 500ms). Error: "failed to take snapshot of the volume, pvc-aa394dc4-207e-11e9-a1e9-52540088830b: \"timestamp: seconds:1548420049301024459  after 10000-01-01\""
I0125 12:40:49.333688       1 snapshot_controller_base.go:169] enqueued "default/rbd-pvc-snapshot" for sync
I0125 12:40:49.334159       1 snapshot_controller_base.go:201] snapshotWorker[default/rbd-pvc-snapshot]
I0125 12:40:49.334166       1 snapshot_controller_base.go:204] snapshotWorker: snapshot namespace [default] name [rbd-pvc-snapshot]
I0125 12:40:49.334173       1 snapshot_controller_base.go:347] checkAndUpdateSnapshotClass [rbd-pvc-snapshot]: VolumeSnapshotClassName [csi-rbdplugin-snapclass]
I0125 12:40:49.334177       1 snapshot_controller.go:878] getSnapshotClass: VolumeSnapshotClassName [csi-rbdplugin-snapclass]
I0125 12:40:49.334183       1 snapshot_controller_base.go:364] VolumeSnapshotClass Snapshotter [csi-rbdplugin] Snapshot Controller snapshotterName [csi-rbdplugin]
I0125 12:40:49.334188       1 snapshot_controller_base.go:215] passed checkAndUpdateSnapshotClass for snapshot "default/rbd-pvc-snapshot"
I0125 12:40:49.334194       1 snapshot_controller_base.go:377] updateSnapshot "default/rbd-pvc-snapshot"
I0125 12:40:49.334201       1 util.go:135] storeObjectUpdate updating snapshot "default/rbd-pvc-snapshot" with version 33150
I0125 12:40:49.334209       1 snapshot_controller.go:176] synchonizing VolumeSnapshot[default/rbd-pvc-snapshot]: bound to: "", Completed: false
I0125 12:40:49.334214       1 snapshot_controller.go:242] syncUnreadySnapshot default/rbd-pvc-snapshot
I0125 12:40:49.334219       1 snapshot_controller.go:313] No VolumeSnapshotContent for VolumeSnapshot default/rbd-pvc-snapshot found
I0125 12:40:49.334232       1 event.go:221] Event(v1.ObjectReference{Kind:"VolumeSnapshot", Namespace:"default", Name:"rbd-pvc-snapshot", UID:"70cc0ba9-209e-11e9-a1e9-52540088830b", APIVersion:"snapshot.storage.k8s.io/v1alpha1", ResourceVersion:"33150", FieldPath:""}): type: 'Warning' reason: 'SnapshotCreationFailed' Failed to create snapshot: failed to take snapshot of the volume, pvc-aa394dc4-207e-11e9-a1e9-52540088830b: "timestamp: seconds:1548420049301024459  after 10000-01-01"

[🎩︎]mrajanna@localhost ceph-csi $]cat main.go 
package main

import (
	"fmt"
	"time"

	"github.com/golang/protobuf/ptypes"
	"github.com/golang/protobuf/ptypes/timestamp"
)

func timestampToUnixTime(t *timestamp.Timestamp) (int64, error) {
	time, err := ptypes.Timestamp(t)
	if err != nil {
		return -1, err
	}
	// TODO: clean this up, we probably don't need this translation layer
	// and can just use time.Time
	return time.UnixNano(), nil
}

func main() {
	t := &timestamp.Timestamp{
		Seconds: time.Now().UnixNano(),
	}
	_, e := timestampToUnixTime(t)
fmt.Println("error in conversion",e)
}
[🎩︎]mrajanna@localhost ceph-csi $]
[🎩︎]mrajanna@localhost ceph-csi $]go run main.go 
error in conversion timestamp: seconds:1548422522284252217  after 10000-01-01

I1010 09:49:43.820983       1 rbd_util.go:124] rbd: create pvc-c46136c5-cc71-11e8-b494-deadbeef0100 size 0G format 2 (features: layering) using mon 192.168.7.2:6789,192.168.7.4:6789,192.168.7.6:6789,192.168.7.8:6789, pool rbd id admin key AQAe07xbq/TsOhAAkLrH6vaRDo/xxVZg/Y6qJg==

# rbd info pvc-c46136c5-cc71-11e8-b494-deadbeef0100
rbd image 'pvc-c46136c5-cc71-11e8-b494-deadbeef0100':
	size 0 B in 0 objects
	order 22 (4 MiB objects)
	id: 5e36643c9869
	block_name_prefix: rbd_data.5e36643c9869
	format: 2
	features: layering
	op_features: 
	flags: 
	create_timestamp: Wed Oct 10 09:49:43 2018

# setfattr -n ceph.quota.max_bytes -v 5368709120 /var/lib/kubelet/plugins/csi-cephfsplugin/controller/volumes/root-csi-cephfs-378acacb-e5ed-11e8-9b8b-c60474a907dc
sh: setfattr: not found

# setfattr -n ceph.quota.max_bytes -v 5368709120 /var/lib/kubelet/plugins/csi-cephfsplugin/controller/volumes/root-csi-cephfs-378acacb-e5ed-11e8-9b8b-c60474a907dc
setfattr: root-csi-cephfs-378acacb-e5ed-11e8-9b8b-c60474a907dc: Operation not supported

I0808 15:05:19.650648       1 mount_linux.go:198] Cannot run systemd-run, assuming non-systemd OS
I0808 15:05:19.650672       1 mount_linux.go:199] systemd-run failed with: exit status 1
I0808 15:05:19.650688       1 mount_linux.go:200] systemd-run output: Failed to create bus connection: No such file or directory

<snip>
STEP: checking the claim
STEP: checking the PV
STEP: checking the created volume is writable and has the PV's mount options
Aug 10 16:11:27.635: INFO: Waiting up to 15m0s for pod "pvc-volume-tester-bv9xm" in namespace "e2e-tests-csi-moc
k-plugin-gtvnf" to be "success or failure"
Aug 10 16:11:27.653: INFO: Pod "pvc-volume-tester-bv9xm": Phase="Pending", Reason="", readiness=false. Elapsed:
18.335075ms
Aug 10 16:11:29.656: INFO: Pod "pvc-volume-tester-bv9xm": Phase="Pending", Reason="", readiness=false. Elapsed:
2.021046636s
<snip>
Aug 10 16:15:37.809: INFO: Pod "pvc-volume-tester-bv9xm": Phase="Pending", Reason="", readiness=false. Elapsed: 
4m10.174227655s     

# kubectl describe pod/pvc-volume-tester-bv9xm -n e2e-tests-csi-mock-plugin-gtvnf
<snip>
Events:
  Type     Reason                  Age                  From                     Message
  ----     ------                  ----                 ----                     -------
  Normal   SuccessfulAttachVolume  3m21s                attachdetach-controller  AttachVolume.Attach succeeded for volume "pvc-06c1380b9cb811e8"
  Warning  FailedMount             78s                  kubelet, 127.0.0.1       Unable to mount volumes for pod "pvc-volume-tester-bv9xm_e2e-tests-csi-mock-plugin-gtvnf(0927cd50-9cb8-11e8-bdb4-525400b854f0)": timeout expired waiting for volumes to attach or mount for pod "e2e-tests-csi-mock-plugin-gtvnf"/"pvc-volume-tester-bv9xm". list of unmounted volumes=[my-volume]. list of unattached volumes=[my-volume default-token-27qzg]
  Warning  FailedMount             65s (x9 over 3m13s)  kubelet, 127.0.0.1       MountVolume.MountDevice failed for volume "pvc-06c1380b9cb811e8" : rpc error: code = InvalidArgument desc = stage secrets cannot be nil or empty

$ kubectl create -f vendor/github.com/ceph/ceph-csi/examples/rbd/pvc.yaml 
persistentvolumeclaim "rbd-pvc" created
pohly@pohly-desktop:/nvme/gopath/src/github.com/intel/oim$

provisioner: I1008 08:01:35.609957       1 reflector.go:286] github.com/kubernetes-csi/external-provisioner/vendor/github.com/kubernetes-incubator/external-storage/lib/controller/controller.go:496: forcing resync
provisioner: I1008 08:01:35.610034       1 reflector.go:286] github.com/kubernetes-csi/external-provisioner/vendor/github.com/kubernetes-incubator/external-storage/lib/controller/controller.go:497: forcing resync
provisioner: I1008 08:01:35.610242       1 reflector.go:286] github.com/kubernetes-csi/external-provisioner/vendor/github.com/kubernetes-incubator/external-storage/lib/controller/controller.go:498: forcing resync
kubeprovisioner: I1008 08:01:38.335887       1 controller.go:1167] scheduleOperation[lock-provision-default/rbd-pvc[59a6fe14-cad0-11e8-a12b-deadbeef0100]]
 provisioner: I1008 08:01:38.358055       1 leaderelection.go:156] attempting to acquire leader lease...
provisioner: I1008 08:01:38.363500       1 leaderelection.go:178] successfully acquired lease to provision for pvc default/rbd-pvc
provisioner: I1008 08:01:38.363569       1 controller.go:1167] scheduleOperation[provision-default/rbd-pvc[59a6fe14-cad0-11e8-a12b-deadbeef0100]]
provisioner: I1008 08:01:38.363597       1 controller.go:836] provisionClaimOperation [default/rbd-pvc] started, class: "csi-rbd"
provisioner: I1008 08:01:38.363596       1 controller.go:988] claim update received: MODIFIED default/rbd-pvc Pending
provisioner: I1008 08:01:38.366059       1 controller.go:103] GRPC call: /csi.v0.Identity/GetPluginCapabilities
provisioner: I1008 08:01:38.366077       1 controller.go:104] GRPC request: 
rbdplugin: I1008 08:01:38.366930       1 utils.go:96] GRPC call: /csi.v0.Identity/GetPluginCapabilities
rbdplugin: I1008 08:01:38.366977       1 utils.go:97] GRPC request: 
rbdplugin: I1008 08:01:38.367012       1 utils.go:102] GRPC response: capabilities:<service:<type:CONTROLLER_SERVICE > > 
provisioner: I1008 08:01:38.367756       1 controller.go:106] GRPC response: capabilities:<service:<type:CONTROLLER_SERVICE > > 
provisioner: I1008 08:01:38.367836       1 controller.go:107] GRPC error: <nil>
provisioner: I1008 08:01:38.367855       1 controller.go:103] GRPC call: /csi.v0.Controller/ControllerGetCapabilities
provisioner: I1008 08:01:38.367861       1 controller.go:104] GRPC request: 
provisioner: I1008 08:01:38.368525       1 controller.go:106] GRPC response: capabilities:<rpc:<type:CREATE_DELETE_VOLUME > > capabilities:<rpc:<type:PUBLISH_UNPUBLISH_VOLUME > > capabilities:<rpc:<type:CREATE_DELETE_SNAPSHOT > > capabilities:<rpc:<type:LIST_SNAPSHOTS > > 
provisioner: I1008 08:01:38.368617       1 controller.go:107] GRPC error: <nil>
provisioner: I1008 08:01:38.368633       1 controller.go:103] GRPC call: /csi.v0.Identity/GetPluginInfo
provisioner: I1008 08:01:38.368638       1 controller.go:104] GRPC request: 
provisioner: I1008 08:01:38.369051       1 controller.go:106] GRPC response: name:"csi-rbdplugin" vendor_version:"0.3.0" 
provisioner: I1008 08:01:38.369104       1 controller.go:107] GRPC error: <nil>
rbdplugin: I1008 08:01:38.368070       1 utils.go:96] GRPC call: /csi.v0.Controller/ControllerGetCapabilities
rbdplugin: I1008 08:01:38.368085       1 utils.go:97] GRPC request: 
rbdplugin: I1008 08:01:38.368120       1 controllerserver-default.go:82] Using default ControllerGetCapabilities
rbdplugin: I1008 08:01:38.368126       1 utils.go:102] GRPC response: capabilities:<rpc:<type:CREATE_DELETE_VOLUME > > capabilities:<rpc:<type:PUBLISH_UNPUBLISH_VOLUME > > capabilities:<rpc:<type:CREATE_DELETE_SNAPSHOT > > capabilities:<rpc:<type:LIST_SNAPSHOTS > > 
rbdplugin: I1008 08:01:38.368866       1 utils.go:96] GRPC call: /csi.v0.Identity/GetPluginInfo
rbdplugin: I1008 08:01:38.368889       1 utils.go:97] GRPC request: 
rbdplugin: I1008 08:01:38.368904       1 identityserver-default.go:32] Using default GetPluginInfo
rbdplugin: I1008 08:01:38.368910       1 utils.go:102] GRPC response: name:"csi-rbdplugin" vendor_version:"0.3.0" 
provisioner: I1008 08:01:38.372762       1 controller.go:103] GRPC call: /csi.v0.Controller/CreateVolume
provisioner: I1008 08:01:38.372775       1 controller.go:104] GRPC request: name:"pvc-59a6fe14cad011e8" capacity_range:<required_bytes:1073741824 > volume_capabilities:<mount:<> access_mode:<mode:SINGLE_NODE_WRITER > > parameters:<key:"adminid" value:"admin" > parameters:<key:"csiNodePublishSecretName" value:"csi-rbd-secret" > parameters:<key:"csiNodePublishSecretNamespace" value:"default" > parameters:<key:"csiProvisionerSecretName" value:"csi-rbd-secret" > parameters:<key:"csiProvisionerSecretNamespace" value:"default" > parameters:<key:"imageFeatures" value:"layering" > parameters:<key:"imageFormat" value:"2" > parameters:<key:"monValueFromSecret" value:"monitors" > parameters:<key:"pool" value:"rbd" > parameters:<key:"userid" value:"kubernetes" > controller_create_secrets:<key:"admin" value:"AQD0Crtb7+x9OhAAK4DAHLj+hXeA3Kjzs1xWgA==\n" > controller_create_secrets:<key:"kubernetes" value:"AQD1Crtbpr0aOxAAimVzMGWaCnaiNOc8UiWvzg==\n" > controller_create_secrets:<key:"monitors" value:"192.168.7.2:6789,192.168.7.4:6789,192.168.7.6:6789,192.168.7.8:6789" > 
rbdplugin: I1008 08:01:38.373483       1 utils.go:96] GRPC call: /csi.v0.Controller/CreateVolume
rbdplugin: I1008 08:01:38.373495       1 utils.go:97] GRPC request: name:"pvc-59a6fe14cad011e8" capacity_range:<required_bytes:1073741824 > volume_capabilities:<mount:<> access_mode:<mode:SINGLE_NODE_WRITER > > parameters:<key:"adminid" value:"admin" > parameters:<key:"csiNodePublishSecretName" value:"csi-rbd-secret" > parameters:<key:"csiNodePublishSecretNamespace" value:"default" > parameters:<key:"csiProvisionerSecretName" value:"csi-rbd-secret" > parameters:<key:"csiProvisionerSecretNamespace" value:"default" > parameters:<key:"imageFeatures" value:"layering" > parameters:<key:"imageFormat" value:"2" > parameters:<key:"monValueFromSecret" value:"monitors" > parameters:<key:"pool" value:"rbd" > parameters:<key:"userid" value:"kubernetes" > controller_create_secrets:<key:"admin" value:"AQD0Crtb7+x9OhAAK4DAHLj+hXeA3Kjzs1xWgA==\n" > controller_create_secrets:<key:"kubernetes" value:"AQD1Crtbpr0aOxAAimVzMGWaCnaiNOc8UiWvzg==\n" > controller_create_secrets:<key:"monitors" value:"192.168.7.2:6789,192.168.7.4:6789,192.168.7.6:6789,192.168.7.8:6789" > 
rbdplugin: I1008 08:01:38.373774       1 rbd_util.go:159] rbd: status pvc-59a6fe14cad011e8 using mon 192.168.7.2:6789,192.168.7.4:6789,192.168.7.6:6789,192.168.7.8:6789, pool rbd id kubernetes key AQD1Crtbpr0aOxAAimVzMGWaCnaiNOc8UiWvzg==
  rbdplugin: I1008 08:01:38.456663       1 rbd_util.go:123] rbd: create pvc-59a6fe14cad011e8 size 1G format 2 (features: layering) using mon 192.168.7.2:6789,192.168.7.4:6789,192.168.7.6:6789,192.168.7.8:6789, pool rbd id admin key AQD0Crtb7+x9OhAAK4DAHLj+hXeA3Kjzs1xWgA==
provisioner: I1008 08:01:40.370639       1 controller.go:988] claim update received: MODIFIED default/rbd-pvc Pending
provisioner: I1008 08:01:40.370973       1 leaderelection.go:215] succesfully renewed lease to provision for pvc default/rbd-pvc
provisioner: I1008 08:01:42.377545       1 leaderelection.go:215] succesfully renewed lease to provision for pvc default/rbd-pvc
provisioner: I1008 08:01:42.377580       1 controller.go:988] claim update received: MODIFIED default/rbd-pvc Pending
provisioner: I1008 08:01:44.386215       1 controller.go:988] claim update received: MODIFIED default/rbd-pvc Pending
provisioner: I1008 08:01:44.386246       1 leaderelection.go:215] succesfully renewed lease to provision for pvc default/rbd-pvc
provisioner: I1008 08:01:46.393559       1 leaderelection.go:215] succesfully renewed lease to provision for pvc default/rbd-pvc
provisioner: I1008 08:01:46.393587       1 controller.go:988] claim update received: MODIFIED default/rbd-pvc Pending
provisioner: I1008 08:01:48.372945       1 controller.go:106] GRPC response: 
provisioner: I1008 08:01:48.373023       1 controller.go:107] GRPC error: rpc error: code = DeadlineExceeded desc = context deadline exceeded
provisioner: W1008 08:01:48.373039       1 controller.go:354] CreateVolume timeout: 10s has expired, operation will be retried
provisioner: I1008 08:01:48.407423       1 leaderelection.go:215] succesfully renewed lease to provision for pvc default/rbd-pvc
provisioner: I1008 08:01:48.407635       1 controller.go:988] claim update received: MODIFIED default/rbd-pvc Pending
provisioner: I1008 08:01:50.414551       1 leaderelection.go:215] succesfully renewed lease to provision for pvc default/rbd-pvc
provisioner: I1008 08:01:50.414565       1 controller.go:988] claim update received: MODIFIED default/rbd-pvc Pending
provisioner: I1008 08:01:50.610254       1 reflector.go:286] github.com/kubernetes-csi/external-provisioner/vendor/github.com/kubernetes-incubator/external-storage/lib/controller/controller.go:496: forcing resync
provisioner: I1008 08:01:50.610245       1 reflector.go:286] github.com/kubernetes-csi/external-provisioner/vendor/github.com/kubernetes-incubator/external-storage/lib/controller/controller.go:497: forcing resync
provisioner: I1008 08:01:50.610372       1 controller.go:1167] scheduleOperation[provision-default/rbd-pvc[59a6fe14-cad0-11e8-a12b-deadbeef0100]]
provisioner: I1008 08:01:50.610407       1 reflector.go:286] github.com/kubernetes-csi/external-provisioner/vendor/github.com/kubernetes-incubator/external-storage/lib/controller/controller.go:498: forcing resync
provisioner: I1008 08:01:50.610411       1 controller.go:1172] operation "provision-default/rbd-pvc[59a6fe14-cad0-11e8-a12b-deadbeef0100]" is already running, skipping
provisioner: I1008 08:01:52.421748       1 leaderelection.go:215] succesfully renewed lease to provision for pvc default/rbd-pvc
provisioner: I1008 08:01:52.421750       1 controller.go:988] claim update received: MODIFIED default/rbd-pvc Pending
rbdplugin: I1008 08:01:52.869954       1 controllerserver.go:132] create volume pvc-59a6fe14cad011e8
rbdplugin: I1008 08:01:52.870255       1 rbd_util.go:319] rbd: successfully saved volInfo: &{VolName:pvc-59a6fe14cad011e8 VolID:csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101 Monitors: MonValueFromSecret:monitors Pool:rbd ImageFormat:2 ImageFeatures:layering VolSize:1073741824 AdminId:admin UserId:kubernetes Mounter:rbd} into file: /var/lib/kubelet/plugins/csi-rbdplugin/controller/csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101.json
rbdplugin: I1008 08:01:52.870384       1 utils.go:102] GRPC response: volume:<capacity_bytes:1073741824 id:"csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101" attributes:<key:"adminid" value:"admin" > attributes:<key:"csiNodePublishSecretName" value:"csi-rbd-secret" > attributes:<key:"csiNodePublishSecretNamespace" value:"default" > attributes:<key:"csiProvisionerSecretName" value:"csi-rbd-secret" > attributes:<key:"csiProvisionerSecretNamespace" value:"default" > attributes:<key:"imageFeatures" value:"layering" > attributes:<key:"imageFormat" value:"2" > attributes:<key:"monValueFromSecret" value:"monitors" > attributes:<key:"pool" value:"rbd" > attributes:<key:"userid" value:"kubernetes" > > 
provisioner: I1008 08:01:53.373233       1 controller.go:103] GRPC call: /csi.v0.Controller/CreateVolume
provisioner: I1008 08:01:53.373258       1 controller.go:104] GRPC request: name:"pvc-59a6fe14cad011e8" capacity_range:<required_bytes:1073741824 > volume_capabilities:<mount:<> access_mode:<mode:SINGLE_NODE_WRITER > > parameters:<key:"adminid" value:"admin" > parameters:<key:"csiNodePublishSecretName" value:"csi-rbd-secret" > parameters:<key:"csiNodePublishSecretNamespace" value:"default" > parameters:<key:"csiProvisionerSecretName" value:"csi-rbd-secret" > parameters:<key:"csiProvisionerSecretNamespace" value:"default" > parameters:<key:"imageFeatures" value:"layering" > parameters:<key:"imageFormat" value:"2" > parameters:<key:"monValueFromSecret" value:"monitors" > parameters:<key:"pool" value:"rbd" > parameters:<key:"userid" value:"kubernetes" > controller_create_secrets:<key:"admin" value:"AQD0Crtb7+x9OhAAK4DAHLj+hXeA3Kjzs1xWgA==\n" > controller_create_secrets:<key:"kubernetes" value:"AQD1Crtbpr0aOxAAimVzMGWaCnaiNOc8UiWvzg==\n" > controller_create_secrets:<key:"monitors" value:"192.168.7.2:6789,192.168.7.4:6789,192.168.7.6:6789,192.168.7.8:6789" > 
rbdplugin: I1008 08:01:53.373919       1 utils.go:96] GRPC call: /csi.v0.Controller/CreateVolume
rbdplugin: I1008 08:01:53.373948       1 utils.go:97] GRPC request: name:"pvc-59a6fe14cad011e8" capacity_range:<required_bytes:1073741824 > volume_capabilities:<mount:<> access_mode:<mode:SINGLE_NODE_WRITER > > parameters:<key:"adminid" value:"admin" > parameters:<key:"csiNodePublishSecretName" value:"csi-rbd-secret" > parameters:<key:"csiNodePublishSecretNamespace" value:"default" > parameters:<key:"csiProvisionerSecretName" value:"csi-rbd-secret" > parameters:<key:"csiProvisionerSecretNamespace" value:"default" > parameters:<key:"imageFeatures" value:"layering" > parameters:<key:"imageFormat" value:"2" > parameters:<key:"monValueFromSecret" value:"monitors" > parameters:<key:"pool" value:"rbd" > parameters:<key:"userid" value:"kubernetes" > controller_create_secrets:<key:"admin" value:"AQD0Crtb7+x9OhAAK4DAHLj+hXeA3Kjzs1xWgA==\n" > controller_create_secrets:<key:"kubernetes" value:"AQD1Crtbpr0aOxAAimVzMGWaCnaiNOc8UiWvzg==\n" > controller_create_secrets:<key:"monitors" value:"192.168.7.2:6789,192.168.7.4:6789,192.168.7.6:6789,192.168.7.8:6789" > 
rbdplugin: I1008 08:01:53.374047       1 utils.go:102] GRPC response: volume:<capacity_bytes:1073741824 id:"csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101" attributes:<key:"adminid" value:"admin" > attributes:<key:"csiNodePublishSecretName" value:"csi-rbd-secret" > attributes:<key:"csiNodePublishSecretNamespace" value:"default" > attributes:<key:"csiProvisionerSecretName" value:"csi-rbd-secret" > attributes:<key:"csiProvisionerSecretNamespace" value:"default" > attributes:<key:"imageFeatures" value:"layering" > attributes:<key:"imageFormat" value:"2" > attributes:<key:"monValueFromSecret" value:"monitors" > attributes:<key:"pool" value:"rbd" > attributes:<key:"userid" value:"kubernetes" > > 
provisioner: I1008 08:01:53.374459       1 controller.go:106] GRPC response: volume:<capacity_bytes:1073741824 id:"csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101" attributes:<key:"adminid" value:"admin" > attributes:<key:"csiNodePublishSecretName" value:"csi-rbd-secret" > attributes:<key:"csiNodePublishSecretNamespace" value:"default" > attributes:<key:"csiProvisionerSecretName" value:"csi-rbd-secret" > attributes:<key:"csiProvisionerSecretNamespace" value:"default" > attributes:<key:"imageFeatures" value:"layering" > attributes:<key:"imageFormat" value:"2" > attributes:<key:"monValueFromSecret" value:"monitors" > attributes:<key:"pool" value:"rbd" > attributes:<key:"userid" value:"kubernetes" > > 
provisioner: I1008 08:01:53.374548       1 controller.go:107] GRPC error: <nil>
provisioner: I1008 08:01:53.374569       1 controller.go:367] create volume rep: {CapacityBytes:1073741824 Id:csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101 Attributes:map[csiNodePublishSecretName:csi-rbd-secret csiProvisionerSecretNamespace:default monValueFromSecret:monitors imageFormat:2 pool:rbd csiProvisionerSecretName:csi-rbd-secret imageFeatures:layering userid:kubernetes adminid:admin csiNodePublishSecretNamespace:default] ContentSource:<nil> AccessibleTopology:[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
provisioner: I1008 08:01:53.374645       1 controller.go:424] successfully created PV {GCEPersistentDisk:nil AWSElasticBlockStore:nil HostPath:nil Glusterfs:nil NFS:nil RBD:nil ISCSI:nil Cinder:nil CephFS:nil FC:nil Flocker:nil FlexVolume:nil AzureFile:nil VsphereVolume:nil Quobyte:nil AzureDisk:nil PhotonPersistentDisk:nil PortworxVolume:nil ScaleIO:nil Local:nil StorageOS:nil CSI:&CSIPersistentVolumeSource{Driver:csi-rbdplugin,VolumeHandle:csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101,ReadOnly:false,FSType:ext4,VolumeAttributes:map[string]string{adminid: admin,csiNodePublishSecretName: csi-rbd-secret,csiNodePublishSecretNamespace: default,csiProvisionerSecretName: csi-rbd-secret,csiProvisionerSecretNamespace: default,imageFeatures: layering,imageFormat: 2,monValueFromSecret: monitors,pool: rbd,storage.kubernetes.io/csiProvisionerIdentity: 1538984890575-8081-csi-rbdplugin,userid: kubernetes,},ControllerPublishSecretRef:nil,NodeStageSecretRef:nil,NodePublishSecretRef:&SecretReference{Name:csi-rbd-secret,Namespace:default,},}}
provisioner: I1008 08:01:53.375867       1 controller.go:900] volume "pvc-59a6fe14cad011e8" for claim "default/rbd-pvc" created
provisioner: I1008 08:01:53.375900       1 controller.go:914] provisionClaimOperation [default/rbd-pvc]: trying to save volume pvc-59a6fe14cad011e8
provisioner: I1008 08:01:53.403500       1 controller.go:917] volume "pvc-59a6fe14cad011e8" for claim "default/rbd-pvc" saved
provisioner: I1008 08:01:53.403545       1 controller.go:953] volume "pvc-59a6fe14cad011e8" provisioned for claim "default/rbd-pvc"
provisioner: I1008 08:01:53.416990       1 controller.go:1010] claim event received: ADDED default/rbd-pvc.155b935a39d220b7 default/rbd-pvc ProvisioningSucceeded
provisioner: I1008 08:01:54.444729       1 leaderelection.go:215] succesfully renewed lease to provision for pvc default/rbd-pvc
provisioner: I1008 08:01:54.444790       1 leaderelection.go:198] stopped trying to renew lease to provision for pvc default/rbd-pvc, task succeeded
provisioner: I1008 08:01:54.444825       1 controller.go:988] claim update received: MODIFIED default/rbd-pvc Pending

$ kubectl delete -f vendor/github.com/ceph/ceph-csi/examples/rbd/pvc.yaml 
persistentvolumeclaim "rbd-pvc" deleted

provisioner: I1008 08:05:16.456748       1 controller.go:1167] scheduleOperation[delete-pvc-59a6fe14cad011e8[6b1db6e5-cad0-11e8-a12b-deadbeef0100]]
provisioner: I1008 08:05:16.456801       1 controller.go:1115] deleteVolumeOperation [pvc-59a6fe14cad011e8] started
provisioner: I1008 08:05:16.462164       1 controller.go:103] GRPC call: /csi.v0.Identity/GetPluginCapabilities
provisioner: I1008 08:05:16.462199       1 controller.go:104] GRPC request: 
rbdplugin: I1008 08:05:16.462577       1 utils.go:96] GRPC call: /csi.v0.Identity/GetPluginCapabilities
rbdplugin: I1008 08:05:16.462610       1 utils.go:97] GRPC request: 
rbdplugin: I1008 08:05:16.462634       1 utils.go:102] GRPC response: capabilities:<service:<type:CONTROLLER_SERVICE > > 
provisioner: I1008 08:05:16.462917       1 controller.go:106] GRPC response: capabilities:<service:<type:CONTROLLER_SERVICE > > 
provisioner: I1008 08:05:16.462970       1 controller.go:107] GRPC error: <nil>
provisioner: I1008 08:05:16.462985       1 controller.go:103] GRPC call: /csi.v0.Controller/ControllerGetCapabilities
provisioner: I1008 08:05:16.462992       1 controller.go:104] GRPC request: 
provisioner: I1008 08:05:16.463640       1 controller.go:106] GRPC response: capabilities:<rpc:<type:CREATE_DELETE_VOLUME > > capabilities:<rpc:<type:PUBLISH_UNPUBLISH_VOLUME > > capabilities:<rpc:<type:CREATE_DELETE_SNAPSHOT > > capabilities:<rpc:<type:LIST_SNAPSHOTS > > 
provisioner: I1008 08:05:16.463713       1 controller.go:107] GRPC error: <nil>
provisioner: I1008 08:05:16.463727       1 controller.go:103] GRPC call: /csi.v0.Identity/GetPluginInfo
provisioner: I1008 08:05:16.463734       1 controller.go:104] GRPC request: 
provisioner: I1008 08:05:16.464700       1 controller.go:106] GRPC response: name:"csi-rbdplugin" vendor_version:"0.3.0" 
provisioner: I1008 08:05:16.464739       1 controller.go:107] GRPC error: <nil>
rbdplugin: I1008 08:05:16.463263       1 utils.go:96] GRPC call: /csi.v0.Controller/ControllerGetCapabilities
rbdplugin: I1008 08:05:16.463297       1 utils.go:97] GRPC request: 
rbdplugin: I1008 08:05:16.463344       1 controllerserver-default.go:82] Using default ControllerGetCapabilities
rbdplugin: I1008 08:05:16.463367       1 utils.go:102] GRPC response: capabilities:<rpc:<type:CREATE_DELETE_VOLUME > > capabilities:<rpc:<type:PUBLISH_UNPUBLISH_VOLUME > > capabilities:<rpc:<type:CREATE_DELETE_SNAPSHOT > > capabilities:<rpc:<type:LIST_SNAPSHOTS > > 
rbdplugin: I1008 08:05:16.464432       1 utils.go:96] GRPC call: /csi.v0.Identity/GetPluginInfo
rbdplugin: I1008 08:05:16.464470       1 utils.go:97] GRPC request: 
rbdplugin: I1008 08:05:16.464491       1 identityserver-default.go:32] Using default GetPluginInfo
rbdplugin: I1008 08:05:16.464499       1 utils.go:102] GRPC response: name:"csi-rbdplugin" vendor_version:"0.3.0" 
provisioner: I1008 08:05:16.470193       1 controller.go:103] GRPC call: /csi.v0.Controller/DeleteVolume
provisioner: I1008 08:05:16.470210       1 controller.go:104] GRPC request: volume_id:"csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101" controller_delete_secrets:<key:"admin" value:"AQD0Crtb7+x9OhAAK4DAHLj+hXeA3Kjzs1xWgA==\n" > controller_delete_secrets:<key:"kubernetes" value:"AQD1Crtbpr0aOxAAimVzMGWaCnaiNOc8UiWvzg==\n" > controller_delete_secrets:<key:"monitors" value:"192.168.7.2:6789,192.168.7.4:6789,192.168.7.6:6789,192.168.7.8:6789" > 
rbdplugin: I1008 08:05:16.470518       1 utils.go:96] GRPC call: /csi.v0.Controller/DeleteVolume
rbdplugin: I1008 08:05:16.470531       1 utils.go:97] GRPC request: volume_id:"csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101" controller_delete_secrets:<key:"admin" value:"AQD0Crtb7+x9OhAAK4DAHLj+hXeA3Kjzs1xWgA==\n" > controller_delete_secrets:<key:"kubernetes" value:"AQD1Crtbpr0aOxAAimVzMGWaCnaiNOc8UiWvzg==\n" > controller_delete_secrets:<key:"monitors" value:"192.168.7.2:6789,192.168.7.4:6789,192.168.7.6:6789,192.168.7.8:6789" > 
rbdplugin: I1008 08:05:16.470638       1 controllerserver.go:163] deleting volume pvc-59a6fe14cad011e8
rbdplugin: I1008 08:05:16.470646       1 rbd_util.go:159] rbd: status pvc-59a6fe14cad011e8 using mon 192.168.7.2:6789,192.168.7.4:6789,192.168.7.6:6789,192.168.7.8:6789, pool rbd id admin key AQD0Crtb7+x9OhAAK4DAHLj+hXeA3Kjzs1xWgA==
rbdplugin: W1008 08:05:16.576405       1 rbd_util.go:181] rbd: no watchers on pvc-59a6fe14cad011e8
rbdplugin: I1008 08:05:16.576446       1 rbd_util.go:207] rbd: rm pvc-59a6fe14cad011e8 using mon 192.168.7.2:6789,192.168.7.4:6789,192.168.7.6:6789,192.168.7.8:6789, pool rbd id admin key AQD0Crtb7+x9OhAAK4DAHLj+hXeA3Kjzs1xWgA==
provisioner: I1008 08:05:20.614510       1 reflector.go:286] github.com/kubernetes-csi/external-provisioner/vendor/github.com/kubernetes-incubator/external-storage/lib/controller/controller.go:497: forcing resync
provisioner: I1008 08:05:20.614510       1 reflector.go:286] github.com/kubernetes-csi/external-provisioner/vendor/github.com/kubernetes-incubator/external-storage/lib/controller/controller.go:496: forcing resync
provisioner: I1008 08:05:20.614600       1 controller.go:1167] scheduleOperation[delete-pvc-59a6fe14cad011e8[6b1db6e5-cad0-11e8-a12b-deadbeef0100]]
provisioner: I1008 08:05:20.614615       1 controller.go:1172] operation "delete-pvc-59a6fe14cad011e8[6b1db6e5-cad0-11e8-a12b-deadbeef0100]" is already running, skipping
provisioner: I1008 08:05:20.614567       1 reflector.go:286] github.com/kubernetes-csi/external-provisioner/vendor/github.com/kubernetes-incubator/external-storage/lib/controller/controller.go:498: forcing resync
provisioner: I1008 08:05:26.470607       1 controller.go:106] GRPC response: 
provisioner: I1008 08:05:26.470676       1 controller.go:107] GRPC error: rpc error: code = DeadlineExceeded desc = context deadline exceeded
provisioner: E1008 08:05:26.470695       1 controller.go:1138] Deletion of volume "pvc-59a6fe14cad011e8" failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
provisioner: E1008 08:05:26.470797       1 goroutinemap.go:150] Operation for "delete-pvc-59a6fe14cad011e8[6b1db6e5-cad0-11e8-a12b-deadbeef0100]" failed. No retries permitted until 2018-10-08 08:05:26.970758008 +0000 UTC m=+1036.417161060 (durationBeforeRetry 500ms). Error: "rpc error: code = DeadlineExceeded desc = context deadline exceeded"
rbdplugin: I1008 08:05:32.984535       1 rbd_util.go:341] rbd: Deleting file for Volume: csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101 at: /var/lib/kubelet/plugins/csi-rbdplugin/controller resulting path: /var/lib/kubelet/plugins/csi-rbdplugin/controller/csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101.json
rbdplugin: I1008 08:05:32.984653       1 utils.go:102] GRPC response: 
provisioner: I1008 08:05:35.614802       1 reflector.go:286] github.com/kubernetes-csi/external-provisioner/vendor/github.com/kubernetes-incubator/external-storage/lib/controller/controller.go:497: forcing resync
provisioner: I1008 08:05:35.614835       1 reflector.go:286] github.com/kubernetes-csi/external-provisioner/vendor/github.com/kubernetes-incubator/external-storage/lib/controller/controller.go:496: forcing resync
provisioner: I1008 08:05:35.614816       1 reflector.go:286] github.com/kubernetes-csi/external-provisioner/vendor/github.com/kubernetes-incubator/external-storage/lib/controller/controller.go:498: forcing resync
provisioner: I1008 08:05:35.614917       1 controller.go:1167] scheduleOperation[delete-pvc-59a6fe14cad011e8[6b1db6e5-cad0-11e8-a12b-deadbeef0100]]
provisioner: I1008 08:05:35.614967       1 controller.go:1115] deleteVolumeOperation [pvc-59a6fe14cad011e8] started
provisioner: I1008 08:05:35.623719       1 controller.go:103] GRPC call: /csi.v0.Identity/GetPluginCapabilities
provisioner: I1008 08:05:35.623747       1 controller.go:104] GRPC request: 
rbdplugin: I1008 08:05:35.624093       1 utils.go:96] GRPC call: /csi.v0.Identity/GetPluginCapabilities
rbdplugin: I1008 08:05:35.624117       1 utils.go:97] GRPC request: 
rbdplugin: I1008 08:05:35.624140       1 utils.go:102] GRPC response: capabilities:<service:<type:CONTROLLER_SERVICE > > 
provisioner: I1008 08:05:35.624368       1 controller.go:106] GRPC response: capabilities:<service:<type:CONTROLLER_SERVICE > > 
provisioner: I1008 08:05:35.624430       1 controller.go:107] GRPC error: <nil>
provisioner: I1008 08:05:35.624444       1 controller.go:103] GRPC call: /csi.v0.Controller/ControllerGetCapabilities
provisioner: I1008 08:05:35.624450       1 controller.go:104] GRPC request: 
provisioner: I1008 08:05:35.624946       1 controller.go:106] GRPC response: capabilities:<rpc:<type:CREATE_DELETE_VOLUME > > capabilities:<rpc:<type:PUBLISH_UNPUBLISH_VOLUME > > capabilities:<rpc:<type:CREATE_DELETE_SNAPSHOT > > capabilities:<rpc:<type:LIST_SNAPSHOTS > > 
provisioner: I1008 08:05:35.625010       1 controller.go:107] GRPC error: <nil>
provisioner: I1008 08:05:35.625023       1 controller.go:103] GRPC call: /csi.v0.Identity/GetPluginInfo
provisioner: I1008 08:05:35.625029       1 controller.go:104] GRPC request: 
provisioner: I1008 08:05:35.625575       1 controller.go:106] GRPC response: name:"csi-rbdplugin" vendor_version:"0.3.0" 
provisioner: I1008 08:05:35.625614       1 controller.go:107] GRPC error: <nil>
rbdplugin: I1008 08:05:35.624666       1 utils.go:96] GRPC call: /csi.v0.Controller/ControllerGetCapabilities
rbdplugin: I1008 08:05:35.624684       1 utils.go:97] GRPC request: 
rbdplugin: I1008 08:05:35.624702       1 controllerserver-default.go:82] Using default ControllerGetCapabilities
rbdplugin: I1008 08:05:35.624709       1 utils.go:102] GRPC response: capabilities:<rpc:<type:CREATE_DELETE_VOLUME > > capabilities:<rpc:<type:PUBLISH_UNPUBLISH_VOLUME > > capabilities:<rpc:<type:CREATE_DELETE_SNAPSHOT > > capabilities:<rpc:<type:LIST_SNAPSHOTS > > 
rbdplugin: I1008 08:05:35.625379       1 utils.go:96] GRPC call: /csi.v0.Identity/GetPluginInfo
rbdplugin: I1008 08:05:35.625396       1 utils.go:97] GRPC request: 
rbdplugin: I1008 08:05:35.625412       1 identityserver-default.go:32] Using default GetPluginInfo
rbdplugin: I1008 08:05:35.625419       1 utils.go:102] GRPC response: name:"csi-rbdplugin" vendor_version:"0.3.0" 
provisioner: I1008 08:05:35.631465       1 controller.go:103] GRPC call: /csi.v0.Controller/DeleteVolume
provisioner: I1008 08:05:35.631479       1 controller.go:104] GRPC request: volume_id:"csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101" controller_delete_secrets:<key:"admin" value:"AQD0Crtb7+x9OhAAK4DAHLj+hXeA3Kjzs1xWgA==\n" > controller_delete_secrets:<key:"kubernetes" value:"AQD1Crtbpr0aOxAAimVzMGWaCnaiNOc8UiWvzg==\n" > controller_delete_secrets:<key:"monitors" value:"192.168.7.2:6789,192.168.7.4:6789,192.168.7.6:6789,192.168.7.8:6789" > 
provisioner: I1008 08:05:35.631961       1 controller.go:106] GRPC response: 
provisioner: I1008 08:05:35.631981       1 controller.go:107] GRPC error: rpc error: code = Unknown desc = rbd: open err /var/lib/kubelet/plugins/csi-rbdplugin/controller/csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101.json/open /var/lib/kubelet/plugins/csi-rbdplugin/controller/csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101.json: no such file or directory
provisioner: E1008 08:05:35.632007       1 controller.go:1138] Deletion of volume "pvc-59a6fe14cad011e8" failed: rpc error: code = Unknown desc = rbd: open err /var/lib/kubelet/plugins/csi-rbdplugin/controller/csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101.json/open /var/lib/kubelet/plugins/csi-rbdplugin/controller/csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101.json: no such file or directory
provisioner: E1008 08:05:35.632084       1 goroutinemap.go:150] Operation for "delete-pvc-59a6fe14cad011e8[6b1db6e5-cad0-11e8-a12b-deadbeef0100]" failed. No retries permitted until 2018-10-08 08:05:36.632050943 +0000 UTC m=+1046.078453983 (durationBeforeRetry 1s). Error: "rpc error: code = Unknown desc = rbd: open err /var/lib/kubelet/plugins/csi-rbdplugin/controller/csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101.json/open /var/lib/kubelet/plugins/csi-rbdplugin/controller/csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101.json: no such file or directory"
rbdplugin: I1008 08:05:35.631704       1 utils.go:96] GRPC call: /csi.v0.Controller/DeleteVolume
rbdplugin: I1008 08:05:35.631724       1 utils.go:97] GRPC request: volume_id:"csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101" controller_delete_secrets:<key:"admin" value:"AQD0Crtb7+x9OhAAK4DAHLj+hXeA3Kjzs1xWgA==\n" > controller_delete_secrets:<key:"kubernetes" value:"AQD1Crtbpr0aOxAAimVzMGWaCnaiNOc8UiWvzg==\n" > controller_delete_secrets:<key:"monitors" value:"192.168.7.2:6789,192.168.7.4:6789,192.168.7.6:6789,192.168.7.8:6789" > 
rbdplugin: E1008 08:05:35.631783       1 utils.go:100] GRPC error: rbd: open err /var/lib/kubelet/plugins/csi-rbdplugin/controller/csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101.json/open /var/lib/kubelet/plugins/csi-rbdplugin/controller/csi-rbd-622a252c-cad0-11e8-9112-deadbeef0101.json: no such file or directory
...