Solved: cisco 887 adsl "Interface Vi1 unbound from profile Di0"

afshan_nava · ‎07-12-2011

Hi everyone

i recently got an 887 adsl router to be added for internet.... hoping the configuration should be the same as 877 i have done the following configs...

interface ATM0

no ip address

no atm ilmi-keepalive

!

interface ATM0.1 point-to-point

pvc 8/35

pppoe-client dial-pool-number 1

interface Dialer0

ip address negotiated

encapsulation ppp

dialer pool 1

ppp authentication chap pap callin

ppp chap hostname ******

ppp chap password 0 ***

ppp pap sent-username ****** password 0 ***

with this config on a 877 it works perfectly... but on the 887 it doesnt... the basic output i get is as follows

*Jul 11 21:22:31.111: %DIALER-6-BIND: Interface Vi1 bound to profile Di0

*Jul 11 21:22:31.115: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to up

*Jul 11 21:22:31.119: Vi1 PPP: No remote authentication for call-out

*Jul 11 21:22:34.307: %DIALER-6-UNBIND: Interface Vi1 unbound from profile Di0

*Jul 11 21:22:34.311: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to down

Am i missing something on the 887?

Afshan

Peter Paluch · ‎07-14-2011

Afshan,

So far, we have tried everything reasonable. We streamlined the configuration and removed unnecessary commands, we have verified its correctness, we have even reviewed the debugs closely. We have gone as far as stripping every functionality from the Dialer interface and leaving it to build a basic plain PPP connection with practically no Layer3 protocol being transported or even allowed on it. Everything was unsuccessful. At this point, I am willing to say that this looks like an IOS bug.

Do you have an option of trying a more recent IOS version for your router, i.e. 15.1(4)M, or perhaps downgrading back to 12.4(24)T5?

Also, do you have a support contract with Cisco? If so then you can raise a TAC ticket directly from this thread. I guess Cisco TAC engineers would have a pretty good overview of what is going on basing on the wealth of debug information and experiments we've done in our conversations here.

Best regards,

Peter

View solution in original post

Peter Paluch · ‎07-12-2011

Hello Afshan,

Unless you are absolutely sure you need the command ppp authentication chap pap callin then please remove that command from your Di0 interface. If that does not help please run the debug ppp negotiation and debug ppp authentication and enclose the results in your response.

Thank you!

Best regards,

Peter

afshan_nava · ‎07-12-2011

Peter

yes i am not sure about the "callin".... and therefore i did try removing it.... and using "ppp authentication pap chap"

this is the responce form "debug ppp negotiontion"

Router#

*Jul 12 20:15:12.267: %DIALER-6-BIND: Interface Vi1 bound to profile Di0

*Jul 12 20:15:12.271: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to up

*Jul 12 20:15:12.271: Vi1 PPP: Sending cstate UP notification

*Jul 12 20:15:12.271: Vi1 PPP: Processing CstateUp message

*Jul 12 20:15:12.275: PPP: Alloc Context [852F5F84]

*Jul 12 20:15:12.275: ppp14 PPP: Phase is ESTABLISHING

*Jul 12 20:15:12.275: Vi1 PPP: Using dialer call direction

*Jul 12 20:15:12.275: Vi1 PPP: Treating connection as a callout

*Jul 12 20:15:12.275: Vi1 PPP: Session handle[EA00000E] Session id[14]

*Jul 12 20:15:12.275: Vi1 LCP: Event[OPEN] State[Initial to Starting]

*Jul 12 20:15:12.279: Vi1 LCP: O CONFREQ [Starting] id 1 len 14

*Jul 12 20:15:12.279: Vi1 LCP: AuthProto PAP (0x0304C023)

*Jul 12 20:15:12.279: Vi1 LCP: MagicNumber 0xDF1F42FE (0x0506DF1F42FE)

*Jul 12 20:15:12.279: Vi1 LCP: Event[UP] State[Starting to REQsent]

*Jul 12 20:15:12.307: Vi1 LCP: I CONFREJ [REQsent] id 1 len 8

*Jul 12 20:15:12.307: Vi1 LCP: AuthProto PAP (0x0304C023)

*Jul 12 20:15:12.307: Vi1 LCP: O CONFREQ [REQsent] id 2 len 15

*Jul 12 20:15:12.307: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 12 20:15:12.307: Vi1 LCP: MagicNumber 0xDF1F42FE (0x0506DF1F42FE)

*Jul 12 20:15:12.307: Vi1 LCP: Event[Receive ConfNak/Rej] State[REQsent to REQsent]

*Jul 12 20:15:12.331: Vi1 LCP: I CONFREJ [REQsent] id 2 len 9

*Jul 12 20:15:12.331: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 12 20:15:12.331: Vi1 LCP: O CONFREQ [REQsent] id 3 len 14

*Jul 12 20:15:12.331: Vi1 LCP: AuthProto PAP (0x0304C023)

*Jul 12 20:15:12.331: Vi1 LCP: MagicNumber 0xDF1F42FE (0x0506DF1F42FE)

*Jul 12 20:15:12.331: Vi1 LCP: Event[Receive ConfNak/Rej] State[REQsent to REQsent]

*Jul 12 20:15:12.355: Vi1 LCP: I CONFREJ [REQsent] id 3 len 8

