PPPOE authentication with Plusnet FTTP not working

[#1]

Debug logs from the Palo alto attached, shows authentication failure same as previous logs

2023-02-21 07:29:39.431 +0000 debug: pan_pppoe_ok_to_send(pan_pppoe_fsm.c:352): [0xffd0038c60/16][0] Ok to send, ha_state:0 (fsm state is:1) for ethernet1/1
2023-02-21 07:29:39.432 +0000 debug: pan_pppoe_send_padi(pan_pppoe_fsm.c:402): [0xffd0038c60/16][0] Sending PADI on ethernet1/1
2023-02-21 07:29:39.432 +0000 debug: pan_pppoe_output(pan_pppoe_thread.c:1048): [0xffd0038c60/16][0] Sent 44 (36 on wire) bytes of PPPoE pkt to DP on socket 6
2023-02-21 07:29:39.434 +0000 debug: pan_ppp_get_pppoe_fsm(pan_ppp_fsm.c:108): Found ppp_fsm_info[0] unit for ifindex: 16, pppoe_fsm 0xffd0038c60
2023-02-21 07:29:39.434 +0000 debug: pan_pppoed_select_callback(pan_pppoe_thread.c:189): [0xffd0038c60]/16] len:68 ---------[Received a PPPoE/PPP ctrl packet]--------------
2023-02-21 07:29:39.434 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1298): [0xffd0038c60/16][0] Received PPPoE pkt from AC mac: f8:13:08:41:31:03 on: ethernet1/1
2023-02-21 07:29:39.434 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1303): [0xffd0038c60/16][0] etype:0x8863, Code:0x7(PADO), Sess ID:0, Len:48
2023-02-21 07:29:39.434 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1311): [0xffd0038c60/16][0] ******** Run PPPoE FSM *******
2023-02-21 07:29:39.434 +0000 debug: pan_pppoe_recv_pado(pan_pppoe_fsm.c:724): [0xffd0038c60/16][0] Received PADO on ethernet1/1
2023-02-21 07:29:39.434 +0000 debug: parse_pppoe_tags(pan_pppoe_fsm.c:260): Retrieved tag:0x101(PAN_PPPOE_SVC_NAME_TAG) of length:0 and value:Null
2023-02-21 07:29:39.434 +0000 debug: parse_pppoe_tags(pan_pppoe_fsm.c:261): remaining:44
2023-02-21 07:29:39.434 +0000 debug: parse_pppoe_tags(pan_pppoe_fsm.c:260): Retrieved tag:0x102(PAN_PPPOE_AC_NAME_TAG) of length:12 and value:acc-aln2.nao
2023-02-21 07:29:39.435 +0000 debug: parse_pppoe_tags(pan_pppoe_fsm.c:261): remaining:28
2023-02-21 07:29:39.435 +0000 debug: parse_pppoe_tags(pan_pppoe_fsm.c:260): Retrieved tag:0x103(PAN_PPPOE_HOST_UNIQ_NAME_TAG) of length:4 and value:g<9B><AE>i
2023-02-21 07:29:39.435 +0000 debug: parse_pppoe_tags(pan_pppoe_fsm.c:261): remaining:20
2023-02-21 07:29:39.435 +0000 debug: parse_pppoe_tags(pan_pppoe_fsm.c:260): Retrieved tag:0x104(PAN_PPPOE_AC_COOKIE_TAG) of length:16 and value:4<ED><AC><CD><CC>Y<A8><A2><E2>^RESC0{<F1>}q
2023-02-21 07:29:39.435 +0000 debug: parse_pppoe_tags(pan_pppoe_fsm.c:261): remaining:0
2023-02-21 07:29:39.435 +0000 debug: pan_pppoe_send_padr(pan_pppoe_fsm.c:579): [0xffd0038c60/16][0] Sending PADR on ethernet1/1
2023-02-21 07:29:39.435 +0000 debug: pan_pppoe_output(pan_pppoe_thread.c:1048): [0xffd0038c60/16][0] Sent 64 (56 on wire) bytes of PPPoE pkt to DP on socket 6
2023-02-21 07:29:39.437 +0000 debug: pan_ppp_get_pppoe_fsm(pan_ppp_fsm.c:108): Found ppp_fsm_info[0] unit for ifindex: 16, pppoe_fsm 0xffd0038c60
2023-02-21 07:29:39.437 +0000 debug: pan_pppoed_select_callback(pan_pppoe_thread.c:185):
2023-02-21 07:29:39.437 +0000 debug: pan_pppoed_select_callback(pan_pppoe_thread.c:189): [0xffd0038c60]/16] len:60 ---------[Received a PPPoE/PPP ctrl packet]--------------
2023-02-21 07:29:39.437 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1298): [0xffd0038c60/16][0] Received PPPoE pkt from AC mac: f8:13:08:41:31:03 on: ethernet1/1
2023-02-21 07:29:39.437 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1303): [0xffd0038c60/16][0] etype:0x8863, Code:0x65(PADS), Sess ID:4085, Len:12
2023-02-21 07:29:39.437 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1311): [0xffd0038c60/16][0] ******** Run PPPoE FSM *******
2023-02-21 07:29:39.437 +0000 debug: pan_pppoe_recv_pads(pan_pppoe_fsm.c:846): [0xffd0038c60/16][0] Received PADS on ethernet1/1
2023-02-21 07:29:39.437 +0000 debug: parse_pppoe_tags(pan_pppoe_fsm.c:260): Retrieved tag:0x101(PAN_PPPOE_SVC_NAME_TAG) of length:0 and value:Null
2023-02-21 07:29:39.437 +0000 debug: parse_pppoe_tags(pan_pppoe_fsm.c:261): remaining:8
2023-02-21 07:29:39.437 +0000 debug: parse_pppoe_tags(pan_pppoe_fsm.c:260): Retrieved tag:0x103(PAN_PPPOE_HOST_UNIQ_NAME_TAG) of length:4 and value:Z<AF>^R+
2023-02-21 07:29:39.438 +0000 debug: parse_pppoe_tags(pan_pppoe_fsm.c:261): remaining:0
2023-02-21 07:29:39.438 +0000 debug: pan_pppoe_recv_pads(pan_pppoe_fsm.c:905): [0xffd0038c60/16][0] >>>>> PPPoE CONNECTED ON: ethernet1/1, STARTING LCP <<<<<<
2023-02-21 07:29:39.438 +0000 debug: log_write(ppp/utils.c:679): [0xffd0038c60/16][0] PPP SENT: [LCP ConfReq id=0x1 <magic 0xb4d8b7f4>]
2023-02-21 07:29:39.438 +0000 debug: pan_pppoe_output(pan_pppoe_thread.c:1048): [0xffd0038c60/16][0] Sent 40 (32 on wire) bytes of PPPoE pkt to DP on socket 6
2023-02-21 07:29:39.481 +0000 debug: pan_ppp_get_pppoe_fsm(pan_ppp_fsm.c:108): Found ppp_fsm_info[0] unit for ifindex: 16, pppoe_fsm 0xffd0038c60
2023-02-21 07:29:39.481 +0000 debug: pan_pppoed_select_callback(pan_pppoe_thread.c:185):
2023-02-21 07:29:39.481 +0000 debug: pan_pppoed_select_callback(pan_pppoe_thread.c:189): [0xffd0038c60]/16] len:60 ---------[Received a PPPoE/PPP ctrl packet]--------------
2023-02-21 07:29:39.481 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1298): [0xffd0038c60/16][0] Received PPPoE pkt from AC mac: f8:13:08:41:31:03 on: ethernet1/1
2023-02-21 07:29:39.481 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1303): [0xffd0038c60/16][0] etype:0x8864, Code:0x0(PPP SESS), Sess ID:4085, Len:21
2023-02-21 07:29:39.481 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1330): [0xffd0038c60/16][0] ... Run PPP FSM ...
2023-02-21 07:29:39.482 +0000 debug: log_write(ppp/utils.c:679): [0xffd0038c60/16][0] PPP RCVD: [LCP ConfReq id=0x5e <mru 1492> <auth chap MD5> <magic 0x56884b49>]
2023-02-21 07:29:39.482 +0000 debug: log_write(ppp/utils.c:679): lcp_reqci: returning CONFACK.
2023-02-21 07:29:39.482 +0000 debug: log_write(ppp/utils.c:679): [0xffd0038c60/16][0] PPP SENT: [LCP ConfAck id=0x5e <mru 1492> <auth chap MD5> <magic 0x56884b49>]
2023-02-21 07:29:39.482 +0000 debug: pan_pppoe_output(pan_pppoe_thread.c:1048): [0xffd0038c60/16][0] Sent 49 (41 on wire) bytes of PPPoE pkt to DP on socket 6
2023-02-21 07:29:39.482 +0000 debug: pan_ppp_get_pppoe_fsm(pan_ppp_fsm.c:108): Found ppp_fsm_info[0] unit for ifindex: 16, pppoe_fsm 0xffd0038c60
2023-02-21 07:29:39.482 +0000 debug: pan_pppoed_select_callback(pan_pppoe_thread.c:185):
2023-02-21 07:29:39.482 +0000 debug: pan_pppoed_select_callback(pan_pppoe_thread.c:189): [0xffd0038c60]/16] len:60 ---------[Received a PPPoE/PPP ctrl packet]--------------
2023-02-21 07:29:39.482 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1298): [0xffd0038c60/16][0] Received PPPoE pkt from AC mac: f8:13:08:41:31:03 on: ethernet1/1
2023-02-21 07:29:39.482 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1303): [0xffd0038c60/16][0] etype:0x8864, Code:0x0(PPP SESS), Sess ID:4085, Len:12
2023-02-21 07:29:39.482 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1330): [0xffd0038c60/16][0] ... Run PPP FSM ...
2023-02-21 07:29:39.482 +0000 debug: log_write(ppp/utils.c:679): [0xffd0038c60/16][0] PPP RCVD: [LCP ConfAck id=0x1 <magic 0xb4d8b7f4>]
2023-02-21 07:29:39.483 +0000 debug: log_write(ppp/utils.c:679): ho->mru:1492, wo->mru:1492, go->mru:1492

