Comment 1 for bug 1917750

Another data point, this time in the nova-live-migration job. Again I see two volumes attached from different backends with the same WWN, this time os-brick returns different sd devices and not the device-mapper links:

https://zuul.opendev.org/t/openstack/build/fb643b53835341ac8589afeadfa7044d/log/compute1/logs/screen-n-cpu.txt

Mar 08 22:29:56.730776 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: DEBUG os_brick.initiator.connectors.iscsi [None req-a7c2d69f-2b26-46a5-9588-0500ed40ecf2 tempest-LiveMigrationTest-303521084 tempest-LiveMigrationTest-303521084-project] Connected to sda using {'target_discovered': False, 'target_portal': '10.208.224.42:3260', 'target_iqn': 'iqn.2010-10.org.openstack:volume-3d034a25-2301-44f7-b10a-7e0a46402c29', 'target_lun': 1, 'volume_id': '3d034a25-2301-44f7-b10a-7e0a46402c29', 'auth_method': 'CHAP', 'auth_username': 'V2L87oQWgpAL7wPMRFng', 'auth_password': '***', 'encrypted': False, 'qos_specs': None, 'access_mode': 'rw', 'cacheable': False} {{(pid=53492) _connect_vol /usr/local/lib/python3.8/dist-packages/os_brick/initiator/connectors/iscsi.py:675}}
Mar 08 22:29:56.732310 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: DEBUG os_brick.initiator.connectors.iscsi [None req-a7c2d69f-2b26-46a5-9588-0500ed40ecf2 tempest-LiveMigrationTest-303521084 tempest-LiveMigrationTest-303521084-project] <== connect_volume: return (1163ms) {'type': 'block', 'scsi_wwn': '360000000000000000e00000000010001', 'path': '/dev/sda'} {{(pid=53492) trace_logging_wrapper /usr/local/lib/python3.8/dist-packages/os_brick/utils.py:171}}
Mar 08 22:29:56.732775 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: DEBUG nova.virt.libvirt.volume.iscsi [None req-a7c2d69f-2b26-46a5-9588-0500ed40ecf2 tempest-LiveMigrationTest-303521084 tempest-LiveMigrationTest-303521084-project] Attached iSCSI volume {'type': 'block', 'scsi_wwn': '360000000000000000e00000000010001', 'path': '/dev/sda'} {{(pid=53492) connect_volume /opt/stack/nova/nova/virt/libvirt/volume/iscsi.py:65}}

Mar 08 22:30:02.484937 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: DEBUG os_brick.initiator.connectors.iscsi [None req-2ade7ce2-8fca-4d71-8c30-496fa8e8fce4 tempest-LiveAutoBlockMigrationV225Test-766901728 tempest-LiveAutoBlockMigrationV225Test-766901728-project-admin] Connected to sdb using {'target_discovered': False, 'target_portal': '10.208.224.30:3260', 'target_iqn': 'iqn.2010-10.org.openstack:volume-2384d911-102d-4b91-bd63-4c73baabd6b6', 'target_lun': 1, 'volume_id': '2384d911-102d-4b91-bd63-4c73baabd6b6', 'auth_method': 'CHAP', 'auth_username': 'rpEQU9A9uBRqDkLWVwkL', 'auth_password': '***', 'encrypted': False, 'qos_specs': None, 'access_mode': 'rw', 'cacheable': False} {{(pid=53492) _connect_vol /usr/local/lib/python3.8/dist-packages/os_brick/initiator/connectors/iscsi.py:675}}
Mar 08 22:30:02.487079 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: DEBUG os_brick.initiator.connectors.iscsi [None req-2ade7ce2-8fca-4d71-8c30-496fa8e8fce4 tempest-LiveAutoBlockMigrationV225Test-766901728 tempest-LiveAutoBlockMigrationV225Test-766901728-project-admin] <== connect_volume: return (1164ms) {'type': 'block', 'scsi_wwn': '360000000000000000e00000000010001', 'path': '/dev/sdb'} {{(pid=53492) trace_logging_wrapper /usr/local/lib/python3.8/dist-packages/os_brick/utils.py:171}}
Mar 08 22:30:02.487948 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: DEBUG nova.virt.libvirt.volume.iscsi [None req-2ade7ce2-8fca-4d71-8c30-496fa8e8fce4 tempest-LiveAutoBlockMigrationV225Test-766901728 tempest-LiveAutoBlockMigrationV225Test-766901728-project-admin] Attached iSCSI volume {'type': 'block', 'scsi_wwn': '360000000000000000e00000000010001', 'path': '/dev/sdb'} {{(pid=53492) connect_volume /opt/stack/nova/nova/virt/libvirt/volume/iscsi.py:65}}

Later the first volume is detached with the end of that test:

