Actions
Bug #14977
open
Kea fails to restart due to race between process termination and startup
Added by Jim Pingle about 1 year ago. Updated 22 days ago.
Start date:
Due date:
% Done:
100%
Estimated time:
Plus Target Version:
24.11
Release Notes:
Default
Affected Version:
Affected Architecture:
Description
If for some reason the Kea control socket lock file is present while Kea is stopped, then Kea can never start until that file is removed.
Attempting to start Kea while /tmp/kea4-ctrl-socket.lock exists, even if Kea is not currently running, results in a fatal error preventing Kea from running:
Nov 13 13:07:53 kea-dhcp4 32826 ERROR [kea-dhcp4.dhcp4.0x1c655d812000] DHCP4_INIT_FAIL failed to initialize Kea server: configuration error using file '/usr/local/etc/kea/kea-dhcp4.conf': cannot lock socket lockfile, /tmp/kea4-ctrl-socket.lock, : Resource temporarily unavailable
Removing the socket file allows Kea to start (rm /tmp/kea4-ctrl-socket.lock).
Forum thread: https://forum.netgate.com/post/1135910
Related issues
Updated by Suriname Clubcard 8 months ago
I just experienced exactly this same problem:
DHCP4_CONFIG_LOAD_FAIL configuration error using file: /usr/local/etc/kea/kea-dhcp4.conf, reason: cannot lock socket lockfile, /tmp/kea4-ctrl-socket.lock, : Resource temporarily unavailable
pfSense 2.7.2.
Updated by Jim Pingle 8 months ago
- Status changed from New to Closed
- % Done changed from 0 to 100
I can't reproduce this at all on current snapshots. I've killed the process and left the old file in place, killed it and made a file owned by another user, killed it and made a file with invalid permissions, and so on. Every time it starts right back up perfectly. I've tried restarting the process by save/apply, by using the service controls, and so on. I even killed it, left the lock in place, and rebooted. Every time it starts right up.
It's possible they fixed it upstream or something else changed that made it a non-issue.
Updated by Nicholas Ruddick 7 months ago
This issue was occurring for me too, and I have found a resolution. It manifests itself as a "ghost" kea process which is not logging, or visible to keactrl.
Log entries:
| May 2 18:32:00 | kea-dhcp4 | 46377 | ERROR [kea-dhcp4.dhcp4.0xbb13ee12000] DHCP4_INIT_FAIL failed to initialize Kea server: configuration error using file '/usr/local/etc/kea/kea-dhcp4.conf': cannot lock socket lockfile, /tmp/kea4-ctrl-socket.lock, : Resource temporarily unavailable |
| May 2 18:32:00 | kea-dhcp4 | 46377 | ERROR [kea-dhcp4.dhcp4.0xbb13ee12000] DHCP4_CONFIG_LOAD_FAIL configuration error using file: /usr/local/etc/kea/kea-dhcp4.conf, reason: cannot lock socket lockfile, /tmp/kea4-ctrl-socket.lock, : Resource temporarily unavailable |
| May 2 18:32:00 | kea-dhcp4 | 46377 | ERROR [kea-dhcp4.dhcp4.0xbb13ee12000] DHCP4_PARSER_COMMIT_FAIL parser failed to commit changes: cannot lock socket lockfile, /tmp/kea4-ctrl-socket.lock, : Resource temporarily unavailable |
Ghost process not recognised by keactrl:
[2.7.2-RELEASE][root@firewall]/root: ps aux | grep kea
root 68622 0.0 0.5 52584 20556 - S 06:51 0:03.26 /usr/local/sbin/kea-dhcp4 -c /usr/local/etc/kea/kea-dhcp4.conf
root 82813 0.0 0.1 12752 2164 0 S+ 18:36 0:00.00 grep kea
[2.7.2-RELEASE][root@firewall]/tmp: ls -l /tmp/ | grep kea
srwxr-xr-x 1 root wheel 0 May 2 06:51 kea4-ctrl-socket
-rw------- 1 root wheel 0 May 2 06:51 kea4-ctrl-socket.lock
[2.7.2-RELEASE][root@firewall]/tmp: keactrl version
keactrl: 2.4.0
kea-dhcp4: 2.4.0
kea-dhcp6: 2.4.0
kea-dhcp-ddns: 2.4.0
kea-ctrl-agent: 2.4.0
[2.7.2-RELEASE][root@firewall]/root: keactrl status
DHCPv4 server: inactive
DHCPv6 server: inactive
DHCP DDNS: inactive
Control Agent: inactive
Kea DHCPv4 configuration file: /usr/local/etc/kea/kea-dhcp4.conf
Kea DHCPv6 configuration file: /usr/local/etc/kea/kea-dhcp6.conf
Kea DHCP DDNS configuration file: /usr/local/etc/kea/kea-dhcp-ddns.conf
Kea Control Agent configuration file: /usr/local/etc/kea/kea-ctrl-agent.conf
keactrl configuration file: /usr/local/etc/kea/keactrl.conf
Restarting from command line fails:
[2.7.2-RELEASE][root@firewall]/tmp: /usr/local/sbin/kea-dhcp4 -c /usr/local/etc/kea/kea-dhcp4.conf
2024-05-02 18:41:54.873 INFO [kea-dhcp4.dhcp4/5978.0x6e5c6812000] DHCP4_STARTING Kea DHCPv4 server version 2.4.0 (stable) starting
2024-05-02 18:41:54.877 ERROR [kea-dhcp4.dhcp4/5978.0x6e5c6812000] DHCP4_INIT_FAIL failed to initialize Kea server: configuration error using file '/usr/local/etc/kea/kea-dhcp4.conf'
: cannot lock socket lockfile, /tmp/kea4-ctrl-socket.lock, : Resource temporarily unavailable
keactrl stop does not work:
[2.7.2-RELEASE][root@firewall]/tmp: keactrl stop
INFO/keactrl: kea-dhcp4 isn't running.
INFO/keactrl: kea-dhcp6 isn't running.
INFO/keactrl: kea-dhcp-ddns isn't running.
INFO/keactrl: kea-ctrl-agent isn't running.
[2.7.2-RELEASE][root@firewall]/tmp: ps aux | grep kea
root 68622 0.0 0.5 52584 20556 - S 06:51 0:03.30 /usr/local/sbin/kea-dhcp4 -c /usr/local/etc/kea/kea-dhcp4.conf
kill INT or -2 successfully clears the process:
[2.7.2-RELEASE][root@firewall]/tmp: kill -1 68622
[2.7.2-RELEASE][root@firewall]/tmp: ps aux | grep kea
root 68622 0.5 0.5 52584 20740 - S 06:51 0:03.35 /usr/local/sbin/kea-dhcp4 -c /usr/local/etc/kea/kea-dhcp4.conf
root 10329 0.0 0.1 12752 2168 0 S+ 18:48 0:00.00 grep kea
[2.7.2-RELEASE][root@firewall]/tmp: kill -2 68622
[2.7.2-RELEASE][root@firewall]/tmp: ps aux | grep kea
root 19501 0.0 0.1 12752 2164 0 S+ 18:49 0:00.00 grep kea
kea-dhcp4 services then starts successfully:
[2.7.2-RELEASE][root@firewall]/tmp: ps aux | grep kea
root 53145 0.0 0.5 39640 19580 - S 18:50 0:00.06 /usr/local/sbin/kea-dhcp4 -c /usr/local/etc/kea/kea-dhcp4.conf
root 99465 0.0 0.1 12752 2164 0 S+ 18:50 0:00.00 grep kea
[2.7.2-RELEASE][root@firewall]/tmp: keactrl status
DHCPv4 server: active
DHCPv6 server: inactive
DHCP DDNS: inactive
Control Agent: inactive
Kea DHCPv4 configuration file: /usr/local/etc/kea/kea-dhcp4.conf
Kea DHCPv6 configuration file: /usr/local/etc/kea/kea-dhcp6.conf
Kea DHCP DDNS configuration file: /usr/local/etc/kea/kea-dhcp-ddns.conf
Kea Control Agent configuration file: /usr/local/etc/kea/kea-ctrl-agent.conf
keactrl configuration file: /usr/local/etc/kea/keactrl.conf
BUT then oddly shuts down again exactly 1 minute later:
May 2 19:07:00 firewall kea-dhcp4[58287]: INFO [kea-dhcp4.dhcp4.0x2139c3212000] DHCP4_STARTED Kea DHCPv4 server version 2.4.0 started
May 2 19:07:54 firewall kea-dhcp4[58287]: INFO [kea-dhcp4.commands.0x2139c3212000] COMMAND_RECEIVED Received command 'lease4-get-all'
May 2 19:08:00 firewall kea-dhcp4[58287]: INFO [kea-dhcp4.dhcp4.0x2139c3212000] DHCP4_SHUTDOWN server shutdown
I checked Service Watchdog configuration and could see both dhcpd AND kea-dhcpd4 as actively monitored!
Once I REMOVED dhcpd from Service Watchdog, the repeated stop and start of the kea-dhcp4 service was resolved. So could the bug be fixed by checking to remove "dhcpd" from Service Watchdog when a user transitions dhcp configuration from ISC DHCP (Deprecated) to Kea DHCP?
Updated by Yuri Weinstein 7 months ago
I have experienced the same problem today 2 days after updating to 24.03-RELEASE
In addition to all described above, it seems that TailScale service was messed up as well, after the kea failure.
This bug seems alive
Updated by Jim Pingle 7 months ago
- Status changed from Closed to New
- Plus Target Version changed from 24.03 to 24.07
Yuri Weinstein wrote in #note-4:
I have experienced the same problem today 2 days after updating to 24.03-RELEASE
In addition to all described above, it seems that TailScale service was messed up as well, after the kea failure.
This bug seems alive
Any hints as to what might have led to it being in the broken state? I tried all manner of killing/crashing it and even making dummy lock files but I can't make it fail here now.
Updated by Yuri Weinstein 7 months ago
Jim Pingle wrote in #note-5:
Any hints as to what might have led to it being in the broken state? I tried all manner of killing/crashing it and even making dummy lock files but I can't make it fail here now.
No. I managed to restore both DHCP and TS to a good state by switching "Kea DHCP" to "ISC DHCP (Deprecated)" back and forth and now both seem happy. No clue what caused the failure
Updated by Dean Arnold 7 months ago
I just switched to kea and am seeing the service get marked as stopped while the process is still running. Same socket error.
This has happened a number of times today, but I just reproduced it when disabling IPV6 on my WAN, although note this appears to be just one circumstance under which this issue occurs.
Here is the log:
May 5 09:43:49 az-gateway kea-dhcp4[34622]: INFO [kea-dhcp4.dhcpsrv.0x314274216600] EVAL_RESULT Expression pool_lan_0 evaluated to 1
May 5 09:43:49 az-gateway kea-dhcp4[34622]: INFO [kea-dhcp4.dhcpsrv.0x314274216600] EVAL_RESULT Expression pool_opt1_0 evaluated to 1
May 5 09:43:49 az-gateway kea-dhcp4[34622]: INFO [kea-dhcp4.dhcpsrv.0x314274216600] EVAL_RESULT Expression pool_opt2_0 evaluated to 1
May 5 09:43:49 az-gateway kea-dhcp4[34622]: INFO [kea-dhcp4.dhcpsrv.0x314274216600] EVAL_RESULT Expression pool_opt3_0 evaluated to 1
May 5 09:43:49 az-gateway kea-dhcp4[34622]: INFO [kea-dhcp4.dhcpsrv.0x314274216600] EVAL_RESULT Expression pool_opt4_0 evaluated to 1
May 5 09:43:49 az-gateway kea-dhcp4[34622]: INFO [kea-dhcp4.leases.0x314274216600] DHCP4_LEASE_ALLOC [hwtype=1 74:c6:3b:f6:00:ae], cid=[no info], tid=0x5bd9c1f7: lease 192.168.123.40 has been allocated for 72
00 seconds
May 5 09:44:44 az-gateway dhclient[75199]: connection closed
May 5 09:44:44 az-gateway dhclient[75199]: exiting.
May 5 09:44:45 az-gateway dhcp6c[89672]: exit without release
May 5 09:44:45 az-gateway dhcp6c[89672]: Bypassing address release because of -n flag
May 5 09:44:45 az-gateway dhcp6c[89672]: remove an address 2001:558:6045:20:78f8:f685:95b5:7871/128 on ice1
May 5 09:44:45 az-gateway dhcp6c[89672]: Bypassing address release because of -n flag
May 5 09:44:45 az-gateway dhcp6c[21910]: lstat failed: No such file or directory
May 5 09:44:46 az-gateway dhclient[26925]: PREINIT
May 5 09:44:46 az-gateway dhclient[25866]: DHCPREQUEST on ice1 to 255.255.255.255 port 67
May 5 09:44:46 az-gateway dhclient[25866]: DHCPACK from 96.120.90.149
May 5 09:44:46 az-gateway dhclient[28406]: REBOOT
May 5 09:44:46 az-gateway dhclient[29468]: Starting add_new_address()
May 5 09:44:46 az-gateway dhclient[30061]: ifconfig ice1 inet 67.161.34.70 netmask 255.255.248.0 broadcast 255.255.255.255
May 5 09:44:46 az-gateway dhclient[31202]: New IP Address (ice1): 67.161.34.70
May 5 09:44:46 az-gateway dhclient[31552]: New Subnet Mask (ice1): 255.255.248.0
May 5 09:44:46 az-gateway dhclient[32201]: New Broadcast Address (ice1): 255.255.255.255
May 5 09:44:46 az-gateway dhclient[32647]: New Routers (ice1): 67.161.32.1
May 5 09:44:46 az-gateway dhclient[33394]: Adding new routes to interface: ice1
May 5 09:44:47 az-gateway dhclient[34675]: /sbin/route add -host 67.161.32.1 -iface ice1
May 5 09:44:47 az-gateway dhclient[35687]: /sbin/route add default 67.161.32.1
May 5 09:44:47 az-gateway dhclient[36368]: Creating resolv.conf
May 5 09:44:47 az-gateway dhclient[25866]: bound to 67.161.34.70 -- renewal in 3316 seconds.
May 5 09:44:48 az-gateway kea-dhcp4[34622]: INFO [kea-dhcp4.dhcp4.0x314274212000] DHCP4_SHUTDOWN server shutdown
May 5 09:44:48 az-gateway kea-dhcp4[34622]: INFO [kea-dhcp4.lease-cmds-hooks.0x314274212000] LEASE_CMDS_DEINIT_OK unloading Lease Commands hooks library successful
May 5 09:44:48 az-gateway kea-dhcp4[34622]: INFO [kea-dhcp4.hooks.0x314274212000] HOOKS_LIBRARY_CLOSED hooks library /usr/local/lib/kea/hooks/libdhcp_lease_cmds.so successfully closed
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.hosts.0x309daf412000] HOSTS_BACKENDS_REGISTERED the following host backend types are available:
May 5 09:44:48 az-gateway kea-dhcp4[66818]: WARN [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_MT_DISABLED_QUEUE_CONTROL disabling dhcp queue control when multi-threading is enabled.
May 5 09:44:48 az-gateway kea-dhcp4[66818]: WARN [kea-dhcp4.dhcp4.0x309daf412000] DHCP4_RESERVATIONS_LOOKUP_FIRST_ENABLED Multi-threading is enabled and host reservations lookup is always performed first.
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.hooks.0x309daf412000] HOOKS_LIBRARY_CLOSED hooks library /usr/local/lib/kea/hooks/libdhcp_lease_cmds.so successfully closed
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_NEW_SUBNET4 a new subnet has been added to configuration: 192.168.121.0/24 with params: valid-lifetime=7200
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_NEW_SUBNET4 a new subnet has been added to configuration: 192.168.120.0/24 with params: valid-lifetime=7200
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_NEW_SUBNET4 a new subnet has been added to configuration: 192.168.122.0/24 with params: valid-lifetime=7200
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_NEW_SUBNET4 a new subnet has been added to configuration: 192.168.123.0/24 with params: valid-lifetime=7200
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_NEW_SUBNET4 a new subnet has been added to configuration: 192.168.124.0/24 with params: valid-lifetime=7200
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_SOCKET_TYPE_SELECT using socket type raw
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_ADD_IFACE listening on interface ice0
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_ADD_IFACE listening on interface ice0.120
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_ADD_IFACE listening on interface ice0.122
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_ADD_IFACE listening on interface ice0.123
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_ADD_IFACE listening on interface ice0.124
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_SOCKET_TYPE_DEFAULT "dhcp-socket-type" not specified , using default socket type raw
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.hooks.0x309daf412000] HOOKS_LIBRARY_LOADED hooks library /usr/local/lib/kea/hooks/libdhcp_lease_cmds.so successfully loaded
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcp4.0x309daf412000] DHCP4_CONFIG_COMPLETE DHCPv4 server has completed configuration: added IPv4 subnets: 5; DDNS: disabled
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_MEMFILE_DB opening memory file lease database: name=/var/lib/kea/dhcp4.leases persist=true type=memfile universe=4
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_MEMFILE_LEASE_FILE_LOAD loading leases from file /var/lib/kea/dhcp4.leases.2
May 5 09:44:48 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_MEMFILE_LEASE_FILE_LOAD loading leases from file /var/lib/kea/dhcp4.leases
May 5 09:44:49 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_MEMFILE_EXTRACT_EXTENDED_INFO4 extracting extended info saw 62 leases, extended info sanity checks modified 0 / upda
ted 0 leases and 0 leases have relay or remote id
May 5 09:44:49 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_MEMFILE_LFC_SETUP setting up the Lease File Cleanup interval to 3600 sec
May 5 09:44:49 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_USE_ALLOCATOR using the iterative allocator for V4 leases in subnet 192.168.121.0/24
May 5 09:44:49 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_USE_ALLOCATOR using the iterative allocator for V4 leases in subnet 192.168.120.0/24
May 5 09:44:49 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_USE_ALLOCATOR using the iterative allocator for V4 leases in subnet 192.168.122.0/24
May 5 09:44:49 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_USE_ALLOCATOR using the iterative allocator for V4 leases in subnet 192.168.123.0/24
May 5 09:44:49 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcpsrv.0x309daf412000] DHCPSRV_CFGMGR_USE_ALLOCATOR using the iterative allocator for V4 leases in subnet 192.168.124.0/24
May 5 09:44:49 az-gateway kea-dhcp4[66818]: WARN [kea-dhcp4.dhcp4.0x309daf412000] DHCP4_MULTI_THREADING_INFO enabled: yes, number of threads: 2, queue size: 64
May 5 09:44:49 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcp4.0x309daf412000] DHCP4_STARTED Kea DHCPv4 server version 2.4.1 started
May 5 09:44:56 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.dhcp4.0x309daf412000] DHCP4_SHUTDOWN server shutdown
May 5 09:44:56 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.lease-cmds-hooks.0x309daf412000] LEASE_CMDS_DEINIT_OK unloading Lease Commands hooks library successful
May 5 09:44:56 az-gateway kea-dhcp4[66818]: INFO [kea-dhcp4.hooks.0x309daf412000] HOOKS_LIBRARY_CLOSED hooks library /usr/local/lib/kea/hooks/libdhcp_lease_cmds.so successfully closed
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.hosts.0x34370c212000] HOSTS_BACKENDS_REGISTERED the following host backend types are available:
May 5 09:44:56 az-gateway kea-dhcp4[80522]: WARN [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_MT_DISABLED_QUEUE_CONTROL disabling dhcp queue control when multi-threading is enabled.
May 5 09:44:56 az-gateway kea-dhcp4[80522]: WARN [kea-dhcp4.dhcp4.0x34370c212000] DHCP4_RESERVATIONS_LOOKUP_FIRST_ENABLED Multi-threading is enabled and host reservations lookup is always performed first.
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.hooks.0x34370c212000] HOOKS_LIBRARY_CLOSED hooks library /usr/local/lib/kea/hooks/libdhcp_lease_cmds.so successfully closed
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_CFGMGR_NEW_SUBNET4 a new subnet has been added to configuration: 192.168.121.0/24 with params: valid-lifetime=7200
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_CFGMGR_NEW_SUBNET4 a new subnet has been added to configuration: 192.168.120.0/24 with params: valid-lifetime=7200
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_CFGMGR_ADD_IFACE listening on interface ice0.122
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_CFGMGR_ADD_IFACE listening on interface ice0.123
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_CFGMGR_ADD_IFACE listening on interface ice0.124
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_CFGMGR_SOCKET_TYPE_DEFAULT "dhcp-socket-type" not specified , using default socket type raw
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.commands.0x34370c212000] COMMAND_ACCEPTOR_START Starting to accept connections via unix domain socket bound to /tmp/kea4-ctrl-socket
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.lease-cmds-hooks.0x34370c212000] LEASE_CMDS_INIT_OK loading Lease Commands hooks library successful
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.hooks.0x34370c212000] HOOKS_LIBRARY_LOADED hooks library /usr/local/lib/kea/hooks/libdhcp_lease_cmds.so successfully loaded
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcp4.0x34370c212000] DHCP4_CONFIG_COMPLETE DHCPv4 server has completed configuration: added IPv4 subnets: 5; DDNS: disabled
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_MEMFILE_DB opening memory file lease database: name=/var/lib/kea/dhcp4.leases persist=true type=memfile universe=4
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_MEMFILE_LEASE_FILE_LOAD loading leases from file /var/lib/kea/dhcp4.leases.2
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_MEMFILE_LEASE_FILE_LOAD loading leases from file /var/lib/kea/dhcp4.leases
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_MEMFILE_EXTRACT_EXTENDED_INFO4 extracting extended info saw 62 leases, extended info sanity checks modified 0 / upda
ted 0 leases and 0 leases have relay or remote id
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_MEMFILE_LFC_SETUP setting up the Lease File Cleanup interval to 3600 sec
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_CFGMGR_USE_ALLOCATOR using the iterative allocator for V4 leases in subnet 192.168.121.0/24
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_CFGMGR_USE_ALLOCATOR using the iterative allocator for V4 leases in subnet 192.168.120.0/24
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_CFGMGR_USE_ALLOCATOR using the iterative allocator for V4 leases in subnet 192.168.122.0/24
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_CFGMGR_USE_ALLOCATOR using the iterative allocator for V4 leases in subnet 192.168.123.0/24
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcpsrv.0x34370c212000] DHCPSRV_CFGMGR_USE_ALLOCATOR using the iterative allocator for V4 leases in subnet 192.168.124.0/24
May 5 09:44:56 az-gateway kea-dhcp4[80522]: WARN [kea-dhcp4.dhcp4.0x34370c212000] DHCP4_MULTI_THREADING_INFO enabled: yes, number of threads: 2, queue size: 64
May 5 09:44:56 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcp4.0x34370c212000] DHCP4_STARTED Kea DHCPv4 server version 2.4.1 started
May 5 09:45:19 az-gateway kea-dhcp4[94142]: INFO [kea-dhcp4.hosts.0x11511a12000] HOSTS_BACKENDS_REGISTERED the following host backend types are available:
May 5 09:45:19 az-gateway kea-dhcp4[94142]: WARN [kea-dhcp4.dhcpsrv.0x11511a12000] DHCPSRV_MT_DISABLED_QUEUE_CONTROL disabling dhcp queue control when multi-threading is enabled.
May 5 09:45:19 az-gateway kea-dhcp4[94142]: WARN [kea-dhcp4.dhcp4.0x11511a12000] DHCP4_RESERVATIONS_LOOKUP_FIRST_ENABLED Multi-threading is enabled and host reservations lookup is always performed first.
May 5 09:45:19 az-gateway kea-dhcp4[94142]: INFO [kea-dhcp4.hooks.0x11511a12000] HOOKS_LIBRARY_CLOSED hooks library /usr/local/lib/kea/hooks/libdhcp_lease_cmds.so successfully closed
May 5 09:45:19 az-gateway kea-dhcp4[94142]: INFO [kea-dhcp4.dhcpsrv.0x11511a12000] DHCPSRV_CFGMGR_NEW_SUBNET4 a new subnet has been added to configuration: 192.168.121.0/24 with params: valid-lifetime=7200
May 5 09:45:19 az-gateway kea-dhcp4[94142]: INFO [kea-dhcp4.dhcpsrv.0x11511a12000] DHCPSRV_CFGMGR_NEW_SUBNET4 a new subnet has been added to configuration: 192.168.120.0/24 with params: valid-lifetime=7200
May 5 09:45:19 az-gateway kea-dhcp4[94142]: INFO [kea-dhcp4.dhcpsrv.0x11511a12000] DHCPSRV_CFGMGR_NEW_SUBNET4 a new subnet has been added to configuration: 192.168.122.0/24 with params: valid-lifetime=7200
May 5 09:45:19 az-gateway kea-dhcp4[94142]: INFO [kea-dhcp4.dhcpsrv.0x11511a12000] DHCPSRV_CFGMGR_NEW_SUBNET4 a new subnet has been added to configuration: 192.168.123.0/24 with params: valid-lifetime=7200
May 5 09:45:19 az-gateway kea-dhcp4[94142]: INFO [kea-dhcp4.dhcpsrv.0x11511a12000] DHCPSRV_CFGMGR_NEW_SUBNET4 a new subnet has been added to configuration: 192.168.124.0/24 with params: valid-lifetime=7200
May 5 09:45:19 az-gateway kea-dhcp4[94142]: INFO [kea-dhcp4.dhcpsrv.0x11511a12000] DHCPSRV_CFGMGR_SOCKET_TYPE_SELECT using socket type raw
May 5 09:45:19 az-gateway kea-dhcp4[94142]: INFO [kea-dhcp4.dhcpsrv.0x11511a12000] DHCPSRV_CFGMGR_ADD_IFACE listening on interface ice0
May 5 09:45:19 az-gateway kea-dhcp4[94142]: INFO [kea-dhcp4.dhcpsrv.0x11511a12000] DHCPSRV_CFGMGR_ADD_IFACE listening on interface ice0.120
May 5 09:45:19 az-gateway kea-dhcp4[94142]: INFO [kea-dhcp4.dhcpsrv.0x11511a12000] DHCPSRV_CFGMGR_ADD_IFACE listening on interface ice0.122
May 5 09:45:19 az-gateway kea-dhcp4[94142]: INFO [kea-dhcp4.dhcpsrv.0x11511a12000] DHCPSRV_CFGMGR_ADD_IFACE listening on interface ice0.123
May 5 09:45:19 az-gateway kea-dhcp4[94142]: INFO [kea-dhcp4.dhcpsrv.0x11511a12000] DHCPSRV_CFGMGR_ADD_IFACE listening on interface ice0.124
May 5 09:45:19 az-gateway kea-dhcp4[94142]: INFO [kea-dhcp4.dhcpsrv.0x11511a12000] DHCPSRV_CFGMGR_SOCKET_TYPE_DEFAULT "dhcp-socket-type" not specified , using default socket type raw
May 5 09:45:19 az-gateway kea-dhcp4[94142]: ERROR [kea-dhcp4.dhcp4.0x11511a12000] DHCP4_PARSER_COMMIT_FAIL parser failed to commit changes: cannot lock socket lockfile, /tmp/kea4-ctrl-socket.lock, : Resource t
emporarily unavailable
May 5 09:45:19 az-gateway kea-dhcp4[94142]: ERROR [kea-dhcp4.dhcp4.0x11511a12000] DHCP4_CONFIG_LOAD_FAIL configuration error using file: /usr/local/etc/kea/kea-dhcp4.conf, reason: cannot lock socket lockfile,
/tmp/kea4-ctrl-socket.lock, : Resource temporarily unavailable
May 5 09:45:19 az-gateway kea-dhcp4[94142]: ERROR [kea-dhcp4.dhcp4.0x11511a12000] DHCP4_INIT_FAIL failed to initialize Kea server: configuration error using file '/usr/local/etc/kea/kea-dhcp4.conf': cannot loc
k socket lockfile, /tmp/kea4-ctrl-socket.lock, : Resource temporarily unavailable
May 5 09:45:19 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.dhcp4.0x34370c212000] DHCP4_SHUTDOWN server shutdown
May 5 09:45:19 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.lease-cmds-hooks.0x34370c212000] LEASE_CMDS_DEINIT_OK unloading Lease Commands hooks library successful
May 5 09:45:19 az-gateway kea-dhcp4[80522]: INFO [kea-dhcp4.hooks.0x34370c212000] HOOKS_LIBRARY_CLOSED hooks library /usr/local/lib/kea/hooks/libdhcp_lease_cmds.so successfully closed
Updated by Ricardo Mendes 6 months ago
Following up on forum post https://forum.netgate.com/topic/188337/
I am reporting this same issue. I've been using KEA since it came out with pfSense and this is a situation that occurs sporadically and I haven't been able to identify the source for the crash.
In all these months this has happened maybe around 5 times. I start losing access to some hosts, and checking on the firewall I see the KEA service is stopped.
Trying to start it always fails.
May 22 12:16:03 kea-dhcp4 20512 ERROR [kea-dhcp4.dhcp4.0xdd682612000] DHCP4_INIT_FAIL failed to initialize Kea server: configuration error using file '/usr/local/etc/kea/kea-dhcp4.conf': cannot lock socket lockfile, /tmp/kea4-ctrl-socket.lock, : Resource temporarily unavailable
May 22 12:16:03 kea-dhcp4 20512 ERROR [kea-dhcp4.dhcp4.0xdd682612000] DHCP4_CONFIG_LOAD_FAIL configuration error using file: /usr/local/etc/kea/kea-dhcp4.conf, reason: cannot lock socket lockfile, /tmp/kea4-ctrl-socket.lock, : Resource temporarily unavailable
May 22 12:16:03 kea-dhcp6 20782 ERROR [kea-dhcp6.dhcp6.0x3731b6012000] DHCP6_INIT_FAIL failed to initialize Kea server: configuration error using file '/usr/local/etc/kea/kea-dhcp6.conf': cannot lock socket lockfile, /tmp/kea6-ctrl-socket.lock, : Resource temporarily unavailable
May 22 12:16:03 kea-dhcp4 20512 ERROR [kea-dhcp4.dhcp4.0xdd682612000] DHCP4_PARSER_COMMIT_FAIL parser failed to commit changes: cannot lock socket lockfile, /tmp/kea4-ctrl-socket.lock, : Resource temporarily unavailable
May 22 12:16:03 kea-dhcp6 20782 ERROR [kea-dhcp6.dhcp6.0x3731b6012000] DHCP6_CONFIG_LOAD_FAIL configuration error using file: /usr/local/etc/kea/kea-dhcp6.conf, reason: cannot lock socket lockfile, /tmp/kea6-ctrl-socket.lock, : Resource temporarily unavailable
May 22 12:16:03 kea-dhcp4 20512 INFO [kea-dhcp4.dhcpsrv.0xdd682612000] DHCPSRV_CFGMGR_SOCKET_TYPE_DEFAULT "dhcp-socket-type" not specified , using default socket type raw
May 22 12:16:03 kea-dhcp6 20782 ERROR [kea-dhcp6.dhcp6.0x3731b6012000] DHCP6_PARSER_COMMIT_FAIL parser failed to commit changes: cannot lock socket lockfile, /tmp/kea6-ctrl-socket.lock, : Resource temporarily unavailable
Resolution is a firewall reboot and all services come up OK.
Updated by Jim Pingle 6 months ago
- Plus Target Version changed from 24.07 to 24.08
Updated by Zachary Cohen 2 months ago
This issue has impacted me on numerous occasions, only when the service is killed in an unclean fashion.
I also can't replicate the behavior by creating dummy lock files -- the service will still start.
Due to this unexplained behavior, I implemented a hacky workaround: creating a cron job which executes the following script:
[ `keactrl status | grep 'DHCPv4 server:' | awk '{print $3}'` = "inactive" ] && [ -f /tmp/kea4-ctrl-socket.lock ] && rm -f /tmp/kea4-ctrl-socket.lock && keactrl start -s dhcp4
Updated by Jim Pingle about 1 month ago
- Plus Target Version changed from 24.08 to 24.11
Without some way to reliably reproduce the conditions in which this happens I'm hesitant to blindly commit something on the chance it might help. I've killed the kea processes in various ways and even when it does leave a lock, it restarts itself just fine. So there must be some other component to it.
If we can figure that out, it would go a long way toward making sure it gets fixed properly.
Updated by Jim Pingle about 1 month ago
- Plus Target Version changed from 24.11 to 25.01
Updated by robi robi about 1 month ago
I switched back to ISC on my systems affected by this issue.
Updated by Christian McDonald 23 days ago
- Status changed from New to Feedback
- Plus Target Version changed from 25.01 to 24.11
I think(tm) we have a fix for this.
Updated by Christian McDonald 22 days ago
- Subject changed from Stale Kea control socket lock file can prevent Kea from starting to Kea fails to restart due to race between process termination and startup
Updated by Jim Pingle 15 days ago
- Has duplicate Regression #15823: Kea service is down and cannot be enabled after down event added
Actions