dhcpcd-discuss

RE: TIMEOUT on Rebind?

David Hauck

Wed Jun 01 21:43:53 2016

Hi Roy,
 
On Tuesday, May 31, 2016 10:46 PM, Roy Marples wrote:
> Hi David
> 
> On Tuesday 31 May 2016 23:17:29 David Hauck wrote:
>> OK, I tried 'lastlease' in my 'dhcpcd.conf' file and see the following:
>> 
>> 20160531 15:57:47.103 info daemon(dhcpcd):eth1: carrier lost 20160531
>> 15:57:47.109 info daemon(dhcpcd):eth1: 60-custom: received
>> reason=NOCARRIER, ip=, sn=, gw=, dns=, options=, hn= 20160531
>> 15:57:47.109 info daemon(dhcpcd):eth1: deleting route to
>> 205.159.216.128/25 20160531 15:57:47.109 info daemon(dhcpcd):eth1:
>> deleting default route via 205.159.216.130 20160531 15:57:47.115 info
>> daemon(dhcpcd):eth1: 60- custom: received reason=EXPIRE, ip=, sn=, gw=,
>> dns=, options=, hn= 20160531 15:57:50.313 info daemon(dhcpcd):eth1:
>> carrier acquired 20160531 15:57:50.319 info daemon(dhcpcd):eth1:
>> 60-custom: received reason=CARRIER, ip=, sn=, gw=, dns=, options=, hn=
>> 20160531 15:57:50.319 info daemon(dhcpcd):eth1: IAID e0:53:f3:9f
>> 20160531 15:57:50.434 info daemon(dhcpcd):eth1: rebinding lease of
>> 205.159.216.184 20160531 15:57:55.435 info daemon(dhcpcd):eth1: leased
>> 205.159.216.184 for 28800 seconds 20160531 15:57:55.435 info
>> daemon(dhcpcd):eth1: adding route to 205.159.216.128/25 20160531
>> 15:57:55.435 info daemon(dhcpcd):eth1: adding default route via
>> 205.159.216.130 20160531 15:57:55.442 info daemon(dhcpcd):eth1: 60-
>> custom: received reason=REBOOT, ip=205.159.216.184, 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= 20160531 15:57:55.455 info daemon(dhcpcd):eth1:
>> soliciting a DHCP lease
>> 
>> I never see a transition occur beyond the line above? This looks the
>> same as when I don't have 'lastlease' specified. Should I be seeing
>> something else
>> (note: I also don't see any TIMEOUT transition)?
> 
> Looks to me like there was a valid DHCP transaction :) 

Notwithstanding what you say above, why does the last line say "soliciting a DHCP lease"?

Also, when I try this again now, I see the following:

20160601 14:36:19.169 info daemon(dhcpcd):eth1: carrier lost
20160601 14:36:19.175 info daemon(dhcpcd):eth1: 60-netacquire: received reason=NOCARRIER, beeppid=0, ip=, sn=, gw=, dns=, options=, hn=
20160601 14:36:19.186 info daemon(dhcpcd):eth1: deleting route to 205.159.216.128/25
20160601 14:36:19.186 info daemon(dhcpcd):eth1: deleting default route via 205.159.216.130
20160601 14:36:19.192 info daemon(dhcpcd):eth1: 60-netacquire: received reason=EXPIRE, beeppid=0, ip=, sn=, gw=, dns=, options=, hn=
20160601 14:36:26.690 info daemon(dhcpcd):eth1: carrier acquired
20160601 14:36:26.696 info daemon(dhcpcd):eth1: 60-netacquire: received reason=CARRIER, beeppid=0, ip=, sn=, gw=, dns=, options=, hn=
20160601 14:36:26.696 info daemon(dhcpcd):eth1: IAID e0:53:f3:9f
20160601 14:36:27.466 info daemon(dhcpcd):eth1: soliciting a DHCP lease

This doesn't have the intervening messages as the first trace regarding "rebinding" but it does end the same way: with "soliciting a DHCP lease". In both traces I never see a TIMEOUT reason code in the hook scripts (both traces are with 'lastlease' present in dhcpcd.conf).

What's going on here?

Thx,
-David

> I turned off my DHCP server and ran this:
> 
> $ sudo dhcpcd -dB4 --lastlease --noipv4ll dhcpcd-6.11.0 starting dev:
> loaded udev wlp4s0: executing `/libexec/dhcpcd-run-hooks' PREINIT
> wlp4s0: executing `/libexec/dhcpcd-run-hooks' CARRIER DUID
> 00:01:00:01:1b:79:14:0c:e8:94:f6:3f:9b:95 wlp4s0: IAID f8:59:7b:b2
> wlp4s0: delaying IPv4 for 0.6 seconds wlp4s0: reading lease
> `/var/db/dhcpcd-wlp4s0-UberNET.lease' wlp4s0: rebinding lease of
> 10.73.2.30 wlp4s0: sending REQUEST (xid 0x6701a20f), next in 3.5 seconds
> wlp4s0: sending REQUEST (xid 0x6701a20f), next in 7.4 seconds wlp4s0:
> leased 10.73.2.30 for 3600 seconds wlp4s0: renew in 1800 seconds, rebind
> in 3150 seconds wlp4s0: IP address 10.73.2.30/24 already exists wlp4s0:
> changing route to 10.73.2.0/24 wlp4s0: changing default route via
> 10.73.2.1 wlp4s0: ARP announcing 10.73.2.30 (1 of 2), next in 2.0
> seconds wlp4s0: executing `/libexec/dhcpcd-run-hooks' TIMEOUT wlp4s0:
> soliciting a DHCP lease wlp4s0: sending DISCOVER (xid 0x9dc3daf3), next
> in 3.6 seconds wlp4s0: ARP announcing 10.73.2.30 (2 of 2) wlp4s0:
> sending DISCOVER (xid 0x9dc3daf3), next in 7.9 seconds ^Creceived
> SIGINT, stopping wlp4s0: removing interface wlp4s0: executing
> `/libexec/dhcpcd-run-hooks' STOPPED dev: unloaded udev dhcpcd exited $
> 
> Roy

Follow-Ups:
Re: TIMEOUT on Rebind?Roy Marples
References:
TIMEOUT on Rebind?David Hauck
RE: TIMEOUT on Rebind?David Hauck
RE: TIMEOUT on Rebind?David Hauck
Re: TIMEOUT on Rebind?Roy Marples
Archive administrator: postmaster@marples.name