nova-network fails using FlatDHCPManager in Grizzly

[Phil Hopkins]

Running nova-network on Fedora 17, Grizzly (openstack-nova-2013.1-0.10.g3.fc19.noarch) setting network_manager=nova.network.manager.FlatManager, nova-network starts and runs properly. However when changing to network_manager=nova.network.manager.FlatDHCPManager and restarting nova-network, it fails with the following in the file /var/log/nova/network.log:

2013-04-02 07:29:12.139 1571 AUDIT nova.service [-] Starting network node (version 2013.1-0.10.g3.fc19)
2013-04-02 07:29:12.140 1571 DEBUG nova.network.l3 [-] Initializing linux_net L3 driver initialize /usr/lib/python2.7/site-packages/nova/network/l3.py:81
2013-04-02 07:29:12.140 1571 DEBUG nova.openstack.common.lockutils [-] Got semaphore "iptables" for method "_apply"... inner /usr/lib/python2.7/site-packages/nova/openstack/co
mmon/lockutils.py:185
2013-04-02 07:29:12.140 1571 DEBUG nova.openstack.common.lockutils [-] Attempting to grab file lock "iptables" for method "_apply"... inner /usr/lib/python2.7/site-packages/no
va/openstack/common/lockutils.py:196
2013-04-02 07:29:12.214 1571 CRITICAL nova [-] [Errno 13] Permission denied: '/var/lock/nova'
2013-04-02 07:29:12.214 1571 TRACE nova Traceback (most recent call last):
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/bin/nova-network", line 54, in <module>
2013-04-02 07:29:12.214 1571 TRACE nova service.wait()
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib/python2.7/site-packages/nova/service.py", line 689, in wait
2013-04-02 07:29:12.214 1571 TRACE nova _launcher.wait()
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib/python2.7/site-packages/nova/service.py", line 209, in wait
2013-04-02 07:29:12.214 1571 TRACE nova super(ServiceLauncher, self).wait()
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib/python2.7/site-packages/nova/service.py", line 179, in wait
2013-04-02 07:29:12.214 1571 TRACE nova service.wait()
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib/python2.7/site-packages/eventlet/greenthread.py", line 166, in wait
2013-04-02 07:29:12.214 1571 TRACE nova return self._exit_event.wait()
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib/python2.7/site-packages/eventlet/event.py", line 116, in wait
2013-04-02 07:29:12.214 1571 TRACE nova return hubs.get_hub().switch()
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 177, in switch
2013-04-02 07:29:12.214 1571 TRACE nova return self.greenlet.switch()
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib/python2.7/site-packages/eventlet/greenthread.py", line 192, in main
2013-04-02 07:29:12.214 1571 TRACE nova result = function(*args, **kwargs)
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib/python2.7/site-packages/nova/service.py", line 147, in run_server
2013-04-02 07:29:12.214 1571 TRACE nova server.start()
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib/python2.7/site-packages/nova/service.py", line 429, in start
2013-04-02 07:29:12.214 1571 TRACE nova self.manager.init_host()
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib/python2.7/site-packages/nova/network/manager.py", line 1562, in init_host
2013-04-02 07:29:12.214 1571 TRACE nova self.l3driver.initialize()
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib/python2.7/site-packages/nova/network/l3.py", line 82, in initialize
2013-04-02 07:29:12.214 1571 TRACE nova linux_net.init_host()
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib/python2.7/site-packages/nova/network/linux_net.py", line 633, in init_host
2013-04-02 07:29:12.214 1571 TRACE nova add_snat_rule(ip_range)
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib/python2.7/site-packages/nova/network/linux_net.py", line 623, in add_snat_rule
2013-04-02 07:29:12.214 1571 TRACE nova iptables_manager.apply()
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib/python2.7/site-packages/nova/network/linux_net.py", line 383, in apply
2013-04-02 07:29:12.214 1571 TRACE nova self._apply()
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py", line 210, in inner
2013-04-02 07:29:12.214 1571 TRACE nova fileutils.ensure_tree(local_lock_path)
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib/python2.7/site-packages/nova/openstack/common/fileutils.py", line 29, in ensure_tree
2013-04-02 07:29:12.214 1571 TRACE nova os.makedirs(path)
2013-04-02 07:29:12.214 1571 TRACE nova File "/usr/lib64/python2.7/os.py", line 157, in makedirs
2013-04-02 07:29:12.214 1571 TRACE nova mkdir(name, mode)
2013-04-02 07:29:12.214 1571 TRACE nova OSError: [Errno 13] Permission denied: '/var/lock/nova'

