Mailing List Archive: Cisco: NAS

Modems not responding on cisco AS5300.

Index | Next | Previous | View Threaded

mays at win

Aug 25, 2008, 11:40 AM

Post #1 of 12 (3870 views)
Permalink

Modems not responding on cisco AS5300.

We're working with a Cisco AS5300, and have been having a problem wherein it will answer a call, but the call never gets forwarded to a modem. Sometimes it works, usually not. There is some reason to believe that it works after a call has hit a modem once. It fails the first time and works after that, but I can't confirm that.

Here's the "debug modem csm" output from a failed call. I've bolded what I assume is the important text.

as5300_frv_1#
*Apr 27 00:30:32.087: ISDN Dc2 SC Q921d: srl_send_l2_pak:
source_id = IUA, dest_id = Q.931, prim = DL_DATA_IND
priv_len = 4 int_id = 0x62D3E3E0 datasize = 62
*Apr 27 00:30:32.087: ISDN Dc2 SC Q921d: data = 0x62D3E3E0000000010241040000010000
*Apr 27 00:30:32.091: 080207AB0504038090A21803A1838E1E
*Apr 27 00:30:32.091: 0281836C0CA181353032383135373030
*Apr 27 00:30:32.091: 30700BA134333433393431323334
*Apr 27 00:30:32.091: ISDN Dc2 SC BACKHAUL: L3IF_rx_L2_pak: received data 0x080207AB0504038090A21803A1838E1E
*Apr 27 00:30:32.091: 0281836C0CA181353032383135373030
*Apr 27 00:30:32.091: 30700BA134333433393431323334
*Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_Go: source = 0x20A, event = 0x241, call id = 0x0, int id = 0x0
*Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB state 0 event 0x5 ces 1
*Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref = 0x87AB SETUP:U0_Setup(nlcb)
*Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_state_change: callref 0x87AB old NULL_STATE, new CALL_PRESENT
*Apr 27 00:30:32.091: ISDN Dc2 SC CC: CCPRI_Go: source id 0x300, call id 0xE, event 0x341 (pre-ccb recovery)
*Apr 27 00:30:32.091: ISDN Dc2 SC CC: CCPRI_Go: call id 0x2 cref 0xE event 0x87AB Source->L3
*Apr 27 00:30:32.095: ISDN Dc2 SC CC: CCPCC_CallIdle: event 0x90 b channel 0 nfas int_id 0 call_id 0xE
*Apr 27 00:30:32.095: ISDN Dc2 SC CC: CCPRI_AcceptChanId: Negotiated int_id 0 bchan 0 cref 0x87AB call_id 0x000E lo_chan 14 final int_id/bchan 2/14 cause 0
*Apr 27 00:30:32.095: ISDN Dc2 SC TGRM: get_tgrm_avail_state: idb 0x62D3E3E0 bchan 14 service_state 0 call_state 2 false busy 0x0 dsl 2
*Apr 27 00:30:32.095: ISDN Dc2 SC TGRM: update_tgrm_call_status: idb 0x62D3E3E0 bchan 14 availability state 1 call state(prev,new) (0,2), dsl 2
*Apr 27 00:30:32.095: ISDN Dc2 SC TGRM: update_tgrm_call_status: Calling TGRM with tgrm_call_isdn_update: idb 0x62D3E3E0 bchan 14 call state 1 call type 2 call dir 1
*Apr 27 00:30:32.095: ISDN Dc2 SC EVENT: process_rxstate: ces/callid 1/0xE calltype 2 CALL_INCOMING
*Apr 27 00:30:32.095: ISDN Dc2 SC PACKET: process_rxstate: 0x4C0201000E1A04040000100218042003
*Apr 27 00:30:32.095: 0E02700C020134333433393431323334
*Apr 27 00:30:32.095: 04038090A21803A1838E1E0281836C0C
*Apr 27 00:30:32.095: A18135303238313537303030700BA134
*Apr 27 00:30:32.095: 333433393431323334
*Apr 27 00:30:32.095: ISDN Dc2 SC EVENTd: calltrkr_incoming_call: call_id=0xE
*Apr 27 00:30:32.095: ISDN Dc2 SC EVENTd: calltrkr_setup_received: isdn_info=1658087904l, call_id=0xE ANSWER
*Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: calltrkr_setup_received: isdn_info=1658675348l, call_id=0xE ANSWER
*Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: call_incoming: b channel 13, call type is VOICE ULAW
*Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: call_incoming: Received a VOICE call from 5028157000 on b channel 13 at 64 Kb/s
*Apr 27 00:30:32.099: VDEV_ALLOCATE: 2/51 is allocated
*Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: isdn_fromdialer: RM returned call_type 1 resource type 0 response 2
*Apr 27 00:30:32.099: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call id 0x0, event 0x4A (pre-ccb recovery)
*Apr 27 00:30:32.099: ISDN Dc2 SC CC: CCPRI_Go: call_id 0xE cref 0x87AB event 0x4A Source->HOST
*Apr 27 00:30:32.099: ISDN Dc2 SC CC: CCPCC_CallOffered: event = 0x4A b channel 14 nfas int_id 2 call_id 0xE
*Apr 27 00:30:32.099: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event = 0x340, call id = 0xE, int id = 0x2
*Apr 27 00:30:32.099: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB state 6 event 0x88 ces 1
*Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref = 0x87AB CC_CALL_PROC_REQ:U6_CallProcReq(nlcb)
*Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 10 octets 0x080287AB021803A9838E
*Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: srl_send_l3_pak:
source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
priv_len = 4 int_id = 0x62D3E3E0 datasize = 26
*Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: data = 0x62D3E3E0000100000240046A00010800
*Apr 27 00:30:32.103: 080287AB021803A9838E
*Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: L3_state_change: callref 0x87AB old CALL_PRESENT, new IN_CALL_PROC
*Apr 27 00:30:32.103: ISDN Dc2 SC EVENT: UserIdle: callid 0xE received ACCEPT_CALL (0x13)
*Apr 27 00:30:32.103: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0, call_id=0xE, ces=0x0
bchan=0xD, event=0x1, cause=0x0
*Apr 27 00:30:32.103: dev in call to isdn : set dnis_collected & fap_notify
*Apr 27 00:30:32.103: EVENT_FROM_ISDN:(000E): DEV_INCALL at slot 2, port 51
*Apr 27 00:30:32.103: EVENT_FROM_ISDN: decode:calling oct3 0xA1, called oct3 0xA1, oct3a 0x0,mask 0x3D
*Apr 27 00:30:32.103: EVENT_FROM_ISDN: csm_call_info:calling oct3 0xA1, called oct3 0xA1, oct3a 0x0,mask 0x3D
*Apr 27 00:30:32.103: CSM_PROC_IDLE: CSM_EVENT_ISDN_CALL at slot 2, port 51
*Apr 27 00:30:32.103: Mica Modem(2/51): Configure(0x1 = 0x0)
*Apr 27 00:30:32.103: Mica Modem(2/51): Configure(0x23 = 0x0)
*Apr 27 00:30:32.103: Mica Modem(2/51): Call Setup
*Apr 27 00:30:32.103: csm_connect_pri_vdev: TS allocated at bp_stream 0, bp_Ch 13, vdev_common 0x625BA2C4 2/51
*Apr 27 00:30:32.107: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call id 0x0, event 0x4E (pre-ccb recovery)
*Apr 27 00:30:32.107: ISDN Dc2 SC CC: CCPRI_Go: call_id 0xE cref 0x87AB event 0x4E Source->HOST
*Apr 27 00:30:32.107: ISDN Dc2 SC CC: CCPCC_CallRoutingIn: executing with event = 4E in state = CALL ROUTING_IN
*Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event = 0x340, call id = 0xE, int id = 0x2
*Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB state 9 event 0x86 ces 1
*Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref = 0x87AB CC_ALERTING_REQ:U9_AlertingReq(nlcb)
*Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 5 octets 0x080287AB01
*Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: srl_send_l3_pak:
source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
*Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: data = 0x62D3E3E0000100000240046A00010800
*Apr 27 00:30:32.107: 080287AB01
*Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_state_change: callref 0x87AB old IN_CALL_PROC, new CALL_RECEIVED
*Apr 27 00:30:32.175: Mica Modem(2/51): State Transition to Call Setup
*Apr 27 00:30:32.175: Mica Modem(2/51): Went offhook
*Apr 27 00:30:32.175: CSM_PROC_IC2_RING: CSM_EVENT_MODEM_OFFHOOK at slot 2, port 51
*Apr 27 00:30:32.175: ISDN Dc2 SC EVENT: process_modem_command: received event VOICE_ANS on callid 0xE and bchan 13 ces 0 cause 16 switch type 25
*Apr 27 00:30:32.175: ISDN Dc2 SC EVENTd: isdn_send_connect: msg 74, call id 0xE, ces 0 bchan 13, call type VOICE
*Apr 27 00:30:32.175: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call id 0x0, event 0x4A (pre-ccb recovery)
*Apr 27 00:30:32.175: ISDN Dc2 SC CC: CCPRI_Go: call_id 0xE cref 0x87AB event 0x4A Source->HOST
*Apr 27 00:30:32.175: ISDN Dc2 SC CC: CCPCC_CallRinging: event 0x4A b channel 14 nfas int_id 2 call_id 0xE
*Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event = 0x340, call id = 0xE, int id = 0x2
*Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB state 7 event 0x81 ces 1
*Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref = 0x87AB CC_SETUP_RESP:U7_SetupResp(nlcb)
*Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 5 octets 0x080287AB07
*Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: srl_send_l3_pak:
source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
*Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: data = 0x62D3E3E0000100000240046A00010800
*Apr 27 00:30:32.179: 080287AB07
*Apr 27 00:30:32.179: ISDN Dc2 SC LIFd: LIF_StartTimer: timer (0x630C8090), ticks (4000), event (0x131C)
*Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_state_change: callref 0x87AB old CALL_RECEIVED, new CONNECT_REQUEST
*Apr 27 00:30:32.323: ISDN Dc2 SC Q921d: srl_send_l2_pak:
source_id = IUA, dest_id = Q.931, prim = DL_DATA_IND
priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
*Apr 27 00:30:32.323: ISDN Dc2 SC Q921d: data = 0x62D3E3E0000000010241040000010000
*Apr 27 00:30:32.323: 080207AB0F
*Apr 27 00:30:32.323: ISDN Dc2 SC BACKHAUL: L3IF_rx_L2_pak: received data 0x080207AB0F
*Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_Go: source = 0x20A, event = 0x241, call id = 0x0, int id = 0x0
*Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB state 8 event 0xF ces 1
*Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref = 0x87AB CONNECT_ACK:U8_ConnectAck(nlcb)
*Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_state_change: callref 0x87AB old CONNECT_REQUEST, new CALL_ACTIVE
*Apr 27 00:30:32.327: ISDN Dc2 SC CC: CCPRI_Go: source id 0x300, call id 0xE, event 0x341 (pre-ccb recovery)
*Apr 27 00:30:32.327: ISDN Dc2 SC CC: CCPRI_Go: dispatching event 0x92 call id 0xE cref 0x87AB Source->L3
*Apr 27 00:30:32.327: ISDN Dc2 SC CC: CCPCC_CallRoutingIn: executing with event = 92 in state = CALL ROUTING_IN
*Apr 27 00:30:32.327: ISDN Dc2 SC EVENT: process_rxstate: ces/callid 1/0xE calltype 2 CALL_PROGRESS
*Apr 27 00:30:32.327: ISDN Dc2 SC PACKET: process_rxstate: 0x4E0201000E031E0187
*Apr 27 00:30:32.327: ISDN Dc2 SC EVENTd: calltrkr_call_connect: isdn_info=0x62DD6094, call_id=0xE
*Apr 27 00:30:32.327: ISDN Dc2 SC EVENTd: calltrkr_call_connect: hndl=14l, cntrl_slot=0, cntrl_port=2, cntrl_channel=2.
*Apr 27 00:30:32.327: ISDN Dc2 SC EVENTd: call_progress: CALL_CONNECTED b channel 13 call id 0xE
*Apr 27 00:30:32.327: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0, call_id=0xE, ces=0x0
bchan=0xD, event=0x4, cause=0x0
*Apr 27 00:30:32.327: EVENT_FROM_ISDN:(000E): DEV_CONNECTED at slot 2, port 51
*Apr 27 00:30:32.327: CSM_PROC_IC6_WAIT_FOR_CONNECT: CSM_EVENT_ISDN_CONNECTED at slot 2, port 51
*Apr 27 00:30:32.327: Mica Modem(2/51): Link Initiate
*Apr 27 00:30:32.327: %ISDN-6-CONNECT: Interface Serial2:13 is now connected to 5028157000 N/A
*Apr 27 00:30:33.419: Mica Modem(2/51): State Transition to Connect
*Apr 27 00:30:33.435: Mica Modem(2/51): State Transition to V8bis Exchange
*Apr 27 00:30:37.879: Mica Modem(2/51): State Transition to Link
*Apr 27 00:30:42.147: Mica Modem(2/51): State Transition to Trainup
*Apr 27 00:30:50.015: Mica Modem(2/51): State Transition to Terminating
*Apr 27 00:30:50.451: %CALLRECORD-3-MICA_TERSE_CALL_FAILED_REC: DS0 slot/contr/chan=0/2/13, slot/port=2/51, call_id=E, calling=5028157000, called=4343941234, time=17, finl-state=Train Up, disc(modem)=6102 Condition occurred during call setup/DSP condition/failure in modem training up
*Apr 27 00:30:50.615: Mica Modem(2/51): State Transition to Idle
*Apr 27 00:30:50.615: Mica Modem(2/51): Went onhook
*Apr 27 00:30:50.615: CSM_PROC_IC7_OC6_CONNECTED: CSM_EVENT_MODEM_ONHOOK at slot 2, port 51
*Apr 27 00:30:50.615: CSM_PROC_IC7_OC6_CONNECTED: cause code to isdn 0x0
*Apr 27 00:30:50.615: CSM(2/51): Enter csm_enter_idle_state
*Apr 27 00:30:50.615: VDEV_DEALLOCATE: slot 2, port 51 is deallocated
*Apr 27 00:30:50.619: ISDN Dc2 SC EVENT: process_modem_command: received event VOICE_HANGUP on callid 0xE and bchan 13 ces 0 cause 16 switch type 25
*Apr 27 00:30:50.619: ISDN Dc2 SC EVENTd: process_modem_command: call id 0xE ces may have changed is now 1
*Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: process_disconnect: call id 0xE, call type is VOICE, b_idb 0x62DCDA0C, ces 1, cause Normal call clearing(0x10)
*Apr 27 00:30:50.623: %ISDN-6-DISCONNECT: Interface Serial2:13 disconnected from 5028157000 , call lasted 18 seconds
*Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected: isdn_info=0x62DD6094, call_id=0xE
*Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected: hndl=14l, cause=16, Normal call clearing
*Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: process_disconnect: Raw Release Message 0x4BFF01000E040802FF900803809081
*Apr 27 00:31:00.211: ISDN Dc2 SC Q921d: srl_send_l2_pak:
source_id = IUA, dest_id = Q.931, prim = DL_DATA_IND
priv_len = 4 int_id = 0x62D3E3E0 datasize = 25
*Apr 27 00:31:00.215: ISDN Dc2 SC Q921d: data = 0x62D3E3E0000000010241040000010000
*Apr 27 00:31:00.215: 080207AB4D08028010
*Apr 27 00:31:00.215: ISDN Dc2 SC BACKHAUL: L3IF_rx_L2_pak: received data 0x080207AB4D08028010
*Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_Go: source = 0x20A, event = 0x241, call id = 0x0, int id = 0x0
*Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB state 10 event 0x4D ces 1
*Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref = 0x87AB RELEASE:Ux_Release(nlcb)
*Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_state_change: callref 0x87AB old CALL_ACTIVE, new RELEASE_REQUEST
*Apr 27 00:31:00.215: ISDN Dc2 SC CC: CCPRI_Go: source id 0x300, call id 0xE, event 0x341 (pre-ccb recovery)
*Apr 27 00:31:00.215: ISDN Dc2 SC CC: CCPRI_Go: dispatching event 0x97 call id 0xE cref 0x87AB Source->L3
*Apr 27 00:31:00.215: ISDN Dc2 SC CC: CCPCC_CallConnected: event 0x97 b channel 14 nfas int_id 2 call_id 0xE
*Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: CC_CHAN_GetUserpri: using call_id = 0xE
*Apr 27 00:31:00.219: ISDN Dc2 SC CCd: CC_CHAN_ReleaseChanpri: channel 14
*Apr 27 00:31:00.219: ISDN Dc2 SC TGRM: get_tgrm_avail_state: idb 0x62D3E3E0 bchan 14 service_state 0 call_state 0 false busy 0x0 dsl 2
*Apr 27 00:31:00.219: ISDN Dc2 SC TGRM: update_tgrm_call_status: idb 0x62D3E3E0 bchan 14 availability state 1 call state(prev,new) (2,0), dsl 2
*Apr 27 00:31:00.219: ISDN Dc2 SC TGRM: update_tgrm_call_status: Calling TGRM with tgrm_call_isdn_update: idb 0x62D3E3E0 bchan 14 call state 0 call type 0 call dir 1
*Apr 27 00:31:00.219: ISDN EVENTd: cc_clear_free_list freed 0x6339ABFC
*Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event = 0x340, call id = 0xE, int id = 0x2
*Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB state 19 event 0xAB ces 1
*Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref = 0x87AB CC_REL_COMP_REQ:U19_RelCompReq(nlcb)
*Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 5 octets 0x080287AB5A
*Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: srl_send_l3_pak:
source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
*Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: data = 0x62D3E3E0000100000240046A00010806
*Apr 27 00:31:00.219: 080287AB5A
*Apr 27 00:31:00.223: ISDN Dc2 SC Q931d: L3_state_change: callref 0x87AB old RELEASE_REQUEST, new NULL_STATE
*Apr 27 00:31:00.223: ISDN Dc2 SC EVENT: process_rxstate: ces/callid 1/0xE calltype 2 CALL_DISC
*Apr 27 00:31:00.223: ISDN Dc2 SC PACKET: process_rxstate: 0x4B0201000E0308011008028010
*Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: process_rxstate: cause=0x10 (16), cause_present=1
*Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected: isdn_info=0x62D469E0, call_id=0xE
*Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected: isdn_info=0x62DD6094, call_id=0xE
*Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected: isdn_info=0x62D469E0, call_id=0xE
*Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected: isdn_info=0x62DD6094, call_id=0xE
*Apr 27 00:31:00.223: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0, call_id=0xE, ces=0x1
bchan=0xD, event=0x0, cause=0x10
*Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: process_disc_ack: call id 0xE, ces 1, call type VOICE cause 0x10
*Apr 27 00:31:00.223: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call id 0x0, event 0x57 (pre-ccb recovery)
*Apr 27 00:31:00.223: ISDN Dc2 SC SERROR: CCPRI_Go: call id 0xE event 0x57 No ccb Source->HOST
*Apr 27 00:31:00.223: ISDN Dc2 SC EVENT: process_rxstate: ces/callid 1/0xE calltype 2 CALL_CLEARED
*Apr 27 00:31:00.227: ISDN Dc2 SC PACKET: process_rxstate: 0x570201000E0008028010
*Apr 27 00:31:00.227: ISDN Dc2 SC EVENTd: process_rxstate: cause=0x10 (16), cause_present=1
*Apr 27 00:31:00.227: ISDN Dc2 SC EVENTd: calltrkr_call_cleared: isdn_info=0x62D469E0, call_id=0xE
*Apr 27 00:31:00.227: ISDN Dc2 SC EVENTd: calltrkr_call_cleared: isdn_info=0x62DD6094, call_id=0xE
*Apr 27 00:31:00.227: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0, call_id=0xE, ces=0x1
bchan=0xD, event=0x0, cause=0x10

