[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