[Kea-users] Duplicate logging
Darren Ankney
darren.ankney at gmail.com
Fri Aug 14 08:35:16 UTC 2026
Hi Jim,
Have a look at the relay address field in wireshark. Perhaps multiple
relays are picking up the packets and relaying them to the DHCP
server? If not, perhaps there is some VLAN problem where VLAN tags
are not being dealt with properly at ingress and so two copies of the
packets are being presented to Kea (which does not support VLAN
tagginb by the way). Or Kea is listening on a physical interface and
should be listening on a VLAN interface?
Thank you,
Darren Ankney
On Wed, Aug 12, 2026 at 11:19 AM Jim <jim at wrightthisway.com> wrote:
>
> Hey Darren. I really appreciate the assistance here, and I’ve been able to confirm this is not a Kea issue. Yesterday I did an actual tcpdump on the dhcp server itself and found that it was seeing two packets coming in for dhcp. Oddly sniffing the network connection to the server externally was only seeing a single packet. And NTP packets aren’t duplicated. I’ve uninstalled some security/antivirus tools here that I thought may have been causing issues but nothing I’ve tried has cleared this up.
>
> I don’t have any explanation for where these dupe packets are coming from, my next step is likely going to be to reimage the server and build it back up.
>
> Sent from my iPhone
>
> > On Aug 11, 2026, at 7:58 PM, Darren Ankney <darren.ankney at gmail.com> wrote:
> >
> > Hi Jim,
> >
> > The thread ID is this part: 139861628155584 inside the square
> > brackets. For one of the packets it is: 139861628155584 and for the
> > other it is 139861619762880 the part you thought was the thread id is
> > the transaction ID (see RFC 2131). That matches but that is
> > unsurprising with a duplicated packet. If the logs were being
> > duplicated then the thread ids would be exactly the same.
> >
> > Thank you,
> > Darren Ankney
> >
> >> On Mon, Aug 10, 2026 at 11:31 AM <jim at wrightthisway.com> wrote:
> >>
> >> Hey Darren, it looks to me like the thread ID does match? 0xf90b62 for
> >> both.
> >>
> >> I've done a packet capture for that server, it also acts as an NTP
> >> server and those packets appear normal and not duplicated. Looking at
> >> the DHCP packets, I'm only seeing ONE Discover packets going to the
> >> server, but then see two replies. So the DHCP server is handling this
> >> twice.
> >>
> >> Time Source Destination Protocol Length Info
> >> 2.008807 100.67.122.254 100.67.10.20 DHCP 337 DHCP
> >> Discover - Transaction ID 0xbaef852c
> >> 2.009683 100.67.10.20 100.67.122.254 DHCP 363 DHCP Offer
> >> - Transaction ID 0xbaef852c
> >> 2.010090 100.67.10.20 100.67.122.254 DHCP 363 DHCP Offer
> >> - Transaction ID 0xbaef852c
> >>
> >> And with only one Kea process running, I'm really stumped as to what's
> >> going on here.
> >>
> >>
> >>> On 2026-08-10 03:41, Darren Ankney wrote:
> >>> Hi Jim,
> >>>
> >>> Adding the thread ID (and inspection of the log configuration)
> >>> indicates that these are not duplicated log messages:
> >>>
> >>> 2026-08-09 11:55:20.510 INFO [kea-dhcp4.dhcp4/312252.139861619762880]
> >>> DHCP4_QUERY_LABEL received query: [hwtype=1 b4:45:06:eb:25:69],
> >>> cid=[01:b4:45:06:eb:25:69], tid=0xf908b62
> >>>
> >>> 2026-08-09 11:55:20.510 INFO [kea-dhcp4.dhcp4/312252.139861628155584]
> >>> DHCP4_QUERY_LABEL received query: [hwtype=1 b4:45:06:eb:25:69],
> >>> cid=[01:b4:45:06:eb:25:69], tid=0xf908b62
> >>>
> >>> Note that the thread ID between the two messages above do not match.
> >>> These are most likely duplicated packets.
> >>>
> >>> Thank you,
> >>> Darren Ankney
> >>>
> >>> On Sun, Aug 9, 2026 at 12:04 PM <jim at wrightthisway.com> wrote:
> >>>>
> >>>> Hi Darren, you are correct that the [%c/%i.%t] pattern wasn't part of
> >>>> my
> >>>> logging, I went back to my earliest config file and didn't see it
> >>>> listed, not sure if the RHEL package had that changed or not by
> >>>> default,
> >>>> but I did just now add that to my pattern.
> >>>>
> >>>> "loggers": [
> >>>> {
> >>>> "name": "kea-dhcp4",
> >>>> "output-options": [
> >>>> {
> >>>> "output": "kea-dhcp4.log",
> >>>> "pattern": "%D{%Y-%m-%d %H:%M:%S.%q} %-5p [%c/%i.%t]
> >>>> %m\n",
> >>>> "maxsize": 150000000,
> >>>> "maxver": 8
> >>>> }
> >>>> ],
> >>>>
> >>>> "severity": "INFO"
> >>>> },
> >>>>
> >>>> Here is the updated logging I'm seeing:
> >>>> 2026-08-09 11:55:20.510 INFO [kea-dhcp4.dhcp4/312252.139861619762880]
> >>>> DHCP4_QUERY_LABEL received query: [hwtype=1 b4:45:06:eb:25:69],
> >>>> cid=[01:b4:45:06:eb:25:69], tid=0xf908b62
> >>>> 2026-08-09 11:55:20.510 INFO [kea-dhcp4.dhcp4/312252.139861628155584]
> >>>> DHCP4_QUERY_LABEL received query: [hwtype=1 b4:45:06:eb:25:69],
> >>>> cid=[01:b4:45:06:eb:25:69], tid=0xf908b62
> >>>> 2026-08-09 11:55:20.510 INFO
> >>>> [kea-dhcp4.packets/312252.139861619762880]
> >>>> DHCP4_PACKET_RECEIVED [hwtype=1 b4:45:06:eb:25:69],
> >>>> cid=[01:b4:45:06:eb:25:69], tid=0xf908b627: DHCPINF.254 to
> >>>> 100.67.10.20
> >>>> on interface eno16895np0
> >>>> 2026-08-09 11:55:20.510 INFO
> >>>> [kea-dhcp4.packets/312252.139861628155584]
> >>>> DHCP4_PACKET_RECEIVED [hwtype=1 b4:45:06:eb:25:69],
> >>>> cid=[01:b4:45:06:eb:25:69], tid=0xf908b627: DHCPINF.254 to
> >>>> 100.67.10.20
> >>>> on interface eno16895np0
> >>>> 2026-08-09 11:55:20.510 INFO
> >>>> [kea-dhcp4.packets/312252.139861628155584]
> >>>> DHCP4_PACKET_SEND [hwtype=1 b4:45:06:eb:25:69],
> >>>> cid=[01:b4:45:06:eb:25:69], tid=0xf908b627: trying to s.67.10.20:67 to
> >>>> 100.67.98.232:68 on interface eno16895np0
> >>>> 2026-08-09 11:55:20.510 INFO
> >>>> [kea-dhcp4.packets/312252.139861619762880]
> >>>> DHCP4_PACKET_SEND [hwtype=1 b4:45:06:eb:25:69],
> >>>> cid=[01:b4:45:06:eb:25:69], tid=0xf908b627: trying to s.67.10.20:67 to
> >>>> 100.67.98.232:68 on interface eno16895np0
> >>>>
> >>>> As far as I can tell I only have one Kea process running on this
> >>>> server.
> >>>> [root at 100671020-2 kea]# ps aux | grep kea
> >>>> kea 312252 0.0 0.1 1832636 24524 ? Ssl 11:55 0:00
> >>>> /usr/sbin/kea-dhcp4 -c /etc/kea/kea-dhcp4.conf
> >>>> root 312828 0.0 0.0 227704 2260 pts/1 S+ 12:01 0:00
> >>>> grep
> >>>> --color=auto kea
> >>>>
> >>>>
> >>>> Again, this happened suddenly with no changes to the system at that
> >>>> time. My next step is to get a packet dump from what's reaching this
> >>>> server to see if somehow packets being sent are duplicated for some
> >>>> reason, that will be for Monday though.
> >>>>
> >>>>
> >>>> On 2026-08-08 05:01, Darren Ankney wrote:
> >>>>> Hi,
> >>>>>
> >>>>> It won't be possible to help you with this without at least the
> >>>>> loggers section of your configuration. It also looks like you may
> >>>>> have changed the logging pattern and did not include this part:
> >>>>> "[%c/%i.%t]" which would have shown which logger was producing the
> >>>>> log, the process id (to rule out the possibility of multiple Kea
> >>>>> servers running), and finally the thread id (which would have been the
> >>>>> final piece proving that it was the same log duplicated).
> >>>>> Additionally, these values are often helpful when you are trying to
> >>>>> trace what happened with a particular packet as they can move to
> >>>>> different threads when parked during certain hook callouts and the
> >>>>> like. It is often helpful to organize the logs by thread id when
> >>>>> looking deeply at some behavior.
> >>>>>
> >>>>> Please attach a copy of your "loggers" configuration to progress
> >>>>> troubleshooting.
> >>>>>
> >>>>> Thank you,
> >>>>> Darren Ankney
> >>>>>
> >>>>> On Fri, Aug 7, 2026 at 4:10 PM Jim <jim at wrightthisway.com> wrote:
> >>>>>>
> >>>>>> I don’t check my logs often but was making an update to my config and
> >>>>>> something odd caught my eye, I’m getting a number of lines duplicated.
> >>>>>> My config hasn’t changed for months until today, and this started
> >>>>>> happening back in July 28, it looks like Kea reloaded itself and
> >>>>>> that’s when the dupes began.
> >>>>>>
> >>>>>> I checked the logs and all I see is Version 3.0.3 listed both before
> >>>>>> and after that, so I don’t think the actual software release changed,
> >>>>>> yum shows my version as 3.0.3-1.el10_2.
> >>>>>>
> >>>>>> Sample log lines that are dupes:
> >>>>>>
> >>>>>> 2026-08-07 16:01:09.625 INFO DHCP4_QUERY_LABEL received query:
> >>>>>> [hwtype=1 0c:29:ef:e2:05:80], cid=[no info], tid=0xd14ec51b
> >>>>>>
> >>>>>> 2026-08-07 16:01:09.625 INFO DHCP4_QUERY_LABEL received query:
> >>>>>> [hwtype=1 0c:29:ef:e2:05:80], cid=[no info], tid=0xd14ec51b
> >>>>>>
> >>>>>> 2026-08-07 16:01:09.625 INFO DHCP4_PACKET_RECEIVED [hwtype=1
> >>>>>> 0c:29:ef:e2:05:80], cid=[no info], tid=0xd14ec51b: DHCPDISCOVER (type
> >>>>>> 1) received from 100.67.122.254 to 100.67.10.20 on interface
> >>>>>> eno16895np0
> >>>>>>
> >>>>>> 2026-08-07 16:01:09.625 INFO DHCP4_PACKET_RECEIVED [hwtype=1
> >>>>>> 0c:29:ef:e2:05:80], cid=[no info], tid=0xd14ec51b: DHCPDISCOVER (type
> >>>>>> 1) received from 100.67.122.254 to 100.67.10.20 on interface
> >>>>>> eno16895np0
> >>>>>>
> >>>>>> 2026-08-07 16:01:09.626 INFO DHCP4_PACKET_SEND [hwtype=1
> >>>>>> 0c:29:ef:e2:05:80], cid=[no info], tid=0xd14ec51b: trying to send
> >>>>>> packet DHCPOFFER (type 2) from 100.67.10.20:67 to 100.67.122.254:67 on
> >>>>>> interface eno16895np0
> >>>>>>
> >>>>>> 2026-08-07 16:01:09.626 INFO DHCP4_PACKET_SEND [hwtype=1
> >>>>>> 0c:29:ef:e2:05:80], cid=[no info], tid=0xd14ec51b: trying to send
> >>>>>> packet DHCPOFFER (type 2) from 100.67.10.20:67 to 100.67.122.254:67 on
> >>>>>> interface eno16895np0
> >>>>>>
> >>>>>> --
> >>>>>> ISC funds the development of this software with paid support
> >>>>>> subscriptions. Contact us at https://www.isc.org/contact/ for more
> >>>>>> information.
> >>>>>>
> >>>>>> To unsubscribe visit https://lists.isc.org/mailman/listinfo/kea-users.
> >>>>>> Kea-users at lists.isc.org
More information about the Kea-users
mailing list