continue_on_fail triggered by NORMAL_CLEARING
We have a freeswitch box acting as a DR backup to the live system (called "freedom2" because that is what our vendor calls it). We are using continue_on_fail to catch conditions when the live system is down in order to forward it to a DR fifo. Occasionally (rarely) I'm getting a BYE back from the live system and the call is getting sent to DR and I can't figure out why this is happening. Would someone please take a glance at this and help me understand if I'm doing this wrong or if FreeSWITCH is misbehaving here? We are running FreeSWITCH Version 1.6.20+git~20180507T185611Z~43a9feb7f8~64bit (git 43a9feb 2018-05-07 18:56:11Z 64bit) /proc/version: Linux version 3.16.0-6-amd64 (debian-kernel@lists.debian.org) (gcc version 4.9.2 (Debian 4.9.2-10+deb8u1) ) #1 SMP Debian 3.16.56-1+deb8u1 (2018-05-08) /etc/debian_version: 8.10 Here is the dialplan in question: <extension name='freedom2 (default)' continue='false' priority='99'> <condition field='destination_number' expression='^\+?1?(\d+)$'> <action application="log" data="ALERT INBOUND ${sip_gateway} -> $1 -> freedom2"/> <action application="limit" data="hash inbound freedom2 38 freedomlimit$1"/> <action application="set" data="continue_on_fail=NORMAL_TEMPORARY_FAILURE,USER_BUSY,NO_ANSWER,NO_ROUTE_DESTINATION,UNALLOCATED_NUMBER"/> <action application="bridge" data="sofia/internal/$1@$${freedom2_trunk}"/> <action application="log" data="ALERT FREEDOM2 CALL FAILURE, SENDING $1 TO q1_dr_mode"/> <action application="set" data="route=q1_dr_mode"/> <action application="jitterbuffer" data="60"/> <action application="set" data="effective_caller_id_name=${custom_caller_name}"/> <action application="set" data="effective_caller_id_number=${custom_caller_id}"/> <action application="set" data="origination_caller_id_name=${custom_caller_name}"/> <action application="set" data="origination_caller_id_number=${custom_caller_id}"/> <action application="answer"/> <action application="playback" data="/dr/caller_preannounce.wav"/> <action application="set" data="fifo_chime_list=/dr/caller_preannounce.wav"/> <action application="set" data="fifo_chime_freq=30"/> <action application="set" data="fifo_music=$${hold_music}"/> <action application="fifo" data="q1 in"/> </condition> </extension> Here is an example of a call that got sent to the live system, even though the call appears to have ended in NORMAL_CLEARING. I started with the BYE packet back from the live system and cut it off at the point that the log application executes on the line after the bridge. I attempted to replace instances of public IP and phone #'s with placeholders. recv 361 bytes from udp/[$${freedom2_trunk}]:5060 at 11:50:43.514704: ------------------------------------------------------------------------ BYE sip:mod_sofia@$${freeswitch_ip}:5060 SIP/2.0 Via: SIP/2.0/UDP $${freedom2_trunk}:5060;branch=z9hG4bK707449280;rport From: <sip:${DID}@$${freedom2_trunk}>;tag=934960508 To: "${ANI}" <sip:${ANI}@$${freeswitch_ip}>;tag=FS9pD3eK574Sj Call-ID: 42db32d8-0220-1237-a8a1-02217f6f1b40 CSeq: 125455605 BYE Max-Forwards: 70 User-Agent: eConn 1.03 Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f6608004290): msg 0x7f6608061fc0 (361 bytes) from udp/$${freedom2_trunk}:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received BYE sip:mod_sofia@$${freeswitch_ip}:5060 SIP/2.0 (CSeq 125455605) nta.c:3248 agent_aliases() nta: canonizing sip:mod_sofia@$${freeswitch_ip}:5060 with contact nta.c:3060 agent_recv_request() nta: BYE (125455605) going to existing leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:271 nua_stack_event() nua(0x7f65fc01dcd0): event i_bye 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [NOTICE] sofia.c:1012 Hangup sofia/internal/${DID}@$${freedom2_trunk} [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:529 nua_signal() nua(0x7f65fc01dcd0): sent signal r_respond nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:529 nua_signal() nua(0x7f65fc01dcd0): sent signal r_destroy nua_stack.c:573 nua_stack_signal() nua(0x7f65fc01dcd0): recv signal r_respond 200 OK nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f6608074730, ...) called tport.c:3257 tport_tsend() tport_tsend(0x7f6608004290) tpn = UDP/$${freedom2_trunk}:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = $${freedom2_trunk}:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f6608004290): not found by name UDP/$${freedom2_trunk}:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f6608004290): 517 bytes of 517 to udp/$${freedom2_trunk}:5060 tport.c:3492 tport_send_msg() tport_vsend returned 517 send 517 bytes to udp/[$${freedom2_trunk}]:5060 at 11:50:43.534548: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP $${freedom2_trunk}:5060;branch=z9hG4bK707449280;rport=5060 From: <sip:${DID}@$${freedom2_trunk}>;tag=934960508 To: "${ANI}" <sip:${ANI}@$${freeswitch_ip}>;tag=FS9pD3eK574Sj Call-ID: 42db32d8-0220-1237-a8a1-02217f6f1b40 CSeq: 125455605 BYE User-Agent: FreeSWITCH-mod_sofia/1.6.20+git~20180507T185611Z~43a9feb7f8~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ nta.c:6791 incoming_reply() nta: sent 200 OK for BYE (125455605) nta.c:1350 set_timeout() nta: timer set to 32000 ms nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f65fc01dcd0): removing session usage nua_session.c:4139 signal_call_state_change() nua(0x7f65fc01dcd0): call state changed: ready -> terminated nua_stack.c:271 nua_stack_event() nua(0x7f65fc01dcd0): event i_state 200 Session Terminated nua_stack.c:271 nua_stack_event() nua(0x7f65fc01dcd0): event i_terminated 200 Session Terminated soa.c:356 soa_destroy() soa_destroy(static::0x7f6608074730) called nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f6608030530) nua_stack.c:569 nua_stack_signal() nua(0x7f65fc01dcd0): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/${DID}@ $${freedom2_trunk}] 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/${DID}@$${freedom2_trunk}) State EXCHANGE_MEDIA going to sleep 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/${DID}@$${freedom2_trunk}) Running State Change CS_HANGUP (Cur 2 Tot 455) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/${DID}@$${freedom2_trunk}) Callstate Change ACTIVE -> HANGUP 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/${DID}@$${freedom2_trunk}) State HANGUP 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] mod_sofia.c:438 Channel sofia/internal/${DID}@$${freedom2_trunk} hanging up, cause: NORMAL_CLEARING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:60 sofia/internal/${DID}@$${freedom2_trunk} Standard HANGUP, cause: NORMAL_CLEARING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/${DID}@$${freedom2_trunk}) State HANGUP going to sleep 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/${DID}@$${freedom2_trunk}) State Change CS_HANGUP -> CS_REPORTING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/${DID}@$${freedom2_trunk}) Running State Change CS_REPORTING (Cur 2 Tot 455) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/${DID}@$${freedom2_trunk}) State REPORTING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:174 sofia/internal/${DID}@$${freedom2_trunk} Standard REPORTING, cause: NORMAL_CLEARING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/${DID}@$${freedom2_trunk}) State REPORTING going to sleep 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/${DID}@$${freedom2_trunk}) State Change CS_REPORTING -> CS_DESTROY 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_session.c:1665 Session 455 (sofia/internal/${DID}@$${freedom2_trunk}) Locked, Waiting on external entities dea5af71-7a9d-4da0-b783-048dc5344a3d 2018-07-14 11:50:43.524096 [DEBUG] switch_ivr_bridge.c:706 sofia/internal/${DID}@$${freedom2_trunk} ending bridge by request from write function dea5af71-7a9d-4da0-b783-048dc5344a3d 2018-07-14 11:50:43.524096 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/external/${ANI}@ ${carrier_ip}] 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [NOTICE] switch_core_session.c:1683 Session 455 (sofia/internal/${DID}@$${freedom2_trunk}) Ended 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/${DID}@$${freedom2_trunk} [CS_DESTROY] dea5af71-7a9d-4da0-b783-048dc5344a3d EXECUTE sofia/external/${ANI}@${carrier_ip} log(ALERT FREEDOM2 CALL FAILURE, SENDING ${DID} TO q1_dr_mode) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/${DID}@$${freedom2_trunk}) Running State Change CS_DESTROY (Cur 1 Tot 455) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/${DID}@$${freedom2_trunk}) State DESTROY 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] mod_sofia.c:343 sofia/internal/${DID}@$${freedom2_trunk} SOFIA DESTROY dea5af71-7a9d-4da0-b783-048dc5344a3d 2018-07-14 11:50:43.524096 [ALERT] mod_dptools.c:1742 FREEDOM2 CALL FAILURE, SENDING ${DID} TO q1_dr_mode Royce Mitchell, IT Consultant ITAS Solutions royce3@itas-solutions.com
I switched to transfer_on_fail and that look like it might have fixed the problem. Waiting on volume testing to confirm. Royce Mitchell, IT Consultant ITAS Solutions royce3@itas-solutions.com On Sat, Jul 14, 2018 at 12:25 PM, Royce Mitchell III <royce3@gmail.com> wrote:
We have a freeswitch box acting as a DR backup to the live system (called "freedom2" because that is what our vendor calls it). We are using continue_on_fail to catch conditions when the live system is down in order to forward it to a DR fifo.
Occasionally (rarely) I'm getting a BYE back from the live system and the call is getting sent to DR and I can't figure out why this is happening. Would someone please take a glance at this and help me understand if I'm doing this wrong or if FreeSWITCH is misbehaving here?
We are running FreeSWITCH Version 1.6.20+git~20180507T185611Z~43a9feb7f8~64bit (git 43a9feb 2018-05-07 18:56:11Z 64bit)
/proc/version: Linux version 3.16.0-6-amd64 (debian-kernel@lists.debian. org) (gcc version 4.9.2 (Debian 4.9.2-10+deb8u1) ) #1 SMP Debian 3.16.56-1+deb8u1 (2018-05-08)
/etc/debian_version: 8.10
Here is the dialplan in question:
<extension name='freedom2 (default)' continue='false' priority='99'> <condition field='destination_number' expression='^\+?1?(\d+)$'> <action application="log" data="ALERT INBOUND ${sip_gateway} -> $1 -> freedom2"/> <action application="limit" data="hash inbound freedom2 38 freedomlimit$1"/> <action application="set" data="continue_on_fail=NORMAL_ TEMPORARY_FAILURE,USER_BUSY,NO_ANSWER,NO_ROUTE_DESTINATION,UNALLOCATED_ NUMBER"/> <action application="bridge" data="sofia/internal/$1@$${ freedom2_trunk}"/>
<action application="log" data="ALERT FREEDOM2 CALL FAILURE, SENDING $1 TO q1_dr_mode"/>
<action application="set" data="route=q1_dr_mode"/> <action application="jitterbuffer" data="60"/> <action application="set" data="effective_caller_id_ name=${custom_caller_name}"/> <action application="set" data="effective_caller_id_ number=${custom_caller_id}"/> <action application="set" data="origination_caller_id_ name=${custom_caller_name}"/> <action application="set" data="origination_caller_id_ number=${custom_caller_id}"/> <action application="answer"/> <action application="playback" data="/dr/caller_preannounce.wav"/> <action application="set" data="fifo_chime_list=/dr/ caller_preannounce.wav"/> <action application="set" data="fifo_chime_freq=30"/> <action application="set" data="fifo_music=$${hold_music}"/> <action application="fifo" data="q1 in"/> </condition> </extension>
Here is an example of a call that got sent to the live system, even though the call appears to have ended in NORMAL_CLEARING. I started with the BYE packet back from the live system and cut it off at the point that the log application executes on the line after the bridge.
I attempted to replace instances of public IP and phone #'s with placeholders.
recv 361 bytes from udp/[$${freedom2_trunk}]:5060 at 11:50:43.514704: ----------------------------------------------------------- ------------- BYE sip:mod_sofia@$${freeswitch_ip}:5060 SIP/2.0 Via: SIP/2.0/UDP $${freedom2_trunk}:5060;branch=z9hG4bK707449280;rport From: <sip:${DID}@$${freedom2_trunk}>;tag=934960508 To: "${ANI}" <sip:${ANI}@$${freeswitch_ip}>;tag=FS9pD3eK574Sj Call-ID: 42db32d8-0220-1237-a8a1-02217f6f1b40 CSeq: 125455605 BYE Max-Forwards: 70 User-Agent: eConn 1.03 Content-Length: 0
----------------------------------------------------------- ------------- tport.c:3023 tport_deliver() tport_deliver(0x7f6608004290): msg 0x7f6608061fc0 (361 bytes) from udp/$${freedom2_trunk}:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received BYE sip:mod_sofia@ $${freeswitch_ip}:5060 SIP/2.0 (CSeq 125455605) nta.c:3248 agent_aliases() nta: canonizing sip:mod_sofia@$${freeswitch_ip}:5060 with contact nta.c:3060 agent_recv_request() nta: BYE (125455605) going to existing leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:271 nua_stack_event() nua(0x7f65fc01dcd0): event i_bye 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [NOTICE] sofia.c:1012 Hangup sofia/internal/${DID}@$${freedom2_trunk} [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:529 nua_signal() nua(0x7f65fc01dcd0): sent signal r_respond nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:529 nua_signal() nua(0x7f65fc01dcd0): sent signal r_destroy nua_stack.c:573 nua_stack_signal() nua(0x7f65fc01dcd0): recv signal r_respond 200 OK nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f6608074730, ...) called tport.c:3257 tport_tsend() tport_tsend(0x7f6608004290) tpn = UDP/$${freedom2_trunk}:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = $${freedom2_trunk}:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f6608004290): not found by name UDP/$${freedom2_trunk}:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f6608004290): 517 bytes of 517 to udp/$${freedom2_trunk}:5060 tport.c:3492 tport_send_msg() tport_vsend returned 517 send 517 bytes to udp/[$${freedom2_trunk}]:5060 at 11:50:43.534548: ----------------------------------------------------------- ------------- SIP/2.0 200 OK Via: SIP/2.0/UDP $${freedom2_trunk}:5060;branch=z9hG4bK707449280;rport= 5060 From: <sip:${DID}@$${freedom2_trunk}>;tag=934960508 To: "${ANI}" <sip:${ANI}@$${freeswitch_ip}>;tag=FS9pD3eK574Sj Call-ID: 42db32d8-0220-1237-a8a1-02217f6f1b40 CSeq: 125455605 BYE User-Agent: FreeSWITCH-mod_sofia/1.6.20+git~20180507T185611Z~ 43a9feb7f8~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0
----------------------------------------------------------- ------------- nta.c:6791 incoming_reply() nta: sent 200 OK for BYE (125455605) nta.c:1350 set_timeout() nta: timer set to 32000 ms nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f65fc01dcd0): removing session usage nua_session.c:4139 signal_call_state_change() nua(0x7f65fc01dcd0): call state changed: ready -> terminated nua_stack.c:271 nua_stack_event() nua(0x7f65fc01dcd0): event i_state 200 Session Terminated nua_stack.c:271 nua_stack_event() nua(0x7f65fc01dcd0): event i_terminated 200 Session Terminated soa.c:356 soa_destroy() soa_destroy(static::0x7f6608074730) called nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f6608030530) nua_stack.c:569 nua_stack_signal() nua(0x7f65fc01dcd0): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/${DID}@$${ freedom2_trunk}] 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/${DID}@$${freedom2_trunk}) State EXCHANGE_MEDIA going to sleep 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/${DID}@$${freedom2_trunk}) Running State Change CS_HANGUP (Cur 2 Tot 455) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/${DID}@$${freedom2_trunk}) Callstate Change ACTIVE -> HANGUP 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/${DID}@$${freedom2_trunk}) State HANGUP 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] mod_sofia.c:438 Channel sofia/internal/${DID}@$${freedom2_trunk} hanging up, cause: NORMAL_CLEARING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:60 sofia/internal/${DID}@$${freedom2_trunk} Standard HANGUP, cause: NORMAL_CLEARING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/${DID}@$${freedom2_trunk}) State HANGUP going to sleep 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/${DID}@$${freedom2_trunk}) State Change CS_HANGUP -> CS_REPORTING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/${DID}@$${freedom2_trunk}) Running State Change CS_REPORTING (Cur 2 Tot 455) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/${DID}@$${freedom2_trunk}) State REPORTING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:174 sofia/internal/${DID}@$${freedom2_trunk} Standard REPORTING, cause: NORMAL_CLEARING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/${DID}@$${freedom2_trunk}) State REPORTING going to sleep 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/${DID}@$${freedom2_trunk}) State Change CS_REPORTING -> CS_DESTROY 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_session.c:1665 Session 455 (sofia/internal/${DID}@$${freedom2_trunk}) Locked, Waiting on external entities dea5af71-7a9d-4da0-b783-048dc5344a3d 2018-07-14 11:50:43.524096 [DEBUG] switch_ivr_bridge.c:706 sofia/internal/${DID}@$${freedom2_trunk} ending bridge by request from write function dea5af71-7a9d-4da0-b783-048dc5344a3d 2018-07-14 11:50:43.524096 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/external/${ANI}@${ carrier_ip}] 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [NOTICE] switch_core_session.c:1683 Session 455 (sofia/internal/${DID}@$${freedom2_trunk}) Ended 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/${DID}@$${freedom2_trunk} [CS_DESTROY] dea5af71-7a9d-4da0-b783-048dc5344a3d EXECUTE sofia/external/${ANI}@${carrier_ip} log(ALERT FREEDOM2 CALL FAILURE, SENDING ${DID} TO q1_dr_mode) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/${DID}@$${freedom2_trunk}) Running State Change CS_DESTROY (Cur 1 Tot 455) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/${DID}@$${freedom2_trunk}) State DESTROY 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] mod_sofia.c:343 sofia/internal/${DID}@$${freedom2_trunk} SOFIA DESTROY dea5af71-7a9d-4da0-b783-048dc5344a3d 2018-07-14 11:50:43.524096 [ALERT] mod_dptools.c:1742 FREEDOM2 CALL FAILURE, SENDING ${DID} TO q1_dr_mode
Royce Mitchell, IT Consultant ITAS Solutions royce3@itas-solutions.com
I think I finally identified the problem. I wasn't setting hangup_after_bridge=true If that's the case.... Is there any scenario where setting continue_on_fail=true and hangup_after_bridge=false makes sense? If not, would the FreeSWITCH be open to a patch that at least emits a WARNING when this scenario occurs Can the following page be modified to mention that you probably want to set hangup_after_bridge=true for this setting to take effect? https://freeswitch.org/confluence/display/FREESWITCH/continue_on_fail Royce Mitchell, IT Consultant ITAS Solutions royce3@itas-solutions.com On Tue, Jul 17, 2018 at 9:53 AM, Royce Mitchell III <royce3@gmail.com> wrote:
I switched to transfer_on_fail and that look like it might have fixed the problem. Waiting on volume testing to confirm.
Royce Mitchell, IT Consultant ITAS Solutions royce3@itas-solutions.com
On Sat, Jul 14, 2018 at 12:25 PM, Royce Mitchell III <royce3@gmail.com> wrote:
We have a freeswitch box acting as a DR backup to the live system (called "freedom2" because that is what our vendor calls it). We are using continue_on_fail to catch conditions when the live system is down in order to forward it to a DR fifo.
Occasionally (rarely) I'm getting a BYE back from the live system and the call is getting sent to DR and I can't figure out why this is happening. Would someone please take a glance at this and help me understand if I'm doing this wrong or if FreeSWITCH is misbehaving here?
We are running FreeSWITCH Version 1.6.20+git~20180507T185611Z~43a9feb7f8~64bit (git 43a9feb 2018-05-07 18:56:11Z 64bit)
/proc/version: Linux version 3.16.0-6-amd64 ( debian-kernel@lists.debian.org) (gcc version 4.9.2 (Debian 4.9.2-10+deb8u1) ) #1 SMP Debian 3.16.56-1+deb8u1 (2018-05-08)
/etc/debian_version: 8.10
Here is the dialplan in question:
<extension name='freedom2 (default)' continue='false' priority='99'> <condition field='destination_number' expression='^\+?1?(\d+)$'> <action application="log" data="ALERT INBOUND ${sip_gateway} -> $1 -> freedom2"/> <action application="limit" data="hash inbound freedom2 38 freedomlimit$1"/> <action application="set" data="continue_on_fail=NORMAL_ TEMPORARY_FAILURE,USER_BUSY,NO_ANSWER,NO_ROUTE_DESTINATION, UNALLOCATED_NUMBER"/> <action application="bridge" data="sofia/internal/$1@$${fre edom2_trunk}"/>
<action application="log" data="ALERT FREEDOM2 CALL FAILURE, SENDING $1 TO q1_dr_mode"/>
<action application="set" data="route=q1_dr_mode"/> <action application="jitterbuffer" data="60"/> <action application="set" data="effective_caller_id_name =${custom_caller_name}"/> <action application="set" data="effective_caller_id_numb er=${custom_caller_id}"/> <action application="set" data="origination_caller_id_na me=${custom_caller_name}"/> <action application="set" data="origination_caller_id_nu mber=${custom_caller_id}"/> <action application="answer"/> <action application="playback" data="/dr/caller_preannounce.wav"/> <action application="set" data="fifo_chime_list=/dr/call er_preannounce.wav"/> <action application="set" data="fifo_chime_freq=30"/> <action application="set" data="fifo_music=$${hold_music}"/> <action application="fifo" data="q1 in"/> </condition> </extension>
Here is an example of a call that got sent to the live system, even though the call appears to have ended in NORMAL_CLEARING. I started with the BYE packet back from the live system and cut it off at the point that the log application executes on the line after the bridge.
I attempted to replace instances of public IP and phone #'s with placeholders.
recv 361 bytes from udp/[$${freedom2_trunk}]:5060 at 11:50:43.514704: ----------------------------------------------------------- ------------- BYE sip:mod_sofia@$${freeswitch_ip}:5060 SIP/2.0 Via: SIP/2.0/UDP $${freedom2_trunk}:5060;branch=z9hG4bK707449280;rport From: <sip:${DID}@$${freedom2_trunk}>;tag=934960508 To: "${ANI}" <sip:${ANI}@$${freeswitch_ip}>;tag=FS9pD3eK574Sj Call-ID: 42db32d8-0220-1237-a8a1-02217f6f1b40 CSeq: 125455605 BYE Max-Forwards: 70 User-Agent: eConn 1.03 Content-Length: 0
----------------------------------------------------------- ------------- tport.c:3023 tport_deliver() tport_deliver(0x7f6608004290): msg 0x7f6608061fc0 (361 bytes) from udp/$${freedom2_trunk}:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received BYE sip:mod_sofia@ $${freeswitch_ip}:5060 SIP/2.0 (CSeq 125455605) nta.c:3248 agent_aliases() nta: canonizing sip:mod_sofia@$${freeswitch_ip}:5060 with contact nta.c:3060 agent_recv_request() nta: BYE (125455605) going to existing leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:271 nua_stack_event() nua(0x7f65fc01dcd0): event i_bye 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [NOTICE] sofia.c:1012 Hangup sofia/internal/${DID}@$${freedom2_trunk} [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:529 nua_signal() nua(0x7f65fc01dcd0): sent signal r_respond nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:529 nua_signal() nua(0x7f65fc01dcd0): sent signal r_destroy nua_stack.c:573 nua_stack_signal() nua(0x7f65fc01dcd0): recv signal r_respond 200 OK nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f6608074730, ...) called tport.c:3257 tport_tsend() tport_tsend(0x7f6608004290) tpn = UDP/$${freedom2_trunk}:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = $${freedom2_trunk}:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f6608004290): not found by name UDP/$${freedom2_trunk}:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f6608004290): 517 bytes of 517 to udp/$${freedom2_trunk}:5060 tport.c:3492 tport_send_msg() tport_vsend returned 517 send 517 bytes to udp/[$${freedom2_trunk}]:5060 at 11:50:43.534548: ----------------------------------------------------------- ------------- SIP/2.0 200 OK Via: SIP/2.0/UDP $${freedom2_trunk}:5060;branch =z9hG4bK707449280;rport=5060 From: <sip:${DID}@$${freedom2_trunk}>;tag=934960508 To: "${ANI}" <sip:${ANI}@$${freeswitch_ip}>;tag=FS9pD3eK574Sj Call-ID: 42db32d8-0220-1237-a8a1-02217f6f1b40 CSeq: 125455605 BYE User-Agent: FreeSWITCH-mod_sofia/1.6.20+gi t~20180507T185611Z~43a9feb7f8~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0
----------------------------------------------------------- ------------- nta.c:6791 incoming_reply() nta: sent 200 OK for BYE (125455605) nta.c:1350 set_timeout() nta: timer set to 32000 ms nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f65fc01dcd0): removing session usage nua_session.c:4139 signal_call_state_change() nua(0x7f65fc01dcd0): call state changed: ready -> terminated nua_stack.c:271 nua_stack_event() nua(0x7f65fc01dcd0): event i_state 200 Session Terminated nua_stack.c:271 nua_stack_event() nua(0x7f65fc01dcd0): event i_terminated 200 Session Terminated soa.c:356 soa_destroy() soa_destroy(static::0x7f6608074730) called nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f6608030530) nua_stack.c:569 nua_stack_signal() nua(0x7f65fc01dcd0): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/${DID}@$${free dom2_trunk}] 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/${DID}@$${freedom2_trunk}) State EXCHANGE_MEDIA going to sleep 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/${DID}@$${freedom2_trunk}) Running State Change CS_HANGUP (Cur 2 Tot 455) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/${DID}@$${freedom2_trunk}) Callstate Change ACTIVE -> HANGUP 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/${DID}@$${freedom2_trunk}) State HANGUP 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] mod_sofia.c:438 Channel sofia/internal/${DID}@$${freedom2_trunk} hanging up, cause: NORMAL_CLEARING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:60 sofia/internal/${DID}@$${freedom2_trunk} Standard HANGUP, cause: NORMAL_CLEARING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/${DID}@$${freedom2_trunk}) State HANGUP going to sleep 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/${DID}@$${freedom2_trunk}) State Change CS_HANGUP -> CS_REPORTING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/${DID}@$${freedom2_trunk}) Running State Change CS_REPORTING (Cur 2 Tot 455) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/${DID}@$${freedom2_trunk}) State REPORTING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:174 sofia/internal/${DID}@$${freedom2_trunk} Standard REPORTING, cause: NORMAL_CLEARING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/${DID}@$${freedom2_trunk}) State REPORTING going to sleep 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/${DID}@$${freedom2_trunk}) State Change CS_REPORTING -> CS_DESTROY 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_session.c:1665 Session 455 (sofia/internal/${DID}@$${freedom2_trunk}) Locked, Waiting on external entities dea5af71-7a9d-4da0-b783-048dc5344a3d 2018-07-14 11:50:43.524096 [DEBUG] switch_ivr_bridge.c:706 sofia/internal/${DID}@$${freedom2_trunk} ending bridge by request from write function dea5af71-7a9d-4da0-b783-048dc5344a3d 2018-07-14 11:50:43.524096 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/external/${ANI}@${carri er_ip}] 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [NOTICE] switch_core_session.c:1683 Session 455 (sofia/internal/${DID}@$${freedom2_trunk}) Ended 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/${DID}@$${freedom2_trunk} [CS_DESTROY] dea5af71-7a9d-4da0-b783-048dc5344a3d EXECUTE sofia/external/${ANI}@ ${carrier_ip} log(ALERT FREEDOM2 CALL FAILURE, SENDING ${DID} TO q1_dr_mode) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/${DID}@$${freedom2_trunk}) Running State Change CS_DESTROY (Cur 1 Tot 455) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/${DID}@$${freedom2_trunk}) State DESTROY 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] mod_sofia.c:343 sofia/internal/${DID}@$${freedom2_trunk} SOFIA DESTROY dea5af71-7a9d-4da0-b783-048dc5344a3d 2018-07-14 11:50:43.524096 [ALERT] mod_dptools.c:1742 FREEDOM2 CALL FAILURE, SENDING ${DID} TO q1_dr_mode
Royce Mitchell, IT Consultant ITAS Solutions royce3@itas-solutions.com
Hi, You also need to set hangup_after_bridge=true Best Regards, -- Vallimamod Abdullah SIP Solutions github.com/vma/esl <http://github.com/vma/esl> linkedin.com/in/vallimamod .
On 14 Jul 2018, at 19:25, Royce Mitchell III <royce3@gmail.com <mailto:royce3@gmail.com>> wrote:
We have a freeswitch box acting as a DR backup to the live system (called "freedom2" because that is what our vendor calls it). We are using continue_on_fail to catch conditions when the live system is down in order to forward it to a DR fifo.
Occasionally (rarely) I'm getting a BYE back from the live system and the call is getting sent to DR and I can't figure out why this is happening. Would someone please take a glance at this and help me understand if I'm doing this wrong or if FreeSWITCH is misbehaving here?
We are running FreeSWITCH Version 1.6.20+git~20180507T185611Z~43a9feb7f8~64bit (git 43a9feb 2018-05-07 18:56:11Z 64bit)
/proc/version: Linux version 3.16.0-6-amd64 (debian-kernel@lists.debian.org <mailto:debian-kernel@lists.debian.org>) (gcc version 4.9.2 (Debian 4.9.2-10+deb8u1) ) #1 SMP Debian 3.16.56-1+deb8u1 (2018-05-08)
/etc/debian_version: 8.10
Here is the dialplan in question:
<extension name='freedom2 (default)' continue='false' priority='99'> <condition field='destination_number' expression='^\+?1?(\d+)$'> <action application="log" data="ALERT INBOUND ${sip_gateway} -> $1 -> freedom2"/> <action application="limit" data="hash inbound freedom2 38 freedomlimit$1"/> <action application="set" data="continue_on_fail=NORMAL_TEMPORARY_FAILURE,USER_BUSY,NO_ANSWER,NO_ROUTE_DESTINATION,UNALLOCATED_NUMBER"/> <action application="bridge" data="sofia/internal/$1@$${freedom2_trunk}"/>
<action application="log" data="ALERT FREEDOM2 CALL FAILURE, SENDING $1 TO q1_dr_mode"/>
<action application="set" data="route=q1_dr_mode"/> <action application="jitterbuffer" data="60"/> <action application="set" data="effective_caller_id_name=${custom_caller_name}"/> <action application="set" data="effective_caller_id_number=${custom_caller_id}"/> <action application="set" data="origination_caller_id_name=${custom_caller_name}"/> <action application="set" data="origination_caller_id_number=${custom_caller_id}"/> <action application="answer"/> <action application="playback" data="/dr/caller_preannounce.wav"/> <action application="set" data="fifo_chime_list=/dr/caller_preannounce.wav"/> <action application="set" data="fifo_chime_freq=30"/> <action application="set" data="fifo_music=$${hold_music}"/> <action application="fifo" data="q1 in"/> </condition> </extension>
Here is an example of a call that got sent to the live system, even though the call appears to have ended in NORMAL_CLEARING. I started with the BYE packet back from the live system and cut it off at the point that the log application executes on the line after the bridge.
I attempted to replace instances of public IP and phone #'s with placeholders.
recv 361 bytes from udp/[$${freedom2_trunk}]:5060 at 11:50:43.514704: ------------------------------------------------------------------------ BYE sip:mod_sofia@$${freeswitch_ip}:5060 <sip:mod_sofia@$${freeswitch_ip}:5060> SIP/2.0 Via: SIP/2.0/UDP $${freedom2_trunk}:5060;branch=z9hG4bK707449280;rport From: <sip:${DID}@$${freedom2_trunk} <sip:${DID}@$${freedom2_trunk}>>;tag=934960508 To: "${ANI}" <sip:${ANI}@$${freeswitch_ip} <sip:${ANI}@$${freeswitch_ip}>>;tag=FS9pD3eK574Sj Call-ID: 42db32d8-0220-1237-a8a1-02217f6f1b40 CSeq: 125455605 BYE Max-Forwards: 70 User-Agent: eConn 1.03 Content-Length: 0
------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f6608004290): msg 0x7f6608061fc0 (361 bytes) from udp/$${freedom2_trunk}:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received BYE sip:mod_sofia@$${freeswitch_ip}:5060 <sip:mod_sofia@$${freeswitch_ip}:5060> SIP/2.0 (CSeq 125455605) nta.c:3248 agent_aliases() nta: canonizing sip:mod_sofia@$${freeswitch_ip}:5060 <sip:mod_sofia@$${freeswitch_ip}:5060> with contact nta.c:3060 agent_recv_request() nta: BYE (125455605) going to existing leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:271 nua_stack_event() nua(0x7f65fc01dcd0): event i_bye 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [NOTICE] sofia.c:1012 Hangup sofia/internal/${DID}@$${freedom2_trunk} [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:529 nua_signal() nua(0x7f65fc01dcd0): sent signal r_respond nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:529 nua_signal() nua(0x7f65fc01dcd0): sent signal r_destroy nua_stack.c:573 nua_stack_signal() nua(0x7f65fc01dcd0): recv signal r_respond 200 OK nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f6608074730, ...) called tport.c:3257 tport_tsend() tport_tsend(0x7f6608004290) tpn = UDP/$${freedom2_trunk}:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = $${freedom2_trunk}:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f6608004290): not found by name UDP/$${freedom2_trunk}:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f6608004290): 517 bytes of 517 to udp/$${freedom2_trunk}:5060 tport.c:3492 tport_send_msg() tport_vsend returned 517 send 517 bytes to udp/[$${freedom2_trunk}]:5060 at 11:50:43.534548: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP $${freedom2_trunk}:5060;branch=z9hG4bK707449280;rport=5060 From: <sip:${DID}@$${freedom2_trunk} <sip:${DID}@$${freedom2_trunk}>>;tag=934960508 To: "${ANI}" <sip:${ANI}@$${freeswitch_ip} <sip:${ANI}@$${freeswitch_ip}>>;tag=FS9pD3eK574Sj Call-ID: 42db32d8-0220-1237-a8a1-02217f6f1b40 CSeq: 125455605 BYE User-Agent: FreeSWITCH-mod_sofia/1.6.20+git~20180507T185611Z~43a9feb7f8~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0
------------------------------------------------------------------------ nta.c:6791 incoming_reply() nta: sent 200 OK for BYE (125455605) nta.c:1350 set_timeout() nta: timer set to 32000 ms nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f65fc01dcd0): removing session usage nua_session.c:4139 signal_call_state_change() nua(0x7f65fc01dcd0): call state changed: ready -> terminated nua_stack.c:271 nua_stack_event() nua(0x7f65fc01dcd0): event i_state 200 Session Terminated nua_stack.c:271 nua_stack_event() nua(0x7f65fc01dcd0): event i_terminated 200 Session Terminated soa.c:356 soa_destroy() soa_destroy(static::0x7f6608074730) called nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f6608030530) nua_stack.c:569 nua_stack_signal() nua(0x7f65fc01dcd0): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/${DID}@$${freedom2_trunk}] 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/${DID}@$${freedom2_trunk}) State EXCHANGE_MEDIA going to sleep 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/${DID}@$${freedom2_trunk}) Running State Change CS_HANGUP (Cur 2 Tot 455) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/${DID}@$${freedom2_trunk}) Callstate Change ACTIVE -> HANGUP 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/${DID}@$${freedom2_trunk}) State HANGUP 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] mod_sofia.c:438 Channel sofia/internal/${DID}@$${freedom2_trunk} hanging up, cause: NORMAL_CLEARING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:60 sofia/internal/${DID}@$${freedom2_trunk} Standard HANGUP, cause: NORMAL_CLEARING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/${DID}@$${freedom2_trunk}) State HANGUP going to sleep 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/${DID}@$${freedom2_trunk}) State Change CS_HANGUP -> CS_REPORTING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/${DID}@$${freedom2_trunk}) Running State Change CS_REPORTING (Cur 2 Tot 455) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/${DID}@$${freedom2_trunk}) State REPORTING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:174 sofia/internal/${DID}@$${freedom2_trunk} Standard REPORTING, cause: NORMAL_CLEARING 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/${DID}@$${freedom2_trunk}) State REPORTING going to sleep 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/${DID}@$${freedom2_trunk}) State Change CS_REPORTING -> CS_DESTROY 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_session.c:1665 Session 455 (sofia/internal/${DID}@$${freedom2_trunk}) Locked, Waiting on external entities dea5af71-7a9d-4da0-b783-048dc5344a3d 2018-07-14 11:50:43.524096 [DEBUG] switch_ivr_bridge.c:706 sofia/internal/${DID}@$${freedom2_trunk} ending bridge by request from write function dea5af71-7a9d-4da0-b783-048dc5344a3d 2018-07-14 11:50:43.524096 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/external/${ANI}@${carrier_ip}] 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [NOTICE] switch_core_session.c:1683 Session 455 (sofia/internal/${DID}@$${freedom2_trunk}) Ended 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/${DID}@$${freedom2_trunk} [CS_DESTROY] dea5af71-7a9d-4da0-b783-048dc5344a3d EXECUTE sofia/external/${ANI}@${carrier_ip} log(ALERT FREEDOM2 CALL FAILURE, SENDING ${DID} TO q1_dr_mode) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/${DID}@$${freedom2_trunk}) Running State Change CS_DESTROY (Cur 1 Tot 455) 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/${DID}@$${freedom2_trunk}) State DESTROY 3a6ef51f-e02e-42d3-ab91-34fcc7e5bd60 2018-07-14 11:50:43.524096 [DEBUG] mod_sofia.c:343 sofia/internal/${DID}@$${freedom2_trunk} SOFIA DESTROY dea5af71-7a9d-4da0-b783-048dc5344a3d 2018-07-14 11:50:43.524096 [ALERT] mod_dptools.c:1742 FREEDOM2 CALL FAILURE, SENDING ${DID} TO q1_dr_mode
Royce Mitchell, IT Consultant ITAS Solutions royce3@itas-solutions.com <mailto:royce3@itas-solutions.com>_________________________________________________________________________ Professional FreeSWITCH Services sales@freeswitch.com <mailto:sales@freeswitch.com> https://freeswitch.com
Official FreeSWITCH Sites https://freeswitch.com/oss https://freeswitch.org/confluence https://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 https://freeswitch.com
participants (2)
-
Royce Mitchell III
-
Vallimamod Abdullah