[Freeswitch-users] Fax on Sangoma

Tue Mar 27 01:14:46 MSD 2012

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 at 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 at gmail.com
> > wrote:
>
>> Can you show dialplan snippet.
>> 24.03.2012 19:24 пользователь "Anita Hall" <anita.hall at 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 at freeswitch.org
>>> http://www.freeswitchsolutions.com
>>>
>>> 
>>> 
>>>
>>> Official FreeSWITCH Sites
>>> http://www.freeswitch.org
>>> http://wiki.freeswitch.org
>>> http://www.cluecon.com
>>>
>>> FreeSWITCH-users mailing list
>>> FreeSWITCH-users at 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 at freeswitch.org
>> http://www.freeswitchsolutions.com
>>
>> 
>> 
>>
>> Official FreeSWITCH Sites
>> http://www.freeswitch.org
>> http://wiki.freeswitch.org
>> http://www.cluecon.com
>>
>> FreeSWITCH-users mailing list
>> FreeSWITCH-users at lists.freeswitch.org
>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>> http://www.freeswitch.org
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20120327/05a644fe/attachment-0001.html 