Skip to content

DHCPINFORM is only logged on DEBUG level

Describe the bug

I'm currently working on a project to migrate a Windows DHCP server environment to Kea. Right now both are active and I'm looking at logs and tcpdump captures while fiddling with the config.

I got confused because there were DHCPACK messages originated by the Kea server while there was not a single log entry visible. Increasing the logging verbosity to DEBUG shows a large number of messages, all with severity DEBUG.

Kea should not interact with clients over the network without logging.

To Reproduce Steps to reproduce the behavior:

  1. Run Kea dhcpv4 with a logging config like https://gitlab.isc.org/isc-projects/kea/-/blob/master/doc/examples/kea4/single-subnet.json?ref_type=heads
  2. have a client send DHCPINFORM while running tcpdump
  3. observe a DHCPACK being generated in tcpdump with Kea not logging a single line

Expected behavior

At least one line should be logged on INFO level when Kea is receiving and answering a DHCPINFORM request.

Environment:

  • Kea version: 2.4.1
  • OS: Debian Bookworm

Additional Information

2024-01-02 20:14:36.523 DEBUG [kea-dhcp4.packets/1.140376903606784] DHCP4_BUFFER_RECEIVED received buffer from 10.1.0.142:68 to 255.255.255.255:67 over interface ens19
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.dhcpsrv/1.140376869664512] DHCPSRV_SUBNET4_SELECT_NO_RAI_OPTIONS No RAI options found to use for subnet selection.
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.dhcpsrv/1.140376869664512] DHCPSRV_SUBNET4_SELECT_NO_RELAY_ADDRESS Relay address (giaddr) in client packet is empty.
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.dhcpsrv/1.140376869664512] DHCPSRV_SUBNET4_SELECT_BY_INTERFACE_NO_MATCH No subnet matches interface: ens19
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.dhcpsrv/1.140376869664512] DHCPSRV_CFGMGR_SUBNET4_ADDR selected subnet 10.1.0.0/16 for packet received by matching address 10.1.4.1
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.packets/1.140376869664512] DHCP4_SUBNET_SELECTED [hwtype=1 ee:bd:63:c3:73:93], cid=[01:ee:bd:63:c3:73:93], tid=0xfe6e0c6f: the subnet with ID 10001000 was selected for client assignments
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.packets/1.140376869664512] DHCP4_PACKET_RECEIVED [hwtype=1 ee:bd:63:c3:73:93], cid=[01:ee:bd:63:c3:73:93], tid=0xfe6e0c6f: DHCPINFORM (type 8) received from 10.1.0.142 to 255.255.255.255 on interface ens19
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.dhcpsrv/1.140376869664512] DHCPSRV_SUBNET4_SELECT_NO_RAI_OPTIONS No RAI options found to use for subnet selection.
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.dhcpsrv/1.140376869664512] DHCPSRV_SUBNET4_SELECT_NO_RELAY_ADDRESS Relay address (giaddr) in client packet is empty.
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.dhcpsrv/1.140376869664512] DHCPSRV_SUBNET4_SELECT_BY_INTERFACE_NO_MATCH No subnet matches interface: ens19
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.dhcpsrv/1.140376869664512] DHCPSRV_CFGMGR_SUBNET4_ADDR selected subnet 10.1.0.0/16 for packet received by matching address 10.1.4.1
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.packets/1.140376869664512] DHCP4_SUBNET_SELECTED [hwtype=1 ee:bd:63:c3:73:93], cid=[01:ee:bd:63:c3:73:93], tid=0xfe6e0c6f: the subnet with ID 10001000 was selected for client assignments
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.hosts/1.140376869664512] HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER get one host with IPv4 reservation for subnet id 0, identified by hwaddr=EEBD63C37393
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.hosts/1.140376869664512] HOSTS_CFG_GET_ALL_IDENTIFIER get all hosts with reservations using identifier: hwaddr=EEBD63C37393
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.hosts/1.140376869664512] HOSTS_CFG_GET_ALL_IDENTIFIER_COUNT using identifier hwaddr=EEBD63C37393, found 1 host(s)
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.hosts/1.140376869664512] HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER_NULL host not found using subnet id 0 and identifier hwaddr=EEBD63C37393
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.hosts/1.140376869664512] HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER get one host with IPv4 reservation for subnet id 0, identified by client-id=01EEBD63C37393
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.hosts/1.140376869664512] HOSTS_CFG_GET_ALL_IDENTIFIER get all hosts with reservations using identifier: client-id=01EEBD63C37393
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.hosts/1.140376869664512] HOSTS_CFG_GET_ALL_IDENTIFIER_COUNT using identifier client-id=01EEBD63C37393, found 0 host(s)
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.hosts/1.140376869664512] HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER_NULL host not found using subnet id 0 and identifier client-id=01EEBD63C37393
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.hosts/1.140376869664512] HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER get one host with IPv4 reservation for subnet id 10001000, identified by hwaddr=EEBD63C37393
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.hosts/1.140376869664512] HOSTS_CFG_GET_ALL_IDENTIFIER get all hosts with reservations using identifier: hwaddr=EEBD63C37393
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.hosts/1.140376869664512] HOSTS_CFG_GET_ALL_IDENTIFIER_COUNT using identifier hwaddr=EEBD63C37393, found 1 host(s)
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.hosts/1.140376869664512] HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER_HOST using subnet id 10001000 and identifier hwaddr=EEBD63C37393, found host: hwaddr=EEBD63C37393 ipv4_subnet_id=10001000 hostname=(empty) ipv4_reservation=10.1.0.142 siaddr=(no) sname=(empty) file=(empty) key=(empty) ipv6_reservations=(none)
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.dhcp4/1.140376869664512] DHCP4_CLASS_ASSIGNED [hwtype=1 ee:bd:63:c3:73:93], cid=[01:ee:bd:63:c3:73:93], tid=0xfe6e0c6f: client packet has been assigned to the following class(es): KNOWN
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.dhcp4/1.140376869664512] DHCP4_CLASS_ASSIGNED [hwtype=1 ee:bd:63:c3:73:93], cid=[01:ee:bd:63:c3:73:93], tid=0xfe6e0c6f: client packet has been assigned to the following class(es): ALL, VENDOR_CLASS_MSFT 5.0, KNOWN
dhcp4_1       | 2024-01-02 20:14:36.524 DEBUG [kea-dhcp4.packets/1.140376869664512] DHCP4_PACKET_SEND [hwtype=1 ee:bd:63:c3:73:93], cid=[01:ee:bd:63:c3:73:93], tid=0xfe6e0c6f: trying to send packet DHCPACK (type 5) from 10.1.4.1:67 to 10.1.0.142:68 on interface ens19
To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information