dhcpcd-discuss

Home Other Lists Thread Index Date Index Search
Thread Prev Thread Next Date Prev Date Next Thread Index Date Index

Re: dhcpcd 7.0.8 - Device did not check if it's original address was in use before probing for a new address

Roy Marples

Mon Jan 14 11:22:45 2019
On 13/01/2019 17:57, Stefano Cappa wrote:
I'm trying to run Apple BonjourConformanceTest 1.5.0 to test my device with dhcpcd.
In particular this *ipv4 Link-Local sub-test called "Cable Change Handling"*: 
*Cable Change Handling ("hot-plugging")
*The operator disconnects and reconnects the device's network cable. The test tool verifies that *the device repeats its address probing to verify that its address is still unique.  The test tool *denies the first probe and verifies that the device picks a new address and probes/announces *again.  It is a warning if the device does not use its original address as its first probing candidate.
When I was using dhcpcd 6.11.5 this test was ok, but with dhcpcd 7.0.8 it throws an error.
This is the log (with only the relevant part, but if you want I can share the full log): 

START (SUBSEQUENT CONFLICTS)
(...)
DEBUG_2 12:18:39.324487: source Mac:0:4:9f:5:c:f9, source IP:169.254.224.168, target Mac:0:0:0:0:0:0, target IP:169.254.224.168 
NOTICE  12:18:39.324521: Received announcement from     169.254.224.168
PASSED (SUBSEQUENT CONFLICTS)

Press enter to continue.
*
*
*START (CABLE CHANGE HANDLING)*
Please unplug the device's network cable for ten seconds and then reconnect.
For a device being tested over its wireless interface, cause the interface to disassociate from the access point and then re-associate with the access point. 

DEBUG_2 12:18:49.331166: Device name: en7
DEBUG_2 12:19:08.721914: source Mac:0:4:9f:5:c:f9, source IP:0.0.0.0, target Mac:0:0:0:0:0:0, target IP:169.254.19.151 *ERROR   12:19:08.721996: Device did not check if it's original address was in use before probing for a new address  ...continuing* 
NOTICE  12:19:08.722008: Denying probe for              169.254.19.151
DEBUG_2 12:19:08.722096: Denying ARP for 169.254.19.151
DEBUG_2 12:19:08.722266: Device name: en7
DEBUG_2 12:19:08.733324: source Mac:0:e0:4c:36:0:13, source IP:169.254.19.151, target Mac:0:4:9f:5:c:f9, target IP:0.0.0.0 
DEBUG_2 12:19:09.310409: Ignoring packet from base station : 169.254.90.201
DEBUG_2 12:19:09.310453: timeout: to_ms 50, timedif_ms 51
DEBUG_2 12:19:09.733606: source Mac:0:4:9f:5:c:f9, source IP:0.0.0.0, target Mac:0:0:0:0:0:0, target IP:169.254.122.252 DEBUG_2 12:19:09.733663: new_device_mac: 0:4:9f:5:c:f9, ts->device_mac: 0:4:9f:5:c:f9 
NOTICE  12:19:09.733686: Received probe for new address 169.254.122.252
DEBUG_2 12:19:09.733807: Device name: en7
DEBUG_2 12:19:10.779044: source Mac:0:4:9f:5:c:f9, source IP:0.0.0.0, target Mac:0:0:0:0:0:0, target IP:169.254.122.252 
NOTICE  12:19:10.779096: Received probe from            169.254.122.252
DEBUG_2 12:19:10.779214: Device name: en7
DEBUG_2 12:19:12.552533: source Mac:0:4:9f:5:c:f9, source IP:0.0.0.0, target Mac:0:0:0:0:0:0, target IP:169.254.122.252 
NOTICE  12:19:12.552588: Received probe from            169.254.122.252
DEBUG_2 12:19:12.552704: Device name: en7
DEBUG_2 12:19:14.582095: source Mac:0:4:9f:5:c:f9, source IP:169.254.122.252, target Mac:0:0:0:0:0:0, target IP:169.254.122.252 
DEBUG_2 12:19:14.582254: Device name: en7
DEBUG_2 12:19:15.877961: source Mac:0:4:9f:5:c:f9, source IP:169.254.122.252, target Mac:0:0:0:0:0:0, target IP:208.67.222.222 NOTICE  12:19:15.878017: arp src dst address mismatch: Did not receive 2 announcements after 3 unanswered probes., continuing 
NOTICE  12:19:15.878034: Received announcement from     208.67.222.222
PASSED (CABLE CHANGE HANDLING)
As you can see there is this error: "*ERROR   12:19:08.721996: Device did not check if it's original address was in use before probing for a new address  ...continuing*" 
With dhcpcd 6.0.8 this wasn't happening.

To run this test I executed dhcpcd with -d -B and this is the full log.
The important part in the last one, after my comment with //.