*Jul 12 20:15:12.355: Vi1 LCP: AuthProto PAP (0x0304C023)

*Jul 12 20:15:12.355: Vi1 LCP: O CONFREQ [REQsent] id 4 len 15

*Jul 12 20:15:12.355: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 12 20:15:12.355: Vi1 LCP: MagicNumber 0xDF1F42FE (0x0506DF1F42FE)

*Jul 12 20:15:12.355: Vi1 LCP: Event[Receive ConfNak/Rej] State[REQsent to REQsent]

*Jul 12 20:15:12.391: Vi1 LCP: I CONFREJ [REQsent] id 4 len 9

*Jul 12 20:15:12.391: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 12 20:15:12.391: Vi1 LCP: O CONFREQ [REQsent] id 5 len 14

*Jul 12 20:15:12.391: Vi1 LCP: AuthProto PAP (0x0304C023)

*Jul 12 20:15:12.391: Vi1 LCP: MagicNumber 0xDF1F42FE (0x0506DF1F42FE)

*Jul 12 20:15:12.391: Vi1 LCP: Event[Receive ConfNak/Rej] State[REQsent to REQsent]

*Jul 12 20:15:12.415: Vi1 LCP: I CONFREJ [REQsent] id 5 len 8

*Jul 12 20:15:12.415: Vi1 LCP: AuthProto PAP (0x0304C023)

*Jul 12 20:15:12.415: Vi1 LCP: O CONFREQ [REQsent] id 6 len 15

*Jul 12 20:15:12.415: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 12 20:15:12.415: Vi1 LCP: MagicNumber 0xDF1F42FE (0x0506DF1F42FE)

*Jul 12 20:15:12.415: Vi1 LCP: Event[Receive ConfNak/Rej] State[REQsent to REQsent]

*Jul 12 20:15:12.439: Vi1 LCP: I CONFREJ [REQsent] id 6 len 9

*Jul 12 20:15:12.439: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 12 20:15:12.439: Vi1 LCP: O CONFREQ [REQsent] id 7 len 14

*Jul 12 20:15:12.439: Vi1 LCP: AuthProto PAP (0x0304C023)

*Jul 12 20:15:12.439: Vi1 LCP: MagicNumber 0xDF1F42FE (0x0506DF1F42FE)

*Jul 12 20:15:12.439: Vi1 LCP: Event[Receive ConfNak/Rej] State[REQsent to REQsent]

*Jul 12 20:15:12.463: Vi1 LCP: I CONFREJ [REQsent] id 7 len 8

*Jul 12 20:15:12.463: Vi1 LCP: AuthProto PAP (0x0304C023)

*Jul 12 20:15:12.463: Vi1 LCP: O CONFREQ [REQsent] id 8 len 15

*Jul 12 20:15:12.463: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 12 20:15:12.463: Vi1 LCP: MagicNumber 0xDF1F42FE (0x0506DF1F42FE)

*Jul 12 20:15:12.463: Vi1 LCP: Event[Receive ConfNak/Rej] State[REQsent to REQsent]

*Jul 12 20:15:12.487: Vi1 LCP: I CONFREJ [REQsent] id 8 len 9

*Jul 12 20:15:12.487: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 12 20:15:12.487: Vi1 LCP: O CONFREQ [REQsent] id 9 len 14

*Jul 12 20:15:12.487: Vi1 LCP: AuthProto PAP (0x0304C023)

*Jul 12 20:15:12.487: Vi1 LCP: MagicNumber 0xDF1F42FE (0x0506DF1F42FE)

*Jul 12 20:15:12.487: Vi1 LCP: Event[Receive ConfNak/Rej] State[REQsent to REQsent]

*Jul 12 20:15:12.511: Vi1 LCP: I CONFREJ [REQsent] id 9 len 8

*Jul 12 20:15:12.511: Vi1 LCP: AuthProto PAP (0x0304C023)

*Jul 12 20:15:12.511: Vi1 LCP: O CONFREQ [REQsent] id 10 len 15

*Jul 12 20:15:12.511: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 12 20:15:12.511: Vi1 LCP: MagicNumber 0xDF1F42FE (0x0506DF1F42FE)

*Jul 12 20:15:12.511: Vi1 LCP: Event[Receive ConfNak/Rej] State[REQsent to REQsent]

*Jul 12 20:15:12.535: Vi1 LCP: I CONFREJ [REQsent] id 10 len 9

*Jul 12 20:15:12.535: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 12 20:15:12.535: Vi1 LCP: Received too many CONFREJs. Closing CP

*Jul 12 20:15:12.535: Vi1 PPP DISC: LCP failed to negotiate

*Jul 12 20:15:12.535: Vi1 LCP: O TERMREQ [REQsent] id 11 len 4

*Jul 12 20:15:12.535: Vi1 LCP: Event[CLOSE] State[REQsent to Closing]

*Jul 12 20:15:12.559: Vi1 LCP: I TERMACK [Closing] id 11 len 4

*Jul 12 20:15:12.559: Vi1 LCP: Event[Receive TermAck] State[Closing to Closed]

*Jul 12 20:15:12.559: Vi1 LCP: Event[DOWN] State[Closed to Initial]

*Jul 12 20:15:12.559: Vi1 PPP: Phase is DOWN

*Jul 12 20:15:12.563: %DIALER-6-UNBIND: Interface Vi1 unbound from profile Di0

