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

dlewis_nepean · Oct 13, 2022, 9:51 AM

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

Protectli box with intel nics
Supermicro E300-8D with Intel nics

Thanks in advance for any help

stephenw10 · Oct 14, 2022, 3:01 AM

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

dlewis_nepean · Oct 14, 2022, 3:01 AM

@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.

dlewis_nepean · Oct 14, 2022, 3:03 AM

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

stephenw10 · Oct 14, 2022, 3:49 PM

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

dlewis_nepean · Oct 14, 2022, 3:49 PM

@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

stephenw10 · Oct 14, 2022, 5:06 PM

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

dlewis_nepean · Oct 15, 2022, 3:07 AM

@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.

stephenw10 · Oct 15, 2022, 10:37 AM

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