02-18-2003 01:41 PM - edited 03-02-2019 05:11 AM
Following is a debug of an PPPoe PAP authentication attempt between a Cisco 2610 connected to a ADSL modem. When attempting to logon using PAP the message dated "*Feb 28 22:55:09.474" where "choice:" is being send back to the router appears to be causing an authentication problem. The ISP hasn't a clue. Any ideas.
Thanks
Lars
*Feb 28 22:55:08.043: %DIALER-6-BIND: Interface Vi1 bound to profile Di1
*Feb 28 22:55:08.047: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state t
o up
*Feb 28 22:55:08.063: Vi1 PPP: Treating connection as a callout
*Feb 28 22:55:08.063: Vi1 PPP: Phase is ESTABLISHING, Active Open [0 sess, 0 loa
d]
*Feb 28 22:55:08.067: Vi1 PPP: No remote authentication for call-out
*Feb 28 22:55:08.067: Vi1 LCP: O CONFREQ [Closed] id 1 len 10
*Feb 28 22:55:08.067: Vi1 LCP: MagicNumber 0x05CE8AB4 (0x050605CE8AB4)
*Feb 28 22:55:08.091: Vi1 LCP: I CONFREQ [REQsent] id 112 len 18
*Feb 28 22:55:08.091: Vi1 LCP: MRU 1492 (0x010405D4)
*Feb 28 22:55:08.091: Vi1 LCP: AuthProto PAP (0x0304C023)
*Feb 28 22:55:08.091: Vi1 LCP: MagicNumber 0x08250D35 (0x050608250D35)
*Feb 28 22:55:08.095: Vi1 LCP: O CONFNAK [REQsent] id 112 len 8
*Feb 28 22:55:08.095: Vi1 LCP: MRU 1500 (0x010405DC)
*Feb 28 22:55:08.095: Vi1 LCP: I CONFACK [REQsent] id 1 len 10
*Feb 28 22:55:08.095: Vi1 LCP: MagicNumber 0x05CE8AB4 (0x050605CE8AB4)
*Feb 28 22:55:08.123: Vi1 LCP: I CONFREQ [ACKrcvd] id 113 len 18
*Feb 28 22:55:08.123: Vi1 LCP: MRU 1492 (0x010405D4)
*Feb 28 22:55:08.123: Vi1 LCP: AuthProto PAP (0x0304C023)
*Feb 28 22:55:08.127: Vi1 LCP: MagicNumber 0x08250D35 (0x050608250D35)
*Feb 28 22:55:08.127: Vi1 LCP: O CONFNAK [ACKrcvd] id 113 len 8
*Feb 28 22:55:08.127: Vi1 LCP: MRU 1500 (0x010405DC)
*Feb 28 22:55:08.139: Vi1 LCP: I CONFREQ [ACKrcvd] id 114 len 18
*Feb 28 22:55:08.139: Vi1 LCP: MRU 1492 (0x010405D4)
*Feb 28 22:55:08.139: Vi1 LCP: AuthProto PAP (0x0304C023)
*Feb 28 22:55:08.143: Vi1 LCP: MagicNumber 0x08250D35 (0x050608250D35)
*Feb 28 22:55:08.143: Vi1 LCP: O CONFNAK [ACKrcvd] id 114 len 8
*Feb 28 22:55:08.143: Vi1 LCP: MRU 1500 (0x010405DC)
*Feb 28 22:55:08.155: Vi1 LCP: I CONFREQ [ACKrcvd] id 115 len 18
*Feb 28 22:55:08.155: Vi1 LCP: MRU 1492 (0x010405D4)
*Feb 28 22:55:08.159: Vi1 LCP: AuthProto PAP (0x0304C023)
*Feb 28 22:55:08.159: Vi1 LCP: MagicNumber 0x08250D35 (0x050608250D35)
*Feb 28 22:55:08.159: Vi1 LCP: O CONFNAK [ACKrcvd] id 115 len 8
*Feb 28 22:55:08.159: Vi1 LCP: MRU 1500 (0x010405DC)
*Feb 28 22:55:08.171: Vi1 LCP: I CONFREQ [ACKrcvd] id 116 len 18
*Feb 28 22:55:08.175: Vi1 LCP: MRU 1492 (0x010405D4)
*Feb 28 22:55:08.175: Vi1 LCP: AuthProto PAP (0x0304C023)
*Feb 28 22:55:08.175: Vi1 LCP: MagicNumber 0x08250D35 (0x050608250D35)
*Feb 28 22:55:08.175: Vi1 LCP: O CONFNAK [ACKrcvd] id 116 len 8
*Feb 28 22:55:08.175: Vi1 LCP: MRU 1500 (0x010405DC)
*Feb 28 22:55:08.191: Vi1 LCP: I CONFREQ [ACKrcvd] id 117 len 18
*Feb 28 22:55:08.191: Vi1 LCP: MRU 1492 (0x010405D4)
*Feb 28 22:55:08.191: Vi1 LCP: AuthProto PAP (0x0304C023)
*Feb 28 22:55:08.191: Vi1 LCP: MagicNumber 0x08250D35 (0x050608250D35)
*Feb 28 22:55:08.191: Vi1 LCP: O CONFREJ [ACKrcvd] id 117 len 8
*Feb 28 22:55:08.191: Vi1 LCP: MRU 1492 (0x010405D4)
*Feb 28 22:55:08.223: Vi1 LCP: I CONFREQ [ACKrcvd] id 118 len 14
*Feb 28 22:55:08.223: Vi1 LCP: AuthProto PAP (0x0304C023)
*Feb 28 22:55:08.223: Vi1 LCP: MagicNumber 0x08250D35 (0x050608250D35)
*Feb 28 22:55:08.223: Vi1 LCP: O CONFACK [ACKrcvd] id 118 len 14
*Feb 28 22:55:08.227: Vi1 LCP: AuthProto PAP (0x0304C023)
*Feb 28 22:55:08.227: Vi1 LCP: MagicNumber 0x08250D35 (0x050608250D35)
*Feb 28 22:55:08.227: Vi1 LCP: State is Open
*Feb 28 22:55:08.227: Vi1 PPP: Phase is AUTHENTICATING, by the peer [0 sess, 0 l
oad]
*Feb 28 22:55:08.231: Vi1 PAP: O AUTH-REQ id 20 len 22 from "aq15a6"
*Feb 28 22:55:09.474: Vi1 PAP: I AUTH-ACK id 20 len 13 msg is "choice: "
*Feb 28 22:55:09.474: Vi1 PPP: Phase is UP [0 sess, 0 load]
*Feb 28 22:55:09.474: Vi1 IPCP: O CONFREQ [Closed] id 1 len 10
*Feb 28 22:55:09.478: Vi1 IPCP: Address 0.0.0.0 (0x030600000000)
*Feb 28 22:55:09.478: Vi1 LCP: I TERMREQ [Open] id 119 len 4
*Feb 28 22:55:09.478: Vi1 LCP: O TERMACK [Open] id 119 len 4
*Feb 28 22:55:10.475: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Ac
cess1, changed state to up
*Feb 28 22:55:11.473: Vi1 IPCP: TIMEout: State REQsent
*Feb 28 22:55:11.473: Vi1 IPCP: O CONFREQ [REQsent] id 2 len 10
*Feb 28 22:55:11.473: Vi1 IPCP: Address 0.0.0.0 (0x030600000000)
*Feb 28 22:55:11.477: Vi1 LCP: TIMEout: State TERMsent
*Feb 28 22:55:11.477: Vi1 LCP: State is Closed
*Feb 28 22:55:11.477: Vi1 IPCP: State is Closed
*Feb 28 22:55:11.477: Vi1 PPP: Phase is DOWN [0 sess, 0 load]
*Feb 28 22:55:11.477: %DIALER-6-UNBIND: Interface Vi1 unbound from profile Di1
*Feb 28 22:55:11.481: Vi1 PPP: Phase is ESTABLISHING, Passive Open [0 sess, 0 lo
ad]
*Feb 28 22:55:11.481: Vi1 PPP: No remote authentication for call-out
*Feb 28 22:55:11.481: Vi1 LCP: State is Listen
*Feb 28 22:55:11.573: Vi1 LCP: State is Closed
*Feb 28 22:55:11.577: Vi1 PPP: Phase is DOWN [0 sess, 0 load]
*Feb 28 22:55:12.478: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access1, changed state to down
02-18-2003 01:54 PM
Feb 28 22:55:08.227: Vi1 LCP: State is Open
*Feb 28 22:55:08.227: Vi1 PPP: Phase is AUTHENTICATING, by the peer [0 sess, 0 load]
*Feb 28 22:55:08.231: Vi1 PAP: O AUTH-REQ id 20 len 22 from "aq15a6"
*Feb 28 22:55:09.474: Vi1 PAP: I AUTH-ACK id 20 len 13 msg is "choice: "
*Feb 28 22:55:09.474: Vi1 PPP: Phase is UP [0 sess, 0 load]
*Feb 28 22:55:09.474: Vi1 IPCP: O CONFREQ [Closed] id 1 len 10
*Feb 28 22:55:09.478: Vi1 IPCP: Address 0.0.0.0 (0x030600000000)<===
*Feb 28 22:55:09.478: Vi1 LCP: I TERMREQ [Open] id 119 len 4 <====
The problem seems to be during IPCP on the aggregation router, we request an IP address from the ISP (send out 0.0.0.0) but immediately get back an Termination request (TERMREQ).
Thanks, Mak.
02-18-2003 02:24 PM
Mak,
Thanks for you response. The reason I was using dhcp instead of the static address we requested was that the subnet mask they claim I need to use is 255.255.255.255 but the router won't accept it. So I thought I would tackle the auth problem first then the mask problem. The interesting thing is that a Linksys BEFSR11 will get an address ok but the 2610 fails. As soon as I brought this up with the ISP they said then it not our problem. If I could find a way determining the mask if it in fact is not 255.255.255.255 then I could go the static route since it appears that the auth is working.
Thanks
Lars
02-18-2003 02:51 PM
In IPCP negotation we do not negotiate the address subnet mask....I am not very clear with what the ISP is telling you, can you try out the following:
conf term
interface loopback10
ip address x.x.x.x 255.255.255.255 (where x.x.x.x is the static IP address given by the ISP)
int dialer 1
ip unnumbered loopback10
Capture debug ppp nego with these commands added.
Thanks, Mak.
02-18-2003 03:49 PM
Mak,
Here is the debug and the relevant parts of the config.
Thanks
Lars
interface Loopback10
ip address 66.112.64.166 255.255.255.255
interface Ethernet0/1
no ip address
ip nat outside
no ip route-cache
no ip mroute-cache
shutdown
half-duplex
pppoe enable
pppoe-client dial-pool-number 1
no cdp enable
interface Dialer1
ip unnumbered Loopback10
ip mtu 1492
ip nat outside
encapsulation ppp
no ip mroute-cache
dialer pool 1
dialer-group 1
no cdp enable
ppp pap sent-username xzy09875 password 7 065E0a73441d0F0107
*Feb 28 18:15:56.507: %LINK-3-UPDOWN: Interface Ethernet0/1, changed state to up
*Feb 28 18:15:57.508: %LINEPROTO-5-UPDOWN: Line protocol on Interface Ethernet0/
1, changed state to up
*Feb 28 18:16:05.369: Vi1 PPP: Phase is DOWN, Setup [0 sess, 0 load]
*Feb 28 18:16:05.373: %DIALER-6-BIND: Interface Vi1 bound to profile Di1
*Feb 28 18:16:05.377: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state t
o up
*Feb 28 18:16:05.393: Vi1 PPP: Treating connection as a callout
*Feb 28 18:16:05.397: Vi1 PPP: Phase is ESTABLISHING, Active Open [0 sess, 0 loa
d]
*Feb 28 18:16:05.397: Vi1 PPP: No remote authentication for call-out
*Feb 28 18:16:05.397: Vi1 LCP: O CONFREQ [Closed] id 1 len 10
*Feb 28 18:16:05.397: Vi1 LCP: MagicNumber 0x04CF1187 (0x050604CF1187)
*Feb 28 18:16:05.421: Vi1 LCP: I CONFREQ [REQsent] id 158 len 18
*Feb 28 18:16:05.421: Vi1 LCP: MRU 1492 (0x010405D4)
*Feb 28 18:16:05.421: Vi1 LCP: AuthProto PAP (0x0304C023)
*Feb 28 18:16:05.421: Vi1 LCP: MagicNumber 0x083046E2 (0x0506083046E2)
*Feb 28 18:16:05.421: Vi1 LCP: O CONFNAK [REQsent] id 158 len 8
*Feb 28 18:16:05.425: Vi1 LCP: MRU 1500 (0x010405DC)
*Feb 28 18:16:05.425: Vi1 LCP: I CONFACK [REQsent] id 1 len 10
*Feb 28 18:16:05.425: Vi1 LCP: MagicNumber 0x04CF1187 (0x050604CF1187)
*Feb 28 18:16:05.437: Vi1 LCP: I CONFREQ [ACKrcvd] id 159 len 18
*Feb 28 18:16:05.437: Vi1 LCP: MRU 1492 (0x010405D4)
*Feb 28 18:16:05.437: Vi1 LCP: AuthProto PAP (0x0304C023)
*Feb 28 18:16:05.437: Vi1 LCP: MagicNumber 0x083046E2 (0x0506083046E2)
*Feb 28 18:16:05.441: Vi1 LCP: O CONFNAK [ACKrcvd] id 159 len 8
*Feb 28 18:16:05.441: Vi1 LCP: MRU 1500 (0x010405DC)
*Feb 28 18:16:05.453: Vi1 LCP: I CONFREQ [ACKrcvd] id 160 len 18
*Feb 28 18:16:05.453: Vi1 LCP: MRU 1492 (0x010405D4)
*Feb 28 18:16:05.453: Vi1 LCP: AuthProto PAP (0x0304C023)
*Feb 28 18:16:05.453: Vi1 LCP: MagicNumber 0x083046E2 (0x0506083046E2)
*Feb 28 18:16:05.457: Vi1 LCP: O CONFNAK [ACKrcvd] id 160 len 8
*Feb 28 18:16:05.457: Vi1 LCP: MRU 1500 (0x010405DC)
*Feb 28 18:16:05.469: Vi1 LCP: I CONFREQ [ACKrcvd] id 161 len 18
*Feb 28 18:16:05.469: Vi1 LCP: MRU 1492 (0x010405D4)
*Feb 28 18:16:05.469: Vi1 LCP: AuthProto PAP (0x0304C023)
*Feb 28 18:16:05.473: Vi1 LCP: MagicNumber 0x083046E2 (0x0506083046E2)
*Feb 28 18:16:05.473: Vi1 LCP: O CONFNAK [ACKrcvd] id 161 len 8
*Feb 28 18:16:05.473: Vi1 LCP: MRU 1500 (0x010405DC)
*Feb 28 18:16:05.489: Vi1 LCP: I CONFREQ [ACKrcvd] id 162 len 18
*Feb 28 18:16:05.489: Vi1 LCP: MRU 1492 (0x010405D4)
*Feb 28 18:16:05.489: Vi1 LCP: AuthProto PAP (0x0304C023)
*Feb 28 18:16:05.489: Vi1 LCP: MagicNumber 0x083046E2 (0x0506083046E2)
*Feb 28 18:16:05.489: Vi1 LCP: O CONFNAK [ACKrcvd] id 162 len 8
*Feb 28 18:16:05.493: Vi1 LCP: MRU 1500 (0x010405DC)
*Feb 28 18:16:05.522: Vi1 LCP: I CONFREQ [ACKrcvd] id 163 len 18
*Feb 28 18:16:05.522: Vi1 LCP: MRU 1492 (0x010405D4)
*Feb 28 18:16:05.522: Vi1 LCP: AuthProto PAP (0x0304C023)
*Feb 28 18:16:05.522: Vi1 LCP: MagicNumber 0x083046E2 (0x0506083046E2)
*Feb 28 18:16:05.522: Vi1 LCP: O CONFREJ [ACKrcvd] id 163 len 8
*Feb 28 18:16:05.526: Vi1 LCP: MRU 1492 (0x010405D4)
*Feb 28 18:16:05.538: Vi1 LCP: I CONFREQ [ACKrcvd] id 164 len 14
*Feb 28 18:16:05.538: Vi1 LCP: AuthProto PAP (0x0304C023)
*Feb 28 18:16:05.538: Vi1 LCP: MagicNumber 0x083046E2 (0x0506083046E2)
*Feb 28 18:16:05.538: Vi1 LCP: O CONFACK [ACKrcvd] id 164 len 14
*Feb 28 18:16:05.538: Vi1 LCP: AuthProto PAP (0x0304C023)
*Feb 28 18:16:05.542: Vi1 LCP: MagicNumber 0x083046E2 (0x0506083046E2)
*Feb 28 18:16:05.542: Vi1 LCP: State is Open
*Feb 28 18:16:05.542: Vi1 PPP: Phase is AUTHENTICATING, by the peer [0 sess, 0 l
oad]
*Feb 28 18:16:05.542: Vi1 PAP: O AUTH-REQ id 5 len 22 from "ctr09875"
*Feb 28 18:16:06.788: Vi1 PAP: I AUTH-ACK id 5 len 13 msg is "choice: "
*Feb 28 18:16:06.788: Vi1 PPP: Phase is UP [0 sess, 0 load]
*Feb 28 18:16:06.788: Vi1 IPCP: O CONFREQ [Closed] id 1 len 10
*Feb 28 18:16:06.792: Vi1 IPCP: Address 66.112.64.166 (0x0306427040A6)
*Feb 28 18:16:06.792: Vi1 LCP: I TERMREQ [Open] id 165 len 4
*Feb 28 18:16:06.792: Vi1 LCP: O TERMACK [Open] id 165 len 4
*Feb 28 18:16:07.789: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Ac
cess1, changed state to up
*Feb 28 18:16:08.787: Vi1 IPCP: TIMEout: State REQsent
*Feb 28 18:16:08.787: Vi1 IPCP: O CONFREQ [REQsent] id 2 len 10
*Feb 28 18:16:08.787: Vi1 IPCP: Address 66.112.64.166 (0x0306427040A6)
*Feb 28 18:16:08.791: Vi1 LCP: TIMEout: State TERMsent
*Feb 28 18:16:08.791: Vi1 LCP: State is Closed
*Feb 28 18:16:08.791: Vi1 IPCP: State is Closed
*Feb 28 18:16:08.791: Vi1 PPP: Phase is DOWN [0 sess, 0 load]
*Feb 28 18:16:08.791: %DIALER-6-UNBIND: Interface Vi1 unbound from profile Di1
*Feb 28 18:16:08.795: Vi1 PPP: Phase is ESTABLISHING, Passive Open [0 sess, 0 lo
ad]
*Feb 28 18:16:08.795: Vi1 PPP: No remote authentication for call-out
*Feb 28 18:16:08.795: Vi1 LCP: State is Listen
*Feb 28 18:16:08.887: Vi1 LCP: State is Closed
*Feb 28 18:16:08.887: Vi1 PPP: Phase is DOWN [0 sess, 0 load]
*Feb 28 18:16:09.793: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Ac
cess1, changed state to down
02-18-2003 04:21 PM
We see the same point of failure here....if the ISP is looking for a static address, we are sending it but still get a TERMREQ from their end during IPCP phase.
Just curious, I see different username sent & configured under the dialer1.
Thanks, Mak.
02-18-2003 04:45 PM
Mak,
I just changed it for posting. I am still using the same username and password. I will try the ISP again tomorrow and see how far I get.
Thanks again
Lars
Discover and save your favorite ideas. Come back to expert answers, step-by-step guides, recent topics, and more.
New here? Get started with these tips. How to use Community New member guide