*Jul 12 20:15:12.567: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to down

Router#

and this is for "debug ppp authentication"

Router#

*Jul 12 20:23:55.391: %LINK-3-UPDOWN: Interface ATM0, changed state to up

*Jul 12 20:23:56.391: %LINEPROTO-5-UPDOWN: Line protocol on Interface ATM0, changed state to up

*Jul 12 20:23:59.407: %DIALER-6-BIND: Interface Vi1 bound to profile Di0

*Jul 12 20:23:59.411: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to up

*Jul 12 20:23:59.415: Vi1 PPP: Using dialer call direction

*Jul 12 20:23:59.415: Vi1 PPP: Treating connection as a callout

*Jul 12 20:23:59.415: Vi1 PPP: Session handle[6A000010] Session id[16]

*Jul 12 20:23:59.699: %DIALER-6-UNBIND: Interface Vi1 unbound from profile Di0

*Jul 12 20:23:59.703: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to down

*Jul 12 20:24:22.315: %DIALER-6-BIND: Interface Vi1 bound to profile Di0

*Jul 12 20:24:22.319: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to up

*Jul 12 20:24:22.323: Vi1 PPP: Using dialer call direction

*Jul 12 20:24:22.323: Vi1 PPP: Treating connection as a callout

*Jul 12 20:24:22.323: Vi1 PPP: Session handle[C4000011] Session id[17]

*Jul 12 20:24:22.595: %DIALER-6-UNBIND: Interface Vi1 unbound from profile Di0

*Jul 12 20:24:22.599: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to down

Router#

pls help me

Thanks

Peter Paluch · ‎07-12-2011

Afshan,

Please remove also the command ppp authentication pap chap - in other words, there shall be no command present in the Dialer0 configuration that starts with the words "ppp authentication". Using that command, you are forcing your DSL provider to authenticate to you which is wrong - only you are authenticating towards your DSL provider, not vice versa. Your Di0 configuration should look only as follows:

interface Dialer0

ip address negotiated

encapsulation ppp

dialer pool 1

ppp chap hostname ******

ppp chap password 0 ***

ppp pap sent-username ****** password 0 ***

Give it a try - and if it does not work either then please enclose the output of the same debug commands once more.

Best regards,

Peter

afshan_nava · ‎07-12-2011

Peter

did as u said, but no luck... the output follows..... Also note, we have other routers over hear with that command, and it does work....

Router#

*Jul 12 21:26:02.023: %DIALER-6-BIND: Interface Vi1 bound to profile Di0

*Jul 12 21:26:02.027: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to up

*Jul 12 21:26:02.031: Vi1 PPP: Using dialer call direction

*Jul 12 21:26:02.031: Vi1 PPP: Treating connection as a callout

*Jul 12 21:26:02.031: Vi1 PPP: Session handle[B700001B] Session id[27]

*Jul 12 21:26:05.047: Vi1 PPP: No authorization without authentication

*Jul 12 21:26:05.063: Vi1 CHAP: I CHALLENGE id 1 len 21

*Jul 12 21:26:05.063: Vi1 CHAP: No name received from peer

*Jul 12 21:26:05.063: Vi1 CHAP: Using hostname from interface CHAP

*Jul 12 21:26:05.063: Vi1 CHAP: Using password from interface CHAP

*Jul 12 21:26:05.063: Vi1 CHAP: O RESPONSE id 1 len 29 from "s4131152"

*Jul 12 21:26:05.123: Vi1 CHAP: I SUCCESS id 1 len 35 msg is "Authentication success,Welcome!"

*Jul 12 21:26:05.131: %DIALER-6-UNBIND: Interface Vi1 unbound from profile Di0

*Jul 12 21:26:05.135: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to down

Router#

PPP protocol negotiation debugging is on

Router#

*Jul 12 21:26:52.763: %DIALER-6-BIND: Interface Vi1 bound to profile Di0

*Jul 12 21:26:52.767: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to up

*Jul 12 21:26:52.767: Vi1 PPP: Sending cstate UP notification

*Jul 12 21:26:52.767: Vi1 PPP: Processing CstateUp message

*Jul 12 21:26:52.771: PPP: Alloc Context [852F5F84]

*Jul 12 21:26:52.771: ppp29 PPP: Phase is ESTABLISHING

*Jul 12 21:26:52.771: Vi1 PPP: Using dialer call direction

*Jul 12 21:26:52.771: Vi1 PPP: Treating connection as a callout

*Jul 12 21:26:52.771: Vi1 PPP: Session handle[A500001D] Session id[29]

*Jul 12 21:26:52.771: Vi1 LCP: Event[OPEN] State[Initial to Starting]

*Jul 12 21:26:52.771: Vi1 PPP: No remote authentication for call-out

*Jul 12 21:26:52.775: Vi1 LCP: O CONFREQ [Starting] id 1 len 10

*Jul 12 21:26:52.775: Vi1 LCP: MagicNumber 0xDF60E1E1 (0x0506DF60E1E1)

*Jul 12 21:26:52.775: Vi1 LCP: Event[UP] State[Starting to REQsent]

*Jul 12 21:26:52.799: Vi1 LCP: I CONFACK [REQsent] id 1 len 10

*Jul 12 21:26:52.799: Vi1 LCP: MagicNumber 0xDF60E1E1 (0x0506DF60E1E1)

