dhcpcd-discuss

Hi again,

On Monday, June 06, 2016 12:50 PM, David Hauck wrote:
> On Monday, June 06, 2016 12:36 PM, David Hauck wrote:
>> Hi Roy,
>> 
>> On Monday, June 06, 2016 12:25 PM, Roy Marples wrote:
>>> Hi David
>>> 
>>> On 06/06/2016 18:47, David Hauck wrote:
>>>> I don't have reboot configured for a specific value and my
>>>> understanding is that this defaults to 5s in this case.
>>>> 
>>>>> If this fails, dhcpcd will use the last lease if it's not expired
>>>>> and the lastlease option is enabled. At this point you should see
>>>>> the TIMEOUT reason.
>>>> 
>>>> Right, OK, I definitely don't see this reason code show up. Any
>>>> more ideas why?
>>> 
>>> None!
>>> So lets add some debug code to find out.
>>> Patch attached - you should see an extra DEBUG line with some
>>> parameteres. Both should be non zero.
>>> Let me know.
>> 
>> OK, thx, I'll try this. Although the patch you provided is likely
>> for a different version of dhcpcd (again, I'm running v6.7.1); it is
>> simple enough that I can modify it easily for the v6.7.1 code though.
> 
> OK, here's what I see (this is back to the first case again where the
> rebind happens quickly followed by the later "soliciting a DHCP lease"
> stall . I mentioned last Wednesday that I also see cases where CARRIER
> immediately transitions to the "soliciting a DHCP lease" stall.
> 
> 20160606 12:42:53.869 info daemon(dhcpcd):eth1: carrier lost 20160606
> 12:42:53.889 info daemon(dhcpcd):eth1: 60-custom: received
> reason=NOCARRIER, ip=, sn=, gw=, dns=, options=, hn= 20160606
> 12:42:53.889 info daemon(dhcpcd):eth1: deleting route to
> 205.159.216.128/25 20160606 12:42:53.889 info daemon(dhcpcd):eth1:
> deleting default route via 205.159.216.130 20160606 12:42:53.906 info
> daemon(dhcpcd):eth1: 60-custom: received reason=EXPIRE, ip=, sn=, gw=,
> dns=, options=, hn= 20160606 12:42:58.284 info daemon(dhcpcd):eth1:
> carrier acquired 20160606 12:42:58.290 info daemon(dhcpcd):eth1:
> 60-custom: received reason=CARRIER, ip=, sn=, gw=, dns=, options=, hn=
> 20160606 12:42:58.291 info daemon(dhcpcd):eth1: IAID e0:53:f3:9f
> 20160606 12:42:58.729 info daemon(dhcpcd):eth1: rebinding lease of
> 205.159.216.183 20160606 12:42:58.729 info daemon(dhcpcd):DEBUG 128 1  
> <=== here's the syslog line that was added 20160606 12:43:03.729 info
> daemon(dhcpcd):eth1: leased 205.159.216.183 for 28800 seconds 20160606
> 12:43:03.729 info daemon(dhcpcd):eth1: adding route to
> 205.159.216.128/25 20160606 12:43:03.729 info daemon(dhcpcd):eth1:
> adding default route via 205.159.216.130 20160606 12:43:03.738 info
> daemon(dhcpcd):eth1: 60-custom: received reason=REBOOT,
> ip=205.159.216.183, sn=255.255.255.128, gw=205.159.216.130,
> dns=205.159.216.147 172.20.0.6 205.159.216.73, options=, hn= 20160606
> 12:43:03.749 info daemon(dhcpcd):eth1: soliciting a DHCP lease

And here's another example:
20160606 15:02:31.587 info daemon(dhcpcd):eth1: carrier lost
20160606 15:02:31.593 info daemon(dhcpcd):eth1: 60-custom: received reason=NOCARRIER, ip=, sn=, gw=, dns=, options=, hn=
20160606 15:02:31.593 info daemon(dhcpcd):eth1: deleting route to 205.159.216.128/25
20160606 15:02:31.593 info daemon(dhcpcd):eth1: deleting default route via 205.159.216.130
20160606 15:02:31.600 info daemon(dhcpcd):eth1: 60-custom: received reason=EXPIRE, ip=, sn=, gw=, dns=, options=, hn=
.... [notice the time gap here - 18+hrs with NOCARRIER
20160607 10:21:37.868 info daemon(dhcpcd):eth1: carrier acquired
20160607 10:21:37.874 info daemon(dhcpcd):eth1: 60-custom: received reason=CARRIER, ip=, sn=, gw=, dns=, options=, hn=
20160607 10:21:37.875 info daemon(dhcpcd):eth1: IAID e0:53:f3:9f
20160607 10:21:38.462 info daemon(dhcpcd):eth1: soliciting a DHCP lease
 
Because of the long duration the lease has expired (lease duration here is 8hrs). From an earlier email, you mentioned:
"TIMEOUT will only be seen when lastlease is enabled AND a DHCP server could not be contacted within the timeout period."

It seems that in both of the above cases I should be seeing the TIMEOUT reason (but I don't). Given the results (including your tests where this apparently works for you) so far do you think this is just a bug in v6.7.1 (again, not entirely straightforward for me test the trunk at this point - maybe it's not so difficult for you to try v6.7.1?)?

Regards,
-David