Contents

Introduction

Components Used

ISG Accounting

Topology

Configuration

RADIUS Config

PPP-Client-1 Configuration

BRAS-ASR1K Configuration

Cisco IOS® XE Show Commands

show aaa servers

show aaa method-lists accounting

show aaa sessions

show aaa service-profiles

show aaa user

show subscriber session username detail

show subscriber service name detailed

show subscriber session username feature accounting detailed

show subscriber session username PPPoE-Client-1 | i Switch

show ssm switch id

Kernel Show Commands

show platform software subscriber fp active accounting

show platform software subscriber fp active segment

show platform software subscriber fp active segment id

show platform software subscriber session username

QFP (Quantum Flow Processor) / ESP (Embedded Switch Processor) Show Commands

show platform hardware qfp active feature subscriber session

show platform hardware qfp active feature subscriber segment id

show platform hardware qfp active feature subscriber session id

show platform hardware qfp active feature subscriber segment id

show platform hardware qfp active feature subscriber session id

show platform hardware qfp active feature subscriber state feature accounting

Cisco IOS® XE Debugs

Debug Output

Introduction

This document describes remediation of ISG Accounting feature applied to PPPoE Session with Traffic Class "Internet" on ASR1000 with Cisco IOS® XE.

Components Used

The information in this document was created from the devices in a specific lab environment. All of the devices used in this document started with a cleared (default) configuration. If your network is live, ensure that you understand the potential impact of any command.

ISG Accounting

Included in this document is Configuration, verification of the feature in Cisco IOS® XE, verification of programming in the Linux Kernel, verification of programming of the the feature in hardware (QFP/ESP) and the debugs associated from Session initialisation to completion.

The ISG accounting feature gathers usage statistics on the overall session or service of the client.

In this example, ISG accounting was applied to the traffic-class Internet (Service) which was applied via the RADIUS Attributes from the User and Service Profile on the RADIUS Server.

More information can be found at:

https://www.cisco.com/c/en/us/td/docs/ios-xml/ios/isg/configuration/xe-3s/isg-xe-3s-book/isg-accounting.html

Topology

Configuration

This is a configuration example of ISG Session and Service Accounting.

RADIUS Config

RADIUS User and Service Profile Definition used here:

#### User Profile Definition ####

PPPoE-Client-1 Cleartext-Password := "cisco"

Framed-Protocol = PPP,

Service-Type = Framed,

Cisco-Account-Info += "AINTERNET",

#### Internet Service Profile Definition ####

DEFAULT Prefix == "INTERNET", Auth-Type := Accept

Cisco-AVPair += "ip:traffic-class=in access-group name ACL-Internet-In",

Cisco-AVPair += "ip:traffic-class=in default drop",

Cisco-AVPair += "ip:traffic-class=out access-group name ACL-Internet-Out",

Cisco-AVPair += "ip:traffic-class=out default drop",

Cisco-AVPair += "accounting-list=ACCNT_LIST1",

PPP-Client-1 Configuration

!

interface GigabitEthernet0/3/0

description description ######### ISG to BRAS-ASR1K Gi2/3/4 #########

no ip address

duplex auto

speed auto

pppoe enable group global

pppoe-client dial-pool-number 2

!

interface Dialer2

description ######### Static PPP Dialer #########

mtu 1492

ip address negotiated

encapsulation ppp

dialer pool 2

dialer idle-timeout 0

dialer persistent

ppp mtu adaptive

ppp authentication pap callin

ppp pap sent-username PPPoE-Client-1 password 7 104D000A0618

BRAS-ASR1K Configuration

!

aaa new-model

!

!

aaa group server radius RADIUS_AUTH

server 192.168.111.9

ip radius source-interface GigabitEthernet2/0/4.200

deadtime 3

load-balance method least-outstanding ignore-preferred-server

!

!

aaa authentication login default local

aaa authentication ppp default local group RADIUS_AUTH

aaa authorization network default group RADIUS_AUTH local

aaa authorization configuration default group RADIUS_AUTH

aaa authorization subscriber-service default local group RADIUS_AUTH

aaa authorization subscriber-service TEST local group RADIUS_AUTH

aaa accounting delay-start all

aaa accounting update periodic 21

aaa accounting include auth-profile framed-ip-address

aaa accounting include auth-profile framed-ipv6-prefix

aaa accounting include auth-profile delegated-ipv6-prefix

aaa accounting network default start-stop group RADIUS_AUTH

aaa accounting network ACCNT_LIST1 start-stop group RADIUS_AUTH

!

aaa nas port extended

!

bba-group pppoe Static-PPPoE

virtual-template 2

!

interface Loopback2

description ######## Static PPP Session Loopback ########

ip address 192.0.2.0 255.255.255.255

!

interface GigabitEthernet2/0/4.200

encapsulation dot1Q 200

ip address 192.168.111.1 255.255.255.0

!

interface GigabitEthernet2/3/4

description ######## ISG to PPP-Client-1 Gi0/2/0 ########

no ip address

negotiation auto

pppoe enable group Static-PPPoE

cdp enable

!

interface Virtual-Template2

description ###### Static-PPPoE ######

ip unnumbered Loopback2

ip verify unicast source reachable-via rx

ip tcp adjust-mss 1452

no logging event link-status

peer default ip address pool syd-dhcp

keepalive 60

ppp mtu adaptive

ppp authentication pap

ppp ipcp dns 192.0.2.4 192.0.2.5

!

ip local pool syd-dhcp 192.0.2.1 192.0.2.6

Cisco IOS® XE Show Commands

Verification of ISG Accounting in Cisco IOS® XE and association with AAA/RADIUS Servers.

show aaa servers

BRAS-ASR1K#show aaa servers

RADIUS: id 1, priority 1, host 192.168.111.9, auth-port 1645, acct-port 1646

State: current UP, duration 73946s, previous duration 0s

Dead: total time 0s, count 0

Quarantined: No

Authen: request 2902, timeouts 0, failover 0, retransmission 0

Response: accept 2897, reject 5, challenge 0

Response: unexpected 0, server error 0, incorrect 0, time 2ms

Transaction: success 2902, failure 0

Throttled: transaction 0, timeout 0, failure 0

Author: request 8690, timeouts 0, failover 0, retransmission 0

Response: accept 8690, reject 0, challenge 0

Response: unexpected 0, server error 0, incorrect 0, time 2ms

Transaction: success 8690, failure 0

Throttled: transaction 0, timeout 0, failure 0

Account: request 18, timeouts 0, failover 0, retransmission 0

Request: start 5, interim 10, stop 3

Response: start 5, interim 10, stop 3

Response: unexpected 0, server error 0, incorrect 0, time 7ms

Transaction: success 18, failure 0

Throttled: transaction 0, timeout 0, failure 0

Elapsed time since counters last cleared: 20h32m

Estimated Outstanding Access Transactions: 0

Estimated Outstanding Accounting Transactions: 0

Estimated Throttled Access Transactions: 0

Estimated Throttled Accounting Transactions: 0

Maximum Throttled Transactions: access 0, accounting 0

Requests per minute past 24 hours:

high - 20 hours, 30 minutes ago: 12

low  - 20 hours, 32 minutes ago: 0

average: 9

show aaa method-lists accounting

BRAS-ASR1K#show aaa method-lists accounting

acct queue=AAA_ML_ACCT_SHELL

acct queue=AAA_ML_ACCT_AUTH_PROXY

acct queue=AAA_ML_ACCT_NET

name=ACCNT_LIST1 valid=TRUE id=AE000012 Action=START STOP :state=ALIVE : SERVER_GROUP RADIUS_AUTH

show aaa sessions

BRAS-ASR1K#show aaa sessions

Total sessions since last reload: 2921

Session Id: 2922

Unique Id: 2931

User Name: PPPoE-Client-1

IP Address: 192.0.2.3

Idle Time: 0

CT Call Handle: 0

show aaa service-profiles

BRAS-ASR1K#show aaa service-profiles

1> Service Name: Internet

show aaa user <UID>

BRAS-ASR1K#show aaa user 2931

Unique id 2931 is currently in use.

No data for type 0

No data for type EXEC

No data for type CONN

NET: Username=PPPoE-Client-1

Session Id=00000B6A Unique Id=00000B73

Start Sent=1 Stop Only=N

stop_has_been_sent=N

Method List=7F742FA2D8F8 : Name = default

Attribute list:

7F7430450570 0 00000001 session-id(408) 4 2922(B6A)

7F74304505B0 0 00000001 start_time(418) 4 Aug 30 2016 13:06:47

7F74304505F0 0 00000081 clid-mac-addr(42) 14 35 30 35 37 2E 61 38 64 38 2E 30 32 64 38

7F7430450630 0 00000002 session-type(692) 4 ipv4-only

7F7430450670 0 00000001 Framed-Protocol(111) 4 PPP

7F7430451998 0 00000002 media-protocol-state(980) 4 stateup

7F74304519D8 0 00000001 addr(8) 4 192.0.2.3

7F7430451A18 0 00000001 protocol(337) 4 ip

--------

NET: Username=PPPoE-Client-1

Session Id=00000B6B Unique Id=00000B73

Start Sent=1 Stop Only=N

stop_has_been_sent=N

Method List=7F7419C2CE40 : Name = ACCNT_LIST1

Attribute list:

7F7430450D80 0 00000001 session-id(408) 4 2923(B6B)

7F7430450DC0 0 00000001 start_time(418) 4 Aug 30 2016 13:06:48

7F7430450E00 0 00000001 Framed-Protocol(111) 4 PPP

7F7430450E40 0 00000081 ssg-service-info(489) 9 NInternet

7F7430450E80 0 00000081 parent-session-id(404) 8 00000B6A

7F7430450ED8 0 00000001 addr(8) 4 192.0.2.3

7F7430450F18 0 00000001 protocol(337) 4 ip

Flow id is 1

Cli hdl is 4A000002

No authen data

--------

No data for type CMD

No data for type SYSTEM

No data for type VRRS

No data for type RM CALL

No data for type RM VPDN

No data for type AUTH PROXY

No data for type DOT1X

No data for type CALL

No data for type VPDN-TUNNEL

No data for type VPDN-TUNNEL-LINK

No data for type IPSEC-TUNNEL

No data for type MCAST

No data for type RESOURCE

No data for type SSG

No data for type IDENTITY

No data for type ConnectedApps

Accounting:

log=0x1000000020C241

Events recorded :

CALL START

ATTR REPLACE

NET UP

IPCP_PASS

INTERIM START

VPDN NET UP

FLOW UP

update method(s) :

PERIODIC

update interval = 1260

Outstanding Stop Records : 0

Dynamic attribute list:

7F7430450ED8 0 00000001 connect-progress(75) 4 LAN Ses Up

7F7430450F18 0 00000001 pre-session-time(334) 4 0(0)

7F7430450F58 0 00000001 nas-tx-speed(481) 4 1000000000(3B9ACA00)

7F7430450F98 0 00000001 nas-rx-speed(78) 4 1000000000(3B9ACA00)

7F7430450FD8 0 00000001 elapsed_time(414) 4 958(3BE)

7F7430450D80 0 00000001 bytes_in(146) 4 1592(638)

7F7430450DC0 0 00000001 bytes_out(311) 4 1574(626)

show subscriber session username <username> detail

BRAS-ASR1K#show subscriber session username PPPoE-Client-1 detail

Type: PPPoE, UID: 900, State: authen, Identity: PPPoE-Client-1

IPv4 Address: 192.0.2.3

Session Up-time: 00:21:13, Last Changed: 00:21:13

Interface: Virtual-Access2.1

Switch-ID: 15701

Policy information:

Context 7F7439B43390: Handle 8B000F38

AAA_id 00000B73: Flow_handle 0

Authentication status: authen

Downloaded User profile, excluding services:

Framed-Protocol      0   1 [PPP]

service-type         0   2 [Framed]

ssg-account-info     0   "AInternet"

Downloaded User profile, including services:

Framed-Protocol      0   1 [PPP]

service-type         0   2 [Framed]

ssg-account-info     0   "AInternet"

ssg-service-info     0   "IInternet"

traffic-class        0   "in access-group name ACL-Internet-In"

traffic-class        0   "in default drop"

traffic-class        0   "out access-group name ACL-Internet-Out"

traffic-class        0   "out default drop"

accounting-list      0   "ACCNT_LIST1"

Config history for session (recent to oldest):

Access-type: Web-service-logon Client: SM

Policy event: Got More Keys (Service)

Profile name: Internet, 3 references

ssg-service-info     0   "IInternet"

traffic-class        0   "in access-group name ACL-Internet-In"

traffic-class        0   "in default drop"

traffic-class        0   "out access-group name ACL-Internet-Out"

traffic-class        0   "out default drop"

accounting-list      0   "ACCNT_LIST1"

Access-type: PPP Client: SM

Policy event: Got More Keys

Profile name: PPPoE-Client-1, 3 references

Framed-Protocol      0   1 [PPP]

service-type         0   2 [Framed]

ssg-account-info     0   "AInternet"

Access-type: PPP Client: SM

Policy event: Got More Keys

Profile name: PPPoE-Client-1, 3 references

Framed-Protocol      0   1 [PPP]

service-type         0   2 [Framed]

ssg-account-info     0   "AInternet"

Active services associated with session:

name "Internet"

Rules, actions and conditions executed:

subscriber rule-map default-internal-rule

condition always event service-start

1 service-policy type service identifier service-name

Classifiers:

Class-id    Dir   Packets    Bytes                  Pri.  Definition

0           In    5          500                    0    Match Any

1           Out   5          500                    0    Match Any

11584       In    5          500                    0    Match ACL ACL-Internet-In

11585       Out   5          500                    0    Match ACL ACL-Internet-Out

4294967294  In    0          0                      -    Drop

4294967295  Out   0          0                      -    Drop

Features:

Accounting:

Class-id   Dir  Packets    Bytes                 Source

11584      In   5          500                   Internet

11585      Out  5          500                   Internet

Configuration Sources:

Type  Active Time  AAA Service ID  Name

SVC   00:21:13     385875970       Internet

USR   00:21:13     -               Peruser

INT   00:21:13     -               Virtual-Template2

show subscriber service name <name> detailed

BRAS-ASR1K#show subscriber service name Internet  detailed

Service "Internet":

Version 1:

SVM ID                : B20001F1

Class Id  In: 00011584

Class Id Out: 00011585

Locked by             : SVM-Printer            [1]

Locked by             : PM-Service             [1]

Locked by             : FM-Bind                [1]

Locked by             : Accounting-Feature     [1]

Profile               : 7F7439BF3510

Profile name: Internet, 3 references

ssg-service-info     0   "IInternet"

traffic-class        0   "in access-group name ACL-Internet-In"

traffic-class        0   "in default drop"

traffic-class        0   "out access-group name ACL-Internet-Out"

traffic-class        0   "out default drop"

accounting-list      0   "ACCNT_LIST1"

Feature               : Accounting

Feature IDB type      : Sub-if or not required

Feature Data          : 32 bytes:

: 000000 00 00 B2 00 01 F1 00 00  ........

: 000008 00 00 00 00 7F 74 3A 09  .....t:.

: 000010 31 58 00 00 7C 0F 00 00  1x..|...

: 000018 00 01 00 00 00 00 00 00  ........

Current Subscriber Information using service "Internet"

Total sessions: 1

Codes: Lterm - Local Term, Fwd - forwarded, unauth - unathenticated, authen -

authenticated, TC Ct. - Number of Traffic Classes on the main session

Uniq ID Interface    State    Service     Up-time  TC Ct. Identifier

900     Vi2.1        authen   Lterm       02:17:59 1      PPPoE-Client-1

show subscriber session username <username> feature accounting detailed

BRAS-ASR1K#show subscriber session username PPPoE-Client-1 feature accounting detailed

--------------------------------------------------

Type: PPPoE, UID: 900, State: authen, Identity: PPPoE-Client-1

IPv4 Address: 192.0.2.3

Session Up-time: 02:16:05, Last Changed: 02:16:05

Interface: Virtual-Access2.1

Switch-ID: 15701

Features:

Accounting:

Class-id   Dir Packets-v4 Bytes-v4              Packets-v6 Bytes-v6              Source

11584      In  5          500                   0          0                     Internet

