run-intances gets "Failed to Spawn" status

Asked by Graham Hemingway

I pulled the update from last night. As always, here is my setup: http://imgur.com/7ADzf

I run euca-run-instances and the instance quickly goes to "failed to spawn". Here is the output from the machine with nova-compute on it (openstack03):

2011-04-29 09:07:45,707 INFO nova.virt.libvirt_conn [-] Compute_service record updated for openstack03
2011-04-29 09:07:45,715 DEBUG nova.rpc [-] Initing the Adapter Consumer for compute from (pid=1838) __init__ /usr/lib/pymodules/python2.6/nova/rpc.py:157
2011-04-29 09:07:45,763 DEBUG nova.rpc [-] Initing the Adapter Consumer for compute.openstack03 from (pid=1838) __init__ /usr/lib/pymodules/python2.6/nova/rpc.py:157
2011-04-29 09:07:45,802 INFO nova.rpc [-] Created "compute_fanout" fanout exchange with "compute" routing key
2011-04-29 09:07:45,802 DEBUG nova.rpc [-] Initing the Adapter Consumer for compute from (pid=1838) __init__ /usr/lib/pymodules/python2.6/nova/rpc.py:157
2011-04-29 09:11:05,725 DEBUG nova.rpc [-] received {'_context_request_id': 'F33W3S2G9M04A0LXKL51', '_context_read_deleted': False, 'args': {'instance_id': 20, 'injected_files': None, 'availability_zone': None}, '_context_is_admin': True, '_context_timestamp': '2011-04-29T14:11:04Z', '_context_user': 'heminggs', 'method': 'run_instance', '_context_project': 'vhf-sandbox', '_context_remote_address': '192.168.50.1'} from (pid=1838) _receive /usr/lib/pymodules/python2.6/nova/rpc.py:177
2011-04-29 09:11:05,726 DEBUG nova.rpc [-] unpacked context: {'timestamp': '2011-04-29T14:11:04Z', 'remote_address': '192.168.50.1', 'project': 'vhf-sandbox', 'is_admin': True, 'user': 'heminggs', 'request_id': 'F33W3S2G9M04A0LXKL51', 'read_deleted': False} from (pid=1838) _unpack_context /usr/lib/pymodules/python2.6/nova/rpc.py:350
2011-04-29 09:11:05,802 AUDIT nova.compute.manager [F33W3S2G9M04A0LXKL51 heminggs vhf-sandbox] instance 20: starting...
2011-04-29 09:11:05,959 DEBUG nova.rpc [-] Making asynchronous call on network.openstack01 ... from (pid=1838) call /usr/lib/pymodules/python2.6/nova/rpc.py:370
2011-04-29 09:11:05,959 DEBUG nova.rpc [-] MSG_ID is 16232ebb2755481285c2d8cc8ef5ea3e from (pid=1838) call /usr/lib/pymodules/python2.6/nova/rpc.py:373
2011-04-29 09:11:06,448 DEBUG nova.utils [-] Attempting to grab semaphore "ensure_bridge" for method "ensure_bridge"... from (pid=1838) inner /usr/lib/pymodules/python2.6/nova/utils.py:591
2011-04-29 09:11:06,448 DEBUG nova.utils [-] Attempting to grab file lock "ensure_bridge" for method "ensure_bridge"... from (pid=1838) inner /usr/lib/pymodules/python2.6/nova/utils.py:596
2011-04-29 09:11:06,449 DEBUG nova.utils [-] Running cmd (subprocess): ip link show dev br100 from (pid=1838) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-29 09:11:06,454 DEBUG nova.utils [-] Running cmd (subprocess): sudo route -n from (pid=1838) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-29 09:11:06,462 DEBUG nova.utils [-] Running cmd (subprocess): sudo ip addr show dev eth2 scope global from (pid=1838) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-29 09:11:06,471 DEBUG nova.utils [-] Running cmd (subprocess): sudo brctl addif br100 eth2 from (pid=1838) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-29 09:11:06,478 DEBUG nova.utils [-] Result was 1 from (pid=1838) execute /usr/lib/pymodules/python2.6/nova/utils.py:157
2011-04-29 09:11:06,555 DEBUG nova.virt.libvirt_conn [-] instance instance-00000014: starting toXML method from (pid=1838) to_xml /usr/lib/pymodules/python2.6/nova/virt/libvirt_conn.py:1034
2011-04-29 09:11:06,710 DEBUG nova.virt.libvirt_conn [-] instance instance-00000014: finished toXML method from (pid=1838) to_xml /usr/lib/pymodules/python2.6/nova/virt/libvirt_conn.py:1037
2011-04-29 09:11:06,728 INFO nova [-] called setup_basic_filtering in nwfilter
2011-04-29 09:11:06,728 INFO nova [-] ensuring static filters
2011-04-29 09:11:06,799 ERROR nova.exception [-] Uncaught exception
(nova.exception): TRACE: Traceback (most recent call last):
(nova.exception): TRACE: File "/usr/lib/pymodules/python2.6/nova/exception.py", line 115, in _wrap
(nova.exception): TRACE: return f(*args, **kw)
(nova.exception): TRACE: File "/usr/lib/pymodules/python2.6/nova/virt/libvirt_conn.py", line 623, in spawn
(nova.exception): TRACE: self.firewall_driver.prepare_instance_filter(instance, network_info)
(nova.exception): TRACE: File "/usr/lib/pymodules/python2.6/nova/virt/libvirt_conn.py", line 2001, in prepare_instance_filter
(nova.exception): TRACE: self.add_filters_for_instance(instance, network_info)
(nova.exception): TRACE: File "/usr/lib/pymodules/python2.6/nova/virt/libvirt_conn.py", line 2032, in add_filters_for_instance
(nova.exception): TRACE: network_info)
(nova.exception): TRACE: File "/usr/lib/pymodules/python2.6/nova/virt/libvirt_conn.py", line 2013, in _filters_for_instance
(nova.exception): TRACE: for ip in mapping['ip6s']]
(nova.exception): TRACE: KeyError: 'ip6s'
(nova.exception): TRACE:
2011-04-29 09:11:06,800 ERROR nova.compute.manager [F33W3S2G9M04A0LXKL51 heminggs vhf-sandbox] Instance '20' failed to spawn. Is virtualization enabled in the BIOS?
(nova.compute.manager): TRACE: Traceback (most recent call last):
(nova.compute.manager): TRACE: File "/usr/lib/pymodules/python2.6/nova/compute/manager.py", line 240, in run_instance
(nova.compute.manager): TRACE: self.driver.spawn(instance_ref)
(nova.compute.manager): TRACE: File "/usr/lib/pymodules/python2.6/nova/exception.py", line 121, in _wrap
(nova.compute.manager): TRACE: raise Error(str(e))
(nova.compute.manager): TRACE: Error: 'ip6s'
(nova.compute.manager): TRACE:

