'headroom' KeyError while creating instance

[David Kranz]

A gate job failed with this error in the n-cpu log. The job is http://logs.openstack.org/13/145713/7/gate/gate-tempest-dsvm-full/71a2280/

From http://logs.openstack.org/13/145713/7/gate/gate-tempest-dsvm-full/71a2280/logs/screen-n-cpu.txt.gz

2015-01-13 12:24:35.148 29194 ERROR nova.compute.manager [-] Instance failed network setup after 1 attempt(s)
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager Traceback (most recent call last):
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager File "/opt/stack/new/nova/nova/compute/manager.py", line 1676, in _allocate_network_async
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager dhcp_options=dhcp_options)
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager File "/opt/stack/new/nova/nova/network/api.py", line 47, in wrapped
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager return func(self, context, *args, **kwargs)
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager File "/opt/stack/new/nova/nova/network/base_api.py", line 64, in wrapper
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager res = f(self, context, *args, **kwargs)
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager File "/opt/stack/new/nova/nova/network/api.py", line 276, in allocate_for_instance
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager nw_info = self.network_rpcapi.allocate_for_instance(context, **args)
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager File "/opt/stack/new/nova/nova/network/rpcapi.py", line 189, in allocate_for_instance
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager macs=jsonutils.to_primitive(macs))
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/client.py", line 152, in call
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager retry=self.retry)
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/transport.py", line 90, in _send
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager timeout=timeout, retry=retry)
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/_drivers/amqpdriver.py", line 436, in send
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager retry=retry)
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/_drivers/amqpdriver.py", line 427, in _send
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager raise result
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager KeyError: u'\'headroom\'\nTraceback (most recent call last):\n\n File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 137, in _dispatch_and_reply\n incoming.message))\n\n File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 180, in _dispatch\n return self._do_dispatch(endpoint, method, ctxt, args)\n\n File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 126, in _do_dispatch\n result = getattr(endpoint, method)(ctxt, **new_args)\n\n File "/opt/stack/new/nova/nova/network/floating_ips.py", line 113, in allocate_for_instance\n **kwargs)\n\n File "/opt/stack/new/nova/nova/network/manager.py", line 501, in allocate_for_instance\n requested_networks=requested_networks)\n\n File "/opt/stack/new/nova/nova/network/manager.py", line 193, in _allocate_fixed_ips\n vpn=vpn, address=address)\n\n File "/opt/stack/new/nova/nova/network/manager.py", line 857, in allocate_fixed_ip\n headroom = exc.kwargs[\'headroom\']\n\nKeyError: \'headroom\'\n'
2015-01-13 12:24:35.148 29194 TRACE nova.compute.manager
Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/eventlet/queue.py", line 117, in switch
    self.greenlet.switch(value)
  File "/usr/local/lib/python2.7/dist-packages/eventlet/greenthread.py", line 214, in main
    result = function(*args, **kwargs)
  File "/opt/stack/new/nova/nova/compute/manager.py", line 1676, in _allocate_network_async
    dhcp_options=dhcp_options)
  File "/opt/stack/new/nova/nova/network/api.py", line 47, in wrapped
    return func(self, context, *args, **kwargs)
  File "/opt/stack/new/nova/nova/network/base_api.py", line 64, in wrapper
    res = f(self, context, *args, **kwargs)
  File "/opt/stack/new/nova/nova/network/api.py", line 276, in allocate_for_instance
    nw_info = self.network_rpcapi.allocate_for_instance(context, **args)
  File "/opt/stack/new/nova/nova/network/rpcapi.py", line 189, in allocate_for_instance
    macs=jsonutils.to_primitive(macs))
  File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/client.py", line 152, in call
    retry=self.retry)
  File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/transport.py", line 90, in _send
    timeout=timeout, retry=retry)
  File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/_drivers/amqpdriver.py", line 436, in send
    retry=retry)
  File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/_drivers/amqpdriver.py", line 427, in _send
    raise result
