I have a machine running VyOS (1.5-rolling-202407270020) for a small home network. It’s also the DHCP server for the local network.
For some reason, it’s been having weird DHCP lease issues for a while after rebooting. At first I thought these were intermittent and random - but it seems it might be some race condition?
System version:
vyos@vyos:~$ show system image
Name Default boot Running
------------------------ -------------- ---------
1.5-rolling-202407270020 Yes Yes
1.5-rolling-202309170024
These are the network interfaces on the VyOS router:
vyos@vyos:~$ show interfaces
Codes: S - State, L - Link, u - Up, D - Down, A - Admin Down
Interface IP Address MAC VRF MTU S/L Description
----------- ----------------- ----------------- ------- ----- ----- ------------------
eth0 - 80:a2:35:7f:df:67 default 1500 u/u
eth0.2 - 80:a2:35:7f:df:67 default 1500 u/u Internode WAN
eth1 - 80:a2:35:7f:df:6f default 1500 u/D
eth2 - 80:a2:35:7f:df:70 default 1500 u/D
eth3 - 80:a2:35:7f:df:71 default 1500 u/D
eth4 - 80:a2:35:7f:df:72 default 1500 u/D
eth5 10.19.1.1/24 80:a2:35:7f:df:68 default 1500 u/D LAN
eth6 10.19.10.1/24 80:a2:35:7f:df:69 default 1500 u/D Management_Network
eth7 - 80:a2:35:7f:df:6a default 1500 u/D
eth8 - 80:a2:35:7f:df:6b default 1500 u/D
eth9 - 80:a2:35:7f:df:6c default 1500 u/D
eth10 - 80:a2:35:7f:df:6d default 1500 u/D
eth11 - 80:a2:35:7f:df:6e default 1500 u/D
lo 127.0.0.1/8 00:00:00:00:00:00 default 65536 u/u
::1/128
pppoe0 220.253.243.14/32 n/a default 1492 u/u
Looking at the DHCP server logs (show log dhcp server - output below) - it almost seems like there might be some race condition on startup - where eth5 is not ready yet - kea-dhcp tries to startup on that interface, then fails, and doesn’t bother retrying?
If I manually restart the VyOS DHCP - it suddenly starts issuing DHCP leases again.
Has anybody seen this sort of issue before?
Oct 01 11:27:38 kea-dhcp4[4308]: 2024-10-01 11:27:38.969 WARN [kea-dhcp4.dhcpsrv/4308.140704356454912] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: the interface pim6reg has no usable IPv4 addresses configured
Oct 01 11:27:38 kea-dhcp4[4308]: 2024-10-01 11:27:38.969 WARN [kea-dhcp4.dhcpsrv/4308.140704356454912] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: the interface eth0.2 has no usable IPv4 addresses configured
4308.140704356454912] DHCP4_OPEN_SOCKETS_FAILED maximum number of open service sockets attempts: 5, has been exhausted without success
Oct 01 11:27:55 kea-dhcp4[4308]: 2024-10-01 11:27:55.811 INFO [kea-dhcp4.commands/4308.140704356454912] COMMAND_RECEIVED Received command 'lease4-get-all'
Oct 01 11:27:55 kea-dhcp4[4308]: 2024-10-01 11:27:55.812 INFO [kea-dhcp4.commands/4308.140704356454912] COMMAND_RECEIVED Received command 'config-get'
Oct 01 11:29:02 kea-dhcp4[4308]: 2024-10-01 11:29:02.883 INFO [kea-dhcp4.commands/4308.140704356454912] COMMAND_RECEIVED Received command 'lease4-get-all'
Oct 01 11:29:02 kea-dhcp4[4308]: 2024-10-01 11:29:02.883 INFO [kea-dhcp4.commands/4308.140704356454912] COMMAND_RECEIVED Received command 'config-get'
Oct 01 11:30:25 kea-dhcp4[4308]: 2024-10-01 11:30:25.313 INFO [kea-dhcp4.commands/4308.140704356454912] COMMAND_RECEIVED Received command 'lease4-get-all'
Oct 01 11:30:25 kea-dhcp4[4308]: 2024-10-01 11:30:25.314 INFO [kea-dhcp4.commands/4308.140704356454912] COMMAND_RECEIVED Received command 'config-get'
Oct 01 11:30:59 systemd[1]: Stopping kea-dhcp4-server.service - Kea IPv4 DHCP daemon...
Oct 01 11:30:59 kea-dhcp4[4308]: 2024-10-01 11:30:59.834 INFO [kea-dhcp4.dhcp4/4308.140704356454912] DHCP4_SHUTDOWN server shutdown
Oct 01 11:30:59 kea-dhcp4[4308]: 2024-10-01 11:30:59.834 INFO [kea-dhcp4.lease-cmds-hooks/4308.140704356454912] LEASE_CMDS_DEINIT_OK unloading Lease Commands hooks library successful
nu/kea/hooks/libdhcp_lease_cmds.so successfully closed
Oct 01 11:30:59 systemd[1]: kea-dhcp4-server.service: Deactivated successfully.
Oct 01 11:30:59 systemd[1]: Stopped kea-dhcp4-server.service - Kea IPv4 DHCP daemon.
Oct 01 11:30:59 systemd[1]: Started kea-dhcp4-server.service - Kea IPv4 DHCP daemon.
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.893 INFO [kea-dhcp4.dhcp4/6938.139757984457216] DHCP4_STARTING Kea DHCPv4 server version 2.4.1 (stable) starting
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.895 INFO [kea-dhcp4.hosts/6938.139757984457216] HOSTS_BACKENDS_REGISTERED the following host backend types are available: mysql postgresql
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.895 WARN [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_MT_DISABLED_QUEUE_CONTROL disabling dhcp queue control when multi-threading is enabled.
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.896 WARN [kea-dhcp4.dhcp4/6938.139757984457216] DHCP4_RESERVATIONS_LOOKUP_FIRST_ENABLED Multi-threading is enabled and host reservations lookup is always performed first.
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.897 INFO [kea-dhcp4.hooks/6938.139757984457216] HOOKS_LIBRARY_CLOSED hooks library /usr/lib/x86_64-linux-gnu/kea/hooks/libdhcp_lease_cmds.so successfully closed
o configuration: 10.19.1.0/24 with params: valid-lifetime=86400
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.898 INFO [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_CFGMGR_NEW_SUBNET4 a new subnet has been added to configuration: 10.19.10.0/24 with params: valid-lifetime=86400
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.898 INFO [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_CFGMGR_SOCKET_TYPE_SELECT using socket type raw
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.899 INFO [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_CFGMGR_SOCKET_TYPE_SELECT using socket type raw
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.899 INFO [kea-dhcp4.commands/6938.139757984457216] COMMAND_ACCEPTOR_START Starting to accept connections via unix domain socket bound to /run/kea/dhcp4-ctrl-socket
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.901 INFO [kea-dhcp4.lease-cmds-hooks/6938.139757984457216] LEASE_CMDS_INIT_OK loading Lease Commands hooks library successful
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.901 INFO [kea-dhcp4.hooks/6938.139757984457216] HOOKS_LIBRARY_LOADED hooks library /usr/lib/x86_64-linux-gnu/kea/hooks/libdhcp_lease_cmds.so successfully loaded
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.901 INFO [kea-dhcp4.dhcp4/6938.139757984457216] DHCP4_CONFIG_COMPLETE DHCPv4 server has completed configuration: added IPv4 subnets: 2; DDNS: disabled
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.904 INFO [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_MEMFILE_DB opening memory file lease database: name=/config/dhcp/dhcp4-leases.csv persist=true type=memfile universe=4
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.904 INFO [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_MEMFILE_LEASE_FILE_LOAD loading leases from file /config/dhcp/dhcp4-leases.csv.2
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.904 INFO [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_MEMFILE_LEASE_FILE_LOAD loading leases from file /config/dhcp/dhcp4-leases.csv
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.905 INFO [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_MEMFILE_EXTRACT_EXTENDED_INFO4 extracting extended info saw 0 leases, extended info sanity checks modified 0 / updated 0 leases and 0 leases have relay or remote id
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.905 INFO [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_MEMFILE_LFC_SETUP setting up the Lease File Cleanup interval to 3600 sec
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.905 WARN [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: the interface eth0 has no usable IPv4 addresses configured
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.914 WARN [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: the interface eth6 is not running
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.914 WARN [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: the interface eth7 is not running
v/6938.139757984457216] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: the interface eth8 is not running
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.914 WARN [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: the interface eth9 is not running
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.914 WARN [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: the interface eth10 is not running
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.914 WARN [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: the interface eth11 is not running
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.914 WARN [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: the interface eth1 is not running
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.915 WARN [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: the interface eth2 is not running
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.915 WARN [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: the interface eth3 is not running
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.915 WARN [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: the interface eth4 is not running
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.915 WARN [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: the interface pim6reg has no usable IPv4 addresses configured
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.915 WARN [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: the interface eth0.2 has no usable IPv4 addresses configured
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.915 WARN [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: Failed to open socket on interface pppoe0, reason: failed to bind fallback socket to address 10.20.20.223, port 67, reason: Cannot assign requested address - is another DHCP server running?
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.915 INFO [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_CFGMGR_USE_ALLOCATOR using the iterative allocator for V4 leases in subnet 10.19.1.0/24
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.915 INFO [kea-dhcp4.dhcpsrv/6938.139757984457216] DHCPSRV_CFGMGR_USE_ALLOCATOR using the iterative allocator for V4 leases in subnet 10.19.10.0/24
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.916 WARN [kea-dhcp4.dhcp4/6938.139757984457216] DHCP4_MULTI_THREADING_INFO enabled: yes, number of threads: 8, queue size: 64
Oct 01 11:30:59 kea-dhcp4[6938]: 2024-10-01 11:30:59.916 INFO [kea-dhcp4.dhcp4/6938.139757984457216] DHCP4_STARTED Kea DHCPv4 server version 2.4.1 started
/6938.139757950510784] DHCP4_LEASE_ADVERT [hwtype=1 80:8d:b7:ce:a4:74], cid=[01:80:8d:b7:ce:a4:74], tid=0xcbc9cb73: lease 10.19.1.50 will be advertised
Oct 01 11:31:01 kea-dhcp4[6938]: 2024-10-01 11:31:01.127 INFO [kea-dhcp4.leases/6938.139757942118080] DHCP4_LEASE_ALLOC [hwtype=1 80:8d:b7:ce:a4:74], cid=[01:80:8d:b7:ce:a4:74], tid=0xcbc9cb73: lease 10.19.1.50 has been allocated for 86400 seconds
Oct 01 11:31:02 kea-dhcp4[6938]: 2024-10-01 11:31:02.141 INFO [kea-dhcp4.leases/6938.139757933725376] DHCP4_LEASE_ADVERT [hwtype=1 00:13:c6:08:98:2b], cid=[01:00:13:c6:08:98:2b], tid=0x7e120453: lease 10.19.1.51 will be advertised
Oct 01 11:31:02 kea-dhcp4[6938]: 2024-10-01 11:31:02.161 INFO [kea-dhcp4.leases/6938.139757925332672] DHCP4_LEASE_ALLOC [hwtype=1 00:13:c6:08:98:2b], cid=[01:00:13:c6:08:98:2b], tid=0x7e120453: lease 10.19.1.51 has been allocated for 86400 seconds
Oct 01 11:31:03 kea-dhcp4[6938]: 2024-10-01 11:31:03.608 INFO [kea-dhcp4.leases/6938.139757916939968] DHCP4_LEASE_ADVERT [hwtype=1 80:8d:b7:ce:b4:b0], cid=[01:80:8d:b7:ce:b4:b0], tid=0x222c439: lease 10.19.1.52 will be advertised
Oct 01 11:31:03 kea-dhcp4[6938]: 2024-10-01 11:31:03.624 INFO [kea-dhcp4.leases/6938.139757908547264] DHCP4_LEASE_ALLOC [hwtype=1 80:8d:b7:ce:b4:b0], cid=[01:80:8d:b7:ce:b4:b0], tid=0x222c439: lease 10.19.1.52 has been allocated for 86400 seconds