03-06-2013 03:10 AM - edited 03-04-2019 07:12 PM
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
03-06-2013 03:59 AM
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
03-06-2013 06:13 AM
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]
03-06-2013 10:54 AM
Hi,
Looks like IPCP layer failure from debugs. Please trun on debug ip peer. To look further.
Hope it will help.
Best regards,
Abzal
03-06-2013 11:35 AM
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
03-06-2013 03:07 PM
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
03-07-2013 02:31 AM
Hi Peter, Upgraded the Cisco. A bit brute force to resolve but did the trick.
Regards
David
08-09-2016 05:14 AM
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
08-23-2016 11:00 PM
The Information from the Provider using PAP was wrong...he is doing Chap...
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