PPPoE not reconnecting

[bobbythomas]

 Hi Team,

It was a smooth transition from 18.1 to 18.7 everything went well but after the upgrade I started noticing issues with my PPPoE connection, if the connection goes down it doesn't come back automatically, I have to login to firewall and issue connect option or reload the interface to bring back the connection. I have a multiwan setup and I don't see any specific logs. Anyone else experienced this?

Thank you,
Regards,
Bobby Thomas

[bobbythomas]

System log only shows removing interface from Multi WAN group as link state is down. While ppps.log shows only events from 3rd August (The day I performed the update).

[marjohn56]

I don't have multiwan, but do use PPPOE, I've not had any issues with it.

[bobbythomas]

I think the issue is with PPPoE, even if the PPPoE link is up the the gateway shows down. When the primary link goes down the pppoe link doesn't takeover, it will be in down state as the gateway monitoring fails. I rolled back to 18.1 (vm snapshot) and it is working fine. So this is something related to pppoe on 18.7.

[marjohn56]

can you post some the system logs showing when this happens?


Please obfuscate any incriminating IP addresses. , but leave the first and the last quartet so we can tell whether its a local or global address.

[bobbythomas]

Sure, I will attach the logs today evening, right now I am not in a position to roll back to 18.7 as I will lose internet.

I will update this thread soon.

Thank you,
Regards,
Bobby Thomas

[bobbythomas]

Apologies for the delay. It doesn't seems to be related to the version, I see the issue on 18.1 as well as on 18.7. Even if PPPoE hadnshake completes the gateway remains down. I see an IPV4 address getting assigned to it but then the gateway is marked down. I don't see packets going outbound through that gateway and when I try to ping an outside ip -8.8.8.8 using the gateway IP it shows no route found. Below is the output from the ppps.log file. I have obfuscated the IP and account details. First is the link termination event log and second part is the connection event log.

Code: [Select]

