(juno) gate-grenade-dsvm-ironic-sideways failing with NoValidHost due to PortNotUsable

[Matt Riedemann]

http://logs.openstack.org/82/169782/1/gate/gate-grenade-dsvm-ironic-sideways/d82f6a1/logs/new/screen-n-cpu.txt.gz?level=TRACE#_2015-04-19_08_36_06_412

2015-04-19 08:36:06.209 26279 ERROR nova.virt.ironic.driver [-] Error preparing deploy for instance 85a4a66e-24b0-48a4-ada6-1d29edee7adb on baremetal node f75b4bf9-6e6d-44fb-b4e8-ece394357440.
2015-04-19 08:36:06.412 26279 ERROR nova.compute.manager [-] [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] Instance failed to spawn
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] Traceback (most recent call last):
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] File "/opt/stack/new/nova/nova/compute/manager.py", line 2261, in _build_resources
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] yield resources
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] File "/opt/stack/new/nova/nova/compute/manager.py", line 2131, in _build_and_run_instance
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] block_device_info=block_device_info)
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] File "/opt/stack/new/nova/nova/virt/ironic/driver.py", line 645, in spawn
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] self._cleanup_deploy(context, node, instance, network_info)
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] File "/opt/stack/new/nova/nova/openstack/common/excutils.py", line 82, in __exit__
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] six.reraise(self.type_, self.value, self.tb)
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] File "/opt/stack/new/nova/nova/virt/ironic/driver.py", line 637, in spawn
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] self._plug_vifs(node, instance, network_info)
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] File "/opt/stack/new/nova/nova/virt/ironic/driver.py", line 900, in _plug_vifs
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] network_info_str = str(network_info)
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] File "/opt/stack/new/nova/nova/network/model.py", line 467, in __str__
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] return self._sync_wrapper(fn, *args, **kwargs)
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] File "/opt/stack/new/nova/nova/network/model.py", line 450, in _sync_wrapper
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] self.wait()
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] File "/opt/stack/new/nova/nova/network/model.py", line 482, in wait
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] self[:] = self._gt.wait()
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] File "/usr/local/lib/python2.7/dist-packages/eventlet/greenthread.py", line 173, in wait
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] return self._exit_event.wait()
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] File "/usr/local/lib/python2.7/dist-packages/eventlet/event.py", line 125, in wait
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] current.throw(*self._exc)
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] File "/usr/local/lib/python2.7/dist-packages/eventlet/greenthread.py", line 212, in main
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] result = function(*args, **kwargs)
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] File "/opt/stack/new/nova/nova/compute/manager.py", line 1661, in _allocate_network_async
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] dhcp_options=dhcp_options)
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] File "/opt/stack/new/nova/nova/network/neutronv2/api.py", line 300, in allocate_for_instance
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] instance=instance.uuid)
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb] PortNotUsable: Port b16075c4-af7a-4795-a26e-8d5eb0b39f49 not usable for instance 85a4a66e-24b0-48a4-ada6-1d29edee7adb.
2015-04-19 08:36:06.412 26279 TRACE nova.compute.manager [instance: 85a4a66e-24b0-48a4-ada6-1d29edee7adb]

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiSW5zdGFuY2UgZmFpbGVkIHRvIHNwYXduXCIgQU5EIG1lc3NhZ2U6XCJhbGxvY2F0ZV9mb3JfaW5zdGFuY2VcIiBBTkQgbWVzc2FnZTpcIlBvcnROb3RVc2FibGVcIiBBTkQgdGFnczpcInNjcmVlbi1uLWNwdS50eHRcIiIsImZpZWxkcyI6W10sIm9mZnNldCI6MCwidGltZWZyYW1lIjoiNjA0ODAwIiwiZ3JhcGhtb2RlIjoiY291bnQiLCJ0aW1lIjp7InVzZXJfaW50ZXJ2YWwiOjB9LCJzdGFtcCI6MTQyOTQ0ODM3NjAxN30=

29 hits since 4/17. This is only on ironic grenade jobs and only on stable/juno.

[Matt Riedemann (mriedem)]

This backport was merged to stable/juno nova on 4/16, wondering if it's causing problems:

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

[Matt Riedemann (mriedem)]

e-r query: https://review.openstack.org/#/c/175210/

[Matt Riedemann (mriedem)]

This is the breaking change: https://review.openstack.org/#/c/162886/

[Matt Riedemann (mriedem)]

Revert: https://review.openstack.org/#/c/175219/

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/175458

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/175219
Committed: https://git.openstack.org/cgit/openstack/tempest/commit/?id=92b63aa8211b6a54f47c3ec2f1c77abf15017be8
Submitter: Jenkins
Branch: master

commit 92b63aa8211b6a54f47c3ec2f1c77abf15017be8
Author: Matt Riedemann <email address hidden>
Date: Sun Apr 19 15:45:38 2015 +0000

    Revert "Test creation of server attached to created port"

    This reverts commit 2b34ec3ff444e6e6ec7b3e52832ecd6e8ca20552

    This breaks gate-grenade-dsvm-ironic-sideways on
    stable/juno because the requested port's mac address is not
    in the list of available mac addresses from the ironic
    driver.

    It's also unclear how useful this is given we already have
    the test_preserve_preexisting_port test which is
    essentially testing the same scenario, except it's not
    run on stable/icehouse or stable/juno since preserving
    pre-existing ports in nova wasn't fixed until Kilo.

    Change-Id: I24403c1ae734b2137ddee5c3bf5a1594cf5375d8
    Closes-Bug: #1445917

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/175458
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=a4705d8aff9c3d25e8c5b615b7464a1b4488038b
Submitter: Jenkins
Branch: master

commit a4705d8aff9c3d25e8c5b615b7464a1b4488038b
Author: Matt Riedemann <email address hidden>
Date: Mon Apr 20 08:12:26 2015 -0700

    neutron: log hypervisor_macs before raising PortNotUsable

    Knowing what the requested port's mac address is and the set of
    available hypervisor macs are is useful information when the request
    fails, so log those at debug level.

    Related-Bug: #1445917

    Change-Id: Ib7980376fcef9d52d22c9663aa00df6968794711