Solved: PPPOE MRU LCP negotiation failure.

abdalalhmohamed10 · ‎08-13-2013

I tray to enable pppoe on the cisco 1841 router but i'm facing lcp negotiation failure regarding MRU mismatch and the session terminated.

i tried to use the both "ppp mtu adaptive" and "ppp-max-payload" commands but it's not supported on the router image.

so i want any help to solve this problem.

the system image is : c1841-advsecurityk9-mz.124-15.T3.bin

the home dsl router is in bridge mode connected to the fa 0/0 of the router.

here is the ppp negotiation and authentication debug

*Aug 7 09:17:18.708: Vi2 LCP: Timeout: State REQsent

*Aug 7 09:17:18.708: Vi2 LCP: O CONFREQ [REQsent] id 2 len 10

*Aug 7 09:17:18.708: Vi2 LCP: MagicNumber 0x22F0FFE2 (0x050622F0FFE2)

*Aug 7 09:17:20.724: Vi2 LCP: Timeout: State REQ

Sawah#sent

*Aug 7 09:17:20.724: Vi2 LCP: O CONFREQ [REQsent] id 3 len 10

*Aug 7 09:17:20.724: Vi2 LCP: MagicNumber 0x22F0FFE2 (0x050622F0FFE2)

*Aug 7 09:17:22.216: Vi2 LCP: I CONFREQ [REQsent] id 1 len 18

*Aug 7 09:17:22.216: Vi2 LCP: MRU 1492 (0x010405D4)

*Aug 7 09:17:22.216: Vi2 LCP: AuthProto PAP (0x0304C023)

*Aug 7 09:17:22.216: Vi2 LCP: MagicNumber 0x1D5EFA59 (0x05061D5EFA59)

*Aug 7 09:17:22.220: Vi2 LCP: O CONFNAK [REQsent] id 1 len 8

*Aug 7 09:17:22.220: Vi2 LCP: MRU 1500 (0x010405DC)

*Aug 7 09:17:22.740: Vi2 LCP: Timeout: State REQsent

*Aug 7 09:17:22.740: Vi2 LCP: O CONFREQ [REQsent] id 4 len 10

*Aug 7 09:17:22.740: Vi2 LCP: MagicNumber 0x22F0FFE2 (0x050622F0FFE2)

*Aug 7 09:17:24.232: Vi2 LCP: I CONFREQ [REQsent] id 2 len 18

*Aug 7 09:17:24.232: Vi2 LCP: MRU 1492 (0x010405D4)

*Aug 7 09:17:24.232: Vi2 LCP: AuthProto PAP (0x0304C023)

*Aug 7 09:17:24.232: Vi2 LCP: MagicNumber 0x1D5EFA59 (0x05061D5EFA59)

*Aug 7 09:17:24.232: Vi2 LCP: O CONFNAK [REQsent] id 2 len 8

*Aug 7 09:17:24.236: Vi2 LCP:

Sawah#MRU 1500 (0x010405DC)

*Aug 7 09:17:24.756: Vi2 LCP: Timeout: State REQsent

*Aug 7 09:17:24.756: Vi2 LCP: O CONFREQ [REQsent] id 5 len 10

*Aug 7 09:17:24.756: Vi2 LCP: MagicNumber 0x22F0FFE2 (0x050622F0FFE2)

*Aug 7 09:17:26.248: Vi2 LCP: I CONFREQ [REQsent] id 3 len 18

*Aug 7 09:17:26.252: Vi2 LCP: MRU 1492 (0x010405D4)

*Aug 7 09:17:26.252: Vi2 LCP: AuthProto PAP (0x0304C023)

*Aug 7 09:17:26.252: Vi2 LCP: MagicNumber 0x1D5EFA59 (0x05061D5EFA59)

*Aug 7 09:17:26.252: Vi2 LCP: O CONFNAK [REQsent] id 3 len 8

*Aug 7 09:17:26.252: Vi2 LCP: MRU 1500 (0x010405DC)

*Aug 7 09:17:26.772: Vi2 LCP: Timeout: State REQsent

*Aug 7 09:17:26.772: Vi2 LCP: O CONFREQ [REQsent] id 6 len 10

*Aug 7 09:17:26.772: Vi2 LCP: MagicNumber 0x22F0FFE2 (0x050622F0FFE2)

*Aug 7 09:17:28.268: Vi2 LCP: I CONFREQ [REQsent] id 4 len 18

*Aug 7 09:17:28.268: Vi2 LCP: MRU 1492 (0x010405D4)

*Aug 7 09:17:28.268: Vi2 LCP: AuthProto PAP (0x0304C023)

