Mailing List Archive: Dial-IN problems with an AS5200

Dial-IN problems with an AS5200

Aug 21, 2003, 3:55 AM

Post #1 of 4 (966 views)

Hi!

I have an strange behavior on an AS5200. Sometimes you can dial-in
without any Problems and sometimes it hangs up.
I've tried different IOS Versions but nothing helps.
(12.0(7)T3, 12.1(20), 12.1(10)AA)

The failure that occurs is always the same. It doesn't matter
which IOS Version I try.
Does anyone has seen a failure like this?

Thankful for any support,
Ahmad Cheikh-Moussa

Here is an debug output from the AS5200 and a Cisco 1003:
At this Moment the AS5200 runs 12.0(7)T3

Cisco AS5200
Aug 21 11:10:17.456 MEST: ISDN Se0:15: RX <- SETUP pd = 8 callref = 0x38C3
Aug 21 11:10:17.460 MEST: Bearer Capability i = 0x8890
Aug 21 11:10:17.464 MEST: Channel ID i = 0xA9838A
Aug 21 11:10:17.468 MEST: Calling Party Number i = 0x2181,
'431XXXXX'
Aug 21 11:10:17.472 MEST: Called Party Number i = 0xA1, '431XXXXX'
Aug 21 11:10:17.484 MEST: ISDN Se0:15: Incoming call id = 0x1D0, dsl 0
Aug 21 11:10:17.492 MEST: ISDN Se0:15: received CALL_INCOMING call_id 0x1D0
Aug 21 11:10:17.496 MEST: ISDN Se0:15: CALL_INCOMING: call type is DATA,
bchan = 9
Aug 21 11:10:17.500 MEST: ISDN Se0:15: Event: Received a DATA call from
431XXXXXX on B10 at 64 Kb/s
Aug 21 11:10:17.504 MEST: ISDN Se0:15: RM returned call_type 0 resource
type 0
Aug 21 11:10:17.516 MEST: ISDN Se0:15: TX -> CALL_PROC pd = 8 callref
= 0xB8C3
Aug 21 11:10:17.520 MEST: Channel ID i = 0xA9838A
Aug 21 11:10:17.528 MEST: ISDN Se0:15: isdn_send_connect(): msg 74, call
id 0x1D0, ces 1 bchan 9, call type DATA
Aug 21 11:10:17.596 MEST: %LINK-3-UPDOWN: Interface Serial0:9, changed
state to up
Aug 21 11:10:17.632 MEST: Se0:9 PPP: Treating connection as a callin
Aug 21 11:10:17.636 MEST: Se0:9 PPP: Phase is ESTABLISHING, Passive Open
Aug 21 11:10:17.640 MEST: Se0:9 CHAP: Using alternate hostname XX-ki
Aug 21 11:10:17.640 MEST: Se0:9 LCP: State is Listen
Aug 21 11:10:17.656 MEST: ISDN Se0:15: TX -> CONNECT pd = 8 callref =
0xB8C3
Aug 21 11:10:17.660 MEST: Channel ID i = 0xA9838A
Aug 21 11:10:17.696 MEST: ISDN Se0:15: RX <- CONNECT_ACK pd = 8
callref = 0x38C3
Aug 21 11:10:17.712 MEST: ISDN Se0:15: received CALL_PROGRESSing call_id
0x1D0
Aug 21 11:10:17.716 MEST: ISDN Se0:15: CALL_PROGRESS: CALL_CONNECTED
call id 0x1D0, bchan -1, dsl 0
Aug 21 11:10:19.644 MEST: Se0:9 LCP: TIMEout: State Listen
Aug 21 11:10:19.648 MEST: Se0:9 CHAP: Using alternate hostname XX-ki
Aug 21 11:10:19.656 MEST: Se0:9 LCP: O CONFREQ [Listen] id 164 len 31
Aug 21 11:10:19.660 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
Aug 21 11:10:19.664 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
(0x050664DBEE75)
Aug 21 11:10:19.668 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
Aug 21 11:10:19.672 MEST: Se0:9 LCP: EndpointDisc 1 Local
(0x130C016E65747573652D6B69)
Aug 21 11:10:21.652 MEST: Se0:9 LCP: TIMEout: State REQsent
Aug 21 11:10:21.656 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 165 len 31
Aug 21 11:10:21.660 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
Aug 21 11:10:21.664 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
(0x050664DBEE75)
Aug 21 11:10:21.668 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
Aug 21 11:10:21.672 MEST: Se0:9 LCP: EndpointDisc 1 Local
(0x130C016E65747573652D6B69)
Aug 21 11:10:23.628 MEST: %ISDN-6-CONNECT: Interface Serial0:9 is now
connected to 431XXXXXX
Aug 21 11:10:23.652 MEST: Se0:9 LCP: TIMEout: State REQsent
Aug 21 11:10:23.656 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 166 len 31
Aug 21 11:10:23.660 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
Aug 21 11:10:23.664 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
(0x050664DBEE75)
Aug 21 11:10:23.668 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
Aug 21 11:10:23.672 MEST: Se0:9 LCP: EndpointDisc 1 Local
(0x130C016E65747573652D6B69)
Aug 21 11:10:25.652 MEST: Se0:9 LCP: TIMEout: State REQsent
Aug 21 11:10:25.656 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 167 len 31
Aug 21 11:10:25.660 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
Aug 21 11:10:25.664 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
(0x050664DBEE75)
Aug 21 11:10:25.668 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
Aug 21 11:10:25.672 MEST: Se0:9 LCP: EndpointDisc 1 Local
(0x130C016E65747573652D6B69)
Aug 21 11:10:27.652 MEST: Se0:9 LCP: TIMEout: State REQsent
Aug 21 11:10:27.656 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 168 len 31
Aug 21 11:10:27.660 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
Aug 21 11:10:27.664 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
(0x050664DBEE75)
Aug 21 11:10:27.668 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
Aug 21 11:10:27.672 MEST: Se0:9 LCP: EndpointDisc 1 Local
(0x130C016E65747573652D6B69)
Aug 21 11:10:29.708 MEST: Se0:9 LCP: TIMEout: State REQsent
Aug 21 11:10:29.712 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 169 len 31
Aug 21 11:10:29.716 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
Aug 21 11:10:29.720 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
(0x050664DBEE75)
Aug 21 11:10:29.724 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
Aug 21 11:10:29.728 MEST: Se0:9 LCP: EndpointDisc 1 Local
(0x130C016E65747573652D6B69)
Aug 21 11:10:31.772 MEST: Se0:9 LCP: TIMEout: State REQsent
Aug 21 11:10:31.776 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 170 len 31
Aug 21 11:10:31.780 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
Aug 21 11:10:31.784 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
(0x050664DBEE75)
Aug 21 11:10:31.788 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
Aug 21 11:10:31.792 MEST: Se0:9 LCP: EndpointDisc 1 Local
(0x130C016E65747573652D6B69)
Aug 21 11:10:33.840 MEST: Se0:9 LCP: TIMEout: State REQsent
Aug 21 11:10:33.844 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 171 len 31
Aug 21 11:10:33.848 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
Aug 21 11:10:33.852 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
(0x050664DBEE75)
Aug 21 11:10:33.856 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
Aug 21 11:10:33.860 MEST: Se0:9 LCP: EndpointDisc 1 Local
(0x130C016E65747573652D6B69)
Aug 21 11:10:35.900 MEST: Se0:9 LCP: TIMEout: State REQsent
Aug 21 11:10:35.908 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 172 len 31
Aug 21 11:10:35.912 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
Aug 21 11:10:35.916 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
(0x050664DBEE75)
Aug 21 11:10:35.920 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
Aug 21 11:10:35.924 MEST: Se0:9 LCP: EndpointDisc 1 Local
(0x130C016E65747573652D6B69)
Aug 21 11:10:37.964 MEST: Se0:9 LCP: TIMEout: State REQsent
Aug 21 11:10:37.972 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 173 len 31
Aug 21 11:10:37.972 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
Aug 21 11:10:37.976 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
(0x050664DBEE75)
Aug 21 11:10:37.980 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
Aug 21 11:10:37.988 MEST: Se0:9 LCP: EndpointDisc 1 Local
(0x130C016E65747573652D6B69)
Aug 21 11:10:38.596 MEST: ISDN Se0:15: RX <- DISCONNECT pd = 8 callref
= 0x38C3
Aug 21 11:10:38.600 MEST: Cause i = 0x8090 - Normal call clearing
Aug 21 11:10:38.616 MEST: ISDN Se0:15: received CALL_DISC call_id 0x1D0
Aug 21 11:10:38.624 MEST: %ISDN-6-DISCONNECT: Interface Serial0:9
disconnected from 431XX , call lasted 21 seconds
Aug 21 11:10:38.728 MEST: %LINK-3-UPDOWN: Interface Serial0:9, changed
state to down
Aug 21 11:10:38.756 MEST: Se0:9 LCP: State is Closed
Aug 21 11:10:38.760 MEST: Se0:9 PPP: Phase is DOWN
Cisco 1003

