i've got it resolved.Problem

acitycisco · ‎11-25-2014

Hello. Just starting with ISG.

My final goal is to force ISG device to periodically check if user still has access to the service without interrupting pppoe session. if user access should be prohibited by some reason, he should be redirected to billing web-page.

First step is to make periodic check part.

Here is user profile:

user1   Cleartext-Password := "user1"
        Cisco-Account-Info += "AANY",
        Cisco-Control-Info += "QV1000000",
        Cisco-Account-Info += "QU;10240000;D;10240000",

ANY     Cleartext-Password := "cisco", Service-Type == Outbound-User
        Cisco-AVPair += "ip:traffic-class=in access-group name CM_T_ANY",
        Cisco-AVPair += "ip:traffic-class=in default drop",
        Cisco-AVPair += "ip:traffic-class=out access-group name CM_T_ANY",
        Cisco-AVPair += "ip:traffic-class=out default drop",
        Cisco-AVPair += "prepaid-config=PREPAID",

Here is ASR 1002X , 03.10.03.S software:

aaa authentication ppp FREERADIUS group freeradius
aaa authorization network FREERADIUS group freeradius
aaa authorization subscriber-service FREERADIUS local group freeradius
aaa accounting network FREERADIUS start-stop group freeradius
!
aaa group server radius freeradius
 server-private 10.0.6.10 auth-port 1812 acct-port 1813 key 7 142417081E013E
!
subscriber feature prepaid PREPAID
 threshold time 0 seconds
 threshold volume 1 Kbytes
 interim-interval 1 minutes
 method-list author FREERADIUS
 method-list accounting FREERADIUS
 password cisco
!

User is authenticated, service downloaded but no periodical checks coming to RADIUS and no quota get depleted.

What am i doing wrong?

asr-1002x-01#show subscriber session  username user1 detailed
Type: PPPoE, UID: 200, State: authen, Identity: user1
IPv4 Address: 192.168.128.127
IPv6 Address: 2A01:8960:4::
Session Up-time: 00:22:11, Last Changed: 00:22:11
Interface: Virtual-Access2.1
Switch-ID: 4677

Policy information:
  Context 7FBB6473CB60: Handle A80009BE
  AAA_id 00001B1F: 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   "AANY"
    ssg-control-info     0   "QV1000000"
    ssg-account-info     0   "QU;10240000;D;10240000"
    prefix               0   00 40 2A 01 89 60 00 04 00 00 00 00 00 00 00 00 00 00
    Interface-Id         0   00 00 00 00 00 00 00 01
    route                0   "2a01:8960:5::/56"
    delegated-prefix     0   00 38 2A 01 89 60 00 05 00 00 00 00 00 00 00 00 00 00
  Downloaded User profile, including services:
    Framed-Protocol      0   1 [PPP]
    service-type         0   2 [Framed]
    ssg-account-info     0   "AANY"
    ssg-control-info     0   "QV1000000"
    ssg-account-info     0   "QU;10240000;D;10240000"
    prefix               0   00 40 2A 01 89 60 00 04 00 00 00 00 00 00 00 00 00 00
    Interface-Id         0   00 00 00 00 00 00 00 01
    route                0   "2a01:8960:5::/56"
    delegated-prefix     0   00 38 2A 01 89 60 00 05 00 00 00 00 00 00 00 00 00 00
  Config history for session (recent to oldest):
    Access-type: Web-service-logon Client: SM
     Policy event: Apply Config Success (Unapplied) (Service)
      Profile name: ANY, 3 references
        traffic-class        0   "in access-group name CM_T_ANY"
        traffic-class        0   "in default drop"
        traffic-class        0   "out access-group name CM_T_ANY"
        traffic-class        0   "out default drop"
    Access-type: Web-service-logon Client: SM
     Policy event: Process Config Connecting (Service)
      Profile name: ANY, 3 references
        traffic-class        0   "in access-group name CM_T_ANY"
        traffic-class        0   "in default drop"
        traffic-class        0   "out access-group name CM_T_ANY"
        traffic-class        0   "out default drop"
    Access-type: PPP Client: SM
     Policy event: Process Config Connecting
      Profile name: apply-config-only, 2 references
        Framed-Protocol      0   1 [PPP]
        service-type         0   2 [Framed]
        ssg-account-info     0   "AANY"
        ssg-control-info     0   "QV1000000"
        ssg-account-info     0   "QU;10240000;D;10240000"
        prefix               0   00 40 2A 01 89 60 00 04 00 00 00 00 00 00 00 00 00 00
        Interface-Id         0   00 00 00 00 00 00 00 01
        route                0   "2a01:8960:5::/56"
        delegated-prefix     0   00 38 2A 01 89 60 00 05 00 00 00 00 00 00 00 00 00 00
  Rules, actions and conditions executed:
    subscriber rule-map default-internal-rule
      condition always event service-start
        1 service-policy type service identifier service-name
    subscriber rule-map default-internal-rule
      condition always event service-stop
        1 service-policy type service unapply identifier service-name

Classifiers:
Class-id    Dir   Packets    Bytes                  Pri.  Definition
0           In    229275     13175066               0    Match Any
1           Out   714381     1038574772             0    Match Any

Features:

Static Routes:
Class-id  Configuration Status           Source
0          This feature is enabled       Peruser

Policing:
Class-id   Dir  Avg. Rate   Normal Burst  Excess Burst Source
0          In   10240000    1920000       3840000      Peruser
1          Out  10240000    1920000       3840000      Peruser

DHCPv6 PD from AAA:
Class-id  Configuration Status           Source
0          This feature is enabled       Peruser

Configuration Sources:
Type  Active Time  AAA Service ID  Name
USR   00:22:11     -               Peruser
INT   00:22:11     -               Virtual-Template2

Manuel Rodriguez · ‎11-25-2014

Hi,

The prepaid feature never got applied to the session. That's why you don't see any authorization request (periodical checks) for quota.

It seems like you want to use service named "ANY" as the prepaid service. It seems like that service may have been applied but got removed for some reason (looking at the rules executed by your policy we see service-start and then service-stop were executed):

subscriber rule-map default-internal-rule
      condition always event service-start
        1 service-policy type service identifier service-name
    subscriber rule-map default-internal-rule
      condition always event service-stop
        1 service-policy type service unapply identifier service-name

Something is happening with the service. By the time you are collecting the output, the service is not applied at all in the session.

I would suggest to collect:

- debug subscriber policy all

- debug radius

- debug aaa coa

- debug subscriber feature all

- Full config of device

Also, I noted that you are returning quota attribute in the subscriber radius profile:

user1   Cleartext-Password := "user1"
        Cisco-Account-Info += "AANY",
        Cisco-Control-Info += "QV1000000",
        Cisco-Account-Info += "QU;10240000;D;10240000",

That is not correct. This attribute should be returned on the prepaid authorization request (quota check).

Regards

acitycisco · ‎11-25-2014

I tried not specifying quota, but NAS never ask RADIUS for it.

For all my experiments i'm using second bba group with second virtual template and FREERADUIS aaa list.

Here's debugs:

