I0923 16:51:20.773142       1 cephcsi.go:191] Driver version: v3.11.0 and Git version: bc24b5eca87626d690a29effa9d7420cc0154a7a
I0923 16:51:20.773269       1 cephcsi.go:223] Starting driver type: rbd with name: rbd.csi.ceph.com
I0923 16:51:20.773281       1 driver.go:95] Enabling controller service capability: CREATE_DELETE_VOLUME
I0923 16:51:20.773285       1 driver.go:95] Enabling controller service capability: CREATE_DELETE_SNAPSHOT
I0923 16:51:20.773288       1 driver.go:95] Enabling controller service capability: CLONE_VOLUME
I0923 16:51:20.773291       1 driver.go:95] Enabling controller service capability: EXPAND_VOLUME
I0923 16:51:20.773295       1 driver.go:108] Enabling volume access mode: SINGLE_NODE_WRITER
I0923 16:51:20.773298       1 driver.go:108] Enabling volume access mode: MULTI_NODE_MULTI_WRITER
I0923 16:51:20.773302       1 driver.go:108] Enabling volume access mode: SINGLE_NODE_SINGLE_WRITER
I0923 16:51:20.773305       1 driver.go:108] Enabling volume access mode: SINGLE_NODE_MULTI_WRITER
I0923 16:51:20.773595       1 server.go:117] Listening for connections on address: &net.UnixAddr{Name:"//csi/csi-provisioner.sock", Net:"unix"}
I0923 16:51:20.773752       1 server.go:114] listening for CSI-Addons requests on address: &net.UnixAddr{Name:"/csi/csi-addons.sock", Net:"unix"}
I0923 16:51:25.356773       1 utils.go:198] ID: 1 GRPC call: /csi.v1.Identity/Probe
I0923 16:51:25.358647       1 utils.go:199] ID: 1 GRPC request: {}
I0923 16:51:25.358725       1 utils.go:205] ID: 1 GRPC response: {}
I0923 16:51:25.361774       1 utils.go:198] ID: 2 GRPC call: /csi.v1.Identity/GetPluginInfo
I0923 16:51:25.361915       1 utils.go:199] ID: 2 GRPC request: {}
I0923 16:51:25.361965       1 identityserver-default.go:40] ID: 2 Using default GetPluginInfo
I0923 16:51:25.362053       1 utils.go:205] ID: 2 GRPC response: {"name":"rbd.csi.ceph.com","vendor_version":"v3.11.0"}
I0923 16:51:25.364013       1 utils.go:198] ID: 3 GRPC call: /csi.v1.Identity/Probe
I0923 16:51:25.364064       1 utils.go:199] ID: 3 GRPC request: {}
I0923 16:51:25.364087       1 utils.go:205] ID: 3 GRPC response: {}
I0923 16:51:25.364535       1 utils.go:198] ID: 4 GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0923 16:51:25.364622       1 utils.go:199] ID: 4 GRPC request: {}
I0923 16:51:25.364987       1 utils.go:205] ID: 4 GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}},{"Type":{"VolumeExpansion":{"type":1}}},{"Type":{"Service":{"type":2}}}]}
I0923 16:51:25.366721       1 utils.go:198] ID: 5 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0923 16:51:25.366833       1 utils.go:199] ID: 5 GRPC request: {}
I0923 16:51:25.366852       1 controllerserver-default.go:42] ID: 5 Using default ControllerGetCapabilities
I0923 16:51:25.367039       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}}}]}
I0923 16:51:26.934755       1 utils.go:198] ID: 6 GRPC call: /csi.v1.Identity/Probe
I0923 16:51:26.934806       1 utils.go:199] ID: 6 GRPC request: {}
I0923 16:51:26.934829       1 utils.go:205] ID: 6 GRPC response: {}
I0923 16:51:26.937916       1 utils.go:198] ID: 7 GRPC call: /csi.v1.Identity/GetPluginInfo
I0923 16:51:26.937961       1 utils.go:199] ID: 7 GRPC request: {}
I0923 16:51:26.937995       1 identityserver-default.go:40] ID: 7 Using default GetPluginInfo
I0923 16:51:26.938028       1 utils.go:205] ID: 7 GRPC response: {"name":"rbd.csi.ceph.com","vendor_version":"v3.11.0"}
I0923 16:51:26.947652       1 utils.go:198] ID: 8 GRPC call: /csi.v1.Identity/Probe
I0923 16:51:26.947718       1 utils.go:199] ID: 8 GRPC request: {}
I0923 16:51:26.947764       1 utils.go:205] ID: 8 GRPC response: {}
I0923 16:51:26.948785       1 utils.go:198] ID: 9 GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0923 16:51:26.948856       1 utils.go:199] ID: 9 GRPC request: {}
I0923 16:51:26.949006       1 utils.go:205] ID: 9 GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}},{"Type":{"VolumeExpansion":{"type":1}}},{"Type":{"Service":{"type":2}}}]}
I0923 16:51:26.950370       1 utils.go:198] ID: 10 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0923 16:51:26.950396       1 utils.go:199] ID: 10 GRPC request: {}
I0923 16:51:26.950408       1 controllerserver-default.go:42] ID: 10 Using default ControllerGetCapabilities
I0923 16:51:26.950497       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}}}]}
I0923 16:51:26.951559       1 utils.go:198] ID: 11 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0923 16:51:26.951606       1 utils.go:199] ID: 11 GRPC request: {}
I0923 16:51:26.951620       1 controllerserver-default.go:42] ID: 11 Using default ControllerGetCapabilities
I0923 16:51:26.951784       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}}}]}
I0923 16:51:26.954419       1 utils.go:198] ID: 12 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0923 16:51:26.954446       1 utils.go:199] ID: 12 GRPC request: {}
I0923 16:51:26.954455       1 controllerserver-default.go:42] ID: 12 Using default ControllerGetCapabilities
I0923 16:51:26.954620       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}}}]}
I0923 16:51:28.360749       1 utils.go:198] ID: 13 GRPC call: /csi.v1.Identity/GetPluginInfo
I0923 16:51:28.360790       1 utils.go:199] ID: 13 GRPC request: {}
I0923 16:51:28.360799       1 identityserver-default.go:40] ID: 13 Using default GetPluginInfo
I0923 16:51:28.360831       1 utils.go:205] ID: 13 GRPC response: {"name":"rbd.csi.ceph.com","vendor_version":"v3.11.0"}
I0923 16:51:28.362616       1 utils.go:198] ID: 14 GRPC call: /csi.v1.Identity/Probe
I0923 16:51:28.362637       1 utils.go:199] ID: 14 GRPC request: {}
I0923 16:51:28.362651       1 utils.go:205] ID: 14 GRPC response: {}
I0923 16:51:28.363433       1 utils.go:198] ID: 15 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0923 16:51:28.363511       1 utils.go:199] ID: 15 GRPC request: {}
I0923 16:51:28.363549       1 controllerserver-default.go:42] ID: 15 Using default ControllerGetCapabilities
I0923 16:51:28.363732       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}}}]}
I0923 16:51:29.849107       1 utils.go:198] ID: 16 GRPC call: /csi.v1.Identity/Probe
I0923 16:51:29.849168       1 utils.go:199] ID: 16 GRPC request: {}
I0923 16:51:29.849350       1 utils.go:205] ID: 16 GRPC response: {}
I0923 16:51:29.852379       1 utils.go:198] ID: 17 GRPC call: /csi.v1.Identity/GetPluginInfo
I0923 16:51:29.852412       1 utils.go:199] ID: 17 GRPC request: {}
I0923 16:51:29.852539       1 identityserver-default.go:40] ID: 17 Using default GetPluginInfo
I0923 16:51:29.852685       1 utils.go:205] ID: 17 GRPC response: {"name":"rbd.csi.ceph.com","vendor_version":"v3.11.0"}
I0923 16:51:29.857721       1 utils.go:198] ID: 18 GRPC call: /csi.v1.Identity/Probe
I0923 16:51:29.857786       1 utils.go:199] ID: 18 GRPC request: {}
I0923 16:51:29.857813       1 utils.go:205] ID: 18 GRPC response: {}
I0923 16:51:29.858451       1 utils.go:198] ID: 19 GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0923 16:51:29.858481       1 utils.go:199] ID: 19 GRPC request: {}
I0923 16:51:29.859115       1 utils.go:205] ID: 19 GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}},{"Type":{"VolumeExpansion":{"type":1}}},{"Type":{"Service":{"type":2}}}]}
I0923 16:51:29.860154       1 utils.go:198] ID: 20 GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0923 16:51:29.860192       1 utils.go:199] ID: 20 GRPC request: {}
I0923 16:51:29.860205       1 controllerserver-default.go:42] ID: 20 Using default ControllerGetCapabilities
I0923 16:51:29.860369       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}}}]}
I0923 16:52:30.147718       1 utils.go:198] ID: 21 GRPC call: /csi.v1.Identity/Probe
I0923 16:52:30.147774       1 utils.go:199] ID: 21 GRPC request: {}
I0923 16:52:30.147797       1 utils.go:205] ID: 21 GRPC response: {}
I0923 16:53:30.091723       1 utils.go:198] ID: 22 GRPC call: /csi.v1.Identity/Probe
I0923 16:53:30.091803       1 utils.go:199] ID: 22 GRPC request: {}
I0923 16:53:30.091826       1 utils.go:205] ID: 22 GRPC response: {}
I0923 16:54:30.089164       1 utils.go:198] ID: 23 GRPC call: /csi.v1.Identity/Probe
I0923 16:54:30.089217       1 utils.go:199] ID: 23 GRPC request: {}
I0923 16:54:30.089240       1 utils.go:205] ID: 23 GRPC response: {}
I0923 16:55:30.100481       1 utils.go:198] ID: 24 GRPC call: /csi.v1.Identity/Probe
I0923 16:55:30.101062       1 utils.go:199] ID: 24 GRPC request: {}
I0923 16:55:30.101159       1 utils.go:205] ID: 24 GRPC response: {}
I0923 16:55:59.444068       1 utils.go:198] ID: 25 Req-ID: pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4 GRPC call: /csi.v1.Controller/CreateVolume
I0923 16:55:59.444454       1 utils.go:199] ID: 25 Req-ID: pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4 GRPC request: {"capacity_range":{"required_bytes":5368709120},"name":"pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4","parameters":{"clusterID":"4837cbf8-4f90-4300-b3f6-726c9b9f89b4","csi.storage.k8s.io/pv/name":"pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4","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}}]}
I0923 16:55:59.444718       1 rbd_util.go:1315] ID: 25 Req-ID: pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4 setting disableInUseChecks: false image features: [layering] mounter: rbd
E0923 16:55:59.469726       1 omap.go:80] ID: 25 Req-ID: pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4 omap not found (pool="kube", namespace="", name="csi.volumes.default"): rados: ret=-2, No such file or directory
I0923 16:55:59.489559       1 omap.go:159] ID: 25 Req-ID: pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4 set omap keys (pool="kube", namespace="", name="csi.volumes.default"): map[csi.volume.pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4:16161cde-027b-4b7c-a607-67660ae540b7])
I0923 16:55:59.496882       1 omap.go:159] ID: 25 Req-ID: pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4 set omap keys (pool="kube", namespace="", name="csi.volume.16161cde-027b-4b7c-a607-67660ae540b7"): map[csi.imagename:csi-vol-16161cde-027b-4b7c-a607-67660ae540b7 csi.volname:pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4 csi.volume.owner:default])
I0923 16:55:59.496916       1 rbd_journal.go:491] ID: 25 Req-ID: pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4 generated Volume ID (0001-0024-4837cbf8-4f90-4300-b3f6-726c9b9f89b4-0000000000000002-16161cde-027b-4b7c-a607-67660ae540b7) and image name (csi-vol-16161cde-027b-4b7c-a607-67660ae540b7) for request name (pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4)
I0923 16:55:59.496982       1 rbd_util.go:423] ID: 25 Req-ID: pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4 rbd: create kube/csi-vol-16161cde-027b-4b7c-a607-67660ae540b7 size 5120M (features: [layering]) using mon 162.253.55.176
I0923 16:55:59.497019       1 rbd_util.go:1563] ID: 25 Req-ID: pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4 setting image options on kube/csi-vol-16161cde-027b-4b7c-a607-67660ae540b7
I0923 16:55:59.535586       1 controllerserver.go:763] ID: 25 Req-ID: pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4 created image kube/csi-vol-16161cde-027b-4b7c-a607-67660ae540b7 backed for request name pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4
I0923 16:55:59.576565       1 omap.go:159] ID: 25 Req-ID: pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4 set omap keys (pool="kube", namespace="", name="csi.volume.16161cde-027b-4b7c-a607-67660ae540b7"): map[csi.imageid:37f41e00530c])
I0923 16:55:59.675814       1 utils.go:205] ID: 25 Req-ID: pvc-47ae01aa-3e12-4da8-bc5c-4c0101ae1dd4 GRPC response: {"volume":{"capacity_bytes":5368709120,"volume_context":{"clusterID":"4837cbf8-4f90-4300-b3f6-726c9b9f89b4","imageFeatures":"layering","imageName":"csi-vol-16161cde-027b-4b7c-a607-67660ae540b7","journalPool":"kube","pool":"kube"},"volume_id":"0001-0024-4837cbf8-4f90-4300-b3f6-726c9b9f89b4-0000000000000002-16161cde-027b-4b7c-a607-67660ae540b7"}}
I0923 16:56:30.089895       1 utils.go:198] ID: 26 GRPC call: /csi.v1.Identity/Probe
I0923 16:56:30.089944       1 utils.go:199] ID: 26 GRPC request: {}
I0923 16:56:30.089966       1 utils.go:205] ID: 26 GRPC response: {}