Solved: ASR 1002-X PPPoE problem with Virtual-Access sub-interfaces

Blaz Zupancic · ‎03-19-2015

Hi there!

I have one problem with setting up PPPoE aggregation on ASR 1002-X. I want L2 session locally terminate and authenticate through FreeRADIUS.

The ppp negotiation is successfully negotiated, but then ASR report this error:

%FMANRP_ESS-4-FULLVAI: Session creation failed due to Full Virtual-Access Interfaces not being supported. Check that all applied Virtual-Template and RADIUS features support Virtual-Access sub-interfaces. swidb= 0x7F89929A0260, ifnum= 31

I found a few cases where this error it was appeared, and i tried all that solutions. I removed Framed-Compression (Van-Jacobsen-TCP-IP), i apply command "aaa policy interface-config allow-subinterface" in global config. If i do "test virtual-Template 10 subinterface" i receive Subinterfaces may be created using Virtual-Template10. I tried many different attributes on RADIUS config, but with no success on this error.

Here is my config on ASR:

version 15.4
service timestamps debug datetime msec
service timestamps log datetime msec
no service dhcp
no platform punt-keepalive disable-kernel-core
platform hardware throughput level 5000000
!
hostname BRAS_2
!
boot-start-marker
boot-end-marker
!
aqm-register-fnf
!
vrf definition Mgmt-intf
!
address-family ipv4
exit-address-family
!
address-family ipv6
exit-address-family
!
enable secret 5 $1$zmQx$o9m4DE91f4eA3ZQdHKzYu.
!
aaa new-model
!
!
aaa group server radius RADIUS_BRAS
server name RADIUS_SERV_1
!
aaa authentication login default local
aaa authentication login PPPoE_LIST group RADIUS_BRAS
aaa authentication ppp default local
aaa authentication ppp PPPoE_LIST group RADIUS_BRAS
aaa authorization network default group RADIUS_BRAS
aaa authorization network PPPoE_LIST group RADIUS_BRAS
aaa authorization subscriber-service default local group RADIUS_BRAS
aaa accounting network PPPoE_LIST start-stop group RADIUS_BRA
!
!
!
!
aaa server radius dynamic-author
client 172.19.1.10
auth-type any
!
aaa session-id common
aaa policy interface-config allow-subinterface
!
transport-map type persistent webui WEB_INT
server
secure-server
!

no ip domain lookup
ip domain name x.net

ip dhcp relay information option
ip dhcp relay information trust-all
!
!

!
!
subscriber service password service
no subscriber templating
virtual-profile virtual-template 10
!
multilink virtual-template 10
multilink bundle-name authenticated
!

!
license udi pid ASR1002-X sn JAE181701N9
license accept end user agreement
license boot level advipservices
archive
log config
logging enable
logging size 300
spanning-tree extend system-id
!
!
redundancy
mode sso
!

!
cdp run
!
class-map type control match-any PPPoE_CM
match service-name PPPoE_SRV
!
policy-map type control PPPoE
class type control PPPoE_CM event service-start
10 service-policy type service identifier service-name
!
class type control always event session-start
10 authenticate aaa list PPPoE_AUTHEN
!
!
!
policy-map 1M_IN
class class-default
police 1000000 1000000
policy-map 1M_OUT
class class-default
police 1000000 1000000
!

bba-group pppoe BBA_PPPoE
virtual-template 10
!
bba-group pppoe TEST_PPPoE
virtual-template 20
sessions per-vc limit 8
sessions per-mac limit 2
sessions per-vlan limit 50
!
!
interface Loopback10
ip address x.x.138.1 255.255.255.0
!
interface Loopback20
ip address 192.168.5.1 255.255.255.255
!
interface Loopback2000
no ip address
!
interface GigabitEthernet0/0/0
no ip address
speed 1000
no negotiation auto
!
interface GigabitEthernet0/0/0.2011
ip unnumbered Loopback2000
!
interface GigabitEthernet0/0/0.2056
encapsulation dot1Q 2056
pppoe enable group BBA_PPPoE
!
interface GigabitEthernet0/0/1
no ip address
negotiation auto
!
interface GigabitEthernet0/0/1.1
encapsulation dot1Q 1 native
ip address x.x.161.7 255.255.255.240
ip access-group OUTSIDE in
!
interface GigabitEthernet0/0/1.511
encapsulation dot1Q 511
ip address 172.19.1.5 255.255.255.0
!
interface GigabitEthernet0/0/2
no ip address
shutdown
negotiation auto
!
interface GigabitEthernet0/0/3
no ip address
shutdown
negotiation auto
!
interface GigabitEthernet0/0/4
no ip address
shutdown
negotiation auto
!
interface GigabitEthernet0/0/5
no ip address
shutdown
negotiation auto
!
interface GigabitEthernet0
vrf forwarding Mgmt-intf
ip address 10.0.99.102 255.255.255.0
negotiation auto
!
interface Virtual-Template10
ip unnumbered Loopback10
no ip redirects
peer default ip address pool STATIC
ppp authentication chap PPPoE_LIST
ppp authorization PPPoE_LIST
ppp accounting PPPoE_LIST
ppp ipcp dns x.x.161.20 x.x.161.30
!
router ospf 1
router-id x.x.161.7
shutdown
network x.x.161.0 0.0.0.15 area 0
!
ip local pool STATIC x.x.138.2 x.x.138.254
ip forward-protocol nd
!
ip http server
ip http authentication local
ip http secure-server
ip route 0.0.0.0 0.0.0.0 x.x.161.5
ip route x.x..23.99 255.255.255.255 x.x.161.5
ip route vrf Mgmt-intf 0.0.0.0 0.0.0.0 10.0.99.254
!
permit ip any any
ip access-list extended OUTSIDE
permit ip any host x.x.161.7
permit ip any x.x.138.0 0.0.0.255
deny ip any any
!
ip radius source-interface GigabitEthernet0/0/1.511

