[c-nsp] PPPoE negotiation trouble on 12.3(12)
Oliver Boehmer (oboehmer)
oboehmer at cisco.com
Thu Jan 6 04:54:23 EST 2005
Blaz,
can you enable "debug radius authen" and "debug aaa per-user"? it could
be related to the ACL which is being applied:
Jan 6 08:39:28: Vi2.1 IPCP: State is Open
Jan 6 08:39:28: AAA/AUTHOR: Processing PerUser AV outacl
Jan 6 08:39:28: Vi2.1 IPCP: O TERMREQ [Open] id 2 len 4
"debug aaa per-user" shows more information about this.
When you disable authorization, we don't apply the ACL, and the
connection comes up fine.
oli
P.S: I'd downgrade to 12.3(10b), 12.3(12) has some issues wrt PPP
(CSCsa47225)
Blaz Zupan <> wrote on Thursday, January 06, 2005 10:41 AM:
> Until now, we have been using RBE for our DSL customers, but due to
> some
> upcoming network changes we need to start using PPPoE. I'm now
> fighting with
> the most basic thing: I can not successfully establish a PPP
> connection when I
> use authorization through radius.
>
> Here is my config:
>
> aaa authentication ppp adsl group adsl
> aaa authorization network adsl group adsl if-authenticated
> aaa accounting network adsl start-stop group adsl
>
> vpdn-group 1
> accept-dialin
> protocol pppoe
> virtual-template 1
>
> interface Virtual-Template1
> mtu 1492
> ip unnumbered ATM2/0
> no peer default ip address
> ppp authentication chap callin adsl
> ppp authorization adsl
> ppp accounting adsl
> ppp ipcp dns 212.18.32.10 212.18.32.12
> ppp ipcp address required
>
> The radius server is configured to assign a static IP to my test user.
> After starting a PPPoE connection on a Windows XP client, the
> connection seems
> to come up but is immediately dropped and the Windows PC reports that
> the
> remote end dropped the connection. Below is the output of an example
> session
> with debug ppp negotiation, debug ppp authentication, debug aaa
> authentication and debug aaa authorization turned on.
>
> Jan 6 08:39:28: AAA/BIND(000000FB): Bind i/f Virtual-Template1
> Jan 6 08:39:28: ppp123 PPP: Using default call direction
> Jan 6 08:39:28: ppp123 PPP: Treating connection as a dedicated line
> Jan 6 08:39:28: ppp123 PPP: Phase is ESTABLISHING, Active Open
> Jan 6 08:39:28: ppp123 AAA/AUTHOR/LCP: Authorization succeeds
> trivially
> Jan 6 08:39:28: ppp123 LCP: O CONFREQ [Closed] id 1 len 19
> Jan 6 08:39:28: ppp123 LCP: MRU 1492 (0x010405D4)
> Jan 6 08:39:28: ppp123 LCP: AuthProto CHAP (0x0305C22305)
> Jan 6 08:39:28: ppp123 LCP: MagicNumber 0x1326FD20
> (0x05061326FD20)
> Jan 6 08:39:28: ppp123 LCP: I CONFREQ [REQsent] id 0 len 17
> Jan 6 08:39:28: ppp123 LCP: MRU 1466 (0x010405BA)
> Jan 6 08:39:28: ppp123 LCP: MagicNumber 0x4CFF5A91
> (0x05064CFF5A91)
> Jan 6 08:39:28: ppp123 LCP: Callback 6 (0x0D0306)
> Jan 6 08:39:28: ppp123 LCP: O CONFREJ [REQsent] id 0 len 7
> Jan 6 08:39:28: ppp123 LCP: Callback 6 (0x0D0306)
> Jan 6 08:39:28: ppp123 LCP: I CONFACK [REQsent] id 1 len 19
> Jan 6 08:39:28: ppp123 LCP: MRU 1492 (0x010405D4)
> Jan 6 08:39:28: ppp123 LCP: AuthProto CHAP (0x0305C22305)
> Jan 6 08:39:28: ppp123 LCP: MagicNumber 0x1326FD20
> (0x05061326FD20)
> Jan 6 08:39:28: ppp123 LCP: I CONFREQ [ACKrcvd] id 1 len 14
> Jan 6 08:39:28: ppp123 LCP: MRU 1466 (0x010405BA)
> Jan 6 08:39:28: ppp123 LCP: MagicNumber 0x4CFF5A91
> (0x05064CFF5A91)
> Jan 6 08:39:28: ppp123 LCP: O CONFNAK [ACKrcvd] id 1 len 8
> Jan 6 08:39:28: ppp123 LCP: MRU 1492 (0x010405D4)
> Jan 6 08:39:28: ppp123 LCP: I CONFREQ [ACKrcvd] id 2 len 14
> Jan 6 08:39:28: ppp123 LCP: MRU 1466 (0x010405BA)
> Jan 6 08:39:28: ppp123 LCP: MagicNumber 0x4CFF5A91
> (0x05064CFF5A91)
> Jan 6 08:39:28: ppp123 LCP: O CONFNAK [ACKrcvd] id 2 len 8
> Jan 6 08:39:28: ppp123 LCP: MRU 1492 (0x010405D4)
> Jan 6 08:39:28: ppp123 LCP: I CONFREQ [ACKrcvd] id 3 len 14
> Jan 6 08:39:28: ppp123 LCP: MRU 1492 (0x010405D4)
> Jan 6 08:39:28: ppp123 LCP: MagicNumber 0x4CFF5A91
> (0x05064CFF5A91)
> Jan 6 08:39:28: ppp123 LCP: O CONFACK [ACKrcvd] id 3 len 14
> Jan 6 08:39:28: ppp123 LCP: MRU 1492 (0x010405D4)
> Jan 6 08:39:28: ppp123 LCP: MagicNumber 0x4CFF5A91
> (0x05064CFF5A91)
> Jan 6 08:39:28: ppp123 LCP: State is Open
> Jan 6 08:39:28: ppp123 PPP: Phase is AUTHENTICATING, by this end
> Jan 6 08:39:28: ppp123 CHAP: O CHALLENGE id 1 len 29 from "maribor1"
> Jan 6 08:39:28: ppp123 LCP: I IDENTIFY [Open] id 4 len 18 magic
> 0x4CFF5A91 MSRASV5.10
> Jan 6 08:39:28: ppp123 LCP: I IDENTIFY [Open] id 5 len 24 magic
> 0x4CFF5A91 MSRAS-0-DAMJANXP
> Jan 6 08:39:28: ppp123 CHAP: I RESPONSE id 1 len 25 from "blaz"
> Jan 6 08:39:28: ppp123 PPP: Phase is FORWARDING, Attempting Forward
> Jan 6 08:39:28: ppp123 PPP: Phase is AUTHENTICATING, Unauthenticated
> User
> Jan 6 08:39:28: AAA/AUTHEN/PPP (000000FB): Pick method list 'adsl'
> Jan 6 08:39:28: ppp123 PPP/AAA: Check Attr: routing
> Jan 6 08:39:28: ppp123 PPP/AAA: Check Attr: Framed-MTU
> Jan 6 08:39:28: ppp123 PPP/AAA: Check Attr: Framed-Protocol
> Jan 6 08:39:28: ppp123 PPP/AAA: Check Attr: service-type
> Jan 6 08:39:28: ppp123 PPP/AAA: Check Attr: idletime: Peruser
> Jan 6 08:39:28: ppp123 PPP/AAA: Check Attr: outacl: Peruser
> Jan 6 08:39:28: ppp123 PPP/AAA: Check Attr: addr
> Jan 6 08:39:28: ppp123 PPP/AAA: Check Attr: netmask
> Jan 6 08:39:28: ppp123 PPP: Phase is FORWARDING, Attempting Forward
> Jan 6 08:39:28: AAA/BIND(000000FB): Bind i/f Virtual-Access2.1
> Jan 6 08:39:28: Vi2.1 PPP: Phase is AUTHENTICATING, Authenticated
> User
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/LCP: Process Author
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/LCP: Process Attr: service-type
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/LCP: Process Attr: idletime
> Jan 6 08:39:28: AAA/AUTHOR: Processing PerUser AV idletime
> Jan 6 08:39:28: Vi2.1 CHAP: O SUCCESS id 1 len 4
> Jan 6 08:39:28: Vi2.1 PPP: Phase is UP
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: FSM authorization not needed
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/FSM: We can start IPCP
> Jan 6 08:39:28: Vi2.1 IPCP: O CONFREQ [Closed] id 1 len 10
> Jan 6 08:39:28: Vi2.1 IPCP: Address 212.18.38.1 (0x0306D4122601)
> Jan 6 08:39:28: Vi2.1 PPP: Process pending ncp packets
> Jan 6 08:39:28: Vi2.1 CCP: I CONFREQ [Not negotiated] id 6 len 10
> Jan 6 08:39:28: Vi2.1 CCP: MS-PPC supported bits 0x00000001
> (0x120600000001)
> Jan 6 08:39:28: Vi2.1 LCP: O PROTREJ [Open] id 2 len 16 protocol CCP
> (0x80FD0106000A120600000001) Jan 6 08:39:28: Vi2.1 IPCP: I CONFREQ
> [REQsent] id 7 len 34
> Jan 6 08:39:28: Vi2.1 IPCP: Address 0.0.0.0 (0x030600000000)
> Jan 6 08:39:28: Vi2.1 IPCP: PrimaryDNS 0.0.0.0 (0x810600000000)
> Jan 6 08:39:28: Vi2.1 IPCP: PrimaryWINS 0.0.0.0 (0x820600000000)
> Jan 6 08:39:28: Vi2.1 IPCP: SecondaryDNS 0.0.0.0 (0x830600000000)
> Jan 6 08:39:28: Vi2.1 IPCP: SecondaryWINS 0.0.0.0 (0x840600000000)
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: Start. Her address 0.0.0.0,
> we want 0.0.0.0
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: Processing AV routing
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: Set routing to FALSE
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: Processing AV outacl
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: Processing AV addr
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: Processing AV netmask
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: Authorization succeeded
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: Done. Her address 0.0.0.0,
> we want 212.18.36.160
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: no author-info for primary dns
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: no author-info for primary
> wins
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: no author-info for seconday
> dns
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: no author-info for seconday
> wins
> Jan 6 08:39:28: Vi2.1 IPCP: O CONFREJ [REQsent] id 7 len 16
> Jan 6 08:39:28: Vi2.1 IPCP: PrimaryWINS 0.0.0.0 (0x820600000000)
> Jan 6 08:39:28: Vi2.1 IPCP: SecondaryWINS 0.0.0.0 (0x840600000000)
> Jan 6 08:39:28: Vi2.1 IPCP: I CONFACK [REQsent] id 1 len 10
> Jan 6 08:39:28: Vi2.1 IPCP: Address 212.18.38.1 (0x0306D4122601)
> Jan 6 08:39:28: Vi2.1 IPCP: I CONFREQ [ACKrcvd] id 8 len 22
> Jan 6 08:39:28: Vi2.1 IPCP: Address 0.0.0.0 (0x030600000000)
> Jan 6 08:39:28: Vi2.1 IPCP: PrimaryDNS 0.0.0.0 (0x810600000000)
> Jan 6 08:39:28: Vi2.1 IPCP: SecondaryDNS 0.0.0.0 (0x830600000000)
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: no author-info for primary dns
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: no author-info for seconday
> dns
> Jan 6 08:39:28: Vi2.1 IPCP: O CONFNAK [ACKrcvd] id 8 len 22
> Jan 6 08:39:28: Vi2.1 IPCP: Address 212.18.36.160 (0x0306D41224A0)
> Jan 6 08:39:28: Vi2.1 IPCP: PrimaryDNS 212.18.32.10
> (0x8106D412200A)
> Jan 6 08:39:28: Vi2.1 IPCP: SecondaryDNS 212.18.32.12
> (0x8306D412200C)
> Jan 6 08:39:28: Vi2.1 IPCP: I CONFREQ [ACKrcvd] id 9 len 22
> Jan 6 08:39:28: Vi2.1 IPCP: Address 212.18.36.160 (0x0306D41224A0)
> Jan 6 08:39:28: Vi2.1 IPCP: PrimaryDNS 212.18.32.10
> (0x8106D412200A)
> Jan 6 08:39:28: Vi2.1 IPCP: SecondaryDNS 212.18.32.12
> (0x8306D412200C)
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: no author-info for primary dns
> Jan 6 08:39:28: Vi2.1 AAA/AUTHOR/IPCP: no author-info for seconday
> dns
> Jan 6 08:39:28: Vi2.1 IPCP: O CONFACK [ACKrcvd] id 9 len 22
> Jan 6 08:39:28: Vi2.1 IPCP: Address 212.18.36.160 (0x0306D41224A0)
> Jan 6 08:39:28: Vi2.1 IPCP: PrimaryDNS 212.18.32.10
> (0x8106D412200A)
> Jan 6 08:39:28: Vi2.1 IPCP: SecondaryDNS 212.18.32.12
> (0x8306D412200C)
> Jan 6 08:39:28: Vi2.1 IPCP: State is Open
> Jan 6 08:39:28: AAA/AUTHOR: Processing PerUser AV outacl
> Jan 6 08:39:28: Vi2.1 IPCP: O TERMREQ [Open] id 2 len 4
> Jan 6 08:39:28: Vi2.1 IPCP: I TERMACK [TERMsent] id 2 len 4
> Jan 6 08:39:28: Vi2.1 IPCP: State is Closed
> Jan 6 08:39:28: Vi2.1 LCP: O TERMREQ [Open] id 2 len 4
> Jan 6 08:39:28: Vi2.1 PPP: Phase is TERMINATING
> Jan 6 08:39:28: Vi2.1 PPP: Block vaccess from being freed [0x18]
> Jan 6 08:39:28: Vi2.1 PPP: Sending Acct Event[Down] id[FB]
> Jan 6 08:39:28: Vi2.1 LCP: State is Closed
> Jan 6 08:39:28: Vi2.1 PPP: Phase is DOWN
> Jan 6 08:39:28: Vi2.1 PPP: Unlocked by [0x10] Still Locked by [0x8]
> Jan 6 08:39:28: Vi2.1 PPP: Unlocked by [0x8] Still Locked by [0x0]
> Jan 6 08:39:28: Vi2.1 PPP: Free previously blocked vaccess
>
>
>
> What puzzles me is this part:
>
> Jan 6 08:39:28: Vi2.1 IPCP: O CONFACK [ACKrcvd] id 9 len 22
> Jan 6 08:39:28: Vi2.1 IPCP: Address 212.18.36.160 (0x0306D41224A0)
> Jan 6 08:39:28: Vi2.1 IPCP: PrimaryDNS 212.18.32.10
> (0x8106D412200A)
> Jan 6 08:39:28: Vi2.1 IPCP: SecondaryDNS 212.18.32.12
> (0x8306D412200C)
> Jan 6 08:39:28: Vi2.1 IPCP: State is Open
> Jan 6 08:39:28: AAA/AUTHOR: Processing PerUser AV outacl
> Jan 6 08:39:28: Vi2.1 IPCP: O TERMREQ [Open] id 2 len 4
> Jan 6 08:39:28: Vi2.1 IPCP: I TERMACK [TERMsent] id 2 len 4
>
> Basically, we confirm to the client his IP address and the DNS
> servers and
> confirm that "IPCP State is Open". But, next we simply drop the
> connection
> with "O TERMREQ". Why? There is simply no reason why. Nothing failed
> in the
> negotiation, there are no errors, everything seems fine.
>
> Then I change my configuration like this:
>
> interface Virtual-Template1
> peer default ip address pool test
> no ppp authorization adsl
>
> ip local pool test 212.18.36.160 212.18.36.160
>
> So, basically instead of assigning the IP through radius, I assign it
> from a
> local pool. With this config, the connection comes up just fine.
>
> Cisco 7206 VXR running 12.3(12) IP Plus.
>
> I've turned all the debugging I could, but found no indication on why
> the
> Cisco terminates the PPP session after all PPP phases came up
> successfully.
>
> Any ideas?
> _______________________________________________
> 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