[Kea-users] IPV6 client gets the wrong IP for sometime after a reboot

Tue Jan 17 09:54:46 UTC 2023

Hi,

I have observed that an IPV6 client gets the wrong IP when it reboots.
See detailed logs below.
The problem seems to be due to the fact the DUID of the client changes after reboot.
Anyone else has observed the same ?
How to go around that and make sure that the client gets the correct IP straightaway after reboot ?
Thanks,
Veronique

# Initial boot: client (with hw mac address "CLIENT_MAC_ADDRESS") gets the expected reserved IP "good_static_ip" using duid "first_duid" :

2023-01-16 17:01:53.859 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_SELECTED duid=[first_duid], tid=0x3c6a47: the subnet with ID 2156730624 was selected for client assignments
2023-01-16 17:01:53.860 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_ALLOC_NO_LEASES_HR no leases found but reservations exist for client duid=[first_duid], tid=0x3c6a47
2023-01-16 17:01:53.860 INFO  [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_HR_ADDR_GRANTED reserved address good_static_ip was assigned to client duid=[first_duid], tid=0x3c6a47
2023-01-16 17:01:53.860 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_DYNAMICALLY_CHANGED duid=[first_duid], tid=0x3c6a47: changed selected subnet dynamic_pool/64 to subnet good_subnet/64 from shared network Shared-S1000-S-PR90 for client assignments
2023-01-16 17:01:54.721 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_SELECTED duid=[first_duid], tid=0xb60809: the subnet with ID 2156730624 was selected for client assignments
2023-01-16 17:01:54.722 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_ALLOC_NO_LEASES_HR no leases found but reservations exist for client duid=[first_duid], tid=0xb60809
2023-01-16 17:01:54.722 INFO  [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_HR_ADDR_GRANTED reserved address good_static_ip was assigned to client duid=[first_duid], tid=0xb60809
2023-01-16 17:01:54.722 INFO  [kea-dhcp6.leases/21898.139652277565632] DHCP6_LEASE_ALLOC duid=[first_duid], tid=0xb60809: lease for address good_static_ip and iaid=795307976 has been allocated for 3606 seconds

2023-01-16 17:01:54.723 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_DYNAMICALLY_CHANGED duid=[first_duid], tid=0xb60809: changed selected subnet dynamic_pool/64 to subnet good_subnet/64 from shared network Shared-S1000-S-PR90 for client assignments
2023-01-16 17:02:15.585 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_SELECTED duid=[first_duid], tid=0x992ae0: the subnet with ID 2156730624 was selected for client assignments
2023-01-16 17:02:16.874 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_SELECTED duid=[first_duid], tid=0x2f49fd: the subnet with ID 2156730624 was selected for client assignments
2023-01-16 17:02:16.875 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_ALLOC_LEASES_HR leases and static reservations found for client duid=[first_duid], tid=0x2f49fd
2023-01-16 17:02:16.875 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_ALLOC_HR_LEASE_EXISTS duid=[first_duid], tid=0x2f49fd: lease type IA_NA for reserved address/prefix good_static_ip already exists
2023-01-16 17:02:17.871 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_SELECTED duid=[first_duid], tid=0x5abee0: the subnet with ID 2156730624 was selected for client assignments
2023-01-16 17:02:17.872 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_ALLOC_LEASES_HR leases and static reservations found for client duid=[first_duid], tid=0x5abee0
2023-01-16 17:02:17.872 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_ALLOC_HR_LEASE_EXISTS duid=[first_duid], tid=0x5abee0: lease type IA_NA for reserved address/prefix good_static_ip already exists
2023-01-16 17:02:17.873 INFO  [kea-dhcp6.leases/21898.139652277565632] DHCP6_LEASE_ALLOC duid=[first_duid], tid=0x5abee0: lease for address good_static_ip and iaid=795307976 has been allocated for 3606 seconds

# IP renew works fine: (note: that lease will get released later at 18:22:17.301 )

2023-01-16 17:32:21.452 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_SELECTED duid=[first_duid], tid=0x7c37af: the subnet with ID 2156730624 was selected for client assignments
2023-01-16 17:32:21.453 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_RENEW_REMOVE_RESERVED duid=[first_duid], tid=0x7c37af: checking if existing client's leases are reserved for another client
2023-01-16 17:32:21.453 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_RENEW_HR allocating leases reserved for the client duid=[first_duid], tid=0x7c37af as a result of Renew
2023-01-16 17:32:21.453 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_ALLOC_HR_LEASE_EXISTS duid=[first_duid], tid=0x7c37af: lease type IA_NA for reserved address/prefix good_static_ip already exists
2023-01-16 17:32:21.453 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_EXTEND_LEASE duid=[first_duid], tid=0x7c37af: extending lifetime of the lease type IA_NA, address good_static_ip
2023-01-16 17:32:21.453 INFO  [kea-dhcp6.leases/21898.139652277565632] DHCP6_LEASE_RENEW duid=[first_duid], tid=0x7c37af: lease for address good_static_ip and iaid=795307976 has been allocated
2023-01-16 17:32:21.453 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_DYNAMICALLY_CHANGED duid=[first_duid], tid=0x7c37af: changed selected subnet dynamic_pool/64 to subnet good_subnet/64 from shared network Shared-S1000-S-PR90 for client assignments

# Then the client reboots and comes back with a new duid "second_duid" :

2023-01-16 17:52:09.455 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_SELECTED duid=[second_duid], tid=0xedb614: the subnet with ID 2156730624 was selected for client assignments

# the host-reservation is found:

2023-01-16 17:52:09.477 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_ALLOC_NO_LEASES_HR no leases found but reservations exist for client duid=[second_duid], tid=0xedb614

# but KEA says it that the lease is not available: why ?

2023-01-16 17:52:09.478 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_ALLOC_UNRESERVED no static reservations available - trying to dynamically allocate leases for client duid=[second_duid], tid=0xedb614
2023-01-16 17:52:10.290 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_SELECTED duid=[second_duid], tid=0xedb614: the subnet with ID 2156730624 was selected for client assignments
2023-01-16 17:52:10.291 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_ALLOC_NO_LEASES_HR no leases found but reservations exist for client duid=[second_duid], tid=0xedb614
2023-01-16 17:52:10.291 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_ALLOC_UNRESERVED no static reservations available - trying to dynamically allocate leases for client duid=[second_duid], tid=0xedb614
2023-01-16 17:52:12.252 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_SELECTED duid=[second_duid], tid=0xedb614: the subnet with ID 2156730624 was selected for client assignments
2023-01-16 17:52:12.253 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_ALLOC_NO_LEASES_HR no leases found but reservations exist for client duid=[second_duid], tid=0xedb614
2023-01-16 17:52:12.253 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_ALLOC_UNRESERVED no static reservations available - trying to dynamically allocate leases for client duid=[second_duid], tid=0xedb614
2023-01-16 17:52:13.080 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_SELECTED duid=[second_duid], tid=0x648b27: the subnet with ID 2156730624 was selected for client assignments
2023-01-16 17:52:13.081 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_ALLOC_NO_LEASES_HR no leases found but reservations exist for client duid=[second_duid], tid=0x648b27

# then it allocates a dynamic IP to the client:

2023-01-16 17:52:13.081 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_ALLOC_UNRESERVED no static reservations available - trying to dynamically allocate leases for client duid=[second_duid], tid=0x648b27
2023-01-16 17:52:13.082 INFO  [kea-dhcp6.leases/21898.139652277565632] DHCP6_LEASE_ALLOC duid=[second_duid], tid=0x648b27: lease for address bad_dynamic_ip and iaid=795307976 has been allocated for 3606 seconds

# KEA renews the dynamic IP:

2023-01-16 18:22:17.301 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_SELECTED duid=[second_duid], tid=0x2c3a45: the subnet with ID 2156730624 was selected for client assignments
2023-01-16 18:22:17.306 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_RENEW_REMOVE_RESERVED duid=[second_duid], tid=0x2c3a45: checking if existing client's leases are reserved for another client
2023-01-16 18:22:17.306 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_RENEW_HR allocating leases reserved for the client duid=[second_duid], tid=0x2c3a45 as a result of Renew
2023-01-16 18:22:17.306 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_EXTEND_LEASE duid=[second_duid], tid=0x2c3a45: extending lifetime of the lease type IA_NA, address bad_dynamic_ip
2023-01-16 18:22:17.306 INFO  [kea-dhcp6.leases/21898.139652277565632] DHCP6_LEASE_RENEW duid=[second_duid], tid=0x2c3a45: lease for address bad_dynamic_ip and iaid=795307976 has been allocated

# Here the good IP lease expires and is released:

2023-01-16 18:32:36.837 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_LEASE_RECLAIM duid=[first_duid], [hwtype=1 CLIENT_MAC_ADDRESS]: reclaiming expired lease for prefix good_static_ip/128

# bad lease gets renewed:

2023-01-16 18:52:20.926 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_SELECTED duid=[second_duid], tid=0x36841c: the subnet with ID 2156730624 was selected for client assignments
2023-01-16 18:52:20.927 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_RENEW_REMOVE_RESERVED duid=[second_duid], tid=0x36841c: checking if existing client's leases are reserved for another client
2023-01-16 18:52:20.928 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_RENEW_HR allocating leases reserved for the client duid=[second_duid], tid=0x36841c as a result of Renew
2023-01-16 18:52:20.928 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_EXTEND_LEASE duid=[second_duid], tid=0x36841c: extending lifetime of the lease type IA_NA, address bad_dynamic_ip
2023-01-16 18:52:20.928 INFO  [kea-dhcp6.leases/21898.139652277565632] DHCP6_LEASE_RENEW duid=[second_duid], tid=0x36841c: lease for address bad_dynamic_ip and iaid=795307976 has been allocated

# bad lease gets renewed once more:

2023-01-16 19:22:24.560 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_SELECTED duid=[second_duid], tid=0x6b5563: the subnet with ID 2156730624 was selected for client assignments
2023-01-16 19:22:24.562 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_RENEW_REMOVE_RESERVED duid=[second_duid], tid=0x6b5563: checking if existing client's leases are reserved for another client
2023-01-16 19:22:24.562 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_RENEW_HR allocating leases reserved for the client duid=[second_duid], tid=0x6b5563 as a result of Renew
2023-01-16 19:22:24.563 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_EXTEND_LEASE duid=[second_duid], tid=0x6b5563: extending lifetime of the lease type IA_NA, address bad_dynamic_ip
2023-01-16 19:22:24.563 INFO  [kea-dhcp6.leases/21898.139652277565632] DHCP6_LEASE_RENEW duid=[second_duid], tid=0x6b5563: lease for address bad_dynamic_ip and iaid=795307976 has been allocated

# Now finally the good IP is allocated again to the client:

2023-01-16 19:52:28.104 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_SELECTED duid=[second_duid], tid=0x83f3a8: the subnet with ID 2156730624 was selected for client assignments
2023-01-16 19:52:28.105 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_RENEW_REMOVE_RESERVED duid=[second_duid], tid=0x83f3a8: checking if existing client's leases are reserved for another client
2023-01-16 19:52:28.105 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_RENEW_HR allocating leases reserved for the client duid=[second_duid], tid=0x83f3a8 as a result of Renew
2023-01-16 19:52:28.105 INFO  [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_HR_ADDR_GRANTED reserved address good_static_ip was assigned to client duid=[second_duid], tid=0x83f3a8
2023-01-16 19:52:28.106 INFO  [kea-dhcp6.leases/21898.139652277565632] DHCP6_LEASE_RENEW duid=[second_duid], tid=0x83f3a8: lease for address good_static_ip and iaid=795307976 has been allocated
2023-01-16 19:52:28.106 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_DYNAMICALLY_CHANGED duid=[second_duid], tid=0x83f3a8: changed selected subnet dynamic_pool/64 to subnet good_subnet/64 from shared network Shared-S1000-S-PR90 for client assignments

2023-01-16 20:22:31.830 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_SELECTED duid=[second_duid], tid=0xdd8bf0: the subnet with ID 2156730624 was selected for client assignments
2023-01-16 20:22:31.831 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_RENEW_REMOVE_RESERVED duid=[second_duid], tid=0xdd8bf0: checking if existing client's leases are reserved for another client
2023-01-16 20:22:31.831 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_RENEW_HR allocating leases reserved for the client duid=[second_duid], tid=0xdd8bf0 as a result of Renew
2023-01-16 20:22:31.831 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_ALLOC_HR_LEASE_EXISTS duid=[second_duid], tid=0xdd8bf0: lease type IA_NA for reserved address/prefix good_static_ip already exists
2023-01-16 20:22:31.831 DEBUG [kea-dhcp6.alloc-engine/21898.139652277565632] ALLOC_ENGINE_V6_EXTEND_LEASE duid=[second_duid], tid=0xdd8bf0: extending lifetime of the lease type IA_NA, address good_static_ip
2023-01-16 20:22:31.831 INFO  [kea-dhcp6.leases/21898.139652277565632] DHCP6_LEASE_RENEW duid=[second_duid], tid=0xdd8bf0: lease for address good_static_ip and iaid=795307976 has been allocated
2023-01-16 20:22:31.831 DEBUG [kea-dhcp6.packets/21898.139652277565632] DHCP6_SUBNET_DYNAMICALLY_CHANGED duid=[second_duid], tid=0xdd8bf0: changed selected subnet dynamic_pool/64 to subnet good_subnet/64 from shared network Shared-S1000-S-PR90 for client assignments

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.isc.org/pipermail/kea-users/attachments/20230117/7a06af06/attachment-0001.htm>