[Kea-users] Kea 1.6.3: ALLOC_ENGINE_V6_ALLOC_FAIL warning message even if the address is successfully assigned

Fri Jan 22 13:53:35 UTC 2021

Below is the same sequence with logs set to DEBUG:

2021-01-22 13:06:16.011 DEBUG [kea-dhcp6.dhcpsrv/1]
DHCPSRV_TIMERMGR_RUN_TIMER_OPERATION running operation for timer:
reclaim-expired-leases
2021-01-22 13:06:16.011 DEBUG [kea-dhcp6.alloc-engine/1]
ALLOC_ENGINE_V6_LEASES_RECLAMATION_START starting reclamation of expired
leases (limit = 100 leases or 250 milliseconds)
2021-01-22 13:06:16.011 DEBUG [kea-dhcp6.dhcpsrv/1]
DHCPSRV_MEMFILE_GET_EXPIRED6 obtaining maximum 101 of expired IPv6 leases
2021-01-22 13:06:16.011 DEBUG [kea-dhcp6.alloc-engine/1]
ALLOC_ENGINE_V6_LEASES_RECLAMATION_COMPLETE reclaimed 0 leases in 0.020 ms
2021-01-22 13:06:16.011 DEBUG [kea-dhcp6.alloc-engine/1]
ALLOC_ENGINE_V6_NO_MORE_EXPIRED_LEASES all expired leases have been
reclaimed
2021-01-22 13:06:16.011 DEBUG [kea-dhcp6.dhcpsrv/1]
DHCPSRV_TIMERMGR_START_TIMER starting timer: reclaim-expired-leases
2021-01-22 13:06:19.081 DEBUG [kea-dhcp6.packets/1] DHCP6_BUFFER_RECEIVED
received buffer from fd10:2::2:547 to fd10::7f17:0 over interface eth0
2021-01-22 13:06:19.081 DEBUG [kea-dhcp6.options/1] DHCP6_BUFFER_UNPACK
parsing buffer received from fd10:2::2 to fd10::7f17 over interface eth0
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.packets/1] DHCP6_PACKET_RECEIVED
duid=[00:03:00:06:00:17:3b:05:00:5f:00:30], tid=0xafcafc: SOLICIT (type 1)
received from fd10:2::2 to fd10::7f17 on interface eth0
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.packets/1] DHCP6_QUERY_DATA
duid=[00:03:00:06:00:17:3b:05:00:5f:00:30], tid=0xafcafc, packet details:
localAddr=[fd10::7f17]:0 remoteAddr=[fd10:2::2]:547
msgtype=1(SOLICIT), transid=0xafcafc
type=00001, len=00012: 00:03:00:06:00:17:3b:05:00:5f:00:30
type=00003(IA_NA), len=00012: iaid=0, t1=0, t2=0
type=00006, len=00002: 17(uint16)
type=00008, len=00002: 0 (uint16)
type=00014, len=00000:
type=00025(IA_PD), len=00012: iaid=0, t1=0, t2=0
1 relay(s):
relay[0]: msg-type=12(RELAY_FORWARD), hop-count=0,
link-address=fd10:1::, peer-address=fe80::217:3b05:5f:30, 2 option(s)
type=00018, len=00004: 00:00:00:17
type=00037, len=00022: 9 (uint32) 020041000000000A0003000100FEC897B048
(binary)