access-list 23 permit x.x..47.26
access-list 23 permit x.x..23.96 0.0.0.15
access-list 23 permit x.x.161.0 0.0.0.255

!
!
!
radius-server attribute 44 include-in-access-req default-vrf
radius-server attribute 6 on-for-login-auth
radius-server attribute 8 include-in-access-req
radius-server attribute 32 include-in-access-req
radius-server attribute 32 include-in-accounting-req
radius-server attribute 55 include-in-acct-req
radius-server attribute 55 access-request include
radius-server attribute 4 172.19.1.5
!
radius server RADIUS_SERV_1
address ipv4 172.19.1.10 auth-port 1812 acct-port 1813
key xxxxxxxxxxxx
!

RADIUS:

Service-Type = Framed-User

Framed-Protocol = PPP

Framed-Compression = none

Framed-IP-Address = x.x.138.2

Framed-IP-Netmask = 255.255.255.255

DEBUG:

Mar 19 11:22:33.931: PPPoE 268: I PADT R:646e.ea08.d58f L:88f0.31ad.3f00 2056 Gi0/0/0.2056
contiguous pak, size 36
88 F0 31 AD 3F 00 64 6E EA 08 D5 8F 81 00 28 08
88 63 11 A7 01 0C 00 0C 01 03 00 04 00 48 C0 18
01 01 00 00
Mar 19 11:22:37.252: PPPoE 268: I PADT R:646e.ea08.d58f L:88f0.31ad.3f00 2056 Gi0/0/0.2056
contiguous pak, size 36
88 F0 31 AD 3F 00 64 6E EA 08 D5 8F 81 00 28 08
88 63 11 A7 01 0C 00 0C 01 03 00 04 00 48 C0 18
01 01 00 00
Mar 19 11:22:37.543: PPPoE 268: I PADT R:646e.ea08.d58f L:88f0.31ad.3f00 2056 Gi0/0/0.2056
contiguous pak, size 36
88 F0 31 AD 3F 00 64 6E EA 08 D5 8F 81 00 28 08
88 63 11 A7 01 0C 00 0C 01 03 00 04 00 48 C0 18
01 01 00 00
Mar 19 11:22:37.643: PPPoE 0: I PADI R:646e.ea08.d58f L:ffff.ffff.ffff 2056 Gi0/0/0.2056
contiguous pak, size 106
FF FF FF FF FF FF 64 6E EA 08 D5 8F 81 00 28 08
88 63 11 09 00 00 00 52 01 03 00 04 00 48 C0 18
01 01 00 00 01 05 00 42 00 00 0D E9 01 36 49 53
4B 52 41 54 45 4C 3A 44 53 30 37 5F 36 33 36 32
2D 43 45 5F 53 47 54 5F ...
Mar 19 11:22:37.643: Service tag: NULL Tag
Mar 19 11:22:37.644: PPPoE 0: O PADO, R:88f0.31ad.3f00 L:646e.ea08.d58f 2056 Gi0/0/0.2056
Mar 19 11:22:37.644: Service tag: NULL Tag
contiguous pak, size 136
64 6E EA 08 D5 8F 88 F0 31 AD 3F 00 81 00 08 08
88 63 11 07 00 00 00 70 01 03 00 04 00 48 C0 18
01 01 00 00 01 05 00 42 00 00 0D E9 01 36 49 53
4B 52 41 54 45 4C 3A 44 53 30 37 5F 36 33 36 32
2D 43 45 5F 53 47 54 5F ...
Mar 19 11:22:37.655: PPPoE 0: I PADR R:646e.ea08.d58f L:88f0.31ad.3f00 2056 Gi0/0/0.2056
contiguous pak, size 126
88 F0 31 AD 3F 00 64 6E EA 08 D5 8F 81 00 28 08
88 63 11 19 00 00 00 66 01 01 00 00 01 03 00 04
00 48 C0 18 01 04 00 10 9C FB F6 E5 AF 44 F9 67
1E E7 DE 72 75 53 41 83 01 05 00 42 00 00 0D E9
01 36 49 53 4B 52 41 54 ...
Mar 19 11:22:37.655: Service tag: NULL Tag
Mar 19 11:22:37.655: PPPoE : encap string prepared
contiguous pak, size 24
64 6E EA 08 D5 8F 88 F0 31 AD 3F 00 81 00 08 08
88 64 11 00 01 0D 00 00
Mar 19 11:22:37.655: [269]PPPoE 269: Access IE handle allocated
Mar 19 11:22:37.655: [269]PPPoE 269: AAA get retrieved attrs
Mar 19 11:22:37.655: [269]PPPoE 269: AAA get nas port details
Mar 19 11:22:37.655: [269]PPPoE 269: Error adjusting nas port format did
Mar 19 11:22:37.655: AAA/BIND(000001F3): Bind i/f Virtual-Template10
Mar 19 11:22:37.655: [269]PPPoE 269: AAA get dynamic attrs
Mar 19 11:22:37.655: [269]PPPoE 269: AAA unique ID 1F3 allocated
Mar 19 11:22:37.655: [269]PPPoE 269: No AAA accounting method list
Mar 19 11:22:37.655: [269]PPPoE 269: Service request sent to SSS
Mar 19 11:22:37.655: [269]PPPoE 269: Created, Service: None R:88f0.31ad.3f00 L:646e.ea08.d58f 2056 Gi0/0/0.2056
Mar 19 11:22:37.655: SSS INFO: Element type is AAA-Id = 499 (000001F3)
Mar 19 11:22:37.655: SSS INFO: Element type is AccIe-Hdl = 1375731981 (5200010D)
Mar 19 11:22:37.655: SSS INFO: Element type is SHDB-Handle = 905969933 (3600010D)
Mar 19 11:22:37.655: SSS INFO: Element type is Input Interface = "GigabitEthernet0/0/0.2056"
Mar 19 11:22:37.655: SSS INFO: Element type is Access-Type = 3 (PPPoE)
Mar 19 11:22:37.655: SSS INFO: Element type is Protocol-Type = 0 (PPP Access Protocol)
Mar 19 11:22:37.655: SSS INFO: Element type is Media-Type = 1 (Ethernet)
Mar 19 11:22:37.655: SSS INFO: Element type is Switch-Id = 13415 (00003467)
Mar 19 11:22:37.655: SSS INFO: Element type is Segment-Hdl = 13416 (00003468)
Mar 19 11:22:37.655: SSS MGR [uid:269]: Sending a Session Assert ID Mgr request
Mar 19 11:22:37.655: SSS MGR [uid:269]: Updating ID Mgr with the following keys:
aaa-unique-id 0 499 (0x1F3)
Mar 19 11:22:37.655: SSS MGR [uid:269]: ID Mgr returned status: 'success' for Session Assert
Mar 19 11:22:37.655: SSS MGR [uid:269]: Handling Policy Service Authorize action (1 pending sessions)
Mar 19 11:22:37.656: SSS PM [uid:269][7F899228A670][AAA ID:499]: RM/VPDN disabled: RM/VPDN author not needed
Mar 19 11:22:37.656: SSS PM [uid:269][7F899228A670][AAA ID:499]: VPDN disabled: AAA author not needed
Mar 19 11:22:37.656: SSS PM [uid:269][7F899228A670][AAA ID:499]: SGBP disabled: SGF author not needed
Mar 19 11:22:37.656: SSS MGR [uid:269]: Got reply Local Terminate from PM
Mar 19 11:22:37.656: SSS MGR [uid:269]: Handling Connect Local Service action
Mar 19 11:22:37.656: SSS MGR [uid:269]: Need the resource type determined key
Mar 19 11:22:37.656: SSS MGR [uid:269]: Handling Need More Keys action
Mar 19 11:22:37.656: SSS MGR [uid:269]: Not yet ready to start the Local service
Mar 19 11:22:37.656: [269]PPPoE 269: State NAS_PORT_POLICY_INQUIRY Event SSS MORE KEYS
Mar 19 11:22:37.656: PPP: Alloc Context [7F8985A949E0]
Mar 19 11:22:37.656: ppp269 PPP: Phase is ESTABLISHING
Mar 19 11:22:37.656: [269]PPPoE 269: data path set to PPP
Mar 19 11:22:37.656: [269]PPPoE 269: Segment (SSS class): PROVISION
Mar 19 11:22:37.656: [269]PPPoE 269: State PROVISION_PPP Event SSM PROVISIONED
Mar 19 11:22:37.656: [269]PPPoE 269: O PADS R:646e.ea08.d58f L:88f0.31ad.3f00 Gi0/0/0.2056
contiguous pak, size 126
64 6E EA 08 D5 8F 88 F0 31 AD 3F 00 81 00 08 08
88 63 11 65 01 0D 00 66 01 01 00 00 01 03 00 04
00 48 C0 18 01 04 00 10 9C FB F6 E5 AF 44 F9 67
1E E7 DE 72 75 53 41 83 01 05 00 42 00 00 0D E9
01 36 49 53 4B 52 41 54 ...
Mar 19 11:22:37.656: [269]PPPoE 269 <Gi0/0/0.2056:2056>: Unable to add line attributes from ANCP
Mar 19 11:22:37.656: [269]PPPoE 269: Unable to Add ANCP Line attributes to the PPPoE Authen attributes
Mar 19 11:22:37.656: ppp269 PPP: Using vpn set call direction
Mar 19 11:22:37.656: ppp269 PPP: Treating connection as a callin
Mar 19 11:22:37.656: ppp269 PPP: Session handle[C100010D] Session id[269]
Mar 19 11:22:37.656: ppp269 LCP: Event[OPEN] State[Initial to Starting]
Mar 19 11:22:37.656: ppp269 PPP LCP: Enter passive mode, state[Stopped]
Mar 19 11:22:37.704: ppp269 LCP: I CONFREQ [Stopped] id 29 len 10
Mar 19 11:22:37.704: ppp269 LCP: MagicNumber 0x1C9EFCED (0x05061C9EFCED)
Mar 19 11:22:37.704: ppp269 LCP: O CONFREQ [Stopped] id 1 len 19
Mar 19 11:22:37.704: ppp269 LCP: MRU 1492 (0x010405D4)
Mar 19 11:22:37.704: ppp269 LCP: AuthProto CHAP (0x0305C22305)
Mar 19 11:22:37.704: ppp269 LCP: MagicNumber 0xF58F09A5 (0x0506F58F09A5)
Mar 19 11:22:37.704: ppp269 LCP: O CONFACK [Stopped] id 29 len 10
Mar 19 11:22:37.704: ppp269 LCP: MagicNumber 0x1C9EFCED (0x05061C9EFCED)
Mar 19 11:22:37.704: ppp269 LCP: Event[Receive ConfReq+] State[Stopped to ACKsent]
Mar 19 11:22:37.715: ppp269 LCP: I CONFACK [ACKsent] id 1 len 19
Mar 19 11:22:37.715: ppp269 LCP: MRU 1492 (0x010405D4)
Mar 19 11:22:37.715: ppp269 LCP: AuthProto CHAP (0x0305C22305)
Mar 19 11:22:37.715: ppp269 LCP: MagicNumber 0xF58F09A5 (0x0506F58F09A5)
Mar 19 11:22:37.715: ppp269 LCP: Event[Receive ConfAck] State[ACKsent to Open]
Mar 19 11:22:37.716: ppp269 LCP-FS: I ECHOREQ [Open] id 0 len 8 magic 0x1C9EFCED
Mar 19 11:22:37.716: ppp269 LCP-FS: O ECHOREP [Open] id 0 len 8 magic 0xF58F09A5
Mar 19 11:22:37.717: ppp269 PPP: Phase is AUTHENTICATING, by this end
Mar 19 11:22:37.717: ppp269 CHAP: O CHALLENGE id 1 len 27 from "BRAS_2"
Mar 19 11:22:37.717: ppp269 LCP: State is Open
Mar 19 11:22:37.729: ppp269 CHAP: I RESPONSE id 1 len 28 from "test001"
Mar 19 11:22:37.729: ppp269 PPP: Phase is FORWARDING, Attempting Forward
Mar 19 11:22:37.729: SSS INFO: Element type is Protocol-Type = 0 (PPP Access Protocol)
Mar 19 11:22:37.729: SSS INFO: Element type is Unauth-User = "test001"
Mar 19 11:22:37.729: SSS INFO: Element type is AccIe-Hdl = 1375731981 (5200010D)
Mar 19 11:22:37.729: SSS INFO: Element type is AAA-Id = 499 (000001F3)
Mar 19 11:22:37.729: SSS INFO: Element type is Access-Type = 0 (PPP)
Mar 19 11:22:37.729: SSS MGR [uid:269]: Sending a Session Update ID Mgr request
Mar 19 11:22:37.729: SSS MGR [uid:269]: Updating ID Mgr with the following keys:
username 0 "test001"
aaa-unique-id 0 499 (0x1F3)
Mar 19 11:22:37.729: SSS MGR [uid:269]: ID Mgr returned status: 'updated' for Session Update
Mar 19 11:22:37.729: SSS MGR [uid:269]: Handling Connect Local Service action
Mar 19 11:22:37.729: SSS MGR [uid:269]: Need the resource type determined key
Mar 19 11:22:37.729: SSS MGR [uid:269]: Handling Need More Keys action
Mar 19 11:22:37.729: SSS MGR [uid:269]: Not yet ready to start the Local service
Mar 19 11:22:37.729: ppp269 PPP: Phase is AUTHENTICATING, Unauthenticated User
Mar 19 11:22:37.729: AAA/AUTHEN/PPP (000001F3): Pick method list 'PPPoE_LIST'
Mar 19 11:22:37.729: RADIUS/ENCODE(000001F3):Orig. component type = PPPoE
Mar 19 11:22:37.729: RADIUS: DSL line rate attributes successfully added
Mar 19 11:22:37.729: RADIUS(000001F3): Config NAS IPv6: ::
Mar 19 11:22:37.729: RADIUS/ENCODE: No idb found! Framed IP Addr might not be included
Mar 19 11:22:37.729: RADIUS/ENCODE(000001F3): acct_session_id: 489
Mar 19 11:22:37.729: RADIUS(000001F3): sending
Mar 19 11:22:37.729: RADIUS(000001F3): Send Access-Request to 172.19.1.10:1812 id 1645/19, len 166
Mar 19 11:22:37.729: RADIUS: authenticator 8E C6 9B F9 18 A2 18 C2 - 37 0A 5D 34 C3 2B 9D 59
Mar 19 11:22:37.729: RADIUS: Framed-Protocol [7] 6 PPP [1]
Mar 19 11:22:37.729: RADIUS: User-Name [1] 9 "test001"
Mar 19 11:22:37.729: RADIUS: CHAP-Password [3] 19 *
Mar 19 11:22:37.729: RADIUS: NAS-Port-Type [61] 6 Virtual [5]
Mar 19 11:22:37.729: RADIUS: NAS-Port [5] 6 0
Mar 19 11:22:37.729: RADIUS: NAS-Port-Id [87] 12 "0/0/0/2056"
Mar 19 11:22:37.729: RADIUS: Vendor, Cisco [26] 41
Mar 19 11:22:37.729: RADIUS: Cisco AVpair [1] 35 "client-mac-address=646e.ea08.d58f"
Mar 19 11:22:37.729: RADIUS: Service-Type [6] 6 Framed [2]
Mar 19 11:22:37.729: RADIUS: NAS-IP-Address [4] 6 172.19.1.5
Mar 19 11:22:37.729: RADIUS: Acct-Session-Id [44] 10 "000001E9"
Mar 19 11:22:37.729: RADIUS: Nas-Identifier [32] 19 "BRAS_2.x.net"
Mar 19 11:22:37.729: RADIUS: Event-Timestamp [55] 6 1426764157
Mar 19 11:22:37.729: RADIUS(000001F3): Sending a IPv4 Radius Packet
Mar 19 11:22:37.730: RADIUS(000001F3): Started 5 sec timeout
Mar 19 11:22:37.737: RADIUS: Received from id 1645/19 172.19.1.10:1812, Access-Accept, len 50
Mar 19 11:22:37.737: RADIUS: authenticator 8D AE E1 AF EE 25 FA 0C - 91 63 9C E7 D5 52 ED 27
Mar 19 11:22:37.737: RADIUS: Framed-Protocol [7] 6 PPP [1]
Mar 19 11:22:37.737: RADIUS: Framed-Compression [13] 6 None [0]
Mar 19 11:22:37.737: RADIUS: Framed-IP-Address [8] 6 x.x.138.2
Mar 19 11:22:37.737: RADIUS: Framed-IP-Netmask [9] 6 255.255.255.255
Mar 19 11:22:37.737: RADIUS: Service-Type [6] 6 Framed [2]
Mar 19 11:22:37.737: RADIUS(000001F3): Received from id 1645/19
Mar 19 11:22:37.737: ppp269 PPP: Phase is FORWARDING, Attempting Forward
Mar 19 11:22:37.737: SSS INFO: Element type is Protocol-Type = 0 (PPP Access Protocol)
Mar 19 11:22:37.737: SSS INFO: Element type is Final = 1 (YES)
Mar 19 11:22:37.737: SSS INFO: Element type is Auth-User = "test001"
Mar 19 11:22:37.737: SSS INFO: Element type is AAA-Attr-List = 6F00155C
Mar 19 11:22:37.737: SSS INFO: Element type is Framed-Protocol 0 1 [PPP]
Mar 19 11:22:37.737: SSS INFO: Element type is link-compression 0 5 [no-vj]
Mar 19 11:22:37.737: SSS INFO: Element type is addr 0 x.x.138.2
Mar 19 11:22:37.737: SSS INFO: Element type is netmask 0 255.255.255.255
Mar 19 11:22:37.737: SSS INFO: Element type is service-type 0 2 [Framed]
Mar 19 11:22:37.737: SSS INFO: Element type is Resource-Determined = 1 (YES)
Mar 19 11:22:37.737: SSS INFO: Element type is Access-Type = 0 (PPP)
Mar 19 11:22:37.737: SSS MGR [uid:269]: Handling Connect Local Service action
Mar 19 11:22:37.737: SSS MGR [uid:269]: Rcvd an AAA attr list from SIP, pushing it to the PM
Mar 19 11:22:37.737: SSS MGR [uid:269]: Handling Send Policy Push Cng action
Mar 19 11:22:37.737: SSS MGR [uid:269]: Not yet ready to start the Local service
Mar 19 11:22:37.738: SSS MGR [uid:269]: Got reply Apply Config from PM
Mar 19 11:22:37.738: SSS MGR [uid:269]: Successfully applied policy config
Mar 19 11:22:37.738: SSS MGR [uid:269]: Handling Connect Local Service action
Mar 19 11:22:37.738: SSS LTERM [uid:269]: Processing Local termination request
Mar 19 11:22:37.738: SSS LTERM [uid:269]: Features require a full vaccess interface
Mar 19 11:22:37.738: VT:Sending vaccess request, id 0xF90002A1
Mar 19 11:22:37.738: SSS LTERM [uid:269]: Sent create-clone request to vtemplate manager
Mar 19 11:22:37.738: VT:Processing vaccess requests, 1 outstanding
Mar 19 11:22:37.738: VT:Processing create-clone request
Mar 19 11:22:37.738: VT:Create and clone interface, Vt10
Mar 19 11:22:37.738: VT[Vi3]:Reuse PPP interface, recycle queue size 1
Mar 19 11:22:37.738: VT[Vi3]:Set to default using 'encap ppp'
Mar 19 11:22:37.738: VT[Vi3]:Vaccess created, va_swidb: 7F89929A0260
Mar 19 11:22:37.738: SSS MGR: Create SSS Mgr Subblock 0x7F899223FD78
Mar 19 11:22:37.738: VT[Vi3]:Cloning a vaccess
Mar 19 11:22:37.738: VT[Vi3]:Vtemplate num 10 updated in va-info
Mar 19 11:22:37.738: VT[Vi3]:Added new vtemplate cloneblk, now cloning from vtemplate
Mar 19 11:22:37.738: VT[Vi3]:Clone Vaccess from Virtual-Template10 (21 bytes)
Mar 19 11:22:37.738: VT[Vi3]:no ip redirects
Mar 19 11:22:37.738: VT[Vi3]:end
Mar 19 11:22:37.738: VT[Vi3]:Applying config commands on process "VTEMPLATE Background Mgr" (458)
Mar 19 11:22:37.738: VT[Vi3]:no ip redirects
Mar 19 11:22:37.739: VT[Vi3]:end
Mar 19 11:22:37.739: VT[Vi3]:Request took 1 msec, 1 msec processing time
Mar 19 11:22:37.739: VT[Vi3]:MTUs ip 1500, sub 1500, max 1500, default 1500
Mar 19 11:22:37.739: VT[Vi3]:Processing vaccess response, id 0xF90002A1, result success (1)
Mar 19 11:22:37.740: SSS LTERM [uid:269]: Created vaccess interface Vi3
Mar 19 11:22:37.740: SSS LTERM [uid:269]: prot type:0 childsip:0 rootsip:3
Mar 19 11:22:37.740: SSS LTERM [uid:269]: Segment provision successful
Mar 19 11:22:37.740: SSS MGR [uid:269]: Handling Local Service Connected action
Mar 19 11:22:37.740: SSS MGR [uid:269]: Apply for Vi3: segment 13416, owner 4177527457
Mar 19 11:22:37.740: SSS MGR [uid:269]: Interface config 7F89913BA208
Mar 19 11:22:37.740: SSS MGR [uid:269]: Per-user config 3400009A
Mar 19 11:22:37.740: SSS LTERM [uid:269]: Vi3 Switching session provisioned
Mar 19 11:22:37.740: INFO: AAA/AUTHOR: Processing PerUser AV link-compression
Mar 19 11:22:37.740: AAA/PER-USER:INFO: No peruser DB associated with id 0
Mar 19 11:22:37.740: Vi3 AAA/PER-USER/link-compression: Disable of header compression not required
Mar 19 11:22:37.740: SSS MGR [uid:269]: Handling Local Service Connected, Features Applied action
Mar 19 11:22:37.740: [269]PPPoE 269: State LCP_NEGOTIATION Event SSS CONNECT LOCAL
Mar 19 11:22:37.741: [269]PPPoE 269: Segment (SSS class): UPDATED
Mar 19 11:22:37.741: SSS LTERM [uid:269]: Installed Vi3 process path switching vector
Mar 19 11:22:37.741: SSS LTERM [uid:269]: Installed Vi3 fastsend path switching vector
Mar 19 11:22:37.741: [269]PPPoE 269: Segment (SSS class): BOUND
Mar 19 11:22:37.741: [269]PPPoE 269: data path set to Virtual Acess
Mar 19 11:22:37.741: [269]PPPoE 269: State LCP_NEGOTIATION Event SSM UPDATED
Mar 19 11:22:37.741: AAA/BIND(000001F3): Bind i/f Virtual-Access3
Mar 19 11:22:37.741: Vi3 PPP: Phase is AUTHENTICATING, Authenticated User
Mar 19 11:22:37.741: Vi3 CHAP: O SUCCESS id 1 len 4
Mar 19 11:22:37.741: [269]PPPoE 269: AAA get dynamic attrs
Mar 19 11:22:37.741: Vi3 PPP: Phase is UP
Mar 19 11:22:37.741: Vi3 IPCP: Protocol configured, start CP. state[Initial]
Mar 19 11:22:37.741: Vi3 IPCP: Event[OPEN] State[Initial to Starting]
Mar 19 11:22:37.742: Vi3 IPCP: O CONFREQ [Starting] id 1 len 10
Mar 19 11:22:37.742: Vi3 IPCP: Address x.x.138.1 (0x030605208A01)
Mar 19 11:22:37.742: Vi3 IPCP: Event[UP] State[Starting to REQsent]
Mar 19 11:22:37.742: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access3, changed state to up
Mar 19 11:22:37.742: %LINK-3-UPDOWN: Interface Virtual-Access3, changed state to up
Mar 19 11:22:37.743: [269]PPPoE 269: State PTA_BINDING Event STATIC BIND RESPONSE
Mar 19 11:22:37.743: [269]PPPoE 269: Connected PTA
Mar 19 11:22:37.752: Vi3 IPCP: I CONFREQ [REQsent] id 67 len 22
Mar 19 11:22:37.752: Vi3 IPCP: Address 0.0.0.0 (0x030600000000)
Mar 19 11:22:37.752: Vi3 IPCP: PrimaryDNS 0.0.0.0 (0x810600000000)
Mar 19 11:22:37.752: Vi3 IPCP: SecondaryDNS 0.0.0.0 (0x830600000000)
Mar 19 11:22:37.752: Vi3 IPCP AUTHOR: Start. Her address 0.0.0.0, we want 0.0.0.0
Mar 19 11:22:37.752: Vi3 IPCP AUTHOR: Done. Her address 0.0.0.0, we want x.x.138.2
Mar 19 11:22:37.752: Vi3 IPCP: O CONFNAK [REQsent] id 67 len 22
Mar 19 11:22:37.752: Vi3 IPCP: Address x.x.138.2 (0x030605208A02)
Mar 19 11:22:37.752: Vi3 IPCP: PrimaryDNS x.x.161.20 (0x81065BC7A114)
Mar 19 11:22:37.752: Vi3 IPCP: SecondaryDNS x.x.161.30 (0x83065BC7A11E)
Mar 19 11:22:37.752: Vi3 IPCP: Event[Receive ConfReq-] State[REQsent to REQsent]
Mar 19 11:22:37.753: Vi3 IPCP: I CONFACK [REQsent] id 1 len 10
Mar 19 11:22:37.753: Vi3 IPCP: Address x.x.138.1 (0x030605208A01)
Mar 19 11:22:37.753: Vi3 IPCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]
Mar 19 11:22:37.763: Vi3 IPCP: I CONFREQ [ACKrcvd] id 68 len 22
Mar 19 11:22:37.763: Vi3 IPCP: Address x.x.138.2 (0x030605208A02)
Mar 19 11:22:37.763: Vi3 IPCP: PrimaryDNS x.x.161.20 (0x81065BC7A114)
Mar 19 11:22:37.763: Vi3 IPCP: SecondaryDNS x.x.161.30 (0x83065BC7A11E)
Mar 19 11:22:37.763: Vi3 IPCP: O CONFACK [ACKrcvd] id 68 len 22
Mar 19 11:22:37.763: Vi3 IPCP: Address x.x.138.2 (0x030605208A02)
Mar 19 11:22:37.763: Vi3 IPCP: PrimaryDNS x.x.161.20 (0x81065BC7A114)
Mar 19 11:22:37.763: Vi3 IPCP: SecondaryDNS x.x.161.30 (0x83065BC7A11E)
Mar 19 11:22:37.763: Vi3 IPCP: Event[Receive ConfReq+] State[ACKrcvd to Open]
Mar 19 11:22:37.781: Vi3 IPCP: State is Open
Mar 19 11:22:37.781: PPPoE : ipfib_encapstr prepared
contiguous pak, size 26
64 6E EA 08 D5 8F 88 F0 31 AD 3F 00 81 00 08 08
88 64 11 00 01 0D 00 00 00 21
Mar 19 11:22:37.782: SSS MGR [uid:269]: Sending a Session Update ID Mgr request
Mar 19 11:22:37.782: SSS MGR [uid:269]: Updating ID Mgr with the following data- smgr hdl0xF90002A1 :
addr 0 x.x.138.2
Mar 19 11:22:37.782: SSS MGR [uid:269]: ID Mgr returned status: 'updated' for Session Update
Mar 19 11:22:37.782: %FMANRP_ESS-4-FULLVAI: Session creation failed due to Full Virtual-Access Interfaces not being supported. Check that all applied Virtual-Template and RADIUS features support Virtual-Access sub-interfaces. swidb= 0x7F89929A0260, ifnum= 31
Mar 19 11:22:37.782: Vi3 Added to neighbor route AVL tree: topoid 0, address x.x.138.2
Mar 19 11:22:37.782: Vi3 IPCP: Install route to x.x.138.2
Mar 19 11:22:37.782: VT[Vi3]:Vaccess descriptor block flag set to 0x1
Mar 19 11:22:37.782: SSS LTERM [uid:269]: LTERM segment handle synced ccm group id:0
Mar 19 11:22:37.782: [269]PPPoE 269: State LOCALLY_TERMINATED Event SSM DISCONNECT
Mar 19 11:22:37.783: Vi3 PPP DISC: Lower Layer disconnected
Mar 19 11:22:37.783: Vi3 PPP: Sending Acct Event[Down] id[1F3]
Mar 19 11:22:37.783: [269]PPPoE 269: AAA get dynamic attrs
Mar 19 11:22:37.783: PPP: NET STOP send to AAA.
Mar 19 11:22:37.783: Vi3 IPCP: Event[DOWN] State[Open to Starting]
Mar 19 11:22:37.783: Vi3 IPCP: Event[CLOSE] State[Starting to Initial]
Mar 19 11:22:37.783: Vi3 LCP: O TERMREQ [Open] id 2 len 4
Mar 19 11:22:37.783: Vi3 LCP: Event[CLOSE] State[Open to Closing]
Mar 19 11:22:37.783: Vi3 PPP: Phase is TERMINATING
Mar 19 11:22:37.783: [269]PPPoE 269: O PADT R:646e.ea08.d58f L:88f0.31ad.3f00 Gi0/0/0.2056
contiguous pak, size 64
64 6E EA 08 D5 8F 88 F0 31 AD 3F 00 81 00 08 08
88 63 11 A7 01 0D 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Mar 19 11:22:37.783: [269]PPPoE 269: Destroying R:646e.ea08.d58f L:88f0.31ad.3f00 2056 Gi0/0/0.2056
Mar 19 11:22:37.783: PPPoE: Returning Vaccess Virtual-Access3
Mar 19 11:22:37.783: Vi3 PPP: Block vaccess from being freed [0x10]
Mar 19 11:22:37.783: VT[Vi3]:Ignoring free request, vaccess still in use by PPP
Mar 19 11:22:37.783: [269]PPPoE 269: AAA account stopped
Mar 19 11:22:37.784: Vi3 Deleted neighbor route from AVL tree: topoid 0, address x.x.138.2
Mar 19 11:22:37.784: Vi3 IPCP: Remove route to x.x.138.2
Mar 19 11:22:37.784: Vi3 LCP: Event[DOWN] State[Closing to Initial]
Mar 19 11:22:37.784: Vi3 PPP: Unlocked by [0x10] Still Locked by [0x0]
Mar 19 11:22:37.784: Vi3 PPP: Free previously blocked vaccess
Mar 19 11:22:37.784: SSS LTERM [uid:269]: Vi3 is still in use by LTERM data-plane
Mar 19 11:22:37.784: VT[Vi3]:Ignoring free request, vaccess still in use by LTERM data-plane
Mar 19 11:22:37.784: Vi3 PPP: Phase is DOWN
Mar 19 11:22:37.784: SSS MGR [uid:269]: Processing a client disconnect
Mar 19 11:22:37.784: SSS MGR [uid:269]: Handling Send Service Disconnect action
Mar 19 11:22:37.784: SSS MGR [uid:269]: No accounting feature installed skipping attribute gathering
Mar 19 11:22:37.784: SSS INFO: Element type is IETF-Disc-Cause = 6 (00000006)
Mar 19 11:22:37.784: SSS INFO: Element type is Ascend-Disc-Cause = 52 (00000034)
Mar 19 11:22:37.784: SSS MGR [uid:269]: Handling Disconnecting, Network Service Feature Clean action
Mar 19 11:22:37.784: SSS MGR [uid:269]: Sending a Session End ID Mgr request
Mar 19 11:22:37.784: SSS MGR [uid:269]: ID Mgr returned status: 'deleted' for Session End
Mar 19 11:22:37.784: SSS MGR [uid:269]: Freeing vaccess interface Vi3, 7F89929A0260
Mar 19 11:22:37.784: SSS LTERM [uid:269]: Vi3 is still in use by LTERM data-plane
Mar 19 11:22:37.784: VT[Vi3]:Ignoring free request, vaccess still in use by LTERM data-plane
Mar 19 11:22:37.784: SSS MGR [uid:269]: Clean up SSS Mgr Subblock 0x7F899223FD78
Mar 19 11:22:37.784: SSS MGR [uid:269]: Publish session done aaa 499, uid 269
Mar 19 11:22:37.784: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access3, changed state to down
Mar 19 11:22:37.785: %LINK-3-UPDOWN: Interface Virtual-Access3, changed state to down
Mar 19 11:22:37.785: [269]PPPoE 269: Segment (SSS class): UNBOUND
Mar 19 11:22:37.785: SSS LTERM [uid:269]: Switching session unprovisioned
Mar 19 11:22:37.785: SSS LTERM [uid:269]: Uninstalled Vi3 process path switching vector
Mar 19 11:22:37.785: SSS LTERM [uid:269]: Uninstalled Vi3 fastsend path switching vector
Mar 19 11:22:37.786: [269]PPPoE 269: Vi3 Block vaccess from being freed.
Mar 19 11:22:37.786: VT[Vi3]:Ignoring free request, vaccess still in use by PPPoE switching
Mar 19 11:22:37.786: [269]PPPoE 269: Segment (SSS class): UNPROVISION
Mar 19 11:22:37.786: VT[Vi3]:Processing request to free vaccess
Mar 19 11:22:37.786: VT[Vi3]:Interface and line protocol are down, proceed to free
Mar 19 11:22:37.786: VT[Vi3]:Vaccess descriptor block flag set to 0x1
Mar 19 11:22:37.786: VT[Vi3]:HA: Sent Del chkpt for vaccess with if_num 31
Mar 19 11:22:37.786: VT[Vi3]:Updated ref id to 139
Mar 19 11:22:37.786: VT[Vi3]:Vaccess free request complete, reference id 139
Mar 19 11:22:37.786: VT:Clean up dirty vaccess queue, size 1
Mar 19 11:22:37.786: VT[Vi3]:Found a dirty vaccess cloned from vtemplate
Mar 19 11:22:37.786: VT[Vi3]:Unclone vaccess, 1 command(s) to be removed
Mar 19 11:22:37.786: VT[Vi3]:default ip redirects
Mar 19 11:22:37.786: VT[Vi3]:end
Mar 19 11:22:37.786: VT[Vi3]:Applying config commands on process "VTEMPLATE Background Mgr" (458)
Mar 19 11:22:37.786: VT[Vi3]:default ip redirects
Mar 19 11:22:37.786: VT[Vi3]:end
Mar 19 11:22:37.787: VT[Vi3]:Remove cloneblk vtemplate from vaccess with vtemplate
Mar 19 11:22:37.787: VT[Vi3]:Hardware address 88f0.31ad.3f00
Mar 19 11:22:37.787: VT[Vi3]:Posting VA recycle req
Mar 19 11:22:37.787: VT[Vi3]:Notifying VA recycle client VT
Mar 19 11:22:37.787: VT[Vi3]:VA recycle client VT returned DONE
Mar 19 11:22:37.787: VT[Vi3]:Notifying VA recycle client ASR1K FMANRP ESS
Mar 19 11:22:37.787: VT[Vi3]:VA recycle client ASR1K FMANRP ESS returned OK
Mar 19 11:22:37.787: VT[Vi3]:Starting VA recycle timer for client ASR1K FMANRP ESS
Mar 19 11:22:37.792: VT[Vi3]:VA Recycle client ASR1K FMANRP ESS Done
Mar 19 11:22:37.792: VT[Vi3]:Posting VA recycle req
Mar 19 11:22:37.792: VT[Vi3]:Notifying VA recycle client VT-RF
Mar 19 11:22:37.792: VT[Vi3]:HA: Waiting for Del-ack
Mar 19 11:22:37.792: VT[Vi3]:VA recycle client VT-RF returned OK
Mar 19 11:22:37.886: VT[Vi3]:HA: Vaccess recycled on RRP
Mar 19 11:22:37.886: VT[Vi3]:HA: Notifying VA Recycle facility
Mar 19 11:22:37.886: VT[Vi3]:VA Recycle client VT-RF Done
Mar 19 11:22:37.886: VT[Vi3]:Posting VA recycle req
Mar 19 11:22:37.886: VT[Vi3]:Done with VA recycle
Mar 19 11:22:37.886: VT[Vi3]:Deleting if index table entry
Mar 19 11:22:37.886: VT[Vi3]:Add vaccess to recycle queue, queue size 1

