cancel
Showing results for 
Search instead for 
Did you mean: 
cancel
2781
Views
15
Helpful
8
Replies
davidfield
Participant

881 PPPOE and Authentication

Hello All,

I have a strange one and can't seem to source the problem.

Summary of setup   Internal Network --------Cisco 881-(PPPOE)------------------------(CHAP)---ISP Mikrotik Router  -----------internet

Basically it was working then there was a power outage and now it wont authenticate against the Mikrotik router.   Strange thing is CHAP seams happy with the username and password. Then just terminates the connection.

I've also tried PAP but not joy.  Nothing appears to have changed. I have access to the Mikrotik and it looks the same as before also.

Any pointers on where I should look?

Dave

interface Dialer1

description Internet

bandwidth 7500

ip address negotiated

no ip redirects

no ip unreachables

no ip proxy-arp

ip flow ingress

ip nat outside

ip inspect CCP_LOW out

ip virtual-reassembly

encapsulation ppp

dialer pool 1

dialer-group 1

ppp authentication chap pap callin

ppp chap hostname philip

ppp chap password 0 philip

ppp pap sent-username philip password 0 philip

ppp ipcp dns request

ppp ipcp address accept

Debug

Mar  6 10:20:35.001: Vi2 PPP: Phase is AUTHENTICATING, by the peer

Mar  6 10:20:35.001: Vi2 LCP: State is Open

Mar  6 10:20:35.009: Vi2 CHAP: I CHALLENGE id 1 len 21

Mar  6 10:20:35.009: Vi2 CHAP: No name received from peer

Mar  6 10:20:35.009: Vi2 CHAP: Using hostname from interface CHAP

Mar  6 10:20:35.013: Vi2 CHAP: Using password from interface CHAP

Mar  6 10:20:35.013: Vi2 CHAP: O RESPONSE id 1 len 27 from "philip"

Mar  6 10:20:35.021: Vi2 CHAP: I SUCCESS id 1 len 12 msg is "Welcome."

Mar  6 10:20:35.021: Vi2 PPP: Phase is FORWARDING, Attempting Forward

Mar  6 10:20:35.021: Vi2 PPP: Queue IPCP code[1] id[1]

Mar  6 10:20:35.021: Vi2 PPP: Queue TAGCP code[1] id[1]

Mar  6 10:20:35.025: Vi2 PPP DISC: Lower Layer disconnected

Mar  6 10:20:35.025: Vi2 LCP: O TERMREQ [Open] id 2 len 4

Mar  6 10:20:35.025: Vi2 LCP: Event[CLOSE] State[Open to Closing]

Mar  6 10:20:35.025: Vi2 PPP: Phase is TERMINATING

Mar  6 10:20:35.025: %DIALER-6-UNBIND: Interface Vi2 unbound from profile Di1

Mar  6 10:20:35.029: Vi2 PPP: Block vaccess from being freed [0x10]

Mar  6 10:20:35.029: Vi2 LCP: Event[DOWN] State[Closing to Initial]

Mar  6 10:20:35.029: Vi2 PPP: Unlocked by [0x10] Still Locked by [0x0]

Mar  6 10:20:35.029: Vi2 PPP: Free previously blocked vaccess

Mar  6 10:20:35.029: Vi2 PPP: Phase is DOWN

Mar  6 10:20:35.029: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to down

Mar  6 10:20:35.001: Vi2 PPP: Phase is AUTHENTICATING, by the peer

Mar  6 10:20:35.001: Vi2 LCP: State is Open

Mar  6 10:20:35.009: Vi2 CHAP: I CHALLENGE id 1 len 21

Mar  6 10:20:35.009: Vi2 CHAP: No name received from peer

Mar  6 10:20:35.009: Vi2 CHAP: Using hostname from interface CHAP

Mar  6 10:20:35.013: Vi2 CHAP: Using password from interface CHAP

Mar  6 10:20:35.013: Vi2 CHAP: O RESPONSE id 1 len 27 from "philip"