chapuser#
chapuser#deb
chapuser#debug isd
chapuser#debug isdn q93
chapuser#debug isdn q931
ISDN Q931 packets debugging is on
chapuser#deb
chapuser#debug ppp au
chapuser#debug ppp authentication
PPP authentication debugging is on
chapuser#deb
chapuser#debug ppp neg
chapuser#debug ppp negotiation
PPP protocol negotiation debugging is on
chapuser#
chapuser#
chapuser#
chapuser#

Type escape sequence to abort.

00:38:38: %ISDN-6-LAYER2UP: Layer 2 for Interface BR0, TEI 80 changed to up
00:38:38: ISDN BR0: TX -> SETUP pd = 8 callref = 0x04
00:38:38: Bearer Capability i = 0x8890
00:38:38: Channel ID i = 0x83
00:38:38: Called Party Number i = 0x80, '00431XXXXXX',
Plan:Unknown, Type:Unknown
00:38:38: ISDN BR0: RX <- SETUP_ACK pd = 8 callref = 0x84
00:38:38: Channel ID i = 0x89.
00:38:40: ISDN BR0: RX <- CALL_PROC pd = 8 callref = 0x84
00:38:40: ISDN BR0: RX <- CONNECT pd = 8 callref = 0x84
00:38:40: Date/Time i = 0x0308140B1E
00:38:40: Connected Number i = 0x2183343331323630383030
00:38:40: ISDN BR0: TX -> CONNECT_ACK pd = 8 callref = 0x04
00:38:40: %LINK-3-UPDOWN: Interface BRI0:1, changed state to up
00:38:40: %DIALER-6-BIND: Interface BR0:1 bound to profile Di1
00:38:40: BR0:1 PPP: Treating connection as a callout
00:38:40: BR0:1 PPP: Phase is ESTABLISHING, Active Open
00:38:40: BR0:1 PPP: No remote authentication for call-out
00:38:40: BR0:1 LCP: O CONFREQ [Closed] id 21 len 10
00:38:40: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0)
00:38:41: ISDN BR0: RX <- FACILITY pd = 8 callref = 0x84
00:38:41: Facility i =
0x91A1130202027B020122300AA1053003020100820100
00:38:41: - ETSI Supplementary Service, Invoke, AOC-D Charging
Units: 0
00:38:41: BRI0:1: AOC-D Recorded Units = 0.
00:38:42: BR0:1 LCP: TIMEout: State REQsent
00:38:42: BR0:1 LCP: O CONFREQ [REQsent] id 22 len 10
00:38:42: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0).
00:38:44: BR0:1 LCP: TIMEout: State REQsent
00:38:44: BR0:1 LCP: O CONFREQ [REQsent] id 23 len 10
00:38:44: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0).
00:38:46: %ISDN-6-CONNECT: Interface BRI0:1 is now connected to 00431XXXXXX
00:38:46: BR0:1 LCP: TIMEout: State REQsent
00:38:46: BR0:1 LCP: O CONFREQ [REQsent] id 24 len 10
00:38:46: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0).
Success rate is 0 percent (0/5)
chapuser#
00:38:48: BR0:1 LCP: TIMEout: State REQsent
00:38:48: BR0:1 LCP: O CONFREQ [REQsent] id 25 len 10
00:38:48: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0)
chapuser#
00:38:50: BR0:1 LCP: TIMEout: State REQsent
00:38:50: BR0:1 LCP: O CONFREQ [REQsent] id 26 len 10
00:38:50: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0)
00:38:52: BR0:1 LCP: TIMEout: State REQsent
00:38:52: BR0:1 LCP: O CONFREQ [REQsent] id 27 len 10
00:38:52: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0)
00:38:54: BR0:1 LCP: TIMEout: State REQsent
00:38:54: BR0:1 LCP: O CONFREQ [REQsent] id 28 len 10
00:38:54: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0)
00:38:56: BR0:1 LCP: TIMEout: State REQsent
00:38:56: BR0:1 LCP: O CONFREQ [REQsent] id 29 len 10
00:38:56: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0)
00:38:58: BR0:1 LCP: TIMEout: State REQsent
00:38:58: BR0:1 LCP: O CONFREQ [REQsent] id 30 len 10
00:38:58: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0)
00:39:00: BR0:1 LCP: TIMEout: State REQsent
00:39:00: BR0:1 PPP: Treating connection as a callout
00:39:00: %DIALER-6-UNBIND: Interface BR0:1 unbound from profile Di1
00:39:00: BR0:1 LCP: State is Listen
00:39:00: %ISDN-6-DISCONNECT: Interface BRI0:1 disconnected from
00431XXXXX , call lasted 20 seconds
00:39:00: ISDN BR0: TX -> DISCONNECT pd = 8 callref = 0x04
00:39:00: Cause i = 0x8090 - Normal call clearing
00:39:01: ISDN BR0: RX <- RELEASE pd = 8 callref = 0x84
00:39:01: Cause i = 0x809F - Normal, unspecified
00:39:01: ISDN BR0: TX -> RELEASE_COMP pd = 8 callref = 0x04
00:39:01: %LINK-3-UPDOWN: Interface BRI0:1, changed state to down
00:39:01: BR0:1 LCP: State is Closed
00:39:01: BR0:1 PPP: Phase is DOWN
chapuser#
00:39:11: %ISDN-6-LAYER2DOWN: Layer 2 for Interface BR0, TEI 80 changed
to down
chapuser#

