PPPoE Authentication Failure

Lionel271 · ‎08-22-2019

I have the following PPPoE configuration on a router:

aaa new-model
!
aaa authentication ppp default group radius
aaa authentication dot1x default group radius
aaa authorization network default group radius 
aaa accounting delay-start
aaa accounting dot1x default start-stop group radius
aaa accounting network default start-stop group radius
!
aaa session-id common
!
bba-group pppoe global
 virtual-template 1
interface GigabitEthernet0/1/0
 description PPPoE
 ip address 172.16.153.1 255.255.255.252
 ip rip advertise 4
 load-interval 30
 duplex auto
 speed auto
 pppoe enable group global
!
interface Virtual-Template1
 mtu 1492
 ip unnumbered GigabitEthernet0/1/0
 peer default ip address pool CLIENT
 ppp authentication pap chap
!
ip local pool CLIENT 172.16.153.129 172.16.153.254
!
radius-server attribute 6 on-for-login-auth
radius-server attribute nas-port-id include vendor-class-id plus remote-id plus circuit-id 
!
radius server radius1
 address ipv4 172.16.152.190 auth-port 1812 acct-port 1813
 key 7 myserverkey
!
radius server radius2
 address ipv4 10.1.115.183 auth-port 1812 acct-port 1813
 key 7 myserverkey
!

I am trying to authenticate with PPPoE using a computer plugged into GigabitEthernet0/1/0 (Windows 10). My credentials are rejected, even though the RADIUS server passes an Access-Accept method and the router seems to recognize it:

