'MAC affinity' doing the exact opposite, leading to 'pool churn'?

Mon Sep 24 14:55:38 UTC 2007

I've observed a case in which the exact same client (a GNU/Linux machine) is
getting a different IP from the same peer (primary) in a failover pair upon
each (re)boot.  My guess is that, since the previous lease had already expired,
that lease was allocated to the *OTHER* (secondary) peer after expiry, although
it was given to the client by the primary peer before.  Because the primary
needs to answer the request due to load balancing, it can't but give the
client a new IP.  It seems a case of 'MAC affinity' doing exactly the opposite
of what can be expected.  Or am I misinterpreting this?

And now for the details:
Both failover peers ran a regular ISC DHCP 3.1.0 server.  The client was a
GNU/Linux machine that requested an IP upon boot, was powered down afterwards
and then booted again after the previous lease had expired.  MCLT was set to
180, max-lease-time to 360, `load balance max seconds` to 3.  These are the
logs of the two DHCP servers (s1, the primary, and s2, the secondary peer):

### s1
16:40:29 s1 dhcpd: DHCPDISCOVER from 00:0f:1f:84:ca:f2 via eth1
16:40:30 s1 dhcpd: DHCPOFFER on 134.58.217.140 to 00:0f:1f:84:ca:f2 via eth1
16:40:30 s1 dhcpd: DHCPREQUEST for 134.58.217.140 (134.58.217.231) from 00:0f:1f:84:ca:f2 via eth1
16:40:30 s1 dhcpd: DHCPACK on 134.58.217.140 to 00:0f:1f:84:ca:f2 via eth1
16:40:31 s1 dhcpd: DHCPREQUEST for 134.58.217.140 (134.58.217.231) from 00:0f:1f:84:ca:f2 via eth1
16:40:31 s1 dhcpd: DHCPACK on 134.58.217.140 to 00:0f:1f:84:ca:f2 via eth1
16:40:31 s1 dhcpd: bind update on 134.58.217.140 got ack from dhcp-failover: xid mismatch.
16:46:51 s1 dhcpd: DHCPDISCOVER from 00:0f:1f:84:ca:f2 via eth1
16:46:52 s1 dhcpd: DHCPOFFER on 134.58.217.139 to 00:0f:1f:84:ca:f2 via eth1
16:46:52 s1 dhcpd: DHCPREQUEST for 134.58.217.139 (134.58.217.231) from 00:0f:1f:84:ca:f2 via eth1
16:46:52 s1 dhcpd: DHCPACK on 134.58.217.139 to 00:0f:1f:84:ca:f2 via eth1
16:46:53 s1 dhcpd: DHCPREQUEST for 134.58.217.139 (134.58.217.231) from 00:0f:1f:84:ca:f2 via eth1
16:46:53 s1 dhcpd: DHCPACK on 134.58.217.139 to 00:0f:1f:84:ca:f2 via eth1
16:46:53 s1 dhcpd: bind update on 134.58.217.139 got ack from dhcp-failover: xid mismatch.
17:22:40 s1 dhcpd: DHCPDISCOVER from 00:0f:1f:84:ca:f2 via eth1
17:22:41 s1 dhcpd: DHCPOFFER on 134.58.217.138 to 00:0f:1f:84:ca:f2 via eth1
17:22:42 s1 dhcpd: DHCPDISCOVER from 00:0f:1f:84:ca:f2 via eth1
17:22:42 s1 dhcpd: DHCPOFFER on 134.58.217.138 to 00:0f:1f:84:ca:f2 via eth1
17:22:42 s1 dhcpd: DHCPREQUEST for 134.58.217.138 (134.58.217.231) from 00:0f:1f:84:ca:f2 via eth1
17:22:42 s1 dhcpd: DHCPACK on 134.58.217.138 to 00:0f:1f:84:ca:f2 via eth1
17:26:22 s1 dhcpd: DHCPDISCOVER from 00:0f:1f:84:ca:f2 via eth1
17:26:22 s1 dhcpd: DHCPREQUEST for 134.58.217.138 (134.58.217.232) from 00:0f:1f:84:ca:f2 via eth1: lease owned by peer
17:26:23 s1 dhcpd: DHCPOFFER on 134.58.217.137 to 00:0f:1f:84:ca:f2 via eth1
17:34:41 s1 dhcpd: balancing pool 80de718 134.58.217/24  total 201  free 118  backup 83  lts 17  max-own (+/-)20
17:34:41 s1 dhcpd: balanced pool 80de718 134.58.217/24  total 201  free 117  backup 84  lts 16  max-misbal 30
17:34:41 s1 dhcpd: balancing pool 80da890 172.16.0/24  total 60  free 36  backup 24  lts 6  max-own (+/-)6
17:34:41 s1 dhcpd: balanced pool 80da890 172.16.0/24  total 60  free 36  backup 24  lts 6  max-misbal 9
17:34:41 s1 dhcpd: Wrote 108 leases to leases file.
17:36:31 s1 dhcpd: DHCPDISCOVER from 00:0f:1f:84:ca:f2 via eth1
17:36:32 s1 dhcpd: DHCPOFFER on 134.58.217.144 to 00:0f:1f:84:ca:f2 via eth1
17:36:32 s1 dhcpd: DHCPREQUEST for 134.58.217.144 (134.58.217.231) from 00:0f:1f:84:ca:f2 via eth1
17:36:32 s1 dhcpd: DHCPACK on 134.58.217.144 to 00:0f:1f:84:ca:f2 via eth1
17:36:33 s1 dhcpd: DHCPREQUEST for 134.58.217.144 (134.58.217.231) from 00:0f:1f:84:ca:f2 via eth1
17:36:33 s1 dhcpd: DHCPACK on 134.58.217.144 to 00:0f:1f:84:ca:f2 via eth1

