Discussion:
[Dnsmasq-discuss] dhcp entries not being removed from dnsmasq
Graeme Peterson
2017-05-17 16:24:29 UTC
Permalink
Hi all.

Sorry if this issue has been discussed and resolved, I am new to the
list. I tried to find it in the list, and came across this reference to
the issue from Jan 2016:

http://lists.thekelleys.org.uk/pipermail/dnsmasq-discuss/2016q1/010273.html

What I am seeing is with OpenStack Newton on Ubuntu 16.10
(4.8.0-49-generic), with force_dhcp_release=True in /etc/nova/nova.conf,
using tcpdump on the netns for the relevant Openstack network, I see
dnsmasq receives the dhcp request, issues an IP, and that IP should be
released (Openstack should be calling dhcp_release, I need to figure out
how to verify that it is or is not happening, however
force_dhcp_release=True is explicitly set in /etc/nova/nova.conf) , but
it seems like the dhcp entry isn't being entirely released. The odd
thing is that when a new VM wants an IP, tcpdump shows the request
coming in for an address, but no reply, and OpenStack thinks it got an
IP - the same one that used to belong to the recently terminated VM -
but there is no dhcp offer in the tcpdump, and the dnsmasq log shows:

May 16 16:53:15 dnsmasq-dhcp[40394]: 3306068020
DHCPREQUEST(tapc5399cce-70) 132.16.0.13 fa:16:3e:8e:83:97
May 16 16:53:15 dnsmasq-dhcp[40394]: 3306068020 tags: tag0, known,
tapc5399cce-70
May 16 16:53:15 dnsmasq-dhcp[40394]: 3306068020 DHCPACK(tapc5399cce-70)
132.16.0.13 fa:16:3e:8e:83:97 host-132-16-0-13
...
...
...
May 16 16:57:12 dnsmasq-dhcp[40394]: 461988430 available DHCP subnet:
132.16.0.0/255.255.0.0
May 16 16:57:12 dnsmasq-dhcp[40394]: not using configured address
132.16.0.13 because it is leased to fa:16:3e:8e:83:97
May 16 16:57:12 dnsmasq-dhcp[40394]: 461988430
DHCPDISCOVER(tapc5399cce-70) 192.168.0.51 fa:16:3e:31:de:d3 no address
available

I don't see a log entry for a release of 132.16.0.13, not sure if there
should be one.

Is this a known and hopefully fixed issue? Can I provide further info to
help investigate it?

Thanks,
Graeme
Graeme Peterson
2017-05-17 18:12:06 UTC
Permalink
I found the following entry in /var/log/auth.log which shows neutron as
root (sudo) calling dhcp_release on IP: 132.16.0.13, MAC:
fa:16:3e:8e:83:97 two minutes after the DHCPACK and two minutes before
the dnsmasq-dhcp log failure saying: "not using configured address
132.16.0.13 because it is leased to fa:16:3e:8e:83:97". Looks to me like
Openstack is calling dhcp_release correctly. The dnsmask log is in a
folder named "34705fcf-4f9c-48eb-b0bc-ac5091e181c8", same as the arg to
ip netns exec without the "qdhcp-" prefix. So far it looks like a
dhcp_release/dnsmasq issue to my untrained eye. I have been able to work
around it somewhat by setting the max lease time to 30 seconds, although
that seems to be introducing other issues, more investigation required
there.

./auth.log:May 16 16:55:21 my-ucs-69 sudo: neutron : TTY=unknown ;
PWD=/var/lib/neutron ; USER=root ; COMMAND=/usr/bin/neutron-rootwrap
/etc/neutron/rootwrap.conf ip netns exec
qdhcp-34705fcf-4f9c-48eb-b0bc-ac5091e181c8 dhcp_release tapc5399cce-70
132.16.0.13 fa:16:3e:8e:83:97

