[Dnsmasq-discuss] 3 secs dhcp delay

Harald Dunkel harald.dunkel at aixigo.de
Thu Jan 17 10:30:01 GMT 2019


Hi folks,

I see a 3 to 4 secs delay for dnsmasq's dhcp protocol. Example:

Strongswan's dhcp plugin obtains an IP address on behalf of the peer (a
road warrior laptop). The strongswan logfile on the host says

:
Jan 14 10:48:07 18[IKE] <IPSec-IKEv2|43> peer requested virtual IP %any
Jan 14 10:48:07 18[CFG] <IPSec-IKEv2|43> sending DHCP DISCOVER to 172.16.122.9
Jan 14 10:48:08 18[CFG] <IPSec-IKEv2|43> sending DHCP DISCOVER to 172.16.122.9
Jan 14 10:48:10 18[CFG] <IPSec-IKEv2|43> sending DHCP DISCOVER to 172.16.122.9
Jan 14 10:48:10 16[CFG] received DHCP OFFER 172.16.122.65 from 172.16.122.9
Jan 14 10:48:10 18[CFG] <IPSec-IKEv2|43> sending DHCP REQUEST for 172.16.122.65 to 172.16.122.9
Jan 14 10:48:10 18[CFG] <IPSec-IKEv2|43> sending DHCP REQUEST for 172.16.122.65 to 172.16.122.9
Jan 14 10:48:10 18[CFG] <IPSec-IKEv2|43> sending DHCP REQUEST for 172.16.122.65 to 172.16.122.9
Jan 14 10:48:10 15[CFG] received DHCP ACK for 172.16.122.65
Jan 14 10:48:10 18[IKE] <IPSec-IKEv2|43> assigning virtual IP 172.16.122.65 to peer 'C=DE, ST=NRW, L=Metropolis, O=example AG, CN=roadwarrior.ac.example.de, E=security at example.de'
:

dnsmasq's logfile contains this:

:
Jan 14 10:48:00 dnsmasq-dhcp[10542]: 1657285313 available DHCP range: 172.16.122.10 -- 172.16.122.254
Jan 14 10:48:00 dnsmasq-dhcp[10542]: 1657285313 DHCPRELEASE(eth1) 172.16.122.65 7a:a7:c5:fc:7d:59
Jan 14 10:48:07 dnsmasq-dhcp[10542]: 2364812771 available DHCP range: 172.16.122.10 -- 172.16.122.254
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 DHCPDISCOVER(eth1) 7a:a7:c5:fc:7d:59
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 tags: eth1
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 DHCPOFFER(eth1) 172.16.122.65 7a:a7:c5:fc:7d:59
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 requested options: 6:dns-server, 44:netbios-ns
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 next server: 172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  1 option: 53 message-type  2
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 54 server-identifier  172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 51 lease-time  12h
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 58 T1  6h
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 59 T2  10h30m
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option:  1 netmask  255.255.255.0
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 28 broadcast  172.16.122.255
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option:  6 dns-server  172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 available DHCP range: 172.16.122.10 -- 172.16.122.254
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 DHCPDISCOVER(eth1) 7a:a7:c5:fc:7d:59
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 tags: eth1
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 DHCPOFFER(eth1) 172.16.122.65 7a:a7:c5:fc:7d:59
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 requested options: 6:dns-server, 44:netbios-ns
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 next server: 172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  1 option: 53 message-type  2
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 54 server-identifier  172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 51 lease-time  12h
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 58 T1  6h
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 59 T2  10h30m
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option:  1 netmask  255.255.255.0
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 28 broadcast  172.16.122.255
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option:  6 dns-server  172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 available DHCP range: 172.16.122.10 -- 172.16.122.254
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 DHCPDISCOVER(eth1) 7a:a7:c5:fc:7d:59
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 tags: eth1
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 DHCPOFFER(eth1) 172.16.122.65 7a:a7:c5:fc:7d:59
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 requested options: 6:dns-server, 44:netbios-ns
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 next server: 172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  1 option: 53 message-type  2
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 54 server-identifier  172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 51 lease-time  12h
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 58 T1  6h
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 59 T2  10h30m
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option:  1 netmask  255.255.255.0
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 28 broadcast  172.16.122.255
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option:  6 dns-server  172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 available DHCP range: 172.16.122.10 -- 172.16.122.254
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 DHCPREQUEST(eth1) 172.16.122.65 7a:a7:c5:fc:7d:59
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 tags: eth1
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 DHCPACK(eth1) 172.16.122.65 7a:a7:c5:fc:7d:59
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 requested options: 6:dns-server, 44:netbios-ns
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 next server: 172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  1 option: 53 message-type  5
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 54 server-identifier  172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 51 lease-time  12h
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 58 T1  6h
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 59 T2  10h30m
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option:  1 netmask  255.255.255.0
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 28 broadcast  172.16.122.255
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option:  6 dns-server  172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 available DHCP range: 172.16.122.10 -- 172.16.122.254
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 DHCPREQUEST(eth1) 172.16.122.65 7a:a7:c5:fc:7d:59
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 tags: eth1
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 DHCPACK(eth1) 172.16.122.65 7a:a7:c5:fc:7d:59
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 requested options: 6:dns-server, 44:netbios-ns
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 next server: 172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  1 option: 53 message-type  5
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 54 server-identifier  172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 51 lease-time  12h
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 58 T1  6h
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 59 T2  10h30m
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option:  1 netmask  255.255.255.0
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 28 broadcast  172.16.122.255
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option:  6 dns-server  172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 available DHCP range: 172.16.122.10 -- 172.16.122.254
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 DHCPREQUEST(eth1) 172.16.122.65 7a:a7:c5:fc:7d:59
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 tags: eth1
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 DHCPACK(eth1) 172.16.122.65 7a:a7:c5:fc:7d:59
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 requested options: 6:dns-server, 44:netbios-ns
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 next server: 172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  1 option: 53 message-type  5
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 54 server-identifier  172.16.122.9
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 51 lease-time  12h
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 58 T1  6h
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 59 T2  10h30m
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option:  1 netmask  255.255.255.0
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option: 28 broadcast  172.16.122.255
Jan 14 10:48:10 dnsmasq-dhcp[10542]: 2364812771 sent size:  4 option:  6 dns-server  172.16.122.9
Jan 14 10:48:10 dnsmasq[10542]: query[SOA] local from 172.16.122.65
Jan 14 10:48:10 dnsmasq[10542]: forwarded local to 172.16.96.124
Jan 14 10:48:10 dnsmasq[10542]: forwarded local to 172.16.96.123
Jan 14 10:48:10 dnsmasq[10542]: query[SOA] local from 172.16.122.65
Jan 14 10:48:10 dnsmasq[10542]: forwarded local to 172.16.96.124
Jan 14 10:48:10 dnsmasq[10542]: forwarded local to 172.16.96.123
:

