Strange RXFAX Delay - Hangup Hook
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"?> <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 <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@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 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@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 2018-08-13 05:41:39.127583 [NOTICE] mod_dptools.c:1286 Hangup sofia/external/61XXXXXXXXX@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@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 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:42:10.847595 [DEBUG] switch_core_state_machine.c:619 (sofia/external/61XXXXXXXXX@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@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@2xx.xx.xxx.xxx) State REPORTING 2018-08-13 05:42:10.847595 [DEBUG] switch_core_state_machine.c:174 sofia/external/61XXXXXXXXX@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@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@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@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@2xx.xx.xxx.xxx) Ended 2018-08-13 05:42:10.847595 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx [CS_DESTROY] 2018-08-13 05:42:10.847595 [DEBUG] switch_core_state_machine.c:741 (sofia/external/61XXXXXXXXX@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@2xx.xx.xxx.xxx) State DESTROY 2018-08-13 05:42:10.847595 [DEBUG] mod_sofia.c:343 sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx SOFIA DESTROY 2018-08-13 05:42:10.847595 [DEBUG] switch_core_state_machine.c:181 sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx Standard DESTROY 2018-08-13 05:42:10.847595 [DEBUG] switch_core_state_machine.c:751 (sofia/external/61XXXXXXXXX@2xx.xx.xxx.xxx) State DESTROY going to sleep Cheers, Tim
participants (1)
-
Tim Bowyer