Mar  6 10:20:35.021: Vi2 CHAP: I SUCCESS id 1 len 12 msg is "Welcome."

Mar  6 10:20:35.021: Vi2 PPP: Phase is FORWARDING, Attempting Forward

Mar  6 10:20:35.021: Vi2 PPP: Queue IPCP code[1] id[1]

Mar  6 10:20:35.021: Vi2 PPP: Queue TAGCP code[1] id[1]

Mar  6 10:20:35.025: Vi2 PPP DISC: Lower Layer disconnected

Mar  6 10:20:35.025: Vi2 LCP: O TERMREQ [Open] id 2 len 4

Mar  6 10:20:35.025: Vi2 LCP: Event[CLOSE] State[Open to Closing]

Mar  6 10:20:35.025: Vi2 PPP: Phase is TERMINATING

Mar  6 10:20:35.025: %DIALER-6-UNBIND: Interface Vi2 unbound from profile Di1

Mar  6 10:20:35.029: Vi2 PPP: Block vaccess from being freed [0x10]

Mar  6 10:20:35.029: Vi2 LCP: Event[DOWN] State[Closing to Initial]

Mar  6 10:20:35.029: Vi2 PPP: Unlocked by [0x10] Still Locked by [0x0]

Mar  6 10:20:35.029: Vi2 PPP: Free previously blocked vaccess

Mar  6 10:20:35.029: Vi2 PPP: Phase is DOWN

Mar  6 10:20:35.029: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to down

8 REPLIES 8
Peter Paluch
Hall of Fame Cisco Employee

Hello Dave,

Thanks for adding the debug and configuration to your post - it helped quite a lot.

While I do not have a definitive answer, I am focusing on the following segment of the debug:

Mar  6 10:20:35.025: Vi2 PPP DISC: Lower Layer disconnected

Mar  6 10:20:35.025: Vi2 LCP: O TERMREQ [Open] id 2 len 4

Mar  6 10:20:35.025: Vi2 LCP: Event[CLOSE] State[Open to Closing]

Mar  6 10:20:35.025: Vi2 PPP: Phase is TERMINATING

Mar  6 10:20:35.025: %DIALER-6-UNBIND: Interface Vi2 unbound from profile Di1

It says that the lower layer is disconnecting. That would mean that the PPPoE session is being terminated for whatever reason. Can you issue the debug pppoe event and debug pppoe error and debug pppoe packet and post the entire result here?

Thank you!

Best regards,

Peter

Hi Peter,


Thansk for assisting.

I have the following Debug enabled

PPP:

PPP authentication debugging is on

PPP protocol negotiation debugging is on

PPPoE:

PPPoE protocol events debugging is on

PPPoE control packets debugging is on

PPPoE protocol errors debugging is on

Debug results

*Mar  1 04:32:42.486:  Sending PADI: Interface = Vlan1

*Mar  1 04:32:42.486: pppoe_send_padi:

contiguous pak, size 60

FF FF FF FF FF FF 00 23 5E 8C A9 C4 88 63 11 09

00 00 00 10 01 01 00 00 01 03 00 08 92 00 00 01

00 00 1D 31 00 00 00 00 00 00 00 00 00 00 00 00

00 00 00 00 00 00 00 00 00 00 00 00

*Mar  1 04:32:42.486: PPPoE 0: I PADO  R:000c.42e2.9c81 L:0023.5e8c.a9c4 Vl1

contiguous pak, size 88

00 23 5E 8C A9 C4 00 0C 42 E2 9C 81 88 63 11 07

00 00 00 44 01 03 00 08 92 00 00 01 00 00 1D 31

01 01 00 00 01 02 00 20 50 68 69 6C 69 70 20 52

65 79 6E 6F 6C 64 73 20 2D 20 43 6C 6F 6E 68 75

67 68 20 48 6F 75 73 65 ...

*Mar  1 04:32:44.534:  PPPOE: we've got our pado and the pado timer went off

*Mar  1 04:32:44.534: OUT PADR from PPPoE Session

contiguous pak, size 88

