Volume attachment timeout during ControllerPublishVolume operation in KubeVirt CSI   

  4.18  

    100%

    1. create hostedcluster 4.18 with mce 2.8 on kubevirt 4.18
    2. create pvc and test pod on hostedcluster
    3. pod cann't ready
    

test pod can't ready
    

test pod can be ready
    

➜  oc apply -f - <<EOF
apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  name: test-pvc
spec:
  accessModes:
    - ReadWriteOnce
  resources:
    requests:
      storage: 10Gi
EOF
➜  oc apply -f - <<EOF
apiVersion: v1
kind: Pod
metadata:
  name: test-pod
spec:
  containers:
    - name: app
      image: busybox
      command: ["/bin/sh", "-c", "sleep 3600"]
      volumeMounts:
        - mountPath: "/data"
          name: pvc-storage
  volumes:
    - name: pvc-storage
      persistentVolumeClaim:
        claimName: test-pvc
EOF

➜  my git:(main) ✗ oc logs -n local-cluster-af9a30e4bf0204931238 kubevirt-csi-controller-6bf6866f6d-vs62b                                                                           
Defaulted container "csi-driver" out of: csi-driver, csi-provisioner, csi-attacher, csi-liveness-probe, csi-snapshotter
I1206 09:36:33.457547       1 kubevirt-csi-driver.go:57] Driver vendor csi.kubevirt.io 0.2.0
I1206 09:36:33.461274       1 kubevirt-csi-driver.go:100] Storage class enforcement string: 
allowDefault: true
allowAll: false
I1206 09:36:33.461762       1 driver.go:57] Setting the rpc server
I1206 09:36:33.461823       1 server.go:93] Start listening with scheme unix, addr /var/lib/csi/sockets/pluginproxy/csi.sock
I1206 09:36:33.462136       1 server.go:112] Listening for connections on address: &net.UnixAddr{Name:"/var/lib/csi/sockets/pluginproxy/csi.sock", Net:"unix"}
I1206 09:36:36.772798       1 server.go:121] /csi.v1.Identity/Probe called with request: {}
I1206 09:36:36.811930       1 server.go:126] /csi.v1.Identity/Probe returned with response: {"ready":{"value":true}}
I1206 09:36:36.813725       1 server.go:121] /csi.v1.Identity/GetPluginInfo called with request: {}
I1206 09:36:36.813750       1 server.go:126] /csi.v1.Identity/GetPluginInfo returned with response: {"name":"csi.kubevirt.io","vendor_version":"0.2.0"}
I1206 09:36:36.815634       1 server.go:121] /csi.v1.Identity/GetPluginCapabilities called with request: {}
I1206 09:36:36.815663       1 server.go:126] /csi.v1.Identity/GetPluginCapabilities returned with response: {"capabilities":[{"Type":{"Service":{"type":1}}}]}
I1206 09:36:36.816242       1 server.go:121] /csi.v1.Controller/ControllerGetCapabilities called with request: {}
I1206 09:36:36.816296       1 server.go:126] /csi.v1.Controller/ControllerGetCapabilities returned with response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":7}}}]}
I1206 09:36:39.153598       1 server.go:121] /csi.v1.Identity/Probe called with request: {}
I1206 09:36:39.154430       1 server.go:126] /csi.v1.Identity/Probe returned with response: {"ready":{"value":true}}
I1206 09:36:39.156847       1 server.go:121] /csi.v1.Identity/GetPluginInfo called with request: {}
I1206 09:36:39.156879       1 server.go:126] /csi.v1.Identity/GetPluginInfo returned with response: {"name":"csi.kubevirt.io","vendor_version":"0.2.0"}
I1206 09:36:39.157418       1 server.go:121] /csi.v1.Identity/GetPluginCapabilities called with request: {}
I1206 09:36:39.157445       1 server.go:126] /csi.v1.Identity/GetPluginCapabilities returned with response: {"capabilities":[{"Type":{"Service":{"type":1}}}]}
I1206 09:36:39.158206       1 server.go:121] /csi.v1.Controller/ControllerGetCapabilities called with request: {}
I1206 09:36:39.158230       1 server.go:126] /csi.v1.Controller/ControllerGetCapabilities returned with response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":7}}}]}
I1206 09:36:40.916913       1 server.go:121] /csi.v1.Identity/GetPluginInfo called with request: {}
I1206 09:36:40.916963       1 server.go:126] /csi.v1.Identity/GetPluginInfo returned with response: {"name":"csi.kubevirt.io","vendor_version":"0.2.0"}
I1206 09:36:43.205778       1 server.go:121] /csi.v1.Identity/GetPluginInfo called with request: {}
I1206 09:36:43.205827       1 server.go:126] /csi.v1.Identity/GetPluginInfo returned with response: {"name":"csi.kubevirt.io","vendor_version":"0.2.0"}
I1206 09:36:43.210679       1 server.go:121] /csi.v1.Identity/Probe called with request: {}
I1206 09:36:43.211891       1 server.go:126] /csi.v1.Identity/Probe returned with response: {"ready":{"value":true}}
I1206 09:36:43.218760       1 server.go:121] /csi.v1.Controller/ControllerGetCapabilities called with request: {}
I1206 09:36:43.218803       1 server.go:126] /csi.v1.Controller/ControllerGetCapabilities returned with response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":7}}}]}
I1206 09:54:14.408849       1 server.go:121] /csi.v1.Controller/CreateVolume called with request: {"capacity_range":{"required_bytes":10737418240},"name":"pvc-ddb3be17-8f4f-443d-a190-e610bcee5507","parameters":{"bus":"scsi"},"volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}}]}
I1206 09:54:14.409149       1 controller.go:120] Create Volume Request: name:"pvc-ddb3be17-8f4f-443d-a190-e610bcee5507" capacity_range:{required_bytes:10737418240} volume_capabilities:{mount:{fs_type:"ext4"} access_mode:{mode:SINGLE_NODE_WRITER}} parameters:{key:"bus" value:"scsi"}
I1206 09:54:14.416771       1 controller.go:198] creating new DataVolume local-cluster-af9a30e4bf0204931238/pvc-ddb3be17-8f4f-443d-a190-e610bcee5507
I1206 09:54:14.434770       1 server.go:126] /csi.v1.Controller/CreateVolume returned with response: {"volume":{"capacity_bytes":10737418240,"volume_context":{"bus":"scsi","serial":"44382b6f-47ef-4411-a1b5-4f555257c9b2"},"volume_id":"pvc-ddb3be17-8f4f-443d-a190-e610bcee5507"}}
I1206 09:54:41.664810       1 server.go:121] /csi.v1.Controller/ControllerPublishVolume called with request: {"node_id":"498d8710-bcd5-5785-882c-944604fd9314","volume_capability":{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}},"volume_context":{"bus":"scsi","serial":"44382b6f-47ef-4411-a1b5-4f555257c9b2","storage.kubernetes.io/csiProvisionerIdentity":"1733477796816-7129-csi.kubevirt.io"},"volume_id":"pvc-ddb3be17-8f4f-443d-a190-e610bcee5507"}
I1206 09:54:41.670304       1 controller.go:336] Attaching DataVolume pvc-ddb3be17-8f4f-443d-a190-e610bcee5507 to Node ID 498d8710-bcd5-5785-882c-944604fd9314
I1206 09:54:41.680670       1 controller.go:352] Start attaching DataVolume pvc-ddb3be17-8f4f-443d-a190-e610bcee5507 to VM af9a30e4bf0204931238-8x9dq-d6d2p. Volume name: pvc-ddb3be17-8f4f-443d-a190-e610bcee5507. Serial: 44382b6f-47ef-4411-a1b5-4f555257c9b2. Bus: scsi
E1206 09:56:41.719272       1 controller.go:390] volume pvc-ddb3be17-8f4f-443d-a190-e610bcee5507 failed to be ready in time (2m) in VM af9a30e4bf0204931238-8x9dq-d6d2p, client rate limiter Wait returned an error: context deadline exceeded
E1206 09:56:41.719303       1 server.go:124] /csi.v1.Controller/ControllerPublishVolume returned with error: client rate limiter Wait returned an error: context deadline exceeded
I1206 09:56:41.725068       1 server.go:121] /csi.v1.Controller/ControllerPublishVolume called with request: {"node_id":"498d8710-bcd5-5785-882c-944604fd9314","volume_capability":{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}},"volume_context":{"bus":"scsi","serial":"44382b6f-47ef-4411-a1b5-4f555257c9b2","storage.kubernetes.io/csiProvisionerIdentity":"1733477796816-7129-csi.kubevirt.io"},"volume_id":"pvc-ddb3be17-8f4f-443d-a190-e610bcee5507"}
I1206 09:56:41.730245       1 controller.go:336] Attaching DataVolume pvc-ddb3be17-8f4f-443d-a190-e610bcee5507 to Node ID 498d8710-bcd5-5785-882c-944604fd9314
I1206 09:56:41.736873       1 controller.go:352] Start attaching DataVolume pvc-ddb3be17-8f4f-443d-a190-e610bcee5507 to VM af9a30e4bf0204931238-8x9dq-d6d2p. Volume name: pvc-ddb3be17-8f4f-443d-a190-e610bcee5507. Serial: 44382b6f-47ef-4411-a1b5-4f555257c9b2. Bus: scsi
E1206 09:58:41.741561       1 controller.go:390] volume pvc-ddb3be17-8f4f-443d-a190-e610bcee5507 failed to be ready in time (2m) in VM af9a30e4bf0204931238-8x9dq-d6d2p, client rate limiter Wait returned an error: rate: Wait(n=1) would exceed context deadline
E1206 09:58:41.741588       1 server.go:124] /csi.v1.Controller/ControllerPublishVolume returned with error: client rate limiter Wait returned an error: rate: Wait(n=1) would exceed context deadline
I1206 09:58:41.747386       1 server.go:121] /csi.v1.Controller/ControllerPublishVolume called with request: {"node_id":"498d8710-bcd5-5785-882c-944604fd9314","volume_capability":{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}},"volume_context":{"bus":"scsi","serial":"44382b6f-47ef-4411-a1b5-4f555257c9b2","storage.kubernetes.io/csiProvisionerIdentity":"1733477796816-7129-csi.kubevirt.io"},"volume_id":"pvc-ddb3be17-8f4f-443d-a190-e610bcee5507"}
I1206 09:58:41.752396       1 controller.go:336] Attaching DataVolume pvc-ddb3be17-8f4f-443d-a190-e610bcee5507 to Node ID 498d8710-bcd5-5785-882c-944604fd9314
I1206 09:58:41.756334       1 controller.go:352] Start attaching DataVolume pvc-ddb3be17-8f4f-443d-a190-e610bcee5507 to VM af9a30e4bf0204931238-8x9dq-d6d2p. Volume name: pvc-ddb3be17-8f4f-443d-a190-e610bcee5507. Serial: 44382b6f-47ef-4411-a1b5-4f555257c9b2. Bus: scsi