InvalidUUID exception after vifs plug failed

[Francois Deppierraz]

An openstack deployment under Ubuntu 14.04 which was upgraded all the way from havana. After a recent upgrade of nova-compute from 2014.1.3-0ubuntu2 to 2014.1.4-0ubuntu2, nova-compute doesn't start anymore on one of the compute nodes.

My guess is that the root cause here is missing data in network_info for this particular instance. However, nova-compute should not exit in this case.

2015-04-28 22:25:05.021 10017 AUDIT nova.service [-] Starting compute node (version 2014.1.4)
2015-04-28 22:25:05.022 10017 DEBUG nova.virt.libvirt.driver [-] Connecting to libvirt: qemu:///system _get_new_connection /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:672
2015-04-28 22:25:05.058 10017 DEBUG nova.virt.libvirt.driver [-] Registering for lifecycle events <nova.virt.libvirt.driver.LibvirtDriver object at 0x7fa1e5978e90> _get_new_connection /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:688
2015-04-28 22:25:05.061 10017 DEBUG nova.virt.libvirt.driver [-] Registering for connection events: <nova.virt.libvirt.driver.LibvirtDriver object at 0x7fa1e5978e90> _get_new_connection /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:700
2015-04-28 22:25:05.079 10017 DEBUG nova.virt.libvirt.config [-] Generated XML ('<cpu>\n <arch>x86_64</arch>\n <model>SandyBridge</model>\n <vendor>Intel</vendor>\n <topology sockets="1" cores="8" threads="2"/>\n <feature name="acpi"/>\n <feature name="dca"/>\n <feature name="ds"/>\n <feature name="ds_cpl"/>\n <feature name="dtes64"/>\n <feature name="est"/>\n <feature name="ht"/>\n <feature name="monitor"/>\n <feature name="osxsave"/>\n <feature name="pbe"/>\n <feature name="pcid"/>\n <feature name="pdcm"/>\n <feature name="pdpe1gb"/>\n <feature name="smx"/>\n <feature name="ss"/>\n <feature name="tm"/>\n <feature name="tm2"/>\n <feature name="vme"/>\n <feature name="vmx"/>\n <feature name="xtpr"/>\n</cpu>\n',) to_xml /usr/lib/python2.7/dist-packages/nova/virt/libvirt/config.py:71
2015-04-28 22:25:05.086 10017 DEBUG nova.virt.libvirt.driver [-] Starting native event thread _init_events /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:625
2015-04-28 22:25:05.087 10017 DEBUG nova.virt.libvirt.driver [-] Starting green dispatch thread _init_events /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:630
2015-04-28 22:25:05.290 10017 DEBUG nova.compute.manager [-] [instance: 6c33e4b2-009b-49f3-8b7a-8b1dd5cce344] Checking state _get_power_state /usr/lib/python2.7/dist-packages/nova/compute/manager.py:1088
2015-04-28 22:25:05.296 10017 DEBUG nova.compute.manager [-] [instance: 6c33e4b2-009b-49f3-8b7a-8b1dd5cce344] Checking state _get_power_state /usr/lib/python2.7/dist-packages/nova/compute/manager.py:1088
2015-04-28 22:25:05.302 10017 DEBUG nova.virt.libvirt.vif [-] vif_type=ovs instance=<nova.objects.instance.Instance object at 0x7fa1e573b0d0> vif=VIF({'ovs_interfaceid': u'61c90c3f-24fc-4a58-8f6f-a7caf485fe50', 'network': Network({'bridge': u'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'10.27.72.8'})], 'version': 4, 'meta': {u'dhcp_server': u'10.27.72.11'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'10.26.10.1'}), IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'10.27.21.2'})], 'routes': [], 'cidr': u'10.27.72.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.27.72.1'})})], 'meta': {u'injected': False, u'tenant_id': u'6966cc471a354147901586eed21e4c4e'}, 'id': u'1e5a7f58-a380-4636-9857-4e707e608530', 'label': u'c2c-vlan72'}), 'devname': u'tap61c90c3f-24', 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:a4:d0:75', 'active': True, 'type': u'ovs', 'id': u'61c90c3f-24fc-4a58-8f6f-a7caf485fe50', 'qbg_params': None}) plug /usr/lib/python2.7/dist-packages/nova/virt/libvirt/vif.py:592
2015-04-28 22:25:05.306 10017 DEBUG nova.compute.manager [-] [instance: 6c33e4b2-009b-49f3-8b7a-8b1dd5cce344] Checking state _get_power_state /usr/lib/python2.7/dist-packages/nova/compute/manager.py:1088
2015-04-28 22:25:05.313 10017 DEBUG nova.compute.manager [-] [instance: 6c33e4b2-009b-49f3-8b7a-8b1dd5cce344] Current state is 1, state in DB is 1. _init_instance /usr/lib/python2.7/dist-packages/nova/compute/manager.py:966
2015-04-28 22:25:05.314 10017 DEBUG nova.compute.manager [-] [instance: 08991862-8385-41fa-9ac8-b59dea1e8e61] Checking state _get_power_state /usr/lib/python2.7/dist-packages/nova/compute/manager.py:1088
2015-04-28 22:25:05.320 10017 DEBUG nova.compute.manager [-] [instance: 08991862-8385-41fa-9ac8-b59dea1e8e61] Checking state _get_power_state /usr/lib/python2.7/dist-packages/nova/compute/manager.py:1088
2015-04-28 22:25:05.327 10017 DEBUG nova.virt.libvirt.vif [-] vif_type=None instance=<nova.objects.instance.Instance object at 0x7fa1e57bc450> vif=VIF({'ovs_interfaceid': None, 'network': Network({'bridge': None, 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'10.27.71.16'})], 'version': 4, 'meta': {u'dhcp_server': u'10.27.71.23'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'10.26.10.1'}), IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'10.27.21.2'})], 'routes': [], 'cidr': u'10.27.71.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.27.71.1'})})], 'meta': {u'injected': False, u'tenant_id': u'445ed83efc894d11963d10be98d6c2ab'}, 'id': u'05bdb9ac-4cbc-467d-b355-269c4b6f9733', 'label': u'c2c-vlan71'}), 'devname': u'tape3e7ac16-33', 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:d8:b7:3d', 'active': True, 'type': None, 'id': u'e3e7ac16-3333-4fd2-a182-0996d2a6a1d1', 'qbg_params': None}) plug /usr/lib/python2.7/dist-packages/nova/virt/libvirt/vif.py:592
2015-04-28 22:25:05.328 10017 ERROR nova.compute.manager [-] [instance: 08991862-8385-41fa-9ac8-b59dea1e8e61] Vifs plug failed
2015-04-28 22:25:05.328 10017 TRACE nova.compute.manager [instance: 08991862-8385-41fa-9ac8-b59dea1e8e61] Traceback (most recent call last):
2015-04-28 22:25:05.328 10017 TRACE nova.compute.manager [instance: 08991862-8385-41fa-9ac8-b59dea1e8e61] File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 924, in _init_instance
2015-04-28 22:25:05.328 10017 TRACE nova.compute.manager [instance: 08991862-8385-41fa-9ac8-b59dea1e8e61] self.driver.plug_vifs(instance, net_info)
2015-04-28 22:25:05.328 10017 TRACE nova.compute.manager [instance: 08991862-8385-41fa-9ac8-b59dea1e8e61] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 861, in plug_vifs
2015-04-28 22:25:05.328 10017 TRACE nova.compute.manager [instance: 08991862-8385-41fa-9ac8-b59dea1e8e61] self.vif_driver.plug(instance, vif)
2015-04-28 22:25:05.328 10017 TRACE nova.compute.manager [instance: 08991862-8385-41fa-9ac8-b59dea1e8e61] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/vif.py", line 596, in plug
2015-04-28 22:25:05.328 10017 TRACE nova.compute.manager [instance: 08991862-8385-41fa-9ac8-b59dea1e8e61] _("vif_type parameter must be present "
2015-04-28 22:25:05.328 10017 TRACE nova.compute.manager [instance: 08991862-8385-41fa-9ac8-b59dea1e8e61] VirtualInterfacePlugException: vif_type parameter must be present for this vif_driver implementation
2015-04-28 22:25:05.328 10017 TRACE nova.compute.manager [instance: 08991862-8385-41fa-9ac8-b59dea1e8e61]
2015-04-28 22:25:05.347 10017 ERROR nova.openstack.common.threadgroup [-] <nova.objects.instance.Instance object at 0x7fb928cd1ed0>
Traceback (most recent call last):

  File "/usr/lib/python2.7/dist-packages/oslo/messaging/rpc/server.py", line 139, in inner
    return func(*args, **kwargs)

  File "/usr/lib/python2.7/dist-packages/nova/conductor/manager.py", line 130, in instance_update
    context, instance_uuid, updates)

  File "/usr/lib/python2.7/dist-packages/nova/db/api.py", line 742, in instance_update_and_get_original
    columns_to_join=columns_to_join)

  File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 164, in wrapper
    return f(*args, **kwargs)

  File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 2216, in instance_update_and_get_original
    columns_to_join=columns_to_join)

  File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 202, in wrapped
    return f(*args, **kwargs)

  File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 2250, in _instance_update
    raise exception.InvalidUUID(instance_uuid)

