No dpinger session running for gateway - for no reason when switching WANs

pfpv · Aug 4, 2022, 5:57 PM

I am on triple-WAN with fail over.
WAN-DHCP - cable modem - Tier 1 [let's call it WAN1]
WAN2_PPPOE - VDSL - Tier 2
WAN3CELL_DHCP - LTE modem in bridge mode - Tier 3

I am on pfSense Plus 22.05, the latest.

Everything seemed to run fine until one day I decided to remove a dumb switch from between the cable modem (the WAN_DHCP) and pfSense. I unplugged Ethernet cables, removed the switch and plugged them back in less than a minute. I expected pfSense to fail over to WAN2_PPOE and it kind of did until I noticed that one of my 5 Dynamic DNS IPs was updated briefly to WAN3CELL_DHCP but then to WAN2_PPPOE. I noticed that only from Pushover messages that I get.

I had a look at the logs and saw pfSense failed over to WAN2, updated the first DynDSN, than showed message

/rc.dyndns.update: dpinger: No dpinger session running for gateway WAN2_PPPOE

for no reason. Switched to WAN3. Updated the second DynDNS. 3 second later switched to WAN2. Re-updated the second DynDNS to WAN2 IP and after that everything went as normal - updated the rest of DynDNS and failed back to WAN1 after I reconnected the cables.

Below is the full log around this unusual event. I think the developers should have a look as it seems there was some kind of a race condition that caused that "No dpinger session running for gateway".

Jul 30 13:53:56 	php-fpm 	48340 	/rc.dyndns.update: phpDynDNS: updating cache file /conf/dyndns_PreferWANcustom'*'1.cache: [WAN2-IP]
Jul 30 13:53:55 	php-fpm 	454 	/rc.dyndns.update: phpDynDNS (*): (Success) IP Address Updated Successfully!
Jul 30 13:53:55 	php-fpm 	454 	/rc.dyndns.update: phpDynDNS: updating cache file /conf/dyndns_PreferWANcustom'*'1.cache: [WAN3-IP]
Jul 30 13:53:55 	php-fpm 	202 	/rc.filter_configure_sync: GW States: Gateway is down but its IP address cannot be located. Skipping state kill.: WAN_DHCP
Jul 30 13:53:54 	php-fpm 	453 	/rc.filter_configure_sync: GW States: Gateway is down but its IP address cannot be located. Skipping state kill.: WAN_DHCP
Jul 30 13:53:53 	php-fpm 	48340 	/rc.dyndns.update: phpDynDNS (*): No change in my IP address and/or 15 days has not passed. Not updating dynamic DNS entry.
Jul 30 13:53:52 	php-fpm 	454 	/rc.dyndns.update: Default gateway setting Interface WAN2_PPPOE Gateway as default.
Jul 30 13:53:52 	php-fpm 	454 	/rc.dyndns.update: Gateway, switch to: WAN2_PPPOE
Jul 30 13:53:52 	php-fpm 	453 	/rc.filter_configure_sync: Default gateway setting Interface WAN2_PPPOE Gateway as default.
Jul 30 13:53:52 	php-fpm 	453 	/rc.filter_configure_sync: Gateway, switch to: WAN2_PPPOE
Jul 30 13:53:51 	check_reload_status 	483 	Reloading filter
Jul 30 13:53:51 	check_reload_status 	483 	Restarting OpenVPN tunnels/interfaces
Jul 30 13:53:51 	check_reload_status 	483 	Restarting IPsec tunnels
Jul 30 13:53:51 	check_reload_status 	483 	updating dyndns WAN_DHCP
Jul 30 13:53:51 	rc.gateway_alarm 	24258 	>>> Gateway alarm: WAN_DHCP (Addr:x.x.x.x Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%)
Jul 30 13:53:49 	php-fpm 	454 	/rc.dyndns.update: Default gateway setting Interface WAN3CELL_DHCP Gateway as default.
Jul 30 13:53:49 	php-fpm 	454 	/rc.dyndns.update: Gateway, switch to: WAN3CELL_DHCP
Jul 30 13:53:49 	check_reload_status 	483 	Reloading filter
Jul 30 13:53:49 	php-fpm 	454 	/rc.dyndns.update: dpinger: No dpinger session running for gateway WAN2_PPPOE
Jul 30 13:53:49 	php-fpm 	202 	/rc.linkup: Removing static route for monitor q.q.q.q and adding a new route through [WAN3-IP]
Jul 30 13:53:49 	php-fpm 	48340 	/rc.filter_configure_sync: GW States: Killing states for down gateway: WAN_DHCP, [WAN1-IP]
Jul 30 13:53:49 	php 	44710 	notify_monitor.php: Message sent to xxx OK
Jul 30 13:53:48 	php-fpm 	454 	/rc.dyndns.update: phpDynDNS (*): (Success) IP Address Updated Successfully!
Jul 30 13:53:48 	php-fpm 	454 	/rc.dyndns.update: phpDynDNS: updating cache file /conf/dyndns_PreferWANcustom'*'0.cache: [WAN2-IP]
Jul 30 13:53:48 	php-fpm 	202 	/rc.linkup: DEVD Ethernet detached event for wan
Jul 30 13:53:47 	php-fpm 	48340 	/rc.filter_configure_sync: Default gateway setting Interface WAN2_PPPOE Gateway as default.
Jul 30 13:53:47 	php-fpm 	454 	/rc.dyndns.update: Default gateway setting Interface WAN2_PPPOE Gateway as default.
Jul 30 13:53:47 	php-fpm 	48340 	/rc.filter_configure_sync: Gateway, switch to: WAN2_PPPOE
Jul 30 13:53:47 	php-fpm 	454 	/rc.dyndns.update: Gateway, switch to: WAN2_PPPOE
Jul 30 13:53:47 	php-fpm 	453 	x.x.x.x|y.y.y.y|WAN_DHCP|24.41ms|6.498ms|21%|down|highloss
Jul 30 13:53:47 	php-fpm 	453 	/rc.openvpn: MONITOR: WAN_DHCP has packet loss, omitting from routing group PreferWAN
Jul 30 13:53:47 	kernel 		igb0: link state changed to DOWN

pfpv · Aug 4, 2022, 11:26 PM

I encountered another issue with dpinger. I changed one unimportant parameter in the WAN interface (CIDR length for the alias IPv4 address). Pressed save and apply and noticed that my IP switched over to the failover WAN2, then back to WAN1. I looked at the logs and found this:

php-fpm 	89297 	/interfaces.php: The command '/usr/local/bin/dpinger -S -r 0 -i WAN_DHCP -B x.x.x.x -p /var/run/dpinger_WAN_DHCP~x.x.x.x~y.y.y.y.pid -u /var/run/dpinger_WAN_DHCP~x.x.x.x~y.y.y.y.sock -C "/etc/rc.gateway_alarm" -d 1 -s 500 -l 2000 -t 30000 -A 1000 -D 500 -L 20 y.y.y.y.>/dev/null' returned exit code '1', the output was ''

It's weird that I saw changes for WAN3 that I haven't touched. I think the developers should have a look at the whole multi-WAN system. More logs:

Aug 4 19:02:27 	php-fpm 	73902 	/rc.filter_configure_sync: Default gateway setting Interface WAN_DHCP Gateway as default.
Aug 4 19:02:27 	php-fpm 	73902 	/rc.filter_configure_sync: Gateway, switch to: WAN_DHCP
Aug 4 19:02:25 	upsmon 	11497 	Startup successful
Aug 4 19:02:25 	php-fpm 	48340 	/rc.start_packages: Starting service nut
Aug 4 19:02:25 	upsmon 	85376 	Signal 15: exiting
Aug 4 19:02:25 	php-fpm 	48340 	/rc.start_packages: Stopping service nut
Aug 4 19:02:25 	php-fpm 	48340 	/rc.start_packages: Restarting/Starting all packages.
Aug 4 19:02:24 	check_reload_status 	483 	Starting packages
Aug 4 19:02:24 	php-fpm 	89297 	/interfaces.php: Creating rrd update script
Aug 4 19:02:24 	check_reload_status 	483 	Reloading filter
Aug 4 19:02:24 	php-fpm 	89297 	/interfaces.php: Removing static route for monitor m.m.m.m and adding a new route through n.n.n.n [this is untouched WAN3]
Aug 4 19:02:24 	php-fpm 	89297 	/interfaces.php: Removing static route for monitor y.y.y.y and adding a new route through x1.x1.x1.x1 [this is WAN1]
Aug 4 19:02:24 	php-fpm 	89297 	/interfaces.php: Resyncing OpenVPN instances for interface WAN.
Aug 4 19:02:23 	php 	77068 	notify_monitor.php: Message sent to X OK
Aug 4 19:02:22 	php-fpm 	202 	/rc.dyndns.update: phpDynDNS (): (Success) IP Address Updated Successfully!
Aug 4 19:02:22 	php-fpm 	202 	/rc.dyndns.update: phpDynDNS: updating cache file /conf/dyndns_PreferWANcustom''0.cache: k.k.k.k  [this is WAN2 IP]
Aug 4 19:02:21 	check_reload_status 	483 	updating dyndns wan
Aug 4 19:02:19 	dhcpleases 	50889 	Could not deliver signal HUP to process 71960: No such process.
Aug 4 19:02:18 	check_reload_status 	483 	Restarting IPsec tunnels
Aug 4 19:02:18 	php-fpm 	775 	/rc.filter_configure_sync: Gateway, switch to: WAN2_PPPOE
Aug 4 19:02:18 	php-fpm 	89297 	/interfaces.php: Default gateway setting Interface WAN2_PPPOE Gateway as default.
Aug 4 19:02:18 	php-fpm 	89297 	/interfaces.php: Gateway, switch to: WAN2_PPPOE
Aug 4 19:02:17 	check_reload_status 	483 	Reloading filter
Aug 4 19:02:17 	php-fpm 	98601 	/rc.newwanip: rc.newwanip: on (IP address: x.x.x.x) (interface: WAN[wan]) (real interface: igb0).
Aug 4 19:02:17 	php-fpm 	98601 	/rc.newwanip: rc.newwanip: Info: starting on igb0.
Aug 4 19:02:16 	check_reload_status 	483 	rc.newwanip starting igb0
Aug 4 19:02:16 	php-fpm 	89297 	/interfaces.php: Error starting gateway monitor for WAN_DHCP
Aug 4 19:02:16 	php-fpm 	89297 	/interfaces.php: The command '/usr/local/bin/dpinger -S -r 0 -i WAN_DHCP -B x.x.x.x -p /var/run/dpinger_WAN_DHCP~x.x.x.x~y.y.y.y.pid -u /var/run/dpinger_WAN_DHCP~x.x.x.x~y.y.y.y.sock -C "/etc/rc.gateway_alarm" -d 1 -s 500 -l 2000 -t 30000 -A 1000 -D 500 -L 20 y.y.y.y.>/dev/null' returned exit code '1', the output was ''
Aug 4 19:02:16 	php-fpm 	89297 	/interfaces.php: Removing static route for monitor m.m.m.m and adding a new route through n.n.n.n  [this is really weird - this is untouched WAN3]