ASR9K LAC to LNS forwarding PPP issues

dkfastcom · ‎06-29-2019

Hi All,

We have been testing LAC functionality due to a need to migrate some network functions to our ASR9010 chassis.

At a very high level it appears that the VPDN tunnel is establishing to the downstream LNS (ASR1001) however there is no PPP credentials then being seen by the downstream LNS.

Unfortunately due to some legacy 1Gb port requirements we are running on version 6.0.2 code to support the legacy trident card however the PPPoE / LAC termination and forwarding is all being done on a typhoon A9K-24X10GE-SE.

Items which are relevant:

1. Inbound PPPoE subscribers hit the bundle-ether interface and authentication starts.

2. If realmtest.local is seen then forward this to the LNS downstream. The LAC is getting these VPDN details from radius and establishing the VPDN tunnel successfully. (Note the VPDN is established within a VRF)

3. If the subscriber belongs to anything else terminate locally on the 9k. (This is working without any issue).

So to confirm we are seeing the policies work and either forward or terminate based on the above.

We see the VPDN tunnel stand up and establish. We then dont see any PPPoE attempts at the LNS via the tunnel.

Based on the VPDN and PPP debug log attached I can see:

PAP: Ack duplicate REQUEST (id 0x5) received after authentication has completed

It appears that maybe the LAC is seeing the auth request again and not forwarding it in the VPDN tunnel?

Have been working through this for several weeks now and have not yet been able to crack it so any ideas on what could be the cause would be greatly appreciated.

Thanks

Daniel

++++++ CONFIG ++++++

A9k-VPDN tunnel up:

Destination VRF-name Status Load Connects Disconnects Retries
10.0.0.1 18015:1801510 ACTIVE 1 1 0 0

Cisco LNS VPDN tunnel up:
26784 50126 a9k-lac est 10.0.0.2 1 7

A9k-Relevant Config

interface Bundle-Ether1500.41
service-policy type control subscriber POLICY_PTA_LAC
pppoe enable bba-group PPPOE-FIBRE
encapsulation dot1q 41
!

policy-map type control subscriber POLICY_PTA_LAC
event session-start match-first
class type control subscriber CLASS_PPP do-until-failure
10 activate dynamic-template LCP_FEATURE
!
!
event session-activate match-first
class type control subscriber CLASS_LAC do-until-failure
10 authorize aaa list default format vpdn_domain password cisco
!
class type control subscriber CLASS_PPP do-until-failure
10 authenticate aaa list default
20 activate dynamic-template PTA
!
!
end-policy-map
!
class-map type control subscriber match-any PPP
match protocol ppp
end-class-map
!
aaa attribute format vpdn_domain
username-strip prefix-delimiter @
!
class-map type control subscriber match-all CLASS_LAC
match domain realmtest.local format vpdn_domain
end-class-map
!
class-map type control subscriber match-all CLASS_PPP
match protocol ppp
end-class-map
!
dynamic-template
type ppp PTA
ipv4 mtu 1492
ipv4 verify unicast source reachable-via rx
!
type ppp LCP_FEATURE
ppp timeout retry 3
ppp authentication pap
ppp timeout authentication 5
!
!
aaa attribute format vpdn_domain
username-strip prefix-delimiter @
!
vpdn
l2tp reassembly
history failure
logging local
logging user
logging cause normal
logging dead-cache
logging tunnel-drop
template default
tunnel busy timeout 600
l2tp-class class
dsl-line-info-forwarding
!
!

Giuseppe Larosa · ‎06-29-2019

Hello Dan,

looking at the debug log I have noticed the following lines:

