25.07.r.20250709.2036 First Boot WireGuard Service not running

Bob.Dig

@stephenw10 said in 25.07.r.20250709.2036 First Boot WireGuard Service not running:

No errors shown?

Ok, used the Log Filter function the first time in my life.

Jul 21 09:37:46 	vnstatd 	49296 	Error: pidfile "/var/run/vnstat/vnstat.pid" lock failed (Resource temporarily unavailable), exiting.
Jul 21 09:37:26 	php-cgi 	709 	rc.bootup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1753083446] unbound[58124:0] error: bind: address already in use [1753083446] unbound[58124:0] fatal error: could not open ports'
Jul 21 09:37:16 	kernel 		module_register_init: MOD_LOAD (iwi_monitor_fw, 0xffffffff8077ff30, 0) error 1
Jul 21 09:37:16 	kernel 		module_register_init: MOD_LOAD (iwi_ibss_fw, 0xffffffff8077fe80, 0) error 1
Jul 21 09:37:16 	kernel 		module_register_init: MOD_LOAD (iwi_bss_fw, 0xffffffff8077fdd0, 0) error 1
Jul 21 09:37:16 	kernel 		module_register_init: MOD_LOAD (ipw_monitor_fw, 0xffffffff80760760, 0) error 1
Jul 21 09:37:16 	kernel 		module_register_init: MOD_LOAD (ipw_ibss_fw, 0xffffffff807606b0, 0) error 1
Jul 21 09:37:16 	kernel 		module_register_init: MOD_LOAD (ipw_bss_fw, 0xffffffff80760600, 0) error 1
Jul 21 09:34:32 	nginx 		2025/07/21 09:34:32 [error] 73048#100275: send() failed (54: Connection reset by peer) while logging to syslog, server: unix:/var/run/log


Jul 21 09:53:20 	php_wg 	12725 	/usr/local/pkg/wireguard/includes/wg_service.inc: The command '/usr/local/bin/dpinger -S -r 0 -i VPNcWgNtcpGW -B 10.3.9.26 -p /var/run/dpinger_VPNcWgNtcpGW~10.3.9.26~10.3.9.25.pid -u /var/run/dpinger_VPNcWgNtcpGW~10.3.9.26~10.3.9.25.sock -C "/etc/rc.gateway_alarm" -d 1 -s 500 -l 2000 -t 60000 -A 1000 -D 500 -L 20 10.3.9.25 >/dev/null' returned exit code '1', the output was ''
Jul 21 09:53:20 	php_wg 	12725 	/usr/local/pkg/wireguard/includes/wg_service.inc: The command '/usr/local/bin/dpinger -S -r 0 -i VPNcOciOPNGW -B 10.3.9.13 -p /var/run/dpinger_VPNcOciOPNGW~10.3.9.13~10.3.9.14.pid -u /var/run/dpinger_VPNcOciOPNGW~10.3.9.13~10.3.9.14.sock -C "/etc/rc.gateway_alarm" -d 1 -s 500 -l 2000 -t 60000 -A 1000 -D 500 -L 20 10.3.9.14 >/dev/null' returned exit code '1', the output was ''
Jul 21 09:53:20 	php_wg 	12725 	/usr/local/pkg/wireguard/includes/wg_service.inc: The command '/usr/local/bin/dpinger -S -r 0 -i VPNcOciPFGW -B 10.3.9.9 -p /var/run/dpinger_VPNcOciPFGW~10.3.9.9~10.3.9.10.pid -u /var/run/dpinger_VPNcOciPFGW~10.3.9.9~10.3.9.10.sock -C "/etc/rc.gateway_alarm" -d 1 -s 500 -l 2000 -t 60000 -A 1000 -D 500 -L 20 10.3.9.10 >/dev/null' returned exit code '1', the output was ''
Jul 21 09:48:24 	php-cgi 	709 	rc.bootup: The command '/usr/local/sbin/strongswanrc stop' returned exit code '1', the output was 'strongswan not running? (check /var/run/daemon-charon.pid).'
Jul 21 09:48:17 	php-fpm 	589 	/rc.newwanip: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1753084097] unbound[46889:0] error: bind: address already in use [1753084097] unbound[46889:0] fatal error: could not open ports'

stephenw10

Hmm, most of those errors are common and harmless.