--
Ahmad Cheikh-Moussa
NetUSE AG
Dr.-Hell-Stra?e, 24107 Kiel, Federal Republic of Germany
Telefon: +49 431 386435 00 -- Telefax: +49 431 386435 99
Service: Service@NetUSE.DE -- http://NetUSE.DE/

Re: Dial-IN problems with an AS5200 [ In reply to ]

Aaron at cisco

Aug 21, 2003, 8:28 AM

Post #2 of 4 (957 views)

Permalink

Your debugs show that the call connected at ISDN layer 3,
but that the sync PPP packets sent by each side failed
successfully to be received by the other side.

Presumably if you were to do a "show interface WHATEVER:B-CHANNEL"
before and after the call, you would see packets transmitted
and input errors incrementing.

This is very likely simply caused by transmission problems
in your circuit network.

A less likely cause would be a problem in the AS5200, where
some particular timeslot in the E1 controller is misbehaving.
See if the failing calls are or are not associated with the
E1 timeslot. If so, then this would be the 5200's fault,
not the PSTN's.

Aaron

---

> Hi!

> I have an strange behavior on an AS5200. Sometimes you can dial-in
> without any Problems and sometimes it hangs up.
> I've tried different IOS Versions but nothing helps.
> (12.0(7)T3, 12.1(20), 12.1(10)AA)