Thanks again,
Graeme
Post by Graeme Peterson
Hi all.
http://lists.thekelleys.org.uk/pipermail/dnsmasq-discuss/2016q1/010273.html
May 16 16:53:15 dnsmasq-dhcp[40394]: 3306068020 DHCPREQUEST(tapc5399cce-70) 132.16.0.13 fa:16:3e:8e:83:97
May 16 16:53:15 dnsmasq-dhcp[40394]: 3306068020 tags: tag0, known, tapc5399cce-70
May 16 16:53:15 dnsmasq-dhcp[40394]: 3306068020 DHCPACK(tapc5399cce-70) 132.16.0.13 fa:16:3e:8e:83:97 host-132-16-0-13
...
...
...
May 16 16:57:12 dnsmasq-dhcp[40394]: 461988430 available DHCP subnet: 132.16.0.0/255.255.0.0
May 16 16:57:12 dnsmasq-dhcp[40394]: not using configured address 132.16.0.13 because it is leased to fa:16:3e:8e:83:97
May 16 16:57:12 dnsmasq-dhcp[40394]: 461988430 DHCPDISCOVER(tapc5399cce-70) 192.168.0.51 fa:16:3e:31:de:d3 no address available
I don't see a log entry for a release of 132.16.0.13, not sure if there should be one.
Is this a known and hopefully fixed issue? Can I provide further info to help investigate it?
Thanks,
Graeme
_______________________________________________
Dnsmasq-discuss mailing list
http://lists.thekelleys.org.uk/mailman/listinfo/dnsmasq-discuss
Simon Kelley
2017-05-17 18:39:07 UTC
Permalink
Ah, didn't read this before my previous reply.

dhcp_release is getting called, but dnsmasq is not getting the packet
(dhcp_release works by faking up a DHCP message as if it's coming from
the DHCP client, which tells the server to release the lease.)

If you can't see the packet in your packet dump, then that's significant.

Note that dhcp_release needs an "interface" parameter. That has to be
correct.

Cheers,

Simon.
Post by Graeme Peterson
I found the following entry in /var/log/auth.log which shows neutron as
fa:16:3e:8e:83:97 two minutes after the DHCPACK and two minutes before
the dnsmasq-dhcp log failure saying: "not using configured address
132.16.0.13 because it is leased to fa:16:3e:8e:83:97". Looks to me like
Openstack is calling dhcp_release correctly. The dnsmask log is in a
folder named "34705fcf-4f9c-48eb-b0bc-ac5091e181c8", same as the arg to
ip netns exec without the "qdhcp-" prefix. So far it looks like a
dhcp_release/dnsmasq issue to my untrained eye. I have been able to work
around it somewhat by setting the max lease time to 30 seconds, although
that seems to be introducing other issues, more investigation required
there.
./auth.log:May 16 16:55:21 my-ucs-69 sudo: neutron : TTY=unknown ;
PWD=/var/lib/neutron ; USER=root ; COMMAND=/usr/bin/neutron-rootwrap
/etc/neutron/rootwrap.conf ip netns exec
qdhcp-34705fcf-4f9c-48eb-b0bc-ac5091e181c8 dhcp_release tapc5399cce-70
132.16.0.13 fa:16:3e:8e:83:97
Thanks again,
Graeme
Post by Graeme Peterson
Hi all.
Sorry if this issue has been discussed and resolved, I am new to the
list. I tried to find it in the list, and came across this reference
http://lists.thekelleys.org.uk/pipermail/dnsmasq-discuss/2016q1/010273.html
What I am seeing is with OpenStack Newton on Ubuntu 16.10
(4.8.0-49-generic), with force_dhcp_release=True in
/etc/nova/nova.conf, using tcpdump on the netns for the relevant
Openstack network, I see dnsmasq receives the dhcp request, issues an
IP, and that IP should be released (Openstack should be calling
dhcp_release, I need to figure out how to verify that it is or is not
happening, however force_dhcp_release=True is explicitly set in
/etc/nova/nova.conf) , but it seems like the dhcp entry isn't being
entirely released. The odd thing is that when a new VM wants an IP,
tcpdump shows the request coming in for an address, but no reply, and
OpenStack thinks it got an IP - the same one that used to belong to
the recently terminated VM - but there is no dhcp offer in the
May 16 16:53:15 dnsmasq-dhcp[40394]: 3306068020
DHCPREQUEST(tapc5399cce-70) 132.16.0.13 fa:16:3e:8e:83:97
May 16 16:53:15 dnsmasq-dhcp[40394]: 3306068020 tags: tag0, known, tapc5399cce-70
May 16 16:53:15 dnsmasq-dhcp[40394]: 3306068020
DHCPACK(tapc5399cce-70) 132.16.0.13 fa:16:3e:8e:83:97 host-132-16-0-13
...
...
...
132.16.0.0/255.255.0.0
May 16 16:57:12 dnsmasq-dhcp[40394]: not using configured address
132.16.0.13 because it is leased to fa:16:3e:8e:83:97
May 16 16:57:12 dnsmasq-dhcp[40394]: 461988430
DHCPDISCOVER(tapc5399cce-70) 192.168.0.51 fa:16:3e:31:de:d3 no address
available
I don't see a log entry for a release of 132.16.0.13, not sure if there should be one.
Is this a known and hopefully fixed issue? Can I provide further info
to help investigate it?
Thanks,
Graeme
_______________________________________________
Dnsmasq-discuss mailing list
http://lists.thekelleys.org.uk/mailman/listinfo/dnsmasq-discuss
_______________________________________________
Dnsmasq-discuss mailing list
http://lists.thekelleys.org.uk/mailman/listinfo/dnsmasq-discuss
Simon Kelley
2017-05-17 19:24:39 UTC
Permalink
dhcp_release is a bit of a hack, and I guess the packet it generates
could be blocked by all sorts of iptables rules. It also doesn't seem to
support the interface (eg tapc5399cce-70) having more than one IP
address on the same subnet, in case that's a problem.