InvalidUUID: <nova.objects.instance.Instance object at 0x7fb928cd1ed0>
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup Traceback (most recent call last):
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/nova/openstack/common/threadgroup.py", line 117, in wait
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup x.wait()
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/nova/openstack/common/threadgroup.py", line 49, in wait
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup return self.thread.wait()
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/eventlet/greenthread.py", line 168, in wait
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup return self._exit_event.wait()
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/eventlet/event.py", line 116, in wait
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup return hubs.get_hub().switch()
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 187, in switch
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup return self.greenlet.switch()
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/eventlet/greenthread.py", line 194, in main
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup result = function(*args, **kwargs)
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/nova/openstack/common/service.py", line 483, in run_service
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup service.start()
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/nova/service.py", line 163, in start
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup self.manager.init_host()
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 1071, in init_host
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup self._init_instance(context, instance)
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 930, in _init_instance
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup self._set_instance_error_state(context, instance)
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 653, in _set_instance_error_state
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup vm_state=vm_states.ERROR)
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 645, in _instance_update
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup **kwargs)
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/nova/conductor/api.py", line 364, in instance_update
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup updates, 'conductor')
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/nova/conductor/rpcapi.py", line 161, in instance_update
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup service=service)
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/oslo/messaging/rpc/client.py", line 150, in call
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup wait_for_reply=True, timeout=timeout)
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/oslo/messaging/transport.py", line 90, in _send
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup timeout=timeout)
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/oslo/messaging/_drivers/amqpdriver.py", line 412, in send
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup return self._send(target, ctxt, message, wait_for_reply, timeout)
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/oslo/messaging/_drivers/amqpdriver.py", line 405, in _send
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup raise result
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup InvalidUUID_Remote: <nova.objects.instance.Instance object at 0x7fb928cd1ed0>
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup Traceback (most recent call last):
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/oslo/messaging/rpc/server.py", line 139, in inner
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup return func(*args, **kwargs)
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/nova/conductor/manager.py", line 130, in instance_update
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup context, instance_uuid, updates)
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/nova/db/api.py", line 742, in instance_update_and_get_original
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup columns_to_join=columns_to_join)
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 164, in wrapper
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup return f(*args, **kwargs)
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 2216, in instance_update_and_get_original
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup columns_to_join=columns_to_join)
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 202, in wrapped
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup return f(*args, **kwargs)
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/api.py", line 2250, in _instance_update
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup raise exception.InvalidUUID(instance_uuid)
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup InvalidUUID: <nova.objects.instance.Instance object at 0x7fb928cd1ed0>
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup
2015-04-28 22:25:05.347 10017 TRACE nova.openstack.common.threadgroup