2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.dhcpsrv/1] DHCPSRV_CFGMGR_SUBNET6
retrieved subnet fd10:1::/64 for address hint fd10:1::
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.packets/1] DHCP6_SUBNET_SELECTED
duid=[00:03:00:06:00:17:3b:05:00:5f:00:30], tid=0xafcafc: the subnet with ID
1002 was selected for client assignments
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.packets/1] DHCP6_SUBNET_DATA
duid=[00:03:00:06:00:17:3b:05:00:5f:00:30], tid=0xafcafc: the selected
subnet details: fd10:1::/64
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.hosts/1]
HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER get one host with IPv6 reservation
for subnet id 1002, identified by hwaddr=00173B05005F0030
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.hosts/1]
HOSTS_CFG_GET_ALL_IDENTIFIER get all hosts with reservations using
identifier: hwaddr=00173B05005F0030
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.hosts/1]
HOSTS_CFG_GET_ALL_IDENTIFIER_COUNT using identifier hwaddr=00173B05005F0030,
found 0 host(s)
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.hosts/1]
HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER_NULL host not found using subnet id
1002 and identifier hwaddr=00173B05005F0030
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.hosts/1]
HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER get one host with IPv6 reservation
for subnet id 1002, identified by duid=0003000600173B05005F0030
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.hosts/1]
HOSTS_CFG_GET_ALL_IDENTIFIER get all hosts with reservations using
identifier: duid=0003000600173B05005F0030
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.hosts/1]
HOSTS_CFG_GET_ALL_IDENTIFIER_COUNT using identifier
duid=0003000600173B05005F0030, found 0 host(s)
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.hosts/1]
HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER_NULL host not found using subnet id
1002 and identifier duid=0003000600173B05005F0030
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.dhcp6/1] DHCP6_CLASS_ASSIGNED
duid=[00:03:00:06:00:17:3b:05:00:5f:00:30], tid=0xafcafc: client packet has
been assigned to the following class(es): UNKNOWN
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.options/1] DHCP6_RAPID_COMMIT
duid=[00:03:00:06:00:17:3b:05:00:5f:00:30], tid=0xafcafc: Rapid Commit
option received, following 2-way exchange
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.leases/1]
DHCP6_PROCESS_IA_NA_REQUEST duid=[00:03:00:06:00:17:3b:05:00:5f:00:30],
tid=0xafcafc: server is processing IA_NA option with iaid=0 and hint=(no
hint)
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.dhcpsrv/1]
DHCPSRV_MEMFILE_GET_IAID_DUID obtaining IPv6 leases for IAID 0 and DUID
00:03:00:06:00:17:3b:05:00:5f:00:30 and lease type IA_NA
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.alloc-engine/1]
ALLOC_ENGINE_V6_ALLOC_LEASES_NO_HR no reservations found but leases exist
for client duid=[00:03:00:06:00:17:3b:05:00:5f:00:30], tid=0xafcafc
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.hosts/1]
HOSTS_CFG_GET_ONE_SUBNET_ID_ADDRESS6 get one host with reservation for
subnet id 1002 and including IPv6 address fd10:1::1
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.hosts/1]
HOSTS_CFG_GET_ALL_SUBNET_ID_ADDRESS6 get all hosts with reservations for
subnet id 1002 and IPv6 address fd10:1::1
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.hosts/1]
HOSTS_CFG_GET_ALL_SUBNET_ID_ADDRESS6_COUNT using subnet id 1002 and address
fd10:1::1, found 0 host(s)
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.hosts/1]
HOSTS_CFG_GET_ONE_SUBNET_ID_ADDRESS6_NULL host not found using subnet id
1002 and address fd10:1::1
2021-01-22 13:06:19.082 DEBUG [kea-dhcp6.dhcpsrv/1]
DHCPSRV_MEMFILE_UPDATE_ADDR6 updating IPv6 lease for address fd10:1::1
2021-01-22 13:06:19.083 INFO  [kea-dhcp6.leases/1] DHCP6_LEASE_ALLOC
duid=[00:03:00:06:00:17:3b:05:00:5f:00:30], tid=0xafcafc: lease for address
fd10:1::1 and iaid=0 has been allocated for 2592000 seconds
2021-01-22 13:06:19.083 DEBUG [kea-dhcp6.leases/1] DHCP6_LEASE_DATA
duid=[00:03:00:06:00:17:3b:05:00:5f:00:30], tid=0xafcafc: detailed lease
information for iaid=0: Type:          IA_NA(0)
Address:       fd10:1::1
Prefix length: 128
IAID:          0
Pref life:     2592000
Valid life:    2592000
Cltt:          1611320779
DUID:          00:03:00:06:00:17:3b:05:00:5f:00:30
Hardware addr: 00:17:3b:05:00:5f:00:30
Subnet ID:     1002
State:         default

