Project

General

Profile

Actions

Regression #15823

closed

Kea service is down and cannot be enabled after down event

Added by Marcelo Cury about 2 months ago. Updated about 2 months ago.

Status:
Duplicate
Priority:
Normal
Category:
DHCP (IPv4)
Target version:
-
Start date:
Due date:
% Done:

0%

Estimated time:
Plus Target Version:
Release Notes:
Force Exclusion
Affected Version:
Affected Architecture:
4100

Description

Found KEA DHCP server down today, checked logs and noticed a down event.
Tried to enabled it again, and the same logs appeared about a cannot lock socket lockfile, /var/run/kea4-ctrl-socket.lock, : Resource temporarily unavailable

Logs:
2024-11-06T02:50:50.000-03:00 php-fpm35081: /rc.newwanip: Removing static route for monitor 8.8.4.4 and adding a new route through 192.168.255.233
2024-11-06T02:50:50.000-03:00 php-fpm35081: /rc.newwanip: Removing static route for monitor 8.8.8.8 and adding a new route through 192.168.255.238
2024-11-06T02:50:50.000-03:00 dpinger34691: exiting on signal 15
2024-11-06T02:50:50.000-03:00 dpinger35739: exiting on signal 15
2024-11-06T02:50:50.000-03:00 dpinger30356: send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 8.8.4.4 bind_addr 192.168.255.234 identifier "NETGW "
2024-11-06T02:50:50.000-03:00 dpinger30810: send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 8.8.8.8 bind_addr 192.168.255.237 identifier "OIGW "
2024-11-06T02:50:51.000-03:00 php-fpm1650: /rc.dyndns.update: MONITOR: NETGW is available now, adding to routing group OI_NET
2024-11-06T02:50:51.000-03:00 php-fpm1650: 8.8.4.4|192.168.255.234|NETGW|16.492ms|4.583ms|0.0%|online|none
2024-11-06T02:50:51.000-03:00 unbound41161: [41161:0] info: service stopped (unbound 1.22.0).
2024-11-06T02:50:51.000-03:00 unbound41161: [41161:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-11-06T02:50:51.000-03:00 unbound41161: [41161:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
2024-11-06T02:50:51.000-03:00 unbound41161: [41161:0] info: server stats for thread 1: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2024-11-06T02:50:51.000-03:00 unbound41161: [41161:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
2024-11-06T02:50:51.000-03:00 php-fpm1650: /rc.dyndns.update: Dynamic DNS custom (): Public IP address could not be extracted from Check IP Service
2024-11-06T02:50:51.000-03:00 php-fpm1650: /rc.dyndns.update: Dynamic Dns (): Current WAN IP could not be determined, skipping update process.
2024-11-06T02:50:51.000-03:00 php-fpm1650: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:50:52.000-03:00 php-fpm92252: /rc.dyndns.update: Dynamic DNS custom (): Public IP address could not be extracted from Check IP Service
2024-11-06T02:50:52.000-03:00 php-fpm1650: /rc.dyndns.update: Dynamic DNS custom (): Public IP address could not be extracted from Check IP Service
2024-11-06T02:50:52.000-03:00 php-fpm92252: /rc.dyndns.update: Dynamic DNS () There was an error trying to determine the public IP for interface - OI_NET (ix2 ).
2024-11-06T02:50:52.000-03:00 php-fpm1650: /rc.dyndns.update: Dynamic DNS () There was an error trying to determine the public IP for interface - OI_NET (ix2 ).
2024-11-06T02:50:52.000-03:00 php-fpm73962: /rc.dyndns.update: Dynamic DNS custom (): Public IP address could not be extracted from Check IP Service
2024-11-06T02:50:52.000-03:00 php-fpm73962: /rc.dyndns.update: Dynamic DNS () There was an error trying to determine the public IP for interface - OI_NET (ix2 ).
2024-11-06T02:50:52.000-03:00 php-fpm89428: /rc.newwanip: Dynamic DNS custom (): Public IP address could not be extracted from Check IP Service
2024-11-06T02:50:52.000-03:00 php-fpm89428: /rc.newwanip: Dynamic DNS () There was an error trying to determine the public IP for interface - OI_NET (ix2 ).
2024-11-06T02:50:52.000-03:00 unbound87325: [87325:0] notice: init module 0: validator
2024-11-06T02:50:52.000-03:00 unbound87325: [87325:0] notice: init module 1: iterator
2024-11-06T02:50:52.000-03:00 unbound87325: [87325:0] info: start of service (unbound 1.22.0).
2024-11-06T02:50:53.000-03:00 php-fpm30187: /rc.start_packages: Configuration Change: (system): pfBlockerNG: saving DNSBL changes
2024-11-06T02:50:53.000-03:00 check_reload_status658: Syncing firewall
2024-11-06T02:50:54.000-03:00 tail_pfb24580: [pfBlockerNG] Firewall Filter Service stopped
2024-11-06T02:50:54.000-03:00 php_pfb25108: [pfBlockerNG] filterlog daemon stopped
2024-11-06T02:50:54.000-03:00 tail_pfb27634: [pfBlockerNG] Firewall Filter Service started
2024-11-06T02:50:55.000-03:00 php_pfb27860: [pfBlockerNG] filterlog daemon started
2024-11-06T02:50:56.000-03:00 unbound87325: [87325:1] info: generate keytag query _ta-4f66. NULL IN
2024-11-06T02:50:57.000-03:00 php-fpm96740: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:50:58.000-03:00 php-fpm92252: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:50:59.000-03:00 php-fpm73962: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:00.000-03:00 kea-dhcp45682: WARN [kea-dhcp4.dhcpsrv.0xd90ada12000] DHCPSRV_MT_DISABLED_QUEUE_CONTROL disabling dhcp queue control when multi-threading is enabled.
2024-11-06T02:51:00.000-03:00 kea-dhcp45682: WARN [kea-dhcp4.dhcp4.0xd90ada12000] DHCP4_RESERVATIONS_LOOKUP_FIRST_ENABLED Multi-threading is enabled and host reservations lookup is always performed first.
2024-11-06T02:51:00.000-03:00 kea-dhcp45682: ERROR [kea-dhcp4.dhcp4.0xd90ada12000] DHCP4_PARSER_COMMIT_FAIL parser failed to commit changes: cannot lock socket lockfile, /var/run/kea4-ctrl-socket.lock, : Resource temporarily unavailable
2024-11-06T02:51:00.000-03:00 kea-dhcp45682: ERROR [kea-dhcp4.dhcp4.0xd90ada12000] DHCP4_CONFIG_LOAD_FAIL configuration error using file: /usr/local/etc/kea/kea-dhcp4.conf, reason: cannot lock socket lockfile, /var/run/kea4-ctrl-socket.lock, : Resource temporarily unavailable
2024-11-06T02:51:00.000-03:00 kea-dhcp45682: ERROR [kea-dhcp4.dhcp4.0xd90ada12000] DHCP4_INIT_FAIL failed to initialize Kea server: configuration error using file '/usr/local/etc/kea/kea-dhcp4.conf': cannot lock socket lockfile, /var/run/kea4-ctrl-socket.lock, : Resource temporarily unavailable
2024-11-06T02:51:00.000-03:00 php-fpm89428: /rc.newwanip: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:00.000-03:00 php-cgi94640: servicewatchdog_cron.php: Service Watchdog detected service nut stopped. Restarting nut (UPS monitoring daemon)
2024-11-06T02:51:00.000-03:00 upsmon28154: Startup successful
2024-11-06T02:51:00.000-03:00 kea-dhcp429687: WARN [kea-dhcp4.dhcpsrv.0x13b3a7412000] DHCPSRV_MT_DISABLED_QUEUE_CONTROL disabling dhcp queue control when multi-threading is enabled.
2024-11-06T02:51:00.000-03:00 kea-dhcp429687: WARN [kea-dhcp4.dhcp4.0x13b3a7412000] DHCP4_RESERVATIONS_LOOKUP_FIRST_ENABLED Multi-threading is enabled and host reservations lookup is always performed first.
2024-11-06T02:51:00.000-03:00 kea-dhcp429687: ERROR [kea-dhcp4.dhcp4.0x13b3a7412000] DHCP4_PARSER_COMMIT_FAIL parser failed to commit changes: cannot lock socket lockfile, /var/run/kea4-ctrl-socket.lock, : Resource temporarily unavailable
2024-11-06T02:51:00.000-03:00 kea-dhcp429687: ERROR [kea-dhcp4.dhcp4.0x13b3a7412000] DHCP4_CONFIG_LOAD_FAIL configuration error using file: /usr/local/etc/kea/kea-dhcp4.conf, reason: cannot lock socket lockfile, /var/run/kea4-ctrl-socket.lock, : Resource temporarily unavailable
2024-11-06T02:51:00.000-03:00 kea-dhcp429687: ERROR [kea-dhcp4.dhcp4.0x13b3a7412000] DHCP4_INIT_FAIL failed to initialize Kea server: configuration error using file '/usr/local/etc/kea/kea-dhcp4.conf': cannot lock socket lockfile, /var/run/kea4-ctrl-socket.lock, : Resource temporarily unavailable
2024-11-06T02:51:01.000-03:00 php-fpm69280: /rc.newwanip: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:02.000-03:00 php-fpm35081: /rc.newwanip: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:02.000-03:00 php-fpm96740: /rc.dyndns.update: Dynamic DNS custom (): Public IP address could not be extracted from Check IP Service
2024-11-06T02:51:02.000-03:00 php-fpm96740: /rc.dyndns.update: Dynamic Dns (): Current WAN IP could not be determined, skipping update process.
2024-11-06T02:51:02.000-03:00 php-fpm96740: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:04.000-03:00 php-fpm69280: /rc.newwanip: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:04.000-03:00 php-fpm96740: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:06.000-03:00 php-fpm96740: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:06.000-03:00 php-fpm92252: /rc.dyndns.update: Dynamic DNS custom (): Public IP address could not be extracted from Check IP Service
2024-11-06T02:51:06.000-03:00 php-fpm92252: /rc.dyndns.update: Dynamic Dns (): Current WAN IP could not be determined, skipping update process.
2024-11-06T02:51:06.000-03:00 php-fpm92252: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:06.000-03:00 php-fpm35081: /rc.newwanip: Dynamic DNS custom (): Public IP address could not be extracted from Check IP Service
2024-11-06T02:51:06.000-03:00 php-fpm35081: /rc.newwanip: Dynamic DNS () There was an error trying to determine the public IP for interface - OI_NET (ix2 ).
2024-11-06T02:51:06.000-03:00 php-fpm73962: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:07.000-03:00 php-fpm96740: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:08.000-03:00 php-fpm92252: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:08.000-03:00 php-fpm89428: /rc.newwanip: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:09.000-03:00 php-fpm73962: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:10.000-03:00 php-fpm89428: /rc.newwanip: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:10.000-03:00 php-fpm69280: /rc.newwanip: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:11.000-03:00 php-fpm92252: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:11.000-03:00 php-fpm35081: /rc.newwanip: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:11.000-03:00 php-fpm89428: /rc.newwanip: Resyncing OpenVPN instances for interface NET.
2024-11-06T02:51:11.000-03:00 php-fpm89428: /rc.newwanip: Creating rrd update script
2024-11-06T02:51:12.000-03:00 php-fpm96740: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2024-11-06T02:51:13.000-03:00 php-fpm89428: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 192.168.255.234 -> 192.168.255.234 - Restarting packages.
2024-11-06T02:51:13.000-03:00 check_reload_status658: Starting packages
2024-11-06T02:51:13.000-03:00 check_reload_status658: Reloading filter
2024-11-06T02:51:13.000-03:00 check_reload_status658: Reloading filter
2024-11-06T02:51:14.000-03:00 php-fpm69280: /rc.newwanip: Dynamic DNS custom (): Public IP address could not be extracted from Check IP Service
2024-11-06T02:51:14.000-03:00 php-fpm69280: /rc.newwanip: Dynamic DNS () There was an error trying to determine the public IP for interface - OI_NET (ix2 ).
2024-11-06T02:51:14.000-03:00 php-fpm1650: /rc.start_packages: Restarting/Starting all packages.
2024-11-06T02:51:14.000-03:00 php-fpm1650: /rc.start_packages: Stopping service nut
2024-11-06T02:51:14.000-03:00 upsmon28704: Signal 15: exiting
2024-11-06T02:51:14.000-03:00 php-fpm1650: /rc.start_packages: Starting service nut
2024-11-06T02:51:14.000-03:00 upsmon31891: Startup successful

I'm using 24.11.b.20241031.0600 build on a SG-4100 device.
Packages installed:
acme
aws-wizard
ipsec-profile-wizard
Netgate_Firmware_Upgrade
nut (configured to reach a remote server, not using the USB port from the nobreak to the SG-4100)
pfBlockerNG-devel (only IP based feeds in use, DNSBL disabled)
Service_Watchdog (Only NUT added to the service_watchdog)
System_Patches
WireGuard


Related issues

Is duplicate of Bug #14977: Kea fails to restart due to race between process termination and startupResolvedChristian McDonald

Actions
Actions #1

Updated by Jim Pingle about 2 months ago

  • Tracker changed from Bug to Regression
  • Project changed from pfSense Plus to pfSense
  • Subject changed from KEA service is down and cannot be enabled after down event. to KEA service is down and cannot be enabled after down event
  • Category changed from DHCP Server (IPv4) to DHCP (IPv4)
  • Assignee set to Christian McDonald
  • Target version set to 2.8.0
  • Affected Plus Version deleted (24.11)
  • Plus Target Version set to 24.11
Actions #2

Updated by Jim Pingle about 2 months ago

The error here is the same as #14977 but that build should have the fix in it, unless something else is happening in this specific case.

Does the /var/run/kea4-ctrl-socket.lock file actually still exist on your setup while Kea isn't running? If so, does removing that file allow it to start?

Actions #3

Updated by Marcelo Cury about 2 months ago

The file exists.
[24.11-BETA][]/root: ls lah /var/run/kea4-ctrl-socket.lock
-rw------
1 root wheel 0B Nov 6 02:50 /var/run/kea4-ctrl-socket.lock

Just deleted that file with a simple rm /var/run/kea4-ctrl-socket.lock and the service started normally after, service is green again.

Actions #4

Updated by Christian McDonald about 2 months ago

  • Status changed from New to Duplicate
  • Parent task set to #14977
Actions #5

Updated by Christian McDonald about 2 months ago

  • Subject changed from KEA service is down and cannot be enabled after down event to Kea service is down and cannot be enabled after down event
  • Release Notes changed from Default to Force Exclusion
Actions #6

Updated by Jim Pingle about 2 months ago

  • Target version deleted (2.8.0)
  • Parent task deleted (#14977)
  • Plus Target Version deleted (24.11)
Actions #7

Updated by Jim Pingle about 2 months ago

  • Is duplicate of Bug #14977: Kea fails to restart due to race between process termination and startup added
Actions

Also available in: Atom PDF