2023-02-21 07:29:39.483 +0000 debug: log_write(ppp/utils.c:679): MTU: final:1492, mru:1492, mtu:1492, allow mru:16384

2023-02-21 07:29:39.483 +0000 debug: log_write(ppp/utils.c:679): [0xffd0038c60/16][0] PPP SENT: [LCP EchoReq id=0x0 magic=0xb4d8b7f4]
2023-02-21 07:29:39.483 +0000 debug: pan_pppoe_output(pan_pppoe_thread.c:1048): [0xffd0038c60/16][0] Sent 38 (30 on wire) bytes of PPPoE pkt to DP on socket 6
2023-02-21 07:29:39.483 +0000 debug: ppp_get_user_name(pan_ppp_fsm.c:396): [0xffd0038c60/16][0] >>>>> LCP DONE ON: ethernet1/1, STARTING AUTH <<<<<<
2023-02-21 07:29:39.483 +0000 debug: pan_ppp_get_pppoe_fsm(pan_ppp_fsm.c:108): Found ppp_fsm_info[0] unit for ifindex: 16, pppoe_fsm 0xffd0038c60
2023-02-21 07:29:39.483 +0000 debug: pan_pppoed_select_callback(pan_pppoe_thread.c:185):
2023-02-21 07:29:39.483 +0000 debug: pan_pppoed_select_callback(pan_pppoe_thread.c:189): [0xffd0038c60]/16] len:95 ---------[Received a PPPoE/PPP ctrl packet]--------------
2023-02-21 07:29:39.483 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1298): [0xffd0038c60/16][0] Received PPPoE pkt from AC mac: f8:13:08:41:31:03 on: ethernet1/1
2023-02-21 07:29:39.483 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1303): [0xffd0038c60/16][0] etype:0x8864, Code:0x0(PPP SESS), Sess ID:4085, Len:75
2023-02-21 07:29:39.483 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1330): [0xffd0038c60/16][0] ... Run PPP FSM ...
2023-02-21 07:29:39.484 +0000 debug: log_write(ppp/utils.c:679): [0xffd0038c60/16][0] PPP RCVD: [CHAP Challenge id=0x1 <b320700d7eb72daa2cbf9b5968956b53275ff3a6630956568246bd93a1842f55a41fe123560f4d824f695bb7fec70b26277ecc0b88a3e08a>, name = "acc-aln2.nao"]
2023-02-21 07:29:39.484 +0000 debug: log_write(ppp/utils.c:679): [0xffd0038c60/16][0] PPP SENT: [CHAP Response id=0x1 <a62e7af087ed4446d2d9b5ae8258fe61>, name = "username@plusdsl.net"]
2023-02-21 07:29:39.484 +0000 debug: pan_pppoe_output(pan_pppoe_thread.c:1048): [0xffd0038c60/16][0] Sent 75 (67 on wire) bytes of PPPoE pkt to DP on socket 6
2023-02-21 07:29:39.491 +0000 debug: pan_ppp_get_pppoe_fsm(pan_ppp_fsm.c:108): Found ppp_fsm_info[0] unit for ifindex: 16, pppoe_fsm 0xffd0038c60
2023-02-21 07:29:39.491 +0000 debug: pan_pppoed_select_callback(pan_pppoe_thread.c:185):
2023-02-21 07:29:39.491 +0000 debug: pan_pppoed_select_callback(pan_pppoe_thread.c:189): [0xffd0038c60]/16] len:60 ---------[Received a PPPoE/PPP ctrl packet]--------------
2023-02-21 07:29:39.491 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1298): [0xffd0038c60/16][0] Received PPPoE pkt from AC mac: f8:13:08:41:31:03 on: ethernet1/1
2023-02-21 07:29:39.491 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1303): [0xffd0038c60/16][0] etype:0x8864, Code:0x0(PPP SESS), Sess ID:4085, Len:10
2023-02-21 07:29:39.491 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1330): [0xffd0038c60/16][0] ... Run PPP FSM ...
2023-02-21 07:29:39.492 +0000 debug: log_write(ppp/utils.c:679): [0xffd0038c60/16][0] PPP RCVD: [LCP EchoRep id=0x0 magic=0x56884b49]
2023-02-21 07:29:39.500 +0000 debug: pan_ppp_get_pppoe_fsm(pan_ppp_fsm.c:108): Found ppp_fsm_info[0] unit for ifindex: 16, pppoe_fsm 0xffd0038c60
2023-02-21 07:29:39.500 +0000 debug: pan_pppoed_select_callback(pan_pppoe_thread.c:185):
2023-02-21 07:29:39.500 +0000 debug: pan_pppoed_select_callback(pan_pppoe_thread.c:189): [0xffd0038c60]/16] len:60 ---------[Received a PPPoE/PPP ctrl packet]--------------
2023-02-21 07:29:39.500 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1298): [0xffd0038c60/16][0] Received PPPoE pkt from AC mac: f8:13:08:41:31:03 on: ethernet1/1
2023-02-21 07:29:39.500 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1303): [0xffd0038c60/16][0] etype:0x8864, Code:0x0(PPP SESS), Sess ID:4085, Len:33
2023-02-21 07:29:39.500 +0000 debug: pan_pppoe_recv_pkt(pan_pppoe_fsm.c:1330): [0xffd0038c60/16][0] ... Run PPP FSM ...
2023-02-21 07:29:39.501 +0000 debug: log_write(ppp/utils.c:679): [0xffd0038c60/16][0] PPP RCVD: [CHAP Failure id=0x1 "CHAP authentication failure"]
2023-02-21 07:29:39.501 +0000 debug: log_write(ppp/utils.c:679): CHAP authentication failed: CHAP authentication failure
2023-02-21 07:29:39.501 +0000 debug: log_write(ppp/utils.c:679): CHAP authentication failed
2023-02-21 07:29:39.502 +0000 debug: log_write(ppp/utils.c:679): [0xffd0038c60/16][0] PPP SENT: [LCP TermReq id=0x2 "Failed to authenticate ourselves to peer"]
2023-02-21 07:29:39.502 +0000 debug: pan_pppoe_output(pan_pppoe_thread.c:1048): [0xffd0038c60/16][0] Sent 74 (66 on wire) bytes of PPPoE pkt to DP on socket 6