*Jul 12 21:26:52.799: Vi1 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]

*Jul 12 21:26:54.775: Vi1 LCP: O CONFREQ [ACKrcvd] id 2 len 10

*Jul 12 21:26:54.775: Vi1 LCP: MagicNumber 0xDF60E1E1 (0x0506DF60E1E1)

*Jul 12 21:26:54.775: Vi1 LCP: Event[Timeout+] State[ACKrcvd to REQsent]

*Jul 12 21:26:54.799: Vi1 LCP: I CONFACK [REQsent] id 2 len 10

*Jul 12 21:26:54.799: Vi1 LCP: MagicNumber 0xDF60E1E1 (0x0506DF60E1E1)

*Jul 12 21:26:54.799: Vi1 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]

*Jul 12 21:26:55.755: Vi1 LCP: I CONFREQ [ACKrcvd] id 1 len 19

*Jul 12 21:26:55.755: Vi1 LCP: MRU 1460 (0x010405B4)

*Jul 12 21:26:55.755: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 12 21:26:55.755: Vi1 LCP: MagicNumber 0x06023D43 (0x050606023D43)

*Jul 12 21:26:55.755: Vi1 LCP: O CONFNAK [ACKrcvd] id 1 len 8

*Jul 12 21:26:55.755: Vi1 LCP: MRU 1500 (0x010405DC)

*Jul 12 21:26:55.755: Vi1 LCP: Event[Receive ConfReq-] State[ACKrcvd to ACKrcvd]

*Jul 12 21:26:55.783: Vi1 LCP: I CONFREQ [ACKrcvd] id 2 len 19

*Jul 12 21:26:55.783: Vi1 LCP: MRU 1500 (0x010405DC)

*Jul 12 21:26:55.783: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 12 21:26:55.783: Vi1 LCP: MagicNumber 0x06023D43 (0x050606023D43)

*Jul 12 21:26:55.783: Vi1 LCP: O CONFACK [ACKrcvd] id 2 len 19

*Jul 12 21:26:55.783: Vi1 LCP: MRU 1500 (0x010405DC)

*Jul 12 21:26:55.783: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 12 21:26:55.783: Vi1 LCP: MagicNumber 0x06023D43 (0x050606023D43)

*Jul 12 21:26:55.783: Vi1 LCP: Event[Receive ConfReq+] State[ACKrcvd to Open]

*Jul 12 21:26:55.799: Vi1 PPP: Phase is AUTHENTICATING, by the peer

*Jul 12 21:26:55.799: Vi1 LCP: State is Open

*Jul 12 21:26:55.807: Vi1 CHAP: I CHALLENGE id 1 len 21

*Jul 12 21:26:55.807: Vi1 CHAP: No name received from peer

*Jul 12 21:26:55.807: Vi1 CHAP: Using hostname from interface CHAP

*Jul 12 21:26:55.807: Vi1 CHAP: Using password from interface CHAP

*Jul 12 21:26:55.807: Vi1 CHAP: O RESPONSE id 1 len 29 from "s4131152"

*Jul 12 21:26:55.863: Vi1 CHAP: I SUCCESS id 1 len 35 msg is "Authentication success,Welcome!"

*Jul 12 21:26:55.863: Vi1 PPP: Phase is FORWARDING, Attempting Forward

*Jul 12 21:26:55.867: Vi1 PPP: Queue IPCP code[1] id[0]

*Jul 12 21:26:55.867: Vi1 PPP DISC: Lower Layer disconnected

*Jul 12 21:26:55.867: Vi1 LCP: O TERMREQ [Open] id 3 len 4

*Jul 12 21:26:55.867: Vi1 LCP: Event[CLOSE] State[Open to Closing]

*Jul 12 21:26:55.867: Vi1 PPP: Phase is TERMINATING

*Jul 12 21:26:55.871: %DIALER-6-UNBIND: Interface Vi1 unbound from profile Di0

*Jul 12 21:26:55.871: Vi1 PPP: Block vaccess from being freed [0x10]

*Jul 12 21:26:55.871: Vi1 LCP: Event[DOWN] State[Closing to Initial]

*Jul 12 21:26:55.871: Vi1 PPP: Unlocked by [0x10] Still Locked by [0x0]

*Jul 12 21:26:55.871: Vi1 PPP: Free previously blocked vaccess

*Jul 12 21:26:55.871: Vi1 PPP: Phase is DOWN

*Jul 12 21:26:55.875: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to down

Router#

thanks

Peter Paluch · ‎07-12-2011

Afshan,

You may be using the ppp authentication pap chap [ callin ] on your other routers but the fact is that it is inappropriate to have it on your interfaces, and you are simply lucky that it does not cause problems on your other routers, obviously because of the callin keyword which does not seem to work correctly on this particular IOS. Please do not put that command back - leave your Dialer0 as I suggested in my last reply.

From what you have posted, the authentication phase of the PPP runs fine, and just as the IP protocol parameter negotiation is about to take place, the line gets disconnected. That may be caused by various reasons:

There are no more free IP addresses to be assigned to your router here (for the ip address negotiated command)
The maximum simultaneous number of logins for that particular CAP login/password combination is exceeded

Can you please run all these debugs and post the result?

debug ppp negotiation

debug ppp error

debug pppoe events

debug pppoe errors

Thank you!

