dhcpcd-discuss

On Tuesday, October 21, 2014 11:47 AM, Roy Marples wrote:
> 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/df962c4b2df9834e7b6d0425bf
> d77e000c369456?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.

I am interested in your opinion/gut feeling about this. Mine tells me that this is the incorrect behaviour - i.e., there is now a DHCP server present on the network and the DHCP client now first try to establish contact with it. Another way to look at this is if I brought the interface down (ifdown eth1) and then back up (ifup eth1) the client would indeed establish contact with the DHCP server (and not attempt to renew the old IPV4LL lease).

Thanks,
-David

> Thanks
> 
> Roy