>> -MA[391]: [VPDN:CALL:EVENT]: Sending call 0 to VPDN MGR for user 'dan.test@realmtest.local' (sub_label:0x392 sub_ifh:0x8031060 replay:0).
RP/0/RSP0/CPU0:Jun 29 18:52:03.214 : vpdn_mgr[1214]: [VPDN:CALL:EVENT]: vpdn_cs_ipc_callback Received IPC input waiting notification
RP/0/RSP0/CPU0:Jun 29 18:52:03.214 : vpdn_mgr[1214]: [VPDN:CALL:EVENT]: New session added, total sessions: 1.
RP/0/RSP0/CPU0:Jun 29 18:52:03.214 : vpdn_mgr[1214]: [VPDN:CALL:DATA]: Session 0x392 (sub_ifh:0x8031060 sub_parent_ifh:0x80199e0), Username: dan.test@realmtest.local
>>>>RP/0/RSP0/CPU0:Jun 29 18:52:03.214 : vpdn_mgr[1214]: [VPDN:CALL:DATA]: Tunnel Endpoints: 0.0.0.0 <--> 0.0.0.0
RP/0/RSP0/CPU0:Jun 29 18:52:03.214 : vpdn_mgr[1214]: [VPDN:CALL:DATA]: Tunnel Type: 3, Tunnel Medium Type: 0
RP/0/RSP0/CPU0:Jun 29 18:52:03.214 : vpdn_mgr[1214]: [VPDN:CALL:DATA]: Tunnel Client Auth ID: , Tunnel Server Auth ID: , Tunnel Authen: FALSE
RP/0/RSP0/CPU0:Jun 29 18:52:03.214 : vpdn_mgr[1214]: [VPDN:CALL:DATA]: Nas Port ID: ^O^P ^B^C^D, Rx Speed: 1000000000, Tx Speed: 1000000000
>>>>RP/0/RSP0/CPU0:Jun 29 18:52:03.214 : vpdn_mgr[1214]: [VPDN:CALL:DATA]: Tunnel VRF ID: 0

I would like to point out two aspects:

A) tunnel endpoints are both 0.0.0.0

>>>>RP/0/RSP0/CPU0:Jun 29 18:52:03.214 : vpdn_mgr[1214]: [VPDN:CALL:DATA]: Tunnel Endpoints: 0.0.0.0 <--> 0.0.0.0

B) the tunnel VRF ID is 0

RP/0/RSP0/CPU0:Jun 29 18:52:03.214 : vpdn_mgr[1214]: [VPDN:CALL:DATA]: Tunnel VRF ID: 0

You have written that the VPDN tunnel is in a VRF, tunnel VRF ID 0 makes me think of Global routing table.

The fact that the tunnel endpoints are set both to 0.0.0.0 make me think the device is not finding the correct VPDN tunnel to use for forwarding PPP frames.

In configuration under vpdn I would expect to find a reference to VPDN tunnel and to the VRF it belongs to.

But this is just a first look.

Edit:

making some search on Cisco site I have found the following example of a VPDN template for IOS XR 6.0.x

Configuring the VPDN Template

Perform this task to configure the vpdn template:

SUMMARY STEPS

configure
vpdn template
l2tp-class class_name
tunnel busy timeout timeout_value
caller-id mask-method remove match match_substring
dsl-line-info-forwarding
ip tos type_of_service_value
vpn id value
vpn vrf vrf_name
commit

Note the steps 8 and 9, step 9 specify the VRFs

see

https://www.cisco.com/c/en/us/td/docs/routers/asr9000/software/asr9k_r6-0/bng/configuration/guide/b-bng-cg60xasr9k/b-bng-cg60xasr9k_chapter_0101.html#task_27EED8D34A6541998F29E951411D4637

And

https://www.cisco.com/c/en/us/td/docs/routers/asr9000/software/asr9k_r6-0/bng/configuration/guide/b-bng-cg60xasr9k/b-bng-cg60xasr9k_chapter_0101.html#concept_A9F34995A4C54E73909CD490BC9F27A8

Hope to help

Giuseppe

dkfastcom · ‎06-29-2019

Hi Giuseppe,

Thanks for the reply. Yes I noticed that as well and as follows:

1. AAA is setting up the VPDN tunnel:

222 TEST Service-Type Outbound-User = 0
225 TEST Tunnel-Type IPv4 = 0
226 TEST Cisco-AVPair vpdn:ip-addresses=10.0.0.1 += 0
228 TEST Cisco-AVPair vpdn:l2tp-tunnel-password=xxxx += 0
229 TEST Cisco-AVPair vpdn:tunnel-id=a9k-lac += 0
231 TEST Cisco-AVPair vpdn:dsl-line-info-forwarding=1 += 0
232 TEST Cisco-AVPair vpdn:vpn-vrf=18015:1801510 += 0

I can see the VPDN tunnel stood up.

A9k-VPDN tunnel up:

Destination VRF-name Status Load Connects Disconnects Retries
10.0.0.1 18015:1801510 ACTIVE 1 1 0 0

Cisco LNS VPDN tunnel up:
26784 50126 a9k-lac est 10.0.0.2 1 7

So what I think might be happening here is:

1. We initially strip and authenticate @realmtest.local so we can forward to a downstream wholesaler LAC.

2. This is being setup per the above confirmed VPDN tunnel.

3. The ASR is somehow not associating username@realmtest.local to be forwarded within the VPDN tunnel.

I am having a look at the local VPDN template below and will see if this has any impact.

