Comment 1 for bug 2002535

Below is the actions executed by cinder at the time of the failure:

Jan 13 02:47:52 e2e-os-pstorenfs105 cinder-volume[369491]: INFO cinder.volume.manager [req-387efd2d-a695-4f9f-850e-aa55cb0c9890 req-5dd551a8-1c4c-404f-b232-ef9ca400335d admin None] Terminate volume connection completed successfully.
Jan 13 02:47:52 e2e-os-pstorenfs105 cinder-volume[369491]: DEBUG cinder.volume.manager [req-387efd2d-a695-4f9f-850e-aa55cb0c9890 req-5dd551a8-1c4c-404f-b232-ef9ca400335d admin None] Deleting attachment 09b84254-c092-4cfc-9af9-c08a6f770efb. {{(pid=369491) attachment_delete /opt/stack/new/cinder/cinder/volume/manager.py:4998}}
Jan 13 02:47:53 e2e-os-pstorenfs105 cinder-volume[369491]: DEBUG cinder.volume.drivers.nfs [req-387efd2d-a695-4f9f-850e-aa55cb0c9890 req-771ac965-6761-482d-bd2c-e2ec2c2b1a39 admin None] Initializing connection to volume 00d0f8b9-98e4-4d00-b697-24097efd1a9f. Connector: {'platform': 'x86_64', 'os_type': 'linux', 'ip': '10.228.225.105', 'host': 'e2e-os-pstorenfs105', 'multipath': True, 'initiator': 'iqn.2005-03.org.open-iscsi:37fab0269180', 'do_local_attach': False, 'uuid': '0801a08f-93fd-4be3-8a20-b3607ffd0c14', 'system uuid': '422a6a69-7f46-aab6-c409-74221f8028af', 'nvme_native_multipath': False, 'mountpoint': '/dev/vda'} {{(pid=369491) initialize_connection /opt/stack/new/cinder/cinder/volume/drivers/nfs.py:138}}
Jan 13 02:47:53 e2e-os-pstorenfs105 cinder-volume[369491]: DEBUG oslo_concurrency.processutils [req-387efd2d-a695-4f9f-850e-aa55cb0c9890 req-771ac965-6761-482d-bd2c-e2ec2c2b1a39 admin None] Running cmd (subprocess): /usr/bin/python3.8 -m oslo_concurrency.prlimit --as=1073741824 --cpu=60 -- sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C qemu-img info --output=json --force-share /opt/stack/data/cinder/mnt/0f31b785b44925eea1ad3ce3b8eff927/volume-00d0f8b9-98e4-4d00-b697-24097efd1a9f {{(pid=369491) execute /usr/local/lib/python3.8/dist-packages/oslo_concurrency/processutils.py:384}}
Jan 13 02:47:54 e2e-os-pstorenfs105 cinder-volume[369491]: DEBUG oslo_concurrency.processutils [req-387efd2d-a695-4f9f-850e-aa55cb0c9890 req-771ac965-6761-482d-bd2c-e2ec2c2b1a39 admin None] CMD "/usr/bin/python3.8 -m oslo_concurrency.prlimit --as=1073741824 --cpu=60 -- sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C qemu-img info --output=json --force-share /opt/stack/data/cinder/mnt/0f31b785b44925eea1ad3ce3b8eff927/volume-00d0f8b9-98e4-4d00-b697-24097efd1a9f" returned: 0 in 0.560s {{(pid=369491) execute /usr/local/lib/python3.8/dist-packages/oslo_concurrency/processutils.py:422}}
Jan 13 02:47:54 e2e-os-pstorenfs105 cinder-volume[369491]: DEBUG cinder.volume.drivers.nfs [req-387efd2d-a695-4f9f-850e-aa55cb0c9890 req-771ac965-6761-482d-bd2c-e2ec2c2b1a39 admin None] NfsDriver: conn_info: {'driver_volume_type': 'nfs', 'data': {'export': '172.16.20.10:/openstack-nfs1', 'name': 'volume-00d0f8b9-98e4-4d00-b697-24097efd1a9f', 'options': None, 'format': 'raw'}, 'mount_point_base': '/opt/stack/data/cinder/mnt'} {{(pid=369491) initialize_connection /opt/stack/new/cinder/cinder/volume/drivers/nfs.py:164}}
Jan 13 02:47:54 e2e-os-pstorenfs105 cinder-volume[369491]: DEBUG cinder.volume.manager [req-387efd2d-a695-4f9f-850e-aa55cb0c9890 req-771ac965-6761-482d-bd2c-e2ec2c2b1a39 admin None] Connection info returned from driver {'export': '172.16.20.10:/openstack-nfs1', 'name': 'volume-00d0f8b9-98e4-4d00-b697-24097efd1a9f', 'options': None, 'format': 'raw', 'qos_specs': None, 'access_mode': 'rw', 'encrypted': False, 'cacheable': False, 'driver_volume_type': 'nfs', 'mount_point_base': '/opt/stack/data/cinder/mnt', 'attachment_id': 'bf8597e9-b485-4461-9fb1-4cffc38f2638'} {{(pid=369491) _connection_create /opt/stack/new/cinder/cinder/volume/manager.py:4867}}
Jan 13 02:47:54 e2e-os-pstorenfs105 cinder-volume[369491]: INFO cinder.volume.manager [req-387efd2d-a695-4f9f-850e-aa55cb0c9890 req-771ac965-6761-482d-bd2c-e2ec2c2b1a39 admin None] attachment_update completed successfully

