[Freeswitch-users] continue_on_fail triggered by NORMAL_CLEARING

Royce Mitchell III royce3 at gmail.com
Tue Jul 17 14:53:54 UTC 2018


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 at itas-solutions.com

On Sat, Jul 14, 2018 at 12:25 PM, Royce Mitchell III <royce3 at 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 at 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 at itas-solutions.com
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20180717/114920ad/attachment-0001.html>


More information about the FreeSWITCH-users mailing list