Bug 1482846

I had an initial investigation and I was taking 3514f0c5b56a00fac as an example.

==============================================
Instance 633de8f9-79f2-4817-95eb-d821a5f98706
multipath LUN id 3514f0c5b56a00fac
volume id 68e9f336-29dd-4cc3-b8b4-71eccfcd7f81
==============================================

Instance was 633de8f9-79f2-4817-95eb-d821a5f98706 terminated, and along with that the volume attached to it should be detached from the compute node.

2017-08-16 16:37:09,324.324 14176 INFO nova.compute.manager [req-fa377441-1d8d-461b-a916-8f4200cd9e83 153ca67f24b02da9c8ffe20d74eaa2d19316faa4530d00659be6cfc90c9a62cd 0e4da53fae3d482c853573d0e09d93ba - - -] [instance: 633de8f9-79f2-4817-95eb-d821a5f98706] Terminating instance

The multipath paths were removed smoothly as following

2017-08-16 16:37:10,000.000 14176 DEBUG os_brick.initiator.linuxscsi [req-fa377441-1d8d-461b-a916-8f4200cd9e83 153ca67f24b02da9c8ffe20d74eaa2d19316faa4530d00659be6cfc90c9a62cd 0e4da53fae3d482c853573d0e09d93ba - - -] Flush multipath device 3514f0c5b56a00fac flush_multipath_device /usr/lib/python2.7/site-packages/os_brick/initiator/linuxscsi.py:157

2017-08-16 16:37:10,003.003 14176 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): multipath -f 3514f0c5b56a00fac out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194

2017-08-16 16:37:10,127.127 14176 DEBUG oslo.privsep.daemon [-] CMD "multipath -f 3514f0c5b56a00fac" returned: 0 in 0.126s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194

But at the same time in /var/log/messages of the compute node, scsi disk was added back to kernel (/var/log/messages is needed please let me know.)

Aug 16 16:37:10 hudccm21 <kern.notice> kernel:sd 14:0:0:20: [sdl] 41943040 512-byte logical blocks: (21.4 GB/20.0 GiB)
Aug 16 16:37:10 hudccm21 <kern.notice> kernel:scsi 14:0:0:21: Direct-Access     XtremIO  XtremApp         40p0 PQ: 0 ANSI: 6
Aug 16 16:37:10 hudccm21 <kern.notice> kernel:sd 14:0:0:20: [sdl] Write Protect is off
Aug 16 16:37:10 hudccm21 <kern.notice> kernel:sd 14:0:0:20: [sdl] Write cache: enabled, read cache: enabled, supports DPO and FUA
Aug 16 16:37:10 hudccm21 <kern.info> kernel: sdl: sdl1 sdl2
Aug 16 16:37:10 hudccm21 <kern.notice> kernel:sd 14:0:0:20: [sdl] Attached SCSI disk


3 seconds later, the rest of the paths were identified and they formed a multipath device again.

Aug 16 16:37:13 hudccm21 <daemon.notice> multipathd:sdr [65:16]: path added to devmap 3514f0c5b56a00fac
Aug 16 16:37:13 hudccm21 <daemon.notice> multipathd:sdp [8:240]: path added to devmap 3514f0c5b56a00fac
Aug 16 16:37:13 hudccm21 <daemon.notice> multipathd:sdt [65:48]: path added to devmap 3514f0c5b56a00fac

