[c-nsp] L2TP DSL issue with 7204 + FreeRadius
Skeeve Stevens
skeeve at skeeve.org
Mon Nov 13 01:30:24 EST 2006
IOS (tm) 7200 Software (C7200-IS-M), Version 12.3(9e), RELEASE SOFTWARE
(fc1)
Image text-base: 0x60008AF4, data-base: 0x61C7A000
ROM: System Bootstrap, Version 12.0(19990210:195103) [12.0XE 105],
DEVELOPMENT SOFTWARE
System image file is "disk0:c7200-is-mz.123-9e.bin"
cisco 7204VXR (NPE300) processor (revision B) with 229376K/65536K bytes of
memory.
Processor board ID 21282380
R7000 CPU at 262MHz, Implementation 39, Rev 1.0, 256KB L2 Cache
Even though the NPE300 isn't officially supported by it, I am currently
uploading c7200-is-mz.123-21.bin to it which came out on 9/11.
I will let you know if it fixes anything.
This is a greenfield site.. There is no other radius accounting and this
radius server only being used by this router.
...Skeeve
-----Original Message-----
From: Stephen Fulton [mailto:cisco-nsp at lists.esoteric.ca]
Sent: Monday, 13 November 2006 3:52 PM
To: skeeve at skeeve.org
Cc: cisco-nsp at puck.nether.net
Subject: Re: [c-nsp] L2TP DSL issue with 7204 + FreeRadius
Skeeve,
The failure appears to be occurring during the RADIUS accounting portion of
the session. What version of IOS are you running, and have you turned on
debugging on FreeRADIUS? Does RADIUS accounting work for other types of
sessions?
-- Stephen
Skeeve Stevens wrote:
>
>
>
> Hey all,
>
> As you can see below... the sessions are authenticating, coming up,
> and then going down... something in the AAA/ACCT area seems to be
> killing it but I do not know what.
>
> Included is the Cisco debug, Radius Output and relevant Cisco
config.
>
> If you can help, it would be much appreciated.
>
> ...Skeeve
>
>
> Cisco log -
>
> Debug running:
> General OS:
> AAA Authentication debugging is on
> AAA Authorization debugging is on
> AAA Accounting debugging is on
> AAA IPC Manager debugs debugging is on
> PPP:
> PPP authentication debugging is on
> Radius protocol debugging is on
> Radius packet protocol (authentication) debugging is on
>
>
> VPN:
> VPDN call event debugging is on
> VPDN events debugging is on
>
> ====
> psyd001-LNS#
> Nov 13 14:13:50.073 AEST: AAA/BIND(000002AB): Bind i/f
> Virtual-Template1 Nov 13 14:13:50.073 AEST: AAA/ACCT/CLIENT(000002AB):
> recv 155520000bps xmit 155520000bps Nov 13 14:13:50.077 AEST:
> AAA/ACCT/HC(000002AB): Register VPDN/3E0007DA 155Mbit/s, poll every
> 30.3000s Nov 13 14:13:50.077 AEST: AAA/ACCT/HC(000002AB): Update
> VPDN/3E0007DA Nov 13 14:13:50.077 AEST: AAA/ACCT/HC(000002AB):
> VPDN/3E0007DA [init-sess]
> (rx/tx) base 0/0 pre 0/0 call 0/0
> Nov 13 14:13:50.077 AEST: AAA/ACCT/HC(000002AB): VPDN/3E0007DA
> [init-sess]
> (rx/tx) adjusted, pre 0/0 call 0/0
> Nov 13 14:13:50.077 AEST: AAA/ACCT/EVENT/(000002AB): CALL START Nov 13
> 14:13:50.077 AEST: Getting session id for NET(000002AB) : db=637D61F8
> Nov 13 14:13:50.077 AEST: AAA/ACCT(00000000): add node, session 683
> Nov 13 14:13:50.077 AEST: AAA/ACCT/NET(000002AB): add, count 1 Nov 13
> 14:13:50.077 AEST: AAA/ACCT/EVENT/(000002AB): ATTR ADD Nov 13
> 14:13:50.077 AEST: AAA/ACCT/NET(000002AB): Pick method list 'default'
> Nov 13 14:13:50.077 AEST: AAA/ACCT/SETMLIST(000002AB): Handle 0, mlist
> 6396616C, Name default Nov 13 14:13:50.077 AEST: AAA/ACCT(000002AB):
> Type NET: Periodic timer initialized Nov 13 14:13:50.077 AEST: ppp671
> PPP: Authorization required Nov 13 14:13:50.077 AEST:
> AAA/ACCT/NET(000002AB): Pick method list 'default'
> Nov 13 14:13:50.077 AEST: AAA/ACCT/SETMLIST(000002AB): Handle 0, mlist
> 6396616C, Name default Nov 13 14:13:50.077 AEST: AAA/AUTHEN/PPP
> (000002AB): Pick method list 'default'
> Nov 13 14:13:50.077 AEST: AAA/IPC(000002AB): Sending authen/author
> message to AAA server pid 43 Nov 13 14:13:50.077 AEST: ppp671 PPP:
> Sent PAP LOGIN Request Nov 13 14:13:50.077 AEST:
> RADIUS/ENCODE(000002AB):Orig. component type = VPDN Nov 13
> 14:13:50.077 AEST: RADIUS(000002AB): Storing nasport 671 in rad_db Nov
> 13 14:13:50.077 AEST: RADIUS(000002AB): Config NAS IP: xxx.xxx.8.3 Nov
> 13 14:13:50.077 AEST: Getting session id for NET(000002AB) :
> db=637D61F8 Nov 13 14:13:50.077 AEST: RADIUS/ENCODE(000002AB):
> acct_session_id: 683 Nov 13 14:13:50.077 AEST: RADIUS(000002AB):
> sending Nov 13 14:13:50.077 AEST: RADIUS(000002AB): Send
> Access-Request to
> xxx.xx.102.10:1645 id 1645/164, len 134 Nov 13 14:13:50.077 AEST:
> RADIUS: authenticator FA 9B DF 9D 2D 42 AA 21 -
> C3 62 AA 1E 1E 99 57 F7
> Nov 13 14:13:50.077 AEST: RADIUS: Framed-Protocol [7] 6 PPP
> [1]
> Nov 13 14:13:50.081 AEST: RADIUS: User-Name [1] 26
> "skeeve at xxxxxxxdsl.com.au"
> Nov 13 14:13:50.081 AEST: RADIUS: User-Password [2] 18 *
> Nov 13 14:13:50.081 AEST: RADIUS: NAS-Port-Type [61] 6 Virtual
> [5]
> Nov 13 14:13:50.081 AEST: RADIUS: Vendor, Cisco [26] 23
> Nov 13 14:13:50.081 AEST: RADIUS: cisco-nas-port [2] 17
> "Uniq-Sess-ID671"
> Nov 13 14:13:50.081 AEST: RADIUS: NAS-Port [5] 6 671
>
> Nov 13 14:13:50.081 AEST: RADIUS: Calling-Station-Id [31] 17
> "nnb110200201120"
> Nov 13 14:13:50.081 AEST: RADIUS: Service-Type [6] 6 Framed
> [2]
> Nov 13 14:13:50.081 AEST: RADIUS: NAS-IP-Address [4] 6
xxx.xxx.8.3
>
> Nov 13 14:13:50.085 AEST: RADIUS: Received from id 1645/164
> xxx.xx.102.10:1645, Access-Accept, len 71 Nov 13 14:13:50.085 AEST:
> RADIUS: authenticator D8 69 8C B3 47 3F 43 A1 -
> 79 45 8C 71 53 F1 26 B5
> Nov 13 14:13:50.085 AEST: RADIUS: Service-Type [6] 6 Framed
> [2]
> Nov 13 14:13:50.085 AEST: RADIUS: Framed-Protocol [7] 6 PPP
> [1]
> Nov 13 14:13:50.085 AEST: RADIUS: Framed-IP-Address [8] 6
> xxx.xxx.11.2
> Nov 13 14:13:50.085 AEST: RADIUS: Framed-IP-Netmask [9] 6
> 255.255.255.0
> Nov 13 14:13:50.085 AEST: RADIUS: Framed-Routing [10] 6 3
>
> Nov 13 14:13:50.085 AEST: RADIUS: Filter-Id [11] 9
> Nov 13 14:13:50.085 AEST: RADIUS: 73 74 64 2E 70 70 70
> [std.ppp]
> Nov 13 14:13:50.085 AEST: RADIUS: Framed-MTU [12] 6 1500
>
> Nov 13 14:13:50.085 AEST: RADIUS: Framed-Compression [13] 6 VJ TCP/IP
> Header Compressi[1]
> Nov 13 14:13:50.085 AEST: RADIUS(000002AB): Received from id 1645/164
> Nov 13 14:13:50.085 AEST: ppp671 PPP: Received LOGIN Response PASS Nov
> 13 14:13:50.085 AEST: ppp671 PPP/AAA: Check Attr: service-type Nov 13
> 14:13:50.085 AEST: ppp671 PPP/AAA: Check Attr: Framed-Protocol Nov 13
> 14:13:50.085 AEST: ppp671 PPP/AAA: Check Attr: addr Nov 13
> 14:13:50.085 AEST: ppp671 PPP/AAA: Check Attr: route: Peruser Nov 13
> 14:13:50.085 AEST: ppp671 PPP/AAA: Check Attr: netmask Nov 13
> 14:13:50.085 AEST: ppp671 PPP/AAA: Check Attr: routing Nov 13
> 14:13:50.085 AEST: ppp671 PPP/AAA: Check Attr: outacl: Peruser Nov 13
> 14:13:50.085 AEST: ppp671 PPP/AAA: Check Attr: Framed-MTU Nov 13
> 14:13:50.085 AEST: ppp671 PPP/AAA: Check Attr: link-compression:
> Peruser Full Vaccess
> Nov 13 14:13:50.089 AEST: Vi3 Tnl/Sn 34840/672 L2TP: Virtual interface
> created for skeeve at xxxxxxxdsl.com.au, bandwidth 155520 Kbps Nov 13
> 14:13:50.089 AEST: AAA/BIND(000002AB): Bind i/f Virtual-Access3 Nov 13
> 14:13:50.089 AEST: Vi3 Tnl/Sn 34840/672 L2TP: VPDN session up Nov 13
> 14:13:50.093 AEST: %LINK-3-UPDOWN: Interface Virtual-Access3, changed
> state to up Nov 13 14:13:50.093 AEST: Vi3 AAA/AUTHOR/LCP: Process
> Author Nov 13 14:13:50.093 AEST: Vi3 AAA/AUTHOR/LCP: Process Attr:
> service-type Nov 13 14:13:50.093 AEST: Vi3 AAA/AUTHOR/LCP: Process
> Attr: link-compression Nov 13 14:13:50.093 AEST: AAA/AUTHOR:
> Processing PerUser AV link-compression Nov 13 14:13:50.093 AEST: Vi3
> AAA/AUTHOR/LCP: IF_config:
> ip tcp header-compression
>
> Nov 13 14:13:50.093 AEST: Vi3 PAP: O AUTH-ACK id 1 len 5 Nov 13
> 14:13:50.093 AEST: AAA/ACCT/NET(000002AB): Pick method list 'default'
> Nov 13 14:13:50.093 AEST: AAA/ACCT/SETMLIST(000002AB): Handle 0, mlist
> 6396616C, Name default Nov 13 14:13:50.093 AEST:
> AAA/ACCT/EVENT/(000002AB): NET UP Nov 13 14:13:50.093 AEST:
> AAA/ACCT/CLIENT(000002AB): recv 155520000bps xmit 155520000bps Nov 13
> 14:13:50.093 AEST: AAA/ACCT/HC(000002AB): Update VPDN/3E0007DA Nov 13
> 14:13:50.093 AEST: AAA/ACCT/HC(000002AB): VPDN/3E0007DA [pre-sess]
> (rx/tx) base 0/0 pre 0/0 call 0/0
> Nov 13 14:13:50.093 AEST: AAA/ACCT/HC(000002AB): VPDN/3E0007DA
> [pre-sess]
> (rx/tx) adjusted, pre 0/0 call 0/0
> Nov 13 14:13:50.093 AEST: Vi3 AAA/AUTHOR/IPCP: FSM authorization not
> needed Nov 13 14:13:50.093 AEST: Vi3 AAA/AUTHOR/FSM: We can start IPCP
> Nov 13 14:13:50.121 AEST: Vi3 AAA/AUTHOR/IPCP: Start. Her address
> 0.0.0.0, we want 0.0.0.0 Nov 13 14:13:50.121 AEST: Vi3
> AAA/AUTHOR/IPCP: Processing AV addr Nov 13 14:13:50.121 AEST: Vi3
> AAA/AUTHOR/IPCP: Processing AV route Nov 13 14:13:50.121 AEST: Vi3
> AAA/AUTHOR/IPCP: Processing AV netmask Nov 13 14:13:50.125 AEST: Vi3
> AAA/AUTHOR/IPCP: Processing AV routing Nov 13 14:13:50.125 AEST: Vi3
> AAA/AUTHOR/IPCP: Set routing to TRUE Nov 13 14:13:50.125 AEST: Vi3
> AAA/AUTHOR/IPCP: Processing AV outacl Nov 13 14:13:50.125 AEST: Vi3
> AAA/AUTHOR/IPCP: Authorization succeeded Nov 13 14:13:50.125 AEST: Vi3
> AAA/AUTHOR/IPCP: Done. Her address 0.0.0.0, we want xxx.xxx.11.2 Nov
> 13 14:13:50.125 AEST: Vi3 AAA/AUTHOR/IPCP: no author-info for primary
> dns Nov 13 14:13:50.125 AEST: Vi3 AAA/AUTHOR/IPCP: no author-info for
> seconday dns Nov 13 14:13:50.157 AEST: AAA/AUTHOR: Processing PerUser
> AV route Nov 13 14:13:50.157 AEST: AAA/AUTHOR: Processing PerUser AV
> outacl Nov 13 14:13:51.093 AEST: %LINEPROTO-5-UPDOWN: Line protocol on
> Interface Virtual-Access3, changed state to up Nov 13 14:13:55.637
> AEST: AAA/ACCT/NET(000002AB): Pick method list 'default'
> Nov 13 14:13:55.637 AEST: AAA/ACCT/SETMLIST(000002AB): Handle 0, mlist
> 6396616C, Name default Nov 13 14:13:55.637 AEST:
> AAA/ACCT/EVENT/(000002AB): NET DOWN Nov 13 14:13:55.637 AEST:
> AAA/ACCT/CLIENT(000002AB): recv 155520000bps xmit 155520000bps Nov 13
> 14:13:55.637 AEST: AAA/ACCT/HC(000002AB): Update VPDN/3E0007DA Nov 13
> 14:13:55.637 AEST: AAA/ACCT/HC(000002AB): VPDN/3E0007DA [sess]
> (rx/tx) base 0/0 pre 0/0 call 150/123
> Nov 13 14:13:55.637 AEST: AAA/ACCT/HC(000002AB): VPDN/3E0007DA [sess]
> (rx/tx) adjusted, pre 0/0 call 150/123 Nov 13 14:13:55.637 AEST:
> AAA/ACCT/NET(000002AB): Accounting record not sent Nov 13 14:13:55.637
> AEST: AAA/ACCT(000002AB): del node, session 683 Nov 13 14:13:55.637
> AEST: AAA/ACCT/NET(000002AB): free_rec, count 0 Nov 13 14:13:55.637
> AEST: AAA/ACCT/NET(000002AB) reccnt 0, csr FALSE, osr 0 Nov 13
> 14:13:55.825 AEST: AAA/ACCT/EVENT/(000002AB): NET DOWN Nov 13
> 14:13:55.825 AEST: AAA/ACCT(000002AB): Duplicate action NET DOWN Nov
> 13 14:13:55.825 AEST: AAA/ACCT/CLIENT(000002AB): recv 155520000bps
> xmit 155520000bps Nov 13 14:13:55.825 AEST: AAA/ACCT/HC(000002AB):
> Update VPDN/3E0007DA Nov 13 14:13:55.825 AEST: AAA/ACCT/HC(000002AB):
> VPDN/3E0007DA [sess]
> (rx/tx) base 0/0 pre 0/0 call 150/131
> Nov 13 14:13:55.825 AEST: AAA/ACCT/HC(000002AB): VPDN/3E0007DA [sess]
> (rx/tx) adjusted, pre 0/0 call 150/131 Nov 13 14:13:55.825 AEST:
> AAA/ACCT/HC(000002AB): Deregister VPDN/3E0007DA Nov 13 14:13:55.825
> AEST: Vi3 VPDN: Reseting interface Nov 13 14:13:55.825 AEST:
> AAA/ACCT/EVENT/(000002AB): CALL STOP Nov 13 14:13:55.825 AEST:
> AAA/ACCT(000002AB) reccnt 0, osr 0 Nov 13 14:13:55.829 AEST:
> %LINK-3-UPDOWN: Interface Virtual-Access3, changed state to down Nov
> 13 14:13:56.829 AEST: %LINEPROTO-5-UPDOWN: Line protocol on Interface
> Virtual-Access3, changed state to down ===
>
>
>
> Radius log:
>
> rad_recv: Access-Request packet from host xxx.xxx.8.3:1645, id=164,
> length=134
> Framed-Protocol = PPP
> User-Name = "skeeve at xxxxxxxdsl.com.au"
> User-Password = "testing"
> NAS-Port-Type = Virtual
> Cisco-NAS-Port = "Uniq-Sess-ID671"
> NAS-Port = 671
> Calling-Station-Id = "nnb110200201120"
> Service-Type = Framed-User
> NAS-IP-Address = xxx.xxx.8.3
> Mon Nov 13 14:13:50 2006 : Debug: Processing the authorize section of
> radiusd.conf
> Mon Nov 13 14:13:50 2006 : Debug: modcall: entering group authorize
> for request 3
> Mon Nov 13 14:13:50 2006 : Debug: modsingle[authorize]: calling
preprocess
> (rlm_preprocess) for request 3
> Mon Nov 13 14:13:50 2006 : Debug: modsingle[authorize]: returned from
> preprocess (rlm_preprocess) for request 3
> Mon Nov 13 14:13:50 2006 : Debug: modcall[authorize]: module
"preprocess"
> returns ok for request 3
> Mon Nov 13 14:13:50 2006 : Debug: modsingle[authorize]: calling chap
> (rlm_chap) for request 3
> Mon Nov 13 14:13:50 2006 : Debug: modsingle[authorize]: returned from
chap
> (rlm_chap) for request 3
> Mon Nov 13 14:13:50 2006 : Debug: modcall[authorize]: module "chap"
> returns noop for request 3
> Mon Nov 13 14:13:50 2006 : Debug: modsingle[authorize]: calling mschap
> (rlm_mschap) for request 3
> Mon Nov 13 14:13:50 2006 : Debug: modsingle[authorize]: returned from
> mschap (rlm_mschap) for request 3
> Mon Nov 13 14:13:50 2006 : Debug: modcall[authorize]: module "mschap"
> returns noop for request 3
> Mon Nov 13 14:13:50 2006 : Debug: modsingle[authorize]: calling suffix
> (rlm_realm) for request 3
> Mon Nov 13 14:13:50 2006 : Debug: rlm_realm: Looking up realm
> "xxxxxxxdsl.com.au" for User-Name = "skeeve at xxxxxxxdsl.com.au"
> Mon Nov 13 14:13:50 2006 : Debug: rlm_realm: Found realm
> "xxxxxxxdsl.com.au"
> Mon Nov 13 14:13:50 2006 : Debug: rlm_realm: Proxying request from
user
> skeeve to realm xxxxxxxdsl.com.au
> Mon Nov 13 14:13:50 2006 : Debug: rlm_realm: Adding Realm =
> "xxxxxxxdsl.com.au"
> Mon Nov 13 14:13:50 2006 : Debug: rlm_realm: Authentication realm is
> LOCAL.
> Mon Nov 13 14:13:50 2006 : Debug: modsingle[authorize]: returned from
> suffix (rlm_realm) for request 3
> Mon Nov 13 14:13:50 2006 : Debug: modcall[authorize]: module "suffix"
> returns noop for request 3
> Mon Nov 13 14:13:50 2006 : Debug: modsingle[authorize]: calling files
> (rlm_files) for request 3
> Mon Nov 13 14:13:50 2006 : Debug: users: Matched entry
> skeeve at xxxxxxxdsl.com.au at line 1
> Mon Nov 13 14:13:50 2006 : Debug: modsingle[authorize]: returned from
> files (rlm_files) for request 3
> Mon Nov 13 14:13:50 2006 : Debug: modcall[authorize]: module "files"
> returns ok for request 3
> Mon Nov 13 14:13:50 2006 : Debug: modcall: leaving group authorize
> (returns
> ok) for request 3
> Mon Nov 13 14:13:50 2006 : Debug: rad_check_password: Found Auth-Type
> Local
> Mon Nov 13 14:13:50 2006 : Debug: auth: type Local Mon Nov 13 14:13:50
> 2006 : Debug: auth: user supplied User-Password matches local
> User-Password Mon Nov 13 14:13:50 2006 : Auth: Login OK:
> [skeeve at xxxxxxxdsl.com.au/testing] (from client Cisco7200 port 671 cli
> nnb110200201120)
> Sending Access-Accept of id 164 to xxx.xxx.8.3 port 1645
> Service-Type = Framed-User
> Framed-Protocol = PPP
> Framed-IP-Address = xxx.xxx.11.2
> Framed-IP-Netmask = 255.255.255.0
> Framed-Routing = Broadcast-Listen
> Framed-Filter-Id = "std.ppp"
> Framed-MTU = 1500
> Framed-Compression = Van-Jacobson-TCP-IP Mon Nov 13 14:13:50
> 2006 : Debug: Finished request 3 Mon Nov 13 14:13:50 2006 : Debug:
> Going to the next request Mon Nov 13 14:13:50 2006 : Debug: ---
> Walking the entire request list --- Mon Nov 13 14:13:50 2006 : Debug:
> Waking up in 6 seconds...
>
> ===
>
> Cisco Config
> !
> aaa new-model
> !
> !
> aaa group server radius israd
> server xxx.xx.102.10 auth-port 1645 acct-port 1646 !
> aaa authentication login default local aaa authentication ppp default
> if-needed local group israd none aaa authorization exec default local
> group israd aaa authorization network default group israd none aaa
> accounting delay-start aaa accounting update periodic 15 aaa
> accounting network default start-stop group radius aaa accounting
> connection default start-stop group radius aaa accounting system
> default start-stop group radius aaa session-id common !
> vpdn enable
> vpdn authen-before-forward
> vpdn logging
> vpdn logging local
> vpdn logging tunnel-drop
> vpdn history failure table-size 50
> vpdn session-limit 1000
> vpdn ip udp ignore checksum
> vpdn search-order domain
> !
> vpdn-group aapt-dsl-direct
> ! Default L2TP VPDN group
> accept-dialin
> protocol l2tp
> virtual-template 1
> local name lns-cca01.xxxxxxx.com.au
> lcp renegotiation on-mismatch
> l2tp tunnel password 7 xx
> ip pmtu
> ip mtu adjust
> !
> !
> interface Loopback1
> description Loopback for DSL
> ip address xxx.xxx.8.3 255.255.255.255 !
> interface Virtual-Template1
> ip unnumbered Loopback1
> ip tcp adjust-mss 1360
> no peer default ip address
> down-when-looped
> ppp mtu adaptive
> ppp authentication chap pap
> !
>
>
> !
> radius-server configure-nas
> radius-server host xxx.xx.10 auth-port 1645 acct-port 1646 key 7 xxxxx
> radius-server retransmit 2 radius-server timeout 2 radius-server
> deadtime 1 radius-server key 7 xxxxx radius-server vsa send accounting
> radius-server vsa send authentication !
>
>
>
>
>
> _______________________________________________________
> Skeeve Stevens, RHCE Email: skeeve at skeeve.org
> Website: www.skeeve.org - Telephone: (0414) 753 383 skype://skeeve
> Address: P.O Box 1035, Epping, NSW, 1710, Australia
>
> eIntellego - skeeve at eintellego.net - www.eintellego.net
> _______________________________________________________
> I'm a groove licked love child king of the verse Si vis pacem, para
> bellum
>
>
>
>
> _______________________________________________
> cisco-nsp mailing list cisco-nsp at puck.nether.net
> https://puck.nether.net/mailman/listinfo/cisco-nsp
> archive at http://puck.nether.net/pipermail/cisco-nsp/
More information about the cisco-nsp
mailing list