tempest-dsvm-postgres-full fail with 'Error. Unable to associate floating ip'

[Nilesh Bhosale]

Jenkins job failed with 'Error. Unable to associate floating ip'.
Logs can be found here:
http://logs.openstack.org/67/120067/2/check/check-tempest-dsvm-postgres-full/1a45f89/console.html

Log snippet:
2014-09-10 18:55:16.527 | 2014-09-10 18:30:55,125 24275 INFO [tempest.common.rest_client] Request (TestVolumeBootPattern:_run_cleanups): 404 GET http://127.0.0.1:8776/v1/5e4676bdfb7548b3b4dd4b084cee1752/volumes/651d8b59-df65-442c-9165-1b993374b24a 0.025s
2014-09-10 18:55:16.527 | 2014-09-10 18:30:55,157 24275 INFO [tempest.common.rest_client] Request (TestVolumeBootPattern:_run_cleanups): 404 GET http://127.0.0.1:8774/v2/5e4676bdfb7548b3b4dd4b084cee1752/servers/25b9a6b8-dc48-47d3-9569-620e47ff0495 0.032s
2014-09-10 18:55:16.527 | 2014-09-10 18:30:55,191 24275 INFO [tempest.common.rest_client] Request (TestVolumeBootPattern:_run_cleanups): 404 GET http://127.0.0.1:8774/v2/5e4676bdfb7548b3b4dd4b084cee1752/servers/bbf6f5c4-7f2f-48ec-9d86-50c89d636a6d 0.032s
2014-09-10 18:55:16.527 | }}}
2014-09-10 18:55:16.527 |
2014-09-10 18:55:16.527 | Traceback (most recent call last):
2014-09-10 18:55:16.527 | File "tempest/test.py", line 128, in wrapper
2014-09-10 18:55:16.527 | return f(self, *func_args, **func_kwargs)
2014-09-10 18:55:16.528 | File "tempest/scenario/test_volume_boot_pattern.py", line 164, in test_volume_boot_pattern
2014-09-10 18:55:16.528 | keypair)
2014-09-10 18:55:16.528 | File "tempest/scenario/test_volume_boot_pattern.py", line 108, in _ssh_to_server
2014-09-10 18:55:16.528 | floating_ip['ip'], server['id'])
2014-09-10 18:55:16.528 | File "tempest/services/compute/json/floating_ips_client.py", line 80, in associate_floating_ip_to_server
2014-09-10 18:55:16.528 | resp, body = self.post(url, post_body)
2014-09-10 18:55:16.528 | File "tempest/common/rest_client.py", line 219, in post
2014-09-10 18:55:16.528 | return self.request('POST', url, extra_headers, headers, body)
2014-09-10 18:55:16.528 | File "tempest/common/rest_client.py", line 435, in request
2014-09-10 18:55:16.528 | resp, resp_body)
2014-09-10 18:55:16.529 | File "tempest/common/rest_client.py", line 484, in _error_checker
2014-09-10 18:55:16.529 | raise exceptions.BadRequest(resp_body)
2014-09-10 18:55:16.529 | BadRequest: Bad request
2014-09-10 18:55:16.529 | Details: {u'message': u'Error. Unable to associate floating ip', u'code': 400}

[Nilesh Bhosale (nilesh-bhosale)]

I didn't see this issue post a recheck on my change https://review.openstack.org/#/c/120067/.
Probably a temporary Jenkins environment issue.

[Henry Gessau (gessau)]

This test was run with nova-network, so it is not applicable to neutron.

[Eugene Nikanorov (enikanorov)]

Agree with Henry, adding nova, removing neutron

[Sean Dague (sdague)]

nova-api:

2014-09-10 18:28:07.120 ERROR nova.api.openstack.compute.contrib.floating_ips [req-c0a4e3d4-35f6-4c4a-99f7-4b7fa6fec030 TestVolumeBootPattern-685024276 TestVolumeBootPattern-724196437] Error. Unable to associate floating ip
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips Traceback (most recent call last):
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips File "/opt/stack/new/nova/nova/api/openstack/compute/contrib/floating_ips.py", line 240, in _add_floating_ip
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips fixed_address=fixed_address)
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips File "/opt/stack/new/nova/nova/network/api.py", line 48, in wrapped
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips return func(self, context, *args, **kwargs)
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips File "/opt/stack/new/nova/nova/network/base_api.py", line 60, in wrapper
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips res = f(self, context, *args, **kwargs)
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips File "/opt/stack/new/nova/nova/network/api.py", line 222, in associate_floating_ip
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips context, floating_address, fixed_address, affect_auto_assigned)
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips File "/opt/stack/new/nova/nova/utils.py", line 949, in wrapper
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips return func(*args, **kwargs)
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/server.py", line 139, in inner
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips return func(*args, **kwargs)
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips File "/opt/stack/new/nova/nova/network/floating_ips.py", line 349, in associate_floating_ip
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips fixed_ip.instance_uuid)
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips File "/opt/stack/new/nova/nova/network/rpcapi.py", line 335, in _associate_floating_ip
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips interface=interface, instance_uuid=instance_uuid)
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/client.py", line 152, in call
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips retry=self.retry)
2014-09-10 18:28:07.120 21523 TRACE nova.api.openstack.compute.contrib.floating_ips File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/transport.py", line 90, in _send
2014-09-10...

