Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    PPPoE session dropping intermittently

    Scheduled Pinned Locked Moved General pfSense Questions
    8 Posts 2 Posters 1.4k Views
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • O
      Orbixx
      last edited by

      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
      1 Reply Last reply Reply Quote 0
      • stephenw10S
        stephenw10 Netgate Administrator
        last edited by

        Is it on igb0? The log shows that NIC losing link entirely, like the modem rebooted maybe....

        Steve

        1 Reply Last reply Reply Quote 0
        • O
          Orbixx
          last edited by

          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.

          1 Reply Last reply Reply Quote 0
          • stephenw10S
            stephenw10 Netgate Administrator
            last edited by

            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

            1 Reply Last reply Reply Quote 0
            • O
              Orbixx
              last edited by

              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.

              1 Reply Last reply Reply Quote 0
              • O
                Orbixx
                last edited by

                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! :)

                1 Reply Last reply Reply Quote 0
                • O
                  Orbixx
                  last edited by

                  All good so far. Will give it a few more days before calling it a success!

                  1 Reply Last reply Reply Quote 1
                  • O
                    Orbixx
                    last edited by

                    4 days uptime. Looks like it was a fault in the ISP router!

                    1 Reply Last reply Reply Quote 1
                    • First post
                      Last post
                    Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.