dpinger stops (crashes?) after update to 2.6.0

stephenw10 · Feb 18, 2022, 3:36 PM

Hmm, those logs are both dpinger starting. There are no errors on the system log in between those showing why it stopped?

Klaus2314 · Feb 18, 2022, 3:47 PM

@stephenw10 only this
login-to-view

(this was just weh it happened the next time)

login-to-view

Needless to say during that event Internet didn't go down for me.

stephenw10 · Feb 18, 2022, 4:56 PM

Hmm, none of that is an error. It just stops silently....

Is that with 'Gateway Monitoring Action' disabled? I wonder if it's trying to do something and failing.

Klaus2314 · Feb 18, 2022, 5:04 PM

@stephenw10 login-to-view

Klaus2314 · Feb 18, 2022, 5:30 PM

Just to see what happens I have now set the monitor address to the Fibre modem (the actual gateway) instead of Quad9.

stephenw10 · Feb 18, 2022, 5:55 PM

Ok, that's a reasonable test.

If you only have one WAN disabling the monitoring action is also a good test.

Klaus2314 · Feb 21, 2022, 11:44 AM

Ok, so after a couple of days I can see that dpinger stops (and is restarted by watchdog) right after pfblocker has updated at 3AM which also leads to a restart of unbound. So somehow dpinger doesn't seem to like that and decides to stop.
All the same cron settings since before the update to 2.6.0 though.
Interestingly it doesn't happen at all on my second installation (21.6) SG1100 also running pfblocker. For some reason on that system dpinger keeps on trucking.

stephenw10 · Feb 22, 2022, 1:24 AM

Do you have DNS-BL runing on both? That's what would restart Unbound.

No idea why restarting Unbound would cause an issue for dpinger though.

Klaus2314 · Feb 23, 2022, 9:57 AM

@stephenw10 Yes more or less same setup on both appliances. No crashes on the SG1100.
Another thing. It seems like the notification page does not store the email password so I am not getting any notifications anymore. When I paste the password again and trigger a test email it will go through. However after hitting save and coming back to that page the PW has been lost.
This also has worked just fine before the update. And: The latter also only happens on the 2.6.0 installation, not on the SG1100.
After sending the test email I can see the PW field on that settings page fall back to some old PW it has stored by the amount of dots in that field. When I hit send test email again it fails because of wrong PW. So it just doesn't seem to store that setting.

Klaus2314 · Feb 23, 2022, 10:48 AM

Ok sorry, the email thing was user error. It's a bit confusing. The email pw gets used AFTER saving. So that works now. And 5 minutes later I get a message that dpinger has been relaunched by watchdog.

stephenw10 · Feb 23, 2022, 2:27 PM

Hmm, well anything logged to show why Unbound stops? In the system or resolver logs?

NollipfSense · Feb 23, 2022, 3:10 PM

I get the same exact behavior mostly night at 16minutes pass midnight dpinger stops and sometimes at 5minutes pass midnight and on rare occasion during it stops. Most of the time now the error is sento 50, sometimes there are latency alarm and clear latency. I added this to the system turnable: kern.ipc.maxsockbuf Maximum socket buffer size 1000000
That seems to take of the sento error 65.

Klaus2314 · Feb 25, 2022, 10:04 PM

@stephenw10 So I tried to reproduce the dpinger thing and simply pulled the cable going to the WAN port of pfsense (instead of waiting for the next time the connect goes down) and put it back in. A second later I receive a notification email that dpinger was relaunched by watch dog. I did it 3-4 times again. Dpinger stops every single time.

This was with Gateway Monitoring Action turned off, btw.

On the same ticket I found that the patch cable going into pfsense has a bad connection when moved so the ping dropping out might have been caused by the cable being just on the edge of failing and then reconnecting.

However this doesn't explain why dpinger decides to stop doing it's thing when that happens. And this definitely didn't happen before the upgrade.

Hm...

stephenw10 · Feb 25, 2022, 10:18 PM

Mmm, I would expect dpinger to stop if the WAN loses link and that's the only gateway. But it should start again when you reconnect it. Without needing the watchdog package.

Steve

Klaus2314 · Feb 25, 2022, 10:24 PM

@stephenw10 Right, that makes sense. So maybe that's a new bug then? The fact that dpinger doesn't come back to life after a disconnect? (unlike the previous version of pfsense I mean)

stephenw10 · Feb 26, 2022, 7:00 AM

Mmm, it could be. It feels like a timing issue. Not sure what might have changed there though.

I expect to see something logged with it trying to start and failing....

NollipfSense · Feb 26, 2022, 7:02 AM

@stephenw10 said in dpinger stops (crashes?) after update to 2.6.0:

I expect to see something logged with it trying to start and failing

Since upgrading to 2.6RC, every night at 16 pass midnight I get error 50 that causes Dpinger to stop...when it stops it was contacting the ISP's DHCP server...here is from earlier:

login-to-view

stephenw10 · Feb 26, 2022, 2:14 PM

You are probably hitting this: https://redmine.pfsense.org/issues/12827
Try the suggested temporary workaround there.

Steve

reberhar · Feb 26, 2022, 2:15 PM

I lose dpinger after suricata updates. I can even uninstall and install, or reinstall suricata and dpinger goes off. It seems to have something to do with suricata resetting the wan port. I am running suricata in legacy mode, but even with blocking turned off it happens. Every morning early I restart dpinger on 3 of my sites. One site has 4 heads. It seems to fail on only one of them.

The gateway logs are often not helpful. There are lots of these, but they happen during the day as well and I do not lose dpinger when they happen.

Feb 19 00:32:43 dpinger 89107 WAN_DHCP 192.168.0.1: sendto error: 65

The general logs show quite a lot of manipulating of the wan port. I am assuming that dpinger lose its target during these few minutes.

Feb 26 00:36:04 check_reload_status 2729 Reloading filter
Feb 26 00:35:38 check_reload_status 2729 updating dyndns wan
Feb 26 00:35:24 php-fpm 35378 /rc.newwanip: rc.newwanip: on (IP address: 10.0.0.1) (interface: LAN[lan]) (real interface: igb1).
Feb 26 00:35:24 php-fpm 35378 /rc.newwanip: rc.newwanip: Info: starting on igb1.
Feb 26 00:35:23 check_reload_status 2729 rc.newwanip starting igb1
Feb 26 00:35:23 php-fpm 35378 /rc.linkup: Hotplug event detected for LAN(lan) static IP (10.0.0.1 )
Feb 26 00:35:22 kernel igb1: link state changed to UP
Feb 26 00:35:22 check_reload_status 2729 Linkup starting igb1
Feb 26 00:35:19 check_reload_status 2729 Reloading filter
Feb 26 00:35:19 kernel igb1: promiscuous mode enabled
Feb 26 00:35:19 php-fpm 35378 /rc.linkup: Hotplug event detected for LAN(lan) static IP (10.0.0.1 )
Feb 26 00:35:18 kernel igb1: link state changed to DOWN
Feb 26 00:35:18 check_reload_status 2729 Linkup starting igb1
Feb 26 00:35:07 check_reload_status 2729 Reloading filter
Feb 26 00:35:07 php-fpm 35378 /rc.newwanip: rc.newwanip: on (IP address: 192.168.0.3) (interface: WAN[wan]) (real interface: igb0).
Feb 26 00:35:07 php-fpm 35378 /rc.newwanip: rc.newwanip: Info: starting on igb0.
Feb 26 00:35:06 check_reload_status 2729 Restarting IPsec tunnels
Feb 26 00:35:06 check_reload_status 2729 rc.newwanip starting igb0
Feb 26 00:35:05 check_reload_status 2729 Reloading filter
Feb 26 00:35:05 php-fpm 51175 /rc.linkup: HOTPLUG: Configuring interface wan
Feb 26 00:35:05 php-fpm 51175 /rc.linkup: DEVD Ethernet attached event for wan
Feb 26 00:35:04 php-fpm 86088 /rc.linkup: DEVD Ethernet detached event for wan
Feb 26 00:35:04 check_reload_status 2729 Reloading filter
Feb 26 00:34:34 check_reload_status 2729 updating dyndns wan
Feb 26 00:34:20 check_reload_status 2729 Reloading filter
Feb 26 00:34:20 php-fpm 20850 /rc.newwanip: rc.newwanip: on (IP address: 192.168.0.3) (interface: WAN[wan]) (real interface: igb0).
Feb 26 00:34:20 php-fpm 20850 /rc.newwanip: rc.newwanip: Info: starting on igb0.
Feb 26 00:34:19 check_reload_status 2729 Restarting IPsec tunnels
Feb 26 00:34:19 check_reload_status 2729 rc.newwanip starting igb0
Feb 26 00:34:18 kernel igb0: link state changed to UP
Feb 26 00:34:18 check_reload_status 2729 Linkup starting igb0
Feb 26 00:34:14 kernel igb0: link state changed to DOWN
Feb 26 00:34:14 check_reload_status 2729 Linkup starting igb0
Feb 26 00:34:14 php-fpm 43501 /rc.linkup: HOTPLUG: Configuring interface wan
Feb 26 00:34:14 php-fpm 43501 /rc.linkup: DEVD Ethernet attached event for wan
Feb 26 00:34:13 kernel igb0: link state changed to UP
Feb 26 00:34:13 check_reload_status 2729 Linkup starting igb0
Feb 26 00:34:12 check_reload_status 2729 Reloading filter
Feb 26 00:34:11 php-fpm 55570 /rc.linkup: DEVD Ethernet detached event for wan
Feb 26 00:34:10 kernel igb0: promiscuous mode enabled
Feb 26 00:34:10 check_reload_status 2729 Linkup starting igb0
Feb 26 00:34:10 kernel igb0: link state changed to DOWN
Feb 26 00:31:21 php 26894 [Suricata] The Rules update has finished.
Feb 26 00:31:21 php 26894 [Suricata] Suricata has restarted with your new set of rules for LAN...
Feb 26 00:31:21 php 26894 [Suricata] Suricata START for LAN(igb1)...
Feb 26 00:31:14 check_reload_status 2729 Reloading filter
Feb 26 00:31:14 php-fpm 35378 /rc.newwanip: rc.newwanip: on (IP address: 10.0.0.1) (interface: LAN[lan]) (real interface: igb1).
Feb 26 00:31:14 php-fpm 35378 /rc.newwanip: rc.newwanip: Info: starting on igb1.
Feb 26 00:31:13 check_reload_status 2729 Reloading filter
Feb 26 00:31:13 check_reload_status 2729 rc.newwanip starting igb1
Feb 26 00:31:13 php-fpm 35378 /rc.linkup: Hotplug event detected for LAN(lan) static IP (10.0.0.1 )
Feb 26 00:31:12 kernel igb1: link state changed to UP
Feb 26 00:31:12 check_reload_status 2729 Linkup starting igb1
Feb 26 00:31:10 check_reload_status 2729 Reloading filter
Feb 26 00:31:10 php-fpm 19761 /rc.linkup: Hotplug event detected for LAN(lan) static IP (10.0.0.1 )
Feb 26 00:31:09 kernel igb1: promiscuous mode disabled
Feb 26 00:31:09 kernel igb1: link state changed to DOWN
Feb 26 00:31:09 check_reload_status 2729 Linkup starting igb1
Feb 26 00:31:06 php 26894 [Suricata] Suricata STOP for LAN(igb1)...
Feb 26 00:31:04 php 26894 [Suricata] Building new sid-msg.map file for LAN...
Feb 26 00:31:04 php 26894 [Suricata] Enabling any flowbit-required rules for: LAN...
Feb 26 00:31:02 php 26894 [Suricata] Updating rules configuration for: LAN ...
Feb 26 00:31:02 php 26894 [Suricata] Suricata has restarted with your new set of rules for WAN...
Feb 26 00:31:02 php 26894 [Suricata] Suricata START for WAN(igb0)...
Feb 26 00:30:49 kernel igb0: promiscuous mode disabled
Feb 26 00:30:47 php 26894 [Suricata] Suricata STOP for WAN(igb0)...
Feb 26 00:30:45 php 26894 [Suricata] Building new sid-msg.map file for WAN...
Feb 26 00:30:45 php 26894 [Suricata] Enabling any flowbit-required rules for: WAN...
Feb 26 00:30:42 php 26894 [Suricata] Updating rules configuration for: WAN ...
Feb 26 00:30:40 php 26894 [Suricata] Snort GPLv2 Community Rules file update downloaded successfully.
Feb 26 00:30:39 php 26894 [Suricata] There is a new set of Snort GPLv2 Community Rules posted. Downloading community-rules.tar.gz...
Feb 26 00:30:38 php 26894 [Suricata] Emerging Threats Open rules file update downloaded successfully.
Feb 26 00:30:36 php 26894 [Suricata] There is a new set of Emerging Threats Open rules posted. Downloading emerging.rules.tar.gz...
Feb 26 00:24:00 sshguard 51492 Now monitoring attacks.
Feb 26 00:24:00 sshguard 46998 Exiting on signal.

stephenw10 · Feb 26, 2022, 2:19 PM

@reberhar said in dpinger stops (crashes?) after update to 2.6.0:

Feb 26 00:35:24 php-fpm 35378 /rc.newwanip: rc.newwanip: on (IP address: 10.0.0.1) (interface: LAN[lan]) (real interface: igb1).
Feb 26 00:35:24 php-fpm 35378 /rc.newwanip: rc.newwanip: Info: starting on igb1.
Feb 26 00:35:23 check_reload_status 2729 rc.newwanip starting igb1

Your LAN is also losing link and it's triggering the newwanip script which should not happen unless it incorrectly has a gateway defined on it. Unless it's actually a second WAN.

Steve