Nov 26 08:55:57: SSS PM: ANCP not enabled on 'TenGigabitEthernet0/1/0.299' - not retrieving default shaper value
Nov 26 08:55:59: RADIUS/ENCODE(00001B97):Orig. component type = PPPoE
Nov 26 08:55:59: RADIUS: DSL line rate attributes successfully added
Nov 26 08:55:59: RADIUS(00001B97): Config NAS IP: 10.0.6.21
Nov 26 08:55:59: RADIUS(00001B97): Config NAS IPv6: ::
Nov 26 08:55:59: RADIUS/ENCODE: No idb found! Framed IP Addr might not be included
Nov 26 08:55:59: RADIUS/ENCODE(00001B97): acct_session_id: 7072
Nov 26 08:55:59: RADIUS(00001B97): sending
Nov 26 08:55:59: RADIUS(00001B97): Send Access-Request to 10.0.6.10:1812 id 1645/156, len 138
Nov 26 08:55:59: RADIUS:  authenticator DD A0 1E 36 65 E4 E6 38 - B0 10 9F 51 6A 11 24 09
Nov 26 08:55:59: RADIUS:  Framed-Protocol     [7]   6   PPP                       [1]
Nov 26 08:55:59: RADIUS:  User-Name           [1]   7   "user1"
Nov 26 08:55:59: RADIUS:  CHAP-Password       [3]   19  *
Nov 26 08:55:59: RADIUS:  NAS-Port-Type       [61]  6   Virtual                   [5]
Nov 26 08:55:59: RADIUS:  NAS-Port            [5]   6   0
Nov 26 08:55:59: RADIUS:  NAS-Port-Id         [87]  11  "0/1/0/299"
Nov 26 08:55:59: RADIUS:  Vendor, Cisco       [26]  41
Nov 26 08:55:59: RADIUS:   Cisco AVpair       [1]   35  "client-mac-address=000c.2964.a91e"
Nov 26 08:55:59: RADIUS:  Service-Type        [6]   6   Framed                    [2]
Nov 26 08:55:59: RADIUS:  NAS-IP-Address      [4]   6   10.0.6.21
Nov 26 08:55:59: RADIUS:  Acct-Session-Id     [44]  10  "00001BA0"
Nov 26 08:55:59: RADIUS(00001B97): Sending a IPv4 Radius Packet
Nov 26 08:55:59: RADIUS(00001B97): Started 5 sec timeout
Nov 26 08:55:59: RADIUS: Received from id 1645/156 10.0.6.10:1812, Access-Accept, len 44
Nov 26 08:55:59: RADIUS:  authenticator 3C 62 99 46 6E BA 39 24 - AB CF A6 D4 12 83 2D B8
Nov 26 08:55:59: RADIUS:  Framed-Protocol     [7]   6   PPP                       [1]
Nov 26 08:55:59: RADIUS:  Service-Type        [6]   6   Framed                    [2]
Nov 26 08:55:59: RADIUS:  Vendor, Cisco       [26]  12
Nov 26 08:55:59: RADIUS:   ssg-account-info   [250] 6   "AANY"
Nov 26 08:55:59: RADIUS(00001B97): Received from id 1645/156
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Authen status update; is now "authen"
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: IDMGR: assert authen status "authen"
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: IDMGR:  send event Session Update
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: IDMGR:  with username "user1"
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Session activation: ok
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Username key not found in set domain key API
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Username key does not have a delimiter in set domain key API
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Client block is NULL in get client block with handle 260009C1
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Updated key list:
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]:   AAA-Attr-List = 3A001B08
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]:     Framed-Protocol      0   1 [PPP]
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]:     service-type         0   2 [Framed]
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]:     ssg-account-info     0   "AANY"
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]:   Access-Type = 0 (PPP)
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]:   Session-Handle = 3472884087 (CF000177)
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]:   SHDB-Handle = 3388997707 (CA00004B)
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]:   Input Interface = "TenGigabitEthernet0/1/0.299"
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]:   Converted-Session = 0 (NO)
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]:   Media-Type = 1 (Ethernet)
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]:   Authen-Status = 0 (Authenticated)
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]:   Nasport = PPPoEoVLAN: slot 0 adapter 1 port 0 sub-interface 299 IP 0.0.0.0 VPI 0 VCI 0 VLAN 299
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]:   Protocol-Type = 0 (PPP Access Protocol)
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]:   Final = 1 (YES)
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]:   Auth-User = "user1"
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: SM Policy invoke - Process Config Connecting
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Access type PPP
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Access type PPP: final key
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Handling Config Request from Client
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Event <got process config req>, State: wait-for-events to wait-process-config-complete
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Handling Process Config
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Apply config request set to AAA list
Config:   Framed-Protocol      0   1 [PPP]
Config:   service-type         0   2 [Framed]
Config:   ssg-account-info     0   "AANY"
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Sending apply-config-only request to AAA
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: SSS PM: Allocating per-user profile info
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: SSS PM: Add per-user profile info to policy context
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Root SIP PPPoE
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]:  Enable PPPoE parsing
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]:  Enable PPP parsing
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: ACTIVE HANDLE[0]: Snapshot captured in Active context
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: ACTIVE HANDLE[0]: Active context created
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Event <make request>, state changed from idle to authorizing
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Active key set to Auth-User
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Authorizing key apply-config-only
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Spoofed AAA reply sent for key apply-config-only
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Received an AAA pass
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: [7FBB6473CB60]:Reply message not exist
 Initial attr  Framed-Protocol      0   1 [PPP]
 Initial attr  service-type         0   2 [Framed]
 Initial attr  ssg-account-info     0   "AANY"
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Could not parse AAA interim interval
Nov 26 08:55:59: COA_HA: [ERR] Unable to get coa_ctx from shdb 0xCA00004B
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: RULE: Service Name = ANY Ok
Nov 26 08:55:59: SSS PM: PARAMETERIZED-QoS: QOS parameters
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: RULE: VRF Parsing routine:
  Framed-Protocol      0   1 [PPP]
  service-type         0   2 [Framed]
  ssg-account-info     0   "AANY"