The attachment is then deleted and recreated but got stucked into attaching state:

stack@e2e-os-pstorenfs105:~$ openstack --os-volume-api-version 3.27 volume attachment list
+--------------------------------------+--------------------------------------+--------------------------------------+-----------+
| ID | Volume ID | Server ID | Status |
+--------------------------------------+--------------------------------------+--------------------------------------+-----------+
| bf8597e9-b485-4461-9fb1-4cffc38f2638 | 00d0f8b9-98e4-4d00-b697-24097efd1a9f | 1163001d-db23-47b0-85ec-eb1b88cacc8b | attaching |
+--------------------------------------+--------------------------------------+--------------------------------------+-----------+

We can notice as well that the properties of the attachment don't match what is sent through the logs:

openstack --os-volume-api-version 3.27 volume attachment show bf8597e9-b485-4461-9fb1-4cffc38f2638

...[Truncated]
| Properties | access_mode='rw', attachment_id='bf8597e9-b485-4461-9fb1-4cffc38f2638', cacheable='False', driver_volume_type='nfs', encrypted='False', export='172.16.20.10:/openstack-nfs1', format='qcow2', mount_point_base='/opt/stack/data/cinder/mnt', name='volume-00d0f8b9-98e4-4d00-b697-24097efd1a9f', options=, qos_specs= |

In the cinder logfile:

Jan 13 02:47:54 e2e-os-pstorenfs105 cinder-volume[369491]: DEBUG cinder.volume.manager [req-387efd2d-a695-4f9f-850e-aa55cb0c9890 req-771ac965-6761-482d-bd2c-e2ec2c2b1a39 admin None] Connection info returned from driver {'export': '172.16.20.10:/openstack-nfs1', 'name': 'volume-00d0f8b9-98e4-4d00-b697-24097efd1a9f', 'options': None, 'format': 'raw', 'qos_specs': None, 'access_mode': 'rw', 'encrypted': False, 'cacheable': False, 'driver_volume_type': 'nfs', 'mount_point_base': '/opt/stack/data/cinder/mnt', 'attachment_id': 'bf8597e9-b485-4461-9fb1-4cffc38f2638'} {{(pid=369491) _connection_create /opt/stack/new/cinder/cinder/volume/manager.py:4867}}