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


  • LAYER 8 Rebel Alliance

    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.


  • LAYER 8 Rebel Alliance

    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


Log in to reply