root@firewall:~ # cat /var/log/ppps.log
Aug  7 19:47:15 firewall ppp: caught fatal signal TERM
Aug  7 19:47:15 firewall ppp: [opt1] IFACE: Close event
Aug  7 19:47:15 firewall ppp: [opt1] IPCP: Close event
Aug  7 19:47:15 firewall ppp: [opt1] IPCP: state change Opened --> Closing
Aug  7 19:47:15 firewall ppp: [opt1] IPCP: SendTerminateReq #4
Aug  7 19:47:15 firewall ppp: [opt1] IPCP: LayerDown
Aug  7 19:47:21 firewall ppp: [opt1] IFACE: Down event
Aug  7 19:47:21 firewall ppp: [opt1] IFACE: Rename interface pppoe0 to pppoe0
Aug  7 19:47:21 firewall ppp: [opt1] IPV6CP: Close event
Aug  7 19:47:21 firewall ppp: [opt1] IPV6CP: state change Stopped --> Closed
Aug  7 19:47:21 firewall ppp: [opt1] IPCP: SendTerminateReq #5
Aug  7 19:47:21 firewall ppp: [opt1] IPCP: rec'd Terminate Ack #4 (Closing)
Aug  7 19:47:21 firewall ppp: [opt1] IPCP: state change Closing --> Closed
Aug  7 19:47:21 firewall ppp: [opt1] IPCP: LayerFinish
Aug  7 19:47:21 firewall ppp: [opt1] Bundle: No NCPs left. Closing links...
Aug  7 19:47:21 firewall ppp: [opt1] Bundle: closing link "opt1_link0"...
Aug  7 19:47:21 firewall ppp: [opt1_link0] LCP: rec'd Terminate Request #162 (Opened)
Aug  7 19:47:21 firewall ppp: [opt1_link0] LCP: state change Opened --> Stopping
Aug  7 19:47:21 firewall ppp: [opt1_link0] Link: Leave bundle "opt1"
Aug  7 19:47:21 firewall ppp: [opt1] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Aug  7 19:47:21 firewall ppp: [opt1] IPCP: Close event
Aug  7 19:47:21 firewall ppp: [opt1] IPV6CP: Close event
Aug  7 19:47:21 firewall ppp: [opt1] IPCP: Down event
Aug  7 19:47:21 firewall ppp: [opt1] IPCP: state change Closed --> Initial
Aug  7 19:47:21 firewall ppp: [opt1] IPV6CP: Down event
Aug  7 19:47:21 firewall ppp: [opt1] IPV6CP: state change Closed --> Initial
Aug  7 19:47:21 firewall ppp: [opt1_link0] LCP: SendTerminateAck #4
Aug  7 19:47:21 firewall ppp: [opt1_link0] LCP: LayerDown
Aug  7 19:47:21 firewall ppp: [opt1_link0] Link: CLOSE event
Aug  7 19:47:21 firewall ppp: [opt1_link0] LCP: Close event
Aug  7 19:47:21 firewall ppp: [opt1_link0] LCP: state change Stopping --> Closing
Aug  7 19:47:23 firewall ppp: [opt1_link0] LCP: state change Closing --> Closed
Aug  7 19:47:23 firewall ppp: [opt1_link0] LCP: LayerFinish
Aug  7 19:47:23 firewall ppp: [opt1] Bundle: Shutdown
Aug  7 19:47:23 firewall ppp: [opt1_link0] Link: Shutdown
Aug  7 19:47:23 firewall ppp: process 55878 terminated
Aug  7 19:47:31 firewall ppp: Multi-link PPP daemon for FreeBSD
Aug  7 19:47:31 firewall ppp:
Aug  7 19:47:31 firewall ppp: process 10919 started, version 5.8 (root@opn-build-amd64-1 01:58 20-Mar-2018)
Aug  7 19:47:31 firewall ppp: web: web is not running
Aug  7 19:47:31 firewall ppp: [opt1] Bundle: Interface ng1 created
Aug  7 19:47:31 firewall ppp: [opt1_link0] Link: OPEN event
Aug  7 19:47:31 firewall ppp: [opt1_link0] LCP: Open event
Aug  7 19:47:31 firewall ppp: [opt1_link0] LCP: state change Initial --> Starting
Aug  7 19:47:31 firewall ppp: [opt1_link0] LCP: LayerStart
Aug  7 19:47:31 firewall ppp: [opt1_link0] PPPoE: Connecting to ''
Aug  7 19:47:31 firewall ppp: PPPoE: rec'd ACNAME "**************************"
Aug  7 19:47:32 firewall ppp: [opt1_link0] PPPoE: connection successful
Aug  7 19:47:32 firewall ppp: [opt1_link0] Link: UP event
Aug  7 19:47:32 firewall ppp: [opt1_link0] LCP: Up event
Aug  7 19:47:32 firewall ppp: [opt1_link0] LCP: state change Starting --> Req-Sent
Aug  7 19:47:32 firewall ppp: [opt1_link0] LCP: SendConfigReq #1
Aug  7 19:47:32 firewall ppp: [opt1_link0]   PROTOCOMP
Aug  7 19:47:32 firewall ppp: [opt1_link0]   MRU 1492
Aug  7 19:47:32 firewall ppp: [opt1_link0]   MAGICNUM 0x255203f7
Aug  7 19:47:32 firewall ppp: [opt1_link0] LCP: rec'd Configure Request #61 (Req-Sent)
Aug  7 19:47:32 firewall ppp: [opt1_link0]   MRU 1460
Aug  7 19:47:32 firewall ppp: [opt1_link0]   AUTHPROTO CHAP MD5
Aug  7 19:47:32 firewall ppp: [opt1_link0]   MAGICNUM 0x341270db
Aug  7 19:47:32 firewall ppp: [opt1_link0] LCP: SendConfigAck #61
Aug  7 19:47:32 firewall ppp: [opt1_link0]   MRU 1460
Aug  7 19:47:32 firewall ppp: [opt1_link0]   AUTHPROTO CHAP MD5
Aug  7 19:47:32 firewall ppp: [opt1_link0]   MAGICNUM 0x341270db
Aug  7 19:47:32 firewall ppp: [opt1_link0] LCP: state change Req-Sent --> Ack-Sent
Aug  7 19:47:32 firewall ppp: [opt1_link0] LCP: rec'd Configure Reject #1 (Ack-Sent)
Aug  7 19:47:32 firewall ppp: [opt1_link0]   PROTOCOMP
Aug  7 19:47:32 firewall ppp: [opt1_link0] LCP: SendConfigReq #2
Aug  7 19:47:32 firewall ppp: [opt1_link0]   MRU 1492
Aug  7 19:47:32 firewall ppp: [opt1_link0]   MAGICNUM 0x255203f7
Aug  7 19:47:32 firewall ppp: [opt1_link0] LCP: rec'd Configure Nak #2 (Ack-Sent)
Aug  7 19:47:32 firewall ppp: [opt1_link0]   MRU 1460
Aug  7 19:47:32 firewall ppp: [opt1_link0] LCP: SendConfigReq #3
Aug  7 19:47:32 firewall ppp: [opt1_link0]   MRU 1460
Aug  7 19:47:32 firewall ppp: [opt1_link0]   MAGICNUM 0x255203f7
Aug  7 19:47:32 firewall ppp: [opt1_link0] LCP: rec'd Configure Ack #3 (Ack-Sent)
Aug  7 19:47:32 firewall ppp: [opt1_link0]   MRU 1460
Aug  7 19:47:32 firewall ppp: [opt1_link0]   MAGICNUM 0x255203f7
Aug  7 19:47:32 firewall ppp: [opt1_link0] LCP: state change Ack-Sent --> Opened
Aug  7 19:47:32 firewall ppp: [opt1_link0] LCP: auth: peer wants CHAP, I want nothing
Aug  7 19:47:32 firewall ppp: [opt1_link0] LCP: LayerUp
Aug  7 19:47:32 firewall ppp: [opt1_link0] CHAP: rec'd CHALLENGE #1 len: 39
Aug  7 19:47:32 firewall ppp: [opt1_link0]   Name: "*************"
Aug  7 19:47:32 firewall ppp: [opt1_link0] CHAP: Using authname "**************"
Aug  7 19:47:32 firewall ppp: [opt1_link0] CHAP: sending RESPONSE #1 len: 40
Aug  7 19:47:32 firewall ppp: [opt1_link0] CHAP: rec'd SUCCESS #1 len: 26
Aug  7 19:47:32 firewall ppp: [opt1_link0]   MESG: Authentication Success
Aug  7 19:47:32 firewall ppp: [opt1_link0] LCP: authorization successful
Aug  7 19:47:32 firewall ppp: [opt1_link0] Link: Matched action 'bundle "opt1" ""'
Aug  7 19:47:32 firewall ppp: [opt1_link0] Link: Join bundle "opt1"
Aug  7 19:47:32 firewall ppp: [opt1] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Aug  7 19:47:32 firewall ppp: [opt1] IPCP: Open event
Aug  7 19:47:32 firewall ppp: [opt1] IPCP: state change Initial --> Starting
Aug  7 19:47:32 firewall ppp: [opt1] IPCP: LayerStart
Aug  7 19:47:32 firewall ppp: [opt1] IPV6CP: Open event
Aug  7 19:47:32 firewall ppp: [opt1] IPV6CP: state change Initial --> Starting
Aug  7 19:47:32 firewall ppp: [opt1] IPV6CP: LayerStart
Aug  7 19:47:32 firewall ppp: [opt1] IPCP: Up event
Aug  7 19:47:32 firewall ppp: [opt1] IPCP: state change Starting --> Req-Sent
Aug  7 19:47:32 firewall ppp: [opt1] IPCP: SendConfigReq #1
Aug  7 19:47:32 firewall ppp: [opt1]   IPADDR 0.0.0.0
Aug  7 19:47:32 firewall ppp: [opt1]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug  7 19:47:32 firewall ppp: [opt1] IPV6CP: Up event
Aug  7 19:47:32 firewall ppp: [opt1] IPV6CP: state change Starting --> Req-Sent
Aug  7 19:47:32 firewall ppp: [opt1] IPV6CP: SendConfigReq #1
Aug  7 19:47:32 firewall ppp: [opt1] IPCP: rec'd Configure Request #18 (Req-Sent)
Aug  7 19:47:32 firewall ppp: [opt1]   IPADDR 117.xxx.yyy.1
Aug  7 19:47:32 firewall ppp: [opt1]     117.xxx.yyy.1 is OK
Aug  7 19:47:32 firewall ppp: [opt1] IPCP: SendConfigAck #18
Aug  7 19:47:32 firewall ppp: [opt1]   IPADDR 117.xxx.yyy.1
Aug  7 19:47:32 firewall ppp: [opt1] IPCP: state change Req-Sent --> Ack-Sent
Aug  7 19:47:33 firewall ppp: [opt1] IPCP: rec'd Configure Reject #1 (Ack-Sent)
Aug  7 19:47:33 firewall ppp: [opt1]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug  7 19:47:33 firewall ppp: [opt1] IPCP: SendConfigReq #2
Aug  7 19:47:33 firewall ppp: [opt1]   IPADDR 0.0.0.0
Aug  7 19:47:33 firewall ppp: [opt1_link0] LCP: rec'd Protocol Reject #62 (Opened)
Aug  7 19:47:33 firewall ppp: [opt1_link0] LCP: protocol IPV6CP was rejected
Aug  7 19:47:33 firewall ppp: [opt1] IPV6CP: protocol was rejected by peer
Aug  7 19:47:33 firewall ppp: [opt1] IPV6CP: state change Req-Sent --> Stopped
Aug  7 19:47:33 firewall ppp: [opt1] IPV6CP: LayerFinish
Aug  7 19:47:33 firewall ppp: [opt1] IPCP: rec'd Configure Nak #2 (Ack-Sent)
Aug  7 19:47:33 firewall ppp: [opt1]   IPADDR 117.xxx.zzz.14
Aug  7 19:47:33 firewall ppp: [opt1]     117.221.187.14 is OK
Aug  7 19:47:33 firewall ppp: [opt1] IPCP: SendConfigReq #3
Aug  7 19:47:33 firewall ppp: [opt1]   IPADDR 117.xxx.zzz.14
Aug  7 19:47:33 firewall ppp: [opt1] IPCP: rec'd Configure Ack #3 (Ack-Sent)
Aug  7 19:47:33 firewall ppp: [opt1]   IPADDR 117.xxx.zzz.14
Aug  7 19:47:33 firewall ppp: [opt1] IPCP: state change Ack-Sent --> Opened
Aug  7 19:47:33 firewall ppp: [opt1] IPCP: LayerUp
Aug  7 19:47:33 firewall ppp: [opt1]   117.xxx.zzz.14 -> 117.xxx.yyy.1
Aug  7 19:47:33 firewall ppp: [opt1] IFACE: Add route 0.0.0.0/0 117.xxx.yyy.1 failed: File exists
Aug  7 19:48:08 firewall ppp: [opt1] IFACE: Up event
Aug  7 19:48:08 firewall ppp: [opt1] IFACE: Rename interface ng1 to pppoe0

