Nova compute backtraces with nova KeyError: 1 when using VMwareVCDriver

[Jacob Cherkas]

Nova 2013.1 from Ubuntu packages.

compute_driver=vmwareapi.VMwareVCDriver

Configured to use Quantum.

network_api_class=nova.network.quantumv2.api.API

We can reproduce the backtrace 100% of the time.

Boot a nova instance that gets scheduled to a VMware VirtualCenter. The instance boots just fine and everything works.

If, at any point, you restart nova-compute for VCDriver you get:

2013-05-09 10:27:02.029 12071 TRACE nova File "/usr/bin/nova-compute", line 85, in <module>
2013-05-09 10:27:02.029 12071 TRACE nova service.wait()
2013-05-09 10:27:02.029 12071 TRACE nova File "/usr/lib/python2.7/dist-packages/nova/service.py", line 689, in wait
2013-05-09 10:27:02.029 12071 TRACE nova _launcher.wait()
2013-05-09 10:27:02.029 12071 TRACE nova File "/usr/lib/python2.7/dist-packages/nova/service.py", line 209, in wait
2013-05-09 10:27:02.029 12071 TRACE nova super(ServiceLauncher, self).wait()
2013-05-09 10:27:02.029 12071 TRACE nova File "/usr/lib/python2.7/dist-packages/nova/service.py", line 179, in wait
2013-05-09 10:27:02.029 12071 TRACE nova service.wait()
2013-05-09 10:27:02.029 12071 TRACE nova File "/usr/lib/python2.7/dist-packages/eventlet/greenthread.py", line 168, in wait
2013-05-09 10:27:02.029 12071 TRACE nova return self._exit_event.wait()
2013-05-09 10:27:02.029 12071 TRACE nova File "/usr/lib/python2.7/dist-packages/eventlet/event.py", line 116, in wait
2013-05-09 10:27:02.029 12071 TRACE nova return hubs.get_hub().switch()
2013-05-09 10:27:02.029 12071 TRACE nova File "/usr/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 187, in switch
2013-05-09 10:27:02.029 12071 TRACE nova return self.greenlet.switch()
2013-05-09 10:27:02.029 12071 TRACE nova File "/usr/lib/python2.7/dist-packages/eventlet/greenthread.py", line 194, in main
2013-05-09 10:27:02.029 12071 TRACE nova result = function(*args, **kwargs)
2013-05-09 10:27:02.029 12071 TRACE nova File "/usr/lib/python2.7/dist-packages/nova/service.py", line 147, in run_server
2013-05-09 10:27:02.029 12071 TRACE nova server.start()
2013-05-09 10:27:02.029 12071 TRACE nova File "/usr/lib/python2.7/dist-packages/nova/service.py", line 429, in start
2013-05-09 10:27:02.029 12071 TRACE nova self.manager.init_host()
2013-05-09 10:27:02.029 12071 TRACE nova File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 585, in init_host
2013-05-09 10:27:02.029 12071 TRACE nova self._init_instance(context, instance)
2013-05-09 10:27:02.029 12071 TRACE nova File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 469, in _init_instance
2013-05-09 10:27:02.029 12071 TRACE nova if legacy_net_info and legacy_net_info[0][1].get('vif_type') is None:
2013-05-09 10:27:02.029 12071 TRACE nova KeyError: 1
2013-05-09 10:27:02.029 12071 TRACE nova

nova-compute can no longer start. Only way to start nova-compute after is to delete the instance via nova delete.

This then soft deletes the instance from the DB but leave the running instances on the HV and there is no record of the instance from nova going forward.

Change-Id I1b839bf791b402b933354d9c17c5713fde21ab09 included the update instance network info cache to include vif_type .

Hopefully Yaguang Tang can take a look and provide feedback.

[Jacob Cherkas (jcherkas)]

Additional info.

Logging whats in legacy_net_info:

013-05-10 12:15:14.142 ERROR nova.compute.manager [req-d80bc6bc-5851-4e6b-a070-cada772cc31f None None] ('######', [VIF({'ovs_interfaceid': None, 'network': Network({'bridge': None, 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.0.22'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.0.23'}, 'dns': [], 'routes': [], 'cidr': u'192.168.0.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.0.1'})})], 'meta': {u'injected': False, u'tenant_id': u'26af345b8c5b4cf881a68eb3151febd9'}, 'id': u'32fd60c1-02bb-4147-a005-c8a907f8669a', 'label': u'workLan'}), 'devname': u'tapb933bd2d-29', 'qbh_params': None, 'meta': {}, 'address': u'fa:16:3e:0a:2a:71', 'type': None, 'id': u'b933bd2d-29c2-4a8e-9c06-7bdc7c249b7c', 'qbg_params': None})])

[Yaguang Tang (heut2008)]

this has been fixed by commit

commit 948d1fefe6cb1e17c5567d3cf3313e13c16a3d57
Author: Rick Harris <email address hidden>
Date: Wed Apr 3 21:09:50 2013 +0000

    Fix legacy_net_info guard

    The existing code assumes that `legacy_net_info` is always in legacy
    mode, meaning a list of tuples which causes it to break when passed a
    new-style NetworkInfo object.

    Fixes bug 1164152

    Change-Id: I2131d9b24045cd7531454b65d97776b11ec3ab02

[Yaguang Tang (heut2008)]

note that this bug has also been backport to 2013.1.1, you may need to wait sometime for ubuntu cloud archive update to 2013.1.1.