[Dnsmasq-discuss] OpenWrt - dnsmasq - debugging delayed responses
Arseny Vakhrushev
neoxic at icloud.com
Thu Jul 16 02:13:40 BST 2020
Hello all,
I'm trying to debug delayed DHCP responses in OpenWrt 19.07.3. The machine is connected to the router via Ethernet to eliminate possible network latency and packet loss.
# dnsmasq -v
Dnsmasq version 2.80
From the perspective of DHCP traffic on the router, I see the following:
---------------------------------------------------------------------------
17:34:07.837572 IP (tos 0x0, ttl 64, id 59861, offset 0, flags [none], proto UDP (17), length 328)
192.168.1.108.68 > 192.168.1.1.67: BOOTP/DHCP, Request from 34:36:3b:d2:c9:ea, length 300, xid 0xb690ebe6, Flags [none]
Client-IP 192.168.1.108
Client-Ethernet-Address 34:36:3b:d2:c9:ea
Vendor-rfc1048 Extensions
Magic Cookie 0x63825363
DHCP-Message Option 53, length 1: Release
Client-ID Option 61, length 7: ether 34:36:3b:d2:c9:ea
Server-ID Option 54, length 4: 192.168.1.1
17:34:07.838003 IP (tos 0x0, ttl 255, id 24328, offset 0, flags [none], proto UDP (17), length 328)
0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request from 34:36:3b:d2:c9:ea, length 300, xid 0xdd8f9ad8, Flags [none]
Client-Ethernet-Address 34:36:3b:d2:c9:ea
Vendor-rfc1048 Extensions
Magic Cookie 0x63825363
DHCP-Message Option 53, length 1: Discover
Parameter-Request Option 55, length 10:
Subnet-Mask, Classless-Static-Route, Default-Gateway, Domain-Name-Server
Domain-Name, Option 119, Option 252, LDAP
Netbios-Name-Server, Netbios-Node
MSZ Option 57, length 2: 1500
Client-ID Option 61, length 7: ether 34:36:3b:d2:c9:ea
Lease-Time Option 51, length 4: 7776000
Hostname Option 12, length 8: "seny-mbp"
17:34:09.840200 IP (tos 0x0, ttl 255, id 24329, offset 0, flags [none], proto UDP (17), length 328)
0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request from 34:36:3b:d2:c9:ea, length 300, xid 0xdd8f9ad8, secs 2, Flags [none]
Client-Ethernet-Address 34:36:3b:d2:c9:ea
Vendor-rfc1048 Extensions
Magic Cookie 0x63825363
DHCP-Message Option 53, length 1: Discover
Parameter-Request Option 55, length 10:
Subnet-Mask, Classless-Static-Route, Default-Gateway, Domain-Name-Server
Domain-Name, Option 119, Option 252, LDAP
Netbios-Name-Server, Netbios-Node
MSZ Option 57, length 2: 1500
Client-ID Option 61, length 7: ether 34:36:3b:d2:c9:ea
Lease-Time Option 51, length 4: 7776000
Hostname Option 12, length 8: "seny-mbp"
17:34:10.872500 IP (tos 0xc0, ttl 64, id 30295, offset 0, flags [none], proto UDP (17), length 328)
192.168.1.1.67 > 192.168.1.108.68: BOOTP/DHCP, Reply, length 300, xid 0xdd8f9ad8, Flags [none]
Your-IP 192.168.1.108
Server-IP 192.168.1.1
Client-Ethernet-Address 34:36:3b:d2:c9:ea
Vendor-rfc1048 Extensions
Magic Cookie 0x63825363
DHCP-Message Option 53, length 1: Offer
Server-ID Option 54, length 4: 192.168.1.1
Lease-Time Option 51, length 4: 43200
RN Option 58, length 4: 21600
RB Option 59, length 4: 37800
Subnet-Mask Option 1, length 4: 255.255.255.0
BR Option 28, length 4: 192.168.1.255
Default-Gateway Option 3, length 4: 192.168.1.1
Domain-Name-Server Option 6, length 4: 192.168.1.1
Domain-Name Option 15, length 3: "lan"
17:34:10.873198 IP (tos 0xc0, ttl 64, id 30296, offset 0, flags [none], proto UDP (17), length 328)
192.168.1.1.67 > 192.168.1.108.68: BOOTP/DHCP, Reply, length 300, xid 0xdd8f9ad8, secs 2, Flags [none]
Your-IP 192.168.1.108
Server-IP 192.168.1.1
Client-Ethernet-Address 34:36:3b:d2:c9:ea
Vendor-rfc1048 Extensions
Magic Cookie 0x63825363
DHCP-Message Option 53, length 1: Offer
Server-ID Option 54, length 4: 192.168.1.1
Lease-Time Option 51, length 4: 43200
RN Option 58, length 4: 21600
RB Option 59, length 4: 37800
Subnet-Mask Option 1, length 4: 255.255.255.0
BR Option 28, length 4: 192.168.1.255
Default-Gateway Option 3, length 4: 192.168.1.1
Domain-Name-Server Option 6, length 4: 192.168.1.1
Domain-Name Option 15, length 3: "lan"
17:34:11.939144 IP (tos 0x0, ttl 255, id 24330, offset 0, flags [none], proto UDP (17), length 328)
0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request from 34:36:3b:d2:c9:ea, length 300, xid 0xdd8f9ad8, secs 4, Flags [none]
Client-Ethernet-Address 34:36:3b:d2:c9:ea
Vendor-rfc1048 Extensions
Magic Cookie 0x63825363
DHCP-Message Option 53, length 1: Request
Parameter-Request Option 55, length 10:
Subnet-Mask, Classless-Static-Route, Default-Gateway, Domain-Name-Server
Domain-Name, Option 119, Option 252, LDAP
Netbios-Name-Server, Netbios-Node
MSZ Option 57, length 2: 1500
Client-ID Option 61, length 7: ether 34:36:3b:d2:c9:ea
Requested-IP Option 50, length 4: 192.168.1.108
Server-ID Option 54, length 4: 192.168.1.1
Hostname Option 12, length 8: "seny-mbp"
17:34:11.940391 IP (tos 0xc0, ttl 64, id 30369, offset 0, flags [none], proto UDP (17), length 328)
192.168.1.1.67 > 192.168.1.108.68: BOOTP/DHCP, Reply, length 300, xid 0xdd8f9ad8, secs 4, Flags [none]
Your-IP 192.168.1.108
Server-IP 192.168.1.1
Client-Ethernet-Address 34:36:3b:d2:c9:ea
Vendor-rfc1048 Extensions
Magic Cookie 0x63825363
DHCP-Message Option 53, length 1: ACK
Server-ID Option 54, length 4: 192.168.1.1
Lease-Time Option 51, length 4: 43200
RN Option 58, length 4: 21600
RB Option 59, length 4: 37800
Subnet-Mask Option 1, length 4: 255.255.255.0
BR Option 28, length 4: 192.168.1.255
Default-Gateway Option 3, length 4: 192.168.1.1
Domain-Name-Server Option 6, length 4: 192.168.1.1
Domain-Name Option 15, length 3: "lan"
---------------------------------------------------------------------------
In a nutshell, DHCP messages are received (>>) and sent (<<) with the following timestamps:
17:34:07.837572 >> Release
17:34:07.838003 >> Discover
17:34:09.840200 >> Discover
17:34:10.872500 << Offer
17:34:10.873198 << Offer
17:34:11.939144 >> Request
17:34:11.940391 << ACK
But from the perspective of the system log, the timestamps are different:
Wed Jul 15 17:34:07 2020 local0.info dnsmasq-dhcp[8462]: DHCPRELEASE(br-lan) 192.168.1.108 34:36:3b:d2:c9:ea
Wed Jul 15 17:34:10 2020 local0.info dnsmasq-dhcp[8462]: DHCPDISCOVER(br-lan) 34:36:3b:d2:c9:ea
Wed Jul 15 17:34:10 2020 local0.info dnsmasq-dhcp[8462]: DHCPOFFER(br-lan) 192.168.1.108 34:36:3b:d2:c9:ea
Wed Jul 15 17:34:10 2020 local0.info dnsmasq-dhcp[8462]: DHCPDISCOVER(br-lan) 34:36:3b:d2:c9:ea
Wed Jul 15 17:34:10 2020 local0.info dnsmasq-dhcp[8462]: DHCPOFFER(br-lan) 192.168.1.108 34:36:3b:d2:c9:ea
Wed Jul 15 17:34:11 2020 local0.info dnsmasq-dhcp[8462]: DHCPREQUEST(br-lan) 192.168.1.108 34:36:3b:d2:c9:ea
Wed Jul 15 17:34:11 2020 local0.info dnsmasq-dhcp[8462]: DHCPACK(br-lan) 192.168.1.108 34:36:3b:d2:c9:ea seny-mbp
I can see that for some reason dnsmasq delays the processing of the first Discover request for 3 seconds and of the second Discover request for 1 second, then logs them as though they have been received simultaneously and sends two corresponding Offer responses in a row. There seems to be nothing in the RFC denoting any kind of processing delays in a server.
As a side note, I can see that the client delayed its Request message for 1 second after receiving an offer, but I guess it might have been already in the middle of some retrasmission strategy since it obviously deemed the first Discover as lost. Let's leave it to the client for now as an unrelated issue.
I tried playing with the debugging options of dnsmasq as well as with all the DHCP related options including dhcp-reply-delay with no apparent success.
Please advise! Thank you!
Best regards,
Arseny
More information about the Dnsmasq-discuss
mailing list