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
    

  • Netgate Administrator

    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.


  • Netgate Administrator

    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!


Log in to reply