Hello all,
this morning one of my VMs was not reachable. Upon investigating it turns out it’s not getting a valid IPv4 lease. It’s the only VM getting DHCP from VyOS in a separate network.
vincent@lollipot-central:~$ show version
Version: VyOS 1.5-rolling-202412160007
Release train: current
Release flavor: generic
Built by: [email protected]
Built on: Mon 16 Dec 2024 00:07 UTC
Build UUID: b8cd31f7-b8e3-443a-98da-45b4cfa867c2
Build commit ID: 64737049995158
Architecture: x86_64
Boot via: installed image
System type: KVM guest
Secure Boot: n/a (BIOS)
Hardware vendor: QEMU
Hardware model: Standard PC (i440FX + PIIX, 1996)
Hardware S/N:
Hardware UUID: df3bd66b-a30a-42e2-a824-57439af15abb
Copyright: VyOS maintainers and contributors
DHCP Config:
vincent@lollipot-central# show service dhcp-server
shared-network-name lollipot {
subnet 192.168.230.0/24 {
lease 86400
option {
default-router 192.168.230.1
domain-name lollipot.club
name-server 192.168.230.1
}
range 0 {
start 192.168.230.10
stop 192.168.230.30
}
subnet-id 1
}
}
[edit]
According to VyOS the lease is still valid:
vincent@lollipot-central:~$ show dhcp server leases
IP Address MAC address State Lease start Lease expiration Remaining Pool Hostname Origin
-------------- ----------------- ------- ------------------- ------------------- ----------- -------- ----------- --------
192.168.230.10 7e:b5:5e:9f:db:b3 active 2025/01/10 22:39:42 2025/01/11 22:39:42 11:35:48 lollipot lollipot-mx local
Looking further into the logs there seems to be an error after rotating the leases CSV file. I tried renewing the leases on the VM manually:
Jan 10 21:39:01 DhcpLFC[2214550]: INFO [DhcpLFC.140423106427328] LFC_ROTATING LFC rotating files
Jan 10 21:39:01 DhcpLFC[2214550]: INFO [DhcpLFC.140423106427328] LFC_TERMINATE LFC finished processing
Jan 10 22:39:02 kea-dhcp4[3971]: 2025-01-10 22:39:02.393 INFO [kea-dhcp4.dhcpsrv/3971.140557845844480] DHCPSRV_MEMFILE_LFC_START starting Lease File Cleanup
Jan 10 22:39:02 kea-dhcp4[3971]: 2025-01-10 22:39:02.394 INFO [kea-dhcp4.dhcpsrv/3971.140557845844480] DHCPSRV_MEMFILE_LFC_EXECUTE executing Lease File Cleanup using: /usr/sbin/kea-lfc -4 -x /config/dhcp/dhcp4-leases.csv.2 -i /config/dhcp/dhcp4-leases.csv.1 -o /config/dhcp/dhcp4-leases.csv.output -f /config/dhcp/dhcp4-leases.csv.completed -p /config/dhcp/dhcp4-leases.csv.pid -c ignored-path
Jan 10 22:39:02 DhcpLFC[2225850]: INFO [DhcpLFC.139851438062016] LFC_START Starting lease file cleanup
Jan 10 22:39:02 DhcpLFC[2225850]: INFO [DhcpLFC.139851438062016] LFC_PROCESSING Previous file: /config/dhcp/dhcp4-leases.csv.2, copy file: /config/dhcp/dhcp4-leases.csv.1
Jan 10 22:39:02 DhcpLFC[2225850]: INFO [DhcpLFC.dhcpsrv.139851438062016] DHCPSRV_MEMFILE_LEASE_FILE_LOAD loading leases from file /config/dhcp/dhcp4-leases.csv.2
Jan 10 22:39:02 DhcpLFC[2225850]: INFO [DhcpLFC.dhcpsrv.139851438062016] DHCPSRV_MEMFILE_LEASE_FILE_LOAD loading leases from file /config/dhcp/dhcp4-leases.csv.1
Jan 10 22:39:02 DhcpLFC[2225850]: INFO [DhcpLFC.139851438062016] LFC_READ_STATS Leases: 1, attempts: 3, errors: 0.
Jan 10 22:39:02 DhcpLFC[2225850]: INFO [DhcpLFC.139851438062016] LFC_WRITE_STATS Leases: 1, attempts: 1, errors: 0.
Jan 10 22:39:02 DhcpLFC[2225850]: INFO [DhcpLFC.139851438062016] LFC_ROTATING LFC rotating files
Jan 10 22:39:02 DhcpLFC[2225850]: INFO [DhcpLFC.139851438062016] LFC_TERMINATE LFC finished processing
Jan 10 22:39:42 kea-dhcp4[3971]: 2025-01-10 22:39:42.591 INFO [kea-dhcp4.leases/3971.140557811898048] DHCP4_LEASE_ALLOC [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0xa07d92df: lease 192.168.230.10 has been allocated for 86400 seconds
Jan 10 23:39:03 kea-dhcp4[3971]: 2025-01-10 23:39:03.371 INFO [kea-dhcp4.dhcpsrv/3971.140557845844480] DHCPSRV_MEMFILE_LFC_START starting Lease File Cleanup
Jan 10 23:39:03 kea-dhcp4[3971]: 2025-01-10 23:39:03.373 INFO [kea-dhcp4.dhcpsrv/3971.140557845844480] DHCPSRV_MEMFILE_LFC_EXECUTE executing Lease File Cleanup using: /usr/sbin/kea-lfc -4 -x /config/dhcp/dhcp4-leases.csv.2 -i /config/dhcp/dhcp4-leases.csv.1 -o /config/dhcp/dhcp4-leases.csv.output -f /config/dhcp/dhcp4-leases.csv.completed -p /config/dhcp/dhcp4-leases.csv.pid -c ignored-path
Jan 10 23:39:03 DhcpLFC[2237161]: INFO [DhcpLFC.139818867657152] LFC_START Starting lease file cleanup
Jan 10 23:39:03 DhcpLFC[2237161]: INFO [DhcpLFC.139818867657152] LFC_PROCESSING Previous file: /config/dhcp/dhcp4-leases.csv.2, copy file: /config/dhcp/dhcp4-leases.csv.1
Jan 10 23:39:03 DhcpLFC[2237161]: INFO [DhcpLFC.dhcpsrv.139818867657152] DHCPSRV_MEMFILE_LEASE_FILE_LOAD loading leases from file /config/dhcp/dhcp4-leases.csv.2
Jan 10 23:39:03 DhcpLFC[2237161]: INFO [DhcpLFC.dhcpsrv.139818867657152] DHCPSRV_MEMFILE_LEASE_FILE_LOAD loading leases from file /config/dhcp/dhcp4-leases.csv.1
Jan 10 23:39:03 DhcpLFC[2237161]: INFO [DhcpLFC.139818867657152] LFC_READ_STATS Leases: 2, attempts: 4, errors: 0.
Jan 10 23:39:03 DhcpLFC[2237161]: INFO [DhcpLFC.139818867657152] LFC_WRITE_STATS Leases: 1, attempts: 1, errors: 0.
Jan 10 23:39:03 DhcpLFC[2237161]: INFO [DhcpLFC.139818867657152] LFC_ROTATING LFC rotating files
Jan 10 23:39:03 DhcpLFC[2237161]: INFO [DhcpLFC.139818867657152] LFC_TERMINATE LFC finished processing
Jan 11 11:11:41 kea-dhcp4[3971]: 2025-01-11 11:11:41.004 INFO [kea-dhcp4.leases/3971.140557811898048] DHCP4_LEASE_ADVERT [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0x323d20b6: lease 192.168.230.10 will be advertised
Jan 11 11:11:41 kea-dhcp4[3971]: 2025-01-11 11:11:41.006 ERROR [kea-dhcp4.alloc-engine/3971.140557811898048] ALLOC_ENGINE_V4_ALLOC_ERROR [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0x323d20b6: error during attempt to allocate an IPv4 address: failed to write CSV row '192.168.230.10,7e:b5:5e:9f:db:b3,ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50,86400,1736676701,1,0,0,lollipot-mx,0,,0' to the file '/config/dhcp/dhcp4-leases.csv'
Jan 11 11:14:01 kea-dhcp4[3971]: 2025-01-11 11:14:01.943 INFO [kea-dhcp4.leases/3971.140557811898048] DHCP4_LEASE_ADVERT [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0xadc7e931: lease 192.168.230.10 will be advertised
Jan 11 11:14:01 kea-dhcp4[3971]: 2025-01-11 11:14:01.946 ERROR [kea-dhcp4.alloc-engine/3971.140557811898048] ALLOC_ENGINE_V4_ALLOC_ERROR [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0xadc7e931: error during attempt to allocate an IPv4 address: failed to write CSV row '192.168.230.10,7e:b5:5e:9f:db:b3,ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50,86400,1736676841,1,0,0,lollipot-mx,0,,0' to the file '/config/dhcp/dhcp4-leases.csv'
Jan 11 11:14:01 kea-dhcp4[3971]: 2025-01-11 11:14:01.950 INFO [kea-dhcp4.leases/3971.140557811898048] DHCP4_LEASE_ADVERT [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0xc84e1588: lease 192.168.230.10 will be advertised
Jan 11 11:14:01 kea-dhcp4[3971]: 2025-01-11 11:14:01.967 INFO [kea-dhcp4.leases/3971.140557811898048] DHCP4_LEASE_ADVERT [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0x1b9afb31: lease 192.168.230.10 will be advertised
Jan 11 11:14:01 kea-dhcp4[3971]: 2025-01-11 11:14:01.969 ERROR [kea-dhcp4.alloc-engine/3971.140557811898048] ALLOC_ENGINE_V4_ALLOC_ERROR [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0x1b9afb31: error during attempt to allocate an IPv4 address: failed to write CSV row '192.168.230.10,7e:b5:5e:9f:db:b3,ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50,86400,1736676841,1,0,0,lollipot-mx,0,,0' to the file '/config/dhcp/dhcp4-leases.csv'
Jan 11 11:14:01 kea-dhcp4[3971]: 2025-01-11 11:14:01.974 INFO [kea-dhcp4.leases/3971.140557811898048] DHCP4_LEASE_ADVERT [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0x4096be1: lease 192.168.230.10 will be advertised
Jan 11 11:14:01 kea-dhcp4[3971]: 2025-01-11 11:14:01.977 ERROR [kea-dhcp4.alloc-engine/3971.140557811898048] ALLOC_ENGINE_V4_ALLOC_ERROR [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0x4096be1: error during attempt to allocate an IPv4 address: failed to write CSV row '192.168.230.10,7e:b5:5e:9f:db:b3,ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50,86400,1736676841,1,0,0,lollipot-mx,0,,0' to the file '/config/dhcp/dhcp4-leases.csv'
Jan 11 11:14:03 kea-dhcp4[3971]: 2025-01-11 11:14:03.011 INFO [kea-dhcp4.leases/3971.140557811898048] DHCP4_LEASE_ADVERT [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0x61807a67: lease 192.168.230.10 will be advertised
Jan 11 11:14:03 kea-dhcp4[3971]: 2025-01-11 11:14:03.013 ERROR [kea-dhcp4.alloc-engine/3971.140557811898048] ALLOC_ENGINE_V4_ALLOC_ERROR [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0x61807a67: error during attempt to allocate an IPv4 address: failed to write CSV row '192.168.230.10,7e:b5:5e:9f:db:b3,ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50,86400,1736676843,1,0,0,lollipot-mx,0,,0' to the file '/config/dhcp/dhcp4-leases.csv'
Jan 11 11:14:05 kea-dhcp4[3971]: 2025-01-11 11:14:05.261 INFO [kea-dhcp4.leases/3971.140557811898048] DHCP4_LEASE_ADVERT [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0xe6715133: lease 192.168.230.10 will be advertised
Jan 11 11:14:05 kea-dhcp4[3971]: 2025-01-11 11:14:05.262 ERROR [kea-dhcp4.alloc-engine/3971.140557811898048] ALLOC_ENGINE_V4_ALLOC_ERROR [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0xe6715133: error during attempt to allocate an IPv4 address: failed to write CSV row '192.168.230.10,7e:b5:5e:9f:db:b3,ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50,86400,1736676845,1,0,0,lollipot-mx,0,,0' to the file '/config/dhcp/dhcp4-leases.csv'
Jan 11 11:14:09 kea-dhcp4[3971]: 2025-01-11 11:14:09.511 INFO [kea-dhcp4.leases/3971.140557811898048] DHCP4_LEASE_ADVERT [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0x887213c6: lease 192.168.230.10 will be advertised
Jan 11 11:14:09 kea-dhcp4[3971]: 2025-01-11 11:14:09.516 ERROR [kea-dhcp4.alloc-engine/3971.140557811898048] ALLOC_ENGINE_V4_ALLOC_ERROR [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0x887213c6: error during attempt to allocate an IPv4 address: failed to write CSV row '192.168.230.10,7e:b5:5e:9f:db:b3,ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50,86400,1736676849,1,0,0,lollipot-mx,0,,0' to the file '/config/dhcp/dhcp4-leases.csv'
Jan 11 11:14:17 kea-dhcp4[3971]: 2025-01-11 11:14:17.762 INFO [kea-dhcp4.leases/3971.140557811898048] DHCP4_LEASE_ADVERT [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0xf4266f6b: lease 192.168.230.10 will be advertised
Jan 11 11:14:17 kea-dhcp4[3971]: 2025-01-11 11:14:17.762 ERROR [kea-dhcp4.alloc-engine/3971.140557811898048] ALLOC_ENGINE_V4_ALLOC_ERROR [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0xf4266f6b: error during attempt to allocate an IPv4 address: failed to write CSV row '192.168.230.10,7e:b5:5e:9f:db:b3,ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50,86400,1736676857,1,0,0,lollipot-mx,0,,0' to the file '/config/dhcp/dhcp4-leases.csv'
Jan 11 11:14:34 kea-dhcp4[3971]: 2025-01-11 11:14:34.012 INFO [kea-dhcp4.leases/3971.140557811898048] DHCP4_LEASE_ADVERT [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0x2ca85c6e: lease 192.168.230.10 will be advertised
Jan 11 11:14:34 kea-dhcp4[3971]: 2025-01-11 11:14:34.014 ERROR [kea-dhcp4.alloc-engine/3971.140557811898048] ALLOC_ENGINE_V4_ALLOC_ERROR [hwtype=1 7e:b5:5e:9f:db:b3], cid=[ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50], tid=0x2ca85c6e: error during attempt to allocate an IPv4 address: failed to write CSV row '192.168.230.10,7e:b5:5e:9f:db:b3,ff:9e:37:69:8c:00:02:00:00:ab:11:2a:b6:2c:4d:30:0d:1b:50,86400,1736676874,1,0,0,lollipot-mx,0,,0' to the file '/config/dhcp/dhcp4-leases.csv'
Permission of the folder (did not touch anything):
vincent@lollipot-central:~$ ls -lisa /config/dhcp/
total 16
1782 4 drwxrwxr-x 2 root vyattacfg 4096 Jan 11 08:39 .
637 4 drwxrwsr-x 1 root vyattacfg 4096 Dec 18 11:31 ..
133692 0 -rw-r--r-- 1 _kea _kea 0 Jan 11 11:18 dhcp4-leases.csv
134047 4 -rw-r--r-- 1 _kea _kea 111 Jan 11 07:39 dhcp4-leases.csv.1
134058 4 -rw-r--r-- 1 _kea _kea 241 Jan 11 07:39 dhcp4-leases.csv.2
134036 0 -rw-r--r-- 1 _kea _kea 0 Jan 11 08:39 dhcp4-leases.csv.pid
dhcp4-leases.csv is completely empty, while dhcp4-leases.csv.2 still has the CSV header, but no content.
My next step would be to reboot the VyOS system, but I’ve given the VM a static IP instead, in case you want me to run some commands on it.