I wanted to share additional insights for this bug.  It appears there is a race condition in Nova that causes Nova to tear down the iSCSI connection to the volume before the volume swap happens.  

Below is the analysis.

Tempest.log shows (filtering just on the common.waiters process).  This provides a high level but effective summary of the operations as they are happening.



1- Create Volume 1
2022-09-30 02:47:31.421 998746 INFO tempest.common.waiters [-] volume 34a66f7b-9580-4b83-b853-dbca4b43c13e reached available after waiting for 15.421489 seconds
2- Create Volume 2
2022-09-30 02:47:47.021 998746 INFO tempest.common.waiters [-] volume cd473ad8-afb4-4373-abbd-42845cdefed4 reached available after waiting for 16.021275 seconds
3- Create and boot instance 1 and instance 2 (But seems more like a timeout to wait for the instances to report ready)
2022-09-30 02:48:49.301 998746 INFO tempest.common.waiters [-] State transition "BUILD/scheduling" ==> "ACTIVE/None" after 61 second wait
4- Attach Volume 1 to instance 1
2022-09-30 02:49:05.578 998746 INFO tempest.common.waiters [-] Attachment b0e48a10-a2b7-49f8-9226-db8bea7dc901 created for volume 34a66f7b-9580-4b83-b853-dbca4b43c13e to server 0d711b7b-4693-4a7e-9a94-ca4186b4a670 after waiting for 15.578472 seconds
5- Attach Volume 1 to instance 2
2022-09-30 02:49:21.178 998746 INFO tempest.common.waiters [-] Attachment ea690a72-b43f-4155-b882-704c4d780d0e created for volume 34a66f7b-9580-4b83-b853-dbca4b43c13e to server b87546de-0ad9-4c78-ab53-bd2245c40fb8 after waiting for 16.178497 seconds
6- Swap Volumes
2022-09-30 02:51:52.798 998746 INFO tempest.common.waiters [-] volume 34a66f7b-9580-4b83-b853-dbca4b43c13e reached in-use after waiting for 151.798836 seconds



Nova Logs shows:  




Sep 30 02:47:50  Lock "compute_resources" "released" by "nova.compute.resource_tracker.ResourceTracker.instance_claim" :: held 0.220s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:47:50  Lock "compute_resources" "released" by "nova.compute.resource_tracker.ResourceTracker.instance_claim" :: held 0.246s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:47:50  Lock "/opt/stack/data/nova/instances/0d711b7b-4693-4a7e-9a94-ca4186b4a670/disk.info" "released" by "nova.virt.libvirt.imagebackend.Image.resolve_driver_format.<locals>.write_to_disk_info_file" :: held 0.003s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:47:50  Lock "/opt/stack/data/nova/instances/b87546de-0ad9-4c78-ab53-bd2245c40fb8/disk.info" "released" by "nova.virt.libvirt.imagebackend.Image.resolve_driver_format.<locals>.write_to_disk_info_file" :: held 0.002s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:47:50  Lock "bf54a85eb14ee030c394d58e82febb0f522d915a" "released" by "nova.virt.libvirt.imagebackend.Qcow2.create_image.<locals>.create_qcow2_image" :: held 0.241s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:47:51  Lock "bf54a85eb14ee030c394d58e82febb0f522d915a" "released" by "nova.virt.libvirt.imagebackend.Qcow2.create_image.<locals>.create_qcow2_image" :: held 0.344s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:47:51  Lock "vgpu_resources" "released" by "nova.virt.libvirt.driver.LibvirtDriver._allocate_mdevs" :: held 0.001s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:47:51  Lock "vgpu_resources" "released" by "nova.virt.libvirt.driver.LibvirtDriver._allocate_mdevs" :: held 0.000s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:47:52  Lock "b87546de-0ad9-4c78-ab53-bd2245c40fb8-events" "released" by "nova.compute.manager.InstanceEvents.prepare_for_instance_event.<locals>._create_or_get_event" :: held 0.001s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:47:52  Lock "0d711b7b-4693-4a7e-9a94-ca4186b4a670-events" "released" by "nova.compute.manager.InstanceEvents.prepare_for_instance_event.<locals>._create_or_get_event" :: held 0.001s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:47:58  Lock "0d711b7b-4693-4a7e-9a94-ca4186b4a670" "released" by "nova.compute.manager.ComputeManager.build_and_run_instance.<locals>._locked_do_build_and_run_instance" :: held 8.460s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:47:58  Lock "b87546de-0ad9-4c78-ab53-bd2245c40fb8" "released" by "nova.compute.manager.ComputeManager.build_and_run_instance.<locals>._locked_do_build_and_run_instance" :: held 8.487s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:48:50  Lock "0d711b7b-4693-4a7e-9a94-ca4186b4a670" "released" by "nova.compute.manager.ComputeManager.reserve_block_device_name.<locals>.do_reserve" :: held 0.293s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:49:02  Lock "connect_to_iscsi_portal-192.168.0.57:3260-iqn.2005-03.org.open-iscsi:fcdef5ffc8a8.hpexp-target" "released" by "os_brick.initiator.connectors.iscsi.ISCSIConnector._connect_to_iscsi_portal_unsafe" :: held 2.169s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:49:03  Lock "connect_volume" "released" by "os_brick.initiator.connectors.iscsi.ISCSIConnector.connect_volume" :: held 3.202s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:49:03  Lock "0d711b7b-4693-4a7e-9a94-ca4186b4a670" "released" by "nova.compute.manager.ComputeManager.attach_volume.<locals>.do_attach_volume" :: held 13.409s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:49:05  Lock "b87546de-0ad9-4c78-ab53-bd2245c40fb8" "released" by "nova.compute.manager.ComputeManager.reserve_block_device_name.<locals>.do_reserve" :: held 0.082s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:49:15  Lock "connect_to_iscsi_portal-192.168.0.57:3260-iqn.2005-03.org.open-iscsi:fcdef5ffc8a8.hpexp-target" "released" by "os_brick.initiator.connectors.iscsi.ISCSIConnector._connect_to_iscsi_portal_unsafe" :: held 0.055s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:49:15  Lock "connect_volume" "released" by "os_brick.initiator.connectors.iscsi.ISCSIConnector.connect_volume" :: held 0.077s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:49:15  Lock "b87546de-0ad9-4c78-ab53-bd2245c40fb8" "released" by "nova.compute.manager.ComputeManager.attach_volume.<locals>.do_attach_volume" :: held 9.919s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:49:33  Lock "connect_to_iscsi_portal-192.168.0.57:3260-iqn.2005-03.org.open-iscsi:fcdef5ffc8a8.hpexp-target" "released" by "os_brick.initiator.connectors.iscsi.ISCSIConnector._connect_to_iscsi_portal_unsafe" :: held 0.059s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:49:34  Lock "connect_volume" "released" by "os_brick.initiator.connectors.iscsi.ISCSIConnector.connect_volume" :: held 1.109s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:51:47  Lock "connect_volume" "released" by "os_brick.initiator.connectors.iscsi.ISCSIConnector.disconnect_volume" :: held 0.156s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 02:51:55  Lock "0d711b7b-4693-4a7e-9a94-ca4186b4a670" "released" by "nova.compute.manager.ComputeManager.swap_volume.<locals>._do_locked_swap_volume" :: held 153.400s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 03:07:18  Lock "b87546de-0ad9-4c78-ab53-bd2245c40fb8" "released" by "nova.compute.manager.ComputeManager.detach_volume.<locals>.do_detach_volume" :: held 1.869s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 03:08:18  Lock "connect_volume" "released" by "os_brick.initiator.connectors.iscsi.ISCSIConnector.disconnect_volume" :: held 0.210s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 03:08:29  Lock "0d711b7b-4693-4a7e-9a94-ca4186b4a670" "released" by "nova.compute.manager.ComputeManager.detach_volume.<locals>.do_detach_volume" :: held 12.629s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 03:09:17  Lock "0d711b7b-4693-4a7e-9a94-ca4186b4a670-events" "released" by "nova.compute.manager.InstanceEvents.clear_events_for_instance.<locals>._clear_events" :: held 0.001s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 03:09:17  Lock "b87546de-0ad9-4c78-ab53-bd2245c40fb8-events" "released" by "nova.compute.manager.InstanceEvents.clear_events_for_instance.<locals>._clear_events" :: held 0.001s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 03:09:19  Lock "compute_resources" "released" by "nova.compute.resource_tracker.ResourceTracker.update_usage" :: held 0.091s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 30 03:09:19  Lock "compute_resources" "released" by "nova.compute.resource_tracker.ResourceTracker.update_usage" :: held 0.076s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}