But those dpinger failures are interesting. Do those IPs exist in the routing table?

When you say you have to enable the gateways by hand what exactly are you doing?

Bob.Dig

@stephenw10 said in 25.07.r.20250709.2036 First Boot WireGuard Service not running:

But those dpinger failures are interesting. Do those IPs exist in the routing table?

Not exactly sure what you mean.

10.3.9.0/29	link#16	U	1	1420	tun_wg3	
10.3.9.1	link#2	UHS	6	16384	lo0	
10.3.9.8/30	link#17	U	7	1420	tun_wg4	
10.3.9.9	link#2	UHS	17	16384	lo0	
10.3.9.12/30	link#18	U	23	1420	tun_wg5	
10.3.9.13	link#2	UHS	27	16384	lo0	
10.3.9.24/29	link#20	U	31	1420	tun_wg0	
10.3.9.26	link#2	UHS	55	16384	lo0	
10.3.12.0/24	link#19	U	60	1280	tun_wg6	
10.3.12.1	link#2	UHS	41	16384	lo0	
10.3.13.0/24	link#27	U	5	1500	hn0.2	
10.3.13.1	link#2	UHS	26	16384	lo0	
10.3.178.0/24	link#8	U	37	1500	hn3	
10.3.178.2	link#2	UHS	57	16384	lo0

@stephenw10 said in 25.07.r.20250709.2036 First Boot WireGuard Service not running:

When you say you have to enable the gateways by hand what exactly are you doing?

Mostly this (klicking it):
Screenshot 2025-07-21 141228.png
But this is only an example, because every WireGuard running through OpenWRT-VMs is doing fine, only WireGuard running on pfSense itself makes problems.

Right now, when I went there, I saw one gateway was down again and WG was stopped. This is new behavior to me. Interestingly it was that tunnel again, which I had recreated (the last Gateway in the picture).

The other end is a WireGuard installation done by me inside of Debian (Proxmox VE). I disabled and re-enabled the gateway (instead of just enabling it, because it was already enabled by me after the boot, where it was disabled like all the others) and I restarted WireGuard, up again and running. This is odd and problematic. "Fixing" it after a reboot is one thing but having it going down while in use is another...

Bob.Dig

@stephenw10 Here is the config of the most problematic WG-Interface, just in case.

Bob.Dig

@stephenw10 Sidenote, I noticed that Lawrence Systems would do it differently, making the gateway address the same as the interface address but I don't think that this is mandatory and the Configuration Recipe doesn't show that either.

stephenw10

Yup I meant if the tunnel subnets did not exist then dpinger would be expected to fail. They are there in that output but is that after rebooting when WG fails to start?

It feels like it could be a timing/ordering issue where dpinger tries to start before the WG config has been applied creating the routes. But if so that should be evident in the log order.

Bob.Dig

@stephenw10 said in 25.07.r.20250709.2036 First Boot WireGuard Service not running:

They are there in that output but is that after rebooting when WG fails to start?

Here is right after a reboot with WG down, again.

10.3.9.0/29	link#16	U	7	1420	tun_wg3	
10.3.9.1	link#2	UHS	8	16384	lo0	
10.3.9.8/30	link#17	U	30	1420	tun_wg4	
10.3.9.9	link#2	UHS	34	16384	lo0	
10.3.9.12/30	link#18	U	53	1420	tun_wg5	
10.3.9.13	link#2	UHS	54	16384	lo0	
10.3.9.24/29	link#20	U	58	1420	tun_wg0	
10.3.9.26	link#2	UHS	60	16384	lo0	
10.3.12.0/24	link#19	U	55	1280	tun_wg6	
10.3.12.1	link#2	UHS	56	16384	lo0	
10.3.13.0/24	link#27	U	20	1500	hn0.2	
10.3.13.1	link#2	UHS	25	16384	lo0	
10.3.178.0/24	link#8	U	9	1500	hn3	
10.3.178.2	link#2	UHS	10	16384	lo0

With every reboot I will get a new IPv6 and often IPv4 thanks to PPPoE and my ISP...

stephenw10

Hmm, so can you see in the logs that dpinger is failing to start during that reboot? And can you see if that's before WG tries to start?

Bob.Dig

@stephenw10 Hope this helps...

System LogsSystemGeneral.txt

