hi,
    I have successfully installed freeswitch and it is working fine while calling from one sip device to other.
but I face problem when I make a outbound call using gateway.

According to freeswitch log I can see that freeswitch is getting gateway configuration and it is suppose to send INVITE to the gateway,but the problem is that freeswitch is not sending any INVITE to the gateway.

these are the fs_cli logs

    INVITE sip:+918146234576@sip.test.com SIP/2.0
       Record-Route: <sip:88.80.160.31;lr=on;ftag=
aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz>
       Via: SIP/2.0/UDP 88.80.160.31;branch=z9hG4bKd602.9af44717.0
       Via: SIP/2.0/UDP 112.196.33.74:11220;rport=62926;branch=z9hG4bKPj.w0giarvUkQ67HPw3uK5Z6NsdtAUWvEV
       From: <sip:user1@sip.test.com>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
       To: <sip:+918146234576@sip.test.com>
       Contact: <sip:user1@112.196.33.74:62926;ob>
       Call-ID: 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
       CSeq: 26826 INVITE
       Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
       Supported: replaces, 100rel, timer, norefersub
       Session-Expires: 1800
       Min-SE: 90
       User-Agent: CSipSimple_A89-15/r2330
       Proxy-Authorization: Digest username="user1", realm="sip.test.com", nonce="2da67792-9ddb-11e3-ae8b-69d00812b6c2", uri="sip:+918146234576@sip.test.com", response="894cfec80fc7a1c04b2ad7b46eb1c4c5", algorithm=MD5, cnonce="y6HH8DROqT9Ue8iZVcHNFRyB.LGnEDII", qop=auth, nc=00000001
       Content-Type: application/sdp
       Content-Length:   344
       X-AUTH-IP: 112.196.33.74
      
       v=0
       o=- 3602293864 3602293864 IN IP4 112.196.33.74
       s=pjmedia
       c=IN IP4 112.196.33.74
       t=0 0
       m=audio 4226 RTP/AVP 99 0 8 101
       c=IN IP4 112.196.33.74
       a=rtcp:9246 IN IP4 112.196.33.74
       a=sendrecv
       a=rtpmap:99 SILK/24000
       a=fmtp:99 useinbandfec=0
       a=rtpmap:0 PCMU/8000
       a=rtpmap:8 PCMA/8000
       a=rtpmap:101 telephone-event/8000
       a=fmtp:101 0-15
       ------------------------------------------------------------------------
    send 469 bytes to udp/[88.80.160.31]:5060 at 05:10:44.257584:
       ------------------------------------------------------------------------
       SIP/2.0 100 Trying
       Via: SIP/2.0/UDP 88.80.160.31;branch=z9hG4bKd602.9af44717.0
       Via: SIP/2.0/UDP 112.196.33.74:11220;rport=62926;branch=z9hG4bKPj.w0giarvUkQ67HPw3uK5Z6NsdtAUWvEV
       Record-Route: <sip:88.80.160.31;lr=on;ftag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz>
       From: <sip:user1@sip.test.com>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
       To: <sip:+918146234576@sip.test.com>
       Call-ID: 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
       CSeq: 26826 INVITE
       User-Agent: 2600hz
       Content-Length: 0
      
       ------------------------------------------------------------------------
    2014-02-25 00:10:44.243689 [DEBUG] sofia.c:1937 Re-attaching to session 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
    2014-02-25 00:10:44.243689 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
    2014-02-25 00:10:44.243689 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
    2014-02-25 00:10:44.263688 [DEBUG] sofia.c:8156 1 acls to check for proxy
    2014-02-25 00:10:44.263688 [DEBUG] sofia.c:8161 checking 88.80.160.31 against acl authoritative
    2014-02-25 00:10:44.263688 [INFO] sofia.c:8163 88.80.160.31 is a proxy according to the authoritative acl
    2014-02-25 00:10:44.263688 [DEBUG] sofia.c:8173 network ip is a proxy
    2014-02-25 00:10:44.263688 [DEBUG] sofia.c:8177 found auth ip [X-AUTH-IP] header of [112.196.33.74]
    2014-02-25 00:10:44.263688 [DEBUG] sofia.c:8201 IP 88.80.160.31 Rejected by acl "trusted". Falling back to Digest auth.
    2014-02-25 00:10:44.263688 [DEBUG] kazoo_fetch_agent.c:216 Sending directory XML request (2dc8752c-9ddb-11e3-ae8c-69d00812b6c2) to ecallmgr@kaz2.test.nl <2.1184.0>
    2014-02-25 00:10:44.263688 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecallmgr@kaz2.test.nl <2.1184.0>
    2014-02-25 00:10:44.383689 [DEBUG] kazoo_fetch_agent.c:277 Received directory XML (2dc8752c-9ddb-11e3-ae8c-69d00812b6c2) after 120ms: <document type="freeswitch/xml"><section name="directory"><domain name="sip.test.com"><user id="user1"><variables><variable name="ecallmgr_Inception" value="on-net"/><variable name="ecallmgr_Authorizing-Type" value="device"/><variable name="ecallmgr_Authorizing-ID" value="3b46b4ceec6bb18dd8985792d7b5693e"/><variable name="ecallmgr_Account-ID" value="502cc62fa8097dd6d753fea7c7ef91a1"/><variable name="ecallmgr_Realm" value="sip.test.com"/><variable name="ecallmgr_Username" value="user1"/></variables><params><param name="password" value="user1"/></params></user></domain></section></document>
    2014-02-25 00:10:44.383689 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/user1@sip.test.com entering state [received][100]
    2014-02-25 00:10:44.383689 [DEBUG] sofia.c:5899 Remote SDP:
    v=0
    o=- 3602293864 3602293864 IN IP4 112.196.33.74
    s=pjmedia
    c=IN IP4 112.196.33.74
    t=0 0
    m=audio 4226 RTP/AVP 99 0 8 101
    c=IN IP4 112.196.33.74
    a=rtpmap:99 SILK/24000
    a=fmtp:99 useinbandfec=0
    a=rtpmap:0 PCMU/8000
    a=rtpmap:8 PCMA/8000
    a=rtpmap:101 telephone-event/8000
    a=fmtp:101 0-15
    a=rtcp:9246 IN IP4 112.196.33.74

    2014-02-25 00:10:44.383689 [DEBUG] sofia.c:6144 (sofia/sipinterface_1/user1@sip.test.com) State Change CS_NEW -> CS_INIT
    2014-02-25 00:10:44.383689 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
    2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/user1@sip.test.com) Running State Change CS_INIT
    2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:507 (sofia/sipinterface_1/user1@sip.test.com) State INIT
    2014-02-25 00:10:44.383689 [DEBUG] mod_sofia.c:87 sofia/sipinterface_1/user1@sip.test.com SOFIA INIT
    2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/user1@sip.test.com Standard INIT
    2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/user1@sip.test.com) State Change CS_INIT -> CS_ROUTING
    2014-02-25 00:10:44.383689 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
    2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:507 (sofia/sipinterface_1/user1@sip.test.com) State INIT going to sleep
    2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/user1@sip.test.com) Running State Change CS_ROUTING
    2014-02-25 00:10:44.383689 [DEBUG] switch_channel.c:2179 (sofia/sipinterface_1/user1@sip.test.com) Callstate Change DOWN -> RINGING
    2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/user1@sip.test.com) State ROUTING
    2014-02-25 00:10:44.383689 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/user1@sip.test.com SOFIA ROUTING
    2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:164 sofia/sipinterface_1/user1@sip.test.com Standard ROUTING
    2014-02-25 00:10:44.383689 [INFO] mod_dialplan_xml.c:558 Processing user1 <user1>->+918146234576 in context context_2
    2014-02-25 00:10:44.383689 [DEBUG] kazoo_fetch_agent.c:216 Sending dialplan XML request (2ddb9918-9ddb-11e3-ae8e-69d00812b6c2) to ecallmgr@kaz2.test.nl <2.1185.0>
    2014-02-25 00:10:44.403683 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecallmgr@kaz2.test.nl <2.1185.0>
    2014-02-25 00:10:44.543689 [DEBUG] kazoo_fetch_agent.c:277 Received dialplan XML (2ddb9918-9ddb-11e3-ae8e-69d00812b6c2) after 160ms: <document type="freeswitch/xml"><section name="dialplan" description="Route Park Response"><context name="context_2"><extension name="park"><condition><action application="log" data="NOTICE log|${uuid}|ecallmgr@kaz2.test.nl won call control"/><action application="export" data="ecallmgr_Ecallmgr-Node=ecallmgr@kaz2.test.nl"/><condition field="variable_ecallmgr_Bridge-ID" expression="^$"><action application="export" data="ecallmgr_Bridge-ID=${UUID}"/></condition><action application="set" data="ringback=%(2000,4000,440,480)"/><action application="set" data="transfer_ringback=%(2000,4000,440,480)"/><action application="park"/></condition></extension></context></section></document>
    Dialplan: sofia/sipinterface_1/user1@sip.test.com parsing [context_2->park] continue=false
    |--- Dialplan: Processing recursive conditions level:1 [park_recur_1] require-nested=TRUE
    |--- Dialplan: sofia/sipinterface_1/user1@sip.test.com Regex (PASS) [park_recur_1] variable_ecallmgr_Bridge-ID() =~ /^$/ break=on-false
    |--- Dialplan: sofia/sipinterface_1/user1@sip.test.com Action export(ecallmgr_Bridge-ID=${UUID})
    Dialplan: sofia/sipinterface_1/user1@sip.test.com Absolute Condition [park]
    Dialplan: sofia/sipinterface_1/user1@sip.test.com Action log(NOTICE log|${uuid}|ecallmgr@kaz2.test.nl won call control)
    Dialplan: sofia/sipinterface_1/user1@sip.test.com Action export(ecallmgr_Ecallmgr-Node=ecallmgr@kaz2.test.nl)
    Dialplan: sofia/sipinterface_1/user1@sip.test.com Action set(ringback=%(2000,4000,440,480))
    Dialplan: sofia/sipinterface_1/user1@sip.test.com Action set(transfer_ringback=%(2000,4000,440,480))
    Dialplan: sofia/sipinterface_1/user1@sip.test.com Action park()
    2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:214 (sofia/sipinterface_1/user1@sip.test.com) State Change CS_ROUTING -> CS_EXECUTE
    2014-02-25 00:10:44.543689 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
    2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/user1@sip.test.com) State ROUTING going to sleep
    2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/user1@sip.test.com) Running State Change CS_EXECUTE
    2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:530 (sofia/sipinterface_1/user1@sip.test.com) State EXECUTE
    2014-02-25 00:10:44.543689 [DEBUG] mod_sofia.c:178 sofia/sipinterface_1/user1@sip.test.com SOFIA EXECUTE
    2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:256 sofia/sipinterface_1/user1@sip.test.com Standard EXECUTE
    EXECUTE sofia/sipinterface_1/user1@sip.test.com export(ecallmgr_Bridge-ID=0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO)
    2014-02-25 00:10:44.543689 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [ecallmgr_Bridge-ID]=[0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO]
    EXECUTE sofia/sipinterface_1/user1@sip.test.com log(NOTICE log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|ecallmgr@kaz2.test.nl won call control)
    2014-02-25 00:10:44.543689 [NOTICE] mod_dptools.c:1634 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|ecallmgr@kaz2.test.nl won call control
    EXECUTE sofia/sipinterface_1/user1@sip.test.com export(ecallmgr_Ecallmgr-Node=ecallmgr@kaz2.test.nl)
    2014-02-25 00:10:44.543689 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [ecallmgr_Ecallmgr-Node]=[ecallmgr@kaz2.test.nl]
    EXECUTE sofia/sipinterface_1/user1@sip.test.com set(ringback=%(2000,4000,440,480))
    2014-02-25 00:10:44.543689 [DEBUG] mod_dptools.c:1402 sofia/sipinterface_1/user1@sip.test.com SET [ringback]=[%(2000,4000,440,480)]
    EXECUTE sofia/sipinterface_1/user1@sip.test.com set(transfer_ringback=%(2000,4000,440,480))
    2014-02-25 00:10:44.543689 [DEBUG] mod_dptools.c:1402 sofia/sipinterface_1/user1@sip.test.com SET [transfer_ringback]=[%(2000,4000,440,480)]
    EXECUTE sofia/sipinterface_1/user1@sip.test.com park()
    2014-02-25 00:10:44.543689 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecallmgr@kaz2.test.nl <2.11883.4>
    2014-02-25 00:10:44.563813 [INFO] kazoo_node.c:627 exec: uuid_setvar_multi(0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO ecallmgr_Channel-Authorized=true;ecallmgr_Account-ID=502cc62fa8097dd6d753fea7c7ef91a1)
    2014-02-25 00:10:44.563813 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecallmgr@kaz2.test.nl <2.11883.4>
    2014-02-25 00:10:44.723684 [INFO] kazoo_node.c:627 exec: uuid_setvar_multi(0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO effective_caller_id_name=Martin;effective_caller_id_number=+xxxxxxxxxxx;ecallmgr_Channel-Authorized=true;ecallmgr_Username=user1;ecallmgr_Realm=sip.test.com;ecallmgr_Account-ID=502cc62fa8097dd6d753fea7c7ef91a1;ecallmgr_Authorizing-ID=3b46b4ceec6bb18dd8985792d7b5693e;ecallmgr_Authorizing-Type=device;ecallmgr_Inception=on-net;ecallmgr_Fetch-ID=2ddb9918-9ddb-11e3-ae8e-69d00812b6c2)
    2014-02-25 00:10:44.723684 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecallmgr@kaz2.test.nl <2.11912.4>
    freeswitch@internal>
    2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: set ignore_display_updates=true
    2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: set continue_on_fail=true
    2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: export sip_redirect_context=context_2
    2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: bridge {ignore_display_updates='true',ecallmgr_Account-ID='502cc62fa8097dd6d753fea7c7ef91a1',ecallmgr_Reseller-ID='cf9c1c7b7a5d5894bc0c0fbc9420c403',effective_caller_id_number='+xxxxxxxxxxx',effective_caller_id_name='Martin',origination_caller_id_number='+xxxxxxxxxxx',origination_caller_id_name='Martin',ignore_early_media='false',local_var_clobber='true'}[sip_auth_password='xxxxxxxxxxxx',sip_auth_username='xxxxxxxxxxx',ecallmgr_Global-Resource='false',ecallmgr_Resource-ID='b50436c83efa77bb94e1241c872fa7c0',absolute_codec_string='^^:PCMU:PCMA:G722:G7221@16000h:G7221@32000h',leg_progress_timeout='60',effective_callee_id_number='+918146234576',effective_callee_id_name='918146234576']sofia/sipinterface_1/+918146234576@sip.sipnl.net
    2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: event Event-Name=CUSTOM,Event-Subclass=whistle::masquerade,whistle_event_name=CHANNEL_EXECUTE_COMPLETE,whistle_application_name=bridge
    2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: park
    2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:305 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|transfered call to xferext extension
    2014-02-25 00:10:45.043686 [DEBUG] switch_core_session.c:1183 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
    2014-02-25 00:10:45.043686 [DEBUG] switch_channel.c:3098 (sofia/sipinterface_1/user1@sip.test.com) State Change CS_EXECUTE -> CS_ROUTING
    2014-02-25 00:10:45.043686 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
    2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:530 (sofia/sipinterface_1/user1@sip.test.com) State EXECUTE going to sleep
    2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/user1@sip.test.com) Running State Change CS_ROUTING
    2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/user1@sip.test.com) State ROUTING
    2014-02-25 00:10:45.063687 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/user1@sip.test.com SOFIA ROUTING
    2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:164 sofia/sipinterface_1/user1@sip.test.com Standard ROUTING
    2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:184 (sofia/sipinterface_1/user1@sip.test.com) State Change CS_ROUTING -> CS_EXECUTE
    2014-02-25 00:10:45.063687 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
    2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/user1@sip.test.com) State ROUTING going to sleep
    2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/user1@sip.test.com) Running State Change CS_EXECUTE
    2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:530 (sofia/sipinterface_1/user1@sip.test.com) State EXECUTE
    2014-02-25 00:10:45.063687 [DEBUG] mod_sofia.c:178 sofia/sipinterface_1/user1@sip.test.com SOFIA EXECUTE
    2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:256 sofia/sipinterface_1/user1@sip.test.com Standard EXECUTE
    EXECUTE sofia/sipinterface_1/user1@sip.test.com set(ignore_display_updates=true)
    2014-02-25 00:10:45.063687 [DEBUG] mod_dptools.c:1402 sofia/sipinterface_1/user1@sip.test.com SET [ignore_display_updates]=[true]
    EXECUTE sofia/sipinterface_1/user1@sip.test.com set(continue_on_fail=true)
    2014-02-25 00:10:45.063687 [DEBUG] mod_dptools.c:1402 sofia/sipinterface_1/user1@sip.test.com SET [continue_on_fail]=[true]
    EXECUTE sofia/sipinterface_1/user1@sip.test.com export(sip_redirect_context=context_2)
    2014-02-25 00:10:45.063687 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [sip_redirect_context]=[context_2]
    EXECUTE sofia/sipinterface_1/user1@sip.test.com bridge({ignore_display_updates='true',ecallmgr_Account-ID='502cc62fa8097dd6d753fea7c7ef91a1',ecallmgr_Reseller-ID='cf9c1c7b7a5d5894bc0c0fbc9420c403',effective_caller_id_number='+xxxxxxxxxxx',effective_caller_id_name='Martin',origination_caller_id_number='+xxxxxxxxxxx',origination_caller_id_name='Martin',ignore_early_media='false',local_var_clobber='true'}[sip_auth_password='xxxxxxxxxxxx',sip_auth_username='xxxxxxxxxxx',ecallmgr_Global-Resource='false',ecallmgr_Resource-ID='b50436c83efa77bb94e1241c872fa7c0',absolute_codec_string='^^:PCMU:PCMA:G722:G7221@16000h:G7221@32000h',leg_progress_timeout='60',effective_callee_id_number='+918146234576',effective_callee_id_name='918146234576']sofia/sipinterface_1/+918146234576@sip.sipnl.net)
    2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/user1@sip.test.com EXPORTING[export_vars] [ecallmgr_Bridge-ID]=[0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO] to event
    2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/user1@sip.test.com EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[ecallmgr@kaz2.test.nl] to event
    2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/user1@sip.test.com EXPORTING[export_vars] [sip_redirect_context]=[context_2] to event
    2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:2071 Parsing global variables
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [ignore_display_updates]=[true]
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [ecallmgr_Account-ID]=[502cc62fa8097dd6d753fea7c7ef91a1]
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [ecallmgr_Reseller-ID]=[cf9c1c7b7a5d5894bc0c0fbc9420c403]
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [effective_caller_id_number]=[+xxxxxxxxxxx]
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [effective_caller_id_name]=[Martin]
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [origination_caller_id_number]=[+xxxxxxxxxxx]
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [origination_caller_id_name]=[Martin]
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [ignore_early_media]=[false]
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [local_var_clobber]=[true]
    2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:2518 Parsing session specific variables
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [sip_auth_password]=[xxxxxxxxxxxx]
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [sip_auth_username]=[xxxxxxxxxxx]
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [ecallmgr_Global-Resource]=[false]
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [ecallmgr_Resource-ID]=[b50436c83efa77bb94e1241c872fa7c0]
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [absolute_codec_string]=[^^:PCMU:PCMA:G722:G7221@16000h:G7221@32000h]
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [leg_progress_timeout]=[60]
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [effective_callee_id_number]=[+918146234576]
    2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [effective_callee_id_name]=[918146234576]
    2014-02-25 00:10:45.083685 [NOTICE] switch_channel.c:1055 New Channel sofia/sipinterface_1/+918146234576@sip.sipnl.net [2e446736-9ddb-11e3-ae9b-69d00812b6c2]
    2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:4456 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State Change CS_NEW -> CS_INIT
    2014-02-25 00:10:45.083685 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/+918146234576@sip.sipnl.net [BREAK]
    2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:2821 sofia/sipinterface_1/+918146234576@sip.sipnl.net Setting leg progress timeout to 60
    2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) Running State Change CS_INIT
    2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:507 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State INIT
    2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:87 sofia/sipinterface_1/+918146234576@sip.sipnl.net SOFIA INIT
    2014-02-25 00:10:45.083685 [INFO] switch_nat.c:590 NAT port mapping disabled
    2014-02-25 00:10:45.083685 [DEBUG] sofia_glue.c:1225 Local SDP:
    v=0
    o=FreeSWITCH 1393277355 1393277356 IN IP4 31.220.27.158
    s=FreeSWITCH
    c=IN IP4 31.220.27.158
    t=0 0
    m=audio 27690 RTP/AVP 0 8 9 98 99 101 13
    a=rtpmap:98 G7221/16000
    a=fmtp:98 bitrate=32000
    a=rtpmap:99 G7221/32000
    a=fmtp:99 bitrate=48000
    a=rtpmap:101 telephone-event/8000
    a=fmtp:101 0-16
    a=ptime:20
    a=sendrecv

    2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/+918146234576@sip.sipnl.net Standard INIT
    2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State Change CS_INIT -> CS_ROUTING
    2014-02-25 00:10:45.083685 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/+918146234576@sip.sipnl.net [BREAK]
    2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:507 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State INIT going to sleep
    2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) Running State Change CS_ROUTING
    2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State ROUTING
    2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/+918146234576@sip.sipnl.net SOFIA ROUTING
    2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:67 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State Change CS_ROUTING -> CS_CONSUME_MEDIA
    2014-02-25 00:10:45.083685 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/+918146234576@sip.sipnl.net [BREAK]
    2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State ROUTING going to sleep
    2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) Running State Change CS_CONSUME_MEDIA
    2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:542 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State CONSUME_MEDIA
    2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:542 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State CONSUME_MEDIA going to sleep
    2014-02-25 00:10:45.083685 [INFO] kazoo_node.c:627 exec: uuid_setvar_multi(2e446736-9ddb-11e3-ae9b-69d00812b6c2 ecallmgr_Channel-Authorized=true;ecallmgr_Global-Resource=false;ecallmgr_Reseller-ID=cf9c1c7b7a5d5894bc0c0fbc9420c403;ecallmgr_Account-ID=502cc62fa8097dd6d753fea7c7ef91a1)
    2014-02-25 00:10:45.083685 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecallmgr@kaz2.test.nl <2.11955.4>
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+918146234576@sip.sipnl.net [BREAK]
    2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/+918146234576@sip.sipnl.net entering state [calling][0]
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+918146234576@sip.sipnl.net [BREAK]
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+918146234576@sip.sipnl.net [BREAK]
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+918146234576@sip.sipnl.net [BREAK]
    2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/+918146234576@sip.sipnl.net entering state [terminated][503]
    2014-02-25 00:10:45.103685 [NOTICE] sofia.c:6733 Hangup sofia/sipinterface_1/+918146234576@sip.sipnl.net [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE]
    2014-02-25 00:10:45.103685 [DEBUG] switch_channel.c:3212 Send signal sofia/sipinterface_1/+918146234576@sip.sipnl.net [KILL]
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/+918146234576@sip.sipnl.net [BREAK]
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) Running State Change CS_HANGUP
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:731 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State HANGUP
    2014-02-25 00:10:45.103685 [DEBUG] mod_sofia.c:413 Channel sofia/sipinterface_1/+918146234576@sip.sipnl.net hanging up, cause: NORMAL_TEMPORARY_FAILURE
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:58 sofia/sipinterface_1/+918146234576@sip.sipnl.net Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:731 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State HANGUP going to sleep
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:744 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) Callstate Change DOWN -> HANGUP
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:499 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State Change CS_HANGUP -> CS_REPORTING
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/+918146234576@sip.sipnl.net [BREAK]
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) Running State Change CS_REPORTING
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:816 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State REPORTING
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:102 sofia/sipinterface_1/+918146234576@sip.sipnl.net Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:816 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State REPORTING going to sleep
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:493 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State Change CS_REPORTING -> CS_DESTROY
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/+918146234576@sip.sipnl.net [BREAK]
    2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1591 Session 15 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) Locked, Waiting on external entities
    2014-02-25 00:10:45.123885 [DEBUG] switch_ivr_originate.c:3678 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
    2014-02-25 00:10:45.123885 [INFO] mod_dptools.c:3244 Originate Failed.  Cause: NORMAL_TEMPORARY_FAILURE
    EXECUTE sofia/sipinterface_1/user1@sip.test.com event(Event-Name=CUSTOM,Event-Subclass=whistle::masquerade,whistle_event_name=CHANNEL_EXECUTE_COMPLETE,whistle_application_name=bridge)
    EXECUTE sofia/sipinterface_1/user1@sip.test.com park()
    2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1609 Session 15 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) Ended
    2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1613 Close Channel sofia/sipinterface_1/+918146234576@sip.sipnl.net [CS_DESTROY]
    2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:618 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) Callstate Change HANGUP -> DOWN
    2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:621 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) Running State Change CS_DESTROY
    2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:631 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State DESTROY
    2014-02-25 00:10:45.123885 [DEBUG] mod_sofia.c:323 sofia/sipinterface_1/+918146234576@sip.sipnl.net SOFIA DESTROY
    2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:109 sofia/sipinterface_1/+918146234576@sip.sipnl.net Standard DESTROY
    2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:631 (sofia/sipinterface_1/+918146234576@sip.sipnl.net) State DESTROY going to sleep
    2014-02-25 00:10:45.183685 [NOTICE] kazoo_node.c:285 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|executing pre_answer
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_session.c:1183 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
    2014-02-25 00:10:45.183685 [DEBUG] switch_ivr.c:615 sofia/sipinterface_1/user1@sip.test.com Command Execute pre_answer()
    EXECUTE sofia/sipinterface_1/user1@sip.test.com pre_answer()
    2014-02-25 00:10:45.183685 [INFO] mod_dptools.c:1260 Sending early media
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [SILK:99:24000:20:0]/[G7221:115:32000:20:48000]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [SILK:99:24000:20:0]/[G7221:107:16000:20:32000]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [SILK:99:24000:20:0]/[G722:9:8000:20:64000]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [SILK:99:24000:20:0]/[PCMU:0:8000:20:64000]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [SILK:99:24000:20:0]/[PCMA:8:8000:20:64000]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [SILK:99:24000:20:0]/[GSM:3:8000:20:13200]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMU:0:8000:20:64000]/[G7221:115:32000:20:48000]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMU:0:8000:20:64000]/[G7221:107:16000:20:32000]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3220 Audio Codec Compare [PCMU:0:8000:20:64000] ++++ is saved as a match
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMA:8:8000:20:64000]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMU:0:8000:20:64000]/[GSM:3:8000:20:13200]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMA:8:8000:20:64000]/[G7221:115:32000:20:48000]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMA:8:8000:20:64000]/[G7221:107:16000:20:32000]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMA:8:8000:20:64000]/[G722:9:8000:20:64000]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3220 Audio Codec Compare [PCMA:8:8000:20:64000] ++++ is saved as a match
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMA:8:8000:20:64000]/[GSM:3:8000:20:13200]
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3092 Set telephone-event payload to 101
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:2125 Set Codec sofia/sipinterface_1/user1@sip.test.com PCMU/8000 20 ms 160 samples 64000 bits
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_codec.c:111 sofia/sipinterface_1/user1@sip.test.com Original read codec set to PCMU:0
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3398 Set 2833 dtmf send/recv payload to 101
    2014-02-25 00:10:45.183685 [INFO] switch_nat.c:590 NAT port mapping disabled
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:4586 AUDIO RTP [sofia/sipinterface_1/user1@sip.test.com] 31.220.27.158 port 20696 -> 112.196.33.74 port 4226 codec: 0 ms: 20
    2014-02-25 00:10:45.183685 [DEBUG] switch_rtp.c:3068 Starting timer [soft] 160 bytes per 20ms
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:4930 Set 2833 dtmf send payload to 101
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:4936 Set 2833 dtmf receive payload to 101
    2014-02-25 00:10:45.183685 [NOTICE] sofia_media.c:92 Pre-Answer sofia/sipinterface_1/user1@sip.test.com!
    2014-02-25 00:10:45.183685 [DEBUG] switch_channel.c:3405 (sofia/sipinterface_1/user1@sip.test.com) Callstate Change RINGING -> EARLY
    2014-02-25 00:10:45.183685 [DEBUG] mod_sofia.c:2099 Ring SDP:
    v=0
    o=FreeSWITCH 1393284349 1393284350 IN IP4 31.220.27.158
    s=FreeSWITCH
    c=IN IP4 31.220.27.158
    t=0 0
    m=audio 20696 RTP/AVP 0 101
    a=rtpmap:0 PCMU/8000
    a=rtpmap:101 telephone-event/8000
    a=fmtp:101 0-16
    a=ptime:20
    a=sendrecv

    2014-02-25 00:10:45.183685 [DEBUG] switch_core_session.c:903 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
    2014-02-25 00:10:45.183685 [DEBUG] switch_ivr.c:959 Codec Activated L16@8000hz 1 channels 20ms
    send 1297 bytes to udp/[88.80.160.31]:5060 at 05:10:45.197608:
       ------------------------------------------------------------------------
       SIP/2.0 183 Session Progress
       Via: SIP/2.0/UDP 88.80.160.31;branch=z9hG4bKd602.9af44717.0
       Via: SIP/2.0/UDP 112.196.33.74:11220;rport=62926;branch=z9hG4bKPj.w0giarvUkQ67HPw3uK5Z6NsdtAUWvEV
       Record-Route: <sip:88.80.160.31;lr=on;ftag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz>
       From: <sip:user1@sip.test.com>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
       To: <sip:+918146234576@sip.test.com>;tag=0KtN4j4SvttFc
       Call-ID: 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
       CSeq: 26826 INVITE
       Contact: <sip:+918146234576@31.220.27.158:11000;transport=udp>
       User-Agent: 2600hz
       Accept: application/sdp
       Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
       Supported: precondition, path, replaces
       Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
       Content-Type: application/sdp
       Content-Disposition: session
       Content-Length: 222
       Remote-Party-ID: "+918146234576" <sip:+918146234576@sip.test.com>;party=calling;privacy=off;screen=no
      
       v=0
       o=FreeSWITCH 1393284349 1393284350 IN IP4 31.220.27.158
       s=FreeSWITCH
       c=IN IP4 31.220.27.158
       t=0 0
       m=audio 20696 RTP/AVP 0 101
       a=rtpmap:0 PCMU/8000
       a=rtpmap:101 telephone-event/8000
       a=fmtp:101 0-16
       a=ptime:20
       ------------------------------------------------------------------------
    2014-02-25 00:10:45.183685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
    2014-02-25 00:10:45.183685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/user1@sip.test.com entering state [early][183]
    2014-02-25 00:10:45.303686 [NOTICE] kazoo_node.c:285 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|executing playback ${http_get(http://127.0.0.1:15984/system_media/fault-can_not_be_completed_at_this_time/fault-can_not_be_completed_at_this_time.wav)}
    2014-02-25 00:10:45.303686 [DEBUG] switch_core_session.c:1183 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
    2014-02-25 00:10:45.303686 [DEBUG] switch_ivr.c:615 sofia/sipinterface_1/user1@sip.test.com Command Execute playback(${http_get(http://127.0.0.1:15984/system_media/fault-can_not_be_completed_at_this_time/fault-can_not_be_completed_at_this_time.wav)})
    2014-02-25 00:10:45.323688 [DEBUG] mod_http_cache.c:523 Locked cache
    2014-02-25 00:10:45.323688 [DEBUG] mod_http_cache.c:651 Cache HIT: size = 1 (0 MB), hit ratio = 8/9
    2014-02-25 00:10:45.323688 [DEBUG] mod_http_cache.c:534 Unlocked cache
    EXECUTE sofia/sipinterface_1/user1@sip.test.com playback(/usr/share/freeswitch/http_cache/39/6c5fb6-9d53-11e3-adae-69d00812b6c2.wav)
    2014-02-25 00:10:45.323688 [DEBUG] switch_core_file.c:216 File /usr/share/freeswitch/http_cache/39/6c5fb6-9d53-11e3-adae-69d00812b6c2.wav sample rate 16000 doesn't match requested rate 8000
    2014-02-25 00:10:45.323688 [DEBUG] switch_ivr_play_say.c:1315 Codec Activated L16@8000hz 1 channels 20ms
    2014-02-25 00:10:46.603692 [INFO] switch_rtp.c:5174 Auto Changing port from 112.196.33.74:4226 to 112.196.33.74:62840
    2014-02-25 00:10:49.503708 [DEBUG] switch_ivr_play_say.c:1719 done playing file /usr/share/freeswitch/http_cache/39/6c5fb6-9d53-11e3-adae-69d00812b6c2.wav
    2014-02-25 00:10:49.503708 [NOTICE] kazoo_node.c:285 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|executing respond 503 Normal temporary failure
    2014-02-25 00:10:49.503708 [DEBUG] switch_core_session.c:1183 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
    2014-02-25 00:10:49.543698 [DEBUG] switch_ivr.c:615 sofia/sipinterface_1/user1@sip.test.com Command Execute respond(503 Normal temporary failure)
    EXECUTE sofia/sipinterface_1/user1@sip.test.com respond(503 Normal temporary failure)
    2014-02-25 00:10:49.543698 [DEBUG] mod_sofia.c:1919 Responding with 503 [Normal temporary failure]
    2014-02-25 00:10:49.543698 [NOTICE] mod_sofia.c:1978 Hangup sofia/sipinterface_1/user1@sip.test.com [CS_EXECUTE] [NORMAL_TEMPORARY_FAILURE]
    2014-02-25 00:10:49.543698 [DEBUG] switch_channel.c:3212 Send signal sofia/sipinterface_1/user1@sip.test.com [KILL]
    2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
    2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:2852 sofia/sipinterface_1/user1@sip.test.com skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
    2014-02-25 00:10:49.543698 [DEBUG] switch_ivr.c:658 sofia/sipinterface_1/user1@sip.test.com skip receive message [AUDIO_SYNC] (channel is hungup already)
    2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:2852 sofia/sipinterface_1/user1@sip.test.com skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
    2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:530 (sofia/sipinterface_1/user1@sip.test.com) State EXECUTE going to sleep
    2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/user1@sip.test.com) Running State Change CS_HANGUP
    2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:731 (sofia/sipinterface_1/user1@sip.test.com) State HANGUP
    2014-02-25 00:10:49.543698 [DEBUG] mod_sofia.c:407 sofia/sipinterface_1/user1@sip.test.com Overriding SIP cause 503 with 503 from the other leg
    2014-02-25 00:10:49.543698 [DEBUG] mod_sofia.c:413 Channel sofia/sipinterface_1/user1@sip.test.com hanging up, cause: NORMAL_TEMPORARY_FAILURE
    2014-02-25 00:10:49.543698 [DEBUG] mod_sofia.c:553 Responding to INVITE with: 503
    2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:58 sofia/sipinterface_1/user1@sip.test.com Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
    2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:731 (sofia/sipinterface_1/user1@sip.test.com) State HANGUP going to sleep
    2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:744 (sofia/sipinterface_1/user1@sip.test.com) Callstate Change EARLY -> HANGUP
    2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:499 (sofia/sipinterface_1/user1@sip.test.com) State Change CS_HANGUP -> CS_REPORTING
    2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
    send 910 bytes to udp/[88.80.160.31]:5060 at 05:10:49.558765:
       ------------------------------------------------------------------------
       SIP/2.0 503 Normal temporary failure
       Via: SIP/2.0/UDP 88.80.160.31;branch=z9hG4bKd602.9af44717.0
       Via: SIP/2.0/UDP 112.196.33.74:11220;rport=62926;branch=z9hG4bKPj.w0giarvUkQ67HPw3uK5Z6NsdtAUWvEV
       From: <sip:user1@sip.test.com>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
       To: <sip:+918146234576@sip.test.com>;tag=0KtN4j4SvttFc
       Call-ID: 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
       CSeq: 26826 INVITE
       User-Agent: 2600hz2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/user1@sip.test.com) Running State Change CS_REPORTING

       Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
       Supported: precondition, path, replaces
       Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
       Reason: Q.850;cause=41;text="NORMAL_TEMPORARY_FAILURE"
       Content-Length: 0
       Remote-Party-ID: "+918146234576" <sip:+918146234576@sip.test.com>;party=calling;privacy=off;screen=no




can anyone tell me what is the problem and how to solve it.



regards,
        vinay