os-brick 2.5.0 failed on VMAX: 'os_brick.initiator.connectors.fibre_channel._wait_for_device_discovery'

[liu tracy]

os-brick 2.5.0 failed on VMAX: 'os_brick.initiator.connectors.fibre_channel._wait_for_device_discovery' with the following errors.

May 18 02:49:37.503322 cdh2h8 nova-compute[16909]: DEBUG os_brick.initiator.linuxfc [None req-31195476-0112-4d2b-a576-0dd065c584ee tempest-TestVolumeSwap-1490199447 tempest-TestVolumeSwap-1490199447] Could not get HBA channel and SCSI target ID, path: /sys/class/fc_transport/target3:*, reason: Unexpected error while running command.
May 18 02:49:37.503530 cdh2h8 nova-compute[16909]: Command: grep -Gil "50000973a803045b\|50000973a803041b" /sys/class/fc_transport/target3:*/port_name
May 18 02:49:37.503743 cdh2h8 nova-compute[16909]: Exit code: 2
May 18 02:49:37.505540 cdh2h8 nova-compute[16909]: Stdout: u''
May 18 02:49:37.505767 cdh2h8 nova-compute[16909]: Stderr: u'grep: /sys/class/fc_transport/target3:*/port_name: No such file or directory\n' {{(pid=16909) _get_hba_channel_scsi_target /usr/local/lib/python2.7/dist-packages/os_brick/initiator/linuxfc.py:76}}
May 18 02:49:37.505999 cdh2h8 nova-compute[16909]: DEBUG oslo_concurrency.processutils [None req-31195476-0112-4d2b-a576-0dd065c584ee tempest-TestVolumeSwap-1490199447 tempest-TestVolumeSwap-1490199447] Running cmd (subprocess): grep -Gil "50000973a803045b\|50000973a803041b" /sys/class/fc_transport/target4:*/port_name {{(pid=16909) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372}}
May 18 02:49:37.513265 cdh2h8 nova-compute[16909]: DEBUG oslo_concurrency.processutils [None req-31195476-0112-4d2b-a576-0dd065c584ee tempest-TestVolumeSwap-1490199447 tempest-TestVolumeSwap-1490199447] CMD "grep -Gil "50000973a803045b\|50000973a803041b" /sys/class/fc_transport/target4:*/port_name" returned: 0 in 0.009s {{(pid=16909) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409}}
May 18 02:49:37.514593 cdh2h8 nova-compute[16909]: ERROR oslo.service.loopingcall [None req-31195476-0112-4d2b-a576-0dd065c584ee tempest-TestVolumeSwap-1490199447 tempest-TestVolumeSwap-1490199447] Fixed interval looping call 'os_brick.initiator.connectors.fibre_channel._wait_for_device_discovery' failed: TypeError: 'NoneType' object is not iterable
May 18 02:49:37.514778 cdh2h8 nova-compute[16909]: ERROR oslo.service.loopingcall Traceback (most recent call last):
May 18 02:49:37.514951 cdh2h8 nova-compute[16909]: ERROR oslo.service.loopingcall File "/usr/local/lib/python2.7/dist-packages/oslo_service/loopingcall.py", line 193, in _run_loop
May 18 02:49:37.515125 cdh2h8 nova-compute[16909]: ERROR oslo.service.loopingcall result = func(*self.args, **self.kw)
May 18 02:49:37.515292 cdh2h8 nova-compute[16909]: ERROR oslo.service.loopingcall File "/usr/local/lib/python2.7/dist-packages/os_brick/initiator/connectors/fibre_channel.py", line 160, in _wait_for_device_discovery
May 18 02:49:37.515464 cdh2h8 nova-compute[16909]: ERROR oslo.service.loopingcall self._linuxfc.rescan_hosts(hbas, connection_properties)
May 18 02:49:37.515629 cdh2h8 nova-compute[16909]: ERROR oslo.service.loopingcall File "/usr/local/lib/python2.7/dist-packages/os_brick/initiator/linuxfc.py", line 112, in rescan_hosts
May 18 02:49:37.515794 cdh2h8 nova-compute[16909]: ERROR oslo.service.loopingcall for hba_channel, target_id in cts:
May 18 02:49:37.515958 cdh2h8 nova-compute[16909]: ERROR oslo.service.loopingcall TypeError: 'NoneType' object is not iterable
May 18 02:49:37.516139 cdh2h8 nova-compute[16909]: ERROR oslo.service.loopingcall
May 18 02:49:37.516358 cdh2h8 nova-compute[16909]: DEBUG oslo_concurrency.lockutils [None req-31195476-0112-4d2b-a576-0dd065c584ee tempest-TestVolumeSwap-1490199447 tempest-TestVolumeSwap-1490199447] Lock "connect_volume" released by "os_brick.initiator.connectors.fibre_channel.connect_volume" :: held 1.438s {{(pid=16909) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:285}}
May 18 02:49:37.516541 cdh2h8 nova-compute[16909]: DEBUG os_brick.initiator.connectors.fibre_channel [None req-31195476-0112-4d2b-a576-0dd065c584ee tempest-TestVolumeSwap-1490199447 tempest-TestVolumeSwap-1490199447] <== connect_volume: exception (1438ms) TypeError("'NoneType' object is not iterable",) {{(pid=16909) trace_logging_wrapper /usr/local/lib/python2.7/dist-packages/os_brick/utils.py:156}}
May 18 02:49:37.517018 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [None req-31195476-0112-4d2b-a576-0dd065c584ee tempest-TestVolumeSwap-1490199447 tempest-TestVolumeSwap-1490199447] [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] Driver failed to attach volume c1d1bac6-d4a5-46b7-9343-5a04d3c8592a at /dev/vdb: TypeError: 'NoneType' object is not iterable
May 18 02:49:37.517201 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] Traceback (most recent call last):
May 18 02:49:37.517384 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] File "/opt/stack/new/nova/nova/virt/block_device.py", line 554, in _volume_attach
May 18 02:49:37.517563 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] device_type=self['device_type'], encryption=encryption)
May 18 02:49:37.517730 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 1390, in attach_volume
May 18 02:49:37.517917 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] encryption=encryption)
May 18 02:49:37.518103 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 1188, in _connect_volume
May 18 02:49:37.518273 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] vol_driver.connect_volume(connection_info, instance)
May 18 02:49:37.518440 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] File "/opt/stack/new/nova/nova/virt/libvirt/volume/fibrechannel.py", line 54, in connect_volume
May 18 02:49:37.518605 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] device_info = self.connector.connect_volume(connection_info['data'])
May 18 02:49:37.518771 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] File "/usr/local/lib/python2.7/dist-packages/os_brick/utils.py", line 150, in trace_logging_wrapper
May 18 02:49:37.518943 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] result = f(*args, **kwargs)
May 18 02:49:37.519125 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] File "/usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py", line 274, in inner
May 18 02:49:37.519329 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] return f(*args, **kwargs)
May 18 02:49:37.519583 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] File "/usr/local/lib/python2.7/dist-packages/os_brick/initiator/connectors/fibre_channel.py", line 168, in connect_volume
May 18 02:49:37.519750 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] timer.start(interval=2).wait()
May 18 02:49:37.519934 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] File "/usr/local/lib/python2.7/dist-packages/eventlet/event.py", line 121, in wait
May 18 02:49:37.520134 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] return hubs.get_hub().switch()
May 18 02:49:37.520333 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 294, in switch
May 18 02:49:37.520503 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] return self.greenlet.switch()
May 18 02:49:37.520668 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] File "/usr/local/lib/python2.7/dist-packages/oslo_service/loopingcall.py", line 193, in _run_loop
May 18 02:49:37.520837 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] result = func(*self.args, **self.kw)
May 18 02:49:37.521001 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] File "/usr/local/lib/python2.7/dist-packages/os_brick/initiator/connectors/fibre_channel.py", line 160, in _wait_for_device_discovery
May 18 02:49:37.521614 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] self._linuxfc.rescan_hosts(hbas, connection_properties)
May 18 02:49:37.521769 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] File "/usr/local/lib/python2.7/dist-packages/os_brick/initiator/linuxfc.py", line 112, in rescan_hosts
May 18 02:49:37.521917 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] for hba_channel, target_id in cts:
May 18 02:49:37.522064 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10] TypeError: 'NoneType' object is not iterable
May 18 02:49:37.522225 cdh2h8 nova-compute[16909]: ERROR nova.virt.block_device [instance: 26aba8b8-317e-4aa7-8fec-67abdd227d10]
May 18 02:49:37.522373 cdh2h8 nova-compute[16909]: DEBUG cinderclient.v3

