[c-nsp] L2TP DSL issue with 7204 + FreeRadius

Skeeve Stevens skeeve at skeeve.org
Mon Nov 13 02:40:04 EST 2006


 

Here goes.

Now with:

General OS:
  AAA Authentication debugging is on
  AAA Authorization debugging is on
  AAA Accounting debugging is on
  AAA Per-user attributes debugging is on
PPP:
  PPP authentication debugging is on
Radius protocol debugging is on
Radius protocol verbose debugging is on
Radius packet protocol debugging is on


VPN:
  VPDN call event debugging is on
  VPDN events debugging is on

Nov 13 18:35:50.439 AEST: AAA/BIND(0000000A): Bind i/f Virtual-Template1 
Nov 13 18:35:50.439 AEST: AAA/ACCT/CLIENT(0000000A): recv 155520000bps xmit
155520000bps
Nov 13 18:35:50.439 AEST: AAA/ACCT/HC(0000000A): Register VPDN/F4000009
155Mbit/s, poll every 30.3000s
Nov 13 18:35:50.439 AEST: AAA/ACCT/HC(0000000A): Update VPDN/F4000009 
Nov 13 18:35:50.439 AEST: AAA/ACCT/HC(0000000A): VPDN/F4000009 [init-sess]
(rx/tx) base 0/0 pre 0/0 call 0/0
Nov 13 18:35:50.439 AEST: AAA/ACCT/HC(0000000A): VPDN/F4000009 [init-sess]
(rx/tx) adjusted, pre 0/0 call 0/0
Nov 13 18:35:50.439 AEST: AAA/ACCT/EVENT/(0000000A): CALL START
Nov 13 18:35:50.439 AEST: Getting session id for NET(0000000A) : db=66A6FC68
Nov 13 18:35:50.439 AEST: AAA/ACCT(00000000): add node, session 10
Nov 13 18:35:50.439 AEST: AAA/ACCT/NET(0000000A): add, count 1
Nov 13 18:35:50.439 AEST: AAA/ACCT/EVENT/(0000000A): ATTR ADD
Nov 13 18:35:50.439 AEST: AAA/ACCT/NET(0000000A): Pick method list 'default'
Nov 13 18:35:50.443 AEST: AAA/ACCT/SETMLIST(0000000A): Handle 0, mlist
639660BC, Name default
Nov 13 18:35:50.443 AEST: AAA/ACCT(0000000A): Type NET: Periodic timer
initialized
Nov 13 18:35:50.443 AEST: ppp4 PPP: Authorization required
Nov 13 18:35:50.443 AEST: AAA/ACCT/NET(0000000A): Pick method list 'default'
Nov 13 18:35:50.443 AEST: AAA/ACCT/SETMLIST(0000000A): Handle 0, mlist
639660BC, Name default
Nov 13 18:35:50.443 AEST: AAA/AUTHEN/PPP (0000000A): Pick method list
'default' 
Nov 13 18:35:50.443 AEST: ppp4 PPP: Sent PAP LOGIN Request
Nov 13 18:35:50.443 AEST: RADIUS/ENCODE(0000000A):Orig. component type =
VPDN
Nov 13 18:35:50.443 AEST: RADIUS(0000000A): Storing nasport 4 in rad_db
Nov 13 18:35:50.443 AEST: RADIUS(0000000A): Config NAS IP: x.1
Nov 13 18:35:50.443 AEST: Getting session id for NET(0000000A) : db=66A6FC68
Nov 13 18:35:50.443 AEST: RADIUS/ENCODE(0000000A): acct_session_id: 10
Nov 13 18:35:50.443 AEST: RADIUS(0000000A): sending
Nov 13 18:35:50.443 AEST: RADIUS(0000000A): Send Access-Request to x.10:1645
id 1645/5, len 132
Nov 13 18:35:50.443 AEST: RADIUS:  authenticator E2 9C CD 5B 34 3F 31 9A -
D6 94 31 84 D0 93 D9 7D
Nov 13 18:35:50.443 AEST: RADIUS:  Framed-Protocol     [7]   6   PPP
[1]
Nov 13 18:35:50.443 AEST: RADIUS:  User-Name           [1]   26
"skeeve at x.com.au"
Nov 13 18:35:50.443 AEST: RADIUS:  User-Password       [2]   18  *
Nov 13 18:35:50.443 AEST: RADIUS:  NAS-Port-Type       [61]  6   Virtual
[5]
Nov 13 18:35:50.443 AEST: RADIUS:  Vendor, Cisco       [26]  21  
Nov 13 18:35:50.443 AEST: RADIUS:   cisco-nas-port     [2]   15
"Uniq-Sess-ID4"
Nov 13 18:35:50.443 AEST: RADIUS:  NAS-Port            [5]   6   4

Nov 13 18:35:50.443 AEST: RADIUS:  Calling-Station-Id  [31]  17
"nnb110200201120"
Nov 13 18:35:50.443 AEST: RADIUS:  Service-Type        [6]   6   Framed
[2]
Nov 13 18:35:50.443 AEST: RADIUS:  NAS-IP-Address      [4]   6   x.1