Aaron at cisco

Aug 25, 2008, 12:48 PM

Post #2 of 12 (3589 views)
Permalink

Re: Modems not responding on cisco AS5300. [In reply to]

Hi Joseph,

(Boy, it's been awhile since this list has gotten a legitimate question!)

>From the debugs, it looks like this call into modem 2/51 simply failed
to train. It is possible that the DSP that handles 2/51 (and 2/50) has
gone into some bad state; can't tell from the debugs alone.

I would get the "show modem csr" output and see whether there is an
inordinately large % of failed calls into this DSP (i.e. 2/50 and 2/51),
when compared with other modems in this 5300 that handle the same client
base.

If so, then I suppose this would be a DSP bug of some sort. Could try
upgrading to the last portware (2.9.5.0) if you're not already running
it. If that doesn't clear it up, then could configure Modem Recovery.

Configuring MICA Modem Recovery
http://www.cisco.com/en/US/tech/tk801/tk36/technologies_tech_note09186a0080094cac.shtml

Hth,

Aaron

----

> We're working with a Cisco AS5300, and have been having a problem
> wherein it will answer a call, but the call never gets forwarded to a
> modem. Sometimes it works, usually not. There is some reason to
> believe that it works after a call has hit a modem once. It fails the
> first time and works after that, but I can't confirm that.
>
> Here's the "debug modem csm" output from a failed call. I've bolded
> what I assume is the important text.
>
> as5300_frv_1#
> *Apr 27 00:30:32.087: ISDN Dc2 SC Q921d: srl_send_l2_pak:
> source_id = IUA, dest_id = Q.931, prim = DL_DATA_IND
> priv_len = 4 int_id = 0x62D3E3E0 datasize = 62
> *Apr 27 00:30:32.087: ISDN Dc2 SC Q921d: data =
> 0x62D3E3E0000000010241040000010000
> *Apr 27 00:30:32.091: 080207AB0504038090A21803A1838E1E
> *Apr 27 00:30:32.091: 0281836C0CA181353032383135373030
> *Apr 27 00:30:32.091: 30700BA134333433393431323334
> *Apr 27 00:30:32.091: ISDN Dc2 SC BACKHAUL: L3IF_rx_L2_pak: received
> data 0x080207AB0504038090A21803A1838E1E
> *Apr 27 00:30:32.091: 0281836C0CA181353032383135373030
> *Apr 27 00:30:32.091: 30700BA134333433393431323334
> *Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_Go: source = 0x20A, event
> = 0x241, call id = 0x0, int id = 0x0
> *Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
> state 0 event 0x5 ces 1
> *Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
> 0x87AB SETUP:U0_Setup(nlcb)
> *Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_state_change: callref
> 0x87AB old NULL_STATE, new CALL_PRESENT
> *Apr 27 00:30:32.091: ISDN Dc2 SC CC: CCPRI_Go: source id 0x300, call
> id 0xE, event 0x341 (pre-ccb recovery)
> *Apr 27 00:30:32.091: ISDN Dc2 SC CC: CCPRI_Go: call id 0x2 cref 0xE
> event 0x87AB Source->L3
> *Apr 27 00:30:32.095: ISDN Dc2 SC CC: CCPCC_CallIdle: event 0x90 b
> channel 0 nfas int_id 0 call_id 0xE
> *Apr 27 00:30:32.095: ISDN Dc2 SC CC: CCPRI_AcceptChanId: Negotiated
> int_id 0 bchan 0 cref 0x87AB call_id 0x000E lo_chan 14 final
> int_id/bchan 2/14 cause 0
> *Apr 27 00:30:32.095: ISDN Dc2 SC TGRM: get_tgrm_avail_state: idb
> 0x62D3E3E0 bchan 14 service_state 0 call_state 2 false busy 0x0 dsl 2
> *Apr 27 00:30:32.095: ISDN Dc2 SC TGRM: update_tgrm_call_status: idb
> 0x62D3E3E0 bchan 14 availability state 1 call state(prev,new) (0,2), dsl 2
> *Apr 27 00:30:32.095: ISDN Dc2 SC TGRM: update_tgrm_call_status:
> Calling TGRM with tgrm_call_isdn_update: idb 0x62D3E3E0 bchan 14 call
> state 1 call type 2 call dir 1
> *Apr 27 00:30:32.095: ISDN Dc2 SC EVENT: process_rxstate: ces/callid
> 1/0xE calltype 2 CALL_INCOMING
> *Apr 27 00:30:32.095: ISDN Dc2 SC PACKET: process_rxstate:
> 0x4C0201000E1A04040000100218042003
> *Apr 27 00:30:32.095: 0E02700C020134333433393431323334
> *Apr 27 00:30:32.095: 04038090A21803A1838E1E0281836C0C
> *Apr 27 00:30:32.095: A18135303238313537303030700BA134
> *Apr 27 00:30:32.095: 333433393431323334
> *Apr 27 00:30:32.095: ISDN Dc2 SC EVENTd: calltrkr_incoming_call:
> call_id=0xE
> *Apr 27 00:30:32.095: ISDN Dc2 SC EVENTd: calltrkr_setup_received:
> isdn_info=1658087904l, call_id=0xE ANSWER
> *Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: calltrkr_setup_received:
> isdn_info=1658675348l, call_id=0xE ANSWER
> *Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: call_incoming: b channel 13,
> call type is VOICE ULAW
> *Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: call_incoming: Received a
> VOICE call from 5028157000 on b channel 13 at 64 Kb/s
> *Apr 27 00:30:32.099: VDEV_ALLOCATE: 2/51 is allocated
> *Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: isdn_fromdialer: RM returned
> call_type 1 resource type 0 response 2
> *Apr 27 00:30:32.099: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call
> id 0x0, event 0x4A (pre-ccb recovery)
> *Apr 27 00:30:32.099: ISDN Dc2 SC CC: CCPRI_Go: call_id 0xE cref
> 0x87AB event 0x4A Source->HOST
> *Apr 27 00:30:32.099: ISDN Dc2 SC CC: CCPCC_CallOffered: event = 0x4A
> b channel 14 nfas int_id 2 call_id 0xE
> *Apr 27 00:30:32.099: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event
> = 0x340, call id = 0xE, int id = 0x2
> *Apr 27 00:30:32.099: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
> state 6 event 0x88 ces 1
> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
> 0x87AB CC_CALL_PROC_REQ:U6_CallProcReq(nlcb)
> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 10
> octets 0x080287AB021803A9838E
> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: srl_send_l3_pak:
> source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
> priv_len = 4 int_id = 0x62D3E3E0 datasize = 26
> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: data =
> 0x62D3E3E0000100000240046A00010800
> *Apr 27 00:30:32.103: 080287AB021803A9838E
> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: L3_state_change: callref
> 0x87AB old CALL_PRESENT, new IN_CALL_PROC
> *Apr 27 00:30:32.103: ISDN Dc2 SC EVENT: UserIdle: callid 0xE received
> ACCEPT_CALL (0x13)
> *Apr 27 00:30:32.103: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0,
> call_id=0xE, ces=0x0
> bchan=0xD, event=0x1, cause=0x0
> *Apr 27 00:30:32.103: dev in call to isdn : set dnis_collected &
> fap_notify
> *Apr 27 00:30:32.103: EVENT_FROM_ISDN:(000E): DEV_INCALL at slot 2,
> port 51
> *Apr 27 00:30:32.103: EVENT_FROM_ISDN: decode:calling oct3 0xA1,
> called oct3 0xA1, oct3a 0x0,mask 0x3D
> *Apr 27 00:30:32.103: EVENT_FROM_ISDN: csm_call_info:calling oct3
> 0xA1, called oct3 0xA1, oct3a 0x0,mask 0x3D
> *Apr 27 00:30:32.103: CSM_PROC_IDLE: CSM_EVENT_ISDN_CALL at slot 2,
> port 51
> *Apr 27 00:30:32.103: Mica Modem(2/51): Configure(0x1 = 0x0)
> *Apr 27 00:30:32.103: Mica Modem(2/51): Configure(0x23 = 0x0)
> *Apr 27 00:30:32.103: Mica Modem(2/51): Call Setup
> *Apr 27 00:30:32.103: csm_connect_pri_vdev: TS allocated at bp_stream
> 0, bp_Ch 13, vdev_common 0x625BA2C4 2/51
> *Apr 27 00:30:32.107: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call
> id 0x0, event 0x4E (pre-ccb recovery)
> *Apr 27 00:30:32.107: ISDN Dc2 SC CC: CCPRI_Go: call_id 0xE cref
> 0x87AB event 0x4E Source->HOST
> *Apr 27 00:30:32.107: ISDN Dc2 SC CC: CCPCC_CallRoutingIn: executing
> with event = 4E in state = CALL ROUTING_IN
> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event
> = 0x340, call id = 0xE, int id = 0x2
> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
> state 9 event 0x86 ces 1
> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
> 0x87AB CC_ALERTING_REQ:U9_AlertingReq(nlcb)
> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 5
> octets 0x080287AB01
> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: srl_send_l3_pak:
> source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
> priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: data =
> 0x62D3E3E0000100000240046A00010800
> *Apr 27 00:30:32.107: 080287AB01
> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_state_change: callref
> 0x87AB old IN_CALL_PROC, new CALL_RECEIVED
> *Apr 27 00:30:32.175: Mica Modem(2/51): State Transition to Call Setup
> *Apr 27 00:30:32.175: Mica Modem(2/51): Went offhook
> *Apr 27 00:30:32.175: CSM_PROC_IC2_RING: CSM_EVENT_MODEM_OFFHOOK at
> slot 2, port 51
> *Apr 27 00:30:32.175: ISDN Dc2 SC EVENT: process_modem_command:
> received event VOICE_ANS on callid 0xE and bchan 13 ces 0 cause 16
> switch type 25
> *Apr 27 00:30:32.175: ISDN Dc2 SC EVENTd: isdn_send_connect: msg 74,
> call id 0xE, ces 0 bchan 13, call type VOICE
> *Apr 27 00:30:32.175: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call
> id 0x0, event 0x4A (pre-ccb recovery)
> *Apr 27 00:30:32.175: ISDN Dc2 SC CC: CCPRI_Go: call_id 0xE cref
> 0x87AB event 0x4A Source->HOST
> *Apr 27 00:30:32.175: ISDN Dc2 SC CC: CCPCC_CallRinging: event 0x4A b
> channel 14 nfas int_id 2 call_id 0xE
> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event
> = 0x340, call id = 0xE, int id = 0x2
> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
> state 7 event 0x81 ces 1
> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
> 0x87AB CC_SETUP_RESP:U7_SetupResp(nlcb)
> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 5
> octets 0x080287AB07
> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: srl_send_l3_pak:
> source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
> priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: data =
> 0x62D3E3E0000100000240046A00010800
> *Apr 27 00:30:32.179: 080287AB07
> *Apr 27 00:30:32.179: ISDN Dc2 SC LIFd: LIF_StartTimer: timer
> (0x630C8090), ticks (4000), event (0x131C)
> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_state_change: callref
> 0x87AB old CALL_RECEIVED, new CONNECT_REQUEST
> *Apr 27 00:30:32.323: ISDN Dc2 SC Q921d: srl_send_l2_pak:
> source_id = IUA, dest_id = Q.931, prim = DL_DATA_IND
> priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
> *Apr 27 00:30:32.323: ISDN Dc2 SC Q921d: data =
> 0x62D3E3E0000000010241040000010000
> *Apr 27 00:30:32.323: 080207AB0F
> *Apr 27 00:30:32.323: ISDN Dc2 SC BACKHAUL: L3IF_rx_L2_pak: received
> data 0x080207AB0F
> *Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_Go: source = 0x20A, event
> = 0x241, call id = 0x0, int id = 0x0
> *Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
> state 8 event 0xF ces 1
> *Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
> 0x87AB CONNECT_ACK:U8_ConnectAck(nlcb)
> *Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_state_change: callref
> 0x87AB old CONNECT_REQUEST, new CALL_ACTIVE
> *Apr 27 00:30:32.327: ISDN Dc2 SC CC: CCPRI_Go: source id 0x300, call
> id 0xE, event 0x341 (pre-ccb recovery)
> *Apr 27 00:30:32.327: ISDN Dc2 SC CC: CCPRI_Go: dispatching event 0x92
> call id 0xE cref 0x87AB Source->L3
> *Apr 27 00:30:32.327: ISDN Dc2 SC CC: CCPCC_CallRoutingIn: executing
> with event = 92 in state = CALL ROUTING_IN
> *Apr 27 00:30:32.327: ISDN Dc2 SC EVENT: process_rxstate: ces/callid
> 1/0xE calltype 2 CALL_PROGRESS
> *Apr 27 00:30:32.327: ISDN Dc2 SC PACKET: process_rxstate:
> 0x4E0201000E031E0187
> *Apr 27 00:30:32.327: ISDN Dc2 SC EVENTd: calltrkr_call_connect:
> isdn_info=0x62DD6094, call_id=0xE
> *Apr 27 00:30:32.327: ISDN Dc2 SC EVENTd: calltrkr_call_connect:
> hndl=14l, cntrl_slot=0, cntrl_port=2, cntrl_channel=2.
> *Apr 27 00:30:32.327: ISDN Dc2 SC EVENTd: call_progress:
> CALL_CONNECTED b channel 13 call id 0xE
> *Apr 27 00:30:32.327: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0,
> call_id=0xE, ces=0x0
> bchan=0xD, event=0x4, cause=0x0
> *Apr 27 00:30:32.327: EVENT_FROM_ISDN:(000E): DEV_CONNECTED at slot 2,
> port 51
> *Apr 27 00:30:32.327: CSM_PROC_IC6_WAIT_FOR_CONNECT:
> CSM_EVENT_ISDN_CONNECTED at slot 2, port 51
> *Apr 27 00:30:32.327: Mica Modem(2/51): Link Initiate
> *Apr 27 00:30:32.327: %ISDN-6-CONNECT: Interface Serial2:13 is now
> connected to 5028157000 N/A
> *Apr 27 00:30:33.419: Mica Modem(2/51): State Transition to Connect
> *Apr 27 00:30:33.435: Mica Modem(2/51): State Transition to V8bis Exchange
> *Apr 27 00:30:37.879: Mica Modem(2/51): State Transition to Link
> **Apr 27 00:30:42.147: Mica Modem(2/51): State Transition to Trainup
> *Apr 27 00:30:50.015: Mica Modem(2/51): State Transition to Terminating
> *Apr 27 00:30:50.451: %CALLRECORD-3-MICA_TERSE_CALL_FAILED_REC: DS0
> slot/contr/chan=0/2/13, slot/port=2/51, call_id=E, calling=5028157000,
> called=4343941234, time=17, finl-state=Train Up, disc(modem)=6102
> Condition occurred during call setup/DSP condition/failure in modem
> training up
> **Apr 27 00:30:50.615: Mica Modem(2/51): State Transition to Idle
> *Apr 27 00:30:50.615: Mica Modem(2/51): Went onhook
> *Apr 27 00:30:50.615: CSM_PROC_IC7_OC6_CONNECTED:
> CSM_EVENT_MODEM_ONHOOK at slot 2, port 51
> *Apr 27 00:30:50.615: CSM_PROC_IC7_OC6_CONNECTED: cause code to isdn 0x0
> *Apr 27 00:30:50.615: CSM(2/51): Enter csm_enter_idle_state
> *Apr 27 00:30:50.615: VDEV_DEALLOCATE: slot 2, port 51 is deallocated
> *Apr 27 00:30:50.619: ISDN Dc2 SC EVENT: process_modem_command:
> received event VOICE_HANGUP on callid 0xE and bchan 13 ces 0 cause 16
> switch type 25
> *Apr 27 00:30:50.619: ISDN Dc2 SC EVENTd: process_modem_command: call
> id 0xE ces may have changed is now 1
> *Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: process_disconnect: call id
> 0xE, call type is VOICE, b_idb 0x62DCDA0C, ces 1, cause Normal call
> clearing(0x10)
> *Apr 27 00:30:50.623: %ISDN-6-DISCONNECT: Interface Serial2:13
> disconnected from 5028157000 , call lasted 18 seconds
> *Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
> isdn_info=0x62DD6094, call_id=0xE
> *Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
> hndl=14l, cause=16, Normal call clearing
> *Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: process_disconnect: Raw
> Release Message 0x4BFF01000E040802FF900803809081
> *Apr 27 00:31:00.211: ISDN Dc2 SC Q921d: srl_send_l2_pak:
> source_id = IUA, dest_id = Q.931, prim = DL_DATA_IND
> priv_len = 4 int_id = 0x62D3E3E0 datasize = 25
> *Apr 27 00:31:00.215: ISDN Dc2 SC Q921d: data =
> 0x62D3E3E0000000010241040000010000
> *Apr 27 00:31:00.215: 080207AB4D08028010
> *Apr 27 00:31:00.215: ISDN Dc2 SC BACKHAUL: L3IF_rx_L2_pak: received
> data 0x080207AB4D08028010
> *Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_Go: source = 0x20A, event
> = 0x241, call id = 0x0, int id = 0x0
> *Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
> state 10 event 0x4D ces 1
> *Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
> 0x87AB RELEASE:Ux_Release(nlcb)
> *Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_state_change: callref
> 0x87AB old CALL_ACTIVE, new RELEASE_REQUEST
> *Apr 27 00:31:00.215: ISDN Dc2 SC CC: CCPRI_Go: source id 0x300, call
> id 0xE, event 0x341 (pre-ccb recovery)
> *Apr 27 00:31:00.215: ISDN Dc2 SC CC: CCPRI_Go: dispatching event 0x97
> call id 0xE cref 0x87AB Source->L3
> *Apr 27 00:31:00.215: ISDN Dc2 SC CC: CCPCC_CallConnected: event 0x97
> b channel 14 nfas int_id 2 call_id 0xE
> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: CC_CHAN_GetUserpri: using
> call_id = 0xE
> *Apr 27 00:31:00.219: ISDN Dc2 SC CCd: CC_CHAN_ReleaseChanpri: channel 14
> *Apr 27 00:31:00.219: ISDN Dc2 SC TGRM: get_tgrm_avail_state: idb
> 0x62D3E3E0 bchan 14 service_state 0 call_state 0 false busy 0x0 dsl 2
> *Apr 27 00:31:00.219: ISDN Dc2 SC TGRM: update_tgrm_call_status: idb
> 0x62D3E3E0 bchan 14 availability state 1 call state(prev,new) (2,0), dsl 2
> *Apr 27 00:31:00.219: ISDN Dc2 SC TGRM: update_tgrm_call_status:
> Calling TGRM with tgrm_call_isdn_update: idb 0x62D3E3E0 bchan 14 call
> state 0 call type 0 call dir 1
> *Apr 27 00:31:00.219: ISDN EVENTd: cc_clear_free_list freed 0x6339ABFC
> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event
> = 0x340, call id = 0xE, int id = 0x2
> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
> state 19 event 0xAB ces 1
> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
> 0x87AB CC_REL_COMP_REQ:U19_RelCompReq(nlcb)
> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 5
> octets 0x080287AB5A
> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: srl_send_l3_pak:
> source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
> priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: data =
> 0x62D3E3E0000100000240046A00010806
> *Apr 27 00:31:00.219: 080287AB5A
> *Apr 27 00:31:00.223: ISDN Dc2 SC Q931d: L3_state_change: callref
> 0x87AB old RELEASE_REQUEST, new NULL_STATE
> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENT: process_rxstate: ces/callid
> 1/0xE calltype 2 CALL_DISC
> *Apr 27 00:31:00.223: ISDN Dc2 SC PACKET: process_rxstate:
> 0x4B0201000E0308011008028010
> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: process_rxstate: cause=0x10
> (16), cause_present=1
> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
> isdn_info=0x62D469E0, call_id=0xE
> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
> isdn_info=0x62DD6094, call_id=0xE
> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
> isdn_info=0x62D469E0, call_id=0xE
> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
> isdn_info=0x62DD6094, call_id=0xE
> *Apr 27 00:31:00.223: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0,
> call_id=0xE, ces=0x1
> bchan=0xD, event=0x0, cause=0x10
> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: process_disc_ack: call id
> 0xE, ces 1, call type VOICE cause 0x10
> *Apr 27 00:31:00.223: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call
> id 0x0, event 0x57 (pre-ccb recovery)
> *Apr 27 00:31:00.223: ISDN Dc2 SC SERROR: CCPRI_Go: call id 0xE event
> 0x57 No ccb Source->HOST
> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENT: process_rxstate: ces/callid
> 1/0xE calltype 2 CALL_CLEARED
> *Apr 27 00:31:00.227: ISDN Dc2 SC PACKET: process_rxstate:
> 0x570201000E0008028010
> *Apr 27 00:31:00.227: ISDN Dc2 SC EVENTd: process_rxstate: cause=0x10
> (16), cause_present=1
> *Apr 27 00:31:00.227: ISDN Dc2 SC EVENTd: calltrkr_call_cleared:
> isdn_info=0x62D469E0, call_id=0xE
> *Apr 27 00:31:00.227: ISDN Dc2 SC EVENTd: calltrkr_call_cleared:
> isdn_info=0x62DD6094, call_id=0xE
> *Apr 27 00:31:00.227: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0,
> call_id=0xE, ces=0x1
> bchan=0xD, event=0x0, cause=0x10
> ------------------------------------------------------------------------
>
> _______________________________________________
> cisco-nas mailing list
> cisco-nas [at] puck
> https://puck.nether.net/mailman/listinfo/cisco-nas

mays at win

Aug 25, 2008, 12:53 PM

Post #3 of 12 (3562 views)
Permalink

Re: Modems not responding on cisco AS5300. [In reply to]

> From the debugs, it looks like this call into modem 2/51 simply failed
> to train. It is possible that the DSP that handles 2/51 (and 2/50) has
> gone into some bad state; can't tell from the debugs alone.

Yeah. If you're calling it on the phone when this issue occurs, you see that
in the debug logs but what you hear on the phone is just dead air. No modem,
nothing.

Thanks for the suggestions, I'll try them and report what happens.

_______________________________________________
cisco-nas mailing list
cisco-nas [at] puck
https://puck.nether.net/mailman/listinfo/cisco-nas

Aaron at cisco

Aug 25, 2008, 12:56 PM

Post #4 of 12 (3584 views)
Permalink

Re: Modems not responding on cisco AS5300. [In reply to]

>> From the debugs, it looks like this call into modem 2/51 simply failed
>> to train. It is possible that the DSP that handles 2/51 (and 2/50) has
>> gone into some bad state; can't tell from the debugs alone.
>>
>
> Yeah. If you're calling it on the phone when this issue occurs, you see that
> in the debug logs but what you hear on the phone is just dead air. No modem,
> nothing.
>

Good test - then I definitely go with the dead DSP theory.

> Thanks for the suggestions, I'll try them and report what happens.
>

There's one more thing you can do - hunt down the client modem that is
putting the DSP into the bad state.

I.e. look at your modem logs and find out who had last called right
before the DSP went into the bad state. (Here I assume that you are
getting CLID from the switch.) There may be a pattern - you may see the
same CLID popping up over and over again when the DSP goes bad. If you
can figure out who this is, you can offer them a free modem if they stop
calling you with this one. (Don't laugh, we have had some other
customers employ this technique successfully.)

Aaron
_______________________________________________
cisco-nas mailing list
cisco-nas [at] puck
https://puck.nether.net/mailman/listinfo/cisco-nas

paula.j.nailor at verizon

Aug 25, 2008, 3:54 PM

Post #5 of 12 (3525 views)
Permalink

Re: Verizon is hiring! [In reply to]

I’m with Verizon Telecom Recruiting - your experience is a possible fit
for positions at Verizon.

Our job opportunities can be viewed on our site,
https://www22.verizon.com/about/careers/jobsearch/?referrer=VZCCareers. If
you are not seeking new employment, feel free to pass this message on to
an associate who has similar business and educational experience.

Regards,

Paula J. Nailor
Management Staffing & Recruiting
240 East 38th Street, Room 1517
New York, NY 10016

646-227-6822 TEL
212-949-0386 FAX

Paula Nailor
Verizon Communications
National Recruiting Team
Partner Solutions, HR, Public Affairs, Finance
240 East 38th Street, 15th floor
New York, NY 10016

646-227-6822 Tel
212-949-0386 Fax

WANT MORE INFORMATION ON OUR VERIZON PRODUCTS? CALL ME.

DSL, FiOS Internet, FiOS TV, DirecTV, Games on Demand, ISDN, CPE Data
systems.

Get the message: http://vbn.verizon.com/flawless This is FiOS. This is
big!

To find out about our careers at Verizon Telecom visit
www.verizontelecom.jobs

mays at win

Aug 25, 2008, 4:51 PM

Post #6 of 12 (3593 views)
Permalink

Re: Modems not responding on cisco AS5300. [In reply to]

More news on this problem. There are two modem cards in this box. Each with
48 active modems, so 1/0 1/47 and 2/0 2/47.

In dialing through all the modems, I get modem tone on 1/0 to 1/11 then dead
air on 1/12 to 1/17, then tone again on 1/18 to 1/47. Then modem tone on 2/0
to 2/11, then dead air on 2/12 to 2/17, then modem tone again on 2/18 to
2/47.

If it were just one card, easy, bad spe chipset. But it seems awfully damned
coincidental to have the same set of chips bad on each card. Is there any
shared circuitry for positions x/12 to x/17 in the slots on the motherboard?
I don't see anything at all in the config that specifically references those
modem ranges, but could there be any modem thing that is causing it?

----- Original Message -----
From: "Aaron Leonard" <Aaron [at] cisco>
To: "Joseph Mays" <mays [at] win>
Cc: <cisco-nas [at] puck>
Sent: Monday, August 25, 2008 3:48 PM
Subject: Re: [cisco-nas] Modems not responding on cisco AS5300.

> Hi Joseph,
>
> (Boy, it's been awhile since this list has gotten a legitimate question!)
>
> From the debugs, it looks like this call into modem 2/51 simply failed
> to train. It is possible that the DSP that handles 2/51 (and 2/50) has
> gone into some bad state; can't tell from the debugs alone.
>
> I would get the "show modem csr" output and see whether there is an
> inordinately large % of failed calls into this DSP (i.e. 2/50 and 2/51),
> when compared with other modems in this 5300 that handle the same client
> base.
>
> If so, then I suppose this would be a DSP bug of some sort. Could try
> upgrading to the last portware (2.9.5.0) if you're not already running
> it. If that doesn't clear it up, then could configure Modem Recovery.
>
> Configuring MICA Modem Recovery
> http://www.cisco.com/en/US/tech/tk801/tk36/technologies_tech_note09186a0080094cac.shtml
>
> Hth,
>
> Aaron
>
> ----
>
>> We're working with a Cisco AS5300, and have been having a problem
>> wherein it will answer a call, but the call never gets forwarded to a
>> modem. Sometimes it works, usually not. There is some reason to
>> believe that it works after a call has hit a modem once. It fails the
>> first time and works after that, but I can't confirm that.
>>
>> Here's the "debug modem csm" output from a failed call. I've bolded
>> what I assume is the important text.
>>
>> as5300_frv_1#
>> *Apr 27 00:30:32.087: ISDN Dc2 SC Q921d: srl_send_l2_pak:
>> source_id = IUA, dest_id = Q.931, prim = DL_DATA_IND
>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 62
>> *Apr 27 00:30:32.087: ISDN Dc2 SC Q921d: data =
>> 0x62D3E3E0000000010241040000010000
>> *Apr 27 00:30:32.091: 080207AB0504038090A21803A1838E1E
>> *Apr 27 00:30:32.091: 0281836C0CA181353032383135373030
>> *Apr 27 00:30:32.091: 30700BA134333433393431323334
>> *Apr 27 00:30:32.091: ISDN Dc2 SC BACKHAUL: L3IF_rx_L2_pak: received
>> data 0x080207AB0504038090A21803A1838E1E
>> *Apr 27 00:30:32.091: 0281836C0CA181353032383135373030
>> *Apr 27 00:30:32.091: 30700BA134333433393431323334
>> *Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_Go: source = 0x20A, event
>> = 0x241, call id = 0x0, int id = 0x0
>> *Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>> state 0 event 0x5 ces 1
>> *Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>> 0x87AB SETUP:U0_Setup(nlcb)
>> *Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_state_change: callref
>> 0x87AB old NULL_STATE, new CALL_PRESENT
>> *Apr 27 00:30:32.091: ISDN Dc2 SC CC: CCPRI_Go: source id 0x300, call
>> id 0xE, event 0x341 (pre-ccb recovery)
>> *Apr 27 00:30:32.091: ISDN Dc2 SC CC: CCPRI_Go: call id 0x2 cref 0xE
>> event 0x87AB Source->L3
>> *Apr 27 00:30:32.095: ISDN Dc2 SC CC: CCPCC_CallIdle: event 0x90 b
>> channel 0 nfas int_id 0 call_id 0xE
>> *Apr 27 00:30:32.095: ISDN Dc2 SC CC: CCPRI_AcceptChanId: Negotiated
>> int_id 0 bchan 0 cref 0x87AB call_id 0x000E lo_chan 14 final
>> int_id/bchan 2/14 cause 0
>> *Apr 27 00:30:32.095: ISDN Dc2 SC TGRM: get_tgrm_avail_state: idb
>> 0x62D3E3E0 bchan 14 service_state 0 call_state 2 false busy 0x0 dsl 2
>> *Apr 27 00:30:32.095: ISDN Dc2 SC TGRM: update_tgrm_call_status: idb
>> 0x62D3E3E0 bchan 14 availability state 1 call state(prev,new) (0,2), dsl
>> 2
>> *Apr 27 00:30:32.095: ISDN Dc2 SC TGRM: update_tgrm_call_status:
>> Calling TGRM with tgrm_call_isdn_update: idb 0x62D3E3E0 bchan 14 call
>> state 1 call type 2 call dir 1
>> *Apr 27 00:30:32.095: ISDN Dc2 SC EVENT: process_rxstate: ces/callid
>> 1/0xE calltype 2 CALL_INCOMING
>> *Apr 27 00:30:32.095: ISDN Dc2 SC PACKET: process_rxstate:
>> 0x4C0201000E1A04040000100218042003
>> *Apr 27 00:30:32.095: 0E02700C020134333433393431323334
>> *Apr 27 00:30:32.095: 04038090A21803A1838E1E0281836C0C
>> *Apr 27 00:30:32.095: A18135303238313537303030700BA134
>> *Apr 27 00:30:32.095: 333433393431323334
>> *Apr 27 00:30:32.095: ISDN Dc2 SC EVENTd: calltrkr_incoming_call:
>> call_id=0xE
>> *Apr 27 00:30:32.095: ISDN Dc2 SC EVENTd: calltrkr_setup_received:
>> isdn_info=1658087904l, call_id=0xE ANSWER
>> *Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: calltrkr_setup_received:
>> isdn_info=1658675348l, call_id=0xE ANSWER
>> *Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: call_incoming: b channel 13,
>> call type is VOICE ULAW
>> *Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: call_incoming: Received a
>> VOICE call from 5028157000 on b channel 13 at 64 Kb/s
>> *Apr 27 00:30:32.099: VDEV_ALLOCATE: 2/51 is allocated
>> *Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: isdn_fromdialer: RM returned
>> call_type 1 resource type 0 response 2
>> *Apr 27 00:30:32.099: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call
>> id 0x0, event 0x4A (pre-ccb recovery)
>> *Apr 27 00:30:32.099: ISDN Dc2 SC CC: CCPRI_Go: call_id 0xE cref
>> 0x87AB event 0x4A Source->HOST
>> *Apr 27 00:30:32.099: ISDN Dc2 SC CC: CCPCC_CallOffered: event = 0x4A
>> b channel 14 nfas int_id 2 call_id 0xE
>> *Apr 27 00:30:32.099: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event
>> = 0x340, call id = 0xE, int id = 0x2
>> *Apr 27 00:30:32.099: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>> state 6 event 0x88 ces 1
>> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>> 0x87AB CC_CALL_PROC_REQ:U6_CallProcReq(nlcb)
>> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 10
>> octets 0x080287AB021803A9838E
>> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: srl_send_l3_pak:
>> source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 26
>> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: data =
>> 0x62D3E3E0000100000240046A00010800
>> *Apr 27 00:30:32.103: 080287AB021803A9838E
>> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: L3_state_change: callref
>> 0x87AB old CALL_PRESENT, new IN_CALL_PROC
>> *Apr 27 00:30:32.103: ISDN Dc2 SC EVENT: UserIdle: callid 0xE received
>> ACCEPT_CALL (0x13)
>> *Apr 27 00:30:32.103: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0,
>> call_id=0xE, ces=0x0
>> bchan=0xD, event=0x1, cause=0x0
>> *Apr 27 00:30:32.103: dev in call to isdn : set dnis_collected &
>> fap_notify
>> *Apr 27 00:30:32.103: EVENT_FROM_ISDN:(000E): DEV_INCALL at slot 2,
>> port 51
>> *Apr 27 00:30:32.103: EVENT_FROM_ISDN: decode:calling oct3 0xA1,
>> called oct3 0xA1, oct3a 0x0,mask 0x3D
>> *Apr 27 00:30:32.103: EVENT_FROM_ISDN: csm_call_info:calling oct3
>> 0xA1, called oct3 0xA1, oct3a 0x0,mask 0x3D
>> *Apr 27 00:30:32.103: CSM_PROC_IDLE: CSM_EVENT_ISDN_CALL at slot 2,
>> port 51
>> *Apr 27 00:30:32.103: Mica Modem(2/51): Configure(0x1 = 0x0)
>> *Apr 27 00:30:32.103: Mica Modem(2/51): Configure(0x23 = 0x0)
>> *Apr 27 00:30:32.103: Mica Modem(2/51): Call Setup
>> *Apr 27 00:30:32.103: csm_connect_pri_vdev: TS allocated at bp_stream
>> 0, bp_Ch 13, vdev_common 0x625BA2C4 2/51
>> *Apr 27 00:30:32.107: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call
>> id 0x0, event 0x4E (pre-ccb recovery)
>> *Apr 27 00:30:32.107: ISDN Dc2 SC CC: CCPRI_Go: call_id 0xE cref
>> 0x87AB event 0x4E Source->HOST
>> *Apr 27 00:30:32.107: ISDN Dc2 SC CC: CCPCC_CallRoutingIn: executing
>> with event = 4E in state = CALL ROUTING_IN
>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event
>> = 0x340, call id = 0xE, int id = 0x2
>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>> state 9 event 0x86 ces 1
>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>> 0x87AB CC_ALERTING_REQ:U9_AlertingReq(nlcb)
>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 5
>> octets 0x080287AB01
>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: srl_send_l3_pak:
>> source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: data =
>> 0x62D3E3E0000100000240046A00010800
>> *Apr 27 00:30:32.107: 080287AB01
>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_state_change: callref
>> 0x87AB old IN_CALL_PROC, new CALL_RECEIVED
>> *Apr 27 00:30:32.175: Mica Modem(2/51): State Transition to Call Setup
>> *Apr 27 00:30:32.175: Mica Modem(2/51): Went offhook
>> *Apr 27 00:30:32.175: CSM_PROC_IC2_RING: CSM_EVENT_MODEM_OFFHOOK at
>> slot 2, port 51
>> *Apr 27 00:30:32.175: ISDN Dc2 SC EVENT: process_modem_command:
>> received event VOICE_ANS on callid 0xE and bchan 13 ces 0 cause 16
>> switch type 25
>> *Apr 27 00:30:32.175: ISDN Dc2 SC EVENTd: isdn_send_connect: msg 74,
>> call id 0xE, ces 0 bchan 13, call type VOICE
>> *Apr 27 00:30:32.175: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call
>> id 0x0, event 0x4A (pre-ccb recovery)
>> *Apr 27 00:30:32.175: ISDN Dc2 SC CC: CCPRI_Go: call_id 0xE cref
>> 0x87AB event 0x4A Source->HOST
>> *Apr 27 00:30:32.175: ISDN Dc2 SC CC: CCPCC_CallRinging: event 0x4A b
>> channel 14 nfas int_id 2 call_id 0xE
>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event
>> = 0x340, call id = 0xE, int id = 0x2
>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>> state 7 event 0x81 ces 1
>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>> 0x87AB CC_SETUP_RESP:U7_SetupResp(nlcb)
>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 5
>> octets 0x080287AB07
>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: srl_send_l3_pak:
>> source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: data =
>> 0x62D3E3E0000100000240046A00010800
>> *Apr 27 00:30:32.179: 080287AB07
>> *Apr 27 00:30:32.179: ISDN Dc2 SC LIFd: LIF_StartTimer: timer
>> (0x630C8090), ticks (4000), event (0x131C)
>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_state_change: callref
>> 0x87AB old CALL_RECEIVED, new CONNECT_REQUEST
>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q921d: srl_send_l2_pak:
>> source_id = IUA, dest_id = Q.931, prim = DL_DATA_IND
>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q921d: data =
>> 0x62D3E3E0000000010241040000010000
>> *Apr 27 00:30:32.323: 080207AB0F
>> *Apr 27 00:30:32.323: ISDN Dc2 SC BACKHAUL: L3IF_rx_L2_pak: received
>> data 0x080207AB0F
>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_Go: source = 0x20A, event
>> = 0x241, call id = 0x0, int id = 0x0
>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>> state 8 event 0xF ces 1
>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>> 0x87AB CONNECT_ACK:U8_ConnectAck(nlcb)
>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_state_change: callref
>> 0x87AB old CONNECT_REQUEST, new CALL_ACTIVE
>> *Apr 27 00:30:32.327: ISDN Dc2 SC CC: CCPRI_Go: source id 0x300, call
>> id 0xE, event 0x341 (pre-ccb recovery)
>> *Apr 27 00:30:32.327: ISDN Dc2 SC CC: CCPRI_Go: dispatching event 0x92
>> call id 0xE cref 0x87AB Source->L3
>> *Apr 27 00:30:32.327: ISDN Dc2 SC CC: CCPCC_CallRoutingIn: executing
>> with event = 92 in state = CALL ROUTING_IN
>> *Apr 27 00:30:32.327: ISDN Dc2 SC EVENT: process_rxstate: ces/callid
>> 1/0xE calltype 2 CALL_PROGRESS
>> *Apr 27 00:30:32.327: ISDN Dc2 SC PACKET: process_rxstate:
>> 0x4E0201000E031E0187
>> *Apr 27 00:30:32.327: ISDN Dc2 SC EVENTd: calltrkr_call_connect:
>> isdn_info=0x62DD6094, call_id=0xE
>> *Apr 27 00:30:32.327: ISDN Dc2 SC EVENTd: calltrkr_call_connect:
>> hndl=14l, cntrl_slot=0, cntrl_port=2, cntrl_channel=2.
>> *Apr 27 00:30:32.327: ISDN Dc2 SC EVENTd: call_progress:
>> CALL_CONNECTED b channel 13 call id 0xE
>> *Apr 27 00:30:32.327: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0,
>> call_id=0xE, ces=0x0
>> bchan=0xD, event=0x4, cause=0x0
>> *Apr 27 00:30:32.327: EVENT_FROM_ISDN:(000E): DEV_CONNECTED at slot 2,
>> port 51
>> *Apr 27 00:30:32.327: CSM_PROC_IC6_WAIT_FOR_CONNECT:
>> CSM_EVENT_ISDN_CONNECTED at slot 2, port 51
>> *Apr 27 00:30:32.327: Mica Modem(2/51): Link Initiate
>> *Apr 27 00:30:32.327: %ISDN-6-CONNECT: Interface Serial2:13 is now
>> connected to 5028157000 N/A
>> *Apr 27 00:30:33.419: Mica Modem(2/51): State Transition to Connect
>> *Apr 27 00:30:33.435: Mica Modem(2/51): State Transition to V8bis
>> Exchange
>> *Apr 27 00:30:37.879: Mica Modem(2/51): State Transition to Link
>> **Apr 27 00:30:42.147: Mica Modem(2/51): State Transition to Trainup
>> *Apr 27 00:30:50.015: Mica Modem(2/51): State Transition to Terminating
>> *Apr 27 00:30:50.451: %CALLRECORD-3-MICA_TERSE_CALL_FAILED_REC: DS0
>> slot/contr/chan=0/2/13, slot/port=2/51, call_id=E, calling=5028157000,
>> called=4343941234, time=17, finl-state=Train Up, disc(modem)=6102
>> Condition occurred during call setup/DSP condition/failure in modem
>> training up
>> **Apr 27 00:30:50.615: Mica Modem(2/51): State Transition to Idle
>> *Apr 27 00:30:50.615: Mica Modem(2/51): Went onhook
>> *Apr 27 00:30:50.615: CSM_PROC_IC7_OC6_CONNECTED:
>> CSM_EVENT_MODEM_ONHOOK at slot 2, port 51
>> *Apr 27 00:30:50.615: CSM_PROC_IC7_OC6_CONNECTED: cause code to isdn 0x0
>> *Apr 27 00:30:50.615: CSM(2/51): Enter csm_enter_idle_state
>> *Apr 27 00:30:50.615: VDEV_DEALLOCATE: slot 2, port 51 is deallocated
>> *Apr 27 00:30:50.619: ISDN Dc2 SC EVENT: process_modem_command:
>> received event VOICE_HANGUP on callid 0xE and bchan 13 ces 0 cause 16
>> switch type 25
>> *Apr 27 00:30:50.619: ISDN Dc2 SC EVENTd: process_modem_command: call
>> id 0xE ces may have changed is now 1
>> *Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: process_disconnect: call id
>> 0xE, call type is VOICE, b_idb 0x62DCDA0C, ces 1, cause Normal call
>> clearing(0x10)
>> *Apr 27 00:30:50.623: %ISDN-6-DISCONNECT: Interface Serial2:13
>> disconnected from 5028157000 , call lasted 18 seconds
>> *Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>> isdn_info=0x62DD6094, call_id=0xE
>> *Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>> hndl=14l, cause=16, Normal call clearing
>> *Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: process_disconnect: Raw
>> Release Message 0x4BFF01000E040802FF900803809081
>> *Apr 27 00:31:00.211: ISDN Dc2 SC Q921d: srl_send_l2_pak:
>> source_id = IUA, dest_id = Q.931, prim = DL_DATA_IND
>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 25
>> *Apr 27 00:31:00.215: ISDN Dc2 SC Q921d: data =
>> 0x62D3E3E0000000010241040000010000
>> *Apr 27 00:31:00.215: 080207AB4D08028010
>> *Apr 27 00:31:00.215: ISDN Dc2 SC BACKHAUL: L3IF_rx_L2_pak: received
>> data 0x080207AB4D08028010
>> *Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_Go: source = 0x20A, event
>> = 0x241, call id = 0x0, int id = 0x0
>> *Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>> state 10 event 0x4D ces 1
>> *Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>> 0x87AB RELEASE:Ux_Release(nlcb)
>> *Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_state_change: callref
>> 0x87AB old CALL_ACTIVE, new RELEASE_REQUEST
>> *Apr 27 00:31:00.215: ISDN Dc2 SC CC: CCPRI_Go: source id 0x300, call
>> id 0xE, event 0x341 (pre-ccb recovery)
>> *Apr 27 00:31:00.215: ISDN Dc2 SC CC: CCPRI_Go: dispatching event 0x97
>> call id 0xE cref 0x87AB Source->L3
>> *Apr 27 00:31:00.215: ISDN Dc2 SC CC: CCPCC_CallConnected: event 0x97
>> b channel 14 nfas int_id 2 call_id 0xE
>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: CC_CHAN_GetUserpri: using
>> call_id = 0xE
>> *Apr 27 00:31:00.219: ISDN Dc2 SC CCd: CC_CHAN_ReleaseChanpri: channel 14
>> *Apr 27 00:31:00.219: ISDN Dc2 SC TGRM: get_tgrm_avail_state: idb
>> 0x62D3E3E0 bchan 14 service_state 0 call_state 0 false busy 0x0 dsl 2
>> *Apr 27 00:31:00.219: ISDN Dc2 SC TGRM: update_tgrm_call_status: idb
>> 0x62D3E3E0 bchan 14 availability state 1 call state(prev,new) (2,0), dsl
>> 2
>> *Apr 27 00:31:00.219: ISDN Dc2 SC TGRM: update_tgrm_call_status:
>> Calling TGRM with tgrm_call_isdn_update: idb 0x62D3E3E0 bchan 14 call
>> state 0 call type 0 call dir 1
>> *Apr 27 00:31:00.219: ISDN EVENTd: cc_clear_free_list freed 0x6339ABFC
>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event
>> = 0x340, call id = 0xE, int id = 0x2
>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>> state 19 event 0xAB ces 1
>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>> 0x87AB CC_REL_COMP_REQ:U19_RelCompReq(nlcb)
>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 5
>> octets 0x080287AB5A
>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: srl_send_l3_pak:
>> source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: data =
>> 0x62D3E3E0000100000240046A00010806
>> *Apr 27 00:31:00.219: 080287AB5A
>> *Apr 27 00:31:00.223: ISDN Dc2 SC Q931d: L3_state_change: callref
>> 0x87AB old RELEASE_REQUEST, new NULL_STATE
>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENT: process_rxstate: ces/callid
>> 1/0xE calltype 2 CALL_DISC
>> *Apr 27 00:31:00.223: ISDN Dc2 SC PACKET: process_rxstate:
>> 0x4B0201000E0308011008028010
>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: process_rxstate: cause=0x10
>> (16), cause_present=1
>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>> isdn_info=0x62D469E0, call_id=0xE
>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>> isdn_info=0x62DD6094, call_id=0xE
>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>> isdn_info=0x62D469E0, call_id=0xE
>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>> isdn_info=0x62DD6094, call_id=0xE
>> *Apr 27 00:31:00.223: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0,
>> call_id=0xE, ces=0x1
>> bchan=0xD, event=0x0, cause=0x10
>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: process_disc_ack: call id
>> 0xE, ces 1, call type VOICE cause 0x10
>> *Apr 27 00:31:00.223: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call
>> id 0x0, event 0x57 (pre-ccb recovery)
>> *Apr 27 00:31:00.223: ISDN Dc2 SC SERROR: CCPRI_Go: call id 0xE event
>> 0x57 No ccb Source->HOST
>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENT: process_rxstate: ces/callid
>> 1/0xE calltype 2 CALL_CLEARED
>> *Apr 27 00:31:00.227: ISDN Dc2 SC PACKET: process_rxstate:
>> 0x570201000E0008028010
>> *Apr 27 00:31:00.227: ISDN Dc2 SC EVENTd: process_rxstate: cause=0x10
>> (16), cause_present=1
>> *Apr 27 00:31:00.227: ISDN Dc2 SC EVENTd: calltrkr_call_cleared:
>> isdn_info=0x62D469E0, call_id=0xE
>> *Apr 27 00:31:00.227: ISDN Dc2 SC EVENTd: calltrkr_call_cleared:
>> isdn_info=0x62DD6094, call_id=0xE
>> *Apr 27 00:31:00.227: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0,
>> call_id=0xE, ces=0x1
>> bchan=0xD, event=0x0, cause=0x10
>> ------------------------------------------------------------------------
>>
>> _______________________________________________
>> cisco-nas mailing list
>> cisco-nas [at] puck
>> https://puck.nether.net/mailman/listinfo/cisco-nas
>
>

_______________________________________________
cisco-nas mailing list
cisco-nas [at] puck
https://puck.nether.net/mailman/listinfo/cisco-nas

Aaron at cisco

Aug 25, 2008, 5:18 PM

Post #7 of 12 (3573 views)
Permalink

Re: Modems not responding on cisco AS5300. [In reply to]

Joseph,

If this problem affects groups of 6 ports, and if the first port number
in that affected group is evenly divisible by 6, then I would say that
you are suffering not from "DSP death" but from "hex death".

Background: MICA modems (the older HMMs anyway) were implemented with 6
modems module. The 6 modems shared a single i960 control processor
(CP), and each 2 modems shared one DSP (i.e. 3 DSPs per HMM.)

So it sounds like the CP, not the DSP, has crashed. Right now I
wouldn't blame the slot (never having heard of such a thing), but the CP
code, and figure it's just happenstance that the third HMM on each card
happened to fail.

In any case, the guidance below is still generally applicable - i.e. run
latest code (2.9.5.0); turn on modem recovery.

Aaron

------------------------------------------------------------------------

> More news on this problem. There are two modem cards in this box. Each with
> 48 active modems, so 1/0 1/47 and 2/0 2/47.
>
> In dialing through all the modems, I get modem tone on 1/0 to 1/11 then dead
> air on 1/12 to 1/17, then tone again on 1/18 to 1/47. Then modem tone on 2/0
> to 2/11, then dead air on 2/12 to 2/17, then modem tone again on 2/18 to
> 2/47.
>
> If it were just one card, easy, bad spe chipset. But it seems awfully damned
> coincidental to have the same set of chips bad on each card. Is there any
> shared circuitry for positions x/12 to x/17 in the slots on the motherboard?
> I don't see anything at all in the config that specifically references those
> modem ranges, but could there be any modem thing that is causing it?
>
>
>
>
> ----- Original Message -----
> From: "Aaron Leonard" <Aaron [at] cisco>
> To: "Joseph Mays" <mays [at] win>
> Cc: <cisco-nas [at] puck>
> Sent: Monday, August 25, 2008 3:48 PM
> Subject: Re: [cisco-nas] Modems not responding on cisco AS5300.
>
>
>
>> Hi Joseph,
>>
>> (Boy, it's been awhile since this list has gotten a legitimate question!)
>>
>> From the debugs, it looks like this call into modem 2/51 simply failed
>> to train. It is possible that the DSP that handles 2/51 (and 2/50) has
>> gone into some bad state; can't tell from the debugs alone.
>>
>> I would get the "show modem csr" output and see whether there is an
>> inordinately large % of failed calls into this DSP (i.e. 2/50 and 2/51),
>> when compared with other modems in this 5300 that handle the same client
>> base.
>>
>> If so, then I suppose this would be a DSP bug of some sort. Could try
>> upgrading to the last portware (2.9.5.0) if you're not already running
>> it. If that doesn't clear it up, then could configure Modem Recovery.
>>
>> Configuring MICA Modem Recovery
>> http://www.cisco.com/en/US/tech/tk801/tk36/technologies_tech_note09186a0080094cac.shtml
>>
>> Hth,
>>
>> Aaron
>>
>> ----
>>
>>
>>> We're working with a Cisco AS5300, and have been having a problem
>>> wherein it will answer a call, but the call never gets forwarded to a
>>> modem. Sometimes it works, usually not. There is some reason to
>>> believe that it works after a call has hit a modem once. It fails the
>>> first time and works after that, but I can't confirm that.
>>>
>>> Here's the "debug modem csm" output from a failed call. I've bolded
>>> what I assume is the important text.
>>>
>>> as5300_frv_1#
>>> *Apr 27 00:30:32.087: ISDN Dc2 SC Q921d: srl_send_l2_pak:
>>> source_id = IUA, dest_id = Q.931, prim = DL_DATA_IND
>>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 62
>>> *Apr 27 00:30:32.087: ISDN Dc2 SC Q921d: data =
>>> 0x62D3E3E0000000010241040000010000
>>> *Apr 27 00:30:32.091: 080207AB0504038090A21803A1838E1E
>>> *Apr 27 00:30:32.091: 0281836C0CA181353032383135373030
>>> *Apr 27 00:30:32.091: 30700BA134333433393431323334
>>> *Apr 27 00:30:32.091: ISDN Dc2 SC BACKHAUL: L3IF_rx_L2_pak: received
>>> data 0x080207AB0504038090A21803A1838E1E
>>> *Apr 27 00:30:32.091: 0281836C0CA181353032383135373030
>>> *Apr 27 00:30:32.091: 30700BA134333433393431323334
>>> *Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_Go: source = 0x20A, event
>>> = 0x241, call id = 0x0, int id = 0x0
>>> *Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>>> state 0 event 0x5 ces 1
>>> *Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>>> 0x87AB SETUP:U0_Setup(nlcb)
>>> *Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_state_change: callref
>>> 0x87AB old NULL_STATE, new CALL_PRESENT
>>> *Apr 27 00:30:32.091: ISDN Dc2 SC CC: CCPRI_Go: source id 0x300, call
>>> id 0xE, event 0x341 (pre-ccb recovery)
>>> *Apr 27 00:30:32.091: ISDN Dc2 SC CC: CCPRI_Go: call id 0x2 cref 0xE
>>> event 0x87AB Source->L3
>>> *Apr 27 00:30:32.095: ISDN Dc2 SC CC: CCPCC_CallIdle: event 0x90 b
>>> channel 0 nfas int_id 0 call_id 0xE
>>> *Apr 27 00:30:32.095: ISDN Dc2 SC CC: CCPRI_AcceptChanId: Negotiated
>>> int_id 0 bchan 0 cref 0x87AB call_id 0x000E lo_chan 14 final
>>> int_id/bchan 2/14 cause 0
>>> *Apr 27 00:30:32.095: ISDN Dc2 SC TGRM: get_tgrm_avail_state: idb
>>> 0x62D3E3E0 bchan 14 service_state 0 call_state 2 false busy 0x0 dsl 2
>>> *Apr 27 00:30:32.095: ISDN Dc2 SC TGRM: update_tgrm_call_status: idb
>>> 0x62D3E3E0 bchan 14 availability state 1 call state(prev,new) (0,2), dsl
>>> 2
>>> *Apr 27 00:30:32.095: ISDN Dc2 SC TGRM: update_tgrm_call_status:
>>> Calling TGRM with tgrm_call_isdn_update: idb 0x62D3E3E0 bchan 14 call
>>> state 1 call type 2 call dir 1
>>> *Apr 27 00:30:32.095: ISDN Dc2 SC EVENT: process_rxstate: ces/callid
>>> 1/0xE calltype 2 CALL_INCOMING
>>> *Apr 27 00:30:32.095: ISDN Dc2 SC PACKET: process_rxstate:
>>> 0x4C0201000E1A04040000100218042003
>>> *Apr 27 00:30:32.095: 0E02700C020134333433393431323334
>>> *Apr 27 00:30:32.095: 04038090A21803A1838E1E0281836C0C
>>> *Apr 27 00:30:32.095: A18135303238313537303030700BA134
>>> *Apr 27 00:30:32.095: 333433393431323334
>>> *Apr 27 00:30:32.095: ISDN Dc2 SC EVENTd: calltrkr_incoming_call:
>>> call_id=0xE
>>> *Apr 27 00:30:32.095: ISDN Dc2 SC EVENTd: calltrkr_setup_received:
>>> isdn_info=1658087904l, call_id=0xE ANSWER
>>> *Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: calltrkr_setup_received:
>>> isdn_info=1658675348l, call_id=0xE ANSWER
>>> *Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: call_incoming: b channel 13,
>>> call type is VOICE ULAW
>>> *Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: call_incoming: Received a
>>> VOICE call from 5028157000 on b channel 13 at 64 Kb/s
>>> *Apr 27 00:30:32.099: VDEV_ALLOCATE: 2/51 is allocated
>>> *Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: isdn_fromdialer: RM returned
>>> call_type 1 resource type 0 response 2
>>> *Apr 27 00:30:32.099: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call
>>> id 0x0, event 0x4A (pre-ccb recovery)
>>> *Apr 27 00:30:32.099: ISDN Dc2 SC CC: CCPRI_Go: call_id 0xE cref
>>> 0x87AB event 0x4A Source->HOST
>>> *Apr 27 00:30:32.099: ISDN Dc2 SC CC: CCPCC_CallOffered: event = 0x4A
>>> b channel 14 nfas int_id 2 call_id 0xE
>>> *Apr 27 00:30:32.099: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event
>>> = 0x340, call id = 0xE, int id = 0x2
>>> *Apr 27 00:30:32.099: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>>> state 6 event 0x88 ces 1
>>> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>>> 0x87AB CC_CALL_PROC_REQ:U6_CallProcReq(nlcb)
>>> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 10
>>> octets 0x080287AB021803A9838E
>>> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: srl_send_l3_pak:
>>> source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
>>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 26
>>> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: data =
>>> 0x62D3E3E0000100000240046A00010800
>>> *Apr 27 00:30:32.103: 080287AB021803A9838E
>>> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: L3_state_change: callref
>>> 0x87AB old CALL_PRESENT, new IN_CALL_PROC
>>> *Apr 27 00:30:32.103: ISDN Dc2 SC EVENT: UserIdle: callid 0xE received
>>> ACCEPT_CALL (0x13)
>>> *Apr 27 00:30:32.103: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0,
>>> call_id=0xE, ces=0x0
>>> bchan=0xD, event=0x1, cause=0x0
>>> *Apr 27 00:30:32.103: dev in call to isdn : set dnis_collected &
>>> fap_notify
>>> *Apr 27 00:30:32.103: EVENT_FROM_ISDN:(000E): DEV_INCALL at slot 2,
>>> port 51
>>> *Apr 27 00:30:32.103: EVENT_FROM_ISDN: decode:calling oct3 0xA1,
>>> called oct3 0xA1, oct3a 0x0,mask 0x3D
>>> *Apr 27 00:30:32.103: EVENT_FROM_ISDN: csm_call_info:calling oct3
>>> 0xA1, called oct3 0xA1, oct3a 0x0,mask 0x3D
>>> *Apr 27 00:30:32.103: CSM_PROC_IDLE: CSM_EVENT_ISDN_CALL at slot 2,
>>> port 51
>>> *Apr 27 00:30:32.103: Mica Modem(2/51): Configure(0x1 = 0x0)
>>> *Apr 27 00:30:32.103: Mica Modem(2/51): Configure(0x23 = 0x0)
>>> *Apr 27 00:30:32.103: Mica Modem(2/51): Call Setup
>>> *Apr 27 00:30:32.103: csm_connect_pri_vdev: TS allocated at bp_stream
>>> 0, bp_Ch 13, vdev_common 0x625BA2C4 2/51
>>> *Apr 27 00:30:32.107: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call
>>> id 0x0, event 0x4E (pre-ccb recovery)
>>> *Apr 27 00:30:32.107: ISDN Dc2 SC CC: CCPRI_Go: call_id 0xE cref
>>> 0x87AB event 0x4E Source->HOST
>>> *Apr 27 00:30:32.107: ISDN Dc2 SC CC: CCPCC_CallRoutingIn: executing
>>> with event = 4E in state = CALL ROUTING_IN
>>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event
>>> = 0x340, call id = 0xE, int id = 0x2
>>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>>> state 9 event 0x86 ces 1
>>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>>> 0x87AB CC_ALERTING_REQ:U9_AlertingReq(nlcb)
>>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 5
>>> octets 0x080287AB01
>>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: srl_send_l3_pak:
>>> source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
>>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
>>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: data =
>>> 0x62D3E3E0000100000240046A00010800
>>> *Apr 27 00:30:32.107: 080287AB01
>>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_state_change: callref
>>> 0x87AB old IN_CALL_PROC, new CALL_RECEIVED
>>> *Apr 27 00:30:32.175: Mica Modem(2/51): State Transition to Call Setup
>>> *Apr 27 00:30:32.175: Mica Modem(2/51): Went offhook
>>> *Apr 27 00:30:32.175: CSM_PROC_IC2_RING: CSM_EVENT_MODEM_OFFHOOK at
>>> slot 2, port 51
>>> *Apr 27 00:30:32.175: ISDN Dc2 SC EVENT: process_modem_command:
>>> received event VOICE_ANS on callid 0xE and bchan 13 ces 0 cause 16
>>> switch type 25
>>> *Apr 27 00:30:32.175: ISDN Dc2 SC EVENTd: isdn_send_connect: msg 74,
>>> call id 0xE, ces 0 bchan 13, call type VOICE
>>> *Apr 27 00:30:32.175: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call
>>> id 0x0, event 0x4A (pre-ccb recovery)
>>> *Apr 27 00:30:32.175: ISDN Dc2 SC CC: CCPRI_Go: call_id 0xE cref
>>> 0x87AB event 0x4A Source->HOST
>>> *Apr 27 00:30:32.175: ISDN Dc2 SC CC: CCPCC_CallRinging: event 0x4A b
>>> channel 14 nfas int_id 2 call_id 0xE
>>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event
>>> = 0x340, call id = 0xE, int id = 0x2
>>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>>> state 7 event 0x81 ces 1
>>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>>> 0x87AB CC_SETUP_RESP:U7_SetupResp(nlcb)
>>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 5
>>> octets 0x080287AB07
>>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: srl_send_l3_pak:
>>> source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
>>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
>>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: data =
>>> 0x62D3E3E0000100000240046A00010800
>>> *Apr 27 00:30:32.179: 080287AB07
>>> *Apr 27 00:30:32.179: ISDN Dc2 SC LIFd: LIF_StartTimer: timer
>>> (0x630C8090), ticks (4000), event (0x131C)
>>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_state_change: callref
>>> 0x87AB old CALL_RECEIVED, new CONNECT_REQUEST
>>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q921d: srl_send_l2_pak:
>>> source_id = IUA, dest_id = Q.931, prim = DL_DATA_IND
>>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
>>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q921d: data =
>>> 0x62D3E3E0000000010241040000010000
>>> *Apr 27 00:30:32.323: 080207AB0F
>>> *Apr 27 00:30:32.323: ISDN Dc2 SC BACKHAUL: L3IF_rx_L2_pak: received
>>> data 0x080207AB0F
>>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_Go: source = 0x20A, event
>>> = 0x241, call id = 0x0, int id = 0x0
>>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>>> state 8 event 0xF ces 1
>>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>>> 0x87AB CONNECT_ACK:U8_ConnectAck(nlcb)
>>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_state_change: callref
>>> 0x87AB old CONNECT_REQUEST, new CALL_ACTIVE
>>> *Apr 27 00:30:32.327: ISDN Dc2 SC CC: CCPRI_Go: source id 0x300, call
>>> id 0xE, event 0x341 (pre-ccb recovery)
>>> *Apr 27 00:30:32.327: ISDN Dc2 SC CC: CCPRI_Go: dispatching event 0x92
>>> call id 0xE cref 0x87AB Source->L3
>>> *Apr 27 00:30:32.327: ISDN Dc2 SC CC: CCPCC_CallRoutingIn: executing
>>> with event = 92 in state = CALL ROUTING_IN
>>> *Apr 27 00:30:32.327: ISDN Dc2 SC EVENT: process_rxstate: ces/callid
>>> 1/0xE calltype 2 CALL_PROGRESS
>>> *Apr 27 00:30:32.327: ISDN Dc2 SC PACKET: process_rxstate:
>>> 0x4E0201000E031E0187
>>> *Apr 27 00:30:32.327: ISDN Dc2 SC EVENTd: calltrkr_call_connect:
>>> isdn_info=0x62DD6094, call_id=0xE
>>> *Apr 27 00:30:32.327: ISDN Dc2 SC EVENTd: calltrkr_call_connect:
>>> hndl=14l, cntrl_slot=0, cntrl_port=2, cntrl_channel=2.
>>> *Apr 27 00:30:32.327: ISDN Dc2 SC EVENTd: call_progress:
>>> CALL_CONNECTED b channel 13 call id 0xE
>>> *Apr 27 00:30:32.327: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0,
>>> call_id=0xE, ces=0x0
>>> bchan=0xD, event=0x4, cause=0x0
>>> *Apr 27 00:30:32.327: EVENT_FROM_ISDN:(000E): DEV_CONNECTED at slot 2,
>>> port 51
>>> *Apr 27 00:30:32.327: CSM_PROC_IC6_WAIT_FOR_CONNECT:
>>> CSM_EVENT_ISDN_CONNECTED at slot 2, port 51
>>> *Apr 27 00:30:32.327: Mica Modem(2/51): Link Initiate
>>> *Apr 27 00:30:32.327: %ISDN-6-CONNECT: Interface Serial2:13 is now
>>> connected to 5028157000 N/A
>>> *Apr 27 00:30:33.419: Mica Modem(2/51): State Transition to Connect
>>> *Apr 27 00:30:33.435: Mica Modem(2/51): State Transition to V8bis
>>> Exchange
>>> *Apr 27 00:30:37.879: Mica Modem(2/51): State Transition to Link
>>> **Apr 27 00:30:42.147: Mica Modem(2/51): State Transition to Trainup
>>> *Apr 27 00:30:50.015: Mica Modem(2/51): State Transition to Terminating
>>> *Apr 27 00:30:50.451: %CALLRECORD-3-MICA_TERSE_CALL_FAILED_REC: DS0
>>> slot/contr/chan=0/2/13, slot/port=2/51, call_id=E, calling=5028157000,
>>> called=4343941234, time=17, finl-state=Train Up, disc(modem)=6102
>>> Condition occurred during call setup/DSP condition/failure in modem
>>> training up
>>> **Apr 27 00:30:50.615: Mica Modem(2/51): State Transition to Idle
>>> *Apr 27 00:30:50.615: Mica Modem(2/51): Went onhook
>>> *Apr 27 00:30:50.615: CSM_PROC_IC7_OC6_CONNECTED:
>>> CSM_EVENT_MODEM_ONHOOK at slot 2, port 51
>>> *Apr 27 00:30:50.615: CSM_PROC_IC7_OC6_CONNECTED: cause code to isdn 0x0
>>> *Apr 27 00:30:50.615: CSM(2/51): Enter csm_enter_idle_state
>>> *Apr 27 00:30:50.615: VDEV_DEALLOCATE: slot 2, port 51 is deallocated
>>> *Apr 27 00:30:50.619: ISDN Dc2 SC EVENT: process_modem_command:
>>> received event VOICE_HANGUP on callid 0xE and bchan 13 ces 0 cause 16
>>> switch type 25
>>> *Apr 27 00:30:50.619: ISDN Dc2 SC EVENTd: process_modem_command: call
>>> id 0xE ces may have changed is now 1
>>> *Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: process_disconnect: call id
>>> 0xE, call type is VOICE, b_idb 0x62DCDA0C, ces 1, cause Normal call
>>> clearing(0x10)
>>> *Apr 27 00:30:50.623: %ISDN-6-DISCONNECT: Interface Serial2:13
>>> disconnected from 5028157000 , call lasted 18 seconds
>>> *Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>>> isdn_info=0x62DD6094, call_id=0xE
>>> *Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>>> hndl=14l, cause=16, Normal call clearing
>>> *Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: process_disconnect: Raw
>>> Release Message 0x4BFF01000E040802FF900803809081
>>> *Apr 27 00:31:00.211: ISDN Dc2 SC Q921d: srl_send_l2_pak:
>>> source_id = IUA, dest_id = Q.931, prim = DL_DATA_IND
>>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 25
>>> *Apr 27 00:31:00.215: ISDN Dc2 SC Q921d: data =
>>> 0x62D3E3E0000000010241040000010000
>>> *Apr 27 00:31:00.215: 080207AB4D08028010
>>> *Apr 27 00:31:00.215: ISDN Dc2 SC BACKHAUL: L3IF_rx_L2_pak: received
>>> data 0x080207AB4D08028010
>>> *Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_Go: source = 0x20A, event
>>> = 0x241, call id = 0x0, int id = 0x0
>>> *Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>>> state 10 event 0x4D ces 1
>>> *Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>>> 0x87AB RELEASE:Ux_Release(nlcb)
>>> *Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_state_change: callref
>>> 0x87AB old CALL_ACTIVE, new RELEASE_REQUEST
>>> *Apr 27 00:31:00.215: ISDN Dc2 SC CC: CCPRI_Go: source id 0x300, call
>>> id 0xE, event 0x341 (pre-ccb recovery)
>>> *Apr 27 00:31:00.215: ISDN Dc2 SC CC: CCPRI_Go: dispatching event 0x97
>>> call id 0xE cref 0x87AB Source->L3
>>> *Apr 27 00:31:00.215: ISDN Dc2 SC CC: CCPCC_CallConnected: event 0x97
>>> b channel 14 nfas int_id 2 call_id 0xE
>>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: CC_CHAN_GetUserpri: using
>>> call_id = 0xE
>>> *Apr 27 00:31:00.219: ISDN Dc2 SC CCd: CC_CHAN_ReleaseChanpri: channel 14
>>> *Apr 27 00:31:00.219: ISDN Dc2 SC TGRM: get_tgrm_avail_state: idb
>>> 0x62D3E3E0 bchan 14 service_state 0 call_state 0 false busy 0x0 dsl 2
>>> *Apr 27 00:31:00.219: ISDN Dc2 SC TGRM: update_tgrm_call_status: idb
>>> 0x62D3E3E0 bchan 14 availability state 1 call state(prev,new) (2,0), dsl
>>> 2
>>> *Apr 27 00:31:00.219: ISDN Dc2 SC TGRM: update_tgrm_call_status:
>>> Calling TGRM with tgrm_call_isdn_update: idb 0x62D3E3E0 bchan 14 call
>>> state 0 call type 0 call dir 1
>>> *Apr 27 00:31:00.219: ISDN EVENTd: cc_clear_free_list freed 0x6339ABFC
>>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event
>>> = 0x340, call id = 0xE, int id = 0x2
>>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>>> state 19 event 0xAB ces 1
>>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>>> 0x87AB CC_REL_COMP_REQ:U19_RelCompReq(nlcb)
>>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 5
>>> octets 0x080287AB5A
>>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: srl_send_l3_pak:
>>> source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
>>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
>>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: data =
>>> 0x62D3E3E0000100000240046A00010806
>>> *Apr 27 00:31:00.219: 080287AB5A
>>> *Apr 27 00:31:00.223: ISDN Dc2 SC Q931d: L3_state_change: callref
>>> 0x87AB old RELEASE_REQUEST, new NULL_STATE
>>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENT: process_rxstate: ces/callid
>>> 1/0xE calltype 2 CALL_DISC
>>> *Apr 27 00:31:00.223: ISDN Dc2 SC PACKET: process_rxstate:
>>> 0x4B0201000E0308011008028010
>>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: process_rxstate: cause=0x10
>>> (16), cause_present=1
>>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>>> isdn_info=0x62D469E0, call_id=0xE
>>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>>> isdn_info=0x62DD6094, call_id=0xE
>>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>>> isdn_info=0x62D469E0, call_id=0xE
>>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>>> isdn_info=0x62DD6094, call_id=0xE
>>> *Apr 27 00:31:00.223: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0,
>>> call_id=0xE, ces=0x1
>>> bchan=0xD, event=0x0, cause=0x10
>>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: process_disc_ack: call id
>>> 0xE, ces 1, call type VOICE cause 0x10
>>> *Apr 27 00:31:00.223: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call
>>> id 0x0, event 0x57 (pre-ccb recovery)
>>> *Apr 27 00:31:00.223: ISDN Dc2 SC SERROR: CCPRI_Go: call id 0xE event
>>> 0x57 No ccb Source->HOST
>>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENT: process_rxstate: ces/callid
>>> 1/0xE calltype 2 CALL_CLEARED
>>> *Apr 27 00:31:00.227: ISDN Dc2 SC PACKET: process_rxstate:
>>> 0x570201000E0008028010
>>> *Apr 27 00:31:00.227: ISDN Dc2 SC EVENTd: process_rxstate: cause=0x10
>>> (16), cause_present=1
>>> *Apr 27 00:31:00.227: ISDN Dc2 SC EVENTd: calltrkr_call_cleared:
>>> isdn_info=0x62D469E0, call_id=0xE
>>> *Apr 27 00:31:00.227: ISDN Dc2 SC EVENTd: calltrkr_call_cleared:
>>> isdn_info=0x62DD6094, call_id=0xE
>>> *Apr 27 00:31:00.227: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0,
>>> call_id=0xE, ces=0x1
>>> bchan=0xD, event=0x0, cause=0x10
>>> ------------------------------------------------------------------------
>>>
>>> _______________________________________________
>>> cisco-nas mailing list
>>> cisco-nas [at] puck
>>> https://puck.nether.net/mailman/listinfo/cisco-nas
>>>
>>

_______________________________________________
cisco-nas mailing list
cisco-nas [at] puck
https://puck.nether.net/mailman/listinfo/cisco-nas

mays at win

Aug 25, 2008, 5:27 PM

Post #8 of 12 (3550 views)
Permalink

Re: Modems not responding on cisco AS5300. [In reply to]

Well, what's puzzling me is that it's the same six modems on two cards in
the box. So I'm wondering if the slots the cards are plugged into share any
circuitry.

----- Original Message -----
From: "Aaron Leonard" <Aaron [at] cisco>
To: "Joseph Mays" <mays [at] win>
Cc: <cisco-nas [at] puck>; "Mike Andrews" <mandrews [at] bit0>
Sent: Monday, August 25, 2008 8:18 PM
Subject: Re: [cisco-nas] Modems not responding on cisco AS5300.

> Joseph,
>
> If this problem affects groups of 6 ports, and if the first port number
> in that affected group is evenly divisible by 6, then I would say that
> you are suffering not from "DSP death" but from "hex death".
>
> Background: MICA modems (the older HMMs anyway) were implemented with 6
> modems module. The 6 modems shared a single i960 control processor
> (CP), and each 2 modems shared one DSP (i.e. 3 DSPs per HMM.)
>
> So it sounds like the CP, not the DSP, has crashed. Right now I
> wouldn't blame the slot (never having heard of such a thing), but the CP
> code, and figure it's just happenstance that the third HMM on each card
> happened to fail.
>
> In any case, the guidance below is still generally applicable - i.e. run
> latest code (2.9.5.0); turn on modem recovery.
>
> Aaron
>
> ------------------------------------------------------------------------
>
>> More news on this problem. There are two modem cards in this box. Each
>> with
>> 48 active modems, so 1/0 1/47 and 2/0 2/47.
>>
>> In dialing through all the modems, I get modem tone on 1/0 to 1/11 then
>> dead
>> air on 1/12 to 1/17, then tone again on 1/18 to 1/47. Then modem tone on
>> 2/0
>> to 2/11, then dead air on 2/12 to 2/17, then modem tone again on 2/18 to
>> 2/47.
>>
>> If it were just one card, easy, bad spe chipset. But it seems awfully
>> damned
>> coincidental to have the same set of chips bad on each card. Is there any
>> shared circuitry for positions x/12 to x/17 in the slots on the
>> motherboard?
>> I don't see anything at all in the config that specifically references
>> those
>> modem ranges, but could there be any modem thing that is causing it?
>>
>>
>>
>>
>> ----- Original Message -----
>> From: "Aaron Leonard" <Aaron [at] cisco>
>> To: "Joseph Mays" <mays [at] win>
>> Cc: <cisco-nas [at] puck>
>> Sent: Monday, August 25, 2008 3:48 PM
>> Subject: Re: [cisco-nas] Modems not responding on cisco AS5300.
>>
>>
>>
>>> Hi Joseph,
>>>
>>> (Boy, it's been awhile since this list has gotten a legitimate
>>> question!)
>>>
>>> From the debugs, it looks like this call into modem 2/51 simply failed
>>> to train. It is possible that the DSP that handles 2/51 (and 2/50) has
>>> gone into some bad state; can't tell from the debugs alone.
>>>
>>> I would get the "show modem csr" output and see whether there is an
>>> inordinately large % of failed calls into this DSP (i.e. 2/50 and 2/51),
>>> when compared with other modems in this 5300 that handle the same client
>>> base.
>>>
>>> If so, then I suppose this would be a DSP bug of some sort. Could try
>>> upgrading to the last portware (2.9.5.0) if you're not already running
>>> it. If that doesn't clear it up, then could configure Modem Recovery.
>>>
>>> Configuring MICA Modem Recovery
>>> http://www.cisco.com/en/US/tech/tk801/tk36/technologies_tech_note09186a0080094cac.shtml
>>>
>>> Hth,
>>>
>>> Aaron
>>>
>>> ----
>>>
>>>
>>>> We're working with a Cisco AS5300, and have been having a problem
>>>> wherein it will answer a call, but the call never gets forwarded to a
>>>> modem. Sometimes it works, usually not. There is some reason to
>>>> believe that it works after a call has hit a modem once. It fails the
>>>> first time and works after that, but I can't confirm that.
>>>>
>>>> Here's the "debug modem csm" output from a failed call. I've bolded
>>>> what I assume is the important text.
>>>>
>>>> as5300_frv_1#
>>>> *Apr 27 00:30:32.087: ISDN Dc2 SC Q921d: srl_send_l2_pak:
>>>> source_id = IUA, dest_id = Q.931, prim = DL_DATA_IND
>>>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 62
>>>> *Apr 27 00:30:32.087: ISDN Dc2 SC Q921d: data =
>>>> 0x62D3E3E0000000010241040000010000
>>>> *Apr 27 00:30:32.091: 080207AB0504038090A21803A1838E1E
>>>> *Apr 27 00:30:32.091: 0281836C0CA181353032383135373030
>>>> *Apr 27 00:30:32.091: 30700BA134333433393431323334
>>>> *Apr 27 00:30:32.091: ISDN Dc2 SC BACKHAUL: L3IF_rx_L2_pak: received
>>>> data 0x080207AB0504038090A21803A1838E1E
>>>> *Apr 27 00:30:32.091: 0281836C0CA181353032383135373030
>>>> *Apr 27 00:30:32.091: 30700BA134333433393431323334
>>>> *Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_Go: source = 0x20A, event
>>>> = 0x241, call id = 0x0, int id = 0x0
>>>> *Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>>>> state 0 event 0x5 ces 1
>>>> *Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>>>> 0x87AB SETUP:U0_Setup(nlcb)
>>>> *Apr 27 00:30:32.091: ISDN Dc2 SC Q931d: L3_state_change: callref
>>>> 0x87AB old NULL_STATE, new CALL_PRESENT
>>>> *Apr 27 00:30:32.091: ISDN Dc2 SC CC: CCPRI_Go: source id 0x300, call
>>>> id 0xE, event 0x341 (pre-ccb recovery)
>>>> *Apr 27 00:30:32.091: ISDN Dc2 SC CC: CCPRI_Go: call id 0x2 cref 0xE
>>>> event 0x87AB Source->L3
>>>> *Apr 27 00:30:32.095: ISDN Dc2 SC CC: CCPCC_CallIdle: event 0x90 b
>>>> channel 0 nfas int_id 0 call_id 0xE
>>>> *Apr 27 00:30:32.095: ISDN Dc2 SC CC: CCPRI_AcceptChanId: Negotiated
>>>> int_id 0 bchan 0 cref 0x87AB call_id 0x000E lo_chan 14 final
>>>> int_id/bchan 2/14 cause 0
>>>> *Apr 27 00:30:32.095: ISDN Dc2 SC TGRM: get_tgrm_avail_state: idb
>>>> 0x62D3E3E0 bchan 14 service_state 0 call_state 2 false busy 0x0 dsl 2
>>>> *Apr 27 00:30:32.095: ISDN Dc2 SC TGRM: update_tgrm_call_status: idb
>>>> 0x62D3E3E0 bchan 14 availability state 1 call state(prev,new) (0,2),
>>>> dsl
>>>> 2
>>>> *Apr 27 00:30:32.095: ISDN Dc2 SC TGRM: update_tgrm_call_status:
>>>> Calling TGRM with tgrm_call_isdn_update: idb 0x62D3E3E0 bchan 14 call
>>>> state 1 call type 2 call dir 1
>>>> *Apr 27 00:30:32.095: ISDN Dc2 SC EVENT: process_rxstate: ces/callid
>>>> 1/0xE calltype 2 CALL_INCOMING
>>>> *Apr 27 00:30:32.095: ISDN Dc2 SC PACKET: process_rxstate:
>>>> 0x4C0201000E1A04040000100218042003
>>>> *Apr 27 00:30:32.095: 0E02700C020134333433393431323334
>>>> *Apr 27 00:30:32.095: 04038090A21803A1838E1E0281836C0C
>>>> *Apr 27 00:30:32.095: A18135303238313537303030700BA134
>>>> *Apr 27 00:30:32.095: 333433393431323334
>>>> *Apr 27 00:30:32.095: ISDN Dc2 SC EVENTd: calltrkr_incoming_call:
>>>> call_id=0xE
>>>> *Apr 27 00:30:32.095: ISDN Dc2 SC EVENTd: calltrkr_setup_received:
>>>> isdn_info=1658087904l, call_id=0xE ANSWER
>>>> *Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: calltrkr_setup_received:
>>>> isdn_info=1658675348l, call_id=0xE ANSWER
>>>> *Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: call_incoming: b channel 13,
>>>> call type is VOICE ULAW
>>>> *Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: call_incoming: Received a
>>>> VOICE call from 5028157000 on b channel 13 at 64 Kb/s
>>>> *Apr 27 00:30:32.099: VDEV_ALLOCATE: 2/51 is allocated
>>>> *Apr 27 00:30:32.099: ISDN Dc2 SC EVENTd: isdn_fromdialer: RM returned
>>>> call_type 1 resource type 0 response 2
>>>> *Apr 27 00:30:32.099: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call
>>>> id 0x0, event 0x4A (pre-ccb recovery)
>>>> *Apr 27 00:30:32.099: ISDN Dc2 SC CC: CCPRI_Go: call_id 0xE cref
>>>> 0x87AB event 0x4A Source->HOST
>>>> *Apr 27 00:30:32.099: ISDN Dc2 SC CC: CCPCC_CallOffered: event = 0x4A
>>>> b channel 14 nfas int_id 2 call_id 0xE
>>>> *Apr 27 00:30:32.099: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event
>>>> = 0x340, call id = 0xE, int id = 0x2
>>>> *Apr 27 00:30:32.099: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>>>> state 6 event 0x88 ces 1
>>>> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>>>> 0x87AB CC_CALL_PROC_REQ:U6_CallProcReq(nlcb)
>>>> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 10
>>>> octets 0x080287AB021803A9838E
>>>> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: srl_send_l3_pak:
>>>> source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
>>>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 26
>>>> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: data =
>>>> 0x62D3E3E0000100000240046A00010800
>>>> *Apr 27 00:30:32.103: 080287AB021803A9838E
>>>> *Apr 27 00:30:32.103: ISDN Dc2 SC Q931d: L3_state_change: callref
>>>> 0x87AB old CALL_PRESENT, new IN_CALL_PROC
>>>> *Apr 27 00:30:32.103: ISDN Dc2 SC EVENT: UserIdle: callid 0xE received
>>>> ACCEPT_CALL (0x13)
>>>> *Apr 27 00:30:32.103: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0,
>>>> call_id=0xE, ces=0x0
>>>> bchan=0xD, event=0x1, cause=0x0
>>>> *Apr 27 00:30:32.103: dev in call to isdn : set dnis_collected &
>>>> fap_notify
>>>> *Apr 27 00:30:32.103: EVENT_FROM_ISDN:(000E): DEV_INCALL at slot 2,
>>>> port 51
>>>> *Apr 27 00:30:32.103: EVENT_FROM_ISDN: decode:calling oct3 0xA1,
>>>> called oct3 0xA1, oct3a 0x0,mask 0x3D
>>>> *Apr 27 00:30:32.103: EVENT_FROM_ISDN: csm_call_info:calling oct3
>>>> 0xA1, called oct3 0xA1, oct3a 0x0,mask 0x3D
>>>> *Apr 27 00:30:32.103: CSM_PROC_IDLE: CSM_EVENT_ISDN_CALL at slot 2,
>>>> port 51
>>>> *Apr 27 00:30:32.103: Mica Modem(2/51): Configure(0x1 = 0x0)
>>>> *Apr 27 00:30:32.103: Mica Modem(2/51): Configure(0x23 = 0x0)
>>>> *Apr 27 00:30:32.103: Mica Modem(2/51): Call Setup
>>>> *Apr 27 00:30:32.103: csm_connect_pri_vdev: TS allocated at bp_stream
>>>> 0, bp_Ch 13, vdev_common 0x625BA2C4 2/51
>>>> *Apr 27 00:30:32.107: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call
>>>> id 0x0, event 0x4E (pre-ccb recovery)
>>>> *Apr 27 00:30:32.107: ISDN Dc2 SC CC: CCPRI_Go: call_id 0xE cref
>>>> 0x87AB event 0x4E Source->HOST
>>>> *Apr 27 00:30:32.107: ISDN Dc2 SC CC: CCPCC_CallRoutingIn: executing
>>>> with event = 4E in state = CALL ROUTING_IN
>>>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event
>>>> = 0x340, call id = 0xE, int id = 0x2
>>>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>>>> state 9 event 0x86 ces 1
>>>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>>>> 0x87AB CC_ALERTING_REQ:U9_AlertingReq(nlcb)
>>>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 5
>>>> octets 0x080287AB01
>>>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: srl_send_l3_pak:
>>>> source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
>>>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
>>>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: data =
>>>> 0x62D3E3E0000100000240046A00010800
>>>> *Apr 27 00:30:32.107: 080287AB01
>>>> *Apr 27 00:30:32.107: ISDN Dc2 SC Q931d: L3_state_change: callref
>>>> 0x87AB old IN_CALL_PROC, new CALL_RECEIVED
>>>> *Apr 27 00:30:32.175: Mica Modem(2/51): State Transition to Call Setup
>>>> *Apr 27 00:30:32.175: Mica Modem(2/51): Went offhook
>>>> *Apr 27 00:30:32.175: CSM_PROC_IC2_RING: CSM_EVENT_MODEM_OFFHOOK at
>>>> slot 2, port 51
>>>> *Apr 27 00:30:32.175: ISDN Dc2 SC EVENT: process_modem_command:
>>>> received event VOICE_ANS on callid 0xE and bchan 13 ces 0 cause 16
>>>> switch type 25
>>>> *Apr 27 00:30:32.175: ISDN Dc2 SC EVENTd: isdn_send_connect: msg 74,
>>>> call id 0xE, ces 0 bchan 13, call type VOICE
>>>> *Apr 27 00:30:32.175: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call
>>>> id 0x0, event 0x4A (pre-ccb recovery)
>>>> *Apr 27 00:30:32.175: ISDN Dc2 SC CC: CCPRI_Go: call_id 0xE cref
>>>> 0x87AB event 0x4A Source->HOST
>>>> *Apr 27 00:30:32.175: ISDN Dc2 SC CC: CCPCC_CallRinging: event 0x4A b
>>>> channel 14 nfas int_id 2 call_id 0xE
>>>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event
>>>> = 0x340, call id = 0xE, int id = 0x2
>>>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>>>> state 7 event 0x81 ces 1
>>>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>>>> 0x87AB CC_SETUP_RESP:U7_SetupResp(nlcb)
>>>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 5
>>>> octets 0x080287AB07
>>>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: srl_send_l3_pak:
>>>> source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
>>>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
>>>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: data =
>>>> 0x62D3E3E0000100000240046A00010800
>>>> *Apr 27 00:30:32.179: 080287AB07
>>>> *Apr 27 00:30:32.179: ISDN Dc2 SC LIFd: LIF_StartTimer: timer
>>>> (0x630C8090), ticks (4000), event (0x131C)
>>>> *Apr 27 00:30:32.179: ISDN Dc2 SC Q931d: L3_state_change: callref
>>>> 0x87AB old CALL_RECEIVED, new CONNECT_REQUEST
>>>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q921d: srl_send_l2_pak:
>>>> source_id = IUA, dest_id = Q.931, prim = DL_DATA_IND
>>>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
>>>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q921d: data =
>>>> 0x62D3E3E0000000010241040000010000
>>>> *Apr 27 00:30:32.323: 080207AB0F
>>>> *Apr 27 00:30:32.323: ISDN Dc2 SC BACKHAUL: L3IF_rx_L2_pak: received
>>>> data 0x080207AB0F
>>>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_Go: source = 0x20A, event
>>>> = 0x241, call id = 0x0, int id = 0x0
>>>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>>>> state 8 event 0xF ces 1
>>>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>>>> 0x87AB CONNECT_ACK:U8_ConnectAck(nlcb)
>>>> *Apr 27 00:30:32.323: ISDN Dc2 SC Q931d: L3_state_change: callref
>>>> 0x87AB old CONNECT_REQUEST, new CALL_ACTIVE
>>>> *Apr 27 00:30:32.327: ISDN Dc2 SC CC: CCPRI_Go: source id 0x300, call
>>>> id 0xE, event 0x341 (pre-ccb recovery)
>>>> *Apr 27 00:30:32.327: ISDN Dc2 SC CC: CCPRI_Go: dispatching event 0x92
>>>> call id 0xE cref 0x87AB Source->L3
>>>> *Apr 27 00:30:32.327: ISDN Dc2 SC CC: CCPCC_CallRoutingIn: executing
>>>> with event = 92 in state = CALL ROUTING_IN
>>>> *Apr 27 00:30:32.327: ISDN Dc2 SC EVENT: process_rxstate: ces/callid
>>>> 1/0xE calltype 2 CALL_PROGRESS
>>>> *Apr 27 00:30:32.327: ISDN Dc2 SC PACKET: process_rxstate:
>>>> 0x4E0201000E031E0187
>>>> *Apr 27 00:30:32.327: ISDN Dc2 SC EVENTd: calltrkr_call_connect:
>>>> isdn_info=0x62DD6094, call_id=0xE
>>>> *Apr 27 00:30:32.327: ISDN Dc2 SC EVENTd: calltrkr_call_connect:
>>>> hndl=14l, cntrl_slot=0, cntrl_port=2, cntrl_channel=2.
>>>> *Apr 27 00:30:32.327: ISDN Dc2 SC EVENTd: call_progress:
>>>> CALL_CONNECTED b channel 13 call id 0xE
>>>> *Apr 27 00:30:32.327: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0,
>>>> call_id=0xE, ces=0x0
>>>> bchan=0xD, event=0x4, cause=0x0
>>>> *Apr 27 00:30:32.327: EVENT_FROM_ISDN:(000E): DEV_CONNECTED at slot 2,
>>>> port 51
>>>> *Apr 27 00:30:32.327: CSM_PROC_IC6_WAIT_FOR_CONNECT:
>>>> CSM_EVENT_ISDN_CONNECTED at slot 2, port 51
>>>> *Apr 27 00:30:32.327: Mica Modem(2/51): Link Initiate
>>>> *Apr 27 00:30:32.327: %ISDN-6-CONNECT: Interface Serial2:13 is now
>>>> connected to 5028157000 N/A
>>>> *Apr 27 00:30:33.419: Mica Modem(2/51): State Transition to Connect
>>>> *Apr 27 00:30:33.435: Mica Modem(2/51): State Transition to V8bis
>>>> Exchange
>>>> *Apr 27 00:30:37.879: Mica Modem(2/51): State Transition to Link
>>>> **Apr 27 00:30:42.147: Mica Modem(2/51): State Transition to Trainup
>>>> *Apr 27 00:30:50.015: Mica Modem(2/51): State Transition to Terminating
>>>> *Apr 27 00:30:50.451: %CALLRECORD-3-MICA_TERSE_CALL_FAILED_REC: DS0
>>>> slot/contr/chan=0/2/13, slot/port=2/51, call_id=E, calling=5028157000,
>>>> called=4343941234, time=17, finl-state=Train Up, disc(modem)=6102
>>>> Condition occurred during call setup/DSP condition/failure in modem
>>>> training up
>>>> **Apr 27 00:30:50.615: Mica Modem(2/51): State Transition to Idle
>>>> *Apr 27 00:30:50.615: Mica Modem(2/51): Went onhook
>>>> *Apr 27 00:30:50.615: CSM_PROC_IC7_OC6_CONNECTED:
>>>> CSM_EVENT_MODEM_ONHOOK at slot 2, port 51
>>>> *Apr 27 00:30:50.615: CSM_PROC_IC7_OC6_CONNECTED: cause code to isdn
>>>> 0x0
>>>> *Apr 27 00:30:50.615: CSM(2/51): Enter csm_enter_idle_state
>>>> *Apr 27 00:30:50.615: VDEV_DEALLOCATE: slot 2, port 51 is deallocated
>>>> *Apr 27 00:30:50.619: ISDN Dc2 SC EVENT: process_modem_command:
>>>> received event VOICE_HANGUP on callid 0xE and bchan 13 ces 0 cause 16
>>>> switch type 25
>>>> *Apr 27 00:30:50.619: ISDN Dc2 SC EVENTd: process_modem_command: call
>>>> id 0xE ces may have changed is now 1
>>>> *Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: process_disconnect: call id
>>>> 0xE, call type is VOICE, b_idb 0x62DCDA0C, ces 1, cause Normal call
>>>> clearing(0x10)
>>>> *Apr 27 00:30:50.623: %ISDN-6-DISCONNECT: Interface Serial2:13
>>>> disconnected from 5028157000 , call lasted 18 seconds
>>>> *Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>>>> isdn_info=0x62DD6094, call_id=0xE
>>>> *Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>>>> hndl=14l, cause=16, Normal call clearing
>>>> *Apr 27 00:30:50.623: ISDN Dc2 SC EVENTd: process_disconnect: Raw
>>>> Release Message 0x4BFF01000E040802FF900803809081
>>>> *Apr 27 00:31:00.211: ISDN Dc2 SC Q921d: srl_send_l2_pak:
>>>> source_id = IUA, dest_id = Q.931, prim = DL_DATA_IND
>>>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 25
>>>> *Apr 27 00:31:00.215: ISDN Dc2 SC Q921d: data =
>>>> 0x62D3E3E0000000010241040000010000
>>>> *Apr 27 00:31:00.215: 080207AB4D08028010
>>>> *Apr 27 00:31:00.215: ISDN Dc2 SC BACKHAUL: L3IF_rx_L2_pak: received
>>>> data 0x080207AB4D08028010
>>>> *Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_Go: source = 0x20A, event
>>>> = 0x241, call id = 0x0, int id = 0x0
>>>> *Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>>>> state 10 event 0x4D ces 1
>>>> *Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>>>> 0x87AB RELEASE:Ux_Release(nlcb)
>>>> *Apr 27 00:31:00.215: ISDN Dc2 SC Q931d: L3_state_change: callref
>>>> 0x87AB old CALL_ACTIVE, new RELEASE_REQUEST
>>>> *Apr 27 00:31:00.215: ISDN Dc2 SC CC: CCPRI_Go: source id 0x300, call
>>>> id 0xE, event 0x341 (pre-ccb recovery)
>>>> *Apr 27 00:31:00.215: ISDN Dc2 SC CC: CCPRI_Go: dispatching event 0x97
>>>> call id 0xE cref 0x87AB Source->L3
>>>> *Apr 27 00:31:00.215: ISDN Dc2 SC CC: CCPCC_CallConnected: event 0x97
>>>> b channel 14 nfas int_id 2 call_id 0xE
>>>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: CC_CHAN_GetUserpri: using
>>>> call_id = 0xE
>>>> *Apr 27 00:31:00.219: ISDN Dc2 SC CCd: CC_CHAN_ReleaseChanpri: channel
>>>> 14
>>>> *Apr 27 00:31:00.219: ISDN Dc2 SC TGRM: get_tgrm_avail_state: idb
>>>> 0x62D3E3E0 bchan 14 service_state 0 call_state 0 false busy 0x0 dsl 2
>>>> *Apr 27 00:31:00.219: ISDN Dc2 SC TGRM: update_tgrm_call_status: idb
>>>> 0x62D3E3E0 bchan 14 availability state 1 call state(prev,new) (2,0),
>>>> dsl
>>>> 2
>>>> *Apr 27 00:31:00.219: ISDN Dc2 SC TGRM: update_tgrm_call_status:
>>>> Calling TGRM with tgrm_call_isdn_update: idb 0x62D3E3E0 bchan 14 call
>>>> state 0 call type 0 call dir 1
>>>> *Apr 27 00:31:00.219: ISDN EVENTd: cc_clear_free_list freed 0x6339ABFC
>>>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_Go: source = 0x400, event
>>>> = 0x340, call id = 0xE, int id = 0x2
>>>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_Go: call_id 0xE cr 0x87AB
>>>> state 19 event 0xAB ces 1
>>>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_ProcessEvent: callref =
>>>> 0x87AB CC_REL_COMP_REQ:U19_RelCompReq(nlcb)
>>>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: L3_TxSarMsg: InfoLen = 5
>>>> octets 0x080287AB5A
>>>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: srl_send_l3_pak:
>>>> source_id = Q.931, dest_id = IUA, prim = DL_DATA_REQ
>>>> priv_len = 4 int_id = 0x62D3E3E0 datasize = 21
>>>> *Apr 27 00:31:00.219: ISDN Dc2 SC Q931d: data =
>>>> 0x62D3E3E0000100000240046A00010806
>>>> *Apr 27 00:31:00.219: 080287AB5A
>>>> *Apr 27 00:31:00.223: ISDN Dc2 SC Q931d: L3_state_change: callref
>>>> 0x87AB old RELEASE_REQUEST, new NULL_STATE
>>>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENT: process_rxstate: ces/callid
>>>> 1/0xE calltype 2 CALL_DISC
>>>> *Apr 27 00:31:00.223: ISDN Dc2 SC PACKET: process_rxstate:
>>>> 0x4B0201000E0308011008028010
>>>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: process_rxstate: cause=0x10
>>>> (16), cause_present=1
>>>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>>>> isdn_info=0x62D469E0, call_id=0xE
>>>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>>>> isdn_info=0x62DD6094, call_id=0xE
>>>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>>>> isdn_info=0x62D469E0, call_id=0xE
>>>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: calltrkr_call_disconnected:
>>>> isdn_info=0x62DD6094, call_id=0xE
>>>> *Apr 27 00:31:00.223: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0,
>>>> call_id=0xE, ces=0x1
>>>> bchan=0xD, event=0x0, cause=0x10
>>>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENTd: process_disc_ack: call id
>>>> 0xE, ces 1, call type VOICE cause 0x10
>>>> *Apr 27 00:31:00.223: ISDN Dc0 SC CC: CCPRI_Go: source id 0x500, call
>>>> id 0x0, event 0x57 (pre-ccb recovery)
>>>> *Apr 27 00:31:00.223: ISDN Dc2 SC SERROR: CCPRI_Go: call id 0xE event
>>>> 0x57 No ccb Source->HOST
>>>> *Apr 27 00:31:00.223: ISDN Dc2 SC EVENT: process_rxstate: ces/callid
>>>> 1/0xE calltype 2 CALL_CLEARED
>>>> *Apr 27 00:31:00.227: ISDN Dc2 SC PACKET: process_rxstate:
>>>> 0x570201000E0008028010
>>>> *Apr 27 00:31:00.227: ISDN Dc2 SC EVENTd: process_rxstate: cause=0x10
>>>> (16), cause_present=1
>>>> *Apr 27 00:31:00.227: ISDN Dc2 SC EVENTd: calltrkr_call_cleared:
>>>> isdn_info=0x62D469E0, call_id=0xE
>>>> *Apr 27 00:31:00.227: ISDN Dc2 SC EVENTd: calltrkr_call_cleared:
>>>> isdn_info=0x62DD6094, call_id=0xE
>>>> *Apr 27 00:31:00.227: EVENT_FROM_ISDN: dchan_idb=0x62D3E3E0,
>>>> call_id=0xE, ces=0x1
>>>> bchan=0xD, event=0x0, cause=0x10
>>>> ------------------------------------------------------------------------
>>>>
>>>> _______________________________________________
>>>> cisco-nas mailing list
>>>> cisco-nas [at] puck
>>>> https://puck.nether.net/mailman/listinfo/cisco-nas
>>>>
>>>
>

_______________________________________________
cisco-nas mailing list
cisco-nas [at] puck
https://puck.nether.net/mailman/listinfo/cisco-nas

mays at win

Aug 25, 2008, 7:15 PM

Post #9 of 12 (3557 views)
Permalink

Re: Modems not responding on cisco AS5300. [In reply to]

> Well, what's puzzling me is that it's the same six modems on two cards in
> the box. So I'm wondering if the slots the cards are plugged into share
> any circuitry.

Okay, so we have another AS5300 with the same hardware, same IOS, same modem
firmware, exact same config except for things like the IP number. I went
through and tested every modem on it. The following modems failed repeatedly
on two tests.

1/36 *
-
1/38 *
1/39 *
1/40 *
1/41 *
-
1/43 *

2/36 *
-
2/38 *
2/39 *
2/40 *
2/41 *
-
2/43 *

The same six modems on each card -- though not all in one SPE clump this
time. I'm out of ideas. Not that I had that many in the first place.

_______________________________________________
cisco-nas mailing list
cisco-nas [at] puck
https://puck.nether.net/mailman/listinfo/cisco-nas

mtinka at globaltransit

Aug 25, 2008, 7:20 PM

Post #10 of 12 (3565 views)
Permalink

Re: Modems not responding on cisco AS5300. [In reply to]

On Tuesday 26 August 2008 08:18:42 Aaron Leonard wrote:

> In any case, the guidance below is still generally
> applicable - i.e. run latest code (2.9.5.0); turn on
> modem recovery.

You also want to run an IOS revision no later than 12.3(5)f.

Anything more recent than this will continuously cause your
modems to go into a BAD state.

Cheers,

Mark.

Attachments:

signature.asc (0.82 KB)

Aaron at cisco

Aug 26, 2008, 8:20 AM

Post #11 of 12 (3519 views)
Permalink

Re: Modems not responding on cisco AS5300. [In reply to]

That's baffling, I must admit. Never seen such a thing before.

----

>> Well, what's puzzling me is that it's the same six modems on two cards in
>> the box. So I'm wondering if the slots the cards are plugged into share
>> any circuitry.
>>
>
> Okay, so we have another AS5300 with the same hardware, same IOS, same modem
> firmware, exact same config except for things like the IP number. I went
> through and tested every modem on it. The following modems failed repeatedly
> on two tests.
>
> 1/36 *
> -
> 1/38 *
> 1/39 *
> 1/40 *
> 1/41 *
> -
> 1/43 *
>
> 2/36 *
> -
> 2/38 *
> 2/39 *
> 2/40 *
> 2/41 *
> -
> 2/43 *
>
> The same six modems on each card -- though not all in one SPE clump this
> time. I'm out of ideas. Not that I had that many in the first place.
>

_______________________________________________
cisco-nas mailing list
cisco-nas [at] puck
https://puck.nether.net/mailman/listinfo/cisco-nas

cgregory at hwcn

Aug 26, 2008, 2:27 PM

Post #12 of 12 (3534 views)
Permalink

Re: Modems not responding on cisco AS5300. [In reply to]

On Mon, 25 Aug 2008, Joseph Mays wrote:
> Okay, so we have another AS5300 with the same hardware, same IOS, same
> modem firmware, exact same config except for things like the IP
> number. I went through and tested every modem on it. The following
> modems failed repeatedly on two tests.
> The same six modems on each card -- though not all in one SPE clump this
> time. I'm out of ideas. Not that I had that many in the first place.

Is this on a set of PRI lines? Are we certain that the phone company does
not have a fault with *their* equipment? If they are running an integrated
system, *they* might have circuits 'shared' between PRI's in the
manner that produces patterns as you are seeing.... Does the pattern
*change* when you reset the AS5300?

- Charles

_______________________________________________
cisco-nas mailing list
cisco-nas [at] puck
https://puck.nether.net/mailman/listinfo/cisco-nas

Index | Next | Previous | View Threaded

Interested in having your list archived? Contact Gossamer Threads