dhcpcd-discuss

On 21/10/2014 18:31, David Hauck wrote:
> 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.

This is an off by one error, it should be MAX_CONFLICTS (10) from
RFC3927, section 9.
http://roy.marples.name/projects/dhcpcd/ci/df962c4b2df9834e7b6d0425bfd77e000c369456?sbs=0

> 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.

I don't think there is any guidance as such.

In the ideal world we should attempt both DHCP and IPv4LL at the same
time, but the dhcpcd event loop cannot do that easily yet. One
possibility is to create a pseudo interface for it as we do for the
IA_NA + IA_PD DHCPv6 case, but that was very hard to manage.

But right now, dhcpcd rightly or wrongly attempts to configure IPv4LL on
carrier up if the last address was IPv4LL.

Thanks

Roy