No IP on PPPoE clients by ASR1002

[netrunner]

Hello everybody,

we are experiencing a strange problem in our ASR1002 behaviour when a PPPoE client connects for AAA.

ASR1002 is a PPPoE server that checks credentials with radius. The clients authenticates correctly but then it does not receive any IP address.

How's possible? We have 31 other PPPoE clients that work ok.

ASR1k2#show subscriber session | inc andrea
519     Vi2.32       authen   Lterm       00:00:52 0      andrea.c*********
ASR-OF-TO#show ppp all | inc 2.32
Vi2.32       LCP+ CHAP+            LocalT   0.0.0.0         \
ASR1k2#

And this is the running-config

ASR1k2#show run
Building configuration...

Current configuration : 19451 bytes
!
! Last configuration change at 09:20:08 ITA Mon Sep 21 2020 by admin
! NVRAM config last updated at 09:58:27 ITA Sat Sep 19 2020 by admin
!
version 15.5
service timestamps debug datetime msec
service timestamps log datetime msec
service password-encryption
no platform punt-keepalive disable-kernel-core
!
hostname ASR1k2
!
boot-start-marker
boot-end-marker
!
!
vrf definition Mgmt-intf
 !
 address-family ipv4
 exit-address-family
 !
 address-family ipv6
 exit-address-family
!
logging buffered 10240 informational
!
aaa new-model
aaa session-mib disconnect
!
!
aaa group server radius hal-radius
 server name hal-radius1
 retransmit 2
 timeout 120
!
aaa group server radius hal-accounting1
 server name hal-accounting1
 retransmit 2
 timeout 120
!
aaa group server radius hal-accounting2
 server name hal-accounting2
 retransmit 2
 timeout 120
!
aaa authentication login default local
aaa authentication ppp default group hal-radius
aaa authorization exec default local
aaa authorization network default group hal-radius
aaa authorization subscriber-service default local group hal-radius
aaa accounting delay-start all
aaa accounting update periodic 10
aaa accounting network default start-stop broadcast group hal-radius group hal-accounting1 group hal-accounting2
!
!
!
!
aaa server radius dynamic-author
 client 10.5.0.4 server-key **********
 server-key *************
 auth-type any
!
aaa session-id unique
aaa policy interface-config allow-subinterface
clock timezone ITA 1 0
clock summer-time ITA recurring last Sun Mar 2:00 last Sun Oct 2:00
!
!
!
!
!
!
!
!
!
!
!


ip name-server **************

ip domain name **********.it
!
!
!
!
!
!
!
!
!
!
subscriber templating
!
multilink bundle-name authenticated
!
!
!
!
!
!
!
!
!
!
spanning-tree extend system-id
!
username admin privilege 15 password ***************
!
redundancy
 mode none
!
!
!
!
!
cdp run
!
!
!
!
bba-group pppoe global
 virtual-template 1
 sessions max limit 64000
 sessions per-vc limit 64000
 sessions per-mac limit 64000
 sessions per-vlan limit 64000 inner 64000
 sessions per-vc throttle 100 30 1800
 sessions per-mac throttle 100 30 1800
 sessions per-vlan throttle 100 30 1800
 sessions auto cleanup
!
!
!
interface Loopback1
 ip address 176.56.136.6 255.255.255.248
 ip ospf network point-to-point
!
interface Loopback2
 description management loopback
 ip address 10.5.92.252 255.255.255.255
!
interface Port-channel1
 no ip address
 no negotiation auto
!
interface Port-channel1.1
 description s694-c10 name.lastname1
 encapsulation dot1Q 694 second-dot1q 10
 pppoe enable group global
!
interface Port-channel1.2
 description s695-c21 name.lastname2
 encapsulation dot1Q 695 second-dot1q 21
 pppoe enable group global
!
interface Port-channel1.3
 description s694-c13 name.lastnam3
 encapsulation dot1Q 694 second-dot1q 13
 pppoe enable group global
!
interface Port-channel1.4
 description s272-c10 name.lastname4
 encapsulation dot1Q 272 second-dot1q 10
 pppoe enable group global

[other 50 Port channel]

interface Port-channel1.55
 description s487-c14 andrea.c********
 encapsulation dot1Q 487 second-dot1q 14
 pppoe enable group global