Best regards,

Peter

Peter Paluch · ‎07-12-2011

Afshan,

In addition to the debugs I have requested, can you try using the command ppp mtu adaptive on your Dialer0 interface to see if the line comes up? In the debugs posted so far, I see a single CONFNAK regarding the MRU size that could be alleviated using the ppp mtu adaptive command. Still, if that does not help, we have to see the debugs I have called for.

In my personal opinion, the firmware is probably not the cause here because the line is actually capable of successfully performing the initial PPP negotiation phases, in other words, it is capable of carrying data.

Best regards,

Peter

afshan_nava · ‎07-12-2011

peter

i changed the "ppp mtu aduptive" still no luck.... also made the "ip mtu 1452" still no doesnt work...

the following is wht u requested with "ppp mtu aduptive" set on dialer 0

Router#debug pppoe events

PPPoE protocol events debugging is on

Router#

*Jul 12 22:17:32.559: Sending PADI: vc=8/35

*Jul 12 22:17:32.679: PPPoE 0: I PADO R:00e0.fcb7.4462 L:1cdf.0f12.ea34 8/35 ATM0.1

*Jul 12 22:17:32.991: PPPoE 0: I PADO R:0018.82d3.bc99 L:1cdf.0f12.ea34 8/35 ATM0.1

*Jul 12 22:17:34.607: PPPOE: we've got our pado and the pado timer went off

*Jul 12 22:17:34.607: OUT PADR from PPPoE Session

*Jul 12 22:17:34.639: PPPoE 860: I PADS R:00e0.fcb7.4462 L:1cdf.0f12.ea34 8/35 ATM0.1

*Jul 12 22:17:34.639: IN PADS from PPPoE Session

*Jul 12 22:17:34.639: %DIALER-6-BIND: Interface Vi1 bound to profile Di0

*Jul 12 22:17:34.639: PPPoE: Virtual Access interface obtained.

*Jul 12 22:17:34.639: PPPoE : encap string prepared

*Jul 12 22:17:34.639: [0]PPPoE 860: data path set to PPPoE Client

*Jul 12 22:17:34.643: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to up

*Jul 12 22:17:37.755: PPPoE : Shutting down client session

*Jul 12 22:17:37.755: [0]PPPoE 860: O PADT R:00e0.fcb7.4462 L:1cdf.0f12.ea34 8/35 ATM0.1

*Jul 12 22:17:37.755: %DIALER-6-UNBIND: Interface Vi1 unbound from profile Di0

*Jul 12 22:17:37.759: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to down

*Jul 12 22:17:37.779: PPPoE 860: I PADT R:00e0.fcb7.4462 L:1cdf.0f12.ea34 8/35 ATM0.1

Router#

Router#debug pppoe errors

PPPoE protocol errors debugging is on

Router#

*Jul 12 22:18:25.335: %DIALER-6-BIND: Interface Vi1 bound to profile Di0

*Jul 12 22:18:25.339: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to up

*Jul 12 22:18:28.467: PPPoE: Failed to add PPPoE switching subblock

*Jul 12 22:18:28.467: %DIALER-6-UNBIND: Interface Vi1 unbound from profile Di0

*Jul 12 22:18:28.471: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to down

*Jul 12 22:18:28.471: PPPoE: Unexpected Event!. PPPoE switching Subblockdestroy called

Router#

thanks

Peter Paluch · ‎07-12-2011

Hello Afshan,

I am intrigued by the following line in the debug output:

*Jul 12 22:18:28.467: PPPoE: Failed to add PPPoE switching subblock

However, because you have performed only a single debug at a time, I cannot correlate this event in sequence to other debugs. Therefore, please, issue all these commands:

debug ppp negotiation

debug ppp error

debug pppoe events

debug pppoe errors

and post the debug output of all these four debugs activated at the same time. Thank you!

Best regards,

Peter

afshan_nava · ‎07-12-2011

Peter

me too... i googled that error the first day i got this problem, unfortunately could not find anything on it....

anyway... here u go with the output u requested...

Router#debug ppp negotiation

PPP protocol negotiation debugging is on

Router#debug ppp error

PPP protocol errors debugging is on

Router#debug pppoe events

PPPoE protocol events debugging is on

Router#debug pppoe errors

*Jul 13 06:02:24.631: padi timer expired

PPPoE protocol errors debugging is on

Router#

*Jul 13 06:02:26.679: padi timer expired

*Jul 13 06:02:28.727: padi timer expired

*Jul 13 06:02:30.775: padi timer expired

*Jul 13 06:03:36.367: %LINK-3-UPDOWN: Interface ATM0, changed state to up

*Jul 13 06:03:37.367: %LINEPROTO-5-UPDOWN: Line protocol on Interface ATM0, changed state to up

*Jul 13 06:03:38.367: padi timer expired

*Jul 13 06:03:40.415: padi timer expired

*Jul 13 06:03:41.423: PPPoE:ATM0.1 8/35, Got ATM VC Event

*Jul 13 06:03:42.463: padi timer expired

*Jul 13 06:03:42.463: Sending PADI: vc=8/35

*Jul 13 06:03:42.491: PPPoE 0: I PADO R:0018.82d3.bc99 L:1cdf.0f12.ea34 8/35 ATM0.1

