Show Posts
1
General Discussion / PPPoE Service Failure
« on: April 21, 2022, 10:17:38 am »
Hello everyone,
As this thread shares similarities with https://forum.opnsense.org/index.php?topic=26640.msg128800#msg128800 or https://forum.opnsense.org/index.php?topic=24844.msg119128#msg119128 we provide a much deeper description an are working on an internal and permanent solution. If anyone has any feedback, we'd appreciate it.
For one of our customers, we have around a hundred OPNsense firewalls (on Simple Machines) setup in their subsidiaries. In two specific cases, we are facing a service shutdown issue after either :
- Configuration changes, for instance on QoS settings and rebooting
- Upgrading the system (versions range from 18.7.2 to 21.1.9) and rebooting
Then, while trying to reestablish a connection over PPPoE, a timeout happens and results in service failure, which makes remote operations unavailable. Thus, we have to physically get to the firewalls to apply the following workaround :
From the web admin, in the WAN Interface configuration :
Disable Interface -> Apply, Reenable Interface -> Apply
(This fixes the problem)
As we are in a process of configuring all of these firewalls, it becomes complex for us to physically apply that solution and we have noticed this happens on about 8% of the targeted machines.
So we actually have 2 questions:
1) Is there a permanent fix or solution to this issue ?
2) Is there a way to perform this workaround by other means than connecting to the web administration (e.g. command line), that would allow us to monitor and perform the operation without having to be physically on each site?
Below are the logs (ppps.log) for two cases identified, that we could track down. Both of the computers below are running on OPNsense 19.1.10. Yet, we’ve had the problem happened in the past with higher versions (e.g. 20.1.9).
Case 1, service dies after timeout:
Apr 11 21:03:39 firewall-u9488 ppp: [wan_link0] LCP: LayerStart
Apr 11 21:03:39 firewall-u9488 ppp: [wan_link0] PPPoE: Connecting to ''
Apr 11 21:03:48 firewall-u9488 ppp: [wan_link0] PPPoE connection timeout after 9 seconds
Apr 11 21:03:48 firewall-u9488 ppp: [wan_link0] Link: DOWN event
Apr 11 21:03:48 firewall-u9488 ppp: [wan_link0] LCP: Down event
Apr 11 21:03:48 firewall-u9488 ppp: [wan_link0] Link: reconnection attempt 1 in 4 seconds
Apr 11 21:03:52 firewall-u9488 ppp: [wan_link0] Link: reconnection attempt 1
Apr 11 21:03:52 firewall-u9488 ppp: [wan_link0] PPPoE: Connecting to ''
Apr 11 21:04:01 firewall-u9488 ppp: [wan_link0] PPPoE connection timeout after 9 seconds
Apr 11 21:04:01 firewall-u9488 ppp: [wan_link0] Link: DOWN event
Apr 11 21:04:01 firewall-u9488 ppp: [wan_link0] LCP: Down event
Apr 11 21:04:01 firewall-u9488 ppp: [wan_link0] Link: reconnection attempt 2 in 2 seconds
Apr 11 21:04:03 firewall-u9488 ppp: [wan_link0] Link: reconnection attempt 2
Apr 11 21:04:03 firewall-u9488 ppp: [wan_link0] PPPoE: Connecting to ''
Apr 11 21:04:03 firewall-u9488 ppp: Multi-link PPP daemon for FreeBSD
Apr 11 21:04:03 firewall-u9488 ppp:
Apr 11 21:04:03 firewall-u9488 ppp: process 26251 started, version 5.8 (root@opn-build-amd64-2 01:32 11-Mar-2019)
Apr 11 21:04:03 firewall-u9488 ppp: caught fatal signal TERM
Apr 11 21:04:03 firewall-u9488 ppp: [wan] IFACE: Close event
Apr 11 21:04:03 firewall-u9488 ppp: [wan] IPCP: Close event
Apr 11 21:04:03 firewall-u9488 ppp: [wan] IPV6CP: Close event
Apr 11 21:04:03 firewall-u9488 ppp: waiting for process 53035 to die...
Apr 11 21:04:04 firewall-u9488 ppp: waiting for process 53035 to die...
Apr 11 21:04:05 firewall-u9488 ppp: [wan] Bundle: Shutdown
…
Case 2, service times out, established but still shuts down:
Apr 11 21:03:58 firewall-u9426 ppp: [wan_link0] PPPoE: Connecting to ''
Apr 11 21:04:07 firewall-u9426 ppp: [wan_link0] PPPoE connection timeout after 9 seconds
Apr 11 21:04:07 firewall-u9426 ppp: [wan_link0] Link: DOWN event
Apr 11 21:04:07 firewall-u9426 ppp: [wan_link0] LCP: Down event
Apr 11 21:04:07 firewall-u9426 ppp: [wan_link0] Link: reconnection attempt 2 in 1 seconds
Apr 11 21:04:08 firewall-u9426 ppp: [wan_link0] Link: reconnection attempt 2
Apr 11 21:04:08 firewall-u9426 ppp: [wan_link0] PPPoE: Connecting to ''
Apr 11 21:04:11 firewall-u9426 ppp: Multi-link PPP daemon for FreeBSD
Apr 11 21:04:11 firewall-u9426 ppp:
Apr 11 21:04:11 firewall-u9426 ppp: process 12987 started, version 5.8 (root@opn-build-amd64-2 01:32 11-Mar-2019)
Apr 11 21:04:11 firewall-u9426 ppp: caught fatal signal TERM
Apr 11 21:04:11 firewall-u9426 ppp: [wan] IFACE: Close event
Apr 11 21:04:11 firewall-u9426 ppp: [wan] IPCP: Close event
Apr 11 21:04:11 firewall-u9426 ppp: [wan] IPV6CP: Close event
Apr 11 21:04:11 firewall-u9426 ppp: waiting for process 16119 to die...
Apr 11 21:04:12 firewall-u9426 ppp: waiting for process 16119 to die...
Apr 11 21:04:13 firewall-u9426 ppp: [wan] Bundle: Shutdown
Apr 11 21:04:13 firewall-u9426 ppp: [wan_link0] Link: Shutdown
Apr 11 21:04:13 firewall-u9426 ppp: process 16119 terminated
Apr 11 21:04:13 firewall-u9426 ppp: web: web is not running
Apr 11 21:04:13 firewall-u9426 ppp: [wan] Bundle: Interface ng0 created
Apr 11 21:04:13 firewall-u9426 ppp: [wan_link0] Link: OPEN event
Apr 11 21:04:13 firewall-u9426 ppp: [wan_link0] LCP: Open event
Apr 11 21:04:13 firewall-u9426 ppp: [wan_link0] LCP: state change Initial --> Starting
Apr 11 21:04:13 firewall-u9426 ppp: [wan_link0] LCP: LayerStart
Apr 11 21:04:13 firewall-u9426 ppp: [wan_link0] PPPoE: Connecting to ''
Apr 11 21:04:15 firewall-u9426 ppp: PPPoE: rec'd ACNAME "ipi-lsp690-r-bn-03"
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] PPPoE: connection successful
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] Link: UP event
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] LCP: Up event
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] LCP: state change Starting --> Req-Sent
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] LCP: SendConfigReq #1
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] PROTOCOMP
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] MRU 1492
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] MAGICNUM 0x9031514a
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] LCP: rec'd Configure Reject #1 (Req-Sent)
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] PROTOCOMP
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] LCP: SendConfigReq #2
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] MRU 1492
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] MAGICNUM 0x9031514a
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] LCP: rec'd Configure Ack #2 (Req-Sent)
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] MRU 1492
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] MAGICNUM 0x9031514a
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Rcvd
Apr 11 21:04:16 firewall-u9426 ppp: caught fatal signal TERM
Apr 11 21:04:16 firewall-u9426 ppp: [wan] IFACE: Close event
Apr 11 21:04:16 firewall-u9426 ppp: [wan] IPCP: Close event
Apr 11 21:04:16 firewall-u9426 ppp: [wan] IPV6CP: Close event
Apr 11 21:04:17 firewall-u9426 ppp: [wan_link0] LCP: state change Ack-Rcvd --> Req-Sent
Apr 11 21:04:17 firewall-u9426 ppp: [wan_link0] LCP: SendConfigReq #3
Apr 11 21:04:17 firewall-u9426 ppp: [wan_link0] MRU 1492
Apr 11 21:04:17 firewall-u9426 ppp: [wan_link0] MAGICNUM 0x9031514a
Apr 11 21:04:17 firewall-u9426 ppp: [wan_link0] LCP: rec'd Configure Ack #3 (Req-Sent)
Apr 11 21:04:17 firewall-u9426 ppp: [wan_link0] MRU 1492
Apr 11 21:04:17 firewall-u9426 ppp: [wan_link0] MAGICNUM 0x9031514a
Apr 11 21:04:17 firewall-u9426 ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Rcvd
Apr 11 21:04:18 firewall-u9426 ppp: [wan] Bundle: Shutdown
Apr 11 21:04:18 firewall-u9426 ppp: [wan_link0] Link: Shutdown
Apr 11 21:04:18 firewall-u9426 ppp: process 12987 terminated
Thank you very much in advance.
As this thread shares similarities with https://forum.opnsense.org/index.php?topic=26640.msg128800#msg128800 or https://forum.opnsense.org/index.php?topic=24844.msg119128#msg119128 we provide a much deeper description an are working on an internal and permanent solution. If anyone has any feedback, we'd appreciate it.
For one of our customers, we have around a hundred OPNsense firewalls (on Simple Machines) setup in their subsidiaries. In two specific cases, we are facing a service shutdown issue after either :
- Configuration changes, for instance on QoS settings and rebooting
- Upgrading the system (versions range from 18.7.2 to 21.1.9) and rebooting
Then, while trying to reestablish a connection over PPPoE, a timeout happens and results in service failure, which makes remote operations unavailable. Thus, we have to physically get to the firewalls to apply the following workaround :
From the web admin, in the WAN Interface configuration :
Disable Interface -> Apply, Reenable Interface -> Apply
(This fixes the problem)
As we are in a process of configuring all of these firewalls, it becomes complex for us to physically apply that solution and we have noticed this happens on about 8% of the targeted machines.
So we actually have 2 questions:
1) Is there a permanent fix or solution to this issue ?
2) Is there a way to perform this workaround by other means than connecting to the web administration (e.g. command line), that would allow us to monitor and perform the operation without having to be physically on each site?
Below are the logs (ppps.log) for two cases identified, that we could track down. Both of the computers below are running on OPNsense 19.1.10. Yet, we’ve had the problem happened in the past with higher versions (e.g. 20.1.9).
Case 1, service dies after timeout:
Apr 11 21:03:39 firewall-u9488 ppp: [wan_link0] LCP: LayerStart
Apr 11 21:03:39 firewall-u9488 ppp: [wan_link0] PPPoE: Connecting to ''
Apr 11 21:03:48 firewall-u9488 ppp: [wan_link0] PPPoE connection timeout after 9 seconds
Apr 11 21:03:48 firewall-u9488 ppp: [wan_link0] Link: DOWN event
Apr 11 21:03:48 firewall-u9488 ppp: [wan_link0] LCP: Down event
Apr 11 21:03:48 firewall-u9488 ppp: [wan_link0] Link: reconnection attempt 1 in 4 seconds
Apr 11 21:03:52 firewall-u9488 ppp: [wan_link0] Link: reconnection attempt 1
Apr 11 21:03:52 firewall-u9488 ppp: [wan_link0] PPPoE: Connecting to ''
Apr 11 21:04:01 firewall-u9488 ppp: [wan_link0] PPPoE connection timeout after 9 seconds
Apr 11 21:04:01 firewall-u9488 ppp: [wan_link0] Link: DOWN event
Apr 11 21:04:01 firewall-u9488 ppp: [wan_link0] LCP: Down event
Apr 11 21:04:01 firewall-u9488 ppp: [wan_link0] Link: reconnection attempt 2 in 2 seconds
Apr 11 21:04:03 firewall-u9488 ppp: [wan_link0] Link: reconnection attempt 2
Apr 11 21:04:03 firewall-u9488 ppp: [wan_link0] PPPoE: Connecting to ''
Apr 11 21:04:03 firewall-u9488 ppp: Multi-link PPP daemon for FreeBSD
Apr 11 21:04:03 firewall-u9488 ppp:
Apr 11 21:04:03 firewall-u9488 ppp: process 26251 started, version 5.8 (root@opn-build-amd64-2 01:32 11-Mar-2019)
Apr 11 21:04:03 firewall-u9488 ppp: caught fatal signal TERM
Apr 11 21:04:03 firewall-u9488 ppp: [wan] IFACE: Close event
Apr 11 21:04:03 firewall-u9488 ppp: [wan] IPCP: Close event
Apr 11 21:04:03 firewall-u9488 ppp: [wan] IPV6CP: Close event
Apr 11 21:04:03 firewall-u9488 ppp: waiting for process 53035 to die...
Apr 11 21:04:04 firewall-u9488 ppp: waiting for process 53035 to die...
Apr 11 21:04:05 firewall-u9488 ppp: [wan] Bundle: Shutdown
…
Case 2, service times out, established but still shuts down:
Apr 11 21:03:58 firewall-u9426 ppp: [wan_link0] PPPoE: Connecting to ''
Apr 11 21:04:07 firewall-u9426 ppp: [wan_link0] PPPoE connection timeout after 9 seconds
Apr 11 21:04:07 firewall-u9426 ppp: [wan_link0] Link: DOWN event
Apr 11 21:04:07 firewall-u9426 ppp: [wan_link0] LCP: Down event
Apr 11 21:04:07 firewall-u9426 ppp: [wan_link0] Link: reconnection attempt 2 in 1 seconds
Apr 11 21:04:08 firewall-u9426 ppp: [wan_link0] Link: reconnection attempt 2
Apr 11 21:04:08 firewall-u9426 ppp: [wan_link0] PPPoE: Connecting to ''
Apr 11 21:04:11 firewall-u9426 ppp: Multi-link PPP daemon for FreeBSD
Apr 11 21:04:11 firewall-u9426 ppp:
Apr 11 21:04:11 firewall-u9426 ppp: process 12987 started, version 5.8 (root@opn-build-amd64-2 01:32 11-Mar-2019)
Apr 11 21:04:11 firewall-u9426 ppp: caught fatal signal TERM
Apr 11 21:04:11 firewall-u9426 ppp: [wan] IFACE: Close event
Apr 11 21:04:11 firewall-u9426 ppp: [wan] IPCP: Close event
Apr 11 21:04:11 firewall-u9426 ppp: [wan] IPV6CP: Close event
Apr 11 21:04:11 firewall-u9426 ppp: waiting for process 16119 to die...
Apr 11 21:04:12 firewall-u9426 ppp: waiting for process 16119 to die...
Apr 11 21:04:13 firewall-u9426 ppp: [wan] Bundle: Shutdown
Apr 11 21:04:13 firewall-u9426 ppp: [wan_link0] Link: Shutdown
Apr 11 21:04:13 firewall-u9426 ppp: process 16119 terminated
Apr 11 21:04:13 firewall-u9426 ppp: web: web is not running
Apr 11 21:04:13 firewall-u9426 ppp: [wan] Bundle: Interface ng0 created
Apr 11 21:04:13 firewall-u9426 ppp: [wan_link0] Link: OPEN event
Apr 11 21:04:13 firewall-u9426 ppp: [wan_link0] LCP: Open event
Apr 11 21:04:13 firewall-u9426 ppp: [wan_link0] LCP: state change Initial --> Starting
Apr 11 21:04:13 firewall-u9426 ppp: [wan_link0] LCP: LayerStart
Apr 11 21:04:13 firewall-u9426 ppp: [wan_link0] PPPoE: Connecting to ''
Apr 11 21:04:15 firewall-u9426 ppp: PPPoE: rec'd ACNAME "ipi-lsp690-r-bn-03"
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] PPPoE: connection successful
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] Link: UP event
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] LCP: Up event
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] LCP: state change Starting --> Req-Sent
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] LCP: SendConfigReq #1
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] PROTOCOMP
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] MRU 1492
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] MAGICNUM 0x9031514a
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] LCP: rec'd Configure Reject #1 (Req-Sent)
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] PROTOCOMP
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] LCP: SendConfigReq #2
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] MRU 1492
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] MAGICNUM 0x9031514a
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] LCP: rec'd Configure Ack #2 (Req-Sent)
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] MRU 1492
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] MAGICNUM 0x9031514a
Apr 11 21:04:15 firewall-u9426 ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Rcvd
Apr 11 21:04:16 firewall-u9426 ppp: caught fatal signal TERM
Apr 11 21:04:16 firewall-u9426 ppp: [wan] IFACE: Close event
Apr 11 21:04:16 firewall-u9426 ppp: [wan] IPCP: Close event
Apr 11 21:04:16 firewall-u9426 ppp: [wan] IPV6CP: Close event
Apr 11 21:04:17 firewall-u9426 ppp: [wan_link0] LCP: state change Ack-Rcvd --> Req-Sent
Apr 11 21:04:17 firewall-u9426 ppp: [wan_link0] LCP: SendConfigReq #3
Apr 11 21:04:17 firewall-u9426 ppp: [wan_link0] MRU 1492
Apr 11 21:04:17 firewall-u9426 ppp: [wan_link0] MAGICNUM 0x9031514a
Apr 11 21:04:17 firewall-u9426 ppp: [wan_link0] LCP: rec'd Configure Ack #3 (Req-Sent)
Apr 11 21:04:17 firewall-u9426 ppp: [wan_link0] MRU 1492
Apr 11 21:04:17 firewall-u9426 ppp: [wan_link0] MAGICNUM 0x9031514a
Apr 11 21:04:17 firewall-u9426 ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Rcvd
Apr 11 21:04:18 firewall-u9426 ppp: [wan] Bundle: Shutdown
Apr 11 21:04:18 firewall-u9426 ppp: [wan_link0] Link: Shutdown
Apr 11 21:04:18 firewall-u9426 ppp: process 12987 terminated
Thank you very much in advance.