 | Start a set with this search |
 | Include this search in one of my sets |
 | Exclude this search from one of my sets |
 | Permalink to these results Paste this link in email or IM: |
 | Atom feed for tracking future search results Paste this URL into your reader: |
3 messages in net.nether.puck.cisco-nsp[c-nsp] PPPoE negotiation trouble on ...| From | Sent On | Attachments |
|---|---|---|
| Blaz Zupan | Jan 6, 2005 4:40 am | |
| Oliver Boehmer (oboehmer) | Jan 6, 2005 4:55 am | |
| Blaz Zupan | Jan 6, 2005 5:45 am |
| Permalink for this message Paste this link in email or IM: |
| Permalink for this thread Paste this link in email or IM: |
| Atom feed for this thread Paste this URL into your reader: |
| Subject: | [c-nsp] PPPoE negotiation trouble on 12.3(12) | Actions... |
|---|---|---|
| From: | Blaz Zupan (bl...@inlimbo.org) | |
| Date: | Jan 6, 2005 4:40:52 am | |
| List: | net.nether.puck.cisco-nsp | |
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?