spawning of instance failed during network setup: error in method hydrate in nova/network/model.py

[Christian Berendt]

using the latest snapshots from jenkins i receive the following traceback (from nova-compute) when i try to start a new instance. not sure what's wrong at the moment. using xen with libvirt (if this matters).

2012-02-25 14:45:50 ERROR nova.compute.manager [-] [instance: 0be67df3-12b4-432f-8555-961a746b0ae0] Instance failed network setup
(nova.compute.manager): TRACE: Traceback (most recent call last):
(nova.compute.manager): TRACE: File "/usr/lib64/python2.6/site-packages/nova/compute/manager.py", line 560, in _allocate_network
(nova.compute.manager): TRACE: requested_networks=requested_networks)
(nova.compute.manager): TRACE: File "/usr/lib64/python2.6/site-packages/nova/network/api.py", line 172, in allocate_for_instance
(nova.compute.manager): TRACE: return network_model.NetworkInfo.hydrate(nw_info)
(nova.compute.manager): TRACE: File "/usr/lib64/python2.6/site-packages/nova/network/model.py", line 262, in hydrate
(nova.compute.manager): TRACE: return NetworkInfo([VIF.hydrate(vif) for vif in network_info])
(nova.compute.manager): TRACE: File "/usr/lib64/python2.6/site-packages/nova/network/model.py", line 240, in hydrate
(nova.compute.manager): TRACE: vif = VIF(**vif)
(nova.compute.manager): TRACE: TypeError: __init__() keywords must be strings
(nova.compute.manager): TRACE:
2012-02-25 14:45:50 ERROR nova.rpc.common [-] Exception during message handling
(nova.rpc.common): TRACE: Traceback (most recent call last):
(nova.rpc.common): TRACE: File "/usr/lib64/python2.6/site-packages/nova/rpc/amqp.py", line 250, in _process_data
(nova.rpc.common): TRACE: rval = node_func(context=ctxt, **node_args)
(nova.rpc.common): TRACE: File "/usr/lib64/python2.6/site-packages/nova/exception.py", line 112, in wrapped
(nova.rpc.common): TRACE: return f(*args, **kw)
(nova.rpc.common): TRACE: File "/usr/lib64/python2.6/site-packages/nova/compute/manager.py", line 180, in decorated_function
(nova.rpc.common): TRACE: sys.exc_info())
(nova.rpc.common): TRACE: File "/usr/lib64/python2.6/contextlib.py", line 23, in __exit__
(nova.rpc.common): TRACE: self.gen.next()
(nova.rpc.common): TRACE: File "/usr/lib64/python2.6/site-packages/nova/compute/manager.py", line 174, in decorated_function
(nova.rpc.common): TRACE: return function(self, context, instance_uuid, *args, **kwargs)
(nova.rpc.common): TRACE: File "/usr/lib64/python2.6/site-packages/nova/compute/manager.py", line 649, in run_instance
(nova.rpc.common): TRACE: self._run_instance(context, instance_uuid, **kwargs)
(nova.rpc.common): TRACE: File "/usr/lib64/python2.6/site-packages/nova/compute/manager.py", line 452, in _run_instance
(nova.rpc.common): TRACE: self._set_instance_error_state(context, instance_uuid)
(nova.rpc.common): TRACE: File "/usr/lib64/python2.6/contextlib.py", line 23, in __exit__
(nova.rpc.common): TRACE: self.gen.next()
(nova.rpc.common): TRACE: File "/usr/lib64/python2.6/site-packages/nova/compute/manager.py", line 425, in _run_instance
(nova.rpc.common): TRACE: requested_networks)
(nova.rpc.common): TRACE: File "/usr/lib64/python2.6/site-packages/nova/compute/manager.py", line 560, in _allocate_network
(nova.rpc.common): TRACE: requested_networks=requested_networks)
(nova.rpc.common): TRACE: File "/usr/lib64/python2.6/site-packages/nova/network/api.py", line 172, in allocate_for_instance
(nova.rpc.common): TRACE: return network_model.NetworkInfo.hydrate(nw_info)
(nova.rpc.common): TRACE: File "/usr/lib64/python2.6/site-packages/nova/network/model.py", line 262, in hydrate
(nova.rpc.common): TRACE: return NetworkInfo([VIF.hydrate(vif) for vif in network_info])
(nova.rpc.common): TRACE: File "/usr/lib64/python2.6/site-packages/nova/network/model.py", line 240, in hydrate
(nova.rpc.common): TRACE: vif = VIF(**vif)
(nova.rpc.common): TRACE: TypeError: __init__() keywords must be strings
(nova.rpc.common): TRACE:

nova-network looks good, the ip address got assigned:

2012-02-25 14:50:40 DEBUG nova.network.manager [req-73f13147-514b-4950-8d23-62b52da22038 berendt bb9beb5446db45b2a1e09dc6fef154df] floating IP allocation for instance |14| from (pid=4897) allocate_for_instance /usr/lib64/python2.6/site-packages/nova/network/manager.py:289
2012-02-25 14:50:40 DEBUG nova.network.manager [req-73f13147-514b-4950-8d23-62b52da22038 berendt bb9beb5446db45b2a1e09dc6fef154df] network allocations for instance |14| from (pid=4897) allocate_for_instance /usr/lib64/python2.6/site-packages/nova/network/manager.py:872
2012-02-25 14:50:40 DEBUG nova.network.manager [req-73f13147-514b-4950-8d23-62b52da22038 berendt bb9beb5446db45b2a1e09dc6fef154df] networks retrieved for instance |14|: |[<nova.db.sqlalchemy.models.Network object at 0x2e5d990>]| from (pid=4897) allocate_for_instance /usr/lib64/python2.6/site-packages/nova/network/manager.py:878

