Packages Restarting
-
Not sure if this is the same problem mentioned here:
https://forum.netgate.com/topic/174723/hotplug-event-causes-rc-start_packages-restarting-starting-all-packages/49but my router is frequently going offline. Seems to happen when my back-up (failover ) goes down. However, Gateway Monitoring and Gateway Action are disabled for the failover WAN. Per the above msg thread, I've enabled DHCP6 on both the primary and failover WAN.
Sep 4 18:43:30 php-fpm 383 /status_logs.php: Configuration Change: User1@10.101.11.ZZZ (Local Database): Log Display Settings Saved (no backup, no sync): General Sep 4 18:41:42 nginx 2023/09/04 18:41:42 [crit] 71527#100276: *11791 SSL_write() failed (13: Permission denied) while processing HTTP/2 connection, client: 10.101.11.ZZZ, server: 0.0.0.0:443 Sep 4 18:41:03 php_pfb 76080 [pfBlockerNG] filterlog daemon started Sep 4 18:41:03 php 76582 [pfBlockerNG] DNSBL parser daemon started Sep 4 18:41:01 tail_pfb 76054 [pfBlockerNG] Firewall Filter Service started Sep 4 18:41:01 lighttpd_pfb 75286 [pfBlockerNG] DNSBL Webserver started Sep 4 18:41:01 lighttpd_pfb 73387 [pfBlockerNG] DNSBL Webserver stopped Sep 4 18:41:01 php_pfb 72379 [pfBlockerNG] filterlog daemon stopped Sep 4 18:41:01 tail_pfb 71968 [pfBlockerNG] Firewall Filter Service stopped Sep 4 18:41:01 vnstatd 70474 Error: pidfile "/var/run/vnstat/vnstat.pid" lock failed (Resource temporarily unavailable), exiting. Sep 4 18:41:01 vnstatd 68807 Monitoring (14): pfsync0 (1000 Mbit) pflog0 (1000 Mbit) ovpns1 (1000 Mbit) ovpnc3 (1000 Mbit) igb2.31 (1000 Mbit) igb2.251 (1000 Mbit) igb2.111 (1000 Mbit) igb2.11 (1000 Mbit) igb2.101 (1000 Mbit) igb2.1 (1000 Mbit) igb2 (1000 Mbit) igb1 (1000 Mbit) igb0 (100 Mbit) enc0 (1000 Mbit) Sep 4 18:41:01 vnstatd 68807 vnStat daemon 2.10 started. (pid:68807 uid:0 gid:0) Sep 4 18:41:01 vnstatd 1625 SIGTERM received, exiting. Sep 4 18:40:50 vnstatd 60195 Error: pidfile "/var/run/vnstat/vnstat.pid" lock failed (Resource temporarily unavailable), exiting. Sep 4 18:40:47 upsmon 77613 Communications with UPS upsNetwork established Sep 4 18:40:47 upsd 79096 User local-monitor@::1 logged into UPS [upsNetwork] Sep 4 18:40:45 upsd 79096 Connected to UPS [upsNetwork]: usbhid-ups-upsNetwork Sep 4 18:40:43 usbhid-ups 80740 Startup successful Sep 4 18:40:43 upsd 79096 Startup successful Sep 4 18:40:43 upsd 79034 Can't connect to UPS [upsNetwork] (usbhid-ups-upsNetwork): Connection refused Sep 4 18:40:43 upsd 79034 listening on 127.0.0.1 port 3493 Sep 4 18:40:43 upsd 79034 listening on ::1 port 3493 Sep 4 18:40:42 upsmon 77613 Communications with UPS upsNetwork lost Sep 4 18:40:42 upsmon 77613 UPS [upsNetwork]: connect failed: Connection failure: Connection refused Sep 4 18:40:42 upsmon 77575 Startup successful Sep 4 18:40:40 usbhid-ups 74562 Startup successful Sep 4 18:40:40 upsd 74274 Startup successful Sep 4 18:40:40 upsd 74005 Can't connect to UPS [upsNetwork] (usbhid-ups-upsNetwork): No such file or directory Sep 4 18:40:40 upsd 74005 listening on 127.0.0.1 port 3493 Sep 4 18:40:40 upsd 74005 listening on ::1 port 3493 Sep 4 18:40:39 upsmon 52306 Communications with UPS upsNetwork lost Sep 4 18:40:39 upsmon 52306 UPS [upsNetwork]: connect failed: Connection failure: Connection refused Sep 4 18:40:39 upsmon 51471 Startup successful Sep 4 18:40:39 php-fpm 90488 /rc.start_packages: Starting service nut Sep 4 18:40:39 usbhid-ups 9444 Signal 15: exiting Sep 4 18:40:39 upsd 8339 Signal 15: exiting Sep 4 18:40:39 upsd 8339 mainloop: Interrupted system call Sep 4 18:40:39 upsmon 6299 Signal 15: exiting Sep 4 18:40:39 php-fpm 90488 /rc.start_packages: Stopping service nut Sep 4 18:40:39 php-fpm 90488 /rc.start_packages: Restarting/Starting all packages. Sep 4 18:40:37 check_reload_status 412 Reloading filter Sep 4 18:40:37 check_reload_status 412 Starting packages Sep 4 18:40:37 php-fpm 85288 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 192.168.5.XX -> 30.XXX.XXX.XXX - Restarting packages. Sep 4 18:40:35 php-fpm 85288 /rc.newwanip: Creating rrd update script Sep 4 18:40:35 php-fpm 85288 /rc.newwanip: Resyncing OpenVPN instances for interface WANSEC. Sep 4 18:40:35 php-fpm 85288 /rc.newwanip: IP Address has changed, killing all states (ip_change_kill_states is set). Sep 4 18:40:32 php-fpm 85288 /rc.newwanip: Removing static route for monitor 9.9.9.9 and adding a new route through 38.XX.XX.XX Sep 4 18:40:24 rtsold 68073 <cap_rssend> sendmsg on igb1: Permission denied Sep 4 18:40:20 rtsold 68073 <cap_rssend> sendmsg on igb1: Permission denied Sep 4 18:40:16 check_reload_status 412 Reloading filter Sep 4 18:40:16 rtsold 68073 <cap_rssend> sendmsg on igb1: Permission denied Sep 4 18:40:16 php-fpm 75382 /rc.linkup: Removing static route for monitor 9.9.9.9 and adding a new route through 38.XX.XX.XX Sep 4 18:40:16 check_reload_status 412 updating dyndns opt6 Sep 4 18:40:16 check_reload_status 412 Restarting IPsec tunnels Sep 4 18:40:13 php-fpm 75382 /rc.linkup: Starting rtsold process on opt6(igb1) Sep 4 18:40:13 php-fpm 75382 /rc.linkup: Starting DHCP6 client for interfaces igb0,igb1 in DHCP6 without RA mode Sep 4 18:40:13 php-fpm 85288 /rc.newwanip: rc.newwanip: on (IP address: 30.XXX.XXX.XXX) (interface: WANSEC[opt6]) (real interface: igb1). Sep 4 18:40:13 php-fpm 85288 /rc.newwanip: rc.newwanip: Info: starting on igb1. Sep 4 18:40:12 php-fpm 75382 /rc.linkup: Accept router advertisements on interface igb1 Sep 4 18:40:12 php-fpm 75382 /rc.linkup: Accept router advertisements on interface igb0 Sep 4 18:40:12 php-fpm 75382 /rc.linkup: calling interface_dhcpv6_configure. Sep 4 18:40:12 check_reload_status 412 rc.newwanip starting igb1 Sep 4 18:40:07 php-fpm 75382 /rc.linkup: HOTPLUG: Configuring interface opt6 Sep 4 18:40:07 php-fpm 75382 /rc.linkup: DEVD Ethernet attached event for opt6 Sep 4 18:40:07 php-fpm 75382 /rc.linkup: Hotplug event detected for WANSEC(opt6) dynamic IP address (4: dhcp, 6: dhcp6) Sep 4 18:40:06 kernel igb1: link state changed to UP Sep 4 18:40:06 check_reload_status 412 Linkup starting igb1 Sep 4 18:40:01 php_pfb 13536 [pfBlockerNG] filterlog daemon started Sep 4 18:40:00 php 9976 [pfBlockerNG] DNSBL parser daemon started Sep 4 18:39:59 tail_pfb 12215 [pfBlockerNG] Firewall Filter Service started Sep 4 18:39:59 nginx 2023/09/04 18:39:59 [crit] 71527#100276: *11768 SSL_write() failed (13: Permission denied) while processing HTTP/2 connection, client: 10.101.11.ZZZ, server: 0.0.0.0:443 Sep 4 18:39:59 lighttpd_pfb 7261 [pfBlockerNG] DNSBL Webserver started Sep 4 18:39:59 lighttpd_pfb 5403 [pfBlockerNG] DNSBL Webserver stopped Sep 4 18:39:59 php_pfb 5152 [pfBlockerNG] filterlog daemon stopped Sep 4 18:39:59 tail_pfb 4955 [pfBlockerNG] Firewall Filter Service stopped Sep 4 18:39:59 vnstatd 1625 Monitoring (14): pfsync0 (1000 Mbit) pflog0 (1000 Mbit) ovpns1 (1000 Mbit) ovpnc3 (1000 Mbit) igb2.31 (1000 Mbit) igb2.251 (1000 Mbit) igb2.111 (1000 Mbit) igb2.11 (1000 Mbit) igb2.101 (1000 Mbit) igb2.1 (1000 Mbit) igb2 (1000 Mbit) igb1 (1000 Mbit) igb0 (100 Mbit) enc0 (1000 Mbit) Sep 4 18:39:59 vnstatd 1625 vnStat daemon 2.10 started. (pid:1625 uid:0 gid:0) Sep 4 18:39:59 vnstatd 3311 Error: pidfile "/var/run/vnstat/vnstat.pid" lock failed (Resource temporarily unavailable), exiting. Sep 4 18:39:59 vnstatd 83106 SIGTERM received, exiting. Sep 4 18:39:57 check_reload_status 412 Reloading filter Sep 4 18:39:56 php-fpm 383 /rc.linkup: Removing static route for monitor 9.9.9.9 and adding a new route through 38.XX.XX.XX Sep 4 18:39:56 php-fpm 383 /rc.linkup: Starting DHCP6 client for interfaces igb0 in DHCP6 without RA mode Sep 4 18:39:55 php-fpm 383 /rc.linkup: Accept router advertisements on interface igb0 Sep 4 18:39:54 php-fpm 383 /rc.linkup: DEVD Ethernet detached event for opt6 Sep 4 18:39:54 php-fpm 383 /rc.linkup: Hotplug event detected for WANSEC(opt6) dynamic IP address (4: dhcp, 6: dhcp6) Sep 4 18:39:53 check_reload_status 412 Linkup starting igb1 Sep 4 18:39:53 kernel igb1: link state changed to DOWN Sep 4 18:39:48 vnstatd 83838 Error: pidfile "/var/run/vnstat/vnstat.pid" lock failed (Resource temporarily unavailable), exiting. Sep 4 18:39:44 upsmon 6299 Communications with UPS upsNetwork established Sep 4 18:39:44 upsd 8339 User local-monitor@::1 logged into UPS [upsNetwork] Sep 4 18:39:42 upsd 8339 Connected to UPS [upsNetwork]: usbhid-ups-upsNetwork Sep 4 18:39:41 usbhid-ups 9444 Startup successful Sep 4 18:39:40 upsd 8339 Startup successful Sep 4 18:39:40 upsd 8140 Can't connect to UPS [upsNetwork] (usbhid-ups-upsNetwork): Connection refused Sep 4 18:39:40 upsd 8140 listening on 127.0.0.1 port 3493 Sep 4 18:39:40 upsd 8140 listening on ::1 port 3493 Sep 4 18:39:39 upsmon 6299 Communications with UPS upsNetwork lost Sep 4 18:39:39 upsmon 6299 UPS [upsNetwork]: connect failed: Connection failure: Connection refused Sep 4 18:39:39 upsmon 6252 Startup successful Sep 4 18:39:37 upsd 4249 Startup successful Sep 4 18:39:37 upsd 4073 Connected to UPS [upsNetwork]: usbhid-ups-upsNetwork Sep 4 18:39:37 upsd 4073 listening on 127.0.0.1 port 3493 Sep 4 18:39:37 upsd 4073 listening on ::1 port 3493 Sep 4 18:39:37 usbhid-ups 3881 Startup successful Sep 4 18:39:36 upsmon 81310 Communications with UPS upsNetwork lost Sep 4 18:39:36 upsmon 81310 UPS [upsNetwork]: connect failed: Connection failure: Connection refused Sep 4 18:39:36 upsmon 80773 Startup successful Sep 4 18:39:36 usbhid-ups 10908 Signal 15: exiting Sep 4 18:39:36 php-fpm 34325 /rc.start_packages: Starting service nut Sep 4 18:39:36 upsd 10737 Signal 15: exiting Sep 4 18:39:36 upsd 10737 mainloop: Interrupted system call Sep 4 18:39:36 upsmon 7991 upsmon parent: read Sep 4 18:39:36 upsmon 8464 Signal 15: exiting Sep 4 18:39:36 php-fpm 34325 /rc.start_packages: Stopping service nut Sep 4 18:39:36 php-fpm 34325 /rc.start_packages: Restarting/Starting all packages. Sep 4 18:39:35 check_reload_status 412 Reloading filter Sep 4 18:39:35 check_reload_status 412 Starting packages Sep 4 18:39:35 php-fpm 85288 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 33.XXX.XXX.XXX -> 192.168.5.XX - Restarting packages. Sep 4 18:39:33 php-fpm 85288 /rc.newwanip: Creating rrd update script Sep 4 18:39:33 php-fpm 85288 /rc.newwanip: Resyncing OpenVPN instances for interface WANSEC. Sep 4 18:39:33 php-fpm 85288 /rc.newwanip: IP Address has changed, killing all states (ip_change_kill_states is set). Sep 4 18:39:30 php-fpm 85288 /rc.newwanip: Removing static route for monitor 9.9.9.9 and adding a new route through 38.XX.XX.XX Sep 4 18:39:21 rtsold 6694 <cap_rssend> sendmsg on igb1: Permission denied Sep 4 18:39:17 rtsold 6694 <cap_rssend> sendmsg on igb1: Permission denied Sep 4 18:39:14 check_reload_status 412 Reloading filter Sep 4 18:39:13 rtsold 6694 <cap_rssend> sendmsg on igb1: Permission denied Sep 4 18:39:13 php-fpm 90488 /rc.linkup: Removing static route for monitor 9.9.9.9 and adding a new route through 38.XX.XX.XX Sep 4 18:39:13 check_reload_status 412 updating dyndns opt6 Sep 4 18:39:13 check_reload_status 412 Restarting IPsec tunnels Sep 4 18:39:11 php-fpm 90488 /rc.linkup: Starting rtsold process on opt6(igb1) Sep 4 18:39:11 php-fpm 90488 /rc.linkup: Starting DHCP6 client for interfaces igb0,igb1 in DHCP6 without RA mode Sep 4 18:39:11 php-fpm 85288 /rc.newwanip: rc.newwanip: on (IP address: 192.168.5.XX) (interface: WANSEC[opt6]) (real interface: igb1). Sep 4 18:39:11 php-fpm 85288 /rc.newwanip: rc.newwanip: Info: starting on igb1. Sep 4 18:39:10 php-fpm 90488 /rc.linkup: Accept router advertisements on interface igb1 Sep 4 18:39:10 php-fpm 90488 /rc.linkup: Accept router advertisements on interface igb0 Sep 4 18:39:10 php-fpm 90488 /rc.linkup: calling interface_dhcpv6_configure. Sep 4 18:39:10 check_reload_status 412 rc.newwanip starting igb1 Sep 4 18:39:06 upsmon 8464 Communications with UPS upsNetwork established Sep 4 18:39:06 upsd 10737 User local-monitor@::1 logged into UPS [upsNetwork] Sep 4 18:39:05 php-fpm 90488 /rc.linkup: HOTPLUG: Configuring interface opt6 Sep 4 18:39:05 php-fpm 90488 /rc.linkup: DEVD Ethernet attached event for opt6 Sep 4 18:39:05 php-fpm 90488 /rc.linkup: Hotplug event detected for WANSEC(opt6) dynamic IP address (4: dhcp, 6: dhcp6) Sep 4 18:39:04 kernel igb1: link state changed to UP Sep 4 18:39:04 check_reload_status 412 Linkup starting igb1 Sep 4 18:39:02 upsd 10737 Connected to UPS [upsNetwork]: usbhid-ups-upsNetwork Sep 4 18:39:02 usbhid-ups 10908 Startup successful Sep 4 18:39:02 upsd 10737 Startup successful Sep 4 18:39:02 upsd 9657 Can't connect to UPS [upsNetwork] (usbhid-ups-upsNetwork): Connection refused Sep 4 18:39:02 upsd 9657 listening on 127.0.0.1 port 3493 Sep 4 18:39:02 upsd 9657 listening on ::1 port 3493 Sep 4 18:39:01 upsmon 8464 Communications with UPS upsNetwork lost Sep 4 18:39:01 upsmon 8464 UPS [upsNetwork]: connect failed: Connection failure: Connection refused Sep 4 18:39:01 upsmon 7991 Startup successful Sep 4 18:39:01 php-cgi 1242 servicewatchdog_cron.php: Service Watchdog detected service nut stopped. Restarting nut (UPS monitoring daemon) Sep 4 18:39:00 sshguard 1874 Now monitoring attacks. Sep 4 18:39:00 sshguard 52385 Exiting on signal. Sep 4 18:38:59 check_reload_status 412 Reloading filter Sep 4 18:38:59 php-fpm 74296 /rc.linkup: Removing static route for monitor 9.9.9.9 and adding a new route through 38.XX.XX.XX Sep 4 18:38:59 php-fpm 74296 /rc.linkup: Starting DHCP6 client for interfaces igb0 in DHCP6 without RA mode Sep 4 18:38:58 php-fpm 74296 /rc.linkup: Accept router advertisements on interface igb0 Sep 4 18:38:57 php-fpm 74296 /rc.linkup: DEVD Ethernet detached event for opt6 Sep 4 18:38:57 php-fpm 74296 /rc.linkup: Hotplug event detected for WANSEC(opt6) dynamic IP address (4: dhcp, 6: dhcp6) Sep 4 18:38:56 kernel igb1: link state changed to DOWN Sep 4 18:38:56 check_reload_status 412 Linkup starting igb1 Sep 4 18:38:28 php_pfb 90598 [pfBlockerNG] filterlog daemon started Sep 4 18:38:28 php 88420 [pfBlockerNG] DNSBL parser daemon started Sep 4 18:38:27 php-fpm 85288 /index.php: Successful login for user 'User1' from: 10.101.11.ZZZ (Local Database) Sep 4 18:38:27 tail_pfb 90224 [pfBlockerNG] Firewall Filter Service started Sep 4 18:38:26 php_pfb 87232 [pfBlockerNG] filterlog daemon stopped Sep 4 18:38:26 lighttpd_pfb 87578 [pfBlockerNG] DNSBL Webserver started Sep 4 18:38:26 tail_pfb 86578 [pfBlockerNG] Firewall Filter Service stopped Sep 4 18:38:26 lighttpd_pfb 85518 [pfBlockerNG] DNSBL Webserver stopped Sep 4 18:38:26 vnstatd 83106 Monitoring (14): pfsync0 (1000 Mbit) pflog0 (1000 Mbit) ovpns1 (1000 Mbit) ovpnc3 (1000 Mbit) igb2.31 (1000 Mbit) igb2.251 (1000 Mbit) igb2.111 (1000 Mbit) igb2.11 (1000 Mbit) igb2.101 (1000 Mbit) igb2.1 (1000 Mbit) igb2 (1000 Mbit) igb1 (1000 Mbit) igb0 (100 Mbit) enc0 (1000 Mbit) Sep 4 18:38:26 vnstatd 83106 vnStat daemon 2.10 started. (pid:83106 uid:0 gid:0) Sep 4 18:38:26 vnstatd 84277 Error: pidfile "/var/run/vnstat/vnstat.pid" lock failed (Resource temporarily unavailable), exiting. Sep 4 18:38:26 vnstatd 35668 SIGTERM received, exiting. Sep 4 18:38:16 vnstatd 73930 Error: pidfile "/var/run/vnstat/vnstat.pid" lock failed (Resource temporarily unavailable), exiting. Sep 4 18:38:10 upsd 97781 Connected to UPS [upsNetwork]: usbhid-ups-upsNetwork Sep 4 18:38:08 usbhid-ups 97831 Startup successful Sep 4 18:38:08 upsd 97781 Startup successful Sep 4 18:38:08 upsd 97563 Can't connect to UPS [upsNetwork] (usbhid-ups-upsNetwork): Connection refused Sep 4 18:38:08 upsd 97563 listening on 127.0.0.1 port 3493 Sep 4 18:38:08 upsd 97563 listening on ::1 port 3493 Sep 4 18:38:05 upsd 94399 Startup successful Sep 4 18:38:05 upsd 94217 Connected to UPS [upsNetwork]: usbhid-ups-upsNetwork Sep 4 18:38:05 upsd 94217 listening on 127.0.0.1 port 3493 Sep 4 18:38:05 upsd 94217 listening on ::1 port 3493 Sep 4 18:38:04 usbhid-ups 89403 Startup successful Sep 4 18:38:04 upsmon 69087 Communications with UPS upsNetwork lost Sep 4 18:38:04 upsmon 69087 UPS [upsNetwork]: connect failed: Connection failure: Connection refused Sep 4 18:38:04 upsmon 67978 Startup successful Sep 4 18:38:04 php-fpm 90488 /rc.start_packages: Starting service nut Sep 4 18:38:04 usbhid-ups 50723 Signal 15: exiting Sep 4 18:38:04 upsd 49915 Signal 15: exiting Sep 4 18:38:04 upsd 49915 mainloop: Interrupted system call Sep 4 18:38:04 upsmon 48021 Signal 15: exiting Sep 4 18:38:04 php-fpm 90488 /rc.start_packages: Stopping service nut Sep 4 18:38:04 php-fpm 90488 /rc.start_packages: Restarting/Starting all packages. Sep 4 18:38:02 check_reload_status 412 Reloading filter Sep 4 18:38:02 check_reload_status 412 Starting packages Sep 4 18:38:02 php-fpm 383 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 192.168.5.XX -> 33.XXX.XXX.XX - Restarting packages. Sep 4 18:38:02 upsmon 48021 Communications with UPS upsNetwork lost Sep 4 18:38:02 upsmon 48021 Poll UPS [upsNetwork] failed - Write error: Permission denied Sep 4 18:38:00 php-fpm 383 /rc.newwanip: Creating rrd update script Sep 4 18:38:00 php-fpm 383 /rc.newwanip: Resyncing OpenVPN instances for interface WANSEC. Sep 4 18:38:00 php-fpm 383 /rc.newwanip: IP Address has changed, killing all states (ip_change_kill_states is set). Sep 4 18:37:57 php-fpm 383 /rc.newwanip: Removing static route for monitor 9.9.9.9 and adding a new route through 38.XX.XX.XX Sep 4 18:37:49 php 43905 [pfBlockerNG] DNSBL parser daemon started Sep 4 18:37:49 php_pfb 43380 [pfBlockerNG] filterlog daemon started Sep 4 18:37:48 rtsold 76174 <cap_rssend> sendmsg on igb1: Permission denied Sep 4 18:37:47 lighttpd_pfb 43247 [pfBlockerNG] DNSBL Webserver started Sep 4 18:37:47 tail_pfb 43077 [pfBlockerNG] Firewall Filter Service started Sep 4 18:37:47 lighttpd_pfb 39309 [pfBlockerNG] DNSBL Webserver stopped Sep 4 18:37:47 php_pfb 38929 [pfBlockerNG] filterlog daemon stopped Sep 4 18:37:47 tail_pfb 38700 [pfBlockerNG] Firewall Filter Service stopped Sep 4 18:37:46 vnstatd 37887 Error: pidfile "/var/run/vnstat/vnstat.pid" lock failed (Resource temporarily unavailable), exiting. Sep 4 18:37:46 vnstatd 35668 Monitoring (14): pfsync0 (1000 Mbit) pflog0 (1000 Mbit) ovpns1 (1000 Mbit) ovpnc3 (1000 Mbit) igb2.31 (1000 Mbit) igb2.251 (1000 Mbit) igb2.111 (1000 Mbit) igb2.11 (1000 Mbit) igb2.101 (1000 Mbit) igb2.1 (1000 Mbit) igb2 (1000 Mbit) igb1 (1000 Mbit) igb0 (100 Mbit) enc0 (1000 Mbit) Sep 4 18:37:46 vnstatd 35668 vnStat daemon 2.10 started. (pid:35668 uid:0 gid:0) Sep 4 18:37:46 vnstatd 81540 SIGTERM received, exiting. Sep 4 18:37:44 rtsold 76174 <cap_rssend> sendmsg on igb1: Permission denied Sep 4 18:37:40 rtsold 76174 <cap_rssend> sendmsg on igb1: Permission denied Sep 4 18:37:40 check_reload_status 412 Reloading filter Sep 4 18:37:40 php-fpm 85288 /rc.linkup: Removing static route for monitor 9.9.9.9 and adding a new route through 38.XX.XX.XX Sep 4 18:37:40 check_reload_status 412 updating dyndns opt6 Sep 4 18:37:40 check_reload_status 412 Restarting IPsec tunnels Sep 4 18:37:38 php-fpm 85288 /rc.linkup: Starting rtsold process on opt6(igb1) Sep 4 18:37:38 php-fpm 85288 /rc.linkup: Starting DHCP6 client for interfaces igb0,igb1 in DHCP6 without RA mode Sep 4 18:37:38 php-fpm 383 /rc.newwanip: rc.newwanip: on (IP address: 33.254.211.57) (interface: WANSEC[opt6]) (real interface: igb1). Sep 4 18:37:38 php-fpm 383 /rc.newwanip: rc.newwanip: Info: starting on igb1. Sep 4 18:37:37 php-fpm 85288 /rc.linkup: Accept router advertisements on interface igb1 Sep 4 18:37:37 php-fpm 85288 /rc.linkup: Accept router advertisements on interface igb0 Sep 4 18:37:37 php-fpm 85288 /rc.linkup: calling interface_dhcpv6_configure. Sep 4 18:37:37 check_reload_status 412 rc.newwanip starting igb1 Sep 4 18:37:36 vnstatd 50743 Error: pidfile "/var/run/vnstat/vnstat.pid" lock failed (Resource temporarily unavailable), exiting. Sep 4 18:37:32 php-fpm 85288 /rc.linkup: HOTPLUG: Configuring interface opt6 Sep 4 18:37:32 php-fpm 85288 /rc.linkup: DEVD Ethernet attached event for opt6 Sep 4 18:37:32 php-fpm 85288 /rc.linkup: Hotplug event detected for WANSEC(opt6) dynamic IP address (4: dhcp, 6: dhcp6) Sep 4 18:37:31 upsmon 48021 Communications with UPS upsNetwork established Sep 4 18:37:31 upsd 49915 User local-monitor@::1 logged into UPS [upsNetwork] Sep 4 18:37:31 kernel igb1: link state changed to UP Sep 4 18:37:31 check_reload_status 412 Linkup starting igb1 Sep 4 18:37:29 upsd 49915 Connected to UPS [upsNetwork]: usbhid-ups-upsNetwork Sep 4 18:37:28 usbhid-ups 50723 Startup successful Sep 4 18:37:27 upsd 49915 Startup successful Sep 4 18:37:27 upsd 49584 Can't connect to UPS [upsNetwork] (usbhid-ups-upsNetwork): Connection refused Sep 4 18:37:27 upsd 49584 listening on 127.0.0.1 port 3493 Sep 4 18:37:27 upsd 49584 listening on ::1 port 3493 Sep 4 18:37:26 upsmon 48021 Communications with UPS upsNetwork lost Sep 4 18:37:26 upsmon 48021 UPS [upsNetwork]: connect failed: Connection failure: Connection refused Sep 4 18:37:26 upsmon 47776 Startup successful Sep 4 18:37:26 check_reload_status 412 Reloading filter Sep 4 18:37:26 php-fpm 51040 /rc.linkup: Removing static route for monitor 9.9.9.9 and adding a new route through 38.XX.XX.XX Sep 4 18:37:26 php-fpm 51040 /rc.linkup: Starting DHCP6 client for interfaces igb0 in DHCP6 without RA mode Sep 4 18:37:25 php-fpm 51040 /rc.linkup: Accept router advertisements on interface igb0 Sep 4 18:37:25 usbhid-ups 39689 Startup successful Sep 4 18:37:24 upsd 39563 Startup successful Sep 4 18:37:24 upsd 39267 Can't connect to UPS [upsNetwork] (usbhid-ups-upsNetwork): No such file or directory Sep 4 18:37:24 upsd 39267 listening on 127.0.0.1 port 3493 Sep 4 18:37:24 upsd 39267 listening on ::1 port 3493 Sep 4 18:37:24 php-fpm 51040 /rc.linkup: DEVD Ethernet detached event for opt6 Sep 4 18:37:24 php-fpm 51040 /rc.linkup: Hotplug event detected for WANSEC(opt6) dynamic IP address (4: dhcp, 6: dhcp6) Sep 4 18:37:23 upsmon 19607 Communications with UPS upsNetwork lost Sep 4 18:37:23 upsmon 19607 UPS [upsNetwork]: connect failed: Connection failure: Connection refused Sep 4 18:37:23 upsmon 18613 Startup successful Sep 4 18:37:23 php-fpm 75382 /rc.start_packages: Starting service nut Sep 4 18:37:23 usbhid-ups 7082 Signal 15: exiting Sep 4 18:37:23 upsd 97612 Signal 15: exiting Sep 4 18:37:23 upsd 97612 mainloop: Interrupted system call Sep 4 18:37:23 upsmon 95636 Signal 15: exiting Sep 4 18:37:23 php-fpm 75382 /rc.start_packages: Stopping service nut Sep 4 18:37:23 php-fpm 75382 /rc.start_packages: Restarting/Starting all packages. Sep 4 18:37:23 check_reload_status 412 Linkup starting igb1 Sep 4 18:37:23 kernel igb1: link state changed to DOWN Sep 4 18:37:23 upsmon 95636 Communications with UPS upsNetwork lost Sep 4 18:37:23 upsmon 95636 Poll UPS [upsNetwork] failed - Write error: Permission denied Sep 4 18:37:22 check_reload_status 412 Reloading filter Sep 4 18:37:22 check_reload_status 412 Starting packages Sep 4 18:37:22 php-fpm 34325 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 30.XXX.XXX.XXX -> 192.168.5.XX - Restarting packages. Sep 4 18:37:20 php-fpm 34325 /rc.newwanip: Creating rrd update script Sep 4 18:37:20 php-fpm 34325 /rc.newwanip: Resyncing OpenVPN instances for interface WANSEC. Sep 4 18:37:19 php-fpm 34325 /rc.newwanip: IP Address has changed, killing all states (ip_change_kill_states is set). Sep 4 18:37:17 php-fpm 34325 /rc.newwanip: Removing static route for monitor 9.9.9.9 and adding a new route through 38.XX.XX.XX Sep 4 18:37:08 rtsold 8065 <cap_rssend> sendmsg on igb1: Permission denied Sep 4 18:37:04 rtsold 8065 <cap_rssend> sendmsg on igb1: Permission denied Sep 4 18:37:01 check_reload_status 412 Reloading filter Sep 4 18:37:00 php-fpm 90488 /rc.linkup: Removing static route for monitor 9.9.9.9 and adding a new route through 38.XX.XX.XX Sep 4 18:37:00 check_reload_status 412 updating dyndns opt6 Sep 4 18:37:00 check_reload_status 412 Restarting IPsec tunnels Sep 4 18:37:00 rtsold 8065 <cap_rssend> sendmsg on igb1: Permission denied Sep 4 18:36:58 php-fpm 90488 /rc.linkup: Starting rtsold process on opt6(igb1) Sep 4 18:36:58 php-fpm 90488 /rc.linkup: Starting DHCP6 client for interfaces igb0,igb1 in DHCP6 without RA mode Sep 4 18:36:58 php-fpm 34325 /rc.newwanip: rc.newwanip: on (IP address: 192.168.5.XX) (interface: WANSEC[opt6]) (real interface: igb1). Sep 4 18:36:58 php-fpm 34325 /rc.newwanip: rc.newwanip: Info: starting on igb1. Sep 4 18:36:57 php-fpm 90488 /rc.linkup: Accept router advertisements on interface igb1 Sep 4 18:36:57 php-fpm 90488 /rc.linkup: Accept router advertisements on interface igb0 Sep 4 18:36:57 php-fpm 90488 /rc.linkup: calling interface_dhcpv6_configure. Sep 4 18:36:57 check_reload_status 412 rc.newwanip starting igb1 Sep 4 18:36:52 php-fpm 90488 /rc.linkup: HOTPLUG: Configuring interface opt6 Sep 4 18:36:52 php-fpm 90488 /rc.linkup: DEVD Ethernet attached event for opt6 Sep 4 18:36:52 php-fpm 90488 /rc.linkup: Hotplug event detected for WANSEC(opt6) dynamic IP address (4: dhcp, 6: dhcp6) Sep 4 18:36:51 kernel igb1: link state changed to UP Sep 4 18:36:51 check_reload_status 412 Linkup starting igb1 Sep 4 18:36:42 check_reload_status 412 Reloading filter Sep 4 18:36:42 php-fpm 74296 /rc.linkup: Removing static route for monitor 9.9.9.9 and adding a new route through 38.XX.XX.XX Sep 4 18:36:42 php-fpm 74296 /rc.linkup: Starting DHCP6 client for interfaces igb0 in DHCP6 without RA mode Sep 4 18:36:41 php-fpm 74296 /rc.linkup: Accept router advertisements on interface igb0 Sep 4 18:36:40 php-fpm 74296 /rc.linkup: DEVD Ethernet detached event for opt6 Sep 4 18:36:40 php-fpm 74296 /rc.linkup: Hotplug event detected for WANSEC(opt6) dynamic IP address (4: dhcp, 6: dhcp6) Sep 4 18:36:38 check_reload_status 412 Linkup starting igb1 Sep 4 18:36:38 kernel igb1: link state changed to DOWN Sep 4 18:08:00 sshguard 52385 Now monitoring attacks. -
X Ximulate referenced this topic on
-
igb1 is the backup WAN?
The issue in the linked thread is if an internal interface changes state and it not set to track a WAN for IPv6. So this is not that.
Packages should restart if a WAN changes IP. Anything that uses that IP would need to.
What is igb1 connected to? Why is it losing link to that?
Steve
-
@stephenw10 Yes, igb1 is the backup WAN. Its connected to a Netgear LB1121 (https://www.netgear.com/support/product/lb1121).
I have the Gateway Group set-up as a standard Failover, per the docs. So igb1 is Tier 2. Last night, I Enabled Gateway Monitoring & Gateway Action with default Monitoring IP. And, rebooted the router and the Netgear modem. Per the log, things calmed down then about 2:30am it picked up again thru about abput 4am. Since 4am I haven't seen any package restarts.
On a whim, I just deleted two cron jobs (one was a shutdown -r) but neither were scheduled for those times.
My primary Gateway (igb0) is a wISP. The bandwidth gets saturated at times, eventually leading to the failover. That was happening a lot the last several days (holiday weekend, so the wISP gets hammered by its customers).
Would frequent switching between gateways cause this? I've tried bumping up probe times (& related settings). Not really sure how else to deal with the GG switching during these episodes. I've also wondered if the Monitoring IP might be an issue; perhaps 1.1.1.1, 8.8.8.8, 9.9.9.9, etc are throttling the probes.
Other thing is, I didn't notice this until recently & wonder if its a V2.7 issue.
-
I wouldn't expect to see igb1 actually lose link whatever the gateway is doing. Does the Netgear modem device also log a loss of link?
-
I don't see a way to read logs from the Netgear LTE modem.
The router logs show this activity on until about 4am again, then calm. Issue picked up again this morning, I suspect about the time I turned on the Android TV. This morning I decided to disconnect the Neatgear LTE modem. So far, no issues.
I'm now wondering if the Primary WAN Latency Threshold & Packet Loss Threshold are too low, currently:
Latency: 350/500
Packet Loss: 15/35
So, AndroidTV (or some other devices) starts streaming, my wISP bandwidth get saturated. However, doesn't make sense that this is happening overnight until 4am. -
It also shouldn't cause the NIC to actually lose link. That should only happen if the NIC has it's setting changed or the other end of the link (the modem) drops it.
-
@stephenw10 Thanks. Since disconnecting the Netgear LTE modem, the system logs have been quiter. So maybe the modem or some other hardware issue (that I will narrow down.) To further complicate things, in reviewing last nights system log (below) its appears to me that maybe the wISP is losing connection or Quad9 is having issues. Reviewing logs from Sep 1, I see the same behaviour: GW_Primary alarm at 2:36am with various log e tries until about 04:00. I think this has been ongoing for some time, and I have tried different Monitor IPs during that time so I don't think its Quad9
Sep 7 03:49:24 php-fpm 87590 /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Sep 7 03:49:23 php-fpm 1107 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed IP addresses. Reloading endpoints that may use GW_Primary. Sep 7 03:49:21 check_reload_status 412 Reloading filter Sep 7 03:49:21 check_reload_status 412 Restarting OpenVPN tunnels/interfaces Sep 7 03:49:21 check_reload_status 412 Restarting IPsec tunnels Sep 7 03:49:21 check_reload_status 412 updating dyndns GW_Primary Sep 7 03:49:21 rc.gateway_alarm 95468 >>> Gateway alarm: GW_Primary (Addr:9.9.9.9 Alarm:0 RTT:23.544ms RTTsd:6.640ms Loss:0%) Sep 7 03:49:10 php-cgi 95611 notify_monitor.php: Message sent to dev.note@domain.org OK Sep 7 03:48:59 php-fpm 18413 /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Sep 7 03:48:58 php-fpm 22 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed IP addresses. Reloading endpoints that may use GW_Primary. Sep 7 03:48:58 php-fpm 22 9.9.9.9|38.XX.XX.Y7|GW_Primary|29.876ms|7.593ms|0.0%|online|none Sep 7 03:48:58 php-fpm 22 /rc.openvpn: MONITOR: GW_Primary is available now, adding to routing group GWG_Failover Sep 7 03:48:56 check_reload_status 412 Reloading filter Sep 7 03:48:56 check_reload_status 412 Restarting OpenVPN tunnels/interfaces Sep 7 03:48:56 check_reload_status 412 Restarting IPsec tunnels Sep 7 03:48:56 check_reload_status 412 updating dyndns GW_Primary Sep 7 03:48:56 rc.gateway_alarm 63076 >>> Gateway alarm: GW_Primary (Addr:9.9.9.9 Alarm:1 RTT:29.821ms RTTsd:7.671ms Loss:0%) Sep 7 03:47:44 php-fpm 383 /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Sep 7 03:47:43 php-fpm 1107 /rc.filter_configure_sync: An error occurred while trying to find the interface got 38.XX.XX.Y6 . The rule has not been added. Sep 7 03:47:43 php-fpm 3255 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed IP addresses. Reloading endpoints that may use GW_Primary. Sep 7 03:47:41 check_reload_status 412 Reloading filter Sep 7 03:47:41 check_reload_status 412 Restarting OpenVPN tunnels/interfaces Sep 7 03:47:41 check_reload_status 412 Restarting IPsec tunnels Sep 7 03:47:41 check_reload_status 412 updating dyndns GW_Primary Sep 7 03:47:41 rc.gateway_alarm 30240 >>> Gateway alarm: GW_Primary (Addr:9.9.9.9 Alarm:1 RTT:4219.342ms RTTsd:3736.108ms Loss:75%) Sep 7 03:45:01 php-cgi 82400 rc.filter_configure_sync: An error occurred while trying to find the interface got 38.XX.XX.Y6 . The rule has not been added. Sep 7 03:30:01 php-cgi 57273 rc.filter_configure_sync: An error occurred while trying to find the interface got 38.XX.XX.Y6 . The rule has not been added. Sep 7 03:15:02 php-cgi 83850 rc.filter_configure_sync: An error occurred while trying to find the interface got 38.XX.XX.Y6 . The rule has not been added. Sep 7 03:00:02 php-cgi 53983 rc.filter_configure_sync: An error occurred while trying to find the interface got 38.XX.XX.Y6 . The rule has not been added. Sep 7 02:45:01 php-cgi 21419 rc.filter_configure_sync: An error occurred while trying to find the interface got 38.XX.XX.Y6 . The rule has not been added. Sep 7 02:37:03 php-cgi 63727 notify_monitor.php: Could not send the message to dev.note@domain.org -- Error: Failed to connect to ssl://smtp.dreamhost.com:465 [SMTP: Failed to connect socket: php_network_getaddresses: getaddrinfo for smtp.dreamhost.com failed: Address family for hostname not supported (code: -1, response: )] Sep 7 02:36:28 php-fpm 22 /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Sep 7 02:36:27 php-fpm 87590 /rc.filter_configure_sync: An error occurred while trying to find the interface got 38.XX.XX.Y6 . The rule has not been added. Sep 7 02:36:26 php-fpm 8672 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed IP addresses. Reloading endpoints that may use GW_Primary. Sep 7 02:36:26 php-fpm 8672 9.9.9.9|38.XX.XX.Y7|GW_Primary|18.317ms|1.492ms|45%|down|highloss Sep 7 02:36:26 php-fpm 8672 /rc.openvpn: MONITOR: GW_Primary has packet loss, omitting from routing group GWG_Failover Sep 7 02:36:25 check_reload_status 412 Reloading filter Sep 7 02:36:25 check_reload_status 412 Restarting OpenVPN tunnels/interfaces Sep 7 02:36:25 check_reload_status 412 Restarting IPsec tunnels Sep 7 02:36:25 check_reload_status 412 updating dyndns GW_Primary Sep 7 02:36:25 rc.gateway_alarm 29639 >>> Gateway alarm: GW_Primary (Addr:9.9.9.9 Alarm:1 RTT:18.495ms RTTsd:1.552ms Loss:40%) -
Yeah sounds like maybe that modem has an issue. I would not expect it to lose link on the Ethernet like that. Does it really not log anything? I assume it has some sort of UI you have access to?
WISPs can be hard to tune the gateway monitoring for. You do need that and gateway action enabled though if you need to failover.
-
@stephenw10 The Netgear modem does have a simple UI, but no obvious way to view logs. I don't see anything in its manual either. It may require Netgear support to get involved.
-
Does it show uptime? Any way to know if it rebooted?
-
No, I don't see uptime or any other way to tell if its rebooted. I've tried different cables. I was going to try to swap-out the wall wart & put a switch between the router and the modem. Haven't done that yet. In the meantime, I'm corrosponding with the ISP about the nightly outages.
-
@stephenw10 Factory reset modem seems to have cleared up the link issue. ISP claims nightly outage is scheduled service
-
X Ximulate referenced this topic on
