Ask Your Question

Revision history [back]

click to hide/show revision 1
initial version

"nova start" fails to find cinder volume, yet volume is attached to node

Upgraded from liberty to newton. Trying to start vm back up on upgraded compute node. The vm was shutdown, then the update was performed, now I can't start that vm. I can create a new vm, cinder backed, and it creates the volume on the dell san , and attaches to host, and starts fine. However, the existing VM keeps failing to start.

The device in the libvirt.xml shows the disk dev as :

source dev="/dev/disk/by-id/dm-uuid-mpath-36000d3100314f600000000000000018a"/

and multipath -l shows the device as well

mpathcd (36000d3100314f600000000000000018a) dm-2 COMPELNT,Compellent Vol
size=60G features='1 queue_if_no_path' hwhandler='0' wp=rw -+- policy='service-time 0' prio=0 status=active |- 1:0:0:1 sdb 8:16 active undef running |- 1:0:3:1 sdd 8:48 active undef running |- 8:0:0:1 sdc 8:32 active undef running - 8:0:3:1 sde 8:64 active undef running

from the nova-compute log, it looks like its trying to locate the volume at lun5, yet the volume isn't attached as lun5

If I look at the devices that the multipathd output shows them as (sdb-sdd) [root@div18oscomp2 by-path]# ls -l | grep sd[b-e] lrwxrwxrwx. 1 root root 9 Apr 10 06:13 pci-0000:04:00.0-fc-0x5000d3100314f624-lun-1 -> ../../sdd lrwxrwxrwx. 1 root root 9 Apr 10 06:13 pci-0000:04:00.0-fc-0x5000d3100314f626-lun-1 -> ../../sdb lrwxrwxrwx. 1 root root 9 Apr 10 06:13 pci-0000:04:00.1-fc-0x5000d3100314f623-lun-1 -> ../../sde lrwxrwxrwx. 1 root root 9 Apr 10 06:13 pci-0000:04:00.1-fc-0x5000d3100314f625-lun-1 -> ../../sdc

Yet, in the below log, its looking for a different device path Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f624-lun-5

Why is nova looking for lun5, when the volume is on lun-1???? Where does it get lun5 from??

Any help would be appreciated