But _cleanup_volumes(what's this?) was called as following, noticing that it took 7+ seconds to detach a volume. 

nova-compute.log

2017-08-16 16:37:19,548.548 14176 INFO nova.compute.manager [req-fa377441-1d8d-461b-a916-8f4200cd9e83 153ca67f24b02da9c8ffe20d74eaa2d19316faa4530d00659be6cfc90c9a62cd 0e4da53fae3d482c853573d0e09d93ba - - -] [instance: 633de8f9-79f2-4817-95eb-d821a5f98706] Took 7.28 seconds to detach 1 volumes for instance.


2017-08-16 16:37:19,571.571 14176 DEBUG nova.compute.manager [req-fa377441-1d8d-461b-a916-8f4200cd9e83 153ca67f24b02da9c8ffe20d74eaa2d19316faa4530d00659be6cfc90c9a62cd 0e4da53fae3d482c853573d0e09d93ba - - -] [instance: 633de8f9-79f2-4817-95eb-d821a5f98706] terminating bdm BlockDeviceMapping(boot_index=0,connection_info='{"driver_volume_type": "iscsi", "connector": {"platform": "x86_64", "host": "hudccm21.localdomain", "do_local_attach": false, "ip": "192.168.224.1", "os_type": "linux2", "multipath": true, "initiator": "iqn.1994-05.com.redhat:a5cd5fghi9k"}, "serial": "68e9f336-29dd-4cc3-b8b4-71eccfcd7f81", "data": {"target_luns": [20, 20, 20, 20], "target_iqns": ["iqn.2008-05.com.xtremio:ckm00171600424-514f0c500d470605", "iqn.2008-05.com.xtremio:ckm00171600424-514f0c500d470601", "iqn.2008-05.com.xtremio:ckm00171600424-514f0c500d470604", "iqn.2008-05.com.xtremio:ckm00171600424-514f0c500d470600"], "device_path": "/dev/disk/by-id/dm-uuid-mpath-3514f0c5b56a00fac", "target_discovered": false, "encrypted": false, "qos_specs": null, "target_iqn": "iqn.2008-05.com.xtremio:ckm00171600424-514f0c500d470600", "target_portals": ["192.168.231.35:3260", "192.168.231.33:3260", "192.168.231.34:3260", "192.168.231.32:3260"], "target_lun": 20, "access_mode": "rw", "target_portal": "192.168.231.32:3260"}}',created_at=2017-08-15T08:09:03Z,delete_on_termination=False,deleted=False,deleted_at=None,destination_type='volume',device_name='/dev/vda',device_type='disk',disk_bus='virtio',guest_format=None,id=12930,image_id='a540bf6d-559b-4a73-9fd2-d62264f3ecc7',instance=<?>,instance_uuid=633de8f9-79f2-4817-95eb-d821a5f98706,no_device=False,snapshot_id=None,source_type='image',tag=None,updated_at=2017-08-15T08:15:19Z,volume_id='68e9f336-29dd-4cc3-b8b4-71eccfcd7f81',volume_size=20) _cleanup_volumes /usr/lib/python2.7/site-packages/nova/compute/manager.py:2260

After that, the failed paths were added back again and no more multipath -f was called, thus failed paths existed on the compute node all the time before we manually flush it. And since then, tur checker was complaining 4 paths were down for 3514f0c5b56a00fac and this kind of log filled the /var/log/messages.

Aug 16 16:37:20 hudccm21 <daemon.warning> multipathd:3514f0c5b56a00fac: sdl - tur checker reports path is down
Aug 16 16:37:24 hudccm21 <daemon.warning> multipathd:3514f0c5b56a00fac: sdr - tur checker reports path is down
Aug 16 16:37:24 hudccm21 <daemon.warning> multipathd:3514f0c5b56a00fac: sdt - tur checker reports path is down
Aug 16 16:37:25 hudccm21 <daemon.notice> multipathd:3514f0c5b56a00fac: sdl - tur checker reports path is down
Aug 16 16:37:25 hudccm21 <daemon.warning> multipathd:3514f0c5b56a00fac: sdp - tur checker reports path is down

This smells like a duplicate of https://bugzilla.redhat.com/show_bug.cgi?id=1441066

Moving this across the python-os-brick, we would like to get a test package to the customer to confirm this is resolved before closing this out as a duplicate.

Agree, there are available hotfixes for the multi-path fixes.  Moving this the cinder squad to confirm.

Hi Paul,

Thank you for your update.

I will inform my customer that we are working on a testing build and I will wait for any update from this bz.

Best Regards,
Chen

This is a duplicate of the effort to refactor the whole iSCSI attach/detach mechanism to provide a more robust solution, because it's the basic case where the initiator does an automatic scan and re-adds LUNs that had just been removed but have not yet been unmapped.

The complete fix requires a new os-brick and cinder packages, which will be going through QA soon, and an iscsi-initiator-utils package version 6.2.0.874-2 or higher to include the disabling of automatic scans on the iSCSI initiator.

*** This bug has been marked as a duplicate of bug 1441066 ***

Hi Gorka,

Sorry for reopening the bug.

I noticed python-os-brick 1.6.1.6 has released and you mentioned that we need to have a newer iscsi-initiator-utils as well. Is there any other packages (for example, any cinder packages) which need to be updated as well ?

Best Regards,
Chen

Hi Chen,

Yes and you will find all the details in the 10z5 errata from the duplicate BZs:

https://access.redhat.com/errata/RHBA-2017:2825

Thanks,
Paul