stephenw10

Do you have kern.cam.boot_delay=10000 in /boot/loader.conf?

I note it is removed from some hosts and could be relevant here.

Bob.Dig

@stephenw10 said in 25.07.r.20250709.2036 First Boot WireGuard Service not running:

Do you have kern.cam.boot_delay=10000 in /boot/loader.conf?

Don't think so, changed nothing myself I would say.

opensolaris_load="YES"
zfs_load="YES"
kern.geom.label.disk_ident.enable="0"
kern.geom.label.gptid.enable="0"
kern.ipc.nmbclusters="1000000"
kern.ipc.nmbjumbo9="524288"
kern.ipc.nmbjumbop="524288"
loader_conf_files="/boot/loader.conf.lua"
boot_serial="NO"
autoboot_delay="3"
debug.ddb.capture.bufsize="524288"
hw.e6000sw.default_disabled=1
net.link.ifqmaxlen="128"
machdep.hwpstate_pkg_ctrl="1"
net.pf.states_hashsize="262144"

if _ENV["smbios.system.maker"] == "Netgate" then
	if _ENV["smbios.system.product"] == "4100" or _ENV["smbios.system.product"] == "6100" or _ENV["smbios.system.product"] == "6200" or _ENV["smbios.system.product"] == "8200" then
		print("Netgate Cordoba System detected.")
		_ENV["console"]="efi"
		_ENV["hint.cordbuc.0.at"]="isa"
		_ENV["hint.cordbuc.0.port"]="0x800"

		_ENV["hint.gpioled.0.at"]="gpiobus0"
		_ENV["hint.gpioled.0.pins"]="0x001"
		_ENV["hint.gpioled.0.name"]="red1"
		_ENV["hint.gpioled.0.invert"]="1"

		_ENV["hint.gpioled.1.at"]="gpiobus0"
		_ENV["hint.gpioled.1.pins"]="0x002"
		_ENV["hint.gpioled.1.name"]="green1"
		_ENV["hint.gpioled.1.invert"]="1"

		_ENV["hint.gpioled.2.at"]="gpiobus0"
		_ENV["hint.gpioled.2.pins"]="0x004"
		_ENV["hint.gpioled.2.name"]="blue1"
		_ENV["hint.gpioled.2.invert"]="1"

		_ENV["hint.gpioled.3.at"]="gpiobus0"
		_ENV["hint.gpioled.3.pins"]="0x008"
		_ENV["hint.gpioled.3.name"]="amber1"
		_ENV["hint.gpioled.3.invert"]="1"

		_ENV["hint.gpioled.4.at"]="gpiobus0"
		_ENV["hint.gpioled.4.pins"]="0x010"
		_ENV["hint.gpioled.4.name"]="red2"
		_ENV["hint.gpioled.4.invert"]="1"

		_ENV["hint.gpioled.5.at"]="gpiobus0"
		_ENV["hint.gpioled.5.pins"]="0x020"
		_ENV["hint.gpioled.5.name"]="green2"
		_ENV["hint.gpioled.5.invert"]="1"

		_ENV["hint.gpioled.6.at"]="gpiobus0"
		_ENV["hint.gpioled.6.pins"]="0x040"
		_ENV["hint.gpioled.6.name"]="blue2"
		_ENV["hint.gpioled.6.invert"]="1"

		_ENV["hint.gpioled.7.at"]="gpiobus0"
		_ENV["hint.gpioled.7.pins"]="0x080"
		_ENV["hint.gpioled.7.name"]="amber2"
		_ENV["hint.gpioled.7.invert"]="1"

		_ENV["hint.gpioled.8.at"]="gpiobus0"
		_ENV["hint.gpioled.8.pins"]="0x100"
		_ENV["hint.gpioled.8.name"]="red3"
		_ENV["hint.gpioled.8.invert"]="1"

		_ENV["hint.gpioled.9.at"]="gpiobus0"
		_ENV["hint.gpioled.9.pins"]="0x200"
		_ENV["hint.gpioled.9.name"]="green3"
		_ENV["hint.gpioled.9.invert"]="1"

		_ENV["hint.gpioled.10.at"]="gpiobus0"
		_ENV["hint.gpioled.10.pins"]="0x400"
		_ENV["hint.gpioled.10.name"]="blue3"
		_ENV["hint.gpioled.10.invert"]="1"

		_ENV["hint.gpioled.11.at"]="gpiobus0"
		_ENV["hint.gpioled.11.pins"]="0x800"
		_ENV["hint.gpioled.11.name"]="amber3"
		_ENV["hint.gpioled.11.invert"]="1"
	end
	if _ENV["smbios.system.product"] == "4200" then
		print("Netgate 4200 detected.")
		_ENV["console"]="efi"
		_ENV["hw.uart.console"]="mm:0xfe03e000"
		_ENV["dev.igc.0.iflib.override_nrxqs"]="1";
		_ENV["dev.igc.1.iflib.override_nrxqs"]="1";
		_ENV["dev.igc.2.iflib.override_nrxqs"]="1";
		_ENV["dev.igc.3.iflib.override_nrxqs"]="1";
	end
	if _ENV["smbios.system.product"] == "8300" then
		print("Netgate 8300 detected.")
		_ENV["ice_ddp_load"]="yes"
		_ENV["led_8300_load"]="yes"
		_ENV["igpio_load"]="yes"
		_ENV["kern.crypto.iimb.max_threads"]="12"
	end
