[kea-dev] KEA ignoring subnet choice between hooks

Hreiðar Jóelsson hreidar.joelsson at gagnaveita.is
Tue Nov 6 13:50:50 UTC 2018


Hi, I'm developing a hook that govern which subnet is selected from multiple subnets in a shared network for an incoming DHCP package. My network has several subnets per each service (VLAN), one which has restricted addresses (10.20x.x.x) and several that have non-restricted addresses (192.168.x.x in my dev env). The hook I have now does this by using lease policies which it reads from external Redis database. The problem I'm encountering is moving devices between subnets after they have once got a lease. When a device has got a lease from one subnet it is hard to get KEA to provision a lease from another one as it is overwriting the subnet of choice made in subnet4_select hook in the lease4_select hook. This is done in the main process in between these two hooks as I put my choice in subnet4_select by:

int subnet4_select(CalloutHandle& handle) {
  Subnet4Ptr subnet;
  handle.getArgument("subnet4", subnet);
  ...
  // set chosen subnet to Subnet4Ptr  my_subnet_choice
  ...
  handle.setArgument("subnet4", my_subnet_choice);
  handle.setContext("subnet4", my_subnet_choice);
}

But when I check the subnet in lease4_select KEA has change it to the one previously used:

int lease4_select(CalloutHandle& handle) {
  handle.getArgument("subnet4", kea_subnet);
  handle.getContext("subnet4", my_subnet_choice);

if(kea_subnet->getID() != my_subnet_choice->getID())
    {
        LOG_DEBUG(my_logger,50, LEASE4_SELECT_MISMATCH);
        handle.setContext(CONTEXT_PARAMETER_NAK, true);
        lease->decline(0);
    }

I added this check & nak code in lease4_select and lease4_renew hooks to deal with the cases when a device is sending a renew message to force the client to send a discover message insted, but this ends in discover nak loop between KEA and that client. I can resolve this behavior be reloading KEA or by removing that client record from the mem file.

Lease affinity is one thing I imagine could be in my way, but I believe I have turned it off with the following config and still seeing this behavior:

"expired-leases-processing": {
      "flush-reclaimed-timer-wait-time": 0,
      "hold-reclaimed-time": 0,
      "max-reclaim-leases": 0,
      "max-reclaim-time": 0,
      "reclaim-timer-wait-time": 30,
      "unwarned-reclaim-cycles": 5
    }

Any other ideas on what could explain this behavior? I see a DHCP4_SUBNET_DYNAMICALLY_CHANGED message in the provided logs that I would like to know more about.



Here are some more logs to support my case:

### kea dhcp log
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.callouts/7456] HOOKS_CALLOUTS_BEGIN begin all callouts for hook subnet4_select
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.callouts/7456] HOOKS_CALLOUT_CALLED hooks library with index 1 has called a callout on hook subnet4_select that has address 0x7f491302ab5f (callout duration: 0.172 ms)
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.callouts/7456] HOOKS_CALLOUTS_COMPLETE completed callouts for hook subnet4_select (total callouts duration: 0.172 ms)
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.packets/7456] DHCP4_SUBNET_SELECTED [hwtype=1 c8:d3:ff:ee:ff:4c], cid=[01:c8:d3:ff:ee:ff:4c], tid=0xabef9463: the subnet with ID 6 was selected for client assignments
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.packets/7456] DHCP4_SUBNET_DATA [hwtype=1 c8:d3:ff:ee:ff:4c], cid=[01:c8:d3:ff:ee:ff:4c], tid=0xabef9463: the selected subnet details: 192.168.30.0/24
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.hosts/7456] HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER get one host with IPv4 reservation for subnet id 6, identified by hwaddr=C8D3FFEEFF4C
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.hosts/7456] HOSTS_CFG_GET_ALL_IDENTIFIER get all hosts with reservations using identifier: hwaddr=C8D3FFEEFF4C
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.hosts/7456] HOSTS_CFG_GET_ALL_IDENTIFIER_COUNT using identifier hwaddr=C8D3FFEEFF4C, found 0 host(s)
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.hosts/7456] HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER_NULL host not found using subnet id 6 and identifier hwaddr=C8D3FFEEFF4C
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.hosts/7456] HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER get one host with IPv4 reservation for subnet id 6, identified by client-id=01C8D3FFEEFF4C
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.hosts/7456] HOSTS_CFG_GET_ALL_IDENTIFIER get all hosts with reservations using identifier: client-id=01C8D3FFEEFF4C
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.hosts/7456] HOSTS_CFG_GET_ALL_IDENTIFIER_COUNT using identifier client-id=01C8D3FFEEFF4C, found 0 host(s)
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.hosts/7456] HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER_NULL host not found using subnet id 6 and identifier client-id=01C8D3FFEEFF4C
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.dhcp4/7456] DHCP4_CLASS_ASSIGNED [hwtype=1 c8:d3:ff:ee:ff:4c], cid=[01:c8:d3:ff:ee:ff:4c], tid=0xabef9463: client packet has been assigned to the following class(es): UNKNOWN
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.dhcp4/7456] DHCP4_CLASS_ASSIGNED [hwtype=1 c8:d3:ff:ee:ff:4c], cid=[01:c8:d3:ff:ee:ff:4c], tid=0xabef9463: client packet has been assigned to the following class(es): ALL, VENDOR_CLASS_MSFT 5.0, UNKNOWN
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.ddns/7456] DHCP4_CLIENT_HOSTNAME_PROCESS [hwtype=1 c8:d3:ff:ee:ff:4c], cid=[01:c8:d3:ff:ee:ff:4c], tid=0xabef9463: processing client's Hostname option
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.ddns/7456] DHCP4_CLIENT_HOSTNAME_DATA [hwtype=1 c8:d3:ff:ee:ff:4c], cid=[01:c8:d3:ff:ee:ff:4c], tid=0xabef9463: client sent Hostname option: DESKTOP-FKUL6EB
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.ddns/7456] DHCP4_CLIENT_HOSTNAME_DATA [hwtype=1 c8:d3:ff:ee:ff:4c], cid=[01:c8:d3:ff:ee:ff:4c], tid=0xabef9463: client sent Hostname option: DESKTOP-FKUL6EB
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.ddns/7456] DHCP4_RESPONSE_HOSTNAME_DATA [hwtype=1 c8:d3:ff:ee:ff:4c], cid=[01:c8:d3:ff:ee:ff:4c], tid=0xabef9463: including Hostname option in the server's response: DESKTOP-FKUL6EB
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.dhcpsrv/7456] DHCPSRV_MEMFILE_GET_CLIENTID obtaining IPv4 leases for client ID 01:c8:d3:ff:ee:ff:4c
2018-10-30 12:30:19.466 DEBUG [kea-dhcp4.dhcpsrv/7456] DHCPSRV_MEMFILE_GET_HWADDR obtaining IPv4 leases for hardware address hwtype=1 c8:d3:ff:ee:ff:4c
2018-10-30 12:30:19.467 DEBUG [kea-dhcp4.alloc-engine/7456] ALLOC_ENGINE_V4_OFFER_NEW_LEASE allocation engine will try to offer new lease to the client [hwtype=1 c8:d3:ff:ee:ff:4c], cid=[01:c8:d3:ff:ee:ff:4c], tid=0xabef9463
2018-10-30 12:30:19.467 DEBUG [kea-dhcp4.dhcpsrv/7456] DHCPSRV_MEMFILE_GET_ADDR4 obtaining IPv4 lease for address 10.206.0.13
2018-10-30 12:30:19.467 DEBUG [kea-dhcp4.callouts/7456] HOOKS_CALLOUTS_BEGIN begin all callouts for hook lease4_select
2018-10-30 12:30:19.467 DEBUG [kea-dhcp4.callouts/7456] HOOKS_CALLOUT_CALLED hooks library with index 1 has called a callout on hook lease4_select that has address 0x7f491302b6ca (callout duration: 0.146 ms)
2018-10-30 12:30:19.467 DEBUG [kea-dhcp4.callouts/7456] HOOKS_CALLOUTS_COMPLETE completed callouts for hook lease4_select (total callouts duration: 0.146 ms)
2018-10-30 12:30:19.467 DEBUG [kea-dhcp4.dhcpsrv/7456] DHCPSRV_MEMFILE_GET_ADDR4 obtaining IPv4 lease for address 10.206.0.13
2018-10-30 12:30:19.467 DEBUG [kea-dhcp4.packets/7456] DHCP4_SUBNET_DYNAMICALLY_CHANGED [hwtype=1 c8:d3:ff:ee:ff:4c], cid=[01:c8:d3:ff:ee:ff:4c], tid=0xabef9463: changed selected subnet 192.168.30.0/24 to subnet 10.206.0.0/22 from shared network GR-Internet-AG06 for client assignments
2018-10-30 12:30:19.467 INFO  [kea-dhcp4.leases/7456] DHCP4_LEASE_ADVERT [hwtype=1 c8:d3:ff:ee:ff:4c], cid=[01:c8:d3:ff:ee:ff:4c], tid=0xabef9463: lease 10.206.0.13 will be advertised
2018-10-30 12:30:19.467 DEBUG [kea-dhcp4.ddns/7456] DHCP4_RESPONSE_HOSTNAME_GENERATE [hwtype=1 c8:d3:ff:ee:ff:4c], cid=[01:c8:d3:ff:ee:ff:4c], tid=0xabef9463: server has generated hostname myhost-10-206-0-13 for the client
2018-10-30 12:30:19.467 DEBUG [kea-dhcp4.callouts/7456] HOOKS_CALLOUTS_BEGIN begin all callouts for hook pkt4_send
2018-10-30 12:30:19.467 DEBUG [kea-dhcp4.callouts/7456] HOOKS_CALLOUT_CALLED hooks library with index 1 has called a callout on hook pkt4_send that has address 0x7f491302a4db (callout duration: 0.093 ms)
2018-10-30 12:30:19.467 DEBUG [kea-dhcp4.callouts/7456] HOOKS_CALLOUTS_COMPLETE completed callouts for hook pkt4_send (total callouts duration: 0.093 ms)
2018-10-30 12:30:19.467 DEBUG [kea-dhcp4.options/7456] DHCP4_PACKET_PACK [hwtype=1 c8:d3:ff:ee:ff:4c], cid=[01:c8:d3:ff:ee:ff:4c], tid=0xabef9463: preparing on-wire format of the packet to be sent
2018-10-30 12:30:19.467 DEBUG [kea-dhcp4.packets/7456] DHCP4_PACKET_SEND [hwtype=1 c8:d3:ff:ee:ff:4c], cid=[01:c8:d3:ff:ee:ff:4c], tid=0xabef9463: trying to send packet DHCPNAK (type 6) from 192.168.15.80:67 to 10.206.0.2:67 on interface ens33
2018-10-30 12:30:19.467 DEBUG [kea-dhcp4.packets/7456] DHCP4_RESPONSE_DATA [hwtype=1 c8:d3:ff:ee:ff:4c], cid=[01:c8:d3:ff:ee:ff:4c], tid=0xabef9463: responding with packet DHCPNAK (type 6), packet details: local_address=192.168.15.80:67, remote_address=10.206.0.2:67, msg_type=DHCPNAK (6), transid=0xabef9463,