*Jul 13 06:03:42.875: PPPoE 0: I PADO R:00e0.fcb7.4462 L:1cdf.0f12.ea34 8/35 ATM0.1

*Jul 13 06:03:44.511: PPPOE: we've got our pado and the pado timer went off

*Jul 13 06:03:44.511: OUT PADR from PPPoE Session

*Jul 13 06:03:44.539: PPPoE 4776: I PADS R:0018.82d3.bc99 L:1cdf.0f12.ea34 8/35 ATM0.1

*Jul 13 06:03:44.539: IN PADS from PPPoE Session

*Jul 13 06:03:44.543: %DIALER-6-BIND: Interface Vi1 bound to profile Di0

*Jul 13 06:03:44.543: PPPoE: Virtual Access interface obtained.

*Jul 13 06:03:44.543: PPPoE : encap string prepared

*Jul 13 06:03:44.543: [0]PPPoE 4776: data path set to PPPoE Client

*Jul 13 06:03:44.547: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to up

*Jul 13 06:03:44.547: Vi1 PPP: Sending cstate UP notification

*Jul 13 06:03:44.547: Vi1 PPP: Processing CstateUp message

*Jul 13 06:03:44.575: PPP: Alloc Context [850226C4]

*Jul 13 06:03:44.575: ppp1 PPP: Phase is ESTABLISHING

*Jul 13 06:03:44.575: Vi1 PPP: Using dialer call direction

*Jul 13 06:03:44.575: Vi1 PPP: Treating connection as a callout

*Jul 13 06:03:44.575: Vi1 PPP: Session handle[8C000001] Session id[1]

*Jul 13 06:03:44.575: Vi1 LCP: Event[OPEN] State[Initial to Starting]

*Jul 13 06:03:44.575: Vi1 PPP: No remote authentication for call-out

*Jul 13 06:03:44.575: Vi1 LCP: O CONFREQ [Starting] id 1 len 10

*Jul 13 06:03:44.575: Vi1 LCP: MagicNumber 0xDF189141 (0x0506DF189141)

*Jul 13 06:03:44.575: Vi1 LCP: Event[UP] State[Starting to REQsent]

*Jul 13 06:03:44.599: Vi1 LCP: I CONFACK [REQsent] id 1 len 10

*Jul 13 06:03:44.599: Vi1 LCP: MagicNumber 0xDF189141 (0x0506DF189141)

*Jul 13 06:03:44.599: Vi1 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]

*Jul 13 06:03:46.587: Vi1 LCP: O CONFREQ [ACKrcvd] id 2 len 10

*Jul 13 06:03:46.587: Vi1 LCP: MagicNumber 0xDF189141 (0x0506DF189141)

*Jul 13 06:03:46.587: Vi1 LCP: Event[Timeout+] State[ACKrcvd to REQsent]

*Jul 13 06:03:46.607: Vi1 LCP: I CONFACK [REQsent] id 2 len 10

*Jul 13 06:03:46.607: Vi1 LCP: MagicNumber 0xDF189141 (0x0506DF189141)

*Jul 13 06:03:46.611: Vi1 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]

*Jul 13 06:03:47.523: Vi1 LCP: I CONFREQ [ACKrcvd] id 1 len 19

*Jul 13 06:03:47.523: Vi1 LCP: MRU 1460 (0x010405B4)

*Jul 13 06:03:47.523: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 13 06:03:47.523: Vi1 LCP: MagicNumber 0x06020117 (0x050606020117)

*Jul 13 06:03:47.523: Vi1 LCP: O CONFACK [ACKrcvd] id 1 len 19

*Jul 13 06:03:47.523: Vi1 LCP: MRU 1460 (0x010405B4)

*Jul 13 06:03:47.523: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 13 06:03:47.523: Vi1 LCP: MagicNumber 0x06020117 (0x050606020117)

*Jul 13 06:03:47.523: Vi1 LCP: Event[Receive ConfReq+] State[ACKrcvd to Open]

*Jul 13 06:03:47.547: Vi1 PPP: Phase is AUTHENTICATING, by the peer

*Jul 13 06:03:47.547: Vi1 LCP: State is Open

*Jul 13 06:03:47.547: Vi1 CHAP: I CHALLENGE id 1 len 21

*Jul 13 06:03:47.547: Vi1 CHAP: No name received from peer

*Jul 13 06:03:47.547: Vi1 CHAP: Using hostname from interface CHAP

*Jul 13 06:03:47.547: Vi1 CHAP: Using password from interface CHAP

*Jul 13 06:03:47.547: Vi1 CHAP: O RESPONSE id 1 len 29 from "s4647092"

*Jul 13 06:03:47.611: Vi1 CHAP: I SUCCESS id 1 len 35 msg is "Authentication success,Welcome!"

*Jul 13 06:03:47.611: Vi1 PPP: Phase is FORWARDING, Attempting Forward

*Jul 13 06:03:47.619: Vi1 PPP: Queue IPCP code[1] id[0]

*Jul 13 06:03:47.619: Vi1 PPP DISC: Lower Layer disconnected

*Jul 13 06:03:47.619: Vi1 LCP: O TERMREQ [Open] id 3 len 4

*Jul 13 06:03:47.619: Vi1 LCP: Event[CLOSE] State[Open to Closing]

*Jul 13 06:03:47.619: Vi1 PPP: Phase is TERMINATING

*Jul 13 06:03:47.623: PPPoE : Shutting down client session

