dhcpcd-discuss

On Tuesday, October 21, 2014 9:00 AM, David Hauck wrote:
> Hi Roy,
> 
> On Tuesday, October 21, 2014 4:24 AM, Roy Marples wrote:
>> Hi David
>> 
>> On 20/10/2014 20:46, David Hauck wrote:

<snip>

>> Because dhcpcd did actually assign the address, the IPv4LL conflict
>> counter was reset and started the process over.
>> 
>> This is fixed here:
>> 
>> http://roy.marples.name/projects/dhcpcd/ci/36e83c64395acafc9030cadef3b
>> 5fd3082edccbd?sbs=0
>> 
>> Basically we now only reset the conflict counter after the
>> announcing is complete or we bind a non IPv4LL address. If we hit
>> the conflict counter dhcpcd now transitions back to DHCP discovery.
> 
> What is the conflict "counter"?
> 
>> Another minor related issue is fixed here:
>> 
>> http://roy.marples.name/projects/dhcpcd/ci/528f024cddbc23e7589eaf9f2e8
>> c54ad7408277e?sbs=0
> 
> I'll integrate both of these and let you know what I find.

These changes help the expiry transition to DHCP DISCOVER now, so this is working to get a proper exchange happening with the connected DHCP server once C2 is connected. Here's the trace (and see below for a question):

