BNG FOR ASR9912(5.2.4) error 691

ruky79181 · ‎05-13-2016

Hello everyone.

I am trying to configure bng on ASR 9912 (5.2.4) for PPPoE .

Configuration is done but PPPoE dial show error 691

Hers is my configuration and debug information!!!!!!!!

radius-server host 10.10.5.101 auth-port 1812 acct-port 1813
key 7 1543525B5D7B73
!
aaa attribute format NAS-PORT-ID
circuit-id plus remote-id
!
aaa radius attribute nas-port format e SSAAPPPPQQQQQQQQQQVVVVVVVVVVUUUU type 36
aaa radius attribute nas-port-id format NAS-PORT-ID
aaa group server radius cn_radius_group1
server 10.10.5.101 auth-port 1812 acct-port 1813
source-interface Loopback0
!
aaa accounting subscriber radius_group1 group cn_radius_group1
aaa authentication subscriber radius_group1 group cn_radius_group1

!

dynamic-template
type ppp PPPoE
ppp authentication pap chap
ppp ipcp peer-address pool IPv4_Pool1
ipv4 unnumbered Loopback100
!
!

dynamic-template
type ppp PPPoE
ppp authentication pap chap
ppp ipcp peer-address pool IPv4_Pool1
ipv4 unnumbered Loopback100
!

pool vrf default ipv4 IPv4_Pool1
address-range 192.168.10.1 192.168.34.255

!

class-map type control subscriber match-all PPPoE
match protocol ppp
end-class-map
!

policy-map type control subscriber PPPoE
event session-start match-first
class type control subscriber PPPoE do-until-failure
1 activate dynamic-template PPPoE
!
!
event session-activate match-all
class type control subscriber PPPoE do-until-failure
10 authenticate aaa list radius_group1
!
!
end-policy-map
!

interface Bundle-Ether9.70
service-policy type control subscriber PPPoE
pppoe enable bba-group BBA
encapsulation dot1q 70

Loopback100 100.100.100.100 Up Up

Bundle-Ether9.70 unassigned Up Up

FeatureID: A9K-BNG-LIC-8K (Slot based, Permanent)
Total licenses 2
Available for use         2
Allocated to location     0
Active                    0
Store name             Permanent
Store index               2
    Pool: Owner
      Total licenses in pool: 2
      Status: Available     2    Operational:    0

RP/0/RP0/CPU0:ASR#show subscriber manager disconnect-history unique summary
Sat May 14 02:54:20.407 GMT

[ IEDGE DISCONNECT HISTORY UNIQUE EVENTS ]

Location: 0/RP0/CPU0

Count Last Interface          Last Time Disconnected Disconnect reason
===== ==============          ====================== =================

14     BE9.70.pppoe14          2016:05:13 16:51:59     PPP LCP FSM finished,
                                                       DC: 0 AC: 23 TC: 17
4      BE9.70.pppoe18          2016:05:13 16:57:39     Received Term-Req (or
                                                       Prot-Rej), DC: 0 AC: 28
                                                       TC: 1
5      BE9.70.pppoe23          2016:05:13 17:23:04     Feature Installation
                                                       Failure, DC: 0 AC: 26
                                                       TC: 17
6      BE9.70.pppoe29          2016:05:14 02:48:54     Feature Installation
                                                       Failure, DC: 0 AC: 25
                                                       TC: 17

Location: 0/RP1/CPU0

Location: 0/0/CPU0

Location: 0/3/CPU0

Location: 0/5/CPU0

RP/0/RP0/CPU0:ASR#show subscriber session all
Sat May 14 02:55:06.917 GMT
Codes: IN - Initialize, CN - Connecting, CD - Connected, AC - Activated,
       ID - Idle, DN - Disconnecting, ED - End

Type         Interface                State     Subscriber IP Addr / Prefix
                                                LNS Address (Vrf)
--------------------------------------------------------------------------------