Nov 13 18:35:50.451 AEST: RADIUS: Received from id 1645/5 x.10:1645,
Access-Accept, len 65
Nov 13 18:35:50.451 AEST: RADIUS:  authenticator 66 2B 38 61 8D B1 5A 4A -
E1 F1 D6 51 19 1E C1 DD
Nov 13 18:35:50.451 AEST: RADIUS:  Service-Type        [6]   6   Framed
[2]
Nov 13 18:35:50.451 AEST: RADIUS:  Framed-Protocol     [7]   6   PPP
[1]
Nov 13 18:35:50.451 AEST: RADIUS:  Framed-IP-Address   [8]   6   x.9.2

Nov 13 18:35:50.451 AEST: RADIUS:  Framed-IP-Netmask   [9]   6
255.255.255.254           
Nov 13 18:35:50.451 AEST: RADIUS:  Framed-Routing      [10]  6   3

Nov 13 18:35:50.451 AEST: RADIUS:  Filter-Id           [11]  9   
Nov 13 18:35:50.451 AEST: RADIUS:   73 74 64 2E 70 70 70
[std.ppp]
Nov 13 18:35:50.451 AEST: RADIUS:  Framed-MTU          [12]  6   1500

Nov 13 18:35:50.451 AEST: RADIUS(0000000A): Received from id 1645/5
Nov 13 18:35:50.451 AEST: ppp4 PPP: Received LOGIN Response PASS
Nov 13 18:35:50.451 AEST: ppp4 PPP/AAA: Check Attr: service-type
Nov 13 18:35:50.451 AEST: ppp4 PPP/AAA: Check Attr: Framed-Protocol
Nov 13 18:35:50.451 AEST: ppp4 PPP/AAA: Check Attr: addr
Nov 13 18:35:50.451 AEST: ppp4 PPP/AAA: Check Attr: route: Peruser
Nov 13 18:35:50.451 AEST: ppp4 PPP/AAA: Check Attr: netmask
Nov 13 18:35:50.451 AEST: ppp4 PPP/AAA: Check Attr: routing
Nov 13 18:35:50.451 AEST: ppp4 PPP/AAA: Check Attr: outacl: Peruser
Nov 13 18:35:50.451 AEST: ppp4 PPP/AAA: Check Attr: Framed-MTU
Nov 13 18:35:50.455 AEST: Vi3 Tnl/Sn 2343/5 L2TP: Virtual interface created
for skeeve at x.com.au, bandwidth 155520 Kbps
Nov 13 18:35:50.455 AEST: AAA/BIND(0000000A): Bind i/f Virtual-Access3 
Nov 13 18:35:50.455 AEST: Vi3 Tnl/Sn 2343/5 L2TP: VPDN session up
Nov 13 18:35:50.459 AEST: %LINK-3-UPDOWN: Interface Virtual-Access3, changed
state to up
Nov 13 18:35:50.459 AEST: Vi3 AAA/AUTHOR/LCP: Process Author
Nov 13 18:35:50.459 AEST: Vi3 AAA/AUTHOR/LCP: Process Attr: service-type
Nov 13 18:35:50.459 AEST: Vi3 PAP: O AUTH-ACK id 1 len 5
Nov 13 18:35:50.459 AEST: AAA/ACCT/NET(0000000A): Pick method list 'default'
Nov 13 18:35:50.459 AEST: AAA/ACCT/SETMLIST(0000000A): Handle 0, mlist
639660BC, Name default
Nov 13 18:35:50.459 AEST: AAA/ACCT/EVENT/(0000000A): NET UP
Nov 13 18:35:50.459 AEST: AAA/ACCT/CLIENT(0000000A): recv 155520000bps xmit
155520000bps
Nov 13 18:35:50.459 AEST: AAA/ACCT/HC(0000000A): Update VPDN/F4000009 
Nov 13 18:35:50.459 AEST: AAA/ACCT/HC(0000000A): VPDN/F4000009 [pre-sess]
(rx/tx) base 0/0 pre 0/0 call 0/0
Nov 13 18:35:50.459 AEST: AAA/ACCT/HC(0000000A): VPDN/F4000009 [pre-sess]
(rx/tx) adjusted, pre 0/0 call 0/0
Nov 13 18:35:50.459 AEST: Vi3 AAA/AUTHOR/IPCP: FSM authorization not needed
Nov 13 18:35:50.459 AEST: Vi3 AAA/AUTHOR/FSM: We can start IPCP
Nov 13 18:35:50.539 AEST: Vi3 AAA/AUTHOR/IPCP: Start.  Her address 0.0.0.0,
we want 0.0.0.0
Nov 13 18:35:50.539 AEST: Vi3 AAA/AUTHOR/IPCP: Processing AV addr
Nov 13 18:35:50.539 AEST: Vi3 AAA/AUTHOR/IPCP: Processing AV route
Nov 13 18:35:50.539 AEST: Vi3 AAA/AUTHOR/IPCP: Processing AV netmask
Nov 13 18:35:50.539 AEST: Vi3 AAA/AUTHOR/IPCP: Processing AV routing
Nov 13 18:35:50.539 AEST: Vi3 AAA/AUTHOR/IPCP: Set routing to TRUE
Nov 13 18:35:50.539 AEST: Vi3 AAA/AUTHOR/IPCP: Processing AV outacl
Nov 13 18:35:50.539 AEST: Vi3 AAA/AUTHOR/IPCP: Authorization succeeded
Nov 13 18:35:50.539 AEST: Vi3 AAA/AUTHOR/IPCP: Done.  Her address 0.0.0.0,
we want 203.160.9.2
Nov 13 18:35:50.539 AEST: Vi3 AAA/AUTHOR/IPCP: no author-info for primary
dns
Nov 13 18:35:50.539 AEST: Vi3 AAA/AUTHOR/IPCP: no author-info for seconday
dns
Nov 13 18:35:50.611 AEST: AAA/AUTHOR: Processing PerUser AV route
Nov 13 18:35:50.611 AEST: AAA/AUTHOR: Processing PerUser AV outacl
Nov 13 18:35:50.611 AEST: Vi3 AAA/PER-USER/access-group: acl std.ppp for
proto IP does not exist
Nov 13 18:35:51.459 AEST: %LINEPROTO-5-UPDOWN: Line protocol on Interface
Virtual-Access3, changed state to up
Nov 13 18:35:57.571 AEST: AAA/ACCT/NET(0000000A): Pick method list 'default'
Nov 13 18:35:57.571 AEST: AAA/ACCT/SETMLIST(0000000A): Handle 0, mlist
639660BC, Name default
Nov 13 18:35:57.571 AEST: AAA/ACCT/EVENT/(0000000A): NET DOWN
Nov 13 18:35:57.571 AEST: AAA/ACCT/CLIENT(0000000A): recv 155520000bps xmit
155520000bps
Nov 13 18:35:57.571 AEST: AAA/ACCT/HC(0000000A): Update VPDN/F4000009 
Nov 13 18:35:57.571 AEST: AAA/ACCT/HC(0000000A): VPDN/F4000009 [sess]
(rx/tx) base 0/0 pre 0/0 call 128/95
Nov 13 18:35:57.571 AEST: AAA/ACCT/HC(0000000A): VPDN/F4000009 [sess]
(rx/tx) adjusted, pre 0/0 call 128/95
Nov 13 18:35:57.571 AEST: AAA/ACCT/NET(0000000A): Accounting record not sent
Nov 13 18:35:57.571 AEST: AAA/ACCT(0000000A): del node, session 10
Nov 13 18:35:57.571 AEST: AAA/ACCT/NET(0000000A): free_rec, count 0
Nov 13 18:35:57.571 AEST: AAA/ACCT/NET(0000000A) reccnt 0, csr FALSE, osr 0
Nov 13 18:35:58.831 AEST: AAA/ACCT/EVENT/(0000000A): NET DOWN
Nov 13 18:35:58.831 AEST: AAA/ACCT(0000000A): Duplicate action NET DOWN
Nov 13 18:35:58.831 AEST: AAA/ACCT/CLIENT(0000000A): recv 155520000bps xmit
155520000bps
Nov 13 18:35:58.831 AEST: AAA/ACCT/HC(0000000A): Update VPDN/F4000009 
Nov 13 18:35:58.831 AEST: AAA/ACCT/HC(0000000A): VPDN/F4000009 [sess]
(rx/tx) base 0/0 pre 0/0 call 128/103
Nov 13 18:35:58.831 AEST: AAA/ACCT/HC(0000000A): VPDN/F4000009 [sess]
(rx/tx) adjusted, pre 0/0 call 128/103
Nov 13 18:35:58.831 AEST: AAA/ACCT/HC(0000000A): Deregister VPDN/F4000009 
Nov 13 18:35:58.831 AEST: Vi3 VPDN: Reseting interface
Nov 13 18:35:58.831 AEST: AAA/ACCT/EVENT/(0000000A): CALL STOP
Nov 13 18:35:58.831 AEST: AAA/ACCT(0000000A) reccnt 0, osr 0
Nov 13 18:35:58.835 AEST: %LINK-3-UPDOWN: Interface Virtual-Access3, changed
state to down
Nov 13 18:35:59.835 AEST: %LINEPROTO-5-UPDOWN: Line protocol on Interface
Virtual-Access3, changed state to down

-----Original Message-----
From: Oliver Boehmer (oboehmer) [mailto:oboehmer at cisco.com] 
Sent: Monday, 13 November 2006 6:07 PM
To: skeeve at skeeve.org
Subject: RE: [c-nsp] L2TP DSL issue with 7204 + FreeRadius

cisco-nsp-bounces at puck.nether.net <> wrote on Monday, November 13, 2006
4:22 AM:

> 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.

please include "deb aaa per-user" in the set of debugs.

Please don't use VJ-Compression, this will cause all your packets being
process-switched.. 

	oli



More information about the cisco-nsp mailing list