Re: Calls are Connected but Dropped After a Certain Time.

julienf28 · ‎05-11-2010

We have a FoIP envrionment and before I start blaming the software, I want to make sure that my routing is properly done. I'm able to place a fax call from one branch office to another but the call gets dropped.

RightFax ---------------à2811---------(out one of the ports of the FXO card)---------àVG248-------------àPSTN------------àFax machine

Attached are the trace of the Vg248 and the running config of the 2811 that I've got setup.

I've used the configuration guide http://docs.google.com/viewer?a=v&q=cache:7VWnAmhhiYIJ:www.cisco.com/application/pdf/paws/44948/faxvg248.pdf+configuring+vg248+to+send+fax&hl=en&gl=ca&pid=bl&srcid=ADGEESgxDmCbg_0MqYYK6Qx_H5yGJcJs-AhCsxgz1LUmi_XHxSLHwxo_DkBfH-NiR3u4HgycyXLy4IiCp9ax_w...

for fax-passthrough to help me configure the ports on the vg248.

The dial-peer I'm using right now is this one...

dial-peer voice 6 pots
destination-pattern 91[2-9]..[2-9]...
information-type fax
fax rate fax
no digit-strip
port 0/0/0

Here is the result that debug vpm all showed me.

*May 12 16:09:15.110: htsp_timer_stop3 htsp_setup_req
*May 12 16:09:15.110: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_HTSP_SETUP_REQ]fxols_onhook_setup
*May 12 16:09:15.110: [0/0/1] set signal state = 0xC timestamp = 0
*May 12 16:09:15.110: dsp_set_sig_state: [0/0/1] packet_len=12 channel_id=129 packet_id=39 state=0xC timestamp=0x0
*May 12 16:09:15.110: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_BUSY, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)
*May 12 16:09:15.114: htsp_timer - 1300 msec
*May 12 16:09:15.454: htsp_process_event: [0/0/1, FXOLS_WAIT_DIAL_TONE, E_DSP_SIG_0110]fxols_disc_clear
*May 12 16:09:15.454: htsp_timer_stop2
*May 12 16:09:15.454: htsp_timer - 1300 msec
*May 12 16:09:16.754: htsp_process_event: [0/0/1, FXOLS_WAIT_DIAL_TONE, E_HTSP_EVENT_TIMER]fxols_wait_dial_timer htsp_dial
*May 12 16:09:19.194: htsp_process_event: [0/0/1, FXOLS_WAIT_DIAL_DONE, E_DSP_DIALING_DONE]fxols_wait_dial_done htsp_progress
*May 12 16:09:19.194: htsp_timer - 350 msec
*May 12 16:09:19.198: htsp_call_bridged invoked
*May 12 16:09:19.546: htsp_process_event: [0/0/1, FXOLS_WAIT_CUT_THRU, E_HTSP_EVENT_TIMER]fxols_handle_cut_thru
*May 12 16:09:19.546: htsp_timer_stop
*May 12 16:09:19.566: flex_dsprm_forking_mixing_support:
*May 12 16:09:19.566: mars_flex_dsprm_current_codec_comp:DSP:0 FLEX Complexity Codec
*May 12 16:09:19.566: DSPWARE Version < 3.0 actual is 23.6.0
*May 12 16:09:19.566: flex_dsprm_forking_mixing_support:
*May 12 16:09:19.566: mars_flex_dsprm_current_codec_comp:DSP:0 FLEX Complexity Codec
*May 12 16:09:19.566: DSPWARE Version < 3.0 actual is 23.6.0
*May 12 16:09:19.570: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_HTSP_VOICE_CUT_THROUGH]fxols_proc_voice
*May 12 16:09:19.570: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_HTSP_VOICE_CUT_THROUGH]fxols_proc_voice
*May 12 16:09:27.930: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_HTSP_VOICE_CUT_THROUGH]fxols_proc_voice
*May 12 16:10:00.574: htsp_timer_stop3 htsp_release_req: cause 127, no_onhook 0
*May 12 16:10:00.582: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_HTSP_RELEASE_REQ]fxols_offhook_release
*May 12 16:10:00.586: htsp_timer_stop
*May 12 16:10:00.586: htsp_timer_stop2
*May 12 16:10:00.586: htsp_timer_stop3
*May 12 16:10:00.586: [0/0/1] set signal state = 0x4 timestamp = 0
*May 12 16:10:00.586: dsp_set_sig_state: [0/0/1] packet_len=12 channel_id=129 packet_id=39 state=0x4 timestamp=0x0
*May 12 16:10:00.586: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)
*May 12 16:10:00.586: htsp_timer - 2000 msec
*May 12 16:10:00.586: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_BUSY, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)
*May 12 16:10:00.590: flex_dsprm_close_cleanup
*May 12 16:10:00.854: htsp_process_event: [0/0/1, FXOLS_GUARD_OUT, E_DSP_SIG_0110]
*May 12 16:10:02.586: htsp_process_event: [0/0/1, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
*May 12 16:10:02.586: TGRM: reg_invoke_tgrm_call_update(0, 0, 1, 65535, 1, TGRM_CALL_IDLE, TGRM_CALL_VOICE, TGRM_DIRECTION_OUT)
*May 12 16:10:02.586: dsp_req_sig_state: [0/0/1] packet_len=8 channel_id=129 packet_id=40
*May 12 16:10:02.586: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0100]

