I0918 05:20:49.458691       1 cephcsi.go:191] Driver version: v3.11.0 and Git version: bc24b5eca87626d690a29effa9d7420cc0154a7a
I0918 05:20:49.458909       1 cephcsi.go:223] Starting driver type: rbd with name: rbd.csi.ceph.com
I0918 05:20:49.458938       1 driver.go:95] Enabling controller service capability: CREATE_DELETE_VOLUME
I0918 05:20:49.458954       1 driver.go:95] Enabling controller service capability: CREATE_DELETE_SNAPSHOT
I0918 05:20:49.458970       1 driver.go:95] Enabling controller service capability: CLONE_VOLUME
I0918 05:20:49.458991       1 driver.go:95] Enabling controller service capability: EXPAND_VOLUME
I0918 05:20:49.459007       1 driver.go:108] Enabling volume access mode: SINGLE_NODE_WRITER
I0918 05:20:49.459021       1 driver.go:108] Enabling volume access mode: MULTI_NODE_MULTI_WRITER
I0918 05:20:49.459033       1 driver.go:108] Enabling volume access mode: SINGLE_NODE_SINGLE_WRITER
I0918 05:20:49.459045       1 driver.go:108] Enabling volume access mode: SINGLE_NODE_MULTI_WRITER
I0918 05:20:49.459302       1 server.go:117] Listening for connections on address: &net.UnixAddr{Name:"//csi/csi-provisioner.sock", Net:"unix"}
I0918 05:20:49.459330       1 server.go:114] listening for CSI-Addons requests on address: &net.UnixAddr{Name:"/csi/csi-addons.sock", Net:"unix"}
I0918 05:20:52.828288       1 utils.go:198] ID: 1 GRPC call: /csi.v1.Identity/Probe
I0918 05:20:52.830712       1 utils.go:199] ID: 1 GRPC request: {}
I0918 05:20:52.830937       1 utils.go:205] ID: 1 GRPC response: {}
I0918 05:20:52.833989       1 utils.go:198] ID: 2 GRPC call: /csi.v1.Identity/GetPluginInfo
I0918 05:20:52.834217       1 utils.go:199] ID: 2 GRPC request: {}
I0918 05:20:52.834272       1 identityserver-default.go:40] ID: 2 Using default GetPluginInfo
I0918 05:20:52.834347       1 utils.go:205] ID: 2 GRPC response: {"name":"rbd.csi.ceph.com","vendor_version":"v3.11.0"}
I0918 05:20:52.841533       1 utils.go:198] ID: 3 GRPC call: /csi.v1.Identity/Probe
I0918 05:20:52.841583       1 utils.go:199] ID: 3 GRPC request: {}
I0918 05:20:52.841614       1 utils.go:205] ID: 3 GRPC response: {}
I0918 05:20:52.841997       1 utils.go:198] ID: 4 GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0918 05:20:52.842067       1 utils.go:199] ID: 4 GRPC request: {}
I0918 05:20:52.842235       1 utils.go:205] ID: 4 GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}},{"Type":{"VolumeExpansion":{"type":1}}},{"Type":{"Service":{"type":2}}}]}
I0918 05:20:52.843134       1 utils.go:198] ID: 5 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0918 05:20:52.843316       1 utils.go:199] ID: 5 GRPC request: {}
I0918 05:20:52.843432       1 controllerserver-default.go:42] ID: 5 Using default ControllerGetCapabilities
I0918 05:20:52.843660       1 utils.go:205] ID: 5 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":7}}},{"Type":{"Rpc":{"type":9}}}]}
I0918 05:20:55.037271       1 utils.go:198] ID: 6 GRPC call: /csi.v1.Identity/Probe
I0918 05:20:55.037325       1 utils.go:199] ID: 6 GRPC request: {}
I0918 05:20:55.037355       1 utils.go:205] ID: 6 GRPC response: {}
I0918 05:20:55.041471       1 utils.go:198] ID: 7 GRPC call: /csi.v1.Identity/GetPluginInfo
I0918 05:20:55.041508       1 utils.go:199] ID: 7 GRPC request: {}
I0918 05:20:55.041523       1 identityserver-default.go:40] ID: 7 Using default GetPluginInfo
I0918 05:20:55.041565       1 utils.go:205] ID: 7 GRPC response: {"name":"rbd.csi.ceph.com","vendor_version":"v3.11.0"}
I0918 05:20:55.044189       1 utils.go:198] ID: 8 GRPC call: /csi.v1.Identity/Probe
I0918 05:20:55.044224       1 utils.go:199] ID: 8 GRPC request: {}
I0918 05:20:55.044246       1 utils.go:205] ID: 8 GRPC response: {}
I0918 05:20:55.044935       1 utils.go:198] ID: 9 GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0918 05:20:55.044979       1 utils.go:199] ID: 9 GRPC request: {}
I0918 05:20:55.045137       1 utils.go:205] ID: 9 GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}},{"Type":{"VolumeExpansion":{"type":1}}},{"Type":{"Service":{"type":2}}}]}
I0918 05:20:55.046326       1 utils.go:198] ID: 10 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0918 05:20:55.046365       1 utils.go:199] ID: 10 GRPC request: {}
I0918 05:20:55.046378       1 controllerserver-default.go:42] ID: 10 Using default ControllerGetCapabilities
I0918 05:20:55.046495       1 utils.go:205] ID: 10 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":7}}},{"Type":{"Rpc":{"type":9}}}]}
I0918 05:20:55.047396       1 utils.go:198] ID: 11 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0918 05:20:55.047460       1 utils.go:199] ID: 11 GRPC request: {}
I0918 05:20:55.047472       1 controllerserver-default.go:42] ID: 11 Using default ControllerGetCapabilities
I0918 05:20:55.047599       1 utils.go:205] ID: 11 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":7}}},{"Type":{"Rpc":{"type":9}}}]}
I0918 05:20:55.048336       1 utils.go:198] ID: 12 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0918 05:20:55.048369       1 utils.go:199] ID: 12 GRPC request: {}
I0918 05:20:55.048380       1 controllerserver-default.go:42] ID: 12 Using default ControllerGetCapabilities
I0918 05:20:55.048488       1 utils.go:205] ID: 12 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":7}}},{"Type":{"Rpc":{"type":9}}}]}
I0918 05:20:56.495585       1 utils.go:198] ID: 13 GRPC call: /csi.v1.Identity/GetPluginInfo
I0918 05:20:56.495628       1 utils.go:199] ID: 13 GRPC request: {}
I0918 05:20:56.495640       1 identityserver-default.go:40] ID: 13 Using default GetPluginInfo
I0918 05:20:56.495865       1 utils.go:205] ID: 13 GRPC response: {"name":"rbd.csi.ceph.com","vendor_version":"v3.11.0"}
I0918 05:20:56.499473       1 utils.go:198] ID: 14 GRPC call: /csi.v1.Identity/Probe
I0918 05:20:56.499514       1 utils.go:199] ID: 14 GRPC request: {}
I0918 05:20:56.499536       1 utils.go:205] ID: 14 GRPC response: {}
I0918 05:20:56.500105       1 utils.go:198] ID: 15 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0918 05:20:56.500140       1 utils.go:199] ID: 15 GRPC request: {}
I0918 05:20:56.500156       1 controllerserver-default.go:42] ID: 15 Using default ControllerGetCapabilities
I0918 05:20:56.500282       1 utils.go:205] ID: 15 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":7}}},{"Type":{"Rpc":{"type":9}}}]}
I0918 05:20:58.017153       1 utils.go:198] ID: 16 GRPC call: /csi.v1.Identity/Probe
I0918 05:20:58.017227       1 utils.go:199] ID: 16 GRPC request: {}
I0918 05:20:58.017256       1 utils.go:205] ID: 16 GRPC response: {}
I0918 05:20:58.020234       1 utils.go:198] ID: 17 GRPC call: /csi.v1.Identity/GetPluginInfo
I0918 05:20:58.020273       1 utils.go:199] ID: 17 GRPC request: {}
I0918 05:20:58.020284       1 identityserver-default.go:40] ID: 17 Using default GetPluginInfo
I0918 05:20:58.020314       1 utils.go:205] ID: 17 GRPC response: {"name":"rbd.csi.ceph.com","vendor_version":"v3.11.0"}
I0918 05:20:58.023808       1 utils.go:198] ID: 18 GRPC call: /csi.v1.Identity/Probe
I0918 05:20:58.023829       1 utils.go:199] ID: 18 GRPC request: {}
I0918 05:20:58.023848       1 utils.go:205] ID: 18 GRPC response: {}
I0918 05:20:58.024199       1 utils.go:198] ID: 19 GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0918 05:20:58.024229       1 utils.go:199] ID: 19 GRPC request: {}
I0918 05:20:58.024318       1 utils.go:205] ID: 19 GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}},{"Type":{"VolumeExpansion":{"type":1}}},{"Type":{"Service":{"type":2}}}]}
I0918 05:20:58.025134       1 utils.go:198] ID: 20 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0918 05:20:58.025192       1 utils.go:199] ID: 20 GRPC request: {}
I0918 05:20:58.025207       1 controllerserver-default.go:42] ID: 20 Using default ControllerGetCapabilities
I0918 05:20:58.025374       1 utils.go:205] ID: 20 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":7}}},{"Type":{"Rpc":{"type":9}}}]}
I0918 05:21:58.239253       1 utils.go:198] ID: 21 GRPC call: /csi.v1.Identity/Probe
I0918 05:21:58.239335       1 utils.go:199] ID: 21 GRPC request: {}
I0918 05:21:58.239359       1 utils.go:205] ID: 21 GRPC response: {}
I0918 05:22:58.240058       1 utils.go:198] ID: 22 GRPC call: /csi.v1.Identity/Probe
I0918 05:22:58.240119       1 utils.go:199] ID: 22 GRPC request: {}
I0918 05:22:58.240176       1 utils.go:205] ID: 22 GRPC response: {}
I0918 05:23:58.239223       1 utils.go:198] ID: 23 GRPC call: /csi.v1.Identity/Probe
I0918 05:23:58.239323       1 utils.go:199] ID: 23 GRPC request: {}
I0918 05:23:58.239382       1 utils.go:205] ID: 23 GRPC response: {}
I0918 05:24:58.257328       1 utils.go:198] ID: 24 GRPC call: /csi.v1.Identity/Probe
I0918 05:24:58.257490       1 utils.go:199] ID: 24 GRPC request: {}
I0918 05:24:58.257642       1 utils.go:205] ID: 24 GRPC response: {}
I0918 05:25:37.090890       1 utils.go:198] ID: 25 Req-ID: pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd GRPC call: /csi.v1.Controller/CreateVolume
I0918 05:25:37.091545       1 utils.go:199] ID: 25 Req-ID: pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd GRPC request: {"capacity_range":{"required_bytes":5368709120},"name":"pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd","parameters":{"clusterID":"4837cbf8-4f90-4300-b3f6-726c9b9f89b4","csi.storage.k8s.io/pv/name":"pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd","csi.storage.k8s.io/pvc/name":"test-pvc","csi.storage.k8s.io/pvc/namespace":"default","imageFeatures":"layering","pool":"kube"},"secrets":"***stripped***","volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"ext4","mount_flags":["discard"]}},"access_mode":{"mode":1}}]}
I0918 05:25:37.091899       1 rbd_util.go:1315] ID: 25 Req-ID: pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd setting disableInUseChecks: false image features: [layering] mounter: rbd
E0918 05:25:37.121748       1 omap.go:80] ID: 25 Req-ID: pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd omap not found (pool="kube", namespace="", name="csi.volumes.default"): rados: ret=-2, No such file or directory
I0918 05:25:37.144463       1 omap.go:159] ID: 25 Req-ID: pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd set omap keys (pool="kube", namespace="", name="csi.volumes.default"): map[csi.volume.pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd:423a751f-b93e-4eff-a46d-ed3a1cec1643])
I0918 05:25:37.153641       1 omap.go:159] ID: 25 Req-ID: pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd set omap keys (pool="kube", namespace="", name="csi.volume.423a751f-b93e-4eff-a46d-ed3a1cec1643"): map[csi.imagename:csi-vol-423a751f-b93e-4eff-a46d-ed3a1cec1643 csi.volname:pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd csi.volume.owner:default])
I0918 05:25:37.153683       1 rbd_journal.go:491] ID: 25 Req-ID: pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd generated Volume ID (0001-0024-4837cbf8-4f90-4300-b3f6-726c9b9f89b4-0000000000000002-423a751f-b93e-4eff-a46d-ed3a1cec1643) and image name (csi-vol-423a751f-b93e-4eff-a46d-ed3a1cec1643) for request name (pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd)
I0918 05:25:37.153807       1 rbd_util.go:423] ID: 25 Req-ID: pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd rbd: create kube/csi-vol-423a751f-b93e-4eff-a46d-ed3a1cec1643 size 5120M (features: [layering]) using mon 162.253.55.242
I0918 05:25:37.153882       1 rbd_util.go:1563] ID: 25 Req-ID: pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd setting image options on kube/csi-vol-423a751f-b93e-4eff-a46d-ed3a1cec1643
I0918 05:25:37.190118       1 controllerserver.go:763] ID: 25 Req-ID: pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd created image kube/csi-vol-423a751f-b93e-4eff-a46d-ed3a1cec1643 backed for request name pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd
I0918 05:25:37.225610       1 omap.go:159] ID: 25 Req-ID: pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd set omap keys (pool="kube", namespace="", name="csi.volume.423a751f-b93e-4eff-a46d-ed3a1cec1643"): map[csi.imageid:37f451ef6a1f])
I0918 05:25:37.332677       1 utils.go:205] ID: 25 Req-ID: pvc-a686788e-8293-4754-b3bf-fe5ed7042ffd GRPC response: {"volume":{"capacity_bytes":5368709120,"volume_context":{"clusterID":"4837cbf8-4f90-4300-b3f6-726c9b9f89b4","imageFeatures":"layering","imageName":"csi-vol-423a751f-b93e-4eff-a46d-ed3a1cec1643","journalPool":"kube","pool":"kube"},"volume_id":"0001-0024-4837cbf8-4f90-4300-b3f6-726c9b9f89b4-0000000000000002-423a751f-b93e-4eff-a46d-ed3a1cec1643"}}
I0918 05:25:58.296447       1 utils.go:198] ID: 26 GRPC call: /csi.v1.Identity/Probe
I0918 05:25:58.296540       1 utils.go:199] ID: 26 GRPC request: {}
I0918 05:25:58.296602       1 utils.go:205] ID: 26 GRPC response: {}