OpenStack Compute (nova)

Instance creation results in ERROR status

Bug #1103745 reported by Miguel Lavalle
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
New
Undecided
Miguel Lavalle

Bug Description

I am working in DevStack deployed on a KVM VM. I am using Quantum for networking. When creating an instance with:

nova boot --image $I --flavor 1 --nic net-id=$N1 vm1

the new instance is left in the following state:

+---------------------------------------------------------+---------+-----------+--------------+
| ID | Name | Status | Networks |
+---------------------------------------------------------+---------+-----------+--------------+
| 1dfeef1f-f0a3-4133-9bf6-e1debda2382f | vm1 | ERROR | |
+---------------------------------------------------------+---------+-----------+--------------+

Reviewing the log file from nova manager, I found the following lines:

2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] Traceback (most recent call last):
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] File "/opt/stack/nova/nova/compute/manager.py", line
965, in _spawn
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] block_device_info)
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] File "/opt/stack/nova/nova/virt/libvirt/driver.py", l
ine 1059, in spawn
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] block_device_info)
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] File "/opt/stack/nova/nova/virt/libvirt/driver.py", l
ine 1978, in _create_domain_and_network
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] self.firewall_driver.setup_basic_filtering(instance
, network_info)
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] File "/opt/stack/nova/nova/virt/libvirt/firewall.py",
 line 234, in setup_basic_filtering
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] self.refresh_provider_fw_rules()
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] File "/opt/stack/nova/nova/virt/firewall.py", line 45
7, in refresh_provider_fw_rules
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] self.iptables.apply()
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] File "/opt/stack/nova/nova/network/linux_net.py", lin
e 358, in apply
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] self._apply()
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] File "/opt/stack/nova/nova/openstack/common/lockutils
.py", line 221, in inner
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] retval = f(*args, **kwargs)
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] File "/opt/stack/nova/nova/network/linux_net.py", lin
e 388, in _apply
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] attempts=5)
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] File "/opt/stack/nova/nova/network/linux_net.py", lin
e 1044, in _execute
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] return utils.execute(*cmd, **kwargs)
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] File "/opt/stack/nova/nova/utils.py", line 232, in ex
ecute
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] cmd=' '.join(cmd))
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] ProcessExecutionError: Unexpected error while running c
ommand.
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] Command: sudo nova-rootwrap /etc/nova/rootwrap.conf ipt
ables-restore -c
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] Exit code: 1
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] Stdout: ''
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f] Stderr: 'iptables-restore: line 1 failed\n'
2013-01-23 13:46:16.357 2616 TRACE nova.compute.manager [instance: 1dfeef1f-f0a3
-4133-9bf6-e1debda2382f]

The ProcessExecutionError in the trace above is caused by class nova.network.linux_net.IptablesManager. Specifically, the error is caused by function _apply when attempting to execute command "iptables-restore -c".

Looking at the git history of module nova.network.linux_net, I found that function _apply in class IptablesManager was recently patched, as shown in https://github.com/openstack/nova/commit/f0539d49271df76222740f76d1b51188ee51a1c3. The intent of this patch was: "Reduce number of iptable-save restore loops. Instead of running iptables-save and iptables-restore per table,
run iptables save and restore on all tables at once.". This patch introduced a bug, though, and function _apply is not resetting correctly the ip_tables anymore. It tries to find all the tables with command "iptables-save -c" and then attempts to reset them with command "iptables-restore -c". The tables found with "iptables-save -c" are:

# Generated by iptables-save v1.4.12 on Wed Jan 23 13:46:12 2013
*nat
:PREROUTING ACCEPT [4:308]
:INPUT ACCEPT [4:308]
:OUTPUT ACCEPT [1371:86222]
:POSTROUTING ACCEPT [1371:86222]
COMMIT
# Completed on Wed Jan 23 13:46:12 2013
# Generated by iptables-save v1.4.12 on Wed Jan 23 13:46:12 2013
*filter
:INPUT ACCEPT [238405:293260324]
:FORWARD ACCEPT [0:0]
:OUTPUT ACCEPT [179580:87206783]
[0:0] -A INPUT -p gre -j ACCEPT
COMMIT

The workaround that I tested is going back to the previous version of nova.network.linux_net. Running with the previous version, I can create instances correctly. The previous version of function _apply works table by table saving them with command "iptables-save -c -t table" and resets them one by one. The tables found with "iptables-save -c -t table" are shown at the end of this message. Clearly, a lot of stuff is being missed by the new version of nova.network.linux_net. I will investigate further and propose a solution

