pfSense 2.6.0 Fails to Recover after WAN Issues
-
@guardian This thread maybe relevant https://forum.netgate.com/topic/169614/wan-does-not-renew-after-reboot
-
So you could see dpinger wasn't running? No monitoring pings in the states or packet capture?
The first thing I would do here is disable whatever is generating these logs:
Feb 7 03:44:00 guardian root[75739]: ~~~~~ 23/02/07-03:44:00-WAN is down-DNS restart not attempted. Feb 7 03:45:00 guardian root[39499]: ***** 23/02/07-03:45:00-WAN is down-VPN restart not attempted.You see to have far more things happening there than I would expect for a simple link bounce.
The logs show the last actual link event here when the WAN came back up:Feb 7 03:15:38 pfsense kernel: em0: link state changed to UPBut the linkup scripts are still running ~30min later. Something there is getting stuck or looping.
That custom script has to be the first suspect.Steve
-
@stephenw10 said in pfSense 2.6.0 Fails to Recover after WAN Issues:
So you could see dpinger wasn't running? No monitoring pings in the states or packet capture?
The first thing I would do here is disable whatever is generating these logs:
Feb 7 03:44:00 guardian root[75739]: ~~~~~ 23/02/07-03:44:00-WAN is down-DNS restart not attempted. Feb 7 03:45:00 guardian root[39499]: ***** 23/02/07-03:45:00-WAN is down-VPN restart not attempted.You see to have far more things happening there than I would expect for a simple link bounce.
The logs show the last actual link event here when the WAN came back up:Feb 7 03:15:38 pfsense kernel: em0: link state changed to UPBut the linkup scripts are still running ~30min later. Something there is getting stuck or looping.
That custom script has to be the first suspect.Thanks Steve ( @stephenw10 ) I've had a similar issue for a long time, that DNS and/or VPN would go offline. These watchdog
scripts have been working for several years, and in this case they have not done anything (whenever they do something they emit a log message). Your suggestion has prompted me to modify the cron times slightly just in case the both of them are interfering with each other. The current cron is */5 * * * * for the DNS, and OpenVPN restart. I've changed the OpenVPN to 1,6,11,16,21,26,31,36,41,51,56 * * * * so that gives unbound a minute to restart before trying to restart OpenVPN.Both scripts rely on a call to pfSsh.php playback gatewaystatus and the output is parsed for the status of OpenVPN gateway or the WAN as required.
# Name Monitor Source Delay StdDev Loss Status Substatus # UDP_TOS_VPNV4 8.8.4.4 xx.xx.xxx.xx 54.926ms 11.309ms 0.0% online none # WAN_DHCP 8.8.8.8 xx.xxx.xxx.xxx 16.37ms 2.843ms 0.0% online noneIf the WAN is not showing as online then both scripts do nothing.
The DNS restart script does a dig on cloudflare.com, and if the search fails, it does a
/usr/local/sbin/pfSsh.php playback svc restart unboundcommand to restart unbound.
The OpenVPN script checks the gateway status, and if the VPN shows as down it then checks if the WAN is UP before it attempts to restart the OpenVPN. So if dpinger is out, then both my watchdogs are useless and turn into NOPs.
I think there is something that is killing dpinger, or there is some sort of issue with the port/network stack.
Thoughts/Comments?
-
So to be clear you are actually seeing dpinger not running?
Like no outbound state and/or no pings in a pcap?
It looks like some race condition you're hitting where the link flapping causes numerous restarts and when dpinger tries to restart the link is down again so it fails out.
When you're in that state if you just start dpinger from Status > Services does it start normally?
-
@guardian said in pfSense 2.6.0 Fails to Recover after WAN Issues:
I am running pfSese 2.6.0 Community edition, and for the most part it has been very stable with the exception of a random issue that occurs from time to time when there are issues with my cable internet provider (Rogers in Canada).
I am also running a VPN client with policy routing that routes traffic from some machines though a VPN.
Over the last couple of days there have been short problems on the WAN, but for some reason the VPN doesn't recover.
When I log in to the webgui (which takes a very long time to respond), the dpinger widget shows both the WAN and VPN as down. However the WAN is NOT DOWN. Machines that are not routed though the VPN work normally, and I can run ping from the command shell and the WAN is passing traffic normally.
If it was just a matter of the VPN, I wrote a small script that runs every 5 minutes that restarts OpenVPN if I can't ping trough the VPN, but that script will not run (by design) if the WAN is down.
The link status incorrectly appearing as down is likely what is causing issues with OpenVPN, and possibly DNS
Any suggestions as to how I might go about troubleshooting this issue.
@stephenw10 thanks for hanging in there with me on this - I really appreciate it.
I did the pcap not on the last, but second last incident, and there was nothing going out. In this case there was nothing but ARPs in the pcap.
The last time, I didn't think to run the pcap again, because Status > Services showed dpinger/dns/openvpn as not running. I clicked the start for each one, and everything was running normally again. Jjust for good measure I did a reboot in case something was corrupted.
After reading your feedback, I took a look at the log again, and this pattern:
Feb 7 03:13:13 pfsense php-fpm[358]: /rc.linkup: DEVD Ethernet detached event for wan
[ ---- Deleted Lines----]
Feb 7 03:13:16 pfsense php-fpm[44538]: /rc.linkup: DEVD Ethernet attached event for wan
Feb 7 03:13:16 pfsense php-fpm[44538]: /rc.linkup: HOTPLUG: Configuring interface wanleads me to believe that the issue was the WAN isn't coming up, and that caused a cascading failure.
The WAN is a Hitron CODA-4582U cable modem operating in bridge mode. I haven't heard of Hitron, but I'm betting it's not great quantity, and the modem may be doing something strange especially at the time it goes offline, or when it comes online gain.
(Since connectivity is generally good, I think the outages are maintenace or possibly when the lease expires.)I took a look at /etc/rc.linkup, and I see that it tries to restart unbound after restarting the interface, but I can't tell if the restart attempt happens if the interface doesn't properly recover since I don't have enough understanding of the context and what all the variables mean.
It looks like a pfBlocker update starts to run while the WAN is down, which may end up putting some stress on the system that causes corruption.
A possible hypothesises is the WAN goes down and doesn't come back up before pfBlocker update runs, then the system doesn't recover.
Also what about this comment from @Patch :
@patch said in pfSense 2.6.0 Fails to Recover after WAN Issues:@guardian This thread maybe relevant https://forum.netgate.com/topic/169614/wan-does-not-renew-after-reboot
As I previously mentioned, this has been an issue for a long time, but until recently my "watchdog" scripts have been solving the problem -- it's just recently that I have noticed that dpinger hasn't recovered.
Thoughts/Comments?
P.S.: As an aside, when connectivity is down, it takes about a minute to log in before the dashboard appears, and there is no feedback that the login button has accepted the click. I suspect that all the widgets that aren't working because the WAN is down are blocking login. This might not be a bad thing to fix. I find myself going in with SSH to find out if the box is alive since the GUI takes so long to come up. If top looks normal, I then try a ping on 8.8.8.8, and by then the GUI MAY be up.
If you find my post useful, please give it a thumbs up!
pfSense 2.7.2-RELEASE -
Mmm, this looks to me like too many things trying to restart in quick succession resulting in a an unexpected condition.
I imagine if you manually disconnect the WAN cable wait 10s then reconnect it the services should recover as expected. Are you able to try that?
It's the flapping link that is causing this:
Feb 7 03:13:12 pfsense kernel: em0: link state changed to DOWN Feb 7 03:13:15 pfsense kernel: em0: link state changed to UP Feb 7 03:13:16 pfsense kernel: em0: link state changed to DOWN Feb 7 03:13:19 pfsense kernel: em0: link state changed to UP Feb 7 03:14:22 pfsense kernel: em0: link state changed to DOWN Feb 7 03:14:24 pfsense kernel: em0: link state changed to UP Feb 7 03:14:25 pfsense kernel: em0: link state changed to DOWN Feb 7 03:14:29 pfsense kernel: em0: link state changed to UP Feb 7 03:15:32 pfsense kernel: em0: link state changed to DOWN Feb 7 03:15:38 pfsense kernel: em0: link state changed to UPThough I agree pfSense should handle this better.
You might also try just rebooting the modem to see how many time the link cycles when it boots as expected.
Steve
-
@stephenw10 said in pfSense 2.6.0 Fails to Recover after WAN Issues:
Mmm, this looks to me like too many things trying to restart in quick succession resulting in a an unexpected condition.
I imagine if you manually disconnect the WAN cable wait 10s then reconnect it the services should recover as expected. Are you able to try that?
I'll keep that in mind for the next time it happens. I'll try unplugging the cable from the modem while it is rebooting, and then plug it in after the modem status lights show connectivity has been restored (Usually about 3-5 minutes).
@stephenw10 said in pfSense 2.6.0 Fails to Recover after WAN Issues:
Though I agree pfSense should handle this better.
You might also try just rebooting the modem to see how many time the link cycles when it boots as expected.
I actually did try rebooting the modem. Even after the system had been functional (with OpenVPN, unbound or both down) for some time, dpinger didn't come back.
EDIT:
Is dpinger always supposed to be running on a properly functioning system?If so, is there any type of watchdog to restart it if it fails?
If not, I was thinking about another script for myself that would check for the presence of processes using ps auxww that contained/usr/local/bin/dpinger. The command line is available and contains the name of the interface so it is easy to test for. How can I restart dpinger from the shell?
So I would have a series of watchdogs: (at minutes past the hour)
5,10,15... : Check if dpinger down, if so restart it.
6,11,16... : Check if unbound down, if so restart it.
7,12,17... : Check if OpenVPN down, if so restart it.
It would be better if the system could protect itself, and possibly provide a flag for plugin authors that they should avoid going out to the internet of connectivity is down.I just remembered this post by @michmoor
@michmoor said in pfSense 2.6.0 Fails to Recover after WAN Issues:- Install the Watchdog service: have it monitor your OpenVPN client. If it detects it down it will restart automatically.
So I have downloaded and installed the package he suggested and configured it to monitor dpinger, unbound and openvpn and removed the cron entries for my scripts. It will be interesting to see if this improves the situation or makes things worse.
Is there any flag available in the code that other apps could use to determine if the WAN is down?
I guess the hardest part of this is that there are so many different use cases that it may be hard to know which interfaces are important for providing internet connectivity. If it can't be determined heuristically , this could be configuration data provided in the GUI.@stephenw10 just wondering do any coding on pfSense? (IIUC you work for Netgate).
I'm assuming that most of Netgate's commercial customers running pfSense are not using heavy plugins and that they likely have redundant hardware and an external watchdog that would reboot a malfunctioning box -- hence this isn't a high priority problem. I'm wondering if @jimp might have something to say on this issue.
////// Aside
Anyway just to be absolutely clear my continued dialog is not intended as criticism -- I am very grateful for Netgate's generosity in supporting this project as open source and only want to solve my issue and hopefully contribute something that might improve things for everyone. -
Your configuration is not unusual. What is unusual is that when the modem has issues it appears to be linking and unlinking multiple times in quick succession. That is triggering a race condition of sorts that ends up without services running.
If you put a switch between the WAN NIC and the modem for example that would almost certainly eliminate this issue.
But testing to see what happens in a controlled situation such as manually reconnecting the WAN cable or rebooting the modem could give some useful data. If the WAN does not flap when doing that then it's something the modem is doing when it fails. -
@stephenw10 said in pfSense 2.6.0 Fails to Recover after WAN Issues:
If you put a switch between the WAN NIC and the modem for example that would almost certainly eliminate this issue.
Interesting idea... I don't have a spare switch at the moment, but I will keep that in mind.But testing to see what happens in a controlled situation such as manually reconnecting the WAN cable or rebooting the modem could give some useful data. If the WAN does not flap when doing that then it's something the modem is doing when it fails.
Hi @stephenw10 OK, I took a few minutes to do some testing, and the TLDR; appears to be that there is something about the way the link on the cable modem comes back up after a reboot.
What I did was to disconnect the cable for 10 minutes and reconnect it without rebooting the modem. The system recovered normally after a couple of minutes.
Then I pulled the power on the modem for 30 seconds and let the modem reboot. The system did not properly recover until I pulled the plug and disconnected the modem from pfSense. I suspect that the modem is restoring link connectivity before the internet connectivity returns, but this is just a guess.
FWIW, here is the log form both tests - I used logger as admin_user from the console to inject a few messages as comments for reference.
Feb 12 03:49:19 pfsense admin_user[16594]: ********************************************************************** Feb 12 03:50:04 pfsense kernel: em0: link state changed to DOWN Feb 12 03:50:04 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 03:50:05 pfsense php-fpm[22688]: /rc.linkup: DEVD Ethernet detached event for wan Feb 12 03:50:06 pfsense php-fpm[22688]: /rc.linkup: Removing static route for monitor 8.8.4.4 and adding a new route through 10.2.110.27 Feb 12 03:50:06 pfsense check_reload_status[396]: Reloading filter Feb 12 03:50:07 pfsense admin_user[96112]: Disconnecting network cable from modem Feb 12 03:50:08 pfsense rc.gateway_alarm[99539]: >>> Gateway alarm: UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%) Feb 12 03:50:08 pfsense check_reload_status[396]: updating dyndns UDP_TOS_VPNV4 Feb 12 03:50:08 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 03:50:08 pfsense check_reload_status[396]: Restarting OpenVPN tunnels/interfaces Feb 12 03:50:08 pfsense check_reload_status[396]: Reloading filter Feb 12 03:50:09 pfsense php-fpm[91128]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 03:50:09 pfsense php-fpm[91128]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use UDP_TOS_VPNV4. Feb 12 03:51:08 pfsense kernel: ovpnc1: link state changed to DOWN Feb 12 03:51:08 pfsense check_reload_status[396]: Reloading filter Feb 12 03:52:00 pfsense php[41801]: servicewatchdog_cron.php: Service Watchdog detected service openvpn stopped. Restarting openvpn (OpenVPN client: VPN STRONG UDP (1197)) Feb 12 03:52:00 pfsense root[48667]: ~~~~~ 23/02/12-03:52:00-WAN is down-DNS restart not attempted. Feb 12 03:52:00 pfsense check_reload_status[396]: Reloading filter Feb 12 03:52:00 pfsense php[48999]: notify_monitor.php: Could not send the message to pfsense@qsv.ca -- Error: Failed to connect to ssl://shadow.mxrouting.net:465 [SMTP: Failed to connect socket: Network is unreachable (code: -1, response: )] Feb 12 03:53:42 pfsense php-fpm[359]: /packages/cron/cron_edit.php: Configuration Change: admin_user@172.16.50.16 (Local Database): Crontab item deleted via cron package Feb 12 03:53:42 pfsense check_reload_status[396]: Syncing firewall Feb 12 04:01:09 pfsense admin_user[99346]: Reconnecting network cable to modem Feb 12 04:01:15 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:01:15 pfsense kernel: em0: link state changed to UP Feb 12 04:01:16 pfsense php-fpm[22688]: /rc.linkup: DEVD Ethernet attached event for wan Feb 12 04:01:16 pfsense php-fpm[22688]: /rc.linkup: HOTPLUG: Configuring interface wan Feb 12 04:01:16 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 12 04:01:16 pfsense php-fpm[22688]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:01:16 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:01:17 pfsense php-fpm[91128]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 12 04:01:17 pfsense php-fpm[91128]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 12 04:01:17 pfsense check_reload_status[396]: Reloading filter Feb 12 04:01:23 pfsense php-fpm[22688]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:01:23 pfsense check_reload_status[396]: updating dyndns wan Feb 12 04:01:57 pfsense php-fpm[22688]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:01:58 pfsense check_reload_status[396]: Reloading filter Feb 12 04:02:32 pfsense kernel: ovpnc1: link state changed to UP Feb 12 04:02:32 pfsense check_reload_status[396]: rc.newwanip starting ovpnc1 Feb 12 04:02:33 pfsense php-fpm[4753]: /rc.newwanip: rc.newwanip: Info: starting on ovpnc1. Feb 12 04:02:33 pfsense php-fpm[4753]: /rc.newwanip: rc.newwanip: on (IP address: 10.28.110.16) (interface: UDP_TOS[opt28]) (real interface: ovpnc1). Feb 12 04:02:39 pfsense php-fpm[4753]: /rc.newwanip: Removing static route for monitor 8.8.8.8 and adding a new route through 99.xxx.xxx.1 Feb 12 04:02:39 pfsense php-fpm[4753]: /rc.newwanip: Removing static route for monitor 8.8.4.4 and adding a new route through 10.28.110.16 Feb 12 04:02:40 pfsense php-fpm[4753]: /rc.newwanip: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:02:40 pfsense php-fpm[4753]: /rc.newwanip: IP Address has changed, killing states on former IP Address 10.2.110.27. Feb 12 04:02:46 pfsense php-fpm[4753]: /rc.newwanip: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:02:46 pfsense php-fpm[4753]: /rc.newwanip: Creating rrd update script Feb 12 04:02:48 pfsense php-fpm[4753]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 10.2.110.27 -> 10.28.110.16 - Restarting packages. Feb 12 04:02:48 pfsense check_reload_status[396]: Starting packages Feb 12 04:02:49 pfsense php-fpm[91128]: /rc.start_packages: Restarting/Starting all packages. Feb 12 04:02:50 pfsense php-fpm[91128]: /rc.start_packages: Reloading syslog-ng for configuration sync Feb 12 04:02:50 pfsense supervise/syslog-ng[19818]: Daemon exited gracefully, not restarting; exitcode='0' Feb 12 04:02:55 pfsense php-fpm[91128]: /rc.start_packages: The command '/usr/local/etc/rc.d/syslog-ng.sh stop' returned exit code '1', the output was '' Feb 12 04:02:56 pfsense check_reload_status[396]: Reloading filter Feb 12 04:02:56 pfsense kernel: em1.1: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.91: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.92: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.93: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.10: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.192: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.254: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.20: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.30: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.40: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.50: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em0: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.1: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.91: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.92: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.93: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.10: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.192: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.254: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.20: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.30: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.40: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.50: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em0: promiscuous mode enabled Feb 12 04:02:59 pfsense lighttpd_pfb[4133]: [pfBlockerNG] DNSBL Webserver stopped Feb 12 04:02:59 pfsense tail_pfb[4327]: [pfBlockerNG] Firewall Filter Service stopped Feb 12 04:02:59 pfsense php_pfb[4627]: [pfBlockerNG] filterlog daemon stopped Feb 12 04:02:59 pfsense lighttpd_pfb[6129]: [pfBlockerNG] DNSBL Webserver started Feb 12 04:02:59 pfsense tail_pfb[9019]: [pfBlockerNG] Firewall Filter Service started Feb 12 04:03:00 pfsense php[6968]: [pfBlockerNG] DNSBL parser daemon started Feb 12 04:03:00 pfsense php[9363]: [pfBlockerNG] filterlog daemon started Feb 12 04:03:38 pfsense admin_user[45430]: Dashboard shows everything back online - Testing complete Feb 12 04:03:41 pfsense admin_user[47476]: ********************************************************************** Feb 12 04:05:18 pfsense admin_user[16322]: ********************************************************************** Feb 12 04:05:27 pfsense admin_user[18252]: reboooting modem Feb 12 04:05:34 pfsense kernel: em0: link state changed to DOWN Feb 12 04:05:34 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:05:35 pfsense php-fpm[4753]: /rc.linkup: DEVD Ethernet detached event for wan Feb 12 04:05:36 pfsense php-fpm[4753]: /rc.linkup: Removing static route for monitor 8.8.4.4 and adding a new route through 10.28.110.16 Feb 12 04:05:36 pfsense check_reload_status[396]: Reloading filter Feb 12 04:05:38 pfsense rc.gateway_alarm[29450]: >>> Gateway alarm: UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%) Feb 12 04:05:38 pfsense check_reload_status[396]: updating dyndns UDP_TOS_VPNV4 Feb 12 04:05:38 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:05:38 pfsense check_reload_status[396]: Restarting OpenVPN tunnels/interfaces Feb 12 04:05:38 pfsense check_reload_status[396]: Reloading filter Feb 12 04:05:39 pfsense php-fpm[38038]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:05:39 pfsense php-fpm[38038]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use UDP_TOS_VPNV4. Feb 12 04:05:46 pfsense admin_user[9863]: modem power off Feb 12 04:06:15 pfsense admin_user[75447]: modem power on Feb 12 04:06:19 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:06:19 pfsense kernel: em0: link state changed to UP Feb 12 04:06:20 pfsense php-fpm[359]: /rc.linkup: DEVD Ethernet attached event for wan Feb 12 04:06:20 pfsense php-fpm[359]: /rc.linkup: HOTPLUG: Configuring interface wan Feb 12 04:07:21 pfsense kernel: em0: link state changed to DOWN Feb 12 04:07:21 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:07:30 pfsense kernel: em0: link state changed to UP Feb 12 04:07:30 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:08:01 pfsense admin_user[85736]: modem all lights flashed Feb 12 04:08:26 pfsense kernel: em0: link state changed to DOWN Feb 12 04:08:26 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:08:33 pfsense kernel: em0: link state changed to UP Feb 12 04:08:33 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:09:52 pfsense php-fpm[359]: /rc.linkup: Default gateway setting Interface WAN_DHCP Gateway as default. Feb 12 04:09:52 pfsense php-fpm[359]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:09:52 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:09:58 pfsense php-fpm[359]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:09:58 pfsense check_reload_status[396]: updating dyndns wan Feb 12 04:10:07 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 12 04:10:08 pfsense php-fpm[91128]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 12 04:10:08 pfsense php-fpm[91128]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 12 04:10:08 pfsense check_reload_status[396]: Reloading filter Feb 12 04:10:11 pfsense admin_user[46872]: modem status lights indicate connectivity restored Feb 12 04:10:33 pfsense php-fpm[359]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:10:33 pfsense check_reload_status[396]: Reloading filter Feb 12 04:10:33 pfsense php-fpm[74959]: /rc.linkup: DEVD Ethernet detached event for wan Feb 12 04:10:34 pfsense php-fpm[74959]: /rc.linkup: Removing static route for monitor 8.8.4.4 and adding a new route through 10.28.110.16 Feb 12 04:10:34 pfsense check_reload_status[396]: Reloading filter Feb 12 04:10:34 pfsense php-fpm[22688]: /rc.linkup: DEVD Ethernet attached event for wan Feb 12 04:10:34 pfsense php-fpm[22688]: /rc.linkup: HOTPLUG: Configuring interface wan Feb 12 04:10:35 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 12 04:10:36 pfsense php-fpm[359]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 12 04:10:36 pfsense php-fpm[359]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 12 04:10:36 pfsense check_reload_status[396]: Reloading filter Feb 12 04:10:37 pfsense rc.gateway_alarm[76647]: >>> Gateway alarm: UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%) Feb 12 04:10:37 pfsense check_reload_status[396]: updating dyndns UDP_TOS_VPNV4 Feb 12 04:10:37 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:10:37 pfsense check_reload_status[396]: Restarting OpenVPN tunnels/interfaces Feb 12 04:10:37 pfsense php-fpm[22688]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:10:37 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:10:38 pfsense php-fpm[74959]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:10:38 pfsense php-fpm[74959]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use UDP_TOS_VPNV4. Feb 12 04:11:11 pfsense php-fpm[22688]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:11:12 pfsense check_reload_status[396]: updating dyndns wan Feb 12 04:11:46 pfsense php-fpm[22688]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:11:47 pfsense check_reload_status[396]: Reloading filter Feb 12 04:11:47 pfsense php-fpm[38038]: /rc.linkup: DEVD Ethernet detached event for wan Feb 12 04:11:48 pfsense php-fpm[38038]: /rc.linkup: Removing static route for monitor 8.8.4.4 and adding a new route through 10.28.110.16 Feb 12 04:11:48 pfsense php-fpm[17557]: /rc.linkup: DEVD Ethernet attached event for wan Feb 12 04:11:48 pfsense check_reload_status[396]: Reloading filter Feb 12 04:11:48 pfsense php-fpm[17557]: /rc.linkup: HOTPLUG: Configuring interface wan Feb 12 04:11:48 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 12 04:11:48 pfsense php-fpm[17557]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:11:48 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:11:49 pfsense php-fpm[91128]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 12 04:11:49 pfsense php-fpm[91128]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 12 04:11:49 pfsense check_reload_status[396]: Reloading filter Feb 12 04:11:50 pfsense rc.gateway_alarm[53702]: >>> Gateway alarm: UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%) Feb 12 04:11:50 pfsense check_reload_status[396]: updating dyndns UDP_TOS_VPNV4 Feb 12 04:11:50 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:11:50 pfsense check_reload_status[396]: Restarting OpenVPN tunnels/interfaces Feb 12 04:11:51 pfsense php-fpm[22688]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:11:51 pfsense php-fpm[22688]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use UDP_TOS_VPNV4. Feb 12 04:12:23 pfsense php-fpm[17557]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:12:23 pfsense check_reload_status[396]: updating dyndns wan Feb 12 04:12:24 pfsense admin_user[32234]: dashboard indicates WAN Unknown / OpenVPN OFFLINE Feb 12 04:12:58 pfsense php-fpm[17557]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:12:58 pfsense check_reload_status[396]: Reloading filter Feb 12 04:15:00 pfsense php[31842]: [pfBlockerNG] Starting cron process. Feb 12 04:16:08 pfsense admin_user[63130]: pfBlocker Update started / Dashboard indicates WAN/OpenVPN Down Feb 12 04:16:14 pfsense kernel: em0: link state changed to DOWN Feb 12 04:16:14 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:16:15 pfsense php-fpm[38038]: /rc.linkup: DEVD Ethernet detached event for wan Feb 12 04:16:16 pfsense php-fpm[38038]: /rc.linkup: Removing static route for monitor 8.8.4.4 and adding a new route through 10.28.110.16 Feb 12 04:16:16 pfsense check_reload_status[396]: Reloading filter Feb 12 04:16:18 pfsense rc.gateway_alarm[24348]: >>> Gateway alarm: UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%) Feb 12 04:16:18 pfsense check_reload_status[396]: updating dyndns UDP_TOS_VPNV4 Feb 12 04:16:18 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:16:18 pfsense check_reload_status[396]: Restarting OpenVPN tunnels/interfaces Feb 12 04:16:18 pfsense check_reload_status[396]: Reloading filter Feb 12 04:16:19 pfsense php-fpm[22688]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:16:19 pfsense php-fpm[22688]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use UDP_TOS_VPNV4. Feb 12 04:16:29 pfsense admin_user[88035]: Cable disconnected from modem Feb 12 04:16:54 pfsense admin_user[85547]: Cable reconnected to modem Feb 12 04:16:55 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:16:55 pfsense kernel: em0: link state changed to UP Feb 12 04:16:56 pfsense php-fpm[76071]: /rc.linkup: DEVD Ethernet attached event for wan Feb 12 04:16:56 pfsense php-fpm[76071]: /rc.linkup: HOTPLUG: Configuring interface wan Feb 12 04:16:56 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 12 04:16:56 pfsense php-fpm[76071]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:16:56 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:16:57 pfsense php-fpm[4753]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 12 04:16:57 pfsense php-fpm[4753]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 12 04:16:57 pfsense check_reload_status[396]: Reloading filter Feb 12 04:17:03 pfsense php-fpm[76071]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:17:03 pfsense check_reload_status[396]: updating dyndns wan Feb 12 04:17:38 pfsense php-fpm[76071]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:17:38 pfsense check_reload_status[396]: Reloading filter Feb 12 04:18:24 pfsense kernel: ovpnc1: link state changed to DOWN Feb 12 04:18:24 pfsense check_reload_status[396]: Reloading filter Feb 12 04:18:25 pfsense kernel: ovpnc1: link state changed to UP Feb 12 04:18:25 pfsense check_reload_status[396]: rc.newwanip starting ovpnc1 Feb 12 04:18:27 pfsense php-fpm[17557]: /rc.newwanip: rc.newwanip: Info: starting on ovpnc1. Feb 12 04:18:27 pfsense php-fpm[17557]: /rc.newwanip: rc.newwanip: on (IP address: 10.16.110.16) (interface: UDP_TOS[opt28]) (real interface: ovpnc1). Feb 12 04:18:37 pfsense php-fpm[17557]: /rc.newwanip: Removing static route for monitor 8.8.8.8 and adding a new route through 99.xxx.xxx.1 Feb 12 04:18:38 pfsense php-fpm[17557]: /rc.newwanip: Removing static route for monitor 8.8.4.4 and adding a new route through 10.16.110.16 Feb 12 04:18:38 pfsense php-fpm[17557]: /rc.newwanip: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:18:38 pfsense php-fpm[17557]: /rc.newwanip: IP Address has changed, killing states on former IP Address 10.28.110.16. Feb 12 04:18:43 pfsense php[31842]: [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Feb 12 04:18:43 pfsense php[31842]: Feb 12 04:18:45 pfsense php-fpm[17557]: /rc.newwanip: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:18:45 pfsense php-fpm[17557]: /rc.newwanip: Creating rrd update script Feb 12 04:18:47 pfsense php-fpm[17557]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 10.28.110.16 -> 10.16.110.16 - Restarting packages. Feb 12 04:18:47 pfsense check_reload_status[396]: Starting packages Feb 12 04:18:48 pfsense php-fpm[38038]: /rc.start_packages: Restarting/Starting all packages. Feb 12 04:18:49 pfsense php-fpm[38038]: /rc.start_packages: Reloading syslog-ng for configuration sync Feb 12 04:18:49 pfsense supervise/syslog-ng[17474]: Daemon exited gracefully, not restarting; exitcode='0' Feb 12 04:18:54 pfsense php-fpm[38038]: /rc.start_packages: The command '/usr/local/etc/rc.d/syslog-ng.sh stop' returned exit code '1', the output was '' Feb 12 04:18:55 pfsense check_reload_status[396]: Reloading filter Feb 12 04:18:55 pfsense kernel: em1.1: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.91: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.92: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.93: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.10: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.192: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.254: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.20: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.30: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.40: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.50: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em0: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.1: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.91: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.92: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.93: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.10: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.192: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.254: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.20: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.30: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.40: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.50: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em0: promiscuous mode enabled Feb 12 04:18:55 pfsense admin_user[51191]: Dashboard shows WAN/OPENVPN now oline Feb 12 04:18:57 pfsense tail_pfb[32202]: [pfBlockerNG] Firewall Filter Service stopped Feb 12 04:18:57 pfsense php_pfb[32309]: [pfBlockerNG] filterlog daemon stopped Feb 12 04:18:58 pfsense lighttpd_pfb[33446]: [pfBlockerNG] DNSBL Webserver stopped Feb 12 04:18:58 pfsense lighttpd_pfb[35056]: [pfBlockerNG] DNSBL Webserver started Feb 12 04:18:58 pfsense tail_pfb[38719]: [pfBlockerNG] Firewall Filter Service started Feb 12 04:18:58 pfsense php[35803]: [pfBlockerNG] DNSBL parser daemon started Feb 12 04:18:59 pfsense php[39232]: [pfBlockerNG] filterlog daemon started Feb 12 04:21:19 pfsense admin_user[22342]: pfBlocker-- Unable to apply rules. Outbound interface option not configured. Feb 12 04:21:33 pfsense admin_user[23930]: System Normal - testing complete Feb 12 04:21:40 pfsense admin_user[24890]: **********************************************************************Any ideas? Any way of monitoring status registers on the WAN NIC? It is also possible that some IPv6 signalling is expected, but I have IPv6 turned off on interrfaces for security reasons as I don't trust myself to deal with it properly.
P.S: Rogers has been quite scary in the past with IPv6 in the past - at one point a couple of years back, default configuration of their modem and default configuration of Windows had everyone's shares exposed to the internet.
-
I would test putting a switch between the modem and pfSense and seeing if that eliminates the issue when rebooting the modem. I would expect it to.
-
@stephenw10 said in pfSense 2.6.0 Fails to Recover after WAN Issues:
I would test putting a switch between the modem and pfSense and seeing if that eliminates the issue when rebooting the modem. I would expect it to.
At the moment I don't have a spare switch available to do that with. Any ideas as to how I might test what is going on (shell script or small php script)? I deactivated my watchdog scripts in favor of the watchdog plugin to see how that works. I have noticed a couple of short gateway issues, but the didn't seem to persist.
I was thinking maybe if there was a loss of WAN connectivity for 5 minutes, but the WAN showed as up to down the interface for say 10-15 seconds and then bring it up again.
What is the best FreeBSD way to do that? Based on your knowledge of how the system works, is pfSense likely to bring the WAN back up? If so how quickly?
Thoughts?
-
FWIW, I'm on Rogers and find my service is extremely reliable. One thing you might want to check is the hardware. A flaky (pardon the technical jargon) computer or bad patch cord could cause problems.
-
You shouldn't need to do more than re-apply the WAN config.
So I'd first try:/etc/rc.linkup start wan -
@jknott said in pfSense 2.6.0 Fails to Recover after WAN Issues:
FWIW, I'm on Rogers and find my service is extremely reliable. One thing you might want to check is the hardware. A flaky (pardon the technical jargon) computer or bad patch cord could cause problems.
@jknott thanks for the reply. I agree the service is very reliable. I can go for months without a problem, then something happens (based on timing, I think it is likely maintenance), the service goes out, and doesn't recover. When I reboot the router, it appears that pfSense doesn't always come back without intervention.. When I did a reboot to test, I found in the trail that I did that pfSense did not come back online until I briefly disconnected the network cable briefly and then reconnected it. That leads me to the conclusion that there is something going on either at the output of the modem, or with the WAN port.
BTW what speed service/modem do you have. I have GB/Hitron CPDA-4582U.
If you find my post useful, please give it a thumbs up!
pfSense 2.7.2-RELEASE -
@stephenw10 said in pfSense 2.6.0 Fails to Recover after WAN Issues:
You shouldn't need to do more than re-apply the WAN config.
So I'd first try:/etc/rc.linkup start wan@stephenw10 - Thanks.... I'll keep that in mind. So far no further issues since my last report. I may go months (or minutes) before the next failure.
Any idea how I can test if dpinger is functioning correctly? I was thinking about a watchdog that would (assuming dpinger is OK) apply
/etc/rc.linkup start wanevery 5 minutes until things came back online. Thoughts?I'll likely pend this till the next time that I have issues.... likely be on a different version of pfSense by that time.
-
@guardian said in pfSense 2.6.0 Fails to Recover after WAN Issues:
@stephenw10 Things have been working well until today. Since you are part of the Netgate team, I though I should ping you on this issue since you were involved before, and maybe someone else might have some bright ideas as well. I've included the log from the relevent time frame at the bottom of this post.It appears that the watchdog plugin is not very useful at restarting the OpenVPN client. I had some issues on the WAN, that screwed up the VPN client: (I think this is what started it):
Mar 2 14:46:14 rc.gateway_alarm 5241 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:1 RTT:593.648ms RTTsd:1382.451ms Loss:0%)The WAN recovered, but the VPN didn't recover, which caused my wife to ask me to investigate. The WAN was UP, VPN was DOWN.
I looked in the OpenVPN log and found this:
Mar 2 17:10:40 openvpn 48841 MANAGEMENT: CMD 'status 2' Mar 2 17:10:40 openvpn 48841 MANAGEMENT: Client connected from /var/etc/openvpn/server4/sock Mar 2 17:10:40 openvpn 73327 MANAGEMENT: Client disconnected Mar 2 17:10:40 openvpn 73327 MANAGEMENT: CMD 'quit' Mar 2 17:10:39 openvpn 73327 MANAGEMENT: CMD 'status 2' Mar 2 17:10:39 openvpn 73327 MANAGEMENT: Client connected from /var/etc/openvpn/server3/sock Mar 2 17:09:53 openvpn 48841 159.203.192.10:54092 SIGUSR1[soft,connection-reset] received, client-instance restarting Mar 2 17:09:53 openvpn 48841 159.203.192.10:54092 Connection reset, restarting [0] Mar 2 17:09:53 openvpn 48841 159.203.192.10:54092 WARNING: Bad encapsulated packet length from peer (5635), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...] Mar 2 17:09:53 openvpn 48841 TCP connection established with [AF_INET]159.203.192.10:54092 Mar 2 17:09:53 openvpn 48841 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 17:09:53 openvpn 48841 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 2 17:09:53 openvpn 48841 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 17:09:53 openvpn 48841 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 2 17:09:46 openvpn 48841 107.170.253.8:57982 SIGUSR1[soft,connection-reset] received, client-instance restarting Mar 2 17:09:46 openvpn 48841 107.170.253.8:57982 Connection reset, restarting [0] Mar 2 17:09:46 openvpn 48841 107.170.253.8:57982 WARNING: Bad encapsulated packet length from peer (5635), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...] Mar 2 17:09:46 openvpn 48841 TCP connection established with [AF_INET]107.170.253.8:57982 Mar 2 17:09:46 openvpn 48841 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 17:09:46 openvpn 48841 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 2 17:09:46 openvpn 48841 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 17:09:46 openvpn 48841 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 2 17:09:37 openvpn 48841 MANAGEMENT: Client disconnected Mar 2 17:09:37 openvpn 48841 MANAGEMENT: CMD 'quit' Mar 2 17:09:37 openvpn 48841 MANAGEMENT: CMD 'status 2' Mar 2 17:09:37 openvpn 48841 MANAGEMENT: Client connected from /var/etc/openvpn/server4/sock Mar 2 17:09:37 openvpn 73327 MANAGEMENT: Client disconnected Mar 2 17:09:37 openvpn 73327 MANAGEMENT: CMD 'quit' Mar 2 17:09:36 openvpn 73327 MANAGEMENT: CMD 'status 2' Mar 2 17:09:36 openvpn 73327 MANAGEMENT: Client connected from /var/etc/openvpn/server3/sock Mar 2 17:08:34 openvpn 48841 MANAGEMENT: Client disconnected Mar 2 17:08:34 openvpn 48841 MANAGEMENT: CMD 'quit' Mar 2 17:08:34 openvpn 48841 MANAGEMENT: CMD 'status 2' Mar 2 17:08:34 openvpn 48841 MANAGEMENT: Client connected from /var/etc/openvpn/server4/sock Mar 2 17:08:34 openvpn 73327 MANAGEMENT: Client disconnected Mar 2 17:08:34 openvpn 73327 MANAGEMENT: CMD 'quit' Mar 2 17:08:34 openvpn 73327 MANAGEMENT: CMD 'status 2' Mar 2 17:08:33 openvpn 73327 MANAGEMENT: Client connected from /var/etc/openvpn/server3/sock Mar 2 17:07:31 openvpn 48841 MANAGEMENT: Client disconnectedNot sure if that gives any clue.
I was able to restart the VPN from the GUI, and it stayed up just fine. That tells me that there is something very different about the pfSense Auto restart and the GUI restart.
I think my little bash script that uses
pfSsh.php playback svc restart openvpn, and AFAIK it was successful in solving this issue (when the WAN doesn't screw up too badly. This has been an issue for me for at least 5 years, and when I put in the watchdog script, it seemed to go away.P.S: Is there any other way than
pfSsh.php playback gatewaystatusto get the status in a more machine readable form that would be easier to work with in a bash script.?Mar 2 06:15:00 php 80917 [pfBlockerNG] Starting cron process. Mar 2 06:16:30 php 80917 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 07:15:00 php 97642 [pfBlockerNG] Starting cron process. Mar 2 07:16:00 sshguard 90642 Exiting on signal. Mar 2 07:16:00 sshguard 75986 Now monitoring attacks. Mar 2 07:16:50 php 97642 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 08:15:00 php 1249 [pfBlockerNG] Starting cron process. Mar 2 08:17:02 php 1249 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 09:15:00 php 12121 [pfBlockerNG] Starting cron process. Mar 2 09:17:04 php 12121 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 10:15:00 php 18697 [pfBlockerNG] Starting cron process. Mar 2 10:17:06 php 18697 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 11:15:00 php 85155 [pfBlockerNG] Starting cron process. Mar 2 11:16:40 php 85155 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 12:15:00 php 91791 [pfBlockerNG] Starting cron process. Mar 2 12:17:17 php 91791 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 12:30:00 php 86652 rc.update_urltables: /etc/rc.update_urltables: Starting up. Mar 2 12:30:00 php 86652 rc.update_urltables: /etc/rc.update_urltables: Sleeping for 33 seconds. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: Starting URL table alias updates Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_MALIP1HR_v4 does not need updating. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_MALIP6HR_v4 does not need updating. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_BBC177IP_v4 does not need updating. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_ULTIMATE_IP_v4 does not need updating. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_PRI1_v4 does not need updating. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_PRI5_v4 does not need updating. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_PRI3_v4 does not need updating. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_PRI2_v4 does not need updating. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_PRI4_v4 does not need updating. Mar 2 13:08:00 sshguard 75986 Exiting on signal. Mar 2 13:08:00 sshguard 49929 Now monitoring attacks. Mar 2 13:15:00 php 62501 [pfBlockerNG] Starting cron process. Mar 2 13:16:58 php 62501 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 14:15:00 php 14690 [pfBlockerNG] Starting cron process. Mar 2 14:16:56 php 14690 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 14:46:14 rc.gateway_alarm 5241 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:1 RTT:593.648ms RTTsd:1382.451ms Loss:0%) Mar 2 14:46:14 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 14:46:14 check_reload_status 396 Restarting IPsec tunnels Mar 2 14:46:14 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 14:46:14 check_reload_status 396 Reloading filter Mar 2 14:46:14 rc.gateway_alarm 7363 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:644.890ms RTTsd:1423.938ms Loss:0%) Mar 2 14:46:14 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 14:46:14 check_reload_status 396 Restarting IPsec tunnels Mar 2 14:46:14 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 14:46:14 check_reload_status 396 Reloading filter Mar 2 14:46:15 php-fpm 17557 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 14:46:15 php-fpm 17557 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 14:46:15 php-fpm 22688 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 14:46:15 php-fpm 22688 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 14:46:45 rc.gateway_alarm 48094 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:0 RTT:371.699ms RTTsd:1075.358ms Loss:0%) Mar 2 14:46:45 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 14:46:45 check_reload_status 396 Restarting IPsec tunnels Mar 2 14:46:45 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 14:46:45 check_reload_status 396 Reloading filter Mar 2 14:46:45 rc.gateway_alarm 49922 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:0 RTT:325.207ms RTTsd:1034.753ms Loss:0%) Mar 2 14:46:45 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 14:46:45 check_reload_status 396 Restarting IPsec tunnels Mar 2 14:46:45 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 14:46:45 check_reload_status 396 Reloading filter Mar 2 14:46:46 php-fpm 38038 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 14:46:46 php-fpm 38038 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 14:46:46 php-fpm 91128 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 14:46:46 php-fpm 91128 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 15:15:00 php 54242 [pfBlockerNG] Starting cron process. Mar 2 15:16:34 php 54242 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 15:41:07 rc.gateway_alarm 26554 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:1 RTT:895.323ms RTTsd:2288.898ms Loss:0%) Mar 2 15:41:07 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 15:41:07 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:41:07 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:41:07 check_reload_status 396 Reloading filter Mar 2 15:41:07 rc.gateway_alarm 28826 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:829.265ms RTTsd:2134.126ms Loss:0%) Mar 2 15:41:07 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 15:41:07 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:41:07 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:41:07 check_reload_status 396 Reloading filter Mar 2 15:41:08 php-fpm 76071 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:41:08 php-fpm 76071 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 15:41:08 php-fpm 91128 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:41:08 php-fpm 91128 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 15:42:10 rc.gateway_alarm 19063 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:0 RTT:34.543ms RTTsd:101.709ms Loss:0%) Mar 2 15:42:10 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 15:42:10 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:42:10 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:42:10 check_reload_status 396 Reloading filter Mar 2 15:42:10 rc.gateway_alarm 20991 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:0 RTT:50.193ms RTTsd:102.034ms Loss:0%) Mar 2 15:42:10 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 15:42:10 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:42:10 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:42:10 check_reload_status 396 Reloading filter Mar 2 15:42:11 php-fpm 22688 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:42:11 php-fpm 22688 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 15:42:11 php-fpm 38038 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:42:11 php-fpm 38038 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 15:48:40 rc.gateway_alarm 63161 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:1 RTT:688.657ms RTTsd:1888.751ms Loss:0%) Mar 2 15:48:41 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 15:48:41 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:48:41 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:48:41 check_reload_status 396 Reloading filter Mar 2 15:48:41 rc.gateway_alarm 65610 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:689.002ms RTTsd:1853.070ms Loss:0%) Mar 2 15:48:41 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 15:48:41 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:48:41 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:48:41 check_reload_status 396 Reloading filter Mar 2 15:48:42 php-fpm 76071 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:48:42 php-fpm 76071 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 15:48:42 php-fpm 38038 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:48:42 php-fpm 38038 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 15:49:45 rc.gateway_alarm 58088 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:0 RTT:29.572ms RTTsd:100.481ms Loss:0%) Mar 2 15:49:45 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 15:49:45 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:49:45 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:49:45 check_reload_status 396 Reloading filter Mar 2 15:49:46 rc.gateway_alarm 60336 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:0 RTT:52.651ms RTTsd:111.949ms Loss:0%) Mar 2 15:49:46 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 15:49:46 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:49:46 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:49:46 check_reload_status 396 Reloading filter Mar 2 15:49:46 php-fpm 74959 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:49:46 php-fpm 74959 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 15:49:47 php-fpm 22688 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:49:47 php-fpm 22688 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 15:53:43 rc.gateway_alarm 61390 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:1 RTT:958.099ms RTTsd:2407.596ms Loss:0%) Mar 2 15:53:43 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 15:53:43 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:53:43 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:53:43 check_reload_status 396 Reloading filter Mar 2 15:53:43 rc.gateway_alarm 63840 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:984.444ms RTTsd:2424.976ms Loss:0%) Mar 2 15:53:43 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 15:53:43 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:53:43 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:53:43 check_reload_status 396 Reloading filter Mar 2 15:53:44 php-fpm 17557 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:53:44 php-fpm 17557 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 15:53:44 php-fpm 22688 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:53:44 php-fpm 22688 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 15:54:47 rc.gateway_alarm 53929 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:0 RTT:34.745ms RTTsd:113.154ms Loss:0%) Mar 2 15:54:47 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 15:54:47 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:54:47 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:54:47 check_reload_status 396 Reloading filter Mar 2 15:54:47 rc.gateway_alarm 57000 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:0 RTT:52.041ms RTTsd:113.582ms Loss:0%) Mar 2 15:54:47 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 15:54:47 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:54:47 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:54:47 check_reload_status 396 Reloading filter Mar 2 15:54:48 php-fpm 17557 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:54:48 php-fpm 17557 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 15:54:48 php-fpm 74959 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:54:48 php-fpm 74959 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 16:15:00 php 96721 [pfBlockerNG] Starting cron process. Mar 2 16:16:44 php 96721 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 16:19:49 rc.gateway_alarm 60859 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:1 RTT:1012.870ms RTTsd:2509.895ms Loss:0%) Mar 2 16:19:49 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 16:19:49 check_reload_status 396 Restarting IPsec tunnels Mar 2 16:19:49 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 16:19:49 check_reload_status 396 Reloading filter Mar 2 16:19:49 rc.gateway_alarm 63012 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:1089.423ms RTTsd:2611.882ms Loss:0%) Mar 2 16:19:49 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 16:19:49 check_reload_status 396 Restarting IPsec tunnels Mar 2 16:19:49 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 16:19:49 check_reload_status 396 Reloading filter Mar 2 16:19:50 php-fpm 74959 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 16:19:50 php-fpm 74959 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 16:19:50 php-fpm 76071 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 16:19:50 php-fpm 76071 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 16:20:05 rc.gateway_alarm 92576 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:1413.616ms RTTsd:2911.066ms Loss:22%) Mar 2 16:20:05 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 16:20:05 check_reload_status 396 Restarting IPsec tunnels Mar 2 16:20:05 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 16:20:05 check_reload_status 396 Reloading filter Mar 2 16:20:06 php-fpm 74959 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 16:20:06 php-fpm 74959 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 16:20:54 rc.gateway_alarm 19106 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:0 RTT:41.868ms RTTsd:133.746ms Loss:0%) Mar 2 16:20:54 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 16:20:54 check_reload_status 396 Restarting IPsec tunnels Mar 2 16:20:54 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 16:20:54 check_reload_status 396 Reloading filter Mar 2 16:20:55 php-fpm 76071 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 16:20:55 php-fpm 76071 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 16:21:01 rc.gateway_alarm 79201 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%) Mar 2 16:21:01 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 16:21:01 check_reload_status 396 Restarting IPsec tunnels Mar 2 16:21:01 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 16:21:01 check_reload_status 396 Reloading filter Mar 2 16:21:02 php-fpm 38038 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 16:21:02 php-fpm 38038 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 16:50:57 root 55932 rc.update_bogons.sh is beginning the update cycle. Mar 2 16:51:03 root 62791 Bogons V4 file downloaded: 14 addresses added. Mar 2 16:51:03 root 62791 Bogons V4 file downloaded: 6 addresses deleted. Mar 2 16:51:03 root 65183 Bogons V6 file downloaded: 45 addresses added. Mar 2 16:51:03 root 65183 Bogons V6 file downloaded: 13 addresses deleted. Mar 2 16:51:03 root 65617 rc.update_bogons.sh is ending the update cycle. Mar 2 17:11:29 php-fpm 4753 /index.php: Successful login for user 'Barry_secure' from: 172.16.50.16 (Local Database) Mar 2 17:13:15 php-fpm 74959 OpenVPN terminate old pid: 70501 Mar 2 17:13:15 kernel ovpnc1: link state changed to DOWN Mar 2 17:13:15 check_reload_status 396 Reloading filter Mar 2 17:13:15 php-fpm 74959 OpenVPN PID written: 23195 Mar 2 17:13:15 check_reload_status 396 Reloading filter Mar 2 17:13:15 kernel ovpnc1: link state changed to UP Mar 2 17:13:15 check_reload_status 396 rc.newwanip starting ovpnc1 Mar 2 17:13:16 php-fpm 91128 /rc.newwanip: rc.newwanip: Info: starting on ovpnc1. Mar 2 17:13:16 php-fpm 91128 /rc.newwanip: rc.newwanip: on (IP address: 10.8.110.23) (interface: VPN_UDP_TOS[opt28]) (real interface: ovpnc1). Mar 2 17:13:34 php-fpm 91128 /rc.newwanip: Removing static route for monitor 8.8.8.8 and adding a new route through 99.ZZZ.ZZZ.1 Mar 2 17:13:34 php-fpm 91128 /rc.newwanip: Removing static route for monitor 8.8.4.4 and adding a new route through 10.8.110.23 Mar 2 17:13:34 php-fpm 91128 /rc.newwanip: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 17:13:34 php-fpm 91128 /rc.newwanip: IP Address has changed, killing states on former IP Address 10.16.110.16. Mar 2 17:13:41 php-fpm 91128 /rc.newwanip: The command '/usr/sbin/arp -s '172.16.50.1' '00:xx:xx:xx:xx:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Mar 2 17:13:42 php-fpm 91128 /rc.newwanip: Creating rrd update script Mar 2 17:13:44 php-fpm 91128 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 10.16.110.16 -> 10.8.110.23 - Restarting packages. Mar 2 17:13:44 check_reload_status 396 Starting packages Mar 2 17:13:45 php-fpm 74959 /rc.start_packages: Restarting/Starting all packages. Mar 2 17:13:45 php-fpm 74959 /rc.start_packages: Reloading syslog-ng for configuration sync Mar 2 17:13:46 supervise/syslog-ng 43274 Daemon exited gracefully, not restarting; exitcode='0' Mar 2 17:13:50 php-fpm 74959 /rc.start_packages: The command '/usr/local/etc/rc.d/syslog-ng.sh stop' returned exit code '1', the output was '' Mar 2 17:13:52 check_reload_status 396 Reloading filter -
Mmm, Ok so right at the end of that log is where you login and restart the VPN client?
The service watchdog doesn't run at any time because the OpenVPN client doesn't ever die. It just keeps trying to connect which is what it's supposed to do.
Your WAN get's marked down numerous times during the 11 hours shown in that log but you can see each time the WAN gateway comes back up and so does the VPN gateway. The pings times to the monitred IP go back down to <50ms:
Mar 2 16:20:54 rc.gateway_alarm 19106 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:0 RTT:41.868ms RTTsd:133.746ms Loss:0%)Until the last time where it comes back up but it at 100% packet loss:
Mar 2 16:21:01 rc.gateway_alarm 79201 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%)We don't have the OpenVPN logs for that time but I imagine they have been repeating since then so it would be that 'Bad encapsulated packet length from peer' error followed by 'Connection reset, restarting [0]'.
Is that OpenVPN client connecting to the same remote address every time or a pool or remote addresses?
It's probably trying to connect to something that isn't an OpenVPN server. It's a TCP connection, what's the remote port?
-
@stephenw10 said in pfSense 2.6.0 Fails to Recover after WAN Issues:
We don't have the OpenVPN logs for that time but I imagine they have been repeating since then so it would be that 'Bad encapsulated packet length from peer' error followed by 'Connection reset, restarting [0]'.
I'm getting a ton of messages like this that are filling the log. (Verbosity Level is set to 4). It turns out that this is my VPN Access server running on port 443 TCP
Mar 2 17:08:34 openvpn 48841 MANAGEMENT: Client disconnected Mar 2 17:08:34 openvpn 48841 MANAGEMENT: CMD 'quit' Mar 2 17:08:34 openvpn 48841 MANAGEMENT: CMD 'status 2' Mar 2 17:08:34 openvpn 48841 MANAGEMENT: Client connected from /var/etc/openvpn/server4/sockand this is my UDP access server
Mar 3 03:43:40 openvpn 73327 MANAGEMENT: Client disconnected Mar 3 03:43:40 openvpn 73327 MANAGEMENT: CMD 'quit' Mar 3 03:43:40 openvpn 73327 MANAGEMENT: CMD 'status 2' Mar 3 03:43:40 openvpn 73327 MANAGEMENT: Client connected from /var/etc/openvpn/server3/sockAre these significant? What are they telling me? Do I need to be worried about these?
(They are not being used as I wasn't away and needing them).I see this on the VPN Client that is the subject of this discussion. Is this an attack?
Mar 3 03:08:24 openvpn 23195 PID_ERR replay-window backtrack occurred [42] [SSL-0] [0__00_____0_0_0________________00000000000_000000000000000000000] 0:374099 0:374057 t=1677830904[0] r=[0,64,15,42,1] sl=[45,64,64,528]There are a lot of probes on my remote access servers:
Mar 3 01:52:35 openvpn 48841 186.211.1.7:61008 SIGUSR1[soft,connection-reset] received, client-instance restarting Mar 3 01:52:35 openvpn 48841 186.211.1.7:61008 Connection reset, restarting [0] Mar 3 01:52:35 openvpn 48841 186.211.1.7:61008 WARNING: Bad encapsulated packet length from peer (5635), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...] Mar 3 01:52:33 openvpn 48841 TCP connection established with [AF_INET]186.211.1.7:61008 Mar 3 01:52:33 openvpn 48841 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 3 01:52:33 openvpn 48841 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 3 01:52:33 openvpn 48841 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 3 01:52:33 openvpn 48841 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key ---------- Mar 3 01:20:11 openvpn 48841 107.170.239.12:51002 SIGUSR1[soft,connection-reset] received, client-instance restarting Mar 3 01:20:11 openvpn 48841 107.170.239.12:51002 Connection reset, restarting [0] Mar 3 01:20:11 openvpn 48841 107.170.239.12:51002 WARNING: Bad encapsulated packet length from peer (5635), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...] Mar 3 01:20:10 openvpn 48841 TCP connection established with [AF_INET]107.170.239.12:51002 Mar 3 01:20:10 openvpn 48841 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 3 01:20:10 openvpn 48841 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 3 01:20:10 openvpn 48841 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 3 01:20:10 openvpn 48841 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key ---------- Mar 3 00:20:48 openvpn 48841 91.193.7.84:60742 SIGUSR1[soft,connection-reset] received, client-instance restarting Mar 3 00:20:48 openvpn 48841 91.193.7.84:60742 Connection reset, restarting [0] Mar 3 00:20:48 openvpn 48841 91.193.7.84:60742 WARNING: Bad encapsulated packet length from peer (39642), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...] Mar 3 00:20:48 openvpn 48841 TCP connection established with [AF_INET]91.193.7.84:60742 Mar 3 00:20:48 openvpn 48841 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 3 00:20:48 openvpn 48841 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 3 00:20:48 openvpn 48841 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 3 00:20:48 openvpn 48841 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key ---------- Mar 2 23:52:48 openvpn 48841 193.106.29.122:61864 SIGUSR1[soft,connection-reset] received, client-instance restarting Mar 2 23:52:48 openvpn 48841 193.106.29.122:61864 Connection reset, restarting [0] Mar 2 23:52:48 openvpn 48841 193.106.29.122:61864 WARNING: Bad encapsulated packet length from peer (5635), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...] Mar 2 23:52:46 openvpn 48841 TCP connection established with [AF_INET]193.106.29.122:61864 Mar 2 23:52:46 openvpn 48841 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 23:52:46 openvpn 48841 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 2 23:52:46 openvpn 48841 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 23:52:46 openvpn 48841 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key ---------- Mar 2 23:47:37 openvpn 48841 198.199.95.35:47508 SIGUSR1[soft,connection-reset] received, client-instance restarting Mar 2 23:47:37 openvpn 48841 198.199.95.35:47508 Connection reset, restarting [0] Mar 2 23:47:37 openvpn 48841 198.199.95.35:47508 WARNING: Bad encapsulated packet length from peer (5635), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...] Mar 2 23:47:37 openvpn 48841 TCP connection established with [AF_INET]198.199.95.35:47508 Mar 2 23:47:37 openvpn 48841 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 23:47:37 openvpn 48841 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 2 23:47:37 openvpn 48841 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 23:47:37 openvpn 48841 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 2 23:47:33 openvpn 48841 107.170.229.7:57352 SIGUSR1[soft,connection-reset] received, client-instance restarting Mar 2 23:47:33 openvpn 48841 107.170.229.7:57352 Connection reset, restarting [0] Mar 2 23:47:33 openvpn 48841 107.170.229.7:57352 WARNING: Bad encapsulated packet length from peer (5635), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...] Mar 2 23:47:33 openvpn 48841 TCP connection established with [AF_INET]107.170.229.7:57352 ---------- Mar 2 23:37:30 openvpn 73327 TLS Error: tls-crypt unwrapping failed from [AF_INET]205.210.31.13:56419 Mar 2 23:37:30 openvpn 73327 tls-crypt unwrap error: packet too short ---------- Mar 2 23:37:09 openvpn 48841 185.180.143.6:48848 SIGUSR1[soft,connection-reset] received, client-instance restarting Mar 2 23:37:09 openvpn 48841 185.180.143.6:48848 Connection reset, restarting [0] Mar 2 23:37:09 openvpn 48841 185.180.143.6:48848 WARNING: Bad encapsulated packet length from peer (5635), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...] Mar 2 23:37:09 openvpn 48841 TCP connection established with [AF_INET]185.180.143.6:48848 Mar 2 23:37:09 openvpn 48841 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 23:37:09 openvpn 48841 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 2 23:37:09 openvpn 48841 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 23:37:09 openvpn 48841 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key ---------- Mar 2 23:30:44 openvpn 48841 128.14.141.34:57556 SIGUSR1[soft,connection-reset] received, client-instance restarting Mar 2 23:30:44 openvpn 48841 128.14.141.34:57556 Connection reset, restarting [0] Mar 2 23:30:44 openvpn 48841 128.14.141.34:57556 WARNING: Bad encapsulated packet length from peer (5635), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...] Mar 2 23:30:44 openvpn 48841 TCP connection established with [AF_INET]128.14.141.34:57556 Mar 2 23:30:44 openvpn 48841 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 23:30:44 openvpn 48841 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 2 23:30:44 openvpn 48841 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 23:30:44 openvpn 48841 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key ---------- Mar 2 23:09:07 openvpn 48841 5.188.210.227:39461 SIGUSR1[soft,connection-reset] received, client-instance restarting Mar 2 23:09:07 openvpn 48841 5.188.210.227:39461 Connection reset, restarting [0] Mar 2 23:09:07 openvpn 48841 5.188.210.227:39461 WARNING: Bad encapsulated packet length from peer (18245), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...] Mar 2 23:09:03 openvpn 48841 TCP connection established with [AF_INET]5.188.210.227:39461 Mar 2 23:09:03 openvpn 48841 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 23:09:03 openvpn 48841 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 2 23:09:03 openvpn 48841 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 23:09:03 openvpn 48841 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit keyI have a remote access server on port 443, and it looks like it is taking a bit of fire. Anything special I should be doing to protect it? (Currently protected by a TLS key + strong cert + password) Unless there is a CVE on OpenVPN I would assume that I should be OK (DDoS is the worst case) I shouldn't really be a target, so I suspect that these are just automated attacks.
Is that OpenVPN client connecting to the same remote address every time or a pool or remote addresses?
It's probably trying to connect to something that isn't an OpenVPN server. It's a TCP connection, what's the remote port?
I didn't realize, but it turns out they are one of my remote access servers. It doesn't relate to the incident, but I'm sure it has happened many times:
Mar 3 03:57:16 openvpn 90372 MANAGEMENT: Client disconnected Mar 3 03:57:16 openvpn 90372 MANAGEMENT: CMD 'quit' Mar 3 03:57:16 openvpn 90372 MANAGEMENT: CMD 'status 2' Mar 3 03:57:16 openvpn 90372 MANAGEMENT: Client connected from /var/etc/openvpn/server3/sock Mar 3 03:56:40 openvpn 90372 Initialization Sequence Completed Mar 3 03:56:40 openvpn 90372 IFCONFIG POOL IPv4: base=172.16.71.2 size=252 Mar 3 03:56:40 openvpn 90372 MULTI: multi_init called, r=256 v=256 Mar 3 03:56:40 openvpn 90372 UDPv4 link remote: [AF_UNSPEC] Mar 3 03:56:40 openvpn 90372 UDPv4 link local (bound): [AF_INET]99.ZZZ.ZZZ.182:1194 Mar 3 03:56:40 openvpn 90372 Socket Buffers: R=[42080->42080] S=[57344->57344] Mar 3 03:56:40 openvpn 90372 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ] Mar 3 03:56:40 openvpn 90372 /usr/local/sbin/ovpn-linkup ovpns3 1500 1622 172.16.71.1 255.255.255.0 init Mar 3 03:56:40 openvpn 90372 /sbin/route add -net 172.16.71.0 172.16.71.2 255.255.255.0 Mar 3 03:56:40 openvpn 90372 /sbin/ifconfig ovpns3 172.16.71.1 172.16.71.2 mtu 1500 netmask 255.255.255.0 up Mar 3 03:56:40 openvpn 90372 do_ifconfig, ipv4=1, ipv6=0 Mar 3 03:56:40 openvpn 90372 TUN/TAP device /dev/tun3 opened Mar 3 03:56:40 openvpn 90372 TUN/TAP device ovpns3 exists previously, keep at program end Mar 3 03:56:40 openvpn 90372 TLS-Auth MTU parms [ L:1622 D:1156 EF:94 EB:0 ET:0 EL:3 ] Mar 3 03:56:40 openvpn 90372 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 3 03:56:40 openvpn 90372 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 3 03:56:40 openvpn 90372 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 3 03:56:40 openvpn 90372 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 3 03:56:40 openvpn 90372 WARNING: experimental option --capath /var/etc/openvpn/server3/ca Mar 3 03:56:40 openvpn 90372 Diffie-Hellman initialized with 2048 bit key Mar 3 03:56:40 openvpn 90372 PLUGIN_INIT: POST /usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so '[/usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so] [/usr/local/sbin/ovpn_auth_verify_async] [user] [TG9jYWwgRGF0YWJhc2U=] [true] [server3] [1194]' intercepted=PLUGIN_AUTH_USER_PASS_VERIFY Mar 3 03:56:40 openvpn 90372 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts Mar 3 03:56:40 openvpn 90372 MANAGEMENT: unix domain socket listening on /var/etc/openvpn/server3/sock Mar 3 03:56:40 openvpn 90032 library versions: OpenSSL 1.1.1l-freebsd 24 Aug 2021, LZO 2.10 Mar 3 03:56:40 openvpn 90032 OpenVPN 2.5.4 amd64-portbld-freebsd12.3 [SSL (OpenSSL)] [LZO] [LZ4] [MH/RECVDA] [AEAD] built on Jan 12 2022 Mar 3 03:56:40 openvpn 90032 auth_user_pass_file = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 pull = DISABLED Mar 3 03:56:40 openvpn 90032 client = DISABLED Mar 3 03:56:40 openvpn 90032 vlan_pvid = 1 Mar 3 03:56:40 openvpn 90032 vlan_accept = all Mar 3 03:56:40 openvpn 90032 vlan_tagging = DISABLED Mar 3 03:56:40 openvpn 90032 port_share_port = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 port_share_host = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 auth_token_secret_file = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 auth_token_lifetime = 0 Mar 3 03:56:40 openvpn 90032 auth_token_generate = DISABLED Mar 3 03:56:40 openvpn 90032 auth_user_pass_verify_script_via_file = DISABLED Mar 3 03:56:40 openvpn 90032 auth_user_pass_verify_script = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 max_routes_per_client = 256 Mar 3 03:56:40 openvpn 90032 max_clients = 4 Mar 3 03:56:40 openvpn 90032 cf_per = 0 Mar 3 03:56:40 openvpn 90032 cf_max = 0 Mar 3 03:56:40 openvpn 90032 duplicate_cn = DISABLED Mar 3 03:56:40 openvpn 90032 enable_c2c = ENABLED Mar 3 03:56:40 openvpn 90032 push_ifconfig_ipv6_remote = :: Mar 3 03:56:40 openvpn 90032 push_ifconfig_ipv6_local = ::/0 Mar 3 03:56:40 openvpn 90032 push_ifconfig_ipv6_defined = DISABLED Mar 3 03:56:40 openvpn 90032 push_ifconfig_remote_netmask = 0.0.0.0 Mar 3 03:56:40 openvpn 90032 push_ifconfig_local = 0.0.0.0 Mar 3 03:56:40 openvpn 90032 push_ifconfig_defined = DISABLED Mar 3 03:56:40 openvpn 90032 tmp_dir = '/tmp' Mar 3 03:56:40 openvpn 90032 ccd_exclusive = DISABLED Mar 3 03:56:40 openvpn 90032 client_config_dir = '/var/etc/openvpn/server3/csc' Mar 3 03:56:40 openvpn 90032 client_disconnect_script = '/usr/local/sbin/openvpn.attributes.sh' Mar 3 03:56:40 openvpn 90032 learn_address_script = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 client_connect_script = '/usr/local/sbin/openvpn.attributes.sh' Mar 3 03:56:40 openvpn 90032 virtual_hash_size = 256 Mar 3 03:56:40 openvpn 90032 real_hash_size = 256 Mar 3 03:56:40 openvpn 90032 tcp_queue_limit = 64 Mar 3 03:56:40 openvpn 90032 n_bcast_buf = 256 Mar 3 03:56:40 openvpn 90032 ifconfig_ipv6_pool_netbits = 0 Mar 3 03:56:40 openvpn 90032 ifconfig_ipv6_pool_base = :: Mar 3 03:56:40 openvpn 90032 ifconfig_ipv6_pool_defined = DISABLED Mar 3 03:56:40 openvpn 90032 ifconfig_pool_persist_refresh_freq = 600 Mar 3 03:56:40 openvpn 90032 ifconfig_pool_persist_filename = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 ifconfig_pool_netmask = 255.255.255.0 Mar 3 03:56:40 openvpn 90032 ifconfig_pool_end = 172.16.71.253 Mar 3 03:56:40 openvpn 90032 ifconfig_pool_start = 172.16.71.2 Mar 3 03:56:40 openvpn 90032 ifconfig_pool_defined = ENABLED Mar 3 03:56:40 openvpn 90032 push_entry = 'ping-restart 60' Mar 3 03:56:40 openvpn 90032 push_entry = 'ping 10' Mar 3 03:56:40 openvpn 90032 push_entry = 'topology subnet' Mar 3 03:56:40 openvpn 90032 push_entry = 'route-gateway 172.16.71.1' Mar 3 03:56:40 openvpn 90032 push_entry = 'redirect-gateway def1' Mar 3 03:56:40 openvpn 90032 push_entry = 'dhcp-option NTP 172.16.71.1' Mar 3 03:56:40 openvpn 90032 push_entry = 'dhcp-option DNS 172.16.71.1' Mar 3 03:56:40 openvpn 90032 server_bridge_pool_end = 0.0.0.0 Mar 3 03:56:40 openvpn 90032 server_bridge_pool_start = 0.0.0.0 Mar 3 03:56:40 openvpn 90032 server_bridge_netmask = 0.0.0.0 Mar 3 03:56:40 openvpn 90032 server_bridge_ip = 0.0.0.0 Mar 3 03:56:40 openvpn 90032 server_netbits_ipv6 = 0 Mar 3 03:56:40 openvpn 90032 server_network_ipv6 = :: Mar 3 03:56:40 openvpn 90032 server_netmask = 255.255.255.0 Mar 3 03:56:40 openvpn 90032 server_network = 172.16.71.0 Mar 3 03:56:40 openvpn 90032 tls_crypt_v2_metadata = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 tls_exit = DISABLED Mar 3 03:56:40 openvpn 90032 push_peer_info = DISABLED Mar 3 03:56:40 openvpn 90032 single_session = DISABLED Mar 3 03:56:40 openvpn 90032 transition_window = 3600 Mar 3 03:56:40 openvpn 90032 handshake_window = 60 Mar 3 03:56:40 openvpn 90032 renegotiate_seconds = 0 Mar 3 03:56:40 openvpn 90032 renegotiate_packets = 0 Mar 3 03:56:40 openvpn 90032 renegotiate_bytes = -1 Mar 3 03:56:40 openvpn 90032 tls_timeout = 2 Mar 3 03:56:40 openvpn 90032 ssl_flags = 4 Mar 3 03:56:40 openvpn 90032 remote_cert_eku = 'TLS Web Client Authentication' Mar 3 03:56:40 openvpn 90032 remote_cert_ku[i] = 0 Mar 3 03:56:40 openvpn 90032 remote_cert_ku[i] = 0 Mar 3 03:56:40 openvpn 90032 remote_cert_ku[i] = 0 Mar 3 03:56:40 openvpn 90032 remote_cert_ku[i] = 0 Mar 3 03:56:40 openvpn 90032 remote_cert_ku[i] = 0 Mar 3 03:56:40 openvpn 90032 remote_cert_ku[i] = 0 Mar 3 03:56:40 openvpn 90032 remote_cert_ku[i] = 0 Mar 3 03:56:40 openvpn 90032 remote_cert_ku[i] = 0 Mar 3 03:56:40 openvpn 90032 remote_cert_ku[i] = 0 Mar 3 03:56:40 openvpn 90032 remote_cert_ku[i] = 0 Mar 3 03:56:40 openvpn 90032 remote_cert_ku[i] = 0 Mar 3 03:56:40 openvpn 90032 remote_cert_ku[i] = 0 Mar 3 03:56:40 openvpn 90032 remote_cert_ku[i] = 0 Mar 3 03:56:40 openvpn 90032 remote_cert_ku[i] = 0 Mar 3 03:56:40 openvpn 90032 remote_cert_ku[i] = 0 Mar 3 03:56:40 openvpn 90032 remote_cert_ku[i] = 224 Mar 3 03:56:40 openvpn 90032 ns_cert_type = 0 Mar 3 03:56:40 openvpn 90032 crl_file = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 verify_x509_name = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 verify_x509_type = 0 Mar 3 03:56:40 openvpn 90032 tls_export_cert = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 tls_verify = '/usr/local/sbin/ovpn_auth_verify tls 'REMOTEACCESS1' 2' Mar 3 03:56:40 openvpn 90032 tls_cert_profile = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 cipher_list_tls13 = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 cipher_list = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 pkcs12_file = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 priv_key_file = '/var/etc/openvpn/server3/key' Mar 3 03:56:40 openvpn 90032 extra_certs_file = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 cert_file = '/var/etc/openvpn/server3/cert' Mar 3 03:56:40 openvpn 90032 dh_file = '/etc/dh-parameters.2048' Mar 3 03:56:40 openvpn 90032 ca_path = '/var/etc/openvpn/server3/ca' Mar 3 03:56:40 openvpn 90032 ca_file = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 tls_client = DISABLED Mar 3 03:56:40 openvpn 90032 tls_server = ENABLED Mar 3 03:56:40 openvpn 90032 test_crypto = DISABLED Mar 3 03:56:40 openvpn 90032 packet_id_file = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 replay_time = 15 Mar 3 03:56:40 openvpn 90032 replay_window = 64 Mar 3 03:56:40 openvpn 90032 mute_replay_warnings = DISABLED Mar 3 03:56:40 openvpn 90032 replay = ENABLED Mar 3 03:56:40 openvpn 90032 engine = DISABLED Mar 3 03:56:40 openvpn 90032 keysize = 0 Mar 3 03:56:40 openvpn 90032 prng_nonce_secret_len = 16 Mar 3 03:56:40 openvpn 90032 prng_hash = 'SHA1' Mar 3 03:56:40 openvpn 90032 authname = 'SHA512' Mar 3 03:56:40 openvpn 90032 ncp_ciphers = 'AES-256-GCM' Mar 3 03:56:40 openvpn 90032 ncp_enabled = ENABLED Mar 3 03:56:40 openvpn 90032 ciphername = 'AES-256-GCM' Mar 3 03:56:40 openvpn 90032 key_direction = not set Mar 3 03:56:40 openvpn 90032 shared_secret_file = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 plugin[0] /usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so '[/usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so] [/usr/local/sbin/ovpn_auth_verify_async] [user] [TG9jYWwgRGF0YWJhc2U=] [true] [server3] [1194]' Mar 3 03:56:40 openvpn 90032 management_flags = 256 Mar 3 03:56:40 openvpn 90032 management_client_group = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 management_client_user = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 management_write_peer_info_file = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 management_echo_buffer_size = 100 Mar 3 03:56:40 openvpn 90032 management_log_history_cache = 250 Mar 3 03:56:40 openvpn 90032 management_user_pass = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 management_port = 'unix' Mar 3 03:56:40 openvpn 90032 management_addr = '/var/etc/openvpn/server3/sock' Mar 3 03:56:40 openvpn 90032 allow_pull_fqdn = DISABLED Mar 3 03:56:40 openvpn 90032 route_gateway_via_dhcp = DISABLED Mar 3 03:56:40 openvpn 90032 route_nopull = DISABLED Mar 3 03:56:40 openvpn 90032 route_delay_defined = DISABLED Mar 3 03:56:40 openvpn 90032 route_delay_window = 30 Mar 3 03:56:40 openvpn 90032 route_delay = 0 Mar 3 03:56:40 openvpn 90032 route_noexec = DISABLED Mar 3 03:56:40 openvpn 90032 route_default_metric = 0 Mar 3 03:56:40 openvpn 90032 route_default_gateway = '172.16.71.2' Mar 3 03:56:40 openvpn 90032 route_script = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 comp.flags = 1 Mar 3 03:56:40 openvpn 90032 comp.alg = 2 Mar 3 03:56:40 openvpn 90032 fast_io = DISABLED Mar 3 03:56:40 openvpn 90032 sockflags = 0 Mar 3 03:56:40 openvpn 90032 sndbuf = 0 Mar 3 03:56:40 openvpn 90032 rcvbuf = 0 Mar 3 03:56:40 openvpn 90032 occ = ENABLED Mar 3 03:56:40 openvpn 90032 status_file_update_freq = 60 Mar 3 03:56:40 openvpn 90032 status_file_version = 1 Mar 3 03:56:40 openvpn 90032 status_file = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 gremlin = 0 Mar 3 03:56:40 openvpn 90032 mute = 0 Mar 3 03:56:40 openvpn 90032 verbosity = 4 Mar 3 03:56:40 openvpn 90032 nice = 0 Mar 3 03:56:40 openvpn 90032 machine_readable_output = DISABLED Mar 3 03:56:40 openvpn 90032 suppress_timestamps = DISABLED Mar 3 03:56:40 openvpn 90032 log = DISABLED Mar 3 03:56:40 openvpn 90032 inetd = 0 Mar 3 03:56:40 openvpn 90032 daemon = ENABLED Mar 3 03:56:40 openvpn 90032 up_delay = DISABLED Mar 3 03:56:40 openvpn 90032 up_restart = DISABLED Mar 3 03:56:40 openvpn 90032 down_pre = DISABLED Mar 3 03:56:40 openvpn 90032 down_script = '/usr/local/sbin/ovpn-linkdown' Mar 3 03:56:40 openvpn 90032 up_script = '/usr/local/sbin/ovpn-linkup' Mar 3 03:56:40 openvpn 90032 writepid = '/var/run/openvpn_server3.pid' Mar 3 03:56:40 openvpn 90032 cd_dir = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 chroot_dir = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 groupname = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 username = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 resolve_in_advance = DISABLED Mar 3 03:56:40 openvpn 90032 resolve_retry_seconds = 1000000000 Mar 3 03:56:40 openvpn 90032 passtos = DISABLED Mar 3 03:56:40 openvpn 90032 persist_key = ENABLED Mar 3 03:56:40 openvpn 90032 persist_remote_ip = ENABLED Mar 3 03:56:40 openvpn 90032 persist_local_ip = DISABLED Mar 3 03:56:40 openvpn 90032 persist_tun = ENABLED Mar 3 03:56:40 openvpn 90032 remap_sigusr1 = 0 Mar 3 03:56:40 openvpn 90032 ping_timer_remote = ENABLED Mar 3 03:56:40 openvpn 90032 ping_rec_timeout_action = 2 Mar 3 03:56:40 openvpn 90032 ping_rec_timeout = 120 Mar 3 03:56:40 openvpn 90032 ping_send_timeout = 10 Mar 3 03:56:40 openvpn 90032 inactivity_timeout = 0 Mar 3 03:56:40 openvpn 90032 keepalive_timeout = 60 Mar 3 03:56:40 openvpn 90032 keepalive_ping = 10 Mar 3 03:56:40 openvpn 90032 mlock = DISABLED Mar 3 03:56:40 openvpn 90032 mtu_test = 0 Mar 3 03:56:40 openvpn 90032 shaper = 0 Mar 3 03:56:40 openvpn 90032 ifconfig_ipv6_remote = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 ifconfig_ipv6_netbits = 0 Mar 3 03:56:40 openvpn 90032 ifconfig_ipv6_local = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 ifconfig_nowarn = DISABLED Mar 3 03:56:40 openvpn 90032 ifconfig_noexec = DISABLED Mar 3 03:56:40 openvpn 90032 ifconfig_remote_netmask = '255.255.255.0' Mar 3 03:56:40 openvpn 90032 ifconfig_local = '172.16.71.1' Mar 3 03:56:40 openvpn 90032 topology = 3 Mar 3 03:56:40 openvpn 90032 lladdr = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 dev_node = '/dev/tun3' Mar 3 03:56:40 openvpn 90032 dev_type = 'tun' Mar 3 03:56:40 openvpn 90032 dev = 'ovpns3' Mar 3 03:56:40 openvpn 90032 ipchange = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 remote_random = DISABLED Mar 3 03:56:40 openvpn 90032 Connection profiles END Mar 3 03:56:40 openvpn 90032 tls_crypt_v2_file = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 tls_crypt_file = '[INLINE]' Mar 3 03:56:40 openvpn 90032 key_direction = not set Mar 3 03:56:40 openvpn 90032 tls_auth_file = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 explicit_exit_notification = 0 Mar 3 03:56:40 openvpn 90032 mssfix = 1450 Mar 3 03:56:40 openvpn 90032 fragment = 0 Mar 3 03:56:40 openvpn 90032 mtu_discover_type = -1 Mar 3 03:56:40 openvpn 90032 tun_mtu_extra_defined = DISABLED Mar 3 03:56:40 openvpn 90032 tun_mtu_extra = 0 Mar 3 03:56:40 openvpn 90032 link_mtu_defined = DISABLED Mar 3 03:56:40 openvpn 90032 link_mtu = 1500 Mar 3 03:56:40 openvpn 90032 tun_mtu_defined = ENABLED Mar 3 03:56:40 openvpn 90032 tun_mtu = 1500 Mar 3 03:56:40 openvpn 90032 socks_proxy_port = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 socks_proxy_server = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 connect_timeout = 120 Mar 3 03:56:40 openvpn 90032 connect_retry_seconds = 5 Mar 3 03:56:40 openvpn 90032 bind_ipv6_only = DISABLED Mar 3 03:56:40 openvpn 90032 bind_local = ENABLED Mar 3 03:56:40 openvpn 90032 bind_defined = DISABLED Mar 3 03:56:40 openvpn 90032 remote_float = ENABLED Mar 3 03:56:40 openvpn 90032 remote_port = '1194' Mar 3 03:56:40 openvpn 90032 remote = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 local_port = '1194' Mar 3 03:56:40 openvpn 90032 local = '99.ZZZ.ZZZ.182' Mar 3 03:56:40 openvpn 90032 proto = udp4 Mar 3 03:56:40 openvpn 90032 Connection profiles [0]: Mar 3 03:56:40 openvpn 90032 connect_retry_max = 0 Mar 3 03:56:40 openvpn 90032 show_tls_ciphers = DISABLED Mar 3 03:56:40 openvpn 90032 key_pass_file = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 genkey_filename = '[UNDEF]' Mar 3 03:56:40 openvpn 90032 genkey = DISABLED Mar 3 03:56:40 openvpn 90032 show_engines = DISABLED Mar 3 03:56:40 openvpn 90032 show_digests = DISABLED Mar 3 03:56:40 openvpn 90032 show_ciphers = DISABLED Mar 3 03:56:40 openvpn 90032 mode = 1 Mar 3 03:56:40 openvpn 90032 config = '/var/etc/openvpn/server3/config.ovpn' Mar 3 03:56:40 openvpn 90032 Current Parameter Settings: Mar 3 03:56:40 openvpn 90032 WARNING: Compression for receiving enabled. Compression has been used in the past to break encryption. Sent packets are not compressed unless "allow-compression yes" is also set. Mar 3 03:56:40 openvpn 73327 SIGTERM[hard,] received, process exiting Mar 3 03:56:40 openvpn 73327 PLUGIN_CLOSE: /usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so Mar 3 03:56:40 openvpn 73327 /usr/local/sbin/ovpn-linkdown ovpns3 1500 1622 172.16.71.1 255.255.255.0 init Mar 3 03:56:40 openvpn 73327 Closing TUN/TAP interface Mar 3 03:56:40 openvpn 73327 event_wait : Interrupted system call (code=4)Unless the remote server issues are causing the VPN client to crash these are a red herring.
Any thoughts?
-
@guardian said in pfSense 2.6.0 Fails to Recover after WAN Issues:
BTW what speed service/modem do you have. I have GB/Hitron CPDA-4582U.
I have a Technicolor CGM4140COM in bridge mode. I pay for 500/30, but get over 900 Mb down and 32 up.
-
Yeah having servers and clients makes things confusing. A server running on TCP port 443 is going to see those packet size errors because https connection attempts if it's open to any external IP.
We probably need to see the OpenVPN logs from the client then. Ideally at the point it tries to connect but fails to pass traffic.
