[c-nsp] L2TP DSL issue with 7204 + FreeRadius
Stephen Fulton
cisco-nsp at lists.esoteric.ca
Sun Nov 12 23:52:13 EST 2006
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