11585      Out 5          500                   0          0                     Internet

Common ACL:

Class-id   Dir Packets-v4 Bytes-v4              Packets-v6 Bytes-v6              Source

Common ACL Definitions:

show subscriber session username PPPoE-Client-1 | i Switch

BRAS-ASR1K#show subscriber session username PPPoE-Client-1 | i Switch

Switch-ID: 15701

show ssm switch id <Switch ID>

BRAS-ASR1K#show ssm switch id 15701

Switch-ID 15701 State: Open

Segment-ID: 23895 Type: Lterm[21]

Switch-ID:                    15701

Allocated By:                 This CPU

Locked By:                    SIP     [1]

Class:                        SSS

State:                        Active

LTERM switching context:

Software IDB Vi2.1

SSS Switch Handle 0x0

Session ID 900

L2 Outbound Features Set

Class:                        ADJ

State:                        Active

LTERM H/W switching context:

Session ID 900

Switching Mode 1

L2 Outbound Features Set

Segment-ID: 19798 Type: PPPoE[19]

Switch-ID:                    15701

Allocated By:                 This CPU

Locked By:                    SIP     [1]

Locked By:                    SSS     [1]

Locked By:                    SSF     [2]

Class:                        SSS

State:                        Active

PPPoE switching context:

Session ID: 2902

Unique ID: 900

PPP handle: 0x38000B56

SSS handle: 0x00000000

Outgoing link: Gi2/3/4

Virtual access interface: Vi2.1

MAC Address Local: 0027.0d2b.4fb4 Remote: 5057.a8d8.02d8

PPPoE encap string [20 bytes]:

5057A8D802D800270D2B4FB4886411000B560000

Class:                        ADJ

State:                        Active

HW segment type: L2HW_PPPOE

ESS Segment= 0x7F742A544BB0, Flags= 0x16, EVSI= 80, extended segment_id= 0x0000005000004D56

Peer ESS Segment= 0x7F742A544AC0, type= 19, seghandle= 0x7F7430243F30

Feature-ID: 7512 Type: ISG Classifier[14]

Segment-ID:     19798

Allocated by:   This CPU

Class: SSS

State:         Active

Class: ADJ

State:         Active

Feature-ID: 11609 Type: Accounting[6]

Segment-ID:     19798

Direction:      Both [11584.11585]

Allocated by:   This CPU

Class: SSS

State:         Active

Class: ADJ

State:         Act

Kernel Show Commands

Verification of ISG Accounting in the Linux Kernel

show platform software subscriber fp active accounting

BRAS-ASR1K#show platform software subscriber fp active accounting

Subscriber Accounting records: Total  : 1

Segment          Class Id In/Out        EVSI     QFP Hdl  AOM State

------------------------------------------------------------------------

0x0000005000004d56      11584/11585         16908315       81  created

show platform software subscriber fp active segment

BRAS-ASR1K#show platform software subscriber fp active segment

Subscriber Segments: Total  : 2

Segment       SegType         EVSI    Changes     AOM Id AOM State

----------------------------------------------------------------------

0x0000005000004d56      PPPoE         80 0x00000000      13008 created

0x0000005000005d57      LTERM         80 0x00000000      13009 created

show platform software subscriber fp active segment id <PPPoE Segment ID>

BRAS-ASR1K#show platform software subscriber fp active segment id 0x0000005000004d56

Segment          SegType        EVSI     Changes      AOM Id  AOM State

-----------------------------------------------------------------------------------

0x0000005000004d56       PPPoE          80  0x00000000       13008  created

PPPoE Session id 0xb56

MAC enctype 0x1

Switch Mode 0x2

Max MTU 0x5d4

VLAN cos 0x8

Phy Intf (on CPP) 0x31

Conditional Debug OFF

MAC Address Local: 00270d2b4fb4

MAC Address Remote: 5057a8d802d8

PPPoE encap string [20 bytes]:5057a8d802d800270d2b4fb4886411000b560000

Flow Information:

Flows activated/attached: 1/1

Input Classes: 1 (Default Drop)

Id       Priority   Flow EVSI  Class-Group Id  Filter Type:

Filter Name

-----------------------------------------------------------------------------

11584           0    16908315  1573220256.1    Named ACL:

ACL-Internet-In

Output Classes: 1 (Default Drop)

Id       Priority   Flow EVSI  Class-Group Id  Filter Type:

Filter Name

-----------------------------------------------------------------------------

11585           0    16908315  1589997875.1    Named ACL:

ACL-Internet-Out

show platform software subscriber fp active segment id <LTERM Segment ID>

BRAS-ASR1K#show platform software subscriber fp active segment id 0x0000005000005d57

Segment          SegType        EVSI     Changes      AOM Id  AOM State

-----------------------------------------------------------------------------------

0x0000005000005d57       LTERM          80  0x00000000       13009  created

LCP Magic 0x2b68bfb2

Switch Mode 0x2

Max MTU 0x5d4

LCP PFC: OFF

Conditional Debug: OFF

show platform software subscriber session username <username>

BRAS-ASR1K#show platform software subscriber session username PPPoE-Client-1

-------- show plat so subscriber fp act session id 80 --------

Session        Segment1        SegType1         Segment2        SegType2   AOM State

---------------------------------------------------------------------------------------------

80   0x0000005000005d57     LTERM     0x0000005000004d56     PPPoE    created

-------- show plat ha qfp act feat subscriber session id 80 --------

Session ID: 80

EVSI type: PPP

SIP Segment ID: 0x5000004d56

SIP Segment type: PPPOE

FSP Segment ID: 0x5000005d57

FSP Segment type: LTERM

QFP if handle: 80

QFP interface name: EVSI80

SIP TX Seq num: 0

SIP RX Seq num: 0

FSP TX Seq num: 0

FSP RX Seq num: 0

Conditon Debug: 0x00000000

TC feature enabled

session

-------- show plat so subscriber fp act segment id 0x0000005000004D56 --------

Segment          SegType        EVSI     Changes      AOM Id  AOM State

-----------------------------------------------------------------------------------

0x0000005000004d56       PPPoE          80  0x00000000       13008  created

PPPoE Session id 0xb56

MAC enctype 0x1

Switch Mode 0x2

Max MTU 0x5d4

VLAN cos 0x8

Phy Intf (on CPP) 0x31

Conditional Debug OFF

MAC Address Local: 00270d2b4fb4

MAC Address Remote: 5057a8d802d8

PPPoE encap string [20 bytes]:5057a8d802d800270d2b4fb4886411000b560000

Flow Information:

Flows activated/attached: 1/1

Input Classes: 1 (Default Drop)

Id       Priority   Flow EVSI  Class-Group Id  Filter Type:

Filter Name

-----------------------------------------------------------------------------

11584           0    16908315  1573220256.1    Named ACL:

ACL-Internet-In

Output Classes: 1 (Default Drop)

Id       Priority   Flow EVSI  Class-Group Id  Filter Type:

Filter Name

-----------------------------------------------------------------------------

11585           0    16908315  1589997875.1    Named ACL:

ACL-Internet-Out

-------- show plat hard qfp act feature subscriber segment id 0x0000005000004D56 --------

Segment ID: 0x5000004d56

EVSI: 80

Peer Segment ID: 0x5000005d57

QFP vsi if handle: 80

QFP interface name: EVSI80

Segment type: PPPOE

Is conditional debug: 0

Is SIP: 1

Segment status: BOUND

Macstring length: 20

00000000  5057  a8d8  02d8  0027  0d2b  4fb4  8864  1100

00000010  0b56  0000  0000  0000  0000  0000  0000  0000

Encap info exmem handle: 0x0

session id: 2902

vcd: 0

mtu: 1492

physical if handle: 49

hash value: 0x00003f00

Input Classes: 1

Class Id  Flow EVSI      CG Id               QFP Hdl

------------------------------------------------------

11584   16908315 1573220256.1                  81

Output Classes: 1

Class Id  Flow EVSI      CG Id               QFP Hdl

------------------------------------------------------

11585   16908315 1589997875.1                  81

-------- show plat so subscriber fp act segment id 0x0000005000005D57 --------

Segment          SegType        EVSI     Changes      AOM Id  AOM State

-----------------------------------------------------------------------------------

0x0000005000005d57       LTERM          80  0x00000000       13009  created

LCP Magic 0x2b68bfb2

Switch Mode 0x2

Max MTU 0x5d4

LCP PFC: OFF

Conditional Debug: OFF

-------- show plat hard qfp act feature subscriber segment id 0x0000005000005D57 --------

Segment ID: 0x5000005d57

EVSI: 80

Peer Segment ID: 0x5000004d56

QFP vsi if handle: 80

QFP interface name: EVSI80

Segment type: LTERM

Is conditional debug: 0

Is SIP: 0

Segment status: BOUND

Macstring length: 0

Encap info exmem handle: 0x0

Input Classes: 1

Class Id  Flow EVSI      CG Id               QFP Hdl

------------------------------------------------------

11584   16908315 1573220256.1                  81

Output Classes: 1

Class Id  Flow EVSI      CG Id               QFP Hdl

------------------------------------------------------

11585   16908315 1589997875.1                  81

-------- show plat hard qfp act feature subscriber session id 16908315 --------

Session ID: 16908315

EVSI type: TC_FLOW

SIP Segment ID: 0x5000004d56

SIP Segment type: PPPOE

FSP Segment ID: 0x0

FSP Segment type: ----

QFP if handle: 81

QFP interface name: EVSI16908315

SIP TX Seq num: 0

SIP RX Seq num: 0

FSP TX Seq num: 0

FSP RX Seq num: 0

Conditon Debug: 0x00000000

Accounting feature enabled

session

QFP (Quantum Flow Processor) / ESP (Embedded Switch Processor) Show Commands

Verification of Traffic Class "Internet" and ISG Accounting programmed into the QFP/ESP

show platform hardware qfp active feature subscriber session

BRAS-ASR1K#show platform hardware qfp active feature subscriber session

Current number sessions: 1

Current number TC flow: 1

Feature Type: A=Accounting D=Policing(DRL) F=FFR L=L4redirect P=Portbundle T=TC

Session    Type      Segment1      SegType1      Segment2      SegType2 Feature Other

----------------------------------------------------------------------------------------

80     PPP 0x0000005000004d56    PPPOE 0x0000005000005d57    LTERM ----T-

16908315 TC_FLOW 0x0000005000004d56    PPPOE 0x0000000000000000     ---- A-----

show platform hardware qfp active feature subscriber segment id <LTERM Session>

BRAS-ASR1K#show platform hardware qfp active feature subscriber segment id 0x0000005000005d57

Segment ID: 0x5000005d57

EVSI: 80

Peer Segment ID: 0x5000004d56

QFP vsi if handle: 80

QFP interface name: EVSI80

Segment type: LTERM

Is conditional debug: 0

Is SIP: 0

Segment status: BOUND

Macstring length: 0

Encap info exmem handle: 0x0

Input Classes: 1

Class Id  Flow EVSI      CG Id               QFP Hdl

------------------------------------------------------

11584   16908315 1573220256.1                  81

Output Classes: 1

Class Id  Flow EVSI      CG Id               QFP Hdl

------------------------------------------------------

11585   16908315 1589997875.1                  81

show platform hardware qfp active feature subscriber session id <session>

BRAS-ASR1K#show platform hardware qfp active feature subscriber session id 80

Session ID: 80

EVSI type: PPP

SIP Segment ID: 0x5000004d56

SIP Segment type: PPPOE

FSP Segment ID: 0x5000005d57

FSP Segment type: LTERM

QFP if handle: 80

QFP interface name: EVSI80

SIP TX Seq num: 0

SIP RX Seq num: 0

FSP TX Seq num: 0

FSP RX Seq num: 0

Conditon Debug: 0x00000000

TC feature enabled

session

show platform hardware qfp active feature subscriber segment id <Segment ID>

BRAS-ASR1K#show platform hardware qfp active feature subscriber segment id 0x0000005000004d56

Segment ID: 0x5000004d56

EVSI: 80

Peer Segment ID: 0x5000005d57

QFP vsi if handle: 80

QFP interface name: EVSI80

Segment type: PPPOE

Is conditional debug: 0

Is SIP: 1

Segment status: BOUND

Macstring length: 20

00000000  5057  a8d8  02d8  0027  0d2b  4fb4  8864  1100

00000010  0b56  0000  0000  0000  0000  0000  0000  0000

Encap info exmem handle: 0x0

session id: 2902

vcd: 0

mtu: 1492

physical if handle: 49

hash value: 0x00003f00

Input Classes: 1

Class Id  Flow EVSI      CG Id               QFP Hdl

------------------------------------------------------

11584   16908315 1573220256.1                  81

Output Classes: 1

Class Id  Flow EVSI      CG Id               QFP Hdl

------------------------------------------------------

11585   16908315 1589997875.1                  81

show platform hardware qfp active feature subscriber session id <session>

BRAS-ASR1K#show platform hardware qfp active feature subscriber session id 16908315

Session ID: 16908315

EVSI type: TC_FLOW

SIP Segment ID: 0x5000004d56

SIP Segment type: PPPOE

FSP Segment ID: 0x0

FSP Segment type: ----

QFP if handle: 81

QFP interface name: EVSI16908315

SIP TX Seq num: 0

SIP RX Seq num: 0

FSP TX Seq num: 0

FSP RX Seq num: 0

Conditon Debug: 0x00000000

Accounting feature enabled

session

show platform hardware qfp active feature subscriber state feature accounting

BRAS-ASR1K#show platform hardware qfp active feature subscriber state feature accounting

Subscriber Accounting State:

Total Install: 2

Total Remove : 1

Total Query  : 0

Total Update : 0

Total Report (in) : 0

Total Report (out): 0

Total Report Failed (in) : 0

Total Report Failed (out): 0

QFP Number 0:

acct_dbg_cfg: 0x00000000

SBS handle (input dir): 0x111bd9a8

SBS handle (output dir): 0x111bda80

Cisco IOS® XE Debugs

Debugs collected for PPP session with ISG Accounting applied.

Warning: Use debug commands with caution. In general, it is recommended that these commands only be used under the direction of your router technical support representative when remediating specific problems. Enabling debugging can disrupt operation of the router when internetworks are experiencing high load conditions. Hence, if logging is enabled, the access server can intermittently freeze as soon as the console port gets overloaded with log messages.

Please refer to this link before enabling any debug commands: https://www.cisco.com/c/en/us/support/docs/dial-access/integrated-services-digital-networks-isdn-channel-associated-signaling-cas/10374-debug.html

debug condition <ip | mac-address>

debug radius

debug subscriber feature name accounting event

debug subscriber feature name accounting error

debug subscriber feature name accounting detail

debug subscriber policy all

debug subscriber service

debug ssm fhm errors

debug ssm fhm events

debug ssm cm errors

debug ssm cm events

debug ssm sm errors

debug ssm sm events

debug ssm xdr error

debug ssm xdr event

Debug Output

Aug 30 02:06:47.698: AAA/AUTHOR: auth_need : user= 'cisco' ruser= 'BRAS-ASR1K'rem_addr= '10.137.80.251' priv= 1 list= '' AUTHOR-TYPE= 'commands'

Aug 30 02:06:47.976: SSM CM: SSM switch id 15701 [0x3D55] allocated

Aug 30 02:06:47.976: SSM CM: provision switch event, switch id 15701

Aug 30 02:06:47.976: SSM CM[19798]: allocate segment: allocated ID

Aug 30 02:06:47.976: SSM CM[19798]: allocate segment: Locking SSM ID

Aug 30 02:06:47.976: SSM SM ID LOCK: [PPPoE Discovery Daemon:id_lock:19798] locker <SIP>: count 0 --> 1

Aug 30 02:06:47.976: SSM CM[19798]: allocate segment: queue ok

Aug 30 02:06:47.976: AAA/BIND(00000B73): Bind i/f Virtual-Template2

Aug 30 02:06:47.976: SSS PM: ANCP not enabled on 'GigabitEthernet2/3/4' - not retrieving default shaper value

Aug 30 02:06:47.976: SSS PM: ANCP not enabled on 'GigabitEthernet2/3/4' - not retrieving default shaper value

Aug 30 02:06:47.977: SSM SM ID LOCK: [PPPoE Discovery Daemon:id_lock:19798] locker <SSS>: count 0 --> 1

