DHCP address is used after DHCP lease time has expired
Summary
After a DHCP lease expires and the DHCP client is requesting a new address by issuing DISCOVER, our device continues to respond to pings on the previous IP address for around 500-800ms. This is enough time for a DHCP server using pings to conclude that the previous IP address is still in use and it shall issue a different address to our device.
Version affected
1.44.2, buildroot 2024.02.1
Steps to reproduce
- Start DHCP server on Host:
sudo dnsmasq --dhcp-range=192.168.199.100,192.168.199.150,255.255.255.0,2m --no-daemon --log-debug --listen-address=192.168.199.1 --log-dhcp --dhcp-authoritative --leasefile-ro
- Wait for device to acquire DHCP-IP-address
- Start
ping
:sudo ping -f <dhcp-ip-address-of-device>
- Stop DHCP server
- Observe network traffic with
wireshark
Actual result
After DHCP lease time expires, device sends DHCP discover to broadcast, but still responds to pings to its previous address for 500-800ms.
Expected result
After DHCP lease time expires, device does not respond to pings to its previous address anymore.
Relevant logs
2024-05-07T09:25:05.259431+0200 NetworkManager[1052]: <debug> [1715066705.2593] dhcp4 (end0): event: send REQUEST of 192.168.199.118 to 255.255.255.255
2024-05-07T09:25:20.258876+0200 NetworkManager[1052]: <trace> [1715066720.2587] dhcp4 (end0): notify: event=expire
2024-05-07T09:25:20.258944+0200 NetworkManager[1052]: <info> [1715066720.2589] dhcp4 (end0): activation: beginning transaction (timeout in 5 seconds)
2024-05-07T09:25:20.259008+0200 NetworkManager[1052]: <info> [1715066720.2589] dhcp4 (end0): state changed no lease
2024-05-07T09:25:20.259095+0200 NetworkManager[1052]: <trace> [1715066720.2590] device[9a739dc311f1e5eb] (end0): ip:dhcp4: lease lost
2024-05-07T09:25:20.259385+0200 NetworkManager[1052]: <debug> [1715066720.2593] dhcp4 (end0): event: send DISCOVER to 255.255.255.255
2024-05-07T09:25:20.716203+0200 NetworkManager[1052]: <trace> [1715066720.7160] platform-linux: delayed-action: schedule read-rtnl
2024-05-07T09:25:20.716256+0200 NetworkManager[1052]: <trace> [1715066720.7162] platform-linux: delayed-action: handle read-rtnl
2024-05-07T09:25:20.716329+0200 NetworkManager[1052]: <trace> [1715066720.7162] platform-linux: rtnl: recvmsg: new message RTM_DELADDR, flags 0, seq 0
2024-05-07T09:25:20.716395+0200 NetworkManager[1052]: <trace> [1715066720.7163] platform-linux: event-notification: RTM_DELADDR, flags 0, seq 0: 2: 192.168.199.118/24
2024-05-07T09:25:20.716493+0200 NetworkManager[1052]: <trace> [1715066720.7164] platform-linux: update-cache-ip4-address: REMOVE: [ip4-address,ddd9029e057125cb,2,+alive,+visible; 192.168.199.118/24 brd 192.168.199.255 lft 0sec pref 0sec lifetime 8024-7904[120,120] dev 2 flags noprefixroute src kernel]
2024-05-07T09:25:20.716532+0200 NetworkManager[1052]: <trace> [1715066720.7165] platform-linux: delayed-action: schedule refresh-all-rtnl-ip4-routes
2024-05-07T09:25:20.716598+0200 NetworkManager[1052]: <trace> [1715066720.7165] platform: (end0) emit signal ip4-address-changed removed: 192.168.199.118/24 brd 192.168.199.255 lft 0sec pref 0sec lifetime 8024-7904[120,120] dev 2 flags noprefixroute src kernel
2024-05-07T09:25:20.716685+0200 NetworkManager[1052]: <debug> [1715066720.7166] platform: (end0) signal: address 4 removed: 192.168.199.118/24 brd 192.168.199.255 lft 0sec pref 0sec lifetime 8024-7904[120,120] dev 2 flags noprefixroute src kernel
2024-05-07T09:25:20.716774+0200 NetworkManager[1052]: <trace> [1715066720.7167] l3cfg[d361507385f3776b,ifindex=2]: acd[192.168.199.118, defending]: address was externally removed
2024-05-07T09:25:20.716826+0200 NetworkManager[1052]: <trace> [1715066720.7167] l3cfg[d361507385f3776b,ifindex=2]: acd[192.168.199.118, external-removed]: set state to external-removed
2024-05-07T09:25:20.716886+0200 NetworkManager[1052]: <debug> [1715066720.7168] l3cfg[d361507385f3776b,ifindex=2]: obj-state: remove from platform: [69634838c18c8220, ip4-address, 192.168.199.118/24 brd* 192.168.199.255 lft 0sec pref 0sec lifetime 8024-7904[120,120] dev 2 src dhcp], nm-configured, was-in-platform
2024-05-07T09:25:20.716939+0200 NetworkManager[1052]: <trace> [1715066720.7169] l3cfg[d361507385f3776b,ifindex=2]: emit signal (platform-change, obj-type=ip4-address, change=removed, obj=192.168.199.118/24 brd 192.168.199.255 lft 0sec pref 0sec lifetime 8024-7904[120,120] dev 2 flags noprefixroute src kernel)
2024-05-07T09:25:20.717029+0200 NetworkManager[1052]: <trace> [1715066720.7169] platform-linux: rtnl: recvmsg: new message RTM_DELROUTE, flags 0, seq 0
2024-05-07T09:25:20.717096+0200 NetworkManager[1052]: <trace> [1715066720.7170] platform-linux: event-notification: RTM_DELROUTE, flags 0, seq 0: type broadcast table 255 192.168.199.255/32 dev 2 metric 0 mss 0 rt-src rt-kernel scope link pref-src 192.168.199.118
2024-05-07T09:25:20.717154+0200 NetworkManager[1052]: <trace> [1715066720.7171] platform-linux: rtnl: recvmsg: new message RTM_DELROUTE, flags 0, seq 0
2024-05-07T09:25:20.717214+0200 NetworkManager[1052]: <trace> [1715066720.7171] platform-linux: event-notification: RTM_DELROUTE, flags 0, seq 0: type local table 255 192.168.199.118/32 dev 2 metric 0 mss 0 rt-src rt-kernel scope host pref-src 192.168.199.118
2024-05-07T09:25:20.717294+0200 NetworkManager[1052]: <trace> [1715066720.7172] platform-linux: update-cache-ip4-route: REMOVE: [ip4-route,c99c83243db654ab,1,+alive,+visible; type local table 255 192.168.199.118/32 dev 2 metric 0 mss 0 rt-src rt-kernel scope host pref-src 192.168.199.118]
2024-05-07T09:25:20.717352+0200 NetworkManager[1052]: <trace> [1715066720.7173] platform: (end0) emit signal ip4-route-changed removed: type local table 255 192.168.199.118/32 dev 2 metric 0 mss 0 rt-src rt-kernel scope host pref-src 192.168.199.118
2024-05-07T09:25:20.717446+0200 NetworkManager[1052]: <debug> [1715066720.7173] platform: (end0) signal: route 4 removed: type local table 255 192.168.199.118/32 dev 2 metric 0 mss 0 rt-src rt-kernel scope host pref-src 192.168.199.118
2024-05-07T09:25:20.717508+0200 NetworkManager[1052]: <trace> [1715066720.7174] l3cfg[d361507385f3776b,ifindex=2]: emit signal (platform-change, obj-type=ip4-route, change=removed, obj=type local table 255 192.168.199.118/32 dev 2 metric 0 mss 0 rt-src rt-kernel scope host pref-src 192.168.199.118)
2024-05-07T09:25:20.717585+0200 NetworkManager[1052]: <trace> [1715066720.7175] platform-linux: rtnl: recvmsg: new message RTM_DELROUTE, flags 0, seq 0
2024-05-07T09:25:20.717639+0200 NetworkManager[1052]: <trace> [1715066720.7176] platform-linux: event-notification: RTM_DELROUTE, flags 0, seq 0: type unicast 192.168.199.0/24 dev 2 metric 100 mss 0 rt-src rt-kernel scope link pref-src 192.168.199.118
2024-05-07T09:25:20.717710+0200 NetworkManager[1052]: <trace> [1715066720.7176] platform-linux: update-cache-ip4-route: REMOVE: [ip4-route,cea8c681a2d7d7ac,2,+alive,+visible; type unicast 192.168.199.0/24 dev 2 metric 100 mss 0 rt-src rt-kernel scope link pref-src 192.168.199.118]
2024-05-07T09:25:20.717763+0200 NetworkManager[1052]: <trace> [1715066720.7177] platform: (end0) emit signal ip4-route-changed removed: type unicast 192.168.199.0/24 dev 2 metric 100 mss 0 rt-src rt-kernel scope link pref-src 192.168.199.118
2024-05-07T09:25:20.717828+0200 NetworkManager[1052]: <debug> [1715066720.7177] platform: (end0) signal: route 4 removed: type unicast 192.168.199.0/24 dev 2 metric 100 mss 0 rt-src rt-kernel scope link pref-src 192.168.199.118
2024-05-07T09:25:20.717892+0200 NetworkManager[1052]: <debug> [1715066720.7178] l3cfg[d361507385f3776b,ifindex=2]: obj-state: remove from platform: [8670dc1dd491cb92, ip4-route, type unicast 192.168.199.0/24 dev 2 metric 100 mss 0 rt-src rt-kernel scope link pref-src 192.168.199.118], nm-configured, was-in-platform
2024-05-07T09:25:20.717942+0200 NetworkManager[1052]: <trace> [1715066720.7179] l3cfg[d361507385f3776b,ifindex=2]: emit signal (platform-change, obj-type=ip4-route, change=removed, obj=type unicast 192.168.199.0/24 dev 2 metric 100 mss 0 rt-src rt-kernel scope link pref-src 192.168.199.118)
2024-05-07T09:25:20.718011+0200 NetworkManager[1052]: <trace> [1715066720.7179] platform-linux: rtnl: recvmsg: new message RTM_DELROUTE, flags 0, seq 0
2024-05-07T09:25:20.718065+0200 NetworkManager[1052]: <trace> [1715066720.7180] platform-linux: event-notification: RTM_DELROUTE, flags 0, seq 0: type unicast 0.0.0.0/0 via 192.168.199.1 dev 2 metric 20100 mss 0 rt-src rt-dhcp scope global pref-src 192.168.199.118
2024-05-07T09:25:20.718141+0200 NetworkManager[1052]: <trace> [1715066720.7181] platform-linux: update-cache-ip4-route: REMOVE: [ip4-route,0091ba21fa62abf4,3,+alive,+visible; type unicast 0.0.0.0/0 via 192.168.199.1 dev 2 metric 20100 mss 0 rt-src rt-dhcp scope global pref-src 192.168.199.118]
2024-05-07T09:25:20.718195+0200 NetworkManager[1052]: <trace> [1715066720.7181] platform: (end0) emit signal ip4-route-changed removed: type unicast 0.0.0.0/0 via 192.168.199.1 dev 2 metric 20100 mss 0 rt-src rt-dhcp scope global pref-src 192.168.199.118
2024-05-07T09:25:20.718262+0200 NetworkManager[1052]: <debug> [1715066720.7182] platform: (end0) signal: route 4 removed: type unicast 0.0.0.0/0 via 192.168.199.1 dev 2 metric 20100 mss 0 rt-src rt-dhcp scope global pref-src 192.168.199.118
2024-05-07T09:25:20.718323+0200 NetworkManager[1052]: <debug> [1715066720.7182] l3cfg[d361507385f3776b,ifindex=2]: obj-state: remove from platform: [85202f2ae085e75e, ip4-route, type unicast 0.0.0.0/0 via 192.168.199.1 dev 2 metric 20100 mss 0 rt-src dhcp pref-src 192.168.199.118], nm-configured, was-in-platform
2024-05-07T09:25:20.718373+0200 NetworkManager[1052]: <trace> [1715066720.7183] l3cfg[d361507385f3776b,ifindex=2]: emit signal (platform-change, obj-type=ip4-route, change=removed, obj=type unicast 0.0.0.0/0 via 192.168.199.1 dev 2 metric 20100 mss 0 rt-src rt-dhcp scope global pref-src 192.168.199.118)
2024-05-07T09:25:20.718441+0200 NetworkManager[1052]: <trace> [1715066720.7184] platform-linux: delayed-action: handle refresh-all-rtnl-ip4-routes
2024-05-07T09:25:20.718485+0200 NetworkManager[1052]: <trace> [1715066720.7184] platform-linux: delayed-action: handle (do-request-all) refresh-all-rtnl-ip4-routes
2024-05-07T09:25:20.718644+0200 NetworkManager[1052]: <trace> [1715066720.7186] platform-linux: delayed-action: schedule wait-for-response-rtnl (seq 87, timeout in 0.199995376, response-type 1)
2024-05-07T09:25:20.718687+0200 NetworkManager[1052]: <trace> [1715066720.7186] platform-linux: delayed-action: handle wait-for-response-rtnl (any)
2024-05-07T09:25:20.718761+0200 NetworkManager[1052]: <trace> [1715066720.7187] platform-linux: rtnl: recvmsg: new message RTM_NEWROUTE, flags multi, seq 87
2024-05-07T09:25:20.718825+0200 NetworkManager[1052]: <trace> [1715066720.7187] platform-linux: event-notification: RTM_NEWROUTE, flags multi, seq 87, in-dump: type unicast 172.31.238.238/32 dev 5 metric 0 mss 0 rt-src rt-kernel scope link pref-src 172.31.238.239
2024-05-07T09:25:20.718883+0200 NetworkManager[1052]: <trace> [1715066720.7188] platform-linux: rtnl: recvmsg: new message RTM_NEWROUTE, flags multi, seq 87
2024-05-07T09:25:20.718938+0200 NetworkManager[1052]: <trace> [1715066720.7189] platform-linux: event-notification: RTM_NEWROUTE, flags multi, seq 87, in-dump: type local table 255 127.0.0.0/8 dev 1 metric 0 mss 0 rt-src rt-kernel scope host pref-src 127.0.0.1
2024-05-07T09:25:20.718988+0200 NetworkManager[1052]: <trace> [1715066720.7189] platform-linux: rtnl: recvmsg: new message RTM_NEWROUTE, flags multi, seq 87
2024-05-07T09:25:20.719040+0200 NetworkManager[1052]: <trace> [1715066720.7190] platform-linux: event-notification: RTM_NEWROUTE, flags multi, seq 87, in-dump: type local table 255 127.0.0.1/32 dev 1 metric 0 mss 0 rt-src rt-kernel scope host pref-src 127.0.0.1
2024-05-07T09:25:20.719090+0200 NetworkManager[1052]: <trace> [1715066720.7190] platform-linux: rtnl: recvmsg: new message RTM_NEWROUTE, flags multi, seq 87
2024-05-07T09:25:20.719143+0200 NetworkManager[1052]: <trace> [1715066720.7191] platform-linux: event-notification: RTM_NEWROUTE, flags multi, seq 87, in-dump: type broadcast table 255 127.255.255.255/32 dev 1 metric 0 mss 0 rt-src rt-kernel scope link pref-src 127.0.0.1
2024-05-07T09:25:20.719185+0200 NetworkManager[1052]: <trace> [1715066720.7191] platform-linux: rtnl: recvmsg: new message RTM_NEWROUTE, flags multi, seq 87
2024-05-07T09:25:20.719243+0200 NetworkManager[1052]: <trace> [1715066720.7192] platform-linux: event-notification: RTM_NEWROUTE, flags multi, seq 87, in-dump: type local table 255 172.31.238.239/32 dev 5 metric 0 mss 0 rt-src rt-kernel scope host pref-src 172.31.238.239
2024-05-07T09:25:20.719321+0200 NetworkManager[1052]: <trace> [1715066720.7192] platform-linux: rtnl: recvmsg: new message NLMSG_DONE, flags multi, seq 87
2024-05-07T09:25:20.719384+0200 NetworkManager[1052]: <trace> [1715066720.7193] platform-linux: delayed-action: complete wait-for-response-rtnl (seq 87, timeout in 0.199261505, response-type 1, success)
2024-05-07T09:25:20.719714+0200 NetworkManager[1052]: <trace> [1715066720.7196] l3cfg[d361507385f3776b,ifindex=2]: emit signal (platform-change-on-idle, obj-type-flags=0x14)
2024-05-07T09:25:20.719787+0200 NetworkManager[1052]: <trace> [1715066720.7197] policy: set-hostname: updating hostname (address changed)
2024-05-07T09:25:20.719832+0200 NetworkManager[1052]: <trace> [1715066720.7198] hostname: transient hostname retrieval failed
2024-05-07T09:25:20.719883+0200 NetworkManager[1052]: <trace> [1715066720.7198] policy: get-hostname: "hostname"
2024-05-07T09:25:20.719927+0200 NetworkManager[1052]: <trace> [1715066720.7198] hostname: transient hostname retrieval failed
2024-05-07T09:25:20.719970+0200 NetworkManager[1052]: <trace> [1715066720.7199] policy: get-hostname: "hostname"
2024-05-07T09:25:20.720009+0200 NetworkManager[1052]: <trace> [1715066720.7199] policy: set-hostname: hostname already set to 'hostname' (from system configuration)
2024-05-07T09:25:20.724165+0200 NetworkManager[1052]: <trace> [1715066720.7240] l3cfg[d361507385f3776b,ifindex=2]: emit signal (acd-event, addr=192.168.199.118, state=external-removed)
2024-05-07T09:25:22.943569+0200 NetworkManager[1052]: <debug> [1715066722.9433] dhcp4 (end0): event: send DISCOVER to 255.255.255.255
2024-05-07T09:25:25.234433+0200 NetworkManager[1052]: <trace> [1715066725.2342] device[9a739dc311f1e5eb] (end0): ip:dhcp4: DHCP failing: timeout getting lease
2024-05-07T09:25:25.234516+0200 NetworkManager[1052]: <debug> [1715066725.2344] device[9a739dc311f1e5eb] (end0): ip:dhcp4: set state fail (was done)
2024-05-07T09:25:25.234567+0200 NetworkManager[1052]: <trace> [1715066725.2345] l3cfg[d361507385f3776b,ifindex=2]: IP configuration changed (mark dirty)
2024-05-07T09:25:25.234615+0200 NetworkManager[1052]: <trace> [1715066725.2345] l3cfg[d361507385f3776b,ifindex=2]: commit on idle (scheduled) (auto)
2024-05-07T09:25:25.237395+0200 NetworkManager[1052]: <trace> [1715066725.2362] l3cfg[d361507385f3776b,ifindex=2]: commit update (auto) (idle handler)
2024-05-07T09:25:25.237620+0200 NetworkManager[1052]: <trace> [1715066725.2375] l3cfg[d361507385f3776b,ifindex=2]: emit signal (l3cd-changed, l3cd-old=[2da2d4eb618e04b2], l3cd-new=[a16b80afd948c92b], commited=0)
2024-05-07T09:25:25.237760+0200 NetworkManager[1052]: <debug> [1715066725.2377] l3cfg[d361507385f3776b,ifindex=2]: obj-state: untrack: [8670dc1dd491cb92, ip4-route, type unicast 192.168.199.0/24 dev 2 metric 100 mss 0 rt-src rt-kernel scope link pref-src 192.168.199.118], nm-configured, was-in-platform
2024-05-07T09:25:25.237843+0200 NetworkManager[1052]: <debug> [1715066725.2378] l3cfg[d361507385f3776b,ifindex=2]: obj-state: untrack: [69634838c18c8220, ip4-address, 192.168.199.118/24 brd* 192.168.199.255 lft 0sec pref 0sec lifetime 8029-7904[120,120] dev 2 src dhcp], nm-configured, was-in-platform
2024-05-07T09:25:25.237897+0200 NetworkManager[1052]: <debug> [1715066725.2378] l3cfg[d361507385f3776b,ifindex=2]: obj-state: untrack: [85202f2ae085e75e, ip4-route, type unicast 0.0.0.0/0 via 192.168.199.1 dev 2 metric 20100 mss 0 rt-src dhcp pref-src 192.168.199.118], nm-configured, was-in-platform
2024-05-07T09:25:25.237952+0200 NetworkManager[1052]: <trace> [1715066725.2379] l3cfg[d361507385f3776b,ifindex=2]: emit signal (l3cd-changed, l3cd-old=[2da2d4eb618e04b2], l3cd-new=[a16b80afd948c92b], commited=1)
wireshark
shows that DISCOVER is sent at "2024-05-07 09:25:20.259384999" while the last ping reply is at "2024-05-07 09:25:20.715143210"
211235 2024-05-07 09:25:20.257435957 192.168.199.1 192.168.199.118 ICMP 98 Echo (ping) request id=0x10b9, seq=39419/64409, ttl=64 (reply in 211236)
211236 2024-05-07 09:25:20.258450334 192.168.199.118 192.168.199.1 ICMP 98 Echo (ping) reply id=0x10b9, seq=39419/64409, ttl=64 (request in 211235)
211237 2024-05-07 09:25:20.258455436 192.168.199.1 192.168.199.118 ICMP 98 Echo (ping) request id=0x10b9, seq=39420/64665, ttl=64 (reply in 211239)
211238 2024-05-07 09:25:20.259384999 0.0.0.0 255.255.255.255 DHCP 347 DHCP Discover - Transaction ID 0xa548882c
211239 2024-05-07 09:25:20.259710471 192.168.199.118 192.168.199.1 ICMP 98 Echo (ping) reply id=0x10b9, seq=39420/64665, ttl=64 (request in 211237)
211240 2024-05-07 09:25:20.259755958 192.168.199.1 192.168.199.118 ICMP 98 Echo (ping) request id=0x10b9, seq=39421/64921, ttl=64 (reply in 211241)
211241 2024-05-07 09:25:20.260763656 192.168.199.118 192.168.199.1 ICMP 98 Echo (ping) reply id=0x10b9, seq=39421/64921, ttl=64 (request in 211240)
211242 2024-05-07 09:25:20.260803331 192.168.199.1 192.168.199.118 ICMP 98 Echo (ping) request id=0x10b9, seq=39422/65177, ttl=64 (reply in 211243)
[...]
212304 2024-05-07 09:25:20.711001873 192.168.199.1 192.168.199.118 ICMP 98 Echo (ping) request id=0x10b9, seq=39950/3740, ttl=64 (reply in 212305)
212305 2024-05-07 09:25:20.711718802 192.168.199.118 192.168.199.1 ICMP 98 Echo (ping) reply id=0x10b9, seq=39950/3740, ttl=64 (request in 212304)
212306 2024-05-07 09:25:20.711770467 192.168.199.1 192.168.199.118 ICMP 98 Echo (ping) request id=0x10b9, seq=39951/3996, ttl=64 (reply in 212307)
212307 2024-05-07 09:25:20.713029550 192.168.199.118 192.168.199.1 ICMP 98 Echo (ping) reply id=0x10b9, seq=39951/3996, ttl=64 (request in 212306)
212308 2024-05-07 09:25:20.713079918 192.168.199.1 192.168.199.118 ICMP 98 Echo (ping) request id=0x10b9, seq=39952/4252, ttl=64 (reply in 212309)
212309 2024-05-07 09:25:20.714105234 192.168.199.118 192.168.199.1 ICMP 98 Echo (ping) reply id=0x10b9, seq=39952/4252, ttl=64 (request in 212308)
212310 2024-05-07 09:25:20.714118795 192.168.199.1 192.168.199.118 ICMP 98 Echo (ping) request id=0x10b9, seq=39953/4508, ttl=64 (reply in 212311)
212311 2024-05-07 09:25:20.715143210 192.168.199.118 192.168.199.1 ICMP 98 Echo (ping) reply id=0x10b9, seq=39953/4508, ttl=64 (request in 212310)
212312 2024-05-07 09:25:20.715154845 192.168.199.1 192.168.199.118 ICMP 98 Echo (ping) request id=0x10b9, seq=39954/4764, ttl=64 (no response found!)
212314 2024-05-07 09:25:20.730355801 192.168.199.1 192.168.199.118 ICMP 98 Echo (ping) request id=0x10b9, seq=39955/5020, ttl=64 (no response found!)