FXO Gateway - Outbound calls get fast busy, inbound working OK

Mike Krasnesky · ‎10-03-2024

Hello, so we've got a small site that has an older 2911 voice gateway controlled by MGCP. It has an FXO card connected to POTS lines, but they are only using the first line I believe.

They had a power outage, and now outbound calls don't work, its a fast busy. Inbound calls still work OK when the number is dialed.

Any ideas?

I've run debug vpm sig and see the following on a successful inbound call

Gateway#debug vpm sig
Voice Port Module signaling debugging is enabled
Gateway#
000172: Oct 3 06:16:06.466 MDT: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=15923 systime=134577
000173: Oct 3 06:16:06.466 MDT: htsp_process_event: [0/2/0, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
000174: Oct 3 06:16:06.466 MDT: htsp_timer - 125 msec
000175: Oct 3 06:16:06.594 MDT: htsp_process_event: [0/2/0, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_timer
000176: Oct 3 06:16:06.594 MDT: htsp_timer - 10000 msec
000177: Oct 3 06:16:06.594 MDT: htsp_timer3 - 5600 msec
000178: Oct 3 06:16:06.594 MDT: [0/2/0] htsp_start_caller_id_rx:Mode BELLCORE. Alerting 0x1
Gateway#
000179: Oct 3 06:16:06.594 MDT: htsp_start_caller_id_rx create dsp_stream_manager
000180: Oct 3 06:16:06.594 MDT: [0/2/0] htsp_dsm_create_success returns 1
Gateway#
000181: Oct 3 06:16:08.498 MDT: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=17956 systime=134780
000182: Oct 3 06:16:08.498 MDT: htsp_process_event: [0/2/0, FXOLS_RINGING, E_DSP_SIG_0100]
000183: Oct 3 06:16:08.498 MDT: fxols_ringing_not
000184: Oct 3 06:16:08.498 MDT: htsp_timer_stop
000185: Oct 3 06:16:08.498 MDT: htsp_timer - 10000 msec
000186: Oct 3 06:16:09.642 MDT: [0/2/0] htsp_dsm_feature_notify_cb returns 2 id=DSM_FEATURE_SM_CALLERID_RX
000187: Oct 3 06:16:09.642 MDT: htsp_process_event: [0/2/0, FXOLS_RINGING, E_HTSP_CALLERID_RX_DONE]
000188: Oct 3 06:16:09.642 MDT: fxols_callerid_done: stop caller ID
000189: Oct 3 06:16:09.642 MDT: [0/2/0] htsp_stop_caller_id_rx. message length 46
000190: Oct 3 06:16:09.642 MDT: htsp_timer_stop3
000191: Oct 3 06:16:09.642 MDT: htsp_timer3 - 20 msec
000192: Oct 3 06:16:09.646 MDT: [0/2/0] htsp_dsm_close_done
000193: Oct 3 06:16:09.662 MDT: htsp_process_event: [0/2/0, FXOLS_STOP_CALLERID_DELAY, E_HTSP_EVENT_TIMER3]
000194: Oct 3 06:16:09.662 MDT: htsp_timer_stop
000195: Oct 3 06:16:09.662 MDT: htsp_timer_stop3 htsp_setup_ind
000196: Oct 3 06:16:09.662 MDT: [0/2/0] get_fxo_caller_id:Caller ID received. Message type=128 length=42 checksum=71
000197: Oct 3 06:16:09.662 MDT: [0/2/0] Caller ID String 80 27 01 08 31 30 30 33 30 36 31 36 07 0F 4D 41 4E 49 54 4F 42 41 20 20 20 20 20 20 20 02 0A 32 30 34 32 32 38 39 34 30 32 71
000198: Oct 3 06:16:09.662 MDT: [0/2/0] get_fxo_caller_id calling num=2042289402 calling name=MANITOBA calling time=10/03 06:16
000199: Oct 3 06:16:09.662 MDT: fxols_callerid_done: call being answered
000200: Oct 3 06:16:09.666 MDT: htsp_process_event: [0/2/0, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
000201: Oct 3 06:16:09.666 MDT: fxols_wait_setup_ack:
000202: Oct 3 06:16:09.666 MDT: [0/2/0] set signal state = 0xC timestamp = 0fxols_check_auto_call
000203: Oct 3 06:16:09.666 MDT: htsp_process_event: [0/2/0, FXOLS_PROCEEDING, E_HTSP_SETUP_ACK]
000204: Oct 3 06:16:09.666 MDT: htsp_process_event: [0/2/0, FXOLS_PROCEEDING, E_HTSP_CONNECT]fxols_offhook_connect
000205: Oct 3 06:16:09.666 MDT: htsp_timer_stop
000206: Oct 3 06:16:09.694 MDT: htsp_process_event: [0/2/0, FXOLS_CONNECT, E_HTSP_VOICE_CUT_THROUGH]fxols_connect_proc_voice
Gateway#
000207: Oct 3 06:16:09.694 MDT: htsp_call_bridged invoked
000208: Oct 3 06:16:09.698 MDT: htsp_process_event: [0/2/0, FXOLS_CONNECT, E_HTSP_VOICE_CUT_THROUGH]fxols_connect_proc_voice
000209: Oct 3 06:16:09.938 MDT: htsp_dsp_message: SEND_SIG_STATUS: state=0x6 timestamp=19399 systime=134924
000210: Oct 3 06:16:09.938 MDT: htsp_process_event: [0/2/0, FXOLS_CONNECT, E_DSP_SIG_0110]fxols_rvs_battery
000211: Oct 3 06:16:09.938 MDT: htsp_timer_stop2
000212: Oct 3 06:16:09.938 MDT: htsp_timer_stop2
Gateway#
000213: Oct 3 06:16:15.578 MDT: htsp_dsp_message: SEND_SIG_STATUS: state=0xC timestamp=25037 systime=135488
000214: Oct 3 06:16:15.578 MDT: htsp_process_event: [0/2/0, FXOLS_CONNECT, E_DSP_SIG_1100]fxols_offhook_disc
000215: Oct 3 06:16:15.578 MDT: htsp_timer2 - 350 msec
000216: Oct 3 06:16:15.930 MDT: htsp_process_event: [0/2/0, FXOLS_CONNECT, E_HTSP_EVENT_TIMER2]fxols_disc_confirm
000217: Oct 3 06:16:15.930 MDT: htsp_timer_stop
000218: Oct 3 06:16:15.930 MDT: htsp_timer_stop2
000219: Oct 3 06:16:15.930 MDT: htsp_timer_stop3
000220: Oct 3 06:16:15.950 MDT: htsp_timer_stop3
Gateway#
000221: Oct 3 06:16:15.970 MDT: htsp_process_event: [0/2/0, FXOLS_REMOTE_RELEASE, E_HTSP_RELEASE_REQ]fxols_offhook_release
000222: Oct 3 06:16:15.970 MDT: htsp_timer_stop
000223: Oct 3 06:16:15.970 MDT: htsp_timer_stop2
000224: Oct 3 06:16:15.970 MDT: htsp_timer_stop3
000225: Oct 3 06:16:15.970 MDT: [0/2/0] set signal state = 0x4 timestamp = 0
000226: Oct 3 06:16:15.970 MDT: htsp_timer - 1000 msec
000227: Oct 3 06:16:16.398 MDT: htsp_dsp_message: SEND_SIG_STATUS: state=0x6 timestamp=25856 systime=135570
000228: Oct 3 06:16:16.398 MDT: htsp_process_event: [0/2/0, FXOLS_GUARD_OUT, E_DSP_SIG_0110]
000229: Oct 3 06:16:16.970 MDT: htsp_process_event: [0/2/0, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
Gateway#
000230: Oct 3 06:16:16.970 MDT: htsp_dsp_message: RESP_SIG_STATUS: state=0x4 timestamp=0 systime=135628
000231: Oct 3 06:16:16.970 MDT: htsp_process_event: [0/2/0, FXOLS_ONHOOK, E_DSP_SIG_0100]

thanks!

Mike Krasnesky · ‎10-03-2024

Sorry i mispoke, this is a failed outbound attempt using debug vpm sig and debug voip ccapi inout:

Gateway#term mon
Gateway#debug vpm sig
Voice Port Module signaling debugging is enabled
Gateway#debug voip ccapi inout
voip ccapi inout debugging is on
Gateway#
000234: Oct 3 08:43:25.055 MDT: htsp_dsp_message: SEND_SIG_STATUS: state=0xC timestamp=7124 systime=1018433
000235: Oct 3 08:43:25.055 MDT: htsp_process_event: [0/2/0, FXOLS_CONNECT, E_DSP_SIG_1100]fxols_offhook_disc
000236: Oct 3 08:43:25.055 MDT: htsp_timer2 - 350 msec
000237: Oct 3 08:43:25.191 MDT: //7/B24DB8558011/CCAPI/ccCallModifyExtended:
Nominator=0x238ECC20, Params=0x238ED058, Call Id=7
000238: Oct 3 08:43:25.191 MDT: //8/B24DB8558011/CCAPI/ccCallModify:
Nominator=0x800, Params=0x238ED630, Call Id=8
000239: Oct 3 08:43:25.191 MDT: //7/B24DB8558011/CCAPI/cc_api_call_modify_done:
Result=0, Interface=0x3FA146EC, Call Id=7
000240: Oct 3 08:43:25.191 MDT: //8/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

000241: Oct 3 08:43:25.191 MDT: cc_api_get_xcode_stream : 5007
000242: Oct 3 08:43:25.191 MDT: //8/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

000243: Oct 3 08:43:25.191 MDT: cc_api_get_xcode_stream : 5007
000244: Oct 3 08:43:25.191 MDT: //8/B24DB8558011/CCAPI/cc_api_call_modify_done:
Result=0, Interface=0x2276C65C, Call Id=8
000245: Oct 3 08:43:25.191 MDT: //8/xxxxxxxxxxxx/CCAPI/cc_api_ha_call_active_notify:

000246: Oct 3 08:43:25.191 MDT: call_info mainst_callID:0x8, peer_callID:0x7, confID:0x4, spi_type:6, media_flo_thru:1,num_streams:1, swmtpmsp_present:0

000247: Oct 3 08:43:25.191 MDT: //8/xxxxxxxxxxxx/CCAPI/cc_api_ha_call_active_notify:

000248: Oct 3 08:43:25.191 MDT: stream[0]: callid:0x8, media_passthrough:0
000249: Oct 3 08:43:25.215 MDT: //7/B24DB8558011/CCAPI/ccCallReportDigits:
(callID=0x7, digit_event=0x0, enable=FALSE, consume=FALSE)
000250: Oct 3 08:43:25.215 MDT: //7/B24DB8558011/CCAPI/ccCallReportDigits:
Enabled=TRUE, Call Id=7
000251: Oct 3 08:43:25.215 MDT: //7/B24DB8558011/CCAPI/cc_api_call_report_digits_done:
(vdbPtr=0x3FA146EC, callID=0x7, disp=0, digit_event=0x0, enable=FALSE, consume=FALSE)
000252: Oct 3 08:43:25.215 MDT: //7/B24DB8558011/CCAPI/cc_api_call_report_digits_done:
Enabled=TRUE, Disposition=0x0, Interface=0x3FA146EC, Call Id=7
000253: Oct 3 08:43:25.215 MDT: //7/B24DB8558011/CCAPI/cc_api_call_report_digits_done:
Call Entry(Initial Digit Timeout=4000(ms), Inter Digit Timeout=4000(ms))
000254: Oct 3 08:43:25.215 MDT: //8/B24DB8558011/CCAPI/ccGetCallStatistics:
Call Stats=0x24F6C918, Call Id=8
000255: Oct 3 08:43:25.215 MDT: //8/B24DB8558011/CCAPI/ccConferenceDestroy:
Conference Id=0x4, Tag=0x0
000256: Oct 3 08:43:25.215 MDT: //8/B24DB8558011/CCAPI/ccConferenceDestroy:

000257: Oct 3 08:43:25.215 MDT: confID:0x4; callEntry1 callID1:0x8, type:9; callEntry2 callID2:0x7, type:6

000258: Oct 3 08:43:25.215 MDT: //8/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

000259: Oct 3 08:43:25.215 MDT: cc_api_get_xcode_stream : 5007
000260: Oct 3 08:43:25.215 MDT: //8/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

000261: Oct 3 08:43:25.215 MDT: cc_api_get_xcode_stream : 5007
000262: Oct 3 08:43:25.215 MDT: //8/B24DB8558011/CCAPI/cc_api_bridge_drop_done:
Conference Id=0x4, Source Interface=0x2276C65C, Source Call Id=8,
Destination Call Id=7, Disposition=0x0, Tag=0x0
000263: Oct 3 08:43:25.215 MDT: //7/B24DB8558011/CCAPI/cc_api_bridge_drop_done:
Conference Id=0x4, Source Interface=0x3FA146EC, Source Call Id=7,
Destination Call Id=8, Disposition=0x0, Tag=0x0
000264: Oct 3 08:43:25.215 MDT: //8/B24DB8558011/CCAPI/cc_generic_bridge_done:
Conference Id=0x4, Source Interface=0x3FA146EC, Source Call Id=7,
Destination Call Id=8, Disposition=0x0, Tag=0x0
000265: Oct 3 08:43:25.215 MDT: //7/B24DB8558011/CCAPI/ccCallDisconnect:
Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
000266: Oct 3 08:43:25.215 MDT: //7/B24DB8558011/CCAPI/ccCallDisconnect:
Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
000267: Oct 3 08:43:25.215 MDT: //7/B24DB8558011/CCAPI/cc_api_get_transfer_info:
Transfer Number=NULL
000268: Oct 3 08:43:25.215 MDT: //8/B24DB8558011/CCAPI/ccCallDisconnect:
Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
000269: Oct 3 08:43:25.215 MDT: //8/B24DB8558011/CCAPI/ccCallDisconnect:
Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
000270: Oct 3 08:43:25.215 MDT: htsp_timer_stop3
000271: Oct 3 08:43:25.227 MDT: //8/B24DB8558011/CCAPI/cc_api_call_disconnect_done:
Disposition=0, Interface=0x2276C65C, Tag=0x0, Call Id=8,
Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
000272: Oct 3 08:43:25.227 MDT: //8/B24DB8558011/CCAPI/cc_api_call_disconnect_done:
Call Disconnect Event Sent
000273: Oct 3 08:43:25.227 MDT: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

000274: Oct 3 08:43:25.227 MDT: :cc_free_feature_vsa freeing 3E3DDE60
000275: Oct 3 08:43:25.227 MDT: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

000276: Oct 3 08:43:25.227 MDT: vsacount in free is 1
000277: Oct 3 08:43:25.235 MDT: htsp_process_event: [0/2/0, FXOLS_CONNECT, E_HTSP_RELEASE_REQ]fxols_offhook_release
000278: Oct 3 08:43:25.235 MDT: htsp_timer_stop
000279: Oct 3 08:43:25.235 MDT: htsp_timer_stop2
000280: Oct 3 08:43:25.235 MDT: htsp_timer_stop3
000281: Oct 3 08:43:25.235 MDT: [0/2/0] set signal state = 0x4 timestamp = 0
000282: Oct 3 08:43:25.235 MDT: htsp_timer - 1000 msec
000283: Oct 3 08:43:25.239 MDT: //7/B24DB8558011/CCAPI/cc_api_call_disconnect_done:
Disposition=0, Interface=0x3FA146EC, Tag=0x0, Call Id=7,
Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
000284: Oct 3 08:43:25.239 MDT: //7/B24DB8558011/CCAPI/cc_api_call_disconnect_done:
Call Disconnect Event Sent
000285: Oct 3 08:43:25.239 MDT: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

000286: Oct 3 08:43:25.239 MDT: :cc_free_feature_vsa freeing 3E3DDF40

000287: Oct 3 08:43:25.239 MDT: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

000288: Oct 3 08:43:25.239 MDT: vsacount in free is 0
000289: Oct 3 08:43:25.879 MDT: htsp_dsp_message: SEND_SIG_STATUS: state=0x6 timestamp=7943 systime=1018515
000290: Oct 3 08:43:25.879 MDT: htsp_process_event: [0/2/0, FXOLS_GUARD_OUT, E_DSP_SIG_0110]
000291: Oct 3 08:43:26.235 MDT: htsp_process_event: [0/2/0, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
000292: Oct 3 08:43:26.235 MDT: htsp_dsp_message: RESP_SIG_STATUS: state=0x4 timestamp=0 systime=1018551
000293: Oct 3 08:43:26.235 MDT: htsp_process_event: [0/2/0, FXOLS_ONHOOK, E_DSP_SIG_0100]
Gateway#

Nithin Eluvathingal · ‎10-03-2024

Could you share the router configurations? Additionally, please attach the logs instead of posting them directly in the message. This would make it easier for us to read.