Buy or Renew
Buy or Renew
Cisco + Splunk: It’s a new day for your data. Learn more.
 
cancel
Turn on suggestions
Auto-suggest helps you quickly narrow down your search results by suggesting possible matches as you type.
Showing results for 
Search instead for 
Did you mean: 
cancel
Start a conversation
1041
Views
0
Helpful
1
Replies

ASR9001-BNG - Can't bring up PPPoE session when using certain RADIUS attributes

bpbp-heyoo
Level 1
Level 1

‎06-17-2019 10:34 PM - edited ‎06-18-2019 12:05 AM

Hi everyone

I have an issue where if I use either Framed-Pool, Framed-IPv6-Pool or Delegated-IPv6-Prefix my PPPoE sessions get stuck in state "CD" on a ASR-9001 running 6.1.4

If I remove those from the RADIUS profile I can bring up a IPv4 session fine. I can't seem to see any problems in the debug log except for the "Trigger 9" error. Please help me debug this further.

 

Thanks

 

my config

Tue Jun 18 15:07:35.714 AEST
pppoe bba-group global
sessions mac limit 2
!

interface Loopback1
ipv4 address [ip] [subnet]
ipv6 address 2001:DB8::12/128
ipv6 enable
!

interface Bundle-Ether10.3000
ipv4 point-to-point
ipv6 enable
service-policy type control subscriber PPP_PM
pppoe enable bba-group global
bundle load-balancing hash dst-ip
encapsulation ambiguous dot1q 3000-3999 second-dot1q any
!

interface TenGigE0/0/2/0
bundle id 10 mode active
!
interface TenGigE0/0/2/1
bundle id 10 mode active
!

policy-map pm-egress-50
class class-default
service-policy default
shape average 50 mbps 1 us
!
end-policy-map
!
policy-map default
class class-default
set dscp default
!
end-policy-map
!

dynamic-template
type ppp PPP_TPL
ppp authentication pap chap
keepalive 60 2
ppp ipcp dns ip1 ip2 
ppp ipv6cp passive
accounting aaa list default type session periodic-interval 5 dual-stack-delay 5
ipv4 verify unicast source reachable-via rx
ipv4 unnumbered Loopback1
ipv6 nd other-config-flag
ipv6 mtu 1492
ipv6 enable
ipv6 unreachables disable
!
!

pool vrf default ipv4 PPPoE_Pool4
address-range 10.20.34.1 10.20.34.254
!
pool vrf default ipv6 PPPoE_Pool6
prefix-length 64
prefix-range 2001:DB8:af00:c000:: 2001:DB8:af00:ffff::
!

policy-map type control subscriber PPP_PM
event session-start match-first
class type control subscriber PPP do-until-failure
10 activate dynamic-template PPP_TPL
!
!
event session-activate match-first
class type control subscriber PPP do-until-failure
10 authenticate aaa list default
!
!
end-policy-map
!