nova-compute log shows: 2017-04-10 15:08:51.325 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] CALL msg_id: 7a593c6f571645a79159d376df77d425 exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:51.343 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 7a593c6f571645a79159d376df77d425 __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:51.800 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received message with unique_id: 8ad49bc12bfd4316a1bfe83e00de9c98 __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:196 2017-04-10 15:08:51.812 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: ccea24299fac4ba98ac4c6d28654ed2e exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:51.827 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: ccea24299fac4ba98ac4c6d28654ed2e __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:51.829 18896 DEBUG nova.objects.instance [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lazy-loading 'flavor' on Instance uuid f248c4bb-95f7-489e-9442-2d5f7588c2c9 obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:1013 2017-04-10 15:08:51.831 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: 2206f6bd1d054150af801dc9e62a978c exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:51.884 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 2206f6bd1d054150af801dc9e62a978c __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:51.888 18896 DEBUG nova.objects.instance [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lazy-loading 'info_cache' on Instance uuid f248c4bb-95f7-489e-9442-2d5f7588c2c9 obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:1013 2017-04-10 15:08:51.890 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: 6a937a4750284e939ed9b8ed7df7049c exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:51.949 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 6a937a4750284e939ed9b8ed7df7049c __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:51.955 18896 DEBUG oslo_concurrency.lockutils [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Acquired semaphore "refresh_cache-f248c4bb-95f7-489e-9442-2d5f7588c2c9" lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:212 2017-04-10 15:08:51.956 18896 DEBUG nova.network.neutronv2.api [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] [instance: f248c4bb-95f7-489e-9442-2d5f7588c2c9] _get_instance_nw_info() _get_instance_nw_info /usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py:1276 2017-04-10 15:08:51.957 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: 49c8a97b42e648f7878c0cf61f43c72e exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:51.973 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 49c8a97b42e648f7878c0cf61f43c72e __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296

2017-04-10 15:08:52.059 18896 DEBUG neutronclient.v2_0.client [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] GET call to neutron for http://div18osvirtha.mydomain.com:9696/v2.0/ports.json?tenant_id=b713ca31297341ad934ad5a19f2ab467&device_id=f248c4bb-95f7-489e-9442-2d5f7588c2c9 used request id req-17ef0312-3bb3-4ee0-8dc6-f66a7f526c45 _append_request_id /usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py:127 2017-04-10 15:08:52.098 18896 DEBUG neutronclient.v2_0.client [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] GET call to neutron for http://div18osvirtha.mydomain.com:9696/v2.0/networks.json?tenant_id=b713ca31297341ad934ad5a19f2ab467&shared=False used request id req-04db3817-1ae8-4b64-b51f-8a0ff34f0d9b _append_request_id /usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py:127 2017-04-10 15:08:52.258 18896 DEBUG neutronclient.v2_0.client [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] GET call to neutron for http://div18osvirtha.mydomain.com:9696/v2.0/networks.json?shared=True used request id req-fb9e5d82-ec07-4550-9efd-b4973f191489 _append_request_id /usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py:127 2017-04-10 15:08:52.259 18896 DEBUG nova.network.neutronv2.api [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] [instance: f248c4bb-95f7-489e-9442-2d5f7588c2c9] Instance cache missing network info. _get_preexisting_port_ids /usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py:2133 2017-04-10 15:08:52.260 18896 DEBUG nova.network.base_api [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] [instance: f248c4bb-95f7-489e-9442-2d5f7588c2c9] Updating instance_info_cache with network_info: [] update_instance_cache_with_nw_info /usr/lib/python2.7/site-packages/nova/network/base_api.py:43 2017-04-10 15:08:52.262 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: f5f64abc44e244439623718c6ef5c7a1 exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:52.285 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: f5f64abc44e244439623718c6ef5c7a1 __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:52.286 18896 DEBUG oslo_concurrency.lockutils [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Releasing semaphore "refresh_cache-f248c4bb-95f7-489e-9442-2d5f7588c2c9" lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:225 2017-04-10 15:08:52.289 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: 49945cde0d7f4e34aa02006eb098795f exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:52.307 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 49945cde0d7f4e34aa02006eb098795f __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:52.315 18896 INFO nova.virt.libvirt.driver [-] [instance: f248c4bb-95f7-489e-9442-2d5f7588c2c9] During wait destroy, instance disappeared. 2017-04-10 15:08:52.622 18896 WARNING nova.virt.osinfo [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Cannot find OS information - Reason: (No configuration information found for operating system Empty) 2017-04-10 15:08:52.623 18896 DEBUG nova.virt.libvirt.driver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] [instance: f248c4bb-95f7-489e-9442-2d5f7588c2c9] Start _get_guest_xml network_info=[] disk_info={'disk_bus': 'virtio', 'cdrom_bus': 'ide', 'mapping': {u'/dev/vda': {'bus': u'virtio', 'boot_index': '1', 'type': u'disk', 'dev': u'vda'}, 'root': {'bus': u'virtio', 'boot_index': '1', 'type': u'disk', 'dev': u'vda'}}} image_meta=ImageMeta(checksum=,container_format=,created_at=,direct_url=,disk_format=,id=,min_disk=60,min_ram=2048,name=,owner=,properties=ImageMetaProps,protected=,size=,status=,tags=,updated_at=,virtual_size=,visibility=) rescue=None block_device_info={'swap': None, 'root_device_name': u'/dev/vda', 'ephemerals': [], 'block_device_mapping': [{'guest_format': None, 'boot_index': 0, 'mount_device': u'/dev/vda', 'connection_info': {u'driver_volume_type': u'fibre_channel', u'connector': {u'wwpns': [u'2100001b3287fa25', u'2101001b32a7fa25'], u'wwnns': [u'2000001b3287fa25', u'2001001b32a7fa25'], u'ip': u'129.162.180.232', u'initiator': u'iqn.1994-05.com.redhat:6eef2c496a17', u'platform': u'x86_64', u'host': u'div18oscomp1', u'do_local_attach': False, u'os_type': u'linux2', u'multipath': True}, u'serial': u'ede15f11-998d-4c58-9872-a5ca78507235', u'data': {u'initiator_target_map': {u'2100001B3287FA25': [u'5000D3100314F626', u'5000D3100314F624'], u'2101001B32A7FA25': [u'5000D3100314F623', u'5000D3100314F625']}, u'target_discovered': True, u'encrypted': False, u'qos_specs': None, u'discard': True, u'target_lun': 5, u'access_mode': u'rw', u'target_wwn': [u'5000D3100314F626', u'5000D3100314F624', u'5000D3100314F623', u'5000D3100314F625'], u'multipath_id': u'36000d3100314f600000000000000018a'}}, 'disk_bus': u'virtio', 'device_type': u'disk', 'delete_on_termination': False}]} _get_guest_xml /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:4655 2017-04-10 15:08:52.623 18896 DEBUG nova.objects.instance [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lazy-loading 'pci_devices' on Instance uuid f248c4bb-95f7-489e-9442-2d5f7588c2c9 obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:1013 2017-04-10 15:08:52.624 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: db748d8b2b384f199762ee135adecd48 exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:52.637 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: db748d8b2b384f199762ee135adecd48 __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:52.637 18896 DEBUG nova.objects.instance [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lazy-loading 'numa_topology' on Instance uuid f248c4bb-95f7-489e-9442-2d5f7588c2c9 obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:1013 2017-04-10 15:08:52.638 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: 0b95965a392c47929d1aa1f948627056 exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:52.648 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 0b95965a392c47929d1aa1f948627056 __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:52.668 18896 DEBUG nova.virt.libvirt.driver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CPU mode 'custom' model 'Penryn' was chosen _get_guest_cpu_model_config /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:3369 2017-04-10 15:08:52.669 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Getting desirable topologies for flavor Flavor(created_at=2016-04-09T12:56:47Z,deleted=False,deleted_at=None,disabled=False,ephemeral_gb=0,extra_specs={},flavorid='d7cafe18-990a-44c4-830a-dff7fc43e057',id=87,is_public=True,memory_mb=4096,name='CPU 2 - RAM 4GB',projects=,root_gb=60,rxtx_factor=1.0,swap=0,updated_at=None,vcpu_weight=0,vcpus=2) and image_meta ImageMeta(checksum=,container_format=,created_at=,direct_url=,disk_format=,id=,min_disk=60,min_ram=2048,name=,owner=,properties=ImageMetaProps,protected=,size=,status=,tags=,updated_at=,virtual_size=,visibility=), allow threads: True _get_desirable_cpu_topologies /usr/lib/python2.7/site-packages/nova/virt/hardware.py:568 2017-04-10 15:08:52.671 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Flavor limits 65536:65536:65536 _get_cpu_topology_constraints /usr/lib/python2.7/site-packages/nova/virt/hardware.py:312 2017-04-10 15:08:52.672 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Image limits 65536:65536:65536 _get_cpu_topology_constraints /usr/lib/python2.7/site-packages/nova/virt/hardware.py:323 2017-04-10 15:08:52.672 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Flavor pref -1:-1:-1 _get_cpu_topology_constraints /usr/lib/python2.7/site-packages/nova/virt/hardware.py:346 2017-04-10 15:08:52.673 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Image pref -1:-1:-1 _get_cpu_topology_constraints /usr/lib/python2.7/site-packages/nova/virt/hardware.py:365 2017-04-10 15:08:52.674 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Chosen -1:-1:-1 limits 65536:65536:65536 _get_cpu_topology_constraints /usr/lib/python2.7/site-packages/nova/virt/hardware.py:394 2017-04-10 15:08:52.674 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Topology preferred VirtCPUTopology(cores=-1,sockets=-1,threads=-1), maximum VirtCPUTopology(cores=65536,sockets=65536,threads=65536) _get_desirable_cpu_topologies /usr/lib/python2.7/site-packages/nova/virt/hardware.py:572 2017-04-10 15:08:52.675 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Build topologies for 2 vcpu(s) 2:2:2 _get_possible_cpu_topologies /usr/lib/python2.7/site-packages/nova/virt/hardware.py:433 2017-04-10 15:08:52.676 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Got 3 possible topologies _get_possible_cpu_topologies /usr/lib/python2.7/site-packages/nova/virt/hardware.py:460 2017-04-10 15:08:52.676 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Possible topologies [VirtCPUTopology(cores=1,sockets=2,threads=1), VirtCPUTopology(cores=2,sockets=1,threads=1), VirtCPUTopology(cores=1,sockets=1,threads=2)] _get_desirable_cpu_topologies /usr/lib/python2.7/site-packages/nova/virt/hardware.py:577 2017-04-10 15:08:52.677 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Sorted desired topologies [VirtCPUTopology(cores=1,sockets=2,threads=1), VirtCPUTopology(cores=2,sockets=1,threads=1), VirtCPUTopology(cores=1,sockets=1,threads=2)] _get_desirable_cpu_topologies /usr/lib/python2.7/site-packages/nova/virt/hardware.py:602 2017-04-10 15:08:52.678 18896 DEBUG nova.objects.instance [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lazy-loading 'vcpu_model' on Instance uuid f248c4bb-95f7-489e-9442-2d5f7588c2c9 obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:1013 2017-04-10 15:08:52.680 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: 3a2d9294df0646cb9700850137304df1 exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:52.692 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 3a2d9294df0646cb9700850137304df1 __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:52.694 18896 DEBUG nova.virt.libvirt.volume.fibrechannel [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Calling os-brick to attach FC Volume connect_volume /usr/lib/python2.7/site-packages/nova/virt/libvirt/volume/fibrechannel.py:52 2017-04-10 15:08:52.695 18896 DEBUG os_brick.initiator.connectors.fibre_channel [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] ==> connect_volume: call {'args': (<os_brick.initiator.connectors.fibre_channel.fibrechannelconnector object="" at="" 0x6185110="">, {u'initiator_target_map': {u'2100001B3287FA25': [u'5000D3100314F626', u'5000D3100314F624'], u'2101001B32A7FA25': [u'5000D3100314F623', u'5000D3100314F625']}, u'target_discovered': True, u'encrypted': False, u'qos_specs': None, u'discard': True, u'target_lun': 5, u'access_mode': u'rw', u'target_wwn': [u'5000D3100314F626', u'5000D3100314F624', u'5000D3100314F623', u'5000D3100314F625'], u'multipath_id': u'36000d3100314f600000000000000018a'}), 'kwargs': {}} trace_logging_wrapper /usr/lib/python2.7/site-packages/os_brick/utils.py:141 2017-04-10 15:08:52.695 18896 DEBUG oslo_concurrency.lockutils [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lock "connect_volume" acquired by "os_brick.initiator.connectors.fibre_channel.connect_volume" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:270 2017-04-10 15:08:52.696 18896 DEBUG os_brick.initiator.connectors.fibre_channel [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] execute = <function execute="" at="" 0x57dade8=""> connect_volume /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:127 2017-04-10 15:08:52.697 18896 INFO oslo.privsep.daemon [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Running privsep helper: ['sudo', 'nova-rootwrap', '/etc/nova/rootwrap.conf', 'privsep-helper', '--config-file', '/usr/share/nova/nova-dist.conf', '--config-file', '/etc/nova/nova.conf', '--privsep_context', 'os_brick.privileged.default', '--privsep_sock_path', '/tmp/tmpB58ZtD/privsep.sock'] 2017-04-10 15:08:53.360 18896 INFO oslo.privsep.daemon [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Spawned new privsep daemon via rootwrap 2017-04-10 15:08:53.361 18896 DEBUG oslo.privsep.daemon [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Accepted privsep connection to /tmp/tmpB58ZtD/privsep.sock __init__ /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:313 2017-04-10 15:08:53.363 18896 INFO oslo.privsep.daemon [-] privsep daemon starting 2017-04-10 15:08:53.364 18896 INFO oslo.privsep.daemon [-] privsep process running with uid/gid: 0/0 2017-04-10 15:08:53.365 18896 INFO oslo.privsep.daemon [-] privsep process running with capabilities (eff/prm/inh): CAP_SYS_ADMIN/CAP_SYS_ADMIN/none 2017-04-10 15:08:53.366 18896 INFO oslo.privsep.daemon [-] privsep daemon running as pid 20156 2017-04-10 15:08:53.367 18896 DEBUG oslo.privsep.daemon [-] privsep: request[102964752]: (1,) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.368 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[102964752]: (2,) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.369 18896 DEBUG oslo.privsep.daemon [-] privsep: request[102964752]: (3, 'os_brick.privileged.rootwrap.execute_root', ('systool', '-c', 'fc_host', '-v'), {}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.449 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): systool -c fc_host -v out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.776 18896 DEBUG oslo.privsep.daemon [-] CMD "systool -c fc_host -v" returned: 0 in 0.327s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.777 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[102964752]: (4, ('Class = "fc_host"\n\n Class Device = "host1"\n Class Device path = "/sys/devices/pci0000:00/0000:00:02.0/0000:04:00.0/host1/fc_host/host1"\n dev_loss_tmo = "45"\n fabric_name = "0x1000000533f7eb2b"\n issue_lip = <store method="" only="">\n max_npiv_vports = "127"\n node_name = "0x2000001b3287a726"\n npiv_vports_inuse = "0"\n port_id = "0x020500"\n port_name = "0x2100001b3287a726"\n port_state = "Online"\n port_type = "NPort (fabric via point-to-point)"\n speed = "4 Gbit"\n supported_classes = "Class 3"\n supported_speeds = "1 Gbit, 2 Gbit, 4 Gbit"\n symbolic_name = "QLE2462 FW:v8.03.00 DVR:v8.07.00.33.07.3-k1"\n system_hostname = ""\n tgtid_bind_type = "wwpn (World Wide Port Name)"\n uevent = \n vport_create = <store method="" only="">\n vport_delete = <store method="" only="">\n\n Device = "host1"\n Device path = "/sys/devices/pci0000:00/0000:00:02.0/0000:04:00.0/host1"\n fw_dump = \n nvram = "ISP \x01"\n optrom_ctl = <store method="" only="">\n optrom = \n reset = <store method="" only="">\n sfp = "\x02\x04\x07"\n uevent = "DEVTYPE=scsi_host"\n vpd = "\x82."\n\n\n Class Device = "host8"\n Class Device path = "/sys/devices/pci0000:00/0000:00:02.0/0000:04:00.1/host8/fc_host/host8"\n dev_loss_tmo = "45"\n fabric_name = "0x1000000533f7de77"\n issue_lip = <store method="" only="">\n max_npiv_vports = "127"\n node_name = "0x2001001b32a7a726"\n npiv_vports_inuse = "0"\n port_id = "0x030500"\n port_name = "0x2101001b32a7a726"\n port_state = "Online"\n port_type = "NPort (fabric via point-to-point)"\n speed = "4 Gbit"\n supported_classes = "Class 3"\n supported_speeds = "1 Gbit, 2 Gbit, 4 Gbit"\n symbolic_name = "QLE2462 FW:v8.03.00 DVR:v8.07.00.33.07.3-k1"\n system_hostname = ""\n tgtid_bind_type = "wwpn (World Wide Port Name)"\n uevent = \n vport_create = <store method="" only="">\n vport_delete = <store method="" only="">\n\n Device = "host8"\n Device path = "/sys/devices/pci0000:00/0000:00:02.0/0000:04:00.1/host8"\n fw_dump = \n nvram = "ISP \x01"\n optrom_ctl = <store method="" only="">\n optrom = \n reset = <store method="" only="">\n sfp = "\x02\x04\x07"\n uevent = "DEVTYPE=scsi_host"\n vpd = "\x82."\n\n\n', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.779 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:53.779 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:53.780 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:53.781 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:53.781 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:53.782 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:53.782 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:53.783 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:53.784 18896 WARNING os_brick.initiator.connectors.fibre_channel [-] Fibre Channel volume device not yet found. Will rescan & retry. Try number: 0. 2017-04-10 15:08:53.784 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:08:53.806 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:08:53.807 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:08:53.807 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host1 (wwnn: 2000001b3287a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:08:53.809 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host1/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.809 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host1/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.822 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host1/scan" returned: 0 in 0.013s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.823 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.824 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:08:53.843 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:08:53.845 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:08:53.845 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host8 (wwnn: 2001001b32a7a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:08:53.847 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host8/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.847 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host8/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.860 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host8/scan" returned: 0 in 0.013s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.860 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:55.781 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:55.782 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:55.783 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:55.783 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:55.784 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:55.784 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:55.785 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:55.785 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:55.786 18896 WARNING os_brick.initiator.connectors.fibre_channel [-] Fibre Channel volume device not yet found. Will rescan & retry. Try number: 1. 2017-04-10 15:08:55.786 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:08:55.808 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:08:55.810 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:08:55.810 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host1 (wwnn: 2000001b3287a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:08:55.812 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host1/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:55.812 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host1/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:55.829 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host1/scan" returned: 0 in 0.016s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:55.830 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:55.830 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:08:55.850 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:08:55.851 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:08:55.852 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host8 (wwnn: 2001001b32a7a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:08:55.854 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host8/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:55.854 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host8/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:55.862 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host8/scan" returned: 0 in 0.008s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:55.862 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:57.784 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:57.784 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:57.785 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:57.785 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:57.786 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:57.786 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:57.787 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:57.787 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:57.788 18896 WARNING os_brick.initiator.connectors.fibre_channel [-] Fibre Channel volume device not yet found. Will rescan & retry. Try number: 2. 2017-04-10 15:08:57.788 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:08:57.810 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:08:57.812 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:08:57.813 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host1 (wwnn: 2000001b3287a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:08:57.814 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host1/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:57.815 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host1/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:57.824 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host1/scan" returned: 0 in 0.008s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:57.824 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:57.825 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:08:57.844 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:08:57.846 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:08:57.847 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host8 (wwnn: 2001001b32a7a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:08:57.848 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host8/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:57.849 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host8/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:57.860 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host8/scan" returned: 0 in 0.011s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:57.861 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:59.783 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:59.784 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:59.784 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:59.785 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:59.785 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:59.786 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:59.786 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:59.787 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:59.787 18896 WARNING os_brick.initiator.connectors.fibre_channel [-] Fibre Channel volume device not yet found. Will rescan & retry. Try number: 3. 2017-04-10 15:08:59.788 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:08:59.811 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:08:59.812 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:08:59.813 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host1 (wwnn: 2000001b3287a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:08:59.815 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host1/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:59.815 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host1/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:59.828 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host1/scan" returned: 0 in 0.012s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:59.828 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:59.829 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:08:59.849 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:08:59.850 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:08:59.851 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host8 (wwnn: 2001001b32a7a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:08:59.853 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host8/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:59.853 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host8/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:59.861 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host8/scan" returned: 0 in 0.008s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:59.862 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:01.328 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] CALL msg_id: a0fda52d5deb4af3b0cb814bca7d5db5 exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:09:01.355 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: a0fda52d5deb4af3b0cb814bca7d5db5 __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:09:01.783 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:01.784 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:01.784 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:01.785 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:01.785 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:01.786 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:01.786 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:01.787 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:01.787 18896 WARNING os_brick.initiator.connectors.fibre_channel [-] Fibre Channel volume device not yet found. Will rescan & retry. Try number: 4. 2017-04-10 15:09:01.788 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:09:01.810 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:09:01.812 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:09:01.812 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host1 (wwnn: 2000001b3287a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:09:01.814 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host1/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:01.814 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host1/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:01.823 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host1/scan" returned: 0 in 0.008s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:01.823 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:01.824 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:09:01.845 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:09:01.846 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:09:01.847 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host8 (wwnn: 2001001b32a7a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:09:01.848 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host8/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:01.849 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host8/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:01.856 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host8/scan" returned: 0 in 0.008s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:01.857 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:03.789 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:03.790 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:03.791 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:03.791 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:03.792 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:03.792 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:03.793 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:03.793 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:03.794 18896 ERROR os_brick.initiator.connectors.fibre_channel [-] Fibre Channel volume device not found. 2017-04-10 15:09:03.794 18896 ERROR oslo.service.loopingcall [-] Fixed interval looping call 'os_brick.initiator.connectors.fibre_channel._wait_for_device_discovery' failed 2017-04-10 15:09:03.794 18896 ERROR oslo.service.loopingcall Traceback (most recent call last): 2017-04-10 15:09:03.794 18896 ERROR oslo.service.loopingcall File "/usr/lib/python2.7/site-packages/oslo_service/loopingcall.py", line 136, in _run_loop 2017-04-10 15:09:03.794 18896 ERROR oslo.service.loopingcall result = func(self.args, *self.kw) 2017-04-10 15:09:03.794 18896 ERROR oslo.service.loopingcall File "/usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py", line 157, in _wait_for_device_discovery 2017-04-10 15:09:03.794 18896 ERROR oslo.service.loopingcall raise exception.NoFibreChannelVolumeDeviceFound() 2017-04-10 15:09:03.794 18896 ERROR oslo.service.loopingcall NoFibreChannelVolumeDeviceFound: Unable to find a Fibre Channel volume device. 2017-04-10 15:09:03.794 18896 ERROR oslo.service.loopingcall 2017-04-10 15:09:03.797 18896 DEBUG oslo_concurrency.lockutils [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lock "connect_volume" released by "os_brick.initiator.connectors.fibre_channel.connect_volume" :: held 11.101s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:282 2017-04-10 15:09:03.797 18896 DEBUG os_brick.initiator.connectors.fibre_channel [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] <== connect_volume: exception (11102ms) NoFibreChannelVolumeDeviceFound(u'Unable to find a Fibre Channel volume device.',) trace_logging_wrapper /usr/lib/python2.7/site-packages/os_brick/utils.py:151 2017-04-10 15:09:03.802 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: 9608ea77a5d9419abfc8a8c832ce0e43 exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:09:03.828 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 9608ea77a5d9419abfc8a8c832ce0e43 __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:09:03.832 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: f183e9cc65594342b60a32e32989610f exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:09:03.872 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: f183e9cc65594342b60a32e32989610f __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:09:03.879 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: 6ad1252275f642da982383d7de6ab85b exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:09:04.021 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 6ad1252275f642da982383d7de6ab85b __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:09:04.028 18896 DEBUG oslo_concurrency.lockutils [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lock "compute_resources" acquired by "nova.compute.resource_tracker.update_usage" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:270 2017-04-10 15:09:04.034 18896 DEBUG oslo_concurrency.lockutils [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lock "compute_resources" released by "nova.compute.resource_tracker.update_usage" :: held 0.006s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:282 2017-04-10 15:09:04.035 18896 INFO nova.compute.manager [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] [instance: f248c4bb-95f7-489e-9442-2d5f7588c2c9] Successfully reverted task state from powering-on on failure for instance. 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Exception during message handling 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server Traceback (most recent call last): 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/server.py", line 133, in _process_incoming 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server res = self.dispatcher.dispatch(message) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 150, in dispatch 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server return self._do_dispatch(endpoint, method, ctxt, args) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 121, in _do_dispatch 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server result = func(ctxt, *new_args) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/exception_wrapper.py", line 75, in wrapped 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server function_name, call_dict, binary) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__ 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server self.force_reraise() 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server six.reraise(self.type_, self.value, self.tb) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/exception_wrapper.py", line 66, in wrapped 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server return f(self, context, *args, *kw) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 188, in decorated_function 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server LOG.warning(msg, e, instance=instance) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__ 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server self.force_reraise() 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server six.reraise(self.type_, self.value, self.tb) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 157, in decorated_function 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server return function(self, context, args, *kwargs) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/utils.py", line 613, in decorated_function 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server return function(self, context, args, *kwargs) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 216, in decorated_function 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server kwargs['instance'], e, sys.exc_info()) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__ 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server self.force_reraise() 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server six.reraise(self.type_, self.value, self.tb) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 204, in decorated_function 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server return function(self, context, args, *kwargs) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2475, in start_instance 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server self._power_on(context, instance) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2445, in _power_on 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server block_device_info) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 2434, in power_on 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server self._hard_reboot(context, instance, network_info, block_device_info) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 2307, in _hard_reboot 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server block_device_info=block_device_info) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 4658, in _get_guest_xml 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server context) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 4483, in _get_guest_config 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server flavor, guest.os_type) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 3523, in _get_guest_storage_config 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server self._connect_volume(connection_info, info) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 1099, in _connect_volume 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server vol_driver.connect_volume(connection_info, disk_info) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/volume/fibrechannel.py", line 53, in connect_volume 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server device_info = self.connector.connect_volume(connection_info['data']) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/os_brick/utils.py", line 145, in trace_logging_wrapper 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server result = f(args, *kwargs) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py", line 271, in inner 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server return f(args, *kwargs) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py", line 172, in connect_volume 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server timer.start(interval=2).wait() 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/eventlet/event.py", line 121, in wait 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server return hubs.get_hub().switch() 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 294, in switch 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server return self.greenlet.switch() 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_service/loopingcall.py", line 136, in _run_loop 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server result = func(self.args, *self.kw) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py", line 157, in _wait_for_device_discovery 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server raise exception.NoFibreChannelVolumeDeviceFound() 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server NoFibreChannelVolumeDeviceFound: Unable to find a Fibre Channel volume device. 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server

"nova start" fails to find cinder volume, yet volume is attached to node

Upgraded from liberty to newton. Trying to start vm back up on upgraded compute node. The vm was shutdown, then the update was performed, now I can't start that vm. I can create a new vm, cinder backed, and it creates the volume on the dell san , and attaches to host, and starts fine. However, the existing VM keeps failing to start.

The device in the libvirt.xml shows the disk dev as :

source dev="/dev/disk/by-id/dm-uuid-mpath-36000d3100314f600000000000000018a"/

and multipath -l shows the device as well

mpathcd (36000d3100314f600000000000000018a) dm-2 COMPELNT,Compellent Vol
size=60G features='1 queue_if_no_path' hwhandler='0' wp=rw -+- `-+- policy='service-time 0' prio=0 status=active |- status=active
1:0:0:1 sdb 8:16 active undef running |- 1:0:3:1 sdd 8:48 active undef running |- 8:0:0:1 sdc 8:32 active undef running
- 8:0:3:1 sde 8:64 active undef running


1:0:3:1 sdd 8:48 active undef running

from the nova-compute log, it looks like its trying to locate the volume at lun5, yet the volume isn't attached as lun5 8:0:0:1 sdc 8:32 active undef running
8:0:3:1 sde 8:64 active undef running

If I look at the devices that the multipathd output shows them as (sdb-sdd) [root@div18oscomp2 by-path]# ls -l | grep sd[b-e] sd[b-e]
lrwxrwxrwx. 1 root root 9 Apr 10 06:13 pci-0000:04:00.0-fc-0x5000d3100314f624-lun-1 -> ../../sdd lrwxrwxrwx. 1 root root 9 Apr 10 06:13 pci-0000:04:00.0-fc-0x5000d3100314f626-lun-1 -> ../../sdb lrwxrwxrwx. 1 root root 9 Apr 10 06:13 pci-0000:04:00.1-fc-0x5000d3100314f623-lun-1 -> ../../sde lrwxrwxrwx. 1 root root 9 Apr 10 06:13 pci-0000:04:00.1-fc-0x5000d3100314f625-lun-1 -> ../../sdc

Yet, in the below log, its looking for a different device path Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f624-lun-5

Why is nova looking for lun5, when the volume is on lun-1???? Where does it get lun5 from??

Any help would be appreciated

nova-compute log shows: 2017-04-10 15:08:51.325 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] CALL msg_id: 7a593c6f571645a79159d376df77d425 exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:51.343 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 7a593c6f571645a79159d376df77d425 __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:51.800 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received message with unique_id: 8ad49bc12bfd4316a1bfe83e00de9c98 __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:196 2017-04-10 15:08:51.812 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: ccea24299fac4ba98ac4c6d28654ed2e exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:51.827 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: ccea24299fac4ba98ac4c6d28654ed2e __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:51.829 18896 DEBUG nova.objects.instance [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lazy-loading 'flavor' on Instance uuid f248c4bb-95f7-489e-9442-2d5f7588c2c9 obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:1013 2017-04-10 15:08:51.831 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: 2206f6bd1d054150af801dc9e62a978c exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:51.884 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 2206f6bd1d054150af801dc9e62a978c __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:51.888 18896 DEBUG nova.objects.instance [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lazy-loading 'info_cache' on Instance uuid f248c4bb-95f7-489e-9442-2d5f7588c2c9 obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:1013 2017-04-10 15:08:51.890 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: 6a937a4750284e939ed9b8ed7df7049c exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:51.949 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 6a937a4750284e939ed9b8ed7df7049c __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:51.955 18896 DEBUG oslo_concurrency.lockutils [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Acquired semaphore "refresh_cache-f248c4bb-95f7-489e-9442-2d5f7588c2c9" lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:212 2017-04-10 15:08:51.956 18896 DEBUG nova.network.neutronv2.api [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] [instance: f248c4bb-95f7-489e-9442-2d5f7588c2c9] _get_instance_nw_info() _get_instance_nw_info /usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py:1276 2017-04-10 15:08:51.957 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: 49c8a97b42e648f7878c0cf61f43c72e exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:51.973 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 49c8a97b42e648f7878c0cf61f43c72e __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296

2017-04-10 15:08:52.059 18896 DEBUG neutronclient.v2_0.client [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] GET call to neutron for http://div18osvirtha.mydomain.com:9696/v2.0/ports.json?tenant_id=b713ca31297341ad934ad5a19f2ab467&device_id=f248c4bb-95f7-489e-9442-2d5f7588c2c9 used request id req-17ef0312-3bb3-4ee0-8dc6-f66a7f526c45 _append_request_id /usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py:127 2017-04-10 15:08:52.098 18896 DEBUG neutronclient.v2_0.client [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] GET call to neutron for http://div18osvirtha.mydomain.com:9696/v2.0/networks.json?tenant_id=b713ca31297341ad934ad5a19f2ab467&shared=False used request id req-04db3817-1ae8-4b64-b51f-8a0ff34f0d9b _append_request_id /usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py:127 2017-04-10 15:08:52.258 18896 DEBUG neutronclient.v2_0.client [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] GET call to neutron for http://div18osvirtha.mydomain.com:9696/v2.0/networks.json?shared=True used request id req-fb9e5d82-ec07-4550-9efd-b4973f191489 _append_request_id /usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py:127 2017-04-10 15:08:52.259 18896 DEBUG nova.network.neutronv2.api [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] [instance: f248c4bb-95f7-489e-9442-2d5f7588c2c9] Instance cache missing network info. _get_preexisting_port_ids /usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py:2133 2017-04-10 15:08:52.260 18896 DEBUG nova.network.base_api [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] [instance: f248c4bb-95f7-489e-9442-2d5f7588c2c9] Updating instance_info_cache with network_info: [] update_instance_cache_with_nw_info /usr/lib/python2.7/site-packages/nova/network/base_api.py:43 2017-04-10 15:08:52.262 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: f5f64abc44e244439623718c6ef5c7a1 exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:52.285 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: f5f64abc44e244439623718c6ef5c7a1 __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:52.286 18896 DEBUG oslo_concurrency.lockutils [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Releasing semaphore "refresh_cache-f248c4bb-95f7-489e-9442-2d5f7588c2c9" lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:225 2017-04-10 15:08:52.289 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: 49945cde0d7f4e34aa02006eb098795f exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:52.307 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 49945cde0d7f4e34aa02006eb098795f __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:52.315 18896 INFO nova.virt.libvirt.driver [-] [instance: f248c4bb-95f7-489e-9442-2d5f7588c2c9] During wait destroy, instance disappeared. 2017-04-10 15:08:52.622 18896 WARNING nova.virt.osinfo [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Cannot find OS information - Reason: (No configuration information found for operating system Empty) 2017-04-10 15:08:52.623 18896 DEBUG nova.virt.libvirt.driver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] [instance: f248c4bb-95f7-489e-9442-2d5f7588c2c9] Start _get_guest_xml network_info=[] disk_info={'disk_bus': 'virtio', 'cdrom_bus': 'ide', 'mapping': {u'/dev/vda': {'bus': u'virtio', 'boot_index': '1', 'type': u'disk', 'dev': u'vda'}, 'root': {'bus': u'virtio', 'boot_index': '1', 'type': u'disk', 'dev': u'vda'}}} image_meta=ImageMeta(checksum=,container_format=,created_at=,direct_url=,disk_format=,id=,min_disk=60,min_ram=2048,name=,owner=,properties=ImageMetaProps,protected=,size=,status=,tags=,updated_at=,virtual_size=,visibility=) rescue=None block_device_info={'swap': None, 'root_device_name': u'/dev/vda', 'ephemerals': [], 'block_device_mapping': [{'guest_format': None, 'boot_index': 0, 'mount_device': u'/dev/vda', 'connection_info': {u'driver_volume_type': u'fibre_channel', u'connector': {u'wwpns': [u'2100001b3287fa25', u'2101001b32a7fa25'], u'wwnns': [u'2000001b3287fa25', u'2001001b32a7fa25'], u'ip': u'129.162.180.232', u'initiator': u'iqn.1994-05.com.redhat:6eef2c496a17', u'platform': u'x86_64', u'host': u'div18oscomp1', u'do_local_attach': False, u'os_type': u'linux2', u'multipath': True}, u'serial': u'ede15f11-998d-4c58-9872-a5ca78507235', u'data': {u'initiator_target_map': {u'2100001B3287FA25': [u'5000D3100314F626', u'5000D3100314F624'], u'2101001B32A7FA25': [u'5000D3100314F623', u'5000D3100314F625']}, u'target_discovered': True, u'encrypted': False, u'qos_specs': None, u'discard': True, u'target_lun': 5, u'access_mode': u'rw', u'target_wwn': [u'5000D3100314F626', u'5000D3100314F624', u'5000D3100314F623', u'5000D3100314F625'], u'multipath_id': u'36000d3100314f600000000000000018a'}}, 'disk_bus': u'virtio', 'device_type': u'disk', 'delete_on_termination': False}]} _get_guest_xml /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:4655 2017-04-10 15:08:52.623 18896 DEBUG nova.objects.instance [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lazy-loading 'pci_devices' on Instance uuid f248c4bb-95f7-489e-9442-2d5f7588c2c9 obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:1013 2017-04-10 15:08:52.624 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: db748d8b2b384f199762ee135adecd48 exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:52.637 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: db748d8b2b384f199762ee135adecd48 __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:52.637 18896 DEBUG nova.objects.instance [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lazy-loading 'numa_topology' on Instance uuid f248c4bb-95f7-489e-9442-2d5f7588c2c9 obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:1013 2017-04-10 15:08:52.638 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: 0b95965a392c47929d1aa1f948627056 exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:52.648 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 0b95965a392c47929d1aa1f948627056 __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:52.668 18896 DEBUG nova.virt.libvirt.driver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CPU mode 'custom' model 'Penryn' was chosen _get_guest_cpu_model_config /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:3369 2017-04-10 15:08:52.669 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Getting desirable topologies for flavor Flavor(created_at=2016-04-09T12:56:47Z,deleted=False,deleted_at=None,disabled=False,ephemeral_gb=0,extra_specs={},flavorid='d7cafe18-990a-44c4-830a-dff7fc43e057',id=87,is_public=True,memory_mb=4096,name='CPU 2 - RAM 4GB',projects=,root_gb=60,rxtx_factor=1.0,swap=0,updated_at=None,vcpu_weight=0,vcpus=2) and image_meta ImageMeta(checksum=,container_format=,created_at=,direct_url=,disk_format=,id=,min_disk=60,min_ram=2048,name=,owner=,properties=ImageMetaProps,protected=,size=,status=,tags=,updated_at=,virtual_size=,visibility=), allow threads: True _get_desirable_cpu_topologies /usr/lib/python2.7/site-packages/nova/virt/hardware.py:568 2017-04-10 15:08:52.671 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Flavor limits 65536:65536:65536 _get_cpu_topology_constraints /usr/lib/python2.7/site-packages/nova/virt/hardware.py:312 2017-04-10 15:08:52.672 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Image limits 65536:65536:65536 _get_cpu_topology_constraints /usr/lib/python2.7/site-packages/nova/virt/hardware.py:323 2017-04-10 15:08:52.672 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Flavor pref -1:-1:-1 _get_cpu_topology_constraints /usr/lib/python2.7/site-packages/nova/virt/hardware.py:346 2017-04-10 15:08:52.673 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Image pref -1:-1:-1 _get_cpu_topology_constraints /usr/lib/python2.7/site-packages/nova/virt/hardware.py:365 2017-04-10 15:08:52.674 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Chosen -1:-1:-1 limits 65536:65536:65536 _get_cpu_topology_constraints /usr/lib/python2.7/site-packages/nova/virt/hardware.py:394 2017-04-10 15:08:52.674 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Topology preferred VirtCPUTopology(cores=-1,sockets=-1,threads=-1), maximum VirtCPUTopology(cores=65536,sockets=65536,threads=65536) _get_desirable_cpu_topologies /usr/lib/python2.7/site-packages/nova/virt/hardware.py:572 2017-04-10 15:08:52.675 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Build topologies for 2 vcpu(s) 2:2:2 _get_possible_cpu_topologies /usr/lib/python2.7/site-packages/nova/virt/hardware.py:433 2017-04-10 15:08:52.676 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Got 3 possible topologies _get_possible_cpu_topologies /usr/lib/python2.7/site-packages/nova/virt/hardware.py:460 2017-04-10 15:08:52.676 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Possible topologies [VirtCPUTopology(cores=1,sockets=2,threads=1), VirtCPUTopology(cores=2,sockets=1,threads=1), VirtCPUTopology(cores=1,sockets=1,threads=2)] _get_desirable_cpu_topologies /usr/lib/python2.7/site-packages/nova/virt/hardware.py:577 2017-04-10 15:08:52.677 18896 DEBUG nova.virt.hardware [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Sorted desired topologies [VirtCPUTopology(cores=1,sockets=2,threads=1), VirtCPUTopology(cores=2,sockets=1,threads=1), VirtCPUTopology(cores=1,sockets=1,threads=2)] _get_desirable_cpu_topologies /usr/lib/python2.7/site-packages/nova/virt/hardware.py:602 2017-04-10 15:08:52.678 18896 DEBUG nova.objects.instance [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lazy-loading 'vcpu_model' on Instance uuid f248c4bb-95f7-489e-9442-2d5f7588c2c9 obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:1013 2017-04-10 15:08:52.680 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: 3a2d9294df0646cb9700850137304df1 exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:08:52.692 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 3a2d9294df0646cb9700850137304df1 __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:08:52.694 18896 DEBUG nova.virt.libvirt.volume.fibrechannel [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Calling os-brick to attach FC Volume connect_volume /usr/lib/python2.7/site-packages/nova/virt/libvirt/volume/fibrechannel.py:52 2017-04-10 15:08:52.695 18896 DEBUG os_brick.initiator.connectors.fibre_channel [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] ==> connect_volume: call {'args': (<os_brick.initiator.connectors.fibre_channel.fibrechannelconnector object="" at="" 0x6185110="">, {u'initiator_target_map': {u'2100001B3287FA25': [u'5000D3100314F626', u'5000D3100314F624'], u'2101001B32A7FA25': [u'5000D3100314F623', u'5000D3100314F625']}, u'target_discovered': True, u'encrypted': False, u'qos_specs': None, u'discard': True, u'target_lun': 5, u'access_mode': u'rw', u'target_wwn': [u'5000D3100314F626', u'5000D3100314F624', u'5000D3100314F623', u'5000D3100314F625'], u'multipath_id': u'36000d3100314f600000000000000018a'}), 'kwargs': {}} trace_logging_wrapper /usr/lib/python2.7/site-packages/os_brick/utils.py:141 2017-04-10 15:08:52.695 18896 DEBUG oslo_concurrency.lockutils [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lock "connect_volume" acquired by "os_brick.initiator.connectors.fibre_channel.connect_volume" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:270 2017-04-10 15:08:52.696 18896 DEBUG os_brick.initiator.connectors.fibre_channel [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] execute = <function execute="" at="" 0x57dade8=""> connect_volume /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:127 2017-04-10 15:08:52.697 18896 INFO oslo.privsep.daemon [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Running privsep helper: ['sudo', 'nova-rootwrap', '/etc/nova/rootwrap.conf', 'privsep-helper', '--config-file', '/usr/share/nova/nova-dist.conf', '--config-file', '/etc/nova/nova.conf', '--privsep_context', 'os_brick.privileged.default', '--privsep_sock_path', '/tmp/tmpB58ZtD/privsep.sock'] 2017-04-10 15:08:53.360 18896 INFO oslo.privsep.daemon [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Spawned new privsep daemon via rootwrap 2017-04-10 15:08:53.361 18896 DEBUG oslo.privsep.daemon [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Accepted privsep connection to /tmp/tmpB58ZtD/privsep.sock __init__ /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:313 2017-04-10 15:08:53.363 18896 INFO oslo.privsep.daemon [-] privsep daemon starting 2017-04-10 15:08:53.364 18896 INFO oslo.privsep.daemon [-] privsep process running with uid/gid: 0/0 2017-04-10 15:08:53.365 18896 INFO oslo.privsep.daemon [-] privsep process running with capabilities (eff/prm/inh): CAP_SYS_ADMIN/CAP_SYS_ADMIN/none 2017-04-10 15:08:53.366 18896 INFO oslo.privsep.daemon [-] privsep daemon running as pid 20156 2017-04-10 15:08:53.367 18896 DEBUG oslo.privsep.daemon [-] privsep: request[102964752]: (1,) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.368 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[102964752]: (2,) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.369 18896 DEBUG oslo.privsep.daemon [-] privsep: request[102964752]: (3, 'os_brick.privileged.rootwrap.execute_root', ('systool', '-c', 'fc_host', '-v'), {}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.449 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): systool -c fc_host -v out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.776 18896 DEBUG oslo.privsep.daemon [-] CMD "systool -c fc_host -v" returned: 0 in 0.327s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.777 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[102964752]: (4, ('Class = "fc_host"\n\n Class Device = "host1"\n Class Device path = "/sys/devices/pci0000:00/0000:00:02.0/0000:04:00.0/host1/fc_host/host1"\n dev_loss_tmo = "45"\n fabric_name = "0x1000000533f7eb2b"\n issue_lip = <store method="" only="">\n max_npiv_vports = "127"\n node_name = "0x2000001b3287a726"\n npiv_vports_inuse = "0"\n port_id = "0x020500"\n port_name = "0x2100001b3287a726"\n port_state = "Online"\n port_type = "NPort (fabric via point-to-point)"\n speed = "4 Gbit"\n supported_classes = "Class 3"\n supported_speeds = "1 Gbit, 2 Gbit, 4 Gbit"\n symbolic_name = "QLE2462 FW:v8.03.00 DVR:v8.07.00.33.07.3-k1"\n system_hostname = ""\n tgtid_bind_type = "wwpn (World Wide Port Name)"\n uevent = \n vport_create = <store method="" only="">\n vport_delete = <store method="" only="">\n\n Device = "host1"\n Device path = "/sys/devices/pci0000:00/0000:00:02.0/0000:04:00.0/host1"\n fw_dump = \n nvram = "ISP \x01"\n optrom_ctl = <store method="" only="">\n optrom = \n reset = <store method="" only="">\n sfp = "\x02\x04\x07"\n uevent = "DEVTYPE=scsi_host"\n vpd = "\x82."\n\n\n Class Device = "host8"\n Class Device path = "/sys/devices/pci0000:00/0000:00:02.0/0000:04:00.1/host8/fc_host/host8"\n dev_loss_tmo = "45"\n fabric_name = "0x1000000533f7de77"\n issue_lip = <store method="" only="">\n max_npiv_vports = "127"\n node_name = "0x2001001b32a7a726"\n npiv_vports_inuse = "0"\n port_id = "0x030500"\n port_name = "0x2101001b32a7a726"\n port_state = "Online"\n port_type = "NPort (fabric via point-to-point)"\n speed = "4 Gbit"\n supported_classes = "Class 3"\n supported_speeds = "1 Gbit, 2 Gbit, 4 Gbit"\n symbolic_name = "QLE2462 FW:v8.03.00 DVR:v8.07.00.33.07.3-k1"\n system_hostname = ""\n tgtid_bind_type = "wwpn (World Wide Port Name)"\n uevent = \n vport_create = <store method="" only="">\n vport_delete = <store method="" only="">\n\n Device = "host8"\n Device path = "/sys/devices/pci0000:00/0000:00:02.0/0000:04:00.1/host8"\n fw_dump = \n nvram = "ISP \x01"\n optrom_ctl = <store method="" only="">\n optrom = \n reset = <store method="" only="">\n sfp = "\x02\x04\x07"\n uevent = "DEVTYPE=scsi_host"\n vpd = "\x82."\n\n\n', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.779 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:53.779 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:53.780 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:53.781 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:53.781 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:53.782 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:53.782 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:53.783 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:53.784 18896 WARNING os_brick.initiator.connectors.fibre_channel [-] Fibre Channel volume device not yet found. Will rescan & retry. Try number: 0. 2017-04-10 15:08:53.784 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:08:53.806 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:08:53.807 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:08:53.807 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host1 (wwnn: 2000001b3287a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:08:53.809 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host1/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.809 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host1/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.822 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host1/scan" returned: 0 in 0.013s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.823 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.824 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:08:53.843 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:08:53.845 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:08:53.845 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host8 (wwnn: 2001001b32a7a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:08:53.847 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host8/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.847 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host8/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.860 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host8/scan" returned: 0 in 0.013s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:53.860 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:55.781 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:55.782 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:55.783 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:55.783 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:55.784 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:55.784 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:55.785 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:55.785 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:55.786 18896 WARNING os_brick.initiator.connectors.fibre_channel [-] Fibre Channel volume device not yet found. Will rescan & retry. Try number: 1. 2017-04-10 15:08:55.786 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:08:55.808 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:08:55.810 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:08:55.810 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host1 (wwnn: 2000001b3287a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:08:55.812 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host1/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:55.812 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host1/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:55.829 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host1/scan" returned: 0 in 0.016s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:55.830 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:55.830 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:08:55.850 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:08:55.851 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:08:55.852 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host8 (wwnn: 2001001b32a7a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:08:55.854 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host8/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:55.854 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host8/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:55.862 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host8/scan" returned: 0 in 0.008s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:55.862 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:57.784 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:57.784 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:57.785 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:57.785 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:57.786 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:57.786 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:57.787 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:57.787 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:57.788 18896 WARNING os_brick.initiator.connectors.fibre_channel [-] Fibre Channel volume device not yet found. Will rescan & retry. Try number: 2. 2017-04-10 15:08:57.788 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:08:57.810 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:08:57.812 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:08:57.813 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host1 (wwnn: 2000001b3287a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:08:57.814 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host1/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:57.815 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host1/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:57.824 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host1/scan" returned: 0 in 0.008s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:57.824 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:57.825 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:08:57.844 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:08:57.846 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:08:57.847 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host8 (wwnn: 2001001b32a7a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:08:57.848 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host8/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:57.849 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host8/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:57.860 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host8/scan" returned: 0 in 0.011s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:57.861 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:59.783 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:59.784 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:59.784 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:59.785 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:59.785 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:59.786 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:59.786 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:59.787 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:08:59.787 18896 WARNING os_brick.initiator.connectors.fibre_channel [-] Fibre Channel volume device not yet found. Will rescan & retry. Try number: 3. 2017-04-10 15:08:59.788 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:08:59.811 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:08:59.812 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:08:59.813 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host1 (wwnn: 2000001b3287a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:08:59.815 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host1/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:59.815 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host1/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:59.828 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host1/scan" returned: 0 in 0.012s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:59.828 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:59.829 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:08:59.849 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:08:59.850 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:08:59.851 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host8 (wwnn: 2001001b32a7a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:08:59.853 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host8/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:59.853 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host8/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:59.861 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host8/scan" returned: 0 in 0.008s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:08:59.862 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:01.328 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] CALL msg_id: a0fda52d5deb4af3b0cb814bca7d5db5 exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:09:01.355 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: a0fda52d5deb4af3b0cb814bca7d5db5 __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:09:01.783 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:01.784 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:01.784 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:01.785 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:01.785 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:01.786 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:01.786 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:01.787 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:01.787 18896 WARNING os_brick.initiator.connectors.fibre_channel [-] Fibre Channel volume device not yet found. Will rescan & retry. Try number: 4. 2017-04-10 15:09:01.788 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:09:01.810 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:09:01.812 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2000001b3287a726 /sys/class/fc_transport/target1:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:09:01.812 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host1 (wwnn: 2000001b3287a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:09:01.814 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host1/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:01.814 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host1/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:01.823 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host1/scan" returned: 0 in 0.008s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:01.823 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:01.824 18896 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:344 2017-04-10 15:09:01.845 18896 DEBUG oslo_concurrency.processutils [-] u'grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name' failed. Not Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:422 2017-04-10 15:09:01.846 18896 ERROR os_brick.initiator.linuxfc [-] Could not get HBA channel and SCSI target ID, reason: [Errno 2] No such file or directory Command: grep 2001001b32a7a726 /sys/class/fc_transport/target8:/node_name Exit code: - Stdout: None Stderr: None 2017-04-10 15:09:01.847 18896 DEBUG os_brick.initiator.linuxfc [-] Scanning host host8 (wwnn: 2001001b32a7a726, c: -, t: -, l: 5) rescan_hosts /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:66 2017-04-10 15:09:01.848 18896 DEBUG oslo.privsep.daemon [-] privsep: request[76917648]: (3, 'os_brick.privileged.rootwrap.execute_root', ('tee', '-a', '/sys/class/scsi_host/host8/scan'), {'process_input': '- - 5'}) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:01.849 18896 DEBUG oslo.privsep.daemon [-] Running cmd (subprocess): tee -a /sys/class/scsi_host/host8/scan out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:01.856 18896 DEBUG oslo.privsep.daemon [-] CMD "tee -a /sys/class/scsi_host/host8/scan" returned: 0 in 0.008s out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:01.857 18896 DEBUG oslo.privsep.daemon [-] privsep: reply[76917648]: (4, ('- - 5', '')) out_of_band /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:194 2017-04-10 15:09:03.789 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:03.790 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:03.791 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:03.791 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.0-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:03.792 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f626-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:03.792 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f624-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:03.793 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f623-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:03.793 18896 DEBUG os_brick.initiator.connectors.fibre_channel [-] Looking for Fibre Channel dev /dev/disk/by-path/pci-0000:04:00.1-fc-0x5000d3100314f625-lun-5 _wait_for_device_discovery /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py:147 2017-04-10 15:09:03.794 18896 ERROR os_brick.initiator.connectors.fibre_channel [-] Fibre Channel volume device not found. 2017-04-10 15:09:03.794 18896 ERROR oslo.service.loopingcall [-] Fixed interval looping call 'os_brick.initiator.connectors.fibre_channel._wait_for_device_discovery' failed 2017-04-10 15:09:03.794 18896 ERROR oslo.service.loopingcall Traceback (most recent call last): 2017-04-10 15:09:03.794 18896 ERROR oslo.service.loopingcall File "/usr/lib/python2.7/site-packages/oslo_service/loopingcall.py", line 136, in _run_loop 2017-04-10 15:09:03.794 18896 ERROR oslo.service.loopingcall result = func(self.args, *self.kw) 2017-04-10 15:09:03.794 18896 ERROR oslo.service.loopingcall File "/usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py", line 157, in _wait_for_device_discovery 2017-04-10 15:09:03.794 18896 ERROR oslo.service.loopingcall raise exception.NoFibreChannelVolumeDeviceFound() 2017-04-10 15:09:03.794 18896 ERROR oslo.service.loopingcall NoFibreChannelVolumeDeviceFound: Unable to find a Fibre Channel volume device. 2017-04-10 15:09:03.794 18896 ERROR oslo.service.loopingcall 2017-04-10 15:09:03.797 18896 DEBUG oslo_concurrency.lockutils [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lock "connect_volume" released by "os_brick.initiator.connectors.fibre_channel.connect_volume" :: held 11.101s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:282 2017-04-10 15:09:03.797 18896 DEBUG os_brick.initiator.connectors.fibre_channel [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] <== connect_volume: exception (11102ms) NoFibreChannelVolumeDeviceFound(u'Unable to find a Fibre Channel volume device.',) trace_logging_wrapper /usr/lib/python2.7/site-packages/os_brick/utils.py:151 2017-04-10 15:09:03.802 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: 9608ea77a5d9419abfc8a8c832ce0e43 exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:09:03.828 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 9608ea77a5d9419abfc8a8c832ce0e43 __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:09:03.832 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: f183e9cc65594342b60a32e32989610f exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:09:03.872 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: f183e9cc65594342b60a32e32989610f __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:09:03.879 18896 DEBUG oslo_messaging._drivers.amqpdriver [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] CALL msg_id: 6ad1252275f642da982383d7de6ab85b exchange 'nova' topic 'conductor' _send /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:448 2017-04-10 15:09:04.021 18896 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 6ad1252275f642da982383d7de6ab85b __call__ /usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:296 2017-04-10 15:09:04.028 18896 DEBUG oslo_concurrency.lockutils [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lock "compute_resources" acquired by "nova.compute.resource_tracker.update_usage" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:270 2017-04-10 15:09:04.034 18896 DEBUG oslo_concurrency.lockutils [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Lock "compute_resources" released by "nova.compute.resource_tracker.update_usage" :: held 0.006s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:282 2017-04-10 15:09:04.035 18896 INFO nova.compute.manager [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] [instance: f248c4bb-95f7-489e-9442-2d5f7588c2c9] Successfully reverted task state from powering-on on failure for instance. 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server [req-75d5269a-de16-4586-8c13-477ea3d446a4 c42f3db35ab54eb69f2c829523c81668 b713ca31297341ad934ad5a19f2ab467 - - -] Exception during message handling 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server Traceback (most recent call last): 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/server.py", line 133, in _process_incoming 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server res = self.dispatcher.dispatch(message) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 150, in dispatch 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server return self._do_dispatch(endpoint, method, ctxt, args) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 121, in _do_dispatch 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server result = func(ctxt, *new_args) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/exception_wrapper.py", line 75, in wrapped 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server function_name, call_dict, binary) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__ 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server self.force_reraise() 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server six.reraise(self.type_, self.value, self.tb) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/exception_wrapper.py", line 66, in wrapped 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server return f(self, context, *args, *kw) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 188, in decorated_function 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server LOG.warning(msg, e, instance=instance) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__ 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server self.force_reraise() 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server six.reraise(self.type_, self.value, self.tb) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 157, in decorated_function 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server return function(self, context, args, *kwargs) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/utils.py", line 613, in decorated_function 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server return function(self, context, args, *kwargs) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 216, in decorated_function 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server kwargs['instance'], e, sys.exc_info()) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__ 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server self.force_reraise() 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server six.reraise(self.type_, self.value, self.tb) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 204, in decorated_function 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server return function(self, context, args, *kwargs) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2475, in start_instance 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server self._power_on(context, instance) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2445, in _power_on 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server block_device_info) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 2434, in power_on 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server self._hard_reboot(context, instance, network_info, block_device_info) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 2307, in _hard_reboot 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server block_device_info=block_device_info) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 4658, in _get_guest_xml 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server context) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 4483, in _get_guest_config 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server flavor, guest.os_type) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 3523, in _get_guest_storage_config 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server self._connect_volume(connection_info, info) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 1099, in _connect_volume 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server vol_driver.connect_volume(connection_info, disk_info) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/volume/fibrechannel.py", line 53, in connect_volume 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server device_info = self.connector.connect_volume(connection_info['data']) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/os_brick/utils.py", line 145, in trace_logging_wrapper 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server result = f(args, *kwargs) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py", line 271, in inner 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server return f(args, *kwargs) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py", line 172, in connect_volume 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server timer.start(interval=2).wait() 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/eventlet/event.py", line 121, in wait 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server return hubs.get_hub().switch() 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 294, in switch 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server return self.greenlet.switch() 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_service/loopingcall.py", line 136, in _run_loop 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server result = func(self.args, *self.kw) 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/os_brick/initiator/connectors/fibre_channel.py", line 157, in _wait_for_device_discovery 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server raise exception.NoFibreChannelVolumeDeviceFound() 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server NoFibreChannelVolumeDeviceFound: Unable to find a Fibre Channel volume device. 2017-04-10 15:09:04.077 18896 ERROR oslo_messaging.rpc.server oslo_messaging.rpc.server