Obviously dnsmasq woke up somehow at 10:48:07 (when strongswan's plugin
initiated the DHCPDISCOVER), but dnsmasq seems to have waited for 3 seconds
to recognize DHCPDISCOVER (at 10:48:10).

I see this delay in other dnsmasq setups as well, e.g. on our smartphone
wlan:

:
Jan 14 08:05:27 dnsmasq-dhcp[53022]: 2932852660 available DHCP range: 10.100.0.10 -- 10.100.255.254
Jan 14 08:05:27 dnsmasq-dhcp[53022]: 2932852660 client provides name: SomebodiesiPhone
Jan 14 08:05:27 dnsmasq-dhcp[53022]: RTR-SOLICIT(em1)
Jan 14 08:05:27 dnsmasq-dhcp[53022]: RTR-ADVERT(em1) 2000:db8:30:fff0::
Jan 14 08:05:31 dnsmasq-dhcp[53022]: 2932852660 DHCPDISCOVER(em1) e0:5f:xx:xx:xx:xx
Jan 14 08:05:31 dnsmasq-dhcp[53022]: 2932852660 tags: em1
Jan 14 08:05:31 dnsmasq-dhcp[53022]: 2932852660 DHCPOFFER(em1) 10.100.21.120 e0:5f:xx:xx:xx:xx
Jan 14 08:05:31 dnsmasq-dhcp[53022]: 2932852660 requested options: 1:netmask, 121:classless-static-route, 3:router,
Jan 14 08:05:31 dnsmasq-dhcp[53022]: 2932852660 requested options: 6:dns-server, 15:domain-name, 119:domain-search,
Jan 14 08:05:31 dnsmasq-dhcp[53022]: 2932852660 requested options: 252
Jan 14 08:05:31 dnsmasq-dhcp[53022]: 2932852660 next server: 10.100.0.2
Jan 14 08:05:31 dnsmasq-dhcp[53022]: 2932852660 sent size:  1 option: 53 message-type  2
Jan 14 08:05:31 dnsmasq-dhcp[53022]: 2932852660 sent size:  4 option: 54 server-identifier  10.100.0.2
:

Using isc-dhcp-server (in a similar strongswan setup) there is no such
delay, so I wonder if this could be improved?

dnsmasq is version 2.80 on Debian 9. strongswan is version 5.7.2, running
on the same host.


Regards
Harri



More information about the Dnsmasq-discuss mailing list