I0918 01:39:36.221490       1 cephcsi.go:191] Driver version: v3.11.0 and Git version: bc24b5eca87626d690a29effa9d7420cc0154a7a
I0918 01:39:36.221616       1 cephcsi.go:223] Starting driver type: rbd with name: rbd.csi.ceph.com
I0918 01:39:36.221629       1 driver.go:95] Enabling controller service capability: CREATE_DELETE_VOLUME
I0918 01:39:36.221632       1 driver.go:95] Enabling controller service capability: CREATE_DELETE_SNAPSHOT
I0918 01:39:36.221635       1 driver.go:95] Enabling controller service capability: CLONE_VOLUME
I0918 01:39:36.221638       1 driver.go:95] Enabling controller service capability: EXPAND_VOLUME
I0918 01:39:36.221642       1 driver.go:108] Enabling volume access mode: SINGLE_NODE_WRITER
I0918 01:39:36.221645       1 driver.go:108] Enabling volume access mode: MULTI_NODE_MULTI_WRITER
I0918 01:39:36.221648       1 driver.go:108] Enabling volume access mode: SINGLE_NODE_SINGLE_WRITER
I0918 01:39:36.221650       1 driver.go:108] Enabling volume access mode: SINGLE_NODE_MULTI_WRITER
I0918 01:39:36.222206       1 server.go:117] Listening for connections on address: &net.UnixAddr{Name:"//csi/csi-provisioner.sock", Net:"unix"}
I0918 01:39:36.222227       1 server.go:114] listening for CSI-Addons requests on address: &net.UnixAddr{Name:"/csi/csi-addons.sock", Net:"unix"}
I0918 01:39:40.589862       1 utils.go:198] ID: 1 GRPC call: /csi.v1.Identity/Probe
I0918 01:39:40.591858       1 utils.go:199] ID: 1 GRPC request: {}
I0918 01:39:40.592107       1 utils.go:205] ID: 1 GRPC response: {}
I0918 01:39:40.594384       1 utils.go:198] ID: 2 GRPC call: /csi.v1.Identity/GetPluginInfo
I0918 01:39:40.594490       1 utils.go:199] ID: 2 GRPC request: {}
I0918 01:39:40.594519       1 identityserver-default.go:40] ID: 2 Using default GetPluginInfo
I0918 01:39:40.594586       1 utils.go:205] ID: 2 GRPC response: {"name":"rbd.csi.ceph.com","vendor_version":"v3.11.0"}
I0918 01:39:40.596440       1 utils.go:198] ID: 3 GRPC call: /csi.v1.Identity/Probe
I0918 01:39:40.596473       1 utils.go:199] ID: 3 GRPC request: {}
I0918 01:39:40.596499       1 utils.go:205] ID: 3 GRPC response: {}
I0918 01:39:40.597067       1 utils.go:198] ID: 4 GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0918 01:39:40.597176       1 utils.go:199] ID: 4 GRPC request: {}
I0918 01:39:40.597365       1 utils.go:205] ID: 4 GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}},{"Type":{"VolumeExpansion":{"type":1}}},{"Type":{"Service":{"type":2}}}]}
I0918 01:39:40.598124       1 utils.go:198] ID: 5 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0918 01:39:40.598204       1 utils.go:199] ID: 5 GRPC request: {}
I0918 01:39:40.598228       1 controllerserver-default.go:42] ID: 5 Using default ControllerGetCapabilities
I0918 01:39:40.598349       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 01:39:42.117227       1 utils.go:198] ID: 6 GRPC call: /csi.v1.Identity/Probe
I0918 01:39:42.117266       1 utils.go:199] ID: 6 GRPC request: {}
I0918 01:39:42.117284       1 utils.go:205] ID: 6 GRPC response: {}
I0918 01:39:42.119212       1 utils.go:198] ID: 7 GRPC call: /csi.v1.Identity/GetPluginInfo
I0918 01:39:42.119237       1 utils.go:199] ID: 7 GRPC request: {}
I0918 01:39:42.119247       1 identityserver-default.go:40] ID: 7 Using default GetPluginInfo
I0918 01:39:42.119277       1 utils.go:205] ID: 7 GRPC response: {"name":"rbd.csi.ceph.com","vendor_version":"v3.11.0"}
I0918 01:39:42.120988       1 utils.go:198] ID: 8 GRPC call: /csi.v1.Identity/Probe
I0918 01:39:42.121029       1 utils.go:199] ID: 8 GRPC request: {}
I0918 01:39:42.121045       1 utils.go:205] ID: 8 GRPC response: {}
I0918 01:39:42.121474       1 utils.go:198] ID: 9 GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0918 01:39:42.121568       1 utils.go:199] ID: 9 GRPC request: {}
I0918 01:39:42.121754       1 utils.go:205] ID: 9 GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}},{"Type":{"VolumeExpansion":{"type":1}}},{"Type":{"Service":{"type":2}}}]}
I0918 01:39:42.122605       1 utils.go:198] ID: 10 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0918 01:39:42.122630       1 utils.go:199] ID: 10 GRPC request: {}
I0918 01:39:42.122639       1 controllerserver-default.go:42] ID: 10 Using default ControllerGetCapabilities
I0918 01:39:42.122717       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 01:39:42.123289       1 utils.go:198] ID: 11 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0918 01:39:42.123431       1 utils.go:199] ID: 11 GRPC request: {}
I0918 01:39:42.123501       1 controllerserver-default.go:42] ID: 11 Using default ControllerGetCapabilities
I0918 01:39:42.123619       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 01:39:42.124044       1 utils.go:198] ID: 12 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0918 01:39:42.124063       1 utils.go:199] ID: 12 GRPC request: {}
I0918 01:39:42.124071       1 controllerserver-default.go:42] ID: 12 Using default ControllerGetCapabilities
I0918 01:39:42.124154       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 01:39:43.627536       1 utils.go:198] ID: 13 GRPC call: /csi.v1.Identity/GetPluginInfo
I0918 01:39:43.627578       1 utils.go:199] ID: 13 GRPC request: {}
I0918 01:39:43.627604       1 identityserver-default.go:40] ID: 13 Using default GetPluginInfo
I0918 01:39:43.627633       1 utils.go:205] ID: 13 GRPC response: {"name":"rbd.csi.ceph.com","vendor_version":"v3.11.0"}
I0918 01:39:43.631946       1 utils.go:198] ID: 14 GRPC call: /csi.v1.Identity/Probe
I0918 01:39:43.631978       1 utils.go:199] ID: 14 GRPC request: {}
I0918 01:39:43.631992       1 utils.go:205] ID: 14 GRPC response: {}
I0918 01:39:43.632548       1 utils.go:198] ID: 15 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0918 01:39:43.632565       1 utils.go:199] ID: 15 GRPC request: {}
I0918 01:39:43.632571       1 controllerserver-default.go:42] ID: 15 Using default ControllerGetCapabilities
I0918 01:39:43.632633       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 01:39:45.354067       1 utils.go:198] ID: 16 GRPC call: /csi.v1.Identity/Probe
I0918 01:39:45.354113       1 utils.go:199] ID: 16 GRPC request: {}
I0918 01:39:45.354134       1 utils.go:205] ID: 16 GRPC response: {}
I0918 01:39:45.360582       1 utils.go:198] ID: 17 GRPC call: /csi.v1.Identity/GetPluginInfo
I0918 01:39:45.360612       1 utils.go:199] ID: 17 GRPC request: {}
I0918 01:39:45.360623       1 identityserver-default.go:40] ID: 17 Using default GetPluginInfo
I0918 01:39:45.360655       1 utils.go:205] ID: 17 GRPC response: {"name":"rbd.csi.ceph.com","vendor_version":"v3.11.0"}
I0918 01:39:45.363389       1 utils.go:198] ID: 18 GRPC call: /csi.v1.Identity/Probe
I0918 01:39:45.363418       1 utils.go:199] ID: 18 GRPC request: {}
I0918 01:39:45.363434       1 utils.go:205] ID: 18 GRPC response: {}
I0918 01:39:45.364053       1 utils.go:198] ID: 19 GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0918 01:39:45.364083       1 utils.go:199] ID: 19 GRPC request: {}
I0918 01:39:45.364202       1 utils.go:205] ID: 19 GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}},{"Type":{"VolumeExpansion":{"type":1}}},{"Type":{"Service":{"type":2}}}]}
I0918 01:39:45.366293       1 utils.go:198] ID: 20 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0918 01:39:45.366338       1 utils.go:199] ID: 20 GRPC request: {}
I0918 01:39:45.366349       1 controllerserver-default.go:42] ID: 20 Using default ControllerGetCapabilities
I0918 01:39:45.366486       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 01:40:45.641289       1 utils.go:198] ID: 21 GRPC call: /csi.v1.Identity/Probe
I0918 01:40:45.641361       1 utils.go:199] ID: 21 GRPC request: {}
I0918 01:40:45.641391       1 utils.go:205] ID: 21 GRPC response: {}
I0918 01:41:45.592638       1 utils.go:198] ID: 22 GRPC call: /csi.v1.Identity/Probe
I0918 01:41:45.593002       1 utils.go:199] ID: 22 GRPC request: {}
I0918 01:41:45.593143       1 utils.go:205] ID: 22 GRPC response: {}
I0918 01:42:45.644293       1 utils.go:198] ID: 23 GRPC call: /csi.v1.Identity/Probe
I0918 01:42:45.644343       1 utils.go:199] ID: 23 GRPC request: {}
I0918 01:42:45.644366       1 utils.go:205] ID: 23 GRPC response: {}
I0918 01:43:45.604229       1 utils.go:198] ID: 24 GRPC call: /csi.v1.Identity/Probe
I0918 01:43:45.604302       1 utils.go:199] ID: 24 GRPC request: {}
I0918 01:43:45.604350       1 utils.go:205] ID: 24 GRPC response: {}
I0918 01:44:15.739509       1 utils.go:198] ID: 25 Req-ID: pvc-2141f65c-0cac-4e21-a904-3cd7f975a855 GRPC call: /csi.v1.Controller/CreateVolume
I0918 01:44:15.740262       1 utils.go:199] ID: 25 Req-ID: pvc-2141f65c-0cac-4e21-a904-3cd7f975a855 GRPC request: {"capacity_range":{"required_bytes":5368709120},"name":"pvc-2141f65c-0cac-4e21-a904-3cd7f975a855","parameters":{"clusterID":"4837cbf8-4f90-4300-b3f6-726c9b9f89b4","csi.storage.k8s.io/pv/name":"pvc-2141f65c-0cac-4e21-a904-3cd7f975a855","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 01:44:15.740846       1 rbd_util.go:1315] ID: 25 Req-ID: pvc-2141f65c-0cac-4e21-a904-3cd7f975a855 setting disableInUseChecks: false image features: [layering] mounter: rbd
E0918 01:44:15.766995       1 omap.go:80] ID: 25 Req-ID: pvc-2141f65c-0cac-4e21-a904-3cd7f975a855 omap not found (pool="kube", namespace="", name="csi.volumes.default"): rados: ret=-2, No such file or directory
I0918 01:44:15.789351       1 omap.go:159] ID: 25 Req-ID: pvc-2141f65c-0cac-4e21-a904-3cd7f975a855 set omap keys (pool="kube", namespace="", name="csi.volumes.default"): map[csi.volume.pvc-2141f65c-0cac-4e21-a904-3cd7f975a855:d9fd20b9-42d9-4fe5-86c0-3b345fcc2c92])
I0918 01:44:15.796730       1 omap.go:159] ID: 25 Req-ID: pvc-2141f65c-0cac-4e21-a904-3cd7f975a855 set omap keys (pool="kube", namespace="", name="csi.volume.d9fd20b9-42d9-4fe5-86c0-3b345fcc2c92"): map[csi.imagename:csi-vol-d9fd20b9-42d9-4fe5-86c0-3b345fcc2c92 csi.volname:pvc-2141f65c-0cac-4e21-a904-3cd7f975a855 csi.volume.owner:default])
I0918 01:44:15.796837       1 rbd_journal.go:491] ID: 25 Req-ID: pvc-2141f65c-0cac-4e21-a904-3cd7f975a855 generated Volume ID (0001-0024-4837cbf8-4f90-4300-b3f6-726c9b9f89b4-0000000000000002-d9fd20b9-42d9-4fe5-86c0-3b345fcc2c92) and image name (csi-vol-d9fd20b9-42d9-4fe5-86c0-3b345fcc2c92) for request name (pvc-2141f65c-0cac-4e21-a904-3cd7f975a855)
I0918 01:44:15.796974       1 rbd_util.go:423] ID: 25 Req-ID: pvc-2141f65c-0cac-4e21-a904-3cd7f975a855 rbd: create kube/csi-vol-d9fd20b9-42d9-4fe5-86c0-3b345fcc2c92 size 5120M (features: [layering]) using mon 162.253.55.102
I0918 01:44:15.797027       1 rbd_util.go:1563] ID: 25 Req-ID: pvc-2141f65c-0cac-4e21-a904-3cd7f975a855 setting image options on kube/csi-vol-d9fd20b9-42d9-4fe5-86c0-3b345fcc2c92
I0918 01:44:15.851352       1 controllerserver.go:763] ID: 25 Req-ID: pvc-2141f65c-0cac-4e21-a904-3cd7f975a855 created image kube/csi-vol-d9fd20b9-42d9-4fe5-86c0-3b345fcc2c92 backed for request name pvc-2141f65c-0cac-4e21-a904-3cd7f975a855
I0918 01:44:15.901722       1 omap.go:159] ID: 25 Req-ID: pvc-2141f65c-0cac-4e21-a904-3cd7f975a855 set omap keys (pool="kube", namespace="", name="csi.volume.d9fd20b9-42d9-4fe5-86c0-3b345fcc2c92"): map[csi.imageid:37f468862280])
I0918 01:44:16.074714       1 utils.go:205] ID: 25 Req-ID: pvc-2141f65c-0cac-4e21-a904-3cd7f975a855 GRPC response: {"volume":{"capacity_bytes":5368709120,"volume_context":{"clusterID":"4837cbf8-4f90-4300-b3f6-726c9b9f89b4","imageFeatures":"layering","imageName":"csi-vol-d9fd20b9-42d9-4fe5-86c0-3b345fcc2c92","journalPool":"kube","pool":"kube"},"volume_id":"0001-0024-4837cbf8-4f90-4300-b3f6-726c9b9f89b4-0000000000000002-d9fd20b9-42d9-4fe5-86c0-3b345fcc2c92"}}
I0918 01:44:45.591008       1 utils.go:198] ID: 26 GRPC call: /csi.v1.Identity/Probe
I0918 01:44:45.591055       1 utils.go:199] ID: 26 GRPC request: {}
I0918 01:44:45.591087       1 utils.go:205] ID: 26 GRPC response: {}