# Generated by iptables-save v1.4.12 on Wed Jan 23 14:15:45 2013
*filter
:INPUT ACCEPT [255912:298029044]
:FORWARD ACCEPT [0:0]
:OUTPUT ACCEPT [195853:92117797]
[0:0] -A INPUT -p gre -j ACCEPT
COMMIT
# Completed on Wed Jan 23 14:15:45 2013
# Generated by iptables-save v1.4.12 on Wed Jan 23 14:15:46 2013
*mangle
:PREROUTING ACCEPT [0:0]
:INPUT ACCEPT [0:0]
:FORWARD ACCEPT [0:0]
:OUTPUT ACCEPT [0:0]
:POSTROUTING ACCEPT [0:0]
COMMIT
# Completed on Wed Jan 23 14:15:46 2013
# Generated by iptables-save v1.4.12 on Wed Jan 23 14:15:46 2013
*nat
:PREROUTING ACCEPT [4:308]
:INPUT ACCEPT [4:308]
:OUTPUT ACCEPT [1774:110778]
:POSTROUTING ACCEPT [1774:110778]
COMMIT
# Completed on Wed Jan 23 14:15:46 2013
# Generated by iptables-save v1.4.12 on Wed Jan 23 14:15:46 2013
*filter
:INPUT ACCEPT [256027:298050719]
:FORWARD ACCEPT [0:0]
:OUTPUT ACCEPT [195967:92139388]
:nova-api-FORWARD - [0:0]
:nova-api-INPUT - [0:0]
:nova-api-OUTPUT - [0:0]
:nova-api-local - [0:0]
:nova-compute-FORWARD - [0:0]
:nova-compute-INPUT - [0:0]
:nova-compute-OUTPUT - [0:0]
:nova-compute-local - [0:0]
:nova-compute-provider - [0:0]
:nova-compute-sg-fallback - [0:0]
:nova-filter-top - [0:0]
[93:11090] -A INPUT -j nova-api-INPUT
[115:21675] -A INPUT -j nova-compute-INPUT
[0:0] -A INPUT -p gre -j ACCEPT
[0:0] -A FORWARD -j nova-filter-top
[0:0] -A FORWARD -j nova-api-FORWARD
[0:0] -A FORWARD -j nova-compute-FORWARD
[114:21591] -A OUTPUT -j nova-filter-top
[92:11038] -A OUTPUT -j nova-api-OUTPUT
[114:21591] -A OUTPUT -j nova-compute-OUTPUT
[0:0] -A nova-api-INPUT -d 172.16.0.2/32 -p tcp -m tcp --dport 8775 -j ACCEPT
[0:0] -A nova-compute-sg-fallback -j DROP
[92:11038] -A nova-filter-top -j nova-api-local
[114:21591] -A nova-filter-top -j nova-compute-local
COMMIT
# Completed on Wed Jan 23 14:15:46 2013
# Generated by iptables-save v1.4.12 on Wed Jan 23 14:15:47 2013
*mangle
:PREROUTING ACCEPT [114:21581]
:INPUT ACCEPT [114:21581]
:FORWARD ACCEPT [0:0]
:OUTPUT ACCEPT [113:21529]
:POSTROUTING ACCEPT [113:21529]
:nova-api-POSTROUTING - [0:0]
:nova-compute-POSTROUTING - [0:0]
[92:11038] -A POSTROUTING -j nova-api-POSTROUTING
[113:21529] -A POSTROUTING -j nova-compute-POSTROUTING
COMMIT
# Completed on Wed Jan 23 14:15:47 2013
# Generated by iptables-save v1.4.12 on Wed Jan 23 14:15:47 2013
*nat
:PREROUTING ACCEPT [4:308]
:INPUT ACCEPT [4:308]
:OUTPUT ACCEPT [1774:110778]
:POSTROUTING ACCEPT [1774:110778]
:nova-api-OUTPUT - [0:0]
:nova-api-POSTROUTING - [0:0]
:nova-api-PREROUTING - [0:0]
:nova-api-float-snat - [0:0]
:nova-api-snat - [0:0]
:nova-compute-OUTPUT - [0:0]
:nova-compute-POSTROUTING - [0:0]
:nova-compute-PREROUTING - [0:0]
:nova-compute-float-snat - [0:0]
:nova-compute-snat - [0:0]
:nova-postrouting-bottom - [0:0]
[0:0] -A PREROUTING -j nova-api-PREROUTING
[0:0] -A PREROUTING -j nova-compute-PREROUTING
[0:0] -A OUTPUT -j nova-api-OUTPUT
[0:0] -A OUTPUT -j nova-compute-OUTPUT
[0:0] -A POSTROUTING -j nova-api-POSTROUTING
[0:0] -A POSTROUTING -j nova-compute-POSTROUTING
[0:0] -A POSTROUTING -j nova-postrouting-bottom
[0:0] -A nova-api-snat -j nova-api-float-snat
[0:0] -A nova-compute-snat -j nova-compute-float-snat
[0:0] -A nova-postrouting-bottom -j nova-api-snat
[0:0] -A nova-postrouting-bottom -j nova-compute-snat
COMMIT
# Completed on Wed Jan 23 14:15:47 2013
# Generated by iptables-save v1.4.12 on Wed Jan 23 14:15:47 2013
*filter
:INPUT ACCEPT [256027:298050719]
:FORWARD ACCEPT [0:0]
:OUTPUT ACCEPT [195967:92139388]
:nova-api-FORWARD - [0:0]
:nova-api-INPUT - [0:0]
:nova-api-OUTPUT - [0:0]
:nova-api-local - [0:0]
:nova-compute-FORWARD - [0:0]
:nova-compute-INPUT - [0:0]
:nova-compute-OUTPUT - [0:0]
:nova-compute-inst-4 - [0:0]
:nova-compute-local - [0:0]
:nova-compute-provider - [0:0]
:nova-compute-sg-fallback - [0:0]
 :nova-filter-top - [0:0]
