05-25-2003 11:35 PM - edited 03-02-2019 07:37 AM
Hello everyone,
I have a Cisco 1000 running IOS 12.0(15). It has only one ISDN interface and we dial only 1 location from here. No dialer profiles. Simple overloading NAT on the BRI interface. The connection ran fine for a while, we didnt change anything. Recently we have problem connecting. What usually happens is that the connection gets stuck either in the LCP phase or in the CHAP authentication phase. Stuck as in sending the auth info over and over again (and receiving responses from the other side, up to a point). Here is a log of the last try:
00:12:58: ISDN BR0: Outgoing call id = 0x8006
00:12:58: ISDN BR0: Event: Call to <phone number> at 64 Kb/s
00:12:58: ISDN BR0: TX -> SETUP pd = 8 callref = 0x06
00:12:58: Bearer Capability i = 0x8890
00:12:58: Channel ID i = 0x83
00:12:58: Called Party Number i = 0x80, '<phone number>'
00:12:58: ISDN BR0: RX <- SETUP_ACK pd = 8 callref = 0x86
00:12:58: Channel ID i = 0x89
00:12:58: ISDN BR0: received HOST_INFORMATION call_id 0x8006
00:13:01: ISDN Event: dsl 0 call_id 0x8006 B channel assigned by switch 0
ISDN BR0: RX <- CONNECT pd = 8 callref = 0x86
00:13:01: Date/Time i = 0x03051A0916
00:13:01: Connected Number i = 0x00C3
00:13:01: ISDN BR0: received HOST_CONNECT call_id 0x8006
00:13:01: %LINK-3-UPDOWN: Interface BRI0:1, changed state to up
00:13:01: %ISDN-6-CONNECT: Interface BRI0:1 is now connected to <phone number>
00:13:01: BR0:1 PPP: Treating connection as a callout
00:13:01: BR0:1 PPP: Phase is ESTABLISHING, Active Open
00:13:01: BR0:1 LCP: O CONFREQ [Closed] id 57 len 15
00:13:01: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:13:01: BR0:1 LCP: MagicNumber 0xE02AC170 (0x0506E02AC170)
00:13:01: ISDN BR0: Event: Connected to <phone number> on B1 at 64 Kb/s
00:13:01: ISDN BR0: TX -> CONNECT_ACK pd = 8 callref = 0x06
00:13:01: ISDN BR0: RX <- FACILITY pd = 8 callref = 0x86
00:13:01: Facility i = 0x91A1130202F6A2020122300AA1053003020101820100
00:13:01: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 1
00:13:01: ISDN BR0: received HOST_FACILITY_INVOKE call_id 0x8006
Facility i = 0x91A1130202F6A2020122300AA1053003020101820100
00:13:01: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 1
00:13:01: BRI0:1: AOC-D Recorded Units = 1
00:13:01: BR0:1 LCP: I CONFREQ [REQsent] id 218 len 15
00:13:01: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:13:01: BR0:1 LCP: MagicNumber 0x08215670 (0x050608215670)
00:13:01: BR0:1 LCP: O CONFACK [REQsent] id 218 len 15
00:13:01: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:13:01: BR0:1 LCP: MagicNumber 0x08215670 (0x050608215670)
00:13:01: BR0:1 LCP: I CONFACK [ACKsent] id 57 len 15
00:13:01: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:13:01: BR0:1 LCP: MagicNumber 0xE02AC170 (0x0506E02AC170)
00:13:01: BR0:1 LCP: State is Open
00:13:01: BR0:1 PPP: Phase is AUTHENTICATING, by both
00:13:01: BR0:1 CHAP: Using alternate hostname AOEI_14
00:13:01: BR0:1 CHAP: O CHALLENGE id 2 len 28 from "AOEI_14"
00:13:02: BR0:1 CHAP: I CHALLENGE id 17 len 29 from "MEM_AOEI"
00:13:02: BR0:1 CHAP: Using alternate hostname AOEI_14
00:13:02: BR0:1 CHAP: O RESPONSE id 17 len 28 from "AOEI_14"
00:13:07: %ISDN-6-CONNECT: Interface BRI0:1 is now connected to <phone number>
00:13:11: ISDN BR0: RX <- FACILITY pd = 8 callref = 0x86
00:13:11: Facility i = 0x91A1130202F6A4020122300AA1053003020103820100
00:13:11: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 3
00:13:11: ISDN BR0: received HOST_FACILITY_INVOKE call_id 0x8006
Facility i = 0x91A1130202F6A4020122300AA1053003020103820100
00:13:11: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 3
00:13:11: BRI0:1: AOC-D Recorded Units = 3
00:13:11: BR0:1 CHAP: Using alternate hostname AOEI_14
00:13:11: BR0:1 CHAP: O CHALLENGE id 3 len 28 from "AOEI_14"
00:13:11: BR0:1 CHAP: O RESPONSE id 17 len 28 from "AOEI_14"
00:13:12: BR0:1 CHAP: I CHALLENGE id 18 len 29 from "MEM_AOEI"
00:13:12: BR0:1 CHAP: Using alternate hostname AOEI_14
00:13:12: BR0:1 CHAP: O RESPONSE id 18 len 28 from "AOEI_14"
00:13:21: ISDN BR0: RX <- FACILITY pd = 8 callref = 0x86
00:13:21: Facility i = 0x91A1130202F6A6020122300AA1053003020105820100
00:13:21: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 5
00:13:21: ISDN BR0: received HOST_FACILITY_INVOKE call_id 0x8006
Facility i = 0x91A1130202F6A6020122300AA1053003020105820100
00:13:21: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 5
00:13:31: ISDN BR0: received HOST_FACILITY_INVOKE call_id 0x8006
Facility i = 0x91A1130202F6AA020122300AA1053003020107820100
00:13:31: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 7
00:13:31: BRI0:1: AOC-D Recorded Units = 7
00:13:31: BR0:1 CHAP: Using alternate hostname AOEI_14
00:13:31: BR0:1 CHAP: O CHALLENGE id 5 len 28 from "AOEI_14"
00:13:31: BR0:1 CHAP: O RESPONSE id 19 len 28 from "AOEI_14"
00:13:32: BR0:1 CHAP: I CHALLENGE id 20 len 29 from "MEM_AOEI"
00:13:32: BR0:1 CHAP: Using alternate hostname AOEI_14
00:13:32: BR0:1 CHAP: O RESPONSE id 20 len 28 from "AOEI_14"
00:13:41: ISDN BR0: RX <- FACILITY pd = 8 callref = 0x86
00:13:41: Facility i = 0x91A1130202F6AC020122300AA1053003020109820100
00:13:41: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 9
00:13:41: ISDN BR0: received HOST_FACILITY_INVOKE call_id 0x8006
Facility i = 0x91A1130202F6AC020122300AA1053003020109820100
00:13:41: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 9
00:13:41: BRI0:1: AOC-D Recorded Units = 9
00:13:41: BR0:1 CHAP: Using alternate hostname AOEI_14
00:13:41: BR0:1 CHAP: O CHALLENGE id 6 len 28 from "AOEI_14"
00:13:41: BR0:1 CHAP: O RESPONSE id 20 len 28 from "AOEI_14"
00:13:42: BR0:1 CHAP: I CHALLENGE id 21 len 29 from "MEM_AOEI"
00:13:42: BR0:1 CHAP: Using alternate hostname AOEI_14
00:13:42: BR0:1 CHAP: O RESPONSE id 21 len 28 from "AOEI_14"
00:13:51: Facility i = 0x91A1130202F6AD020122300AA105300302010B820100
00:13:51: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 11
00:13:51: ISDN BR0: received HOST_FACILITY_INVOKE call_id 0x8006
Facility i = 0x91A1130202F6AD020122300AA105300302010B820100
00:13:51: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 11
00:13:51: BRI0:1: AOC-D Recorded Units = 11
00:13:51: BR0:1 CHAP: Using alternate hostname AOEI_14
00:13:51: BR0:1 CHAP: O CHALLENGE id 7 len 28 from "AOEI_14"
00:13:51: BR0:1 CHAP: O RESPONSE id 21 len 28 from "AOEI_14"
00:13:52: BR0:1 CHAP: I CHALLENGE id 22 len 29 from "MEM_AOEI"
00:13:52: BR0:1 CHAP: Using alternate hostname AOEI_14
00:13:52: BR0:1 CHAP: O RESPONSE id 22 len 28 from "AOEI_14"
00:14:01: ISDN BR0: RX <- FACILITY pd = 8 callref = 0x86
00:14:01: Facility i = 0x91A1130202F6AF020122300AA105300302010D820100
00:14:01: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 13
00:14:01: ISDN BR0: received HOST_FACILITY_INVOKE call_id 0x8006
Facility i = 0x91A1130202F6AF020122300AA105300302010D820100
00:14:01: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 13
00:14:01: BRI0:1: AOC-D Recorded Units = 13
...... cut due to post restrictions ......
00:14:51: BR0:1 PPP: Phase is TERMINATING
00:14:51: BR0:1 LCP: O TERMREQ [Open] id 58 len 4
00:14:51: ISDN BR0: RX <- FACILITY pd = 8 callref = 0x86
00:14:51: Facility i = 0x91A1130202F6BB020122300AA1053003020118820100
00:14:52: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 24
00:14:52: ISDN BR0: received HOST_FACILITY_INVOKE call_id 0x8006
Facility i = 0x91A1130202F6BB020122300AA1053003020118820100
00:14:52: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 24
00:14:52: BRI0:1: AOC-D Recorded Units = 24
00:14:53: BR0:1 LCP: I TERMREQ [TERMsent] id 219 len 4
00:14:53: BR0:1 LCP: O TERMACK [TERMsent] id 219 len 4
00:14:53: BR0:1 LCP: TIMEout: State TERMsent
00:14:53: BR0:1 LCP: O TERMREQ [TERMsent] id 59 len 4
00:14:55: BR0:1 LCP: I TERMREQ [TERMsent] id 220 len 4
00:14:55: BR0:1 LCP: O TERMACK [TERMsent] id 220 len 4
00:14:55: BR0:1 LCP: TIMEout: State TERMsent
00:14:55: BR0:1 LCP: O TERMREQ [TERMsent] id 60 len 4
00:14:57: ISDN BR0: RX <- DISCONNECT pd = 8 callref = 0x86
00:14:57: Cause i = 0x8090 - Normal call clearing
00:14:57: Facility i = 0x91A1130202F6BD020122300AA1053003020119820101
00:14:57: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 25
00:14:57: ISDN BR0: received HOST_FACILITY_INVOKE call_id 0x8006
Cause i = 0x8090 - Normal call clearing
00:14:57: Facility i = 0x91A1130202F6BD020122300AA1053003020119820101
00:14:57: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 25
00:14:57: BRI0:1: AOC-D Recorded Units = 25
00:14:57: ISDN BR0: received HOST_DISCONNECT call_id 0x8006
00:14:57: ISDN BR0: Event: Call to <unknown> was hung up.
00:14:57: %ISDN-6-DISCONNECT: Interface BRI0:1 disconnected from <phone number> , call lasted 116 seconds
00:14:57: %LINK-3-UPDOWN: Interface BRI0:1, changed state to down
00:14:57: BR0:1 LCP: State is Closed
00:14:57: BR0:1 PPP: Phase is DOWN
00:14:57: ISDN BR0: TX -> RELEASE pd = 8 callref = 0x06
00:14:57: ISDN BR0: RX <- RELEASE_COMP pd = 8 callref = 0x86
Sometimes I could reload the router and the connection would work again, without me changing anything. Not anymore, it seems.
Any help or ideas would be greatly appreciated.
Thank you,
Stefan
05-26-2003 12:25 AM
Stefan, we are not seeing incoming RESPONSE from "MEM_AOEI" .
Is "MEM_AOEI" doing authentication via some external AAA server?
If yes, then is that AAA server several hops away from "MEM_AOEI" ?
Could you capture the same debugs from "MEM_AOEI" ?
~Zulfi
05-26-2003 12:49 AM
Unfortunately I dont have the config or debugs from the other side. But I doubt that's the problem because just now I tried again and this time it got stuck in the LCP phase.
00:50:10: BRI0:1: AOC-D Recorded Units = 5
00:50:10: ISDN BR0: received HOST_DISCONNECT call_id 0x800A
00:50:10: ISDN BR0: Event: Call to
00:50:10: %ISDN-6-DISCONNECT: Interface BRI0:1 disconnected from 0061282491800 , call lasted 21 seconds
00:50:10: %LINK-3-UPDOWN: Interface BRI0:1, changed state to down
00:50:10: BR0:1 LCP: State is Closed
00:50:10: BR0:1 PPP: Phase is DOWN
00:50:10: ISDN BR0: TX -> RELEASE pd = 8 callref = 0x0A
00:50:10: ISDN BR0: RX <- RELEASE_COMP pd = 8 callref = 0x8A
00:50:10: ISDN BR0: Outgoing call id = 0x800B
00:50:10: ISDN BR0: Event: Call to 0061282491800 at 64 Kb/s
00:50:10: ISDN BR0: TX -> SETUP pd = 8 callref = 0x0B
00:50:10: Bearer Capability i = 0x8890
00:50:10: Channel ID i = 0x83
00:50:10: Called Party Number i = 0x80, '0061282491800'
00:50:11: ISDN BR0: RX <- SETUP_ACK pd = 8 callref = 0x8B
00:50:11: Channel ID i = 0x89
00:50:11: ISDN BR0: received HOST_INFORMATION call_id 0x800B
00:50:13: ISDN Event: dsl 0 call_id 0x800B B channel assigned by switch 0
ISDN BR0: RX <- CONNECT pd = 8 callref = 0x8B
00:50:13: Date/Time i = 0x03051A093B
00:50:13: Connected Number i = 0x00C3
00:50:13: ISDN BR0: received HOST_CONNECT call_id 0x800B
00:50:13: %LINK-3-UPDOWN: Interface BRI0:1, changed state to up
00:50:13: %ISDN-6-CONNECT: Interface BRI0:1 is now connected to 0061282491800
00:50:13: BR0:1 PPP: Treating connection as a callout
00:50:13: BR0:1 PPP: Phase is ESTABLISHING, Active Open
00:50:13: BR0:1 LCP: O CONFREQ [Closed] id 106 len 15
00:50:13: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:13: BR0:1 LCP: MagicNumber 0xE04CD1A3 (0x0506E04CD1A3)
00:50:13: ISDN BR0: Event: Connected to 0061282491800 on B1 at 64 Kb/s
00:50:13: ISDN BR0: TX -> CONNECT_ACK pd = 8 callref = 0x0B
00:50:13: ISDN BR0: RX <- FACILITY pd = 8 callref = 0x8B
00:50:13: Facility i = 0x91A1130202F8AE020122300AA1053003020101820100
00:50:13: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 1
00:50:13: ISDN BR0: received HOST_FACILITY_INVOKE call_id 0x800B
Facility i = 0x91A1130202F8AE020122300AA1053003020101820100
00:50:13: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 1
00:50:13: BRI0:1: AOC-D Recorded Units = 1
00:50:14: BR0:1 LCP: I CONFREQ [REQsent] id 31 len 15
00:50:14: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:14: BR0:1 LCP: MagicNumber 0x0843240B (0x05060843240B)
00:50:14: BR0:1 LCP: O CONFACK [REQsent] id 31 len 15
00:50:14: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:14: BR0:1 LCP: MagicNumber 0x0843240B (0x05060843240B)
00:50:15: BR0:1 LCP: TIMEout: State ACKsent
00:50:15: BR0:1 LCP: O CONFREQ [ACKsent] id 107 len 15
00:50:15: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:15: BR0:1 LCP: MagicNumber 0xE04CD1A3 (0x0506E04CD1A3)
00:50:16: BR0:1 LCP: I CONFREQ [ACKsent] id 32 len 15
00:50:16: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:16: BR0:1 LCP: MagicNumber 0x0843240B (0x05060843240B)
00:50:16: BR0:1 LCP: O CONFACK [ACKsent] id 32 len 15
00:50:16: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:16: BR0:1 LCP: MagicNumber 0x0843240B (0x05060843240B)
00:50:17: BR0:1 LCP: TIMEout: State ACKsent
00:50:17: BR0:1 LCP: O CONFREQ [ACKsent] id 108 len 15
00:50:17: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:17: BR0:1 LCP: MagicNumber 0xE04CD1A3 (0x0506E04CD1A3)
00:50:18: BR0:1 LCP: I CONFREQ [ACKsent] id 33 len 15
00:50:18: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:18: BR0:1 LCP: MagicNumber 0x0843240B (0x05060843240B)
00:50:18: BR0:1 LCP: O CONFACK [ACKsent] id 33 len 15
00:50:18: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:18: BR0:1 LCP: MagicNumber 0x0843240B (0x05060843240B)
00:50:19: %ISDN-6-CONNECT: Interface BRI0:1 is now connected to 0061282491800
00:50:19: BR0:1 LCP: TIMEout: State ACKsent
00:50:19: BR0:1 LCP: O CONFREQ [ACKsent] id 109 len 15
00:50:19: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:19: BR0:1 LCP: MagicNumber 0xE04CD1A3 (0x0506E04CD1A3)
00:50:20: BR0:1 LCP: I CONFREQ [ACKsent] id 34 len 15
00:50:20: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:30: BR0:1 LCP: I CONFREQ [ACKsent] id 39 len 15
00:50:30: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:30: BR0:1 LCP: MagicNumber 0x0843240B (0x05060843240B)
00:50:30: BR0:1 LCP: O CONFACK [ACKsent] id 39 len 15
00:50:30: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:30: BR0:1 LCP: MagicNumber 0x0843240B (0x05060843240B)
00:50:31: BR0:1 LCP: TIMEout: State ACKsent
00:50:31: BR0:1 LCP: O CONFREQ [ACKsent] id 115 len 15
00:50:31: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:31: BR0:1 LCP: MagicNumber 0xE04CD1A3 (0x0506E04CD1A3)
00:50:32: BR0:1 LCP: I CONFREQ [ACKsent] id 40 len 15
00:50:32: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:32: BR0:1 LCP: MagicNumber 0x0843240B (0x05060843240B)
00:50:32: BR0:1 LCP: O CONFACK [ACKsent] id 40 len 15
00:50:32: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:32: BR0:1 LCP: MagicNumber 0x0843240B (0x05060843240B)
00:50:33: BR0:1 LCP: TIMEout: State ACKsent
00:50:33: BR0:1 LCP: O CONFREQ [ACKsent] id 116 len 15
00:50:33: BR0:1 LCP: AuthProto CHAP (0x0305C22305)
00:50:33: BR0:1 LCP: MagicNumber 0xE04CD1A3 (0x0506E04CD1A3)
00:50:33: ISDN BR0: RX <- FACILITY pd = 8 callref = 0x8B
00:50:33: Facility i = 0x91A1130202F8B8020122300AA1053003020105820100
00:50:33: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 5
00:50:33: ISDN BR0: received HOST_FACILITY_INVOKE call_id 0x800B
Facility i = 0x91A1130202F8B8020122300AA1053003020105820100
00:50:33: - ETSI Supplementary Service, Invoke, AOC-D Charging Units: 5
00:50:33: BRI0:1: AOC-D Recorded Units = 5
An so on until it disconnects eventually.
05-26-2003 12:56 AM
But if you notice , the reason could still be related. We are not seeing an incoming CONFACK from the other side, just as we do not see CHAP RESPONSE from him. It could be either, that the other side is not sending that, or it is but its getting lost in the middle, or its getting all the way through to the BRI interface of the 1000 router but for some reason the interface is dropping it or marking it as error.
~Zulfi
05-26-2003 01:08 AM
You're right, in the first debug set it could be that they do not reply to our request with a CHAP RESPONSE. But in the second debug set we dont even get to that part, the CHAP phase does not begin. What could be the explanation ?
05-26-2003 01:15 AM
Packet loss!
But do a "show int bri0:1" to see if you see inbound CRC errors.
Also, I would try a different IOS to rule out some code malfunction even though does not really look like a bug right now.
~Zulfi
05-26-2003 01:25 AM
I set up the connection on a 2610XM with 12.2.13, just to test it. I got the same errors, the same debugs as in my second set, where it gets stuck at LCP phase, I dont get to CHAP. So different router, different IOS, different ISDN line, same error. And no, I dont get CRC errors on the 1000 nor on the 2600. That would rule out a bug in the IOS I think. Unfortunately I dont have access to the other side as of yet. But I still dont get the behaviour ;)
05-26-2003 01:29 AM
So as you have guessed it right, your side is definitely fine. Look into the other side of this picture. We need info from that end for sure. You might also want to open up a case.
~Zulfi
05-26-2003 11:18 AM
Since two platforms exhibit the same behaviour this probably apprears to be an issue with the remote router or maybe within the network (packet loss / corruption).
We can ensure that all stacks on our router are working correctly + the circuit till the telco switch is ok by trying a isdn bri loopback test:
http://www.cisco.com/warp/public/471/bri_loopback_call.html
Are we calling the same remote end router always? Can we try making a test call to another isdn router?
Thanks, Mak.
05-26-2003 12:24 PM
I belive the ISDN line is fine because I can make connection to another location. I will do the lookback test tomorrow when I get to work, tho. The original call, the one not working, is between Germany and Australia. That's a lot of places where things can go wrong in the ISDN cloud.
Anyway, I am waiting for debug info from the remote router. Will post back as soon as I have details.
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