*Aug 22 10:23:53.130:  Service tag: NULL Tag
*Aug 22 10:23:53.130: PPPoE : encap string prepared
contiguous pak, size 20
*Aug 22 10:23:53.130: [11]PPPoE 11: Access IE handle allocated
*Aug 22 10:23:53.130: [11]PPPoE 11: AAA get retrieved attrs
*Aug 22 10:23:53.130: [11]PPPoE 11: AAA get nas port details
*Aug 22 10:23:53.130: [11]PPPoE 11: Error adjusting nas port format did 
*Aug 22 10:23:53.130: AAA/BIND(0001703E): Bind i/f Virtual-Template1 
*Aug 22 10:23:53.130: [11]PPPoE 11: AAA get dynamic attrs
*Aug 22 10:23:53.130: [11]PPPoE 11: AAA unique ID 1703E allocated
*Aug 22 10:23:53.130: [11]PPPoE 11: AAA method list  set
*Aug 22 10:23:53.134: [11]PPPoE 11: Service request sent to SSS
*Aug 22 10:23:53.134: [11]PPPoE 11: Created, Service: None R:aaaa.bbbb.b8c0 L:aaaa.bbbb.6343 Gi0/1/0
*Aug 22 10:23:53.134: [11]PPPoE 11: State NAS_PORT_POLICY_INQUIRY    Event SSS MORE KEYS
*Aug 22 10:23:53.134: PPP: Alloc Context [18E79F0]
*Aug 22 10:23:53.134: ppp11 PPP: Phase is ESTABLISHING
*Aug 22 10:23:53.134: [11]PPPoE 11: data path set to PPP
*Aug 22 10:23:53.134: [11]PPPoE 11: Segment (SSS class): PROVISION
*Aug 22 10:23:53.134: [11]PPPoE 11: State PROVISION_PPP    Event SSM PROVISIONED
*Aug 22 10:23:53.134: [11]PPPoE 11: O PADS  R:aaaa.bbbb.6343 L:aaaa.bbbb.b8c0 Gi0/1/0
contiguous pak, size 60
*Aug 22 10:23:53.134: ppp11 PPP: Using vpn set call direction
*Aug 22 10:23:53.134: ppp11 PPP: Treating connection as a callin
*Aug 22 10:23:53.134: ppp11 PPP: Session handle[A300000B] Session id[11]
*Aug 22 10:23:53.134: ppp11 LCP: Event[OPEN] State[Initial to Starting]
*Aug 22 10:23:53.134: ppp11 PPP LCP: Enter passive mode, state[Stopped]
*Aug 22 10:23:53.154: ppp11 LCP: I CONFREQ [Stopped] id 0 len 21
*Aug 22 10:23:53.154: ppp11 LCP:    MRU 1480 (0x010405C8)
*Aug 22 10:23:53.154: ppp11 LCP:    MagicNumber 0x6C6B106A (0x05066C6B106A)
*Aug 22 10:23:53.154: ppp11 LCP:    PFC (0x0702)
*Aug 22 10:23:53.154: ppp11 LCP:    ACFC (0x0802)
*Aug 22 10:23:53.154: ppp11 LCP:    Callback 6 (0x0D0306)
*Aug 22 10:23:53.154: ppp11 LCP: O CONFREQ [Stopped] id 1 len 18
*Aug 22 10:23:53.154: ppp11 LCP:    MRU 1492 (0x010405D4)
*Aug 22 10:23:53.154: ppp11 LCP:    AuthProto PAP (0x0304C023)
*Aug 22 10:23:53.154: ppp11 LCP:    MagicNumber 0x44BA631C (0x050644BA631C)
*Aug 22 10:23:53.154: ppp11 LCP: O CONFREJ [Stopped] id 0 len 7
*Aug 22 10:23:53.154: ppp11 LCP:    Callback 6 (0x0D0306)
*Aug 22 10:23:53.154: ppp11 LCP: Event[Receive ConfReq-] State[Stopped to REQsent]
*Aug 22 10:23:53.190: ppp11 LCP: I CONFACK [REQsent] id 1 len 18
*Aug 22 10:23:53.190: ppp11 LCP:    MRU 1492 (0x010405D4)
*Aug 22 10:23:53.190: ppp11 LCP:    AuthProto PAP (0x0304C023)
*Aug 22 10:23:53.190: ppp11 LCP:    MagicNumber 0x44BA631C (0x050644BA631C)
*Aug 22 10:23:53.190: ppp11 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]
*Aug 22 10:23:53.190: ppp11 LCP: I CONFREQ [ACKrcvd] id 1 len 18
*Aug 22 10:23:53.190: ppp11 LCP:    MRU 1480 (0x010405C8)
*Aug 22 10:23:53.190: ppp11 LCP:    MagicNumber 0x6C6B106A (0x05066C6B106A)
*Aug 22 10:23:53.190: ppp11 LCP:    PFC (0x0702)
*Aug 22 10:23:53.190: ppp11 LCP:    ACFC (0x0802)
*Aug 22 10:23:53.190: ppp11 LCP: O CONFNAK [ACKrcvd] id 1 len 8
*Aug 22 10:23:53.190: ppp11 LCP:    MRU 1492 (0x010405D4)
*Aug 22 10:23:53.190: ppp11 LCP: Event[Receive ConfReq-] State[ACKrcvd to ACKrcvd]
*Aug 22 10:23:53.198: ppp11 LCP: I CONFREQ [ACKrcvd] id 2 len 18
*Aug 22 10:23:53.198: ppp11 LCP:    MRU 1480 (0x010405C8)
*Aug 22 10:23:53.198: ppp11 LCP:    MagicNumber 0x6C6B106A (0x05066C6B106A)
*Aug 22 10:23:53.198: ppp11 LCP:    PFC (0x0702)
*Aug 22 10:23:53.198: ppp11 LCP:    ACFC (0x0802)
*Aug 22 10:23:53.198: ppp11 LCP: O CONFNAK [ACKrcvd] id 2 len 8
*Aug 22 10:23:53.198: ppp11 LCP:    MRU 1492 (0x010405D4)
*Aug 22 10:23:53.198: ppp11 LCP: Event[Receive ConfReq-] State[ACKrcvd to ACKrcvd]
*Aug 22 10:23:53.202: ppp11 LCP: I CONFREQ [ACKrcvd] id 3 len 18
*Aug 22 10:23:53.202: ppp11 LCP:    MRU 1492 (0x010405D4)
*Aug 22 10:23:53.202: ppp11 LCP:    MagicNumber 0x6C6B106A (0x05066C6B106A)
*Aug 22 10:23:53.202: ppp11 LCP:    PFC (0x0702)
*Aug 22 10:23:53.202: ppp11 LCP:    ACFC (0x0802)
*Aug 22 10:23:53.202: ppp11 LCP: O CONFACK [ACKrcvd] id 3 len 18
*Aug 22 10:23:53.202: ppp11 LCP:    MRU 1492 (0x010405D4)
*Aug 22 10:23:53.202: ppp11 LCP:    MagicNumber 0x6C6B106A (0x05066C6B106A)
*Aug 22 10:23:53.202: ppp11 LCP:    PFC (0x0702)
*Aug 22 10:23:53.202: ppp11 LCP:    ACFC (0x0802)
*Aug 22 10:23:53.202: ppp11 LCP: Event[Receive ConfReq+] State[ACKrcvd to Open]
*Aug 22 10:23:53.206: ppp11 LCP: I IDENTIFY [Open] id 4 len 18 magic 0x6C6B106AMSRASV5.20
*Aug 22 10:23:53.206: ppp11 LCP: I IDENTIFY [Open] id 5 len 31 magic 0x6C6B106AMSRAS-0-DESKTOP-0D1C4OS
*Aug 22 10:23:53.206: ppp11 LCP: I IDENTIFY [Open] id 6 len 24 magic 0x6C6B106A:TKbbJ,I*+RB_\$_
*Aug 22 10:23:53.210: ppp11 PPP: Queue PAP code[1] id[37]
*Aug 22 10:23:53.226: ppp11 PPP: Phase is AUTHENTICATING, by this end
*Aug 22 10:23:53.226: ppp11 PAP: Redirect packet to ppp11
*Aug 22 10:23:53.226: ppp11 PAP: I AUTH-REQ id 37 len 35 from "pppoetest@myrealm"
*Aug 22 10:23:53.226: ppp11 PAP: Authenticating peer pppoetest@myrealm
*Aug 22 10:23:53.226: ppp11 PPP: Phase is FORWARDING, Attempting Forward
*Aug 22 10:23:53.226: ppp11 LCP: State is Open
*Aug 22 10:23:53.226: ppp11 PPP: Phase is AUTHENTICATING, Unauthenticated User
*Aug 22 10:23:53.226: AAA/AUTHEN/PPP (0001703E): Pick method list 'default' 
*Aug 22 10:23:53.226: ppp11 PPP: Sent PAP LOGIN Request
*Aug 22 10:23:53.226: RADIUS/ENCODE(0001703E):Orig. component type = PPPoE
*Aug 22 10:23:53.226: RADIUS: DSL line rate attributes successfully added
*Aug 22 10:23:53.226: RADIUS(0001703E): Config NAS IP: 0.0.0.0
*Aug 22 10:23:53.226: RADIUS(0001703E): Config NAS IPv6: ::
*Aug 22 10:23:53.226: RADIUS/ENCODE(0001703E): acct_session_id: 94260
*Aug 22 10:23:53.226: RADIUS(0001703E): sending
*Aug 22 10:23:53.226: RADIUS/ENCODE: Best Local IP-Address 172.16.152.1 for Radius-Server 172.16.152.190
*Aug 22 10:23:53.226: RADIUS(0001703E): Send Access-Request to 172.16.152.190:1812 id 1645/11, len 145
*Aug 22 10:23:53.226: RADIUS:  authenticator 40 B1 36 F0 2D 32 66 89 - 73 26 DA 6D 62 C5 84 75
*Aug 22 10:23:53.226: RADIUS:  Framed-Protocol     [7]   6   PPP                       [1]
*Aug 22 10:23:53.226: RADIUS:  User-Name           [1]   27  "pppoetest@myrealm"
*Aug 22 10:23:53.226: RADIUS:  User-Password       [2]   18  *
*Aug 22 10:23:53.226: RADIUS:  NAS-Port-Type       [61]  6   Virtual                   [5]
*Aug 22 10:23:53.226: RADIUS:  NAS-Port            [5]   6   0                         
*Aug 22 10:23:53.226: RADIUS:  NAS-Port-Id         [87]  9   "0/0/1/0"
*Aug 22 10:23:53.226: RADIUS:  Vendor, Cisco       [26]  41  
*Aug 22 10:23:53.226: RADIUS:   Cisco AVpair       [1]   35  "client-mac-address=aaaa.bbbb.6343"
*Aug 22 10:23:53.226: RADIUS:  Service-Type        [6]   6   Framed                    [2]
*Aug 22 10:23:53.226: RADIUS:  NAS-IP-Address      [4]   6   172.16.152.1             
*Aug 22 10:23:53.226: RADIUS(0001703E): Sending a IPv4 Radius Packet
*Aug 22 10:23:53.226: RADIUS(0001703E): Started 5 sec timeout
*Aug 22 10:23:53.274: AAA/BIND(0001703F): Bind i/f  
*Aug 22 10:23:53.274: AAA/AUTHEN/LOGIN (0001703F): Pick method list ' Permanent Local' 
*Aug 22 10:23:53.446: AAA/AUTHEN/LOGIN (0001703C): Pick method list ' Permanent Local' 
*Aug 22 10:23:53.558: RADIUS: Received from id 1645/11 172.16.152.190:1812, Access-Accept, len 195
*Aug 22 10:23:53.558: RADIUS:  authenticator 53 ED 22
*Aug 22 10:23:53.558: RADIUS:  Framed-Protocol     [7]   6   PPP                       [1]
*Aug 22 10:23:53.558: RADIUS:  Framed-Compression  [13]  6   VJ TCP/IP Header Compressi[1]
*Aug 22 10:23:53.558: RADIUS:  Framed-IP-Address   [8]   6   255.255.255.254           
*Aug 22 10:23:53.558: RADIUS:  Framed-IP-Netmask   [9]   6   255.255.255.255           
*Aug 22 10:23:53.558: RADIUS:  Framed-MTU          [12]  6   1452                      
*Aug 22 10:23:53.558: RADIUS:  Service-Type        [6]   6   Framed                    [2]
*Aug 22 10:23:53.558: RADIUS:  Session-Timeout     [27]  6   86400                     
*Aug 22 10:23:53.558: RADIUS:  Idle-Timeout        [28]  6   86400                     
*Aug 22 10:23:53.558: RADIUS:  Acct-Interim-Interva[85]  6   3600                      
*Aug 22 10:23:53.558: RADIUS:  Vendor, Cisco       [26]  37  
*Aug 22 10:23:53.558: RADIUS:   Cisco AVpair       [1]   31  "ip:ip-unnumbered=Loopback1245"
*Aug 22 10:23:53.558: RADIUS:  Vendor, Cisco       [26]  32  
*Aug 22 10:23:53.558: RADIUS:   Cisco AVpair       [1]   26  "ip:addr-pool=ippool1"
*Aug 22 10:23:53.558: RADIUS:  Vendor, Cisco       [26]  52  
*Aug 22 10:23:53.558: RADIUS:   Cisco AVpair       [1]   46  "ip:dns-servers=172.16.152.2  10.1.166.127"
*Aug 22 10:23:53.558: RADIUS(0001703E): Received from id 1645/11
*Aug 22 10:23:53.558: ppp11 PPP: Received LOGIN Response PASS
*Aug 22 10:23:53.558: ppp11 PPP: Phase is FORWARDING, Attempting Forward
*Aug 22 10:23:53.562: [11]PPPoE 11: State LCP_NEGOTIATION    Event SSS DISCONNECT
*Aug 22 10:23:53.562: ppp11 PPP DISC: Lower Layer disconnected
*Aug 22 10:23:53.562: ppp11 PPP: Sending Acct Event[Down] id[1703E]
*Aug 22 10:23:53.562: [11]PPPoE 11: AAA get dynamic attrs
*Aug 22 10:23:53.562: [11]PPPoE 11: AAA get dynamic attrs
*Aug 22 10:23:53.562: PPP: NET STOP send to AAA.
*Aug 22 10:23:53.562: ppp11 PAP: O AUTH-NAK id 37 len 27 msg is "Authentication failure"
*Aug 22 10:23:53.562: ppp11 LCP: O TERMREQ [Open] id 2 len 4
*Aug 22 10:23:53.562: ppp11 LCP: Event[CLOSE] State[Open to Closing]
*Aug 22 10:23:53.562: ppp11 PPP: Phase is TERMINATING
*Aug 22 10:23:53.562: [11]PPPoE 11: O PADT  R:aaaa.bbbb.6343 L:aaaa.bbbb.b8c0 Gi0/1/0
contiguous pak, size 60
*Aug 22 10:23:53.562: [11]PPPoE 11: Destroying  R:aaaa.bbbb.6343 L:aaaa.bbbb.b8c0 Gi0/1/0
*Aug 22 10:23:53.562: [11]PPPoE 11: AAA get dynamic attrs
*Aug 22 10:23:53.562: [11]PPPoE 11: AAA account stopped
*Aug 22 10:23:53.562: [11]PPPoE 11: Segment (SSS class): UNPROVISION
*Aug 22 10:23:53.562: ppp11 LCP: Event[CLOSE] State[Closing to Closing]
*Aug 22 10:23:53.562: ppp11 LCP: Event[DOWN] State[Closing to Initial]
*Aug 22 10:23:53.562: ppp11 PPP: Phase is DOWN
*Aug 22 10:23:53.566: PPPoE 11: I PADT  R:aaaa.bbbb.6343 L:aaaa.bbbb.b8c0 Gi0/1/0
contiguous pak, size 60
*Aug 22 10:23:56.702: AAA/BIND(00017040): Bind i/f