KeyError: u'\'headroom\'\nTraceback (most recent call last):\n\n File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 137, in _dispatch_and_reply\n incoming.message))\n\n File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 180, in _dispatch\n return self._do_dispatch(endpoint, method, ctxt, args)\n\n File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 126, in _do_dispatch\n result = getattr(endpoint, method)(ctxt, **new_args)\n\n File "/opt/stack/new/nova/nova/network/floating_ips.py", line 113, in allocate_for_instance\n **kwargs)\n\n File "/opt/stack/new/nova/nova/network/manager.py", line 501, in allocate_for_instance\n requested_networks=requested_networks)\n\n File "/opt/stack/new/nova/nova/network/manager.py", line 193, in _allocate_fixed_ips\n vpn=vpn, address=address)\n\n File "/opt/stack/new/nova/nova/network/manager.py", line 857, in allocate_fixed_ip\n headroom = exc.kwargs[\'headroom\']\n\nKeyError: \'headroom\'\n'

The console output of the failed test is:

setUpClass (tempest.api.compute.images.test_list_image_filters.ListImageFiltersTestJSON)
2015-01-13 12:41:58.677 | ----------------------------------------------------------------------------------------
2015-01-13 12:41:58.677 |
2015-01-13 12:41:58.677 | Captured traceback:
2015-01-13 12:41:58.677 | ~~~~~~~~~~~~~~~~~~~
2015-01-13 12:41:58.678 | Traceback (most recent call last):
2015-01-13 12:41:58.678 | File "tempest/test.py", line 273, in setUpClass
2015-01-13 12:41:58.678 | cls.resource_setup()
2015-01-13 12:41:58.678 | File "tempest/api/compute/images/test_list_image_filters.py", line 73, in resource_setup
2015-01-13 12:41:58.678 | resp, cls.server2 = cls.create_test_server(wait_until='ACTIVE')
2015-01-13 12:41:58.678 | File "tempest/api/compute/base.py", line 226, in create_test_server
2015-01-13 12:41:58.678 | pass
2015-01-13 12:41:58.678 | File "tempest/openstack/common/excutils.py", line 68, in __exit__
2015-01-13 12:41:58.678 | six.reraise(self.type_, self.value, self.tb)
2015-01-13 12:41:58.678 | File "tempest/api/compute/base.py", line 216, in create_test_server
2015-01-13 12:41:58.679 | server['id'], kwargs['wait_until'])
2015-01-13 12:41:58.679 | File "tempest/services/compute/json/servers_client.py", line 178, in wait_for_server_status
2015-01-13 12:41:58.679 | ready_wait=ready_wait)
2015-01-13 12:41:58.679 | File "tempest/common/waiters.py", line 73, in wait_for_server_status
2015-01-13 12:41:58.679 | server_id=server_id)
2015-01-13 12:41:58.679 | BuildErrorException: Server 8ea4c502-c5b0-4aa7-8a09-17fac3e226f5 failed to build and is in ERROR status
2015-01-13 12:41:58.679 | Details: {u'code': 500, u'message': u'No valid host was found. There are not enough hosts available.', u'created': u'2015-01-13T12:24:36Z'}
2015-01-13 12:41:58.679 |

[Matt Riedemann (mriedem)]

12 hits in 7 days, check and gate, all failures:

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

[Matt Riedemann (mriedem)]

This goes back to at least 1/5 but logstash only retains 10 days worth of history. Nothing is jumping out at me for changes to nova-network since then.

[Matt Riedemann (mriedem)]

This looks like a prime suspect:

https://github.com/openstack/nova/commit/0045f7d50cad345c26ae02394ad57716b270d268

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/147055

[OpenStack Infra (hudson-openstack)]

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

commit 5d924c8a175b9f13cf0c0e3721903fdb19e8f0dc
Author: Matt Riedemann <email address hidden>
Date: Tue Jan 13 18:32:03 2015 -0800

    Fix OverQuota headroom KeyError in nova-network allocate_fixed_ip

    Commit 0045f7d50cad345c26ae02394ad57716b270d268 moved the headroom
    calculation out of the DB API and into the compute API for when
    instances go over quota (more specifically flavor information for an
    instance create), but didn't update the nova-network manager code to
    remove the usage of the headroom kwarg from the OverQuota exception
    for logging.

    This removes the usage of 'headroom' and also fixes the logging a bit so
    the 'used' value makes more sense, where used = in_use + reserved.

    Closes-Bug: #1410310

    Change-Id: I24802e8b5dfe7741b505696c885871a04f769b12