25.07.r.20250709.2036 First Boot WireGuard Service not running

Bob.Dig

@stephenw10 Nothing at boot and nothing that pops into my eyes but I am not versed with the logs in general.

Some stuff:

Jul 20 17:30:38 	vnstatd 	44706 	Interface "hn2.110" disabled.
Jul 20 17:30:38 	vnstatd 	44706 	Interface "hn2.111" disabled.
Jul 20 17:30:38 	vnstatd 	44706 	Interface "hn2.185" disabled.
Jul 20 17:30:38 	vnstatd 	44706 	Interface "hn2.35" disabled.
Jul 20 17:30:38 	vnstatd 	44706 	Interface "tun_wg7" disabled.

These interfaces don't exist anymore, still they are in the logs, why.

Other stuff I picked...

Jul 20 17:30:38 	vnstatd 	50564 	Error: pidfile "/var/run/vnstat/vnstat.pid" lock failed (Resource temporarily unavailable), exiting. 
Jul 20 17:30:27 	kernel 		wg5: changing name to 'tun_wg0'
Jul 20 17:30:27 	kernel 		tun_wg6: link state changed to UP
Jul 20 17:30:27 	kernel 		wg4: changing name to 'tun_wg6'
Jul 20 17:30:27 	kernel 		tun_wg5: link state changed to UP 
Jul 20 17:29:48 	php-fpm 	38554 	/diag_reboot.php: The command '/usr/local/etc/rc.d/wireguardd stop' returned exit code '1', the output was 'umount: /var/unbound/dev: not a file system root directory'

Interestingly same problem at next reboot. While I was going through the logs, I restarted WG in Service Status and it came up, happy about that.

Bob.Dig

@Bob-Dig said in 25.07.r.20250709.2036 First Boot WireGuard Service not running:

not only was the WireGuard Service down again, also none of the tunnels were up...

Correction: None of the gateways corresponding to the tunnels were up. Before, only one gateway wasn't up, now no gateway was up. Have to check with the tunnels next time, if they are partially up or not.

Bob.Dig

@stephenw10 The problem is persistent. On every boot the WireGuard service is disabled and all corresponding gateways are disabled too.
All the WireGuard tunnels are up. If I enable the gateways by hand and then restart WireGuard, it is running fine. At least this is a solution that works.

stephenw10

@Bob-Dig said in 25.07.r.20250709.2036 First Boot WireGuard Service not running:

These interfaces don't exist anymore, still they are in the logs, why.

They probably still exist in the configuration file for one of the traffic monitoring packages, traffic totals maybe? Resaving that with existing interfaces should remove those lines but I doubt they are causing this.

That error stopping wireguard looks to have come from the reboot script. I assume that was after you manually rebooted but before the actual reboot?

@Bob-Dig said in 25.07.r.20250709.2036 First Boot WireGuard Service not running:

If I enable the gateways by hand and then restart WireGuard, it is running fine. At least this is a solution that works.

The wiregaurd tunnel gateways? Or the WAN gateways?
I wouldn't expect the WG gateways to be available if the wireguard service is stopped. Conversely I expect them to become available when it starts and I assume that isn't happening if you have to manually start them.

Bob.Dig

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

I wouldn't expect the WG gateways to be available if the wireguard service is stopped. Conversely I expect them to become available when it starts and I assume that isn't happening if you have to manually start them.

Yep. Although before on stable (and not recreating the first tunnel), it was sometimes the case, that the Service was stopped but almost all tunnels and their gateways where up.

Bob.Dig

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

hat error stopping wireguard looks to have come from the reboot script. I assume that was after you manually rebooted but before the actual reboot?

Probably, because when I "halted" the system and later rebooted, it wasn't there at all.

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?