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 18:45:14 2019
Oh no, sorry, I didn't understand the problem.
The problem is when the cable in unplugged and not a reboot the device.
My mistake. Also the same happens with a fixed mac address.
Il giorno lun 14 gen 2019 alle ore 12:41 Stefano Cappa <
stefano.cappa.ks89@xxxxxxxxx> ha scritto:
> Oh 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