[c-nsp] L2TP LNS issue
Patrick Cole
z at amused.net
Tue Oct 13 07:00:31 EDT 2009
Hi all,
Got a really weird problem that I'm hoping is the result of something simple and
stupid on my part.
I've got a 7204VXR running 12.2(31)SB16 and am trying to terminate a PPP session
using L2TP/VPDN as an LNS. The test LAC is linux using xl2tpd/pppd.
Here is some debug logging from when the connection goes through:
*Oct 8 12:19:17.790: L2TP: I SCCRQ from hatika tnl 19184
*Oct 8 12:19:17.790: AAA/BIND(00000A91): Bind i/f
*Oct 8 12:19:17.790: Tnl 23179 L2TP: Tunnel Authorization started for host hatika
*Oct 8 12:19:17.790: Tnl 23179 L2TP: New tunnel created for remote hatika, address <LAC-IP>
*Oct 8 12:19:17.790: L2X: Tunnel author reply found L2X info
*Oct 8 12:19:17.790: Tnl 23179 L2TP: O SCCRP to hatika tnlid 19184
*Oct 8 12:19:17.790: Tnl 23179 L2TP: Control channel retransmit delay set to 1 seconds
*Oct 8 12:19:17.790: Tnl 23179 L2TP: Tunnel state change from idle to wait-ctl-reply
*Oct 8 12:19:17.798: Tnl 23179 L2TP: I SCCCN from hatika tnl 19184
*Oct 8 12:19:17.798: Tnl 23179 L2TP: Control connection authentication skipped/passed.
*Oct 8 12:19:17.798: Tnl 23179 L2TP: Tunnel auth counter, Overall Ignored, now 63
*Oct 8 12:19:17.798: Tnl 23179 L2TP: Tunnel state change from wait-ctl-reply to established
*Oct 8 12:19:17.798: Tnl 23179 L2TP: SM State established
*Oct 8 12:19:17.798: Tnl 23179 L2TP: Perform early message digest validation for ICRQ
*Oct 8 12:19:17.798: Tnl 23179 L2TP: Control connection authentication skipped/passed.
*Oct 8 12:19:17.798: Tnl 23179 L2TP: Tunnel auth counter, Overall Ignored, now 64
*Oct 8 12:19:17.798: Tnl 23179 L2TP: I ICRQ from hatika tnl 19184
*Oct 8 12:19:17.798: L2X Session DB (Tnl/Sn: 23179/2608): Stored the control session in the session DB
*Oct 8 12:19:17.798: Tnl/Sn 23179/2608 L2TP: Create session
*Oct 8 12:19:17.798: Tnl/Sn 23179/2608 L2TP: Session state change from idle to wait-connect
*Oct 8 12:19:17.798: Tnl/Sn 23179/2608 L2TP: PW-MGMT: PW peer <LAC-IP>, vcid 0
*Oct 8 12:19:17.798: Tnl/Sn 23179/2608 L2TP: PW-MGMT: Reason [Protocol DOWN]
*Oct 8 12:19:17.798: Tnl/Sn 23179/2608 L2TP: PW-MGMT: Local VC DOWN, Remote VC DOWN
*Oct 8 12:19:17.798: Tnl/Sn 23179/2608 L2TP: PW-MGMT: Provisioned NO, Established NO
*Oct 8 12:19:17.798: Tnl/Sn 23179/2608 L2TP: PW-MGMT: No change in PW state
*Oct 8 12:19:17.798: Tnl/Sn 23179/2608 L2TP: Accepted ICRQ, new session created
*Oct 8 12:19:17.798: AAA/BIND(00000A92): Bind i/f
*Oct 8 12:19:17.798: uid:605 Tnl/Sn 23179/2608 L2TP: O ICRP to hatika 19184/39100
*Oct 8 12:19:17.798: Tnl 23179 L2TP: Control channel retransmit delay set to 1 seconds
*Oct 8 12:19:17.806: Tnl 23179 L2TP: Perform early message digest validation for ICCN
*Oct 8 12:19:17.806: Tnl 23179 L2TP: Control connection authentication skipped/passed.
*Oct 8 12:19:17.806: Tnl 23179 L2TP: Tunnel auth counter, Overall Ignored, now 65
*Oct 8 12:19:17.806: uid:605 Tnl/Sn 23179/2608 L2TP: I ICCN from hatika tnl 19184, cl 39100
*Oct 8 12:19:17.806: uid:605 Tnl/Sn 23179/2608 L2TP: Session state change from wait-connect to wait-for-service-selection-iccn
*Oct 8 12:19:17.806: uid:605 Tnl/Sn 23179/2608 L2TP: PW-MGMT: PW peer <LAC-IP>, vcid 0
*Oct 8 12:19:17.806: uid:605 Tnl/Sn 23179/2608 L2TP: PW-MGMT: Reason [Protocol DOWN]
*Oct 8 12:19:17.806: uid:605 Tnl/Sn 23179/2608 L2TP: PW-MGMT: Local VC DOWN, Remote VC DOWN
*Oct 8 12:19:17.806: uid:605 Tnl/Sn 23179/2608 L2TP: PW-MGMT: Provisioned NO, Established NO
*Oct 8 12:19:17.806: uid:605 Tnl/Sn 23179/2608 L2TP: PW-MGMT: No change in PW state
*Oct 8 12:19:17.810: uid:605 Tnl/Sn 23179/2608 L2TP: L2X session data plane setup successful
*Oct 8 12:19:17.810: AAA/BIND(00000A92): Bind i/f Virtual-Template1
*Oct 8 12:19:17.810: L2X Session DB (Tnl/Sn: 23179/2608): Stored the switching session in the session DB
*Oct 8 12:19:17.810: L2TP:(Tnl23179:Sn2608)L2X s/w switching session provisioned
*Oct 8 12:19:17.810: ppp605 PPP: Initialized Context 64744360
*Oct 8 12:19:17.810: ppp605 PPP: Using AAA Unique Id = A92
*Oct 8 12:19:17.810: ppp605 PPP: Dynamic Bind peer_type[4]
*Oct 8 12:19:17.810: ppp605 PPP: Send Message[Dynamic Bind Response]
*Oct 8 12:19:17.810: ppp605 PPP: Authorization required
*Oct 8 12:19:20.818: ppp605 PPP SSS: forwarding request
*Oct 8 12:19:20.822: ppp605 PPP SSS: Receive SSS-Mgr Need-More-Keys
*Oct 8 12:19:20.822: AAA/AUTHEN/PPP (00000A92): Pick method list 'default'
*Oct 8 12:19:20.822: ppp605 PPP: Sent PAP LOGIN Request
*Oct 8 12:19:20.822: RADIUS/ENCODE(00000A92):Orig. component type = VPDN
*Oct 8 12:19:20.822: RADIUS: AAA Unsupported Attr: password [274] 4
*Oct 8 12:19:20.822: RADIUS: 74 65 [ te]
*Oct 8 12:19:20.822: RADIUS: AAA Unsupported Attr: interface [185] 15
*Oct 8 12:19:20.822: RADIUS: 55 6E 69 71 2D 53 65 73 73 2D 49 44 36 [ Uniq-Sess-ID6]
*Oct 8 12:19:20.822: RADIUS(00000A92): Config NAS IP: 0.0.0.0
*Oct 8 12:19:20.822: RADIUS/ENCODE(00000A92): acct_session_id: 2696
*Oct 8 12:19:20.822: RADIUS(00000A92): sending
*Oct 8 12:19:20.822: RADIUS/ENCODE: Best Local IP-Address <NAS-IP> for Radius-Server <RADIUS-SERVER>
*Oct 8 12:19:20.822: RADIUS(00000A92): Send Access-Request to <RADIUS-SERVER>:1812 id 1645/47, len 118
*Oct 8 12:19:20.822: RADIUS: authenticator DF 17 C7 EF 81 4B BD 0D - 1D 8F F6 60 45 93 25 99
*Oct 8 12:19:20.822: RADIUS: Framed-Protocol [7] 6 PPP [1]
*Oct 8 12:19:20.822: RADIUS: User-Name [1] 23 "user at test.realm.com"
*Oct 8 12:19:20.822: RADIUS: User-Password [2] 18 *
*Oct 8 12:19:20.822: RADIUS: Connect-Info [77] 10 "10000000"
*Oct 8 12:19:20.822: RADIUS: NAS-Port-Type [61] 6 Virtual [5]
*Oct 8 12:19:20.822: RADIUS: NAS-Port [5] 6 605
*Oct 8 12:19:20.822: RADIUS: NAS-Port-Id [87] 17 "Uniq-Sess-ID605"
*Oct 8 12:19:20.822: RADIUS: Service-Type [6] 6 Framed [2]
*Oct 8 12:19:20.822: RADIUS: NAS-IP-Address [4] 6 <NASIP>
*Oct 8 12:19:20.890: RADIUS: Received from id 1645/47 <RADIUS-SERVER>:1812, Access-Accept, len 62
*Oct 8 12:19:20.890: RADIUS: authenticator AA B0 25 2A A0 E5 E7 F5 - 46 AC 74 89 92 50 E5 24
*Oct 8 12:19:20.890: RADIUS: Framed-IP-Address [8] 6 10.0.0.1
*Oct 8 12:19:20.890: RADIUS: Framed-IP-Netmask [9] 6 255.255.255.255
*Oct 8 12:19:20.890: RADIUS: Port-Limit [62] 6 1
*Oct 8 12:19:20.890: RADIUS: Framed-MTU [12] 6 1500
*Oct 8 12:19:20.890: RADIUS: Service-Type [6] 6 Framed [2]
*Oct 8 12:19:20.894: RADIUS: Framed-Protocol [7] 6 PPP [1]
*Oct 8 12:19:20.894: RADIUS: Framed-Compression [13] 6 VJ TCP/IP Header Compressi[1]
*Oct 8 12:19:20.894: RADIUS(00000A92): Received from id 1645/47
*Oct 8 12:19:20.894: ppp605 PPP: Received LOGIN Response PASS
*Oct 8 12:19:20.894: ppp605 PPP AUTHOR: Author Data Available
*Oct 8 12:19:20.894: ppp605 PPP: Receive Attrs from[authen] Keep[LCP] MERGE
*Oct 8 12:19:20.894: ppp605 PPP: Skip Attr: addr 10.0.0.1
*Oct 8 12:19:20.894: ppp605 PPP: Skip Attr: netmask 255.255.255.255
*Oct 8 12:19:20.894: ppp605 PPP: Skip Attr: Port-Limit 1 (0x1)
*Oct 8 12:19:20.894: ppp605 PPP: Skip Attr: Framed-MTU 1500 (0x5DC)
*Oct 8 12:19:20.894: ppp605 PPP: Keep Attr: service-type 2 [Framed]
*Oct 8 12:19:20.894: ppp605 PPP: Keep Attr: Framed-Protocol 1 [PPP]
*Oct 8 12:19:20.894: ppp605 PPP: Skip Attr: link-compression 4 [vj]
*Oct 8 12:19:20.894: ppp605 PPP SSS: forwarding request
*Oct 8 12:19:20.894: ppp605 PPP: Receive Attrs from[SSS] Keep[NCPs] MERGE
*Oct 8 12:19:20.894: ppp605 PPP: Keep Attr: addr 10.0.0.1
*Oct 8 12:19:20.894: ppp605 PPP: Keep Attr: netmask 255.255.255.255
*Oct 8 12:19:20.894: ppp605 PPP: Keep Attr: Port-Limit 1 (0x1)
*Oct 8 12:19:20.894: ppp605 PPP: Skip Attr: Framed-MTU 1500 (0x5DC)
*Oct 8 12:19:20.894: ppp605 PPP: Skip Attr: service-type 2 [Framed]
*Oct 8 12:19:20.894: ppp605 PPP: Skip Attr: Framed-Protocol 1 [PPP]
*Oct 8 12:19:20.894: ppp605 PPP: Skip Attr: link-compression 4 [vj]
*Oct 8 12:19:20.898: Vi4 PPP: Change SIP state from Init to Down
*Oct 8 12:19:20.898: Vi4 PPP: old[Init] event[Encap] state[Down]
*Oct 8 12:19:20.902: L2TP:(Tnl23179:Sn2608)L2X s/w session mode changed to L2_L3
*Oct 8 12:19:20.902: L2TP:(Tnl23179:Sn2608)L2X s/w switching session bound
*Oct 8 12:19:20.902: PPP: Bind ppp605 to Virtual-Access4
*Oct 8 12:19:20.902: AAA/BIND(00000A92): Bind i/f Virtual-Access4
*Oct 8 12:19:20.902: Vi4 PPP: Static Bind peer_type[4]
*Oct 8 12:19:20.902: AAA/AUTHEN/PPP (00000A92): Pick method list 'default'
*Oct 8 12:19:20.902: Vi4 PPP: Sent PAP SENDAUTH Request
*Oct 8 12:19:20.902: Vi4 LCP AUTHOR: Process LCP Author Data
*Oct 8 12:19:20.902: Vi4 LCP AUTHOR: Process Attr: service-type
*Oct 8 12:19:20.902: Vi4 LCP AUTHOR: Process Attr: Framed-Protocol
*Oct 8 12:19:20.902: Vi4 LCP AUTHOR: Authorization succeeded
*Oct 8 12:19:20.902: Vi4 PPP: Send Message[Static Bind Response]
<------------------------------------------------------------------------->
*Oct 8 12:19:20.902: RADIUS/ENCODE(00000A92): check username/password; FAIL
*Oct 8 12:19:20.902: RADIUS/ENCODE(00000A92): send packet; FAIL
<------------------------------------------------------------------------->
*Oct 8 12:19:20.902: Vi4 Tnl/Sn 23179/2608 L2TP: Session state change from wait-for-service-selection-iccn to established
*Oct 8 12:19:20.902: Vi4 Tnl/Sn 23179/2608 L2TP: PW-MGMT: PW peer <LAC-IP>, vcid 0
*Oct 8 12:19:20.902: Vi4 Tnl/Sn 23179/2608 L2TP: PW-MGMT: Reason [Protocol UP]
*Oct 8 12:19:20.902: Vi4 Tnl/Sn 23179/2608 L2TP: PW-MGMT: Local VC DOWN, Remote VC DOWN
*Oct 8 12:19:20.902: Vi4 Tnl/Sn 23179/2608 L2TP: PW-MGMT: Provisioned NO, Established YES
*Oct 8 12:19:20.902: Vi4 Tnl/Sn 23179/2608 L2TP: PW-MGMT: No change in PW state
<------------------------------------------------------------------------->
*Oct 8 12:19:20.902: Vi4 PPP: Received SENDAUTH Response FAIL
*Oct 8 12:19:20.902: Vi4 PPP: Sending Acct Event[Down] id[A92]
<------------------------------------------------------------------------->
The above lines seem to be the cause of the drama, just not sure what it means.
*Oct 8 12:19:20.902: Vi4 Tnl/Sn 23179/2608 L2TP: O SLI to hatika 19184/39100
*Oct 8 12:19:20.902: Vi4 Tnl/Sn 23179/2608 L2TP: Sending send ACCM 0xFFFFFFFF and receive ACCM 0xFFFFFFFF
*Oct 8 12:19:20.902: Tnl 23179 L2TP: Control channel retransmit delay set to 1 seconds
*Oct 8 12:19:20.906: %LINK-3-UPDOWN: Interface Virtual-Access4, changed state to up
*Oct 8 12:19:20.910: Tnl 23179 L2TP: Early authen passing ZLB
*Oct 8 12:19:20.914: Vi4 Tnl/Sn 23179/2608 L2TP: O SLI to hatika 19184/39100
*Oct 8 12:19:20.914: Vi4 Tnl/Sn 23179/2608 L2TP: Sending send ACCM 0xFFFFFFFF and receive ACCM 0xFFFFFFFF
*Oct 8 12:19:20.914: Tnl 23179 L2TP: Control channel retransmit delay set to 1 seconds
*Oct 8 12:19:20.914: Vi4 Tnl/Sn 23179/2608 L2TP: O SLI to hatika 19184/39100
*Oct 8 12:19:20.914: Vi4 Tnl/Sn 23179/2608 L2TP: Sending send ACCM 0xFFFFFFFF and receive ACCM 0xFFFFFFFF
*Oct 8 12:19:20.914: Vi4 PPP: Clearing AAA Unique Id = A92
*Oct 8 12:19:20.914: Vi4 PPP: Send Message[Disconnect]
*Oct 8 12:19:20.914: Vi4 Tnl/Sn 23179/2608 L2TP: disconnect (L2X) IETF: 9/nas-error Ascend: 66/VPDN Local PPP Disconnect
*Oct 8 12:19:20.914: Vi4 Tnl/Sn 23179/2608 L2TP: O CDN to hatika 19184/39100
*Oct 8 12:19:20.914: Vi4 Tnl/Sn 23179/2608 L2TP: Destroying session
*Oct 8 12:19:20.914: L2X Session DB (Tnl/Sn: 23179/2608): Removed the control session from the session DB
*Oct 8 12:19:20.914: Vi4 Tnl/Sn 23179/2608 L2TP: Session state change from established to idle
*Oct 8 12:19:20.914: Vi4 Tnl/Sn 23179/2608 L2TP: PW-MGMT: PW peer <LAC-IP>, vcid 0
*Oct 8 12:19:20.914: Vi4 Tnl/Sn 23179/2608 L2TP: PW-MGMT: Reason [Protocol DOWN]
*Oct 8 12:19:20.914: Vi4 Tnl/Sn 23179/2608 L2TP: PW-MGMT: Local VC DOWN, Remote VC DOWN
*Oct 8 12:19:20.914: Vi4 Tnl/Sn 23179/2608 L2TP: PW-MGMT: Provisioned NO, Established NO
*Oct 8 12:19:20.914: Vi4 Tnl/Sn 23179/2608 L2TP: PW-MGMT: No change in PW state
*Oct 8 12:19:20.914: Vi4 Tnl/Sn 23179/2608 L2TP: L2X request teardown data plane
*Oct 8 12:19:20.914: Vi4 Tnl/Sn 23179/2608 L2TP: Unbinding session from idb
*Oct 8 12:19:20.914: Tnl 23179 L2TP: Tunnel state change from established to no-sessions-left
*Oct 8 12:19:20.914: Tnl 23179 L2TP: No more sessions in tunnel, shutdown (likely) in 10 seconds
*Oct 8 12:19:20.914: L2TP:(Tnl23179:Sn2608)L2X s/w switching session unprovisioned
*Oct 8 12:19:20.914: L2X Session DB (Tnl/Sn: 23179/2608): Removed the switching session from the session DB
*Oct 8 12:19:20.918: %LINK-3-UPDOWN: Interface Virtual-Access4, changed state to down
*Oct 8 12:19:20.918: Vi4 PPP: ppp_sip_switching_cleanup
*Oct 8 12:19:20.918: Vi4 PPP: old[Down] event[DeEncap] state[Init]
*Oct 8 12:19:20.918: Tnl 23179 L2TP: Early authen passing ZLB
*Oct 8 12:19:20.922: Tnl 23179 L2TP: Early authen passing ZLB
*Oct 8 12:19:20.922: Tnl 23179 L2TP: Early authen passing ZLB
*Oct 8 12:19:21.862: Tnl 23179 L2TP: Perform early message digest validation for StopCCN
*Oct 8 12:19:21.862: Tnl 23179 L2TP: Control connection authentication skipped/passed.
*Oct 8 12:19:21.862: Tnl 23179 L2TP: Tunnel auth counter, Overall Ignored, now 66
*Oct 8 12:19:21.862: Tnl 23179 L2TP: I StopCCN from hatika tnl 19184
*Oct 8 12:19:21.862: Tnl 23179 L2TP: Tunnel state change from no-sessions-left to shutting-down
*Oct 8 12:19:21.862: Tnl 23179 L2TP: Shutdown tunnel
*Oct 8 12:19:21.866: Tnl 23179 L2TP: Tunnel state change from shutting-down to idle
The radius authentication returns auth accept, the attributes seem fine, but then
something goes wrong and the cisco sends an 0x201 followed by a TermReq:
Oct 13 19:19:51 hatika pppd[27298]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth pap> <magic 0xfb9e08cf> <pcomp> <accomp>]
Oct 13 19:19:53 hatika pppd[27298]: rcvd [LCP ConfReq id=0x1 <asyncmap 0xa0000> <auth pap> <magic 0x18380b6e> <pcomp> <accomp>]
Oct 13 19:19:53 hatika pppd[27298]: sent [LCP ConfAck id=0x1 <asyncmap 0xa0000> <auth pap> <magic 0x18380b6e> <pcomp> <accomp>]
Oct 13 19:19:54 hatika pppd[27298]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth pap> <magic 0xfb9e08cf> <pcomp> <accomp>]
Oct 13 19:19:54 hatika pppd[27298]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <auth pap> <magic 0xfb9e08cf> <pcomp> <accomp>]
Oct 13 19:19:54 hatika pppd[27298]: sent [LCP EchoReq id=0x0 magic=0xfb9e08cf]
Oct 13 19:19:54 hatika pppd[27298]: sent [PAP AuthReq id=0x1 user="user at test.domain.com" password=<hidden>]
Oct 13 19:19:54 hatika pppd[27298]: rcvd [proto=0x201] 00 05 00
Oct 13 19:19:54 hatika pppd[27298]: discarding proto 0x201 in phase 5
Oct 13 19:19:54 hatika pppd[27298]: rcvd [LCP TermReq id=0x2]
Oct 13 19:19:54 hatika pppd[27298]: sent [LCP TermAck id=0x2]
Here is the config on the box:
version 12.2
service timestamps debug datetime msec
service timestamps log datetime msec
no service password-encryption
!
hostname router
!
boot-start-marker
boot system disk0:c7200-js-mz.122-31.SB16.bin
boot-end-marker
!
logging buffered 65535 notifications
!
aaa new-model
!
!
aaa authentication login default local
aaa authentication enable default enable
aaa authentication ppp default if-needed group radius
aaa authorization network default group radius
aaa accounting delay-start vrf default
aaa accounting update periodic 240
!
!
!
!
aaa session-id common
clock timezone GMT 11
ip subnet-zero
!
!
ip name-server <DNS1>
ip name-server <DNS2>
!
!
ip cef
!
!
vpdn enable
!
vpdn-group hatika
accept-dialin
protocol l2tp
virtual-template 1
terminate-from hostname hatika
lcp renegotiation always
no l2tp tunnel authentication
!
mpls traffic-eng tunnels
mpls label protocol ldp
call rsvp-sync
!
!
!
!
!
no file verify auto
username [.....]
username [.....]
!
!
!
interface Loopback1
ip address <LB-IP> 255.255.255.255
!
interface FastEthernet0/0
ip address <IP> 255.255.255.192
speed auto
duplex auto
!
interface Virtual-Template1
description LNS
ip unnumbered FastEthernet0/0
peer default ip address pool test
ppp authentication pap
!
router ospf 1
log-adjacency-changes
area 0.0.0.0 authentication
redistribute connected subnets
redistribute static subnets
network <NET> 0.0.0.63 area 0.0.0.0
!
ip local pool test 10.0.9.1 10.0.9.254
ip classless
ip route 0.0.0.0 0.0.0.0 <IP>
!
no ip http server
!
!
no cdp run
!
radius-server host <RADIUS-SERVER> auth-port 1812 acct-port 1813 key <KEY>
!
control-plane
!
!
!
dial-peer cor custom
!
!
!
!
gatekeeper
shutdown
!
!
line con 0
stopbits 1
line aux 0
stopbits 1
line vty 0 4
!
end
Any assistance appreciated.
Regards,
Pat
More information about the cisco-nsp
mailing list