end

if string.sub(_ENV["smbios.planar.product"], 1, 11) == "80300-0134-" then
	print("Netgate 7100 detected.")
	_ENV["boot_serial"]="YES"
	_ENV["console"]="comconsole"
	_ENV["hint.mdio.0.at"]="ix2"
	_ENV["hint.e6000sw.0.addr"]="0"
	_ENV["hint.e6000sw.0.is8190"]="1"
	_ENV["hint.e6000sw.0.port0disabled"]="1"
	_ENV["hint.e6000sw.0.port9cpu"]="1"
	_ENV["hint.e6000sw.0.port10cpu"]="1"
	_ENV["hint.e6000sw.0.port9speed"]="2500"
	_ENV["hint.e6000sw.0.port10speed"]="2500"
end

if _ENV["smbios.system.product"] == "DFFv2" or _ENV["smbios.system.product"] == "RCC" or _ENV["smbios.system.product"] == "RCC-VE" then
	print("Netgate RCC detected.")
	_ENV["boot_serial"]="YES"
	_ENV["console"]="comconsole"
	_ENV["comconsole_port"]="0x2F8"
	_ENV["hint.uart.0.at"]="isa"
	_ENV["hint.uart.0.flags"]="0x00"
	_ENV["hint.uart.1.at"]="isa"
	_ENV["hint.uart.1.flags"]="0x10"
end

comconsole_speed="115200"

stephenw10

Hmm, try adding it there or to loader.conf.local and see if that changes anything at boot.

Bob.Dig

@stephenw10 said in 25.07.r.20250709.2036 First Boot WireGuard Service not running:

or to loader.conf.local and see if that changes anything at boot.

WG-problem still there. Or did you mean something different?

stephenw10

Nope that's what I meant, the delay at boot could have impacted a race condition at boot.

Looking at that boot log there is a lot of stuff happening during boot. Some of that might be better suppressed but that can cause other issues.

What was the last version that booted correctly?

Bob.Dig

@stephenw10 said in 25.07.r.20250709.2036 First Boot WireGuard Service not running:

What was the last version that booted correctly?

It looks like 25.07.r.20250715.1733 is most problematic with every reboot.
25.07.r.20250709.2036 only had this problem on the first boot after the upgrade.

I just booted through all the snapshots to verify this. Although my network is evolving all the time, but it looks like 25.07.r.20250715.1733 is the reason.

stephenw10

Hmm, OK those dpinger error logs above are not in the given systen log txt. I assume those do appear in the system log? But not at boot?

Bob.Dig

@stephenw10 I can wait 20 minutes and post again if this helps. Can I upload to another place than the public forum? And I guess I should post the logfile and not copying stuff from the browser.

stephenw10

Yup you can upload here: https://nc.netgate.com/nextcloud/s/rLWRrGHTF6MoNaW

Bob.Dig

@stephenw10 This dpinger stuff is only in the log after I "enabled" the gateways by hand.
This time, I had halted pfSense before, kea-dhcp4 wasn't running according to service status widget.

stephenw10

Hmm, so in that log after 'Bootup complete' none of the WG tunnels or gateways were up?