[0:0] -A INPUT -j nova-compute-INPUT
[93:11090] -A INPUT -j nova-api-INPUT
[0:0] -A INPUT -p gre -j ACCEPT
[0:0] -A FORWARD -j nova-filter-top
[0:0] -A FORWARD -j nova-compute-FORWARD
[0:0] -A FORWARD -j nova-api-FORWARD
[114:21591] -A OUTPUT -j nova-filter-top
[0:0] -A OUTPUT -j nova-compute-OUTPUT
[92:11038] -A OUTPUT -j nova-api-OUTPUT
[0:0] -A nova-api-INPUT -d 172.16.0.2/32 -p tcp -m tcp --dport 8775 -j ACCEPT
[0:0] -A nova-compute-inst-4 -m state --state INVALID -j DROP
[0:0] -A nova-compute-inst-4 -m state --state RELATED,ESTABLISHED -j ACCEPT
[0:0] -A nova-compute-inst-4 -j nova-compute-provider
[0:0] -A nova-compute-inst-4 -s 10.0.0.2/32 -p udp -m udp --sport 67 --dport 68
-j ACCEPT
[0:0] -A nova-compute-inst-4 -s 10.0.0.0/24 -j ACCEPT
[0:0] -A nova-compute-inst-4 -j nova-compute-sg-fallback
[0:0] -A nova-compute-local -d 10.0.0.3/32 -j nova-compute-inst-4
[0:0] -A nova-compute-sg-fallback -j DROP
[0:0] -A nova-filter-top -j nova-compute-local
[92:11038] -A nova-filter-top -j nova-api-local
COMMIT
# Completed on Wed Jan 23 14:15:47 2013
# Generated by iptables-save v1.4.12 on Wed Jan 23 14:15:47 2013
*mangle
:PREROUTING ACCEPT [116:21733]
:INPUT ACCEPT [116:21733]
:FORWARD ACCEPT [0:0]
:OUTPUT ACCEPT [114:21629]
:POSTROUTING ACCEPT [114:21629]
:nova-api-POSTROUTING - [0:0]
:nova-compute-POSTROUTING - [0:0]
[1:100] -A POSTROUTING -j nova-compute-POSTROUTING
[93:11138] -A POSTROUTING -j nova-api-POSTROUTING
COMMIT
# Completed on Wed Jan 23 14:15:47 2013
# Generated by iptables-save v1.4.12 on Wed Jan 23 14:15:47 2013
*nat
:PREROUTING ACCEPT [4:308]
:INPUT ACCEPT [4:308]
:OUTPUT ACCEPT [1774:110778]
:POSTROUTING ACCEPT [1774:110778]
:nova-api-OUTPUT - [0:0]
:nova-api-POSTROUTING - [0:0]
:nova-api-PREROUTING - [0:0]
:nova-api-float-snat - [0:0]
:nova-api-snat - [0:0]
:nova-compute-OUTPUT - [0:0]
:nova-compute-POSTROUTING - [0:0]
:nova-compute-PREROUTING - [0:0]
:nova-compute-float-snat - [0:0]
:nova-compute-snat - [0:0]
:nova-postrouting-bottom - [0:0]
[0:0] -A PREROUTING -j nova-compute-PREROUTING
[0:0] -A PREROUTING -j nova-api-PREROUTING
[0:0] -A OUTPUT -j nova-compute-OUTPUT
[0:0] -A OUTPUT -j nova-api-OUTPUT
[0:0] -A POSTROUTING -j nova-compute-POSTROUTING
[0:0] -A POSTROUTING -j nova-api-POSTROUTING
[0:0] -A POSTROUTING -j nova-postrouting-bottom
[0:0] -A nova-api-snat -j nova-api-float-snat
[0:0] -A nova-compute-snat -j nova-compute-float-snat
[0:0] -A nova-postrouting-bottom -j nova-compute-snat
[0:0] -A nova-postrouting-bottom -j nova-api-snat
COMMIT
# Completed on Wed Jan 23 14:15:47 2013

Miguel Lavalle (minsel)
Changed in nova:
assignee: nobody → Miguel Lavalle (minsel)
Revision history for this message
Miguel Lavalle (minsel) wrote :

This bug was also reported here:

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

Revision history for this message
aeva black (tenbrae) wrote :

Also reported here: https://bugs.launchpad.net/nova/+bug/1103436

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.