Aug 30 02:06:47.978: SSM CM[19798]: allocate segment: reserved segment id

Aug 30 02:06:47.978: SSM SM ID LOCK: [SSS Manager:id_lock:19798] locker <SSS>: count 1 --> 2

Aug 30 02:06:47.979: SSS PM [7F7439B43390][AAA ID:0]: Create context 7F7439B43390

Aug 30 02:06:47.979: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Authen status update; is now "unauthen"

Aug 30 02:06:47.979: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR: assert authen status "unauthen"

Aug 30 02:06:47.979: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR:  send event Session Update

Aug 30 02:06:47.980: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Username key not found in set domain key API

Aug 30 02:06:47.980: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Username key not found in set domain key API

Aug 30 02:06:47.980: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Updated NAS port for AAA ID 2931

Aug 30 02:06:47.980: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR:  send event Session Update

Aug 30 02:06:47.981: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Client block is NULL in get client block with handle 8B000F38

Aug 30 02:06:47.981: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Updated key list:

Aug 30 02:06:47.983: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   AAA-Acct-Enbl = 1 (YES)

Aug 30 02:06:47.983: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   SHDB-Handle = 1426064214 (55000356)

Aug 30 02:06:47.983: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Input Interface = "GigabitEthernet2/3/4"

Aug 30 02:06:47.983: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Access-Type = 3 (PPPoE)

Aug 30 02:06:47.983: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Protocol-Type = 0 (PPP Access Protocol)

Aug 30 02:06:47.983: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Media-Type = 1 (Ethernet)

Aug 30 02:06:47.983: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Authen-Status = 1 (Unauthenticated)

Aug 30 02:06:47.983: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Nasport = PPPoEoE: slot 2 adapter 1 port 4 IP 10.66.79.146 VPI 0 VCI 0 VLAN 0

Aug 30 02:06:47.983: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Username key not found in set domain key API

Aug 30 02:06:47.983: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Username key not found in set domain key API

Aug 30 02:06:47.983: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Client block is NULL in get client block with handle 8B000F38

Aug 30 02:06:47.983: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Updated key list:

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   AAA-Acct-Enbl = 1 (YES)

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   SHDB-Handle = 1426064214 (55000356)

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Input Interface = "GigabitEthernet2/3/4"

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Access-Type = 3 (PPPoE)

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Protocol-Type = 0 (PPP Access Protocol)

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Media-Type = 1 (Ethernet)

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Authen-Status = 1 (Unauthenticated)

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Nasport = PPPoEoE: slot 2 adapter 1 port 4 IP 10.66.79.146 VPI 0 VCI 0 VLAN 0

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Session-Handle = 2902460078 (AD0006AE)

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: SM Policy invoke - Service Selection Request

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Access type PPPoE

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Successfully added key SUBTYPE_CONVERTED as FALSE

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE: Looking for a rule for event session-start

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE:  Intf CloneSrc Vt2: service-rule any: None

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE:  Intf InputI/f Gi2/3/4: service-rule any: None

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE:  Glob: service-rule any: None

Aug 30 02:06:47.985: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RM/VPDN disabled: RM/VPDN author not needed

Aug 30 02:06:47.986: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Need the key: Unauth-User

Aug 30 02:06:47.986: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: SIP [PPPoE] can provide more keys

Aug 30 02:06:47.986: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Received Service Request

Aug 30 02:06:47.986: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Event <need keys>, State: initial-req to need-init-keys

Aug 30 02:06:47.986: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Policy reply - Need More Keys

Aug 30 02:06:47.986: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR: Need:  Unauth-User

Aug 30 02:06:47.986: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Asking client for more keys

Aug 30 02:06:47.986: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Policy reply - Need More Keys

Aug 30 02:06:47.986: SSM SM ID LOCK: [SSS Manager:id_unlock:19798] locker <SSS>: count 2 --> 1

Aug 30 02:06:47.986: SSM CM[19798]: deallocate segment: SSM ID still in use: postpone deallocate

Aug 30 02:06:47.986: PPP: Alloc Context [7F74247B3350]

Aug 30 02:06:47.986: ppp900 PPP: Phase is ESTABLISHING

Aug 30 02:06:47.986: SSM CM[19798]: provision segment: standby RP received existing id from active RP

Aug 30 02:06:47.986: SSM XDR[19798]: SSM provison segment, slots no slots (0x0) 0x0 not ready, message suppressed

Aug 30 02:06:47.986: SSM SH[19798]: alloc sbase 0x7F7430243E88 hdl 4D56

Aug 30 02:06:47.986: SSM CM[19798]: [PPPoE] provision first allocated base now, reserved earlier

Aug 30 02:06:47.986: SSM CM[19798]: CM FSM: st Idle, ev Prov seg->Down

Aug 30 02:06:47.986: SSM SH[19798]: init segment base

Aug 30 02:06:47.986: SSM SH[SSS:PPPoE:19798]: init segment class

Aug 30 02:06:47.986: SSM SH[ADJ:PPPoE:19798]: init segment class

Aug 30 02:06:47.986: SSM CM[SSS:PPPoE:19798]: provision segment 1

Aug 30 02:06:47.986: SSM SM[SSS:PPPoE:19798]: Provision segment: Idle -> Prov

Aug 30 02:06:47.986: SSM CM[ADJ:PPPoE:19798]: provision segment 1

Aug 30 02:06:47.986: SSM SM[ADJ:PPPoE:19798]: Provision segment: Idle -> Prov

Aug 30 02:06:47.986: SSM SM[ADJ:PPPoE:19798]: provision segment

Aug 30 02:06:47.986: SSM CM[19798]: [PPPoE] send client event, type=Segment event

Aug 30 02:06:47.987: ppp900 PPP: Using vpn set call direction

Aug 30 02:06:47.987: ppp900 PPP: Treating connection as a callin

Aug 30 02:06:47.987: ppp900 PPP: Session handle[38000B56] Session id[900]

Aug 30 02:06:47.987: ppp900 LCP: Event[OPEN] State[Initial to Starting]

Aug 30 02:06:47.987: ppp900 PPP LCP: Enter passive mode, state[Stopped]

Aug 30 02:06:47.991: ppp900 LCP: I CONFREQ [Stopped] id 1 len 14

Aug 30 02:06:47.991: ppp900 LCP:    MRU 1492 (0x010405D4)

Aug 30 02:06:47.991: ppp900 LCP:    MagicNumber 0x5BFE77FB (0x05065BFE77FB)

Aug 30 02:06:47.991: ppp900 LCP: O CONFREQ [Stopped] id 1 len 18

Aug 30 02:06:47.991: ppp900 LCP:    MRU 1492 (0x010405D4)

Aug 30 02:06:47.991: ppp900 LCP:    AuthProto PAP (0x0304C023)

Aug 30 02:06:47.991: ppp900 LCP:    MagicNumber 0x2B68BFB2 (0x05062B68BFB2)

Aug 30 02:06:47.991: ppp900 LCP: O CONFACK [Stopped] id 1 len 14

Aug 30 02:06:47.991: ppp900 LCP:    MRU 1492 (0x010405D4)

Aug 30 02:06:47.991: ppp900 LCP:    MagicNumber 0x5BFE77FB (0x05065BFE77FB)

Aug 30 02:06:47.991: ppp900 LCP: Event[Receive ConfReq+] State[Stopped to ACKsent]

Aug 30 02:06:47.992: ppp900 LCP: I CONFACK [ACKsent] id 1 len 18

Aug 30 02:06:47.992: ppp900 LCP:    MRU 1492 (0x010405D4)

Aug 30 02:06:47.992: ppp900 LCP:    AuthProto PAP (0x0304C023)

Aug 30 02:06:47.992: ppp900 LCP:    MagicNumber 0x2B68BFB2 (0x05062B68BFB2)

Aug 30 02:06:47.992: ppp900 LCP: Event[Receive ConfAck] State[ACKsent to Open]

Aug 30 02:06:48.008: ppp900 PPP: Phase is AUTHENTICATING, by this end

Aug 30 02:06:48.008: ppp900 LCP: State is Open

Aug 30 02:06:48.017: ppp900 PAP: I AUTH-REQ id 1 len 25 from "PPPoE-Client-1"

Aug 30 02:06:48.017: ppp900 PAP: Authenticating peer PPPoE-Client-1

Aug 30 02:06:48.018: ppp900 PPP: Phase is FORWARDING, Attempting Forward

Aug 30 02:06:48.019: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Username key does not have a delimiter in set domain key API

Aug 30 02:06:48.019: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Username key not found in set domain key API

Aug 30 02:06:48.019: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Client block is NULL in get client block with handle 8B000F38

Aug 30 02:06:48.019: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Updated key list:

Aug 30 02:06:48.021: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Access-Type = 0 (PPP)

Aug 30 02:06:48.021: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   AAA-Acct-Enbl = 1 (YES)

Aug 30 02:06:48.021: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   SHDB-Handle = 1426064214 (55000356)

Aug 30 02:06:48.021: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Input Interface = "GigabitEthernet2/3/4"

Aug 30 02:06:48.021: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Converted-Session = 0 (NO)

Aug 30 02:06:48.021: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Media-Type = 1 (Ethernet)

Aug 30 02:06:48.021: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Authen-Status = 1 (Unauthenticated)

Aug 30 02:06:48.021: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Nasport = PPPoEoE: slot 2 adapter 1 port 4 IP 10.66.79.146 VPI 0 VCI 0 VLAN 0

Aug 30 02:06:48.021: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Session-Handle = 2902460078 (AD0006AE)

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Protocol-Type = 0 (PPP Access Protocol)

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Unauth-User = "PPPoE-Client-1"

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: SM Policy invoke - Got More Keys

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Access type PPP

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE: Looking for a rule for event session-start

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE:  Intf CloneSrc Vt2: service-rule any: None

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE:  Intf InputI/f Gi2/3/4: service-rule any: None

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE:  Glob: service-rule any: None

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Received More Initial Keys

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Event <rcvd keys>, State: need-init-keys to check-auth-needed

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Handling Authorization Check

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Check author needed

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:  Have keyset: Unauth-User, Nasport, Input Interface, AccIe-Hdl, AAA-Id, AAA-Acct-Enbl, SHDB-Handle, Media-Type, Protocol-Type, Session-Handle, Authen-Status, Converted-Session

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:  Want keyset: Auth-User

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:  Do we have key: 'Auth-User'?

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: SIP [PPP] can provide more keys

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:  Policy requires 'Auth-User' key

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Event <need keys>, State: check-auth-needed to need-more-keys

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Policy reply - Need More Keys

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR: Need:  Auth-User

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR: ask for authen status

Aug 30 02:06:48.022: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR:  request, Query Session Authenticated Status

Aug 30 02:06:48.023: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR: reply, Query Session Authenticated Status = no-record-found

Aug 30 02:06:48.023: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR:   session NOT authenticated

Aug 30 02:06:48.023: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Event <idmgr did not get keys>, State: need-more-keys to need-more-keys

Aug 30 02:06:48.023: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Asking client for more keys

Aug 30 02:06:48.023: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Policy reply - Need More Keys

Aug 30 02:06:48.023: ppp900 PPP: Phase is AUTHENTICATING, Unauthenticated User

Aug 30 02:06:48.023: AAA/AUTHEN/PPP (00000B73): Pick method list 'default'

Aug 30 02:06:48.024: RADIUS/ENCODE(00000B73):Orig. component type = PPPoE

Aug 30 02:06:48.024: RADIUS: DSL line rate attributes successfully added

Aug 30 02:06:48.024: RADIUS(00000B73): Config NAS IP: 192.168.111.1

Aug 30 02:06:48.024: RADIUS(00000B73): Config NAS IPv6: ::

Aug 30 02:06:48.024: RADIUS/ENCODE: No idb found! Framed IP Addr is not included

Aug 30 02:06:48.024: RADIUS/ENCODE(00000B73): acct_session_id: 2922

Aug 30 02:06:48.024: RADIUS(00000B73): sending

Aug 30 02:06:48.025: RADIUS(00000B73): Send Access-Request to 192.168.111.9:1645 id 21691/86, len 140

Aug 30 02:06:48.025: RADIUS:  authenticator 61 FF 91 F9 08 29 2F DD - DC 1D 4D 62 BC A5 CC 03

Aug 30 02:06:48.025: RADIUS:  Framed-Protocol     [7]   6   PPP                       [1]

Aug 30 02:06:48.025: RADIUS:  User-Name           [1]   16  "PPPoE-Client-1"

Aug 30 02:06:48.025: RADIUS:  User-Password       [2]   18  *

Aug 30 02:06:48.025: RADIUS:  NAS-Port-Type       [61]  6   Virtual                   [5]

Aug 30 02:06:48.025: RADIUS:  NAS-Port            [5]   6   738197504

Aug 30 02:06:48.025: RADIUS:  NAS-Port-Id         [87]  9   "2/3/4/0"

Aug 30 02:06:48.025: RADIUS:  Vendor, Cisco       [26]  41

Aug 30 02:06:48.025: RADIUS:   Cisco AVpair       [1]   35  "client-mac-address=5057.a8d8.02d8"

Aug 30 02:06:48.025: RADIUS:  Service-Type        [6]   6   Framed                    [2]

Aug 30 02:06:48.025: RADIUS:  NAS-IP-Address      [4]   6   192.168.111.1

Aug 30 02:06:48.025: RADIUS:  Event-Timestamp     [55]  6   1472522808

Aug 30 02:06:48.025: RADIUS(00000B73): Sending a IPv4 Radius Packet

Aug 30 02:06:48.025: RADIUS(00000B73): Started 5 sec timeout

Aug 30 02:06:48.026: RADIUS: Received from id 21691/86 192.168.111.9:1645, Access-Accept, len 49

Aug 30 02:06:48.026: RADIUS:  authenticator 40 8A 85 44 B9 61 A0 80 - 2C 1E 18 1B ED 29 87 57

Aug 30 02:06:48.026: RADIUS:  Framed-Protocol     [7]   6   PPP                       [1]

Aug 30 02:06:48.026: RADIUS:  Service-Type        [6]   6   Framed                    [2]

Aug 30 02:06:48.026: RADIUS:  Vendor, Cisco       [26]  17

Aug 30 02:06:48.026: RADIUS:   ssg-account-info   [250] 11  "AInternet"

Aug 30 02:06:48.026: RADIUS(00000B73): Received from id 21691/86

Aug 30 02:06:48.027: ppp900 PPP: Phase is FORWARDING, Attempting Forward

Aug 30 02:06:48.027: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Authen status update; is now "authen"

Aug 30 02:06:48.027: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR: assert authen status "authen"

Aug 30 02:06:48.027: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR:  send event Session Update

Aug 30 02:06:48.027: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR:  with username "PPPoE-Client-1"

Aug 30 02:06:48.028: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Session activation: ok

Aug 30 02:06:48.028: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Username key does not have a delimiter in set domain key API

Aug 30 02:06:48.028: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Username key does not have a delimiter in set domain key API

Aug 30 02:06:48.028: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Client block is NULL in get client block with handle 8B000F38

Aug 30 02:06:48.028: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Updated key list:

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   AAA-Attr-List = 05001CFF

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:     Framed-Protocol      0   1 [PPP]

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:     service-type         0   2 [Framed]

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:     ssg-account-info     0   "AInternet"

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Access-Type = 0 (PPP)

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Unauth-User = "PPPoE-Client-1"

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   AAA-Acct-Enbl = 1 (YES)

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   SHDB-Handle = 1426064214 (55000356)

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Input Interface = "GigabitEthernet2/3/4"

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Converted-Session = 0 (NO)

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Media-Type = 1 (Ethernet)

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Authen-Status = 0 (Authenticated)

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Nasport = PPPoEoE: slot 2 adapter 1 port 4 IP 10.66.79.146 VPI 0 VCI 0 VLAN 0

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Session-Handle = 2902460078 (AD0006AE)

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Protocol-Type = 0 (PPP Access Protocol)

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Final = 1 (YES)

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:   Auth-User = "PPPoE-Client-1"

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: SM Policy invoke - Got More Keys

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Access type PPP: final key

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Must apply config before continuing

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Handling Config Request from Client

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Event <got process config req>, State: need-more-keys to need-more-keys

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Handling Process Config

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Apply config request set to AAA list