Mar 08 22:30:10.883325 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: INFO nova.virt.libvirt.driver [-] [instance: 56f74c85-dfa1-4e86-8efb-5c37b3e6fcdd] Migration operation has completed
Mar 08 22:30:10.883325 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: INFO nova.compute.manager [-] [instance: 56f74c85-dfa1-4e86-8efb-5c37b3e6fcdd] _post_live_migration() is started..
Mar 08 22:30:10.890231 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: DEBUG nova.virt.libvirt.volume.iscsi [-] [instance: 56f74c85-dfa1-4e86-8efb-5c37b3e6fcdd] calling os-brick to detach iSCSI Volume {{(pid=53492) disconnect_volume /opt/stack/nova/nova/virt/libvirt/volume/iscsi.py:72}}
Mar 08 22:30:10.890231 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: DEBUG os_brick.initiator.connectors.iscsi [-] ==> disconnect_volume: call "{'args': (<os_brick.initiator.connectors.iscsi.ISCSIConnector object at 0x7f1fa07513d0>, {'target_discovered': False, 'target_portal': '10.208.224.42:3260', 'target_iqn': 'iqn.2010-10.org.openstack:volume-3d034a25-2301-44f7-b10a-7e0a46402c29', 'target_lun': 1 , 'volume_id': '3d034a25-2301-44f7-b10a-7e0a46402c29', 'auth_method': 'CHAP', 'auth_username': 'V2L87oQWgpAL7wPMRFng', 'auth_password': '***', 'encrypted': False, 'qos_specs': None, 'access_mode': 'rw', 'c acheable': False, 'device_path': '/dev/sda'}, None), 'kwargs': {}}" {{(pid=53492) trace_logging_wrapper /usr/local/lib/python3.8/dist-packages/os_brick/utils.py:144}}
[..]
Mar 08 22:30:10.920184 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: DEBUG os_brick.initiator.connectors.iscsi [-] Resulting device map defaultdict(<function ISCSIConnector._get_connection_devices.<locals>.<lambda> at 0x7f1fa829e1f0>, {('10.208.224.42:3260', 'iqn.2010-10.org.openstack:volume-3d034a25-2301-44f7-b10a-7e0a46402c29'): ({'sda'}, set())}) {{(pid=53492) _get_connection_devices /usr/local/li b/python3.8/dist-packages/os_brick/initiator/connectors/iscsi.py:856}}
Mar 08 22:30:10.920184 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: DEBUG os_brick.initiator.linuxscsi [-] Removing single pathed devices sda {{(pid=53492) remove_connection /usr/local/lib/python3.8/dist-packages/os_brick/initiator/linuxscsi.py:306}}
Mar 08 22:30:10.920184 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: DEBUG os_brick.initiator.linuxscsi [-] Flushing IO for device /dev/sda {{(pid=53492) flush_device_io /usr/local/lib/python3.8/dist-packages/os_brick/initiator/linuxscsi.py:357}}
Mar 08 22:30:10.927806 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: DEBUG os_brick.initiator.linuxscsi [-] Remove SCSI device /dev/sda with /sys/block/sda/device/delete {{(pid=53492) remove_scsi_device /usr/local/lib/python3.8/dist-packages/os_brick/initiator/linuxscsi.py:74}}
Mar 08 22:30:10.990661 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: DEBUG os_brick.initiator.linuxscsi [-] Checking to see if SCSI volumes sda have been removed. {{(pid=53492) wait_for_volumes_removal /usr/local/lib/python3.8/dist-packages/os_brick/initiator/linuxscsi.py:82}}
Mar 08 22:30:10.991004 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: DEBUG os_brick.initiator.linuxscsi [-] SCSI volumes sda have been removed. {{(pid=53492) wait_for_volumes_removal /usr/local/lib/python3.8/dist-packages/os_brick/initiator/linuxscsi.py:92}}

After this libvirt is then unable to detach the volume from the instance in the second test:

Mar 08 22:30:18.778400 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: DEBUG oslo.service.loopingcall [None req-754a1962-4d51-4f79-9b9e-6b8f72730c03 tempest-LiveAutoBlockMigrationV225Test-1318556871 t empest-LiveAutoBlockMigrationV225Test-1318556871-project] Waiting for function nova.virt.libvirt.guest.Guest.detach_device_with_retry.<locals>._do_wait_and_retry_detach to return. {{(pid=53492) func /usr/l ocal/lib/python3.8/dist-packages/oslo_service/loopingcall.py:435}}
Mar 08 22:30:18.780322 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: DEBUG nova.virt.libvirt.guest [-] detach device xml: <disk type="block" device="disk">
Mar 08 22:30:18.780322 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: <driver name="qemu" type="raw" cache="none" io="native"/>
Mar 08 22:30:18.780322 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: <source dev="/dev/sdb"/>
Mar 08 22:30:18.780322 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: <target dev="vdb" bus="virtio"/>
Mar 08 22:30:18.780322 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: <serial>2384d911-102d-4b91-bd63-4c73baabd6b6</serial>
Mar 08 22:30:18.780322 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: <address type="pci" domain="0x0000" bus="0x00" slot="0x07" function="0x0"/>
Mar 08 22:30:18.780322 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: </disk>
[..]
Mar 08 22:35:28.891370 ubuntu-focal-rax-dfw-0023379061 nova-compute[53492]: WARNING nova.virt.block_device [None req-754a1962-4d51-4f79-9b9e-6b8f72730c03 tempest-LiveAutoBlockMigrationV225Test-1318556871 tempest-LiveAutoBlockMigrationV225Test-1318556871-project] [instance: 0aad2869-ecae-4361-9a2a-3201191da38b] Guest refused to detach volume 2384d911-102d-4b91-bd63-4c73baabd6b6: nova.exception.DeviceDetachFailed: Device detach failed for vdb: Unable to detach the device from the live config.

I've got no evidence to show that libvirt is unable to detach *because* of the earlier volume attachment using the same WWN, it's just a hunch at the moment.