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

vinay vinaysaini.1091 at gmail.com
Tue Feb 25 16:40:26 MSK 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 at sip.test.com 
<mailto:sip%3A%2B918146234576 at 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 at sip.test.com 
<mailto:sip%3Auser1 at sip.test.com>>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
        To: <sip:+918146234576 at sip.test.com 
<mailto:sip%3A%2B918146234576 at sip.test.com>>
        Contact: <sip:user1 at 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 at sip.test.com 
<mailto:sip%3A%2B918146234576 at 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 at sip.test.com 
<mailto:sip%3Auser1 at sip.test.com>>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
        To: <sip:+918146234576 at sip.test.com 
<mailto:sip%3A%2B918146234576 at 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 at sip.test.com 
<mailto:user1 at sip.test.com> [BREAK]
     2014-02-25 00:10:44.243689 [DEBUG] switch_core_session.c:1048 Send 
signal sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at 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 at kaz2.test.nl <mailto:ecallmgr at kaz2.test.nl> <2.1184.0>
     2014-02-25 00:10:44.263688 [DEBUG] kazoo_node.c:1091 Sent erlang 
message to ecallmgr at kaz2.test.nl <mailto:ecallmgr at 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 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at 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 at sip.test.com 
<mailto:user1 at sip.test.com> [BREAK]
     2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:467 
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at sip.test.com>) 
State INIT
     2014-02-25 00:10:44.383689 [DEBUG] mod_sofia.c:87 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> 
SOFIA INIT
     2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:40 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> 
Standard INIT
     2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:48 
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 at sip.test.com 
<mailto:user1 at sip.test.com> [BREAK]
     2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:507 
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at sip.test.com>) 
Running State Change CS_ROUTING
     2014-02-25 00:10:44.383689 [DEBUG] switch_channel.c:2179 
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at sip.test.com>) 
State ROUTING
     2014-02-25 00:10:44.383689 [DEBUG] mod_sofia.c:123 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> 
SOFIA ROUTING
     2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:164 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 at kaz2.test.nl <mailto:ecallmgr at kaz2.test.nl> <2.1185.0>
     2014-02-25 00:10:44.403683 [DEBUG] kazoo_node.c:1091 Sent erlang 
message to ecallmgr at kaz2.test.nl <mailto:ecallmgr at 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 at kaz2.test.nl <mailto:ecallmgr at kaz2.test.nl> won 
call control"/><action application="export" 
data="ecallmgr_Ecallmgr-Node=ecallmgr at kaz2.test.nl 
<mailto:ecallmgr at 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 at sip.test.com 
<mailto:user1 at 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 at sip.test.com 
<mailto:user1 at sip.test.com> Regex (PASS) [park_recur_1] 
variable_ecallmgr_Bridge-ID() =~ /^$/ break=on-false
     |--- Dialplan: sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at sip.test.com> Action export(ecallmgr_Bridge-ID=${UUID})
     Dialplan: sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at sip.test.com> Absolute Condition [park]
     Dialplan: sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at sip.test.com> Action log(NOTICE 
log|${uuid}|ecallmgr at kaz2.test.nl <mailto:ecallmgr at kaz2.test.nl> won 
call control)
     Dialplan: sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at sip.test.com> Action 
export(ecallmgr_Ecallmgr-Node=ecallmgr at kaz2.test.nl 
<mailto:ecallmgr at kaz2.test.nl>)
     Dialplan: sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at sip.test.com> Action set(ringback=%(2000,4000,440,480))
     Dialplan: sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at sip.test.com> Action 
set(transfer_ringback=%(2000,4000,440,480))
     Dialplan: sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at sip.test.com> Action park()
     2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:214 
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 at sip.test.com 
<mailto:user1 at sip.test.com> [BREAK]
     2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:523 
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at sip.test.com>) 
State EXECUTE
     2014-02-25 00:10:44.543689 [DEBUG] mod_sofia.c:178 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> 
SOFIA EXECUTE
     2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:256 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> 
Standard EXECUTE
     EXECUTE sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at 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 at sip.test.com 
