Problem with sending Invite from Freeswitch to the carrier.
3,263 views
Skip to first unread message
vinay saini
Feb 25, 2014, 12:32:30 AM2/25/14
to 2600h...@googlegroups.com
Hi all,
I have deployed Kazoo on six server,which have
2-kazoo server
2-freeswitch server
2-bigcouch server
All of them are clustered together and working fine for device to device calling.But I found problem when making an outbound call through local carrier.
According to kazoo logs I can see that kazoo is forwarding local resource information to the freeswitch but freeswitch is not sending INVITE to the carrier.These are the freeswitch logs which is giving error- 503 Normal temporary failure.
INVITE sip:+91814...@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:us...@sip.test.com>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
To: <sip:+91814...@sip.test.com>
Contact: <sip:us...@112.196.33.74:62926;ob>
Call-ID: 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
CSeq: 26826 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
User-Agent: CSipSimple_A89-15/r2330
Proxy-Authorization: Digest username="user1", realm="sip.test.com", nonce="2da67792-9ddb-11e3-ae8b-69d00812b6c2", uri="sip:+91814...@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:us...@sip.test.com>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
To: <sip:+91814...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:44.243689 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/us...@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 ecal...@kaz2.test.nl <2.1184.0>
2014-02-25 00:10:44.263688 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecal...@kaz2.test.nl <2.1184.0>
2014-02-25 00:10:44.383689 [DEBUG] kazoo_fetch_agent.c:277 Received directory XML (2dc8752c-9ddb-11e3-ae8c-69d00812b6c2) after 120ms: <document type="freeswitch/xml"><section name="directory"><domain name="sip.test.com"><user id="user1"><variables><variable name="ecallmgr_Inception" value="on-net"/><variable name="ecallmgr_Authorizing-Type" value="device"/><variable name="ecallmgr_Authorizing-ID" value="3b46b4ceec6bb18dd8985792d7b5693e"/><variable name="ecallmgr_Account-ID" value="502cc62fa8097dd6d753fea7c7ef91a1"/><variable name="ecallmgr_Realm" value="sip.test.com"/><variable name="ecallmgr_Username" value="user1"/></variables><params><param name="password" value="user1"/></params></user></domain></section></document>
2014-02-25 00:10:44.383689 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/us...@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/us...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/us...@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/us...@sip.test.com) State INIT
2014-02-25 00:10:44.383689 [DEBUG] mod_sofia.c:87 sofia/sipinterface_1/us...@sip.test.com SOFIA INIT
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/us...@sip.test.com Standard INIT
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/us...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:507 (sofia/sipinterface_1/us...@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/us...@sip.test.com) Running State Change CS_ROUTING
2014-02-25 00:10:44.383689 [DEBUG] switch_channel.c:2179 (sofia/sipinterface_1/us...@sip.test.com) Callstate Change DOWN -> RINGING
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/us...@sip.test.com) State ROUTING
2014-02-25 00:10:44.383689 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/us...@sip.test.com SOFIA ROUTING
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:164 sofia/sipinterface_1/us...@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 ecal...@kaz2.test.nl <2.1185.0>
2014-02-25 00:10:44.403683 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecal...@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}|ecal...@kaz2.test.nl won call control"/><action application="export" data="ecallmgr_Ecallmgr-Node=ecal...@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/us...@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/us...@sip.test.com Regex (PASS) [park_recur_1] variable_ecallmgr_Bridge-ID() =~ /^$/ break=on-false
|--- Dialplan: sofia/sipinterface_1/us...@sip.test.com Action export(ecallmgr_Bridge-ID=${UUID})
Dialplan: sofia/sipinterface_1/us...@sip.test.com Absolute Condition [park]
Dialplan: sofia/sipinterface_1/us...@sip.test.com Action log(NOTICE log|${uuid}|ecal...@kaz2.test.nl won call control)
Dialplan: sofia/sipinterface_1/us...@sip.test.com Action export(ecallmgr_Ecallmgr-Node=ecal...@kaz2.test.nl)
Dialplan: sofia/sipinterface_1/us...@sip.test.com Action set(ringback=%(2000,4000,440,480))
Dialplan: sofia/sipinterface_1/us...@sip.test.com Action set(transfer_ringback=%(2000,4000,440,480))
Dialplan: sofia/sipinterface_1/us...@sip.test.com Action park()
2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:214 (sofia/sipinterface_1/us...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/us...@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/us...@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/us...@sip.test.com) State EXECUTE
2014-02-25 00:10:44.543689 [DEBUG] mod_sofia.c:178 sofia/sipinterface_1/us...@sip.test.com SOFIA EXECUTE
2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:256 sofia/sipinterface_1/us...@sip.test.com Standard EXECUTE
EXECUTE sofia/sipinterface_1/us...@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/us...@sip.test.com log(NOTICE log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|ecal...@kaz2.test.nl won call control)
2014-02-25 00:10:44.543689 [NOTICE] mod_dptools.c:1634 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|ecal...@kaz2.test.nl won call control
EXECUTE sofia/sipinterface_1/us...@sip.test.com export(ecallmgr_Ecallmgr-Node=ecal...@kaz2.test.nl)
2014-02-25 00:10:44.543689 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [ecallmgr_Ecallmgr-Node]=[ecal...@kaz2.test.nl]
EXECUTE sofia/sipinterface_1/us...@sip.test.com set(ringback=%(2000,4000,440,480))
2014-02-25 00:10:44.543689 [DEBUG] mod_dptools.c:1402 sofia/sipinterface_1/us...@sip.test.com SET [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/sipinterface_1/us...@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/us...@sip.test.com SET [transfer_ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/sipinterface_1/us...@sip.test.com park()
2014-02-25 00:10:44.543689 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecal...@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 ecal...@kaz2.test.nl <2.11883.4>
2014-02-25 00:10:44.723684 [INFO] kazoo_node.c:627 exec: uuid_setvar_multi(0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO effective_caller_id_name=Martin;effective_caller_id_number=+xxxxxxxxxxx;ecallmgr_Channel-Authorized=true;ecallmgr_Username=user1;ecallmgr_Realm=sip.test.com;ecallmgr_Account-ID=502cc62fa8097dd6d753fea7c7ef91a1;ecallmgr_Authorizing-ID=3b46b4ceec6bb18dd8985792d7b5693e;ecallmgr_Authorizing-Type=device;ecallmgr_Inception=on-net;ecallmgr_Fetch-ID=2ddb9918-9ddb-11e3-ae8e-69d00812b6c2)
2014-02-25 00:10:44.723684 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecal...@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/+918146...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:45.043686 [DEBUG] switch_channel.c:3098 (sofia/sipinterface_1/us...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:530 (sofia/sipinterface_1/us...@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/us...@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/us...@sip.test.com) State ROUTING
2014-02-25 00:10:45.063687 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/us...@sip.test.com SOFIA ROUTING
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:164 sofia/sipinterface_1/us...@sip.test.com Standard ROUTING
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:184 (sofia/sipinterface_1/us...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/us...@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/us...@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/us...@sip.test.com) State EXECUTE
2014-02-25 00:10:45.063687 [DEBUG] mod_sofia.c:178 sofia/sipinterface_1/us...@sip.test.com SOFIA EXECUTE
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:256 sofia/sipinterface_1/us...@sip.test.com Standard EXECUTE
EXECUTE sofia/sipinterface_1/us...@sip.test.com set(ignore_display_updates=true)
2014-02-25 00:10:45.063687 [DEBUG] mod_dptools.c:1402 sofia/sipinterface_1/us...@sip.test.com SET [ignore_display_updates]=[true]
EXECUTE sofia/sipinterface_1/us...@sip.test.com set(continue_on_fail=true)
2014-02-25 00:10:45.063687 [DEBUG] mod_dptools.c:1402 sofia/sipinterface_1/us...@sip.test.com SET [continue_on_fail]=[true]
EXECUTE sofia/sipinterface_1/us...@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/us...@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/+918146...@sip.sipnl.net)
2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/us...@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/us...@sip.test.com EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[ecal...@kaz2.test.nl] to event
2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/us...@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/+918146...@sip.sipnl.net [2e446736-9ddb-11e3-ae9b-69d00812b6c2]
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:4456 (sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:2821 sofia/sipinterface_1/+918146...@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/+918146...@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/+918146...@sip.sipnl.net) State INIT
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:87 sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net Standard INIT
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:507 (sofia/sipinterface_1/+918146...@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/+918146...@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/+918146...@sip.sipnl.net) State ROUTING
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/+918146...@sip.sipnl.net SOFIA ROUTING
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:67 (sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/+918146...@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/+918146...@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/+918146...@sip.sipnl.net) State CONSUME_MEDIA
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:542 (sofia/sipinterface_1/+918146...@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 ecal...@kaz2.test.nl <2.11955.4>
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/+918146...@sip.sipnl.net entering state [terminated][503]
2014-02-25 00:10:45.103685 [NOTICE] sofia.c:6733 Hangup sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net [KILL]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net) State HANGUP
2014-02-25 00:10:45.103685 [DEBUG] mod_sofia.c:413 Channel sofia/sipinterface_1/+918146...@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/+918146...@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/+918146...@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/+918146...@sip.sipnl.net) Callstate Change DOWN -> HANGUP
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:499 (sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net) State REPORTING
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:102 sofia/sipinterface_1/+918146...@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/+918146...@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/+918146...@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/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1591 Session 15 (sofia/sipinterface_1/+918146...@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/us...@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/us...@sip.test.com park()
2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1609 Session 15 (sofia/sipinterface_1/+918146...@sip.sipnl.net) Ended
2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1613 Close Channel sofia/sipinterface_1/+918146...@sip.sipnl.net [CS_DESTROY]
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:618 (sofia/sipinterface_1/+918146...@sip.sipnl.net) Callstate Change HANGUP -> DOWN
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:621 (sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net) State DESTROY
2014-02-25 00:10:45.123885 [DEBUG] mod_sofia.c:323 sofia/sipinterface_1/+918146...@sip.sipnl.net SOFIA DESTROY
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:109 sofia/sipinterface_1/+918146...@sip.sipnl.net Standard DESTROY
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:631 (sofia/sipinterface_1/+918146...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:45.183685 [DEBUG] switch_ivr.c:615 sofia/sipinterface_1/us...@sip.test.com Command Execute pre_answer()
EXECUTE sofia/sipinterface_1/us...@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/us...@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/us...@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/us...@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/us...@sip.test.com!
2014-02-25 00:10:45.183685 [DEBUG] switch_channel.c:3405 (sofia/sipinterface_1/us...@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/us...@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:us...@sip.test.com>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
To: <sip:+91814...@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:+91814...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:45.183685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/us...@sip.test.com entering state [early][183]
2014-02-25 00:10:45.303686 [NOTICE] kazoo_node.c:285 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|executing playback ${http_get(http://127.0.0.1:15984/system_media/fault-can_not_be_completed_at_this_time/fault-can_not_be_completed_at_this_time.wav)}
2014-02-25 00:10:45.303686 [DEBUG] switch_core_session.c:1183 Send signal sofia/sipinterface_1/us...@sip.test.com [BREAK]
2014-02-25 00:10:45.303686 [DEBUG] switch_ivr.c:615 sofia/sipinterface_1/us...@sip.test.com Command Execute playback(${http_get(http://127.0.0.1:15984/system_media/fault-can_not_be_completed_at_this_time/fault-can_not_be_completed_at_this_time.wav)})
2014-02-25 00:10:45.323688 [DEBUG] mod_http_cache.c:523 Locked cache
2014-02-25 00:10:45.323688 [DEBUG] mod_http_cache.c:651 Cache HIT: size = 1 (0 MB), hit ratio = 8/9
2014-02-25 00:10:45.323688 [DEBUG] mod_http_cache.c:534 Unlocked cache
EXECUTE sofia/sipinterface_1/us...@sip.test.com playback(/usr/share/freeswitch/http_cache/39/6c5fb6-9d53-11e3-adae-69d00812b6c2.wav)
2014-02-25 00:10:45.323688 [DEBUG] switch_core_file.c:216 File /usr/share/freeswitch/http_cache/39/6c5fb6-9d53-11e3-adae-69d00812b6c2.wav sample rate 16000 doesn't match requested rate 8000
2014-02-25 00:10:45.323688 [DEBUG] switch_ivr_play_say.c:1315 Codec Activated L16@8000hz 1 channels 20ms
2014-02-25 00:10:46.603692 [INFO] switch_rtp.c:5174 Auto Changing port from 112.196.33.74:4226 to 112.196.33.74:62840
2014-02-25 00:10:49.503708 [DEBUG] switch_ivr_play_say.c:1719 done playing file /usr/share/freeswitch/http_cache/39/6c5fb6-9d53-11e3-adae-69d00812b6c2.wav
2014-02-25 00:10:49.503708 [NOTICE] kazoo_node.c:285 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|executing respond 503 Normal temporary failure
2014-02-25 00:10:49.503708 [DEBUG] switch_core_session.c:1183 Send signal sofia/sipinterface_1/us...@sip.test.com [BREAK]
2014-02-25 00:10:49.543698 [DEBUG] switch_ivr.c:615 sofia/sipinterface_1/us...@sip.test.com Command Execute respond(503 Normal temporary failure)
EXECUTE sofia/sipinterface_1/us...@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/us...@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/us...@sip.test.com [KILL]
2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/us...@sip.test.com [BREAK]
2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:2852 sofia/sipinterface_1/us...@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/us...@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/us...@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/us...@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/us...@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/us...@sip.test.com) State HANGUP
2014-02-25 00:10:49.543698 [DEBUG] mod_sofia.c:407 sofia/sipinterface_1/us...@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/us...@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/us...@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/us...@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/us...@sip.test.com) Callstate Change EARLY -> HANGUP
2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:499 (sofia/sipinterface_1/us...@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/us...@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:us...@sip.test.com>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
To: <sip:+91814...@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/us...@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:+91814...@sip.test.com>;party=calling;privacy=off;screen=no
can anybody advise me what is the problem?And how it can be solved?
Regards,
Vinay
I have deployed Kazoo on six server,which have
2-kazoo server
2-freeswitch server
2-bigcouch server
All of them are clustered together and working fine for device to device calling.But I found problem when making an outbound call through local carrier.
According to kazoo logs I can see that kazoo is forwarding local resource information to the freeswitch but freeswitch is not sending INVITE to the carrier.These are the freeswitch logs which is giving error- 503 Normal temporary failure.
INVITE sip:+91814...@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:us...@sip.test.com>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
To: <sip:+91814...@sip.test.com>
Contact: <sip:us...@112.196.33.74:62926;ob>
Call-ID: 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
CSeq: 26826 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
User-Agent: CSipSimple_A89-15/r2330
Proxy-Authorization: Digest username="user1", realm="sip.test.com", nonce="2da67792-9ddb-11e3-ae8b-69d00812b6c2", uri="sip:+91814...@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:us...@sip.test.com>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
To: <sip:+91814...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:44.243689 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/us...@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 ecal...@kaz2.test.nl <2.1184.0>
2014-02-25 00:10:44.263688 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecal...@kaz2.test.nl <2.1184.0>
2014-02-25 00:10:44.383689 [DEBUG] kazoo_fetch_agent.c:277 Received directory XML (2dc8752c-9ddb-11e3-ae8c-69d00812b6c2) after 120ms: <document type="freeswitch/xml"><section name="directory"><domain name="sip.test.com"><user id="user1"><variables><variable name="ecallmgr_Inception" value="on-net"/><variable name="ecallmgr_Authorizing-Type" value="device"/><variable name="ecallmgr_Authorizing-ID" value="3b46b4ceec6bb18dd8985792d7b5693e"/><variable name="ecallmgr_Account-ID" value="502cc62fa8097dd6d753fea7c7ef91a1"/><variable name="ecallmgr_Realm" value="sip.test.com"/><variable name="ecallmgr_Username" value="user1"/></variables><params><param name="password" value="user1"/></params></user></domain></section></document>
2014-02-25 00:10:44.383689 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/us...@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/us...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/us...@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/us...@sip.test.com) State INIT
2014-02-25 00:10:44.383689 [DEBUG] mod_sofia.c:87 sofia/sipinterface_1/us...@sip.test.com SOFIA INIT
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/us...@sip.test.com Standard INIT
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/us...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:507 (sofia/sipinterface_1/us...@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/us...@sip.test.com) Running State Change CS_ROUTING
2014-02-25 00:10:44.383689 [DEBUG] switch_channel.c:2179 (sofia/sipinterface_1/us...@sip.test.com) Callstate Change DOWN -> RINGING
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/us...@sip.test.com) State ROUTING
2014-02-25 00:10:44.383689 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/us...@sip.test.com SOFIA ROUTING
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:164 sofia/sipinterface_1/us...@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 ecal...@kaz2.test.nl <2.1185.0>
2014-02-25 00:10:44.403683 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecal...@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}|ecal...@kaz2.test.nl won call control"/><action application="export" data="ecallmgr_Ecallmgr-Node=ecal...@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/us...@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/us...@sip.test.com Regex (PASS) [park_recur_1] variable_ecallmgr_Bridge-ID() =~ /^$/ break=on-false
|--- Dialplan: sofia/sipinterface_1/us...@sip.test.com Action export(ecallmgr_Bridge-ID=${UUID})
Dialplan: sofia/sipinterface_1/us...@sip.test.com Absolute Condition [park]
Dialplan: sofia/sipinterface_1/us...@sip.test.com Action log(NOTICE log|${uuid}|ecal...@kaz2.test.nl won call control)
Dialplan: sofia/sipinterface_1/us...@sip.test.com Action export(ecallmgr_Ecallmgr-Node=ecal...@kaz2.test.nl)
Dialplan: sofia/sipinterface_1/us...@sip.test.com Action set(ringback=%(2000,4000,440,480))
Dialplan: sofia/sipinterface_1/us...@sip.test.com Action set(transfer_ringback=%(2000,4000,440,480))
Dialplan: sofia/sipinterface_1/us...@sip.test.com Action park()
2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:214 (sofia/sipinterface_1/us...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/us...@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/us...@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/us...@sip.test.com) State EXECUTE
2014-02-25 00:10:44.543689 [DEBUG] mod_sofia.c:178 sofia/sipinterface_1/us...@sip.test.com SOFIA EXECUTE
2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:256 sofia/sipinterface_1/us...@sip.test.com Standard EXECUTE
EXECUTE sofia/sipinterface_1/us...@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/us...@sip.test.com log(NOTICE log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|ecal...@kaz2.test.nl won call control)
2014-02-25 00:10:44.543689 [NOTICE] mod_dptools.c:1634 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|ecal...@kaz2.test.nl won call control
EXECUTE sofia/sipinterface_1/us...@sip.test.com export(ecallmgr_Ecallmgr-Node=ecal...@kaz2.test.nl)
2014-02-25 00:10:44.543689 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [ecallmgr_Ecallmgr-Node]=[ecal...@kaz2.test.nl]
EXECUTE sofia/sipinterface_1/us...@sip.test.com set(ringback=%(2000,4000,440,480))
2014-02-25 00:10:44.543689 [DEBUG] mod_dptools.c:1402 sofia/sipinterface_1/us...@sip.test.com SET [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/sipinterface_1/us...@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/us...@sip.test.com SET [transfer_ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/sipinterface_1/us...@sip.test.com park()
2014-02-25 00:10:44.543689 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecal...@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 ecal...@kaz2.test.nl <2.11883.4>
2014-02-25 00:10:44.723684 [INFO] kazoo_node.c:627 exec: uuid_setvar_multi(0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO effective_caller_id_name=Martin;effective_caller_id_number=+xxxxxxxxxxx;ecallmgr_Channel-Authorized=true;ecallmgr_Username=user1;ecallmgr_Realm=sip.test.com;ecallmgr_Account-ID=502cc62fa8097dd6d753fea7c7ef91a1;ecallmgr_Authorizing-ID=3b46b4ceec6bb18dd8985792d7b5693e;ecallmgr_Authorizing-Type=device;ecallmgr_Inception=on-net;ecallmgr_Fetch-ID=2ddb9918-9ddb-11e3-ae8e-69d00812b6c2)
2014-02-25 00:10:44.723684 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecal...@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/+918146...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:45.043686 [DEBUG] switch_channel.c:3098 (sofia/sipinterface_1/us...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:530 (sofia/sipinterface_1/us...@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/us...@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/us...@sip.test.com) State ROUTING
2014-02-25 00:10:45.063687 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/us...@sip.test.com SOFIA ROUTING
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:164 sofia/sipinterface_1/us...@sip.test.com Standard ROUTING
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:184 (sofia/sipinterface_1/us...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/us...@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/us...@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/us...@sip.test.com) State EXECUTE
2014-02-25 00:10:45.063687 [DEBUG] mod_sofia.c:178 sofia/sipinterface_1/us...@sip.test.com SOFIA EXECUTE
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:256 sofia/sipinterface_1/us...@sip.test.com Standard EXECUTE
EXECUTE sofia/sipinterface_1/us...@sip.test.com set(ignore_display_updates=true)
2014-02-25 00:10:45.063687 [DEBUG] mod_dptools.c:1402 sofia/sipinterface_1/us...@sip.test.com SET [ignore_display_updates]=[true]
EXECUTE sofia/sipinterface_1/us...@sip.test.com set(continue_on_fail=true)
2014-02-25 00:10:45.063687 [DEBUG] mod_dptools.c:1402 sofia/sipinterface_1/us...@sip.test.com SET [continue_on_fail]=[true]
EXECUTE sofia/sipinterface_1/us...@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/us...@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/+918146...@sip.sipnl.net)
2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/us...@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/us...@sip.test.com EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[ecal...@kaz2.test.nl] to event
2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/us...@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/+918146...@sip.sipnl.net [2e446736-9ddb-11e3-ae9b-69d00812b6c2]
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:4456 (sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:2821 sofia/sipinterface_1/+918146...@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/+918146...@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/+918146...@sip.sipnl.net) State INIT
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:87 sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net Standard INIT
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:507 (sofia/sipinterface_1/+918146...@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/+918146...@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/+918146...@sip.sipnl.net) State ROUTING
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/+918146...@sip.sipnl.net SOFIA ROUTING
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:67 (sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/+918146...@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/+918146...@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/+918146...@sip.sipnl.net) State CONSUME_MEDIA
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:542 (sofia/sipinterface_1/+918146...@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 ecal...@kaz2.test.nl <2.11955.4>
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/+918146...@sip.sipnl.net entering state [terminated][503]
2014-02-25 00:10:45.103685 [NOTICE] sofia.c:6733 Hangup sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net [KILL]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net) State HANGUP
2014-02-25 00:10:45.103685 [DEBUG] mod_sofia.c:413 Channel sofia/sipinterface_1/+918146...@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/+918146...@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/+918146...@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/+918146...@sip.sipnl.net) Callstate Change DOWN -> HANGUP
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:499 (sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net) State REPORTING
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:102 sofia/sipinterface_1/+918146...@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/+918146...@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/+918146...@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/+918146...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1591 Session 15 (sofia/sipinterface_1/+918146...@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/us...@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/us...@sip.test.com park()
2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1609 Session 15 (sofia/sipinterface_1/+918146...@sip.sipnl.net) Ended
2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1613 Close Channel sofia/sipinterface_1/+918146...@sip.sipnl.net [CS_DESTROY]
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:618 (sofia/sipinterface_1/+918146...@sip.sipnl.net) Callstate Change HANGUP -> DOWN
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:621 (sofia/sipinterface_1/+918146...@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/+918146...@sip.sipnl.net) State DESTROY
2014-02-25 00:10:45.123885 [DEBUG] mod_sofia.c:323 sofia/sipinterface_1/+918146...@sip.sipnl.net SOFIA DESTROY
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:109 sofia/sipinterface_1/+918146...@sip.sipnl.net Standard DESTROY
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:631 (sofia/sipinterface_1/+918146...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:45.183685 [DEBUG] switch_ivr.c:615 sofia/sipinterface_1/us...@sip.test.com Command Execute pre_answer()
EXECUTE sofia/sipinterface_1/us...@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/us...@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/us...@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/us...@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/us...@sip.test.com!
2014-02-25 00:10:45.183685 [DEBUG] switch_channel.c:3405 (sofia/sipinterface_1/us...@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/us...@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:us...@sip.test.com>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
To: <sip:+91814...@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:+91814...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:45.183685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/us...@sip.test.com entering state [early][183]
2014-02-25 00:10:45.303686 [NOTICE] kazoo_node.c:285 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|executing playback ${http_get(http://127.0.0.1:15984/system_media/fault-can_not_be_completed_at_this_time/fault-can_not_be_completed_at_this_time.wav)}
2014-02-25 00:10:45.303686 [DEBUG] switch_core_session.c:1183 Send signal sofia/sipinterface_1/us...@sip.test.com [BREAK]
2014-02-25 00:10:45.303686 [DEBUG] switch_ivr.c:615 sofia/sipinterface_1/us...@sip.test.com Command Execute playback(${http_get(http://127.0.0.1:15984/system_media/fault-can_not_be_completed_at_this_time/fault-can_not_be_completed_at_this_time.wav)})
2014-02-25 00:10:45.323688 [DEBUG] mod_http_cache.c:523 Locked cache
2014-02-25 00:10:45.323688 [DEBUG] mod_http_cache.c:651 Cache HIT: size = 1 (0 MB), hit ratio = 8/9
2014-02-25 00:10:45.323688 [DEBUG] mod_http_cache.c:534 Unlocked cache
EXECUTE sofia/sipinterface_1/us...@sip.test.com playback(/usr/share/freeswitch/http_cache/39/6c5fb6-9d53-11e3-adae-69d00812b6c2.wav)
2014-02-25 00:10:45.323688 [DEBUG] switch_core_file.c:216 File /usr/share/freeswitch/http_cache/39/6c5fb6-9d53-11e3-adae-69d00812b6c2.wav sample rate 16000 doesn't match requested rate 8000
2014-02-25 00:10:45.323688 [DEBUG] switch_ivr_play_say.c:1315 Codec Activated L16@8000hz 1 channels 20ms
2014-02-25 00:10:46.603692 [INFO] switch_rtp.c:5174 Auto Changing port from 112.196.33.74:4226 to 112.196.33.74:62840
2014-02-25 00:10:49.503708 [DEBUG] switch_ivr_play_say.c:1719 done playing file /usr/share/freeswitch/http_cache/39/6c5fb6-9d53-11e3-adae-69d00812b6c2.wav
2014-02-25 00:10:49.503708 [NOTICE] kazoo_node.c:285 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|executing respond 503 Normal temporary failure
2014-02-25 00:10:49.503708 [DEBUG] switch_core_session.c:1183 Send signal sofia/sipinterface_1/us...@sip.test.com [BREAK]
2014-02-25 00:10:49.543698 [DEBUG] switch_ivr.c:615 sofia/sipinterface_1/us...@sip.test.com Command Execute respond(503 Normal temporary failure)
EXECUTE sofia/sipinterface_1/us...@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/us...@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/us...@sip.test.com [KILL]
2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/us...@sip.test.com [BREAK]
2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:2852 sofia/sipinterface_1/us...@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/us...@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/us...@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/us...@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/us...@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/us...@sip.test.com) State HANGUP
2014-02-25 00:10:49.543698 [DEBUG] mod_sofia.c:407 sofia/sipinterface_1/us...@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/us...@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/us...@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/us...@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/us...@sip.test.com) Callstate Change EARLY -> HANGUP
2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:499 (sofia/sipinterface_1/us...@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/us...@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:us...@sip.test.com>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
To: <sip:+91814...@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/us...@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:+91814...@sip.test.com>;party=calling;privacy=off;screen=no
can anybody advise me what is the problem?And how it can be solved?
Regards,
Vinay
Darren Schreiber
Feb 25, 2014, 12:37:03 AM2/25/14
to 2600h...@googlegroups.com
Hi,
Thanks for writing.
2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/+91…@sip.sipnl.net entering state [terminated][503]
That line is pretty telling… It means the channel is actually setup. and since it looks like you have SIP trace turned on, assuming you didn’t delete that part, I agree, no INVITE was sent out.
Only reasons I know this can happen are if DNS is failing. Please be sure sip.sipnl.net is actually resolvable. If you have put the FreeSWITCH boxes on a local interface as well in your setup they must have an interface
available that is on a public IP to be able to route outbound to the carrier. They do not route outbound via Kamailio.
Please check these two items and let me know.
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/+91814...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:45.043686 [DEBUG] switch_channel.c:3098 (sofia/sipinterface_1/us...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:530 (sofia/sipinterface_1/us...@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/us...@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/us...@sip.test.com) State ROUTING
2014-02-25 00:10:45.063687 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/us...@sip.test.com SOFIA ROUTING
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:164 sofia/sipinterface_1/us...@sip.test.com Standard ROUTING
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:184 (sofia/sipinterface_1/us...@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/us...@sip.test.com [BREAK]
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/us...@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/us...@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/us...@sip.test.com) State EXECUTE
2014-02-25 00:10:45.063687 [DEBUG] mod_sofia.c:178 sofia/sipinterface_1/us...@sip.test.com SOFIA EXECUTE
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:256 sofia/sipinterface_1/us...@sip.test.com Standard EXECUTE
EXECUTE sofia/sipinterface_1/us...@sip.test.com set(ignore_display_updates=true)
2014-02-25 00:10:45.063687 [DEBUG] mod_dptools.c:1402 sofia/sipinterface_1/us...@sip.test.com SET [ignore_display_updates]=[true]
EXECUTE sofia/sipinterface_1/us...@sip.test.com set(continue_on_fail=true)
2014-02-25 00:10:45.063687 [DEBUG] mod_dptools.c:1402 sofia/sipinterface_1/us...@sip.test.com SET [continue_on_fail]=[true]
EXECUTE sofia/sipinterface_1/us...@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/us...@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/+91814...@sip.sipnl.net)
2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/us...@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/us...@sip.test.com EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[ecal...@kaz2.test.nl] to event
2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/us...@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/+91814...@sip.sipnl.net [2e446736-9ddb-11e3-ae9b-69d00812b6c2]
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:4456 (sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:2821 sofia/sipinterface_1/+91814...@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/+91814...@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/+91814...@sip.sipnl.net) State INIT
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:87 sofia/sipinterface_1/+91814...@sip.sipnl.net SOFIA INIT
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:4456 (sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:2821 sofia/sipinterface_1/+91814...@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/+91814...@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/+91814...@sip.sipnl.net) State INIT
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:87 sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net Standard INIT
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:507 (sofia/sipinterface_1/+91814...@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/+91814...@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/+91814...@sip.sipnl.net) State ROUTING
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/+91814...@sip.sipnl.net SOFIA ROUTING
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:67 (sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/+91814...@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/+91814...@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/+91814...@sip.sipnl.net) State CONSUME_MEDIA
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:542 (sofia/sipinterface_1/+91814...@sip.sipnl.net) State CONSUME_MEDIA going to sleep
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:507 (sofia/sipinterface_1/+91814...@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/+91814...@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/+91814...@sip.sipnl.net) State ROUTING
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/+91814...@sip.sipnl.net SOFIA ROUTING
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:67 (sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/+91814...@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/+91814...@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/+91814...@sip.sipnl.net) State CONSUME_MEDIA
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:542 (sofia/sipinterface_1/+91814...@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 ecal...@kaz2.test.nl <2.11955.4>
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal
sofia/sipinterface_1/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/+91814...@sip.sipnl.net entering state [terminated][503]
2014-02-25 00:10:45.103685 [NOTICE] sofia.c:6733 Hangup sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net [KILL]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net) State HANGUP
2014-02-25 00:10:45.103685 [DEBUG] mod_sofia.c:413 Channel sofia/sipinterface_1/+91814...@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/+91814...@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/+91814...@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/+91814...@sip.sipnl.net) Callstate Change DOWN -> HANGUP
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:499 (sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net) State REPORTING
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:102 sofia/sipinterface_1/+91814...@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/+91814...@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/+91814...@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/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1591 Session 15 (sofia/sipinterface_1/+91814...@sip.sipnl.net) Locked, Waiting on external entities
2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/+91814...@sip.sipnl.net entering state [terminated][503]
2014-02-25 00:10:45.103685 [NOTICE] sofia.c:6733 Hangup sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net [KILL]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net) State HANGUP
2014-02-25 00:10:45.103685 [DEBUG] mod_sofia.c:413 Channel sofia/sipinterface_1/+91814...@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/+91814...@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/+91814...@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/+91814...@sip.sipnl.net) Callstate Change DOWN -> HANGUP
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:499 (sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net) State REPORTING
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:102 sofia/sipinterface_1/+91814...@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/+91814...@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/+91814...@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/+91814...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1591 Session 15 (sofia/sipinterface_1/+91814...@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/us...@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/us...@sip.test.com park()
2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1609 Session 15 (sofia/sipinterface_1/+91814...@sip.sipnl.net) Ended
2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1613 Close Channel sofia/sipinterface_1/+91814...@sip.sipnl.net [CS_DESTROY]
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:618 (sofia/sipinterface_1/+91814...@sip.sipnl.net) Callstate Change HANGUP -> DOWN
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:621 (sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net) State DESTROY
2014-02-25 00:10:45.123885 [DEBUG] mod_sofia.c:323 sofia/sipinterface_1/+91814...@sip.sipnl.net SOFIA DESTROY
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:109 sofia/sipinterface_1/+91814...@sip.sipnl.net Standard DESTROY
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:631 (sofia/sipinterface_1/+91814...@sip.sipnl.net) State DESTROY going to sleep
2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1613 Close Channel sofia/sipinterface_1/+91814...@sip.sipnl.net [CS_DESTROY]
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:618 (sofia/sipinterface_1/+91814...@sip.sipnl.net) Callstate Change HANGUP -> DOWN
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:621 (sofia/sipinterface_1/+91814...@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/+91814...@sip.sipnl.net) State DESTROY
2014-02-25 00:10:45.123885 [DEBUG] mod_sofia.c:323 sofia/sipinterface_1/+91814...@sip.sipnl.net SOFIA DESTROY
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:109 sofia/sipinterface_1/+91814...@sip.sipnl.net Standard DESTROY
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:631 (sofia/sipinterface_1/+91814...@sip.sipnl.net) State DESTROY going to sleep
Contact: <sip:+91814...@31.220.27.158:11000;transport=udp>
--
You received this message because you are subscribed to the Google Groups "2600hz-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email to 2600hz-dev+...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
You received this message because you are subscribed to the Google Groups "2600hz-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email to 2600hz-dev+...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
vinay saini
Feb 25, 2014, 1:09:51 AM2/25/14
to 2600h...@googlegroups.com
Hi Darren,
thanks for your quick response.
as you asked me to check, sip.sipnl.net is resolvable from the freeswitch server I can do ping to it.
and by this line "in your setup they must have an interface available that is on a public IP to be able to route outbound to the carrier." I dont understand properly what you want say. Can you explain me how do I check it.
-Vinay
thanks for your quick response.
as you asked me to check, sip.sipnl.net is resolvable from the freeswitch server I can do ping to it.
and by this line "in your setup they must have an interface available that is on a public IP to be able to route outbound to the carrier." I dont understand properly what you want say. Can you explain me how do I check it.
-Vinay
On Tuesday, February 25, 2014 11:02:30 AM UTC+5:30, vinay saini wrote:
Hi all,
I have deployed Kazoo on six server,which have
2-kazoo server
2-freeswitch server
2-bigcouch server
All of them are clustered together and working fine for device to device calling.But I found problem when making an outbound call through local carrier.
According to kazoo logs I can see that kazoo is forwarding local resource information to the freeswitch but freeswitch is not sending INVITE to the carrier.These are the freeswitch logs which is giving error- 503 Normal temporary failure.
INVITE sip:+91814...@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:us...@sip.test.com>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
To: <sip:+91814...@sip.test.com>
Contact: <sip:us...@112.196.33.74:62926;ob>
Call-ID: 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
CSeq: 26826 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
User-Agent: CSipSimple_A89-15/r2330
Proxy-Authorization: Digest username="user1", realm="sip.test.com", nonce="2da67792-9ddb-11e3-ae8b-69d00812b6c2", uri="sip:+918146234576@sip.test.com", response="894cfec80fc7a1c04b2ad7b46eb1c4c5", algorithm=MD5, cnonce="y6HH8DROqT9Ue8iZVcHNFRyB.LGnEDII", qop=auth, nc=00000001
2014-02-25 00:10:44.243689 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
2014-02-25 00:10:44.243689 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
2014-02-25 00:10:44.263688 [DEBUG] sofia.c:8156 1 acls to check for proxy
2014-02-25 00:10:44.263688 [DEBUG] sofia.c:8161 checking 88.80.160.31 against acl authoritative
2014-02-25 00:10:44.263688 [INFO] sofia.c:8163 88.80.160.31 is a proxy according to the authoritative acl
2014-02-25 00:10:44.263688 [DEBUG] sofia.c:8173 network ip is a proxy
2014-02-25 00:10:44.263688 [DEBUG] sofia.c:8177 found auth ip [X-AUTH-IP] header of [112.196.33.74]
2014-02-25 00:10:44.263688 [DEBUG] sofia.c:8201 IP 88.80.160.31 Rejected by acl "trusted". Falling back to Digest auth.
2014-02-25 00:10:44.263688 [DEBUG] kazoo_fetch_agent.c:216 Sending directory XML request (2dc8752c-9ddb-11e3-ae8c-69d00812b6c2) to ecal...@kaz2.test.nl <2.1184.0>
2014-02-25 00:10:44.263688 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecal...@kaz2.test.nl <2.1184.0>
2014-02-25 00:10:44.383689 [DEBUG] kazoo_fetch_agent.c:277 Received directory XML (2dc8752c-9ddb-11e3-ae8c-69d00812b6c2) after 120ms: <document type="freeswitch/xml"><section name="directory"><domain name="sip.test.com"><user id="user1"><variables><variable name="ecallmgr_Inception" value="on-net"/><variable name="ecallmgr_Authorizing-Type" value="device"/><variable name="ecallmgr_Authorizing-ID" value="3b46b4ceec6bb18dd8985792d7b5693e"/><variable name="ecallmgr_Account-ID" value="502cc62fa8097dd6d753fea7c7ef91a1"/><variable name="ecallmgr_Realm" value="sip.test.com"/><variable name="ecallmgr_Username" value="user1"/></variables><params><param name="password" value="user1"/></params></user></domain></section></document>
2014-02-25 00:10:44.383689 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/user1@sip.test.com entering state [received][100]
2014-02-25 00:10:44.383689 [DEBUG] sofia.c:5899 Remote SDP:
v=0
o=- 3602293864 3602293864 IN IP4 112.196.33.74
s=pjmedia
c=IN IP4 112.196.33.74
t=0 0
m=audio 4226 RTP/AVP 99 0 8 101
c=IN IP4 112.196.33.74
a=rtpmap:99 SILK/24000
a=fmtp:99 useinbandfec=0
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:9246 IN IP4 112.196.33.74
2014-02-25 00:10:44.383689 [DEBUG] sofia.c:6144 (sofia/sipinterface_1/user1@sip.test.com) State Change CS_NEW -> CS_INIT
2014-02-25 00:10:44.383689 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/user1@sip.test.com) Running State Change CS_INIT
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:507 (sofia/sipinterface_1/user1@sip.test.com) State INIT
2014-02-25 00:10:44.383689 [DEBUG] mod_sofia.c:87 sofia/sipinterface_1/user1@sip.test.com SOFIA INIT
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/user1@sip.test.com Standard INIT
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/user1@sip.test.com) State Change CS_INIT -> CS_ROUTING
2014-02-25 00:10:44.383689 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:507 (sofia/sipinterface_1/user1@sip.test.com) State INIT going to sleep
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/user1@sip.test.com) Running State Change CS_ROUTING
2014-02-25 00:10:44.383689 [DEBUG] switch_channel.c:2179 (sofia/sipinterface_1/user1@sip.test.com) Callstate Change DOWN -> RINGING
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/user1@sip.test.com) State ROUTING
2014-02-25 00:10:44.383689 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/user1@sip.test.com SOFIA ROUTING
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:164 sofia/sipinterface_1/user1@sip.test.com Standard ROUTING
2014-02-25 00:10:44.383689 [INFO] mod_dialplan_xml.c:558 Processing user1 <user1>->+918146234576 in context context_2
2014-02-25 00:10:44.383689 [DEBUG] kazoo_fetch_agent.c:216 Sending dialplan XML request (2ddb9918-9ddb-11e3-ae8e-69d00812b6c2) to ecal...@kaz2.test.nl <2.1185.0>
2014-02-25 00:10:44.403683 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecal...@kaz2.test.nl <2.1185.0>
2014-02-25 00:10:44.543689 [DEBUG] kazoo_fetch_agent.c:277 Received dialplan XML (2ddb9918-9ddb-11e3-ae8e-69d00812b6c2) after 160ms: <document type="freeswitch/xml"><section name="dialplan" description="Route Park Response"><context name="context_2"><extension name="park"><condition><action application="log" data="NOTICE log|${uuid}|ecallmgr@kaz2.test.nl won call control"/><action application="export" data="ecallmgr_Ecallmgr-Node=ecal...@kaz2.test.nl"/><condition field="variable_ecallmgr_Bridge-ID" expression="^$"><action application="export" data="ecallmgr_Bridge-ID=${UUID}"/></condition><action application="set" data="ringback=%(2000,4000,440,480)"/><action application="set" data="transfer_ringback=%(2000,4000,440,480)"/><action application="park"/></condition></extension></context></section></document>
Dialplan: sofia/sipinterface_1/user1@sip.test.com parsing [context_2->park] continue=false
|--- Dialplan: Processing recursive conditions level:1 [park_recur_1] require-nested=TRUE
|--- Dialplan: sofia/sipinterface_1/user1@sip.test.com Regex (PASS) [park_recur_1] variable_ecallmgr_Bridge-ID() =~ /^$/ break=on-false
|--- Dialplan: sofia/sipinterface_1/user1@sip.test.com Action export(ecallmgr_Bridge-ID=${UUID})
Dialplan: sofia/sipinterface_1/user1@sip.test.com Absolute Condition [park]
Dialplan: sofia/sipinterface_1/user1@sip.test.com Action log(NOTICE log|${uuid}|ecallmgr@kaz2.test.nl won call control)
Dialplan: sofia/sipinterface_1/user1@sip.test.com Action export(ecallmgr_Ecallmgr-Node=ecal...@kaz2.test.nl)
Dialplan: sofia/sipinterface_1/user1@sip.test.com Action set(ringback=%(2000,4000,440,480))
Dialplan: sofia/sipinterface_1/user1@sip.test.com Action set(transfer_ringback=%(2000,4000,440,480))
Dialplan: sofia/sipinterface_1/user1@sip.test.com Action park()
2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:214 (sofia/sipinterface_1/user1@sip.test.com) State Change CS_ROUTING -> CS_EXECUTE
2014-02-25 00:10:44.543689 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/user1@sip.test.com) State ROUTING going to sleep
2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/user1@sip.test.com) Running State Change CS_EXECUTE
2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:530 (sofia/sipinterface_1/user1@sip.test.com) State EXECUTE
2014-02-25 00:10:44.543689 [DEBUG] mod_sofia.c:178 sofia/sipinterface_1/user1@sip.test.com SOFIA EXECUTE
2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:256 sofia/sipinterface_1/user1@sip.test.com Standard EXECUTE
EXECUTE sofia/sipinterface_1/user1@sip.test.com export(ecallmgr_Bridge-ID=0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO)
2014-02-25 00:10:44.543689 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [ecallmgr_Bridge-ID]=[0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO]
EXECUTE sofia/sipinterface_1/user1@sip.test.com log(NOTICE log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|ecal...@kaz2.test.nl won call control)
2014-02-25 00:10:44.543689 [NOTICE] mod_dptools.c:1634 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|ecal...@kaz2.test.nl won call control
EXECUTE sofia/sipinterface_1/user1@sip.test.com export(ecallmgr_Ecallmgr-Node=ecal...@kaz2.test.nl)
2014-02-25 00:10:44.543689 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [ecallmgr_Ecallmgr-Node]=[ecallm...@kaz2.test.nl]
EXECUTE sofia/sipinterface_1/user1@sip.test.com set(ringback=%(2000,4000,440,480))
2014-02-25 00:10:44.543689 [DEBUG] mod_dptools.c:1402 sofia/sipinterface_1/user1@sip.test.com SET [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/sipinterface_1/user1@sip.test.com set(transfer_ringback=%(2000,4000,440,480))
2014-02-25 00:10:44.543689 [DEBUG] mod_dptools.c:1402 sofia/sipinterface_1/user1@sip.test.com SET [transfer_ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/sipinterface_1/user1@sip.test.com park()
2014-02-25 00:10:44.543689 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecal...@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 ecal...@kaz2.test.nl <2.11883.4>
2014-02-25 00:10:44.723684 [INFO] kazoo_node.c:627 exec: uuid_setvar_multi(0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO effective_caller_id_name=Martin;effective_caller_id_number=+xxxxxxxxxxx;ecallmgr_Channel-Authorized=true;ecallmgr_Username=user1;ecallmgr_Realm=sip.test.com;ecallmgr_Account-ID=502cc62fa8097dd6d753fea7c7ef91a1;ecallmgr_Authorizing-ID=3b46b4ceec6bb18dd8985792d7b5693e;ecallmgr_Authorizing-Type=device;ecallmgr_Inception=on-net;ecallmgr_Fetch-ID=2ddb9918-9ddb-11e3-ae8e-69d00812b6c2)
2014-02-25 00:10:44.723684 [DEBUG] kazoo_node.c:1091 Sent erlang message to ecal...@kaz2.test.nl <2.11912.4>
freeswitch@internal>
2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: set ignore_display_updates=true
2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: set continue_on_fail=true
2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: export sip_redirect_context=context_2
2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: bridge {ignore_display_updates='true',ecallmgr_Account-ID='502cc62fa8097dd6d753fea7c7ef91a1',ecallmgr_Reseller-ID='cf9c1c7b7a5d5894bc0c0fbc9420c403',effective_caller_id_number='+xxxxxxxxxxx',effective_caller_id_name='Martin',origination_caller_id_number='+xxxxxxxxxxx',origination_caller_id_name='Martin',ignore_early_media='false',local_var_clobber='true'}[sip_auth_password='xxxxxxxxxxxx',sip_auth_username='xxxxxxxxxxx',ecallmgr_Global-Resource='false',ecallmgr_Resource-ID='b50436c83efa77bb94e1241c872fa7c0',absolute_codec_string='^^:PCMU:PCMA:G722:G7221@16000h:G7221@32000h',leg_progress_timeout='60',effective_callee_id_number='+918146234576',effective_callee_id_name='918146234576']sofia/sipinterface_1/+918146234576@sip.sipnl.net
2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: event Event-Name=CUSTOM,Event-Subclass=whistle::masquerade,whistle_event_name=CHANNEL_EXECUTE_COMPLETE,whistle_application_name=bridge
2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: park
2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:305 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|transfered call to xferext extension
2014-02-25 00:10:45.043686 [DEBUG] switch_core_session.c:1183 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
2014-02-25 00:10:45.043686 [DEBUG] switch_channel.c:3098 (sofia/sipinterface_1/user1@sip.test.com) State Change CS_EXECUTE -> CS_ROUTING
2014-02-25 00:10:45.043686 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:530 (sofia/sipinterface_1/user1@sip.test.com) State EXECUTE going to sleep
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/user1@sip.test.com) Running State Change CS_ROUTING
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/user1@sip.test.com) State ROUTING
2014-02-25 00:10:45.063687 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/user1@sip.test.com SOFIA ROUTING
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:164 sofia/sipinterface_1/user1@sip.test.com Standard ROUTING
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:184 (sofia/sipinterface_1/user1@sip.test.com) State Change CS_ROUTING -> CS_EXECUTE
2014-02-25 00:10:45.063687 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/user1@sip.test.com) State ROUTING going to sleep
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/user1@sip.test.com) Running State Change CS_EXECUTE
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:530 (sofia/sipinterface_1/user1@sip.test.com) State EXECUTE
2014-02-25 00:10:45.063687 [DEBUG] mod_sofia.c:178 sofia/sipinterface_1/user1@sip.test.com SOFIA EXECUTE
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:256 sofia/sipinterface_1/user1@sip.test.com Standard EXECUTE
EXECUTE sofia/sipinterface_1/user1@sip.test.com set(ignore_display_updates=true)
2014-02-25 00:10:45.063687 [DEBUG] mod_dptools.c:1402 sofia/sipinterface_1/user1@sip.test.com SET [ignore_display_updates]=[true]
EXECUTE sofia/sipinterface_1/user1@sip.test.com set(continue_on_fail=true)
2014-02-25 00:10:45.063687 [DEBUG] mod_dptools.c:1402 sofia/sipinterface_1/user1@sip.test.com SET [continue_on_fail]=[true]
EXECUTE sofia/sipinterface_1/user1@sip.test.com export(sip_redirect_context=context_2)
2014-02-25 00:10:45.063687 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [sip_redirect_context]=[context_2]
EXECUTE sofia/sipinterface_1/user1@sip.test.com bridge({ignore_display_updates='true',ecallmgr_Account-ID='502cc62fa8097dd6d753fea7c7ef91a1',ecallmgr_Reseller-ID='cf9c1c7b7a5d5894bc0c0fbc9420c403',effective_caller_id_number='+xxxxxxxxxxx',effective_caller_id_name='Martin',origination_caller_id_number='+xxxxxxxxxxx',origination_caller_id_name='Martin',ignore_early_media='false',local_var_clobber='true'}[sip_auth_password='xxxxxxxxxxxx',sip_auth_username='xxxxxxxxxxx',ecallmgr_Global-Resource='false',ecallmgr_Resource-ID='b50436c83efa77bb94e1241c872fa7c0',absolute_codec_string='^^:PCMU:PCMA:G722:G7221@16000h:G7221@32000h',leg_progress_timeout='60',effective_callee_id_number='+918146234576',effective_callee_id_name='918146234576']sofia/sipinterface_1/+918146234576@sip.sipnl.net)
2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/user1@sip.test.com EXPORTING[export_vars] [ecallmgr_Bridge-ID]=[0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO] to event
2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/user1@sip.test.com EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[ecallm...@kaz2.test.nl] to event
2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/user1@sip.test.com EXPORTING[export_vars] [sip_redirect_context]=[context_2] to event
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:2071 Parsing global variables
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [ignore_display_updates]=[true]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [ecallmgr_Account-ID]=[502cc62fa8097dd6d753fea7c7ef91a1]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [ecallmgr_Reseller-ID]=[cf9c1c7b7a5d5894bc0c0fbc9420c403]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [effective_caller_id_number]=[+xxxxxxxxxxx]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [effective_caller_id_name]=[Martin]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [origination_caller_id_number]=[+xxxxxxxxxxx]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [origination_caller_id_name]=[Martin]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [ignore_early_media]=[false]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [local_var_clobber]=[true]
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:2518 Parsing session specific variables
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [sip_auth_password]=[xxxxxxxxxxxx]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [sip_auth_username]=[xxxxxxxxxxx]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [ecallmgr_Global-Resource]=[false]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [ecallmgr_Resource-ID]=[b50436c83efa77bb94e1241c872fa7c0]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [absolute_codec_string]=[^^:PCMU:PCMA:G722:G7221@16000h:G7221@32000h]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [leg_progress_timeout]=[60]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [effective_callee_id_number]=[+918146234576]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing variable [effective_callee_id_name]=[918146234576]
2014-02-25 00:10:45.083685 [NOTICE] switch_channel.c:1055 New Channel sofia/sipinterface_1/+9181462345...@sip.sipnl.net [2e446736-9ddb-11e3-ae9b-69d00812b6c2]
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:4456 (sofia/sipinterface_1/+918146234...@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/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:2821 sofia/sipinterface_1/+9181462345...@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/+918146234...@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/+918146234...@sip.sipnl.net) State INIT
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:87 sofia/sipinterface_1/+9181462345...@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/+9181462345...@sip.sipnl.net Standard INIT
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/+918146234...@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/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:507 (sofia/sipinterface_1/+918146234...@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/+918146234...@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/+918146234...@sip.sipnl.net) State ROUTING
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/+9181462345...@sip.sipnl.net SOFIA ROUTING
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:67 (sofia/sipinterface_1/+918146234...@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/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/+918146234...@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/+918146234...@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/+918146234...@sip.sipnl.net) State CONSUME_MEDIA
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:542 (sofia/sipinterface_1/+918146234...@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 ecal...@kaz2.test.nl <2.11955.4>
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/+9181462345...@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/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/+9181462345...@sip.sipnl.net entering state [terminated][503]
2014-02-25 00:10:45.103685 [NOTICE] sofia.c:6733 Hangup sofia/sipinterface_1/+9181462345...@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/+9181462345...@sip.sipnl.net [KILL]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+918146234...@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/+918146234...@sip.sipnl.net) State HANGUP
2014-02-25 00:10:45.103685 [DEBUG] mod_sofia.c:413 Channel sofia/sipinterface_1/+9181462345...@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/+9181462345...@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/+918146234...@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/+918146234...@sip.sipnl.net) Callstate Change DOWN -> HANGUP
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:499 (sofia/sipinterface_1/+918146234...@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/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+918146234...@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/+918146234...@sip.sipnl.net) State REPORTING
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:102 sofia/sipinterface_1/+9181462345...@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/+918146234...@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/+918146234...@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/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1591 Session 15 (sofia/sipinterface_1/+918146234...@sip.sipnl.net) Locked, Waiting on external entities
2014-02-25 00:10:45.123885 [DEBUG] switch_ivr_originate.c:3678 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
2014-02-25 00:10:45.123885 [INFO] mod_dptools.c:3244 Originate Failed. Cause: NORMAL_TEMPORARY_FAILURE
EXECUTE sofia/sipinterface_1/user1@sip.test.com event(Event-Name=CUSTOM,Event-Subclass=whistle::masquerade,whistle_event_name=CHANNEL_EXECUTE_COMPLETE,whistle_application_name=bridge)
EXECUTE sofia/sipinterface_1/user1@sip.test.com park()
2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1609 Session 15 (sofia/sipinterface_1/+918146234...@sip.sipnl.net) Ended
2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1613 Close Channel sofia/sipinterface_1/+9181462345...@sip.sipnl.net [CS_DESTROY]
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:618 (sofia/sipinterface_1/+918146234...@sip.sipnl.net) Callstate Change HANGUP -> DOWN
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:621 (sofia/sipinterface_1/+918146234...@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/+918146234...@sip.sipnl.net) State DESTROY
2014-02-25 00:10:45.123885 [DEBUG] mod_sofia.c:323 sofia/sipinterface_1/+9181462345...@sip.sipnl.net SOFIA DESTROY
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:109 sofia/sipinterface_1/+9181462345...@sip.sipnl.net Standard DESTROY
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:631 (sofia/sipinterface_1/+918146234...@sip.sipnl.net) State DESTROY going to sleep
2014-02-25 00:10:45.183685 [NOTICE] kazoo_node.c:285 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|executing pre_answer
2014-02-25 00:10:45.183685 [DEBUG] switch_core_session.c:1183 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
2014-02-25 00:10:45.183685 [DEBUG] switch_ivr.c:615 sofia/sipinterface_1/user1@sip.test.com Command Execute pre_answer()
EXECUTE sofia/sipinterface_1/user1@sip.test.com pre_answer()
2014-02-25 00:10:45.183685 [INFO] mod_dptools.c:1260 Sending early media
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [SILK:99:24000:20:0]/[G7221:115:32000:20:48000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [SILK:99:24000:20:0]/[G7221:107:16000:20:32000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [SILK:99:24000:20:0]/[G722:9:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [SILK:99:24000:20:0]/[PCMU:0:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [SILK:99:24000:20:0]/[PCMA:8:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [SILK:99:24000:20:0]/[GSM:3:8000:20:13200]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMU:0:8000:20:64000]/[G7221:115:32000:20:48000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMU:0:8000:20:64000]/[G7221:107:16000:20:32000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3220 Audio Codec Compare [PCMU:0:8000:20:64000] ++++ is saved as a match
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMA:8:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMU:0:8000:20:64000]/[GSM:3:8000:20:13200]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMA:8:8000:20:64000]/[G7221:115:32000:20:48000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMA:8:8000:20:64000]/[G7221:107:16000:20:32000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMA:8:8000:20:64000]/[G722:9:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3220 Audio Codec Compare [PCMA:8:8000:20:64000] ++++ is saved as a match
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio Codec Compare [PCMA:8:8000:20:64000]/[GSM:3:8000:20:13200]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3092 Set telephone-event payload to 101
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:2125 Set Codec sofia/sipinterface_1/user1@sip.test.com PCMU/8000 20 ms 160 samples 64000 bits
2014-02-25 00:10:45.183685 [DEBUG] switch_core_codec.c:111 sofia/sipinterface_1/user1@sip.test.com Original read codec set to PCMU:0
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3398 Set 2833 dtmf send/recv payload to 101
2014-02-25 00:10:45.183685 [INFO] switch_nat.c:590 NAT port mapping disabled
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:4586 AUDIO RTP [sofia/sipinterface_1/user1@sip.test.com] 31.220.27.158 port 20696 -> 112.196.33.74 port 4226 codec: 0 ms: 20
2014-02-25 00:10:45.183685 [DEBUG] switch_rtp.c:3068 Starting timer [soft] 160 bytes per 20ms
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:4930 Set 2833 dtmf send payload to 101
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:4936 Set 2833 dtmf receive payload to 101
2014-02-25 00:10:45.183685 [NOTICE] sofia_media.c:92 Pre-Answer sofia/sipinterface_1/user1@sip.test.com!
2014-02-25 00:10:45.183685 [DEBUG] switch_channel.c:3405 (sofia/sipinterface_1/user1@sip.test.com) Callstate Change RINGING -> EARLY
2014-02-25 00:10:45.183685 [DEBUG] mod_sofia.c:2099 Ring SDP:
v=0
o=FreeSWITCH 1393284349 1393284350 IN IP4 31.220.27.158
s=FreeSWITCH
c=IN IP4 31.220.27.158
t=0 0
m=audio 20696 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2014-02-25 00:10:45.183685 [DEBUG] switch_core_session.c:903 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
2014-02-25 00:10:45.183685 [DEBUG] switch_ivr.c:959 Codec Activated L16@8000hz 1 channels 20ms
send 1297 bytes to udp/[88.80.160.31]:5060 at 05:10:45.197608:
------------------------------------------------------------------------
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 88.80.160.31;branch=z9hG4bKd602.9af44717.0
Via: SIP/2.0/UDP 112.196.33.74:11220;rport=62926;branch=z9hG4bKPj.w0giarvUkQ67HPw3uK5Z6NsdtAUWvEV
Record-Route: <sip:88.80.160.31;lr=on;ftag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz>
From: <sip:us...@sip.test.com>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
To: <sip:+91814...@sip.test.com>;tag=0KtN4j4SvttFc
Call-ID: 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
CSeq: 26826 INVITE
Contact: <sip:+91814...@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:+91814...@sip.test.com>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1393284349 1393284350 IN IP4 31.220.27.158
s=FreeSWITCH
c=IN IP4 31.220.27.158
t=0 0
m=audio 20696 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
2014-02-25 00:10:45.183685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
2014-02-25 00:10:45.183685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/user1@sip.test.com entering state [early][183]
2014-02-25 00:10:45.303686 [NOTICE] kazoo_node.c:285 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|executing playback ${http_get(http://127.0.0.1:15984/system_media/fault-can_not_be_completed_at_this_time/fault-can_not_be_completed_at_this_time.wav)}
2014-02-25 00:10:45.303686 [DEBUG] switch_core_session.c:1183 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
2014-02-25 00:10:45.303686 [DEBUG] switch_ivr.c:615 sofia/sipinterface_1/user1@sip.test.com Command Execute playback(${http_get(http://127.0.0.1:15984/system_media/fault-can_not_be_completed_at_this_time/fault-can_not_be_completed_at_this_time.wav)})
2014-02-25 00:10:45.323688 [DEBUG] mod_http_cache.c:523 Locked cache
2014-02-25 00:10:45.323688 [DEBUG] mod_http_cache.c:651 Cache HIT: size = 1 (0 MB), hit ratio = 8/9
2014-02-25 00:10:45.323688 [DEBUG] mod_http_cache.c:534 Unlocked cache
EXECUTE sofia/sipinterface_1/user1@sip.test.com playback(/usr/share/freeswitch/http_cache/39/6c5fb6-9d53-11e3-adae-69d00812b6c2.wav)
2014-02-25 00:10:45.323688 [DEBUG] switch_core_file.c:216 File /usr/share/freeswitch/http_cache/39/6c5fb6-9d53-11e3-adae-69d00812b6c2.wav sample rate 16000 doesn't match requested rate 8000
2014-02-25 00:10:45.323688 [DEBUG] switch_ivr_play_say.c:1315 Codec Activated L16@8000hz 1 channels 20ms
2014-02-25 00:10:46.603692 [INFO] switch_rtp.c:5174 Auto Changing port from 112.196.33.74:4226 to 112.196.33.74:62840
2014-02-25 00:10:49.503708 [DEBUG] switch_ivr_play_say.c:1719 done playing file /usr/share/freeswitch/http_cache/39/6c5fb6-9d53-11e3-adae-69d00812b6c2.wav
2014-02-25 00:10:49.503708 [NOTICE] kazoo_node.c:285 log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|executing respond 503 Normal temporary failure
2014-02-25 00:10:49.503708 [DEBUG] switch_core_session.c:1183 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
2014-02-25 00:10:49.543698 [DEBUG] switch_ivr.c:615 sofia/sipinterface_1/user1@sip.test.com Command Execute respond(503 Normal temporary failure)
EXECUTE sofia/sipinterface_1/user1@sip.test.com respond(503 Normal temporary failure)
2014-02-25 00:10:49.543698 [DEBUG] mod_sofia.c:1919 Responding with 503 [Normal temporary failure]
2014-02-25 00:10:49.543698 [NOTICE] mod_sofia.c:1978 Hangup sofia/sipinterface_1/user1@sip.test.com [CS_EXECUTE] [NORMAL_TEMPORARY_FAILURE]
2014-02-25 00:10:49.543698 [DEBUG] switch_channel.c:3212 Send signal sofia/sipinterface_1/user1@sip.test.com [KILL]
2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:2852 sofia/sipinterface_1/user1@sip.test.com skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2014-02-25 00:10:49.543698 [DEBUG] switch_ivr.c:658 sofia/sipinterface_1/user1@sip.test.com skip receive message [AUDIO_SYNC] (channel is hungup already)
2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:2852 sofia/sipinterface_1/user1@sip.test.com skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:530 (sofia/sipinterface_1/user1@sip.test.com) State EXECUTE going to sleep
2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/user1@sip.test.com) Running State Change CS_HANGUP
2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:731 (sofia/sipinterface_1/user1@sip.test.com) State HANGUP
2014-02-25 00:10:49.543698 [DEBUG] mod_sofia.c:407 sofia/sipinterface_1/user1@sip.test.com Overriding SIP cause 503 with 503 from the other leg
2014-02-25 00:10:49.543698 [DEBUG] mod_sofia.c:413 Channel sofia/sipinterface_1/user1@sip.test.com hanging up, cause: NORMAL_TEMPORARY_FAILURE
2014-02-25 00:10:49.543698 [DEBUG] mod_sofia.c:553 Responding to INVITE with: 503
2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:58 sofia/sipinterface_1/user1@sip.test.com Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:731 (sofia/sipinterface_1/user1@sip.test.com) State HANGUP going to sleep
2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:744 (sofia/sipinterface_1/user1@sip.test.com) Callstate Change EARLY -> HANGUP
2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:499 (sofia/sipinterface_1/user1@sip.test.com) State Change CS_HANGUP -> CS_REPORTING
2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/user1@sip.test.com [BREAK]
send 910 bytes to udp/[88.80.160.31]:5060 at 05:10:49.558765:
------------------------------------------------------------------------
SIP/2.0 503 Normal temporary failure
Via: SIP/2.0/UDP 88.80.160.31;branch=z9hG4bKd602.9af44717.0
Via: SIP/2.0/UDP 112.196.33.74:11220;rport=62926;branch=z9hG4bKPj.w0giarvUkQ67HPw3uK5Z6NsdtAUWvEV
From: <sip:us...@sip.test.com>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
To: <sip:+91814...@sip.test.com>;tag=0KtN4j4SvttFc
Call-ID: 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
CSeq: 26826 INVITE
User-Agent: 2600hz2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/user1@sip.test.com) Running State Change CS_REPORTING
Darren Schreiber
Feb 25, 2014, 1:12:29 AM2/25/14
to 2600h...@googlegroups.com
Hi there,
I'm not sure how to respond much more on this… This sounds more like a basic FreeSWITCH problem. The bridge string is crafted properly I believe and is trying to
reach out to sip.sipnl.net but FreeSWITCH does not know how to get there. So it is returning a 503… but I do not think this is a SIP 503, it’s an indication that FreeSWITCH can’t even get that far. It can’t establish a network route to that host.
You may wish to ask on IRC in #freeswitch why you can’t bridge there, I believe this is outside of anything Kazoo is doing.
From: vinay saini <vinaysa...@gmail.com>
Reply-To: "2600h...@googlegroups.com" <2600h...@googlegroups.com>
Date: Monday, February 24, 2014 at 10:09 PM
To: "2600h...@googlegroups.com" <2600h...@googlegroups.com>
Reply-To: "2600h...@googlegroups.com" <2600h...@googlegroups.com>
Date: Monday, February 24, 2014 at 10:09 PM
To: "2600h...@googlegroups.com" <2600h...@googlegroups.com>
--
Bilal Abbasi
Mar 16, 2017, 1:05:04 PM3/16/17
to 2600hz-dev
Hi,
I came to this post as i got the exact same issue, that is reported to me by the support's guys.It was really new to me as well, so the mistake was that the IP on the carrier was entered with a small space before the IP address, that was not allowing FS to send invite to.
I just removed that and every thing starts working.
I posted the answer to help other when they come to this link.
Cheers
Abbasi
On Tuesday, 25 February 2014 10:32:30 UTC+5, Vinay Saini wrote:
Hi all,
I have deployed Kazoo on six server,which have
2-kazoo server
2-freeswitch server
2-bigcouch server
All of them are clustered together and working fine for device to device calling.But I found problem when making an outbound call through local carrier.
According to kazoo logs I can see that kazoo is forwarding local resource information to the freeswitch but freeswitch is not sending INVITE to the carrier.These are the freeswitch logs which is giving error- 503 Normal temporary failure.
INVITE sip:+918...@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
Contact: <sip:us...@112.196.33.74:62926;ob>
Call-ID: 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
CSeq: 26826 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
User-Agent: CSipSimple_A89-15/r2330
Proxy-Authorization: Digest username="user1", realm="sip.test.com", nonce="2da67792-9ddb-11e3-ae8b-69d00812b6c2", uri="sip:+918...@sip.test.com", response="894cfec80fc7a1c04b2ad7b46eb1c4c5", algorithm=MD5, cnonce="y6HH8DROqT9Ue8iZVcHNFRyB.LGnEDII", qop=auth, nc=00000001
2014-02-25 00:10:44.543689 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [ecallmgr_Ecallmgr-Node]=[ecallm...@kaz2.test.nl]
2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/us...@sip.test.com EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[ecallm...@kaz2.test.nl] to event
2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/us...@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/+9181462345...@sip.sipnl.net [2e446736-9ddb-11e3-ae9b-69d00812b6c2]
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:4456 (sofia/sipinterface_1/+918146234...@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/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:2821 sofia/sipinterface_1/+9181462345...@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/+918146234...@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/+918146234...@sip.sipnl.net) State INIT
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:87 sofia/sipinterface_1/+9181462345...@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/+9181462345...@sip.sipnl.net Standard INIT
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/+918146234...@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/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:507 (sofia/sipinterface_1/+918146234...@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/+918146234...@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/+918146234...@sip.sipnl.net) State ROUTING
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/+9181462345...@sip.sipnl.net SOFIA ROUTING
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:67 (sofia/sipinterface_1/+918146234...@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/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:523 (sofia/sipinterface_1/+918146234...@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/+918146234...@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/+918146234...@sip.sipnl.net) State CONSUME_MEDIA
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:542 (sofia/sipinterface_1/+918146234...@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 ecal...@kaz2.test.nl <2.11955.4>
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/+9181462345...@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/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send signal sofia/sipinterface_1/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel sofia/sipinterface_1/+9181462345...@sip.sipnl.net entering state [terminated][503]
2014-02-25 00:10:45.103685 [NOTICE] sofia.c:6733 Hangup sofia/sipinterface_1/+9181462345...@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/+9181462345...@sip.sipnl.net [KILL]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1383 Send signal sofia/sipinterface_1/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+918146234...@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/+918146234...@sip.sipnl.net) State HANGUP
2014-02-25 00:10:45.103685 [DEBUG] mod_sofia.c:413 Channel sofia/sipinterface_1/+9181462345...@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/+9181462345...@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/+918146234...@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/+918146234...@sip.sipnl.net) Callstate Change DOWN -> HANGUP
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:499 (sofia/sipinterface_1/+918146234...@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/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467 (sofia/sipinterface_1/+918146234...@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/+918146234...@sip.sipnl.net) State REPORTING
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:102 sofia/sipinterface_1/+9181462345...@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/+918146234...@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/+918146234...@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/+9181462345...@sip.sipnl.net [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1591 Session 15 (sofia/sipinterface_1/+918146234...@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/us...@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/us...@sip.test.com park()
2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1609 Session 15 (sofia/sipinterface_1/+918146234...@sip.sipnl.net) Ended
2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1613 Close Channel sofia/sipinterface_1/+9181462345...@sip.sipnl.net [CS_DESTROY]
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:618 (sofia/sipinterface_1/+918146234...@sip.sipnl.net) Callstate Change HANGUP -> DOWN
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:621 (sofia/sipinterface_1/+918146234...@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/+918146234...@sip.sipnl.net) State DESTROY
2014-02-25 00:10:45.123885 [DEBUG] mod_sofia.c:323 sofia/sipinterface_1/+9181462345...@sip.sipnl.net SOFIA DESTROY
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:109 sofia/sipinterface_1/+9181462345...@sip.sipnl.net Standard DESTROY
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:631 (sofia/sipinterface_1/+918146234...@sip.sipnl.net) State DESTROY going to sleep
From: <sip:...@sip.test.com>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
To: <sip:+918...@sip.test.com>;tag=0KtN4j4SvttFc
Call-ID: 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
CSeq: 26826 INVITE
Contact: <sip:+91814...@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:+918...@sip.test.com>;party=calling;privacy=off;screen=no
...
Reply all
Reply to author
Forward
0 new messages