Thanks in advance.

Regards,
Bobby Thomas

[marjohn56]

So if you manually take the interface down and bring it back up then it works?


Could you post that log too please.

[bobbythomas]

No, even if I bring up the interface the gateway status is shown as down. The first section of the logs were created when I manually brought down the interface. I tried enabling IPv6 on the pppoe interface and then I could see a new gateway in the gateway list (see attachment). But the IPv4 is still down.

What could be the reason?

I will attach the pppoe config soon.

Thanks in advance.
Regards,
Bobby Thomas

[Davesworld]

NOT OT but still related to the OP's PPPoE problem:

Mine starting behaving oddly as well after the ISP forced me from DHCP to PPPoE on one of my two ADSL wan links( the one with that carrier). Last night when watching a movie online the machine rebooted itself, I had to release and restart that connection on one instance prior to this. My Roku had enough cache to keep playing during the reboot. Glad I upgraded to the most memory containing model. I only went PPPoE on that wan last Sunday so it's likely not 18.7 specific.

I use the TMPFS option for /var/log so I now belatedly set my OPNsense install to send logs to my file server. I have no logs prior to it rebooting itself. I will say that PPPoE is very talkative compared to other methods. Why PPPoE is even used is another subject, it's needless overhead with a weird MTU size. If it happens again I should have logs on my file server.