After creating the directory /var/lock/nova with the ownership of: nova:root

nova-network now fails with the error:

2013-04-02 07:30:37.143 1838 DEBUG nova.service [-] conductor : <oslo.config.cfg.GroupAttr object at 0x25209d0> wait /usr/lib/python2.7/site-packages/nova/service.py:205
2013-04-02 07:30:37.144 1838 AUDIT nova.service [-] Starting network node (version 2013.1-0.10.g3.fc19)
2013-04-02 07:30:37.144 1838 DEBUG nova.network.l3 [-] Initializing linux_net L3 driver initialize /usr/lib/python2.7/site-packages/nova/network/l3.py:81
2013-04-02 07:30:37.145 1838 DEBUG nova.openstack.common.lockutils [-] Got semaphore "iptables" for method "_apply"... inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:185
2013-04-02 07:30:37.145 1838 DEBUG nova.openstack.common.lockutils [-] Attempting to grab file lock "iptables" for method "_apply"... inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:196
2013-04-02 07:30:37.145 1838 DEBUG nova.openstack.common.lockutils [-] Got file lock "iptables" at /var/lock/nova/nova-iptables for method "_apply"... inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:227
2013-04-02 07:30:37.145 1838 DEBUG nova.utils [-] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-save -c execute /usr/lib/python2.7/site-packages/nova/utils.py:212
2013-04-02 07:30:37.190 1838 DEBUG nova.utils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/utils.py:236
2013-04-02 07:30:37.191 1838 DEBUG nova.utils [-] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-restore -c execute /usr/lib/python2.7/site-packages/nova/utils.py:212
2013-04-02 07:30:37.243 1838 DEBUG nova.utils [-] Result was 2 execute /usr/lib/python2.7/site-packages/nova/utils.py:236
2013-04-02 07:30:37.244 1838 DEBUG nova.utils [-] ['sudo', 'nova-rootwrap', '/etc/nova/rootwrap.conf', 'iptables-restore', '-c'] failed. Retrying. execute /usr/lib/python2.7/site-packages/nova/utils.py:249
2013-04-02 07:30:38.026 1838 DEBUG nova.utils [-] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-restore -c execute /usr/lib/python2.7/site-packages/nova/utils.py:212
2013-04-02 07:30:38.085 1838 DEBUG nova.utils [-] Result was 2 execute /usr/lib/python2.7/site-packages/nova/utils.py:236
2013-04-02 07:30:38.086 1838 DEBUG nova.utils [-] ['sudo', 'nova-rootwrap', '/etc/nova/rootwrap.conf', 'iptables-restore', '-c'] failed. Retrying. execute /usr/lib/python2.7/site-packages/nova/utils.py:249
2013-04-02 07:30:38.567 1838 DEBUG nova.utils [-] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-restore -c execute /usr/lib/python2.7/site-packages/nova/utils.py:212
2013-04-02 07:30:38.619 1838 DEBUG nova.utils [-] Result was 2 execute /usr/lib/python2.7/site-packages/nova/utils.py:236
2013-04-02 07:30:38.620 1838 DEBUG nova.utils [-] ['sudo', 'nova-rootwrap', '/etc/nova/rootwrap.conf', 'iptables-restore', '-c'] failed. Retrying. execute /usr/lib/python2.7/site-packages/nova/utils.py:249
2013-04-02 07:30:39.061 1838 DEBUG nova.utils [-] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-restore -c execute /usr/lib/python2.7/site-packages/nova/utils.py:212
2013-04-02 07:30:39.110 1838 DEBUG nova.utils [-] Result was 2 execute /usr/lib/python2.7/site-packages/nova/utils.py:236
2013-04-02 07:30:39.111 1838 DEBUG nova.utils [-] ['sudo', 'nova-rootwrap', '/etc/nova/rootwrap.conf', 'iptables-restore', '-c'] failed. Retrying. execute /usr/lib/python2.7/site-packages/nova/utils.py:249
2013-04-02 07:30:40.323 1838 DEBUG nova.utils [-] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-restore -c execute /usr/lib/python2.7/site-packages/nova/utils.py:212
2013-04-02 07:30:40.379 1838 DEBUG nova.utils [-] Result was 2 execute /usr/lib/python2.7/site-packages/nova/utils.py:236
2013-04-02 07:30:40.380 1838 DEBUG nova.openstack.common.lockutils [-] Released file lock "iptables" at /var/lock/nova/nova-iptables for method "_apply"... inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:234
2013-04-02 07:30:40.400 1838 CRITICAL nova [-] Unexpected error while running command.
Command: sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-restore -c
Exit code: 2
Stdout: ''
Stderr: "Bad argument `SNAT'\nError occurred at line: 36\nTry `iptables-restore -h' or 'iptables-restore --help' for more information.\n"
2013-04-02 07:30:40.400 1838 TRACE nova Traceback (most recent call last):
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/bin/nova-network", line 54, in <module>
2013-04-02 07:30:40.400 1838 TRACE nova service.wait()
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/nova/service.py", line 689, in wait
2013-04-02 07:30:40.400 1838 TRACE nova _launcher.wait()
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/nova/service.py", line 209, in wait
2013-04-02 07:30:40.400 1838 TRACE nova super(ServiceLauncher, self).wait()
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/nova/service.py", line 179, in wait
2013-04-02 07:30:40.400 1838 TRACE nova service.wait()
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/eventlet/greenthread.py", line 166, in wait
2013-04-02 07:30:40.400 1838 TRACE nova return self._exit_event.wait()
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/eventlet/event.py", line 116, in wait
2013-04-02 07:30:40.400 1838 TRACE nova return hubs.get_hub().switch()
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 177, in switch
2013-04-02 07:30:40.400 1838 TRACE nova return self.greenlet.switch()
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/eventlet/greenthread.py", line 192, in main
2013-04-02 07:30:40.400 1838 TRACE nova result = function(*args, **kwargs)
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/nova/service.py", line 147, in run_server
2013-04-02 07:30:40.400 1838 TRACE nova server.start()
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/nova/service.py", line 429, in start
2013-04-02 07:30:40.400 1838 TRACE nova self.manager.init_host()
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/nova/network/manager.py", line 1562, in init_host
2013-04-02 07:30:40.400 1838 TRACE nova self.l3driver.initialize()
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/nova/network/l3.py", line 82, in initialize
2013-04-02 07:30:40.400 1838 TRACE nova linux_net.init_host()
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/nova/network/linux_net.py", line 633, in init_host
2013-04-02 07:30:40.400 1838 TRACE nova add_snat_rule(ip_range)
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/nova/network/linux_net.py", line 623, in add_snat_rule
2013-04-02 07:30:40.400 1838 TRACE nova iptables_manager.apply()
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/nova/network/linux_net.py", line 383, in apply
2013-04-02 07:30:40.400 1838 TRACE nova self._apply()
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py", line 228, in inner
2013-04-02 07:30:40.400 1838 TRACE nova retval = f(*args, **kwargs)
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/nova/network/linux_net.py", line 409, in _apply
2013-04-02 07:30:40.400 1838 TRACE nova attempts=5)
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/nova/network/linux_net.py", line 1126, in _execute
2013-04-02 07:30:40.400 1838 TRACE nova return utils.execute(*cmd, **kwargs)
2013-04-02 07:30:40.400 1838 TRACE nova File "/usr/lib/python2.7/site-packages/nova/utils.py", line 243, in execute
2013-04-02 07:30:40.400 1838 TRACE nova cmd=' '.join(cmd))
2013-04-02 07:30:40.400 1838 TRACE nova ProcessExecutionError: Unexpected error while running command.
2013-04-02 07:30:40.400 1838 TRACE nova Command: sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-restore -c
2013-04-02 07:30:40.400 1838 TRACE nova Exit code: 2
2013-04-02 07:30:40.400 1838 TRACE nova Stdout: ''
2013-04-02 07:30:40.400 1838 TRACE nova Stderr: "Bad argument `SNAT'\nError occurred at line: 36\nTry `iptables-restore -h' or 'iptables-restore --help' for more information.\n"
2013-04-02 07:30:40.400 1838 TRACE nova

