nvmeof: ListListener grpc call returns empty

[gadididi]

Describe the bug

When we are creating a subsystem with AutoListener feature, the nListListener grpc call (that is called right after) returns empty listener list.
But if we query (via GW cli) it returns right answer.

Environment details

• Image/version of Ceph CSI driver : canary
• Kubernetes cluster version : non relevant
• Ceph cluster version : ceph main (which has AutoListener support)

Steps to reproduce

Steps to reproduce the behavior:

1. create rook env and deploy the main ceph version
2. deploy nvmeof csi provisioner
3. create pvc
4. you will see in the log the return list of listeners from the GW is empty.
5. deploy the node plugin
   6. create test-pod - you will get an error-- the list of listeners is empty!

Actual results

There is no error handling in the provisioner side because we cannot know which listeners (GWs) really exist in this cluster.
Then just when you create test-pod you will catch this error.

Describe what happened

Expected behavior

A clear and concise description of what you expected to happen.

Logs

• csi-provisioner:

I0208 15:25:22.975469       1 utils.go:350] ID: 15 Req-ID: pvc-6ad5a7a7-3c82-4afd-87a2-e0be3651968f GRPC call: /csi.v1.Controller/CreateVolume
I0208 15:25:22.975594       1 utils.go:351] ID: 15 Req-ID: pvc-6ad5a7a7-3c82-4afd-87a2-e0be3651968f GRPC request: {"capacity_range":{"required_bytes":134217728},"name":"pvc-6ad5a7a7-3c82-4afd-87a2-e0be3651968f","parameters":{"clusterID":"rook-ceph","csi.storage.k8s.io/pv/name":"pvc-6ad5a7a7-3c82-4afd-87a2-e0be3651968f","csi.storage.k8s.io/pvc/name":"nvmeof-external-volume","csi.storage.k8s.io/pvc/namespace":"default","imageFeatures":"layering,deep-flatten,exclusive-lock,object-map,fast-diff","imageFormat":"2","networkMask":"10.128.0.0/14","nvmeofGatewayAddress":"172.30.113.58","nvmeofGatewayPort":"5500","pool":"nvmeof","subsystemNQN":"nqn.2016-06.io.spdk:cnode1.rook-ceph"},"secrets":"***stripped***","volume_capabilities":[{"access_mode":{"mode":"SINGLE_NODE_WRITER"},"mount":{"fs_type":"ext4"}}]}
..
..
I0208 15:25:23.174353       1 nvmeof.go:293] ID: 15 Req-ID: pvc-6ad5a7a7-3c82-4afd-87a2-e0be3651968f Subsystem created successfully: nqn.2016-06.io.spdk:cnode1.rook-ceph
..
..
I0208 15:25:24.384533       1 nvmeof.go:504] ID: 15 Req-ID: pvc-6ad5a7a7-3c82-4afd-87a2-e0be3651968f Listing listeners in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph
I0208 15:25:24.407404       1 nvmeof.go:518] ID: 15 Req-ID: pvc-6ad5a7a7-3c82-4afd-87a2-e0be3651968f Listed listeners in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph successfully
I0208 15:25:24.407431       1 controllerserver.go:804] ID: 15 Req-ID: pvc-6ad5a7a7-3c82-4afd-87a2-e0be3651968f Retrieved 0 auto-created listeners

Additional context

from script:

kubectl -n rook-ceph exec -it nvmeof-cli -- /tmp/nvmeof-cli subsystem add --subsystem nqn.2016-06.io.ceph:subsystem.test-integration --network-mask "10.128.0.0/14"
kubectl -n rook-ceph exec -it nvmeof-cli -- /tmp/nvmeof-cli listener list -n nqn.2016-06.io.ceph:subsystem.test-integration.group-a

log:

Listeners for nqn.2016-06.io.ceph:subsystem.test-integration.group-a:
╒═══════════════════════════╤═════════════╤══════════════════╤══════════════════╤══════════╤══════════╤══════════╕
│ Host                      │ Transport   │ Address Family   │ Address          │ Secure   │ Active   │ Manual   │
╞═══════════════════════════╪═════════════╪══════════════════╪══════════════════╪══════════╪══════════╪══════════╡
│ rook-ceph-nvmeof-nvmeof-a │ TCP         │ IPv4             │ 10.131.0.31:4420 │ No       │ Yes      │ No       │
╘═══════════════════════════╧═════════════╧══════════════════╧══════════════════╧══════════╧══════════╧══════════╛