[Francois Deppierraz (francois-ctrlaltdel)]

This bug comes from commit https://git.openstack.org/cgit/openstack/nova/commit/?id=e9cf07b96f57fed0d9f46bd8f24aac491b6cb976 which was backported without commit https://git.openstack.org/cgit/openstack/nova/commit/?id=6b06e45dca465ae3f457b70c1126a8aadd5ccbbc

The function _set_instance_error_state is still expecting a string with the instance uuid as argument instead of an instance object.

Here's a working quick fix:

$ diff -u /usr/lib/python2.7/dist-packages/nova/compute/manager.py.orig /usr/lib/python2.7/dist-packages/nova/compute/manager.py
--- /usr/lib/python2.7/dist-packages/nova/compute/manager.py.orig 2015-04-28 18:49:31.351141001 +0200
+++ /usr/lib/python2.7/dist-packages/nova/compute/manager.py 2015-04-28 22:38:37.548346111 +0200
@@ -927,7 +927,7 @@
         except exception.VirtualInterfacePlugException:
             # we don't want an exception to block the init_host
             LOG.exception(_("Vifs plug failed"), instance=instance)
- self._set_instance_error_state(context, instance)
+ self._set_instance_error_state(context, instance['uuid'])
             return

         if instance.task_state == task_states.RESIZE_MIGRATING:

[jichenjc (jichenjc)]

will try to backport the code to icehouse

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/icehouse
Review: https://review.openstack.org/178603

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/178603
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=378a8d4aeb87cc037127ccab49bcced71e93c88e
Submitter: Jenkins
Branch: stable/icehouse

commit 378a8d4aeb87cc037127ccab49bcced71e93c88e
Author: jichenjc <email address hidden>
Date: Wed Apr 15 20:15:29 2015 +0800

    Use instance.uuid instead of instance

    commit e9cf07b96f57fed0d9f46bd8f24aac491b6cb976
    was ported to Icehouse but the commit
    6b06e45dca465ae3f457b70c1126a8aadd5ccbbc
    was not ported to Icehouse,
    The function _set_instance_error_state is still expecting
    a string with the instance uuid as argument
    instead of an instance object.

    So this patch partially changed the cherry-picked
    commit e9cf07b96f57fed0d9f46bd8f24aac491b6cb976

    Change-Id: I3bdd32d29d37ba375eb5af52758b93d08f387663
    Closes-Bug: #1449742

[jichenjc (jichenjc)]

Mark this fixed due to patch merged

[James Page (james-page)]

Marking Fix Released and 14.04 now has 2015.1.5.