Nov 26 08:55:59: SSS PM: VPDN is not enabled
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Feature
Nov 26 08:55:59: Portbundle Hostkey: portbundle not configured on the router
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: SIP PPP[34E0B60] parsed as Success
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: SIP PPP[40FD520] parsed as Ignore
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: SIP PPPoE[357ECE0] parsed as Success
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: SIP Root parser not installed
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Event <service not found>, state changed from authorizing to complete
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: No service authorization info found
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Active Handle present - 94000170
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Apply config handle [2D001B9D] now set to [B3001B00]
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: ACTIVE HANDLE[0]: Snapshot reverted from Active context to policy context
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Freeing Active Handle; SSS Policy Context Handle = 260009C1
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: ACTIVE HANDLE[2113]: Released active handle
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: PROFILE: store profile "apply-config-only"
Nov 26 08:55:59: SSS PM: PROFILE-DB: is profile "apply-config-only" in DB
Nov 26 08:55:59: SSS PM: PROFILE-DB:  Computed hash value = 669264914
Nov 26 08:55:59: SSS PM: PROFILE-DB:  Yes, but is a new version
Nov 26 08:55:59: SSS PM: PROFILE-DB:    create "apply-config-only"/7FBB636AB768 hdl 65001B90 ref 1
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: PROFILE:  create 7FBB636AF8A8, ref 1
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Event <free request>, state changed from complete to terminal
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Cancel request
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Handling Author Not Found Event
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: Create context 7FBB6473CF00
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: key lists to append are empty
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: Authen status update; is now "unauthen"
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: IDMGR: assert authen status "unauthen"
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: SERVICE [ANY]: Parent 7FBB6473CB60
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: SERVICE [ANY]: Started yet? No
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: IDMGR: service not started yet; can't update
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: Did not update authen status to IDMGR
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: Username key not found in set domain key API
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: Username key not found in set domain key API
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: Updated NAS port for AAA ID 7063
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: IDMGR:  send event Session Update
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: Client block is NULL in get client block with handle 150009C2
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: Updated key list:
Nov 26 08:55:59: SSS PM [7FBB6473CF00]:   Logon-Service = "ANY"
Nov 26 08:55:59: SSS PM [7FBB6473CF00]:   Nasport = PPPoEoVLAN: slot 0 adapter 1 port 0 sub-interface 299 IP 0.0.0.0 VPI 0 VCI 0 VLAN 299
Nov 26 08:55:59: SSS PM [7FBB6473CF00]:   Access-Type = 11 (Web-service-logon)
Nov 26 08:55:59: SSS PM [7FBB6473CF00]:   Authen-Status = 1 (Unauthenticated)
Nov 26 08:55:59: SSS PM [7FBB6473CF00]:   Session-Handle = 3472884087 (CF000177)
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: Service Command-Handler Policy invoke - Service-Start
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: Access type Web-service-logon
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: RULE: Looking for a rule for event service-start
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: RULE:  Intf CloneSrc Vt2: service-rule any: None
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: RULE:  Intf InputI/f Te0/1/0.299: service-rule any: None
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: RULE:  Glob: service-rule any: default-internal-rule
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: RULE:   Evaluate "default-internal-rule" for service-start
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: RULE:    Wrong type "default-internal-rule/always event account-logon"
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: RULE:    Wrong type "default-internal-rule/always event idle-timeout"
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: RULE:    Wrong type "default-internal-rule/always event session-timeout"
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: RULE:    Wrong type "default-internal-rule/always event keepalive-timeout"
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: RULE:    Wrong type "default-internal-rule/always event flow-timeout"
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: RULE:    Matched "default-internal-rule/always event service-start"
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: RULE:    Matched "default-internal-rule/always event service-start/1 service-policy type service identifier service-name"
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: RULE[0]: Start
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: RULE[0]: default-internal-rule/always event service-start/1 service-policy type service identifier service-name
Nov 26 08:55:59: SSS PM CCM:  Found SHDB handle 0xCA00004B for policy context 0x7FBB6473CB60
Nov 26 08:55:59: SSS PM CCM:  [SESSION PM EVENT] Event = NEW-REQUEST (ctx: 0x7FBB6473CB60, action: APPLY-SERVICE)
Nov 26 08:55:59: SSS PM HA:  Dynsess not required shdb = 0xCA00004B spol_ctx = 0x7FBB6473CB60
Nov 26 08:55:59: SSS PM CCM:  Set PM HA as not ready (session 0xCA00004B) successfully
Nov 26 08:55:59: SSS PM HA:  Adding an action (type APPLY-SERVICE) into the PM HA queue
Nov 26 08:55:59: SSS PM HA:  NE: In policy_ha_add_session_info, shdb=0xCA00004B, last=APPLY-SERVICE (6)
Nov 26 08:55:59: SSS PM HA:  In policy_ha_nett_effect_process: ctx=0x7FBB5EBC8FC0, action-type=APPLY-SERVICE, event=SERVICE-START, state=INIT-STATE
Nov 26 08:55:59: SSS PM HA: NE: Didn't find any duplicate service-apply action
Nov 26 08:55:59: SSS PM HA:  Setting current elem, from 0x0 to 0x7FBB5EBC4BF8
Nov 26 08:55:59: SSS PM CCM:  New bulk session (shdb 0xCA00004B), ctx 0x7FBB6473CB60, dsess_hdl 0x0, APPLY-SERVICE OK
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: RULE[0]: Have key Logon-Service
Nov 26 08:55:59: SSS PM [7FBB6473CF00]: RULE[0]: This service ANY is marked as not cancelled
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: State: initial-req to check-auth-needed
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: Event <send auth>, State: check-auth-needed to authorizing
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: Handling AAA service Authorization
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: Sending AAA request for 'ANY'
Nov 26 08:55:59: SVM [ANY]: needs downloading
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: service "ANY" not in cache; needs download
Nov 26 08:55:59: SVM [430000BB/ANY]: allocated version 1
Nov 26 08:55:59: SVM [430000BB/ANY]: [150009C2]: client queued
Nov 26 08:55:59: SVM [430000BB/ANY]: [PM-Download:150009C2] locked 0->1
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: download required
Nov 26 08:55:59: SVM [430000BB/ANY]: [AAA-Download:7FBB6280D928] locked 0->1
Nov 26 08:55:59: SSS AAA AUTHOR: Authorization:Fetching method list from SIP:Web-service-logon
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: using named author method list "FREERADIUS"
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Root SIP PPPoE
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]:  Enable PPPoE parsing
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]:  Enable PPP parsing
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]:  Enable Web-service-logon parsing
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: ACTIVE HANDLE[0]: Snapshot captured in Active context
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: ACTIVE HANDLE[0]: Active context created
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Event <make request>, state changed from idle to authorizing
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Active key set to Apply-Service
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Authorizing key ANY
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Set authorization profile type to service
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: AAA request sent for key ANY
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: RULE[0]: Downloading service "ANY"
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: RULE[1]: Start
Nov 26 08:55:59: RADIUS/ENCODE(00000000):Orig. component type = Invalid
Nov 26 08:55:59: RADIUS(00000000): Config NAS IP: 10.0.6.21
Nov 26 08:55:59: RADIUS(00000000): Config NAS IPv6: ::
Nov 26 08:55:59: RADIUS(00000000): sending
Nov 26 08:55:59: RADIUS: nas-port-id(87) is not found in the request
Nov 26 08:55:59: RADIUS(00000000): Send Access-Request to 10.0.6.10:1812 id 1645/157, len 55
Nov 26 08:55:59: RADIUS:  authenticator B3 F6 A3 5E 7D D8 01 9E - 72 A5 4E D0 79 32 0C 11
Nov 26 08:55:59: RADIUS:  User-Password       [2]   18  *
Nov 26 08:55:59: RADIUS:  User-Name           [1]   5   "ANY"
Nov 26 08:55:59: RADIUS:  Service-Type        [6]   6   Outbound                  [5]
Nov 26 08:55:59: RADIUS:  NAS-IP-Address      [4]   6   10.0.6.21
Nov 26 08:55:59: RADIUS(00000000): Sending a IPv4 Radius Packet
Nov 26 08:55:59: RADIUS(00000000): Started 5 sec timeout
Nov 26 08:55:59: RADIUS: Received from id 1645/157 10.0.6.10:1812, Access-Accept, len 240
Nov 26 08:55:59: RADIUS:  authenticator F2 BB 14 5D 90 BC 76 91 - 8C B3 9B 55 75 69 4A 6B
Nov 26 08:55:59: RADIUS:  Vendor, Cisco       [26]  54
Nov 26 08:55:59: RADIUS:   Cisco AVpair       [1]   48  "ip:traffic-class=in access-group name CM_T_ANY"
Nov 26 08:55:59: RADIUS:  Vendor, Cisco       [26]  40
Nov 26 08:55:59: RADIUS:   Cisco AVpair       [1]   34  "ip:traffic-class=in default drop"
Nov 26 08:55:59: RADIUS:  Vendor, Cisco       [26]  55
Nov 26 08:55:59: RADIUS:   Cisco AVpair       [1]   49  "ip:traffic-class=out access-group name CM_T_ANY"
Nov 26 08:55:59: RADIUS:  Vendor, Cisco       [26]  41
Nov 26 08:55:59: RADIUS:   Cisco AVpair       [1]   35  "ip:traffic-class=out default drop"
Nov 26 08:55:59: RADIUS:  Vendor, Cisco       [26]  30
Nov 26 08:55:59: RADIUS:   Cisco AVpair       [1]   24  "prepaid-config=PREPAID"
Nov 26 08:55:59: RADIUS/DECODE(00000000): There is no General DB. Reply server details may not be recorded
Nov 26 08:55:59: RADIUS(00000000): Received from id 1645/157
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Received an AAA pass
 Initial attr  traffic-class        0   "in access-group name CM_T_ANY"
 Initial attr  traffic-class        0   "in default drop"
 Initial attr  traffic-class        0   "out access-group name CM_T_ANY"
 Initial attr  traffic-class        0   "out default drop"
 Initial attr  prepaid-config       0   "PREPAID"
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Could not parse AAA interim interval
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: PREPAID:Prepaid config= PREPAID
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: PREPAID:No prepaid context in policy context; allocing
Nov 26 08:55:59: SSS PM: PARAMETERIZED-QoS: QOS parameters
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: RULE: VRF Parsing routine:
  traffic-class        0   "in access-group name CM_T_ANY"
  traffic-class        0   "in default drop"
  traffic-class        0   "out access-group name CM_T_ANY"
  traffic-class        0   "out default drop"
