[Freeswitch-users] Problem with sending Invite from Freeswitch to the carrier.
vinay
vinaysaini.1091 at gmail.com
Tue Feb 25 16:40:26 MSK 2014
hi,
I have successfully installed freeswitch and it is working fine
while calling from one sip device to other.
but I face problem when I make a outbound call using gateway.
According to freeswitch log I can see that freeswitch is getting gateway
configuration and it is suppose to send INVITE to the gateway,but the
problem is that freeswitch is not sending any INVITE to the gateway.
these are the fs_cli logs
INVITE sip:+918146234576 at sip.test.com
<mailto:sip%3A%2B918146234576 at sip.test.com> SIP/2.0
Record-Route: <sip:88.80.160.31;lr=on;ftag=
aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz>
Via: SIP/2.0/UDP 88.80.160.31;branch=z9hG4bKd602.9af44717.0
Via: SIP/2.0/UDP
112.196.33.74:11220;rport=62926;branch=z9hG4bKPj.w0giarvUkQ67HPw3uK5Z6NsdtAUWvEV
From: <sip:user1 at sip.test.com
<mailto:sip%3Auser1 at sip.test.com>>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
To: <sip:+918146234576 at sip.test.com
<mailto:sip%3A%2B918146234576 at sip.test.com>>
Contact: <sip:user1 at 112.196.33.74:62926;ob>
Call-ID: 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
CSeq: 26826 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE,
NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
User-Agent: CSipSimple_A89-15/r2330
Proxy-Authorization: Digest username="user1",
realm="sip.test.com <http://sip.test.com>",
nonce="2da67792-9ddb-11e3-ae8b-69d00812b6c2",
uri="sip:+918146234576 at sip.test.com
<mailto:sip%3A%2B918146234576 at sip.test.com>",
response="894cfec80fc7a1c04b2ad7b46eb1c4c5", algorithm=MD5,
cnonce="y6HH8DROqT9Ue8iZVcHNFRyB.LGnEDII", qop=auth, nc=00000001
Content-Type: application/sdp
Content-Length: 344
X-AUTH-IP: 112.196.33.74
v=0
o=- 3602293864 3602293864 IN IP4 112.196.33.74
s=pjmedia
c=IN IP4 112.196.33.74
t=0 0
m=audio 4226 RTP/AVP 99 0 8 101
c=IN IP4 112.196.33.74
a=rtcp:9246 IN IP4 112.196.33.74
a=sendrecv
a=rtpmap:99 SILK/24000
a=fmtp:99 useinbandfec=0
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
------------------------------------------------------------------------
send 469 bytes to udp/[88.80.160.31]:5060 at 05:10:44.257584:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 88.80.160.31;branch=z9hG4bKd602.9af44717.0
Via: SIP/2.0/UDP
112.196.33.74:11220;rport=62926;branch=z9hG4bKPj.w0giarvUkQ67HPw3uK5Z6NsdtAUWvEV
Record-Route:
<sip:88.80.160.31;lr=on;ftag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz>
From: <sip:user1 at sip.test.com
<mailto:sip%3Auser1 at sip.test.com>>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
To: <sip:+918146234576 at sip.test.com
<mailto:sip%3A%2B918146234576 at sip.test.com>>
Call-ID: 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
CSeq: 26826 INVITE
User-Agent: 2600hz
Content-Length: 0
------------------------------------------------------------------------
2014-02-25 00:10:44.243689 [DEBUG] sofia.c:1937 Re-attaching to
session 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
2014-02-25 00:10:44.243689 [DEBUG] switch_core_session.c:1048 Send
signal sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> [BREAK]
2014-02-25 00:10:44.243689 [DEBUG] switch_core_session.c:1048 Send
signal sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> [BREAK]
2014-02-25 00:10:44.263688 [DEBUG] sofia.c:8156 1 acls to check for
proxy
2014-02-25 00:10:44.263688 [DEBUG] sofia.c:8161 checking
88.80.160.31 against acl authoritative
2014-02-25 00:10:44.263688 [INFO] sofia.c:8163 88.80.160.31 is a
proxy according to the authoritative acl
2014-02-25 00:10:44.263688 [DEBUG] sofia.c:8173 network ip is a proxy
2014-02-25 00:10:44.263688 [DEBUG] sofia.c:8177 found auth ip
[X-AUTH-IP] header of [112.196.33.74]
2014-02-25 00:10:44.263688 [DEBUG] sofia.c:8201 IP 88.80.160.31
Rejected by acl "trusted". Falling back to Digest auth.
2014-02-25 00:10:44.263688 [DEBUG] kazoo_fetch_agent.c:216 Sending
directory XML request (2dc8752c-9ddb-11e3-ae8c-69d00812b6c2) to
ecallmgr at kaz2.test.nl <mailto:ecallmgr at kaz2.test.nl> <2.1184.0>
2014-02-25 00:10:44.263688 [DEBUG] kazoo_node.c:1091 Sent erlang
message to ecallmgr at kaz2.test.nl <mailto:ecallmgr at kaz2.test.nl> <2.1184.0>
2014-02-25 00:10:44.383689 [DEBUG] kazoo_fetch_agent.c:277 Received
directory XML (2dc8752c-9ddb-11e3-ae8c-69d00812b6c2) after 120ms:
<document type="freeswitch/xml"><section name="directory"><domain
name="sip.test.com <http://sip.test.com>"><user
id="user1"><variables><variable name="ecallmgr_Inception"
value="on-net"/><variable name="ecallmgr_Authorizing-Type"
value="device"/><variable name="ecallmgr_Authorizing-ID"
value="3b46b4ceec6bb18dd8985792d7b5693e"/><variable
name="ecallmgr_Account-ID"
value="502cc62fa8097dd6d753fea7c7ef91a1"/><variable
name="ecallmgr_Realm" value="sip.test.com
<http://sip.test.com>"/><variable name="ecallmgr_Username"
value="user1"/></variables><params><param name="password"
value="user1"/></params></user></domain></section></document>
2014-02-25 00:10:44.383689 [DEBUG] sofia.c:5889 Channel
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
entering state [received][100]
2014-02-25 00:10:44.383689 [DEBUG] sofia.c:5899 Remote SDP:
v=0
o=- 3602293864 3602293864 IN IP4 112.196.33.74
s=pjmedia
c=IN IP4 112.196.33.74
t=0 0
m=audio 4226 RTP/AVP 99 0 8 101
c=IN IP4 112.196.33.74
a=rtpmap:99 SILK/24000
a=fmtp:99 useinbandfec=0
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:9246 IN IP4 112.196.33.74
2014-02-25 00:10:44.383689 [DEBUG] sofia.c:6144
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State Change CS_NEW -> CS_INIT
2014-02-25 00:10:44.383689 [DEBUG] switch_core_session.c:1383 Send
signal sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> [BREAK]
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:467
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
Running State Change CS_INIT
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:507
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State INIT
2014-02-25 00:10:44.383689 [DEBUG] mod_sofia.c:87
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
SOFIA INIT
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:40
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
Standard INIT
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:48
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State Change CS_INIT -> CS_ROUTING
2014-02-25 00:10:44.383689 [DEBUG] switch_core_session.c:1383 Send
signal sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> [BREAK]
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:507
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State INIT going to sleep
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:467
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
Running State Change CS_ROUTING
2014-02-25 00:10:44.383689 [DEBUG] switch_channel.c:2179
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
Callstate Change DOWN -> RINGING
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:523
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State ROUTING
2014-02-25 00:10:44.383689 [DEBUG] mod_sofia.c:123
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
SOFIA ROUTING
2014-02-25 00:10:44.383689 [DEBUG] switch_core_state_machine.c:164
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
Standard ROUTING
2014-02-25 00:10:44.383689 [INFO] mod_dialplan_xml.c:558 Processing
user1 <user1>->+918146234576 in context context_2
2014-02-25 00:10:44.383689 [DEBUG] kazoo_fetch_agent.c:216 Sending
dialplan XML request (2ddb9918-9ddb-11e3-ae8e-69d00812b6c2) to
ecallmgr at kaz2.test.nl <mailto:ecallmgr at kaz2.test.nl> <2.1185.0>
2014-02-25 00:10:44.403683 [DEBUG] kazoo_node.c:1091 Sent erlang
message to ecallmgr at kaz2.test.nl <mailto:ecallmgr at kaz2.test.nl> <2.1185.0>
2014-02-25 00:10:44.543689 [DEBUG] kazoo_fetch_agent.c:277 Received
dialplan XML (2ddb9918-9ddb-11e3-ae8e-69d00812b6c2) after 160ms:
<document type="freeswitch/xml"><section name="dialplan"
description="Route Park Response"><context name="context_2"><extension
name="park"><condition><action application="log" data="NOTICE
log|${uuid}|ecallmgr at kaz2.test.nl <mailto:ecallmgr at kaz2.test.nl> won
call control"/><action application="export"
data="ecallmgr_Ecallmgr-Node=ecallmgr at kaz2.test.nl
<mailto:ecallmgr at kaz2.test.nl>"/><condition
field="variable_ecallmgr_Bridge-ID" expression="^$"><action
application="export"
data="ecallmgr_Bridge-ID=${UUID}"/></condition><action application="set"
data="ringback=%(2000,4000,440,480)"/><action application="set"
data="transfer_ringback=%(2000,4000,440,480)"/><action
application="park"/></condition></extension></context></section></document>
Dialplan: sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> parsing [context_2->park] continue=false
|--- Dialplan: Processing recursive conditions level:1
[park_recur_1] require-nested=TRUE
|--- Dialplan: sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> Regex (PASS) [park_recur_1]
variable_ecallmgr_Bridge-ID() =~ /^$/ break=on-false
|--- Dialplan: sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> Action export(ecallmgr_Bridge-ID=${UUID})
Dialplan: sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> Absolute Condition [park]
Dialplan: sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> Action log(NOTICE
log|${uuid}|ecallmgr at kaz2.test.nl <mailto:ecallmgr at kaz2.test.nl> won
call control)
Dialplan: sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> Action
export(ecallmgr_Ecallmgr-Node=ecallmgr at kaz2.test.nl
<mailto:ecallmgr at kaz2.test.nl>)
Dialplan: sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> Action set(ringback=%(2000,4000,440,480))
Dialplan: sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> Action
set(transfer_ringback=%(2000,4000,440,480))
Dialplan: sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> Action park()
2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:214
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State Change CS_ROUTING -> CS_EXECUTE
2014-02-25 00:10:44.543689 [DEBUG] switch_core_session.c:1383 Send
signal sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> [BREAK]
2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:523
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State ROUTING going to sleep
2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:467
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
Running State Change CS_EXECUTE
2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:530
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State EXECUTE
2014-02-25 00:10:44.543689 [DEBUG] mod_sofia.c:178
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
SOFIA EXECUTE
2014-02-25 00:10:44.543689 [DEBUG] switch_core_state_machine.c:256
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
Standard EXECUTE
EXECUTE sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com>
export(ecallmgr_Bridge-ID=0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO)
2014-02-25 00:10:44.543689 [DEBUG] switch_channel.c:1247 EXPORT
(export_vars) [ecallmgr_Bridge-ID]=[0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO]
EXECUTE sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> log(NOTICE
log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|ecallmgr at kaz2.test.nl
<mailto:ecallmgr at kaz2.test.nl> won call control)
2014-02-25 00:10:44.543689 [NOTICE] mod_dptools.c:1634
log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|ecallmgr at kaz2.test.nl
<mailto:ecallmgr at kaz2.test.nl> won call control
EXECUTE sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com>
export(ecallmgr_Ecallmgr-Node=ecallmgr at kaz2.test.nl
<mailto:ecallmgr at kaz2.test.nl>)
2014-02-25 00:10:44.543689 [DEBUG] switch_channel.c:1247 EXPORT
(export_vars) [ecallmgr_Ecallmgr-Node]=[ecallmgr at kaz2.test.nl
<mailto:ecallmgr at kaz2.test.nl>]
EXECUTE sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> set(ringback=%(2000,4000,440,480))
2014-02-25 00:10:44.543689 [DEBUG] mod_dptools.c:1402
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> SET
[ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> set(transfer_ringback=%(2000,4000,440,480))
2014-02-25 00:10:44.543689 [DEBUG] mod_dptools.c:1402
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> SET
[transfer_ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> park()
2014-02-25 00:10:44.543689 [DEBUG] kazoo_node.c:1091 Sent erlang
message to ecallmgr at kaz2.test.nl <mailto:ecallmgr at kaz2.test.nl> <2.11883.4>
2014-02-25 00:10:44.563813 [INFO] kazoo_node.c:627 exec:
uuid_setvar_multi(0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
ecallmgr_Channel-Authorized=true;ecallmgr_Account-ID=502cc62fa8097dd6d753fea7c7ef91a1)
2014-02-25 00:10:44.563813 [DEBUG] kazoo_node.c:1091 Sent erlang
message to ecallmgr at kaz2.test.nl <mailto:ecallmgr at kaz2.test.nl> <2.11883.4>
2014-02-25 00:10:44.723684 [INFO] kazoo_node.c:627 exec:
uuid_setvar_multi(0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
effective_caller_id_name=Martin;effective_caller_id_number=+xxxxxxxxxxx;ecallmgr_Channel-Authorized=true;ecallmgr_Username=user1;ecallmgr_Realm=sip.test.com
<http://sip.test.com>;ecallmgr_Account-ID=502cc62fa8097dd6d753fea7c7ef91a1;ecallmgr_Authorizing-ID=3b46b4ceec6bb18dd8985792d7b5693e;ecallmgr_Authorizing-Type=device;ecallmgr_Inception=on-net;ecallmgr_Fetch-ID=2ddb9918-9ddb-11e3-ae8e-69d00812b6c2)
2014-02-25 00:10:44.723684 [DEBUG] kazoo_node.c:1091 Sent erlang
message to ecallmgr at kaz2.test.nl <mailto:ecallmgr at kaz2.test.nl> <2.11912.4>
freeswitch at internal>
2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302
log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: set
ignore_display_updates=true
2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302
log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: set
continue_on_fail=true
2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302
log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: export
sip_redirect_context=context_2
2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302
log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: bridge
{ignore_display_updates='true',ecallmgr_Account-ID='502cc62fa8097dd6d753fea7c7ef91a1',ecallmgr_Reseller-ID='cf9c1c7b7a5d5894bc0c0fbc9420c403',effective_caller_id_number='+xxxxxxxxxxx',effective_caller_id_name='Martin',origination_caller_id_number='+xxxxxxxxxxx',origination_caller_id_name='Martin',ignore_early_media='false',local_var_clobber='true'}[sip_auth_password='xxxxxxxxxxxx',sip_auth_username='xxxxxxxxxxx',ecallmgr_Global-Resource='false',ecallmgr_Resource-ID='b50436c83efa77bb94e1241c872fa7c0',absolute_codec_string='^^:PCMU:PCMA:G722:G7221 at 16000h:G7221 at 32000h',leg_progress_timeout='60',effective_callee_id_number='+918146234576',effective_callee_id_name='918146234576']sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>
2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302
log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: event
Event-Name=CUSTOM,Event-Subclass=whistle::masquerade,whistle_event_name=CHANNEL_EXECUTE_COMPLETE,whistle_application_name=bridge
2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:302
log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|building xferext extension: park
2014-02-25 00:10:45.043686 [NOTICE] kazoo_node.c:305
log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|transfered call to xferext extension
2014-02-25 00:10:45.043686 [DEBUG] switch_core_session.c:1183 Send
signal sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> [BREAK]
2014-02-25 00:10:45.043686 [DEBUG] switch_channel.c:3098
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State Change CS_EXECUTE -> CS_ROUTING
2014-02-25 00:10:45.043686 [DEBUG] switch_core_session.c:1383 Send
signal sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> [BREAK]
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:530
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State EXECUTE going to sleep
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:467
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
Running State Change CS_ROUTING
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:523
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State ROUTING
2014-02-25 00:10:45.063687 [DEBUG] mod_sofia.c:123
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
SOFIA ROUTING
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:164
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
Standard ROUTING
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:184
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State Change CS_ROUTING -> CS_EXECUTE
2014-02-25 00:10:45.063687 [DEBUG] switch_core_session.c:1383 Send
signal sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> [BREAK]
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:523
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State ROUTING going to sleep
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:467
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
Running State Change CS_EXECUTE
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:530
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State EXECUTE
2014-02-25 00:10:45.063687 [DEBUG] mod_sofia.c:178
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
SOFIA EXECUTE
2014-02-25 00:10:45.063687 [DEBUG] switch_core_state_machine.c:256
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
Standard EXECUTE
EXECUTE sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> set(ignore_display_updates=true)
2014-02-25 00:10:45.063687 [DEBUG] mod_dptools.c:1402
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> SET
[ignore_display_updates]=[true]
EXECUTE sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> set(continue_on_fail=true)
2014-02-25 00:10:45.063687 [DEBUG] mod_dptools.c:1402
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> SET
[continue_on_fail]=[true]
EXECUTE sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> export(sip_redirect_context=context_2)
2014-02-25 00:10:45.063687 [DEBUG] switch_channel.c:1247 EXPORT
(export_vars) [sip_redirect_context]=[context_2]
EXECUTE sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com>
bridge({ignore_display_updates='true',ecallmgr_Account-ID='502cc62fa8097dd6d753fea7c7ef91a1',ecallmgr_Reseller-ID='cf9c1c7b7a5d5894bc0c0fbc9420c403',effective_caller_id_number='+xxxxxxxxxxx',effective_caller_id_name='Martin',origination_caller_id_number='+xxxxxxxxxxx',origination_caller_id_name='Martin',ignore_early_media='false',local_var_clobber='true'}[sip_auth_password='xxxxxxxxxxxx',sip_auth_username='xxxxxxxxxxx',ecallmgr_Global-Resource='false',ecallmgr_Resource-ID='b50436c83efa77bb94e1241c872fa7c0',absolute_codec_string='^^:PCMU:PCMA:G722:G7221 at 16000h:G7221 at 32000h',leg_progress_timeout='60',effective_callee_id_number='+918146234576',effective_callee_id_name='918146234576']sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>)
2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
EXPORTING[export_vars]
[ecallmgr_Bridge-ID]=[0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO] to event
2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[ecallmgr at kaz2.test.nl
<mailto:ecallmgr at kaz2.test.nl>] to event
2014-02-25 00:10:45.083685 [DEBUG] switch_channel.c:1201
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
EXPORTING[export_vars] [sip_redirect_context]=[context_2] to event
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:2071
Parsing global variables
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable [ignore_display_updates]=[true]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable [ecallmgr_Account-ID]=[502cc62fa8097dd6d753fea7c7ef91a1]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable [ecallmgr_Reseller-ID]=[cf9c1c7b7a5d5894bc0c0fbc9420c403]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable [effective_caller_id_number]=[+xxxxxxxxxxx]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable [effective_caller_id_name]=[Martin]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable [origination_caller_id_number]=[+xxxxxxxxxxx]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable [origination_caller_id_name]=[Martin]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable [ignore_early_media]=[false]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable [local_var_clobber]=[true]
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:2518
Parsing session specific variables
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable [sip_auth_password]=[xxxxxxxxxxxx]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable [sip_auth_username]=[xxxxxxxxxxx]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable [ecallmgr_Global-Resource]=[false]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable [ecallmgr_Resource-ID]=[b50436c83efa77bb94e1241c872fa7c0]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable
[absolute_codec_string]=[^^:PCMU:PCMA:G722:G7221 at 16000h:G7221 at 32000h]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable [leg_progress_timeout]=[60]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable [effective_callee_id_number]=[+918146234576]
2014-02-25 00:10:45.083685 [DEBUG] switch_event.c:1687 Parsing
variable [effective_callee_id_name]=[918146234576]
2014-02-25 00:10:45.083685 [NOTICE] switch_channel.c:1055 New
Channel sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> [2e446736-9ddb-11e3-ae9b-69d00812b6c2]
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:4456
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State Change CS_NEW -> CS_INIT
2014-02-25 00:10:45.083685 [DEBUG] switch_core_session.c:1383 Send
signal sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:2821
sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> Setting leg progress timeout to 60
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:467
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) Running State Change CS_INIT
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:507
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State INIT
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:87
sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> SOFIA INIT
2014-02-25 00:10:45.083685 [INFO] switch_nat.c:590 NAT port mapping
disabled
2014-02-25 00:10:45.083685 [DEBUG] sofia_glue.c:1225 Local SDP:
v=0
o=FreeSWITCH 1393277355 1393277356 IN IP4 31.220.27.158
s=FreeSWITCH
c=IN IP4 31.220.27.158
t=0 0
m=audio 27690 RTP/AVP 0 8 9 98 99 101 13
a=rtpmap:98 G7221/16000
a=fmtp:98 bitrate=32000
a=rtpmap:99 G7221/32000
a=fmtp:99 bitrate=48000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:40
sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> Standard INIT
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:48
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State Change CS_INIT -> CS_ROUTING
2014-02-25 00:10:45.083685 [DEBUG] switch_core_session.c:1383 Send
signal sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:507
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State INIT going to sleep
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:467
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) Running State Change CS_ROUTING
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:523
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State ROUTING
2014-02-25 00:10:45.083685 [DEBUG] mod_sofia.c:123
sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> SOFIA ROUTING
2014-02-25 00:10:45.083685 [DEBUG] switch_ivr_originate.c:67
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State Change CS_ROUTING ->
CS_CONSUME_MEDIA
2014-02-25 00:10:45.083685 [DEBUG] switch_core_session.c:1383 Send
signal sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> [BREAK]
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:523
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State ROUTING going to sleep
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:467
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) Running State Change CS_CONSUME_MEDIA
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:542
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State CONSUME_MEDIA
2014-02-25 00:10:45.083685 [DEBUG] switch_core_state_machine.c:542
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State CONSUME_MEDIA going to sleep
2014-02-25 00:10:45.083685 [INFO] kazoo_node.c:627 exec:
uuid_setvar_multi(2e446736-9ddb-11e3-ae9b-69d00812b6c2
ecallmgr_Channel-Authorized=true;ecallmgr_Global-Resource=false;ecallmgr_Reseller-ID=cf9c1c7b7a5d5894bc0c0fbc9420c403;ecallmgr_Account-ID=502cc62fa8097dd6d753fea7c7ef91a1)
2014-02-25 00:10:45.083685 [DEBUG] kazoo_node.c:1091 Sent erlang
message to ecallmgr at kaz2.test.nl <mailto:ecallmgr at kaz2.test.nl> <2.11955.4>
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send
signal sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel
sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> entering state [calling][0]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send
signal sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send
signal sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1048 Send
signal sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] sofia.c:5889 Channel
sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> entering state [terminated][503]
2014-02-25 00:10:45.103685 [NOTICE] sofia.c:6733 Hangup
sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> [CS_CONSUME_MEDIA]
[NORMAL_TEMPORARY_FAILURE]
2014-02-25 00:10:45.103685 [DEBUG] switch_channel.c:3212 Send
signal sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> [KILL]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1383 Send
signal sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) Running State Change CS_HANGUP
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:731
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State HANGUP
2014-02-25 00:10:45.103685 [DEBUG] mod_sofia.c:413 Channel
sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> hanging up, cause:
NORMAL_TEMPORARY_FAILURE
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:58
sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> Standard HANGUP, cause:
NORMAL_TEMPORARY_FAILURE
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:731
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State HANGUP going to sleep
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:744
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) Callstate Change DOWN -> HANGUP
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:499
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State Change CS_HANGUP -> CS_REPORTING
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1383 Send
signal sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:467
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) Running State Change CS_REPORTING
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:816
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State REPORTING
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:102
sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> Standard REPORTING, cause:
NORMAL_TEMPORARY_FAILURE
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:816
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State REPORTING going to sleep
2014-02-25 00:10:45.103685 [DEBUG] switch_core_state_machine.c:493
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State Change CS_REPORTING -> CS_DESTROY
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1383 Send
signal sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> [BREAK]
2014-02-25 00:10:45.103685 [DEBUG] switch_core_session.c:1591
Session 15 (sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) Locked, Waiting on external entities
2014-02-25 00:10:45.123885 [DEBUG] switch_ivr_originate.c:3678
Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
2014-02-25 00:10:45.123885 [INFO] mod_dptools.c:3244 Originate
Failed. Cause: NORMAL_TEMPORARY_FAILURE
EXECUTE sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com>
event(Event-Name=CUSTOM,Event-Subclass=whistle::masquerade,whistle_event_name=CHANNEL_EXECUTE_COMPLETE,whistle_application_name=bridge)
EXECUTE sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> park()
2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1609
Session 15 (sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) Ended
2014-02-25 00:10:45.123885 [NOTICE] switch_core_session.c:1613
Close Channel sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> [CS_DESTROY]
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:618
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) Callstate Change HANGUP -> DOWN
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:621
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) Running State Change CS_DESTROY
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:631
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State DESTROY
2014-02-25 00:10:45.123885 [DEBUG] mod_sofia.c:323
sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> SOFIA DESTROY
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:109
sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net> Standard DESTROY
2014-02-25 00:10:45.123885 [DEBUG] switch_core_state_machine.c:631
(sofia/sipinterface_1/+918146234576 at sip.sipnl.net
<mailto:918146234576 at sip.sipnl.net>) State DESTROY going to sleep
2014-02-25 00:10:45.183685 [NOTICE] kazoo_node.c:285
log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|executing pre_answer
2014-02-25 00:10:45.183685 [DEBUG] switch_core_session.c:1183 Send
signal sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> [BREAK]
2014-02-25 00:10:45.183685 [DEBUG] switch_ivr.c:615
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
Command Execute pre_answer()
EXECUTE sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> pre_answer()
2014-02-25 00:10:45.183685 [INFO] mod_dptools.c:1260 Sending early
media
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [SILK:99:24000:20:0]/[G7221:115:32000:20:48000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [SILK:99:24000:20:0]/[G7221:107:16000:20:32000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [SILK:99:24000:20:0]/[G722:9:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [SILK:99:24000:20:0]/[PCMU:0:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [SILK:99:24000:20:0]/[PCMA:8:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [SILK:99:24000:20:0]/[GSM:3:8000:20:13200]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [PCMU:0:8000:20:64000]/[G7221:115:32000:20:48000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [PCMU:0:8000:20:64000]/[G7221:107:16000:20:32000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3220 Audio
Codec Compare [PCMU:0:8000:20:64000] ++++ is saved as a match
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [PCMU:0:8000:20:64000]/[PCMA:8:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [PCMU:0:8000:20:64000]/[GSM:3:8000:20:13200]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [PCMA:8:8000:20:64000]/[G7221:115:32000:20:48000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [PCMA:8:8000:20:64000]/[G7221:107:16000:20:32000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [PCMA:8:8000:20:64000]/[G722:9:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3220 Audio
Codec Compare [PCMA:8:8000:20:64000] ++++ is saved as a match
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3166 Audio
Codec Compare [PCMA:8:8000:20:64000]/[GSM:3:8000:20:13200]
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3092 Set
telephone-event payload to 101
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:2125 Set
Codec sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> PCMU/8000 20 ms 160 samples 64000 bits
2014-02-25 00:10:45.183685 [DEBUG] switch_core_codec.c:111
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
Original read codec set to PCMU:0
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:3398 Set
2833 dtmf send/recv payload to 101
2014-02-25 00:10:45.183685 [INFO] switch_nat.c:590 NAT port mapping
disabled
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:4586 AUDIO
RTP [sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com>] 31.220.27.158 port 20696 -> 112.196.33.74
port 4226 codec: 0 ms: 20
2014-02-25 00:10:45.183685 [DEBUG] switch_rtp.c:3068 Starting timer
[soft] 160 bytes per 20ms
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:4930 Set
2833 dtmf send payload to 101
2014-02-25 00:10:45.183685 [DEBUG] switch_core_media.c:4936 Set
2833 dtmf receive payload to 101
2014-02-25 00:10:45.183685 [NOTICE] sofia_media.c:92 Pre-Answer
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>!
2014-02-25 00:10:45.183685 [DEBUG] switch_channel.c:3405
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
Callstate Change RINGING -> EARLY
2014-02-25 00:10:45.183685 [DEBUG] mod_sofia.c:2099 Ring SDP:
v=0
o=FreeSWITCH 1393284349 1393284350 IN IP4 31.220.27.158
s=FreeSWITCH
c=IN IP4 31.220.27.158
t=0 0
m=audio 20696 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2014-02-25 00:10:45.183685 [DEBUG] switch_core_session.c:903 Send
signal sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> [BREAK]
2014-02-25 00:10:45.183685 [DEBUG] switch_ivr.c:959 Codec Activated
L16 at 8000hz 1 channels 20ms
send 1297 bytes to udp/[88.80.160.31]:5060 at 05:10:45.197608:
------------------------------------------------------------------------
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 88.80.160.31;branch=z9hG4bKd602.9af44717.0
Via: SIP/2.0/UDP
112.196.33.74:11220;rport=62926;branch=z9hG4bKPj.w0giarvUkQ67HPw3uK5Z6NsdtAUWvEV
Record-Route:
<sip:88.80.160.31;lr=on;ftag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz>
From: <sip:user1 at sip.test.com
<mailto:sip%3Auser1 at sip.test.com>>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
To: <sip:+918146234576 at sip.test.com
<mailto:sip%3A%2B918146234576 at sip.test.com>>;tag=0KtN4j4SvttFc
Call-ID: 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
CSeq: 26826 INVITE
Contact: <sip:+918146234576 at 31.220.27.158:11000;transport=udp>
User-Agent: 2600hz
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE,
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: precondition, path, replaces
Allow-Events: talk, hold, conference, presence,
as-feature-event, dialog, line-seize, call-info, sla,
include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 222
Remote-Party-ID: "+918146234576" <sip:+918146234576 at sip.test.com
<mailto:sip%3A%2B918146234576 at sip.test.com>>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1393284349 1393284350 IN IP4 31.220.27.158
s=FreeSWITCH
c=IN IP4 31.220.27.158
t=0 0
m=audio 20696 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
2014-02-25 00:10:45.183685 [DEBUG] switch_core_session.c:1048 Send
signal sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> [BREAK]
2014-02-25 00:10:45.183685 [DEBUG] sofia.c:5889 Channel
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
entering state [early][183]
2014-02-25 00:10:45.303686 [NOTICE] kazoo_node.c:285
log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|executing playback
${http_get(http://127.0.0.1:15984/system_media/fault-can_not_be_completed_at_this_time/fault-can_not_be_completed_at_this_time.wav
<http://127.0.0.1:15984/system_media/fault-can_not_be_completed_at_this_time/fault-can_not_be_completed_at_this_time.wav>)}
2014-02-25 00:10:45.303686 [DEBUG] switch_core_session.c:1183 Send
signal sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> [BREAK]
2014-02-25 00:10:45.303686 [DEBUG] switch_ivr.c:615
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
Command Execute
playback(${http_get(http://127.0.0.1:15984/system_media/fault-can_not_be_completed_at_this_time/fault-can_not_be_completed_at_this_time.wav)
<http://127.0.0.1:15984/system_media/fault-can_not_be_completed_at_this_time/fault-can_not_be_completed_at_this_time.wav%29>})
2014-02-25 00:10:45.323688 [DEBUG] mod_http_cache.c:523 Locked cache
2014-02-25 00:10:45.323688 [DEBUG] mod_http_cache.c:651 Cache HIT:
size = 1 (0 MB), hit ratio = 8/9
2014-02-25 00:10:45.323688 [DEBUG] mod_http_cache.c:534 Unlocked cache
EXECUTE sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com>
playback(/usr/share/freeswitch/http_cache/39/6c5fb6-9d53-11e3-adae-69d00812b6c2.wav)
2014-02-25 00:10:45.323688 [DEBUG] switch_core_file.c:216 File
/usr/share/freeswitch/http_cache/39/6c5fb6-9d53-11e3-adae-69d00812b6c2.wav
sample rate 16000 doesn't match requested rate 8000
2014-02-25 00:10:45.323688 [DEBUG] switch_ivr_play_say.c:1315 Codec
Activated L16 at 8000hz 1 channels 20ms
2014-02-25 00:10:46.603692 [INFO] switch_rtp.c:5174 Auto Changing
port from 112.196.33.74:4226 <http://112.196.33.74:4226> to
112.196.33.74:62840 <http://112.196.33.74:62840>
2014-02-25 00:10:49.503708 [DEBUG] switch_ivr_play_say.c:1719 done
playing file
/usr/share/freeswitch/http_cache/39/6c5fb6-9d53-11e3-adae-69d00812b6c2.wav
2014-02-25 00:10:49.503708 [NOTICE] kazoo_node.c:285
log|0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO|executing respond 503 Normal
temporary failure
2014-02-25 00:10:49.503708 [DEBUG] switch_core_session.c:1183 Send
signal sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> [BREAK]
2014-02-25 00:10:49.543698 [DEBUG] switch_ivr.c:615
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
Command Execute respond(503 Normal temporary failure)
EXECUTE sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> respond(503 Normal temporary failure)
2014-02-25 00:10:49.543698 [DEBUG] mod_sofia.c:1919 Responding with
503 [Normal temporary failure]
2014-02-25 00:10:49.543698 [NOTICE] mod_sofia.c:1978 Hangup
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
[CS_EXECUTE] [NORMAL_TEMPORARY_FAILURE]
2014-02-25 00:10:49.543698 [DEBUG] switch_channel.c:3212 Send
signal sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> [KILL]
2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:1383 Send
signal sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> [BREAK]
2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:2852
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> skip
receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2014-02-25 00:10:49.543698 [DEBUG] switch_ivr.c:658
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> skip
receive message [AUDIO_SYNC] (channel is hungup already)
2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:2852
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com> skip
receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:530
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State EXECUTE going to sleep
2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:467
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
Running State Change CS_HANGUP
2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:731
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State HANGUP
2014-02-25 00:10:49.543698 [DEBUG] mod_sofia.c:407
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
Overriding SIP cause 503 with 503 from the other leg
2014-02-25 00:10:49.543698 [DEBUG] mod_sofia.c:413 Channel
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
hanging up, cause: NORMAL_TEMPORARY_FAILURE
2014-02-25 00:10:49.543698 [DEBUG] mod_sofia.c:553 Responding to
INVITE with: 503
2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:58
sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>
Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:731
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State HANGUP going to sleep
2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:744
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
Callstate Change EARLY -> HANGUP
2014-02-25 00:10:49.543698 [DEBUG] switch_core_state_machine.c:499
(sofia/sipinterface_1/user1 at sip.test.com <mailto:user1 at sip.test.com>)
State Change CS_HANGUP -> CS_REPORTING
2014-02-25 00:10:49.543698 [DEBUG] switch_core_session.c:1383 Send
signal sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com> [BREAK]
send 910 bytes to udp/[88.80.160.31]:5060 at 05:10:49.558765:
------------------------------------------------------------------------
SIP/2.0 503 Normal temporary failure
Via: SIP/2.0/UDP 88.80.160.31;branch=z9hG4bKd602.9af44717.0
Via: SIP/2.0/UDP
112.196.33.74:11220;rport=62926;branch=z9hG4bKPj.w0giarvUkQ67HPw3uK5Z6NsdtAUWvEV
From: <sip:user1 at sip.test.com
<mailto:sip%3Auser1 at sip.test.com>>;tag=aW0i4G-.8DI9G4pbsNbl8EWP1fY76mxz
To: <sip:+918146234576 at sip.test.com
<mailto:sip%3A%2B918146234576 at sip.test.com>>;tag=0KtN4j4SvttFc
Call-ID: 0v4twiSX8ZbXhaUtGh2KBbEpHgQyJmqO
CSeq: 26826 INVITE
User-Agent: 2600hz2014-02-25 00:10:49.543698 [DEBUG]
switch_core_state_machine.c:467 (sofia/sipinterface_1/user1 at sip.test.com
<mailto:user1 at sip.test.com>) Running State Change CS_REPORTING
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE,
REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: precondition, path, replaces
Allow-Events: talk, hold, conference, presence,
as-feature-event, dialog, line-seize, call-info, sla,
include-session-description, presence.winfo, message-summary, refer
Reason: Q.850;cause=41;text="NORMAL_TEMPORARY_FAILURE"
Content-Length: 0
Remote-Party-ID: "+918146234576" <sip:+918146234576 at sip.test.com
<mailto:sip%3A%2B918146234576 at sip.test.com>>;party=calling;privacy=off;screen=no
can anyone tell me what is the problem and how to solve it.
regards,
vinay
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20140225/43c83221/attachment-0001.html
Join us at ClueCon 2013 Aug 6-8, 2013
More information about the FreeSWITCH-users
mailing list