SELinux is disabled and /etc/nova/nova.conf:

[DEFAULT]

# LOGS/STATE
#verbose=True
#debug=True
logdir=/var/log/nova
state_path=/var/lib/nova
lock_path=/var/lock/nova
rootwrap_config=/etc/nova/rootwrap.conf

# SCHEDULER
compute_scheduler_driver=nova.scheduler.filter_scheduler.FilterScheduler

# VOLUMES
volume_driver=nova.volume.driver.ISCSIDriver
volume_group=nova-volumes
volume_name_template=volume-%s
iscsi_helper=tgtadm

# DATABASE
sql_connection=mysql://nova:nova@192.168.122.118/nova

# COMPUTE
libvirt_type=kvm
compute_driver=libvirt.LibvirtDriver
instance_name_template=instance-%08x
api_paste_config=/etc/nova/api-paste.ini

# COMPUTE/APIS: if you have separate configs for separate services
# this flag is required for both nova-api and nova-compute
allow_resize_to_same_host=True

# APIS
osapi_compute_extension=nova.api.openstack.compute.contrib.standard_extensions
ec2_dmz_host=192.168.122.118
s3_host=192.168.122.118

[root@controller ~]# nova-manage service list
Binary Host Zone Status State Updated_At
nova-conductor controller internal enabled :-) 2013-04-02 13:05:26
nova-scheduler controller internal enabled :-) 2013-04-02 13:05:26
nova-cert controller internal enabled :-) 2013-04-02 13:05:26
nova-network controller internal enabled XXX 2013-04-02 12:54:12
nova-compute controller nova enabled :-) 2013-04-02 13:05:24