Nov 26 08:55:59: SSS PM: VPDN is not enabled
Nov 26 08:55:59: SVM [430000BB/ANY]: Set class ids: 228.229
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Feature
Nov 26 08:55:59: SSF[ANY/QoS Policy Map]: TC flow does not support this feature
Nov 26 08:55:59: SSF[ANY/TC]: TC flow does not support this feature
Nov 26 08:55:59: SSF[ANY/Service Config]: TC flow does not support this feature
Nov 26 08:55:59: SSF[ANY/IP Config]: TC flow does not support this feature
Nov 26 08:55:59: SSF[ANY/Interface Config]: TC flow does not support this feature
Nov 26 08:55:59: SSF[ANY/Compression]: TC flow does not support this feature
Nov 26 08:55:59: SSF[ANY/Modem-on-hold]: TC flow does not support this feature
Nov 26 08:55:59: SSF[ANY/Static Routes]: TC flow does not support this feature
Nov 26 08:55:59: SSF[ANY/IPX Static SAPs]: TC flow does not support this feature
Nov 26 08:55:59: SSF[ANY/Per-User ACL]: TC flow does not support this feature
Nov 26 08:55:59: SSF[ANY/Per-User Filter]: TC flow does not support this feature
Nov 26 08:55:59: SSF[ANY/Portbundle Hostkey]: TC flow does not support this feature
Nov 26 08:55:59: SSF[ANY/DHCPv6 PD from AAA]: TC flow does not support this feature
Nov 26 08:55:59: SSF[ANY/Keepalive]: TC flow does not support this feature
Nov 26 08:55:59: SSF[ANY/Tariff Switching]: TC flow does not support this feature
Nov 26 08:55:59: SSF[ANY/Forced Flow Routing]: TC flow does not support this feature
Nov 26 08:55:59: SSF[ANY/Templating End of Transaction]: TC flow does not support this feature
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: SIP PPP[34E0B60] parsed as Success
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: SIP PPP[40FD520] parsed as Ignore
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: SIP PPPoE[357ECE0] parsed as Success
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: SIP Root parser not installed
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: SIP Web-service-logon parser not installed
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Event <service not found>, state changed from authorizing to complete
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: No service authorization info found
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Active Handle present - B5000171
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: Attr list is NULL, apply config handle [0] not reset
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: ACTIVE HANDLE[0]: Snapshot reverted from Active context to policy context
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Freeing Active Handle; SSS Policy Context Handle = 150009C2
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: ACTIVE HANDLE[2113]: Released active handle
Nov 26 08:55:59: SSS PM [7FBB6473C080]: Create context 7FBB6473C080
Nov 26 08:55:59: SSS PM: PROFILE-DB: is profile "ANY" in DB
Nov 26 08:55:59: SSS PM: PROFILE-DB:  Computed hash value = 1769891265
Nov 26 08:55:59: SSS PM: PROFILE-DB:  No, add new list
Nov 26 08:55:59: SSS PM: PROFILE-DB:   create "ANY"
Nov 26 08:55:59: SSS PM: PROFILE-DB:    create "ANY"/7FBB636AB6A8 hdl CF001B0C ref 1
Nov 26 08:55:59: SVM [430000BB/ANY]: downloaded first version
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: SVM download for "ANY" ok
Nov 26 08:55:59: SVM [430000BB/ANY]: [150009C2]: client download ok
Nov 26 08:55:59: SVM [430000BB/ANY]: [SVM-to-client-msg:150009C2] locked 0->1
Nov 26 08:55:59: SVM [430000BB/ANY]: [AAA-Download:7FBB6280D928] unlocked 1->0
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Event <free request>, state changed from complete to terminal
Nov 26 08:55:59: SSS AAA AUTHOR [uid:201]: Cancel request
Nov 26 08:55:59: SSS PM [7FBB6473C080]: Destroy context 7FBB6473C080
Nov 26 08:55:59: SSS PM: [PARAMETERIZED-QoS]: In removed_from_rbpl_ctx_temp_hold for policy handle[ED0009C3
Nov 26 08:55:59: SSS PM: [PARAMETERIZED-QoS]: No rabapol context created yet for handle [ED0009C3], nothing to return
Nov 26 08:55:59: COA_CCM: [SESSION FREE] Policy ctx: 0x7FBB6473C080
Nov 26 08:55:59: COA_CCM: Free session - Ignoring policy context 0x7FBB6473C080 (not our session)
Nov 26 08:55:59: SSS PM CCM:  [SESSION FREE] policy ctx: 0x7FBB6473C080
Nov 26 08:55:59: SSS PM CCM:  [ERR] Free session - Ignoring policy context 0x7FBB6473C080 (not our HA session)
Nov 26 08:55:59: CH-UTILS: Invalid command handle
Nov 26 08:55:59: SSS PM [7FBB6473C080]: PROFILE: destroy all config
Nov 26 08:55:59: SSS PM [7FBB6473C080]: SSS PM: destroy all user profile info from policy context
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: SVM service download success
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: download completed for "ANY" version 1
Nov 26 08:55:59: SVM [430000BB/ANY]: alloc feature info
Nov 26 08:55:59: SVM [430000BB/ANY]: [SVM-Feature-Info:7FBB636DD648] locked 0->1
Nov 26 08:55:59: SVM [430000BB/ANY]: has Policy info
Nov 26 08:55:59: SVM [430000BB/ANY]: [PM-Info:7FBB6484BDC0] locked 0->1
Nov 26 08:55:59: SVM [430000BB/ANY]: has Policy info
Nov 26 08:55:59: SSS PM CCM: Poisoning session for SHDB 0xCA00004B.
Nov 26 08:55:59: SVM [430000BB/ANY]: [PM-Info:7FBB6484BD60] unlocked 1->0
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: PROFILE: store profile "ANY"
Nov 26 08:55:59: SSS PM: PROFILE-DB:   incremented ref "ANY"/7FBB636AB6A8 hdl CF001B0C ref 2
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: PROFILE:  create 7FBB636AF880, ref 1
Nov 26 08:55:59: SVM [430000BB/ANY]: populated client
Nov 26 08:55:59: SVM [430000BB/ANY]: [PM-Download:150009C2] unlocked 1->0
Nov 26 08:55:59: SVM [430000BB/ANY]: [SVM-to-client-msg:150009C2] unlocked 1->0
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: RULE: VRF/Classname Check: session logging off or not VRF/Classname dependent
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: Handling Author Not Found Event
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: Feature info: 7FBB636DD648 Type: Service Config
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]:             : Config level: Service Profile
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]:             : IDB type: Sub-if or not required
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]:             : 16 bytes:
SSS PM [uid:201][7FBB6473CF00]:             : Data: 000000 00 00 43 00 00 BB EA 00  ..c.....
SSS PM [uid:201][7FBB6473CF00]:             : Data: 000008 00 15 15 00 09 C2 00 00  ........
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: Service starting
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: SERVICE [ANY]: Parent 7FBB6473CB60
Nov 26 08:55:59: SVM [430000BB/ANY]: [PM-Service:7FBB53EE6050] locked 0->1
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Client block is NULL in get client block with handle 260009C1
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: SERVICE [ANY]: Start-pending request: Ok
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: Event <srvf not found>, State: authorizing to check-auth-needed
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: Handling Next Authorization Check
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: RULE[0]: Continue
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: RULE[0]: default-internal-rule/always event service-start/1 service-policy type service identifier service-name
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: RULE[0]: No more actions to run
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: RULE[1]: Continue
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: RULE[1]: default-internal-rule/always event service-start/1 service-policy type service identifier service-name
Nov 26 08:55:59: SVM [430000BB/ANY]: already downloaded; sharing
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: RULE[1]: Give default directive
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: RULE[2]: Continue
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: RULE[2]: default-internal-rule/always event service-start/1 service-policy type service identifier service-name
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: Event <srvf found>, State: check-auth-needed to wait-for-events
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: All auto services downloaded and cached,proceed with rule execution
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Service Command-Handler Policy invoke - Auto Services Downloaded
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Session contans a prepaid svc
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Handling Config Apply to SM
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: SSS PM: config_applied is set for Per-User handle [8D0000CB]
Nov 26 08:55:59: SSF: SSF FIB SB required Vi2.1, FALSE
Nov 26 08:55:59: SSF: SSF FIB SB required Vi2.1, FALSE
Nov 26 08:55:59: SSF: SSF FIB SB required Vi2.1, FALSE
Nov 26 08:55:59: SSF: SSF FIB SB required Vi2.1, FALSE
Nov 26 08:55:59: SSF: SSF FIB SB required Vi2.1, FALSE
Nov 26 08:55:59: SSF: SSF FIB SB required Vi2.1, FALSE
Nov 26 08:55:59: SSS PM: SSS PM: Added peruser feature infos when config_applied already set
Nov 26 08:55:59: SSF[uid:201:0.1]: L2HW Segment init returned: Success
Nov 26 08:55:59: SSF[uid:201:0.1]: Sending Apply Config Request to FM
Nov 26 08:55:59: SSF Owner[]: rcv owner avail msg: owner type 4, owner hdl 0x7FBB57E18088, old seg hdl 0, msg seg hdl 872415490, fsb 0x0
Nov 26 08:55:59: SSF Owner [Vi2.1/uid:0]: Created fsb, owner type 4, owner hdl 0x7FBB57E18088, fsb 0x7FBB64D54F88
Nov 26 08:55:59: SSF Owner [Vi2.1/uid:0]: FSM Ev: Owner info avail
Nov 26 08:55:59: FSM Old St: SSF Owner InActive
Nov 26 08:55:59: FSM New St: SSF Owner Owner-Ready
Nov 26 08:55:59: FSM: Act owner avail
Nov 26 08:55:59: SSF[uid:201:0.1]: Received a config apply request from Swidb for segment 7FBB648AEFB0
Nov 26 08:55:59: SSF[Vt2/uid:201:0.1]: Apply Interface configured features from source(7FBB6366B1D8)
Nov 26 08:55:59: SSF[Vt2]: Bind notify.  Incremented ref count: 1
Nov 26 08:55:59: SSF[Vt2/uid:201:0.1]: Segment bound to a Interface configuration source Success
Nov 26 08:55:59: SSF[ANY/uid:201:0.1]: Apply Service Profile configured features from source(430000BB)
Nov 26 08:55:59: SSF[uid:201:0.1]: Request flow segment context to be created
Nov 26 08:55:59: SSF[uid:201:0.1]: L2HW Segment init returned: Success
Nov 26 08:55:59: SSF[ANY/uid:201:228.229]: Apply Service Profile configured features from source(430000BB)
Nov 26 08:55:59: SVM [430000BB/ANY]: [FM-Bind:CF000177] locked 0->1
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: SERVICE [ANY]: Bind notify: Ok
Nov 26 08:55:59: SSF[ANY/uid:201:228.229]: Segment bound to a Service Profile configuration source Success
Nov 26 08:55:59: SSF[Peruser/uid:201:0.1]: Apply Per-user configured features from source(8D0000CB)
Nov 26 08:55:59: SSF[Peruser/uid:201:0.1]: Segment bound to a Per-user configuration source Success
Nov 26 08:55:59: SSF[uid:201:0.1]: L2HW Activate features returned: Success
Nov 26 08:55:59: SSF[uid:201:0.1]: Sent feature apply success msg
Nov 26 08:55:59: SVM [430000BB/ANY]: [SVM-Feature-Info:7FBB636DD648] unlocked 1->0
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: SM Policy invoke - Apply Config Success
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Session contans a prepaid svc
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: Sending first author request
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: PREPAID:Event DO_FIRST_AUTHOR, State: INIT to PROCESSING_FIRST_AUTHOR
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: PREPAID:Performing action: PROCESS_FIRST_AUTHOR
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Client block is NULL in get client block with handle 260009C1
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: PREPAID:Suspending first author till IPCP_PASS
Nov 26 08:55:59: SSF[Peruser]: Did not locate push peruser bind mapping
Nov 26 08:55:59: SSS PM: [PARAMETERIZED-QoS]: No rabapol context created yet for handle [260009C1], returning compatible
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Event <got apply config success>, State: wait-process-config-complete to wait-for-events
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Handling Apply Config; SUCCESS
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: session start done
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Removed attribute list just processed
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: SERVICE [ANY]: Complete-Pending
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: IDMGR: service start
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: IDMGR:  send event Service Assert
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: IDMGR:  with service name "ANY"
Nov 26 08:55:59: SVM [430000BB/ANY]: already downloaded; sharing
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: IDMGR: assert authen status "authen"
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: IDMGR:  send event Service Update
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: IDMGR:  with service name "ANY"
Nov 26 08:55:59: SVM [430000BB/ANY]: already downloaded; sharing
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: IDMGR: update service
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: IDMGR:  send event Service Update
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: IDMGR:  with service name "ANY"
Nov 26 08:55:59: SVM [430000BB/ANY]: already downloaded; sharing
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: SERVICE [ANY]: Started
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: no callback for callback north
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Client block is NULL in get client block with handle 260009C1
Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CB60]: Null client block; Can't update RP
asr-1002x-01#
Nov 26 08:55:59: RADIUS:  Acct-Delay-Time     [41]  6   0
Nov 26 08:55:59: RADIUS(00001B97): Sending a IPv4 Radius Packet
Nov 26 08:55:59: RADIUS(00001B97): Started 5 sec timeout
Nov 26 08:55:59: RADIUS: Received from id 1646/205 10.0.6.10:1813, Accounting-response, len 20
Nov 26 08:55:59: RADIUS:  authenticator 18 6B 22 E6 3F 56 1A 4A - 73 83 5C 79 BD 38 24 8A
asr-1002x-01#
SSS Switch: Pak 7FBB4D5B6D28 sz 14 encap 2
Nov 26 08:56:01: 000000 C0 21 09 7E 00 0C 0C 11  D!N~....
Nov 26 08:56:01: 000008 3B ED FA D5 8D F4        ;.....
Nov 26 08:56:01: SSF: Classified on Layer 2