RP/0/RSP0/CPU0:Jun 18 15:04:06.918 AEST: pppoe_ma[393]: Bundle-Ether10.3000: I dst ffff.ffff.ffff src 18f1.45ce.3d64: len 55 0x1109000000310105002100000de9010f41564330303030383535303033313881040000584882040000d6d70103000400a7f03801010000
RP/0/RSP0/CPU0:Jun 18 15:04:06.918 AEST: pppoe_ma[393]: [PADI-Recv]: Bundle-Ether10.3000 peer-mac 18f1.45ce.3d64
RP/0/RSP0/CPU0:Jun 18 15:04:06.918 AEST: pppoe_ma[393]: [PADI-Recv]: vlan-id-outer 3215 vlan-id-inner 3914
RP/0/RSP0/CPU0:Jun 18 15:04:06.918 AEST: pppoe_ma[393]: [PADI-Recv]: Service-name:
RP/0/RSP0/CPU0:Jun 18 15:04:06.918 AEST: pppoe_ma[393]: [PADI-Recv]: Circuit-id: AVC000085500318
RP/0/RSP0/CPU0:Jun 18 15:04:06.918 AEST: pppoe_ma[393]: [PADI-Recv]: Host-uniq: 00a7f038
RP/0/RSP0/CPU0:Jun 18 15:04:06.918 AEST: pppoe_ma[393]: [PADI-Recv]: DSL Actual Up: 22600
RP/0/RSP0/CPU0:Jun 18 15:04:06.918 AEST: pppoe_ma[393]: [PADI-Recv]: DSL Actual Down: 54999
RP/0/RSP0/CPU0:Jun 18 15:04:06.918 AEST: pppoe_ma[393]: Bundle-Ether10.3000: O dst 18f1.45ce.3d64 src f87b.201b.c3eb: len 37 0x11070000001f0103000400a7f038010100000102000f45512d4153522d393030312d4e424e
RP/0/RSP0/CPU0:Jun 18 15:04:06.918 AEST: pppoe_ma[393]: [PADO-Sent]: Bundle-Ether10.3000 peer-mac 18f1.45ce.3d64
RP/0/RSP0/CPU0:Jun 18 15:04:06.919 AEST: pppoe_ma[393]: [PADO-Sent]: vlan-id-outer 3215 vlan-id-inner 3914
RP/0/RSP0/CPU0:Jun 18 15:04:06.930 AEST: pppoe_ma[393]: Bundle-Ether10.3000: I dst f87b.201b.c3eb src 18f1.45ce.3d64: len 55 0x1119000000310105002100000de9010f41564330303030383535303033313881040000584882040000d6d7010100000103000400a7f038
RP/0/RSP0/CPU0:Jun 18 15:04:06.930 AEST: pppoe_ma[393]: [PADR-Recv]: Bundle-Ether10.3000 peer-mac 18f1.45ce.3d64
RP/0/RSP0/CPU0:Jun 18 15:04:06.930 AEST: pppoe_ma[393]: [PADR-Recv]: vlan-id-outer 3215 vlan-id-inner 3914
RP/0/RSP0/CPU0:Jun 18 15:04:06.930 AEST: pppoe_ma[393]: [PADR-Recv]: Service-name:
RP/0/RSP0/CPU0:Jun 18 15:04:06.930 AEST: pppoe_ma[393]: [PADR-Recv]: Circuit-id: AVC000085500318
RP/0/RSP0/CPU0:Jun 18 15:04:06.930 AEST: pppoe_ma[393]: [PADR-Recv]: Host-uniq: 00a7f038
RP/0/RSP0/CPU0:Jun 18 15:04:06.930 AEST: pppoe_ma[393]: [PADR-Recv]: DSL Actual Up: 22600
RP/0/RSP0/CPU0:Jun 18 15:04:06.930 AEST: pppoe_ma[393]: [PADR-Recv]: DSL Actual Down: 54999
RP/0/RSP0/CPU0:Jun 18 15:04:06.930 AEST: pppoe_ma[393]: Session: Bundle-Ether10.3000: Initializing new session
RP/0/RSP0/CPU0:Jun 18 15:04:06.930 AEST: pppoe_ma[393]: Session: Creating and inserting a new session idb on parent interface Bundle-Ether10.3000, with session id 43
RP/0/RSP0/CPU0:Jun 18 15:04:06.930 AEST: pppoe_ma[393]: Session: Successfully added new session idb to database of parent Bundle-Ether10.3000. Parent session IDB count = 1
RP/0/RSP0/CPU0:Jun 18 15:04:06.930 AEST: pppoe_ma[393]: Session: Queuing interface create on parent interface Bundle-Ether10.3000, with session id 43
LC/0/0/CPU0:Jun 18 15:04:07.019 AEST: pppoe_ea[317]: Interface: 0x000061e0: Creating and inserting a new intf idb
LC/0/0/CPU0:Jun 18 15:04:07.019 AEST: pppoe_ea[317]: Interface: 0x000061e0: Successfully added new intf idb to database
LC/0/0/CPU0:Jun 18 15:04:07.019 AEST: pppoe_ea[317]: Interface: 0x000061e0: INTF CREATE received
LC/0/0/CPU0:Jun 18 15:04:07.020 AEST: pppoe_ea[317]: Interface: 0x000061e0: INTF CREATE(1), idb lookups/creates completed successfully
LC/0/0/CPU0:Jun 18 15:04:07.020 AEST: pppoe_ea[317]: Interface 0x61E0 status is 0 - mark to skip rollback
LC/0/0/CPU0:Jun 18 15:04:07.020 AEST: pppoe_ea[317]: Set resource consumption to 1 for batch
LC/0/0/CPU0:Jun 18 15:04:07.022 AEST: pppoe_ea[317]: Need a total of 2 TCAM indexes
LC/0/0/CPU0:Jun 18 15:04:07.022 AEST: pppoe_ea[317]: Need 1 TCAM indexes for NP #0
LC/0/0/CPU0:Jun 18 15:04:07.022 AEST: pppoe_ea[317]: Allocated memory to hold 1 TCAM indexes for NP #0
LC/0/0/CPU0:Jun 18 15:04:07.022 AEST: pppoe_ea[317]: Need 1 TCAM indexes for NP #1
LC/0/0/CPU0:Jun 18 15:04:07.022 AEST: pppoe_ea[317]: Allocated memory to hold 1 TCAM indexes for NP #1
LC/0/0/CPU0:Jun 18 15:04:07.022 AEST: pppoe_ea[317]: Allocated TCAM 0x2 (0) for NP 0
LC/0/0/CPU0:Jun 18 15:04:07.022 AEST: pppoe_ea[317]: Allocated 1 TCAMs for NP #0
LC/0/0/CPU0:Jun 18 15:04:07.022 AEST: pppoe_ea[317]: Allocated TCAM 0x2 (0) for NP 1
LC/0/0/CPU0:Jun 18 15:04:07.022 AEST: pppoe_ea[317]: Allocated 1 TCAMs for NP #1
LC/0/0/CPU0:Jun 18 15:04:07.022 AEST: pppoe_ea[317]: Set resource consumption to 2 for batch
LC/0/0/CPU0:Jun 18 15:04:07.022 AEST: pppoe_ea[317]: Calculated 14 features needed for batch
LC/0/0/CPU0:Jun 18 15:04:07.022 AEST: pppoe_ea[317]: Storing 14 features for 1 interfaces
LC/0/0/CPU0:Jun 18 15:04:07.023 AEST: pppoe_ea[317]: Found tcam index 0x2 for index0 on np 0
LC/0/0/CPU0:Jun 18 15:04:07.023 AEST: pppoe_ea[317]: Found tcam index 0x2 for index0 on np 1
LC/0/0/CPU0:Jun 18 15:04:07.023 AEST: pppoe_ea[317]: Passed sub_uidb_index to xlate is 0x2
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: Passed sub_uidb_index to xlate is 0x2
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw key entry 0 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw key entry 1 = 0xB
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw key entry 2 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw key entry 3 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw key entry 4 = 0x2B
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw key entry 5 = 0x1
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw Result entry 0 = 0xF
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw Result entry 1 = 0x8F
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw Result entry 2 = 0xAC
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw Result entry 3 = 0xF4
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw Result entry 4 = 0x18
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw Result entry 5 = 0xF1
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw Result entry 6 = 0x45
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw Result entry 7 = 0xCE
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw Result entry 8 = 0x3D
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw Result entry 9 = 0x64
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw Result entry 10 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw Result entry 11 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw Result entry 12 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw Result entry 13 = 0x2
LC/0/0/CPU0:Jun 18 15:04:07.024 AEST: pppoe_ea[317]: PRM Hw Result entry 14 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.025 AEST: pppoe_ea[317]: PRM Hw Result entry 15 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.025 AEST: pppoe_ea[317]: PRM Hw Result entry 16 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.025 AEST: pppoe_ea[317]: PRM Hw Result entry 17 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.025 AEST: pppoe_ea[317]: PRM Hw Result entry 18 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.025 AEST: pppoe_ea[317]: PRM Hw Result entry 19 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.025 AEST: pppoe_ea[317]: PRM Hw Result entry 20 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.025 AEST: pppoe_ea[317]: PRM Hw Result entry 21 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.025 AEST: pppoe_ea[317]: PRM Hw Result entry 22 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.025 AEST: pppoe_ea[317]: PRM Hw Result entry 23 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.025 AEST: pppoe_ea[317]: PRM Hw Result entry 24 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.025 AEST: pppoe_ea[317]: PRM Hw Result entry 25 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.025 AEST: pppoe_ea[317]: PRM Hw Result entry 26 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.025 AEST: pppoe_ea[317]: PRM Hw Result entry 27 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.025 AEST: pppoe_ea[317]: PRM Hw Result entry 28 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.025 AEST: pppoe_ea[317]: PRM Hw Result entry 29 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.025 AEST: pppoe_ea[317]: PRM Hw Result entry 30 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.026 AEST: pppoe_ea[317]: PRM Hw Result entry 31 = 0x0
LC/0/0/CPU0:Jun 18 15:04:07.026 AEST: pppoe_ea[317]: Created table entry(s) for index0, session index 0x2b, sub-parent's uidb index 0xb, entry count 2.
LC/0/0/CPU0:Jun 18 15:04:07.026 AEST: pppoe_ea[317]: Set resource consumption to 3 for batch
LC/0/0/CPU0:Jun 18 15:04:07.026 AEST: pppoe_ea[317]: Program session table for batch COMPLETE, sending the last msg, index0.
LC/0/0/CPU0:Jun 18 15:04:07.027 AEST: pppoe_ea[317]: Stored session ID 43 parent uidb index 0Xb for interface 0x61e0
LC/0/0/CPU0:Jun 18 15:04:07.027 AEST: pppoe_ea[317]: Set resource consumption to 4 for batch
LC/0/0/CPU0:Jun 18 15:04:07.027 AEST: pppoe_ea[317]: Freeing TCAM info
LC/0/0/CPU0:Jun 18 15:04:07.027 AEST: pppoe_ea[317]: Interface 0x61e0 marked as clean
LC/0/0/CPU0:Jun 18 15:04:07.027 AEST: pppoe_ea[317]: No rollback required - all interfaces created successfully
LC/0/0/CPU0:Jun 18 15:04:07.027 AEST: pppoe_ea[317]: Interface: 0x000061e0: INTF CREATE(2), Hardware programming completed successfully
LC/0/0/CPU0:Jun 18 15:04:07.028 AEST: pppoe_ea[317]: Interface: 0x000061e0: INTF CREATE(3), IMC interface create completed successfully
RP/0/RSP0/CPU0:Jun 18 15:04:07.036 AEST: pppoe_ma[393]: Session: 0x00000000: Received interface create cb: No error
RP/0/RSP0/CPU0:Jun 18 15:04:07.036 AEST: pppoe_ma[393]: Session: Bundle-Ether10.3000.pppoe43: Inserting a session idb into global database
RP/0/RSP0/CPU0:Jun 18 15:04:07.036 AEST: pppoe_ma[393]: Session: Bundle-Ether10.3000.pppoe43: Successfully added new session idb to global database. Session IDB count = 1
RP/0/RSP0/CPU0:Jun 18 15:04:07.037 AEST: pppoe_ma[393]: Session: Bundle-Ether10.3000.pppoe43: Received MTU notification, with MTU actual 1500
RP/0/RSP0/CPU0:Jun 18 15:04:07.051 AEST: pppoe_ma[393]: Session: Received AAA batch start notication
RP/0/RSP0/CPU0:Jun 18 15:04:07.051 AEST: pppoe_ma[393]: Session: Bundle-Ether10.3000.pppoe43: Received AAA Session Create cb: No error
RP/0/RSP0/CPU0:Jun 18 15:04:07.052 AEST: pppoe_ma[393]: Session: Received AAA batch end notication
RP/0/RSP0/CPU0:Jun 18 15:04:07.217 AEST: pppoe_ma[393]: Session: Received SubDB batch start notication
RP/0/RSP0/CPU0:Jun 18 15:04:07.217 AEST: pppoe_ma[393]: Session: Bundle-Ether10.3000.pppoe43: Received Activate Config cb: No error
RP/0/RSP0/CPU0:Jun 18 15:04:07.218 AEST: pppoe_ma[393]: Session: Received SubDB batch end notication
RP/0/RSP0/CPU0:Jun 18 15:04:07.318 AEST: pppoe_ma[393]: Session: Bundle-Ether10.3000.pppoe43: Interface ready call succeeded
RP/0/RSP0/CPU0:Jun 18 15:04:07.318 AEST: pppoe_ma[393]: [PADS-Sent]: Bundle-Ether10.3000 peer-mac 18f1.45ce.3d64
RP/0/RSP0/CPU0:Jun 18 15:04:07.318 AEST: pppoe_ma[393]: [PADS-Sent]: vlan-id-outer 3215 vlan-id-inner 3914
RP/0/RSP0/CPU0:Jun 18 15:04:07.318 AEST: pppoe_ma[393]: Bundle-Ether10.3000: O dst 18f1.45ce.3d64 src f87b.201b.c3eb: len 18 0x1165002b000c010100000103000400a7f038
RP/0/RSP0/CPU0:Jun 18 15:04:10.329 AEST: radiusd[1141]: Received request [handle 0x4a1eb210] with server-group : default
RP/0/RSP0/CPU0:Jun 18 15:04:10.329 AEST: radiusd[1141]: Building header for the Authentication request
RP/0/RSP0/CPU0:Jun 18 15:04:10.330 AEST: radiusd[1141]: radius_get_prfrd_srvr_info: Retrive Preferred Server info from attr list
RP/0/RSP0/CPU0:Jun 18 15:04:10.330 AEST: radiusd[1141]: radius_get_prfrd_srvr_info: Preferred server handle is set to NULL
RP/0/RSP0/CPU0:Jun 18 15:04:10.330 AEST: radiusd[1141]: (handle_nas_req) Couldn't retrive the preferred server info
RP/0/RSP0/CPU0:Jun 18 15:04:10.330 AEST: radiusd[1141]: Trying to find the first radius server to use.
RP/0/RSP0/CPU0:Jun 18 15:04:10.330 AEST: radiusd[1141]: Created transaction_id (D000002C) for server group A6000000
RP/0/RSP0/CPU0:Jun 18 15:04:10.330 AEST: radiusd[1141]: Copying remote address 192.168.10.206
RP/0/RSP0/CPU0:Jun 18 15:04:10.330 AEST: radiusd[1141]: Copying remote address 192.168.10.206
RP/0/RSP0/CPU0:Jun 18 15:04:10.330 AEST: radiusd[1141]: Remote address 192.168.10.206
RP/0/RSP0/CPU0:Jun 18 15:04:10.330 AEST: radiusd[1141]: Picking the rad id 20:0 sockfd 0x4A007484
RP/0/RSP0/CPU0:Jun 18 15:04:10.330 AEST: radiusd[1141]: rctx 0x4a20e320 added successfully
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Send Access-Request to 192.168.10.206:1820 id 20, len 491
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: authenticator 6A 4C 55 46 41 74 4C 09 - A7 5A EE F3 59 EF C8 23
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Vendor,Cisco [26] 41
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Cisco AVpair [1] 35 client-mac-address=18f1.45ce.3d64
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Vendor,Unknown [26] 23 Unsupported[1] 17
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Vendor,Cisco [26] 38
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Cisco AVpair [1] 32 circuit-id-tag=AVC000085500318
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Acct-Session-Id [44] 10 00000180
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: NAS-Port-Id [87] 18 0/0/10/3914.3215
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Vendor,Cisco [26] 24
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: cisco-nas-port [2] 18 0/0/10/3914.3215
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: User-Name [1] 14 username
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Service-Type [6] 6 Framed[0]
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: User-Password [2] 18 *
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: AAA Unsupported Attr: user-maxlinks [196] 6
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Vendor,Cisco [26] 33
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Cisco AVpair [1] 27 connect-progress=LCP Open
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Vendor,Cisco [26] 30
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Cisco AVpair [1] 24 connect-rx-speed=22600
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Vendor,Cisco [26] 30
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Cisco AVpair [1] 24 connect-tx-speed=54999
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Vendor,Unknown [26] 12 Unsupported[129] 6
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Vendor,Cisco [26] 39
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Cisco AVpair [1] 33 actual-data-rate-upstream=22600
RP/0/RSP0/CPU0:Jun 18 15:04:10.331 AEST: radiusd[1141]: RADIUS: Vendor,Unknown [26] 12 Unsupported[130] 6
RP/0/RSP0/CPU0:Jun 18 15:04:10.332 AEST: radiusd[1141]: RADIUS: Vendor,Cisco [26] 41
RP/0/RSP0/CPU0:Jun 18 15:04:10.332 AEST: radiusd[1141]: RADIUS: Cisco AVpair [1] 35 actual-data-rate-downstream=54999
RP/0/RSP0/CPU0:Jun 18 15:04:10.332 AEST: radiusd[1141]: RADIUS: Framed-Protocol [7] 6 PPP[0]
RP/0/RSP0/CPU0:Jun 18 15:04:10.332 AEST: radiusd[1141]: RADIUS: NAS-Port-Type [61] 6 Virtual PPPoEoQinQ[0]
RP/0/RSP0/CPU0:Jun 18 15:04:10.332 AEST: radiusd[1141]: RADIUS: Called-Station-Id [30] 17 AVC000085500318
RP/0/RSP0/CPU0:Jun 18 15:04:10.332 AEST: radiusd[1141]: RADIUS: Event-Timestamp [55] 6 1560834250
RP/0/RSP0/CPU0:Jun 18 15:04:10.332 AEST: radiusd[1141]: RADIUS: Nas-Identifier [32] 17 EQ-ASR-9001
RP/0/RSP0/CPU0:Jun 18 15:04:10.332 AEST: radiusd[1141]: RADIUS: NAS-IP-Address [4] 6 10.10.100.2
RP/0/RSP0/CPU0:Jun 18 15:04:10.332 AEST: radiusd[1141]: RADIUS: NAS-IPv6-Address [95] 18 ::
RP/0/RSP0/CPU0:Jun 18 15:04:10.332 AEST: radiusd[1141]: Got global deadtime 0
RP/0/RSP0/CPU0:Jun 18 15:04:10.332 AEST: radiusd[1141]: Using global deadtime = 0 sec
RP/0/RSP0/CPU0:Jun 18 15:04:10.332 AEST: radiusd[1141]: Start timer thread rad_ident 20 remote_port 1820 remote_addr 192.168.10.206, socket 1241543812 rctx 0x4a20e320
RP/0/RSP0/CPU0:Jun 18 15:04:10.332 AEST: radiusd[1141]: Successfully sent packet and started timeout handler for rctx 0x4a20e320
RP/0/RSP0/CPU0:Jun 18 15:04:10.349 AEST: radiusd[1141]: Radius packet decryption complete with rc = 0
RP/0/RSP0/CPU0:Jun 18 15:04:10.349 AEST: radiusd[1141]: RADIUS: Received from id 20 192.168.10.206:1820, Access-Accept, len 119
RP/0/RSP0/CPU0:Jun 18 15:04:10.349 AEST: radiusd[1141]: RADIUS: authenticator E8 4E AA 7C A2 A2 84 AC - B9 87 F7 B3 E5 B5 65 9B
RP/0/RSP0/CPU0:Jun 18 15:04:10.349 AEST: radiusd[1141]: RADIUS: Delegated-IPv6-Prefix[123] 20 2001:DB8:b000:100::/56
RP/0/RSP0/CPU0:Jun 18 15:04:10.349 AEST: radiusd[1141]: RADIUS: Framed-IPv6-Pool [100] 13 PPPoE_Pool6
RP/0/RSP0/CPU0:Jun 18 15:04:10.349 AEST: radiusd[1141]: RADIUS: Framed-IP-Address [8] 6 ipv4_address
RP/0/RSP0/CPU0:Jun 18 15:04:10.350 AEST: radiusd[1141]: RADIUS: Vendor,Cisco [26] 42
RP/0/RSP0/CPU0:Jun 18 15:04:10.350 AEST: radiusd[1141]: RADIUS: Cisco AVpair [1] 36 ip:sub-qos-policy-out=pm-egress-50
RP/0/RSP0/CPU0:Jun 18 15:04:10.350 AEST: radiusd[1141]: RADIUS: Service-Type [6] 6 Framed[0]
RP/0/RSP0/CPU0:Jun 18 15:04:10.350 AEST: radiusd[1141]: RADIUS: Framed-Protocol [7] 6 PPP[0]
RP/0/RSP0/CPU0:Jun 18 15:04:10.350 AEST: radiusd[1141]: RADIUS: Framed-IP-Netmask [9] 6 255.255.255.255
RP/0/RSP0/CPU0:Jun 18 15:04:10.350 AEST: radiusd[1141]: Freeing server group transaction_id (D000002C)
RP/0/RSP0/CPU0:Jun 18 15:04:10.350 AEST: radiusd[1141]: pack_length = 119 radius_len = 119
RP/0/RSP0/CPU0:Jun 18 15:04:10.350 AEST: radiusd[1141]: Calling app inf callback
RP/0/RSP0/CPU0:Jun 18 15:04:10.350 AEST: radiusd[1141]: rad_nas_reply_to_client: Received response from id : 20,packet type 2
RP/0/RSP0/CPU0:Jun 18 15:04:10.350 AEST: radiusd[1141]: (rad_nas_reply_to_client) Successfully decoded the response No error: PASS
RP/0/RSP0/CPU0:Jun 18 15:04:10.350 AEST: radiusd[1141]: (rad_nas_reply_to_client) Successfully stored the preferred server info
RP/0/RSP0/CPU0:Jun 18 15:04:10.350 AEST: radiusd[1141]: (rad_nas_reply_to_client) Send response back to client
RP/0/RSP0/CPU0:EQ-ASR-9001-NBN#no debug allRP/0/RSP0/CPU0:Jun 18 15:04:40.394 AEST: pppoe_ma[393]: Bundle-Ether10.3000: I dst f87b.201b.c3eb src 18f1.45ce.3d64: len 55 0x11a7002b00310105002100000de9010f41564330303030383535303033313881040000584882040000d6d70103000400a7f03801010000
RP/0/RSP0/CPU0:Jun 18 15:04:40.394 AEST: pppoe_ma[393]: [PADT-Recv]: Bundle-Ether10.3000 peer-mac 18f1.45ce.3d64
RP/0/RSP0/CPU0:Jun 18 15:04:40.394 AEST: pppoe_ma[393]: [PADT-Recv]: vlan-id-outer 3215 vlan-id-inner 3914
RP/0/RSP0/CPU0:Jun 18 15:04:40.394 AEST: pppoe_ma[393]: Session: [ERROR] Bundle-Ether10.3000.pppoe43: Session being cleaned up, trigger 9

 