<mailto:user1 at sip.test.com> log(NOTICE 
log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|ecallmgr at kaz2.test.nl 
<mailto:ecallmgr at kaz2.test.nl> won call control)
     2014-02-25 00:10:44.543689 [NOTICE] mod_dptools.c:1634 
log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|ecallmgr at kaz2.test.nl 
<mailto:ecallmgr at kaz2.test.nl> won call control
     EXECUTE sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at sip.test.com> 
export(ecallmgr_Ecallmgr-Node=ecallmgr at kaz2.test.nl 
<mailto:ecallmgr at kaz2.test.nl>)
     2014-02-25 00:10:44.543689 [DEBUG] switch_channel.c:1247 EXPORT 
(export_vars) [ecallmgr_Ecallmgr-Node]=[ecallmgr at kaz2.test.nl 
<mailto:ecallmgr at kaz2.test.nl>]
     EXECUTE sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at 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 at sip.test.com <mailto:user1 at sip.test.com> SET 
[ringback]=[%(2000,4000,440,480)]
     EXECUTE sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at 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 at sip.test.com <mailto:user1 at sip.test.com> SET 
[transfer_ringback]=[%(2000,4000,440,480)]
     EXECUTE sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at sip.test.com> park()
     2014-02-25 00:10:44.543689 [DEBUG] kazoo_node.c:1091 Sent erlang 
message to ecallmgr at kaz2.test.nl <mailto:ecallmgr at 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 at kaz2.test.nl <mailto:ecallmgr at 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 at kaz2.test.nl <mailto:ecallmgr at kaz2.test.nl> <2.11912.4>
     freeswitch at 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 at 16000h:G7221 at 32000h',leg_progress_timeout='60',effective_callee_id_number='+918146234576',effective_callee_id_name='918146234576']sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.test.com 
<mailto:user1 at sip.test.com> [BREAK]
     2014-02-25 00:10:45.043686 [DEBUG] switch_channel.c:3098 
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 at sip.test.com 
<mailto:user1 at sip.test.com> [BREAK]
     2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:530 
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at sip.test.com>) 
State ROUTING
     2014-02-25 00:10:45.063687 [DEBUG] mod_sofia.c:123 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> 
SOFIA ROUTING
     2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:164 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> 
Standard ROUTING
     2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:184 
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 at sip.test.com 
<mailto:user1 at sip.test.com> [BREAK]
     2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:523 
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at sip.test.com>) 
State EXECUTE
     2014-02-25 00:10:45.063687 [DEBUG] mod_sofia.c:178 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> 
SOFIA EXECUTE
     2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:256 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> 
Standard EXECUTE
     EXECUTE sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at sip.test.com> set(ignore_display_updates=true)
     2014-02-25 00:10:45.063687 [DEBUG] mod_dptools.c:1402 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> SET 
[ignore_display_updates]=[true]
     EXECUTE sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at sip.test.com> set(continue_on_fail=true)
     2014-02-25 00:10:45.063687 [DEBUG] mod_dptools.c:1402 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> SET 
[continue_on_fail]=[true]
     EXECUTE sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at 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 at sip.test.com 
<mailto:user1 at 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 at 16000h:G7221 at 32000h',leg_progress_timeout='60',effective_callee_id_number='+918146234576',effective_callee_id_name='918146234576']sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net>)
     2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at sip.test.com> 
EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[ecallmgr at kaz2.test.nl 
<mailto:ecallmgr at kaz2.test.nl>] to event
     2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 at 16000h:G7221 at 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 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> [2e446736-9ddb-11e3-ae9b-69d00812b6c2]
     2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:4456 
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> [BREAK]
     2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:2821 
sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net>) State INIT
     2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:87 
sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> Standard INIT
     2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:48 
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> [BREAK]
     2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:507 
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net>) State ROUTING
     2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:123 
sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> SOFIA ROUTING
     2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:67 
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> [BREAK]
     2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:523 
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net>) State CONSUME_MEDIA
     2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:542 
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at kaz2.test.nl <mailto:ecallmgr at 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 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> [BREAK]
     2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel 
sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> [BREAK]
     2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send 
signal sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> [BREAK]
     2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send 