# RABBITMQ
rabbit_host=192.168.122.118
qpid_host=192.168.122.118
#rpc_backend=nova.rpc.impl_qpid
rpc_backend=nova.openstack.common.rpc.impl_qpid

# GLANCE
image_service=nova.image.glance.GlanceImageService
glance_api_servers=192.168.122.118:9292

# NETWORK
dhcpbridge_flagfile=/etc/nova/nova.conf
dhcpbridge=/usr/bin/nova-dhcpbridge
#network_manager=nova.network.manager.FlatDHCPManager
network_manager=nova.network.manager.FlatManager
#force_dhcp_release=True
dhcpbridge_flagfile=/etc/nova/nova.conf
firewall_driver=nova.virt.libvirt.firewall.IptablesFirewallDriver
# Change my_ip to match each host
my_ip=192.168.122.118
public_interface=eth0
vlan_interface=eth0
flat-injected=False
flat_network_bridge=br100
flat_interface=eth1
fixed_range=''

# NOVNC CONSOLE
novncproxy_base_url=http://192.168.122.178:6080/vnc_auto.html
# Change vncserver_proxyclient_address and vncserver_listen to match each compute host
vncserver_proxyclient_address=192.168.122.178
vncserver_listen=192.168.122.178

# AUTHENTICATION
auth_strategy=keystone
[keystone_authtoken]
auth_host = 192.168.122.118
auth_port = 35357
auth_protocol = http
admin_tenant_name = service
admin_user = nova
admin_password = nova
signing_dirname = /tmp/keystone-signing-nova

[Vish Ishaya (vishvananda)]

the non-existence of /var/lock/nova is a packaging problem. Not sure what is going on with the iptables command however. Can you post a dump of your existing iptables rules?

[Phil Hopkins (phil-hopkins-a)]

Here they are:

iptables -L
Chain INPUT (policy ACCEPT)
target prot opt source destination
ACCEPT tcp -- anywhere anywhere
ACCEPT all -- anywhere anywhere state RELATED,ESTABLISHED
ACCEPT icmp -- anywhere anywhere
ACCEPT all -- anywhere anywhere
ACCEPT tcp -- anywhere anywhere state NEW tcp dpt:ssh
REJECT all -- anywhere anywhere reject-with icmp-host-prohibited

Chain FORWARD (policy ACCEPT)
target prot opt source destination
REJECT all -- anywhere anywhere reject-with icmp-host-prohibited

Chain OUTPUT (policy ACCEPT)
target prot opt source destination

If I clear all of the iptables to:
 iptables -L
Chain INPUT (policy ACCEPT)
target prot opt source destination

Chain FORWARD (policy ACCEPT)
target prot opt source destination

Chain OUTPUT (policy ACCEPT)
target prot opt source destination

The same problem occurs.

Phil

[Brent Eagles (beagles)]

Can you post the results of iptables-save? Also, are there any networks actually defined?

[jagan kumar kotipatruni (jagankumar-k)]

Can u post the results of

iptables -t filter -S
sudo iptables -t nat -S

Seems some problem with in this piece of code.

        for cmd, tables in s:
            for table in tables:
                current_table, _err = self.execute('%s-save' % (cmd,), '-c',
                                                   '-t', '%s' % (table,),
                                                   run_as_root=True,
                                                   attempts=5)
                current_lines = current_table.split('\n')
                new_filter = self._modify_rules(current_lines,
                                                tables[table])
                self.execute('%s-restore' % (cmd,), '-c', run_as_root=True,
                             process_input='\n'.join(new_filter),
                             attempts=5)
        LOG.debug(_("IPTablesManager.apply completed with success"))

I need output of the above commands to debug further.

jagan

[Sean Dague (sdague)]

really old incomplete bug