Config:

!
! Last configuration change at 16:45:50 TMN Tue Nov 25 2014 by lion
! NVRAM config last updated at 16:45:51 TMN Tue Nov 25 2014 by lion
!
version 15.3
service timestamps debug datetime localtime
service timestamps log datetime localtime
service password-encryption
service unsupported-transceiver
no platform punt-keepalive disable-kernel-core
!
hostname asr-1002x-01
!
boot-start-marker
boot system flash bootflash:asr1002x-universalk9.03.10.03.S.153-3.S3-ext.SPA.bin
boot-end-marker
!
aqm-register-fnf
!
vrf definition Mgmt-intf
 !
 address-family ipv4
 exit-address-family
 !
 address-family ipv6
 exit-address-family
!
vrf definition Voice
 !
 address-family ipv4
 exit-address-family
 !
 address-family ipv6
 exit-address-family
!
logging buffered 1024000 informational
!
aaa new-model
!
!
aaa group server radius freeradius
 server-private 10.0.6.10 auth-port 1812 acct-port 1813 key 7 142417081E013E
 ip vrf forwarding Mgmt-intf
 ip radius source-interface GigabitEthernet0
!
aaa group server radius billing
 server-private 10.0.6.102 auth-port 1812 acct-port 1813 key 7 06150A225E4B1D
 ip vrf forwarding Mgmt-intf
 ip radius source-interface GigabitEthernet0
