[c-nsp] PPPoE negotiation trouble on 12.3(12)
Blaz Zupan
blaz at inlimbo.org
Thu Jan 6 04:41:07 EST 2005
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?
More information about the cisco-nsp
mailing list