I'm working with an ISP which is providing ADSL services. My ADSL connection is bouncing up and down and I'm wondering if there is any indication that can be derived from any debug output that would point the finger at my 6 year old ADSL NIM. I've looked at debug ppp verbose, which doesn't display anything too interesting as to why the connection is dropped, so is there anything else I can output to discover the reason as to why my ADSL is dropping?
Appreciate your help.
I appreciate the feedback. Alas I was unable to determine by debug where the tear down of the line was happening. However, accessing the GUI revealed a huge amount of Corrected Blocks and Uncorrected Blocks! So we ordered a new ADSL NIM, replaced it and that has resolved the issue. Just a bad card after 6 years.
Thanks again.
Here is some output of "debug ppp verbose":
2012.12.04 11:09:06 INTERFACE_STATUS.adsl 1/1 changed state to up
2012.12.04 11:09:06 INTERFACE_STATUS.atm 1.1 changed state to up
2012.12.04 11:09:07 PPP.NEGOTIATION PPPtx[atm 1.1] LCP: Conf-Req ID=26 Len=10 MAGIC(dd092d5c)
2012.12.04 11:09:07 INTERFACE_STATUS.atm 1 changed state to up
2012.12.04 11:09:11 PPP.NEGOTIATION PPPtx[atm 1.1] LCP: Conf-Req ID=27 Len=10 MAGIC(dd092d5c)
2012.12.04 11:09:13 PPP.NEGOTIATION PPPrx[atm 1.1] LCP: Conf-Req ID=2 Len=14 AP(PAP)MAGIC(0d6e7762)
2012.12.04 11:09:13 PPP.NEGOTIATION PPPtx[atm 1.1] LCP: Conf-Nak ID=2 Len=9 AP(CHAP)
2012.12.04 11:09:13 PPP.NEGOTIATION PPPrx[atm 1.1] LCP: Conf-Req ID=3 Len=15 AP(CHAP)MAGIC(0d6e7762)
2012.12.04 11:09:13 PPP.NEGOTIATION PPPtx[atm 1.1] LCP: Conf-Ack ID=3 Len=15 AP(CHAP)MAGIC(0d6e7762)
2012.12.04 11:09:15 PPP.NEGOTIATION PPPtx[atm 1.1] LCP: Conf-Req ID=28 Len=10 MAGIC(dd092d5c)
2012.12.04 11:09:15 PPP.NEGOTIATION PPPrx[atm 1.1] LCP: Conf-Ack ID=28 Len=10 MAGIC(dd092d5c)
2012.12.04 11:09:15 PPP.NEGOTIATION PPPFSM: layer up, Protocol=c021
2012.12.04 11:09:15 PPP.NEGOTIATION atm 1.1: LCP up
2012.12.04 11:09:15 PPP.AUTHENTICATION PPPrx[atm 1.1] CHAP: Challenge ID=1 Len=49 ValLen=16 Name(slkc-dsl-gw19.slkc.qwest.net)
2012.12.04 11:09:15 PPP.AUTHENTICATION PPPtx[atm 1.1] CHAP: Response ID=1 Len=25 ValLen=16 Name(****)
2012.12.04 11:09:15 PPP.AUTHENTICATION PPPrx[atm 1.1] CHAP: Success ID=1 Len=4 Message()
2012.12.04 11:09:15 PPP.NEGOTIATION PPPtx[atm 1.1] IPCP: Conf-Req ID=1 Len=22 IP(0.0.0.0) PriDNS(0.0.0.0) SecDNS(0.0.0.0)
2012.12.04 11:09:15 PPP.NEGOTIATION PPPrx[atm 1.1] IPCP: Conf-Req ID=1 Len=10 IP(67.41.239.211)
2012.12.04 11:09:15 PPP.NEGOTIATION PPPtx[atm 1.1] IPCP: Conf-Ack ID=1 Len=10 IP(67.41.239.211)
2012.12.04 11:09:15 PPP.NEGOTIATION PPPrx[atm 1.1] IPCP: Conf-Nak ID=1 Len=22 IP(70.58.39.***) PriDNS(205.171.3.65) SecDNS(205.171.2.65)
2012.12.04 11:09:15 PPP.NEGOTIATION PPPtx[atm 1.1] IPCP: Conf-Req ID=2 Len=22 IP(70.58.39.***) PriDNS(205.171.3.65) SecDNS(205.171.2.65)
2012.12.04 11:09:15 INTERFACE_STATUS.ppp 1 changed state to up
2012.12.04 11:09:15 PPP.NEGOTIATION PPPrx[atm 1.1] IPCP: Conf-Ack ID=2 Len=22 IP(70.58.39.***) PriDNS(205.171.3.65) SecDNS(205.171.2.65)
2012.12.04 11:09:15 PPP.NEGOTIATION PPPFSM: layer up, Protocol=8021
2012.12.04 11:09:15 PPP.NEGOTIATION ppp 1: IPCP up
2012.12.04 11:09:25 PPP PPPtx[atm 1.1] LCP: Echo-Req MAGIC(dd092d5c)
...
2012.12.04 11:15:35 PPP PPPtx[atm 1.1] LCP: Echo-Req MAGIC(dd092d5c)
2012.12.04 11:15:35 INTERFACE_STATUS.adsl 1/1 changed state to down
2012.12.04 11:15:35 INTERFACE_STATUS.atm 1.1 changed state to down
2012.12.04 11:15:36 PPP.NEGOTIATION ppp 1: IPCP down
2012.12.04 11:15:36 PPP.NEGOTIATION atm 1.1: LCP down
2012.12.04 11:15:36 INTERFACE_STATUS.atm 1 changed state to down
2012.12.04 11:15:36 INTERFACE_STATUS.ppp 1 changed state to down
2012.12.04 11:16:00 INTERFACE_STATUS.atm 1.1 changed state to up
2012.12.04 11:16:01 PPP.NEGOTIATION PPPtx[atm 1.1] LCP: Conf-Req ID=67 Len=10 MAGIC(6a6c0752)
2012.12.04 11:16:01 INTERFACE_STATUS.adsl 1/1 changed state to up
2012.12.04 11:16:01 INTERFACE_STATUS.atm 1 changed state to up
2012.12.04 11:16:05 PPP.NEGOTIATION PPPtx[atm 1.1] LCP: Conf-Req ID=68 Len=10 MAGIC(6a6c0752)
2012.12.04 11:16:05 PPP.NEGOTIATION PPPrx[atm 1.1] LCP: Conf-Req ID=1 Len=14 AP(PAP)MAGIC(0d74c90c)
2012.12.04 11:16:05 PPP.NEGOTIATION PPPtx[atm 1.1] LCP: Conf-Nak ID=1 Len=9 AP(CHAP)
2012.12.04 11:16:05 PPP.NEGOTIATION PPPrx[atm 1.1] LCP: Conf-Req ID=2 Len=15 AP(CHAP)MAGIC(0d74c90c)
2012.12.04 11:16:05 PPP.NEGOTIATION PPPtx[atm 1.1] LCP: Conf-Ack ID=2 Len=15 AP(CHAP)MAGIC(0d74c90c)
2012.12.04 11:16:07 PPP.NEGOTIATION PPPrx[atm 1.1] LCP: Conf-Req ID=3 Len=15 AP(CHAP)MAGIC(0d74c90c)
2012.12.04 11:16:07 PPP.NEGOTIATION PPPtx[atm 1.1] LCP: Conf-Ack ID=3 Len=15 AP(CHAP)MAGIC(0d74c90c)
2012.12.04 11:16:09 PPP.NEGOTIATION PPPtx[atm 1.1] LCP: Conf-Req ID=69 Len=10 MAGIC(6a6c0752)
2012.12.04 11:16:09 PPP.NEGOTIATION PPPrx[atm 1.1] LCP: Conf-Ack ID=69 Len=10 MAGIC(6a6c0752)
2012.12.04 11:16:09 PPP.NEGOTIATION PPPFSM: layer up, Protocol=c021
2012.12.04 11:16:09 PPP.NEGOTIATION atm 1.1: LCP up
2012.12.04 11:16:09 PPP.AUTHENTICATION PPPrx[atm 1.1] CHAP: Challenge ID=1 Len=49 ValLen=16 Name(slkc-dsl-gw19.slkc.qwest.net)
2012.12.04 11:16:09 PPP.AUTHENTICATION PPPtx[atm 1.1] CHAP: Response ID=1 Len=25 ValLen=16 Name(****)
2012.12.04 11:16:09 PPP.AUTHENTICATION PPPrx[atm 1.1] CHAP: Success ID=1 Len=4 Message()
2012.12.04 11:16:09 PPP.NEGOTIATION PPPtx[atm 1.1] IPCP: Conf-Req ID=1 Len=22 IP(0.0.0.0) PriDNS(0.0.0.0) SecDNS(0.0.0.0)
2012.12.04 11:16:09 PPP.NEGOTIATION PPPrx[atm 1.1] IPCP: Conf-Nak ID=1 Len=22 IP(70.58.39.***) PriDNS(205.171.3.65) SecDNS(205.171.2.65)
2012.12.04 11:16:09 PPP.NEGOTIATION PPPtx[atm 1.1] IPCP: Conf-Req ID=2 Len=22 IP(70.58.39.***) PriDNS(205.171.3.65) SecDNS(205.171.2.65)
2012.12.04 11:16:09 PPP.NEGOTIATION PPPrx[atm 1.1] IPCP: Conf-Ack ID=2 Len=22 IP(70.58.39.***) PriDNS(205.171.3.65) SecDNS(205.171.2.65)
2012.12.04 11:16:09 INTERFACE_STATUS.ppp 1 changed state to up
2012.12.04 11:16:11 PPP.NEGOTIATION PPPrx[atm 1.1] IPCP: Conf-Req ID=2 Len=10 IP(67.41.239.211)
2012.12.04 11:16:11 PPP.NEGOTIATION PPPtx[atm 1.1] IPCP: Conf-Ack ID=2 Len=10 IP(67.41.239.211)
2012.12.04 11:16:11 PPP.NEGOTIATION PPPFSM: layer up, Protocol=8021
2012.12.04 11:16:11 PPP.NEGOTIATION ppp 1: IPCP up
2012.12.04 11:16:16 INTERFACE_STATUS.adsl 1/1 changed state to down
2012.12.04 11:16:16 INTERFACE_STATUS.atm 1.1 changed state to down
2012.12.04 11:16:17 PPP.NEGOTIATION ppp 1: IPCP down
2012.12.04 11:16:17 PPP.NEGOTIATION atm 1.1: LCP down
2012.12.04 11:16:17 INTERFACE_STATUS.atm 1 changed state to down
2012.12.04 11:16:17 INTERFACE_STATUS.ppp 1 changed state to down
I'm more familiar with the 3100 series, but could you do a "sh int adsl 1/1" ? That has more info on your actual connection. PPP travels over the ADSL circuit, and you want to resolve at the lowest level first. Or at least I do. For 8 hours a day.
Just to verify, I trimmed the log and yeah... it's not a higher level issue. Definitely something from the ADSL interface to the DSLAM inclusive.
2012.12.04 11:09:06 INTERFACE_STATUS.adsl 1/1 changed state to up
[...]
2012.12.04 11:15:35 INTERFACE_STATUS.adsl 1/1 changed state to down
[...]
2012.12.04 11:16:01 INTERFACE_STATUS.adsl 1/1 changed state to up
[...]
2012.12.04 11:16:16 INTERFACE_STATUS.adsl 1/1 changed state to down
I appreciate the feedback. Alas I was unable to determine by debug where the tear down of the line was happening. However, accessing the GUI revealed a huge amount of Corrected Blocks and Uncorrected Blocks! So we ordered a new ADSL NIM, replaced it and that has resolved the issue. Just a bad card after 6 years.
Thanks again.
I went ahead and flagged the "Correct Answer" on this post to make it more visible and help other members of the community find solutions more easily. If you don't feel like the answer I marked was correct, feel free to come back to this post to unmark it and select another in its place with the applicable buttons. If you have any additional information on this that others may benefit from, please come back to this post to provide an update. If you still need assistance, we would be more than happy to continue working with you on this - just let us know in a reply.
Thanks,
Noor