Oh did I mention how much I loathe PPP anything? Not only that but I loathe PPP anything, hehe.

OT:
There is a way to get the solid drive pampering effect of having dynamic content such as logs in TMPFS but not lose the logs after a reboot and that is to have the system back up the logs once per hour to a compressed tarball on the actual hard drive(s) and decompress that file on bootup after TMPFS is mounted. It would compress on a normal shutdown as well. If it was a cold reboot such as when something faults out, you would always have less than an hour's worth of logs missing.

[bobbythomas]

Ok, I tried troubleshooting this but couldn't find anything else, I only see the messages shown above, I see that a route is created for the that gateway, but for some reason it doesn't pass any traffic. I had to disable pppoe bridging on the ADSL modem and had to reconfigure it as a pppoe client. I am good for the time being, only concern is that I have to do a 1 to 1 NAT to the opnsense firewall. I will update this if I find something related to this.

Thank you John and Dave for your support.

Regards,
Bobby Thomas

[Davesworld]

I don't think I added much value to the thread but I am trying to figure out what you did.

Does your Modem have a PPPoE passthrough mode that you are now using rather than a standard bridge or are you handling PPPoE in the modem and letting it supply a local ip to your router's wan creating a double NAT situation? My modem offers PPPoE passthrough as an option. I think the only difference is that with PPPoE passthrough, you are not limited to one PPPoE session as you are with bridged mode which is limited to the one bridged device being an OPNsense router in this case.