What am I doing wrong here? The router appears to accept the user, but then rejects the user and terminates the connection. Are there additional debug commands I should use?

Giuseppe Larosa · ‎08-22-2019

Hello Lionel,

I would not expect to see an IP address defined under gi0/1/0.

However, the Radius server is attempting to push some configuration statements to your router :

*Aug 22 10:23:53.558: RADIUS:   Cisco AVpair       [1]   31  "ip:ip-unnumbered=Loopback1245"
*Aug 22 10:23:53.558: RADIUS:  Vendor, Cisco       [26]  32  
*Aug 22 10:23:53.558: RADIUS:   Cisco AVpair       [1]   26  "ip:addr-pool=ippool1"

Can you check if the loop1245 and the the ip address pool ipool1 exists in your router configuration ?

Because if they do not exist this can be the root cause of your issue

Hope to help

Giuseppe

Lionel271 · ‎08-22-2019

Thank you, Giuseppe.

In fact, they do not exist. These attributes are from a different setup. I have created them now and assigned the IP address to the Loopback instead of the client interface.

I will test again tomorrow as the router is at a different site and I need to cable into the router.

AAA authentication test works in either case (whether Loopback/pool exists or not):

#test aaa group radius pppoetest@myrealm test new-code
User successfully authenticated

USER ATTRIBUTES

Framed-Protocol      0   1 [PPP]
addr                 0   255.255.255.254
netmask              0   255.255.255.255
Framed-MTU           0   1452 (0x5AC)
link-compression     0   4 [vj]
service-type         0   2 [Framed]
timeout              0   86400 (0x15180)
idletime             0   86400 (0x15180)
acct-interval        0   3600 (0xE10)
ip-unnumbered        0   "Loopback1245"
addr-pool            0   "ippool1"
dns-servers          0   "172.16.152.2  10.1.166.127"
noescape             0   True
autocmd              0   " ppp negotiate"