20141021 10:12:43.724 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' NOCARRIER
20141021 10:12:43.741 debug daemon(dhcpcd):eth1: deleting IP address 169.254.157.126/16
20141021 10:12:43.741 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' EXPIRE
20141021 10:12:48.424 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' CARRIER
20141021 10:12:48.433 debug daemon(dhcpcd):eth1: delaying IPv4 for 0.9 seconds
20141021 10:12:49.348 debug daemon(dhcpcd):eth1: reading lease `/var/db/dhcpcd-eth1.lease'
20141021 10:12:49.351 debug daemon(dhcpcd):eth1: checking for 169.254.157.126
20141021 10:12:49.352 debug daemon(dhcpcd):eth1: sending ARP probe (1 of 3), next in 1.8 seconds
20141021 10:12:51.122 debug daemon(dhcpcd):eth1: sending ARP probe (2 of 3), next in 1.4 seconds
20141021 10:12:52.557 debug daemon(dhcpcd):eth1: sending ARP probe (3 of 3), next in 2.0 seconds
20141021 10:12:54.560 debug daemon(dhcpcd):eth1: writing lease `/var/db/dhcpcd-eth1.lease'
20141021 10:12:54.560 debug daemon(dhcpcd):eth1: adding IP address 169.254.157.126/16
20141021 10:12:54.560 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' IPV4LL
20141021 10:12:54.571 debug daemon(dhcpcd):eth1: sending ARP announce (1 of 2), next in 2.0 seconds
20141021 10:12:54.572 debug daemon(dhcpcd):eth1: defended IPv4LL address 169.254.157.126
20141021 10:12:54.674 debug daemon(dhcpcd):eth1: xid 0x3fc9f1f3 is for hwaddr 00:26:18:fe:77:8e:00:00:00:00:00:00:00:00:00:00
20141021 10:12:56.573 debug daemon(dhcpcd):eth1: sending ARP announce (2 of 2)
20141021 10:12:56.573 debug daemon(dhcpcd):eth1: IPv4LL 10 second defence failed for 169.254.157.126
20141021 10:12:56.582 debug daemon(dhcpcd):eth1: deleting IP address 169.254.157.126/16
20141021 10:12:56.582 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' EXPIRE
20141021 10:12:57.596 debug daemon(dhcpcd):eth1: checking for 169.254.99.201
20141021 10:12:57.597 debug daemon(dhcpcd):eth1: sending ARP probe (1 of 3), next in 1.7 seconds
20141021 10:12:59.333 debug daemon(dhcpcd):eth1: sending ARP probe (2 of 3), next in 1.4 seconds
20141021 10:13:00.773 debug daemon(dhcpcd):eth1: sending ARP probe (3 of 3), next in 2.0 seconds
20141021 10:13:02.773 debug daemon(dhcpcd):eth1: writing lease `/var/db/dhcpcd-eth1.lease'
20141021 10:13:02.774 debug daemon(dhcpcd):eth1: adding IP address 169.254.99.201/16
20141021 10:13:02.774 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' IPV4LL
20141021 10:13:02.786 debug daemon(dhcpcd):eth1: sending ARP announce (1 of 2), next in 2.0 seconds
20141021 10:13:02.786 debug daemon(dhcpcd):eth1: defended IPv4LL address 169.254.99.201
20141021 10:13:04.788 debug daemon(dhcpcd):eth1: sending ARP announce (2 of 2)
20141021 10:13:04.788 debug daemon(dhcpcd):eth1: IPv4LL 10 second defence failed for 169.254.99.201
20141021 10:13:04.793 debug daemon(dhcpcd):eth1: deleting IP address 169.254.99.201/16
20141021 10:13:04.793 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' EXPIRE
20141021 10:13:05.820 debug daemon(dhcpcd):eth1: checking for 169.254.200.242
20141021 10:13:05.820 debug daemon(dhcpcd):eth1: sending ARP probe (1 of 3), next in 1.5 seconds
20141021 10:13:07.292 debug daemon(dhcpcd):eth1: sending ARP probe (2 of 3), next in 1.7 seconds
20141021 10:13:08.976 debug daemon(dhcpcd):eth1: sending ARP probe (3 of 3), next in 2.0 seconds
20141021 10:13:10.977 debug daemon(dhcpcd):eth1: writing lease `/var/db/dhcpcd-eth1.lease'
20141021 10:13:10.991 debug daemon(dhcpcd):eth1: adding IP address 169.254.200.242/16
20141021 10:13:10.991 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' IPV4LL
20141021 10:13:11.004 debug daemon(dhcpcd):eth1: sending ARP announce (1 of 2), next in 2.0 seconds
20141021 10:13:11.004 debug daemon(dhcpcd):eth1: defended IPv4LL address 169.254.200.242
20141021 10:13:13.006 debug daemon(dhcpcd):eth1: sending ARP announce (2 of 2)
20141021 10:13:13.006 debug daemon(dhcpcd):eth1: IPv4LL 10 second defence failed for 169.254.200.242
20141021 10:13:13.010 debug daemon(dhcpcd):eth1: deleting IP address 169.254.200.242/16
20141021 10:13:13.011 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' EXPIRE
20141021 10:13:14.026 debug daemon(dhcpcd):eth1: checking for 169.254.29.85
20141021 10:13:14.026 debug daemon(dhcpcd):eth1: sending ARP probe (1 of 3), next in 1.4 seconds
20141021 10:13:15.429 debug daemon(dhcpcd):eth1: sending ARP probe (2 of 3), next in 1.7 seconds
20141021 10:13:17.150 debug daemon(dhcpcd):eth1: sending ARP probe (3 of 3), next in 2.0 seconds
20141021 10:13:19.150 debug daemon(dhcpcd):eth1: writing lease `/var/db/dhcpcd-eth1.lease'
20141021 10:13:19.150 debug daemon(dhcpcd):eth1: adding IP address 169.254.29.85/16
20141021 10:13:19.151 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' IPV4LL
20141021 10:13:19.162 debug daemon(dhcpcd):eth1: sending ARP announce (1 of 2), next in 2.0 seconds
20141021 10:13:19.162 debug daemon(dhcpcd):eth1: defended IPv4LL address 169.254.29.85
20141021 10:13:21.162 debug daemon(dhcpcd):eth1: sending ARP announce (2 of 2)
20141021 10:13:21.162 debug daemon(dhcpcd):eth1: IPv4LL 10 second defence failed for 169.254.29.85
20141021 10:13:21.165 debug daemon(dhcpcd):eth1: deleting IP address 169.254.29.85/16
20141021 10:13:21.166 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' EXPIRE
20141021 10:13:22.189 debug daemon(dhcpcd):eth1: checking for 169.254.50.236
20141021 10:13:22.189 debug daemon(dhcpcd):eth1: sending ARP probe (1 of 3), next in 1.4 seconds
20141021 10:13:23.629 debug daemon(dhcpcd):eth1: sending ARP probe (2 of 3), next in 1.8 seconds
20141021 10:13:25.388 debug daemon(dhcpcd):eth1: sending ARP probe (3 of 3), next in 2.0 seconds
20141021 10:13:27.389 debug daemon(dhcpcd):eth1: writing lease `/var/db/dhcpcd-eth1.lease'
20141021 10:13:27.396 debug daemon(dhcpcd):eth1: adding IP address 169.254.50.236/16
20141021 10:13:27.397 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' IPV4LL
20141021 10:13:27.409 debug daemon(dhcpcd):eth1: sending ARP announce (1 of 2), next in 2.0 seconds
20141021 10:13:27.409 debug daemon(dhcpcd):eth1: defended IPv4LL address 169.254.50.236
20141021 10:13:29.410 debug daemon(dhcpcd):eth1: sending ARP announce (2 of 2)
20141021 10:13:29.410 debug daemon(dhcpcd):eth1: IPv4LL 10 second defence failed for 169.254.50.236
20141021 10:13:29.414 debug daemon(dhcpcd):eth1: deleting IP address 169.254.50.236/16
20141021 10:13:29.415 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' EXPIRE
20141021 10:13:30.429 debug daemon(dhcpcd):eth1: checking for 169.254.36.189
20141021 10:13:30.430 debug daemon(dhcpcd):eth1: sending ARP probe (1 of 3), next in 1.9 seconds
20141021 10:13:32.354 debug daemon(dhcpcd):eth1: sending ARP probe (2 of 3), next in 1.1 seconds
20141021 10:13:33.420 debug daemon(dhcpcd):eth1: sending ARP probe (3 of 3), next in 2.0 seconds
20141021 10:13:35.422 debug daemon(dhcpcd):eth1: writing lease `/var/db/dhcpcd-eth1.lease'
20141021 10:13:35.423 debug daemon(dhcpcd):eth1: adding IP address 169.254.36.189/16
20141021 10:13:35.423 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' IPV4LL
20141021 10:13:35.434 debug daemon(dhcpcd):eth1: sending ARP announce (1 of 2), next in 2.0 seconds
20141021 10:13:35.434 debug daemon(dhcpcd):eth1: defended IPv4LL address 169.254.36.189
20141021 10:13:37.435 debug daemon(dhcpcd):eth1: sending ARP announce (2 of 2)
20141021 10:13:37.435 debug daemon(dhcpcd):eth1: IPv4LL 10 second defence failed for 169.254.36.189
20141021 10:13:37.439 debug daemon(dhcpcd):eth1: deleting IP address 169.254.36.189/16
20141021 10:13:37.440 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' EXPIRE
20141021 10:13:38.462 debug daemon(dhcpcd):eth1: checking for 169.254.176.28
20141021 10:13:38.463 debug daemon(dhcpcd):eth1: sending ARP probe (1 of 3), next in 1.2 seconds
20141021 10:13:39.671 debug daemon(dhcpcd):eth1: sending ARP probe (2 of 3), next in 1.8 seconds
20141021 10:13:41.447 debug daemon(dhcpcd):eth1: sending ARP probe (3 of 3), next in 2.0 seconds
20141021 10:13:43.448 debug daemon(dhcpcd):eth1: writing lease `/var/db/dhcpcd-eth1.lease'
20141021 10:13:43.448 debug daemon(dhcpcd):eth1: adding IP address 169.254.176.28/16
20141021 10:13:43.448 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' IPV4LL
20141021 10:13:43.459 debug daemon(dhcpcd):eth1: sending ARP announce (1 of 2), next in 2.0 seconds
20141021 10:13:43.459 debug daemon(dhcpcd):eth1: defended IPv4LL address 169.254.176.28
20141021 10:13:45.460 debug daemon(dhcpcd):eth1: sending ARP announce (2 of 2)
20141021 10:13:45.460 debug daemon(dhcpcd):eth1: IPv4LL 10 second defence failed for 169.254.176.28
20141021 10:13:45.464 debug daemon(dhcpcd):eth1: deleting IP address 169.254.176.28/16
20141021 10:13:45.465 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' EXPIRE
20141021 10:13:46.479 debug daemon(dhcpcd):eth1: checking for 169.254.202.212
20141021 10:13:46.480 debug daemon(dhcpcd):eth1: sending ARP probe (1 of 3), next in 1.4 seconds
20141021 10:13:47.924 debug daemon(dhcpcd):eth1: sending ARP probe (2 of 3), next in 1.1 seconds
20141021 10:13:49.032 debug daemon(dhcpcd):eth1: sending ARP probe (3 of 3), next in 2.0 seconds
20141021 10:13:51.033 debug daemon(dhcpcd):eth1: writing lease `/var/db/dhcpcd-eth1.lease'
20141021 10:13:51.034 debug daemon(dhcpcd):eth1: adding IP address 169.254.202.212/16
20141021 10:13:51.034 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' IPV4LL
20141021 10:13:51.045 debug daemon(dhcpcd):eth1: sending ARP announce (1 of 2), next in 2.0 seconds
20141021 10:13:51.045 debug daemon(dhcpcd):eth1: defended IPv4LL address 169.254.202.212
20141021 10:13:53.047 debug daemon(dhcpcd):eth1: sending ARP announce (2 of 2)
20141021 10:13:53.047 debug daemon(dhcpcd):eth1: IPv4LL 10 second defence failed for 169.254.202.212
20141021 10:13:53.050 debug daemon(dhcpcd):eth1: deleting IP address 169.254.202.212/16
20141021 10:13:53.051 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' EXPIRE
20141021 10:13:54.065 debug daemon(dhcpcd):eth1: checking for 169.254.215.203
20141021 10:13:54.066 debug daemon(dhcpcd):eth1: sending ARP probe (1 of 3), next in 1.9 seconds
20141021 10:13:56.010 debug daemon(dhcpcd):eth1: sending ARP probe (2 of 3), next in 1.7 seconds
20141021 10:13:57.686 debug daemon(dhcpcd):eth1: sending ARP probe (3 of 3), next in 2.0 seconds
20141021 10:13:59.688 debug daemon(dhcpcd):eth1: writing lease `/var/db/dhcpcd-eth1.lease'
20141021 10:13:59.688 debug daemon(dhcpcd):eth1: adding IP address 169.254.215.203/16
20141021 10:13:59.688 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' IPV4LL
20141021 10:13:59.699 debug daemon(dhcpcd):eth1: sending ARP announce (1 of 2), next in 2.0 seconds
20141021 10:13:59.700 debug daemon(dhcpcd):eth1: defended IPv4LL address 169.254.215.203
20141021 10:14:01.699 debug daemon(dhcpcd):eth1: sending ARP announce (2 of 2)
20141021 10:14:01.700 debug daemon(dhcpcd):eth1: IPv4LL 10 second defence failed for 169.254.215.203
20141021 10:14:01.703 debug daemon(dhcpcd):eth1: deleting IP address 169.254.215.203/16
20141021 10:14:01.704 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' EXPIRE
20141021 10:14:02.727 debug daemon(dhcpcd):eth1: checking for 169.254.138.176
20141021 10:14:02.728 debug daemon(dhcpcd):eth1: sending ARP probe (1 of 3), next in 1.4 seconds
20141021 10:14:04.122 debug daemon(dhcpcd):eth1: sending ARP probe (2 of 3), next in 1.4 seconds
20141021 10:14:05.556 debug daemon(dhcpcd):eth1: sending ARP probe (3 of 3), next in 2.0 seconds
20141021 10:14:07.558 debug daemon(dhcpcd):eth1: writing lease `/var/db/dhcpcd-eth1.lease'
20141021 10:14:07.559 debug daemon(dhcpcd):eth1: adding IP address 169.254.138.176/16
20141021 10:14:07.559 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' IPV4LL
20141021 10:14:07.570 debug daemon(dhcpcd):eth1: sending ARP announce (1 of 2), next in 2.0 seconds
20141021 10:14:07.570 debug daemon(dhcpcd):eth1: defended IPv4LL address 169.254.138.176
20141021 10:14:09.572 debug daemon(dhcpcd):eth1: sending ARP announce (2 of 2)
20141021 10:14:09.572 debug daemon(dhcpcd):eth1: IPv4LL 10 second defence failed for 169.254.138.176
20141021 10:14:09.577 debug daemon(dhcpcd):eth1: deleting IP address 169.254.138.176/16
20141021 10:14:09.577 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' EXPIRE
20141021 10:14:10.593 debug daemon(dhcpcd):eth1: checking for 169.254.69.165
20141021 10:14:10.593 debug daemon(dhcpcd):eth1: sending ARP probe (1 of 3), next in 1.4 seconds
20141021 10:14:11.965 debug daemon(dhcpcd):eth1: sending ARP probe (2 of 3), next in 1.4 seconds
20141021 10:14:13.332 debug daemon(dhcpcd):eth1: sending ARP probe (3 of 3), next in 2.0 seconds
20141021 10:14:15.334 debug daemon(dhcpcd):eth1: writing lease `/var/db/dhcpcd-eth1.lease'
20141021 10:14:15.334 debug daemon(dhcpcd):eth1: adding IP address 169.254.69.165/16
20141021 10:14:15.348 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' IPV4LL
20141021 10:14:15.353 debug daemon(dhcpcd):eth1: sending ARP announce (1 of 2), next in 2.0 seconds
20141021 10:14:15.353 debug daemon(dhcpcd):eth1: defended IPv4LL address 169.254.69.165
20141021 10:14:17.353 debug daemon(dhcpcd):eth1: sending ARP announce (2 of 2)
20141021 10:14:17.353 debug daemon(dhcpcd):eth1: IPv4LL 10 second defence failed for 169.254.69.165
20141021 10:14:17.356 debug daemon(dhcpcd):eth1: deleting IP address 169.254.69.165/16
20141021 10:14:17.357 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' EXPIRE
20141021 10:14:17.366 debug daemon(dhcpcd):eth1: sending DISCOVER (xid 0x46f15e38), next in 60.4 seconds
20141021 10:14:17.370 debug daemon(dhcpcd):eth1: sending REQUEST (xid 0x46f15e38), next in 4.6 seconds
20141021 10:14:17.371 debug daemon(dhcpcd):eth1: acknowledged 205.159.216.180 from 205.159.216.146
20141021 10:14:17.376 debug daemon(dhcpcd):eth1: checking for 205.159.216.180
20141021 10:14:17.377 debug daemon(dhcpcd):eth1: sending ARP probe (1 of 3), next in 1.4 seconds
20141021 10:14:18.757 debug daemon(dhcpcd):eth1: sending ARP probe (2 of 3), next in 1.1 seconds
20141021 10:14:19.887 debug daemon(dhcpcd):eth1: sending ARP probe (3 of 3), next in 2.0 seconds
20141021 10:14:21.889 debug daemon(dhcpcd):eth1: renew in 14400 seconds, rebind in 25200 seconds
20141021 10:14:21.889 debug daemon(dhcpcd):eth1: writing lease `/var/db/dhcpcd-eth1.lease'
20141021 10:14:21.889 debug daemon(dhcpcd):eth1: adding IP address 205.159.216.180/25
20141021 10:14:21.889 debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' BOUND
20141021 10:14:21.916 debug daemon(dhcpcd):eth1: sending ARP announce (1 of 2), next in 2.0 seconds
20141021 10:14:23.918 debug daemon(dhcpcd):eth1: sending ARP announce (2 of 2)

It looks like there were 11 expiry events after C2 was re-connected. So it appears that 11 IPV4LL cycles occurred (i.e., attempted 11 IPV4LL addresses) before sending the DHCP DISCOVER. I would have thought, instead, this transition would have occurred earlier (i.e., either right after CARRIER was detected or after the first failed attempt to recover the original IPV4LL lease). This all really points to whether the transition out of IPV4LL, after a link failure, should return to the original DHCP INIT state when the link is re-established instead of to a state where the lease is used to attempt to re-establish the embedded IPV4LL (i.e., transitioning back to the IPV4LL state). This is where, in my mind, the IPV4LL state is different than the normal BOUND state wrt loss of link.

What do you think? If there's a reference to some guidance in the specification that clarifies this I'd be interested in getting a pointer to it to see if can clarify things for me/us.

Thanks,
-David