[marjohn56]

I wonder if we are being mis-directed. Was the IPv6 link created using the 'Use IPv4' Connectivity' option?

[bobbythomas]

I don't think I added much value to the thread but I am trying to figure out what you did.

Does your Modem have a PPPoE passthrough mode that you are now using rather than a standard bridge or are you handling PPPoE in the modem and letting it supply a local ip to your router's wan creating a double NAT situation? My modem offers PPPoE passthrough as an option. I think the only difference is that with PPPoE passthrough, you are not limited to one PPPoE session as you are with bridged mode which is limited to the one bridged device being an OPNsense router in this case.

I had PPPoE passthrough enabled on the modem and OPNsense was performing PPPoE handshaking, it completes handshaking and receive an ip address and inject the routes on to opnsense but the traffic doesn't go through that link, I can see packets being sent if I do a tcpdump but nothing is received. I now configured PPPoE on the modem and it now receives and IP from ISP. I had to NAT that to opnsense.

I wonder if we are being mis-directed. Was the IPv6 link created using the 'Use IPv4' Connectivity' option?

When the link was not working I tried various ipv6 option and I could see ipv6 showing up, but the outcome is the same, no traffic passes through the link. Even without ipv6 the result is same, gateway is shown down even tuough there is an ip and routes created for the pppoe session.

[marjohn56]

What sort of modem is it, is it just a standard generic unit or is it a custom one supplied by the ISP?


There are known cases where the PPPoE registration requires as specific feature or setting.