In one example this error doesn't appear. If i add in RADIUS attribute Cisco-AVPai+="ip:addr-pool=STATIC", but in other hand PPP negotiation doesn't success (IPCP not installed route etc.).

I have 2 example, when sesion goes up, but this is not solution:

If i do authentication locally then session strats OK.

If i change configuration from aaa authorization network PPPoE_LIST group RADIUS_BRAS to aaa authorization network PPPoE_LIST none session starts OK, but no attribute from RADIUS apply to subscriber profile.

On ASR i have IOS-XE: asr1002x-universalk9.03.12.00.S.154-2.S-std.SPA.bin

I didn't try upgrade IOS.

if you have any advice I would be appreciate.

Many thanks.

Manuel Rodriguez · ‎03-19-2015

Hi Blaz,

In the debugs, I still see Framed-Compression attribute in the access-accept sent from radius:

Mar 19 11:22:37.737: RADIUS: Framed-Compression [13] 6 None [0]

Changing the compression from "Van-Jacobsen-TCP-IP" to 'None' is not enough. You need to remove the Framed-Compression attribute completely from the radius profile for the subscriber.

Could you try that?

Regards

View solution in original post

Manuel Rodriguez · ‎03-19-2015

Hi Blaz,

In the debugs, I still see Framed-Compression attribute in the access-accept sent from radius:

