[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