*Aug 7 09:17:28.268: Vi2 LCP: MagicNumber 0x1D5EFA59 (0x05061D5EFA59)

*Aug 7 09:17:28.268: Vi2

Sawah# LCP: O CONFNAK [REQsent] id 4 len 8

*Aug 7 09:17:28.268: Vi2 LCP: MRU 1500 (0x010405DC)

*Aug 7 09:17:28.788: Vi2 LCP: Timeout: State REQsent

*Aug 7 09:17:28.788: Vi2 LCP: O CONFREQ [REQsent] id 7 len 10

*Aug 7 09:17:28.788: Vi2 LCP: MagicNumber 0x22F0FFE2 (0x050622F0FFE2)

*Aug 7 09:17:30.284: Vi2 LCP: I CONFREQ [REQsent] id 5 len 18

*Aug 7 09:17:30.284: Vi2 LCP: MRU 1492 (0x010405D4)

*Aug 7 09:17:30.284: Vi2 LCP: AuthProto PAP (0x0304C023)

*Aug 7 09:17:30.284: Vi2 LCP: MagicNumber 0x1D5EFA59 (0x05061D5EFA59)

*Aug 7 09:17:30.284: Vi2 LCP: O CONFNAK [REQsent] id 5 len 8

*Aug 7 09:17:30.284: Vi2 LCP: MRU 1500 (0x010405DC)

*Aug 7 09:17:30.804: Vi2 LCP: Timeout: State REQsent

*Aug 7 09:17:30.804: Vi2 LCP: O CONFREQ [REQsent] id 8 len 10

*Aug 7 09:17:30.804: Vi2 LCP: MagicNumber 0x22F0FFE2 (0x050622F0FFE2)

Sawah#

*Aug 7 09:17:32.300: Vi2 LCP: I CONFREQ [REQsent] id 6 len 18

*Aug 7 09:17:32.300: Vi2 LCP: MRU 1492 (0x010405D4)

*Aug 7 09:17:32.300: Vi2 LCP: AuthProto PAP (0x0304C023)

*Aug 7 09:17:32.300: Vi2 LCP: MagicNumber 0x1D5EFA59 (0x05061D5EFA59)

*Aug 7 09:17:32.300: Vi2 LCP: O CONFREJ [REQsent] id 6 len 8

*Aug 7 09:17:32.300: Vi2 LCP: MRU 1492 (0x010405D4)

*Aug 7 09:17:32.820: Vi2 LCP: Timeout: State REQsent

*Aug 7 09:17:32.820: Vi2 LCP: O CONFREQ [REQsent] id 9 len 10

*Aug 7 09:17:32.820: Vi2 LCP: MagicNumber 0x22F0FFE2 (0x050622F0FFE2)

Sawah#

*Aug 7 09:17:34.316: Vi2 LCP: I CONFREQ [REQsent] id 7 len 18

*Aug 7 09:17:34.316: Vi2 LCP: MRU 1492 (0x010405D4)

*Aug 7 09:17:34.316: Vi2 LCP: AuthProto PAP (0x0304C023)

*Aug 7 09:17:34.316: Vi2 LCP: MagicNumber 0x1D5EFA59 (0x05061D5EFA59)

*Aug 7 09:17:34.316: Vi2 LCP: O CONFREJ [REQsent] id 7 len 8

*Aug 7 09:17:34.316: Vi2 LCP: MRU 1492 (0x010405D4)

*Aug 7 09:17:34.836: Vi2 LCP: Timeout: State REQsent

*Aug 7 09:17:34.836: Vi2 LCP: O CONFREQ [REQsent] id 10 len 10

*Aug 7 09:17:34.836: Vi2 LCP: MagicNumber 0x22F0FFE2 (0x050622F0FFE2)

Sawah#

*Aug 7 09:17:36.332: Vi2 LCP: I CONFREQ [REQsent] id 8 len 18

*Aug 7 09:17:36.332: Vi2 LCP: MRU 1492 (0x010405D4)

*Aug 7 09:17:36.332: Vi2 LCP: AuthProto PAP (0x0304C023)

*Aug 7 09:17:36.332: Vi2 LCP: MagicNumber 0x1D5EFA59 (0x05061D5EFA59)

*Aug 7 09:17:36.332: Vi2 LCP: O CONFREJ [REQsent] id 8 len 8

*Aug 7 09:17:36.332: Vi2 LCP: MRU 1492 (0x010405D4)

*Aug 7 09:17:36.852: Vi2 LCP: Timeout: State REQsent

*Aug 7 09:17:36.852: %DIALER-6-UNBIND: Interface Vi2 unbound from profile Di1