My impression is that you're an OpenStack user trying to fix a problem,
but if you're in fact an OpenStack developer, it's worth pointing out
that the DBus control interface to dnsmasq provides a rather better way
of doing the same thing as dhcp_release.

Cheers,

Simon.
Thanks Simon. Appreciate the heads-up on the off-topic parts of my post.
dhcp_release tapc5399cce-70 132.16.0.13 fa:16:3e:8e:83:97
To me that looks good, and lines up with the man page for dhcp_release.
The interface "tapc5399cce-70" is the same as in the dnsmasq-dhcp log
ip netns exec qdhcp-34705fcf-4f9c-48eb-b0bc-ac5091e181c8 ip a
I will try to reproduce again and watch the tcpdump for the release packet.
Thanks,
GP
Post by Simon Kelley
Ah, didn't read this before my previous reply.
dhcp_release is getting called, but dnsmasq is not getting the packet
(dhcp_release works by faking up a DHCP message as if it's coming from
the DHCP client, which tells the server to release the lease.)
If you can't see the packet in your packet dump, then that's significant.
Note that dhcp_release needs an "interface" parameter. That has to be
correct.
Cheers,
Simon.
Post by Graeme Peterson
I found the following entry in /var/log/auth.log which shows neutron as
fa:16:3e:8e:83:97 two minutes after the DHCPACK and two minutes before
the dnsmasq-dhcp log failure saying: "not using configured address
132.16.0.13 because it is leased to fa:16:3e:8e:83:97". Looks to me like
Openstack is calling dhcp_release correctly. The dnsmask log is in a
folder named "34705fcf-4f9c-48eb-b0bc-ac5091e181c8", same as the arg to
ip netns exec without the "qdhcp-" prefix. So far it looks like a
dhcp_release/dnsmasq issue to my untrained eye. I have been able to work
around it somewhat by setting the max lease time to 30 seconds, although
that seems to be introducing other issues, more investigation required
there.
./auth.log:May 16 16:55:21 my-ucs-69 sudo: neutron : TTY=unknown ;
PWD=/var/lib/neutron ; USER=root ; COMMAND=/usr/bin/neutron-rootwrap
/etc/neutron/rootwrap.conf ip netns exec
qdhcp-34705fcf-4f9c-48eb-b0bc-ac5091e181c8 dhcp_release tapc5399cce-70
132.16.0.13 fa:16:3e:8e:83:97
Thanks again,
Graeme
Post by Graeme Peterson
Hi all.
Sorry if this issue has been discussed and resolved, I am new to the
list. I tried to find it in the list, and came across this reference
http://lists.thekelleys.org.uk/pipermail/dnsmasq-discuss/2016q1/010273.html
What I am seeing is with OpenStack Newton on Ubuntu 16.10
(4.8.0-49-generic), with force_dhcp_release=True in
/etc/nova/nova.conf, using tcpdump on the netns for the relevant
Openstack network, I see dnsmasq receives the dhcp request, issues an
IP, and that IP should be released (Openstack should be calling
dhcp_release, I need to figure out how to verify that it is or is not
happening, however force_dhcp_release=True is explicitly set in
/etc/nova/nova.conf) , but it seems like the dhcp entry isn't being
entirely released. The odd thing is that when a new VM wants an IP,
tcpdump shows the request coming in for an address, but no reply, and
OpenStack thinks it got an IP - the same one that used to belong to
the recently terminated VM - but there is no dhcp offer in the
May 16 16:53:15 dnsmasq-dhcp[40394]: 3306068020
DHCPREQUEST(tapc5399cce-70) 132.16.0.13 fa:16:3e:8e:83:97
May 16 16:53:15 dnsmasq-dhcp[40394]: 3306068020 tags: tag0, known, tapc5399cce-70
May 16 16:53:15 dnsmasq-dhcp[40394]: 3306068020
DHCPACK(tapc5399cce-70) 132.16.0.13 fa:16:3e:8e:83:97 host-132-16-0-13
...
...
...
132.16.0.0/255.255.0.0
May 16 16:57:12 dnsmasq-dhcp[40394]: not using configured address
132.16.0.13 because it is leased to fa:16:3e:8e:83:97
May 16 16:57:12 dnsmasq-dhcp[40394]: 461988430
DHCPDISCOVER(tapc5399cce-70) 192.168.0.51 fa:16:3e:31:de:d3 no address
available
I don't see a log entry for a release of 132.16.0.13, not sure if
there should be one.
Is this a known and hopefully fixed issue? Can I provide further info
to help investigate it?
Thanks,
Graeme
_______________________________________________
Dnsmasq-discuss mailing list
http://lists.thekelleys.org.uk/mailman/listinfo/dnsmasq-discuss
_______________________________________________
Dnsmasq-discuss mailing list
http://lists.thekelleys.org.uk/mailman/listinfo/dnsmasq-discuss
_______________________________________________
Dnsmasq-discuss mailing list
http://lists.thekelleys.org.uk/mailman/listinfo/dnsmasq-discuss
Simon Kelley
2017-05-17 18:34:47 UTC
Permalink
You're assuming a lot of knowledge of OpenStack which is strictly
off-topic here.