*Jul 13 06:03:47.623: [0]PPPoE 4776: O PADT R:0018.82d3.bc99 L:1cdf.0f12.ea34 8/35 ATM0.1

*Jul 13 06:03:47.623: PPPoE: Failed to add PPPoE switching subblock

*Jul 13 06:03:47.623: %DIALER-6-UNBIND: Interface Vi1 unbound from profile Di0

*Jul 13 06:03:47.623: Vi1 PPP: Block vaccess from being freed [0x10]

*Jul 13 06:03:47.623: Vi1 LCP: Event[DOWN] State[Closing to Initial]

*Jul 13 06:03:47.623: Vi1 PPP: Unlocked by [0x10] Still Locked by [0x0]

*Jul 13 06:03:47.623: Vi1 PPP: Free previously blocked vaccess

*Jul 13 06:03:47.623: Vi1 PPP: Phase is DOWN

*Jul 13 06:03:47.627: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to down

*Jul 13 06:03:47.627: PPPoE: Unexpected Event!. PPPoE switching Subblockdestroy called

*Jul 13 06:03:47.651: PPPoE 4776: I PADT R:0018.82d3.bc99 L:1cdf.0f12.ea34 8/35 ATM0.1

*Jul 13 06:03:50.611: PPPoE 17056: I PADT R:0018.82d3.bc99 L:001f.9f4a.86c2 8/35 ATM0.1

*Jul 13 06:04:07.807: Sending PADI: vc=8/35

*Jul 13 06:04:07.835: PPPoE 0: I PADO R:0018.82d3.bc99 L:1cdf.0f12.ea34 8/35 ATM0.1

*Jul 13 06:04:07.923: PPPoE 0: I PADO R:00e0.fcb7.4462 L:1cdf.0f12.ea34 8/35 ATM0.1

*Jul 13 06:04:09.855: PPPOE: we've got our pado and the pado timer went off

*Jul 13 06:04:09.855: OUT PADR from PPPoE Session

*Jul 13 06:04:09.883: PPPoE 26402: I PADS R:0018.82d3.bc99 L:1cdf.0f12.ea34 8/35 ATM0.1

*Jul 13 06:04:09.883: IN PADS from PPPoE Session

*Jul 13 06:04:09.883: %DIALER-6-BIND: Interface Vi1 bound to profile Di0

*Jul 13 06:04:09.883: PPPoE: Virtual Access interface obtained.

*Jul 13 06:04:09.883: PPPoE : encap string prepared

*Jul 13 06:04:09.883: [0]PPPoE 26402: data path set to PPPoE Client

*Jul 13 06:04:09.887: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to up

*Jul 13 06:04:09.887: Vi1 PPP: Sending cstate UP notification

*Jul 13 06:04:09.887: Vi1 PPP: Processing CstateUp message

*Jul 13 06:04:09.895: PPP: Alloc Context [850226C4]

*Jul 13 06:04:09.895: ppp2 PPP: Phase is ESTABLISHING

*Jul 13 06:04:09.895: Vi1 PPP: Using dialer call direction

*Jul 13 06:04:09.895: Vi1 PPP: Treating connection as a callout

*Jul 13 06:04:09.895: Vi1 PPP: Session handle[98000002] Session id[2]

*Jul 13 06:04:09.895: Vi1 LCP: Event[OPEN] State[Initial to Starting]

*Jul 13 06:04:09.895: Vi1 PPP: No remote authentication for call-out

*Jul 13 06:04:09.895: Vi1 LCP: O CONFREQ [Starting] id 1 len 10

*Jul 13 06:04:09.895: Vi1 LCP: MagicNumber 0xDF18F42A (0x0506DF18F42A)

*Jul 13 06:04:09.895: Vi1 LCP: Event[UP] State[Starting to REQsent]

*Jul 13 06:04:09.919: Vi1 LCP: I CONFACK [REQsent] id 1 len 10

*Jul 13 06:04:09.919: Vi1 LCP: MagicNumber 0xDF18F42A (0x0506DF18F42A)

*Jul 13 06:04:09.919: Vi1 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]

*Jul 13 06:04:11.899: Vi1 LCP: O CONFREQ [ACKrcvd] id 2 len 10

*Jul 13 06:04:11.899: Vi1 LCP: MagicNumber 0xDF18F42A (0x0506DF18F42A)

*Jul 13 06:04:11.899: Vi1 LCP: Event[Timeout+] State[ACKrcvd to REQsent]

*Jul 13 06:04:11.923: Vi1 LCP: I CONFACK [REQsent] id 2 len 10

*Jul 13 06:04:11.923: Vi1 LCP: MagicNumber 0xDF18F42A (0x0506DF18F42A)

*Jul 13 06:04:11.923: Vi1 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]

*Jul 13 06:04:12.875: Vi1 LCP: I CONFREQ [ACKrcvd] id 1 len 19

*Jul 13 06:04:12.875: Vi1 LCP: MRU 1460 (0x010405B4)

*Jul 13 06:04:12.875: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 13 06:04:12.875: Vi1 LCP: MagicNumber 0x06026D75 (0x050606026D75)

*Jul 13 06:04:12.875: Vi1 LCP: O CONFACK [ACKrcvd] id 1 len 19

*Jul 13 06:04:12.875: Vi1 LCP: MRU 1460 (0x010405B4)