We need to have AAA setting up the realm forwarding however.

Thanks

Dan

xthuijs · ‎06-29-2019

could you share the radius debugs also to see what attributes are being passed from radius?

if we have ipcp like attributes this can coincide with the ability to handle the forward of the subscriber.

(eg ip unnumbered, or the omission of service type outbound)

I would remove this from the template in use also for those same reasons:

ipv4 mtu 1492
ipv4 verify unicast source reachable-via rx

it seems that the lns is not able to complete lcp for some reason. is it an IOS style LNS? if so configure lcp reneg-always

and can you share debugs from the lns side by any chance as well?

cheers!

xander

dkfastcom · ‎06-29-2019

I have just tried removing those template options and still the same result.

I suspect after taking a closer look with the debug on the LNS that yes LCP is looking more like the issue.

Please see attached LNS log. I did notice with the log "ppp1438 PPP DISC: LCP failed to negotiate".

The VPDN config on the 1001 is as follows.

vpdn-group 7
accept-dialin
protocol l2tp
virtual-template 7
vpn vrf 18015:1801510
lcp renegotiation always
l2tp tunnel password 0 XXXXX
!

This is the radius output from the 9k LAC.

RP/0/RSP0/CPU0:Jun 30 11:08:32.582 : radiusd[1137]: RADIUS: Send Access-Request to 192.168.0.248:1812 id 235, len 239
RP/0/RSP0/CPU0:Jun 30 11:08:32.582 : radiusd[1137]: RADIUS: authenticator F2 40 6A 5B 3D C0 52 25 - C0 AA 1C C7 B4 63 24 8C
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 41
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: Cisco AVpair [1] 35 client-mac-address=e48d.8caf.959d
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: Acct-Session-Id [44] 10 00001429
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: NAS-Port-Id [87] 13 0/0/1500/41
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 19
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: cisco-nas-port [2] 13 0/0/1500/41
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: User-Name [1] 17 realmtest.local
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: Service-Type [6] 6 Framed[2]
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: User-Password [2] 18 *
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: AAA Unsupported Attr: user-maxlinks [196] 6
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 33
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: Cisco AVpair [1] 27 connect-progress=LCP Open
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: Framed-Protocol [7] 6 PPP[1]
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: NAS-Port-Type [61] 6 Virtual PPPoEoVLAN[36]
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: Event-Timestamp [55] 6 1561849712
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: Nas-Identifier [32] 14 cr3.vcdc.akl
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: NAS-IP-Address [4] 6 10.0.0.55
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: RADIUS: NAS-IPv6-Address [95] 18 ::
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: Got global deadtime 0
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: Using global deadtime = 0 sec
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: Start timer thread rad_ident 235 remote_port 1812 remote_addr 192.168.0.248, socket 302369908 rctx 0x12205320
RP/0/RSP0/CPU0:Jun 30 11:08:32.583 : radiusd[1137]: Successfully sent packet and started timeout handler for rctx 0x12205320
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: Radius packet decryption complete with rc = 0
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: RADIUS: Received from id 235 192.168.0.248:1812, Access-Accept, len 211
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: RADIUS: authenticator 15 7B C1 1E 3D E3 BE 62 - BC FC C3 06 C1 18 29 2D
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: RADIUS: Service-Type [6] 6 Outbound[5]
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: RADIUS: Tunnel-Type [64] 6 0: L2TP[3]
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 34
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: RADIUS: Cisco AVpair [1] 28 vpdn:ip-addresses=10.0.0.1
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 42
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: RADIUS: Cisco AVpair [1] 36 vpdn:l2tp-tunnel-password=XXXX
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 30
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: RADIUS: Cisco AVpair [1] 24 vpdn:tunnel-id=a9k-lac
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 39
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: RADIUS: Cisco AVpair [1] 33 vpdn:dsl-line-info-forwarding=1
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 34
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: RADIUS: Cisco AVpair [1] 28 vpdn:vpn-vrf=18015:1801510
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: Freeing server group transaction_id (9A000020)
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: pack_length = 211 radius_len = 211
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: Calling app inf callback
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: rad_nas_reply_to_client: Received response from id : 235,packet type 2
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: Total len = 211, Radius len = 211
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: filter not found
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: Decoding the attribute: Service-Type, aaa_type service-type, flags 0x1
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: Decoding the attribute: Tunnel-Type, aaa_type tunnel-type, flags 0x2
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: Attribute [Tunnel-Type] is not yet supported
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: Decoding the attribute: Vendor-Specific, aaa_type invalid attribute, flags 0x21
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: Decoding the attribute: Vendor-Specific, aaa_type invalid attribute, flags 0x21
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: Decoding the attribute: Vendor-Specific, aaa_type invalid attribute, flags 0x21
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: Decoding the attribute: Vendor-Specific, aaa_type invalid attribute, flags 0x21
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: vsa decode: ulong is 0x1
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: Decoding the attribute: Vendor-Specific, aaa_type invalid attribute, flags 0x21
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: (rad_nas_reply_to_client) Successfully decoded the response No error: PASS
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: (rad_nas_reply_to_client) Successfully stored the preferred server info
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: (rad_nas_reply_to_client) Send response back to client