00 0C 42 E2 9C 81 00 23 5E 8C A9 C4 88 63 11 19

00 00 00 44 01 03 00 08 92 00 00 01 00 00 1D 31

01 01 00 00 01 02 00 20 50 68 69 6C 69 70 20 52

65 79 6E 6F 6C 64 73 20 2D 20 43 6C 6F 6E 68 75

67 68 20 48 6F 75 73 65 ...

*Mar  1 04:32:44.534: PPPoE 121: I PADS  R:000c.42e2.9c81 L:0023.5e8c.a9c4 Vl1

contiguous pak, size 60

00 23 5E 8C A9 C4 00 0C 42 E2 9C 81 88 63 11 65

00 79 00 10 01 03 00 08 92 00 00 01 00 00 1D 31

01 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00

00 00 00 00 00 00 00 00 00 00 00 00

*Mar  1 04:32:44.538: IN PADS from PPPoE Session

*Mar  1 04:32:44.538: %DIALER-6-BIND: Interface Vi2 bound to profile Di1

*Mar  1 04:32:44.538: PPPoE: Virtual Access interface obtained.

*Mar  1 04:32:44.538: PPPoE : encap string prepared

*Mar  1 04:32:44.538: [0]PPPoE 121: data path set to PPPoE Client

*Mar  1 04:32:44.550: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to up

*Mar  1 04:32:44.554: Vi2 PPP: Sending cstate UP notification

*Mar  1 04:32:44.554: Vi2 PPP: Processing CstateUp message

*Mar  1 04:32:44.558: PPP: Alloc Context [8468D328]

*Mar  1 04:32:44.558: ppp423 PPP: Phase is ESTABLISHING

*Mar  1 04:32:44.558: Vi2 PPP: Using dialer call direction

*Mar  1 04:32:44.558: Vi2 PPP: Treating connection as a callout

*Mar  1 04:32:44.558: Vi2 PPP: Session handle[C6000027] Session id[423]

*Mar  1 04:32:44.558: Vi2 LCP: Event[OPEN] State[Initial to Starting]

*Mar  1 04:32:44.558: Vi2 PPP: No remote authentication for call-out

*Mar  1 04:32:44.558: Vi2 LCP: O CONFREQ [Starting] id 1 len 10

*Mar  1 04:32:44.558: Vi2 LCP:    MagicNumber 0x242F6A92 (0x0506242F6A92)

*Mar  1 04:32:44.558: Vi2 LCP: Event[UP] State[Starting to REQsent]

*Mar  1 04:32:44.562: Vi2 LCP: I CONFREQ [REQsent] id 1 len 19

*Mar  1 04:32:44.562: Vi2 LCP:    AuthProto CHAP (0x0305C22305)

*Mar  1 04:32:44.562: Vi2 LCP:    MRU 1480 (0x010405C8)

*Mar  1 04:32:44.562: Vi2 LCP:    MagicNumber 0x6EE96069 (0x05066EE96069)

*Mar  1 04:32:44.562: Vi2 LCP: O CONFNAK [REQsent] id 1 len 8

*Mar  1 04:32:44.562: Vi2 LCP:    MRU 1500 (0x010405DC)

*Mar  1 04:32:44.562: Vi2 LCP: Event[Receive ConfReq-] State[REQsent to REQsent]

*Mar  1 04:32:44.562: Vi2 LCP: I CONFACK [REQsent] id 1 len 10

*Mar  1 04:32:44.562: Vi2 LCP:    MagicNumber 0x242F6A92 (0x0506242F6A92)

*Mar  1 04:32:44.562: Vi2 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]

*Mar  1 04:32:44.562: Vi2 LCP: I CONFREQ [ACKrcvd] id 2 len 15

*Mar  1 04:32:44.562: Vi2 LCP:    AuthProto CHAP (0x0305C22305)

*Mar  1 04:32:44.562: Vi2 LCP:    MagicNumber 0x6EE96069 (0x05066EE96069)

*Mar  1 04:32:44.562: Vi2 LCP: O CONFACK [ACKrcvd] id 2 len 15