!
aaa authentication login default local
aaa authentication ppp LOCAL_AUTH local
aaa authentication ppp FREERADIUS group freeradius
aaa authentication ppp BILLING group billing
aaa authorization console
aaa authorization exec default local
aaa authorization network LOCAL_AUTH none
aaa authorization network FREERADIUS group freeradius
aaa authorization network BILLING group billing
aaa authorization subscriber-service FREERADIUS local group freeradius
aaa authorization subscriber-service BILLING local
aaa accounting delay-start all
aaa accounting delay-start extended-delay 2
aaa accounting update periodic 5
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 FREERADIUS start-stop group freeradius
aaa accounting network BILLING start-stop group billing
!
!
!
!
aaa server radius dynamic-author
 client 10.0.6.102 vrf Mgmt-intf server-key 7 120A0014000E18
 client 10.0.6.10 server-key 7 094F471A1A0A
 port 1645
 auth-type any
 ignore session-key
!
aaa session-id common
aaa policy interface-config allow-subinterface
clock timezone TMN 5 0
no ip source-route
!
!
!
!
!

no ip domain lookup
ip domain name local
ip host service 10.0.6.101
ip dhcp excluded-address vrf Voice 10.3.0.0 10.3.127.255
!
ip dhcp pool Voice
 vrf Voice
 network 10.3.0.0 255.255.0.0
!
!
!
ipv6 unicast-routing
ipv6 dhcp iana-route-add
ipv6 dhcp binding track ppp
ipv6 dhcp pool dhcpv6_pool_60
 prefix-delegation pool ppp_delegate_60_v6_pool
 accounting BILLING
!
ipv6 dhcp pool dhcpv6_pool_56
 prefix-delegation pool ppp_delegate_56_v6_pool
 accounting BILLING
!
ipv6 dhcp pool AAA_dhcpv6_pool
 prefix-delegation aaa method-list BILLING
!
!
!
!
!
!
!
subscriber feature prepaid PREPAID
 threshold time 0 seconds
 threshold volume 1 Kbytes
 interim-interval 1 minutes
 method-list author FREERADIUS
 method-list accounting FREERADIUS
 password cisco
!
!
!
flow monitor MON1
 record netflow ipv4 original-output
!
multilink bundle-name authenticated
no virtual-template snmp
!
!
!
!
!
!
!
!
!
license accept end user agreement
archive
 log config
  logging enable
  logging size 300
  hidekeys
 path tftp://service/config/all/$h-$t
 write-memory
spanning-tree extend system-id
!
!
redundancy
 mode none
redirect server-group NoMoney
 server ip A.B.198.3 port 80
!
redirect server-group NoMoneyDNS
 server ip A.B.198.10 port 53
!
!
!
!
!
!
cdp run
!
ip tftp source-interface GigabitEthernet0
ip ssh version 2
lldp run
class-map type traffic match-any CM_ANY6
 match access-group input name CM_T_ANY6
 match access-group output name CM_T_ANY6
!
class-map type traffic match-any CM_ANY
 match access-group input name CM_T_ANY
 match access-group output name CM_T_ANY
!
class-map type traffic match-any CM_T_NoMoney_REDIRECT_DNS
 match access-group input name CM_T_NoMoney_REDIRECT_DNS
!
class-map type traffic match-any CM_T_NoMoney_REDIRECT_WWW
 match access-group input name CM_T_NoMoney_REDIRECT_WWW
!
class-map type traffic match-any CM_T_NoMoney_PASS
 match access-group input name CM_T_NoMoney_PASS
 match access-group output name CM_T_NoMoney_PASS
!
!
policy-map type service NoMoney10
 10 class type traffic CM_T_NoMoney_PASS
 !
 class type traffic default in-out
  drop
 !
!
policy-map type service NoMoney500
 500 class type traffic CM_T_NoMoney_REDIRECT_WWW
  redirect to group NoMoney
 !
 class type traffic default in-out
  drop
 !
!
policy-map type service NoMoney510
 510 class type traffic CM_T_NoMoney_REDIRECT_DNS
  redirect to group NoMoneyDNS
 !
 class type traffic default in-out
  drop
 !
!
policy-map type service Any
 1 class type traffic CM_ANY
  prepaid config PREPAID
 !
 class type traffic default in-out
  drop
 !
!
policy-map type service Any6
 1 class type traffic CM_ANY6
  prepaid config PREPAID
 !
 class type traffic default in-out
  drop
 !
!
policy-map pol2
policy-map pol1
policy-map PM_SPEED_NONE
 class class-default
policy-map rate_10m
 class class-default
  police 10000000 1000000
policy-map PM_TEST
 class class-default
  police 1000000
policy-map rate_1m
 class class-default
  police 1000000 100000
policy-map PM_SPEED_8M
 class class-default
  police 9000000