root@mydevice:~# dhcpcd -d -B -i eth0
dhcpcd-7.0.8 starting
eth0: executing `/usr/libexec/dhcpcd-run-hooks' PREINIT
eth0: executing `/usr/libexec/dhcpcd-run-hooks' NOCARRIER
no interfaces have a carrier
Micrel KSZ8081 or KSZ8091 2188000.ethernet-1:02: attached PHY driver [Micrel KSZ8081 or KSZ8091] (mii_bus:phy_addr=2188000.ethernet-1:02, irq=-1) 
IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
eth0: waiting for carrier
fec 2188000.ethernet eth0: Link is Up - 100Mbps/Full - flow control rx/tx
IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
eth0: carrier acquired
eth0: executing `/usr/libexec/dhcpcd-run-hooks' CARRIER
DUID 00:01:00:01:c7:92:bc:94:00:04:9f:05:0c:f9
eth0: IAID 9f:05:0c:f9
eth0: adding address fe80::fb05:2338:66f3:3187
eth0: pltime infinity, vltime infinity
eth0: delaying IPv6 router solicitation for 0.6 seconds
eth0: delaying IPv4 for 0.6 seconds
eth0: soliciting an IPv6 router
eth0: delaying Router Solicitation for LL address
eth0: soliciting a DHCP lease
eth0: sending DISCOVER (xid 0x4e5bfa8e), next in 4.4 seconds
eth0: sending Router Solicitation
eth0: sending DISCOVER (xid 0x4e5bfa8e), next in 8.7 seconds
eth0: sending Router Solicitation
eth0: probing for an IPv4LL address
eth0: probing for 169.254.19.151
eth0: ARP probing 169.254.19.151 (1 of 3), next in 2.0 seconds
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.19.151
eth0: probing for 169.254.122.252
eth0: ARP probing 169.254.122.252 (1 of 3), next in 1.2 seconds
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.122.252
eth0: probing for 169.254.144.80
eth0: ARP probing 169.254.144.80 (1 of 3), next in 1.2 seconds
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.144.80
eth0: probing for 169.254.235.103
eth0: ARP probing 169.254.235.103 (1 of 3), next in 1.1 seconds
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.235.103
eth0: sending Router Solicitation
eth0: probing for 169.254.156.219
eth0: ARP probing 169.254.156.219 (1 of 3), next in 1.2 seconds
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.156.219
eth0: probing for 169.254.31.200
eth0: ARP probing 169.254.31.200 (1 of 3), next in 1.9 seconds
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.31.200
eth0: probing for 169.254.214.144
eth0: ARP probing 169.254.214.144 (1 of 3), next in 1.3 seconds
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.214.144
eth0: probing for 169.254.84.0
eth0: ARP probing 169.254.84.0 (1 of 3), next in 1.9 seconds
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.84.0
eth0: sending Router Solicitation
eth0: no IPv6 Routers available
eth0: sending DISCOVER (xid 0x4e5bfa8e), next in 15.2 seconds
eth0: probing for 169.254.51.248
eth0: ARP probing 169.254.51.248 (1 of 3), next in 1.2 seconds
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.51.248
eth0: probing for 169.254.52.202
eth0: ARP probing 169.254.52.202 (1 of 3), next in 1.9 seconds
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.52.202
eth0: failed to acquire an IPv4LL address: No such file or directory
eth0: sending DISCOVER (xid 0x4e5bfa8e), next in 31.2 seconds
eth0: sending DISCOVER (xid 0x4e5bfa8e), next in 63.9 seconds
eth0: probing for 169.254.194.128
eth0: ARP probing 169.254.194.128 (1 of 3), next in 1.2 seconds
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.194.128
eth0: sending DISCOVER (xid 0x4e5bfa8e), next in 64.5 seconds
eth0: probing for 169.254.198.183
eth0: ARP probing 169.254.198.183 (1 of 3), next in 1.1 seconds
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.198.183
eth0: sending DISCOVER (xid 0x4e5bfa8e), next in 63.0 seconds
eth0: probing for 169.254.184.88
eth0: ARP probing 169.254.184.88 (1 of 3), next in 1.8 seconds
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.184.88
eth0: sending DISCOVER (xid 0x4e5bfa8e), next in 63.3 seconds
eth0: probing for 169.254.190.133
eth0: ARP probing 169.254.190.133 (1 of 3), next in 1.5 seconds
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.190.133
eth0: probing for 169.254.118.180
eth0: ARP probing 169.254.118.180 (1 of 3), next in 1.2 seconds
eth0: sending DISCOVER (xid 0x4e5bfa8e), next in 63.9 seconds
eth0: ARP probing 169.254.118.180 (2 of 3), next in 1.1 seconds
eth0: ARP probing 169.254.118.180 (3 of 3), next in 2.0 seconds
eth0: using IPv4LL address 169.254.118.180
eth0: adding IP address 169.254.118.180/16 <http://169.254.118.180/16> broadcast 169.254.255.255 
eth0: adding route to 169.254.0.0/16 <http://169.254.0.0/16>
eth0: adding default route
eth0: ARP announcing 169.254.118.180 (1 of 2), next in 2.0 seconds
eth0: executing `/usr/libexec/dhcpcd-run-hooks' IPV4LL
eth0: ARP announcing 169.254.118.180 (2 of 2)
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.118.180
eth0: defended IPv4LL address 169.254.118.180/16 <http://169.254.118.180/16>
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.118.180
eth0: IPv4LL 10 second defence failed for 169.254.118.180/16 <http://169.254.118.180/16> 
eth0: deleting IP address 169.254.118.180/16 <http://169.254.118.180/16>
eth0: executing `/usr/libexec/dhcpcd-run-hooks' IPV4LL
eth0: probing for 169.254.224.168
eth0: ARP probing 169.254.224.168 (1 of 3), next in 1.7 seconds
eth0: ARP probing 169.254.224.168 (2 of 3), next in 1.6 seconds
eth0: ARP probing 169.254.224.168 (3 of 3), next in 2.0 seconds
eth0: using IPv4LL address 169.254.224.168
eth0: adding IP address 169.254.224.168/16 <http://169.254.224.168/16> broadcast 169.254.255.255 
eth0: changing route to 169.254.0.0/16 <http://169.254.0.0/16>
eth0: changing default route
eth0: ARP announcing 169.254.224.168 (1 of 2), next in 2.0 seconds
eth0: executing `/usr/libexec/dhcpcd-run-hooks' IPV4LL
eth0: ARP announcing 169.254.224.168 (2 of 2)
// I disconnect the cable as requested by the certification tool, then I wait 10 seconds and I reconnecte eth cable 




