- Cisco Community
- Technology and Support
- Collaboration
- IP Telephony and Phones
- FXO call disconnects intermittently
- Subscribe to RSS Feed
- Mark Topic as New
- Mark Topic as Read
- Float this Topic for Current User
- Bookmark
- Subscribe
- Mute
- Printer Friendly Page
FXO call disconnects intermittently
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
06-21-2011 01:43 PM - edited 03-16-2019 05:34 AM
Hi
We have following setup: IPPhone----SCCP-->CUCM8.5---->H323-GW(FXO Port)--->PSTN
Inbound calls are perfectly fine but outbound calls drop after 120 Sec(aprox). Here is the configuration of the FXO Port:
voice-port 0/1/1
supervisory disconnect dualtone pre-connect
supervisory answer dualtone
connection plar opx immediate 2205
description ** Tel No. XXXXXXXX **
caller-id enable
!
Dial-peer configuration looks like this:
dial-peer voice 93 pots
destination-pattern 89T
port 0/1/1
!
VoiceRTR(config-voiceport)#do sh ver
Cisco IOS Software, 2800 Software (C2800NM-IPVOICE-M), Version 15.1(4)M, RELEASE SOFTWARE (fc1)
Technical Support: http://www.cisco.com/techsupport
Copyright (c) 1986-2011 by Cisco Systems, Inc.
Compiled Thu 24-Mar-11 14:26 by prod_rel_team
ROM: System Bootstrap, Version 12.4(1r) [hqluong 1r], RELEASE SOFTWARE (fc1)
VoiceRTR uptime is 3 weeks, 3 hours, 34 minutes
System returned to ROM by reload at 20:04:02 BAH Tue May 31 2011
System restarted at 20:05:52 BAH Tue May 31 2011
System image file is "flash:c2800nm-ipvoice-mz.151-4.M.bin"
Last reload type: Normal Reload
Cisco 2811 (revision 1.0) with 249856K/12288K bytes of memory.
Processor board ID FTX1020A3E8
2 FastEthernet interfaces
12 Voice FXO interfaces
2 Voice FXS interfaces
DRAM configuration is 64 bits wide with parity enabled.
239K bytes of non-volatile configuration memory.
62720K bytes of ATA CompactFlash (Read/Write)
License Info:
License UDI:
-------------------------------------------------
Device# PID SN
-------------------------------------------------
*0 CISCO2811 FTX1020XXXX
Configuration register is 0x2102
Any guess...what could be the reason for this?
- Labels:
-
Other IP Telephony
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
06-22-2011 11:17 AM
I have managed to find the debugs that show the diconnect for the call. The disconnect cause code is 16. Can someone advise the cause code dictionary link or what does cause code 16 means?
Jun 21 17:48:51: //3192/001E823CC903/CCAPI/ccCallDisconnect:
Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=16)
Jun 21 17:48:51: //3192/001E823CC903/CCAPI/ccCallDisconnect:
Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
Jun 21 17:48:51: //3192/001E823CC903/CCAPI/ccCallDisconnect:
Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=16)
Jun 21 17:48:51: //3192/001E823CC903/CCAPI/ccCallDisconnect:
Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
06-22-2011 11:21 AM
Means normal call clearing.
You need more debug, as whcih who is disconnecting in first place.
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
06-22-2011 12:43 PM
Here is the complete debug. It looks like that despite the call being answered, it keeps the RING_NO_ANSWER timer on and disconnects the call on the timout of this parameter.
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Jun 22 22:30:56: //3421/808E95A51404/DSPAPI/[0/1:1]/dsp_voice_det_status_change:
Status=32, Timestamp=0, Tone ID=1, Trigger=TRUE
Jun 22 22:30:56: //3421/808E95A51404/DSPAPI/[0/1:1]/dsp_voice_det_status_change:
Status=32, Timestamp=0, Tone ID=1, Trigger=TRUE
Jun 22 22:30:56: //3421/808E95A51404/DSPAPI/[0/1:1]/dsp_voice_det_status_change:
Status=32, Timestamp=0, Tone ID=1, Trigger=TRUE
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/vtsp_process_event:
[state:S_SETUP_REQ_PROC, event:E_RING_NOAN_TIMER]
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/act_ring_noan_timer:
No Answer Timer Expired
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/vtsp_cc_call_disconnected:
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/vtsp_cc_call_disconnected:
Cause Value=19
Jun 22 22:30:57: //3421/808E95A51404/CCAPI/cc_api_call_disconnected:
Cause Value=19, Interface=0x48CE30AC, Call Id=3421
Jun 22 22:30:57: //3421/808E95A51404/CCAPI/cc_api_call_disconnected:
Call Entry(Responsed=TRUE, Cause Value=19, Retry Count=0)
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/vtsp_set_release_source:
Release Direction=Internal, Release Source=Internal Release-PSTN
Jun 22 22:30:57: //3420/808E95A51404/CCAPI/ccCallReleaseResources:
release reserved xcoding resource.
Jun 22 22:30:57: //3421/808E95A51404/CCAPI/cc_api_get_transfer_info:
Transfer Number Is Null
Jun 22 22:30:57: //3421/808E95A51404/CCAPI/ccCallSetAAA_Accounting:
Accounting=0, Call Id=3421
Jun 22 22:30:57: //3420/808E95A51404/CCAPI/ccConferenceDestroy:
Conference Id=0x5B7, Tag=0x0
Jun 22 22:30:57: //3420/808E95A51404/CCAPI/cc_api_bridge_drop_done:
Conference Id=0x5B7, Source Interface=0x48083FCC, Source Call Id=3420,
Destination Call Id=3421, Disposition=0x0, Tag=0x0
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/vtsp_dsm_bridge_status_cb:
Jun 22 22:30:57: //3421/808E95A51404/CCAPI/cc_api_bridge_drop_done:
Conference Id=0x5B7, Source Interface=0x48CE30AC, Source Call Id=3421,
Destination Call Id=3420, Disposition=0x0, Tag=0x0
Jun 22 22:30:57: //3420/808E95A51404/CCAPI/cc_generic_bridge_done:
Conference Id=0x5B7, Source Interface=0x48CE30AC, Source Call Id=3421,
Destination Call Id=3420, Disposition=0x0, Tag=0x0
Jun 22 22:30:57: //3421/808E95A51404/DSPAPI/[0/1:1]/dsp_voice_config_params:
Jun 22 22:30:57: 1 parameter
[0] PAK_SUPPRESS: 1
Jun 22 22:30:57: //3421/808E95A51404/CCAPI/ccCallDisconnect:
Cause Value=19, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=19)
Jun 22 22:30:57: //3421/808E95A51404/CCAPI/ccCallDisconnect:
Cause Value=19, Call Entry(Responsed=TRUE, Cause Value=19)
Jun 22 22:30:57: //3421/808E95A51404/CCAPI/cc_api_get_transfer_info:
Transfer Number Is Null
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/vtsp_process_event:
[state:S_SETUP_REQ_PROC, event:E_CC_DISCONNECT]
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/act_disconnect:
Cause Value=19, Previous Cause Value=19
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/vtsp_ring_noan_timer_stop:
Timer Stop Time=190948646
Jun 22 22:30:57: htsp_timer_stop3
Jun 22 22:30:57: //3420/808E95A51404/CCAPI/ccAssociateStream:
Coder=5, DTMF Relay=1, Vad=0,
Record Function=0x0, Event Queue=0x484FACA4, Stream Context=49F4667C,
Record Context=0x0, Stream Call Id=3422, Call Id=3420
Jun 22 22:30:57: //3420/808E95A51404/CCAPI/ccAssociateStream:
Call Entry(Stream Status=2, Digit Enable=FALSE)
Jun 22 22:30:57: //3421/808E95A51404/DSPAPI/[0/1:1]/dsp_query_info:
Request ID=6, Reset Flag=FALSE Q:TX RX Levels
Jun 22 22:30:57: //3420/808E95A51404/H323/cch323_do_associate: gw_id=1
Jun 22 22:30:57: //3420/808E95A51404/H323/cch323_do_associate: REQUESTED: vad=0, codec=0x5; CONFIGURED: vad=1, codec=0x5; disp=0x0
Jun 22 22:30:57: //3420/808E95A51404/H323/h323_common_setup_rtcp_parameters: updating RTP session type, ccb->status = 4810A602,
olc->rtcp_session.type = 3, do_rtcp = 1, iwf_state = 10,
negotiated_codec = G711_ULAW_64K, mediaWait = 0, h245_lport = 16696,
srcAddress = 10.20.5.2, srcCallID = 3420, h245.status = 21064880
Jun 22 22:30:57: //3420/808E95A51404/CCAPI/cc_api_call_associated:
Interface=0x0, CallId=3420, Disposition=0
Play Function=0x43987AB4, Codec=0x5, Vad=0x0
Media Type=0x1, SPI Context=0x4720E060, Stream CallId=3422
TX Dynamic Pt=0xFF, RX Dynamic Pt=0xFF
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/vtsp_dsm_get_levels_done_cb:
Jun 22 22:30:57: //3421/808E95A51404/DSPAPI/[0/1:1]/dsp_query_info:
Request ID=8, Reset Flag=FALSE Q:PO_Delay PO_Error TX RX Levels Error VQ
Jun 22 22:30:57: //3421/808E95A51404/DSPAPI/[0/1:1]/dsp_tx_stats:
Request ID=8, Packets: Voice=8984, Signaling=0, ComfortNoise=0
TX duration=179680(ms): Voice=179680(ms), FAX=0(ms)
Jun 22 22:30:57: //3421/808E95A51404/DSPAPI/[0/1:1]/dsp_rx_stats:
Request ID=8, Packets: Voice=8978, Signalling=0, ComfortNoise=0
RX duration=179560(ms): Voice=179470(ms), FAX=0(ms)
Packets: Bad Sequence=0, Bad Protocol=0, Late=4, Early=1
Jun 22 22:30:57: //3421/808E95A51404/DSPAPI/[0/1:1]/dsp_playout_delay_stats:
Request ID=8, Current=55(ms), MIN=55(ms), MAX=365(ms)
Clock offset=-315196646(ms), Inter arrival jitter=4(ms)
Jun 22 22:30:57: //3421/808E95A51404/DSPAPI/[0/1:1]/dsp_playout_error_stats:
Request ID=8
Concealment: Predictive=420(ms), Interpolative=0(ms), Silence=0(ms)
Retro Memory update=2(ms), Buffer overflow=0(ms)
Talkspurt endpoint detection errors=0
Jun 22 22:30:57: //3421/808E95A51404/DSPAPI/[0/1:1]/dsp_level_stats:
Request ID=8, TX: power=-72.4(dBm0), mean=-35.7(linear PCM), RX: power=-59.9(dBm0), mean=-17.9(linear PCM)
Background Noise=-61.0(dBm0), ERL level=21.0(dB)
ACOM level=21.0(dB), Current TX act=1, Current RX act=1
Reflector locations: 3(ms) 0(ms) 0(ms), MAX reflector=3(ms)
2 ECAN control words: 7C 1000, ECAN Version=9183.890
Jun 22 22:30:57: //3421/808E95A51404/DSPAPI/[0/1:1]/dsp_error_stats:
Dropped Packets: RX=0 TX=0, Control Packets: RX=42968 TX=15088 TX dropped=0
Jun 22 22:30:57: //3421/808E95A51404/DSPAPI/[0/1:1]/dsp_vq_stats:
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/vtsp_process_event:
[state:S_WAIT_STATS, event:E_VTSP_DSM_STATS_COMPLETE]
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/act_dsm_dsp_stats_complete:
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/vtsp_timer:
Timer Start Time=190948648, Timer Value=60000(ms)
Jun 22 22:30:57: htsp_process_event: [0/0/1, FXOLS_CONNECT, E_HTSP_RELEASE_REQ]fxols_offhook_release
Jun 22 22:30:57: htsp_timer_stop
Jun 22 22:30:57: htsp_timer_stop2
Jun 22 22:30:57: htsp_timer_stop3
Jun 22 22:30:57: [0/0/1] set signal state = 0x4 timestamp = 0
Jun 22 22:30:57: htsp_timer - 2000 msec
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/vtsp_process_event:
[state:S_WAIT_RELEASE, event:E_TSP_DISCONNECT_CONF]
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/act_wrelease_release:
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/vtsp_play_busy_timer_stop:
Timer Stop Time=190948648
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/vtsp_timer_stop:
Timer Stop Time=190948648
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/vtsp_do_call_history:
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/vtsp_do_call_history:
Coder Rate=5
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:1:1/vtsp_is_valid_dsm_handle:
DMGR=0x4B78A238, VTSP CDB=0x4A40CD48
Jun 22 22:30:57: //3421/808E95A51404/DSPAPI/[0/1:1]/dsp_stop_service:
G711_U (5)
Jun 22 22:30:57: //3421/808E95A51404/DSPAPI/[0/1:1]/dsp_close_service:
G711_U (5)
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:-1:-1/vtsp_dsm_closed_cb:
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:-1:-1/vtsp_process_event:
[state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:-1:-1/act_terminate:
Jun 22 22:30:57: //3421/808E95A51404/VTSP:(0/0/1):-1:-1:-1/vtsp_timer_stop:
Timer Stop Time=190948649
Jun 22 22:30:57: //3421/808E95A51404/CCAPI/cc_api_call_disconnect_done:
Disposition=0, Interface=0x48CE30AC, Tag=0x0, Call Id=3421,
Call Entry(Disconnect Cause=19, Voice Class Cause Code=0, Retry Count=0)
Jun 22 22:30:57: //3421/808E95A51404/CCAPI/cc_api_call_disconnect_done:
Call Disconnect Event Sent
Jun 22 22:30:57: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
Jun 22 22:30:57: :cc_free_feature_vsa freeing 4B76FDE8
Jun 22 22:30:57: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
Jun 22 22:30:57: vsacount in free is 1
Jun 22 22:30:57: //-1/808E95A51404/VTSP:(0/0/1):-1:-1:-1/vtsp_free_cdb:
CDB=0x4A40CD48
Jun 22 22:30:57: //3420/808E95A51404/CCAPI/ccDisassociateStream:
Record Context=0x0, Stream Call Id=3422, Call Id=3420
Jun 22 22:30:57: //3420/808E95A51404/CCAPI/ccDisassociateStream:
Call Entry(Stream Status=1, Digit Enable=FALSE)
Jun 22 22:30:57: //-1/xxxxxxxxxxxx/H323/cch323_post_call_statistics: callID=3420
Jun 22 22:30:57: //3420/808E95A51404/CCAPI/ccCallDisconnect:
Cause Value=19, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
Jun 22 22:30:57: //3420/808E95A51404/CCAPI/ccCallDisconnect:
Cause Value=19, Call Entry(Responsed=TRUE, Cause Value=19)
Jun 22 22:30:57: //3420/808E95A51404/CCAPI/cc_api_get_transfer_info:
Transfer Number Is Null
Jun 22 22:30:57: //3420/808E95A51404/H323/cch323_do_disassociate: gw_id=1
Jun 22 22:30:57: //-1/xxxxxxxxxxxx/H323/cch323_do_get_call_statistics: Entry, call_id=3420
Jun 22 22:30:57: //3420/808E95A51404/H323/cch323_do_call_disconnect: gw_id=1, discCause=19
Jun 22 22:30:57: //-1/xxxxxxxxxxxx/H323/cch323_iev_queue_service: Dispatch 0x9 internal event to H225 SM
Jun 22 22:30:57: //3420/808E95A51404/H323/run_h225_sm: Received event H225_EV_RELEASE while at state H225_ALERT
Jun 22 22:30:57: //3420/808E95A51404/H323/cch323_h225_send_release: Cause = 19; Location = 0
Jun 22 22:30:57: //3420/808E95A51404/H323/cch323_h225_send_release: h225TerminateRequest: src address = 169084162; dest address = 10.0.2.6
Jun 22 22:30:57: H225.0 OUTGOING PDU ::=
value H323_UserInformation ::=
{
h323-uu-pdu
{
h323-message-body releaseComplete :
{
protocolIdentifier { 0 0 8 2250 0 4 }
callIdentifier
{
guid '808E95A51A4221E014048003C0A80021'H
}
}
h245Tunneling FALSE
}
}
Jun 22 22:30:57: H225.0 OUTGOING ENCODE BUFFER::= 2580060008914A000411001100808E95A51A4221E014048003C0A8002110800100
Jun 22 22:30:57:
Jun 22 22:30:57: //3420/808E95A51404/H323/cch323_h225_set_new_state: Changing from H225_ALERT state to H225_IDLE state
Jun 22 22:30:57: //3420/808E95A51404/H323/cch323_call_generic_cleanup: Disconnected flag 1
Jun 22 22:30:57: //3420/808E95A51404/H323/cch323_store_call_history_entry: Trying to store call history/remove call_info while RTP session exists
Jun 22 22:30:57: //3420/808E95A51404/H323/cch323_store_call_history_entry: Call Active Playout Mode: 1,Init 60, Min 40, Max 1000, Fax 300
Jun 22 22:30:57: //3420/808E95A51404/H323/cch323_store_call_history_entry: Call History Playout Mode: 1,Init 60, Min 40, Max 1000, Fax 300
Jun 22 22:30:57: //-1/xxxxxxxxxxxx/H323/h323_gw_clean_send_blocked_watch: fd 2
Jun 22 22:30:57: //-1/xxxxxxxxxxxx/H323/h323_gw_clean_send_blocked_watch: fd 4
Jun 22 22:30:57: //-1/xxxxxxxxxxxx/H323/h323_gw_clean_send_blocked_watch: fd 3
Jun 22 22:30:57: //-1/xxxxxxxxxxxx/H323/cch323_cleanup_xport: hashDestroy for TcpFDTbl
Jun 22 22:30:57: //3420/808E95A51404/CCAPI/cc_api_call_disconnect_done:
Disposition=0, Interface=0x48083FCC, Tag=0x0, Call Id=3420,
Call Entry(Disconnect Cause=19, Voice Class Cause Code=0, Retry Count=0)
Jun 22 22:30:57: //3420/808E95A51404/CCAPI/cc_api_call_disconnect_done:
Call Disconnect Event Sent
Jun 22 22:30:57: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
Jun 22 22:30:57: :cc_free_feature_vsa freeing 4B76FEC8
Jun 22 22:30:57: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
Jun 22 22:30:57: vsacount in free is 0
Jun 22 22:30:57: //3420/808E95A51404/H323/cch323_call_generic_cleanup: Freeing ccb (0x4B80E4DC)
Jun 22 22:30:58: htsp_process_event: [0/0/1, FXOLS_GUARD_OUT, E_DSP_SIG_0110]
Jun 22 22:30:59: htsp_process_event: [0/0/1, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
Jun 22 22:30:59: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0100]!
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
06-22-2011 02:15 PM
Sorry, I don't know what is happenign here. Seems to me, CM is disconnecting the call with a causecode of no answer.
Discover and save your favorite ideas. Come back to expert answers, step-by-step guides, recent topics, and more.
New here? Get started with these tips. How to use Community New member guide