### my hook log
2018-10-30 12:30:19.463 DEBUG [kea-dhcp4.virkir-kea-hook/7456] start subnet4_select
2018-10-30 12:30:19.463 DEBUG [kea-dhcp4.virkir-kea-hook/7456] SUBNET4_SELECT_PROCESSING started processing subnet in shared-network
2018-10-30 12:30:19.463 DEBUG [kea-dhcp4.virkir-kea-hook/7456] SUBNET4_SELECT_CAPACITY subnet: "10.206.0.0/22" , capacity: 1019
2018-10-30 12:30:19.463 DEBUG [kea-dhcp4.virkir-kea-hook/7456] SUBNET4_SELECT_CAPACITY subnet: "192.168.30.0/24" , capacity: 245
2018-10-30 12:30:19.463 DEBUG [kea-dhcp4.virkir-kea-hook/7456] SUBNET4_SELECT_ALLOWED using allowed subnet: 192.168.30.0/24
2018-10-30 12:30:19.463 DEBUG [kea-dhcp4.virkir-kea-hook/7456] Start lease4_select
2018-10-30 12:30:19.463 DEBUG [kea-dhcp4.virkir-kea-hook/7456] LEASE4_SELECT_VIRKIR_SUBNET virkir selects this subnet: 192.168.30.0/24
2018-10-30 12:30:19.463 DEBUG [kea-dhcp4.virkir-kea-hook/7456] LEASE4_SELECT_KEA_SUBNET kea want to select this subnet: 10.206.0.0/22
2018-10-30 12:30:19.464 DEBUG [kea-dhcp4.virkir-kea-hook/7456] LEASE4_SELECT_MISMATCH there is a mismatch in subnet selection, clean database and respond with nak
2018-10-30 12:30:19.464 DEBUG [kea-dhcp4.virkir-kea-hook/7456] pkt4_send Start
2018-10-30 12:30:19.464 DEBUG [kea-dhcp4.virkir-kea-hook/7456] PKT4_SEND_NAK sending nak package to client: c8:d3:ff:ee:ff:4c



Regards, Hreiðar.


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.isc.org/pipermail/kea-dev/attachments/20181106/b619be0d/attachment-0001.html>


More information about the kea-dev mailing list