*Jul 13 06:04:12.875: Vi1 LCP: AuthProto CHAP (0x0305C22305)

*Jul 13 06:04:12.875: Vi1 LCP: MagicNumber 0x06026D75 (0x050606026D75)

*Jul 13 06:04:12.875: Vi1 LCP: Event[Receive ConfReq+] State[ACKrcvd to Open]

*Jul 13 06:04:12.891: Vi1 PPP: Phase is AUTHENTICATING, by the peer

*Jul 13 06:04:12.891: Vi1 LCP: State is Open

*Jul 13 06:04:12.899: Vi1 CHAP: I CHALLENGE id 1 len 21

*Jul 13 06:04:12.899: Vi1 CHAP: No name received from peer

*Jul 13 06:04:12.899: Vi1 CHAP: Using hostname from interface CHAP

*Jul 13 06:04:12.899: Vi1 CHAP: Using password from interface CHAP

*Jul 13 06:04:12.899: Vi1 CHAP: O RESPONSE id 1 len 29 from "s4647092"

*Jul 13 06:04:12.955: Vi1 CHAP: I SUCCESS id 1 len 35 msg is "Authentication success,Welcome!"

*Jul 13 06:04:12.955: Vi1 PPP: Phase is FORWARDING, Attempting Forward

*Jul 13 06:04:12.963: Vi1 PPP: Queue IPCP code[1] id[0]

*Jul 13 06:04:12.963: Vi1 PPP DISC: Lower Layer disconnected

*Jul 13 06:04:12.963: Vi1 LCP: O TERMREQ [Open] id 3 len 4

*Jul 13 06:04:12.963: Vi1 LCP: Event[CLOSE] State[Open to Closing]

*Jul 13 06:04:12.963: Vi1 PPP: Phase is TERMINATING

*Jul 13 06:04:12.963: PPPoE : Shutting down client session

*Jul 13 06:04:12.963: [0]PPPoE 26402: O PADT R:0018.82d3.bc99 L:1cdf.0f12.ea34 8/35 ATM0.1

*Jul 13 06:04:12.963: PPPoE: Failed to add PPPoE switching subblock

*Jul 13 06:04:12.967: %DIALER-6-UNBIND: Interface Vi1 unbound from profile Di0

*Jul 13 06:04:12.967: Vi1 PPP: Block vaccess from being freed [0x10]

*Jul 13 06:04:12.967: Vi1 LCP: Event[DOWN] State[Closing to Initial]

*Jul 13 06:04:12.967: Vi1 PPP: Unlocked by [0x10] Still Locked by [0x0]

*Jul 13 06:04:12.967: Vi1 PPP: Free previously blocked vaccess

*Jul 13 06:04:12.967: Vi1 PPP: Phase is DOWN

*Jul 13 06:04:12.967: %LINK-3-UPDOWN: Interface Virtual-Access1, changed state to down

*Jul 13 06:04:12.971: PPPoE: Unexpected Event!. PPPoE switching Subblockdestroy called

*Jul 13 06:04:12.995: PPPoE 26402: I PADT R:0018.82d3.bc99 L:1cdf.0f12.ea34 8/35 ATM0.1

Router#

Peter Paluch · ‎07-12-2011

Afshan,

This is a totally blind shot... but can you use the no ip address on your Dialer0 interface and see if the connection is stable then? I cannot help the feeling that this is somehow related to the IPCP initialization. Sure, the DSL connection would be without any IP address and thus unusable in essence, but I want at least to see if it stops flapping.

Again, please, if using the no ip address won't help, include the above debugs.

What is the version of your IOS? Also, as Paolo suggested, the show dsl interface output may be interesting as well.

Best regards,

Peter

afshan_nava · ‎07-13-2011

Peter

The "no ip address" did not help... the debug output is the same.....

i did she show dsl interface, and this is the adsl firmware i guess..

Init FW: init_AMR-4.0.015_no_bist.bin

Operation FW: AMR-4.0.015.bin

FW Source: embedded

FW Version: 4.0.15

and also the ios

c880data-universalk9-mz.150-1.M3.bin

Peter Paluch · ‎07-14-2011

Afshan,

So far, we have tried everything reasonable. We streamlined the configuration and removed unnecessary commands, we have verified its correctness, we have even reviewed the debugs closely. We have gone as far as stripping every functionality from the Dialer interface and leaving it to build a basic plain PPP connection with practically no Layer3 protocol being transported or even allowed on it. Everything was unsuccessful. At this point, I am willing to say that this looks like an IOS bug.

Do you have an option of trying a more recent IOS version for your router, i.e. 15.1(4)M, or perhaps downgrading back to 12.4(24)T5?

Also, do you have a support contract with Cisco? If so then you can raise a TAC ticket directly from this thread. I guess Cisco TAC engineers would have a pretty good overview of what is going on basing on the wealth of debug information and experiments we've done in our conversations here.

Best regards,

Peter

afshan_nava · ‎07-14-2011

Thanks Buddy

i will try other IOS's....neither did i want to change the OS blindly...... i dont have a support contract for this.... but i can download some softwares.... let me try

Thanks again

afshan_nava · ‎07-15-2011

Hi peter

i changed the IOS to c880data-universalk9-mz.151-4.M1.bin and it started working

THanks Buddy

Afshan