Solution

I added a very short sleep right after subsystem creation and right before the ListListener grpc call and it worked.
probably there is some delay in the nvmeof GW update omap file.
I am going to add retry mechanism with few attempts.

[Madhu-1]

@gadididi isnt this a bug in the nvme not a bug in the csi driver? adding delay is kind of a workaround not the actual bug fix.

[gadididi]

@Madhu-1 yes, you are right. I need to open another issue in nvmeof gw repo. but in the meantime, I will add this workaround, because we would like to proceed with AutoListener instead of manually listeners list

[gadididi]

it is something we need to investigate. on the GW side.

@Madhu-1 , I added retry mechanism and checked:
sometimes it takes ~less than 1 second

I0209 12:31:15.660021       1 controllerserver.go:1206] ID: 18 Req-ID: pvc-34597f0f-c2e2-4789-84e4-dd967fbcf60e Connected to the gateway 172.30.73.100:5500
I0209 12:31:15.660038       1 nvmeof.go:324] ID: 18 Req-ID: pvc-34597f0f-c2e2-4789-84e4-dd967fbcf60e Checking if subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph exists on gateway 172.30.73.100:5500
I0209 12:31:15.670263       1 nvmeof.go:345] ID: 18 Req-ID: pvc-34597f0f-c2e2-4789-84e4-dd967fbcf60e Subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph does not exist
I0209 12:31:15.670295       1 nvmeof.go:256] ID: 18 Req-ID: pvc-34597f0f-c2e2-4789-84e4-dd967fbcf60e Creating NVMe subsystem: nqn.2016-06.io.spdk:cnode1.rook-ceph on gateway 172.30.73.100:5500
I0209 12:31:15.718619       1 nvmeof.go:294] ID: 18 Req-ID: pvc-34597f0f-c2e2-4789-84e4-dd967fbcf60e Subsystem created successfully: nqn.2016-06.io.spdk:cnode1.rook-ceph
I0209 12:31:15.718644       1 controllerserver.go:777] ID: 18 Req-ID: pvc-34597f0f-c2e2-4789-84e4-dd967fbcf60e subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph and Listener [] for the subsystem were created
I0209 12:31:15.718651       1 nvmeof.go:113] ID: 18 Req-ID: pvc-34597f0f-c2e2-4789-84e4-dd967fbcf60e Creating namespace for RBD nvmeof/csi-vol-22714dd0-c089-4a95-b1b8-d1bf99b10b8e in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph
I0209 12:31:16.596159       1 nvmeof.go:144] ID: 18 Req-ID: pvc-34597f0f-c2e2-4789-84e4-dd967fbcf60e Namespace created with NSID: 1
I0209 12:31:16.596303       1 controllerserver.go:785] ID: 18 Req-ID: pvc-34597f0f-c2e2-4789-84e4-dd967fbcf60e Namespace created: nvmeof/csi-vol-22714dd0-c089-4a95-b1b8-d1bf99b10b8e with NSID: 1
I0209 12:31:16.596333       1 nvmeof.go:505] ID: 18 Req-ID: pvc-34597f0f-c2e2-4789-84e4-dd967fbcf60e Listing listeners in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph
I0209 12:31:16.620588       1 nvmeof.go:519] ID: 18 Req-ID: pvc-34597f0f-c2e2-4789-84e4-dd967fbcf60e Listed listeners in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph successfully
I0209 12:31:16.620634       1 controllerserver.go:803] ID: 18 Req-ID: pvc-34597f0f-c2e2-4789-84e4-dd967fbcf60e Retrieved 1 auto-created listeners

and sometimes it takes ~5 seconds:

