PPPoE session dropping intermittently
-
Just trying to rule out my pfSense configuration as an issue here...
From the logs, I cannot determine what is actually happening to cause the PPP session to reset. It seems as though suddenly a new PPP session starts out of nowhere and tears the existing session down. It's happened 4-5 times today. The line itself is FTTP, so the line itself is likely to be fine, leaving my ONU modem or my ISP's equipment at fault. ISP is saying their kit is fine, but they are detecting "frequent disconnections and reconnections with no particular errors showing on their end". I have access to the ONU modem, but it sadly does not have any useful logs.
Is there a way I can get more detailed logs from pfSense? system.log below, showing a couple of drops:
Mar 2 07:07:17 pfSense check_reload_status: Linkup starting igb0 Mar 2 07:07:17 pfSense kernel: igb0: link state changed to DOWN Mar 2 07:07:18 pfSense php-fpm: /rc.linkup: Linkup detected on disabled interface...Ignoring Mar 2 07:07:18 pfSense check_reload_status: Reloading filter Mar 2 07:07:20 pfSense check_reload_status: Linkup starting igb0 Mar 2 07:07:20 pfSense kernel: igb0: link state changed to UP Mar 2 07:07:21 pfSense php-fpm[25829]: /rc.linkup: Linkup detected on disabled interface...Ignoring Mar 2 07:07:21 pfSense ppp: Multi-link PPP daemon for FreeBSD Mar 2 07:07:21 pfSense ppp: Mar 2 07:07:21 pfSense ppp: process 6127 started, version 5.8 (root@pfSense_v2_4_4_amd64-pfSense_v2_4_4-job-09 11:56 16-Nov-2018) Mar 2 07:07:21 pfSense ppp: waiting for process 10520 to die... Mar 2 07:07:21 pfSense ppp: caught fatal signal TERM Mar 2 07:07:21 pfSense ppp: [wan] IFACE: Close event Mar 2 07:07:21 pfSense ppp: [wan] IPCP: Close event Mar 2 07:07:21 pfSense ppp: [wan] IPCP: state change Opened --> Closing Mar 2 07:07:21 pfSense ppp: [wan] IPCP: SendTerminateReq #4 Mar 2 07:07:21 pfSense ppp: [wan] IPCP: LayerDown Mar 2 07:07:21 pfSense php-fpm[25829]: /rc.linkup: calling interface_dhcpv6_configure. Mar 2 07:07:21 pfSense php-fpm[25829]: /rc.linkup: Accept router advertisements on interface igb0 Mar 2 07:07:21 pfSense php-fpm[25829]: /rc.linkup: Starting rtsold process Mar 2 07:07:22 pfSense check_reload_status: Rewriting resolv.conf Mar 2 07:07:22 pfSense ppp: [wan] IFACE: Removing IPv4 address from pppoe1 failed(IGNORING for now. This should be only for PPPoE friendly!): Can't assign requested address Mar 2 07:07:22 pfSense ppp: [wan] IFACE: Down event Mar 2 07:07:22 pfSense ppp: [wan] IFACE: Rename interface pppoe1 to pppoe1 Mar 2 07:07:22 pfSense ppp: [wan] IPV6CP: Close event Mar 2 07:07:22 pfSense ppp: [wan] IPV6CP: state change Stopped --> Closed Mar 2 07:07:22 pfSense ppp: [wan] IPCP: rec'd Terminate Ack #4 (Closing) Mar 2 07:07:22 pfSense ppp: [wan] IPCP: state change Closing --> Closed Mar 2 07:07:22 pfSense ppp: [wan] IPCP: LayerFinish Mar 2 07:07:22 pfSense ppp: [wan] Bundle: No NCPs left. Closing links... Mar 2 07:07:22 pfSense ppp: [wan] Bundle: closing link "wan_link0"... Mar 2 07:07:22 pfSense ppp: [wan_link0] Link: CLOSE event Mar 2 07:07:22 pfSense ppp: [wan_link0] LCP: Close event Mar 2 07:07:22 pfSense ppp: [wan_link0] LCP: state change Opened --> Closing Mar 2 07:07:22 pfSense ppp: [wan_link0] Link: Leave bundle "wan" Mar 2 07:07:22 pfSense ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps Mar 2 07:07:22 pfSense ppp: [wan] IPCP: Close event Mar 2 07:07:22 pfSense ppp: [wan] IPV6CP: Close event Mar 2 07:07:22 pfSense ppp: [wan] IPCP: Down event Mar 2 07:07:22 pfSense ppp: [wan] IPCP: state change Closed --> Initial Mar 2 07:07:22 pfSense ppp: [wan] IPV6CP: Down event Mar 2 07:07:22 pfSense ppp: [wan] IPV6CP: state change Closed --> Initial Mar 2 07:07:22 pfSense ppp: [wan_link0] LCP: SendTerminateReq #2 Mar 2 07:07:22 pfSense ppp: [wan_link0] LCP: LayerDown Mar 2 07:07:22 pfSense ppp: [wan_link0] LCP: rec'd Terminate Ack #2 (Closing) Mar 2 07:07:22 pfSense ppp: [wan_link0] LCP: state change Closing --> Closed Mar 2 07:07:22 pfSense ppp: [wan_link0] LCP: LayerFinish Mar 2 07:07:22 pfSense ppp: [wan_link0] Link: DOWN event Mar 2 07:07:22 pfSense ppp: [wan_link0] LCP: Down event Mar 2 07:07:22 pfSense ppp: [wan_link0] LCP: state change Closed --> Initial Mar 2 07:07:22 pfSense ppp: waiting for process 10520 to die... Mar 2 07:07:23 pfSense ppp: waiting for process 10520 to die... Mar 2 07:07:23 pfSense php-fpm[25829]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. 'WAN_SLAAC' Mar 2 07:07:23 pfSense check_reload_status: Restarting ipsec tunnels Mar 2 07:07:24 pfSense rtsold: Received RA specifying route fe80::21f:6cff:fe25:50c5 for interface wan(igb0) Mar 2 07:07:24 pfSense rtsold: RTSOLD Lock in place - sending SIGHUP to dhcp6c Mar 2 07:07:24 pfSense ppp: [wan] Bundle: Shutdown Mar 2 07:07:24 pfSense ppp: [wan_link0] Link: Shutdown Mar 2 07:07:24 pfSense ppp: process 10520 terminated Mar 2 07:07:24 pfSense ppp: web: web is not running Mar 2 07:07:24 pfSense ppp: [wan] Bundle: Interface ng0 created Mar 2 07:07:24 pfSense ppp: [wan_link0] Link: OPEN event Mar 2 07:07:24 pfSense kernel: ng0: changing name to 'pppoe1' Mar 2 07:07:24 pfSense ppp: [wan_link0] LCP: Open event Mar 2 07:07:24 pfSense ppp: [wan_link0] LCP: state change Initial --> Starting Mar 2 07:07:24 pfSense ppp: [wan_link0] LCP: LayerStart Mar 2 07:07:24 pfSense ppp: [wan_link0] PPPoE: Connecting to '' Mar 2 07:07:24 pfSense ppp: PPPoE: rec'd ACNAME "<MY_LOCAL_ISPS_NODE_NAME>" Mar 2 07:07:24 pfSense ppp: [wan_link0] PPPoE: connection successful Mar 2 07:07:24 pfSense ppp: [wan_link0] Link: UP event Mar 2 07:07:24 pfSense ppp: [wan_link0] LCP: Up event Mar 2 07:07:24 pfSense ppp: [wan_link0] LCP: state change Starting --> Req-Sent Mar 2 07:07:24 pfSense ppp: [wan_link0] LCP: SendConfigReq #1 Mar 2 07:07:24 pfSense ppp: [wan_link0] PROTOCOMP Mar 2 07:07:24 pfSense ppp: [wan_link0] MRU 1492 Mar 2 07:07:24 pfSense ppp: [wan_link0] MAGICNUM 0xbf5f39dd Mar 2 07:07:24 pfSense ppp: [wan_link0] LCP: rec'd Configure Request #1 (Req-Sent) Mar 2 07:07:24 pfSense ppp: [wan_link0] MRU 1454 Mar 2 07:07:24 pfSense ppp: [wan_link0] AUTHPROTO CHAP MD5 Mar 2 07:07:24 pfSense ppp: [wan_link0] MAGICNUM 0x9c1adebb Mar 2 07:07:24 pfSense ppp: [wan_link0] LCP: SendConfigAck #1 Mar 2 07:07:24 pfSense ppp: [wan_link0] MRU 1454 Mar 2 07:07:24 pfSense ppp: [wan_link0] AUTHPROTO CHAP MD5 Mar 2 07:07:24 pfSense ppp: [wan_link0] MAGICNUM 0x9c1adebb Mar 2 07:07:24 pfSense ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Sent Mar 2 07:07:24 pfSense ppp: [wan_link0] LCP: rec'd Configure Ack #1 (Ack-Sent) Mar 2 07:07:24 pfSense ppp: [wan_link0] PROTOCOMP Mar 2 07:07:24 pfSense ppp: [wan_link0] MRU 1492 Mar 2 07:07:24 pfSense ppp: [wan_link0] MAGICNUM 0xbf5f39dd Mar 2 07:07:24 pfSense ppp: [wan_link0] LCP: state change Ack-Sent --> Opened Mar 2 07:07:24 pfSense ppp: [wan_link0] LCP: auth: peer wants CHAP, I want nothing Mar 2 07:07:24 pfSense ppp: [wan_link0] LCP: LayerUp Mar 2 07:07:24 pfSense ppp: [wan_link0] CHAP: rec'd CHALLENGE #1 len: 41 Mar 2 07:07:24 pfSense ppp: [wan_link0] Name: "<MY_LOCAL_ISPS_NODE_NAME>" Mar 2 07:07:24 pfSense ppp: [wan_link0] CHAP: Using authname "<MY_PPPOE_USERNAME>" Mar 2 07:07:24 pfSense ppp: [wan_link0] CHAP: sending RESPONSE #1 len: 40 Mar 2 07:07:24 pfSense ppp: [wan_link0] CHAP: rec'd SUCCESS #1 len: 4 Mar 2 07:07:24 pfSense ppp: [wan_link0] LCP: authorization successful Mar 2 07:07:24 pfSense ppp: [wan_link0] Link: Matched action 'bundle "wan" ""' Mar 2 07:07:24 pfSense ppp: [wan_link0] Link: Join bundle "wan" Mar 2 07:07:24 pfSense ppp: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps Mar 2 07:07:24 pfSense ppp: [wan] IPCP: Open event Mar 2 07:07:24 pfSense ppp: [wan] IPCP: state change Initial --> Starting Mar 2 07:07:24 pfSense ppp: [wan] IPCP: LayerStart Mar 2 07:07:24 pfSense ppp: [wan] IPV6CP: Open event Mar 2 07:07:24 pfSense ppp: [wan] IPV6CP: state change Initial --> Starting Mar 2 07:07:24 pfSense ppp: [wan] IPV6CP: LayerStart Mar 2 07:07:24 pfSense ppp: [wan] IPCP: Up event Mar 2 07:07:24 pfSense ppp: [wan] IPCP: state change Starting --> Req-Sent Mar 2 07:07:24 pfSense ppp: [wan] IPCP: SendConfigReq #1 Mar 2 07:07:24 pfSense ppp: [wan] IPADDR 0.0.0.0 Mar 2 07:07:24 pfSense ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Mar 2 07:07:24 pfSense ppp: [wan] IPV6CP: Up event Mar 2 07:07:24 pfSense ppp: [wan] IPV6CP: state change Starting --> Req-Sent Mar 2 07:07:24 pfSense ppp: [wan] IPV6CP: SendConfigReq #1 Mar 2 07:07:24 pfSense ppp: [wan] IPCP: rec'd Configure Request #1 (Req-Sent) Mar 2 07:07:24 pfSense ppp: [wan] IPADDR <ASSIGNED_IP#1> Mar 2 07:07:24 pfSense ppp: [wan] <ASSIGNED_IP#1> is OK Mar 2 07:07:24 pfSense ppp: [wan] IPCP: SendConfigAck #1 Mar 2 07:07:24 pfSense ppp: [wan] IPADDR <ASSIGNED_IP#1> Mar 2 07:07:24 pfSense ppp: [wan] IPCP: state change Req-Sent --> Ack-Sent Mar 2 07:07:24 pfSense ppp: [wan] IPCP: rec'd Configure Reject #1 (Ack-Sent) Mar 2 07:07:24 pfSense ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Mar 2 07:07:24 pfSense ppp: [wan] IPCP: SendConfigReq #2 Mar 2 07:07:24 pfSense ppp: [wan] IPADDR 0.0.0.0 Mar 2 07:07:24 pfSense ppp: [wan_link0] LCP: rec'd Protocol Reject #1 (Opened) Mar 2 07:07:24 pfSense ppp: [wan_link0] LCP: protocol IPV6CP was rejected Mar 2 07:07:24 pfSense ppp: [wan] IPV6CP: protocol was rejected by peer Mar 2 07:07:24 pfSense ppp: [wan] IPV6CP: state change Req-Sent --> Stopped Mar 2 07:07:24 pfSense ppp: [wan] IPV6CP: LayerFinish Mar 2 07:07:24 pfSense ppp: [wan] IPCP: rec'd Configure Nak #2 (Ack-Sent) Mar 2 07:07:24 pfSense ppp: [wan] IPADDR <ASSIGNED_IP#2> Mar 2 07:07:24 pfSense ppp: [wan] <ASSIGNED_IP#2> is OK Mar 2 07:07:24 pfSense ppp: [wan] IPCP: SendConfigReq #3 Mar 2 07:07:24 pfSense ppp: [wan] IPADDR <ASSIGNED_IP#2> Mar 2 07:07:24 pfSense ppp: [wan] IPCP: rec'd Configure Ack #3 (Ack-Sent) Mar 2 07:07:24 pfSense ppp: [wan] IPADDR <ASSIGNED_IP#2> Mar 2 07:07:24 pfSense ppp: [wan] IPCP: state change Ack-Sent --> Opened Mar 2 07:07:24 pfSense ppp: [wan] IPCP: LayerUp Mar 2 07:07:24 pfSense ppp: [wan] <ASSIGNED_IP#2> -> <ASSIGNED_IP#1> Mar 2 07:07:25 pfSense check_reload_status: rc.newwanip starting pppoe1 Mar 2 07:07:25 pfSense ppp: [wan] IFACE: Up event Mar 2 07:07:25 pfSense ppp: [wan] IFACE: Rename interface ng0 to pppoe1 Mar 2 07:07:26 pfSense php-fpm[66914]: /rc.newwanip: rc.newwanip: Info: starting on pppoe1. Mar 2 07:07:26 pfSense php-fpm[66914]: /rc.newwanip: rc.newwanip: on (IP address: <ASSIGNED_IP#2>) (interface: WAN[wan]) (real interface: pppoe1). Mar 2 07:07:26 pfSense dhcpleases: /etc/hosts changed size from original! Mar 2 07:07:26 pfSense php-fpm[66914]: /rc.newwanip: IP Address has changed, killing states on former IP Address 180.235.19.122. Mar 2 07:07:26 pfSense dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process. Mar 2 07:07:26 pfSense dhcpleases: /etc/hosts changed size from original! Mar 2 07:07:26 pfSense dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process. Mar 2 07:07:26 pfSense dhcpleases: kqueue error: unknown Mar 2 07:07:27 pfSense php-fpm[66914]: /rc.newwanip: Removing static route for monitor 1.1.1.1 and adding a new route through <ASSIGNED_IP#1> Mar 2 07:07:28 pfSense php-fpm[66914]: /rc.newwanip: Default gateway setting Interface WAN_PPPOE Gateway as default. Mar 2 07:07:28 pfSense php-fpm[66914]: /rc.newwanip: Gateway, none 'available' for inet6, use the first one configured. 'WAN_SLAAC' Mar 2 07:07:28 pfSense check_reload_status: updating dyndns wan Mar 2 07:07:28 pfSense check_reload_status: Reloading filter Mar 2 07:07:34 pfSense dhcpleases: /etc/hosts changed size from original! Mar 2 07:07:34 pfSense dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process. Mar 2 07:07:35 pfSense dhcpleases: kqueue error: unknown Mar 2 07:07:54 pfSense php-fpm[35214]: /rc.dyndns.update: Curl error occurred: Could not resolve host: freedns.afraid.org Mar 2 07:07:56 pfSense php-fpm[66914]: /rc.newwanip: phpDynDNS: updating cache file /conf/dyndns_wanfreedns'<my_dyndns_host>'0.cache: <ASSIGNED_IP#2> Mar 2 07:07:56 pfSense php-fpm[66914]: /rc.newwanip: phpDynDNS (<my_dyndns_host>): (Success) IP Address Changed Successfully! Mar 2 07:07:57 pfSense php-fpm[66914]: /rc.newwanip: Resyncing OpenVPN instances for interface WAN. Mar 2 07:07:57 pfSense php-fpm[66914]: OpenVPN terminate old pid: 73561 Mar 2 07:07:57 pfSense kernel: ovpns2: link state changed to DOWN Mar 2 07:07:57 pfSense check_reload_status: Reloading filter Mar 2 07:07:57 pfSense kernel: ovpns2: link state changed to UP Mar 2 07:07:57 pfSense php-fpm[66914]: OpenVPN PID written: 79339 Mar 2 07:07:57 pfSense check_reload_status: Reloading filter Mar 2 07:07:57 pfSense php-fpm[66914]: /rc.newwanip: Creating rrd update script Mar 2 07:07:57 pfSense check_reload_status: rc.newwanip starting ovpns2 Mar 2 07:07:58 pfSense php-fpm[340]: /rc.newwanip: rc.newwanip: Info: starting on ovpns2. Mar 2 07:07:58 pfSense php-fpm[340]: /rc.newwanip: rc.newwanip: on (IP address: 10.0.10.1) (interface: []) (real interface: ovpns2). Mar 2 07:07:58 pfSense php-fpm[340]: /rc.newwanip: rc.newwanip called with empty interface. Mar 2 07:07:58 pfSense php-fpm[340]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - -> 10.0.10.1 - Restarting packages. Mar 2 07:07:58 pfSense check_reload_status: Reloading filter Mar 2 07:07:58 pfSense check_reload_status: Starting packages Mar 2 07:07:59 pfSense php-fpm[340]: /rc.start_packages: Restarting/Starting all packages. Mar 2 07:07:59 pfSense php-fpm[66914]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 180.235.19.122 -> <ASSIGNED_IP#2> - Restarting packages. Mar 2 07:07:59 pfSense check_reload_status: Starting packages Mar 2 07:07:59 pfSense php-fpm[340]: /rc.start_packages: The command '/usr/local/etc/rc.d/bandwidthd.sh stop' returned exit code '1', the output was 'No matching processes were found' Mar 2 07:08:00 pfSense php-fpm: /rc.start_packages: Skipping STARTing packages process because previous/another instance is already running Mar 2 07:08:01 pfSense check_reload_status: Syncing firewall Mar 2 07:08:01 pfSense check_reload_status: Reloading filter Mar 2 07:08:01 pfSense php-fpm[340]: [pfBlockerNG] Restarting firewall filter daemon Mar 2 07:08:01 pfSense php_pfb: [pfBlockerNG] filterlog daemon started Mar 2 07:08:02 pfSense php-cgi: notify_monitor.php: Message sent to <MY_EMAIL> OK Mar 2 07:08:06 pfSense php-fpm[340]: /rc.start_packages: Download file failed with status code 0. URL: http://linuxnet.ca/ieee/oui/ethercodes.dat Mar 2 07:08:07 pfSense php: [pfBlockerNG] DNSBL parser daemon started Mar 2 07:08:07 pfSense php_pfb: [pfBlockerNG] filterlog daemon started Mar 2 07:08:09 pfSense arpwatch: listening on igb1 Mar 2 07:10:05 pfSense php: /usr/sbin/sendmail: Message sent to <MY_EMAIL> OK Mar 2 10:06:20 pfSense check_reload_status: Linkup starting igb0 Mar 2 10:06:20 pfSense kernel: igb0: link state changed to DOWN Mar 2 10:06:21 pfSense php-fpm[25829]: /rc.linkup: Linkup detected on disabled interface...Ignoring Mar 2 10:06:21 pfSense check_reload_status: Reloading filter Mar 2 10:06:24 pfSense check_reload_status: Linkup starting igb0 Mar 2 10:06:24 pfSense kernel: igb0: link state changed to UP Mar 2 10:06:25 pfSense php-fpm[339]: /rc.linkup: Linkup detected on disabled interface...Ignoring Mar 2 10:06:25 pfSense ppp: Multi-link PPP daemon for FreeBSD Mar 2 10:06:25 pfSense ppp: Mar 2 10:06:25 pfSense ppp: process 69222 started, version 5.8 (root@pfSense_v2_4_4_amd64-pfSense_v2_4_4-job-09 11:56 16-Nov-2018) Mar 2 10:06:25 pfSense ppp: waiting for process 6127 to die... Mar 2 10:06:25 pfSense ppp: caught fatal signal TERM Mar 2 10:06:25 pfSense ppp: [wan] IFACE: Close event Mar 2 10:06:25 pfSense ppp: [wan] IPCP: Close event Mar 2 10:06:25 pfSense ppp: [wan] IPCP: state change Opened --> Closing Mar 2 10:06:25 pfSense ppp: [wan] IPCP: SendTerminateReq #4 Mar 2 10:06:25 pfSense ppp: [wan] IPCP: LayerDown Mar 2 10:06:25 pfSense php-fpm[339]: /rc.linkup: calling interface_dhcpv6_configure. Mar 2 10:06:25 pfSense php-fpm[339]: /rc.linkup: Accept router advertisements on interface igb0 Mar 2 10:06:25 pfSense php-fpm[339]: /rc.linkup: Starting rtsold process Mar 2 10:06:25 pfSense check_reload_status: Rewriting resolv.conf Mar 2 10:06:25 pfSense ppp: [wan] IFACE: Removing IPv4 address from pppoe1 failed(IGNORING for now. This should be only for PPPoE friendly!): Can't assign requested address Mar 2 10:06:25 pfSense ppp: [wan] IFACE: Down event Mar 2 10:06:25 pfSense ppp: [wan] IFACE: Rename interface pppoe1 to pppoe1 Mar 2 10:06:25 pfSense ppp: [wan] IPV6CP: Close event Mar 2 10:06:25 pfSense ppp: [wan] IPV6CP: state change Stopped --> Closed Mar 2 10:06:25 pfSense ppp: [wan] IPCP: rec'd Terminate Ack #4 (Closing) Mar 2 10:06:25 pfSense ppp: [wan] IPCP: state change Closing --> Closed Mar 2 10:06:25 pfSense ppp: [wan] IPCP: LayerFinish Mar 2 10:06:25 pfSense ppp: [wan] Bundle: No NCPs left. Closing links... Mar 2 10:06:25 pfSense ppp: [wan] Bundle: closing link "wan_link0"... Mar 2 10:06:25 pfSense ppp: [wan_link0] Link: CLOSE event Mar 2 10:06:25 pfSense ppp: [wan_link0] LCP: Close event Mar 2 10:06:25 pfSense ppp: [wan_link0] LCP: state change Opened --> Closing Mar 2 10:06:25 pfSense ppp: [wan_link0] Link: Leave bundle "wan" Mar 2 10:06:25 pfSense ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps Mar 2 10:06:25 pfSense ppp: [wan] IPCP: Close event Mar 2 10:06:25 pfSense ppp: [wan] IPV6CP: Close event Mar 2 10:06:25 pfSense ppp: [wan] IPCP: Down event Mar 2 10:06:25 pfSense ppp: [wan] IPCP: state change Closed --> Initial Mar 2 10:06:25 pfSense ppp: [wan] IPV6CP: Down event Mar 2 10:06:25 pfSense ppp: [wan] IPV6CP: state change Closed --> Initial Mar 2 10:06:25 pfSense ppp: [wan_link0] LCP: SendTerminateReq #2 Mar 2 10:06:25 pfSense ppp: [wan_link0] LCP: LayerDown Mar 2 10:06:25 pfSense ppp: [wan_link0] LCP: rec'd Terminate Ack #2 (Closing) Mar 2 10:06:25 pfSense ppp: [wan_link0] LCP: state change Closing --> Closed Mar 2 10:06:25 pfSense ppp: [wan_link0] LCP: LayerFinish Mar 2 10:06:25 pfSense ppp: [wan_link0] Link: DOWN event Mar 2 10:06:25 pfSense ppp: [wan_link0] LCP: Down event Mar 2 10:06:25 pfSense ppp: [wan_link0] LCP: state change Closed --> Initial Mar 2 10:06:26 pfSense ppp: waiting for process 6127 to die... Mar 2 10:06:27 pfSense ppp: waiting for process 6127 to die... Mar 2 10:06:27 pfSense php-fpm[339]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. 'WAN_SLAAC' Mar 2 10:06:27 pfSense check_reload_status: Restarting ipsec tunnels Mar 2 10:06:27 pfSense ppp: [wan] Bundle: Shutdown Mar 2 10:06:27 pfSense ppp: [wan_link0] Link: Shutdown Mar 2 10:06:27 pfSense ppp: process 6127 terminated Mar 2 10:06:27 pfSense rtsold[72266]: <rtsock_input_ifannounce> interface pppoe1 removed Mar 2 10:06:28 pfSense rtsold: Received RA specifying route fe80::21f:6cff:fe25:50c5 for interface wan(igb0) Mar 2 10:06:28 pfSense rtsold: RTSOLD Lock in place - sending SIGHUP to dhcp6c Mar 2 10:06:28 pfSense ppp: web: web is not running Mar 2 10:06:28 pfSense ppp: [wan] Bundle: Interface ng0 created Mar 2 10:06:28 pfSense ppp: [wan_link0] Link: OPEN event Mar 2 10:06:28 pfSense kernel: ng0: changing name to 'pppoe1' Mar 2 10:06:28 pfSense ppp: [wan_link0] LCP: Open event Mar 2 10:06:28 pfSense ppp: [wan_link0] LCP: state change Initial --> Starting Mar 2 10:06:28 pfSense ppp: [wan_link0] LCP: LayerStart Mar 2 10:06:28 pfSense ppp: [wan_link0] PPPoE: Connecting to '' Mar 2 10:06:28 pfSense ppp: PPPoE: rec'd ACNAME "<MY_LOCAL_ISPS_NODE_NAME>" Mar 2 10:06:28 pfSense ppp: [wan_link0] PPPoE: connection successful Mar 2 10:06:28 pfSense ppp: [wan_link0] Link: UP event Mar 2 10:06:28 pfSense ppp: [wan_link0] LCP: Up event Mar 2 10:06:28 pfSense ppp: [wan_link0] LCP: state change Starting --> Req-Sent Mar 2 10:06:28 pfSense ppp: [wan_link0] LCP: SendConfigReq #1 Mar 2 10:06:28 pfSense ppp: [wan_link0] PROTOCOMP Mar 2 10:06:28 pfSense ppp: [wan_link0] MRU 1492 Mar 2 10:06:28 pfSense ppp: [wan_link0] MAGICNUM 0x264ee23a Mar 2 10:06:28 pfSense ppp: [wan_link0] LCP: rec'd Configure Request #1 (Req-Sent) Mar 2 10:06:28 pfSense ppp: [wan_link0] MRU 1454 Mar 2 10:06:28 pfSense ppp: [wan_link0] AUTHPROTO CHAP MD5 Mar 2 10:06:28 pfSense ppp: [wan_link0] MAGICNUM 0x9cc0601d Mar 2 10:06:28 pfSense ppp: [wan_link0] LCP: SendConfigAck #1 Mar 2 10:06:28 pfSense ppp: [wan_link0] MRU 1454 Mar 2 10:06:28 pfSense ppp: [wan_link0] AUTHPROTO CHAP MD5 Mar 2 10:06:28 pfSense ppp: [wan_link0] MAGICNUM 0x9cc0601d Mar 2 10:06:28 pfSense ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Sent Mar 2 10:06:28 pfSense ppp: [wan_link0] LCP: rec'd Configure Ack #1 (Ack-Sent) Mar 2 10:06:28 pfSense ppp: [wan_link0] PROTOCOMP Mar 2 10:06:28 pfSense ppp: [wan_link0] MRU 1492 Mar 2 10:06:28 pfSense ppp: [wan_link0] MAGICNUM 0x264ee23a Mar 2 10:06:28 pfSense ppp: [wan_link0] LCP: state change Ack-Sent --> Opened Mar 2 10:06:28 pfSense ppp: [wan_link0] LCP: auth: peer wants CHAP, I want nothing Mar 2 10:06:28 pfSense ppp: [wan_link0] LCP: LayerUp Mar 2 10:06:28 pfSense ppp: [wan_link0] CHAP: rec'd CHALLENGE #1 len: 41 Mar 2 10:06:28 pfSense ppp: [wan_link0] Name: "<MY_LOCAL_ISPS_NODE_NAME>" Mar 2 10:06:28 pfSense ppp: [wan_link0] CHAP: Using authname "<MY_PPPOE_USERNAME>" Mar 2 10:06:28 pfSense ppp: [wan_link0] CHAP: sending RESPONSE #1 len: 40 Mar 2 10:06:28 pfSense ppp: [wan_link0] CHAP: rec'd SUCCESS #1 len: 4 Mar 2 10:06:28 pfSense ppp: [wan_link0] LCP: authorization successful Mar 2 10:06:28 pfSense ppp: [wan_link0] Link: Matched action 'bundle "wan" ""' Mar 2 10:06:28 pfSense ppp: [wan_link0] Link: Join bundle "wan" Mar 2 10:06:28 pfSense ppp: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps Mar 2 10:06:28 pfSense ppp: [wan] IPCP: Open event Mar 2 10:06:28 pfSense ppp: [wan] IPCP: state change Initial --> Starting Mar 2 10:06:28 pfSense ppp: [wan] IPCP: LayerStart Mar 2 10:06:28 pfSense ppp: [wan] IPV6CP: Open event Mar 2 10:06:28 pfSense ppp: [wan] IPV6CP: state change Initial --> Starting Mar 2 10:06:28 pfSense ppp: [wan] IPV6CP: LayerStart Mar 2 10:06:28 pfSense ppp: [wan] IPCP: Up event Mar 2 10:06:28 pfSense ppp: [wan] IPCP: state change Starting --> Req-Sent Mar 2 10:06:28 pfSense ppp: [wan] IPCP: SendConfigReq #1 Mar 2 10:06:28 pfSense ppp: [wan] IPADDR 0.0.0.0 Mar 2 10:06:28 pfSense ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Mar 2 10:06:28 pfSense ppp: [wan] IPV6CP: Up event Mar 2 10:06:28 pfSense ppp: [wan] IPV6CP: state change Starting --> Req-Sent Mar 2 10:06:28 pfSense ppp: [wan] IPV6CP: SendConfigReq #1 Mar 2 10:06:28 pfSense ppp: [wan] IPCP: rec'd Configure Request #1 (Req-Sent) Mar 2 10:06:28 pfSense ppp: [wan] IPADDR <ASSIGNED_IP#1> Mar 2 10:06:28 pfSense ppp: [wan] <ASSIGNED_IP#1> is OK Mar 2 10:06:28 pfSense ppp: [wan] IPCP: SendConfigAck #1 Mar 2 10:06:28 pfSense ppp: [wan] IPADDR <ASSIGNED_IP#1> Mar 2 10:06:28 pfSense ppp: [wan] IPCP: state change Req-Sent --> Ack-Sent Mar 2 10:06:28 pfSense ppp: [wan] IPCP: rec'd Configure Reject #1 (Ack-Sent) Mar 2 10:06:28 pfSense ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Mar 2 10:06:28 pfSense ppp: [wan] IPCP: SendConfigReq #2 Mar 2 10:06:28 pfSense ppp: [wan] IPADDR 0.0.0.0 Mar 2 10:06:28 pfSense ppp: [wan_link0] LCP: rec'd Protocol Reject #1 (Opened) Mar 2 10:06:28 pfSense ppp: [wan_link0] LCP: protocol IPV6CP was rejected Mar 2 10:06:28 pfSense ppp: [wan] IPV6CP: protocol was rejected by peer Mar 2 10:06:28 pfSense ppp: [wan] IPV6CP: state change Req-Sent --> Stopped Mar 2 10:06:28 pfSense ppp: [wan] IPV6CP: LayerFinish Mar 2 10:06:28 pfSense ppp: [wan] IPCP: rec'd Configure Nak #2 (Ack-Sent) Mar 2 10:06:28 pfSense ppp: [wan] IPADDR <ASSIGNED_IP#3> Mar 2 10:06:28 pfSense ppp: [wan] <ASSIGNED_IP#3> is OK Mar 2 10:06:28 pfSense ppp: [wan] IPCP: SendConfigReq #3 Mar 2 10:06:28 pfSense ppp: [wan] IPADDR <ASSIGNED_IP#3> Mar 2 10:06:28 pfSense ppp: [wan] IPCP: rec'd Configure Ack #3 (Ack-Sent) Mar 2 10:06:28 pfSense ppp: [wan] IPADDR <ASSIGNED_IP#3> Mar 2 10:06:28 pfSense ppp: [wan] IPCP: state change Ack-Sent --> Opened Mar 2 10:06:28 pfSense ppp: [wan] IPCP: LayerUp Mar 2 10:06:28 pfSense ppp: [wan] <ASSIGNED_IP#3> -> <ASSIGNED_IP#1> Mar 2 10:06:28 pfSense check_reload_status: rc.newwanip starting pppoe1 Mar 2 10:06:28 pfSense ppp: [wan] IFACE: Up event Mar 2 10:06:28 pfSense ppp: [wan] IFACE: Rename interface ng0 to pppoe1 Mar 2 10:06:29 pfSense php-fpm[66914]: /rc.newwanip: rc.newwanip: Info: starting on pppoe1. Mar 2 10:06:29 pfSense php-fpm[66914]: /rc.newwanip: rc.newwanip: on (IP address: <ASSIGNED_IP#3>) (interface: WAN[wan]) (real interface: pppoe1). Mar 2 10:06:29 pfSense dhcpleases: /etc/hosts changed size from original! Mar 2 10:06:29 pfSense php-fpm[66914]: /rc.newwanip: IP Address has changed, killing states on former IP Address <ASSIGNED_IP#2>. Mar 2 10:06:29 pfSense dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process. Mar 2 10:06:29 pfSense dhcpleases: /etc/hosts changed size from original! Mar 2 10:06:29 pfSense dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process. Mar 2 10:06:30 pfSense dhcpleases: kqueue error: unknown Mar 2 10:06:31 pfSense php-fpm[66914]: /rc.newwanip: Removing static route for monitor 1.1.1.1 and adding a new route through <ASSIGNED_IP#1> Mar 2 10:06:32 pfSense php-fpm[66914]: /rc.newwanip: Default gateway setting Interface WAN_PPPOE Gateway as default. Mar 2 10:06:32 pfSense php-fpm[66914]: /rc.newwanip: Gateway, none 'available' for inet6, use the first one configured. 'WAN_SLAAC' Mar 2 10:06:32 pfSense check_reload_status: updating dyndns wan Mar 2 10:06:32 pfSense check_reload_status: Reloading filter Mar 2 10:06:38 pfSense dhcpleases: /etc/hosts changed size from original! Mar 2 10:06:38 pfSense dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process. Mar 2 10:06:39 pfSense dhcpleases: kqueue error: unknown Mar 2 10:06:58 pfSense php-fpm[35214]: /rc.dyndns.update: Curl error occurred: Could not resolve host: freedns.afraid.org Mar 2 10:07:00 pfSense php-fpm[66914]: /rc.newwanip: phpDynDNS: updating cache file /conf/dyndns_wanfreedns'<my_dyndns_host>'0.cache: <ASSIGNED_IP#3> Mar 2 10:07:00 pfSense php-fpm[66914]: /rc.newwanip: phpDynDNS (<my_dyndns_host>): (Success) IP Address Changed Successfully! Mar 2 10:07:01 pfSense php-fpm[66914]: /rc.newwanip: Resyncing OpenVPN instances for interface WAN. Mar 2 10:07:01 pfSense php-fpm[66914]: OpenVPN terminate old pid: 79339 Mar 2 10:07:01 pfSense kernel: ovpns2: link state changed to DOWN Mar 2 10:07:01 pfSense check_reload_status: Reloading filter Mar 2 10:07:01 pfSense kernel: ovpns2: link state changed to UP Mar 2 10:07:01 pfSense php-fpm[66914]: OpenVPN PID written: 36835 Mar 2 10:07:01 pfSense check_reload_status: Reloading filter Mar 2 10:07:01 pfSense php-fpm[66914]: /rc.newwanip: Creating rrd update script Mar 2 10:07:01 pfSense check_reload_status: rc.newwanip starting ovpns2 Mar 2 10:07:02 pfSense php-fpm[340]: /rc.newwanip: rc.newwanip: Info: starting on ovpns2. Mar 2 10:07:02 pfSense php-fpm[340]: /rc.newwanip: rc.newwanip: on (IP address: 10.0.10.1) (interface: []) (real interface: ovpns2). Mar 2 10:07:02 pfSense php-fpm[340]: /rc.newwanip: rc.newwanip called with empty interface. Mar 2 10:07:02 pfSense php-fpm[340]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - -> 10.0.10.1 - Restarting packages. Mar 2 10:07:02 pfSense check_reload_status: Reloading filter Mar 2 10:07:02 pfSense check_reload_status: Starting packages Mar 2 10:07:03 pfSense php-fpm[340]: /rc.start_packages: Restarting/Starting all packages. Mar 2 10:07:03 pfSense php-fpm[340]: /rc.start_packages: The command '/usr/local/etc/rc.d/bandwidthd.sh stop' returned exit code '1', the output was 'No matching processes were found' Mar 2 10:07:03 pfSense php-fpm[66914]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - <ASSIGNED_IP#2> -> <ASSIGNED_IP#3> - Restarting packages. Mar 2 10:07:03 pfSense check_reload_status: Starting packages Mar 2 10:07:04 pfSense php-fpm[25829]: /rc.start_packages: Skipping STARTing packages process because previous/another instance is already running Mar 2 10:07:05 pfSense check_reload_status: Syncing firewall Mar 2 10:07:05 pfSense check_reload_status: Reloading filter Mar 2 10:07:05 pfSense php-fpm[340]: [pfBlockerNG] Restarting firewall filter daemon Mar 2 10:07:06 pfSense php_pfb: [pfBlockerNG] filterlog daemon started Mar 2 10:07:07 pfSense php-cgi: notify_monitor.php: Message sent to <MY_EMAIL> OK Mar 2 10:07:10 pfSense php-fpm[340]: /rc.start_packages: Download file failed with status code 0. URL: http://linuxnet.ca/ieee/oui/ethercodes.dat Mar 2 10:07:11 pfSense php: [pfBlockerNG] DNSBL parser daemon started Mar 2 10:07:11 pfSense php_pfb: [pfBlockerNG] filterlog daemon started Mar 2 10:07:13 pfSense arpwatch: listening on igb1
-
Is it on igb0? The log shows that NIC losing link entirely, like the modem rebooted maybe....
Steve
-
It is. I think you may be right. The link gets restored quick enough that it might not be rebooting but I think something is definitely happening on the modem. Almost wish it was happening more often so I could catch it during the moment...
Thanks for the input Steve.
-
Do the easy stuff first, swap out the cables, blow the dust out of the ports etc.
You can try adding a switch between igb0 and the modem. That will stop it losing link, the ppp session may not drop if the interruption is brief. It would also rule out any sort of link negotiation errors. If ir changes the behaviour at all that would be a clue.
Steve
-
Thanks. There's a GPON SFP in the ISP-issued router/modem that I can pull out, so I'm gonna grab an SFP->Ethernet media converter and see if I can rule out the modem. I've been looking for an excuse to get rid of the modem for a while to remove unnecessary power draw and heat. I like the suggestion of putting a switch in the middle.
It'd funny if it was just a cable in the end.
-
SFP is loaded in the media converter and my PPP session came up fine. I'll let you know if the connection stabilises or not! :)
-
All good so far. Will give it a few more days before calling it a success!
-
4 days uptime. Looks like it was a fault in the ISP router!