> The failure that occurs is always the same. It doesn't matter
> which IOS Version I try.
> Does anyone has seen a failure like this?

> Thankful for any support,
> Ahmad Cheikh-Moussa

> Here is an debug output from the AS5200 and a Cisco 1003:
> At this Moment the AS5200 runs 12.0(7)T3

> Cisco AS5200
> Aug 21 11:10:17.456 MEST: ISDN Se0:15: RX <- SETUP pd = 8 callref = 0x38C3
> Aug 21 11:10:17.460 MEST: Bearer Capability i = 0x8890
> Aug 21 11:10:17.464 MEST: Channel ID i = 0xA9838A
> Aug 21 11:10:17.468 MEST: Calling Party Number i = 0x2181,
> '431XXXXX'
> Aug 21 11:10:17.472 MEST: Called Party Number i = 0xA1, '431XXXXX'
> Aug 21 11:10:17.484 MEST: ISDN Se0:15: Incoming call id = 0x1D0, dsl 0
> Aug 21 11:10:17.492 MEST: ISDN Se0:15: received CALL_INCOMING call_id 0x1D0
> Aug 21 11:10:17.496 MEST: ISDN Se0:15: CALL_INCOMING: call type is DATA,
> bchan = 9
> Aug 21 11:10:17.500 MEST: ISDN Se0:15: Event: Received a DATA call from
> 431XXXXXX on B10 at 64 Kb/s
> Aug 21 11:10:17.504 MEST: ISDN Se0:15: RM returned call_type 0 resource
> type 0
> Aug 21 11:10:17.516 MEST: ISDN Se0:15: TX -> CALL_PROC pd = 8 callref
> = 0xB8C3
> Aug 21 11:10:17.520 MEST: Channel ID i = 0xA9838A
> Aug 21 11:10:17.528 MEST: ISDN Se0:15: isdn_send_connect(): msg 74, call
> id 0x1D0, ces 1 bchan 9, call type DATA
> Aug 21 11:10:17.596 MEST: %LINK-3-UPDOWN: Interface Serial0:9, changed
> state to up
> Aug 21 11:10:17.632 MEST: Se0:9 PPP: Treating connection as a callin
> Aug 21 11:10:17.636 MEST: Se0:9 PPP: Phase is ESTABLISHING, Passive Open
> Aug 21 11:10:17.640 MEST: Se0:9 CHAP: Using alternate hostname XX-ki
> Aug 21 11:10:17.640 MEST: Se0:9 LCP: State is Listen
> Aug 21 11:10:17.656 MEST: ISDN Se0:15: TX -> CONNECT pd = 8 callref =
> 0xB8C3
> Aug 21 11:10:17.660 MEST: Channel ID i = 0xA9838A
> Aug 21 11:10:17.696 MEST: ISDN Se0:15: RX <- CONNECT_ACK pd = 8
> callref = 0x38C3
> Aug 21 11:10:17.712 MEST: ISDN Se0:15: received CALL_PROGRESSing call_id
> 0x1D0
> Aug 21 11:10:17.716 MEST: ISDN Se0:15: CALL_PROGRESS: CALL_CONNECTED
> call id 0x1D0, bchan -1, dsl 0
> Aug 21 11:10:19.644 MEST: Se0:9 LCP: TIMEout: State Listen
> Aug 21 11:10:19.648 MEST: Se0:9 CHAP: Using alternate hostname XX-ki
> Aug 21 11:10:19.656 MEST: Se0:9 LCP: O CONFREQ [Listen] id 164 len 31
> Aug 21 11:10:19.660 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
> Aug 21 11:10:19.664 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
> (0x050664DBEE75)
> Aug 21 11:10:19.668 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
> Aug 21 11:10:19.672 MEST: Se0:9 LCP: EndpointDisc 1 Local
> (0x130C016E65747573652D6B69)
> Aug 21 11:10:21.652 MEST: Se0:9 LCP: TIMEout: State REQsent
> Aug 21 11:10:21.656 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 165 len 31
> Aug 21 11:10:21.660 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
> Aug 21 11:10:21.664 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
> (0x050664DBEE75)
> Aug 21 11:10:21.668 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
> Aug 21 11:10:21.672 MEST: Se0:9 LCP: EndpointDisc 1 Local
> (0x130C016E65747573652D6B69)
> Aug 21 11:10:23.628 MEST: %ISDN-6-CONNECT: Interface Serial0:9 is now
> connected to 431XXXXXX
> Aug 21 11:10:23.652 MEST: Se0:9 LCP: TIMEout: State REQsent
> Aug 21 11:10:23.656 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 166 len 31
> Aug 21 11:10:23.660 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
> Aug 21 11:10:23.664 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
> (0x050664DBEE75)
> Aug 21 11:10:23.668 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
> Aug 21 11:10:23.672 MEST: Se0:9 LCP: EndpointDisc 1 Local
> (0x130C016E65747573652D6B69)
> Aug 21 11:10:25.652 MEST: Se0:9 LCP: TIMEout: State REQsent
> Aug 21 11:10:25.656 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 167 len 31
> Aug 21 11:10:25.660 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
> Aug 21 11:10:25.664 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
> (0x050664DBEE75)
> Aug 21 11:10:25.668 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
> Aug 21 11:10:25.672 MEST: Se0:9 LCP: EndpointDisc 1 Local
> (0x130C016E65747573652D6B69)
> Aug 21 11:10:27.652 MEST: Se0:9 LCP: TIMEout: State REQsent
> Aug 21 11:10:27.656 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 168 len 31
> Aug 21 11:10:27.660 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
> Aug 21 11:10:27.664 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
> (0x050664DBEE75)
> Aug 21 11:10:27.668 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
> Aug 21 11:10:27.672 MEST: Se0:9 LCP: EndpointDisc 1 Local
> (0x130C016E65747573652D6B69)
> Aug 21 11:10:29.708 MEST: Se0:9 LCP: TIMEout: State REQsent
> Aug 21 11:10:29.712 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 169 len 31
> Aug 21 11:10:29.716 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
> Aug 21 11:10:29.720 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
> (0x050664DBEE75)
> Aug 21 11:10:29.724 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
> Aug 21 11:10:29.728 MEST: Se0:9 LCP: EndpointDisc 1 Local
> (0x130C016E65747573652D6B69)
> Aug 21 11:10:31.772 MEST: Se0:9 LCP: TIMEout: State REQsent
> Aug 21 11:10:31.776 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 170 len 31
> Aug 21 11:10:31.780 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
> Aug 21 11:10:31.784 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
> (0x050664DBEE75)
> Aug 21 11:10:31.788 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
> Aug 21 11:10:31.792 MEST: Se0:9 LCP: EndpointDisc 1 Local
> (0x130C016E65747573652D6B69)
> Aug 21 11:10:33.840 MEST: Se0:9 LCP: TIMEout: State REQsent
> Aug 21 11:10:33.844 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 171 len 31
> Aug 21 11:10:33.848 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
> Aug 21 11:10:33.852 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
> (0x050664DBEE75)
> Aug 21 11:10:33.856 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
> Aug 21 11:10:33.860 MEST: Se0:9 LCP: EndpointDisc 1 Local
> (0x130C016E65747573652D6B69)
> Aug 21 11:10:35.900 MEST: Se0:9 LCP: TIMEout: State REQsent
> Aug 21 11:10:35.908 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 172 len 31
> Aug 21 11:10:35.912 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
> Aug 21 11:10:35.916 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
> (0x050664DBEE75)
> Aug 21 11:10:35.920 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
> Aug 21 11:10:35.924 MEST: Se0:9 LCP: EndpointDisc 1 Local
> (0x130C016E65747573652D6B69)
> Aug 21 11:10:37.964 MEST: Se0:9 LCP: TIMEout: State REQsent
> Aug 21 11:10:37.972 MEST: Se0:9 LCP: O CONFREQ [REQsent] id 173 len 31
> Aug 21 11:10:37.972 MEST: Se0:9 LCP: AuthProto CHAP (0x0305C22305)
> Aug 21 11:10:37.976 MEST: Se0:9 LCP: MagicNumber 0x64DBEE75
> (0x050664DBEE75)
> Aug 21 11:10:37.980 MEST: Se0:9 LCP: MRRU 1524 (0x110405F4)
> Aug 21 11:10:37.988 MEST: Se0:9 LCP: EndpointDisc 1 Local
> (0x130C016E65747573652D6B69)
> Aug 21 11:10:38.596 MEST: ISDN Se0:15: RX <- DISCONNECT pd = 8 callref
> = 0x38C3
> Aug 21 11:10:38.600 MEST: Cause i = 0x8090 - Normal call clearing
> Aug 21 11:10:38.616 MEST: ISDN Se0:15: received CALL_DISC call_id 0x1D0
> Aug 21 11:10:38.624 MEST: %ISDN-6-DISCONNECT: Interface Serial0:9
> disconnected from 431XX , call lasted 21 seconds
> Aug 21 11:10:38.728 MEST: %LINK-3-UPDOWN: Interface Serial0:9, changed
> state to down
> Aug 21 11:10:38.756 MEST: Se0:9 LCP: State is Closed
> Aug 21 11:10:38.760 MEST: Se0:9 PPP: Phase is DOWN
> Cisco 1003