Notice at 02:51:47, there is an iSCSI connector disconnect volume request, right before the SWAP operation 8 secs later.  It appears this iSCSI disconnect intends to detach the volume from the instance and creates the issue with the swap operation since the expected volume is no longer attached.



In successful iterations of this test, the sequence looks as follows:



.......
Sep 29 17:02:00 Lock "connect_volume" "released" by "os_brick.initiator.connectors.iscsi.ISCSIConnector.connect_volume" :: held 1.101s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 29 17:12:21 Lock "4aeaeb5d-295f-4149-9330-a016d9da1730" "released" by "nova.compute.manager.ComputeManager.swap_volume.<locals>._do_locked_swap_volume" :: held 632.783s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 29 17:12:25 Lock "connect_volume" "released" by "os_brick.initiator.connectors.iscsi.ISCSIConnector.disconnect_volume" :: held 0.142s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 29 17:12:40 "90328076-83b8-4854-b6d4-8d96ca63dd00" "released" by "nova.compute.manager.ComputeManager.detach_volume.<locals>.do_detach_volume" :: held 15.745s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 29 17:13:24 "90328076-83b8-4854-b6d4-8d96ca63dd00-events" "released" by "nova.compute.manager.InstanceEvents.clear_events_for_instance.<locals>._clear_events" :: held 0.001s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 29 17:13:25 Lock "4aeaeb5d-295f-4149-9330-a016d9da1730-events" "released" by "nova.compute.manager.InstanceEvents.clear_events_for_instance.<locals>._clear_events" :: held 0.001s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 29 17:13:26 Lock "connect_volume" "released" by "os_brick.initiator.connectors.iscsi.ISCSIConnector.disconnect_volume" :: held 0.292s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 29 17:13:27 Lock "compute_resources" "released" by "nova.compute.resource_tracker.ResourceTracker.update_usage" :: held 0.086s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 29 17:13:27 Lock "90328076-83b8-4854-b6d4-8d96ca63dd00" "released" by "nova.compute.manager.ComputeManager.terminate_instance.<locals>.do_terminate_instance" :: held 2.625s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}
Sep 29 17:13:41 Lock "compute_resources" "released" by "nova.compute.resource_tracker.ResourceTracker.update_usage" :: held 0.086s {{(pid=2571444) inner /usr/local/lib/python3.8/dist-packages/oslo_concurrency/lockutils.py:400}}



Note at line 17:12:21 there is no disconnect before the swap.  They happen after the swap.  



What is causing Nova to intermittently invoke os_brick.initiator.connectors.ISCSIConnector.disconnect_volume  before the swap is likely the root cause of this issue.