Config:   Framed-Protocol      0   1 [PPP]

Config:   service-type         0   2 [Framed]

Config:   ssg-account-info     0   "AInternet"

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Sending PPPoE-Client-1 request to AAA

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: SSS PM: Allocating per-user profile info

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: SSS PM: Add per-user profile info to policy context

Aug 30 02:06:48.032: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Root SIP PPPoE

Aug 30 02:06:48.032: SSS AAA AUTHOR [uid:900][AAA ID:2931]:  Enable PPPoE parsing

Aug 30 02:06:48.032: SSS AAA AUTHOR [uid:900][AAA ID:2931]:  Enable PPP parsing

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: ACTIVE HANDLE[0]: Snapshot captured in Active context

Aug 30 02:06:48.032: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: ACTIVE HANDLE[0]: Active context created

Aug 30 02:06:48.032: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Event <make request>, state changed from idle to authorizing

Aug 30 02:06:48.032: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Active key set to Auth-User

Aug 30 02:06:48.032: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Authorizing key PPPoE-Client-1

Aug 30 02:06:48.033: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Spoofed AAA reply sent for key PPPoE-Client-1

Aug 30 02:06:48.033: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Received an AAA pass

Aug 30 02:06:48.033: SSS AAA AUTHOR [uid:900][AAA ID:2931]: [7F7439B43390]:Reply message not exist

Initial attr  Framed-Protocol      0   1 [PPP]

Initial attr  service-type         0   2 [Framed]

Initial attr  ssg-account-info     0   "AInternet"

Aug 30 02:06:48.033: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:

policy key list does not have IPv4 address

Aug 30 02:06:48.034: COA_HA: [ERR] Unable to get coa_ctx from shdb 0x55000356

Aug 30 02:06:48.034: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE: Service Name = Internet Ok

Aug 30 02:06:48.034: SSS PM: PARAMETERIZED-QoS: QOS parameters

Aug 30 02:06:48.035: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE: VRF Parsing routine:

Framed-Protocol      0   1 [PPP]

service-type         0   2 [Framed]

ssg-account-info     0   "AInternet"

Aug 30 02:06:48.035: SSS PM: No VPDN attributes or policy found

Aug 30 02:06:48.039: SSS AAA AUTHOR [uid:900][AAA ID:2931]: SIP PPP[7F756CC2B030] parsed as Success

Aug 30 02:06:48.039: SSS AAA AUTHOR [uid:900][AAA ID:2931]: SIP PPP[7F756DAD3800] parsed as Ignore

Aug 30 02:06:48.039: SSS AAA AUTHOR [uid:900][AAA ID:2931]: SIP PPPoE[7F756CCD6BF0] parsed as Success

Aug 30 02:06:48.039: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Event <service not found>, state changed from authorizing to complete

Aug 30 02:06:48.039: SSS AAA AUTHOR [uid:900][AAA ID:2931]: No service authorization info found

Aug 30 02:06:48.039: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Active Handle present - B6000D41

Aug 30 02:06:48.039: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Apply config handle [82001D03] now set to [EA001CDB]

Aug 30 02:06:48.039: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: ACTIVE HANDLE[0]: Snapshot reverted from Active context to policy context

Aug 30 02:06:48.039: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Freeing Active Handle; SSS Policy Context Handle = 8B000F38

Aug 30 02:06:48.039: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: ACTIVE HANDLE[29305]: Released active handle

Aug 30 02:06:48.039: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: PROFILE: store profile "PPPoE-Client-1"

Aug 30 02:06:48.039: SSS PM: PROFILE-DB: is profile "PPPoE-Client-1" in DB

Aug 30 02:06:48.039: SSS PM: PROFILE-DB:  Computed hash value = 4099343087

Aug 30 02:06:48.039: SSS PM: PROFILE-DB:  No, add new list

Aug 30 02:06:48.040: SSS PM: PROFILE-DB:   create "PPPoE-Client-1"

Aug 30 02:06:48.040: SSS PM: PROFILE-DB:    create "PPPoE-Client-1"/7F7439BF34E0 hdl A1001D54 ref 1

Aug 30 02:06:48.040: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: PROFILE:  create 7F7439BF7DA0, ref 1

Aug 30 02:06:48.040: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Event <free request>, state changed from complete to terminal

Aug 30 02:06:48.040: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Cancel request

Aug 30 02:06:48.040: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Handling Author Not Found Event

Aug 30 02:06:48.040: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Apply of config finished; returning

Aug 30 02:06:48.040: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: SM Policy invoke - Got More Keys

Aug 30 02:06:48.040: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE: Looking for a rule for event session-start

Aug 30 02:06:48.040: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE:  Intf CloneSrc Vt2: service-rule any: None

Aug 30 02:06:48.040: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE:  Intf InputI/f Gi2/3/4: service-rule any: None

Aug 30 02:06:48.040: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE:  Glob: service-rule any: None

Aug 30 02:06:48.041: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Received More Keys

Aug 30 02:06:48.041: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Event <rcvd keys>, State: need-more-keys to check-auth-needed

Aug 30 02:06:48.041: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Handling Authorization Check

Aug 30 02:06:48.041: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Check author needed

Aug 30 02:06:48.041: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:  Have keyset: Unauth-User, Auth-User, Nasport, Input Interface, AAA-Id, AAA-Acct-Enbl, Resource-Determined, SHDB-Handle, Media-Type, Protocol-Type, Session-Handle, Authen-Status, Converted-Session

Aug 30 02:06:48.041: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:  Want keyset: Auth-User

Aug 30 02:06:48.041: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:  Do we have key: 'Auth-User'?

Aug 30 02:06:48.041: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Event <send auth>, State: check-auth-needed to authorizing

Aug 30 02:06:48.041: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Handling AAA service Authorization

Aug 30 02:06:48.041: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Sending AAA request for 'PPPoE-Client-1'

Aug 30 02:06:48.041: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: SSS PM: Allocating per-user profile info

Aug 30 02:06:48.041: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Authorization:Fetching method list from SIP:PPPoE

Aug 30 02:06:48.041: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Authorization:Failed method list access from SIP:PPPoE

Aug 30 02:06:48.041: SSS PM ERROR: Policy context is NULL or missing action in get aaa author passwd list API

Aug 30 02:06:48.041: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Root SIP PPPoE

Aug 30 02:06:48.041: SSS AAA AUTHOR [uid:900][AAA ID:2931]:  Enable PPPoE parsing

Aug 30 02:06:48.041: SSS AAA AUTHOR [uid:900][AAA ID:2931]:  Enable PPP parsing

Aug 30 02:06:48.041: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: ACTIVE HANDLE[0]: Snapshot captured in Active context

Aug 30 02:06:48.041: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: ACTIVE HANDLE[0]: Active context created

Aug 30 02:06:48.041: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Event <make request>, state changed from idle to authorizing

Aug 30 02:06:48.041: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Active key set to Auth-User

Aug 30 02:06:48.041: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Authorizing key PPPoE-Client-1

Aug 30 02:06:48.042: AAA/AUTHOR (0xB73): Pick method list 'default'

Aug 30 02:06:48.042: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Set authorization profile type default -  user

Aug 30 02:06:48.043: SSS AAA AUTHOR [uid:900][AAA ID:2931]: AAA request sent for key PPPoE-Client-1

Aug 30 02:06:48.043: SSS PM [7F7439B42FB0][AAA ID:0]: Create context 7F7439B42FB0

Aug 30 02:06:48.043: SSS PM [7F7439B42FB0][AAA ID:2931]: key lists to append are empty

Aug 30 02:06:48.043: SSS PM [7F7439B42FB0][AAA ID:2931]: Authen status update; is now "unauthen"

Aug 30 02:06:48.043: SSS PM [7F7439B42FB0][AAA ID:2931]: IDMGR: assert authen status "unauthen"

Aug 30 02:06:48.043: SSS PM [7F7439B42FB0][AAA ID:2931]: SERVICE [Internet]: Parent 7F7439B43390

Aug 30 02:06:48.043: SSS PM [7F7439B42FB0][AAA ID:2931]: SERVICE [Internet]: Started yet? No

Aug 30 02:06:48.043: SSS PM [7F7439B42FB0][AAA ID:2931]: IDMGR: service not started yet; cannot update

Aug 30 02:06:48.043: SSS PM [7F7439B42FB0][AAA ID:2931]: Did not update authen status to IDMGR

Aug 30 02:06:48.043: SSS PM [7F7439B42FB0][AAA ID:2931]: Username key not found in set domain key API

Aug 30 02:06:48.043: SSS PM [7F7439B42FB0][AAA ID:2931]: Username key not found in set domain key API

Aug 30 02:06:48.043: SSS PM [7F7439B42FB0][AAA ID:2931]: Updated NAS port for AAA ID 2931

Aug 30 02:06:48.043: SSS PM [7F7439B42FB0][AAA ID:2931]: IDMGR:  send event Session Update

Aug 30 02:06:48.044: SSS PM [7F7439B42FB0][AAA ID:2931]: Client block is NULL in get client block with handle D8000F3B

Aug 30 02:06:48.045: SSS PM [7F7439B42FB0][AAA ID:2931]: Updated key list:

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]:   Logon-Service = "Internet"

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]:   Nasport = PPPoEoE: slot 2 adapter 1 port 4 IP 10.66.79.146 VPI 0 VCI 0 VLAN 0

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]:   Access-Type = 11 (Web-service-logon)

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]:   Authen-Status = 1 (Unauthenticated)

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]:   Session-Handle = 2902460078 (AD0006AE)

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: Service Command-Handler Policy invoke - Service-Start

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: Access type Web-service-logon

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: RULE: Looking for a rule for event service-start

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: RULE:  Intf CloneSrc Vt2: service-rule any: None

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: RULE:  Intf InputI/f Gi2/3/4: service-rule any: None

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: RULE:  Glob: service-rule any: default-internal-rule

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: RULE:   Evaluate "default-internal-rule" for service-start

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: RULE:    Not matched "default-internal-rule/always event account-logon"

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: RULE:    Not matched "default-internal-rule/always event idle-timeout"

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: RULE:    Not matched "default-internal-rule/always event session-timeout"

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: RULE:    Not matched "default-internal-rule/always event keepalive-timeout"

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: RULE:    Not matched "default-internal-rule/always event flow-timeout"

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: RULE:    Matched "default-internal-rule/always event service-start"

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: RULE:    Matched "default-internal-rule/always event service-start/1 service-policy type service identifier service-name"

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: RULE[0]: Start

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: RULE[0]: default-internal-rule/always event service-start/1 service-policy type service identifier service-name

Aug 30 02:06:48.046: SSS PM CCM:  Found SHDB handle 0x55000356 for policy context 0x7F7439B43390

Aug 30 02:06:48.046: SSS PM CCM:  [SESSION PM EVENT] Event = NEW-REQUEST (ctx: 0x7F7439B43390, action: APPLY-SERVICE)

Aug 30 02:06:48.046: SSS PM HA:  Dynsess not required shdb = 0x55000356 spol_ctx = 0x7F7439B43390

Aug 30 02:06:48.046: SSS PM CCM:  Set PM HA as not ready (session 0x55000356) successfully

Aug 30 02:06:48.046: SSS PM HA:  Adding an action (type APPLY-SERVICE) into the PM HA queue

Aug 30 02:06:48.046: SSS PM HA:  NE: In policy_ha_add_session_info, shdb=0x55000356, last=APPLY-SERVICE (6)

Aug 30 02:06:48.046: SSS PM HA:  In policy_ha_nett_effect_process: ctx=0x7F742BC552A8, action-type=APPLY-SERVICE, event=SERVICE-START, state=INIT-STATE

Aug 30 02:06:48.046: SSS PM HA: NE: Did not find any duplicate service-apply action

Aug 30 02:06:48.046: SSS PM HA:  Setting current elem, from 0x0 to 0x7F742BC50EE0

Aug 30 02:06:48.046: SSS PM CCM:  New bulk session (shdb 0x55000356), ctx 0x7F7439B43390, dsess_hdl 0x0, APPLY-SERVICE OK

Aug 30 02:06:48.046: SSS PM [7F7439B42FB0][AAA ID:2931]: RULE[0]: Have key Logon-Service

Aug 30 02:06:48.047: SSS PM [7F7439B42FB0][AAA ID:2931]: RULE[0]: This service Internet is marked as not cancelled

Aug 30 02:06:48.047: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: State: initial-req to check-auth-needed

Aug 30 02:06:48.047: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: Event <send auth>, State: check-auth-needed to authorizing

Aug 30 02:06:48.047: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: Handling AAA service Authorization

Aug 30 02:06:48.048: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: Sending AAA request for 'Internet'

Aug 30 02:06:48.048: SVM [uid:900][7F7439B42FB0][AAA ID:2931] [Internet]: needs downloading

Aug 30 02:06:48.048: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: service "Internet" not in cache; needs download

Aug 30 02:06:48.049: SVM [uid:900][7F7439B42FB0][AAA ID:2931] [B20001F1/Internet]: allocated version 1

Aug 30 02:06:48.049: SVM [uid:900][7F7439B42FB0][AAA ID:2931] [B20001F1/Internet]: [D8000F3B]: client queued

Aug 30 02:06:48.049: SVM [B20001F1/Internet]: [PM-Download:D8000F3B] locked 0->1

Aug 30 02:06:48.049: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: service download required

Aug 30 02:06:48.049: SVM [B20001F1/Internet]: [AAA-Download:7F743125EEC0] locked 0->1

Aug 30 02:06:48.049: SSS AAA AUTHOR [uid:900][AAA ID:0]: Authorization:Fetching method list from SIP:Web-service-logon

Aug 30 02:06:48.049: SSS AAA AUTHOR [uid:900][AAA ID:0]: Authorization:Failed method list access from SIP:Web-service-logon

Aug 30 02:06:48.049: SSS AAA AUTHOR [uid:900][AAA ID:0]: Root SIP PPPoE

Aug 30 02:06:48.049: SSS AAA AUTHOR [uid:900][AAA ID:0]:  Enable PPPoE parsing

Aug 30 02:06:48.050: SSS AAA AUTHOR [uid:900][AAA ID:0]:  Enable PPP parsing

Aug 30 02:06:48.050: SSS AAA AUTHOR [uid:900][AAA ID:0]:  Enable Web-service-logon parsing

Aug 30 02:06:48.050: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: ACTIVE HANDLE[0]: Snapshot captured in Active context

Aug 30 02:06:48.050: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: ACTIVE HANDLE[0]: Active context created

Aug 30 02:06:48.050: SSS AAA AUTHOR [uid:900][AAA ID:0]: Event <make request>, state changed from idle to authorizing

Aug 30 02:06:48.050: SSS AAA AUTHOR [uid:900][AAA ID:0]: Active key set to Apply-Service

Aug 30 02:06:48.050: SSS AAA AUTHOR [uid:900][AAA ID:0]: Authorizing key Internet

Aug 30 02:06:48.050: AAA/AUTHOR (0x0): Pick method list 'default'

Aug 30 02:06:48.050: SSS AAA AUTHOR [uid:900][AAA ID:0]: Set authorization profile type to service

Aug 30 02:06:48.050: SSS AAA AUTHOR [uid:900][AAA ID:0]: AAA request sent for key Internet

Aug 30 02:06:48.050: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: RULE[0]: Downloading service "Internet"

Aug 30 02:06:48.050: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: RULE[1]: Start

Aug 30 02:06:48.051: RADIUS/ENCODE(00000B73):Orig. component type = PPPoE

Aug 30 02:06:48.051: RADIUS: DSL line rate attributes successfully added

Aug 30 02:06:48.051: RADIUS(00000B73): Config NAS IP: 192.168.111.1

Aug 30 02:06:48.051: RADIUS(00000B73): Config NAS IPv6: ::

Aug 30 02:06:48.051: RADIUS/ENCODE(00000B73): acct_session_id: 2922

Aug 30 02:06:48.051: RADIUS(00000B73): sending

Aug 30 02:06:48.052: RADIUS/ENCODE(00000000):Orig. component type = Invalid

Aug 30 02:06:48.053: RADIUS(00000000): Config NAS IP: 192.168.111.1

