[Freeswitch-users] Strange RXFAX Delay - Hangup Hook

Tim Bowyer timbo at timbo.net.au
Tue Aug 14 00:13:41 UTC 2018 

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 at 7f9729cbe5af> show channels

0 total.

----------------------------
Dialplan as follows
----------------------------

<?xml version="1.0" encoding="UTF-8" standalone="no"?>
<document type="freeswitch/xml">
  <section name="dialplan" description="Incoming Fax">
    <context name="public">
      <extension name="Fax{{ destination_number }}">
        <condition field="destination_number" expression="^({{ destination_number }})$">
           <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<file:///$%7bfax_result_$........................cut>
           <action application="answer" />
                   <action application="playback" data="silence_stream://2000"/>
           {% if subscription.verbose_logging %}
           <action application="set" data="fax_verbose=true"/>
           {% endif %}
                   <action application="set" data="fax_enable_t38_request=true"/>
                   <action application="set" data="fax_enable_t38=true"/>
                                                                   <action application="set" data="fax_ident={{ subscription.rendered_fax_ident }}"/>
                   <action application="set" data="fax_header={{ subscription.rendered_fax_header }}"/>
                   <action application="rxfax" data="/tmp/{{ uuid }}.tif"/>
                   <action application="hangup"/>
       </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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx> Restore previous codec PCMA:8.
EXECUTE sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx> hangup()
2018-08-13 05:41:39.127583 [NOTICE] mod_dptools.c:1286 Hangup sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx> [CS_EXECUTE] [NORMAL_CLEARING]
2018-08-13 05:41:39.127583 [DEBUG] switch_core_session.c:2815 sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) State HANGUP
2018-08-13 05:41:39.127583 [DEBUG] mod_sofia.c:438 Channel sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>
2018-08-13 05:41:39.127583 [DEBUG] switch_core_state_machine.c:60 sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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
OK
Attempting to convert
Updating fax status: http://api:8000/fax/update
OK
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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) Ended
2018-08-08 10:33:54.207573 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx> [CS_DESTROY]
2018-08-08 10:39:01.707631 [NOTICE] switch_channel.c:1104 New Channel sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>!
2018-08-08 10:39:01.787568 [NOTICE] mod_dptools.c:1312 Channel [sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx] has been answered
2018-08-08 10:39:48.487606 [NOTICE] mod_dptools.c:1286 Hangup sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) Ended
2018-08-08 10:40:19.608111 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx> [CS_DESTROY]
2018-08-09 09:51:59.127574 [NOTICE] switch_channel.c:1104 New Channel sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>!
2018-08-09 09:51:59.207595 [NOTICE] mod_dptools.c:1312 Channel [sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx] has been answered
2018-08-09 09:52:46.007578 [NOTICE] mod_dptools.c:1286 Hangup sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) Ended
2018-08-09 09:53:17.807983 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx> [CS_DESTROY]
2018-08-13 05:40:52.187572 [NOTICE] switch_channel.c:1104 New Channel sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>!
2018-08-13 05:40:52.307599 [NOTICE] mod_dptools.c:1312 Channel [sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx] has been answered
2018-08-13 05:41:39.127583 [NOTICE] mod_dptools.c:1286 Hangup sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx> [CS_EXECUTE] [NORMAL_CLEARING]
3.32.124.126 [CS_EXECUTE] [NORMAL_CLEARING]
2018-08-08 10:33:54.207573 [NOTICE] switch_core_session.c:1683 Session 65 (sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) Ended
2018-08-08 10:33:54.207573 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx> [CS_DESTROY]
2018-08-08 10:39:01.707631 [NOTICE] switch_channel.c:1104 New Channel sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>!
2018-08-08 10:39:01.787568 [NOTICE] mod_dptools.c:1312 Channel [sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx] has been answered
2018-08-08 10:39:48.487606 [NOTICE] mod_dptools.c:1286 Hangup sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) Ended
2018-08-08 10:40:19.608111 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx> [CS_DESTROY]
2018-08-09 09:51:59.127574 [NOTICE] switch_channel.c:1104 New Channel sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>!
2018-08-09 09:51:59.207595 [NOTICE] mod_dptools.c:1312 Channel [sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx] has been answered
2018-08-09 09:52:46.007578 [NOTICE] mod_dptools.c:1286 Hangup sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) Ended
2018-08-09 09:53:17.807983 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx> [CS_DESTROY]
2018-08-13 05:40:52.187572 [NOTICE] switch_channel.c:1104 New Channel sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 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 at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>!
2018-08-13 05:40:52.307599 [NOTICE] mod_dptools.c:1312 Channel [sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx] has been answered
2018-08-13 05:41:39.127583 [NOTICE] mod_dptools.c:1286 Hangup sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx> [CS_EXECUTE] [NORMAL_CLEARING]
2018-08-13 05:42:10.847595 [DEBUG] switch_core_state_machine.c:619 (sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) State Change CS_HANGUP -> CS_REPORTING
2018-08-13 05:42:10.847595 [DEBUG] switch_core_state_machine.c:584 (sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) Running State Change CS_REPORTING (Cur 1 Tot 68)
2018-08-13 05:42:10.847595 [DEBUG] switch_core_state_machine.c:938 (sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) State REPORTING
2018-08-13 05:42:10.847595 [DEBUG] switch_core_state_machine.c:174 sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx> Standard REPORTING, cause: NORMAL_CLEARING
2018-08-13 05:42:10.847595 [DEBUG] switch_core_state_machine.c:938 (sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) State REPORTING going to sleep
2018-08-13 05:42:10.847595 [DEBUG] switch_core_state_machine.c:610 (sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) State Change CS_REPORTING -> CS_DESTROY
2018-08-13 05:42:10.847595 [DEBUG] switch_core_session.c:1665 Session 68 (sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) Locked, Waiting on external entities
2018-08-13 05:42:10.847595 [NOTICE] switch_core_session.c:1683 Session 68 (sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) Ended
2018-08-13 05:42:10.847595 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx> [CS_DESTROY]
2018-08-13 05:42:10.847595 [DEBUG] switch_core_state_machine.c:741 (sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) Running State Change CS_DESTROY (Cur 0 Tot 68)
2018-08-13 05:42:10.847595 [DEBUG] switch_core_state_machine.c:751 (sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) State DESTROY
2018-08-13 05:42:10.847595 [DEBUG] mod_sofia.c:343 sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx> SOFIA DESTROY
2018-08-13 05:42:10.847595 [DEBUG] switch_core_state_machine.c:181 sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx> Standard DESTROY
2018-08-13 05:42:10.847595 [DEBUG] switch_core_state_machine.c:751 (sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx<mailto:sofia/external/61XXXXXXXXX at 2xx.xx.xxx.xxx>) State DESTROY going to sleep


Cheers,

Tim



-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20180814/d9ce1d98/attachment-0001.html>

More information about the FreeSWITCH-users mailing list