> chapuser#
> chapuser#deb
> chapuser#debug isd
> chapuser#debug isdn q93
> chapuser#debug isdn q931
> ISDN Q931 packets debugging is on
> chapuser#deb
> chapuser#debug ppp au
> chapuser#debug ppp authentication
> PPP authentication debugging is on
> chapuser#deb
> chapuser#debug ppp neg
> chapuser#debug ppp negotiation
> PPP protocol negotiation debugging is on
> chapuser#
> chapuser#
> chapuser#
> chapuser#

> Type escape sequence to abort.

> 00:38:38: %ISDN-6-LAYER2UP: Layer 2 for Interface BR0, TEI 80 changed to up
> 00:38:38: ISDN BR0: TX -> SETUP pd = 8 callref = 0x04
> 00:38:38: Bearer Capability i = 0x8890
> 00:38:38: Channel ID i = 0x83
> 00:38:38: Called Party Number i = 0x80, '00431XXXXXX',
> Plan:Unknown, Type:Unknown
> 00:38:38: ISDN BR0: RX <- SETUP_ACK pd = 8 callref = 0x84
> 00:38:38: Channel ID i = 0x89.
> 00:38:40: ISDN BR0: RX <- CALL_PROC pd = 8 callref = 0x84
> 00:38:40: ISDN BR0: RX <- CONNECT pd = 8 callref = 0x84
> 00:38:40: Date/Time i = 0x0308140B1E
> 00:38:40: Connected Number i = 0x2183343331323630383030
> 00:38:40: ISDN BR0: TX -> CONNECT_ACK pd = 8 callref = 0x04
> 00:38:40: %LINK-3-UPDOWN: Interface BRI0:1, changed state to up
> 00:38:40: %DIALER-6-BIND: Interface BR0:1 bound to profile Di1
> 00:38:40: BR0:1 PPP: Treating connection as a callout
> 00:38:40: BR0:1 PPP: Phase is ESTABLISHING, Active Open
> 00:38:40: BR0:1 PPP: No remote authentication for call-out
> 00:38:40: BR0:1 LCP: O CONFREQ [Closed] id 21 len 10
> 00:38:40: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0)
> 00:38:41: ISDN BR0: RX <- FACILITY pd = 8 callref = 0x84
> 00:38:41: Facility i =
> 0x91A1130202027B020122300AA1053003020100820100
> 00:38:41: - ETSI Supplementary Service, Invoke, AOC-D Charging
> Units: 0
> 00:38:41: BRI0:1: AOC-D Recorded Units = 0.
> 00:38:42: BR0:1 LCP: TIMEout: State REQsent
> 00:38:42: BR0:1 LCP: O CONFREQ [REQsent] id 22 len 10
> 00:38:42: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0).
> 00:38:44: BR0:1 LCP: TIMEout: State REQsent
> 00:38:44: BR0:1 LCP: O CONFREQ [REQsent] id 23 len 10
> 00:38:44: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0).
> 00:38:46: %ISDN-6-CONNECT: Interface BRI0:1 is now connected to 00431XXXXXX
> 00:38:46: BR0:1 LCP: TIMEout: State REQsent
> 00:38:46: BR0:1 LCP: O CONFREQ [REQsent] id 24 len 10
> 00:38:46: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0).
> Success rate is 0 percent (0/5)
> chapuser#
> 00:38:48: BR0:1 LCP: TIMEout: State REQsent
> 00:38:48: BR0:1 LCP: O CONFREQ [REQsent] id 25 len 10
> 00:38:48: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0)
> chapuser#
> 00:38:50: BR0:1 LCP: TIMEout: State REQsent
> 00:38:50: BR0:1 LCP: O CONFREQ [REQsent] id 26 len 10
> 00:38:50: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0)
> 00:38:52: BR0:1 LCP: TIMEout: State REQsent
> 00:38:52: BR0:1 LCP: O CONFREQ [REQsent] id 27 len 10
> 00:38:52: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0)
> 00:38:54: BR0:1 LCP: TIMEout: State REQsent
> 00:38:54: BR0:1 LCP: O CONFREQ [REQsent] id 28 len 10
> 00:38:54: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0)
> 00:38:56: BR0:1 LCP: TIMEout: State REQsent
> 00:38:56: BR0:1 LCP: O CONFREQ [REQsent] id 29 len 10
> 00:38:56: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0)
> 00:38:58: BR0:1 LCP: TIMEout: State REQsent
> 00:38:58: BR0:1 LCP: O CONFREQ [REQsent] id 30 len 10
> 00:38:58: BR0:1 LCP: MagicNumber 0xE041C8A0 (0x0506E041C8A0)
> 00:39:00: BR0:1 LCP: TIMEout: State REQsent
> 00:39:00: BR0:1 PPP: Treating connection as a callout
> 00:39:00: %DIALER-6-UNBIND: Interface BR0:1 unbound from profile Di1
> 00:39:00: BR0:1 LCP: State is Listen
> 00:39:00: %ISDN-6-DISCONNECT: Interface BRI0:1 disconnected from
> 00431XXXXX , call lasted 20 seconds
> 00:39:00: ISDN BR0: TX -> DISCONNECT pd = 8 callref = 0x04
> 00:39:00: Cause i = 0x8090 - Normal call clearing
> 00:39:01: ISDN BR0: RX <- RELEASE pd = 8 callref = 0x84
> 00:39:01: Cause i = 0x809F - Normal, unspecified
> 00:39:01: ISDN BR0: TX -> RELEASE_COMP pd = 8 callref = 0x04
> 00:39:01: %LINK-3-UPDOWN: Interface BRI0:1, changed state to down
> 00:39:01: BR0:1 LCP: State is Closed
> 00:39:01: BR0:1 PPP: Phase is DOWN
> chapuser#
> 00:39:11: %ISDN-6-LAYER2DOWN: Layer 2 for Interface BR0, TEI 80 changed
> to down
> chapuser#