Aug 30 02:06:48.053: RADIUS(00000000): Config NAS IPv6: ::

Aug 30 02:06:48.053: RADIUS(00000000): sending

Aug 30 02:06:48.053: RADIUS(00000B73): Send Access-Request to 192.168.111.9:1645 id 21691/87, len 134

Aug 30 02:06:48.053: RADIUS:  authenticator AB 9B 13 37 28 45 B9 5F - 8A 0C 45 79 DE 03 67 9A

Aug 30 02:06:48.053: RADIUS:  User-Name           [1]   16  "PPPoE-Client-1"

Aug 30 02:06:48.053: RADIUS:  User-Password       [2]   18  *

Aug 30 02:06:48.053: RADIUS:  NAS-Port-Type       [61]  6   Virtual                   [5]

Aug 30 02:06:48.053: RADIUS:  NAS-Port            [5]   6   738197504

Aug 30 02:06:48.053: RADIUS:  NAS-Port-Id         [87]  9   "2/3/4/0"

Aug 30 02:06:48.053: RADIUS:  Vendor, Cisco       [26]  41

Aug 30 02:06:48.053: RADIUS:   Cisco AVpair       [1]   35  "client-mac-address=5057.a8d8.02d8"

Aug 30 02:06:48.053: RADIUS:  Service-Type        [6]   6   Outbound                  [5]

Aug 30 02:06:48.054: RADIUS:  NAS-IP-Address      [4]   6   192.168.111.1

Aug 30 02:06:48.054: RADIUS:  Event-Timestamp     [55]  6   1472522808

Aug 30 02:06:48.054: RADIUS(00000B73): Sending a IPv4 Radius Packet

Aug 30 02:06:48.054: RADIUS(00000B73): Started 5 sec timeout

Aug 30 02:06:48.054: RADIUS: nas-port-id(87) is not found in the request

Aug 30 02:06:48.054: RADIUS(00000000): Send Access-Request to 192.168.111.9:1645 id 21691/88, len 66

Aug 30 02:06:48.054: RADIUS:  authenticator 88 26 9B 9D 00 39 F7 BB - 95 D3 93 67 B5 FB 35 9A

Aug 30 02:06:48.054: RADIUS:  User-Password       [2]   18  *

Aug 30 02:06:48.054: RADIUS:  User-Name           [1]   10  "Internet"

Aug 30 02:06:48.054: RADIUS:  Service-Type        [6]   6   Outbound                  [5]

Aug 30 02:06:48.054: RADIUS:  NAS-IP-Address      [4]   6   192.168.111.1

Aug 30 02:06:48.054: RADIUS:  Event-Timestamp     [55]  6   1472522808

Aug 30 02:06:48.054: RADIUS(00000000): Sending a IPv4 Radius Packet

Aug 30 02:06:48.054: RADIUS(00000000): Started 5 sec timeout

Aug 30 02:06:48.055: RADIUS: Received from id 21691/87 192.168.111.9:1645, Access-Accept, len 49

Aug 30 02:06:48.055: RADIUS:  authenticator 2C 28 38 54 02 DF 34 8A - AD A4 C6 6A CB E3 AB E9

Aug 30 02:06:48.055: RADIUS:  Framed-Protocol     [7]   6   PPP                       [1]

Aug 30 02:06:48.055: RADIUS:  Service-Type        [6]   6   Framed                    [2]

Aug 30 02:06:48.055: RADIUS:  Vendor, Cisco       [26]  17

Aug 30 02:06:48.055: RADIUS:   ssg-account-info   [250] 11  "AInternet"

Aug 30 02:06:48.056: RADIUS(00000B73): Received from id 21691/87

Aug 30 02:06:48.056: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Received an AAA pass

Aug 30 02:06:48.056: SSS AAA AUTHOR [uid:900][AAA ID:2931]: [7F7439B43390]:Reply message not exist

Initial attr  Framed-Protocol      0   1 [PPP]

Initial attr  service-type         0   2 [Framed]

Initial attr  ssg-account-info     0   "AInternet"

Aug 30 02:06:48.056: SSS PM [uid:900][7F7439B43390][AAA ID:2931]:

policy key list does not have IPv4 address

Aug 30 02:06:48.057: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE: Service Name =Internet is already active on the session, process next service

Aug 30 02:06:48.057: SSS PM: PARAMETERIZED-QoS: QOS parameters

Aug 30 02:06:48.057: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE: VRF Parsing routine:

Framed-Protocol      0   1 [PPP]

service-type         0   2 [Framed]

ssg-account-info     0   "AInternet"

Aug 30 02:06:48.058: SSS PM: No VPDN attributes or policy found

Aug 30 02:06:48.062: SSS AAA AUTHOR [uid:900][AAA ID:2931]: SIP PPP[7F756CC2B030] parsed as Success

Aug 30 02:06:48.062: SSS AAA AUTHOR [uid:900][AAA ID:2931]: SIP PPP[7F756DAD3800] parsed as Ignore

Aug 30 02:06:48.062: SSS AAA AUTHOR [uid:900][AAA ID:2931]: SIP PPPoE[7F756CCD6BF0] parsed as Success

Aug 30 02:06:48.062: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Event <service not found>, state changed from authorizing to complete

Aug 30 02:06:48.062: SSS AAA AUTHOR [uid:900][AAA ID:2931]: No service authorization info found

Aug 30 02:06:48.062: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Active Handle present - 3D000D42

Aug 30 02:06:48.062: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Attr list is NULL, apply config handle [25001CF0] not reset

Aug 30 02:06:48.062: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: ACTIVE HANDLE[0]: Snapshot reverted from Active context to policy context

Aug 30 02:06:48.062: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Freeing Active Handle; SSS Policy Context Handle = 8B000F38

Aug 30 02:06:48.062: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: ACTIVE HANDLE[29305]: Released active handle

Aug 30 02:06:48.062: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: PROFILE: store profile "PPPoE-Client-1"

Aug 30 02:06:48.062: SSS PM: PROFILE-DB: is profile "PPPoE-Client-1" in DB

Aug 30 02:06:48.062: SSS PM: PROFILE-DB:  Computed hash value = 4099343087

Aug 30 02:06:48.062: SSS PM: PROFILE-DB:  Hash value matches that of the existing profile

Aug 30 02:06:48.062: SSS PM: PROFILE-DB:  Attribute content also matches

Aug 30 02:06:48.062: SSS PM: PROFILE-DB:  Yes, is a known version

Aug 30 02:06:48.062: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: PROFILE:  create 7F7439BF7D78, ref 1

Aug 30 02:06:48.062: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Event <free request>, state changed from complete to terminal

Aug 30 02:06:48.062: SSS AAA AUTHOR [uid:900][AAA ID:2931]: Cancel request

Aug 30 02:06:48.062: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Handling Author Not Found Event

Aug 30 02:06:48.062: RADIUS: Received from id 21691/88 192.168.111.9:1645, Access-Accept, len 277

Aug 30 02:06:48.062: RADIUS:  authenticator EE 5E F0 5E 63 B6 4C 3D - 5E C6 A6 4F 7A B8 43 66

Aug 30 02:06:48.062: RADIUS:  Vendor, Cisco       [26]  17

Aug 30 02:06:48.062: RADIUS:   ssg-service-info   [251] 11  "IInternet"

Aug 30 02:06:48.062: RADIUS:  Vendor, Cisco       [26]  61

Aug 30 02:06:48.062: RADIUS:   Cisco AVpair       [1]   55  "ip:traffic-class=in access-group name ACL-Internet-In"

Aug 30 02:06:48.062: RADIUS:  Vendor, Cisco       [26]  40

Aug 30 02:06:48.062: RADIUS:   Cisco AVpair       [1]   34  "ip:traffic-class=in default drop"

Aug 30 02:06:48.062: RADIUS:  Vendor, Cisco       [26]  63

Aug 30 02:06:48.062: RADIUS:   Cisco AVpair       [1]   57  "ip:traffic-class=out access-group name ACL-Internet-Out"

Aug 30 02:06:48.062: RADIUS:  Vendor, Cisco       [26]  41

Aug 30 02:06:48.062: RADIUS:   Cisco AVpair       [1]   35  "ip:traffic-class=out default drop"

Aug 30 02:06:48.062: RADIUS:  Vendor, Cisco       [26]  35

Aug 30 02:06:48.062: RADIUS:   Cisco AVpair       [1]   29  "accounting-list=ACCNT_LIST1"

Aug 30 02:06:48.063: RADIUS/DECODE(00000000): There is no General DB. Reply server details not recorded

Aug 30 02:06:48.063: RADIUS(00000000): Received from id 21691/88

Aug 30 02:06:48.063: SSS AAA AUTHOR [uid:900][AAA ID:0]: Received an AAA pass

Initial attr  ssg-service-info     0   "IInternet"

Initial attr  traffic-class        0   "in access-group name ACL-Internet-In"

Initial attr  traffic-class        0   "in default drop"

Initial attr  traffic-class        0   "out access-group name ACL-Internet-Out"

Initial attr  traffic-class        0   "out default drop"

Initial attr  accounting-list      0   "ACCNT_LIST1"

Aug 30 02:06:48.063: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]:

policy key list does not have IPv4 address

Aug 30 02:06:48.064: SSS PM: PARAMETERIZED-QoS: QOS parameters

Aug 30 02:06:48.064: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: RULE: VRF Parsing routine:

ssg-service-info     0   "IInternet"

traffic-class        0   "in access-group name ACL-Internet-In"

traffic-class        0   "in default drop"

traffic-class        0   "out access-group name ACL-Internet-Out"

traffic-class        0   "out default drop"

accounting-list      0   "ACCNT_LIST1"

Aug 30 02:06:48.065: SSS PM: No VPDN attributes or policy found

Aug 30 02:06:48.066: SVM [B20001F1/Internet]: Set class ids: 11584.11585

Aug 30 02:06:48.068: SSS AAA AUTHOR [uid:900][AAA ID:0]: SIP PPP[7F756CC2B030] parsed as Success

Aug 30 02:06:48.068: SSS AAA AUTHOR [uid:900][AAA ID:0]: SIP PPP[7F756DAD3800] parsed as Ignore

Aug 30 02:06:48.068: SSS AAA AUTHOR [uid:900][AAA ID:0]: SIP PPPoE[7F756CCD6BF0] parsed as Success

Aug 30 02:06:48.068: SSS AAA AUTHOR [uid:900][AAA ID:0]: Event <service not found>, state changed from authorizing to complete

Aug 30 02:06:48.068: SSS AAA AUTHOR [uid:900][AAA ID:0]: No service authorization info found

Aug 30 02:06:48.068: SSS AAA AUTHOR [uid:900][AAA ID:0]: Active Handle present - FD000D43

Aug 30 02:06:48.068: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: Attr list is NULL, apply config handle [0] not reset

Aug 30 02:06:48.068: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: ACTIVE HANDLE[0]: Snapshot reverted from Active context to policy context

Aug 30 02:06:48.068: SSS AAA AUTHOR [uid:900][AAA ID:0]: Freeing Active Handle; SSS Policy Context Handle = D8000F3B

Aug 30 02:06:48.068: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: ACTIVE HANDLE[29305]: Released active handle

Aug 30 02:06:48.068: SSS PM [7F7439B42BD0][AAA ID:0]: Create context 7F7439B42BD0

Aug 30 02:06:48.068: SSS PM: PROFILE-DB: is profile "Internet" in DB

Aug 30 02:06:48.069: SSS PM: PROFILE-DB:  Computed hash value = 4239442925

Aug 30 02:06:48.069: SSS PM: PROFILE-DB:  No, add new list

Aug 30 02:06:48.069: SSS PM: PROFILE-DB:   create "Internet"

Aug 30 02:06:48.069: SSS PM: PROFILE-DB:    create "Internet"/7F7439BF3510 hdl 74001D20 ref 1

Aug 30 02:06:48.069: SVM [7F7439B42BD0][AAA ID:0] [B20001F1/Internet]: set accounting handle

Aug 30 02:06:48.069: SVM [7F7439B42BD0][AAA ID:0] [B20001F1/Internet]: downloaded first version

Aug 30 02:06:48.069: SSS AAA AUTHOR [uid:900][AAA ID:0]: SVM download for "Internet" ok

Aug 30 02:06:48.069: SVM [uid:900][7F7439B42FB0][AAA ID:2931] [B20001F1/Internet]: [D8000F3B]: client download ok

Aug 30 02:06:48.069: SVM [B20001F1/Internet]: [SVM-to-client-msg:D8000F3B] locked 0->1

Aug 30 02:06:48.069: SVM [B20001F1/Internet]: [AAA-Download:7F743125EEC0] unlocked 1->0

Aug 30 02:06:48.069: SSS AAA AUTHOR [uid:900][AAA ID:0]: Event <free request>, state changed from complete to terminal

Aug 30 02:06:48.069: SSS AAA AUTHOR [uid:900][AAA ID:0]: Cancel request

Aug 30 02:06:48.069: SSS PM [7F7439B42BD0][AAA ID:0]: Destroy context 7F7439B42BD0

Aug 30 02:06:48.069: SSS PM: [PARAMETERIZED-QoS]: In removed_from_rbpl_ctx_temp_hold for policy handle[8F000F39

Aug 30 02:06:48.069: SSS PM [7F7439B42BD0][AAA ID:0]: [PARAMETERIZED-QoS]: No rabapol context created yet for handle [8F000F39], nothing to return

Aug 30 02:06:48.069: COA_CCM: [SESSION FREE] Policy ctx: 0x7F7439B42BD0

Aug 30 02:06:48.069: COA_CCM: Free session - Ignoring policy context 0x7F7439B42BD0 (not our session)

Aug 30 02:06:48.069: SSS PM CCM:  [SESSION FREE] policy ctx: 0x7F7439B42BD0

Aug 30 02:06:48.069: SSS PM CCM:  [ERR] Free session - Ignoring policy context 0x7F7439B42BD0 (not our HA session)

Aug 30 02:06:48.069: SSS PM [7F7439B42BD0][AAA ID:0]: PROFILE: destroy all config

Aug 30 02:06:48.069: SSS PM [7F7439B42BD0][AAA ID:0]: SSS PM: destroy all user profile info from policy context

Aug 30 02:06:48.069: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: SVM service download success

Aug 30 02:06:48.069: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: download completed for "Internet" version 1

Aug 30 02:06:48.069: SVM [uid:900][7F7439B42FB0][AAA ID:2931] [B20001F1/Internet]: alloc feature info

Aug 30 02:06:48.069: SVM [B20001F1/Internet]: [SVM-Feature-Info:7F7439BF3C10] locked 0->1

Aug 30 02:06:48.069: SVM [uid:900][7F7439B42FB0][AAA ID:2931] [B20001F1/Internet]: has Policy info

Aug 30 02:06:48.069: SVM [B20001F1/Internet]: [PM-Info:7F7439BE9D78] locked 0->1

Aug 30 02:06:48.069: SVM [uid:900][7F7439B42FB0][AAA ID:2931] [B20001F1/Internet]: has Policy info

Aug 30 02:06:48.069: SVM [B20001F1/Internet]: [PM-Info:7F7439BE9D18] unlocked 1->0

Aug 30 02:06:48.069: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: PROFILE: store profile "Internet"

Aug 30 02:06:48.069: SSS PM: PROFILE-DB:   incremented ref "Internet"/7F7439BF3510 hdl 74001D20 ref 2

Aug 30 02:06:48.069: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: PROFILE:  create 7F7439BF7D50, ref 1

Aug 30 02:06:48.069: SVM [uid:900][7F7439B42FB0][AAA ID:2931] [B20001F1/Internet]: populated client

Aug 30 02:06:48.069: SVM [B20001F1/Internet]: [PM-Download:D8000F3B] unlocked 1->0

Aug 30 02:06:48.069: SVM [B20001F1/Internet]: [SVM-to-client-msg:D8000F3B] unlocked 1->0

Aug 30 02:06:48.069: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: RULE: VRF/Classname Check: session logging off or not VRF/Classname dependent

Aug 30 02:06:48.069: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: Handling Author Not Found Event

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: Feature info: 7F7439BF3C10 Type: Service Config

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]:             : Config level: Service Profile

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]:             : IDB type: Sub-if or not required

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]:             : 16 bytes:

SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]:             : Data: 000000 00 00 B2 00 01 F1 00 00  ........

SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]:             : Data: 000008 00 00 D8 00 0F 3B 00 00  .....;..

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: Service starting

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: SERVICE [Internet]: Parent 7F7439B43390

Aug 30 02:06:48.070: SVM [B20001F1/Internet]: [PM-Service:7F7439BFBE98] locked 0->1

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Client block is NULL in get client block with handle 8B000F38

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: SERVICE [Internet]: Start-pending request: Ok

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: Event <srvf not found>, State: authorizing to check-auth-needed

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: Handling Next Authorization Check

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: RULE[0]: Continue

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: RULE[0]: default-internal-rule/always event service-start/1 service-policy type service identifier service-name

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: RULE[0]: No more actions to run

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: RULE[1]: Continue

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: RULE[1]: default-internal-rule/always event service-start/1 service-policy type service identifier service-name

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: RULE[1]: Give default directive

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: RULE[2]: Continue

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: RULE[2]: default-internal-rule/always event service-start/1 service-policy type service identifier service-name

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: Event <srvf found>, State: check-auth-needed to wait-for-events

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: All auto services downloaded and cached,proceed with rule execution

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Service Command-Handler Policy invoke - Auto Services Downloaded

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Handling Config Apply to SM

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: No service given yet; wait

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Giving the default-directive

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Policy reply - Local Terminate

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: State: authorizing to initial-req

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Event <srvf found>, State: initial-req to wait-for-events

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Handling Service Direction

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Policy reply - Local Terminate

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Plumbing proposed by default, not FSP

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Policy reply - Local Terminate

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE: Looking for a rule for event session-service-found

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE:  Intf CloneSrc Vt2: service-rule any: None

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE:  Intf InputI/f Gi2/3/4: service-rule any: None

Aug 30 02:06:48.070: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: RULE:  Glob: service-rule any: None

Aug 30 02:06:48.082: SSM CM[23895]: provision segment: allocated ID

Aug 30 02:06:48.082: SSM CM[23895]: provision segment: Locking SSM ID

Aug 30 02:06:48.082: SSM SM ID LOCK: [SSS Manager:id_lock:23895] locker <SIP>: count 0 --> 1

Aug 30 02:06:48.082: SSM XDR[23895]: SSM provison segment, slots no slots (0x0) 0x0 not ready, message suppressed

Aug 30 02:06:48.082: SSM SM ID LOCK: [SSS Manager:id_lock:19798] locker <SSF>: count 0 --> 1

Aug 30 02:06:48.083: SSM SM ID LOCK: [SSS Feature Manager:id_lock:19798] locker <SSF>: count 1 --> 2

Aug 30 02:06:48.083: Accounting: Apply outbound direction from Service Profile configuration

Aug 30 02:06:48.083: Accounting: allocated context handle(0x4A000002) for accounting feature cp context(0x7F743A303CF0)

Aug 30 02:06:48.084: Accounting[uid:900]: Seg hdl[%x] Acct Context[%x]: Install service (iedge_acct_install_service_accounting) accounting for

Aug 30 02:06:48.084: Accounting[uid:900]: Trying to get the sync data for ctx[7F743A303CF0] type[3]

Aug 30 02:06:48.084: SVM [B20001F1/Internet]: [Accounting-Feature:7F743A303CF0] locked 0->1

Aug 30 02:06:48.086: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Got AAA flow creation notification for service, AAAID: 0xB73

Aug 30 02:06:48.088: Accounting[uid:900]: Flow ID associated with accounting feature

Aug 30 02:06:48.088: Accounting[uid:900]: Method list set for AAA flow Id

Aug 30 02:06:48.088: Accounting[uid:900]: Username inherited for AAA flow Id

Aug 30 02:06:48.088: Accounting[uid:900]: iedge acct context is NULL or acct accuracy not enabled

Aug 30 02:06:48.088: Accounting[uid:900]: Obtained record(7F743A14CD90) from SSS CQ lib

Aug 30 02:06:48.088: Accounting: iEdge Accounting send flow start record success to AAA.

Aug 30 02:06:48.088: Accounting[uid:900]: Append successful for start record

Aug 30 02:06:48.088: Accounting[uid:900]: Service start record sent

Aug 30 02:06:48.088: Accounting: Update inbound direction from Service Profile configuration

Aug 30 02:06:48.089: SVM [B20001F1/Internet]: [FM-Bind:AD0006AE] locked 0->1

Aug 30 02:06:48.089: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: SERVICE [Internet]: Bind notify: Ok

Aug 30 02:06:48.089: SSM CM FH[19798:ft 7512:7512]: install feature

Aug 30 02:06:48.090: SSM XDR[19798]: SSM feature install, slots no slots (0x0) 0x0 not ready, message suppressed

Aug 30 02:06:48.090: SSM CM FH[19798]: install feature: queue ok [Ready]

Aug 30 02:06:48.090: SSM CM FH[19798:ft 11609:11609]: install feature

Aug 30 02:06:48.090: SSM XDR[19798]: SSM feature install, slots no slots (0x0) 0x0 not ready, message suppressed

Aug 30 02:06:48.090: SSM CM FH[19798]: install feature: queue ok [Ready]

Aug 30 02:06:48.090: SSM CM FH[ft 11609:11609]: update feature

Aug 30 02:06:48.090: SSM XDR: SSM feature update, slots no slots (0x0) 0x0 not ready, message suppressed

Aug 30 02:06:48.090: SSM CM FH[ft 11609:11609]: update feature: queue ok [Ready]

Aug 30 02:06:48.090: SVM [B20001F1/Internet]: [SVM-Feature-Info:7F7439BF3C10] unlocked 1->0

Aug 30 02:06:48.090: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: SM Policy invoke - Apply Config Success

Aug 30 02:06:48.090: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: [PARAMETERIZED-QoS]: No rabapol context created yet for handle [8B000F38], returning compatible

Aug 30 02:06:48.090: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Event <got apply config success>, State: wait-for-events to wait-for-events

Aug 30 02:06:48.090: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Handling Apply Config; SUCCESS

Aug 30 02:06:48.090: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: session start done

Aug 30 02:06:48.090: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Removed attribute list just processed

Aug 30 02:06:48.090: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: SERVICE [Internet]: Complete-Pending

Aug 30 02:06:48.090: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR: service start

Aug 30 02:06:48.090: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR:  send event Service Assert

Aug 30 02:06:48.090: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR:  with service name "Internet"

Aug 30 02:06:48.090: SVM [B20001F1/Internet]: already downloaded; sharing

Aug 30 02:06:48.091: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR: assert authen status "authen"

Aug 30 02:06:48.091: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR:  send event Service Update

Aug 30 02:06:48.091: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: IDMGR:  with service name "Internet"

Aug 30 02:06:48.092: SVM [B20001F1/Internet]: already downloaded; sharing

Aug 30 02:06:48.093: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: IDMGR: update service

Aug 30 02:06:48.093: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: IDMGR:  send event Service Update

Aug 30 02:06:48.093: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: IDMGR:  with service name "Internet"

Aug 30 02:06:48.093: SVM [B20001F1/Internet]: already downloaded; sharing

Aug 30 02:06:48.094: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: SERVICE [Internet]: Started

Aug 30 02:06:48.094: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: no callback for callback north

Aug 30 02:06:48.094: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Client block is NULL in get client block with handle 8B000F38

Aug 30 02:06:48.094: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Null client block; Cannot update RP

Aug 30 02:06:48.094: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: Client block is NULL in get client block with handle 8B000F38

Aug 30 02:06:48.094: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: AUTOSERVICE [Internet]: Clearing set callbacks

Aug 30 02:06:48.094: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: AUTOSERVICE [Internet]: Result Apply Config Success

Aug 30 02:06:48.094: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: AUTOSERVICE [Internet]: Logged onto service.

Aug 30 02:06:48.094: SSS PM [uid:900][7F7439B42FB0][AAA ID:2931]: AUTOSERVICE [Internet]: Removing auto service entry from the parent policy context list

Aug 30 02:06:48.094: COA_HA: [ERR] Unable to get coa_ctx from shdb 0x55000356

Aug 30 02:06:48.094: SSS PM CCM:  Found SHDB handle 0x55000356 for policy context 0x7F7439B43390

Aug 30 02:06:48.094: SSS PM CCM:  [SESSION PM EVENT] Event = REQUEST-SUCCESS (ctx: 0x7F7439B43390)

Aug 30 02:06:48.094: SSS PM CCM:  dynsess handle for shdb handle 0x55000356 not yet available (need to create one)

Aug 30 02:06:48.094: SSS PM HA:  In policy_ha_session_update: Updating PM HA session 0x55000356 (context 0x7F742BC552A8)

Aug 30 02:06:48.094: SSS PM HA: Processing element 7F742BC50EE0

Aug 30 02:06:48.094: SSS PM HA: 7F742BC50EE0 is currently in state 1

Aug 30 02:06:48.094: SSS PM HA: 7F742BC50EE0 state changed to 2

Aug 30 02:06:48.094: SSS PM HA: [uid:900][7F7439B43390][AAA ID:2931] Found NO actions pending to replay (session-start) state READY-STATE

Aug 30 02:06:48.094: SSS PM HA: [uid:900][7F7439B43390][AAA ID:2931] Found 1 actions pending to replay (after-session-start-is-done) state READY-STATE

Aug 30 02:06:48.094: SSS PM HA: [uid:900][7F7439B43390][AAA ID:2931] Found NO actions pending to replay (after-session-start-is-done) state PENDING-STATE

Aug 30 02:06:48.094: SSS PM HA: [uid:900][7F7439B43390][AAA ID:2931] Found NO actions pending to replay (session-start) state SYNCED-STATE

Aug 30 02:06:48.094: SSS PM HA: [uid:900][7F7439B43390][AAA ID:2931] Found NO actions pending to replay (after-session-start-is-done) state SYNCED-STATE

Aug 30 02:06:48.094: SSS PM CCM:  policy_ha_ccm_update_session: There are 1 READY actions and 0 SYNCED actions, so mark CCM READY

Aug 30 02:06:48.094: SSS PM CCM:  Set PM HA as sync ready (session 0x55000356) successfully

Aug 30 02:06:48.094: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: No pending events to process

Aug 30 02:06:48.094: SSS PM [uid:900][7F7439B43390][AAA ID:2931]: No pending eventst

Aug 30 02:06:48.094: Accounting[uid:900]: No need to install accounting on TC session up

Aug 30 02:06:48.096: SSM XDR[19798]: SSM update segment, slots no slots (0x0) 0x0 not ready, message suppressed

Aug 30 02:06:48.096: SSM CM[19798]: update segment: queue ok

Aug 30 02:06:48.096: SSM CM: Query Lterm to PPPoE switching, enabled

Aug 30 02:06:48.096: SSM SH[23895]: alloc sbase 0x7F7430243DB0 hdl 5D57

Aug 30 02:06:48.096: SSM CM[23895]: [Lterm] provision second allocated base now, never reserved

Aug 30 02:06:48.096: SSM CM[23895]: CM FSM: st Down, ev Prov seg->Open

Aug 30 02:06:48.096: SSM SH[23895]: init segment base

Aug 30 02:06:48.096: SSM SH[SSS:Lterm:23895]: init segment class

Aug 30 02:06:48.096: SSM SH[ADJ:Lterm:23895]: init segment class

Aug 30 02:06:48.096: SSM CM[SSS:Lterm:23895]: provision segment 2

Aug 30 02:06:48.096: SSM SM[SSS:Lterm:23895]: Provision segment: Idle -> Prov

Aug 30 02:06:48.096: SSM CM[23895]: [SSS] shQ request send ready event

Aug 30 02:06:48.096: SSM CM[ADJ:Lterm:23895]: provision segment 2

Aug 30 02:06:48.096: SSM SM[ADJ:Lterm:23895]: Provision segment: Idle -> Prov

Aug 30 02:06:48.096: SSM SM[ADJ:Lterm:23895]: lterm provision segment siptype:0

Aug 30 02:06:48.096: SSM CM[23895]: [ADJ] shQ request send ready event

Aug 30 02:06:48.096: SSM CM[23895]: SM msg event send ready event

Aug 30 02:06:48.096: SSM SM[SSS:Lterm:23895]: segment ready

Aug 30 02:06:48.096: SSM SM[SSS:Lterm:23895]: Found segment data: Prov -> Ready

Aug 30 02:06:48.096: SSM CM[23895]: SM msg event send ready event

Aug 30 02:06:48.096: SSM SM[ADJ:Lterm:23895]: segment ready

Aug 30 02:06:48.096: SSM SM[ADJ:Lterm:23895]: Found segment data: Prov -> Ready

Aug 30 02:06:48.097: SSM CM FH[ft 7512:7512]: alloc base: ok

Aug 30 02:06:48.097: SSM CM FH[19798:ft 7512:7512]: alloc class: ok

Aug 30 02:06:48.097: SSM FH FH[19798:ft 7512:7512]: Install feature: Idle -> Installed

Aug 30 02:06:48.098: SSM CM FH[19798:ft 7512:7512]: queue event: feature ready

Aug 30 02:06:48.098: SSM CM FH[19798:ft 7512:7512]: installed class

Aug 30 02:06:48.098: SSM CM FH[19798:ft 7512:7512]: alloc class: ok

Aug 30 02:06:48.098: SSM FH FH[19798:ft 7512:7512]: Install feature: Idle -> Installed

Aug 30 02:06:48.098: SSM FH FH[19798:ft 7512:7512]: Platform feature install

Aug 30 02:06:48.099: SSM CM FH[19798:ft 7512:7512]: queue event: feature ready

Aug 30 02:06:48.099: SSM CM FH[19798:ft 7512:7512]: installed class

Aug 30 02:06:48.099: SSM CM FH[19798:ft 7512:7512]: install: ok

Aug 30 02:06:48.099: SSM CM FH[19798:ft 7512:7512]: feature event: feature ready

Aug 30 02:06:48.099: SSM FH FH[19798:ft 7512:7512]: Feature data ready: Installed -> Ready

Aug 30 02:06:48.099: SSM CM FH[19798:ft 7512:7512]: feature ready, bind?

Aug 30 02:06:48.099: SSM CM FH[SSS:PPPoE:19798]: check ready all: segment failed

Aug 30 02:06:48.099: SSM CM FH[19798]: check ready all: failed for class SSS

Aug 30 02:06:48.099: SSM CM[SSS:PPPoE:19798]: not all segments/features ready

Aug 30 02:06:48.099: SSM CM FH[19798:ft 7512:7512]: feature event: feature ready

Aug 30 02:06:48.099: SSM FH FH[19798:ft 7512:7512]: Feature data ready: Installed -> Ready

Aug 30 02:06:48.099: SSM CM FH[19798:ft 7512:7512]: feature ready, bind?

Aug 30 02:06:48.099: SSM CM FH[ADJ:PPPoE:19798]: check ready all: segment failed

Aug 30 02:06:48.099: SSM CM FH[19798]: check ready all: failed for class ADJ

Aug 30 02:06:48.099: SSM CM[ADJ:PPPoE:19798]: not all segments/features ready

Aug 30 02:06:48.099: SSM CM FH[ft 11609:11609]: alloc base: ok

Aug 30 02:06:48.099: SSM CM FH[19798:ft 11609:11609]: alloc class: ok

Aug 30 02:06:48.099: SSM FH FH[19798:ft 11609:11609]: Install feature: Idle -> Installed

Aug 30 02:06:48.100: SSM ERROR FH FH[19798:ft 11609:11609]: no data-plane context

Aug 30 02:06:48.100: SSM FH FH[uid:900:19798:ft 11609:Accounting:11609]: created 7F743A3BC360

Aug 30 02:06:48.100: SSM FH FH[uid:900:19798:ft 11609:Accounting:11609]: added 7F743A3BC360 [outbound]

Aug 30 02:06:48.101: SSM FH FH[uid:900:19798:ft 11609:Accounting:11609]: installed: ok

Aug 30 02:06:48.101: SSM FH FH[uid:900:19798:ft 11609:Accounting:11609]: installed: ok

Aug 30 02:06:48.101: SSM CM FH[19798:ft 11609:11609]: queue event: feature ready

