Here is a log when the call drops in Phase D after having received 4 pages!

I am seeing this for the first time that call is dropping in Phase D. I think I could fix this, if someone could throw a pointer or two my way. Should I look into mod_spandsp_fax.c or can this be done elsewhere?

f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:52.024887 [DEBUG] mod_spandsp_fax.c:428 ==== Page Received ===========================================================
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:52.024887 [DEBUG] mod_spandsp_fax.c:429 Page no = 4
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:52.024887 [DEBUG] mod_spandsp_fax.c:430 Image size = 1728 x 999 pixels
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:52.024887 [DEBUG] mod_spandsp_fax.c:431 Image resolution = 8031/m x 3850/m
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:52.024887 [DEBUG] mod_spandsp_fax.c:432 Compression = T.6 (3)
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:52.024887 [DEBUG] mod_spandsp_fax.c:433 Compressed image size = 22935 bytes
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:52.024887 [DEBUG] mod_spandsp_fax.c:434 Bad rows = 0
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:52.024887 [DEBUG] mod_spandsp_fax.c:435 Longest bad row run = 0
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:52.024887 [DEBUG] mod_spandsp_fax.c:436 ==============================================================================
2012-03-26 22:02:52.024887 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Changing from state 13 to 14
2012-03-26 22:02:52.024887 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Tx:  MCF with final frame tag
2012-03-26 22:02:52.024887 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Tx:  ff 13 8c
2012-03-26 22:02:52.084891 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier down (-1) in state 14
2012-03-26 22:02:52.084891 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Changing from phase T30_PHASE_D_RX to T30_PHASE_D_TX
2012-03-26 22:02:52.084891 [DEBUG] mod_spandsp_fax.c:286 FLOW FAX Set rx type 0
2012-03-26 22:02:52.084891 [DEBUG] mod_spandsp_fax.c:286 FLOW FAX Set tx type 4
2012-03-26 22:02:53.144909 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 14
2012-03-26 22:02:53.224929 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 14
2012-03-26 22:02:53.224929 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Changing from phase T30_PHASE_D_TX to T30_PHASE_D_RX
2012-03-26 22:02:53.224929 [DEBUG] mod_spandsp_fax.c:286 FLOW FAX Set rx type 4
2012-03-26 22:02:53.224929 [DEBUG] mod_spandsp_fax.c:286 FLOW FAX Set tx type 0
2012-03-26 22:02:53.224929 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Start T4
2012-03-26 22:02:54.384927 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier up (-2) in state 14
2012-03-26 22:02:54.584907 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Framing OK (-6) in state 14
2012-03-26 22:02:54.584907 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Start T4A
2012-03-26 22:02:55.604879 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Bad HDLC CRC received
2012-03-26 22:02:55.604879 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Bad CRC and timer is 7
2012-03-26 22:02:55.664879 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier down (-1) in state 14
2012-03-26 22:02:55.664879 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Start T4B
2012-03-26 22:02:55.684877 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier up (-2) in state 14
2012-03-26 22:02:55.684877 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Stop T4B (1440 remaining)
2012-03-26 22:02:55.704878 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier down (-1) in state 14
2012-03-26 22:02:55.704878 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Start T4B
2012-03-26 22:02:55.844910 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier up (-2) in state 14
2012-03-26 22:02:55.844910 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Stop T4B (480 remaining)
2012-03-26 22:02:55.844910 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier down (-1) in state 14
2012-03-26 22:02:55.844910 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Start T4B
2012-03-26 22:02:56.024878 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 T4B expired in phase T30_PHASE_D_RX, state 14. The line is now quiet.
2012-03-26 22:02:56.024878 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 T4 expired in phase T30_PHASE_D_RX, state 14
2012-03-26 22:02:56.024878 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Retry number 2
2012-03-26 22:02:56.024878 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Repeat command called with nothing to repeat - phase T30_PHASE_D_RX, state 14
2012-03-26 22:02:56.264924 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier up (-2) in state 14
2012-03-26 22:02:56.284900 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier down (-1) in state 14
2012-03-26 22:02:56.804883 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier up (-2) in state 14
2012-03-26 22:02:56.824909 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier down (-1) in state 14
2012-03-26 22:02:56.864878 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier up (-2) in state 14
2012-03-26 22:02:56.864878 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier down (-1) in state 14
2012-03-26 22:02:56.964906 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier up (-2) in state 14
2012-03-26 22:02:56.984901 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier down (-1) in state 14
2012-03-26 22:02:57.084900 [DEBUG] ftmod_libpri.c:1065 -- Hangup REQ on channel 4:1
2012-03-26 22:02:57.084900 [DEBUG] ftmod_libpri.c:1078 [s4c1][4:1] Changed state from UP to TERMINATING
2012-03-26 22:02:57.084900 [DEBUG] ftdm_state.c:511 [s4c1][4:1] Executing state processor for TERMINATING
2012-03-26 22:02:57.084900 [DEBUG] ftmod_libpri.c:679 -- 4:1 STATE [TERMINATING]
2012-03-26 22:02:57.084900 [DEBUG] ftmod_libpri.c:687 [s4c1][4:1] Completed state change from UP to TERMINATING in 0ms
2012-03-26 22:02:57.084900 [DEBUG] ftdm_io.c:5586 [s4c1][4:1] Scheduling safety hangup timer
2012-03-26 22:02:57.084900 [DEBUG] mod_freetdm.c:2416 got clear channel sig [STOP]
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.084900 [DEBUG] switch_channel.c:2848 (FreeTDM/4:1/47615101) Callstate Change ACTIVE -> HANGUP
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.084900 [NOTICE] mod_freetdm.c:2441 Hangup FreeTDM/4:1/47615101 [CS_EXECUTE] [NORMAL_CLEARING]
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.084900 [DEBUG] switch_channel.c:2871 Send signal FreeTDM/4:1/47615101 [KILL]
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.084900 [DEBUG] switch_core_session.c:1180 Send signal FreeTDM/4:1/47615101 [BREAK]
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.104898 [DEBUG] mod_spandsp_fax.c:491 ==============================================================================
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.104898 [DEBUG] mod_spandsp_fax.c:504 Fax processing not successful - result (49) The call dropped prematurely.
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.104898 [DEBUG] mod_spandsp_fax.c:509 Remote station id: 05322405354
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.104898 [DEBUG] mod_spandsp_fax.c:510 Local station id:  Sangoma Fax Ident
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.104898 [DEBUG] mod_spandsp_fax.c:511 Pages transferred: 4
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.104898 [DEBUG] mod_spandsp_fax.c:513 Total fax pages:   4
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.104898 [DEBUG] mod_spandsp_fax.c:514 Image resolution:  8031x3850
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.104898 [DEBUG] mod_spandsp_fax.c:515 Transfer Rate:     4800
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.104898 [DEBUG] mod_spandsp_fax.c:517 ECM status         on
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.104898 [DEBUG] mod_spandsp_fax.c:518 remote country:
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.104898 [DEBUG] mod_spandsp_fax.c:519 remote vendor:
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.104898 [DEBUG] mod_spandsp_fax.c:520 remote model:
f1a680ea-7760-11e1-b0ea-b3286880c45b 2012-03-26 22:02:57.104898 [DEBUG] mod_spandsp_fax.c:522 ==============================================================================
2012-03-26 22:02:57.104898 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Changing from state 14 to 32
2012-03-26 22:02:57.104898 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Changing from phase T30_PHASE_D_RX to T30_PHASE_CALL_FINISHED