signal sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> [BREAK]
     2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel 
sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> entering state [terminated][503]
     2014-02-25 00:10:45.103685 [NOTICE] sofia.c:6733 Hangup 
sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> [KILL]
     2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1383 Send 
signal sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> [BREAK]
     2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467 
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net>) State HANGUP
     2014-02-25 00:10:45.103685 [DEBUG] mod_sofia.c:413 Channel 
sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> [BREAK]
     2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467 
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net>) State REPORTING
     2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:102 
sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> [BREAK]
     2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1591 
Session 15 (sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.test.com 
<mailto:user1 at 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 at sip.test.com 
<mailto:user1 at sip.test.com> park()
     2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1609 
Session 15 (sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net>) Ended
     2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1613 
Close Channel sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> [CS_DESTROY]
     2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:618 
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net>) State DESTROY
     2014-02-25 00:10:45.123885 [DEBUG] mod_sofia.c:323 
sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> SOFIA DESTROY
     2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:109 
sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at sip.sipnl.net> Standard DESTROY
     2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:631 
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net 
<mailto:918146234576 at 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 at sip.test.com 
<mailto:user1 at sip.test.com> [BREAK]
     2014-02-25 00:10:45.183685 [DEBUG] switch_ivr.c:615 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> 
Command Execute pre_answer()
     EXECUTE sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at 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 at sip.test.com 
<mailto:user1 at 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 at sip.test.com <mailto:user1 at 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 at sip.test.com 
<mailto:user1 at 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 at sip.test.com <mailto:user1 at sip.test.com>!
     2014-02-25 00:10:45.183685 [DEBUG] switch_channel.c:3405 
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 at sip.test.com 
<mailto:user1 at sip.test.com> [BREAK]
     2014-02-25 00:10:45.183685 [DEBUG] switch_ivr.c:959 Codec Activated 
L16 at 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 at sip.test.com 
<mailto:sip%3Auser1 at sip.test.com>>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
        To: <sip:+918146234576 at sip.test.com 
<mailto:sip%3A%2B918146234576 at sip.test.com>>;tag=0KtN4j4SvttFc
        Call-ID: 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
        CSeq: 26826 INVITE
        Contact: <sip:+918146234576 at 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 at sip.test.com 
<mailto:sip%3A%2B918146234576 at 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 at sip.test.com 
<mailto:user1 at sip.test.com> [BREAK]
     2014-02-25 00:10:45.183685 [DEBUG] sofia.c:5889 Channel 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 
<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 at sip.test.com 
<mailto:user1 at sip.test.com> [BREAK]
     2014-02-25 00:10:45.303686 [DEBUG] switch_ivr.c:615 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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) 
<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 at sip.test.com 
<mailto:user1 at 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 at 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 at sip.test.com 
<mailto:user1 at sip.test.com> [BREAK]
     2014-02-25 00:10:49.543698 [DEBUG] switch_ivr.c:615 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> 
Command Execute respond(503 Normal temporary failure)
     EXECUTE sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at 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 at sip.test.com <mailto:user1 at 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 at sip.test.com 
<mailto:user1 at sip.test.com> [KILL]
     2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:1383 Send 
signal sofia/sipinterface_1/user1 at sip.test.com 
<mailto:user1 at sip.test.com> [BREAK]
     2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:2852 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at sip.test.com>) 
State HANGUP
     2014-02-25 00:10:49.543698 [DEBUG] mod_sofia.c:407 
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at 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 at sip.test.com <mailto:user1 at 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 at sip.test.com 
<mailto:user1 at 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 at sip.test.com 
<mailto:sip%3Auser1 at sip.test.com>>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
        To: <sip:+918146234576 at sip.test.com 
<mailto:sip%3A%2B918146234576 at 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 at sip.test.com 
<mailto:user1 at 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 at sip.test.com 
<mailto:sip%3A%2B918146234576 at sip.test.com>>;party=calling;privacy=off;screen=no




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



regards,
         vinay



-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20140225/43c83221/attachment-0001.html 


Join us at ClueCon 2013 Aug 6-8, 2013
More information about the FreeSWITCH-users mailing list