Re: dhcpcd 7.0.8 - Device did not check if it's original address was in use before probing for a new address
Stefano Cappa
Mon Jan 14 11:41:47 2019Oh good point. My dev board changes mac address every reboot.
Yes, because most of dev boards have random mac address by default and many
others can ask this.
Thank you very much for the interest to change the behaviour and for the
very fast responses. Really appreciated.
Il lun 14 gen 2019, 12:23 Roy Marples <roy@xxxxxxxxxxxx> ha scritto:
> 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
>
Archive administrator: postmaster@marples.name