Client trying to renew lease being incorrectly sent DHCPNAK and then moved to different IP with ALLOC_ENGINE_V4_DISCOVER_ADDRESS_CONFLICT
Describe the bug A clear and concise description of what the bug is.
I've been running into an issue where a client sends a DHCPDISCOVER and the following is true:
- Client already has a lease
- Client has a reservation matching lease
This is my first bug report so let me know if you need more info
To Reproduce
Steps to reproduce the behavior:
- Run Kea dhcpv4 with a standard subnet config
- Create a reservation for the client
- Client boots up correctly and gets the reservation
- Client later sends a DHCPDISCOVER (not clear why, but it should still be fine) - not that it does come via a relay
138.80.150.1
in this log - Client is assigned the wrong IP because the server sees it as a lease conflict, even though the MAC address matches and everything looks the same to me.
Expected behavior
I would expect the server to just treat the DHCPDISCOVER as a renewal for the existing lease, because of the matching MAC/CID and reservation
Environment:
[root@dhcppal1]# /opt/kea/sbin/kea-dhcp4 -V
1.6.2
tarball
linked with:
log4cplus 1.2.0
OpenSSL 1.1.1g FIPS 21 Apr 2020
database:
Memfile backend 2.1
- OS: RHEL 8.2
- Nothing extra, just used
./configure --prefix=/opt/kea162
- Which hooks where loaded in: HA - in a hot-spare config.
Additional Information Here's the subnet config:
{
# Palmerston
"subnet": "138.80.150.0/24",
"id": 1500,
"pools": [
{ "pool": "138.80.150.10 - 138.80.150.254" }
],
# "valid-lifetime": 691200, # 8 days lease times for servers - recuced because there were leases never being cleaned up
# "renew-timer": 86400, # renew every 1 day
# "rebind-timer": 518400, # rebind after 6 days if needed
### Shortened for testing 20202-11-19 - jtuckey
"valid-lifetime": 6912, # 8 days lease times for servers - recuced because there were leases never being cleaned up
"renew-timer": 864, # renew every 1 day
"rebind-timer": 5184, # rebind after 6 days if needed
"option-data": [
{ "name": "routers", "data": "138.80.150.1" }
],
"reservations": [
# Make sure to also copy the reservations file
<?include "reservations/138.80.150.0_24.json"?>
]
}
Reservation:
{
# jtuckey - 2020-11-05 - dyndnsprd1 dynamic dns server
"hw-address": "00:50:56:8a:db:0e",
"ip-address": "138.80.150.34"
}
Here's a log dump at DEBUG/level 99 of the issue occurring:
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.packets DHCP4_BUFFER_RECEIVED received buffer from 138.80.150.1:67 to 138.80.255.102:67 over interface dhcp
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.callouts HOOKS_CALLOUTS_BEGIN begin all callouts for hook buffer4_receive
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.callouts HOOKS_CALLOUT_CALLED hooks library with index 2 has called a callout on hook buffer4_receive that has address 0x7feb57f2bb80 (callout duration: 0.056 ms)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.callouts HOOKS_CALLOUTS_COMPLETE completed callouts for hook buffer4_receive (total callouts duration: 0.056 ms)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.hooks DHCP4_HOOK_BUFFER_RCVD_SKIP received buffer from 138.80.150.1 to 138.80.255.102 over interface dhcp is not parsed because a callout set the next step to SKIP.
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.packets DHCP4_PACKET_RECEIVED [hwtype=1 00:50:56:8a:db:0e], cid=[01:00:50:56:8a:db:0e], tid=0x333a0e3c: DHCPDISCOVER (type 1) received from 138.80.150.1 to 138.80.255.102 on interface dhcp
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.packets DHCP4_QUERY_DATA [hwtype=1 00:50:56:8a:db:0e], cid=[01:00:50:56:8a:db:0e], tid=0x333a0e3c, packet details: local_address=138.80.255.102:67, remote_address=138.80.150.1:67, msg_type=DHCPDISCOVER (1), transid=0x333a0e3c,
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: options:
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=012, len=010: "dyndnsprd1" (string)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=050, len=004: 138.80.150.34 (ipv4-address)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=053, len=001: 1 (uint8)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=055, len=017: 1(uint8) 2(uint8) 6(uint8) 12(uint8) 15(uint8) 26(uint8) 28(uint8) 121(uint8) 3(uint8) 33(uint8) 40(uint8) 41(uint8) 42(uint8) 119(uint8) 249(uint8) 252(uint8) 17(uint8)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=057, len=002: 576 (uint16)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=061, len=007: 01:00:50:56:8a:db:0e
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.dhcpsrv DHCPSRV_CFGMGR_SUBNET4_ADDR selected subnet 138.80.150.0/24 for packet received by matching address 138.80.150.1
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.packets DHCP4_SUBNET_SELECTED [hwtype=1 00:50:56:8a:db:0e], cid=[01:00:50:56:8a:db:0e], tid=0x333a0e3c: the subnet with ID 1500 was selected for client assignments
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.packets DHCP4_SUBNET_DATA [hwtype=1 00:50:56:8a:db:0e], cid=[01:00:50:56:8a:db:0e], tid=0x333a0e3c: the selected subnet details: 138.80.150.0/24
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.hosts HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER get one host with IPv4 reservation for subnet id 1500, identified by hwaddr=0050568ADB0E
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.hosts HOSTS_CFG_GET_ALL_IDENTIFIER get all hosts with reservations using identifier: hwaddr=0050568ADB0E
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.hosts HOSTS_CFG_GET_ALL_IDENTIFIER_HOST using identifier: hwaddr=0050568ADB0E, found host: hwaddr=0050568ADB0E ipv4_subnet_id=1500 hostname=(empty) ipv4_reservation=138.80.150.34 siaddr=(no) sname=(empty) file=(empty) key=(empty) ipv6_reservations=(none)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.hosts HOSTS_CFG_GET_ALL_IDENTIFIER_COUNT using identifier hwaddr=0050568ADB0E, found 1 host(s)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.hosts HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER_HOST using subnet id 1500 and identifier hwaddr=0050568ADB0E, found host: hwaddr=0050568ADB0E ipv4_subnet_id=1500 hostname=(empty) ipv4_reservation=138.80.150.34 siaddr=(no) sname=(empty) file=(empty) key=(empty) ipv6_reservations=(none)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.dhcp4 DHCP4_CLASS_ASSIGNED [hwtype=1 00:50:56:8a:db:0e], cid=[01:00:50:56:8a:db:0e], tid=0x333a0e3c: client packet has been assigned to the following class(es): KNOWN
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.dhcp4 DHCP4_CLASS_ASSIGNED [hwtype=1 00:50:56:8a:db:0e], cid=[01:00:50:56:8a:db:0e], tid=0x333a0e3c: client packet has been assigned to the following class(es): HA_dhcp1, ALL, KNOWN
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.ddns DHCP4_CLIENT_HOSTNAME_PROCESS [hwtype=1 00:50:56:8a:db:0e], cid=[01:00:50:56:8a:db:0e], tid=0x333a0e3c: processing client's Hostname option
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.ddns DHCP4_CLIENT_HOSTNAME_DATA [hwtype=1 00:50:56:8a:db:0e], cid=[01:00:50:56:8a:db:0e], tid=0x333a0e3c: client sent Hostname option: dyndnsprd1
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.ddns DHCP4_RESPONSE_HOSTNAME_DATA [hwtype=1 00:50:56:8a:db:0e], cid=[01:00:50:56:8a:db:0e], tid=0x333a0e3c: including Hostname option in the server's response: dyndnsprd1
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.dhcpsrv DHCPSRV_MEMFILE_GET_CLIENTID obtaining IPv4 leases for client ID 01:00:50:56:8a:db:0e
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.alloc-engine ALLOC_ENGINE_V4_DISCOVER_HR client [hwtype=1 00:50:56:8a:db:0e], cid=[01:00:50:56:8a:db:0e], tid=0x333a0e3c sending DHCPDISCOVER has reservation for the address 138.80.150.34
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.dhcpsrv DHCPSRV_MEMFILE_GET_ADDR4 obtaining IPv4 lease for address 138.80.150.34
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: WARN kea-dhcp4.alloc-engine ALLOC_ENGINE_V4_DISCOVER_ADDRESS_CONFLICT [hwtype=1 00:50:56:8a:db:0e], cid=[01:00:50:56:8a:db:0e], tid=0x333a0e3c: conflicting reservation for address 138.80.150.34 with existing lease Address: 138.80.150.34
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: Valid life: 6912
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: Cltt: 1605758850
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: Hardware addr: 00:50:56:8a:db:0e
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: Client id: 01:00:50:56:8a:db:0e
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: Subnet ID: 1500
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: State: default
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.hosts HOSTS_CFG_GET_ONE_SUBNET_ID_ADDRESS4 get one host with reservation for subnet id 1500 and IPv4 address 138.80.150.32
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.hosts HOSTS_CFG_GET_ALL_ADDRESS4 get all hosts with reservations for IPv4 address 138.80.150.32
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.hosts HOSTS_CFG_GET_ALL_ADDRESS4_COUNT using address 138.80.150.32, found 0 host(s)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.hosts HOSTS_CFG_GET_ONE_SUBNET_ID_ADDRESS4_NULL host not found using subnet id 1500 and address 138.80.150.32
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.alloc-engine ALLOC_ENGINE_V4_OFFER_EXISTING_LEASE allocation engine will try to offer existing lease to the client [hwtype=1 00:50:56:8a:db:0e], cid=[01:00:50:56:8a:db:0e], tid=0x333a0e3c
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: INFO kea-dhcp4.leases DHCP4_LEASE_ADVERT [hwtype=1 00:50:56:8a:db:0e], cid=[01:00:50:56:8a:db:0e], tid=0x333a0e3c: lease 138.80.150.32 will be advertised
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.options DHCP4_PACKET_PACK [hwtype=1 00:50:56:8a:db:0e], cid=[01:00:50:56:8a:db:0e], tid=0x333a0e3c: preparing on-wire format of the packet to be sent
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.packets DHCP4_PACKET_SEND [hwtype=1 00:50:56:8a:db:0e], cid=[01:00:50:56:8a:db:0e], tid=0x333a0e3c: trying to send packet DHCPOFFER (type 2) from 138.80.255.102:67 to 138.80.150.1:67 on interface dhcp
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.packets DHCP4_RESPONSE_DATA [hwtype=1 00:50:56:8a:db:0e], cid=[01:00:50:56:8a:db:0e], tid=0x333a0e3c: responding with packet DHCPOFFER (type 2), packet details: local_address=138.80.255.102:67, remote_address=138.80.150.1:67, msg_type=DHCPOFFER (2), transid=0x333a0e3c,
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: options:
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=001, len=004: 4294967040 (uint32)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=003, len=004: 138.80.150.1
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=006, len=008: 138.80.255.100 138.80.255.200
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=012, len=010: "dyndnsprd1" (string)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=015, len=010: "cdu.edu.au" (string)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=042, len=012: 138.80.12.1 138.80.12.5 138.80.12.7
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=051, len=004: 6912 (uint32)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=053, len=001: 2 (uint8)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=054, len=004: 138.80.255.102
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=058, len=004: 864 (uint32)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=059, len=004: 5184 (uint32)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=061, len=007: 01:00:50:56:8a:db:0e
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: type=119, len=050: "cdu.edu.au." (fqdn) "cducloud.cdu.edu.au." (fqdn) "cdu-staff.local." (fqdn)
Nov 19 13:53:25 dhcppal1 kea-dhcp4[50758]: DEBUG kea-dhcp4.packets DHCP4_BUFFER_RECEIVED received buffer from 138.80.150.1:67 to 138.80.255.102:67 over interface dhcp
Contacting you
I've available at jay.tuckey <at>
cdu.edu.au or via Gitlab: https://gitlab.com/jaytuck