This is what the subscriber session looks like:

Tue Jun 18 15:17:37.504 AEST
Interface: Bundle-Ether10.3000.pppoe49
Circuit ID: AVC000085500318
Remote ID: Unknown
Type: PPPoE:PTA
IPv4 State: Up Pending, Tue Jun 18 15:16:39 2019
IPv4 Address: ipv4, VRF: default
IPv6 State: Up Pending, Tue Jun 18 15:16:39 2019
Mac Address: 18f1.45ce.3d64
Account-Session Id: 00000186
Nas-Port: Unknown
User name: username
Formatted User name: unknown
Client User name: unknown
Outer VLAN ID: 3215
Inner VLAN ID: 3914
Subscriber Label: 0x00000074
Created: Tue Jun 18 15:16:39 2019
State: Connected
Authentication: authenticated
Authorization: unauthorized
Ifhandle: 0x00006360
Session History ID: 0
Access-interface: Bundle-Ether10.3000
SRG Flags: 0x00000000
Policy Executed:

event Session-Start match-first [at Tue Jun 18 15:16:39 2019]
class type control subscriber PPP do-until-failure [Succeeded]
10 activate dynamic-template PPP_TPL [cerr: No error][aaa: Success]
event Session-Activate match-first [at Tue Jun 18 15:16:40 2019]
class type control subscriber PPP do-until-failure [Succeeded]
10 authenticate aaa list default [cerr: No error][aaa: Success]
Session Accounting: disabled
Last COA request received: unavailable
User Profile received from AAA:
Attribute List: 0x4a01310c
1: delegated-prefix len= 18 value= 2001:DB8:b000:100::/56
2: ipv6-addr-pool len= 11 value= PPPoE_Pool6
3: addr len= 4 value= ipv4
4: sub-qos-policy-out len= 12 value= pm-egress-50
5: service-type len= 4 value= Framed
6: netmask len= 4 value= 255.255.255.255
7: actual-data-rate-upstream len= 4 value= 22600(5848)
8: actual-data-rate-downstream len= 4 value= 54999(d6d7)
Pending Callbacks: PPSM-Sub>Policy,PPSM-Sub>Policy-Disc,Policy>SVM-PDone,
Services:
Name : PPP_TPL
Service-ID : 0x4000002
Type : Template
Status : Applied
-------------------------
[Event History]
Jun 18 15:16:24.192 SUBDB produce done

Labels:
0 Helpful
1 Reply 1

bpbp-heyoo
Level 1
Level 1

‎06-18-2019 10:13 PM

I have managed work around this issue by using the settings in the dynamic-template instead. I've now into a PD issue with this IOS XR release that someone else on this forum had:

 

https://community.cisco.com/t5/service-providers-documents/asr9000-xr-bng-and-dual-stack-ipv4-and-ipv6-sessions/tac-p/3328491/highlight/true#M4959

"Now I've upgraded to 6.1.4 and SLAAC works fine, but now the CPE doesn't get a PD prefix. From DHCP debugging on both sides I can see that the ASR9K receives the request, allocates and installs a prefix in the routing table, and from the DHCP debug output the ASR9K claims to send the response but the CPE doesn't receive it."

 

I see the exact same issue - server responds to the SOLICIT and CPE never receives it. I am not sure but it sounds a bit like this: https://bst.cloudapps.cisco.com/bugsearch/bug/CSCvj47694/?rfs=iqvred

 

I will see if we can upgrade to a newer IOS XR

0 Helpful
Customers Also Viewed These Support Documents