Given that, a couple of observations.

1) If dnsmasq is getting a DHCPELEASE packet, it will log that. Given
you're not seeing that in logs, then either dhcp_release is not being
invoked, or it's getting the wrong parameters, or it's failing. Can you
see the DHCPRLEASE messages in your packet dump?

2) What dhcp client is openstack using? Some DHCP servers will continue
to use a previous address if they fail to contact a DHCP server.

Cheers,
Simon.
Post by Graeme Peterson
Hi all.
Sorry if this issue has been discussed and resolved, I am new to the
list. I tried to find it in the list, and came across this reference to
http://lists.thekelleys.org.uk/pipermail/dnsmasq-discuss/2016q1/010273.html
What I am seeing is with OpenStack Newton on Ubuntu 16.10
(4.8.0-49-generic), with force_dhcp_release=True in /etc/nova/nova.conf,
using tcpdump on the netns for the relevant Openstack network, I see
dnsmasq receives the dhcp request, issues an IP, and that IP should be
released (Openstack should be calling dhcp_release, I need to figure out
how to verify that it is or is not happening, however
force_dhcp_release=True is explicitly set in /etc/nova/nova.conf) , but
it seems like the dhcp entry isn't being entirely released. The odd
thing is that when a new VM wants an IP, tcpdump shows the request
coming in for an address, but no reply, and OpenStack thinks it got an
IP - the same one that used to belong to the recently terminated VM -
May 16 16:53:15 dnsmasq-dhcp[40394]: 3306068020
DHCPREQUEST(tapc5399cce-70) 132.16.0.13 fa:16:3e:8e:83:97
May 16 16:53:15 dnsmasq-dhcp[40394]: 3306068020 tags: tag0, known,
tapc5399cce-70
May 16 16:53:15 dnsmasq-dhcp[40394]: 3306068020 DHCPACK(tapc5399cce-70)
132.16.0.13 fa:16:3e:8e:83:97 host-132-16-0-13
...
...
...
132.16.0.0/255.255.0.0
May 16 16:57:12 dnsmasq-dhcp[40394]: not using configured address
132.16.0.13 because it is leased to fa:16:3e:8e:83:97
May 16 16:57:12 dnsmasq-dhcp[40394]: 461988430
DHCPDISCOVER(tapc5399cce-70) 192.168.0.51 fa:16:3e:31:de:d3 no address
available
I don't see a log entry for a release of 132.16.0.13, not sure if there
should be one.
Is this a known and hopefully fixed issue? Can I provide further info to
help investigate it?
Thanks,
Graeme
_______________________________________________
Dnsmasq-discuss mailing list
http://lists.thekelleys.org.uk/mailman/listinfo/dnsmasq-discuss
Loading...