Hi All,

Have been pulling my hair out trying to work out why we’re getting a strange delay upon completion of a t38 fax using rxfax.

Upon finishing the receiving of a fax, and sending BYE to the originator, freeswitch seems to keep the channel open for exactly 30 seconds then tries to issue another hangup.

Have tried all sorts of things in dialplan, including moving the answer to before the hangup hook – I prefer the answer to be post hangup hook to aid in hunting to different servers in case of API call failures.

What’s also weird, 30 seconds after rxfax completes there are debug entries for time stamps in the CLI from calls in the past?!@

If I do a show channels at idle – there are 0 total

freeswitch@7f9729cbe5af> show channels

0 total.

----------------------------

Dialplan as follows

----------------------------

<?xml version="1.0" encoding="UTF-8" standalone="no"?>

<action application="set" data="api_hangup_hook=system /data/python/process_fax.py {{ uuid }} /tmp/{{ uuid }}.tif {{ formats }} --caller {{ caller }} --fax_result_code \\\${fax_result_$........................cut

{% if subscription.verbose_logging %}

{% endif %}

</condition>

</extension>

</context>

</section>

</document>

----------------------------

Debug logs

----------------------------

2018-08-13 05:41:39.127583 [DEBUG] mod_spandsp_fax.c:496 ==============================================================================

2018-08-13 05:41:39.127583 [DEBUG] mod_spandsp_fax.c:502 Fax successfully received.

2018-08-13 05:41:39.127583 [DEBUG] mod_spandsp_fax.c:526 ==============================================================================

2018-08-13 05:41:39.127583 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T FAX exchange complete

2018-08-13 05:41:39.127583 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Call completed

2018-08-13 05:41:39.127583 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state CALL_FINISHED

2018-08-13 05:41:39.127583 [DEBUG] switch_core_codec.c:248 sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx Restore previous codec PCMA:8.

EXECUTE sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx hangup()

2018-08-13 05:41:39.127583 [NOTICE] mod_dptools.c:1286 Hangup sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx [CS_EXECUTE] [NORMAL_CLEARING]

2018-08-13 05:41:39.127583 [DEBUG] switch_core_session.c:2815 sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)

2018-08-13 05:41:39.127583 [DEBUG] switch_core_state_machine.c:650 (sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx) State EXECUTE going to sleep

2018-08-13 05:41:39.127583 [DEBUG] switch_core_state_machine.c:584 (sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx) Running State Change CS_HANGUP (Cur 1 Tot 68)

2018-08-13 05:41:39.127583 [DEBUG] switch_core_state_machine.c:850 (sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx) Callstate Change ACTIVE -> HANGUP

2018-08-13 05:41:39.127583 [DEBUG] switch_core_state_machine.c:852 (sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx) State HANGUP

2018-08-13 05:41:39.127583 [DEBUG] mod_sofia.c:438 Channel sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx hanging up, cause: NORMAL_CLEARING

>> here’s the BYE

2018-08-13 05:41:39.127583 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx

2018-08-13 05:41:39.127583 [DEBUG] switch_core_state_machine.c:60 sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx Standard HANGUP, cause: NORMAL_CLEARING

2018-08-13 05:41:39.127583 [DEBUG] switch_core_state_machine.c:852 (sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx) State HANGUP going to sleep

>> 30 second delay???

2018-08-13 05:42:10.847595 [DEBUG] switch_core_state_machine.c:783 Hangup Command with Session system(/data/python/process_fax.py 4407e217-a0bb-4e04-a185-b2e42c6e36ff /tmp/4407e217-a0bb-4e04-a185-b2e42c6e36ff.tif --pdf --pdf --caller 61XXXXXXXXX --fax_result_code 0 --fax_result_text 'OK' --fax_remote_station_id '' --fax_document_total_pages 2 --fax_document_transferred_pages 2 --fax_image_resolution '8040x3850' --fax_image_size 37216 --fax_success 1 --fax_v17_disabled 0 --t38_gateway_format '' --t38_peer '' --fax_transfer_rate 14400 --t38_trace_read ''):