fec 2188000.ethernet eth0: Link is Down
eth0: carrier lost
eth0: executing `/usr/libexec/dhcpcd-run-hooks' NOCARRIER
eth0: deleting address fe80::fb05:2338:66f3:3187
eth0: deleting IP address 169.254.224.168/16 <http://169.254.224.168/16>
eth0: deleting route to 169.254.0.0/16 <http://169.254.0.0/16>
eth0: deleting default route
eth0: executing `/usr/libexec/dhcpcd-run-hooks' IPV4LL
eth0: executing `/usr/libexec/dhcpcd-run-hooks' EXPIRE
fec 2188000.ethernet eth0: Link is Up - 100Mbps/Full - flow control rx/tx
eth0: carrier acquired
eth0: executing `/usr/libexec/dhcpcd-run-hooks' CARRIER
eth0: IAID 9f:05:0c:f9
eth0: adding address fe80::fb05:2338:66f3:3187
eth0: pltime infinity, vltime infinity
eth0: delaying IPv6 router solicitation for 0.1 seconds
eth0: delaying IPv4 for 0.3 seconds
eth0: soliciting an IPv6 router
eth0: delaying Router Solicitation for LL address
eth0: soliciting a DHCP lease
eth0: sending DISCOVER (xid 0xf803177e), next in 4.4 seconds
eth0: sending Router Solicitation
eth0: sending DISCOVER (xid 0xf803177e), next in 8.4 seconds
eth0: probing for an IPv4LL address
eth0: probing for 169.254.19.151
eth0: ARP probing 169.254.19.151 (1 of 3), next in 1.2 seconds
eth0: hardware address 00:e0:4c:36:00:13 claims 169.254.19.151
eth0: sending Router Solicitation
eth0: probing for 169.254.122.252
eth0: ARP probing 169.254.122.252 (1 of 3), next in 1.0 seconds
eth0: ARP probing 169.254.122.252 (2 of 3), next in 1.8 seconds
eth0: ARP probing 169.254.122.252 (3 of 3), next in 2.0 seconds
eth0: sending Router Solicitation
eth0: using IPv4LL address 169.254.122.252
eth0: adding IP address 169.254.122.252/16 <http://169.254.122.252/16> broadcast 169.254.255.255 
eth0: adding route to 169.254.0.0/16 <http://169.254.0.0/16>
eth0: adding default route
eth0: ARP announcing 169.254.122.252 (1 of 2), next in 2.0 seconds
eth0: executing `/usr/libexec/dhcpcd-run-hooks' IPV4LL
eth0: sending DISCOVER (xid 0xf803177e), next in 16.4 seconds
eth0: ARP announcing 169.254.122.252 (2 of 2)

// test already finished before, so I killed the process

received SIGINT, stopping
eth0: removing interface
eth0: executing `/usr/libexec/dhcpcd-run-hooks' STOPPED
dhcpcd exited

What do you think?
dhcpcd treats the link down/up event as a reboot, thus seeds the random number from the hardware address. 
This can be changed, will work on it.

Roy
Follow-Ups:
Re: dhcpcd 7.0.8 - Device did not check if it's original address was in use before probing for a new addressRoy Marples
Re: dhcpcd 7.0.8 - Device did not check if it's original address was in use before probing for a new addressStefano Cappa
References:
dhcpcd 7.0.8 - Device did not check if it's original address was in use before probing for a new addressStefano Cappa
Archive administrator: postmaster@marples.name