I checked and BIO does have virt enabled. Any thoughts?
Thanks,
   Graham

Question information

Language:
English Edit question
Status:
Solved
For:
OpenStack Compute (nova) Edit question
Assignee:
No assignee Edit question
Solved by:
Graham Hemingway
Solved:
Last query:
Last reply:
Revision history for this message
Graham Hemingway (graham-hemingway) said :
#1

Ok. I think that I figured this out and it will result in a bug. So, in revision 1034 nova/virt/libvirt_conn.py add_filters_for_instance was changed. It used to have a nice check on the use of ipv6:

2015 if FLAGS.use_ipv6:
2016 self.iptables.ipv6['filter'].add_chain(chain_name)
2017 ips_v6 = [ip['ip'] for (_, mapping) in network_info
2018 for ip in mapping['ip6s']]
2019
2020 for ipv6_address in ips_v6:
2021 self.iptables.ipv6['filter'].add_rule('local',
2022 '-d %s -j $%s' %
2023 (ipv6_address,
2024 chain_name))

But now it assumes the use of ipv6:

 2012 ips_v6 = [ip['ip'] for (_n, mapping) in network_info
 2013 for ip in mapping['ip6s']]

And if ipv6 is not enabled then the ip6s flag is not there which results in the error I posted above. Am I right?
So, to get around this I should be able to enable ipv6 with --use_ipv6=true. But now nova-network fails to start with the following error:

2011-04-29 11:18:22,930 DEBUG nova.utils [-] Running cmd (subprocess): sudo ip -f inet6 addr change None dev br100 from (pid=7951) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-29 11:18:22,937 DEBUG nova.utils [-] Result was 1 from (pid=7951) execute /usr/lib/pymodules/python2.6/nova/utils.py:157
2011-04-29 11:18:22,937 CRITICAL nova [-] Unexpected error while running command.
Command: sudo ip -f inet6 addr change None dev br100
Exit code: 1
Stdout: ''
Stderr: 'Error: an inet prefix is expected rather than "None".\n'
(nova): TRACE: Traceback (most recent call last):
(nova): TRACE: File "/usr/bin/nova-network", line 48, in <module>
(nova): TRACE: service.serve()
(nova): TRACE: File "/usr/lib/pymodules/python2.6/nova/service.py", line 283, in serve
(nova): TRACE: x.start()
(nova): TRACE: File "/usr/lib/pymodules/python2.6/nova/service.py", line 80, in start
(nova): TRACE: self.manager.init_host()
(nova): TRACE: File "/usr/lib/pymodules/python2.6/nova/network/manager.py", line 442, in init_host
(nova): TRACE: super(FlatDHCPManager, self).init_host()
(nova): TRACE: File "/usr/lib/pymodules/python2.6/nova/network/manager.py", line 134, in init_host
(nova): TRACE: self._on_set_network_host(ctxt, network['id'])
(nova): TRACE: File "/usr/lib/pymodules/python2.6/nova/network/manager.py", line 474, in _on_set_network_host
(nova): TRACE: network_ref)
(nova): TRACE: File "/usr/lib/pymodules/python2.6/nova/utils.py", line 604, in inner
(nova): TRACE: retval = f(*args, **kwargs)
(nova): TRACE: File "/usr/lib/pymodules/python2.6/nova/network/linux_net.py", line 489, in ensure_bridge
(nova): TRACE: 'dev', bridge)
(nova): TRACE: File "/usr/lib/pymodules/python2.6/nova/network/linux_net.py", line 666, in _execute
(nova): TRACE: return utils.execute(*cmd, **kwargs)
(nova): TRACE: File "/usr/lib/pymodules/python2.6/nova/utils.py", line 165, in execute
(nova): TRACE: cmd=' '.join(cmd))
(nova): TRACE: ProcessExecutionError: Unexpected error while running command.
(nova): TRACE: Command: sudo ip -f inet6 addr change None dev br100
(nova): TRACE: Exit code: 1
(nova): TRACE: Stdout: ''
(nova): TRACE: Stderr: 'Error: an inet prefix is expected rather than "None".\n'
(nova): TRACE:

