dhcpcd-discuss

On Friday, October 17, 2014 2:52 PM, David Hauck wrote:
> On Friday, October 17, 2014 2:05 PM, David Hauck wrote:
>> On Friday, October 17, 2014 2:00 PM, Roy Marples wrote:
>>> On 2014-10-17 16:56, David Hauck wrote:
>>>> On Friday, October 17, 2014 6:56 AM, Roy Marples wrote:
>>>>> On 17/10/2014 14:25, David Hauck wrote:
>>>>>>> I don't see this problem with dhcpcd-6.5.0 (well, the latest trunk).
>>>>>>> There was a problem, although unrelated, which resulted in this
>>>>>>> patch
>>>>>>> 
>>>>>>> 
>>>>>>> 
>>>>>>> 
>>>>>>> http://roy.marples.name/projects/dhcpcd/ci/4c1f2f8a298ad244f8c739
>>>>>>> 7 1 0b a e46088ea7efd6?sbs=0 But that patch means nothing for
>>>>>>> 6.1.0.
>>>>>>> 
>>>>>>> So, can you test 6.5.0 with that patch please?
>>>>>> 
>>>>>> Sure, I'll test either 6.5.0 of 6.1.0 with the patch, but may
>>>>>> not get to this
>>>>> before the end of the day.
>>>> 
>>>> I did a quick test of this (essentially just a rebuild of 'dhcpcd'
>>>> v6.5.0 and deploy to the target - I didn't deploy the hooks and
>>>> this seems OK since the changes there seem to be irrelevant to my
>>>> configuration) and I'm seeing the same issue.
>>>> 
>>>> Here's my configuration: hostname option rapid_commit option
>>>> domain_name_servers, domain_name, domain_search, host_name option
>>>> classless_static_routes option ntp_servers require
>>>> dhcp_server_identifier nohook lookup-hostname timeout 20 ipv4only
>>>> vendor 01,"0"
>>>> 
>>>> Any ideas for what else to try?
>>> 
>>> Here's my syslog capture using your config on one interface.
>>> 
>>> Oct 17 21:42:26 [dhcpcd] version 6.5.0 starting Oct 17 21:42:27
>>> [dhcpcd] enp3s0: soliciting a DHCP lease Oct 17 21:42:46 [dhcpcd]
>>> timed out Oct 17 21:42:46 [dhcpcd] allowing 8 seconds for IPv4LL
>>> timeout Oct
>>> 17 21:42:47 [dhcpcd] enp3s0: probing for an IPv4LL address Oct 17
>>> 21:42:52 [dhcpcd] enp3s0: using IPv4LL address 169.254.102.37 Oct
>>> 17
>>> 21:42:52 [dhcpcd] enp3s0: adding route to 169.254.0.0/16 Oct 17
>>> 21:42:52 [dhcpcd] forked to background, child pid 8646 Oct 17
>>> 21:43:00 [dhcpcd] enp3s0: carrier lost Oct 17 21:43:00 [dhcpcd]
>>> enp3s0: deleting route to 169.254.0.0/16 Oct 17 21:43:07 [dhcpcd]
>>> enp3s0: carrier acquired Oct 17 21:43:13 [dhcpcd] enp3s0: using
>>> IPv4LL address
>>> 169.254.102.37 Oct 17 21:43:13 [dhcpcd] enp3s0: adding route to
>>> 169.254.0.0/16 Oct 17 21:43:17 [dhcpcd] enp3s0: soliciting a DHCP
>>> lease Oct 17 21:43:17 [dhcpcd] enp3s0: offered 10.73.2.30 from
>>> 10.73.1.1 `uberserver.marples.name' Oct 17 21:43:22 [dhcpcd] enp3s0:
>>> leased
>>> 10.73.2.30 for 3600 seconds Oct 17 21:43:22 [dhcpcd] enp3s0: adding
>>> route to 10.73.2.0/24 Oct 17 21:43:22 [dhcpcd] enp3s0: adding
>>> default route via 10.73.2.1 Oct 17 21:43:22 [dhcpcd] enp3s0:
>>> deleting route to
>>> 169.254.0.0/16
>>> 
>>> As you can see it works fine.
>> 
>> Weird, huh...
>> 
>>> But my version is beyond 6.5.0. However, as I cannot replicate your
>>> issue with it I'll release 6.5.1 tonight which hopefully you can re-test with.
>>> Adding the debug option gives a lot more output, you should use the
>>> same option when reporting back as it tells me a lot more about the
>>> state of dhcpcd.
>> 
>> Sure, thanks.
> 
> I just tried v5.6.1 and it does behave differently (although not like
> your result above). In the v6.5.1 case I don't see the constant
> cycling between IPV4LL and EXPIRE states, but I also don't see the
> expected transition to a new, valid
> lease:
> 
> 20141017 14:39:32.114 info daemon(dhcpcd):version 6.5.1 starting
> 20141017 14:39:32.127 info daemon(dhcpcd):eth1: 60-netacquire: received
> reason=PREINIT, beeppid=0, ip=, sn=, gw=, dns=, options=, hn= 20141017
> 14:39:32.141 info daemon(dhcpcd):eth1: 60-netacquire: received
> reason=NOCARRIER, beeppid=21387, ip=, sn=, gw=, dns=, options=, hn=
> 20141017 14:39:32.216 info daemon(dhcpcd):eth1: waiting for carrier
> 20141017 14:39:33.845 info daemon(dhcpcd):eth1: carrier acquired
> 20141017 14:39:33.859 info daemon(dhcpcd):eth1: 60-netacquire: received
> reason=CARRIER, beeppid=21387, ip=, sn=, gw=, dns=, options=, hn=
> 20141017 14:39:33.859 info daemon(dhcpcd):DUID
> 00:01:00:01:1b:bd:fd:00:00:1b:21:0a:21:03 20141017 14:39:33.860 info
> daemon(dhcpcd):eth1: IAID ab:36:1c:fc 20141017 14:39:34.330 info
> daemon(dhcpcd):eth1: soliciting a DHCP lease 20141017 14:39:52.142
> warning daemon(dhcpcd):allowing 9 seconds for IPv4LL timeout 20141017
> 14:39:54.332 info daemon(dhcpcd):eth1: probing for an IPv4LL address
> 20141017 14:39:58.729 info daemon(dhcpcd):eth1: using IPv4LL address
> 169.254.35.255 20141017 14:39:58.729 info daemon(dhcpcd):eth1: adding
> route to 169.254.0.0/16 20141017 14:39:58.744 info daemon(dhcpcd):eth1:
> 60-netacquire: received reason=IPV4LL, beeppid=21387, ip=169.254.35.255,
> sn=255.255.0.0, gw=, dns=, options=, hn= 20141017 14:39:58.750 info
> daemon(dhcpcd):forked to background, child pid 21608 20141017
> 14:40:14.419 info daemon(dhcpcd):eth1: carrier lost 20141017
> 14:40:14.432 info daemon(dhcpcd):eth1: 60-netacquire: received
> reason=NOCARRIER, beeppid=0, ip=, sn=, gw=, dns=, options=, hn= 20141017
> 14:40:14.442 info daemon(dhcpcd):eth1: deleting route to 169.254.0.0/16
> 20141017 14:40:14.456 info daemon(dhcpcd):eth1: 60-netacquire: received
> reason=EXPIRE, beeppid=21718, ip=, sn=, gw=, dns=, options=, hn=
> 20141017 14:40:23.697 info daemon(dhcpcd):eth1: carrier acquired
> 20141017 14:40:23.711 info daemon(dhcpcd):eth1: 60-netacquire: received
> reason=CARRIER, beeppid=21718, ip=, sn=, gw=, dns=, options=, hn=
> 20141017 14:40:23.711 info daemon(dhcpcd):eth1: IAID ab:36:1c:fc
> 20141017 14:40:29.401 info daemon(dhcpcd):eth1: using IPv4LL address
> 169.254.35.255 20141017 14:40:29.401 info daemon(dhcpcd):eth1: adding
> route to 169.254.0.0/16 20141017 14:40:29.416 info daemon(dhcpcd):eth1:
> 60-netacquire: received reason=IPV4LL, beeppid=21718, ip=169.254.35.255,
> sn=255.255.0.0, gw=, dns=, options=, hn= 20141017 14:40:31.425 warning
> daemon(dhcpcd):eth1: IPv4LL 10 second defence failed 20141017
> 14:40:31.435 info daemon(dhcpcd):eth1: deleting route to 169.254.0.0/16
> 20141017 14:40:31.447 info daemon(dhcpcd):eth1: 60-netacquire: received
> reason=EXPIRE, beeppid=0, ip=, sn=, gw=, dns=, options=, hn= 20141017
> 14:40:32.449 info daemon(dhcpcd):eth1: probing for an IPv4LL address
> 20141017 14:40:37.593 info daemon(dhcpcd):eth1: 60-netacquire: received
> reason=EXPIRE, beeppid=21879, ip=, sn=, gw=, dns=, options=, hn=
> 
> It's now 10mins past the last timestamp above, so I'm not seeing any
> further transitions/activity with dhcpcd in the log.
> 
> I'm using 'if{up|down} eth1' to bring the interface up and down -
> i.e., as
> follows:
> 
> 1. ifdown eth1
> 2. attach C1
> 3. ifup eth1
> 4. remove C1
> 5. attach C2
> 6. review logs

One quick additional note: here's what I see after step 6 above and after the following step:

7. ifdown eth1
8. ifup eth1

20141017 14:53:21.231 info daemon(dhcpcd):sending signal ARLM to pid 21608
20141017 14:53:21.231 info daemon(dhcpcd):received signal ALRM from PID 26807, releasing
20141017 14:53:21.231 info daemon(dhcpcd):eth1: removing interface
20141017 14:53:21.231 info daemon(dhcpcd):waiting for pid 21608 to exit
20141017 14:53:21.245 info daemon(dhcpcd):eth1: 60-netacquire: received reason=STOP, beeppid=21879, ip=, sn=, gw=, dns=, options=, hn=
20141017 14:53:21.262 info daemon(dhcpcd):eth1: 60-netacquire: received reason=STOPPED, beeppid=0, ip=, sn=, gw=, dns=, options=, hn=
20141017 14:53:21.268 info daemon(dhcpcd):exited
20141017 14:54:50.327 info daemon(dhcpcd):version 6.5.1 starting
20141017 14:54:50.340 info daemon(dhcpcd):eth1: 60-netacquire: received reason=PREINIT, beeppid=0, ip=, sn=, gw=, dns=, options=, hn=
20141017 14:54:50.355 info daemon(dhcpcd):eth1: 60-netacquire: received reason=NOCARRIER, beeppid=27393, ip=, sn=, gw=, dns=, options=, hn=
20141017 14:54:50.431 info daemon(dhcpcd):eth1: waiting for carrier
20141017 14:54:53.476 info daemon(dhcpcd):eth1: carrier acquired
20141017 14:54:53.490 info daemon(dhcpcd):eth1: 60-netacquire: received reason=CARRIER, beeppid=27393, ip=, sn=, gw=, dns=, options=, hn=
20141017 14:54:53.491 info daemon(dhcpcd):DUID 00:01:00:01:1b:bd:fd:00:00:1b:21:0a:21:03
20141017 14:54:53.491 info daemon(dhcpcd):eth1: IAID ab:36:1c:fc
20141017 14:54:53.580 info daemon(dhcpcd):eth1: soliciting a DHCP lease
20141017 14:54:58.556 info daemon(dhcpcd):eth1: offered 205.159.216.180 from 205.159.216.146
20141017 14:55:03.416 info daemon(dhcpcd):eth1: leased 205.159.216.180 for 28800 seconds
20141017 14:55:03.416 info daemon(dhcpcd):eth1: adding route to 205.159.216.128/25
20141017 14:55:03.416 info daemon(dhcpcd):eth1: adding default route via 205.159.216.130
20141017 14:55:03.438 info daemon(dhcpcd):eth1: 60-netacquire: received reason=BOUND, beeppid=27393, ip=205.159.216.180, sn=255.255.255.128, gw=205.159.216.130, dns=205.159.216.146 205.159.216.73 172.20.0.3, options=, hn=
20141017 14:55:03.445 info daemon(dhcpcd):forked to background, child pid 27535

This just demonstrates that, with C2 still connected, a full down/up sequence does properly result in a new, valid lease.
 
> I configured v6.5.1 without --disable-debug. I'm thinking you were
> referring to something else when mentioned adding the "debug option".
> What did you mean by this exactly ;)?
> 
> Thanks,
> -David
> 
>> -David
>> 
>>> Thanks
>>> 
>>> Roy