os-brick 2.4.0 succeeded on VMAX "os_brick.initiator.connectors.fibre_channel._wait_for_device_discovery"

logs of os-brick 2.5.0 and 2.4.0 can be found in the following links:

http://publiclogs.emc.com/552243/17/EMC_VMAX_FC/321/logs/pip2-freeze.txt.gz (os-brick 2.5.0)
http://publiclogs.emc.com/554166/8/EMC_VMAX_FC/320/logs/pip2-freeze.txt.gz (os-brick 2.4.0)

[Sam Wan (sam-wan)]

The root cause is that os-brick tries to scan an offline path.
If there's any path failure, the cts from get_cts = self._get_hba_channel_scsi_target will be None
------
({'host_device': u'host1', 'device_path': u'/sys/devices/pci0000:00/0000:00:02.0/0000:04:00.0/host1/fc_host/host1', 'port_name': u'2100000e1ed0498a', 'node_name': u'2000000e1ed0498a'}, None), <--- Note the cts is None if path fails.
({'host_device': u'host3', 'device_path': u'/sys/devices/pci0000:00/0000:00:02.0/0000:04:00.1/host3/fc_host/host3', 'port_name': u'2100000e1ed0498b', 'node_name': u'2000000e1ed0498b'}, [[u'0', u'0']])
------

and this causes TypeError in following code(os_brick/initiator/linuxfc.py):
------
        for hba, cts in process:
            if cts:
                for hba_channel, target_id in cts:
------
We should exclude offline path from rescaning.

[Sam Wan (sam-wan)]

upload a fix: https://review.openstack.org/#/c/569767/

[OpenStack Infra (hudson-openstack)]

Change abandoned by Sean McGinnis (<email address hidden>) on branch: master
Review: https://review.openstack.org/569767
Reason: No longer needed with the merge of the patch mentioned by Erlon. If there are additional changes needed, feel free to restore this patch and update it. Thanks!

[Sam Wan (sam-wan)]

https://review.openstack.org/#/c/571332/