Fax host is api:8000

Fax host scheme is http

{'fax_document_total_pages': '2', 't38_gateway_format': '', 't38_trace_read': '', 't38_peer': '', 'fax_image_resolution': '8040x3850', 'fax_result_text': 'OK', 'fax_v17_disabled': '0', 'caller': '61XXXXXXXXX', 'fax_remote_station_id': '', 'fax_result_code': '0', 'fax_document_transferred_pages': '2', 'fax_image_size': '37216', 'fax_transfer_rate': '14400'}

Updating fax status: http://api:8000/fax/update

Attempting to convert

Updating fax status: http://api:8000/fax/update

Uploading fax files: http://api:8000/fax/upload

{'tiff': <open file '/tmp/4407e217-a0bb-4e04-a185-b2e42c6e36ff.tif', mode 'rb' at 0x7fb570877e40>, 'pdf': <open file '/tmp/3f8e90cc-5b01-4d82-8674-18227449b9c0.pdf', mode 'rb' at 0x7fb570877ed0>}

3.32.124.126 [CS_EXECUTE] [NORMAL_CLEARING]

> > Notices for calls which completed in the past??

2018-08-08 10:33:54.207573 [NOTICE] switch_core_session.c:1683 Session 65 (sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx) Ended

2018-08-08 10:33:54.207573 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx [CS_DESTROY]

2018-08-08 10:39:01.707631 [NOTICE] switch_channel.c:1104 New Channel sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx [9a93cb39-1f2b-4ce2-bfc3-5feee3c9fa01]

2018-08-08 10:39:01.707631 [INFO] mod_dialplan_xml.c:637 Processing 61XXXXXXXXX <61XXXXXXXXX>->61XXXXXXXXX in context public

2018-08-08 10:39:01.787568 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx!

2018-08-08 10:39:01.787568 [NOTICE] mod_dptools.c:1312 Channel [sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx] has been answered

2018-08-08 10:39:48.487606 [NOTICE] mod_dptools.c:1286 Hangup sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx [CS_EXECUTE] [NORMAL_CLEARING]

2018-08-08 10:40:19.608111 [NOTICE] switch_core_session.c:1683 Session 66 (sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx) Ended

2018-08-08 10:40:19.608111 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx [CS_DESTROY]

2018-08-09 09:51:59.127574 [NOTICE] switch_channel.c:1104 New Channel sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx [33f5c499-20e6-4a29-a6f6-daa90b6d35dc]

2018-08-09 09:51:59.127574 [INFO] mod_dialplan_xml.c:637 Processing 61XXXXXXXXX <61XXXXXXXXX>->61XXXXXXXXX in context public

2018-08-09 09:51:59.207595 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx!

2018-08-09 09:51:59.207595 [NOTICE] mod_dptools.c:1312 Channel [sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx] has been answered

2018-08-09 09:52:46.007578 [NOTICE] mod_dptools.c:1286 Hangup sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx [CS_EXECUTE] [NORMAL_CLEARING]

2018-08-09 09:53:17.807983 [NOTICE] switch_core_session.c:1683 Session 67 (sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx) Ended

2018-08-09 09:53:17.807983 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx [CS_DESTROY]

2018-08-13 05:40:52.187572 [NOTICE] switch_channel.c:1104 New Channel sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx [4407e217-a0bb-4e04-a185-b2e42c6e36ff]

2018-08-13 05:40:52.187572 [INFO] mod_dialplan_xml.c:637 Processing 61XXXXXXXXX <61XXXXXXXXX>->61XXXXXXXXX in context public

2018-08-13 05:40:52.307599 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx!

2018-08-13 05:40:52.307599 [NOTICE] mod_dptools.c:1312 Channel [sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx] has been answered