### s2
16:40:28 s2 dhcpd: DHCPDISCOVER from 00:0f:1f:84:ca:f2 via eth1: load balance to peer dhcp-failover
16:40:29 s2 dhcpd: DHCPREQUEST for 134.58.217.140 (134.58.217.231) from 00:0f:1f:84:ca:f2 via eth1: lease owned by peer
16:40:30 s2 dhcpd: DHCPREQUEST for 134.58.217.140 (134.58.217.231) from 00:0f:1f:84:ca:f2 via eth1
16:40:30 s2 dhcpd: DHCPACK on 134.58.217.140 to 00:0f:1f:84:ca:f2 via eth1
16:46:50 s2 dhcpd: DHCPDISCOVER from 00:0f:1f:84:ca:f2 via eth1: load balance to peer dhcp-failover
16:46:51 s2 dhcpd: DHCPREQUEST for 134.58.217.139 (134.58.217.231) from 00:0f:1f:84:ca:f2 via eth1: lease owned by peer
16:46:52 s2 dhcpd: DHCPREQUEST for 134.58.217.139 (134.58.217.231) from 00:0f:1f:84:ca:f2 via eth1
16:46:52 s2 dhcpd: DHCPACK on 134.58.217.139 to 00:0f:1f:84:ca:f2 via eth1
17:22:40 s2 dhcpd: DHCPDISCOVER from 00:0f:1f:84:ca:f2 via eth1: load balance to peer dhcp-failover
17:22:42 s2 dhcpd: DHCPDISCOVER from 00:0f:1f:84:ca:f2 via eth1
17:22:42 s2 dhcpd: DHCPREQUEST for 134.58.217.138 (134.58.217.231) from 00:0f:1f:84:ca:f2 via eth1: lease owned by peer
17:22:43 s2 dhcpd: DHCPOFFER on 134.58.217.139 to 00:0f:1f:84:ca:f2 via eth1
17:26:21 s2 dhcpd: DHCPDISCOVER from 00:0f:1f:84:ca:f2 via eth1
17:26:22 s2 dhcpd: DHCPOFFER on 134.58.217.138 to 00:0f:1f:84:ca:f2 via eth1
17:26:22 s2 dhcpd: DHCPREQUEST for 134.58.217.138 (134.58.217.232) from 00:0f:1f:84:ca:f2 via eth1
17:26:22 s2 dhcpd: DHCPACK on 134.58.217.138 to 00:0f:1f:84:ca:f2 via eth1
17:34:42 s2 dhcpd: Wrote 108 leases to leases file.
17:35:43 s2 dhcpd: balancing pool 80de6f0 134.58.217/24  total 201  free 117  backup 84  lts -16  max-own (+/-)20
17:35:43 s2 dhcpd: balanced pool 80de6f0 134.58.217/24  total 201  free 121  backup 80  lts -20  max-misbal 30
17:35:43 s2 dhcpd: balancing pool 80da890 172.16.0/24  total 60  free 36  backup 24  lts -6  max-own (+/-)6
17:35:43 s2 dhcpd: balanced pool 80da890 172.16.0/24  total 60  free 36  backup 24  lts -6  max-misbal 9
17:36:31 s2 dhcpd: DHCPDISCOVER from 00:0f:1f:84:ca:f2 via eth1: load balance to peer dhcp-failover
17:36:31 s2 dhcpd: DHCPREQUEST for 134.58.217.144 (134.58.217.231) from 00:0f:1f:84:ca:f2 via eth1: lease owned by peer
17:36:33 s2 dhcpd: DHCPREQUEST for 134.58.217.144 (134.58.217.231) from 00:0f:1f:84:ca:f2 via eth1
17:36:33 s2 dhcpd: DHCPACK on 134.58.217.144 to 00:0f:1f:84:ca:f2 via eth1

Disclaimer: http://www.kuleuven.be/cwis/email_disclaimer.htm