Hi Everyone
I got an error trying to establish a pppoe session to a BNG ASR9000, in the debug it seems that que client pppoe its sending a pppoe packet type 11a7 (PADT) to the BNG, just after the client receives a pppoe packet type 1165 (PADS). I just already checked several debugs in the ASR9000 but i couldn't see the reason for this behavior.
Maybe if somebody could guide me, i´ll appreciate a lot.
Thanks in advance.
Regards.
Configuration:
dynamic-template
type ppp PPP_ERT
ppp authentication chap
ppp ipcp peer-address pool PPPoE
ipv4 unnumbered Loopback1000
interface GigabitEthernet0/0/0/15.2
service-policy type control subscriber PPP_PM
pppoe enable bba-group ERT
encapsulation dot1q 2
aaa accounting subscriber default group radius
aaa authorization subscriber default group radius
aaa authentication subscriber default group radius
pppoe bba-group ERT
service selection disable
!
class-map type control subscriber match-any PPP
match protocol ppp
end-class-map
!
!
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_ERT
!
!
event session-activate match-first
class type control subscriber PPP do-until-failure
10 authenticate aaa list default
Debug pppoe packets
debug pppoe all
LC/0/0/CPU0:May 21 12:05:19.947 : pppoe_ea[307]: Created table entry(s) for index0, session index 0xc, sub-parent's uidb index 0x17, entry count 1.
LC/0/0/CPU0:May 21 12:05:19.947 : pppoe_ea[307]: Set resource consumption to 3 for batch
LC/0/0/CPU0:May 21 12:05:19.947 : pppoe_ea[307]: Program session table for batch COMPLETE, sending the last msg, index0.
LC/0/0/CPU0:May 21 12:05:19.948 : pppoe_ea[307]: Stored session ID 12 parent uidb index 0X17 for interface 0x40009c0
LC/0/0/CPU0:May 21 12:05:19.948 : pppoe_ea[307]: Set resource consumption to 4 for batch
LC/0/0/CPU0:May 21 12:05:19.948 : pppoe_ea[307]: Freeing TCAM info
LC/0/0/CPU0:May 21 12:05:19.948 : pppoe_ea[307]: Interface 0x40009c0 marked as clean
LC/0/0/CPU0:May 21 12:05:19.948 : pppoe_ea[307]: No rollback required - all interfaces created successfully
LC/0/0/CPU0:May 21 12:05:19.948 : pppoe_ea[307]: Interface: 0x040009c0: INTF CREATE(2), Hardware programming completed successfully
LC/0/0/CPU0:May 21 12:05:19.948 : pppoe_ea[307]: Interface: 0x040009c0: INTF CREATE(3), IMC interface create completed successfully
LC/0/0/CPU0:May 21 12:05:19.955 : pppoe_ma[308]: Session: 0x00000000: Received interface create cb: No error
LC/0/0/CPU0:May 21 12:05:19.955 : pppoe_ma[308]: Session: GigabitEthernet0/0/0/15.2.pppoe12: Inserting a session idb into global database
LC/0/0/CPU0:May 21 12:05:19.955 : pppoe_ma[308]: Session: GigabitEthernet0/0/0/15.2.pppoe12: Successfully added new session idb to global database. Session IDB count = 1
LC/0/0/CPU0:May 21 12:05:19.956 : pppoe_ma[308]: Session: GigabitEthernet0/0/0/15.2.pppoe12: Received MTU notification, with MTU actual 1500
LC/0/0/CPU0:May 21 12:05:19.969 : pppoe_ma[308]: Session: Received AAA batch start notication
LC/0/0/CPU0:May 21 12:05:19.969 : pppoe_ma[308]: Session: GigabitEthernet0/0/0/15.2.pppoe12: Received AAA Session Create cb: No error
LC/0/0/CPU0:May 21 12:05:19.970 : pppoe_ma[308]: Session: Received AAA batch end notication
LC/0/0/CPU0:May 21 12:05:20.011 : pppoe_ma[308]: Session: Received SubDB batch start notication
LC/0/0/CPU0:May 21 12:05:20.011 : pppoe_ma[308]: Session: GigabitEthernet0/0/0/15.2.pppoe12: Received Activate Config cb: No error
LC/0/0/CPU0:May 21 12:05:20.012 : pppoe_ma[308]: Session: Received SubDB batch end notication
LC/0/0/CPU0:May 21 12:05:20.070 : pppoe_ma[308]: Session: GigabitEthernet0/0/0/15.2.pppoe12: Interface ready call succeeded
LC/0/0/CPU0:May 21 12:05:20.070 : pppoe_ma[308]: [PADS-Sent]: GigabitEthernet0/0/0/15.2 peer-mac ac87.a334.e459
LC/0/0/CPU0:May 21 12:05:20.070 : pppoe_ma[308]: [PADS-Sent]: vlan-id-outer 2
LC/0/0/CPU0:May 21 12:05:20.070 : pppoe_ma[308]: GigabitEthernet0/0/0/15.2: O dst ac87.a334.e459 src 40ce.241b.c3f7: len 22 0x1165000c0010010100000103000800f86c1f80ffffff
LC/0/0/CPU0:May 21 12:05:53.150 : pppoe_ma[308]: GigabitEthernet0/0/0/15.2: I dst 40ce.241b.c3f7 src ac87.a334.e459: len 46 0x11a7000c000000000000000000000000000000000000000000000000000000000000000000000000000000000000
LC/0/0/CPU0:May 21 12:05:53.150 : pppoe_ma[308]: [PADT-Recv]: GigabitEthernet0/0/0/15.2 peer-mac ac87.a334.e459
LC/0/0/CPU0:May 21 12:05:53.150 : pppoe_ma[308]: [PADT-Recv]: vlan-id-outer 2
LC/0/0/CPU0:May 21 12:05:53.150 : pppoe_ma[308]: Session: [ERROR] GigabitEthernet0/0/0/15.2.pppoe12: Session being cleaned up, trigger 9
LC/0/0/CPU0:May 21 12:05:53.250 : pppoe_ma[308]: Session: Received AAA batch start notication
LC/0/0/CPU0:May 21 12:05:53.250 : pppoe_ma[308]: Session: Received AAA batch end notication
LC/0/0/CPU0:May 21 12:05:53.258 : pppoe_ma[308]: Session: 0x040009c0: Received FINAL notification
LC/0/0/CPU0:May 21 12:05:53.258 : pppoe_ma[308]: Session: [ERROR] 0x040009c0: Session being cleaned up, trigger 11
LC/0/0/CPU0:May 21 12:05:53.262 : pppoe_ea[307]: Interface: 0x040009c0: INTF DELETE received
LC/0/0/CPU0:May 21 12:05:53.262 : pppoe_ea[307]: Interface: 0x040009c0: INTF DELETE(1), idb lookups/creates completed successfully
LC/0/0/CPU0:May 21 12:05:53.262 : pppoe_ea[307]: Need a total of 1 TCAM indexes
LC/0/0/CPU0:May 21 12:05:53.262 : pppoe_ea[307]: Need 1 TCAM indexes for NP #0
LC/0/0/CPU0:May 21 12:05:53.262 : pppoe_ea[307]: Allocated memory to hold 1 TCAM indexes for NP #0
LC/0/0/CPU0:May 21 12:05:53.262 : pppoe_ea[307]: Built list of 1 TCAM indexes for NP #0
LC/0/0/CPU0:May 21 12:05:53.262 : pppoe_ea[307]: Freeing 1 TCAMs for NP #0
LC/0/0/CPU0:May 21 12:05:53.262 : pppoe_ea[307]: Freed 1 TCAMs for NP #0
LC/0/0/CPU0:May 21 12:05:53.262 : pppoe_ea[307]: Found tcam index 0x4 for index0 on np 0
LC/0/0/CPU0:May 21 12:05:53.262 : pppoe_ea[307]: Session Table Build For Intf: For delete, subscriber session data 12, parent uidb data 23, result No error (0x0)
LC/0/0/CPU0:May 21 12:05:53.262 : pppoe_ea[307]: PRM Hw key entry 0 = 0x0
LC/0/0/CPU0:May 21 12:05:53.262 : pppoe_ea[307]: PRM Hw key entry 1 = 0x17
LC/0/0/CPU0:May 21 12:05:53.262 : pppoe_ea[307]: PRM Hw key entry 2 = 0x0
LC/0/0/CPU0:May 21 12:05:53.262 : pppoe_ea[307]: PRM Hw key entry 3 = 0x0
LC/0/0/CPU0:May 21 12:05:53.262 : pppoe_ea[307]: PRM Hw key entry 4 = 0xC
LC/0/0/CPU0:May 21 12:05:53.263 : pppoe_ea[307]: PRM Hw key entry 5 = 0x0
LC/0/0/CPU0:May 21 12:05:53.263 : pppoe_ea[307]: Created table entry(s) for index0, session index 0xc, sub-parent's uidb index 0x17, entry count 1.
LC/0/0/CPU0:May 21 12:05:53.263 : pppoe_ea[307]: Free session table for batch COMPLETE, sending the last msg, index0.
LC/0/0/CPU0:May 21 12:05:53.264 : pppoe_ea[307]: Deleting uIDBs for 1 interfaces
LC/0/0/CPU0:May 21 12:05:53.266 : pppoe_ea[307]: Freeing TCAM info
LC/0/0/CPU0:May 21 12:05:53.266 : pppoe_ea[307]: Interface: 0x040009c0: INTF DELETE(2), IMC interface delete completed successfully
LC/0/0/CPU0:May 21 12:05:53.267 : pppoe_ma[308]: Session: 0x040009c0: Interface delete completed successfully
LC/0/0/CPU0:May 21 12:05:53.267 : pppoe_ma[308]: Session: 0x00000000: Successfully removed session idb from global database. Session IDB count = 0
LC/0/0/CPU0:May 21 12:05:53.267 : pppoe_ma[308]: Session: 0x00000000: Successfully removed session idb from parent database. Parent session IDB count = 0