2021-01-22 13:06:19.083 DEBUG [kea-dhcp6.leases/1]
DHCP6_PROCESS_IA_PD_REQUEST duid=[00:03:00:06:00:17:3b:05:00:5f:00:30],
tid=0xafcafc: server is processing IA_PD option with iaid=0 and hint=(no
hint)
2021-01-22 13:06:19.083 DEBUG [kea-dhcp6.dhcpsrv/1]
DHCPSRV_MEMFILE_GET_IAID_DUID obtaining IPv6 leases for IAID 0 and DUID
00:03:00:06:00:17:3b:05:00:5f:00:30 and lease type IA_PD
2021-01-22 13:06:19.083 DEBUG [kea-dhcp6.alloc-engine/1]
ALLOC_ENGINE_V6_ALLOC_UNRESERVED no static reservations available - trying
to dynamically allocate leases for client
duid=[00:03:00:06:00:17:3b:05:00:5f:00:30], tid=0xafcafc
2021-01-22 13:06:19.083 WARN  [kea-dhcp6.alloc-engine/1]
ALLOC_ENGINE_V6_ALLOC_FAIL duid=[00:03:00:06:00:17:3b:05:00:5f:00:30],
tid=0xafcafc: failed to allocate an IPv6 address after 0 attempt(s)
2021-01-22 13:06:19.083 DEBUG [kea-dhcp6.leases/1] DHCP6_PD_LEASE_ALLOC_FAIL
duid=[00:03:00:06:00:17:3b:05:00:5f:00:30], tid=0xafcafc: failed to grant a
prefix lease for iaid=0
2021-01-22 13:06:19.083 DEBUG [kea-dhcp6.options/1]
DHCP6_ADD_STATUS_CODE_FOR_IA duid=[00:03:00:06:00:17:3b:05:00:5f:00:30],
tid=0xafcafc: adding Status Code to IA with iaid=0: NoPrefixAvail(6) "Sorry,
no prefixes could be allocated."
2021-01-22 13:06:19.083 DEBUG [kea-dhcp6.packets/1] DHCP6_PACKET_SEND
duid=[00:03:00:06:00:17:3b:05:00:5f:00:30], tid=0xafcafc: trying to send
packet REPLY (type 7) from [fd10::7f17]:547 to [fd10:2::2]:547 on interface
eth0
2021-01-22 13:06:19.083 DEBUG [kea-dhcp6.packets/1] DHCP6_RESPONSE_DATA
responding with packet type 7 data is localAddr=[fd10::7f17]:547
remoteAddr=[fd10:2::2]:547
msgtype=7(REPLY), transid=0xafcafc
type=00001, len=00012: 00:03:00:06:00:17:3b:05:00:5f:00:30
type=00002, len=00012: 00:02:00:00:09:bf:e2:00:df:5d:b6:e2
type=00003(IA_NA), len=00040: iaid=0, t1=1296000, t2=2073600,
options:
  type=00005(IAADDR), len=00024: address=fd10:1::1, preferred-lft=2592000,
valid-lft=2592000
type=00014, len=00000:
type=00017, len=00024: 26484 (uint32),
options:
  type=00001, len=00016: fd10::1:d (ipv6-address)
type=00025(IA_PD), len=00056: iaid=0, t1=0, t2=0,
options:
  type=00013, len=00040: NoPrefixAvail(6) "Sorry, no prefixes could be
allocated."
1 relay(s):
relay[0]: msg-type=13(RELAY_REPLY), hop-count=0,
link-address=fd10:1::, peer-address=fe80::217:3b05:5f:30, 1 option(s)
type=00018, len=00004: 00:00:00:17

--
Sent from: http://kea-users.7364.n8.nabble.com/