> --
> Ahmad Cheikh-Moussa
> NetUSE AG
> Dr.-Hell-Stra?e, 24107 Kiel, Federal Republic of Germany
> Telefon: +49 431 386435 00 -- Telefax: +49 431 386435 99
> Service: Service@NetUSE.DE -- http://NetUSE.DE/

> _______________________________________________
> cisco-nas mailing list
> cisco-nas@puck.nether.net
> https://puck.nether.net/mailman/listinfo/cisco-nas

Re: Dial-IN problems with an AS5200 [ In reply to ]

hk at netuse

Aug 25, 2003, 3:17 AM

Post #3 of 4 (948 views)

Permalink

Hello!

Thanks for your reply!

Aaron Leonard schrieb:
> Your debugs show that the call connected at ISDN layer 3,
> but that the sync PPP packets sent by each side failed
> successfully to be received by the other side.
>
> Presumably if you were to do a "show interface WHATEVER:B-CHANNEL"
> before and after the call, you would see packets transmitted
> and input errors incrementing.

No, there are no input or output errors increasing on serial 0:x during this
failed calls. Only 'interface resets' and 'carrier transitions' are increasing
by 1 after each failed call.
Also there are no input or output errors on ser 0:15 and 'sh contr e1 0' shows
no errors at all for the last 24h.