policy-map rate_out_10m
 class class-default
  police 10000000 1000000
policy-map rate_in_10m
 class class-default
  police 10000000 1000000
!
!
!
no crypto isakmp default policy
!
!
no crypto ipsec transform-set default
!
!
!
!
!
!
!
!
!
bba-group pppoe 1
 virtual-template 1
 vendor-tag circuit-id service
 vendor-tag remote-id service
 sessions per-mac limit 2
!
bba-group pppoe 2
 virtual-template 2
 vendor-tag circuit-id service
 vendor-tag remote-id service
 sessions per-mac limit 2
!
!
interface Null0
 no ip unreachables
 no ipv6 unreachables
!
interface Loopback0
 ip address A.B.196.6 255.255.255.255
 ipv6 address 2001:7f8::20/128
 ipv6 enable
!
interface Loopback2
 ip address A.B.198.1 255.255.255.0
!
interface GigabitEthernet0/0/0
 no ip address
 negotiation auto
 cdp enable
!
interface GigabitEthernet0/0/1
 no ip address
 negotiation auto
 cdp enable
!
interface GigabitEthernet0/0/2
 no ip address
 negotiation auto
 cdp enable
!
interface GigabitEthernet0/0/3
 no ip address
 negotiation auto
 cdp enable
!
interface GigabitEthernet0/0/4
 no ip address
 negotiation auto
 cdp enable
!
interface GigabitEthernet0/0/5
 no ip address
 negotiation auto
 cdp enable
!
interface TenGigabitEthernet0/1/0
 mtu 9000
 no ip address
 load-interval 30
 cdp enable
 hold-queue 4096 in
!
interface TenGigabitEthernet0/1/0.9
 encapsulation dot1Q 9
 ip address A.B.196.5 255.255.255.254
 ip nat outside
 ip flow monitor MON1 input
 ip flow monitor MON1 output
 ipv6 address 2001:7f8:0:1::2:1/127
 ipv6 nd ra suppress
!
interface TenGigabitEthernet0/1/0.34
 description DM_Inet
 encapsulation dot1Q 34
 ip unnumbered Loopback2
 ip nat outside
 service-policy input PM_SPEED_NONE
 service-policy output PM_SPEED_NONE
!
interface TenGigabitEthernet0/1/0.96
 description DM_Datacenter
 encapsulation dot1Q 96
 ip unnumbered Loopback2
 ip nat outside
 service-policy input PM_SPEED_NONE
 service-policy output PM_SPEED_NONE
!
interface TenGigabitEthernet0/1/0.298
 description IPoE test
 encapsulation dot1Q 298
 ip unnumbered Loopback2
 ip nat outside
!
interface TenGigabitEthernet0/1/0.299
 description PPPoE Test
 encapsulation dot1Q 299
 pppoe enable group 2
!
interface TenGigabitEthernet0/1/0.300
 encapsulation dot1Q 300
 vrf forwarding Voice
 ip address 10.3.0.1 255.255.0.0
!
interface TenGigabitEthernet0/1/0.21000
 description PPPoE
 encapsulation dot1Q 2 second-dot1q 1000-1999
 pppoe enable group 1
 pppoe max-sessions 10000
!
interface TenGigabitEthernet0/1/0.2002000
 description client 2000
 encapsulation dot1Q 200 second-dot1q 2000
 ip unnumbered Loopback2
 ip nat outside
 service-policy input PM_SPEED_8M
 service-policy output PM_SPEED_8M
!
interface GigabitEthernet0
 vrf forwarding Mgmt-intf
 ip address 10.0.6.21 255.255.255.0
 negotiation auto
!
interface Virtual-Template1
 mtu 1492
 ip unnumbered Loopback0
 no ip redirects
 no ip proxy-arp
 ip nat inside
 ip verify unicast reverse-path
 ip tcp adjust-mss 1452
 no logging event link-status
 ipv6 unnumbered Loopback0
 ipv6 enable
 no ipv6 nd ra suppress
 ipv6 dhcp server AAA_dhcpv6_pool
 peer default ip address pool pool192_168
 keepalive 60
 ppp authentication chap ms-chap-v2 BILLING
 ppp authorization BILLING
 ppp accounting BILLING
 ppp ipcp dns A.B.198.10
!
interface Virtual-Template2
 description Testing PPPoE
 mtu 1492
 ip unnumbered Loopback0
 no ip redirects
 no ip proxy-arp
 ip nat inside
 ip verify unicast reverse-path
 ip tcp adjust-mss 1452
 no logging event link-status
 ipv6 unnumbered Loopback0
 ipv6 enable
 no ipv6 nd ra suppress
 ipv6 dhcp server AAA_dhcpv6_pool
 peer default ip address pool pool192_168
 keepalive 60
 ppp authentication chap ms-chap-v2 FREERADIUS
 ppp authorization FREERADIUS
 ppp accounting FREERADIUS
 ppp ipcp dns A.B.198.10
!
ip local pool pool172_17 172.17.0.1 172.17.255.254
ip local pool pool192_168 192.168.128.0 192.168.255.254
ip nat settings mode cgn
no ip nat settings support mapping outside
ip nat pool nat_pool A.B.196.65 A.B.196.127 netmask 255.255.255.0
ip nat inside source list nat pool nat_pool overload
no ip forward-protocol nd
no ip forward-protocol udp tftp
no ip forward-protocol udp domain
no ip forward-protocol udp time
no ip forward-protocol udp netbios-ns
no ip forward-protocol udp netbios-dgm
no ip forward-protocol udp tacacs
!
no ip http server
no ip http secure-server
ip route 0.0.0.0 0.0.0.0 A.B.196.4
ip route A.B.196.128 255.255.255.128 Null0 100
ip route A.B.197.0 255.255.255.0 Null0 100
ip route A.B.198.0 255.255.255.0 Null0 100
ip route A.B.198.2 255.255.255.255 TenGigabitEthernet0/1/0.96 A.B.198.2 name net-console-01
ip route A.B.198.3 255.255.255.255 TenGigabitEthernet0/1/0.96 A.B.198.3 name net-mon-01
ip route A.B.198.4 255.255.255.255 TenGigabitEthernet0/1/0.96 A.B.198.4 name billing-01
ip route A.B.198.5 255.255.255.255 TenGigabitEthernet0/1/0.96 A.B.198.5 name svyazisty
ip route A.B.198.6 255.255.255.255 TenGigabitEthernet0/1/0.96 A.B.198.6 name Linux_test
ip route A.B.198.7 255.255.255.255 TenGigabitEthernet0/1/0.96 A.B.198.7 name SCE_Console
ip route A.B.198.8 255.255.255.255 TenGigabitEthernet0/1/0.96 A.B.198.8 name backup-01
ip route A.B.198.9 255.255.255.255 TenGigabitEthernet0/1/0.298 A.B.198.9 name Linux_test2
ip route A.B.198.10 255.255.255.255 TenGigabitEthernet0/1/0.96 A.B.198.10 name dns-server
ip route A.B.198.16 255.255.255.255 TenGigabitEthernet0/1/0.34 A.B.198.16 name DM
ip route A.B.198.17 255.255.255.255 TenGigabitEthernet0/1/0.34 A.B.198.17 name DM
ip route A.B.198.18 255.255.255.255 TenGigabitEthernet0/1/0.34 A.B.198.18 name DM
ip route A.B.198.19 255.255.255.255 TenGigabitEthernet0/1/0.34 A.B.198.19 name DM
ip route A.B.198.20 255.255.255.255 TenGigabitEthernet0/1/0.34 A.B.198.20 name DM
ip route A.B.198.21 255.255.255.255 TenGigabitEthernet0/1/0.34 A.B.198.21 name DM
ip route A.B.198.22 255.255.255.255 TenGigabitEthernet0/1/0.34 A.B.198.22 name DM
ip route A.B.198.23 255.255.255.255 TenGigabitEthernet0/1/0.34 A.B.198.23 name DM
ip route A.B.198.24 255.255.255.255 TenGigabitEthernet0/1/0.34 A.B.198.24 name DM
ip route A.B.198.25 255.255.255.255 TenGigabitEthernet0/1/0.34 A.B.198.25 name DM
ip route A.B.198.26 255.255.255.255 TenGigabitEthernet0/1/0.34 A.B.198.26 name DM
ip route A.B.198.27 255.255.255.255 TenGigabitEthernet0/1/0.34 A.B.198.27 name DM
ip route A.B.198.28 255.255.255.255 TenGigabitEthernet0/1/0.34 A.B.198.28 name DM
ip route A.B.198.29 255.255.255.255 TenGigabitEthernet0/1/0.34 A.B.198.29 name DM
ip route A.B.198.30 255.255.255.255 TenGigabitEthernet0/1/0.34 A.B.198.30 name DM
ip route A.B.198.31 255.255.255.255 TenGigabitEthernet0/1/0.34 A.B.198.31 name DM
ip route A.B.198.100 255.255.255.255 TenGigabitEthernet0/1/0.2002000 A.B.198.100 name "client 100"
!
ip access-list extended CM_T_ANY
 permit ip any any