!
interface Port-channel2
 no ip address
 no negotiation auto
!
interface Port-channel2.1
 description uplink
 encapsulation dot1Q 192
 ip address 10.15.192.114 255.255.255.0
 ip nat outside
!
interface GigabitEthernet0/0/0
 no ip address
 negotiation auto
 channel-group 1 mode active
!
interface GigabitEthernet0/0/1
 no ip address
 negotiation auto
 channel-group 1 mode active
!
interface GigabitEthernet0/0/2
 no ip address
 negotiation auto
 channel-group 1 mode active
!
interface GigabitEthernet0/0/3
 no ip address
 negotiation auto
 channel-group 1 mode active
!
interface GigabitEthernet0/2/0
 no ip address
 shutdown
 negotiation auto
!
interface GigabitEthernet0/2/1
 no ip address
 shutdown
 negotiation auto
!
interface GigabitEthernet0/2/2
 no ip address
 shutdown
 negotiation auto
!
interface GigabitEthernet0/2/3
 no ip address
 shutdown
 negotiation auto
!
interface GigabitEthernet0/2/4
 no ip address
 negotiation auto
 channel-group 2 mode active
!
interface GigabitEthernet0/2/5
 no ip address
 negotiation auto
 channel-group 2 mode active
!
interface GigabitEthernet0/2/6
 no ip address
 negotiation auto
 channel-group 2 mode active
!
interface GigabitEthernet0/2/7
 no ip address
 negotiation auto
 channel-group 2 mode active
!
interface GigabitEthernet0
 vrf forwarding Mgmt-intf
 ip address 192.168.255.1 255.255.255.240
 negotiation auto
!
interface Virtual-Template1
 mtu 1492
 ip address 100.64.0.1 255.255.128.0
 ip nat inside
 no logging event link-status
 peer default ip address pool DefaultPool
 keepalive 60
 ppp mtu adaptive
 ppp authentication chap pap
 ppp ipcp dns 8.8.8.8
!
router ospf 1
 router-id 10.15.192.114
 log-adjacency-changes detail
 redistribute connected subnets
 redistribute static subnets
 network 10.15.192.0 0.0.0.255 area 0
 network 100.64.0.0 0.0.127.255 area 0.0.0.37
 network 176.******* 0.0.****** area 0.0.0.37
!
ip local pool DefaultPool 100.64.0.2 100.64.127.254
ip nat pool of-natpool 176.****** 176.******* netmask **********
ip nat inside source route-map nat-of pool of-natpool overload
ip forward-protocol nd
!
no ip http server
no ip http secure-server
ip tftp source-interface GigabitEthernet0
ip ssh version 2
!
ip access-list standard ssh-access
 permit *********
 permit ********* 0.0.0.31
 permit ********* 0.255.255.255
 deny   any log
!
ip radius source-interface Loopback2
!
access-list 155 permit ip 100.64.0.0 0.0.127.255 any log
!
route-map nat-of permit 10
 match ip address 155
!
radius-server attribute 8 include-in-access-req
radius-server attribute 32 include-in-access-req
radius-server attribute 32 include-in-accounting-req
radius-server attribute 30 original-called-number
radius-server attribute 4 10.15.192.114
radius-server attribute 31 mac format one-byte delimiter colon
radius-server attribute 31 send nas-port-detail mac-only
radius-server dead-criteria time 120 tries 3
radius-server deadtime 2
!
radius server hal-radius1
 address ipv4 10.******* auth-port 1812 acct-port 1813
 key *******
!
radius server hal-accounting1
 address ipv4 10.******* auth-port 1812 acct-port 1813
 key *******
!
radius server hal-accounting2
 address ipv4 10.******* auth-port 1812 acct-port 1813
 key *******
!
radius server hal-test
 address ipv4 10.******* auth-port 1812 acct-port 1813
 key *******
!
!
control-plane
!
end

Can you help us with this?

[balaji.bandi]

If the issue with only 1 client, then i will verify the config with that client not working vs working.

create or duplicate same config as working one and test it, if this step already done, still not working.

we need to enable debug and understand what went wrong,