Mar 19 11:22:37.737: RADIUS: Framed-Compression [13] 6 None [0]

Changing the compression from "Van-Jacobsen-TCP-IP" to 'None' is not enough. You need to remove the Framed-Compression attribute completely from the radius profile for the subscriber.

Could you try that?

Regards

Blaz Zupancic · ‎03-19-2015

Hi Manuel,

you're amazing :).

For now i was just worked changes in postgresql tables (radreply and radgroupreply) about attributes. When i don't choose Framed-Compression attribute at all, i got in Acess-Accept VJ TCP/IP value.

Now i start search in settings and i find in file /etc/freeradius/users listed default attributes for PPP - i just put comment and now works!

I'm really appreciated for your time. Thanks.

Blaz

Manuel Rodriguez · ‎03-19-2015

Glad it worked! :)

Jonathan Bayless · ‎04-16-2020

I came across this issue myself recently when working with an ASR 1006. In my case the Framed-Compression attribute was only one problem. After fixing that, I still could not get the router to create Virtual Subinterfaces correctly which meant users could not connect. Eventually I found the idea to use the command line 'test' tool on the router to see why it would not create the subinterfaces. When I initially tested, it failed and could not create subinterfaces. The reason was that in the virtual-template configuration I had added 'logging event link-status' which prevents the router from creating subinterfaces for some reason. Once I removed that configuration, the router was able to properly create subinterfaces and worked fine.

test virtual-Template 100 subinterface

Subinterfaces may be created using Virtual-Template100