[Freeswitch-users] Problem with sending Invite from Freeswitch to the carrier.

25 Feb 2014

      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 
<mailto:sip%3A%2B918146234576@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 
<mailto:sip%3Auser1@sip.test.com>>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
        To: <sip:+918146234576@sip.test.com 
<mailto:sip%3A%2B918146234576@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 <http://sip.test.com>", 
nonce="2da67792-9ddb-11e3-ae8b-69d00812b6c2", 
uri="sip:+918146234576@sip.test.com 
<mailto:sip%3A%2B918146234576@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 
<mailto:sip%3Auser1@sip.test.com>>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
        To: <sip:+918146234576@sip.test.com 
<mailto:sip%3A%2B918146234576@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 
<mailto: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 
<mailto: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 <mailto: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 <mailto: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 <http://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 
<http://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 <mailto: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 <mailto: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 
<mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 
<mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto:ecallmgr@kaz2.test.nl> won 
call control"/><action application="export" 
data="ecallmgr_Ecallmgr-Node=ecallmgr@kaz2.test.nl 
<mailto: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 
<mailto: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 
<mailto:user1@sip.test.com> Regex (PASS) [park_recur_1] 
variable_ecallmgr_Bridge-ID() =~ /^$/ break=on-false
     |--- Dialplan: sofia/sipinterface_1/user1@sip.test.com 
<mailto:user1@sip.test.com> Action export(ecallmgr_Bridge-ID=${UUID})
     Dialplan: sofia/sipinterface_1/user1@sip.test.com 
<mailto:user1@sip.test.com> Absolute Condition [park]
     Dialplan: sofia/sipinterface_1/user1@sip.test.com 
<mailto:user1@sip.test.com> Action log(NOTICE 
log|${uuid}|ecallmgr@kaz2.test.nl <mailto:ecallmgr@kaz2.test.nl> won 
call control)
     Dialplan: sofia/sipinterface_1/user1@sip.test.com 
<mailto:user1@sip.test.com> Action 
export(ecallmgr_Ecallmgr-Node=ecallmgr@kaz2.test.nl 
<mailto:ecallmgr@kaz2.test.nl>)
     Dialplan: sofia/sipinterface_1/user1@sip.test.com 
<mailto:user1@sip.test.com> Action set(ringback=%(2000,4000,440,480))
     Dialplan: sofia/sipinterface_1/user1@sip.test.com 
<mailto:user1@sip.test.com> Action 
set(transfer_ringback=%(2000,4000,440,480))
     Dialplan: sofia/sipinterface_1/user1@sip.test.com 
<mailto: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 <mailto: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 
<mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto:user1@sip.test.com> 
Standard EXECUTE
     EXECUTE sofia/sipinterface_1/user1@sip.test.com 
<mailto: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 
<mailto:user1@sip.test.com> log(NOTICE 
log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|ecallmgr@kaz2.test.nl 
<mailto: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 
<mailto:ecallmgr@kaz2.test.nl> won call control
     EXECUTE sofia/sipinterface_1/user1@sip.test.com 
<mailto:user1@sip.test.com> 
export(ecallmgr_Ecallmgr-Node=ecallmgr@kaz2.test.nl 
<mailto: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 
<mailto:ecallmgr@kaz2.test.nl>]
     EXECUTE sofia/sipinterface_1/user1@sip.test.com 
<mailto: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 <mailto:user1@sip.test.com> SET 
[ringback]=[%(2000,4000,440,480)]
     EXECUTE sofia/sipinterface_1/user1@sip.test.com 
<mailto: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 <mailto:user1@sip.test.com> SET 
[transfer_ringback]=[%(2000,4000,440,480)]
     EXECUTE sofia/sipinterface_1/user1@sip.test.com 
<mailto: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 <mailto: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 <mailto: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 
<http://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 <mailto: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 
<mailto: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 
<mailto:user1@sip.test.com> [BREAK]
     2014-02-25 00:10:45.043686 [DEBUG] switch_channel.c:3098 
(sofia/sipinterface_1/user1@sip.test.com <mailto: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 
<mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 
<mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto:user1@sip.test.com> 
Standard EXECUTE
     EXECUTE sofia/sipinterface_1/user1@sip.test.com 
<mailto: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 <mailto:user1@sip.test.com> SET 
[ignore_display_updates]=[true]
     EXECUTE sofia/sipinterface_1/user1@sip.test.com 
<mailto: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 <mailto:user1@sip.test.com> SET 
[continue_on_fail]=[true]
     EXECUTE sofia/sipinterface_1/user1@sip.test.com 
<mailto: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 
<mailto: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 
<mailto:918146234576@sip.sipnl.net>)
     2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 
sofia/sipinterface_1/user1@sip.test.com <mailto: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 <mailto:user1@sip.test.com> 
EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[ecallmgr@kaz2.test.nl 
<mailto: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 <mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 <mailto: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 
<mailto:918146234576@sip.sipnl.net> [BREAK]
     2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel 
sofia/sipinterface_1/+918146234576@sip.sipnl.net 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto:918146234576@sip.sipnl.net> [BREAK]
     2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel 
sofia/sipinterface_1/+918146234576@sip.sipnl.net 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto: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 
<mailto:user1@sip.test.com> [BREAK]
     2014-02-25 00:10:45.183685 [DEBUG] switch_ivr.c:615 
sofia/sipinterface_1/user1@sip.test.com <mailto:user1@sip.test.com> 
Command Execute pre_answer()
     EXECUTE sofia/sipinterface_1/user1@sip.test.com 
<mailto: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 
<mailto: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 <mailto: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 
<mailto: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 <mailto:user1@sip.test.com>!
     2014-02-25 00:10:45.183685 [DEBUG] switch_channel.c:3405 
(sofia/sipinterface_1/user1@sip.test.com <mailto: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 
<mailto: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 
<mailto:sip%3Auser1@sip.test.com>>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
        To: <sip:+918146234576@sip.test.com 
<mailto:sip%3A%2B918146234576@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 
<mailto:sip%3A%2B918146234576@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 
<mailto:user1@sip.test.com> [BREAK]
     2014-02-25 00:10:45.183685 [DEBUG] sofia.c:5889 Channel 
sofia/sipinterface_1/user1@sip.test.com <mailto: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/... 
<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 
<mailto:user1@sip.test.com> [BREAK]
     2014-02-25 00:10:45.303686 [DEBUG] switch_ivr.c:615 
sofia/sipinterface_1/user1@sip.test.com <mailto: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/...) 
<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%29>})
     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 
<mailto: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 <http://112.196.33.74:4226> to 
112.196.33.74:62840 <http://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 
<mailto:user1@sip.test.com> [BREAK]
     2014-02-25 00:10:49.543698 [DEBUG] switch_ivr.c:615 
sofia/sipinterface_1/user1@sip.test.com <mailto:user1@sip.test.com> 
Command Execute respond(503 Normal temporary failure)
     EXECUTE sofia/sipinterface_1/user1@sip.test.com 
<mailto: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 <mailto: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 
<mailto: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 
<mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 
<mailto: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 
<mailto:sip%3Auser1@sip.test.com>>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
        To: <sip:+918146234576@sip.test.com 
<mailto:sip%3A%2B918146234576@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 
<mailto: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 
<mailto:sip%3A%2B918146234576@sip.test.com>>;party=calling;privacy=off;screen=no

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

regards,
         vinay