i receive an ip address for the new instance in nova-br0.conf:

02:16:3e:39:13:e4,testing009.novalocal,10.0.0.2

nova.conf: (br0 manually created on top of interface eth0)

--verbose
--network_manager=nova.network.manager.FlatDHCPManager
--dhcpbridge_flagfile=/etc/nova/nova.conf
--dhcpbridge=/usr/bin/nova-dhcpbridge
--force_dhcp_release
--public_interface=br0
--flat_network_bridge=br0
--sql_connection=mysql://nova:testing@192.168.23.66/nova
--libvirt_type=xen
--instance_name_template=instance-%08x
--api_paste_config=/etc/nova/api-paste.ini
--image_service=nova.image.glance.GlanceImageService
--rabbit_host=192.168.23.66
--rabbit_password=testing
--glance_api_servers=192.168.23.66:9292
--connection_type=libvirt
--firewall_driver=nova.virt.libvirt.firewall.IptablesFirewallDriver
--instances_path=/var/lib/nova/instances
--state_path=/var/lib/nova
--vlan_interface=br0
--my_ip=192.168.23.67

call for my network:

nova-manage network create --label=public --fixed_range_v4=10.0.0.0/24 --num_networks=1 --network_size=256 --bridge=br0 --bridge_interface=eth0 --dns1=4.4.4.4 --dns2=8.8.8.8

br0 receives an ip address:

4: br0: <BROADCAST,MULTICAST,PROMISC,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN
    link/ether 00:14:0b:44:20:91 brd ff:ff:ff:ff:ff:ff
    inet 10.0.0.1/24 brd 10.0.0.255 scope global br0
    inet 192.168.23.67/24 brd 192.168.23.255 scope global br0
    inet6 fe80::214:bff:fe44:2091/64 scope link
       valid_lft forever preferred_lft forever

dnsmasq is running:

 4406 ? S 0:00 dnsmasq --strict-order --bind-interfaces --conf-file= --domain=novalocal --pid-file=/var/lib/nova/networks/nova-br0.pid --listen-address=10.0.0.1 --except-interface=lo --dhcp-range=10.0.0.2,static,120s --dhcp-lease-max=256 --dhcp-hostsfile=/var/lib/nova/networks/nova-br0.conf --dhcp-script=/usr/bin/nova-dhcpbridge --leasefile-ro
 4407 ? S 0:00 dnsmasq --strict-order --bind-interfaces --conf-file= --domain=novalocal --pid-file=/var/lib/nova/networks/nova-br0.pid --listen-address=10.0.0.1 --except-interface=lo --dhcp-range=10.0.0.2,static,120s --dhcp-lease-max=256 --dhcp-hostsfile=/var/lib/nova/networks/nova-br0.conf --dhcp-script=/usr/bin/nova-dhcpbridge --leasefile-ro

[Christian Berendt (berendt)]

tested with tarball nova-2012.1~e4~20120225.12927.tar.gz (git revision 2172e49e8359a62182f58d94d2a9c465a85d9a95)

[Christian Berendt (berendt)]

Looks like it is a problem with the used python version (python-2.6.0-8.14.1) on SLES11 SP1 (and SLES11 SP2 uses 2.6.0, too).

Starting with Python 2.6.5 it's possible to use unicode strings (u'foobar') as keyword arguments (http://bugs.python.org/issue4978). Before Python 2.6.5 using unicode strings as keyword arguments throw an exception (TypeError: __init__() keywords must be strings).

The network_model.NetworkInfo.hydrate method is called with a variable nw_info which contains a lot of unicode strings. So my suggestion for the moment is that it's a problem with Python < 2.6.5.

I think nothing to fix here. I'll open a service request and ask if SUSE can backport the patch for the Python issue 4978.

You can test it with the following code:

>>> def foobar(**kwargs):
... print "lalala"
...

>>> foobar(**{'blar': '1234'})
lalala
>>> foobar(**{u'blar': '1234'})
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
TypeError: foobar() keywords must be strings

[OpenStack Infra (hudson-openstack)]

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

[Christian Berendt (berendt)]

i think we should not set Python >= 2.6.5 as a minimum requirement for running OpenStack Compute (or at least to run nova-network) if there is at least one enterprise distribution using Python < 2.6.5. i think RHEL5 is also using Python < 2.6.5, not sure about RHEL6.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/4544
Committed: http://github.com/openstack/nova/commit/81a1b0a15ad5b0a656bd56d9f87715a8707f986e
Submitter: Jenkins
Branch: master

commit 81a1b0a15ad5b0a656bd56d9f87715a8707f986e
Author: Christian Berendt <email address hidden>
Date: Sun Feb 26 02:39:08 2012 +0100

    make nova-network usable with Python < 2.6.5

    there is in issue in Python < 2.6.5 with using unicode strings as
    keyword arguemnts. see http://bugs.python.org/issue4978 for details.

    because several not-yet-outdated enterprise distributions are using
    Python < 2.6.5 the unicode strings in the keys of the dictionaries in
    used as keyword arguments nova/network/model.py should be converted.

    fixes bug 940941

    Change-Id: Ib1d9955677e228fce6cc8e17fddc780d1a839d84