cancel
Showing results for 
Search instead for 
Did you mean: 
cancel
601
Views
0
Helpful
9
Replies

CHAP Authentication not completing

sra
Level 1
Level 1

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

9 Replies 9

zahmed
Cisco Employee
Cisco Employee

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

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 was hung up.

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.

zahmed
Cisco Employee
Cisco Employee

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

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 ?

zahmed
Cisco Employee
Cisco Employee

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

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 ;)

zahmed
Cisco Employee
Cisco Employee

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

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.

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.