It looks like "sudo ip -f inet6 addr change None dev br100" pukes. I am not an ip expert by a long shot, but I don't even see an "ip addr change command" described in the man pages.

I hope I am missing something here, but it seems there is a code bug trying not to use ipv6 and a possible code bug trying to use ipv6, so I am dead either way. I am going to open a bug on the missing flag check. Please let me know if I should open one on the second issue.

Cheers,
   Graham

Revision history for this message
amy lee (amylee) said :
#2

I probably have the same problem. I did a fresh install of ubuntu natty. installing everything on just one server so far.

and this is my nova.conf:
--dhcpbridge_flagfile=/etc/nova/nova.conf
--dhcpbridge=/usr/bin/nova-dhcpbridge
--logdir=/var/log/nova
--state_path=/var/lib/nova
--verbose
--s3_host=10.0.3.1
--rabbit_host=10.0.3.1
--cc_host=10.0.3.1
--ec2_url=http://10.0.3.1:8773/services/Cloud
--fixed_range=10.1.42.0/24
--network_size=8
--routing_source_ip=10.0.3.1
--sql_connection=mysql://nova:nova@10.0.3.1/nova
--network_manager=nova.network.manager.FlatManager
---

that's it. nothing special.

Revision history for this message
Kevin Bringard (kbringard) said :
#3

Just wanted to add a me too in there.

From what I can tell, I think Graham is right. If you have IP6 disabled, it probably shouldn't try to make the DB call for ip6s (as it doesn't exist).

The other issue is that if you enable ip6 support, it bypasses the first error, but chokes trying to run the ip addr command, because NULL is returned as the IP6 address from the DB, hence the "Stderr: 'Error: an inet prefix is expected rather than "None".\n'" error (in the command "ip -f inet6 addr change None dev br100", "None" should be a valid IP6 address).

I was able to resolve it by doing the following. Please note that I have not done extensive testing on this yet, so your milage may vary:

in nova/virt/libvirt_conn.py, change

  ips_v6 = [ip['ip'] for (_n, mapping) in network_info
    for ip in mapping['ip6s']]
    ipv6_rules = self._create_filter(ips_v6, chain_name)

  return ipv4_rules, ipv6_rules

To be:

        if FLAGS.use_ipv6:
                ips_v6 = [ip['ip'] for (_n, mapping) in network_info
                        for ip in mapping['ip6s']]

                ipv6_rules = self._create_filter(ips_v6, chain_name)
        else:
                ipv6_rules = 'NULL'

        return ipv4_rules, ipv6_rules

This will not try to do the DB lookup if ip6 is false. It appears however that it needs to return both ipv6_rules and ipv4_rules, so if ipv6 isn't set we just set it's rules to null and return them both.

Hopefully this helps someone else...

Revision history for this message
Kevin Bringard (kbringard) said :
#4

Looks like it's been fixed in the trunk (1050) now, FYI

Revision history for this message
Graham Hemingway (graham-hemingway) said :
#5

Per Kevin's message, yes indeed this has been fixed. For all of the gory details please see:

https://bugs.launchpad.net/nova/+bug/773412

Cheers,
   Graham

Revision history for this message
amy lee (amylee) said :
#6

I thought I have the trunk in my ubuntu sources:
deb http://ppa.launchpad.net/nova-core/release/ubuntu natty main
deb-src http://ppa.launchpad.net/nova-core/release/ubuntu natty main
deb http://ppa.launchpad.net/nova-core/trunk/ubuntu natty main
deb-src http://ppa.launchpad.net/nova-core/trunk/ubuntu natty main

but apt-get update and upgrade don't reveal any changes in any of the nova packages. When will the fix be available there or how to I fix it manually?

Revision history for this message
Shweta P (shweta-ap05) said :
#7

I also face the same problem, while VM provision

I tried to upgrade as well using apt-get update and upgrade but my nova package has a verison of 1034. It does not get updated to the latest version. Why is that so

I have the
deb http://ppa.launchpad.net/nova-core/trunk/ubuntu natty main
deb-src http://ppa.launchpad.net/nova-core/trunk/ubuntu natty main

links listed in /etc/apt/source.list