regards,
Anita



On Tue, Mar 27, 2012 at 12:54 AM, Anita Hall <anita.hall@simmortel.com> wrote:
Hi

The dialplan just sends the control to a python script over ESL which gives rxfax(filename.tiff)

I have tried giving the rxfax() command in the dialplan itself with similar results. Many calls drop prematuresly and a good many fail to receive DCS after permitted retries.


regards,
Anita




On Sat, Mar 24, 2012 at 9:24 PM, Anton Kvashenkin <anton.jugatsu@gmail.com> wrote:

Can you show dialplan snippet.

24.03.2012 19:24 пользователь "Anita Hall" <anita.hall@simmortel.com> написал:
Hi

My client had been using an old torrenta cards which game problems with pretty much everything :) After evangelizing the cause of Sangoma for more than 3 months (yes, they are dumb), they are finally making the transition so I am pretty excited. The choice of card is A108D which does a whole bunch of DSP in the hardware.

Now, the first hurdle that I have to make Sangoma jump across is getting incoming Fax over E1 right. We are using mod_spandsp, of course. So, here I will be needing a whole lot of help from the veterans of spandsp and Faxing :) I desperately need Sangoma to pass the Fax test or they will give me torrenta cards all over again!

The primary cause of failures are - (49) The call dropped prematurely and (48) Disconnected after permitted retries.

