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

    Recent PPPOE Issues - not auto reconnecting for some reason, used to.

    Scheduled Pinned Locked Moved General pfSense Questions
    9 Posts 2 Posters 852 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.
    • D
      dlewis_nepean
      last edited by

      I've been using PFSENSE CE for several years now, in several locations (other family members plus 2 at home). All of them use PPPOE.

      Recently (in the last couple of months) I've had an issue with one of my connections at home where the PPPOE drops and doesn't reconnect. It used to, but for some reason now it doesn't. Going to the Status/Interfaces menu I can click connect and it instantly connects. These issues seem to be growing in frequency over the last few days.

      It was just my one connection, now one of the other family members had the same issue (with the same ISP, but different Central office DSL Shelf I might add).

      It makes sense that it's something related to that ISP now that we're both having the issue, but what I don't understand is why isn't it reconnecting.

      Dial on demand is not checked.
      Idle Timeout is blank.

      here is the shortest PPP log snippet , the connection dropped at 4:45 am and I manually reset it at 5:09am. I have sanitized the logs, any ip that actually was there I changed to xxx.xxx.xxx.xxx

      Oct 12 04:45:05 ppp 54887 [wan] IPCP: rec'd Terminate Request #2 (Opened)
      Oct 12 04:45:05 ppp 54887 [wan] IPCP: state change Opened --> Stopping
      Oct 12 04:45:05 ppp 54887 [wan] IPCP: SendTerminateAck #4
      Oct 12 04:45:05 ppp 54887 [wan] IPCP: LayerDown
      Oct 12 04:45:05 ppp 54887 [wan] IFACE: Down event
      Oct 12 04:45:05 ppp 54887 [wan] IFACE: Rename interface pppoe1 to pppoe1
      Oct 12 04:45:07 ppp 54887 [wan] IPCP: state change Stopping --> Stopped
      Oct 12 04:45:07 ppp 54887 [wan] IPCP: LayerFinish
      Oct 12 04:45:07 ppp 54887 [wan] Bundle: No NCPs left. Closing links...
      Oct 12 04:45:07 ppp 54887 [wan] Bundle: closing link "wan_link0"...
      Oct 12 04:45:07 ppp 54887 [wan_link0] Link: CLOSE event
      Oct 12 04:45:07 ppp 54887 [wan_link0] LCP: Close event
      Oct 12 04:45:07 ppp 54887 [wan_link0] LCP: state change Opened --> Closing
      Oct 12 04:45:07 ppp 54887 [wan_link0] Link: Leave bundle "wan"
      Oct 12 04:45:07 ppp 54887 [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
      Oct 12 04:45:07 ppp 54887 [wan] IPCP: Close event
      Oct 12 04:45:07 ppp 54887 [wan] IPCP: state change Stopped --> Closed
      Oct 12 04:45:07 ppp 54887 [wan] IPV6CP: Close event
      Oct 12 04:45:07 ppp 54887 [wan] IPV6CP: state change Stopped --> Closed
      Oct 12 04:45:07 ppp 54887 [wan] IPCP: Down event
      Oct 12 04:45:07 ppp 54887 [wan] IPCP: state change Closed --> Initial
      Oct 12 04:45:07 ppp 54887 [wan] IPV6CP: Down event
      Oct 12 04:45:07 ppp 54887 [wan] IPV6CP: state change Closed --> Initial
      Oct 12 04:45:07 ppp 54887 [wan_link0] LCP: SendTerminateReq #4
      Oct 12 04:45:07 ppp 54887 [wan_link0] LCP: LayerDown
      Oct 12 04:45:09 ppp 54887 [wan_link0] LCP: SendTerminateReq #5
      Oct 12 04:45:11 ppp 54887 [wan_link0] LCP: state change Closing --> Closed
      Oct 12 04:45:11 ppp 54887 [wan_link0] LCP: LayerFinish
      Oct 12 04:45:11 ppp 54887 [wan_link0] Link: DOWN event
      Oct 12 04:45:11 ppp 54887 [wan_link0] LCP: Down event
      Oct 12 04:45:11 ppp 54887 [wan_link0] LCP: state change Closed --> Initial
      Oct 12 05:09:01 ppp 91308 Multi-link PPP daemon for FreeBSD
      Oct 12 05:09:01 ppp 91308 process 91308 started, version 5.9
      Oct 12 05:09:01 ppp 91308 waiting for process 54887 to die...
      Oct 12 05:09:01 ppp 54887 caught fatal signal TERM
      Oct 12 05:09:01 ppp 54887 [wan] IFACE: Close event
      Oct 12 05:09:01 ppp 54887 [wan] IPCP: Close event
      Oct 12 05:09:01 ppp 54887 [wan] IPV6CP: Close event
      Oct 12 05:09:02 ppp 91308 waiting for process 54887 to die...
      Oct 12 05:09:03 ppp 91308 waiting for process 54887 to die...
      Oct 12 05:09:03 ppp 54887 [wan] Bundle: Shutdown
      Oct 12 05:09:03 ppp 54887 [wan_link0] Link: Shutdown
      Oct 12 05:09:03 ppp 54887 process 54887 terminated
      Oct 12 05:09:04 ppp 91308 web: web is not running
      Oct 12 05:09:04 ppp 91308 [wan] Bundle: Interface ng0 created
      Oct 12 05:09:04 ppp 91308 mpd_wan.conf:14: Error in 'set iface addrs xxx.xxx.xxx.xxx'
      Oct 12 05:09:04 ppp 91308 [wan_link0] Link: OPEN event
      Oct 12 05:09:04 ppp 91308 [wan_link0] LCP: Open event
      Oct 12 05:09:04 ppp 91308 [wan_link0] LCP: state change Initial --> Starting
      Oct 12 05:09:04 ppp 91308 [wan_link0] LCP: LayerStart
      Oct 12 05:09:04 ppp 91308 [wan_link0] PPPoE: Connecting to 'INTERNET'
      Oct 12 05:09:04 ppp 91308 PPPoE: rec'd ACNAME "DSL CO SHELF NAME"
      Oct 12 05:09:04 ppp 91308 [wan_link0] PPPoE: connection successful
      Oct 12 05:09:04 ppp 91308 [wan_link0] Link: UP event
      Oct 12 05:09:04 ppp 91308 [wan_link0] LCP: Up event
      Oct 12 05:09:04 ppp 91308 [wan_link0] LCP: state change Starting --> Req-Sent
      Oct 12 05:09:04 ppp 91308 [wan_link0] LCP: SendConfigReq #1
      Oct 12 05:09:04 ppp 91308 [wan_link0] PROTOCOMP
      Oct 12 05:09:04 ppp 91308 [wan_link0] MRU 1492
      Oct 12 05:09:04 ppp 91308 [wan_link0] MAGICNUM 0x1e521d78
      Oct 12 05:09:04 ppp 91308 [wan_link0] LCP: rec'd Configure Request #121 (Req-Sent)
      Oct 12 05:09:04 ppp 91308 [wan_link0] MRU 1492
      Oct 12 05:09:04 ppp 91308 [wan_link0] AUTHPROTO PAP
      Oct 12 05:09:04 ppp 91308 [wan_link0] MAGICNUM 0x00c470b4
      Oct 12 05:09:04 ppp 91308 [wan_link0] LCP: SendConfigAck #121
      Oct 12 05:09:04 ppp 91308 [wan_link0] MRU 1492
      Oct 12 05:09:04 ppp 91308 [wan_link0] AUTHPROTO PAP
      Oct 12 05:09:04 ppp 91308 [wan_link0] MAGICNUM 0x00c470b4
      Oct 12 05:09:04 ppp 91308 [wan_link0] LCP: state change Req-Sent --> Ack-Sent
      Oct 12 05:09:04 ppp 91308 [wan_link0] LCP: rec'd Configure Reject #1 (Ack-Sent)
      Oct 12 05:09:04 ppp 91308 [wan_link0] PROTOCOMP
      Oct 12 05:09:04 ppp 91308 [wan_link0] LCP: SendConfigReq #2
      Oct 12 05:09:04 ppp 91308 [wan_link0] MRU 1492
      Oct 12 05:09:04 ppp 91308 [wan_link0] MAGICNUM 0x1e521d78
      Oct 12 05:09:04 ppp 91308 [wan_link0] LCP: rec'd Configure Ack #2 (Ack-Sent)
      Oct 12 05:09:04 ppp 91308 [wan_link0] MRU 1492
      Oct 12 05:09:04 ppp 91308 [wan_link0] MAGICNUM 0x1e521d78
      Oct 12 05:09:04 ppp 91308 [wan_link0] LCP: state change Ack-Sent --> Opened
      Oct 12 05:09:04 ppp 91308 [wan_link0] LCP: auth: peer wants PAP, I want nothing
      Oct 12 05:09:04 ppp 91308 [wan_link0] PAP: using authname "username@isp.com"
      Oct 12 05:09:04 ppp 91308 [wan_link0] PAP: sending REQUEST #1 len: 28
      Oct 12 05:09:04 ppp 91308 [wan_link0] LCP: LayerUp
      Oct 12 05:09:05 ppp 91308 [wan_link0] LCP: rec'd Configure Request #1 (Opened)
      Oct 12 05:09:05 ppp 91308 [wan_link0] ACCMAP 0x000a0000
      Oct 12 05:09:05 ppp 91308 [wan_link0] MRU 1492
      Oct 12 05:09:05 ppp 91308 [wan_link0] MAGICNUM 0x9bb57090
      Oct 12 05:09:05 ppp 91308 [wan_link0] AUTHPROTO PAP
      Oct 12 05:09:05 ppp 91308 [wan_link0] LCP: LayerDown
      Oct 12 05:09:05 ppp 91308 [wan_link0] LCP: SendConfigReq #3
      Oct 12 05:09:05 ppp 91308 [wan_link0] MRU 1492
      Oct 12 05:09:05 ppp 91308 [wan_link0] MAGICNUM 0x1e521d78
      Oct 12 05:09:05 ppp 91308 [wan_link0] LCP: SendConfigAck #1
      Oct 12 05:09:05 ppp 91308 [wan_link0] ACCMAP 0x000a0000
      Oct 12 05:09:05 ppp 91308 [wan_link0] MRU 1492
      Oct 12 05:09:05 ppp 91308 [wan_link0] MAGICNUM 0x9bb57090
      Oct 12 05:09:05 ppp 91308 [wan_link0] AUTHPROTO PAP
      Oct 12 05:09:05 ppp 91308 [wan_link0] LCP: state change Opened --> Ack-Sent
      Oct 12 05:09:05 ppp 91308 [wan_link0] LCP: rec'd Configure Ack #3 (Ack-Sent)
      Oct 12 05:09:05 ppp 91308 [wan_link0] MRU 1492
      Oct 12 05:09:05 ppp 91308 [wan_link0] MAGICNUM 0x1e521d78
      Oct 12 05:09:05 ppp 91308 [wan_link0] LCP: state change Ack-Sent --> Opened
      Oct 12 05:09:05 ppp 91308 [wan_link0] LCP: auth: peer wants PAP, I want nothing
      Oct 12 05:09:05 ppp 91308 [wan_link0] PAP: using authname "username@isp.com"
      Oct 12 05:09:05 ppp 91308 [wan_link0] PAP: sending REQUEST #1 len: 28
      Oct 12 05:09:05 ppp 91308 [wan_link0] LCP: LayerUp
      Oct 12 05:09:05 ppp 91308 [wan_link0] PAP: rec'd ACK #1 len: 12
      Oct 12 05:09:05 ppp 91308 [wan_link0] MESG: Welcome
      Oct 12 05:09:05 ppp 91308 [wan_link0] LCP: authorization successful
      Oct 12 05:09:05 ppp 91308 [wan_link0] Link: Matched action 'bundle "wan" ""'
      Oct 12 05:09:05 ppp 91308 [wan_link0] Link: Join bundle "wan"
      Oct 12 05:09:05 ppp 91308 [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
      Oct 12 05:09:05 ppp 91308 [wan] IPCP: Open event
      Oct 12 05:09:05 ppp 91308 [wan] IPCP: state change Initial --> Starting
      Oct 12 05:09:05 ppp 91308 [wan] IPCP: LayerStart
      Oct 12 05:09:05 ppp 91308 [wan] IPV6CP: Open event
      Oct 12 05:09:05 ppp 91308 [wan] IPV6CP: state change Initial --> Starting
      Oct 12 05:09:05 ppp 91308 [wan] IPV6CP: LayerStart
      Oct 12 05:09:05 ppp 91308 [wan] IPCP: Up event
      Oct 12 05:09:05 ppp 91308 [wan] IPCP: state change Starting --> Req-Sent
      Oct 12 05:09:05 ppp 91308 [wan] IPCP: SendConfigReq #1
      Oct 12 05:09:05 ppp 91308 [wan] IPADDR 0.0.0.0
      Oct 12 05:09:05 ppp 91308 [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
      Oct 12 05:09:05 ppp 91308 [wan] PRIDNS 0.0.0.0
      Oct 12 05:09:05 ppp 91308 [wan] SECDNS 0.0.0.0
      Oct 12 05:09:05 ppp 91308 [wan] IPV6CP: Up event
      Oct 12 05:09:05 ppp 91308 [wan] IPV6CP: state change Starting --> Req-Sent
      Oct 12 05:09:05 ppp 91308 [wan] IPV6CP: SendConfigReq #1
      Oct 12 05:09:05 ppp 91308 [wan] IPCP: rec'd Configure Request #1 (Req-Sent)
      Oct 12 05:09:05 ppp 91308 [wan] IPADDR xxx.xxx.xxx.xxx
      Oct 12 05:09:05 ppp 91308 [wan] xxx.xxx.xxx.xxx is OK
      Oct 12 05:09:05 ppp 91308 [wan] IPCP: SendConfigAck #1
      Oct 12 05:09:05 ppp 91308 [wan] IPADDR xxx.xxx.xxx.xxx
      Oct 12 05:09:05 ppp 91308 [wan] IPCP: state change Req-Sent --> Ack-Sent
      Oct 12 05:09:05 ppp 91308 [wan] IPCP: rec'd Configure Reject #1 (Ack-Sent)
      Oct 12 05:09:05 ppp 91308 [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
      Oct 12 05:09:05 ppp 91308 [wan] IPCP: SendConfigReq #2
      Oct 12 05:09:05 ppp 91308 [wan] IPADDR 0.0.0.0
      Oct 12 05:09:05 ppp 91308 [wan] PRIDNS 0.0.0.0
      Oct 12 05:09:05 ppp 91308 [wan] SECDNS 0.0.0.0
      Oct 12 05:09:05 ppp 91308 [wan_link0] LCP: rec'd Protocol Reject #1 (Opened)
      Oct 12 05:09:05 ppp 91308 [wan_link0] LCP: protocol IPV6CP was rejected
      Oct 12 05:09:05 ppp 91308 [wan] IPV6CP: protocol was rejected by peer
      Oct 12 05:09:05 ppp 91308 [wan] IPV6CP: state change Req-Sent --> Stopped
      Oct 12 05:09:05 ppp 91308 [wan] IPV6CP: LayerFinish
      Oct 12 05:09:05 ppp 91308 [wan] IPCP: rec'd Configure Nak #2 (Ack-Sent)
      Oct 12 05:09:05 ppp 91308 [wan] IPADDR xxx.xxx.xxx.xxx
      Oct 12 05:09:05 ppp 91308 [wan] xxx.xxx.xxx.xxx is OK
      Oct 12 05:09:05 ppp 91308 [wan] PRIDNS xxx.xxx.xxx.xxx
      Oct 12 05:09:05 ppp 91308 [wan] SECDNS xxx.xxx.xxx.xxx
      Oct 12 05:09:05 ppp 91308 [wan] IPCP: SendConfigReq #3
      Oct 12 05:09:05 ppp 91308 [wan] IPADDR xxx.xxx.xxx.xxx
      Oct 12 05:09:05 ppp 91308 [wan] PRIDNS xxx.xxx.xxx.xxx
      Oct 12 05:09:05 ppp 91308 [wan] SECDNS xxx.xxx.xxx.xxx
      Oct 12 05:09:05 ppp 91308 [wan] IPCP: rec'd Configure Ack #3 (Ack-Sent)
      Oct 12 05:09:05 ppp 91308 [wan] IPADDR xxx.xxx.xxx.xxx
      Oct 12 05:09:05 ppp 91308 [wan] PRIDNS xxx.xxx.xxx.xxx
      Oct 12 05:09:05 ppp 91308 [wan] SECDNS xxx.xxx.xxx.xxx
      Oct 12 05:09:05 ppp 91308 [wan] IPCP: state change Ack-Sent --> Opened
      Oct 12 05:09:05 ppp 91308 [wan] IPCP: LayerUp
      Oct 12 05:09:05 ppp 91308 [wan] xxx.xxx.xxx.xxx -> xxx.xxx.xxx.xxx
      Oct 12 05:09:06 ppp 91308 [wan] IFACE: Up event
      Oct 12 05:09:06 ppp 91308 [wan] IFACE: Rename interface ng0 to pppoe1

      2nd site this morning.. similar, but I only put in the part up to the PPPO connection successful"

      Oct 13 01:13:04 ppp 10069 [wan] IPCP: rec'd Terminate Request #2 (Opened)
      Oct 13 01:13:04 ppp 10069 [wan] IPCP: state change Opened --> Stopping
      Oct 13 01:13:04 ppp 10069 [wan] IPCP: SendTerminateAck #4
      Oct 13 01:13:04 ppp 10069 [wan] IPCP: LayerDown
      Oct 13 01:13:04 ppp 10069 [wan] IFACE: Down event
      Oct 13 01:13:04 ppp 10069 [wan] IFACE: Rename interface pppoe0 to pppoe0
      Oct 13 01:13:04 ppp 10069 [wan] IFACE: Set description "WAN"
      Oct 13 01:13:07 ppp 10069 [wan] IPCP: state change Stopping --> Stopped
      Oct 13 01:13:07 ppp 10069 [wan] IPCP: LayerFinish
      Oct 13 01:13:07 ppp 10069 [wan] Bundle: No NCPs left. Closing links...
      Oct 13 01:13:07 ppp 10069 [wan] Bundle: closing link "wan_link0"...
      Oct 13 01:13:07 ppp 10069 [wan_link0] Link: CLOSE event
      Oct 13 01:13:07 ppp 10069 [wan_link0] LCP: Close event
      Oct 13 01:13:07 ppp 10069 [wan_link0] LCP: state change Opened --> Closing
      Oct 13 01:13:07 ppp 10069 [wan_link0] Link: Leave bundle "wan"
      Oct 13 01:13:07 ppp 10069 [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
      Oct 13 01:13:07 ppp 10069 [wan] IPCP: Close event
      Oct 13 01:13:07 ppp 10069 [wan] IPCP: state change Stopped --> Closed
      Oct 13 01:13:07 ppp 10069 [wan] IPCP: Down event
      Oct 13 01:13:07 ppp 10069 [wan] IPCP: state change Closed --> Initial
      Oct 13 01:13:07 ppp 10069 [wan_link0] LCP: SendTerminateReq #5
      Oct 13 01:13:07 ppp 10069 [wan_link0] LCP: LayerDown
      Oct 13 01:13:09 ppp 10069 [wan_link0] LCP: SendTerminateReq #6
      Oct 13 01:13:11 ppp 10069 [wan_link0] LCP: state change Closing --> Closed
      Oct 13 01:13:11 ppp 10069 [wan_link0] LCP: LayerFinish
      Oct 13 01:13:11 ppp 10069 [wan_link0] Link: DOWN event
      Oct 13 01:13:11 ppp 10069 [wan_link0] LCP: Down event
      Oct 13 01:13:11 ppp 10069 [wan_link0] LCP: state change Closed --> Initial
      Oct 13 05:21:17 ppp 4391 Multi-link PPP daemon for FreeBSD
      Oct 13 05:21:17 ppp 4391 process 4391 started, version 5.9
      Oct 13 05:21:17 ppp 4391 waiting for process 10069 to die...
      Oct 13 05:21:17 ppp 10069 caught fatal signal TERM
      Oct 13 05:21:17 ppp 10069 [wan] IFACE: Close event
      Oct 13 05:21:17 ppp 10069 [wan] IPCP: Close event
      Oct 13 05:21:18 ppp 4391 waiting for process 10069 to die...
      Oct 13 05:21:19 ppp 10069 [wan] Bundle: Shutdown
      Oct 13 05:21:19 ppp 4391 waiting for process 10069 to die...
      Oct 13 05:21:19 ppp 10069 [wan_link0] Link: Shutdown
      Oct 13 05:21:19 ppp 10069 process 10069 terminated
      Oct 13 05:21:20 ppp 4391 web: web is not running
      Oct 13 05:21:20 ppp 4391 [wan] Bundle: Interface ng0 created
      Oct 13 05:21:20 ppp 4391 [wan_link0] Link: OPEN event
      Oct 13 05:21:20 ppp 4391 [wan_link0] LCP: Open event
      Oct 13 05:21:20 ppp 4391 [wan_link0] LCP: state change Initial --> Starting
      Oct 13 05:21:20 ppp 4391 [wan_link0] LCP: LayerStart
      Oct 13 05:21:20 ppp 4391 [wan_link0] PPPoE: Connecting to 'Internet'
      Oct 13 05:21:20 ppp 4391 PPPoE: rec'd ACNAME "DSL CO SHELF"
      Oct 13 05:21:20 ppp 4391 [wan_link0] PPPoE: connection successful

      Has anyone seen this ?
      Any ideas what I could do to get it to reconnect automatically ?
      I hate to even suggest it but maybe even a cron script that checks the PPPOE interface and then restarts it if it's down.

      Is there any way to debug PPPOE in more detail to see more of what is happening ?

      For what it's worth the 2 hardware devices that this is happening on are

      1. Protectli box with intel nics
      2. Supermicro E300-8D with Intel nics

      Thanks in advance for any help

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

        Hmm, that's curious. It looks like the remote side closes the connection and it simply never tries to connect.

        Anything in the system logs when that happens?

        You are running 2.6 in both locations?

        Steve

        D 1 Reply Last reply Reply Quote 0
        • D
          dlewis_nepean @stephenw10
          last edited by

          @stephenw10
          Yup 2.6 everywhere.

          as for system logs I grabbed them from the one system (significantly less running on it, than mine) so there is less garbage, but they both basically say the same thing. I don't see anything that jumps out at me. The PPPOE drops, interfaces drop, my IPSEC tunnels drop and it just sort of sits there until I say connect at 5:21am. I see no errors on any physical interfaces at either site. Both sites are using different modems, in fact both are on different service the one , the Protectli box is an old 6meg straight DSL. The Supermicro is a 50meg ADSL2/VDSL or whatever you want to call it now.

          Oct 13 01:13:04 ppp 10069 [wan] IPCP: rec'd Terminate Request #2 (Opened)
          Oct 13 01:13:04 ppp 10069 [wan] IPCP: state change Opened --> Stopping
          Oct 13 01:13:04 ppp 10069 [wan] IPCP: SendTerminateAck #4
          Oct 13 01:13:04 ppp 10069 [wan] IPCP: LayerDown
          Oct 13 01:13:04 check_reload_status 398 Rewriting resolv.conf
          Oct 13 01:13:04 ppp 10069 [wan] IFACE: Down event
          Oct 13 01:13:04 ppp 10069 [wan] IFACE: Rename interface pppoe0 to pppoe0
          Oct 13 01:13:04 ppp 10069 [wan] IFACE: Set description "WAN"
          Oct 13 01:13:07 ppp 10069 [wan] IPCP: state change Stopping --> Stopped
          Oct 13 01:13:07 ppp 10069 [wan] IPCP: LayerFinish
          Oct 13 01:13:07 ppp 10069 [wan] Bundle: No NCPs left. Closing links...
          Oct 13 01:13:07 ppp 10069 [wan] Bundle: closing link "wan_link0"...
          Oct 13 01:13:07 ppp 10069 [wan_link0] Link: CLOSE event
          Oct 13 01:13:07 ppp 10069 [wan_link0] LCP: Close event
          Oct 13 01:13:07 ppp 10069 [wan_link0] LCP: state change Opened --> Closing
          Oct 13 01:13:07 ppp 10069 [wan_link0] Link: Leave bundle "wan"
          Oct 13 01:13:07 ppp 10069 [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
          Oct 13 01:13:07 ppp 10069 [wan] IPCP: Close event
          Oct 13 01:13:07 ppp 10069 [wan] IPCP: state change Stopped --> Closed
          Oct 13 01:13:07 ppp 10069 [wan] IPCP: Down event
          Oct 13 01:13:07 ppp 10069 [wan] IPCP: state change Closed --> Initial
          Oct 13 01:13:07 ppp 10069 [wan_link0] LCP: SendTerminateReq #5
          Oct 13 01:13:07 ppp 10069 [wan_link0] LCP: LayerDown
          Oct 13 01:13:09 ppp 10069 [wan_link0] LCP: SendTerminateReq #6
          Oct 13 01:13:11 ppp 10069 [wan_link0] LCP: state change Closing --> Closed
          Oct 13 01:13:11 ppp 10069 [wan_link0] LCP: LayerFinish
          Oct 13 01:13:11 ppp 10069 [wan_link0] Link: DOWN event
          Oct 13 01:13:11 ppp 10069 [wan_link0] LCP: Down event
          Oct 13 01:13:11 ppp 10069 [wan_link0] LCP: state change Closed --> Initial
          Oct 13 01:13:19 rc.gateway_alarm 73248 >>> Gateway alarm: WAN_PPPOE (Addr:xxx.xxx.xxx.xxx Alarm:1 RTT:19.468ms RTTsd:41.610ms Loss:21%)
          Oct 13 01:13:19 check_reload_status 398 updating dyndns WAN_PPPOE
          Oct 13 01:13:19 check_reload_status 398 Restarting IPsec tunnels
          Oct 13 01:13:19 check_reload_status 398 Restarting OpenVPN tunnels/interfaces
          Oct 13 01:13:19 check_reload_status 398 Reloading filter
          Oct 13 01:13:19 rc.gateway_alarm 76126 >>> Gateway alarm: DSLCOTEK_VTIV4 (Addr:yyy.yyy.yyy.yyy Alarm:1 RTT:41.122ms RTTsd:12.488ms Loss:21%)
          Oct 13 01:13:19 check_reload_status 398 updating dyndns DSLCOTEK_VTIV4
          Oct 13 01:13:19 check_reload_status 398 Restarting IPsec tunnels
          Oct 13 01:13:19 check_reload_status 398 Restarting OpenVPN tunnels/interfaces
          Oct 13 01:13:19 check_reload_status 398 Reloading filter
          Oct 13 01:13:19 rc.gateway_alarm 78479 >>> Gateway alarm: DSLOFFSITE_VTIV4 (Addr:yyy.yyy.yyy.yyy Alarm:1 RTT:47.043ms RTTsd:52.082ms Loss:22%)
          Oct 13 01:13:20 php-fpm 920 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. ''
          Oct 13 01:13:20 php-fpm 920 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. ''
          Oct 13 01:13:35 php-fpm 61687 /rc.ipsec: IPSEC: One or more IPsec tunnel gateways have changed. Refreshing.
          Oct 13 01:13:35 check_reload_status 398 Reloading filter
          Oct 13 01:13:35 php-fpm 61687 /rc.ipsec: IPsec ERROR: Could not find phase 1 source for connection Tunnel1. Omitting from configuration file.
          Oct 13 01:13:35 php-fpm 61687 /rc.ipsec: IPsec ERROR: Could not find phase 1 source for connection Tunnel2. Omitting from configuration file.
          Oct 13 01:13:35 php-fpm 61687 /rc.ipsec: IPsec ERROR: Could not find phase 1 source for connection Tunnel3. Omitting from configuration file.
          Oct 13 01:23:00 sshguard 49580 Exiting on signal.
          Oct 13 01:23:00 sshguard 62991 Now monitoring attacks.
          Oct 13 01:40:00 sshguard 62991 Exiting on signal.
          Oct 13 01:40:00 sshguard 58989 Now monitoring attacks.
          Oct 13 01:44:00 sshguard 58989 Exiting on signal.
          Oct 13 01:44:00 sshguard 25593 Now monitoring attacks.
          Oct 13 01:57:00 sshguard 25593 Exiting on signal.
          Oct 13 01:57:00 sshguard 77270 Now monitoring attacks.
          Oct 13 02:14:00 sshguard 77270 Exiting on signal.
          Oct 13 02:14:00 sshguard 3241 Now monitoring attacks.
          Oct 13 02:15:00 sshguard 3241 Exiting on signal.
          Oct 13 02:15:00 sshguard 50790 Now monitoring attacks.
          Oct 13 02:31:00 sshguard 50790 Exiting on signal.
          Oct 13 02:31:00 sshguard 87512 Now monitoring attacks.
          Oct 13 02:46:00 sshguard 87512 Exiting on signal.
          Oct 13 02:46:00 sshguard 24487 Now monitoring attacks.
          Oct 13 02:48:00 sshguard 24487 Exiting on signal.
          Oct 13 02:48:00 sshguard 10620 Now monitoring attacks.
          Oct 13 03:05:00 sshguard 10620 Exiting on signal.
          Oct 13 03:05:00 sshguard 40193 Now monitoring attacks.
          Oct 13 03:17:00 sshguard 40193 Exiting on signal.
          Oct 13 03:17:00 sshguard 18223 Now monitoring attacks.
          Oct 13 03:22:00 sshguard 18223 Exiting on signal.
          Oct 13 03:22:00 sshguard 30668 Now monitoring attacks.
          Oct 13 03:39:00 sshguard 30668 Exiting on signal.
          Oct 13 03:39:00 sshguard 57436 Now monitoring attacks.
          Oct 13 03:56:00 sshguard 57436 Exiting on signal.
          Oct 13 03:56:00 sshguard 49773 Now monitoring attacks.
          Oct 13 04:03:00 sshguard 49773 Exiting on signal.
          Oct 13 04:03:00 sshguard 42701 Now monitoring attacks.
          Oct 13 04:13:00 sshguard 42701 Exiting on signal.
          Oct 13 04:13:00 sshguard 78200 Now monitoring attacks.
          Oct 13 04:30:00 sshguard 78200 Exiting on signal.
          Oct 13 04:30:00 sshguard 88685 Now monitoring attacks.
          Oct 13 04:47:00 sshguard 88685 Exiting on signal.
          Oct 13 04:47:00 sshguard 81111 Now monitoring attacks.
          Oct 13 04:51:00 sshguard 81111 Exiting on signal.
          Oct 13 04:51:00 sshguard 53941 Now monitoring attacks.
          Oct 13 05:04:00 sshguard 53941 Exiting on signal.
          Oct 13 05:04:00 sshguard 16576 Now monitoring attacks.
          Oct 13 05:21:00 sshguard 16576 Exiting on signal.
          Oct 13 05:21:00 sshguard 1856 Now monitoring attacks.
          Oct 13 05:21:17 ppp 4391 Multi-link PPP daemon for FreeBSD
          Oct 13 05:21:17 ppp 4391 process 4391 started, version 5.9
          Oct 13 05:21:17 ppp 4391 waiting for process 10069 to die...
          Oct 13 05:21:17 ppp 10069 caught fatal signal TERM
          Oct 13 05:21:17 ppp 10069 [wan] IFACE: Close event
          Oct 13 05:21:17 ppp 10069 [wan] IPCP: Close event
          Oct 13 05:21:18 ppp 4391 waiting for process 10069 to die...
          Oct 13 05:21:19 ppp 10069 [wan] Bundle: Shutdown
          Oct 13 05:21:19 ppp 4391 waiting for process 10069 to die...
          Oct 13 05:21:19 kernel pppoe0: promiscuous mode disabled
          Oct 13 05:21:19 ppp 10069 [wan_link0] Link: Shutdown
          Oct 13 05:21:19 ppp 10069 process 10069 terminated
          Oct 13 05:21:20 ppp 4391 web: web is not running
          Oct 13 05:21:20 ppp 4391 [wan] Bundle: Interface ng0 created
          Oct 13 05:21:20 ppp 4391 [wan_link0] Link: OPEN event
          Oct 13 05:21:20 kernel ng0: changing name to 'pppoe0'
          Oct 13 05:21:20 ppp 4391 [wan_link0] LCP: Open event
          Oct 13 05:21:20 ppp 4391 [wan_link0] LCP: state change Initial --> Starting
          Oct 13 05:21:20 ppp 4391 [wan_link0] LCP: LayerStart
          Oct 13 05:21:20 ppp 4391 [wan_link0] PPPoE: Connecting to 'Internet'
          Oct 13 05:21:20 ppp 4391 PPPoE: rec'd ACNAME "DSL CO SHELF ID"
          Oct 13 05:21:20 ppp 4391 [wan_link0] PPPoE: connection successful
          Oct 13 05:21:20 ppp 4391 [wan_link0] Link: UP event

          If the trend continues It will probably drop tonight again.

          I haven't reached out to the ISP yet, if nothing else other than it simply looks like PFSENSE doesn't even try.. if I was seeing LCP errors, no response etc.. that would be different in my mind. Clearly since they both dropped at a very close time last night I suspect there may have been something going on at the ISP or on Bell Canada's concentrators that forward the connection onto the independent isp, but that still doesn't explain why it didn't even try to reconnect.

          1 Reply Last reply Reply Quote 0
          • D
            dlewis_nepean
            last edited by

            7e90417f-919b-413c-a6c5-18d0d9f107e7-image.png

            and just to show for certain, here's the dial on demand and idle timeout settings, the same on both boxes.

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

              Try checking the generated mpd.conf file. It will be in /var/etc probably named mpd_wan.conf.

              Make sure it has at least:

              	set iface disable on-demand

              and some keep-alive values.

              Though from your logs it looks more like mpd is killed entirely...

              Steve

              D 1 Reply Last reply Reply Quote 0
              • D
                dlewis_nepean @stephenw10
                last edited by

                @stephenw10
                Interestingly enough even though both Gui's looks the same for Dial on demand and idle timeout. the actual config files don't look the same .

                Site1 :

                set iface enable on-demand
                set iface idle 0

                set link keep-alive 10 60
                set link max-redial 0

                Site 2:

                set iface disable on-demand
                set iface idle 0

                set link keep-alive 10 60
                set link max-redial 0

                Full config attached. ppp config snippet.txt

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

                  Hmm, well I would certainly resave the PPP config at site 1 and see if it generates new mpd file with on-demand disabled.

                  D 1 Reply Last reply Reply Quote 0
                  • D
                    dlewis_nepean @stephenw10
                    last edited by

                    @stephenw10
                    ok so @ site 1 I tried resaving the ppp config didn't do anything.
                    I then tried enabling the on-demand option, saving it and then unchecking it and resaving it to see if that would shake something up.
                    still no go..

                    The mpd_wan.conf that is in the /var/etc shows as link from /conf/mpd_wan.conf
                    that one shows it hasn't been written to since July 8th 2020

                    ls -la /conf/mpd_wan.conf
                    -rw-r--r-- 1 root wheel 914 Jul 8 2020 /conf/mpd_wan.conf

                    but sym link to the file shows it was created yesterday

                    lrwxr-xr-x 1 root wheel 18 Oct 13 05:05 mpd_wan.conf -> /conf/mpd_wan.conf

                    All the other pfsense installs I have don't have the sym link they have the actual file in the /var/etc.

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

                      Ah you have a custom file. pfSense allows you to create the file in /conf and it will use that in preference to anything generated by the gui. That way you can use an entirely custom config if you need something that cannot be set using the gui alone.
                      So at some point you must have created that and usually it would be to add something custom.
                      If you just rename that file and resave the page it should create the expected file in /var/etc from the configured gui settings.

                      Steve

                      1 Reply Last reply Reply Quote 0
                      • GertjanG Gertjan referenced this topic on
                      • GertjanG Gertjan referenced this topic on
                      • GertjanG Gertjan referenced this topic on
                      • GertjanG Gertjan referenced this topic on
                      • First post
                        Last post
                      Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.