dhcpcd-discuss

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

Stefano Cappa

Sun Jan 13 18:05:28 2019

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 broadcast 169.254.255.255
eth0: adding route to 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
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
eth0: deleting IP address 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 broadcast 169.254.255.255
eth0: changing route to 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
eth0: deleting route to 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 broadcast 169.254.255.255
eth0: adding route to 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?

thank u.

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
Archive administrator: postmaster@marples.name