Giuseppe Larosa · ‎06-29-2019

Hello Dan,

the debug radius on the ASR9000 provides also meaningful information :

the ASR9000 is receiving from the Radius server some configuration statements including the VRF to be used in form of Cisco AV pairs

However, when it comes to the VPDN tunnel we can note the following lines:

>> RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: Decoding the attribute: Service-Type, aaa_type service-type, flags 0x1
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: Decoding the attribute: Tunnel-Type, aaa_type tunnel-type, flags 0x2
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: Attribute [Tunnel-Type] is not yet supported
RP/0/RSP0/CPU0:Jun 30 11:08:32.588 : radiusd[1137]: Decoding the attribute: Vendor-Specific, aaa_type invalid attribute, flags 0x21

Then on the LNS debug we see the following:

*Jun 29 12:32:05.705: ppp1438 LCP: Event[Timeout+] State[REQsent to REQsent]
*Jun 29 12:32:07.721: ppp1438 PPP DISC: LCP failed to negotiate
*Jun 29 12:32:07.721: ppp1438 PPP: Sending Acct Event[Down] id[764107]
*Jun 29 12:32:07.721: ppp1438 LCP: Event[Timeout-] State[REQsent to Stopped]
*Jun 29 12:32:07.721: ppp1438 LCP: Event[DOWN] State[Stopped to Starting]
*Jun 29 12:32:07.722: ppp1438 PPP: Phase is DOWN

Hope to help

Giuseppe

dkfastcom · ‎06-30-2019

Hi Giuseppe,

Yes I noticed this when I was going through the logs again. I have moved the tunnel-type AAA attribute to be a Cisco-AVPair and this resolves the error being seen with the radius.

The LCP however is still failing to negotiate.

RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: Send Access-Request to 192.168.0.248:1812 id 14, len 239
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: authenticator 55 68 EA 44 72 0A A4 57 - 14 1A CD C4 92 48 4F 05
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 41
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: Cisco AVpair [1] 35 client-mac-address=e48d.8caf.959d
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: Acct-Session-Id [44] 10 0000144c
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: NAS-Port-Id [87] 13 0/0/1500/41
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 19
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: cisco-nas-port [2] 13 0/0/1500/41
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: User-Name [1] 17 realmtest.local
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: Service-Type [6] 6 Framed[2]
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: User-Password [2] 18 *
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: AAA Unsupported Attr: user-maxlinks [196] 6
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 33
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: Cisco AVpair [1] 27 connect-progress=LCP Open
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: Framed-Protocol [7] 6 PPP[1]
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: NAS-Port-Type [61] 6 Virtual PPPoEoVLAN[36]
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: Event-Timestamp [55] 6 1561878907
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: Nas-Identifier [32] 14 cr3.vcdc.akl
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: NAS-IP-Address [4] 6 10.0.0.55
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: RADIUS: NAS-IPv6-Address [95] 18 ::
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: Got global deadtime 0
RP/0/RSP0/CPU0:Jun 30 19:15:07.275 : radiusd[1137]: Using global deadtime = 0 sec
RP/0/RSP0/CPU0:Jun 30 19:15:07.276 : radiusd[1137]: Start timer thread rad_ident 14 remote_port 1812 remote_addr 192.168.0.248, socket 302369964 rctx 0x12205320
RP/0/RSP0/CPU0:Jun 30 19:15:07.276 : radiusd[1137]: Successfully sent packet and started timeout handler for rctx 0x12205320
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: Radius packet decryption complete with rc = 0
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Received from id 14 192.168.0.248:1812, Access-Accept, len 273
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: authenticator A7 AA 63 BE F2 10 B5 B5 - BE 13 4A 49 2A 8B BC F0
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Service-Type [6] 6 Outbound[5]
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 29
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Cisco AVpair [1] 23 vpdn:tunnel-type=l2tp
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 34
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Cisco AVpair [1] 28 vpdn:ip-addresses=10.0.0.1
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 42
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Cisco AVpair [1] 36 vpdn:l2tp-tunnel-password=Net2L2TP
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 30
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Cisco AVpair [1] 24 vpdn:tunnel-id=a9k-lac
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 39
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Cisco AVpair [1] 33 vpdn:dsl-line-info-forwarding=1
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 34
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Cisco AVpair [1] 28 vpdn:vpn-vrf=18015:1801510
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Vendor,Cisco [26] 33
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Cisco AVpair [1] 27 vpdn:tunnel-medium-type=1
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: RADIUS: Framed-Protocol [7] 6 PPP[1]
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: Freeing server group transaction_id (C7000043)
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: pack_length = 273 radius_len = 273
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: Calling app inf callback
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: rad_nas_reply_to_client: Received response from id : 14,packet type 2
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: filter not found
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: Decoding the attribute: Service-Type, aaa_type service-type, flags 0x1
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: Decoding the attribute: Vendor-Specific, aaa_type invalid attribute, flags 0x21
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: Decoding the attribute: Vendor-Specific, aaa_type invalid attribute, flags 0x21
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: Decoding the attribute: Vendor-Specific, aaa_type invalid attribute, flags 0x21
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: Decoding the attribute: Vendor-Specific, aaa_type invalid attribute, flags 0x21
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: Decoding the attribute: Vendor-Specific, aaa_type invalid attribute, flags 0x21
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: vsa decode: ulong is 0x1
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: Decoding the attribute: Vendor-Specific, aaa_type invalid attribute, flags 0x21
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: Decoding the attribute: Vendor-Specific, aaa_type invalid attribute, flags 0x21
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: VSA tunnel-medium-type=1 maps to IPv4
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: Decoding the attribute: Framed-Protocol, aaa_type Framed-Protocol, flags 0x0
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: (rad_nas_reply_to_client) Successfully decoded the response No error: PASS
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: (rad_nas_reply_to_client) Successfully stored the preferred server info
RP/0/RSP0/CPU0:Jun 30 19:15:07.283 : radiusd[1137]: (rad_nas_reply_to_client) Send response back to client
RP/0/RSP0/CPU0:Jun 30 19:15:07.331 : PPP-MA[391]: LCP: Bundle-Ether1500.41.pppoe1835: Tunneling as LAC session

*Jun 29 21:04:11.432: ppp778 PPP DISC: LCP failed to negotiate
*Jun 29 21:04:11.432: ppp778 PPP: Sending Acct Event[Down] id[764CE8]
*Jun 29 21:04:11.432: PPP: NET STOP send to AAA.
*Jun 29 21:04:11.433: ppp778 LCP: Event[Timeout-] State[REQsent to Stopped]
*Jun 29 21:04:11.433: ppp778 LCP: Event[DOWN] State[Stopped to Starting]
*Jun 29 21:04:11.433: ppp778 PPP: Phase is DOWN
*Jun 29 21:04:11.433: L2TUN APP: uid:778/handle/566441Free switch hdl 890026
*Jun 29 21:04:11.433: L2TUN APP: uid:778/handle/566441shutdown app session
*Jun 29 21:04:11.433: L2TUN APP: uid:778/handle/566441Stopping service selection
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA:
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: APP->L2TP: Destroy [11],
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: sock D50003DF
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: serv 0043C4A7
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: data 7FA813EC0080[277]
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: replied on same socket
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA:
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: L2TUN: remove sock D50003DF
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA:
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: Shutting down session
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: Result Code
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: Call disconnected, refer to error msg (2)
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: Error Code
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: Vendor specific (6)
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: Vendor Error
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: None (0)
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: Optional Message
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: "Locally generated disconnect"
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA:
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: FSM-Sn ev App-Disc
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: FSM-Sn in established
*Jun 29 21:04:11.433: L2TP 0030A:3448D:0000EABA: FSM-Sn do App-Disc-Active

xthuijs · ‎06-30-2019

your tunnel attrs are fine, the session is forwarded properly.

what makes me suspicious is in the earlier log it shows that the bng is still dealing with incoming pap acks,

they would need to be forwarded.

the lns debug is trimmed, can you share the full lcp debugs from that end?

it says lcp failed to negotiate, it can be for 2 reasons:

-> the proxy LCP final ack sets sent through l2tp are not acceptable to the LNS, this can be because of an mtu mismatch for instance.

-> confreqs sent and not received or reverse during lcp, this can be caused by a forwarding LAC switch issue on the bng. this would be a sw issue.

the solution to the first problem is to use lcp reneg always under the vpdn group on the lns.

xander