dnsmasq DHCP server doesn't lease a released IP address.

asked 2015-04-30 02:26:10 -0500

Jaesang Lee gravatar image

This is dhcp lease problem during tempest test.

On the our system, OpenStack(kilo) executes dnsmasq service to provide DHCP service for the virtual guests.

When a virtual machine is created or deleted, OpenStack modifies the corresponding dhcp-hostsfile (e.g. /var/lib/nova/networks/nova-br100.conf) and executes dhcp_release command to release the leased IP address the old virtual machine used.(force_dhcp_release=True)

/var/lib/nova/networks/nova-br100.conf

fa:16:3e:8f:5d:22,testvolumebootpatternv2-892805009.novalocal,10.100.1.7
fa:16:3e:1e:8a:78,testminimumbasicscenario-1888487945.novalocal,10.100.1.86
  • But, 10.100.1.7 address didn't associate to instance actually.

vm console log

info: initramfs: up at 0.65
GROWROOT: CHANGED: partition=1 start=16065 old: size=64260 end=80325 new: size=2072385,end=2088450
info: initramfs loading root from /dev/vda1
info: /etc/init.d/rc.sysinit: up at 0.72
info: container: none
Starting logging: OK
Initializing random number generator... done.
Starting acpid: OK
cirros-ds 'local' up at 0.80
no results found for mode=local. up 0.83. searched: nocloud configdrive ec2
Starting network...
udhcpc (v1.20.1) started
Sending discover...
Sending discover...
Sending discover...
Usage: /sbin/cirros-dhcpc <up|down>
No lease, failing
WARN: /etc/rc3.d/S40-network failed
cirros-ds 'net' up at 181.01
checking http://169.254.169.254/2009-04-04/instance-id
failed 1/20: up 181.02. request failed
failed 2/20: up 183.21. request failed
failed 3/20: up 185.23. request failed
failed 4/20: up 187.24. request failed
failed 5/20: up 189.24. request failed

/var/log/syslog

Apr 30 15:54:57 poc4 dnsmasq-dhcp[15300]: not using configured address 10.100.1.7 because it is leased to fa:16:3e:cd:87:ba 
Apr 30 15:54:57 poc4 dnsmasq-dhcp[15300]: DHCPDISCOVER(br100) fa:16:3e:8f:5d:22 no address available
  • but fa:16:3e:cd:87:ba is deleted virtual interface

mysql> select * from virtual_interfaces where address='fa:16:3e:cd:87:ba'\G;

*************************** 1. row ***************************
   created_at: 2015-04-30 06:45:45
   updated_at: NULL
   deleted_at: 2015-04-30 06:47:05
                id: 964
   address: fa:16:3e:cd:87:ba
   network_id: 1
   uuid: 12a1d70d-654d-4dc5-bfd0-c224c33da5b8
   instance_uuid: ad4fae89-e49a-42e3-aa73-5ae31af3cba6
   deleted: 964
1 row in set (0.00 sec)

/var/log/nova/nova-network.log - It shows dhcp_release was excuted properly when vm delete.

2015-04-30 15:48:59.780 15242 DEBUG oslo_concurrency.processutils [req-65c5da1a-8e84-4592-9e40-8d586abf77ad 06ec445e95ff45849a85d806327337a2 ea3837ad61ac460a8bb572303f0bcc60 - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf dhcp_release br100 10.100.1.7 fa:16:3e:cd:87:ba execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:199
2015-04-30 15:48:59.829 15242 DEBUG oslo_concurrency.processutils [req-65c5da1a-8e84-4592-9e40-8d586abf77ad 06ec445e95ff45849a85d806327337a2 ea3837ad61ac460a8bb572303f0bcc60 - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf dhcp_release br100 10.100.1.7 fa:16:3e:cd:87:ba" returned: 0 in 0.049s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:225
2015-04-30 15:48:59.869 15242 INFO nova.network.manager [req-65c5da1a-8e84-4592-9e40-8d586abf77ad 06ec445e95ff45849a85d806327337a2 ea3837ad61ac460a8bb572303f0bcc60 - - -] [instance: ad4fae89-e49a-42e3-aa73-5ae31af3cba6] Network deallocated for instance (fixed ips: '['10.100 ...
(more)
edit retag flag offensive close merge delete

Comments

I'm running into this issue as well. I'm using Kilo on ubuntu with nova-network set up for multi host mode with multiple networks. I have the dhcp force delete option set in nova.conf and see the dhcp_release command called for each network, but do not always see a 'del' in nova-dhcpbridge.log

patrick-east gravatar imagepatrick-east ( 2015-06-09 23:50:46 -0500 )edit