I0209 12:31:50.103293       1 controllerserver.go:1206] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Connected to the gateway 172.30.73.100:5500
I0209 12:31:50.103306       1 nvmeof.go:324] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Checking if subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph exists on gateway 172.30.73.100:5500
I0209 12:31:50.115918       1 nvmeof.go:345] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph does not exist
I0209 12:31:50.115954       1 nvmeof.go:256] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Creating NVMe subsystem: nqn.2016-06.io.spdk:cnode1.rook-ceph on gateway 172.30.73.100:5500
I0209 12:31:50.160521       1 nvmeof.go:294] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Subsystem created successfully: nqn.2016-06.io.spdk:cnode1.rook-ceph
I0209 12:31:50.160558       1 controllerserver.go:777] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph and Listener [] for the subsystem were created
I0209 12:31:50.160586       1 nvmeof.go:113] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Creating namespace for RBD nvmeof/csi-vol-01b8fff7-5f65-4bca-878e-8541478665aa in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph
I0209 12:31:51.333925       1 nvmeof.go:144] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Namespace created with NSID: 1
I0209 12:31:51.333956       1 controllerserver.go:785] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Namespace created: nvmeof/csi-vol-01b8fff7-5f65-4bca-878e-8541478665aa with NSID: 1
I0209 12:31:51.333967       1 nvmeof.go:505] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Listing listeners in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph
I0209 12:31:51.359271       1 nvmeof.go:519] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Listed listeners in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph successfully
I0209 12:31:51.487744       1 nvmeof.go:505] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Listing listeners in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph
I0209 12:31:51.512944       1 nvmeof.go:519] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Listed listeners in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph successfully
I0209 12:31:51.794839       1 nvmeof.go:505] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Listing listeners in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph
I0209 12:31:51.818519       1 nvmeof.go:519] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Listed listeners in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph successfully
I0209 12:31:52.286266       1 nvmeof.go:505] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Listing listeners in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph
I0209 12:31:52.311188       1 nvmeof.go:519] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Listed listeners in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph successfully
I0209 12:31:53.191072       1 nvmeof.go:505] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Listing listeners in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph
I0209 12:31:53.216387       1 nvmeof.go:519] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Listed listeners in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph successfully
I0209 12:31:54.894257       1 nvmeof.go:505] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Listing listeners in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph
I0209 12:31:54.919783       1 nvmeof.go:519] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Listed listeners in subsystem nqn.2016-06.io.spdk:cnode1.rook-ceph successfully
I0209 12:31:54.919816       1 controllerserver.go:803] ID: 20 Req-ID: pvc-e5ccdcc5-cd85-40fe-b140-f134cab97415 Retrieved 1 auto-created listeners

[gadididi]

@Madhu-1
Hi,
I investigate it more.
I tried also via cli:

[root@al-gadi-cluster-node1 ~]# docker run -it --entrypoint /bin/sh quay.io/ceph/nvmeof-cli:1.6.5
sh-5.1# python3 -m control.cli --server-address 10.243.64.93 --server-port 5500 subsystem add -n nqn.2016-06.io.spdk:cnode5 --network-mask "10.243.64.90/30" && python3 -m control.cli --server-address 10.243.64.93 --server-port 5500 --server-address 10.243.64.93 --server-port 5500 listener list -n nqn.2016-06.io.spdk:cnode5.mygroup1
Adding subsystem nqn.2016-06.io.spdk:cnode5.mygroup1: Successful
No listeners for nqn.2016-06.io.spdk:cnode5.mygroup1

# then I waited few seconds. 

sh-5.1# python3 -m control.cli --server-address 10.243.64.93 --server-port 5500 --server-address 10.243.64.93 --server-port 5500 listener list -n nqn.2016-06.io.spdk:cnode5.mygroup1
Listeners for nqn.2016-06.io.spdk:cnode5.mygroup1:
╒═══════════════════════╤═════════════╤══════════════════╤═══════════════════╤══════════╤══════════╤══════════╕
│ Host                  │ Transport   │ Address Family   │ Address           │ Secure   │ Active   │ Manual   │
╞═══════════════════════╪═════════════╪══════════════════╪═══════════════════╪══════════╪══════════╪══════════╡
│ al-gadi-cluster-node2 │ TCP         │ IPv4             │ 10.243.64.91:4420 │ No       │ No       │ No       │
╘═══════════════════════╧═════════════╧══════════════════╧═══════════════════╧══════════╧══════════╧══════════╛

the experimental I have shown above was by run 2 docker command (that take time docker up and down..)
I thought there is cache. but there is not.
The auto created listeners list come from ceph monitor command (nvme-gw listeners). and Ceph has small delay.
So, it is not a bug in nvmeof GW, it just some delay .
So, I am going to add the workaround

[github-actions]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed in a week if no further activity occurs. Thank you for your contributions.