[c-nsp] L2TP DSL issue with 7204 + FreeRadius
Skeeve Stevens
skeeve at skeeve.org
Sun Nov 12 22:22:26 EST 2006
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
More information about the cisco-nsp
mailing list