*Mar  1 04:32:44.562: Vi2 LCP:    AuthProto CHAP (0x0305C22305)

*Mar  1 04:32:44.562: Vi2 LCP:    MagicNumber 0x6EE96069 (0x05066EE96069)

*Mar  1 04:32:44.562: Vi2 LCP: Event[Receive ConfReq+] State[ACKrcvd to Open]

*Mar  1 04:32:44.566: Vi2 PPP: Queue CHAP code[1] id[1]

*Mar  1 04:32:44.582: Vi2 PPP: No authorization without authentication

*Mar  1 04:32:44.582: Vi2 PPP: Phase is AUTHENTICATING, by the peer

*Mar  1 04:32:44.582: Vi2 CHAP: Redirect packet to Vi2

*Mar  1 04:32:44.582: Vi2 CHAP: I CHALLENGE id 1 len 21

*Mar  1 04:32:44.582: Vi2 CHAP: No name received from peer

*Mar  1 04:32:44.582: Vi2 CHAP: Using hostname from interface CHAP

*Mar  1 04:32:44.582: Vi2 CHAP: Using password from interface CHAP

*Mar  1 04:32:44.582: Vi2 CHAP: O RESPONSE id 1 len 27 from "philip"

*Mar  1 04:32:44.582: Vi2 LCP: State is Open

*Mar  1 04:32:44.594: Vi2 CHAP: I SUCCESS id 1 len 12 msg is "Welcome."

*Mar  1 04:32:44.594: Vi2 PPP: Phase is FORWARDING, Attempting Forward

*Mar  1 04:32:44.594: Vi2 PPP: Queue IPCP code[1] id[1]

*Mar  1 04:32:44.594: Vi2 PPP: Queue TAGCP code[1] id[1]

*Mar  1 04:32:44.598: Vi2 PPP DISC: Lower Layer disconnected

*Mar  1 04:32:44.598: Vi2 LCP: O TERMREQ [Open] id 2 len 4

*Mar  1 04:32:44.598: Vi2 LCP: Event[CLOSE] State[Open to Closing]

Hi,

Looks like IPCP layer failure from debugs. Please trun on debug ip peer. To look further.

Hope it will help.

Best regards,
Abzal

Best regards,
Abzal

Thank you for your help Peter and Abzal,

After many hours trying to source the problem I decided to apply a later firmware and it all came back to life.  Very strange as it has been runnign for a year no problem.  Then power outage and the PPPOE chap authentication starts failing on reboot. I can only assume something got corrupted during a memory write when the router went offline.

All good now and I my stress levels are going back to normal.

Thanks again

David

Peter Paluch
Hall of Fame Cisco Employee

Hello David and Abzal,

David, I am glad you got it working although the solution was quite radical But who knows what happened to the device (by the way, did you upgrade the Cisco router or the Mikrotik?)

Abzal, I do not believe that the problem could be related to IPCP. In fact, after LCP came up, there is absolutely no notion of the IPCP in the debugs, meaning it could not have failed.

Best regards,

Peter

Hi Peter,  Upgraded the Cisco.  A bit brute force to resolve but did the trick.

Regards

David

Sorry for opening again this old thread.

I got the same problem with a Cisco 809r.

this is stripped configuration

interface GigabitEthernet0
ip address dhcp
duplex auto
speed auto
pppoe enable group global
pppoe-client dial-pool-number 1

interface Dialer1
description DSL Einwahl Interface
ip address negotiated
no ip redirects
no ip unreachables
no ip proxy-arp
ip mtu 1492
ip nat outside
ip virtual-reassembly in
encapsulation ppp
dialer pool 1
dialer-group 1
no keepalive
ppp authentication pap callin
ppp pap sent-username xxxx password 0 xxxx
ppp ipcp dns request
ppp ipcp mask request
ppp ipcp route default
no cdp enable

dialer-list 1 protocol ip permit

This should work or is something wrong

The Information from the Provider using PAP was wrong...he is doing Chap...