ip access-list extended CM_T_NoMoney_PASS
 permit ip any host A.B.198.3
 permit ip host A.B.198.3 any
 permit udp any host A.B.198.10 eq domain
 permit udp host A.B.198.10 eq domain any
ip access-list extended CM_T_NoMoney_REDIRECT_DNS
 permit udp any any eq domain
ip access-list extended CM_T_NoMoney_REDIRECT_WWW
 permit tcp any any eq www
ip access-list extended POLICE_EXCLUDE
 deny   ip any host A.B.198.3
 deny   ip host A.B.198.3 any
 permit ip any any
ip access-list extended POLICE_EXCLUDE_INV
 permit ip any host A.B.198.3
 permit ip host A.B.198.3 any
ip access-list extended nat
 deny   ip any 10.0.0.0 0.255.255.255
 deny   ip any 172.16.0.0 0.15.255.255
 deny   ip any 192.168.0.0 0.0.255.255
 deny   ip any 169.254.0.0 0.0.255.255
 permit ip 192.168.128.0 0.0.127.255 any
 permit ip 172.17.0.0 0.0.255.255 any
ip access-list extended vty
 permit ip 10.0.6.0 0.0.0.255 any
!
kron occurrence daily-backup at 3:24 recurring
 policy-list backup_rc
!
kron policy-list backup_rc
 cli enable
 cli archive config
!
ipv6 route 2001:7f8:1::/48 Null0
ipv6 route 2001:7f8:2::/48 Null0
ipv6 route 2001:7f8:3::/48 Null0
ipv6 route ::/0 2001:7f8:0:1::2:0
ipv6 local pool ppp_delegate_60_v6_pool 2001:7f8:2::/48 60
ipv6 local pool ppp_delegate_56_v6_pool 2001:7f8:3::/48 56
ipv6 local pool ppp_link_v6_pool 2001:7f8:1::/49 64
!
!
!
radius-server attribute 44 include-in-access-req default-vrf
radius-server attribute 8 include-in-access-req
radius-server attribute 55 include-in-acct-req
radius-server attribute 25 access-request include
radius-server attribute 31 mac format ietf
!
!
ipv6 access-list CM_T_ANY6
 permit ipv6 any any
!
control-plane
!
 !
 !
 !
 !
!
!
!
!
line con 0
 exec-timeout 30 0
 logging synchronous
 history size 256
 stopbits 1
line aux 0
 transport input ssh
 transport output all
 stopbits 1
line vty 0 4
 access-class vty in vrf-also
 exec-timeout 120 0
 logging synchronous
 history size 256
 transport input ssh
 transport output all
line vty 5 15
 access-class vty in vrf-also
 exec-timeout 120 0
 logging synchronous
 history size 256
 transport input ssh
 transport output all
line vty 16 97
 history size 256
!
ntp server vrf Mgmt-intf 10.0.6.10
!
end

acitycisco · ‎11-25-2014

There is strange message in debug:

Nov 26 08:55:59: SSS PM [uid:201][7FBB6473CF00]: PREPAID:Suspending first author till IPCP_PASS

acitycisco · ‎11-25-2014

ISG has really weird behaviour, depending on whether "debug subscriber policy prepaid" turned ON or OFF it sending or not sending service Accounting packes to the radius.

Also if ON, AND "undebug subscriber policy all" it prints in debug:

Nov 26 10:07:42: SSS PM [uid:210][7FBB6473CF00]: PREPAID:No ip address even after IPCP Pass; Terminating service
Nov 26 10:07:42: SSS PM [uid:210][7FBB6473CF00]: PREPAID:Event AUTHOR_FAILURE, State: PROCESSING_FIRST_AUTHOR to END
Nov 26 10:07:42: SSS PM [uid:210][7FBB6473CF00]: PREPAID:Performing action: PROCESS_PREPAID_END

Smells buggy IOS ?

Manuel Rodriguez · ‎11-25-2014

Hi,

It would be better if you provide all the logs requested.

In any case, I've seen that you opened a TAC case for this so I will let my colleague from TAC to continue helping you with this.

Regards.

acitycisco · ‎11-26-2014

Guess what?

I've supplied Framed-IP-Address in users's profile, and prepaid started askinkg radius for quota!

I wonder if it is a bug or feature.

Manuel Rodriguez · ‎11-26-2014

Hi,

In the debugs we can see:

Nov 26 10:07:42: SSS PM [uid:210][7FBB6473CF00]: PREPAID:No ip address even after IPCP Pass; Terminating service

Seems like tehre was some issue where IP address was not provided to CPE via IPCP before prepaid service was being enabled. This caused the service to be terminated.

As I mentioned before, please follow this up under your TAC SR. Perhaps add "debug pppp nego" to the list of debugs I mentioned before and provide it to the TAC engineer working with you in the case.

I will disengage from this thread since you have already a TAC case for this.

Regards

acitycisco · ‎11-26-2014

That is not the case, because peer gets it's IP from pool, configured right on Virtual-Access interface. And it got Internet working anyway.

Also, when radius returns zero quota, Service got removed from session, but user continues to access entire network and ISG never asks for quota again. How to make it keep asking for quota and resume service once there is quota available?

TAC is very, awfully slow.

acitycisco · ‎11-27-2014

i've got it resolved.
Problem was that there were no route to the pool's network and there is a route to real IP network used for manual assignment.
Found out by trying assigning private IP instead of real in RADIUS profile.
I have just added "ip route 192.168.128.0 255.255.128.0 Null0" and prepaid started to work as it should.
Perhaps it should be noted somewhere in documentation or at least in debug message.

ISG PPPoE prepaid