[Sean Dague (sdague)]

nova-cpu:

2014-09-10 18:27:06.310 21614 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /opt/stack/new/nova/nova/openstack/common/periodic_task.py:193
2014-09-10 18:27:06.310 21614 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call <bound method Service.periodic_tasks of <nova.service.Service object at 0x7f777a5170d0>> sleeping for 50.00 seconds _inner /opt/stack/new/nova/nova/openstack/common/loopingcall.py:132
2014-09-10 18:27:56.312 21614 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /opt/stack/new/nova/nova/openstack/common/periodic_task.py:193
2014-09-10 18:28:47.800 21614 ERROR nova.servicegroup.drivers.db [-] model server went away
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db Traceback (most recent call last):
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db File "/opt/stack/new/nova/nova/servicegroup/drivers/db.py", line 99, in _report_state
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db service.service_ref, state_catalog)
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db File "/opt/stack/new/nova/nova/conductor/api.py", line 180, in service_update
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db return self._manager.service_update(context, service, values)
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db File "/opt/stack/new/nova/nova/conductor/rpcapi.py", line 281, in service_update
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db service=service_p, values=values)
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/client.py", line 152, in call
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db retry=self.retry)
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/transport.py", line 90, in _send
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db timeout=timeout, retry=retry)
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/_drivers/amqpdriver.py", line 408, in send
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db retry=retry)
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/_drivers/amqpdriver.py", line 397, in _send
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db result = self._waiter.wait(msg_id, timeout)
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/_drivers/amqpdriver.py", line 285, in wait
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db reply, ending = self._poll_connection(msg_id, timeout)
2014-09-10 18:28:47.800 21614 TRACE nova.servicegroup.drivers.db File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/_drivers/amqpdriver.py", line ...

[Sean Dague (sdague)]

nova-cond:

/opt/stack/new/nova/nova/quota.py:1334
2014-09-10 18:27:07.945 21738 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call <bound method Service.periodic_tasks of <nova.service.Service object at 0x7fa3d0348bd0>> sleeping for 60.00 seconds _inner /opt/stack/new/nova/nova/openstack/common/loopingcall.py:132
2014-09-10 18:28:07.999 21738 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call <bound method Service.periodic_tasks of <nova.service.Service object at 0x7fa3d0348bd0>> sleeping for 60.00 seconds _inner /opt/stack/new/nova/nova/openstack/common/loopingcall.py:132
2014-09-10 18:28:47.823 21734 WARNING nova.openstack.common.loopingcall [-] task <bound method DbDriver._report_state of <nova.servicegroup.drivers.db.DbDriver object at 0x7fa3d0348ed0>> run outlasted interval by 83.63 sec
2014-09-10 18:28:47.878 21737 WARNING nova.openstack.common.loopingcall [-] task <bound method DbDriver._report_state of <nova.servicegroup.drivers.db.DbDriver object at 0x7fa3d0348ed0>> run outlasted interval by 83.82 sec
2014-09-10 18:28:47.918 21738 WARNING nova.openstack.common.loopingcall [-] task <bound method DbDriver._report_state of <nova.servicegroup.drivers.db.DbDriver object at 0x7fa3d0348ed0>> run outlasted interval by 83.31 sec
2014-09-10 18:28:47.925 21736 WARNING nova.openstack.common.loopingcall [-] task <bound method DbDriver._report_state of <nova.servicegroup.drivers.db.DbDriver object at 0x7fa3d0348ed0>> run outlasted interval by 83.67 sec
2014-09-10 18:28:47.928 21739 WARNING nova.openstack.common.loopingcall [-] task <bound method DbDriver._report_state of <nova.servicegroup.drivers.db.DbDriver object at 0x7fa3d0348ed0>> run outlasted interval by 83.72 sec
2014-09-10 18:28:47.924 21732 WARNING nova.openstack.common.loopingcall [-] task <bound method DbDriver._report_state of <nova.servicegroup.drivers.db.DbDriver object at 0x7fa3d0348ed0>> run outlasted interval by 83.72 sec

[Sean Dague (sdague)]

It looks like the periodic job is taking a lock which is consuming all the conductor workers so messages can't get sent?

[Davanum Srinivas (DIMS) (dims-v)]

Is this still a problem?

[Launchpad Janitor (janitor)]

[Expired for OpenStack Compute (nova) because there has been no activity for 60 days.]