*Aug 7 09:17:36.852: Vi2 PPP: Block vaccess from being freed [0x10]

*Aug 7 09:17:36.852: Vi2 LCP: State is Listen

*Aug 7 09:17:36.856: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to down

Sawah#

*Aug 7 09:17:36.856: Vi2 PPP: Sending Acct Event[Down] id[25]

*Aug 7 09:17:36.856: Vi2 LCP: State is Closed

*Aug 7 09:17:36.856: Vi2 PPP: Phase is DOWN

*Aug 7 09:17:36.856: Vi2 PPP: Unlocked by [0x10] Still Locked by [0x2]

*Aug 7 09:17:36.856: Vi2 PPP: Unlocked by [0x2] Still Locked by [0

Sawah#x0]

*Aug 7 09:17:36.856: Vi2 PPP: Free previously blocked vaccess

Sawah#

Thanks.

Peter Paluch · ‎08-20-2013

Hi Abdallah,

Thank you for your update. I wonder - can you try adding the mtu 1492 command to your Dialer1 configuration? Notice that this command has no "ip" keyword and should thus affect all protocols, not just IP. This should be reflected in the LCP negotiation as well.

Best regards,

Peter

View solution in original post

Peter Paluch · ‎08-14-2013

Hello Abdallah,

Have you used the ppp mtu adaptive on the Dialer interface? Please note that all MTU-related configuration must be placed on the Dialer interface, not on the FastEthernet or any other physical interface.

Best regards,

Peter

abdalalhmohamed10 · ‎08-16-2013

Dear Eng/ Peter

Thank you for your replay, i tried to put the command under the dialer interface but it's not there.

this is the option i get :

Sawah(config-if)#ppp m?

max-bad-auth max-configure max-failure max-terminate

ms-chap ms-chap-v2 multilink

and i used this command in the 1900 series without any problems.

Thanks

abdalalhmohamed10 · ‎08-17-2013

FYI, the lcp negotiation some time success but i don't know why and what is the reason to the suddenly acceptance of the MRU value .

any help will be appreciated

Peter Paluch · ‎08-18-2013

Abdallah,

This is strange - can you please post your complete configuration?

Best regards,

Peter

abdalalhmohamed10 · ‎08-18-2013

Dear Peter

Here's the config .

https://www.dropbox.com/s/z3ew3rxm448a7ir/SWConfig.txt

Thanks

Peter Paluch · ‎08-19-2013

Hi Abdallah,

I have had a look at your configuration, and there are some things that need correcting:

Both your Fa0/0 and Fa0/1 are configured with PPPoE client configuration. That does not seem to be correct. It seems that the Fa0/1 is the WAN connection. Therefore, please remove both pppoe enable group global and pppoe-client dial-pool-number 1 from your Fa0/0 configuration, and leave these commands present only on the Fa0/1 interface.
While probably not relevant to your current issue, I do not understand why you have bridge groups configured on your Serial subinterfaces. You do not seem to be bridging any Frame Relay virtual circuits, so the only effect of this configuration is that the IP configuration was moved from Serial subinterfaces to BVI interfaces. Why would that be?
While probably not relevant to your current issue, I recommend removing the ppp authentication chap callin from your Cellular0/1/0 interface. This command has no effect on your authentication towards the ISP, on the contrary, under circumstances, it would require the ISP to authenticate towards your router - something ISPs do not commonly do.
For the same reason, remove the ppp authentication pap callin from your Dialer1 interface.
On your Dialer1 interface, add the ip mtu 1492 command. I am still puzzled why the ppp mtu adaptive command is not available on your Dialer1 interface but the ip mtu 1492 command should be an applicable workaround.
While probably not relevant to your current issue, all static routes that point out the Serial0/0/0.50 interface are unusable and will not ever be placed into your routing table because the Serial0/0/0.50 interface has no IP address configured on it, and is hence not considered to be a usable IP interface.

Would you mind testing out these suggestions? Please back up your configuration beforehand. Also you may remove your current configuration from the Dropbox, as there are sensitive information in that file.

Best regards,

Peter

abdalalhmohamed10 · ‎08-19-2013

Dear Peter

Thanks you for your continued cooperation

i will replay for each point you made separately.

1- i was using the Fa0/0 as the WAN connection then i switched it to the Fa0/1 but i forget to remove the PPPOE configuration. done removing it.

2,3,6 - I know that some of the configuration on the router don't make any sense to me but i'don't have the full authority on the router to change these configurations so i'm trying to do my job without changing any thing that not conflict with my goal.

4- done removing the "ppp authentication pap callin"

5- done adding the command but i'm sure that i put this command on the older configuration but din't effect anything.

here is the PPP negotiation and authentication debug when the LCP negotiation succusse .

Sawah(config-if)#

*Aug 19 12:44:44.464: %LINK-3-UPDOWN: Interface Dialer1, changed state to up

Sawah(config-if)#

*Aug 19 12:44:51.168: %DIALER-6-BIND: Interface Vi3 bound to profile Di1

*Aug 19 12:44:51.168: Vi3 PPP: Phase is DOWN, Setup

*Aug 19 12:44:51.168: Vi3 PPP: Using dialer call direction

*Aug 19 12:44:51.168: Vi3 PPP: Treating connection as a callout

*Aug 19 12:44:51.168: Vi3 PPP: Session handle[1800083B] Session id[0]

*Aug 19 12:44:51.168: Vi3 PPP: Phase is ESTABLISHING, Active Open

*Aug 19 12:44:51.168: Vi3 PPP: Authorization required

*Aug 19 12:44:51.168: Vi3 PPP: No remote authentication for call-out

*Aug 19 12:44:51.168: Vi3 LCP: O CONFREQ [Closed] id 1 len 10

*Aug 19 12:44:51.168: Vi3 LCP: MagicNumber 0x5D19F7D8 (0x05065D19F7D8)

*Aug 19 12:44:51.172: %LINK-3-UPDOWN: Interface Virtual-Access3, changed state to up

*Aug 19 12:44:51.188: Vi3 LCP: I CONFREQ [REQsent] id 1 len 18

*Aug 19 12:44:51.188: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 19 12:44:51.188: Vi3 LCP: AuthProto PAP (0x0304C023)

*Aug 19 12:44:51.188: Vi3 LCP: MagicNumber 0x5BFF5050 (0x05065BFF5050)

*Aug 19 12:44:51.188: Vi3 LCP: O CONFNAK [REQsent] id 1 len 8

*Aug 19 12:44:51.188: Vi3 LCP: MRU 1500 (0x010405DC)

*Aug 19 12:44:51.188: Vi3 LCP: I CONFACK [REQsent] id 1 len 10

*Aug 19 12:44:51.188: Vi3 LCP: MagicNumber 0x5D19F7D8 (0x05065D19F7D8)

*Aug 19 12:44:51.208: Vi3 LCP: I CONFREQ [ACKrcvd] id 2 len 18

*Aug 19 12:44:51.208: Vi3 LCP: MRU 1500 (0x010405DC)

*Aug 19 12:44:51.208: Vi3 LCP: AuthProto PAP (0x0304C023)

*Aug 19 12:44:51.208: Vi3 LCP: MagicNumber 0x5BFF5050 (0x05065BFF5050)

*Aug 19 12:44:51.208: Vi3 LCP: O CONFACK [ACKrcvd] id 2 len 18

*Aug 19 12:44:51.212: Vi3 LCP: MRU 1500 (0x010405DC)

*Aug 19 12:44:51.212: Vi3 LCP: AuthProto PAP (0x0304C023)

*Aug 19 12:44:51.212: Vi3 LCP: MagicNumber 0x5BFF5050 (0x05065BFF5050)

*Aug 19 12:44:51.212: Vi3 LCP: State is Open

*Aug 19 12:44:51.212: Vi3 PPP: No authorization without authentication

*Aug 19 12:44:51.212: Vi3 PPP: Phase is AUTHENTICATING, by the peer

*Aug 19 12:44:51.212: Vi3 PAP: Using hostname from interface PAP

*Aug 19 12:44:51.212: Vi3 PAP: Using password from interface PAP

*Aug 19 12:44:51.212: Vi3 PAP: O AUTH-REQ id 1 len 35 from "2103072@tedata.net.eg"

*Aug 19 12:44:51.356: Vi3 PAP: I AUTH-ACK id 1 len 19 msg is "Welcome To ISG"

*Aug 19 12:44:51.356: Vi3 PPP: Phase is FORWARDING, Attempting Forward

*Aug 19 12:44:51.356: Vi3 PPP: Queue IPCP code[1] id[1]

*Aug 19 12:44:51.360: Vi3 PPP SSS: Receive SSS-Mgr Connect-Local

*Aug 19 12:44:51.360: Vi3 PPP: Phase is ESTABLISHING, Finish LCP

*Aug 19 12:44:51.360: Vi3 PPP: Phase is UP

*Aug 19 12:44:51.360: Vi3 IPCP: O CONFREQ [Closed] id 1 len 10

*Aug 19 12:44:51.360: Vi3 IPCP: Address 41.38.78.102 (0x030629264E66)

Sawah(config-if)#

*Aug 19 12:44:51.360: Vi3 PPP: Process pending ncp packets

*Aug 19 12:44:51.360: Vi3 IPCP: Redirect packet to Vi3

*Aug 19 12:44:51.360: Vi3 IPCP: I CONFREQ [REQsent] id 1 len 10

*Aug 19 12:44:51.360: Vi3 IPCP: Address 163.121.170.172 (0x0306A379AAAC)

*Aug 19 12:44:51.360: Vi3 IPCP: O CONFACK [REQsent] id 1 len 10

*Aug 19 12:44:51.360: Vi3 IPCP: Address 163.121.170.172 (0x0306A379AAAC)

*Aug 19 12:44:51.380: Vi3 IPCP: I CONFNAK [ACKsent] id 1 len 10

*Aug 19 12:44:51.380: Vi3 IPCP: Address 41.38.76.52 (0x030629264C34)

*Aug 19 12:44:51.380: Vi3 IPCP: O CONFREQ [ACKsent] id 2 len 4

*Aug 19 12:44:51.424: Vi3 IPCP: I CONFACK [ACKsent] id 2 len 4

*Aug 19 12:44:51.424: Vi3 IPCP: State is Open

*Aug 19 12:44:51.428: Di1 IPCP: Install route to 163.121.170.172

*Aug 19 12:44:51.428: Vi3 IPCP: Add link info for cef entry 163.121.170.172

Sawah(config-if)#

*Aug 19 12:44:52.360: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access3, changed state to up

is there is any thing this debug mean. i see that the router is request the MRU 1500 value after the CONFNAK message .

the connection work for more than 3 day without any problem but the problem reappear in the case of power outage.

Thanks

Peter Paluch · ‎08-20-2013

Hi Abdallah,

Thank you for your update. I wonder - can you try adding the mtu 1492 command to your Dialer1 configuration? Notice that this command has no "ip" keyword and should thus affect all protocols, not just IP. This should be reflected in the LCP negotiation as well.

Best regards,

Peter

abdalalhmohamed10 · ‎08-20-2013

Dear Peter,

Thank you very much for you appreciated help.

after adding the mtu 1492 command the router start to accept the MRU value and i think the problem solved now , but i have question regarding the below debug why the LCP fails many times with the acceptance of the MRU value from both end .

*Aug 20 08:21:06.768: %DIALER-6-BIND: Interface Vi3 bound to profile Di1

*Aug 20 08:21:06.768: Vi3 PPP: Phase is DOWN, Setup

*Aug 20 08:21:06.768: Vi3 PPP: Using dialer call direction

*Aug 20 08:21:06.768: Vi3 PPP: Treating connection as a callout

*Aug 20 08:21:06.768: Vi3 PPP: Session handle[C7000871] Session id[0]

*Aug 20 08:21:06.768: Vi3 PPP: Phase is ESTABLISHING, Active Open

*Aug 20 08:21:06.768: Vi3 PPP: Authorization required

*Aug 20 08:21:06.768: Vi3 PPP: No remote authentication for call-out

*Aug 20 08:21:06.768: Vi3 LCP: O CONFREQ [Closed] id 1 len 14

*Aug 20 08:21:06.768: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:06.768: Vi3 LCP: MagicNumber 0x614EE072 (0x0506614EE072)

Sawah(config-if)#

*Aug 20 08:21:06.772: %LINK-3-UPDOWN: Interface Virtual-Access3, changed state to up

Sawah(config-if)#

*Aug 20 08:21:08.756: Vi3 LCP: Timeout: State REQsent

*Aug 20 08:21:08.756: Vi3 LCP: O CONFREQ [REQsent] id 2 len 14

*Aug 20 08:21:08.756: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:08.756: Vi3 LCP: MagicNumber 0x614EE072 (0x0506614EE072)

Sawah(config-if)#

*Aug 20 08:21:10.772: Vi3 LCP: Timeout: State REQsent

*Aug 20 08:21:10.772: Vi3 LCP: O CONFREQ [REQsent] id 3 len 14

*Aug 20 08:21:10.772: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:10.772: Vi3 LCP: MagicNumber 0x614EE072 (0x0506614EE072)

Sawah(config-if)#

*Aug 20 08:21:12.788: Vi3 LCP: Timeout: State REQsent

*Aug 20 08:21:12.788: Vi3 LCP: O CONFREQ [REQsent] id 4 len 14

*Aug 20 08:21:12.788: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:12.788: Vi3 LCP: MagicNumber 0x614EE072 (0x0506614EE072)

Sawah(config-if)#

*Aug 20 08:21:14.804: Vi3 LCP: Timeout: State REQsent

*Aug 20 08:21:14.804: Vi3 LCP: O CONFREQ [REQsent] id 5 len 14

*Aug 20 08:21:14.804: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:14.804: Vi3 LCP: MagicNumber 0x614EE072 (0x0506614EE072)

Sawah(config-if)#

*Aug 20 08:21:16.820: Vi3 LCP: Timeout: State REQsent

*Aug 20 08:21:16.820: Vi3 LCP: O CONFREQ [REQsent] id 6 len 14

*Aug 20 08:21:16.820: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:16.820: Vi3 LCP: MagicNumber 0x614EE072 (0x0506614EE072)

Sawah(config-if)#

*Aug 20 08:21:18.836: Vi3 LCP: Timeout: State REQsent

*Aug 20 08:21:18.836: Vi3 LCP: O CONFREQ [REQsent] id 7 len 14

*Aug 20 08:21:18.836: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:18.836: Vi3 LCP: MagicNumber 0x614EE072 (0x0506614EE072)

*Aug 20 08:21:19.132: Vi3 LCP: I CONFREQ [REQsent] id 1 len 18

*Aug 20 08:21:19.132: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:19.132: Vi3 LCP: AuthProto PAP (0x0304C023)

*Aug 20 08:21:19.132: Vi3 LCP: MagicNumber 0x603671EC (0x0506603671EC)

*Aug 20 08:21:19.132: Vi3 LCP: O CONFACK [REQsent] id 1 len 18

*Aug 20 08:21:19.132: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:19.132: Vi3 LCP: AuthProto PAP (0x0304C023)

Sawah(config-if)#

*Aug 20 08:21:19.132: Vi3 LCP: MagicNumber 0x603671EC (0x0506603671EC)

Sawah(config-if)#

*Aug 20 08:21:20.852: Vi3 LCP: Timeout: State ACKsent

*Aug 20 08:21:20.852: Vi3 LCP: O CONFREQ [ACKsent] id 8 len 14

*Aug 20 08:21:20.852: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:20.852: Vi3 LCP: MagicNumber 0x614EE072 (0x0506614EE072)

*Aug 20 08:21:21.148: Vi3 LCP: I CONFREQ [ACKsent] id 2 len 18

*Aug 20 08:21:21.148: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:21.148: Vi3 LCP: AuthProto PAP (0x0304C023)

*Aug 20 08:21:21.148: Vi3 LCP: MagicNumber 0x603671EC (0x0506603671EC)

*Aug 20 08:21:21.148: Vi3 LCP: O CONFACK [ACKsent] id 2 len 18

*Aug 20 08:21:21.148: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:21.148: Vi3 LCP: AuthProto PAP (0x0304C023)

Sawah(config-if)#

*Aug 20 08:21:21.148: Vi3 LCP: MagicNumber 0x603671EC (0x0506603671EC)

Sawah(config-if)#

*Aug 20 08:21:22.868: Vi3 LCP: Timeout: State ACKsent

*Aug 20 08:21:22.868: Vi3 LCP: O CONFREQ [ACKsent] id 9 len 14

*Aug 20 08:21:22.868: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:22.868: Vi3 LCP: MagicNumber 0x614EE072 (0x0506614EE072)

*Aug 20 08:21:23.164: Vi3 LCP: I CONFREQ [ACKsent] id 3 len 18

*Aug 20 08:21:23.164: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:23.164: Vi3 LCP: AuthProto PAP (0x0304C023)

*Aug 20 08:21:23.164: Vi3 LCP: MagicNumber 0x603671EC (0x0506603671EC)

*Aug 20 08:21:23.164: Vi3 LCP: O CONFACK [ACKsent] id 3 len 18

*Aug 20 08:21:23.164: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:23.164: Vi3 LCP: AuthProto PAP (0x0304C023)

Sawah(config-if)#

*Aug 20 08:21:23.164: Vi3 LCP: MagicNumber 0x603671EC (0x0506603671EC)

Sawah(config-if)#

*Aug 20 08:21:24.884: Vi3 LCP: Timeout: State ACKsent

*Aug 20 08:21:24.884: Vi3 LCP: O CONFREQ [ACKsent] id 10 len 14

*Aug 20 08:21:24.884: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:24.884: Vi3 LCP: MagicNumber 0x614EE072 (0x0506614EE072)

*Aug 20 08:21:25.180: Vi3 LCP: I CONFREQ [ACKsent] id 4 len 18

*Aug 20 08:21:25.180: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:25.180: Vi3 LCP: AuthProto PAP (0x0304C023)

*Aug 20 08:21:25.180: Vi3 LCP: MagicNumber 0x603671EC (0x0506603671EC)

*Aug 20 08:21:25.180: Vi3 LCP: O CONFACK [ACKsent] id 4 len 18

*Aug 20 08:21:25.180: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:21:25.180: Vi3 LCP: AuthProto PAP (0x0304C023)

*Aug 20 08:21:25.180: Vi3 LCP: MagicNumber 0x603671EC (0x0506603671EC)

Sawah(config-if)#

*Aug 20 08:21:26.900: Vi3 LCP: Timeout: State ACKsent

*Aug 20 08:21:26.900: %DIALER-6-UNBIND: Interface Vi3 unbound from profile Di1

*Aug 20 08:21:26.900: Vi3 PPP: Block vaccess from being freed [0x10]

*Aug 20 08:21:26.900: Vi3 LCP: State is Listen

*Aug 20 08:21:26.904: %LINK-3-UPDOWN: Interface Virtual-Access3, changed state to down

Sawah(config-if)#

*Aug 20 08:21:26.904: Vi3 PPP: Sending Acct Event[Down] id[18D1]

*Aug 20 08:21:26.904: Vi3 LCP: State is Closed

*Aug 20 08:21:26.904: Vi3 PPP: Phase is DOWN

*Aug 20 08:21:26.904: Vi3 PPP: Unlocked by [0x10] Still Locked by [0x2]

*Aug 20 08:21:26.904: Vi3 PPP: Unlocked by [0x2] Still Locked by [0x0]

*Aug 20 08:21:26.904: Vi3 PPP: Free previously blocked vaccess

and here is the success debug . ( this happened after restarting the modem )

Sawah(config-if)#

*Aug 20 08:23:47.112: %LINEPROTO-5-UPDOWN: Line protocol on Interface FastEthernet0/1, changed state to down

Sawah(config-if)#

*Aug 20 08:23:49.568: %LINEPROTO-5-UPDOWN: Line protocol on Interface FastEthernet0/1, changed state to up

Sawah(config-if)#

*Aug 20 08:24:07.112: %LINEPROTO-5-UPDOWN: Line protocol on Interface FastEthernet0/1, changed state to down

Sawah(config-if)#

*Aug 20 08:24:19.572: %LINEPROTO-5-UPDOWN: Line protocol on Interface FastEthernet0/1, changed state to up

Sawah(config-if)#

*Aug 20 08:25:30.488: %DIALER-6-BIND: Interface Vi3 bound to profile Di1

*Aug 20 08:25:30.488: Vi3 PPP: Phase is DOWN, Setup

*Aug 20 08:25:30.488: Vi3 PPP: Using dialer call direction

*Aug 20 08:25:30.488: Vi3 PPP: Treating connection as a callout

*Aug 20 08:25:30.488: Vi3 PPP: Session handle[9000087D] Session id[0]

*Aug 20 08:25:30.488: Vi3 PPP: Phase is ESTABLISHING, Active Open

*Aug 20 08:25:30.488: Vi3 PPP: Authorization required

*Aug 20 08:25:30.488: Vi3 PPP: No remote authentication for call-out

*Aug 20 08:25:30.492: Vi3 LCP: O CONFREQ [Closed] id 1 len 14

*Aug 20 08:25:30.492: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:25:30.492: Vi3 LCP: MagicNumber 0x6152E69E (0x05066152E69E)

*Aug 20 08:25:30.492: %LINK-3-UPDOWN: Interface Virtual-Access3, changed state to up

*Aug 20 08:25:30.548: Vi3 LCP: I CONFREQ [REQsent] id 1 len 18

*Aug 20 08:25:30.548: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:25:30.548: Vi3 LCP: AuthProto PAP (0x0304C023)

*Aug 20 08:25:30.548: Vi3 LCP: MagicNumber 0x603A4959 (0x0506603A4959)

*Aug 20 08:25:30.548: Vi3 LCP: O CONFACK [REQsent] id 1 len 18

*Aug 20 08:25:30.548: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:25:30.548: Vi3 LCP: AuthProto PAP (0x0304C023)

*Aug 20 08:25:30.548: Vi3 LCP: MagicNumber 0x603A4959 (0x0506603A4959)

*Aug 20 08:25:30.548: Vi3 LCP: I CONFACK [ACKsent] id 1 len 14

*Aug 20 08:25:30.548: Vi3 LCP: MRU 1492 (0x010405D4)

*Aug 20 08:25:30.548: Vi3 LCP: MagicNumber 0x6152E69E (0x05066152E69E)

*Aug 20 08:25:30.548: Vi3 LCP: State is Open

*Aug 20 08:25:30.548: Vi3 PPP: No authorization without authentication

*Aug 20 08:25:30.548: Vi3 PPP: Phase is AUTHENTICATING, by the peer

*Aug 20 08:25:30.548: Vi3 PAP: Using hostname from interface PAP

*Aug 20 08:25:30.548: Vi3 PAP: Using password from interface PAP

*Aug 20 08:25:30.548: Vi3 PAP: O AUTH-REQ id 1 len 35 from "2103072@tedata.net.eg"

*Aug 20 08:25:30.756: Vi3 PAP: I AUTH-ACK id 1 len 19 msg is "Welcome To ISG"

*Aug 20 08:25:30.756: Vi3 PPP: Phase is FORWARDING, Attempting Forward

*Aug 20 08:25:30.756: Vi3 PPP: Queue IPCP code[1] id[1]

*Aug 20 08:25:30.760: Vi3 PPP SSS: Receive SSS-Mgr Connect-Local

*Aug 20 08:25:30.760: Vi3 PPP: Phase is ESTABLISHING, Finish LCP

*Aug 20 08:25:30.760: Vi3 PPP: Phase is UP

*Aug 20 08:25:30.760: Vi3 IPCP: O CONFREQ [Closed] id 1 len 10

*Aug 20 08:25:30.760: Vi3 IPCP: Address 41.38.78.102 (0x030629264E66)

*Aug 20 08:25:30.760: Vi3 PPP: Process pending ncp packets

*Aug 20 08:25:30.760: Vi3 IPCP: Redirect packet to Vi3

*Aug 20 08:25:30.760: Vi3 IPCP: I CONFREQ [REQsent] id 1 len 10

*Aug 20 08:25:30.760: Vi3 IPCP: Address 163.121.170.172 (0x0306A379AAAC)

*Aug 20 08:25:30.760: Vi3 IPCP: O CONFACK [REQsent] id 1 len 10

Sawah(config-if)#

*Aug 20 08:25:30.760: Vi3 IPCP: Address 163.121.170.172 (0x0306A379AAAC)

*Aug 20 08:25:30.780: Vi3 IPCP: I CONFNAK [ACKsent] id 1 len 10

*Aug 20 08:25:30.780: Vi3 IPCP: Address 41.38.76.52 (0x030629264C34)

*Aug 20 08:25:30.780: Vi3 IPCP: O CONFREQ [ACKsent] id 2 len 4

*Aug 20 08:25:30.800: Vi3 IPCP: I CONFACK [ACKsent] id 2 len 4

*Aug 20 08:25:30.800: Vi3 IPCP: State is Open

*Aug 20 08:25:30.804: Di1 IPCP: Install route to 163.121.170.172

*Aug 20 08:25:30.804: Vi3 IPCP: Add link info for cef entry 163.121.170.172

*Aug 20 08:25:31.760: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access3, changed state to up

Sawah(config-if)#

Thanks .

Peter Paluch · ‎08-20-2013

Hello Abdallah,

It seems to me that the problem is at the other end - on the PPPoE access concentrator. For some reason that is not clear from the debug, the access concentrator does not respond to LCP packets in appropriate time. It may be overloaded, or the link itself may be lossy. It is also kind of surprising that at one point, the access concentrator refuses to proceed with the MRU of 1500 bytes, and in some other cases, it accepts it happily. That would actually suggest that there are multiple access concentrators on the other end of the link, configured differently.Some of these concentrators appear to be more liberal with the MRU of 1500 bytes while others stringently insist on using 1492 bytes.

In any case, the problem is outside your router and outside your reach. If the link is fine then this is an issue to be resovled in cooperation with your ISP.

Best regards,

Peter

abdalalhmohamed10 · ‎08-30-2013

Dear Peter,

i hope to find you well

I want to add something related to the lcp timeout that happened after fixing the MRU value. if the power goes down and up the LCP negotiation fail with the same error in the previous debug "LCP: Timeout: State ACKsent", and it keep failing till no end. what i do is switch the ADSL router from bridge mode to PPPOE mode then the connection success right away , then i switch it to bridge mode again and it also success on the cisco router.

it success fast with the home router but it takes more than hour of trying with the cisco router. (except when i do the previously mentioned workaround)

what level to use to debug such behaviour.

thanks.

Peter Paluch · ‎09-01-2013

Hi Abdallah,

To be honest, I am at a loss here. My personal suggestion would be to talk to your ISP whether he can provide any insight what is happening - perhaps some kind of MAC lockdown, either based on the MAC address or on the count of PPPoE sessions.

Perhaps also the following debugs would be interesting:

debug pppoe events

debug pppoe errors

Best regards,

Peter