https://www.cisco.com/c/en/us/support/docs/long-reach-ethernet-lre-digital-subscriber-line-xdsl/asymmetric-digital-subscriber-line-adsl/71119-adslguide-pppoe-dynmcstep.html

[netrunner · Accepted solution]

We checked and the issue is not always with the same client. This is a debug pppoe events just after a clear subscriber session with IP 0.0.0.0

Sep 21 09:04:39.067: [522]PPPoE 2571: Segment (SSS class): UNBOUND
Sep 21 09:04:39.072: [522]PPPoE 2571: State LOCALLY_TERMINATED Event SSS DISCONNECT
Sep 21 09:04:39.072: dyn_attrs->xmit_rate: -294967296 dyn_attrs->rcv_rate: -294967296
Sep 21 09:04:39.072: [522]PPPoE 2571: AAA get dynamic attrs
Sep 21 09:04:39.073: [522]PPPoE 2571: O PADT R:744d.28a6.daa5 L:1c6a.7aa2.c2c0 Po1.52
Sep 21 09:04:39.073: [522]PPPoE 2571: Destroying R:744d.28a6.daa5 L:1c6a.7aa2.c2c0 100 Po1.52
Sep 21 09:04:39.073: PPPoE: Returning Vaccess Virtual-Access2.32
Sep 21 09:04:39.076: [522]PPPoE 2571: AAA account stopped
Sep 21 09:04:39.076: [522]PPPoE 2571: Vi2.32 Block vaccess from being freed.
Sep 21 09:04:39.079: [522]PPPoE 2571: Segment (SSS class): UNPROVISION
Sep 21 09:04:39.090: PPPoE 2571: I PADT R:744d.28a6.daa5 L:1c6a.7aa2.c2c0 100 Po1.52
Sep 21 09:04:39.758: PPPoE 0: I PADI R:744d.28a6.daa5 L:ffff.ffff.ffff 100 Po1.52
Sep 21 09:04:39.758: Service tag: NULL Tag
Sep 21 09:04:39.758: PPPoE 0: O PADO, R:1c6a.7aa2.c2c0 L:744d.28a6.daa5 100 Po1.52
Sep 21 09:04:39.758: Service tag: NULL Tag
Sep 21 09:04:39.770: PPPoE 0: I PADR R:744d.28a6.daa5 L:1c6a.7aa2.c2c0 100 Po1.52
Sep 21 09:04:39.770: Service tag: NULL Tag
Sep 21 09:04:39.770: PPPoE : encap string prepared
Sep 21 09:04:39.770: [523]PPPoE 2572: Access IE handle allocated
Sep 21 09:04:39.770: [523]PPPoE 2572: AAA get retrieved attrs
Sep 21 09:04:39.770: [523]PPPoE 2572: AAA get nas port details
Sep 21 09:04:39.770: dyn_attrs->xmit_rate: -294967296 dyn_attrs->rcv_rate: -294967296
Sep 21 09:04:39.770: [523]PPPoE 2572: AAA get dynamic attrs
Sep 21 09:04:39.770: [523]PPPoE 2572: AAA unique ID A82 allocated
Sep 21 09:04:39.770: [523]PPPoE 2572: AAA method list set
Sep 21 09:04:39.771: [523]PPPoE 2572: Service request sent to SSS
Sep 21 09:04:39.771: [523]PPPoE 2572: Created, Service: None R:1c6a.7aa2.c2c0 L:744d.28a6.daa5 100 Po1.52
Sep 21 09:04:39.772: [523]PPPoE 2572: State NAS_PORT_POLICY_INQUIRY Event SSS MORE KEYS
Sep 21 09:04:39.772: [523]PPPoE 2572: data path set to PPP
Sep 21 09:04:39.772: [523]PPPoE 2572: Segment (SSS class): PROVISION
Sep 21 09:04:39.772: [523]PPPoE 2572: State PROVISION_PPP Event SSM PROVISIONED
Sep 21 09:04:39.772: [523]PPPoE 2572: O PADS R:744d.28a6.daa5 L:1c6a.7aa2.c2c0 Po1.52
Sep 21 09:04:39.938: [523]PPPoE 2572: State LCP_NEGOTIATION Event SSS CONNECT LOCAL
Sep 21 09:04:39.945: [523]PPPoE 2572: Segment (SSS class): UPDATED
Sep 21 09:04:39.945: [523]PPPoE 2572: Segment (SSS class): BOUND
Sep 21 09:04:39.945: [523]PPPoE 2572: data path set to Virtual Acess
Sep 21 09:04:39.952: [523]PPPoE 2572: State LCP_NEGOTIATION Event SSM UPDATED
Sep 21 09:04:39.960: dyn_attrs->xmit_rate: -294967296 dyn_attrs->rcv_rate: -294967296
Sep 21 09:04:39.961: [523]PPPoE 2572: AAA get dynamic attrs
Sep 21 09:04:39.961: [523]PPPoE 2572: State PTA_BINDING Event STATIC BIND RESPONSE
Sep 21 09:04:39.961: [523]PPPoE 2572: Connected PTA