For example, in this case, can I conclude that the other end did not provide a Fax tone or is it something else?

2aeb5f7c-75b5-11e1-8f36-b3286880c45b EXECUTE FreeTDM/4:2/47615728 rxfax(/srv/fax/in/2aeb5f7c-75b5-11e1-8f36-b3286880c45b.tiff)
2aeb5f7c-75b5-11e1-8f36-b3286880c45b 2012-03-24 18:57:57.824906 [DEBUG] mod_spandsp_fax.c:1357 Raw read codec activation Success L16 20000
2aeb5f7c-75b5-11e1-8f36-b3286880c45b 2012-03-24 18:57:57.824906 [DEBUG] switch_core_codec.c:216 FreeTDM/4:2/47615728 Push codec L16:70
2aeb5f7c-75b5-11e1-8f36-b3286880c45b 2012-03-24 18:57:57.824906 [DEBUG] mod_spandsp_fax.c:1373 Raw write codec activation Success L16
2012-03-24 18:57:57.844876 [DEBUG] ftmod_wanpipe.c:965 [s4c2][4:2] First packet read stats: Rx queue len: 1, Rx queue size: 10
2012-03-24 18:57:57.904879 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2012-03-24 18:57:57.924878 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2012-03-24 18:57:58.104877 [DEBUG] ftmod_wanpipe.c:901 [s4c2][4:2] First packet write stats: Tx queue len: 1, Tx queue size: 5, Tx idle: 30
2012-03-24 18:57:58.444908 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2012-03-24 18:57:58.644907 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2012-03-24 18:57:58.664878 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier up (-2) in state 1
2012-03-24 18:57:58.764879 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2012-03-24 18:57:58.764879 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2012-03-24 18:57:58.784878 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2012-03-24 18:57:58.804879 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2012-03-24 18:57:59.244886 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier up (-2) in state 17
2012-03-24 18:57:59.464887 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 HDLC signal status is Carrier down (-1) in state 17
2012-03-24 18:57:59.564903 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 T4 expired in phase T30_PHASE_B_RX, state 17
2012-03-24 18:57:59.564903 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Retry number 1
2012-03-24 18:57:59.564903 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Changing from phase T30_PHASE_B_RX to T30_PHASE_B_TX
2012-03-24 18:57:59.564903 [DEBUG] mod_spandsp_fax.c:286 FLOW FAX Set rx type 0
2012-03-24 18:57:59.564903 [DEBUG] mod_spandsp_fax.c:286 FLOW FAX Set tx type 4
2012-03-24 18:57:59.564903 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Sending ident 'Sangoma Fax Ident'
2012-03-24 18:57:59.564903 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Tx:  CSI without final frame tag
2012-03-24 18:57:59.564903 [DEBUG] mod_spandsp_fax.c:286 FLOW T.30 Tx:  ff 03 40 74 6e 65 64 49 20 78 61 46 20 61 6d 6f 67 6e 61 53 20 20 20
2012-03-24 18:58:00.524877 [DEBUG] ftmod_libpri.c:1065 -- Hangup REQ on channel 4:1
2012-03-24 18:58:00.524877 [DEBUG] ftmod_libpri.c:1078 [s4c1][4:1] Changed state from UP to TERMINATING
2012-03-24 18:58:00.524877 [DEBUG] ftdm_state.c:511 [s4c1][4:1] Executing state processor for TERMINATING


I will need some more hand-holding with logs later :)


regards,
Anita


_________________________________________________________________________
Professional FreeSWITCH Consulting Services:
consulting@freeswitch.org
http://www.freeswitchsolutions.com

FreeSWITCH-powered IP PBX: The CudaTel Communication Server
http://www.cudatel.com

Official FreeSWITCH Sites
http://www.freeswitch.org
http://wiki.freeswitch.org
http://www.cluecon.com

FreeSWITCH-users mailing list
FreeSWITCH-users@lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org


_________________________________________________________________________
Professional FreeSWITCH Consulting Services:
consulting@freeswitch.org
http://www.freeswitchsolutions.com

FreeSWITCH-powered IP PBX: The CudaTel Communication Server
http://www.cudatel.com

Official FreeSWITCH Sites
http://www.freeswitch.org
http://wiki.freeswitch.org
http://www.cluecon.com

FreeSWITCH-users mailing list
FreeSWITCH-users@lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org