Felipe Garrido · ‎05-17-2010

Julien,

The disconnect probably occurs because the two fax machines don't finish the training sequence correctly. One side will eventually time out and drop the call. This could be caused by multiple factors. The first being a misconfiguration on either one of the gateways.

But first, can you clarify the call flow. From the diagram, it looks like the call is being sent out an FXO on the 2811 and back in through a VG248 and then out to the PSTN. Is that correct? If so, what is between the VG248 and the "PSTN"? Is there another voice gateway involved? Why is the fax server not communicating directly with the PSTN?

Do any fax calls work? Is there different behavior on inbound calls?

We first need to straigthen out the call flow before diving into the configuration.

-Felipe

julienf28 · ‎05-17-2010

Sorry...here is the roadmap to how a call is being placed.

faxserver==h323==2811==fxo==vg248==CUCM==PSTN GW==PRI==PSTN=====Fax machine.

I've figured out that there was no Clock line on the controler and the 2811 was using the default dial-peer 0 instead the inbound dialpeer. the problem changed from dropping the call (or timeout) to Line is Busy and the fax server drops the call after 2 secons.

I did a debug isdn q931 and it showed me the following:
000084: *Feb 6 16:26:15.383: ISDN Se1/0:23 Q931: TX -> SETUP pd = 8 callref = 0x0221
        Bearer Capability i = 0x8090A2
                Standard = CCITT
                Transer Capability = Speech
                Transfer Mode = Circuit
                Transfer Rate = 64 kbit/s
        Channel ID i = 0xA98316
                Exclusive, Channel 22
        Calling Party Number i = 0x0081, '9055408208'
                Plan:Unknown, Type:Unknown
        Called Party Number i = 0x80, '16137883600'
                Plan:Unknown, Type:Unknown
000085: *Feb 6 16:26:15.483: ISDN Se1/0:23 Q931: RX <- CALL_PROC pd = 8 callref = 0x8221
        Channel ID i = 0xA98396
                Exclusive, Channel 22
HAMVGP01_3725#
000086: *Feb 6 16:26:17.179: ISDN Se1/0:23 Q931: TX -> DISCONNECT pd = 8 callref = 0x0221
        Cause i = 0x8090 - Normal call clearing
000087: *Feb 6 16:26:17.431: ISDN Se1/0:23 Q931: RX <- RELEASE pd = 8 callref = 0x8221
000088: *Feb 6 16:26:17.443: ISDN Se1/0:23 Q931: TX -> RELEASE_COMP pd = 8 callref = 0x0221
HAMVGP01_3725#term no mon
000089: *Feb 6 16:26:27.215: ISDN Se1/0:23 Q931: TX -> DISCONNECT pd = 8 callref = 0x838E
        Cause i = 0x8090 - Normal call clearing
000090: *Feb 6 16:26:27.331: ISDN Se1/0:23 Q931: RX <- RELEASE pd = 8 callref = 0x038E
000091: *Feb 6 16:26:27.343: ISDN Se1/0:23 Q931: TX -> RELEASE_COMP pd = 8 callref = 0x838E

Felipe Garrido · ‎05-17-2010

Julien,

I would suspect a signaling problem between the 2811 and vg248. Why not have the fax server talk directly with the PSTN gateway or CUCM? Is there a specific reason to send the call through the analog connection?

Can you collect the output of the following from the 2811.

debug voip ccapi inout

debug vpm signal

Please note the calling and called party number.

-Felipe

julienf28 · ‎05-17-2010

Attached is the debug vpm signal.

There were no option for the debug ccapi inout for some reason...weird.

Felipe Garrido · ‎05-17-2010

both debugs were in the file.

Failure occurs due to a codec mismatch between the fax server and this 2811.

*May 17 20:02:24.120: //282/7024CDB3355F/CCAPI/cc_api_call_disconnected:
Cause Value=65, Interface=0x46B71C78, Call Id=282

Check the codec configured under dial-peer voice 1 and verify that the fax server is configured to support it.