pppoe crashes under heavy cpu load
-
I have a situation where ppp client would crash and restart immediately.
It only happens on heavy load
On 2.4.5 it couldn't afford pfblockerng-devel, and it would crash every 15 minutes, at exact times.
On .2.4.5p1 it seems to crash when ntopng and pfblockerng-devel is enabled even though not that often. cpu load reaches 3+ when it happens.
ntopng was at 50% cpu
This is a Intel(R) Celeron(R) CPU N3050 @ 1.60GHz
Current: 1600 MHz, Max: 1601 MHz
2 CPUs: 1 package(s) x 2 core(s)
AES-NI CPU Crypto: Yes (active)ppp logs are always the same. It completes a normal pppoe negotiation and reconnects succesfuly.
I haven't tried it on 2.4.4p3 (yet)Read the log from the bottom.
.....
Jun 10 19:00:28 ppp [wan_link0] PROTOCOMP
Jun 10 19:00:28 ppp [wan_link0] LCP: SendConfigReq #1
Jun 10 19:00:28 ppp [wan_link0] LCP: state change Starting --> Req-Sent
Jun 10 19:00:28 ppp [wan_link0] LCP: Up event
Jun 10 19:00:28 ppp [wan_link0] Link: UP event
Jun 10 19:00:28 ppp [wan_link0] PPPoE: connection successful
Jun 10 19:00:28 ppp [wan_link0] rec'd proto LCP while dead
Jun 10 19:00:28 ppp PPPoE: rec'd ACNAME "akr-ar90"
Jun 10 19:00:28 ppp [wan_link0] PPPoE: Connecting to ''
Jun 10 19:00:28 ppp [wan_link0] LCP: LayerStart
Jun 10 19:00:28 ppp [wan_link0] LCP: state change Initial --> Starting
Jun 10 19:00:28 ppp [wan_link0] LCP: Open event
Jun 10 19:00:28 ppp [wan_link0] Link: OPEN event
Jun 10 19:00:28 ppp [wan] Bundle: Interface ng0 created
Jun 10 19:00:28 ppp web: web is not running
Jun 10 19:00:27 ppp process 22196 terminated
Jun 10 19:00:27 ppp [wan_link0] Link: Shutdown
Jun 10 19:00:27 ppp [wan] Bundle: Shutdown
Jun 10 19:00:27 ppp waiting for process 22196 to die...
Jun 10 19:00:26 ppp waiting for process 22196 to die...
Jun 10 19:00:25 ppp [wan_link0] LCP: state change Closed --> Initial
Jun 10 19:00:25 ppp [wan_link0] LCP: Down event
Jun 10 19:00:25 ppp [wan_link0] Link: DOWN event
Jun 10 19:00:25 ppp [wan_link0] LCP: LayerFinish
Jun 10 19:00:25 ppp [wan_link0] LCP: state change Closing --> Closed
Jun 10 19:00:25 ppp [wan_link0] LCP: rec'd Terminate Ack #3 (Closing)
Jun 10 19:00:25 ppp [wan_link0] LCP: LayerDown
Jun 10 19:00:25 ppp [wan_link0] LCP: SendTerminateReq #3
Jun 10 19:00:25 ppp [wan] IPV6CP: state change Closed --> Initial
Jun 10 19:00:25 ppp [wan] IPV6CP: Down event
Jun 10 19:00:25 ppp [wan] IPCP: state change Closed --> Initial
Jun 10 19:00:25 ppp [wan] IPCP: Down event
Jun 10 19:00:25 ppp [wan] IPV6CP: Close event
Jun 10 19:00:25 ppp [wan] IPCP: Close event
Jun 10 19:00:25 ppp [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Jun 10 19:00:25 ppp [wan_link0] Link: Leave bundle "wan"
Jun 10 19:00:25 ppp [wan_link0] LCP: state change Opened --> Closing
Jun 10 19:00:25 ppp [wan_link0] LCP: Close event
Jun 10 19:00:25 ppp [wan_link0] Link: CLOSE event
Jun 10 19:00:25 ppp [wan] Bundle: closing link "wan_link0"...
Jun 10 19:00:25 ppp [wan] Bundle: No NCPs left. Closing links...
Jun 10 19:00:25 ppp [wan] IPCP: LayerFinish
Jun 10 19:00:25 ppp [wan] IPCP: state change Closing --> Closed
Jun 10 19:00:25 ppp [wan] IPCP: rec'd Terminate Ack #5 (Closing)
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan] IPV6CP: LayerFinish
Jun 10 19:00:25 ppp [wan] IPV6CP: state change Closing --> Closed
Jun 10 19:00:25 ppp [wan] IPV6CP: rec'd Terminate Ack #2 (Closing)
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan_link0] rec'd unexpected protocol IP
Jun 10 19:00:25 ppp [wan] IPCP: SendTerminateReq #5
Jun 10 19:00:25 ppp [wan] IFACE: Rename interface pppoe0 to pppoe0
Jun 10 19:00:25 ppp [wan] IFACE: Down event
Jun 10 19:00:25 ppp waiting for process 22196 to die...
Jun 10 19:00:24 ppp waiting for process 22196 to die...
Jun 10 19:00:24 ppp [wan] IPV6CP: LayerDown
Jun 10 19:00:24 ppp [wan] IPV6CP: SendTerminateReq #2
Jun 10 19:00:24 ppp [wan] IPV6CP: state change Opened --> Closing
Jun 10 19:00:24 ppp [wan] IPV6CP: Close event
Jun 10 19:00:24 ppp [wan] IFACE: Removing IPv4 address from pppoe0 failed(IGNORING for now. This should be only for PPPoE friendly!): Can't assign requested address
Jun 10 19:00:23 ppp waiting for process 22196 to die...
Jun 10 19:00:22 ppp waiting for process 22196 to die...
Jun 10 19:00:21 ppp waiting for process 22196 to die...
Jun 10 19:00:21 ppp [wan] IPCP: LayerDown
Jun 10 19:00:21 ppp [wan] IPCP: SendTerminateReq #4
Jun 10 19:00:21 ppp [wan] IPCP: state change Opened --> Closing
Jun 10 19:00:21 ppp [wan] IPCP: Close event
Jun 10 19:00:21 ppp [wan] IFACE: Close event
Jun 10 19:00:21 ppp caught fatal signal TERM
Jun 10 19:00:21 ppp process 61635 started, version 5.8 (root@pfSense_v2_4_5_amd64-pfSense_v2_4_5-job-04 20:28 17-Dec-2019)
Jun 10 19:00:21 ppp Multi-link PPP daemon for FreeBSD
Jun 10 08:39:48 ppp [wan] 178.59.xxx.xxx -> 62.38.0.170
Jun 10 08:39:48 ppp [wan] IPCP: LayerUp -
Can you define heavy load? What NIC are you using?
I don't use a lot PPPoE but we have one site with 500/500 Mbps fiber and PPPoE and I can't remember any issue.-Rico
-
@Rico About 3 Mbits on a 50/5 connection, with a single steam player.
On a intel nuc with a realtek ethernet.
Cpu went heavy with the combination of ntopng and pfblockerng.
Traffic is obviously not heavy
The thing is that this seems to affect ppoe
Web interface was reacting at all times. -
10 bucks the real cause is your NIC and not the system load. ;-)
Realtek is just bad and combined with PPPoE it's even more worse.
Are you running the driver shipped with FreeBSD/pfSense? You could try with this one then https://forum.netgate.com/topic/135850/official-realtek-driver-binary-1-95-for-2-4-4-release
Or try with Intel NIC if possible.-Rico