This is is a debug pppoe packets just after clearing the session

Sep 21 09:09:22.414: [523]PPPoE 2572: O PADT  R:744d.28a6.daa5 L:1c6a.7aa2.c2c0 Po1.52
contiguous pak, size 64
         74 4D 28 A6 DA A5 1C 6A 7A A2 C2 C0 81 00 00 64
         81 00 00 16 88 63 11 A7 0A 0C 00 00 00 00 00 00
         00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
         00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Sep 21 09:09:22.432: PPPoE 2572: I PADT  R:744d.28a6.daa5 L:1c6a.7aa2.c2c0 100 Po1.52
contiguous pak, size 64
         1C 6A 7A A2 C2 C0 74 4D 28 A6 DA A5 81 00 00 64
         81 00 00 16 88 63 11 A7 0A 0C 00 00 00 00 00 00
         00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
         00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Sep 21 09:09:23.910: PPPoE 0: I PADI  R:744d.28a6.daa5 L:ffff.ffff.ffff 100 Po1.52
contiguous pak, size 40
         FF FF FF FF FF FF 74 4D 28 A6 DA A5 81 00 00 64
         81 00 00 16 88 63 11 09 00 00 00 0C 01 03 00 04
         42 00 B6 00 01 01 00 00
Sep 21 09:09:23.910: PPPoE 0: O PADO, R:1c6a.7aa2.c2c0 L:744d.28a6.daa5 100 Po1.52
Sep 21 09:09:23.910:  Service tag: NULL Tag
contiguous pak, size 73
         74 4D 28 A6 DA A5 1C 6A 7A A2 C2 C0 81 00 00 64
         81 00 00 16 88 63 11 07 00 00 00 2D 01 03 00 04
         42 00 B6 00 01 01 00 00 01 02 00 09 41 53 52 2D
         4F 46 2D 54 4F 01 04 00 10 B3 18 93 68 F8 C7 97
         3B 43 C4 8C FC DA E6 96 ...
Sep 21 09:09:23.922: PPPoE 0: I PADR  R:744d.28a6.daa5 L:1c6a.7aa2.c2c0 100 Po1.52
contiguous pak, size 60
         1C 6A 7A A2 C2 C0 74 4D 28 A6 DA A5 81 00 00 64
         81 00 00 16 88 63 11 19 00 00 00 20 01 03 00 04
         43 00 B6 00 01 01 00 00 01 04 00 10 B3 18 93 68
         F8 C7 97 3B 43 C4 8C FC DA E6 96 1C
Sep 21 09:09:23.924: [527]PPPoE 2573: O PADS  R:744d.28a6.daa5 L:1c6a.7aa2.c2c0 Po1.52
contiguous pak, size 64
         74 4D 28 A6 DA A5 1C 6A 7A A2 C2 C0 81 00 00 64
         81 00 00 16 88 63 11 65 0A 0D 00 20 01 03 00 04
         43 00 B6 00 01 01 00 00 01 04 00 10 B3 18 93 68
         F8 C7 97 3B 43 C4 8C FC DA E6 96 1C 00 00 00 00

No effect in clearing session, same problem again...

[netrunner · Accepted solution]

Solved! The problem was that in Virtual-Template1 there was a 100.64. ip address, so after the 32nd PPPoE client, the ASR router logged "Too many IP on subnet 100.64.0.0"

Solved by using ip unnumbered Loopback3, with Loopback3 ip address 100.64.0.1