TIMEOUT on Rebind?
David Hauck
Mon May 30 22:04:16 2016
Hi Roy,
I have a situation where an interface has an active lease. At some point carrier is lost on the interface and the interface goes through the following sequence (this is with v6.7.1):
20160530 14:26:38.346 info daemon(dhcpcd):eth1: carrier lost
20160530 14:26:38.471 info daemon(dhcpcd):eth1: 60-custom: received reason=NOCARRIER, ip=, sn=, gw=, dns=, options=, hn=
20160530 14:26:38.471 info daemon(dhcpcd):eth1: deleting route to 205.159.216.128/25
20160530 14:26:38.471 info daemon(dhcpcd):eth1: deleting default route via 205.159.216.130
20160530 14:26:38.479 info daemon(dhcpcd):eth1: 60-custom: received reason=EXPIRE, ip=, sn=, gw=, dns=, options=, hn=
Eventually, carrier is re-established:
20160530 14:27:08.118 info daemon(dhcpcd):eth1: carrier acquired
20160530 14:27:08.123 info daemon(dhcpcd):eth1: 60-custom: received reason=CARRIER, ip=, sn=, gw=, dns=, options=, hn=
20160530 14:27:08.124 info daemon(dhcpcd):eth1: IAID e0:53:f3:9f
20160530 14:27:08.794 info daemon(dhcpcd):eth1: rebinding lease of 205.159.216.183
20160530 14:27:13.812 info daemon(dhcpcd):eth1: 60-custom: received reason=EXPIRE, ip=, sn=, gw=, dns=, options=, hn=
20160530 14:27:13.812 info daemon(dhcpcd):eth1: soliciting a DHCP lease
However, at this point no server is reachable. My question is that at this point I would expect the 'timeout' value to engage; i.e., dhcpcd exit if noipv4ll is specified. Do I have this wrong? If so, then the startup state (where timeout expiring results in dhcpcd exiting) and this "timeout after lease lost/rebind" state result in different run states.
Similarly, in the "timeout" during start-up state, I do see that 'dhcpcd' exits (when 'noipv4ll' is defined) when the timeout occurs, but I do not see that this TIMEOUT state reaches the hook functions. Here's what I see in this case (90s timeout):
20160530 14:47:39.266 info daemon(dhcpcd):version 6.7.1 starting
20160530 14:47:39.328 info daemon(dhcpcd):eth1: 60-custom: received reason=PREINIT, ip=, sn=, gw=, dns=, options=, hn=
20160530 14:47:39.337 info daemon(dhcpcd):eth1: 60-custom: received reason=NOCARRIER, ip=, sn=, gw=, dns=, options=, hn=
20160530 14:47:39.574 info daemon(dhcpcd):eth1: waiting for carrier
20160530 14:47:41.098 info daemon(dhcpcd):eth1: carrier acquired
20160530 14:47:41.104 info daemon(dhcpcd):eth1: 60-custom: received reason=CARRIER, ip=, sn=, gw=, dns=, options=, hn=
20160530 14:47:41.111 info daemon(dhcpcd):DUID 00:01:00:01:1e:b4:fb:d1:00:02:b3:cd:61:9b
20160530 14:47:41.116 info daemon(dhcpcd):eth1: IAID e0:53:f3:9f
20160530 14:47:41.874 info daemon(dhcpcd):eth1: soliciting a DHCP lease
20160530 14:49:09.367 info daemon(dhcpcd):exited
Is this expected?
Caveat: I realize I'm running an older version of 'dhcpcd' that is over a year old, but: 1) I have systems in the field that I'm supporting that I need to troubleshoot, and 2) I will need to carve out a chunk of time to consider upgrading to the tip (given the number of changes between these versions, the current set of issues being reported, and the significant number of use cases I will need to retest - especially the various IPv6-related changes over this time).
Any thoughts on what I should be seeing in these cases?
Thanks,
-David
Archive administrator: postmaster@marples.name