RP/0/RP0/CPU0:ASR#debug sub
sub-util subscriber
RP/0/RP0/CPU0:ASR#debug subscriber manager all
Sat May 14 02:56:06.023 GMT
RP/0/RP0/CPU0:E4-KaRaj-TMC.ASR#RP/0/RP0/CPU0:May 14 02:56:12.397 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x0] (0x101e7d68) Action Event eval-subscriber, state changed from initialize to subscriber, trans-id (0x3b)
RP/0/RP0/CPU0:May 14 02:56:12.397 : iedged[253]: [IEDGE:TP1254:PPSM-TRANS:EVENT:0x0] (0x101e7d68) Identity list received from client, trans-id (0x3b)
RP/0/RP0/CPU0:May 14 02:56:12.397 : iedged[253]: [IEDGE:TP1255:PPSM-TRANS:EVENT:0x0] 1: if-handle       len= 4 3104(c20) 2: parent-if-handle len= 4 928(3a0) 3: client-mac-address len= 14 901b.0e5f.1dc3
RP/0/RP0/CPU0:May 14 02:56:12.397 : iedged[253]: [IEDGE:TP1263:PPSM-TRANS:EVENT:0x0] (0x101e7d68) No existing subscriber label for transaction trans-id (0x3b) found in SADB database
RP/0/RP0/CPU0:May 14 02:56:12.397 : iedged[253]: [IEDGE:TP1882:RULEDB:EVENT:0x0] Query for policy Map:PPPoE Success
RP/0/RP0/CPU0:May 14 02:56:12.397 : iedged[253]: [IEDGE:TP2605:ISLM:EVENT:0x0] label count 0 rc 0
RP/0/RP0/CPU0:May 14 02:56:12.397 : iedged[253]: [IEDGE:TP2606:ISLM:EVENT:0x0] rc 0 configured limit allowed
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP1453:PPSM-SUB:EVENT:0x5d] Create Subscriber - state: initialize, trans handle (0x101e7d68), trans-id = (0x3b)
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP1282:PPSM-SUB:EVENT:0x5d] (0x101e7d68) add acct-session-id to SADB for subscriber [0x5d]: 0000001e, trans-id (0x3b)
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP226:SERVICE:EVENT:0x5d] Creating SVM session (0 SB, 0 AS)
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP1292:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Starting transaction for subscriber [0x5d], trans-id (0x3b)
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event transaction-start, state changed from subscriber to subscriber-wait, trans-id (0x3b)
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP1324:PPSM-TRANS:EVENT:0x5d] AAA client type 4, function 25 [Session start request], state: subscriber-wait
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event request-sent, state changed from subscriber-wait to subscriber-wait, trans-id (0x3b)
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP1455:PPSM-SUB:EVENT:0x5d] New Subscriber - state: initialize
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP1446:PPSM-SUB:EVENT:0x5d] Action Event new-session, state changed from initialize to connecting
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP1979:POLICY:EVENT:0x5d] [93] Subscriber policy invoked for Event:Session-Start
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP2058:POLICY:EVENT:0x5d] Found parent interface:0x3a0 in client provided identity list
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP1882:RULEDB:EVENT:0x0] Query for policy Map:PPPoE Success
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP2061:POLICY:EVENT:0x5d] Parent interface 0x000003A0 policy: PPPoE is associated to subscriber session.
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP1702:POLICY:ERROR:0x5d] Unable to get formatted nas-identifier Cerr: 'AAA ATTR' detected the 'fatal' condition 'Invalid attribute found'
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP1896:RULEDB:EVENT:0x0] Query Event:Session-Start in policy-map hdl:1 Success
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP2033:POLICY:EVENT:0x5d] Matched "PPPoE/event Session-Start match-first"
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP2024:POLICY:EVENT:0x5d] Evaluate Class-map PPPoE
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP1874:CLASS-EVAL:EVENT:0x5d] PPPoE: [TRUE]
RP/0/RP0/CPU0:May 14 02:56:12.398 : iedged[253]: [IEDGE:TP2025:POLICY:EVENT:0x5d] Matched "class type control subscriber PPPoE do-until-failure"
RP/0/RP0/CPU0:May 14 02:56:12.399 : iedged[253]: [IEDGE:TP2016:POLICY:EVENT:0x5d] Execute: 1 activate dynamic-template PPPoE
RP/0/RP0/CPU0:May 14 02:56:12.399 : iedged[253]: [IEDGE:TP1745:POLICY:EVENT:0x5d] Retrieved template_type: service
RP/0/RP0/CPU0:May 14 02:56:12.399 : iedged[253]: [IEDGE:TP342:SERVICE:EVENT:0x5d] Applying Svc Templ PPPoE (ML:NULL)
RP/0/RP0/CPU0:May 14 02:56:12.399 : iedged[253]: [IEDGE:TP126:SERVICE:EVENT:0x0] PPPoE (ML:(null)) [0x9e] state UNKN->NEW (UNKN)
RP/0/RP0/CPU0:May 14 02:56:12.399 : iedged[253]: [IEDGE:TP125:SERVICE:EVENT:0x0] PPPoE (ML:(null)) AS 0x10c40420 status UNKNOWN->NEW
RP/0/RP0/CPU0:May 14 02:56:12.399 : iedged[253]: [IEDGE:TP472:SERVICE:EVENT:0x0] [0x9e]HA SP CKPT Add 34:bytes ID:0x40002f78
RP/0/RP0/CPU0:May 14 02:56:12.399 : iedged[253]: [IEDGE:TP473:SERVICE:EVENT:0x0] [0x9e]HA SP CKPT Add RPL[0] AL=0 KL=5 PPPoE
RP/0/RP0/CPU0:May 14 02:56:12.399 : iedged[253]: [IEDGE:TP126:SERVICE:EVENT:0x0] PPPoE (ML:(null)) [0x9e] state NEW->INST (UNKN)
RP/0/RP0/CPU0:May 14 02:56:12.399 : iedged[253]: [IEDGE:TP6088:SERVICE:EVENT:0x0] Process command list, null list
RP/0/RP0/CPU0:May 14 02:56:12.399 : iedged[253]: [IEDGE:TP125:SERVICE:EVENT:0x5d] PPPoE (ML:(null)) AS 0x10c40420 status NEW->REQ-ASC
RP/0/RP0/CPU0:May 14 02:56:12.399 : iedged[253]: [IEDGE:TP168:SERVICE:EVENT:0x5d] Srv params [NONE], svm_service_apply SUBDB ASSOCIATE CALLED
RP/0/RP0/CPU0:May 14 02:56:12.399 : iedged[253]: [IEDGE:TP6184:SERVICE:EVENT:0x5d] svm_subdb_associate SUBDB ASSOCIATE CALLED, service=[PPPoE], params=[NONE]
RP/0/RP0/CPU0:May 14 02:56:12.399 : iedged[253]: [IEDGE:TP169:SERVICE:EVENT:0x5d] PPPoE (ML:(null)) Associated, rc=0x0
RP/0/RP0/CPU0:May 14 02:56:12.399 : iedged[253]: [IEDGE:TP171:SERVICE:EVENT:0x5d] Apply for AS 0x10c40420 REQ-ASC CREATED (ps_f=0x0)
RP/0/RP0/CPU0:May 14 02:56:12.399 : iedged[253]: [IEDGE:TP3930:POLICY:EVENT:0x5d] Policy Handler Results No error 0
RP/0/RP0/CPU0:May 14 02:56:12.401 : iedged[253]: [IEDGE:TP6181:SERVICE:EVENT:0x5d] SubDB Assoc CB - OBJECT PPPoE, srv_label [67108866]
RP/0/RP0/CPU0:May 14 02:56:12.401 : iedged[253]: [IEDGE:TP125:SERVICE:EVENT:0x5d] PPPoE (ML:(null)) AS 0x10c40420 status REQ-ASC->ASSOC
RP/0/RP0/CPU0:May 14 02:56:12.401 : iedged[253]: [IEDGE:TP163:SERVICE:EVENT:0x5d] Apply for AS 0x10c40420 ASSOC ACTIVATE (ps_f=0x1)
RP/0/RP0/CPU0:May 14 02:56:12.401 : iedged[253]: [IEDGE:TP159:SERVICE:EVENT:0x5d] Client apply CB PPPoE (ML:(null)) AS 0x10c40420 ASSOC
RP/0/RP0/CPU0:May 14 02:56:12.401 : iedged[253]: [IEDGE:TP2041:POLICY:EVENT:0x5d] Successfully Executed Action: 1 activate dynamic-template PPPoE
RP/0/RP0/CPU0:May 14 02:56:12.401 : iedged[253]: [IEDGE:TP2043:POLICY:EVENT:0x5d] Continue Executing policy
RP/0/RP0/CPU0:May 14 02:56:12.401 : iedged[253]: [IEDGE:TP2051:POLICY:EVENT:0x5d] Completed executing policy engine, invoking PPSM
RP/0/RP0/CPU0:May 14 02:56:12.401 : iedged[253]: [IEDGE:TP1975:POLICY:EVENT:0x5d] Policy invoke complete called for Event: Session-Start with status No error and auth_result 0
RP/0/RP0/CPU0:May 14 02:56:12.401 : iedged[253]: [IEDGE:TP1976:POLICY:EVENT:0x5d] Calling svm_produce_done
RP/0/RP0/CPU0:May 14 02:56:12.401 : iedged[253]: [IEDGE:TP408:SERVICE:EVENT:0x5d] Produce done (PD) request (ACTIVATE) 1:AS
RP/0/RP0/CPU0:May 14 02:56:12.401 : iedged[253]: [IEDGE:TP410:SERVICE:EVENT:0x5d] Produce done (PD) rc=0x0 REQ:30 (ps_f=0x1)
RP/0/RP0/CPU0:May 14 02:56:12.401 : iedged[253]: [IEDGE:TP241:SERVICE:EVENT:0x5d] PD PENDING REQ=30 ps_f=0x5 1:AS
RP/0/RP0/CPU0:May 14 02:56:12.401 : iedged[253]: [IEDGE:TP125:SERVICE:EVENT:0x5d] PPPoE (ML:(null)) AS 0x10c40420 status ASSOC->REQ-PDA
RP/0/RP0/CPU0:May 14 02:56:12.401 : iedged[253]: [IEDGE:TP242:SERVICE:EVENT:0x5d] PD AS 0x10c40420 REQ-PDA REQ:30 PPPoE
RP/0/RP0/CPU0:May 14 02:56:12.404 : iedged[253]: [IEDGE:TP595:SERVICE:EVENT:0x5d] SubDB PD CB [0x5d] req=30 opts=0x1 EC=0x0 aaa_error_cause=0x1
RP/0/RP0/CPU0:May 14 02:56:12.404 : iedged[253]: [IEDGE:TP251:SERVICE:EVENT:0x5d] Appl PD Done GENed CB REQ:30 result [No error]
RP/0/RP0/CPU0:May 14 02:56:12.404 : iedged[253]: [IEDGE:TP1972:POLICY:EVENT:0x5d] SVM produce done CB for subscriber label [0x5d] GEN returned 0x0. Current event is Session-Start
RP/0/RP0/CPU0:May 14 02:56:12.404 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event request-response, state changed from subscriber-wait to subscriber-wait, trans-id (0x3b)
RP/0/RP0/CPU0:May 14 02:56:12.404 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event request-complete, state changed from subscriber-wait to subscriber-response, trans-id (0x3b)
RP/0/RP0/CPU0:May 14 02:56:12.404 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event transaction-checkpointing, state changed from subscriber-response to checkpoint-wait, trans-id (0x3b)
RP/0/RP0/CPU0:May 14 02:56:12.404 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event transaction-complete, state changed from checkpoint-wait to end, trans-id (0x3b)
RP/0/RP0/CPU0:May 14 02:56:12.404 : iedged[253]: [IEDGE:TP2:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Sending response back to client [pppoe_ma], trans-id (0x3b), sub_label = 0x5dx, ctx = 0xc20, res - No error
RP/0/RP0/CPU0:May 14 02:56:12.404 : iedged[253]: [IEDGE:TP1147:PPSM-API:EVENT:0x5d] CallBack Session start callback for 4 [pppoe_ma], function 25 [Session start request]
RP/0/RP0/CPU0:May 14 02:56:12.404 : iedged[253]: [IEDGE:TP1148:PPSM-API:EVENT:0x5d] cxt [0xc20] auth_res [0] result [No error]
RP/0/RP0/CPU0:May 14 02:56:12.404 : iedged[253]: [IEDGE:TP1446:PPSM-SUB:EVENT:0x5d] Action Event session-connected, state changed from connecting to connected
RP/0/RP0/CPU0:May 14 02:56:12.450 : iedged[253]: [IEDGE:TP595:SERVICE:EVENT:0x5d] SubDB PD CB [0x5d] req=30 opts=0x2 EC=0x0 aaa_error_cause=0x1
RP/0/RP0/CPU0:May 14 02:56:12.450 : iedged[253]: [IEDGE:TP243:SERVICE:EVENT:0x5d] PD complete: ACTIVATE REQ(30:30) (ps_f=0x6)
RP/0/RP0/CPU0:May 14 02:56:12.450 : iedged[253]: [IEDGE:TP6175:SERVICE:EVENT:0x5d] PD complete: ACTIVATE REQ(30:30) (ps_f=0x4)
RP/0/RP0/CPU0:May 14 02:56:12.450 : iedged[253]: [IEDGE:TP125:SERVICE:EVENT:0x5d] PPPoE (ML:(null)) AS 0x10c40420 status REQ-PDA->APPLIED
RP/0/RP0/CPU0:May 14 02:56:12.450 : iedged[253]: [IEDGE:TP246:SERVICE:EVENT:0x5d] PD for AS 0x10c40420 APPLIED ACTIVATE REQ:30
RP/0/RP0/CPU0:May 14 02:56:12.450 : iedged[253]: [IEDGE:TP247:SERVICE:EVENT:0x5d] Application CB for the SVM request, result [No error]
RP/0/RP0/CPU0:May 14 02:56:12.450 : iedged[253]: [IEDGE:TP3972:POLICY:EVENT:0x5d] Complete SVM produce done CB for Start (0x00000000) No error, 1, No error
RP/0/RP0/CPU0:May 14 02:56:15.511 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event eval-subscriber, state changed from initialize to subscriber, trans-id (0x30)
RP/0/RP0/CPU0:May 14 02:56:15.511 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event transaction-start, state changed from subscriber to subscriber-wait, trans-id (0x30)
RP/0/RP0/CPU0:May 14 02:56:15.511 : iedged[253]: [IEDGE:TP1324:PPSM-TRANS:EVENT:0x5d] AAA client type 5, function 7 [Session Activate request], state: subscriber-wait
RP/0/RP0/CPU0:May 14 02:56:15.511 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event request-sent, state changed from subscriber-wait to subscriber-wait, trans-id (0x30)
RP/0/RP0/CPU0:May 14 02:56:15.511 : iedged[253]: [IEDGE:TP1457:PPSM-SUB:EVENT:0x5d] Request - state: connected
RP/0/RP0/CPU0:May 14 02:56:15.511 : iedged[253]: [IEDGE:TP1446:PPSM-SUB:EVENT:0x5d] Action Event request, state changed from connected to connected
RP/0/RP0/CPU0:May 14 02:56:15.511 : iedged[253]: [IEDGE:TP1407:PPSM-SUB:EVENT:0x5d] Action Request - state: connected, event: request, function 7 [Session Activate request]
RP/0/RP0/CPU0:May 14 02:56:15.511 : iedged[253]: [IEDGE:TP5522:PPSM-SUB:EVENT:0x5d] Process Session Activate request (func 7) for client id 5 [ppp_ma:AF_NONE], type 5
RP/0/RP0/CPU0:May 14 02:56:15.511 : iedged[253]: [IEDGE:TP1417:PPSM-SUB:EVENT:0x5d] using id & cred labels attr_hdls 0x10aeacb0 and 0x10b7dd44
RP/0/RP0/CPU0:May 14 02:56:15.511 : iedged[253]: [IEDGE:TP1059:PPSM-SUB:EVENT:0x5d] (0x5d) Added filtered sadb attributes into SADB
RP/0/RP0/CPU0:May 14 02:56:15.511 : iedged[253]: [IEDGE:TP1979:POLICY:EVENT:0x5d] [93] Subscriber policy invoked for Event:Session-Activate
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP2054:POLICY:EVENT:0x5d] Found parent interface: Bundle-Ether9.70 (0x3a0) in SADB
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP1882:RULEDB:EVENT:0x0] Query for policy Map:PPPoE Success
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP2061:POLICY:EVENT:0x5d] Parent interface 0x000003A0 policy: PPPoE is associated to subscriber session.
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP1896:RULEDB:EVENT:0x0] Query Event:Session-Activate in policy-map hdl:1 Success
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP2033:POLICY:EVENT:0x5d] Matched "PPPoE/event Session-Activate match-all"
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP2024:POLICY:EVENT:0x5d] Evaluate Class-map PPPoE
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP1874:CLASS-EVAL:EVENT:0x5d] PPPoE: [TRUE]
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP2025:POLICY:EVENT:0x5d] Matched "class type control subscriber PPPoE do-until-failure"
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP2016:POLICY:EVENT:0x5d] Execute: 10 authenticate aaa list radius_group1
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP1716:POLICY:EVENT:0x5d] Authen Handler invoked
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP1717:POLICY:EVENT:0x5d] Retrieving attributes to send to AUTHEN coordinator
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP1702:POLICY:ERROR:0x5d] Unable to get formatted nas-identifier Cerr: 'AAA ATTR' detected the 'fatal' condition 'Invalid attribute found'
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP845:AUTHEN:EVENT:0x5d] Authen coordinator invoked with method-list radius_group1, attribute list
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP1064:AUTHEN:EVENT:0x5d] Successfully retrieved <6> identity attributes from SADB
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP851:AUTHEN:EVENT:0x5d] Request successfully posted to AAA Base.
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP852:AUTHEN:EVENT:0x5d] Response from Base will be received asynchronously.
RP/0/RP0/CPU0:May 14 02:56:15.512 : iedged[253]: [IEDGE:TP3930:POLICY:EVENT:0x5d] Policy Handler Results No error 0
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP854:AUTHEN:EVENT:0x0] Received response from AAA Base. Analyzing response ...
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP818:AUTHEN:EVENT:0x5d] process_authen_success_response: Authen Received response PASSED. status=0, Result1: No error, Result2: No error
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP825:AUTHEN:EVENT:0x5d] Successfully retrieved <4> Config attributes
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP827:AUTHEN:EVENT:0x5d] process_authen_success_response: Saving authentication data using SVM, msg No error
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP372:SERVICE:EVENT:0x5d] APPLY AS UP ML:radius_group1 AAA list 0x10af2c2c
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP6180:SERVICE:EVENT:0x5d] Process UP services present: NO, count:[0] SVM AAA list 0x10af2c2c
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP6135:SERVICE:EVENT:0x5d] Apply as user profileSVM uB ML:radius_group1 AAA list 0x10af2c2c, UP SRVC cnt 0
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP832:AUTHEN:EVENT:0x5d] process_authen_success_response: Request successfully posted to save Author data in SVM. ASYNC running
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP857:AUTHEN:EVENT:0x5d] aaa_coord_receive_authen_response: AAA req structure freed
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP347:SERVICE:EVENT:0x5d] APPLY AS UP FINALIZE ML:radius_group1 Pqos list 0x0 AAA list 0x10c8e9dc detach list 0x0 PolicyMgr rc=0x0
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP363:SERVICE:EVENT:0x5d] NEW UP (9) U0000005D AAA in list 0x10d2fabc, in/out 0/0
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP646:SERVICE:EVENT:0x5d] Inst U0000005D 0x5d attr=0x10af2c2c rc=0x0: No error
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP649:SERVICE:EVENT:0x5d] Inst PAD REQ 0x5d rc=0x0
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP369:SERVICE:EVENT:0x5d] Installed UP list 0x10af2c2c rc=0x0 U0000005D
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP371:SERVICE:EVENT:0x5d] WAIT POST CB NEW list len 97 U0000005D
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP592:SERVICE:ERROR:0x0] Install TMPL CB ERR [0x5d] rc=0xafe7ba00: 'TmplMgr' detected the 'fatal' condition 'Missing attribute in attribute list'
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP601:SERVICE:EVENT:0x5d] PAD Install CB 0x5d S=0x10baefe4 F=0x42547d8 U0000005D
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP602:SERVICE:ERROR:0x5d] PAD Install CB ERR 0x5d U0000005D rc=0xafe7ba00: 'TmplMgr' detected the 'fatal' condition 'Missing attribute in attribute list'
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP603:SERVICE:EVENT:0x5d] PAD Install CB 0x5d Client-CB U0000005D
RP/0/RP0/CPU0:May 14 02:56:15.514 : iedged[253]: [IEDGE:TP144:SERVICE:EVENT:0x5d] Post UP PAD rc='TmplMgr' detected the 'fatal' condition 'Missing attribute in attribute list' U0000005D, list len 97
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP148:SERVICE:ERROR:0x5d] PAD UP ERR list len 97 rc='TmplMgr' detected the 'fatal' condition 'Missing attribute in attribute list' U0000005D
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP7005:SERVICE:EVENT:0x5d] APPLY UP CB ASSOC FAILED U0000005D list 0x61 rc=0xafe7ba00
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP864:AUTHEN:ERROR:0x5d] authen_svm_response_cb: SVM returned status: FAIL. result1: 'TmplMgr' detected the 'fatal' condition 'Missing attribute in attribute list', result2: No error
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP812:AUTHEN:EVENT:0x5d] Authentication session destructor called.
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP814:AUTHEN:EVENT:0x5d] Authentication transaction context in ublock cleaned up.
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP1660:POLICY:EVENT:0x5d] AAA Coord Invoked AH Callback for 256 result = 0
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP2039:POLICY:ERROR:0x5d] Failed to Execute Action: 10 authenticate aaa list radius_group1, Error: 'TmplMgr' detected the 'fatal' condition 'Missing attribute in attribute list', auth_status: 0
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP2040:POLICY:EVENT:0x5d] Failed in Executing Policy. Aborting further evaluation. auth_res = 0, status = 'TmplMgr' detected the 'fatal' condition 'Missing attribute in attribute list'
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP1975:POLICY:EVENT:0x5d] Policy invoke complete called for Event: Session-Activate with status 'TmplMgr' detected the 'fatal' condition 'Missing attribute in attribute list' and auth_result 0
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP6126:SERVICE:EVENT:0x5d] SVM returned aaa_error_cause [5]
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event request-response, state changed from subscriber-wait to subscriber-wait, trans-id (0x30)
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event request-complete, state changed from subscriber-wait to subscriber-response, trans-id (0x30)
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event transaction-checkpointing, state changed from subscriber-response to checkpoint-wait, trans-id (0x30)
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event transaction-complete, state changed from checkpoint-wait to end, trans-id (0x30)
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP2:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Sending response back to client [ppp_ma], trans-id (0x30), sub_label = 0x5dx, ctx = 0xc20, res - 'TmplMgr' detected the 'fatal' condition 'Missing attribute in attribute list'
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP3610:PPSM-API:ERROR:0x5d] CallBack Session Activate callback for 5 [ppp_ma], Failed function 7 [Session Activate request]
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP3611:PPSM-API:ERROR:0x5d] cxt [0xc20] auth_res [0] result ['TmplMgr' detected the 'fatal' condition 'Missing attribute in attribute list']
RP/0/RP0/CPU0:May 14 02:56:15.515 : iedged[253]: [IEDGE:TP604:SERVICE:EVENT:0x5d] PAD Install CB 0x5d Client-CB RTN U0000005D
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event eval-subscriber, state changed from initialize to subscriber, trans-id (0x30)
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event transaction-start, state changed from subscriber to subscriber-wait, trans-id (0x30)
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP1324:PPSM-TRANS:EVENT:0x5d] AAA client type 5, function 22 [Session disconnect event], state: subscriber-wait
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event request-sent, state changed from subscriber-wait to subscriber-wait, trans-id (0x30)
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP1457:PPSM-SUB:EVENT:0x5d] Request - state: connected
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP1446:PPSM-SUB:EVENT:0x5d] Action Event request, state changed from connected to connected
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP1407:PPSM-SUB:EVENT:0x5d] Action Request - state: connected, event: request, function 22 [Session disconnect event]
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP1979:POLICY:EVENT:0x5d] [93] Subscriber policy invoked for Event:Session-Disconnect
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP2054:POLICY:EVENT:0x5d] Found parent interface: Bundle-Ether9.70 (0x3a0) in SADB
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP1882:RULEDB:EVENT:0x0] Query for policy Map:PPPoE Success
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP2061:POLICY:EVENT:0x5d] Parent interface 0x000003A0 policy: PPPoE is associated to subscriber session.
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP1896:RULEDB:EVENT:0x0] Query Event:Session-Disconnect in policy-map hdl:1 Success
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP2053:POLICY:EVENT:0x5d] Executing default Rule Engine Behavior for Event: Session-Disconnect
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP5035:PPSM-SUB:EVENT:0x5d] Disconnect being triggered by timer expiry event
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP4038:PPSM-SUB:EVENT:0x5d] Request for disconnect notification with disc-cause: 0x00000001, abort: 0x00000000, terminate: 0x00000000.
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP1446:PPSM-SUB:EVENT:0x5d] Action Event disc-signaled, state changed from connected to disconnecting
RP/0/RP0/CPU0:May 14 02:56:15.617 : iedged[253]: [IEDGE:TP3960:PPSM-SUB:EVENT:0x5d] Type: Session disconnect event: disc-cause: 0x00000000, abort: 0x00000019, terminate: 0x00000011, reason: Feature Installation Failure
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP1154:PPSM-API:EVENT:0x5d] [0x5d] Disc notification sent to client 4 [pppoe_ma], ctx 0xc20, trans-id (0x3b)
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP1492:PPSM-SUB:EVENT:0x5d] Disconnect notification sent to client id 4 [pppoe_ma], client type 4
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP1154:PPSM-API:EVENT:0x5d] [0x5d] Disc notification sent to client 5 [ppp_ma], ctx 0xc20, trans-id (0x30)
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP1492:PPSM-SUB:EVENT:0x5d] Disconnect notification sent to client id 5 [ppp_ma], client type 5
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP3930:POLICY:EVENT:0x5d] Policy Handler Results No error 0
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP3929:POLICY:EVENT:0x0] Policy default results No error 69192836
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP2426:PPSM-TRANS:EVENT:0x0] Started 1 session-disconnect transactions, 0 remain in queue, 799 quota_remaining
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP2429:PPSM-TRANS:EVENT:0x0] Session-disconnect queue is empty
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7e00) Action Event eval-subscriber, state changed from initialize to subscriber, trans-id (0x31)
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7e00) Action Event transaction-start, state changed from subscriber to subscriber-wait, trans-id (0x31)
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP1324:PPSM-TRANS:EVENT:0x5d] AAA client type 5, function 21 [Session disconnect ack], state: subscriber-wait
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7e00) Action Event request-sent, state changed from subscriber-wait to subscriber-wait, trans-id (0x31)
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP1500:PPSM-SUB:EVENT:0x5d] Found client id 5 [ppp_ma], client type 5, context for disconnect ack, with response 0
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP1504:PPSM-SUB:EVENT:0x5d] Triggering Unsupported Keep Identity cleanup code for client id 5 [ppp_ma], client type 5
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7e00) Action Event request-response, state changed from subscriber-wait to subscriber-wait, trans-id (0x31)
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7e00) Action Event request-complete, state changed from subscriber-wait to subscriber-response, trans-id (0x31)
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7e00) Action Event transaction-checkpointing, state changed from subscriber-response to checkpoint-wait, trans-id (0x31)
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7e00) Action Event transaction-complete, state changed from checkpoint-wait to end, trans-id (0x31)
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP2:PPSM-TRANS:EVENT:0x5d] (0x101e7e00) Sending response back to client [ppp_ma], trans-id (0x31), sub_label = 0x5dx, ctx = 0xc20, res - No error
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP1147:PPSM-API:EVENT:0x5d] CallBack No callback for 5 [ppp_ma], function 21 [Session disconnect ack]
RP/0/RP0/CPU0:May 14 02:56:15.618 : iedged[253]: [IEDGE:TP1148:PPSM-API:EVENT:0x5d] cxt [0xc20] auth_res [0] result [No error]
RP/0/RP0/CPU0:May 14 02:56:15.641 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7e00) Action Event eval-subscriber, state changed from initialize to subscriber, trans-id (0x3c)
RP/0/RP0/CPU0:May 14 02:56:15.641 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7e00) Action Event transaction-start, state changed from subscriber to subscriber-wait, trans-id (0x3c)
RP/0/RP0/CPU0:May 14 02:56:15.641 : iedged[253]: [IEDGE:TP1324:PPSM-TRANS:EVENT:0x5d] AAA client type 4, function 21 [Session disconnect ack], state: subscriber-wait
RP/0/RP0/CPU0:May 14 02:56:15.641 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7e00) Action Event request-sent, state changed from subscriber-wait to subscriber-wait, trans-id (0x3c)
RP/0/RP0/CPU0:May 14 02:56:15.641 : iedged[253]: [IEDGE:TP1500:PPSM-SUB:EVENT:0x5d] Found client id 4 [pppoe_ma], client type 4, context for disconnect ack, with response 0
RP/0/RP0/CPU0:May 14 02:56:15.641 : iedged[253]: [IEDGE:TP1504:PPSM-SUB:EVENT:0x5d] Triggering Unsupported Keep Identity cleanup code for client id 4 [pppoe_ma], client type 4
RP/0/RP0/CPU0:May 14 02:56:15.641 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7e00) Action Event request-response, state changed from subscriber-wait to subscriber-wait, trans-id (0x3c)
RP/0/RP0/CPU0:May 14 02:56:15.641 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7e00) Action Event request-complete, state changed from subscriber-wait to subscriber-response, trans-id (0x3c)
RP/0/RP0/CPU0:May 14 02:56:15.641 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7e00) Action Event transaction-checkpointing, state changed from subscriber-response to checkpoint-wait, trans-id (0x3c)
RP/0/RP0/CPU0:May 14 02:56:15.641 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7e00) Action Event transaction-complete, state changed from checkpoint-wait to end, trans-id (0x3c)
RP/0/RP0/CPU0:May 14 02:56:15.641 : iedged[253]: [IEDGE:TP2:PPSM-TRANS:EVENT:0x5d] (0x101e7e00) Sending response back to client [pppoe_ma], trans-id (0x3c), sub_label = 0x5dx, ctx = 0xc20, res - No error
RP/0/RP0/CPU0:May 14 02:56:15.641 : iedged[253]: [IEDGE:TP1147:PPSM-API:EVENT:0x5d] CallBack No callback for 4 [pppoe_ma], function 21 [Session disconnect ack]
RP/0/RP0/CPU0:May 14 02:56:15.642 : iedged[253]: [IEDGE:TP1148:PPSM-API:EVENT:0x5d] cxt [0xc20] auth_res [0] result [No error]
RP/0/RP0/CPU0:May 14 02:56:15.642 : iedged[253]: [IEDGE:TP939:ACCT:EVENT:0x5d] Accounting coordinator invoked with Action =1; Account Type=2
RP/0/RP0/CPU0:May 14 02:56:15.642 : iedged[253]: [IEDGE:TP943:ACCT:EVENT:0x5d] Executing Accounting STOP.
RP/0/RP0/CPU0:May 14 02:56:15.642 : iedged[253]: [IEDGE:TP3373:ACCT:EVENT:0x5d] Accounting not configured on this session.
RP/0/RP0/CPU0:May 14 02:56:15.642 : iedged[253]: [IEDGE:TP3062:PPSM-SUB:EVENT:0x5d] PPSM Acct STOP Callback - still waiting for subdb_destroy callback
RP/0/RP0/CPU0:May 14 02:56:15.672 : iedged[253]: [IEDGE:TP2041:POLICY:EVENT:0x5d] Successfully Executed Action: 1 disconnect
RP/0/RP0/CPU0:May 14 02:56:15.672 : iedged[253]: [IEDGE:TP2043:POLICY:EVENT:0x5d] Continue Executing policy
RP/0/RP0/CPU0:May 14 02:56:15.672 : iedged[253]: [IEDGE:TP1975:POLICY:EVENT:0x5d] Policy invoke complete called for Event: Session-Disconnect with status No error and auth_result 0
RP/0/RP0/CPU0:May 14 02:56:15.672 : iedged[253]: [IEDGE:TP1464:PPSM-SUB:EVENT:0x5d] PRE Response, SUB state[disconnecting], result[No error], aaa_error_cause[16]
RP/0/RP0/CPU0:May 14 02:56:15.672 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event request-response, state changed from subscriber-wait to subscriber-wait, trans-id (0x30)
RP/0/RP0/CPU0:May 14 02:56:15.672 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event request-complete, state changed from subscriber-wait to subscriber-response, trans-id (0x30)
RP/0/RP0/CPU0:May 14 02:56:15.672 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event transaction-checkpointing, state changed from subscriber-response to checkpoint-wait, trans-id (0x30)
RP/0/RP0/CPU0:May 14 02:56:15.672 : iedged[253]: [IEDGE:TP1342:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Action Event transaction-complete, state changed from checkpoint-wait to end, trans-id (0x30)
RP/0/RP0/CPU0:May 14 02:56:15.672 : iedged[253]: [IEDGE:TP2:PPSM-TRANS:EVENT:0x5d] (0x101e7d68) Sending response back to client [ppp_ma], trans-id (0x30), sub_label = 0x5dx, ctx = 0xc20, res - No error
RP/0/RP0/CPU0:May 14 02:56:15.672 : iedged[253]: [IEDGE:TP1147:PPSM-API:EVENT:0x5d] CallBack No callback for 5 [ppp_ma], function 22 [Session disconnect event]
RP/0/RP0/CPU0:May 14 02:56:15.672 : iedged[253]: [IEDGE:TP1148:PPSM-API:EVENT:0x5d] cxt [0xc20] auth_res [0] result [No error]
RP/0/RP0/CPU0:May 14 02:56:15.672 : iedged[253]: [IEDGE:TP1446:PPSM-SUB:EVENT:0x5d] Action Event disc-response, state changed from disconnecting to disconnecting
RP/0/RP0/CPU0:May 14 02:56:15.672 : iedged[253]: [IEDGE:TP1446:PPSM-SUB:EVENT:0x5d] Action Event disc-complete, state changed from disconnecting to end
RP/0/RP0/CPU0:May 14 02:56:15.672 : iedged[253]: [IEDGE:TP143:SERVICE:EVENT:0x0] service label 0x9e, destroy PPPoE SB 0x10c3b034
RP/0/RP0/CPU0:May 14 02:56:15.673 : iedged[253]: [IEDGE:TP476:SERVICE:EVENT:0x0] [0x9e]HA SP CKPT deleted ID:0x40002f78
RP/0/RP0/CPU0:May 14 02:56:15.673 : iedged[253]: [IEDGE:TP1355:PPSM-TRANS:EVENT:0x5d] [93] Terminating subscriber session
RP/0/RP0/CPU0:May 14 02:56:15.673 : iedged[253]: [IEDGE:TP7306:PPSM-SUB:EVENT:0x5d] ppsm_subscriber_action_cleanup: mob_coord_delete_session returned No error
RP/0/RP0/CPU0:May 14 02:56:15.673 : iedged[253]: [IEDGE:TP7320:PPSM-SUB:EVENT:0x5d] ppsm_subscriber_action_cleanup: Removed possibly existed in-flight checkpoint; rc is No error
RP/0/RP0/CPU0:May 14 02:56:15.673 : iedged[253]: [IEDGE:TP7205:GENERIC:ERROR:0x0] All Subscribers have been removed on device

Aleksandar Vidakovic · ‎05-17-2016

The cause for disconnect was 'Missing attribute in attribute list'. I presume you have fixed this already by updating the attributes on the radius.

As a generic comment, please note that we highly recommend the XR release 5.3.3 (with the latest Service Pack) for all BNG deployments.

regards,

/Aleksandar