Have I Found a bug?
-
I'm not sure if I have a bug/improper setup or if it's a fault with the provider.
Sometime after 17:00 (~17:02, 17:03 Best guess), my IP phone connection dropped and my wife's Zoom Connection dropped. I was able to ping 8.8.8.8 from my workstation, but could not bring up google.com from the web browser.
I attempted to log into the GUI, and it was unresponsive. After waiting about 30-45 seconds, I logged into the console with SSH and restarted pfSense which resolved the problem. (I didn't reset the cable modem)
FYI pfSense is connected to Rogers Cable Internet (500MB/s speed), for what it is worth. Thanks in advance for any assistance.
pfSense Log:Sep 17 13:54:57 guardian kernel: uhid0 on uhub2 Sep 17 13:54:57 guardian kernel: uhid0: <Logitech USB Keyboard, class 0/0, rev 1.10/64.02, addr 5> on usbus0 Sep 17 13:54:57 guardian kernel: uhid0: no report descriptor Sep 17 13:54:57 guardian kernel: device_attach: uhid0 attach returned 12 Sep 17 13:54:57 guardian kernel: ugen0.4: <Logitech USB Optical Mouse> at usbus0 (disconnected) Sep 17 13:54:57 guardian kernel: ugen0.5: <Logitech USB Keyboard> at usbus0 (disconnected) Sep 17 13:54:57 guardian kernel: ukbd0: at uhub2, port 4, addr 5 (disconnected) Sep 17 13:54:57 guardian kernel: ukbd0: detached Sep 17 13:55:22 guardian kernel: ugen0.4: <Logitech USB Optical Mouse> at usbus0 Sep 17 13:55:23 guardian kernel: ugen0.5: <Logitech USB Keyboard> at usbus0 Sep 17 13:55:23 guardian kernel: ukbd0 on uhub2 Sep 17 13:55:23 guardian kernel: ukbd0: <USB Keyboard> on usbus0 Sep 17 13:55:23 guardian kernel: kbd1 at ukbd0 Sep 17 13:55:23 guardian kernel: uhid0 on uhub2 Sep 17 13:55:23 guardian kernel: uhid0: <Logitech USB Keyboard, class 0/0, rev 1.10/64.02, addr 5> on usbus0 Sep 17 13:55:23 guardian kernel: uhid0: no report descriptor Sep 17 13:55:23 guardian kernel: device_attach: uhid0 attach returned 12 Sep 17 13:55:23 guardian kernel: ugen0.4: <Logitech USB Optical Mouse> at usbus0 (disconnected) Sep 17 13:55:23 guardian kernel: ugen0.5: <Logitech USB Keyboard> at usbus0 (disconnected) Sep 17 13:55:23 guardian kernel: ukbd0: at uhub2, port 4, addr 5 (disconnected) Sep 17 13:55:23 guardian kernel: ukbd0: detached Sep 17 13:55:44 guardian php: [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Sep 17 14:15:10 guardian php: [pfBlockerNG] Starting cron process. Sep 17 14:55:43 guardian php: [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Sep 17 15:15:11 guardian php: [pfBlockerNG] Starting cron process. Sep 17 15:47:18 guardian root: rc.update_bogons.sh is beginning the update cycle. Sep 17 15:47:19 guardian root: Bogons V4 file downloaded: 15 addresses added. Sep 17 15:47:19 guardian root: Bogons V4 file downloaded: 8 addresses deleted. Sep 17 15:47:20 guardian root: Bogons V6 file downloaded: 45 addresses added. Sep 17 15:47:20 guardian root: Bogons V6 file downloaded: 17 addresses deleted. Sep 17 15:47:20 guardian root: rc.update_bogons.sh is ending the update cycle. Sep 17 15:55:40 guardian php: [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Sep 17 16:15:11 guardian php: [pfBlockerNG] Starting cron process. Sep 17 16:56:32 guardian php: [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Sep 17 17:00:08 guardian kernel: ugen0.4: <Logitech USB Optical Mouse> at usbus0 Sep 17 17:00:09 guardian kernel: ugen0.5: <Logitech USB Keyboard> at usbus0 Sep 17 17:00:09 guardian kernel: ukbd0 on uhub2 Sep 17 17:00:09 guardian kernel: ukbd0: <USB Keyboard> on usbus0 Sep 17 17:00:09 guardian kernel: kbd1 at ukbd0 Sep 17 17:00:09 guardian kernel: uhid0 on uhub2 Sep 17 17:00:09 guardian kernel: uhid0: <USB Keyboard> on usbus0 Sep 17 17:00:10 guardian kernel: ugen0.4: <Logitech USB Optical Mouse> at usbus0 (disconnected) Sep 17 17:00:10 guardian kernel: ugen0.5: <Logitech USB Keyboard> at usbus0 (disconnected) Sep 17 17:00:10 guardian kernel: ukbd0: at uhub2, port 4, addr 5 (disconnected) Sep 17 17:00:10 guardian kernel: ukbd0: detached Sep 17 17:00:10 guardian kernel: uhid0: at uhub2, port 4, addr 5 (disconnected) Sep 17 17:00:10 guardian kernel: uhid0: detached Sep 17 17:05:27 guardian rc.gateway_alarm[26841]: >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:23.891ms RTTsd:13.381ms Loss:21%) Sep 17 17:05:27 guardian check_reload_status: updating dyndns VPN_UDP_TOS_VPNV4 Sep 17 17:05:27 guardian check_reload_status: Restarting ipsec tunnels Sep 17 17:05:27 guardian check_reload_status: Restarting OpenVPN tunnels/interfaces Sep 17 17:05:27 guardian check_reload_status: Reloading filter Sep 17 17:05:28 guardian php-fpm[77074]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Sep 17 17:05:28 guardian php-fpm[77074]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Sep 17 17:05:54 guardian kernel: em0: link state changed to DOWN Sep 17 17:05:54 guardian check_reload_status: Linkup starting em0 Sep 17 13:55:23 guardian kernel: ukbd0: at uhub2, port 4, addr 5 (disconnected) Sep 17 13:55:23 guardian kernel: ukbd0: detached Sep 17 13:55:44 guardian php: [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Sep 17 14:15:10 guardian php: [pfBlockerNG] Starting cron process. Sep 17 14:55:43 guardian php: [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Sep 17 15:15:11 guardian php: [pfBlockerNG] Starting cron process. Sep 17 15:47:18 guardian root: rc.update_bogons.sh is beginning the update cycle. Sep 17 15:47:19 guardian root: Bogons V4 file downloaded: 15 addresses added. Sep 17 15:47:19 guardian root: Bogons V4 file downloaded: 8 addresses deleted. Sep 17 15:47:20 guardian root: Bogons V6 file downloaded: 45 addresses added. Sep 17 15:47:20 guardian root: Bogons V6 file downloaded: 17 addresses deleted. Sep 17 15:47:20 guardian root: rc.update_bogons.sh is ending the update cycle. Sep 17 15:55:40 guardian php: [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Sep 17 16:15:11 guardian php: [pfBlockerNG] Starting cron process. Sep 17 16:56:32 guardian php: [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Sep 17 17:00:08 guardian kernel: ugen0.4: <Logitech USB Optical Mouse> at usbus0 Sep 17 17:00:09 guardian kernel: ugen0.5: <Logitech USB Keyboard> at usbus0 Sep 17 17:00:09 guardian kernel: ukbd0 on uhub2 Sep 17 17:00:09 guardian kernel: ukbd0: <USB Keyboard> on usbus0 Sep 17 17:00:09 guardian kernel: kbd1 at ukbd0 Sep 17 17:00:09 guardian kernel: uhid0 on uhub2 Sep 17 17:00:09 guardian kernel: uhid0: <USB Keyboard> on usbus0 Sep 17 17:00:10 guardian kernel: ugen0.4: <Logitech USB Optical Mouse> at usbus0 (disconnected) Sep 17 17:00:10 guardian kernel: ugen0.5: <Logitech USB Keyboard> at usbus0 (disconnected) Sep 17 17:00:10 guardian kernel: ukbd0: at uhub2, port 4, addr 5 (disconnected) Sep 17 17:00:10 guardian kernel: ukbd0: detached Sep 17 17:00:10 guardian kernel: uhid0: at uhub2, port 4, addr 5 (disconnected) Sep 17 17:00:10 guardian kernel: uhid0: detached Sep 17 17:05:27 guardian rc.gateway_alarm[26841]: >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:23.891ms RTTsd:13.381m s Loss:21%) Sep 17 17:05:27 guardian check_reload_status: updating dyndns VPN_UDP_TOS_VPNV4 Sep 17 17:05:27 guardian check_reload_status: Restarting ipsec tunnels Sep 17 17:05:27 guardian check_reload_status: Restarting OpenVPN tunnels/interfaces Sep 17 17:05:27 guardian check_reload_status: Reloading filter Sep 17 17:05:28 guardian php-fpm[77074]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Sep 17 17:05:28 guardian php-fpm[77074]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Sep 17 17:05:54 guardian kernel: em0: link state changed to DOWN Sep 17 17:05:54 guardian check_reload_status: Linkup starting em0 Sep 17 17:05:55 guardian php-fpm[88552]: /rc.linkup: DEVD Ethernet detached event for wan Sep 17 17:05:56 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:05:56 guardian check_reload_status: Reloading filter Sep 17 17:05:56 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:05:56 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:05:56 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:05:56 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:05:56 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:05:57 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:05:57 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:05:57 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:05:57 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:05:57 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:05:57 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:05:57 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:05:57 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:05:57 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:05:57 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 [ 30 Lines Removed] Sep 17 17:06:01 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:06:01 guardian kernel: ovpnc1: link state changed to DOWN Sep 17 17:06:01 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 [ 36 Lines Removed] Sep 17 17:06:01 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:06:01 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:06:01 guardian kernel: ovpnc1: link state changed to DOWN Sep 17 17:06:01 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 [ 17 Lines Removed] Sep 17 17:06:09 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:06:09 guardian rc.gateway_alarm[12340]: >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:1 RTT:30.432ms RTTsd:21.311ms Loss:22%) Sep 17 17:06:09 guardian check_reload_status: updating dyndns WAN_DHCP Sep 17 17:06:09 guardian check_reload_status: Restarting ipsec tunnels Sep 17 17:06:09 guardian check_reload_status: Restarting OpenVPN tunnels/interfaces Sep 17 17:06:09 guardian check_reload_status: Reloading filter Sep 17 17:06:09 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:06:10 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:06:10 guardian php-fpm[77074]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Sep 17 17:06:10 guardian php-fpm[77074]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Sep 17 17:06:10 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 [ 17 Lines Removed] Sep 17 17:06:09 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:06:09 guardian rc.gateway_alarm[12340]: >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:1 RTT:30.432ms RTTsd:21.311ms Loss:22 %) Sep 17 17:06:09 guardian check_reload_status: updating dyndns WAN_DHCP Sep 17 17:06:09 guardian check_reload_status: Restarting ipsec tunnels Sep 17 17:06:09 guardian check_reload_status: Restarting OpenVPN tunnels/interfaces Sep 17 17:06:09 guardian check_reload_status: Reloading filter Sep 17 17:06:09 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:06:10 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:06:10 guardian php-fpm[77074]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Sep 17 17:06:10 guardian php-fpm[77074]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Sep 17 17:06:10 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:05:57 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 [ 30 Lines Removed] Sep 17 17:06:26 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:06:26 guardian kernel: em0: link state changed to UP Sep 17 17:06:26 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 [ 30 Lines Removed] Sep 17 17:06:42 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:06:42 guardian kernel: em0: link state changed to DOWN Sep 17 17:06:42 guardian check_reload_status: Linkup starting em0 Sep 17 17:06:43 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 [ 3 Lines Removed] Sep 17 17:06:45 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:06:45 guardian kernel: em0: link state changed to UP Sep 17 17:06:45 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:06:46 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:06:46 guardian kernel: em0: link state changed to DOWN Sep 17 17:06:46 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 [ 3 Lines Removed] Sep 17 17:06:48 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:06:48 guardian kernel: em0: link state changed to UP Sep 17 17:06:49 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 [ 64 Lines Removed] Sep 17 17:07:21 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:07:21 guardian kernel: em0: link state changed to DOWN Sep 17 17:07:21 guardian check_reload_status: Linkup starting em0 Sep 17 17:07:21 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 [ 11 Lines Removed] Sep 17 17:07:27 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:07:27 guardian kernel: em0: link state changed to UP Sep 17 17:07:28 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 [ 15 Lines Removed] Sep 17 17:07:36 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:07:36 guardian kernel: em0: link state changed to DOWN Sep 17 17:07:36 guardian check_reload_status: Linkup starting em0 Sep 17 17:07:37 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 [ 10 Lines Removed] Sep 17 17:07:43 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:07:43 guardian kernel: em0: link state changed to UP Sep 17 17:07:43 guardian check_reload_status: Linkup starting em0 Sep 17 17:07:43 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 [ 32 Lines Removed] Sep 17 17:08:00 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:08:00 guardian check_reload_status: rc.newwanip starting em0 Sep 17 17:08:00 guardian php-fpm[12989]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Sep 17 17:08:00 guardian check_reload_status: Restarting ipsec tunnels Sep 17 17:08:06 guardian php-fpm[12989]: /rc.linkup: The command '/usr/sbin/arp -s '192.168.50.1' '00:xx:xx:xx:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Sep 17 17:08:07 guardian check_reload_status: updating dyndns wan Sep 17 17:08:07 guardian check_reload_status: Reloading filter Sep 17 17:08:07 guardian php-fpm[24898]: /rc.linkup: DEVD Ethernet detached event for wan Sep 17 17:08:08 guardian check_reload_status: Reloading filter Sep 17 17:08:08 guardian php-fpm[77074]: /rc.linkup: DEVD Ethernet attached event for wan Sep 17 17:08:08 guardian php-fpm[77074]: /rc.linkup: HOTPLUG: Configuring interface wan Sep 17 17:08:08 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:08:08 guardian check_reload_status: rc.newwanip starting em0 Sep 17 17:08:08 guardian php-fpm[77074]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Sep 17 17:08:08 guardian check_reload_status: Restarting ipsec tunnels Sep 17 17:08:42 guardian php-fpm[77074]: /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1600376922] unbound[29232:0] error: bind: address already in use [1600376922] unbound[29232:0] fatal error: could not open ports' Sep 17 17:08:43 guardian php-fpm[77074]: /rc.linkup: The command '/usr/sbin/arp -s '192.168.50.1' '00:xx:xx:xx:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Sep 17 17:08:43 guardian check_reload_status: updating dyndns wan Sep 17 17:08:43 guardian check_reload_status: Reloading filter Sep 17 17:08:43 guardian php-fpm[86818]: /rc.linkup: DEVD Ethernet detached event for wan Sep 17 17:08:43 guardian php-fpm[77074]: /rc.newwanip: rc.newwanip: Info: starting on em0. Sep 17 17:08:43 guardian php-fpm[77074]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xx.133) (interface: WAN[wan]) (real interface: em0). Sep 17 17:08:45 guardian php-fpm[88318]: /rc.linkup: DEVD Ethernet attached event for wan Sep 17 17:08:45 guardian check_reload_status: Reloading filter Sep 17 17:08:45 guardian php-fpm[88318]: /rc.linkup: HOTPLUG: Configuring interface wan Sep 17 17:08:45 guardian check_reload_status: rc.newwanip starting em0 Sep 17 17:08:45 guardian php-fpm[88318]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Sep 17 17:08:45 guardian check_reload_status: Restarting ipsec tunnels Sep 17 17:08:55 guardian php-fpm[88318]: /rc.linkup: The command '/usr/sbin/arp -s '192.168.50.1' '00:xx:xx:xx:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Sep 17 17:08:55 guardian check_reload_status: updating dyndns wan Sep 17 17:08:55 guardian check_reload_status: Reloading filter Sep 17 17:08:55 guardian php-fpm[24234]: /rc.linkup: DEVD Ethernet detached event for wan Sep 17 17:08:55 guardian php-fpm[88318]: /rc.newwanip: rc.newwanip: Info: starting on em0. Sep 17 17:08:55 guardian php-fpm[88318]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xx.133) (interface: WAN[wan]) (real interface: em0). Sep 17 17:08:56 guardian check_reload_status: Reloading filter Sep 17 17:08:56 guardian php-fpm[88552]: /rc.linkup: DEVD Ethernet attached event for wan Sep 17 17:08:56 guardian php-fpm[88552]: /rc.linkup: HOTPLUG: Configuring interface wan Sep 17 17:08:57 guardian kernel: arpresolve: can't allocate llinfo for 99.xxx.xx.1 on em0 Sep 17 17:08:57 guardian check_reload_status: rc.newwanip starting em0 Sep 17 17:08:57 guardian php-fpm[88552]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Sep 17 17:08:57 guardian check_reload_status: Restarting ipsec tunnels Sep 17 17:08:58 guardian rc.gateway_alarm[37668]: >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:0 RTT:23.894ms RTTsd:57.026ms Loss:5%) Sep 17 17:08:58 guardian check_reload_status: updating dyndns WAN_DHCP Sep 17 17:08:58 guardian check_reload_status: Restarting ipsec tunnels Sep 17 17:08:58 guardian check_reload_status: Restarting OpenVPN tunnels/interfaces Sep 17 17:08:58 guardian check_reload_status: Reloading filter Sep 17 17:09:01 guardian root: ***** 20/09/17-17:09:00-VPN_UDP_TOS_VPNV4-Attempting to issue restart to openvpn service... openvpn has been restarted. Sep 17 17:09:31 guardian php-fpm[88552]: /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1600376971] unbound[78689:0] error: bind: address already in use [1600376971] unbound[78689:0] fatal error: could not open ports' Sep 17 17:09:32 guardian php-fpm[88552]: /rc.linkup: The command '/usr/sbin/arp -s '192.168.50.1' '00:xx:xx:xx:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Sep 17 17:09:32 guardian check_reload_status: updating dyndns wan Sep 17 17:09:32 guardian check_reload_status: Reloading filter Sep 17 17:09:32 guardian php-fpm[12989]: /rc.linkup: DEVD Ethernet detached event for wan Sep 17 17:09:33 guardian check_reload_status: Reloading filter Sep 17 17:09:33 guardian php-fpm[24898]: /rc.linkup: DEVD Ethernet attached event for wan Sep 17 17:09:33 guardian php-fpm[24898]: /rc.linkup: HOTPLUG: Configuring interface wan Sep 17 17:09:33 guardian php-fpm[12989]: /rc.newwanip: rc.newwanip: Info: starting on em0. Sep 17 17:09:33 guardian php-fpm[12989]: /rc.newwanip: rc.newwanip: on (IP address: ) (interface: WAN[wan]) (real interface: em0). Sep 17 17:09:33 guardian php-fpm[12989]: /rc.newwanip: rc.newwanip: Failed to update wan IP, restarting... Sep 17 17:09:33 guardian check_reload_status: Configuring interface wan Sep 17 17:09:34 guardian check_reload_status: rc.newwanip starting em0 Sep 17 17:09:34 guardian php-fpm[24898]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Sep 17 17:09:34 guardian check_reload_status: Restarting ipsec tunnels Sep 17 17:09:44 guardian php-fpm[24898]: /rc.linkup: The command '/usr/sbin/arp -s '192.168.50.1' '00:xx:xx:xx:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Sep 17 17:09:44 guardian check_reload_status: updating dyndns wan Sep 17 17:09:44 guardian check_reload_status: Reloading filter Sep 17 17:09:49 guardian php-fpm[77074]: /rc.newwanip: Removing static route for monitor 8.8.8.8 and adding a new route through 99.xxx.xx.1 Sep 17 17:09:49 guardian php-fpm[77074]: /rc.newwanip: Gateway, none 'available' for inet6, use the first one configured. '' Sep 17 17:10:22 guardian kernel: ugen0.4: <Logitech USB Optical Mouse> at usbus0 Sep 17 17:10:22 guardian kernel: ugen0.5: <Logitech USB Keyboard> at usbus0 Sep 17 17:10:22 guardian kernel: ukbd0 on uhub2 Sep 17 17:10:22 guardian kernel: ukbd0: <USB Keyboard> on usbus0 Sep 17 17:10:22 guardian kernel: kbd1 at ukbd0 Sep 17 17:10:22 guardian kernel: uhid0 on uhub2 Sep 17 17:10:22 guardian kernel: uhid0: <USB Keyboard> on usbus0 Sep 17 17:10:23 guardian php-fpm[77074]: /rc.newwanip: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1600377023] unbound[40107:0] error: bind: address already in use [1600377023] unbound[40107:0] fatal error: could not open ports' ###################################################################################################### ## Logged in and Rebooted ###################################################################################################### Sep 17 17:10:24 guardian login: login on ttyv0 as root Sep 17 17:10:25 guardian php-fpm[77074]: /rc.newwanip: The command '/usr/sbin/arp -s '192.168.50.1' '00:xx:xx:xx:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Sep 17 17:10:25 guardian php-fpm[77074]: /rc.newwanip: Resyncing OpenVPN instances for interface WAN. Sep 17 17:10:25 guardian php-fpm[77074]: OpenVPN terminate old pid: 7456 Sep 17 17:10:25 guardian kernel: ovpns3: link state changed to DOWN Sep 17 17:10:25 guardian check_reload_status: Reloading filter Sep 17 17:10:25 guardian php-fpm[77074]: OpenVPN PID written: 80880 Sep 17 17:10:25 guardian check_reload_status: Reloading filter Sep 17 17:10:25 guardian kernel: ovpns3: link state changed to UP Sep 17 17:10:25 guardian check_reload_status: rc.newwanip starting ovpns3 Sep 17 17:10:26 guardian php-fpm[77074]: OpenVPN terminate old pid: 35794 Sep 17 17:10:26 guardian kernel: ovpns4: link state changed to DOWN Sep 17 17:10:26 guardian php-fpm[77074]: OpenVPN PID written: 1598 Sep 17 17:10:26 guardian kernel: ovpns4: link state changed to UP Sep 17 17:10:26 guardian check_reload_status: rc.newwanip starting ovpns4 Sep 17 17:10:26 guardian php-fpm[77074]: OpenVPN terminate old pid: 70970 Sep 17 17:10:29 guardian php-fpm[77074]: /rc.newwanip: OpenVPN ID client1 PID 70970 still running, killing. Sep 17 17:10:29 guardian kernel: ugen0.4: <Logitech USB Optical Mouse> at usbus0 (disconnected) Sep 17 17:10:29 guardian kernel: ugen0.5: <Logitech USB Keyboard> at usbus0 (disconnected) Sep 17 17:10:29 guardian kernel: ukbd0: at uhub2, port 4, addr 5 (disconnected) Sep 17 17:10:29 guardian kernel: ukbd0: detached Sep 17 17:10:29 guardian kernel: uhid0: at uhub2, port 4, addr 5 (disconnected) Sep 17 17:10:29 guardian kernel: uhid0: detached Sep 17 17:10:30 guardian php-fpm[77074]: OpenVPN PID written: 22365 Sep 17 17:10:30 guardian check_reload_status: Reloading filter Sep 17 17:10:30 guardian php-fpm[77074]: /rc.newwanip: Creating rrd update script Sep 17 17:10:32 guardian php-fpm[77074]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 99.xxx.xx.133 -> 99.xxx.xx.133 - Restarting packages. Sep 17 17:10:32 guardian check_reload_status: Starting packages Sep 17 17:10:32 guardian php-fpm[77074]: /rc.newwanip: rc.newwanip: Info: starting on em0. Sep 17 17:10:32 guardian php-fpm[77074]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xx.133) (interface: WAN[wan]) (real interface: em0). Sep 17 17:10:53 guardian php-fpm[86818]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Sep 17 17:10:53 guardian php-fpm[86818]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Sep 17 17:11:41 guardian kernel: ugen0.4: <Logitech USB Optical Mouse> at usbus0 Sep 17 17:11:42 guardian kernel: ugen0.5: <Logitech USB Keyboard> at usbus0 Sep 17 17:11:42 guardian kernel: ukbd0 on uhub2 Sep 17 17:11:42 guardian kernel: ukbd0: <USB Keyboard> on usbus0 Sep 17 17:11:42 guardian kernel: kbd1 at ukbd0 Sep 17 17:11:42 guardian kernel: uhid0 on uhub2 Sep 17 17:11:42 guardian kernel: uhid0: <USB Keyboard> on usbus0 Sep 17 17:11:43 guardian login: login on ttyv0 as root Sep 17 17:12:06 guardian php-cgi: rc.initial.reboot: Stopping all packages. Sep 17 17:12:06 guardian supervise/syslog-ng[12297]: Daemon exited gracefully, not restarting; exitcode='0' Sep 17 17:12:11 guardian php-cgi: rc.initial.reboot: The command '/usr/local/etc/rc.d/syslog-ng.sh stop' returned exit code '1', the output was '' Sep 17 17:12:11 guardian php-cgi: rc.initial.reboot: The command '/usr/bin/killall iperf3' returned exit code '1', the output was 'No matching processes were found' Sep 17 17:12:11 guardian php-cgi: rc.initial.reboot: The command '/usr/local/etc/rc.d/stunnel.sh stop' returned exit code '1', the output was 'No matching processes were found' Sep 17 17:12:11 guardian kernel: em1.1: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.91: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.92: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.93: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.10: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.192: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.254: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.20: promiscuous mode disabled Sep 17 17:12:11 guardian php-cgi: rc.initial.reboot: The command '/usr/bin/killall iperf3' returned exit code '1', the output was 'No m atching processes were found' Sep 17 17:12:11 guardian php-cgi: rc.initial.reboot: The command '/usr/local/etc/rc.d/stunnel.sh stop' returned exit code '1', the outp ut was 'No matching processes were found' Sep 17 17:12:11 guardian kernel: em1.1: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.91: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.92: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.93: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.10: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.192: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.254: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.20: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.30: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.40: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em1.50: promiscuous mode disabled Sep 17 17:12:11 guardian kernel: em0: promiscuous mode disabled Sep 17 17:12:11 guardian php-cgi: rc.initial.reboot: The command '/usr/local/etc/rc.d/tinc.sh stop' returned exit code '1', the output was 'No other tincd is running.' Sep 17 17:12:15 guardian reboot: rebooted by root
-
@guardian What DNS servers are you using on your network? Or, it could be your ISP has a low refresh time (maybe too low) on your WAN IP address, and it's getting reset.
From your logs above:
"pfSense package system has detected an IP change or dynamic WAN reconnection"Do you have your Gateway Monitoring set to "kill states on gateway failure"?
Jeff
-
@akuma1x said in Have I Found a bug?:
could be your ISP has a low refresh time (maybe too low) on your WAN IP address, and it's getting reset.
Thanks for the reply Jeff @akuma1x - It is more likely that the dnsresolver isn't functioning. I have my system configured so the unbound DNS resolver is responsible for all DNS resolution.
AFAIK the lease is 1 week, and based on log, I expect that the lease might have just expired, and renewed. The provider has ip reservation based on hardware/customer id/etc, so IP is unlikely to change-and didn't in this case. It is possible that the IP address might temporairly be set to the default configuration IP address of the gateway before it the IP gets refreshed - I have no way of knowing.
Do you have your Gateway Monitoring set to "kill states on gateway failure"?
How do I set this?
-
@guardian This setting is found in:
System -> Advanced -> Miscellaneous -> Gateway Monitoring
And general gateway settings talked about in the pfsense book:
https://docs.netgate.com/pfsense/en/latest/book/routing/gateway-settings.htmlBy the way, you technically DON'T want to set the gateway states to be killed on a "gateway down" event. It is most useful, and I'm pretty sure required, when you have a multi-WAN setup.
Jeff
-
@guardian said in Have I Found a bug?:
Sep 17 17:05:54 guardian kernel: em0: link state changed to DOWN
That's your WAN right? It looks like it actually lost link for a minute or so and then was flapping for a a while after that. Is it directly connected to the modem? I would say the modem rebooted and whatever you saw just before that was it failing for some reason.
Also is that a USB KVM you have connected to it that keeps connecting and disconnecting? It would be much better if that didn't happen.
Steve
-
Thanks for the reply @akuma1x, @stephenw10 -- individual responses below, but I think that the issue might be unbound becoming confused by a momentary loss of connection (the gateway address becomes something like 192.168.0.10 until the modem reconnects -- and on reconnection it gets the same IP address back [Not a guaranteed static IP, but I've only seen it change every 2 or 3 years unless I change the mac address of my router). As it stands I am letting unbound do resolution right to the root servers, since I don't like the idea of one entity handling my DNS queries, but I'm thinking that maybe I should reexamine this strategy.
@akuma1x said in Have I Found a bug?:
@guardian This setting is found in:
System -> Advanced -> Miscellaneous -> Gateway Monitoring
And general gateway settings talked about in the pfsense book:
https://docs.netgate.com/pfsense/en/latest/book/routing/gateway-settings.htmlBy the way, you technically DON'T want to set the gateway states to be killed on a "gateway down" event. It is most useful, and I'm pretty sure required, when you have a multi-WAN setup.
Jeff
Thanks for the detailed info Jeff... I looked and can confim that "State Killing on Gateway Falure" is DISABLED.
@stephenw10 said in Have I Found a bug?:
@guardian said in Have I Found a bug?:
Sep 17 17:05:54 guardian kernel: em0: link state changed to DOWN
That's your WAN right? It looks like it actually lost link for a minute or so and then was flapping for a a while after that. Is it directly connected to the modem? I would say the modem rebooted and whatever you saw just before that was it failing for some reason.
You got that, it is the WAN. - I think the lease might have rolled over (7 days). Yes, pfSense is connected directly to the modem (modem in bridge mode).
I don't think the instability lasted more than about 20 seconds or so (just a guess), but I find it interesting that I didn't reboot the modem, just pfSense.
I think @akuma1x might have got it right that it was a DNS issue.... I was able to ping an IP address, but name resolution wasn't working.
Also is that a USB KVM you have connected to it that keeps connecting and disconnecting? It would be much better if that didn't happen.
Correct again Steve... that's exactly what is happening, but I don't know what to do about it.... I need access to a console sometimes (times like the one we are talking about). It's been happening for the last 5+ Years, so other than a ton of log spam, I don't know think it is a problem. (Anything I'm missing?)
-
I'm on Rogers too and find them to be rock solid, though it's impossible to rule out interruptions with any provider. Also, they would have nothing to do with the GUI. I'd start looking at problems with what you're running pfSense on.
-
I would not expect it to lose link to the modem whatever the dhcp lease state it. That seems like a problem.
The fact the modem hands it a private IP also seems to confirm that. It will only do that when it loses sync with the upstream cable.
You should add the modems private IP to the 'reject leases from' field in the WAN dhcp setup so pfSense never pulls a private IP which is known to cause problems.Steve
-
Thanks @JKnott / @stephenw10
@JKnott said in Have I Found a bug?:
I'm on Rogers too and find them to be rock solid, though it's impossible to rule out interruptions with any provider. Also, they would have nothing to do with the GUI. I'd start looking at problems with what you're running pfSense on.
It hasn't been a huge problem... AFAIK just the last 2 lease renewals caused. Maybe they would have cleared if I gave them time, but I intervened by resetting the router and/or modem.
What modem are you using? I have a CODA-4582U... I think it is about 2 years old (can't remember exactly)... I assume that the F/W gets updated remotely when the modem boots.
@stephenw10 said in Have I Found a bug?:
I would not expect it to lose link to the modem whatever the dhcp lease state it. That seems like a problem.
The fact the modem hands it a private IP also seems to confirm that. It will only do that when it loses sync with the upstream cable.Agreed... I believe there was a brief loss of sync (but it's just a guess).
You should add the modems private IP to the 'reject leases from' field in the WAN dhcp setup so pfSense never pulls a private IP which is known to cause problems.
Just checked that setting I noticed that I had 192.168.100.1 blocked which is the login for the customer admin screen for the modem. I don't know if I should be blocking 192.168.0.1 as well, or if will prevent reconnection entirely.
**As I said in an earlier post, I thinking that I may have unbound set up incorrectly since it handles ALL DNS (any traffic on port 53 is redirected to unbound to prevent programs using their own dns) on my network back to the root servers.
Anything I should check out that might cause unbound to get confused by a momentary loss like the one indicated in the log?
Is there an easy way to restart unbound from the command line? If it happens again, I would like to try that first before resetting anything. If that clears it, then I'll be closer to figuring it out -- and maybe I'll be lucky and not see another event for a month or two.... who knows.**
Thanks again for the support.
-
I have a Hitron, but I don't recall the model.
-
You have to block whichever DHCP server is handing you that private lease.
It only blocks dhcp it won't stop you accessing the modem.Steve