dhcpd in failover not reusing expired leases

Tue Oct 14 16:06:46 UTC 2008

On Oct 14, 2008, at 11:03 AM, David W. Hankins wrote:
> I would suspect something is causing the failover channel to
> disconnect and hold it down, so the peer misses the binding update
> to active as well as the expired update.  But then it seems to
> reconnect on a restart?
>
> So that's a very strange symptom.

We've checked connectivity between the two servers, they both  
connected to the same Cisco 6509, there are no interface errors or any  
relation to state problems between the peers.  The clocks are sync'd  
via broadcast NTP and the clocks are only a couple of milliseconds off  
from each other.

We did some digging on this one lease in question (there were several  
others like it).

It almost seems like client issues or connectivity issues between the  
client and server.  I keep seeing DHCPREQUEST's from some clients  
every five minutes, our servers send an ACK, but then five minutes,  
more REQUESTS.  Does this seem normal for a 3600 second lease?

For example, the following client we saw requests for a hour or so,  
every five minutes... :

...
Oct 13 14:06:00 dhcp1 dhcpd: DHCPREQUEST for x.x.x.7 from 00:1e: 
90:31:ed:e4 via x.x.x.1: lease owned by peer
Oct 13 14:06:00 dhcp0 dhcpd: DHCPREQUEST for x.x.x.7 from 00:1e: 
90:31:ed:e4 (YOUR-C30BE43EA5) via x.x.x.1
Oct 13 14:06:00 dhcp0 dhcpd: DHCPACK on x.x.x.7 to 00:1e:90:31:ed:e4  
(YOUR-C30BE43EA5) via x.x.x.1
Oct 13 14:11:00 dhcp1 dhcpd: DHCPREQUEST for x.x.x.7 from 00:1e: 
90:31:ed:e4 via x.x.x.1: lease owned by peer
Oct 13 14:11:00 dhcp0 dhcpd: DHCPREQUEST for x.x.x.7 from 00:1e: 
90:31:ed:e4 (YOUR-C30BE43EA5) via x.x.x.1
Oct 13 14:11:00 dhcp0 dhcpd: DHCPACK on x.x.x.7 to 00:1e:90:31:ed:e4  
(YOUR-C30BE43EA5) via x.x.x.1
Oct 13 14:16:00 dhcp1 dhcpd: DHCPREQUEST for x.x.x.7 from 00:1e: 
90:31:ed:e4 via x.x.x.1: lease owned by peer
Oct 13 14:16:00 dhcp0 dhcpd: DHCPREQUEST for x.x.x.7 from 00:1e: 
90:31:ed:e4 (YOUR-C30BE43EA5) via x.x.x.1
Oct 13 14:16:00 dhcp0 dhcpd: DHCPACK on x.x.x.7 to 00:1e:90:31:ed:e4  
(YOUR-C30BE43EA5) via x.x.x.1

The client went away for several hours, then later on we saw:

Oct 13 21:53:57 dhcp1 dhcpd: DHCPDISCOVER from 00:1e:90:31:ed:e4 via  
x.x.x.1: peer holds all free leases
Oct 13 21:53:57 dhcp0 dhcpd: DHCPDISCOVER from 00:1e:90:31:ed:e4 (YOUR- 
C30BE43EA5) via x.x.x.1: network x.x.x/24: no fr
ee leases
Oct 13 21:54:01 dhcp0 dhcpd: DHCPDISCOVER from 00:1e:90:31:ed:e4 (YOUR- 
C30BE43EA5) via x.x.x.1: network x.x.x/24: no fr
ee leases
Oct 13 21:54:01 dhcp1 dhcpd: DHCPDISCOVER from 00:1e:90:31:ed:e4 via  
x.x.x.1: peer holds all free leases
Oct 13 21:54:10 dhcp1 dhcpd: DHCPDISCOVER from 00:1e:90:31:ed:e4 via  
x.x.x.1: peer holds all free leases

This went on forever, seemingly after the servers thought they had no  
free addresses.  After we stopped the secondary, restarted the  
primary, then started the secondary again, that seemed to kick things,  
then when we saw this client try again, we got:

