[ISC-support #19697] forensic_log hook double logs DHCPv6 packets with multiple leases (custom log format)
When using a custom log format with the forensic_log/legal_log premium hook, DHCPv6 packets that have multiple leases (for ex, an IA_NA and IA_PD lease) end up getting double (quadruple?) logged. This issue is not present when not specifying a custom logging format. Logs of the issue follow.
Log entries when no custom log format is present:
2021-11-09 02:55:07 PST Address: 2001:db8:ffff:100::1 has been assigned for 1 hrs 6 mins 40 secs to a device with DUID: 00:04:ac:fa:ac:6d:4b:0f:4c:38:9e:40:92:45:34:ad:4f:55
2021-11-09 02:55:07 PST Prefix: 2001:db8:abcd:1::/64 has been assigned for 1 hrs 6 mins 40 secs to a device with DUID: 00:04:ac:fa:ac:6d:4b:0f:4c:38:9e:40:92:45:34:ad:4f:55Log entries when custom log format from kea-docs is present:
2021-11-09 03:04:21 PST Address: 2001:db8:ffff:100::1 has been assigned for 4000 seconds to a device with DUID: 00:04:ac:fa:ac:6d:4b:0f:4c:38:9e:40:92:45:34:ad:4f:55Prefix: 2001:db8:abcd:1::/64 has been assigned for 4000 seconds to a device with DUID: 00:04:ac:fa:ac:6d:4b:0f:4c:38:9e:40:92:45:34:ad:4f:55
2021-11-09 03:04:21 PST Address: 2001:db8:ffff:100::1 has been assigned for 4000 seconds to a device with DUID: 00:04:ac:fa:ac:6d:4b:0f:4c:38:9e:40:92:45:34:ad:4f:55Prefix: 2001:db8:abcd:1::/64 has been assigned for 4000 seconds to a device with DUID: 00:04:ac:fa:ac:6d:4b:0f:4c:38:9e:40:92:45:34:ad:4f:55I've attached a kea-dhcp6 configuration file that reproduces this issuse. Support19697-config.json
This issue originates from a customer bug report that can be found here: https://support.isc.org/Ticket/Display.html?id=19697
After some quick debugging, I can see that the incorrectly formatted string is being returned from evaluateString() here: https://gitlab.isc.org/isc-private/kea-premium/-/blob/master/src/hooks/dhcp/forensic_log/lease6_callouts.cc#L130
You can see that the genLease6Entry() function has different code paths when using the default logging format vs the custom logging format. With the default logging format, only the first lease passed is worked on. When a custom format string is used, the whole packet as well as the the format string is passed to evaluateString(), which looks like it will try to parse out the contents of entire packet, which causes the log lines to each contain both leases: https://gitlab.isc.org/isc-projects/kea/-/blob/master/src/lib/eval/evaluate.cc#L30
The reason why the double logged entry appears twice is because pkt6_send() (https://gitlab.isc.org/isc-private/kea-premium/-/blob/master/src/hooks/dhcp/forensic_log/lease6_callouts.cc#L365) is calling legalLog6Handler() once per lease in the packet. If more than two leases are included in a packet, say multiple IA_NA leases for multiple interfaces on a requesting box, the number of logged lines will match the number of leases in the packet, and the contents of each log line will show every lease.
I'm not quite sure how to fix this short of writing a new evaluateString() function that works on leases instead of packets.