iapd prefix not released in time for next advertise
On jenkins, and on slow systems, Kea is unable to release prefix in time for incoming Solicit.
The problem exists only when releasing prefix.
Problem observed on test: tests/dhcp/v6/test_prefix_delegation.py::test_prefix_delegation_noprefixavail_release
- Test starts Kea
- Forge sends Solicit with IA-PD and client id and waits for advertise with option 25.
- Forge Sends Request with IA-PD and client id and waits for reply with option 26 in 25.
- Forge second Solicit with IA-PD and client id and waits for advertise with option 25.
- Forge sends Request with IA-PD and client id and waits for reply with option 26 in 25.
- Both available prefixes are assigned
- Forge third Solicit with IA-PD and client id and waits for advertise with no lease available.
- Forge sends Release with client id and waits for reply with confirmation.
- Forge fourth Solicit with IA-PD and client id and waits for advertise with option 26 in 25
On local VM test passes - Kea can release prefix in a timely manner. On Jenkins and local VM with CPU slowed down to 2%, the test fails.
It looks like releasing prefix takes over 200ms after log message on slower machine.
Test run with failure: https://jenkins.aws.isc.org/view/Kea-manual/job/kea-manual/job/tarball-system-tests/235/
Test run with introduced delay after release passes: https://jenkins.aws.isc.org/view/Kea-manual/job/kea-manual/job/tarball-system-tests/234/
2022-12-22 23:00:12.726 DEBUG [kea-dhcp6.packets/2570743.140676907595328] DHCP6_RESPONSE_DATA responding with packet type 7 data is localAddr=[ff02::1:2]:547 remoteAddr=[fe80::21b:2cff:fe00:99]:546
msgtype=7(REPLY), transid=0xa596df
type=00001, len=00014: 00:01:00:01:63:a4:e1:76:00:1b:2c:00:00:99
type=00002, len=00014: 00:01:00:01:2b:37:9d:f8:86:32:67:b7:f6:87
type=00013, len=00041: Success(0) "Summary status for all processed IA_NAs"
type=00025(IA_PD), len=00063: iaid=36171, t1=0, t2=0,
options:
type=00013, len=00047: Success(0) "Lease released. Thank you, please come again."
No relays traversed.
(...)
2022-12-22 23:00:12.862 DEBUG [kea-dhcp6.dhcpsrv/2570743.140676915988032] DHCPSRV_CFGMGR_SUBNET6_IFACE selected subnet 3000::/64 for packet received over interface enp0s9
(...)
2022-12-22 23:00:12.862 WARN [kea-dhcp6.alloc-engine/2570743.140676915988032] ALLOC_ENGINE_V6_ALLOC_FAIL_SUBNET duid=[00:01:00:01:63:a4:e1:76:00:1b:2c:00:00:99], tid=0xa596df: failed to allocate an IPv6 lease in the subnet 3000::/64, subnet-id 1, shared network (none)
Edited by Marcin Godzina