[#2]

Oh well, worth a try!.

It definitely looks like an authentication problem. It's going to be difficult to establish whether the PA is sending the correct username / password , even with packet captures , since its going to be MD5 hashed with a random number seed from the CHAP challenge

I'd try the Cisco if possible...

[#3]

If it helps, I've checked our RADIUS logs for a period of time during which I suspect you were tinkering (~5.15pm on 16/02).

I can see no activity at all in the logs for roughly an hour following the initial disconnection, failed or otherwise.

If my assumption around timings is correct, then that suggests that whatever is happening, the attempts aren't even reaching the place where account validation takes place.

[#4]

Hi Bob that is helpful to know thanks and yes on the 16th I was tinkering, can you check the logs for this morning please as I was troubleshooting again from around 06:00AM and onwards

[#5]

@bobpullen thanks for the input, what about any RADIUS logs from today , corresponding to the time of the debug log above ?

Also the log above is showing a CHAP challenge from "acc-aln2.nao" , is that not a PN/BT concentrator ?

[#6]

The above log shows

2023-02-21 07:29:39.484 +0000 debug: log_write(ppp/utils.c:679): [0xffd0038c60/16][0] PPP SENT: [CHAP Response id=0x1 <a62e7af087ed4446d2d9b5ae8258fe61>, name = "username@plusdsl.net"]

[#7]

Yes because I have removed my username to sanitize the logs

[#8]

I might have used <my-username> for clarity.

I found this guide.

https://knowledgebase.paloaltonetworks.com/KCSArticleDetail?id=kA10g000000ClTKCA0

It suggests using Layer 3 for the PPPoE connection, think you mentioned layer 2 before.

[#9]

The config on the firewall uses L3 for the interface, it will not let you perform PPPOE on a L2 interface.

The L2 mentioned before was for the ONT as far as I am aware it's an L2 device that forwards PPPOE packets across the network to the access concentrator.

[#10]

---

@witherford wrote:

Hi Bob that is helpful to know thanks and yes on the 16th I was tinkering, can you check the logs for this morning please as I was troubleshooting again from around 06:00AM and onwards

---

There was a stopped session around 06:17AM and then nothing until 08:52AM; this is looking for events originating from your physical Wholesale line ID. Assuming the domain in the PPP request is parsed correctly i.e. '@plusdsl.net' then I'd expect to see any and all attempts.

@MisterW wrote:

Also the log above is showing a CHAP challenge from "acc-aln2.nao" , is that not a PN/BT concentrator ?

Not 100% but yes, it's likely the access concentrator. @witherford has a static IP so traffic is L2TP tunnelled from the access network to our BNG's which is where I understand the PPP is terminated/account auth takes place etc. It's the traffic hitting the BNG's and beyond that I'm not seeing. I do not have visibility of what is happening in the access network.

[#11]

Hmm that is strange @ 08:52 is when I moved back over to using the Plusnet router to authenticate.

So far it seems to me as though the Plusnet router is able to successfully authenticate so traffic is able to make it to the "BNG and beyond" as you define it.

The Palo alto is not so you never see the traffic, so the golden question is, who has access to the access concentrator mentioned previously in this thread and can this be passed onto them.

I believe checking the logs on there is the next logical step

[#12]

@bobpullen is there any mileage in trying the 'setup' username ? would that confirm if it is a basic authentication problem.

Appreciate its not going to allow internet access but would you at least see some successful authentications ?

I guess that still wouldnt be conclusive as it wont be L2TP tunneled. However I cant see that being the issue, my account has a static IP, and so is L2TP tunneled, and that works fine, as does the Hub 2 with @witherford s account

@witherford  can you double check the advanced settings for pppoe from the link above by @Dan_the_Van 

[#13]

I have checked all those settings and they are set correctly, the authentication is defined as CHAP, the username and password is defined correctly and the access concentrator is left blank as the device discovers that it's self.

All the settings are the same as VDSL when everything worked fine.

[#14]

All the settings are the same as VDSL when everything worked fine.

That's the most confusing thing.

[#15]

To me there are only two things that have changed here:

1) plugging into the ONT instead of a BT Openreach modem which fundamentally it's the same, as far as I am aware they both act as modems and send PPPOE packets to and from the BT/Plusnet network.

2) The network I connect to on the ISP side is likely to be very different, I reckon and an entirely separate network in ways, I reckon if I went back to the copper network I would likely be connecting to a different access concentrator.