> This is very likely simply caused by transmission problems
> in your circuit network.

Because of the above I doubt this.

> A less likely cause would be a problem in the AS5200, where
> some particular timeslot in the E1 controller is misbehaving.
> See if the failing calls are or are not associated with the
> E1 timeslot. If so, then this would be the 5200's fault,
> not the PSTN's.

When the problem occurs (about 24h after the last reboot??) about 9 out of 10
dialins failed with the mentioned symptoms.
Right after rebooting the AS5200 (almost?) every dialin-attempt is successful.

During the first 3h on most B-channels were only succesful calls (21), on some
were only failed calls (4) and on some were first succesful and later failed
calls (3).

The last thing we've changed before this problem was a RAM- and Flash-Upgrade
combined with an IOS-Upgrade. Could this problem be related to a defective RAM
chip?

Memory seems OK before the reboot:
ranke01#sh mem dead
Head Total(b) Used(b) Free(b) Lowest(b)
Largest(b)
Processor EA32C 15817940 3717648 12100292 11630320
12020164
I/O 20000000 4194304 1551900 2642404 2411572
2639100
...
2360 bytes dead Proceccor Mem

Regards
Hauke Krull
--
Dipl.-Phys. Hauke Krull
NetUSE AG
Dr.-Hell-Straße, D-24107 Kiel, Germany
Fon: +49 431 386435 00 -- Fax: +49 431 386435 99