Aug 30 02:06:48.101: SSM CM FH[19798:ft 11609:11609]: installed class

Aug 30 02:06:48.101: SSM CM FH[19798:ft 11609:11609]: alloc class: ok

Aug 30 02:06:48.101: SSM FH FH[19798:ft 11609:11609]: Install feature: Idle -> Installed

Aug 30 02:06:48.101: SSM FH FH[19798:ft 11609:11609]: Platform feature install

Aug 30 02:06:48.101: SSM CM FH[19798:ft 11609:11609]: queue event: feature ready

Aug 30 02:06:48.101: SSM CM FH[19798:ft 11609:11609]: installed class

Aug 30 02:06:48.101: SSM CM FH[19798:ft 11609:11609]: install: ok

Aug 30 02:06:48.101: SSM CM FH[19798:ft 11609:11609]: feature event: feature ready

Aug 30 02:06:48.101: SSM FH FH[19798:ft 11609:11609]: Feature data ready: Installed -> Ready

Aug 30 02:06:48.101: SSM CM FH[19798:ft 11609:11609]: feature ready, bind?

Aug 30 02:06:48.101: SSM CM FH[SSS:PPPoE:19798]: check ready all: segment failed

Aug 30 02:06:48.101: SSM CM FH[19798]: check ready all: failed for class SSS

Aug 30 02:06:48.101: SSM CM[SSS:PPPoE:19798]: not all segments/features ready

Aug 30 02:06:48.101: SSM CM FH[19798:ft 11609:11609]: feature event: feature ready

Aug 30 02:06:48.101: SSM FH FH[19798:ft 11609:11609]: Feature data ready: Installed -> Ready

Aug 30 02:06:48.101: SSM CM FH[19798:ft 11609:11609]: feature ready, bind?

Aug 30 02:06:48.101: SSM CM FH[ADJ:PPPoE:19798]: check ready all: segment failed

Aug 30 02:06:48.101: SSM CM FH[19798]: check ready all: failed for class ADJ

Aug 30 02:06:48.101: SSM CM[ADJ:PPPoE:19798]: not all segments/features ready

Aug 30 02:06:48.102: SSM FH FH[uid:900:ft 11609:Accounting:11609]: updated: ok

Aug 30 02:06:48.102: SSM FH FH[19798:ft 11609:11609]: Update feature: no state change, Ready

Aug 30 02:06:48.102: SSM FH FH[19798:ft 11609:11609]: created 7F743A3BC308

Aug 30 02:06:48.102: SSM FH FH[19798:ft 11609:11609]: added 7F743A3BC308 [inbound]

Aug 30 02:06:48.102: SSM FH FH[19798:ft 11609:11609]: installed: ok

Aug 30 02:06:48.102: SSM FH FH[uid:900:19798:ft 11609:Accounting:11609]: updated: ok

Aug 30 02:06:48.102: SSM CM FH[19798:ft 11609:11609]: update: class SSS updated

Aug 30 02:06:48.102: SSM FH FH[19798:ft 11609:11609]: Update feature: no state change, Ready

Aug 30 02:06:48.102: SSM FH FH[19798:ft 11609:11609]: Platform feature update

Aug 30 02:06:48.102: SSM CM FH[19798:ft 11609:11609]: update: class ADJ updated

Aug 30 02:06:48.102: SSM CM FH[ft 11609:11609]: update: ok

Aug 30 02:06:48.102: SSM CM[19798]: segment update

Aug 30 02:06:48.102: SSM CM[19798]: CM FSM: st Open, ev Upd seg->Open

Aug 30 02:06:48.102: SSM CM[SSS:PPPoE:19798]: update segment

Aug 30 02:06:48.102: SSM SM[SSS:PPPoE:19798]: Update segment: no state change, Prov

Aug 30 02:06:48.102: SSM CM[19798]: [SSS] shQ request send ready event

Aug 30 02:06:48.102: SSM CM[ADJ:PPPoE:19798]: update segment

Aug 30 02:06:48.102: SSM SM[ADJ:PPPoE:19798]: Update segment: no state change, Prov

Aug 30 02:06:48.102: SSM SM[ADJ:PPPoE:19798]: Update segment

Aug 30 02:06:48.102: SSM CM[19798]: [ADJ] shQ request send ready event

Aug 30 02:06:48.102: SSM CM[19798]: SM msg event send ready event

Aug 30 02:06:48.102: SSM SM[SSS:PPPoE:19798]: segment ready

Aug 30 02:06:48.102: SSM SM[SSS:PPPoE:19798]: Found segment data: Prov -> Ready

Aug 30 02:06:48.102: SSM SM[SSS:Lterm:23895]: Bind segment: Ready -> Active

Aug 30 02:06:48.103: SSM CM[23895]: [SSS] shQ request send ready event

Aug 30 02:06:48.103: SSM SM[SSS:PPPoE:19798]: Bind segment: Ready -> Active

Aug 30 02:06:48.103: SSM CM FH[ft 7512:7512]: prepare for bind

Aug 30 02:06:48.103: SSM FH FH[19798:ft 7512:7512]: Bind feature: Ready -> Active

Aug 30 02:06:48.103: SSM CM FH[ft 11609:11609]: prepare for bind

Aug 30 02:06:48.103: SSM FH FH[19798:ft 11609:11609]: Bind feature: Ready -> Active

Aug 30 02:06:48.103: SSM FH FH[uid:900:19798:ft 11609:Accounting:11609]: bound

Aug 30 02:06:48.103: SSM CM[19798]: SM msg event send ready event

Aug 30 02:06:48.103: SSM SM[ADJ:PPPoE:19798]: segment ready

Aug 30 02:06:48.103: SSM SM[ADJ:PPPoE:19798]: Found segment data: Prov -> Ready

Aug 30 02:06:48.103: SSM SM[ADJ:Lterm:23895]: Bind segment: Ready -> Active

Aug 30 02:06:48.103: SSM SM[ADJ:Lterm:23895]: bind segment siptype:0

Aug 30 02:06:48.103: SSM CM[23895]: [ADJ] shQ request send ready event

Aug 30 02:06:48.103: SSM SM[ADJ:PPPoE:19798]: Bind segment: Ready -> Active

Aug 30 02:06:48.103: SSM SM[ADJ:PPPoE:19798]: bind segment

Aug 30 02:06:48.103: SSM CM FH[ft 7512:7512]: prepare for bind

Aug 30 02:06:48.103: SSM FH FH[19798:ft 7512:7512]: Bind feature: Ready -> Active

Aug 30 02:06:48.103: SSM FH FH[19798:ft 7512:7512]: Platform feature bind

Aug 30 02:06:48.103: SSM CM FH[ft 11609:11609]: prepare for bind

Aug 30 02:06:48.103: SSM FH FH[19798:ft 11609:11609]: Bind feature: Ready -> Active

Aug 30 02:06:48.103: SSM FH FH[19798:ft 11609:11609]: Platform feature bind

Aug 30 02:06:48.103: SSM CM[23895]: SM msg event send ready event

Aug 30 02:06:48.104: SSM SM[SSS:Lterm:23895]: segment ready

Aug 30 02:06:48.104: SSM SM[SSS:Lterm:23895]: Found segment data: no state change, Active

Aug 30 02:06:48.104: SSM CM[23895]: SM msg event send ready event

Aug 30 02:06:48.104: SSM SM[ADJ:Lterm:23895]: segment ready

Aug 30 02:06:48.104: SSM SM[ADJ:Lterm:23895]: Found segment data: no state change, Active

Aug 30 02:06:48.104: SSM CM[19798]: [PPPoE] send client event, type=Segment event

Aug 30 02:06:48.104: SSM CM[23895]: [Lterm] send client event, type=Segment event

Aug 30 02:06:48.104: AAA/BIND(00000B73): Bind i/f Virtual-Access2.1

Aug 30 02:06:48.104: Vi2.1 PPP: Phase is AUTHENTICATING, Authenticated User

Aug 30 02:06:48.104: Vi2.1 PAP: O AUTH-ACK id 1 len 5

Aug 30 02:06:48.104: SSM SM[ADJ:PPPoE:19798]: platform get counters

Aug 30 02:06:48.104: SSS PM: ANCP not enabled on 'GigabitEthernet2/3/4' - not retrieving default shaper value

Aug 30 02:06:48.105: SSS PM: ANCP not enabled on 'GigabitEthernet2/3/4' - not retrieving default shaper value

Aug 30 02:06:48.105: Vi2.1 PPP: Phase is UP

Aug 30 02:06:48.105: Vi2.1 IPCP: Protocol configured, start CP. state[Initial]

Aug 30 02:06:48.105: Vi2.1 IPCP: Event[OPEN] State[Initial to Starting]

Aug 30 02:06:48.105: Vi2.1 IPCP: O CONFREQ [Starting] id 1 len 10

Aug 30 02:06:48.105: Vi2.1 IPCP:    Address 192.0.2.0 (0x0306C8C8C8C8)

Aug 30 02:06:48.105: Vi2.1 IPCP: Event[UP] State[Starting to REQsent]

Aug 30 02:06:48.106: Vi2.1 IPCP: I CONFREQ [REQsent] id 1 len 10

Aug 30 02:06:48.106: Vi2.1 IPCP:    Address 0.0.0.0 (0x030600000000)

Aug 30 02:06:48.106: Vi2.1 IPCP AUTHOR: Start.  Her address 0.0.0.0, we want 0.0.0.0

Aug 30 02:06:48.106: Vi2.1 IPCP AUTHOR: Done.  Her address 0.0.0.0, we want 0.0.0.0

Aug 30 02:06:48.107: Vi2.1 IPCP: Pool returned 192.0.2.3

Aug 30 02:06:48.107: Vi2.1 IPCP: O CONFNAK [REQsent] id 1 len 10

Aug 30 02:06:48.107: Vi2.1 IPCP:    Address 192.0.2.3 (0x03061E1E1E03)

Aug 30 02:06:48.107: Vi2.1 IPCP: Event[Receive ConfReq-] State[REQsent to REQsent]

Aug 30 02:06:48.107: Vi2.1 CDPCP: I CONFREQ [UNKNOWN] id 1 len 4

Aug 30 02:06:48.107: Vi2.1 LCP: O PROTREJ [Open] id 2 len 10 protocol CDPCP (0x01010004)

Aug 30 02:06:48.107: Vi2.1 IPCP: I CONFACK [REQsent] id 1 len 10

Aug 30 02:06:48.107: Vi2.1 IPCP:    Address 192.0.2.0 (0x0306C8C8C8C8)

Aug 30 02:06:48.107: Vi2.1 IPCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]

Aug 30 02:06:48.107: Vi2.1 IPCP: I CONFREQ [ACKrcvd] id 2 len 10

Aug 30 02:06:48.107: Vi2.1 IPCP:    Address 192.0.2.3 (0x03061E1E1E03)

Aug 30 02:06:48.107: Vi2.1 IPCP: O CONFACK [ACKrcvd] id 2 len 10

Aug 30 02:06:48.107: Vi2.1 IPCP:    Address 192.0.2.3 (0x03061E1E1E03)

Aug 30 02:06:48.107: Vi2.1 IPCP: Event[Receive ConfReq+] State[ACKrcvd to Open]

Aug 30 02:06:48.135: Vi2.1 IPCP: State is Open

Aug 30 02:06:48.144: Vi2.1 Added to neighbor route AVL tree: topoid 0, address 192.0.2.3

Aug 30 02:06:48.144: Vi2.1 IPCP: Install route to 192.0.2.3

Aug 30 02:06:48.145: RADIUS/ENCODE(00000B73):Orig. component type = PPPoE

Aug 30 02:06:48.145: RADIUS/ENCODE(00000B73): Acct-session-id pre-pended with Nas Port = 2/3/4/0

Aug 30 02:06:48.145: RADIUS(00000B73): Config NAS IP: 192.168.111.1

Aug 30 02:06:48.145: RADIUS(00000B73): Config NAS IPv6: ::

Aug 30 02:06:48.145: RADIUS(00000B73): sending

Aug 30 02:06:48.145: RADIUS/ENCODE(00000B73):Orig. component type = PPPoE

Aug 30 02:06:48.145: RADIUS/ENCODE(00000B73): Acct-session-id pre-pended with Nas Port = 2/3/4/0

Aug 30 02:06:48.145: RADIUS/ENCODE(00000B73): Acct-session-id pre-pended with Nas Port = 2/3/4/0

Aug 30 02:06:48.146: RADIUS(00000B73): Config NAS IP: 192.168.111.1

Aug 30 02:06:48.146: RADIUS(00000B73): Config NAS IPv6: ::

Aug 30 02:06:48.146: RADIUS(00000B73): sending

Aug 30 02:06:48.150: RADIUS(00000B73): Send Accounting-Request to 192.168.111.9:1646 id 21691/89, len 193

Aug 30 02:06:48.150: RADIUS:  authenticator 1C 0F 3E 87 1C E2 83 59 - BB 04 18 D5 9B 90 C9 2C

Aug 30 02:06:48.150: RADIUS:  Acct-Session-Id     [44]  18  "2/3/4/0_00000B6A"

Aug 30 02:06:48.150: RADIUS:  Framed-Protocol     [7]   6   PPP                       [1]

Aug 30 02:06:48.150: RADIUS:  Framed-IP-Address   [8]   6   192.0.2.3

Aug 30 02:06:48.150: RADIUS:  User-Name           [1]   16  "PPPoE-Client-1"

Aug 30 02:06:48.150: RADIUS:  Vendor, Cisco       [26]  35

Aug 30 02:06:48.150: RADIUS:   Cisco AVpair       [1]   29  "connect-progress=LAN Ses Up"

Aug 30 02:06:48.150: RADIUS:  Acct-Authentic      [45]  6   RADIUS                    [1]

Aug 30 02:06:48.150: RADIUS:  Acct-Status-Type    [40]  6   Start                     [1]

Aug 30 02:06:48.150: RADIUS:  NAS-Port-Type       [61]  6   Virtual                   [5]

Aug 30 02:06:48.150: RADIUS:  NAS-Port            [5]   6   738197504

Aug 30 02:06:48.150: RADIUS:  NAS-Port-Id         [87]  9   "2/3/4/0"

Aug 30 02:06:48.150: RADIUS:  Vendor, Cisco       [26]  41

Aug 30 02:06:48.150: RADIUS:   Cisco AVpair       [1]   35  "client-mac-address=5057.a8d8.02d8"

Aug 30 02:06:48.150: RADIUS:  Service-Type        [6]   6   Framed                    [2]

Aug 30 02:06:48.150: RADIUS:  NAS-IP-Address      [4]   6   192.168.111.1

Aug 30 02:06:48.150: RADIUS:  Acct-Delay-Time     [41]  6   0

Aug 30 02:06:48.150: RADIUS(00000B73): Sending a IPv4 Radius Packet

Aug 30 02:06:48.150: RADIUS(00000B73): Started 5 sec timeout

Aug 30 02:06:48.151: RADIUS(00000B73): Send Accounting-Request to 192.168.111.9:1646 id 21691/90, len 211

Aug 30 02:06:48.151: RADIUS:  authenticator 3B 66 00 B4 0A 1E 8B 0E - 88 8A F1 3E 3E 4C BD A2

Aug 30 02:06:48.151: RADIUS:  Acct-Session-Id     [44]  18  "2/3/4/0_00000B6B"

Aug 30 02:06:48.151: RADIUS:  Framed-Protocol     [7]   6   PPP                       [1]

Aug 30 02:06:48.151: RADIUS:  Vendor, Cisco       [26]  17

Aug 30 02:06:48.151: RADIUS:   ssg-service-info   [251] 11  "NInternet"

Aug 30 02:06:48.151: RADIUS:  Vendor, Cisco       [26]  42

Aug 30 02:06:48.151: RADIUS:   Cisco AVpair       [1]   36  "parent-session-id=2/3/4/0_00000B6A"

Aug 30 02:06:48.151: RADIUS:  Framed-IP-Address   [8]   6   192.0.2.3

Aug 30 02:06:48.151: RADIUS:  User-Name           [1]   16  "PPPoE-Client-1"

Aug 30 02:06:48.151: RADIUS:  Acct-Status-Type    [40]  6   Start                     [1]

