On 17/01/2019 10:30, Harald Dunkel wrote: > 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=secur...@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
The delay is while dnsmasq tests the address it's about to allocate in case some host is already using it. It sends a ICMP echo request (essentially a ping) and if it gets a reply, the test fails. After a 3 second timeout the test succeeds and the address is allocated. If you're happy that there are no machines using IP addresses without leasing them, or that the similar test that DHCP clients do will find this, then you can disable the check in dnsmasq using the --no-oing config flag. Cheers, Simon. _______________________________________________ Dnsmasq-discuss mailing list Dnsmasq-discuss@lists.thekelleys.org.uk http://lists.thekelleys.org.uk/mailman/listinfo/dnsmasq-discuss