Oct 14 09:29:07 dhcp0 dhcpd: DHCPDISCOVER from 00:1e:90:31:ed:e4 via  
x.x.x.1
Oct 14 09:29:07 dhcp1 dhcpd: DHCPDISCOVER from 00:1e:90:31:ed:e4 via  
x.x.x.1: peer holds all free leases
Oct 14 09:29:08 dhcp0 dhcpd: DHCPOFFER on x.x.x.7 to 00:1e:90:31:ed:e4  
(YOUR-C30BE43EA5) via x.x.x.1
Oct 14 09:29:08 dhcp1 dhcpd: DHCPREQUEST for x.x.x.7 (64.22.32.15)  
from 00:1e:90:31:ed:e4 via x.x.x.1: lease owned by peer
Oct 14 09:29:08 dhcp0 dhcpd: uid lease x.x.x.112 for client 00:1e: 
90:31:ed:e4 is duplicate on x.x.x/24
Oct 14 09:29:08 dhcp0 dhcpd: DHCPREQUEST for x.x.x.7 (64.22.32.15)  
from 00:1e:90:31:ed:e4 (YOUR-C30BE43EA5) via x.x.x.1
Oct 14 09:29:08 dhcp0 dhcpd: DHCPACK on x.x.x.7 to 00:1e:90:31:ed:e4  
(YOUR-C30BE43EA5) via x.x.x.1
Oct 14 09:30:09 dhcp0 dhcpd: DHCPACK to x.x.x.7 (00:1e:90:31:ed:e4)  
via inet0
Oct 14 09:30:09 dhcp1 dhcpd: DHCPACK to x.x.x.7 (00:1e:90:31:ed:e4)  
via inet0

Between that time, we looked to see if the IP address the client (.7)  
had was ever leased to another client, and it never was.  Shouldn't  
the lease be returned into the pool once the max-lease time has been  
passed?  In this case, it was several hours and the IP address the  
client had never appeared in the logs again to show as available, yet  
new clients were being denied new leases.

What's weird in the above is that we see the "duplicate" lease (.112)  
noted in the logs... what's interesting is the only thing we have in  
the logs prior to that for the client in reference to that IP address:

Oct 13 10:56:17 dhcp1 dhcpd: DHCPREQUEST for x.x.x.112 from 00:1e: 
90:31:ed:e4 via x.x.x.1: lease owned by peer
Oct 13 10:56:17 dhcp0 dhcpd: DHCPREQUEST for x.x.x.112 from 00:1e: 
90:31:ed:e4 (YOUR-C30BE43EA5) via x.x.x.1
Oct 13 10:56:17 dhcp0 dhcpd: DHCPACK on x.x.x.112 to 00:1e:90:31:ed:e4  
(YOUR-C30BE43EA5) via x.x.x.1
Oct 13 11:01:17 dhcp1 dhcpd: DHCPREQUEST for x.x.x.112 from 00:1e: 
90:31:ed:e4 via x.x.x.1: lease owned by peer
Oct 13 11:01:17 dhcp0 dhcpd: DHCPREQUEST for x.x.x.112 from 00:1e: 
90:31:ed:e4 (YOUR-C30BE43EA5) via x.x.x.1
Oct 13 11:01:17 dhcp0 dhcpd: DHCPACK on x.x.x.112 to 00:1e:90:31:ed:e4  
(YOUR-C30BE43EA5) via x.x.x.1
Oct 13 11:06:17 dhcp1 dhcpd: DHCPREQUEST for x.x.x.112 from 00:1e: 
90:31:ed:e4 via x.x.x.1: lease owned by peer
Oct 13 11:06:17 dhcp0 dhcpd: DHCPREQUEST for x.x.x.112 from 00:1e: 
90:31:ed:e4 (YOUR-C30BE43EA5) via x.x.x.1
Oct 13 11:06:17 dhcp0 dhcpd: DHCPACK on x.x.x.112 to 00:1e:90:31:ed:e4  
(YOUR-C30BE43EA5) via x.x.x.1
Oct 13 12:15:38 dhcp0 dhcpd: DHCPDISCOVER from 00:1e:90:31:ed:e4 (YOUR- 
C30BE43EA5) via x.x.x.1
Oct 13 12:15:38 dhcp1 dhcpd: DHCPDISCOVER from 00:1e:90:31:ed:e4 via  
x.x.x.1: peer holds all free leases
Oct 13 12:15:39 dhcp0 dhcpd: DHCPOFFER on x.x.x.7 to 00:1e:90:31:ed:e4  
(YOUR-C30BE43EA5) via x.x.x.1
Oct 13 12:15:43 dhcp0 dhcpd: DHCPDISCOVER from 00:1e:90:31:ed:e4 (YOUR- 
C30BE43EA5) via x.x.x.1
Oct 13 12:15:43 dhcp0 dhcpd: DHCPOFFER on x.x.x.7 to 00:1e:90:31:ed:e4  
(YOUR-C30BE43EA5) via x.x.x.1

In this example, we may of had this pool set to a 3600 lease, so  
perhaps it looks ok in that the lease expired and it got a new address  
at 12:15...

-- 
Robert Blayzor, BOFH
INOC, LLC
rblayzor at inoc.net
http://www.inoc.net/~rblayzor/