Aug 30 02:06:48.151: RADIUS:  NAS-Port-Type       [61]  6   Virtual                   [5]

Aug 30 02:06:48.151: RADIUS:  NAS-Port            [5]   6   738197504

Aug 30 02:06:48.151: RADIUS:  NAS-Port-Id         [87]  9   "2/3/4/0"

Aug 30 02:06:48.151: RADIUS:  Vendor, Cisco       [26]  41

Aug 30 02:06:48.151: RADIUS:   Cisco AVpair       [1]   35  "client-mac-address=5057.a8d8.02d8"

Aug 30 02:06:48.151: RADIUS:  Service-Type        [6]   6   Framed                    [2]

Aug 30 02:06:48.151: RADIUS:  NAS-IP-Address      [4]   6   192.168.111.1

Aug 30 02:06:48.151: RADIUS:  Acct-Delay-Time     [41]  6   0

Aug 30 02:06:48.151: RADIUS(00000B73): Sending a IPv4 Radius Packet

Aug 30 02:06:48.151: RADIUS(00000B73): Started 5 sec timeout

Aug 30 02:06:48.152: RADIUS: Received from id 21691/89 192.168.111.9:1646, Accounting-response, len 20

Aug 30 02:06:48.152: RADIUS:  authenticator D4 05 9F FC 5C 10 86 93 - 9E 3F E1 E9 73 87 EB CB

Aug 30 02:06:48.153: RADIUS: Received from id 21691/90 192.168.111.9:1646, Accounting-response, len 20

Aug 30 02:06:48.153: RADIUS:  authenticator E1 E1 BD 89 65 E2 9A C3 - 18 41 E3 71 21 4A E4 59

Aug 30 02:06:48.824: AAA/AUTHOR: auth_need : user= 'cisco' ruser= 'BRAS-ASR1K'rem_addr= '10.137.80.251' priv= 1 list= '' AUTHOR-TYPE= 'commands'

<<<SNIP>>>

Aug 30 03:35:00.977: SSM SM[ADJ:PPPoE:19798]: platform get counters

Aug 30 03:35:00.977: SSS PM: ANCP not enabled on 'GigabitEthernet2/3/4' - not retrieving default shaper value

Aug 30 03:35:00.977: SSS PM: ANCP not enabled on 'GigabitEthernet2/3/4' - not retrieving default shaper value

Aug 30 03:35:00.981: RADIUS/ENCODE(00000B73):Orig. component type = PPPoE

Aug 30 03:35:00.981: RADIUS/ENCODE(00000B73): Acct-session-id pre-pended with Nas Port = 2/3/4/0

Aug 30 03:35:00.981: RADIUS(00000B73): Config NAS IP: 192.168.111.1

Aug 30 03:35:00.981: RADIUS(00000B73): Config NAS IPv6: ::

Aug 30 03:35:00.981: RADIUS(00000B73): sending

Aug 30 03:35:00.982: RADIUS(00000B73): Send Accounting-Request to 192.168.111.9:1646 id 21691/97, len 285

Aug 30 03:35:00.982: RADIUS:  authenticator 6B D7 E9 30 D1 77 35 AF - 48 3E 36 70 0D B9 91 EF

Aug 30 03:35:00.982: RADIUS:  Acct-Session-Id     [44]  18  "2/3/4/0_00000B6A"

Aug 30 03:35:00.982: RADIUS:  Framed-Protocol     [7]   6   PPP                       [1]

Aug 30 03:35:00.982: RADIUS:  Framed-IP-Address   [8]   6   192.0.2.3

Aug 30 03:35:00.982: RADIUS:  User-Name           [1]   16  "PPPoE-Client-1"

Aug 30 03:35:00.982: RADIUS:  Vendor, Cisco       [26]  35

Aug 30 03:35:00.982: RADIUS:   Cisco AVpair       [1]   29  "connect-progress=LAN Ses Up"

Aug 30 03:35:00.982: RADIUS:  Vendor, Cisco       [26]  31

Aug 30 03:35:00.982: RADIUS:   Cisco AVpair       [1]   25  "nas-tx-speed=1000000000"

Aug 30 03:35:00.982: RADIUS:  Vendor, Cisco       [26]  31

Aug 30 03:35:00.982: RADIUS:   Cisco AVpair       [1]   25  "nas-rx-speed=1000000000"

Aug 30 03:35:00.982: RADIUS:  Acct-Session-Time   [46]  6   5292

Aug 30 03:35:00.982: RADIUS:  Acct-Input-Octets   [42]  6   9200

Aug 30 03:35:00.982: RADIUS:  Acct-Output-Octets  [43]  6   9182

Aug 30 03:35:00.982: RADIUS:  Acct-Input-Packets  [47]  6   627

Aug 30 03:35:00.982: RADIUS:  Acct-Output-Packets [48]  6   625

Aug 30 03:35:00.982: RADIUS:  Acct-Authentic      [45]  6   RADIUS                    [1]

Aug 30 03:35:00.982: RADIUS:  Acct-Status-Type    [40]  6   Watchdog                  [3]

Aug 30 03:35:00.982: RADIUS:  NAS-Port-Type       [61]  6   Virtual                   [5]

Aug 30 03:35:00.982: RADIUS:  NAS-Port            [5]   6   738197504

Aug 30 03:35:00.982: RADIUS:  NAS-Port-Id         [87]  9   "2/3/4/0"

Aug 30 03:35:00.982: RADIUS:  Vendor, Cisco       [26]  41

Aug 30 03:35:00.982: RADIUS:   Cisco AVpair       [1]   35  "client-mac-address=5057.a8d8.02d8"

Aug 30 03:35:00.982: RADIUS:  Service-Type        [6]   6   Framed                    [2]

Aug 30 03:35:00.982: RADIUS:  NAS-IP-Address      [4]   6   192.168.111.1

Aug 30 03:35:00.982: RADIUS:  Acct-Delay-Time     [41]  6   0

Aug 30 03:35:00.982: RADIUS(00000B73): Sending a IPv4 Radius Packet

Aug 30 03:35:00.982: RADIUS(00000B73): Started 5 sec timeout

Aug 30 03:35:00.983: RADIUS: Received from id 21691/97 192.168.111.9:1646, Accounting-response, len 20

Aug 30 03:35:00.983: RADIUS:  authenticator 78 14 A6 05 ED FA E1 5A - 68 67 96 10 08 92 2A F8

Aug 30 03:35:35.914: EPC CP: Checking for file options based on wireshark support

Aug 30 03:35:35.914: EPC CP: Wireshark not supported

Aug 30 03:35:35.914: EPC CP: Wireshark and file options are not supported

Aug 30 03:35:35.915: AAA/AUTHOR: auth_need : user= 'cisco' ruser= 'BRAS-ASR1K'rem_addr= '10.137.72.162' priv= 15 list= '' AUTHOR-TYPE= 'commands'

Aug 30 03:35:35.915: EPC CP:  Deleting capture

Aug 30 03:35:35.915: EPC CP:  Deleting a capture

Aug 30 03:35:35.915: EPC CP:  In epc_free_cp

Aug 30 03:35:35.915: EPC CP:  Freeing Capture mycap

Aug 30 03:35:35.915: EPC CP:  Cleaning up interfaces

Aug 30 03:35:35.915: EPC CP:  checking for duplicate

Aug 30 03:35:35.915: EPC CP:  Prv. attached if GigabitEthernet2/0/4.200 dir 3, new if to attach Control Plane dir 1

Aug 30 03:35:35.915: EPC CP:  Target not found

Aug 30 03:35:35.915: EPC CP:  checking for duplicate

Aug 30 03:35:35.915: EPC CP:  Prv. attached if GigabitEthernet2/0/4.200 dir 3, new if to attach Control Plane dir 2

Aug 30 03:35:35.915: EPC CP:  Target not found

Aug 30 03:35:35.915: EPC CP:  Deleting all interfaces

Aug 30 03:35:35.922: EPC CP:  Removed Capture, #0

Aug 30 03:35:36.966: %CDP-4-DUPLEX_MISMATCH: duplex mismatch discovered on FastEthernet0/0/0 (not full duplex), with STLD1-630.06.08-7600-RU25 GigabitEthernet1/3 (full duplex).

Aug 30 03:35:39.726: EPC CP: Checking for file options based on wireshark support

Aug 30 03:35:39.726: EPC CP: Wireshark not supported

Aug 30 03:35:39.726: EPC CP: Wireshark and file options are not supported

Aug 30 03:35:40.305: EPC CP: Checking for file options based on wireshark support

Aug 30 03:35:40.305: EPC CP: Wireshark not supported

Aug 30 03:35:40.305: EPC CP: Wireshark and file options are not supported

Aug 30 03:35:41.049: EPC CP: Checking for file options based on wireshark support

Aug 30 03:35:41.049: EPC CP: Wireshark not supported

Aug 30 03:35:41.049: EPC CP: Wireshark and file options are not supported

Aug 30 03:35:41.404: EPC CP: Checking for file options based on wireshark support

Aug 30 03:35:41.404: EPC CP: Wireshark not supported

Aug 30 03:35:41.404: EPC CP: Wireshark and file options are not supported

Aug 30 03:35:41.404: AAA/AUTHOR: auth_need : user= 'cisco' ruser= 'BRAS-ASR1K'rem_addr= '10.137.72.162' priv= 15 list= '' AUTHOR-TYPE= 'commands'

Aug 30 03:36:32.726: %CDP-4-DUPLEX_MISMATCH: duplex mismatch discovered on FastEthernet0/0/0 (not full duplex), with STLD1-630.06.08-7600-RU25 GigabitEthernet1/3 (full duplex).

Aug 30 03:36:42.885: Accounting[uid:900]: Updating Accounting counters from the dataplane

Aug 30 03:36:42.885: SSM FH FH[19798:ft 11609:11609]: get report: ok

Aug 30 03:36:42.885: SSM FH FH COUNTER[19798:ft 11609:11609]: Platform get feature report

Aug 30 03:36:42.885: SSM FH FH[19798:ft 11609:11609]: clear report: ok

Aug 30 03:36:42.885: SSM FH FH[19798:ft 11609:11609]: Platform clear feature report

Aug 30 03:36:42.885: SSM CM FH[ft 11609:11609]: report all complete

Aug 30 03:36:42.885: SSM CM FH[ft 11609:11609]: get report complete

Aug 30 03:36:42.885: Accounting[uid:900]: Collecting records for flow accounting

Aug 30 03:36:42.885: Accounting[uid:900]: Dynamic record gathering started for ctx 7F743A303CF0

Aug 30 03:36:42.885: Accounting[uid:900]: Control info records gathering started for ctx 7F743A303CF0

Aug 30 03:36:42.885: Accounting[uid:900]: Updating Accounting counters from the dataplane

Aug 30 03:36:42.886: SSM FH FH[19798:ft 11609:11609]: get report: ok

Aug 30 03:36:42.886: SSM FH FH COUNTER[19798:ft 11609:11609]: Platform get feature report

Aug 30 03:36:42.886: SSM FH FH[19798:ft 11609:11609]: clear report: ok

Aug 30 03:36:42.886: SSM FH FH[19798:ft 11609:11609]: Platform clear feature report

Aug 30 03:36:42.886: SSM CM FH[ft 11609:11609]: report all complete

Aug 30 03:36:42.886: SSM CM FH[ft 11609:11609]: get report complete

Aug 30 03:36:42.886: Accounting[uid:900]: Updating attribute: I0;500

Aug 30 03:36:42.886: Accounting[uid:900]: Updating attribute: O0;500

Aug 30 03:36:42.888: RADIUS/ENCODE(00000B73):Orig. component type = PPPoE

Aug 30 03:36:42.888: RADIUS/ENCODE(00000B73): Acct-session-id pre-pended with Nas Port = 2/3/4/0

Aug 30 03:36:42.888: RADIUS/ENCODE(00000B73): Acct-session-id pre-pended with Nas Port = 2/3/4/0

Aug 30 03:36:42.888: RADIUS(00000B73): Config NAS IP: 192.168.111.1

Aug 30 03:36:42.888: RADIUS(00000B73): Config NAS IPv6: ::

Aug 30 03:36:42.888: RADIUS(00000B73): sending

Aug 30 03:36:42.889: RADIUS(00000B73): Send Accounting-Request to 192.168.111.9:1646 id 21691/98, len 269

Aug 30 03:36:42.889: RADIUS:  authenticator FB FB EC 49 B6 CF 62 C6 - D9 74 96 78 FF C1 74 71

Aug 30 03:36:42.889: RADIUS:  Acct-Session-Id     [44]  18  "2/3/4/0_00000B6B"

Aug 30 03:36:42.889: RADIUS:  Framed-Protocol     [7]   6   PPP                       [1]

Aug 30 03:36:42.889: RADIUS:  Vendor, Cisco       [26]  17

Aug 30 03:36:42.889: RADIUS:   ssg-service-info   [251] 11  "NInternet"

Aug 30 03:36:42.889: RADIUS:  Vendor, Cisco       [26]  42

Aug 30 03:36:42.889: RADIUS:   Cisco AVpair       [1]   36  "parent-session-id=2/3/4/0_00000B6A"

Aug 30 03:36:42.889: RADIUS:  Framed-IP-Address   [8]   6   192.0.2.3

Aug 30 03:36:42.889: RADIUS:  User-Name           [1]   16  "PPPoE-Client-1"

Aug 30 03:36:42.889: RADIUS:  Vendor, Cisco       [26]  14

Aug 30 03:36:42.889: RADIUS:   ssg-control-info   [253] 8   "I0;500"

Aug 30 03:36:42.889: RADIUS:  Vendor, Cisco       [26]  14

Aug 30 03:36:42.889: RADIUS:   ssg-control-info   [253] 8   "O0;500"

Aug 30 03:36:42.889: RADIUS:  Acct-Input-Packets  [47]  6   5

Aug 30 03:36:42.889: RADIUS:  Acct-Output-Packets [48]  6   5

Aug 30 03:36:42.889: RADIUS:  Acct-Input-Octets   [42]  6   500

Aug 30 03:36:42.889: RADIUS:  Acct-Output-Octets  [43]  6   500

Aug 30 03:36:42.889: RADIUS:  Acct-Session-Time   [46]  6   5394

Aug 30 03:36:42.889: RADIUS:  Acct-Status-Type    [40]  6   Watchdog                  [3]

Aug 30 03:36:42.889: RADIUS:  NAS-Port-Type       [61]  6   Virtual                   [5]

Aug 30 03:36:42.889: RADIUS:  NAS-Port            [5]   6   738197504

Aug 30 03:36:42.889: RADIUS:  NAS-Port-Id         [87]  9   "2/3/4/0"

Aug 30 03:36:42.889: RADIUS:  Vendor, Cisco       [26]  41

Aug 30 03:36:42.889: RADIUS:   Cisco AVpair       [1]   35  "client-mac-address=5057.a8d8.02d8"

Aug 30 03:36:42.889: RADIUS:  Service-Type        [6]   6   Framed                    [2]

Aug 30 03:36:42.889: RADIUS:  NAS-IP-Address      [4]   6   192.168.111.1

Aug 30 03:36:42.889: RADIUS:  Acct-Delay-Time     [41]  6   0

Aug 30 03:36:42.889: RADIUS(00000B73): Sending a IPv4 Radius Packet

Aug 30 03:36:42.889: RADIUS(00000B73): Started 5 sec timeout

Aug 30 03:36:42.890: RADIUS: Received from id 21691/98 192.168.111.9:1646, Accounting-response, len 20

Aug 30 03:36:42.890: RADIUS:  authenticator 55 05 DC BD 7B 39 B0 5F - 9D 9C 0C FF FC 58 26 22

Aug 30 03:36:45.912: %PIM-5-NBRCHG: VRF C1: neighbor 10.11.0.7 DOWN on interface Tunnel4 DR

Aug 30 03:36:45.912: %PIM-5-DRCHG: VRF C1: DR change from neighbor 10.11.0.7 to 10.11.0.2 on interface Tunnel4

Aug 30 03:36:48.779: AAA/AUTHOR: auth_need : user= 'cisco' ruser= 'BRAS-ASR1K'rem_addr= '10.137.72.162' priv= 15 list= '' AUTHOR-TYPE= 'commands'