PPPoE LCP not working under 2.3
-
Hi all,
I'm having hell trying to troubleshoot this intermittent ADSL connection on a remote customer site. It goes down often (like every hour or two on average) due to the underlying line noise issue on this specific line, but then it steadfastly refuses to reconnect via PPPoE despite the attached modem being in sync with the line.
i.e. the setup is PFSENSE -> Draytek Vigor 130 Modem -> ADSL line -> ISP
and the ISP say they can see the modem is in sync, but that their RADIUS servers aren't seeing any PPPoE requests.
I even have the periodic reset set on the WAN line for every hour, but even that doesn't usually make it work.
Here's my PPP logs from yesterday. As you can see, there's a hell of a lot of PPP retries before it eventually bursts into life. This isn't the case with any consumer router which would just connect back up within a second or two.
May 23 20:45:24 ppp [wan_link0] Link: reconnection attempt 237 in 3 seconds
May 23 20:45:27 ppp [wan_link0] Link: reconnection attempt 237
May 23 20:45:27 ppp [wan_link0] PPPoE: Connecting to ''
May 23 20:45:36 ppp [wan_link0] PPPoE connection timeout after 9 seconds
May 23 20:45:36 ppp [wan_link0] Link: DOWN event
May 23 20:45:36 ppp [wan_link0] LCP: Down event
May 23 20:45:36 ppp [wan_link0] Link: reconnection attempt 238 in 2 seconds
May 23 20:45:38 ppp [wan_link0] Link: reconnection attempt 238
May 23 20:45:38 ppp [wan_link0] PPPoE: Connecting to ''
May 23 20:45:47 ppp [wan_link0] PPPoE connection timeout after 9 seconds
May 23 20:45:47 ppp [wan_link0] Link: DOWN event
May 23 20:45:47 ppp [wan_link0] LCP: Down event
May 23 20:45:47 ppp [wan_link0] Link: reconnection attempt 239 in 4 seconds
May 23 20:45:51 ppp [wan_link0] Link: reconnection attempt 239
May 23 20:45:51 ppp [wan_link0] PPPoE: Connecting to ''
May 23 20:46:00 ppp [wan_link0] PPPoE connection timeout after 9 seconds
May 23 20:46:00 ppp [wan_link0] Link: DOWN event
May 23 20:46:00 ppp [wan_link0] LCP: Down event
May 23 20:46:00 ppp [wan_link0] Link: reconnection attempt 240 in 4 seconds
May 23 20:46:04 ppp [wan_link0] Link: reconnection attempt 240
May 23 20:46:04 ppp [wan_link0] PPPoE: Connecting to ''
May 23 20:46:04 ppp PPPoE: rec'd ACNAME "Vigor2000 PPPoE"
May 23 20:46:04 ppp [wan_link0] PPPoE: connection successful
May 23 20:46:04 ppp [wan_link0] Link: UP event
May 23 20:46:04 ppp [wan_link0] LCP: Up event
May 23 20:46:04 ppp [wan_link0] LCP: state change Starting –> Req-Sent
May 23 20:46:04 ppp [wan_link0] LCP: SendConfigReq #1
May 23 20:46:04 ppp [wan_link0] PROTOCOMP
May 23 20:46:04 ppp [wan_link0] MRU 1492
May 23 20:46:04 ppp [wan_link0] MAGICNUM 0x0412fbbe
May 23 20:46:04 ppp [wan_link0] LCP: rec'd Configure Request #56 (Req-Sent)
May 23 20:46:04 ppp [wan_link0] MRU 1492
May 23 20:46:04 ppp [wan_link0] AUTHPROTO CHAP MD5
May 23 20:46:04 ppp [wan_link0] MAGICNUM 0x692bd85b
May 23 20:46:04 ppp [wan_link0] LCP: SendConfigAck #56
May 23 20:46:04 ppp [wan_link0] MRU 1492
May 23 20:46:04 ppp [wan_link0] AUTHPROTO CHAP MD5
May 23 20:46:04 ppp [wan_link0] MAGICNUM 0x692bd85b
May 23 20:46:04 ppp [wan_link0] LCP: state change Req-Sent –> Ack-Sent
May 23 20:46:04 ppp [wan_link0] LCP: rec'd Configure Reject #1 (Ack-Sent)
May 23 20:46:04 ppp [wan_link0] PROTOCOMP
May 23 20:46:04 ppp [wan_link0] LCP: SendConfigReq #2
May 23 20:46:04 ppp [wan_link0] MRU 1492
May 23 20:46:04 ppp [wan_link0] MAGICNUM 0x0412fbbe
May 23 20:46:04 ppp [wan_link0] LCP: rec'd Configure Ack #2 (Ack-Sent)
May 23 20:46:04 ppp [wan_link0] MRU 1492
May 23 20:46:04 ppp [wan_link0] MAGICNUM 0x0412fbbe
May 23 20:46:04 ppp [wan_link0] LCP: state change Ack-Sent –> Opened
May 23 20:46:04 ppp [wan_link0] LCP: auth: peer wants CHAP, I want nothing
May 23 20:46:04 ppp [wan_link0] LCP: LayerUp
May 23 20:46:04 ppp [wan_link0] CHAP: rec'd CHALLENGE #1 len: 31
May 23 20:46:04 ppp [wan_link0] Name: "npe001.eal"
May 23 20:46:04 ppp [wan_link0] CHAP: Using authname "xxxxxxxx@xxxxxxx.co.uk" (I've obfuscated this)
May 23 20:46:04 ppp [wan_link0] CHAP: sending RESPONSE #1 len: 46
May 23 20:46:05 ppp [wan_link0] LCP: rec'd Configure Request #1 (Opened)
May 23 20:46:05 ppp [wan_link0] AUTHPROTO CHAP MD5
May 23 20:46:05 ppp [wan_link0] MAGICNUM 0xa156a5c4
May 23 20:46:05 ppp [wan_link0] LCP: LayerDown
May 23 20:46:05 ppp [wan_link0] LCP: SendConfigReq #3
May 23 20:46:05 ppp [wan_link0] MRU 1492
May 23 20:46:05 ppp [wan_link0] MAGICNUM 0x0412fbbe
May 23 20:46:05 ppp [wan_link0] LCP: SendConfigAck #1
May 23 20:46:05 ppp [wan_link0] AUTHPROTO CHAP MD5
May 23 20:46:05 ppp [wan_link0] MAGICNUM 0xa156a5c4
May 23 20:46:05 ppp [wan_link0] LCP: state change Opened –> Ack-Sent
May 23 20:46:05 ppp [wan_link0] LCP: rec'd Configure Ack #3 (Ack-Sent)
May 23 20:46:05 ppp [wan_link0] MRU 1492
May 23 20:46:05 ppp [wan_link0] MAGICNUM 0x0412fbbe
May 23 20:46:05 ppp [wan_link0] LCP: state change Ack-Sent –> Opened
May 23 20:46:05 ppp [wan_link0] LCP: auth: peer wants CHAP, I want nothing
May 23 20:46:05 ppp [wan_link0] LCP: LayerUp
May 23 20:46:05 ppp [wan_link0] CHAP: rec'd CHALLENGE #2 len: 29
May 23 20:46:05 ppp [wan_link0] Name: "lns4.dc5"
May 23 20:46:05 ppp [wan_link0] CHAP: Using authname "xxxxxxxx@xxxxxxx.co.uk" (I've obfuscated this)
May 23 20:46:05 ppp [wan_link0] CHAP: sending RESPONSE #2 len: 46
May 23 20:46:05 ppp [wan_link0] CHAP: rec'd SUCCESS #2 len: 4
May 23 20:46:05 ppp [wan_link0] LCP: authorization successful
May 23 20:46:05 ppp [wan_link0] Link: Matched action 'bundle "wan" ""'
May 23 20:46:05 ppp [wan_link0] Link: Join bundle "wan"
May 23 20:46:05 ppp [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bpsCan anyone help?
I've ensured that the RFC1918 etc tickboxes are unticked, and have tried 2.3 and 2.3.1 with no change in functionality.
Mike.
-
Just to add to this, it appears i'm getting another instance of this issue which xbipin reported, whereby the PPPoE connection will work first time it boots, but on subsequent reconnections it just sits there unable/unwilling to attempt a negotiation of a CHAP connection. The ISP confirms there's no attempts at their RADIUS, and those are the above logs. If someone is willing to troubleshoot, I am perfectly willing to provide logs/logins/etc to try and sort this issue once and for all.
-
Hi All,
Just to keep everyone in the loop, this is what we've worked out…
Once in a while (maybe <5% of all builds of pfSense) you will eventually build a pfSense instance that for some reason the firewall gets in the way, or other reasons stop the PPPoE service from operating correctly.
The issues above are indicative of the problem manifesting itself. You will have a PPPoE connection that works first time pfSense boots, but then refuses to send CHAP authentication to the ISP's RADIUS server on subsequent reconnects initiated by the line or modem. The only way to reconnect is to reset the WAN line, either by unplugging/replugging the RJ45 from the modem, or by power-cycling the modem, essentially to let pfSense know that it's got to kick itself and restart the WAN link. Anything more subtle than this is just met with CHAP attempts (we assume) which are not then sent onto the ISP.
There is no rhyme or reason to it, and you will pull your hair out trying to troubleshoot it because no matter what you do there are other people telling you "it works for me" (great!) and pfSense unable to troubleshoot the issue due to the perceived lack of logs indicating the problem.
THE ONLY WAY TO FIX THIS IS TO REBUILD YOUR PFSENSE INSTANCE.
I have spent 2 weeks trying to troubleshoot this instance, which wouldn't stay up more than an hour or two max. Hence I drove to site today, downloaded a brand new 2.3.1 ISO and rebuilt the pfSense instance on the same VMware ESXi box with the same networking config, same cables, same Draytek Vigor 130 modem, the lot. Hence nothing else aside from pfSense has changed. This new instance has now been up for over 3 hours, which is a record.
I hope this reply helps others, because whilst there's lots of posts from people such as xbipin etc on here reporting the self same issue, they all appeared to either fix the issue with a rebuild themselves or disappear and nobody gave this answer.
Mike.
-
Any admin/dev available.
Because I decided to give pfsense another chance, upgraded to 2.3, et voila: no more PPPoE. Not even the above solutions are working, it is simply no more VDSL:
WAN_PPPOE
|
| Pending | Pending | Pending | Unknown |Plug a PC directly into the ISP modem/router combo, et voila, internet immediately.
It worked, and it worked stable, on 2.2. And now I doesn't work anymore.
I'm sure it must be something I did wrong, but the only thing I did was press the 'upgrade' button. So to speak.
Jul 4 18:08:26 ppp [wan_link0] PPPoE: Connecting to '' Jul 4 18:08:26 ppp [wan_link0] Link: reconnection attempt 40 Jul 4 18:08:22 ppp [wan_link0] Link: reconnection attempt 40 in 4 seconds Jul 4 18:08:22 ppp [wan_link0] LCP: Down event Jul 4 18:08:22 ppp [wan_link0] Link: DOWN event Jul 4 18:08:22 ppp [wan_link0] PPPoE connection timeout after 9 seconds Jul 4 18:08:13 ppp [wan_link0] PPPoE: Connecting to '' Jul 4 18:08:13 ppp [wan_link0] Link: reconnection attempt 39 Jul 4 18:08:10 ppp [wan_link0] Link: reconnection attempt 39 in 3 seconds Jul 4 18:08:10 ppp [wan_link0] LCP: Down event Jul 4 18:08:10 ppp [wan_link0] Link: DOWN event Jul 4 18:08:10 ppp [wan_link0] PPPoE connection timeout after 9 seconds Jul 4 18:08:01 ppp [wan_link0] PPPoE: Connecting to '' Jul 4 18:08:01 ppp [wan_link0] Link: reconnection attempt 38 Jul 4 18:07:59 ppp [wan_link0] Link: reconnection attempt 38 in 2 seconds Jul 4 18:07:59 ppp [wan_link0] LCP: Down event Jul 4 18:07:59 ppp [wan_link0] Link: DOWN event Jul 4 18:07:59 ppp [wan_link0] PPPoE connection timeout after 9 seconds Jul 4 18:07:50 ppp [wan_link0] PPPoE: Connecting to '' Jul 4 18:07:50 ppp [wan_link0] Link: reconnection attempt 37 Jul 4 18:07:46 ppp [wan_link0] Link: reconnection attempt 37 in 4 seconds Jul 4 18:07:46 ppp [wan_link0] LCP: Down event Jul 4 18:07:46 ppp [wan_link0] Link: DOWN event Jul 4 18:07:46 ppp [wan_link0] PPPoE connection timeout after 9 seconds Jul 4 18:07:37 ppp [wan_link0] PPPoE: Connecting to '' Jul 4 18:07:37 ppp [wan_link0] Link: reconnection attempt 36 Jul 4 18:07:33 ppp [wan_link0] Link: reconnection attempt 36 in 4 seconds Jul 4 18:07:33 ppp [wan_link0] LCP: Down event Jul 4 18:07:33 ppp [wan_link0] Link: DOWN event Jul 4 18:07:33 ppp [wan_link0] PPPoE connection timeout after 9 seconds Jul 4 18:07:24 ppp [wan_link0] PPPoE: Connecting to '' Jul 4 18:07:24 ppp [wan_link0] Link: reconnection attempt 35 Jul 4 18:07:23 ppp [wan_link0] Link: reconnection attempt 35 in 1 seconds Jul 4 18:07:23 ppp [wan_link0] LCP: Down event Jul 4 18:07:23 ppp [wan_link0] Link: DOWN event Jul 4 18:07:23 ppp [wan_link0] PPPoE connection timeout after 9 seconds Jul 4 18:07:14 ppp [wan_link0] PPPoE: Connecting to '' Jul 4 18:07:14 ppp [wan_link0] Link: reconnection attempt 34 Jul 4 18:07:13 ppp [wan_link0] Link: reconnection attempt 34 in 1 seconds Jul 4 18:07:13 ppp [wan_link0] LCP: Down event Jul 4 18:07:13 ppp [wan_link0] Link: DOWN event Jul 4 18:07:13 ppp [wan_link0] PPPoE connection timeout after 9 seconds Jul 4 18:07:04 ppp [wan_link0] PPPoE: Connecting to '' Jul 4 18:07:04 ppp [wan_link0] Link: reconnection attempt 33 Jul 4 18:07:00 ppp [wan_link0] Link: reconnection attempt 33 in 4 seconds Jul 4 18:07:00 ppp [wan_link0] LCP: Down event Jul 4 18:07:00 ppp [wan_link0] Link: DOWN event Jul 4 18:07:00 ppp [wan_link0] PPPoE connection timeout after 9 seconds Jul 4 18:06:51 ppp [wan_link0] PPPoE: Connecting to '' Jul 4 18:06:51 ppp [wan_link0] Link: reconnection attempt 32 Jul 4 18:06:47 ppp [wan_link0] Link: reconnection attempt 32 in 4 seconds Jul 4 18:06:47 ppp [wan_link0] LCP: Down event Jul 4 18:06:47 ppp [wan_link0] Link: DOWN event Jul 4 18:06:47 ppp [wan_link0] PPPoE connection timeout after 9 seconds Jul 4 18:06:38 ppp [wan_link0] PPPoE: Connecting to '' Jul 4 18:06:38 ppp [wan_link0] Link: reconnection attempt 31 Jul 4 18:06:34 ppp [wan_link0] Link: reconnection attempt 31 in 4 seconds Jul 4 18:06:34 ppp [wan_link0] LCP: Down event Jul 4 18:06:34 ppp [wan_link0] Link: DOWN event Jul 4 18:06:34 ppp [wan_link0] PPPoE connection timeout after 9 seconds Jul 4 18:06:25 ppp [wan_link0] PPPoE: Connecting to '' Jul 4 18:06:25 ppp [wan_link0] Link: reconnection attempt 30 Jul 4 18:06:24 ppp [wan_link0] Link: reconnection attempt 30 in 1 seconds Jul 4 18:06:24 ppp [wan_link0] LCP: Down event Jul 4 18:06:24 ppp [wan_link0] Link: DOWN event Jul 4 18:06:24 ppp [wan_link0] PPPoE connection timeout after 9 seconds Jul 4 18:06:15 ppp [wan_link0] PPPoE: Connecting to '' Jul 4 18:06:15 ppp [wan_link0] Link: reconnection attempt 29 Jul 4 18:06:14 ppp [wan_link0] Link: reconnection attempt 29 in 1 seconds Jul 4 18:06:14 ppp [wan_link0] LCP: Down event Jul 4 18:06:14 ppp [wan_link0] Link: DOWN event Jul 4 18:06:14 ppp [wan_link0] PPPoE connection timeout after 9 seconds Jul 4 18:06:05 ppp [wan_link0] PPPoE: Connecting to '' Jul 4 18:06:05 ppp [wan_link0] Link: reconnection attempt 28 Jul 4 18:06:04 ppp [wan_link0] Link: reconnection attempt 28 in 1 seconds Jul 4 18:06:04 ppp [wan_link0] LCP: Down event Jul 4 18:06:04 ppp [wan_link0] Link: DOWN event Jul 4 18:06:04 ppp [wan_link0] PPPoE connection timeout after 9 seconds Jul 4 18:05:59 php [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Jul 4 18:05:55 ppp [wan_link0] PPPoE: Connecting to '' Jul 4 18:05:55 ppp [wan_link0] Link: reconnection attempt 27Please don't tell me to reinstall from scratch. That would only be the 1 billionth time I had to reserve a full day to reinstall pfsense.
-
I've been having the same issues with my ADSL2+ bonded lines. Once the line drops it will continue to fail re connection until the the modem is power cycled.
Jun 24 10:37:16 pfSense ppp: [wan_link0] LCP: no reply to 1 echo request(s) Jun 24 10:37:26 pfSense ppp: [wan_link0] LCP: no reply to 2 echo request(s) Jun 24 10:37:36 pfSense ppp: [wan_link0] LCP: no reply to 3 echo request(s) Jun 24 10:37:46 pfSense ppp: [wan_link0] LCP: no reply to 4 echo request(s) Jun 24 10:37:56 pfSense ppp: [wan_link0] LCP: no reply to 5 echo request(s) Jun 24 10:37:56 pfSense ppp: [wan_link0] LCP: peer not responding to echo requests Jun 24 10:37:56 pfSense ppp: [wan_link0] LCP: state change Opened --> Stopping Jun 24 10:37:56 pfSense ppp: [wan_link0] Link: Leave bundle "wan" Jun 24 10:37:56 pfSense ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps Jun 24 10:37:56 pfSense ppp: [wan] IPCP: Close event Jun 24 10:37:56 pfSense ppp: [wan] IPCP: state change Opened --> Closing Jun 24 10:37:56 pfSense ppp: [wan] IPCP: SendTerminateReq #4 Jun 24 10:37:56 pfSense ppp: [wan] IPCP: LayerDown Jun 24 10:37:56 pfSense ppp: [wan] IFACE: Down event Jun 24 10:37:56 pfSense ppp: [wan] IFACE: Rename interface pppoe0 to pppoe0 Jun 24 10:37:56 pfSense ppp: [wan] IPV6CP: Close event Jun 24 10:37:56 pfSense ppp: [wan] IPV6CP: state change Stopped --> Closed Jun 24 10:37:56 pfSense ppp: [wan] IPCP: Down event Jun 24 10:37:56 pfSense ppp: [wan] IPCP: LayerFinish Jun 24 10:37:56 pfSense ppp: [wan] Bundle: No NCPs left. Closing links... Jun 24 10:37:56 pfSense ppp: [wan] IPCP: state change Closing --> Initial Jun 24 10:37:56 pfSense ppp: [wan] IPV6CP: Down event Jun 24 10:37:56 pfSense ppp: [wan] IPV6CP: state change Closed --> Initial Jun 24 10:37:56 pfSense ppp: [wan_link0] LCP: SendTerminateReq #3 Jun 24 10:37:56 pfSense ppp: [wan_link0] LCP: LayerDown Jun 24 10:37:59 pfSense ppp: [wan_link0] LCP: SendTerminateReq #4 Jun 24 10:38:01 pfSense ppp: [wan_link0] LCP: state change Stopping --> Stopped Jun 24 10:38:01 pfSense ppp: [wan_link0] LCP: LayerFinish Jun 24 10:38:01 pfSense ppp: [wan_link0] PPPoE: connection closed Jun 24 10:38:01 pfSense ppp: [wan_link0] Link: DOWN event Jun 24 10:38:01 pfSense ppp: [wan_link0] LCP: Down event Jun 24 10:38:01 pfSense ppp: [wan_link0] LCP: state change Stopped --> Starting Jun 24 10:38:01 pfSense ppp: [wan_link0] LCP: LayerStart Jun 24 10:38:01 pfSense ppp: [wan_link0] Link: reconnection attempt 1 in 3 seconds Jun 24 10:38:04 pfSense ppp: [wan_link0] Link: reconnection attempt 1 Jun 24 10:38:04 pfSense ppp: [wan_link0] PPPoE: Connecting to '' Jun 24 10:38:13 pfSense ppp: [wan_link0] PPPoE connection timeout after 9 seconds Jun 24 10:38:13 pfSense ppp: [wan_link0] Link: DOWN event Jun 24 10:38:13 pfSense ppp: [wan_link0] LCP: Down event Jun 24 10:38:13 pfSense ppp: [wan_link0] Link: reconnection attempt 2 in 1 seconds Jun 24 10:38:14 pfSense ppp: [wan_link0] Link: reconnection attempt 2 Jun 24 10:38:14 pfSense ppp: [wan_link0] PPPoE: Connecting to '' Jun 24 10:38:23 pfSense ppp: [wan_link0] PPPoE connection timeout after 9 seconds Jun 24 10:38:23 pfSense ppp: [wan_link0] Link: DOWN event Jun 24 10:38:23 pfSense ppp: [wan_link0] LCP: Down event Jun 24 10:38:23 pfSense ppp: [wan_link0] Link: reconnection attempt 3 in 2 seconds Jun 24 10:38:25 pfSense ppp: [wan_link0] Link: reconnection attempt 3 Jun 24 10:38:25 pfSense ppp: [wan_link0] PPPoE: Connecting to '' Jun 24 10:38:34 pfSense ppp: [wan_link0] PPPoE connection timeout after 9 seconds Jun 24 10:38:34 pfSense ppp: [wan_link0] Link: DOWN event Jun 24 10:38:34 pfSense ppp: [wan_link0] LCP: Down event Jun 24 10:38:34 pfSense ppp: [wan_link0] Link: reconnection attempt 4 in 1 seconds Jun 24 10:38:35 pfSense ppp: [wan_link0] Link: reconnection attempt 4 Jun 24 10:38:35 pfSense ppp: [wan_link0] PPPoE: Connecting to '' Jun 24 10:38:44 pfSense ppp: [wan_link0] PPPoE connection timeout after 9 seconds Jun 24 10:38:44 pfSense ppp: [wan_link0] Link: DOWN event Jun 24 10:38:44 pfSense ppp: [wan_link0] LCP: Down event Jun 24 10:38:44 pfSense ppp: [wan_link0] Link: reconnection attempt 5 in 4 seconds Jun 24 10:38:48 pfSense ppp: [wan_link0] Link: reconnection attempt 5 Jun 24 10:38:48 pfSense ppp: [wan_link0] PPPoE: Connecting to '' Jun 24 10:38:57 pfSense ppp: [wan_link0] PPPoE connection timeout after 9 seconds Jun 24 10:38:57 pfSense ppp: [wan_link0] Link: DOWN event Jun 24 10:38:57 pfSense ppp: [wan_link0] LCP: Down event Jun 24 10:38:57 pfSense ppp: [wan_link0] Link: reconnection attempt 6 in 3 seconds Jun 24 10:39:00 pfSense ppp: [wan_link0] Link: reconnection attempt 6 Jun 24 10:39:00 pfSense ppp: [wan_link0] PPPoE: Connecting to '' Jun 24 10:39:09 pfSense ppp: [wan_link0] PPPoE connection timeout after 9 seconds Jun 24 10:39:09 pfSense ppp: [wan_link0] Link: DOWN event Jun 24 10:39:09 pfSense ppp: [wan_link0] LCP: Down event Jun 24 10:39:09 pfSense ppp: [wan_link0] Link: reconnection attempt 7 in 3 seconds Jun 24 10:39:12 pfSense ppp: [wan_link0] Link: reconnection attempt 7 Jun 24 10:39:12 pfSense ppp: [wan_link0] PPPoE: Connecting to '' -
https://forum.pfsense.org/index.php?topic=113750.0