Re: Dial-IN problems with an AS5200 [ In reply to ]

Aaron at cisco

Aug 25, 2003, 11:47 AM

Post #4 of 4 (946 views)

Permalink

> > Your debugs show that the call connected at ISDN layer 3,
> > but that the sync PPP packets sent by each side failed
> > successfully to be received by the other side.
> >
> > Presumably if you were to do a "show interface WHATEVER:B-CHANNEL"
> > before and after the call, you would see packets transmitted
> > and input errors incrementing.

> No, there are no input or output errors increasing on serial 0:x during this
> failed calls. Only 'interface resets' and 'carrier transitions' are increasing
> by 1 after each failed call.
> Also there are no input or output errors on ser 0:15 and 'sh contr e1 0' shows
> no errors at all for the last 24h.

How about the router on the other side of the circuit - is it showing
input errors?

> > This is very likely simply caused by transmission problems
> > in your circuit network.

> Because of the above I doubt this.

If the far-side router is also not seeing input errors incrementing
on its B channel, then I would agree that this is unlikely to be
a circuit error.

> > A less likely cause would be a problem in the AS5200, where
> > some particular timeslot in the E1 controller is misbehaving.
> > See if the failing calls are or are not associated with the
> > E1 timeslot. If so, then this would be the 5200's fault,
> > not the PSTN's.

> When the problem occurs (about 24h after the last reboot??) about 9 out of 10
> dialins failed with the mentioned symptoms.
> Right after rebooting the AS5200 (almost?) every dialin-attempt is successful.

> During the first 3h on most B-channels were only succesful calls (21), on some
> were only failed calls (4) and on some were first succesful and later failed
> calls (3).

> The last thing we've changed before this problem was a RAM- and Flash-Upgrade
> combined with an IOS-Upgrade. Could this problem be related to a defective RAM
> chip?

No, I don't think so. What IOS were you running before the upgrade?
Did you encounter this problem then? What IOS are you running now?

It sounds like this may be CSCds23532, "PPP LCP negotiation doesnt
start for ISDN calls after normal work", which was reported against
12.1(2) thru 12.1(4.2), but which reportedly did not happen with
11.3(4)T or 12.0(9). The problem went away when the AS5200 was replaced with
an AS5300, and the DDTS was marked unreproducible.

Release-note: Modified 001030

On a Cisco AS5200 series access server that is running Cisco IOS Release
12.1(2) and that has a PRI/E1 that receives only data calls that are PC
clients with a terminal adapter (TA), the access server may not receive
incoming PPP link control protocol (LCP) packets and cannot process any
further PPP LCP configuration requests. This situation occurs about once a
week. This situation does not affect Cisco access servers that are running
Cisco IOS Release 11.3(4)T.

Workaround: Reboot the router.

Regards,

Aaron

---

> Memory seems OK before the reboot:
> ranke01#sh mem dead
> Head Total(b) Used(b) Free(b) Lowest(b)
> Largest(b)
> Processor EA32C 15817940 3717648 12100292 11630320
> 12020164
> I/O 20000000 4194304 1551900 2642404 2411572
> 2639100
> ...
> 2360 bytes dead Proceccor Mem

> Regards
> Hauke Krull
> --
> Dipl.-Phys. Hauke Krull
> NetUSE AG
> Dr.-Hell-Straße, D-24107 Kiel, Germany
> Fon: +49 431 386435 00 -- Fax: +49 431 386435 99