[Freeswitch-users] Audio Issue with FreeSWITCH (TLS + SRTP)
Saurabh Kumar Verma
saurabhkumar.verma at vvdntech.com
Wed Sep 9 15:03:40 MSD 2015
Hi,
Hope you're doing good.
I'm facing an issue with having FreeSWITCH (TLS + SRTP).
*Issue:* Audio not coming when I've SRTP(media) enabled on both of the
soft-phone endpoints.
*Observation: *Audio is coming if we don't use SRTP for media encryption.
*Set-up Description:*
I'm registered using TLS and able to make call through FreeSWITCH, but call
is disconnected after 30 sec because there is not media flow between the
endpoints.
I have two softphone (we're using Linphone as soft-phone) registered on FS
server with extension 1003 & 1010, call flow is like:
Call Flow
1003 ------> FS Server -------> 1010
x.x.x.x - Server Public IP
y.y.y.y - Server Local IP
*NOTE:* *For security reasons replaced the actual IPs.*
FreeSWITCH Version Information:
*freeswitch at internal> version*
*FreeSWITCH Version 1.4.21+git~20150901T202622Z~a223dd0236~64bit (git
a223dd0 2015-09-01 20:26:22Z 64bit)*
I've done some changes in default dialplan/configuration in FreeSWITCH:
1. Force FreeSWICTH to listen on TLS port only (By using this parameter *<param
name="tls-only" value="true"/> *in internal as well as external profile).
*freeswitch at internal> sofia status*
* Name Type Data
State*
*=================================================================================================*
* external profile sip:mod_sofia at x.x.x.x:5081
RUNNING (0) (TLS)*
* external::example.com <http://example.com> gateway
sip:joeuser at example.com <sip%3Ajoeuser at example.com> NOREG*
* x.x.x.x alias internal
ALIASED*
* internal profile sip:mod_sofia at x.x.x.x:5061
RUNNING (0) (TLS)*
*=================================================================================================*
*2 profiles 1 alias*
2. Use the ODBC driver for driver (By uncomment this *<!--<param
name="odbc-dsn" value="dsn:user:pass"/>-->* in config files)
In Linphone soft-client, these are the changes has been done:
1. *TLS *as Transport.
2. *SRTP* in Media encryption.
In FreeSWITCH, these are the registration logs showing I'm softphones are
using TLS
*freeswitch at internal> sofia status profile internal reg*
*Registrations:*
*=================================================================================================*
*Call-ID: xmuVdotDkb*
*User: 1003 at x.x.x.x*
*Contact: ""
<sip:1003 at 180.151.83.178:63093;app-id=622464153529;pn-type=google;pn-tok=APA91bF-MsdZGvDi951jjCoTDSJc2reyR2JvYHlgtwpeE1vLAlG2zrOIrBmwzx6PPPAHKfcE8aqaOHFtYFoLVztBeqAqz9Cr6D6waN7VCWSIQk7dAdm9HXQ;transport=tls>*
*Agent: LinphoneAndroid/2.4.1-28-g98516d9 (belle-sip/1.4.1)*
*Status: Registered(TLS)(unknown) EXP(2015-09-09 11:16:30)
EXPSECS(3137)*
*Ping-Status: Reachable*
*Host: ip-y-y-y-y.ec2.internal*
*IP: 180.151.83.178*
*Port: 63093*
*Auth-User: 1003*
*Auth-Realm: x.x.x.x*
*MWI-Account: 1003 at x.x.x.x*
*Call-ID: 6B25YNRXb5*
*User: 1010 at x.x.x.x*
*Contact: ""
<sip:1010 at 180.151.83.178:13916;app-id=622464153529;pn-type=google;pn-tok=APA91bFqivAK_KIDpU_6PM0pf0U8rx9DOKm0vhyNRqjE1Dpq_uPRbTbT-BMwxNP5NmEyCMfnKxa-fjEhI2J-lzLkCcfFphO1hL39cE4VNqAnnfDbVeQbvmQ;transport=tls>*
*Agent: LinphoneAndroid/2.4.1-28-g98516d9 (belle-sip/1.4.1)*
*Status: Registered(TLS)(unknown) EXP(2015-09-09 11:11:31)
EXPSECS(2838)*
*Ping-Status: Reachable*
*Host: ip-y-y-y-y.ec2.internal*
*IP: 180.151.83.178*
*Port: 13916*
*Auth-User: 1010*
*Auth-Realm: x.x.x.x*
*MWI-Account: 1010 at x.x.x.x*
*Total items returned: 2*
*=================================================================================================*
For an active call I can see in the channels table, I'm able to see secure
parameter is set during the call for both of the call legs.
*freeswitch=# select * from channels ;*
* uuid | direction | created |
created_epoch | name | state
| cid_name | cid_num | ip_addr *
* | dest | application | application_data | dialplan | context |
read_codec | read_rate | read_bit_rate | write_codec | write_rate |
write_bit_rate | secure *
* | hostname | presence_id | presence_data |
callstate | callee_name | callee_num | callee_direction |
call_uuid | sent_callee_name | sen*
*t_callee_num | initial_cid_name | initial_cid_num | initial_ip_addr |
initial_dest | initial_dialplan | initial_context *
*--------------------------------------+-----------+---------------------+---------------+------------------------------------------+-------------------+----------------+---------+------------*
*----+------+-------------+------------------------+----------+---------+------------+-----------+---------------+-------------+------------+----------------+----------------------------------*
*-+------------------------------+-------------------+---------------+-----------+---------------+------------+------------------+--------------------------------------+------------------+----*
*-------------+------------------+-----------------+-----------------+--------------+------------------+-----------------*
* 485d07d6-56da-11e5-ac1a-a53fe62ce2f9 | outbound | 2015-09-09 10:05:22 |
1441793122 | sofia/internal/1010 at 180.151.83.178:13916
<http://1010@180.151.83.178:13916> | CS_EXCHANGE_MEDIA | Extension 1003 |
1003 | 180.151.83.*
*178 | 1010 | | | XML | default |
opus | 48000 | 0 | opus | 48000 | 0
| srtp:sdes:AES_CM_256_HMAC_SHA1_80*
* | ip-172-31-42-34.ec2.internal | 1010 at x.x.x.x | | ACTIVE
| Outbound Call | 1010 | SEND |
47fa445c-56da-11e5-abf5-a53fe62ce2f9 | Extension 1003 | 100*
*3 | Extension 1003 | 1003 | 180.151.83.178 | 1010
| XML | default*
* 47fa445c-56da-11e5-abf5-a53fe62ce2f9 | inbound | 2015-09-09 10:05:22 |
1441793122 | sofia/internal/1003 at x.x.x.x | CS_EXECUTE |
1003 | 1003 | 180.151.83.*
*178 | 1010 | bridge | user/1010 at x.x.x.x | XML | default | opus
| 48000 | 0 | opus | 48000 | 0
| srtp:sdes:AES_CM_128_HMAC_SHA1_80*
* | ip-172-31-42-34.ec2.internal | 1003 at x.x.x.x | | ACTIVE
| Outbound Call | 1010 | SEND |
47fa445c-56da-11e5-abf5-a53fe62ce2f9 | Outbound Call | 101*
*0 | 1003 | 1003 | 180.151.83.178 | 1010
| XML | default*
*(2 rows)*
Attached herewith the complete FreeSWITCH log. Please let me know if any
other information is required.
Any help from your side would be really appreciated. Seeking some guidance
& help from FreeSWITCH team.
--
*Thanks:*
Saurabh Kumar Verma
VVDN Technologies Pvt Ltd
*Cell* : +91 7042378747 | *Skype* : saurabh.verma001
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20150909/495629b2/attachment-0001.html
-------------- next part --------------
recv 1411 bytes from tls/[180.151.83.178]:63093 at 10:05:21.510513:
------------------------------------------------------------------------
INVITE sip:1010 at x.x.x.x SIP/2.0
Via: SIP/2.0/TLS 192.168.93.102:45556;branch=z9hG4bK.AFYnEJtkz;rport
From: <sip:1003 at x.x.x.x>;tag=hKZC8L27Q
To: sip:1010 at x.x.x.x
CSeq: 20 INVITE
Call-ID: BbPYZv5Bca
Max-Forwards: 70
Supported: outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 824
Contact: <sip:1003 at 180.151.83.178:63093;transport=tls>;+sip.instance="<urn:uuid:c0dca361-56ce-40ee-ab91-161a0b9a6d6b>"
User-Agent: LinphoneAndroid/2.4.1-28-g98516d9 (belle-sip/1.4.1)
v=0
o=1003 3566 1099 IN IP4 192.168.93.102
s=Talk
c=IN IP4 192.168.93.102
b=AS:380
t=0 0
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 7076 RTP/SAVP 96 97 98 99 0 8 101 100 102
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:97 SILK/16000
a=rtpmap:98 speex/16000
a=fmtp:98 vbr=on
a=rtpmap:99 speex/8000
a=fmtp:99 vbr=on
a=rtpmap:101 telephone-event/48000
a=rtpmap:100 telephone-event/16000
a=rtpmap:102 telephone-event/8000
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:a+yoBUtbPKBYtrMBfjzZsMCYiql5SOxoYUbDFZc3
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:gRAgLfg3vCRKDA5gbaNfpHcGDrwH/GWyy6dnzQe2
a=crypto:3 AES_CM_256_HMAC_SHA1_80 inline:dn9M35kOLue0i/aclkHZGjBFmz6A/GACewZnkf5I
a=crypto:4 AES_CM_256_HMAC_SHA1_32 inline:nbX7w1uUBZShXI5Oui6Otfyw/NHWodUw0kOH2d3f
------------------------------------------------------------------------
send 330 bytes to tls/[180.151.83.178]:63093 at 10:05:21.510915:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/TLS 192.168.93.102:45556;branch=z9hG4bK.AFYnEJtkz;rport=63093;received=180.151.83.178
From: <sip:1003 at x.x.x.x>;tag=hKZC8L27Q
To: sip:1010 at x.x.x.x
Call-ID: BbPYZv5Bca
CSeq: 20 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.4.21+git~20150901T202622Z~a223dd0236~64bit
Content-Length: 0
------------------------------------------------------------------------
2015-09-09 10:05:21.500444 [NOTICE] switch_channel.c:1075 New Channel sofia/internal/1003 at x.x.x.x [47fa445c-56da-11e5-abf5-a53fe62ce2f9]
2015-09-09 10:05:21.500444 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:21.500444 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:21.500444 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1003 at x.x.x.x) Running State Change CS_NEW
2015-09-09 10:05:21.500444 [DEBUG] sofia.c:8925 sofia/internal/1003 at x.x.x.x receiving invite from 180.151.83.178:63093 version: 1.4.21 git a223dd0 2015-09-01 20:26:22Z 64bit
2015-09-09 10:05:21.500444 [DEBUG] sofia.c:9092 IP 180.151.83.178 Rejected by acl "domains". Falling back to Digest auth.
2015-09-09 10:05:21.500444 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/1003 at x.x.x.x) State NEW
send 835 bytes to tls/[180.151.83.178]:63093 at 10:05:21.513879:
------------------------------------------------------------------------
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/TLS 192.168.93.102:45556;branch=z9hG4bK.AFYnEJtkz;rport=63093;received=180.151.83.178
From: <sip:1003 at x.x.x.x>;tag=hKZC8L27Q
To: <sip:1010 at x.x.x.x>;tag=696jg19a5rZvj
Call-ID: BbPYZv5Bca
CSeq: 20 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.4.21+git~20150901T202622Z~a223dd0236~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, 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
Proxy-Authenticate: Digest realm="x.x.x.x", nonce="47fa5ad2-56da-11e5-abf6-a53fe62ce2f9", algorithm=MD5, qop="auth"
Content-Length: 0
------------------------------------------------------------------------
2015-09-09 10:05:21.500444 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:21.500444 [DEBUG] sofia.c:2065 detaching session 47fa445c-56da-11e5-abf5-a53fe62ce2f9
recv 391 bytes from tls/[180.151.83.178]:63093 at 10:05:22.125670:
------------------------------------------------------------------------
ACK sip:1010 at x.x.x.x SIP/2.0
Via: SIP/2.0/TLS 192.168.93.102:45556;branch=z9hG4bK.AFYnEJtkz;rport
Call-ID: BbPYZv5Bca
From: <sip:1003 at x.x.x.x>;tag=hKZC8L27Q
To: <sip:1010 at x.x.x.x>;tag=696jg19a5rZvj
Contact: <sip:1003 at 180.151.83.178:63093;transport=tls>;+sip.instance="<urn:uuid:c0dca361-56ce-40ee-ab91-161a0b9a6d6b>"
Max-Forwards: 70
CSeq: 20 ACK
Content-Length: 0
------------------------------------------------------------------------
recv 1657 bytes from tls/[180.151.83.178]:63093 at 10:05:22.128844:
------------------------------------------------------------------------
INVITE sip:1010 at x.x.x.x SIP/2.0
Via: SIP/2.0/TLS 192.168.93.102:45556;branch=z9hG4bK.cZ3vY0uWP;rport
From: <sip:1003 at x.x.x.x>;tag=hKZC8L27Q
To: sip:1010 at x.x.x.x
CSeq: 21 INVITE
Call-ID: BbPYZv5Bca
Max-Forwards: 70
Supported: outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 824
Contact: <sip:1003 at 180.151.83.178:63093;transport=tls>;+sip.instance="<urn:uuid:c0dca361-56ce-40ee-ab91-161a0b9a6d6b>"
User-Agent: LinphoneAndroid/2.4.1-28-g98516d9 (belle-sip/1.4.1)
Proxy-Authorization: Digest realm="x.x.x.x", nonce="47fa5ad2-56da-11e5-abf6-a53fe62ce2f9", algorithm=MD5, username="1003", uri="sip:1010 at x.x.x.x", response="7051af6f556408074ede39d53ff582c2", cnonce="faaa8515", nc=00000001, qop=auth
v=0
o=1003 3566 1099 IN IP4 192.168.93.102
s=Talk
c=IN IP4 192.168.93.102
b=AS:380
t=0 0
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 7076 RTP/SAVP 96 97 98 99 0 8 101 100 102
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:97 SILK/16000
a=rtpmap:98 speex/16000
a=fmtp:98 vbr=on
a=rtpmap:99 speex/8000
a=fmtp:99 vbr=on
a=rtpmap:101 telephone-event/48000
a=rtpmap:100 telephone-event/16000
a=rtpmap:102 telephone-event/8000
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:a+yoBUtbPKBYtrMBfjzZsMCYiql5SOxoYUbDFZc3
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:gRAgLfg3vCRKDA5gbaNfpHcGDrwH/GWyy6dnzQe2
a=crypto:3 AES_CM_256_HMAC_SHA1_80 inline:dn9M35kOLue0i/aclkHZGjBFmz6A/GACewZnkf5I
a=crypto:4 AES_CM_256_HMAC_SHA1_32 inline:nbX7w1uUBZShXI5Oui6Otfyw/NHWodUw0kOH2d3f
------------------------------------------------------------------------
send 330 bytes to tls/[180.151.83.178]:63093 at 10:05:22.129118:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/TLS 192.168.93.102:45556;branch=z9hG4bK.cZ3vY0uWP;rport=63093;received=180.151.83.178
From: <sip:1003 at x.x.x.x>;tag=hKZC8L27Q
To: sip:1010 at x.x.x.x
Call-ID: BbPYZv5Bca
CSeq: 21 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.4.21+git~20150901T202622Z~a223dd0236~64bit
Content-Length: 0
------------------------------------------------------------------------
2015-09-09 10:05:22.120462 [DEBUG] sofia.c:2173 Re-attaching to session 47fa445c-56da-11e5-abf5-a53fe62ce2f9
2015-09-09 10:05:22.120462 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:22.120462 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:22.120462 [DEBUG] sofia.c:8925 sofia/internal/1003 at x.x.x.x receiving invite from 180.151.83.178:63093 version: 1.4.21 git a223dd0 2015-09-01 20:26:22Z 64bit
2015-09-09 10:05:22.120462 [DEBUG] sofia.c:9092 IP 180.151.83.178 Rejected by acl "domains". Falling back to Digest auth.
2015-09-09 10:05:22.140647 [DEBUG] sofia.c:6634 Channel sofia/internal/1003 at x.x.x.x entering state [received][100]
2015-09-09 10:05:22.140647 [DEBUG] sofia.c:6644 Remote SDP:
v=0
o=1003 3566 1099 IN IP4 192.168.93.102
s=Talk
c=IN IP4 192.168.93.102
b=AS:380
t=0 0
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 7076 RTP/SAVP 96 97 98 99 0 8 101 100 102
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:97 SILK/16000
a=rtpmap:98 speex/16000
a=fmtp:98 vbr=on
a=rtpmap:99 speex/8000
a=fmtp:99 vbr=on
a=rtpmap:101 telephone-event/48000
a=rtpmap:100 telephone-event/16000
a=rtpmap:102 telephone-event/8000
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:a+yoBUtbPKBYtrMBfjzZsMCYiql5SOxoYUbDFZc3
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:gRAgLfg3vCRKDA5gbaNfpHcGDrwH/GWyy6dnzQe2
a=crypto:3 AES_CM_256_HMAC_SHA1_80 inline:dn9M35kOLue0i/aclkHZGjBFmz6A/GACewZnkf5I
a=crypto:4 AES_CM_256_HMAC_SHA1_32 inline:nbX7w1uUBZShXI5Oui6Otfyw/NHWodUw0kOH2d3f
2015-09-09 10:05:22.140647 [DEBUG] sofia.c:6910 (sofia/internal/1003 at x.x.x.x) State Change CS_NEW -> CS_INIT
2015-09-09 10:05:22.140647 [DEBUG] switch_core_session.c:1397 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1003 at x.x.x.x) Running State Change CS_INIT
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/1003 at x.x.x.x) State INIT
2015-09-09 10:05:22.140647 [DEBUG] mod_sofia.c:87 sofia/internal/1003 at x.x.x.x SOFIA INIT
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1003 at x.x.x.x Standard INIT
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1003 at x.x.x.x) State Change CS_INIT -> CS_ROUTING
2015-09-09 10:05:22.140647 [DEBUG] switch_core_session.c:1397 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/1003 at x.x.x.x) State INIT going to sleep
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1003 at x.x.x.x) Running State Change CS_ROUTING
2015-09-09 10:05:22.140647 [DEBUG] switch_channel.c:2204 (sofia/internal/1003 at x.x.x.x) Callstate Change DOWN -> RINGING
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/1003 at x.x.x.x) State ROUTING
2015-09-09 10:05:22.140647 [DEBUG] mod_sofia.c:123 sofia/internal/1003 at x.x.x.x SOFIA ROUTING
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:166 sofia/internal/1003 at x.x.x.x Standard ROUTING
2015-09-09 10:05:22.140647 [INFO] mod_dialplan_xml.c:635 Processing 1003 <1003>->1010 in context default
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->unloop] continue=false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->tod_example] continue=true
Dialplan: sofia/internal/1003 at x.x.x.x Date/Time Match (PASS) [tod_example] break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x Action set(open=true)
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/1003 at x.x.x.x Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [global-intercept] destination_number(1010) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [group-intercept] destination_number(1010) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [intercept-ext] destination_number(1010) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->redial] continue=false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [redial] destination_number(1010) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->global] continue=true
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1003 at x.x.x.x Regex (PASS) [global] ${default_password}(1234) =~ /^1234$/ break=never
Dialplan: sofia/internal/1003 at x.x.x.x Action log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING )
Dialplan: sofia/internal/1003 at x.x.x.x Action log(CRIT Open /usr/local/freeswitch/conf/vars.xml and change the default_password.)
Dialplan: sofia/internal/1003 at x.x.x.x Action log(CRIT Once changed type 'reloadxml' at the console.)
Dialplan: sofia/internal/1003 at x.x.x.x Action log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING )
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never
Dialplan: sofia/internal/1003 at x.x.x.x Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (PASS) [global] ${switch_r_sdp}(v=0
o=1003 3566 1099 IN IP4 192.168.93.102
s=Talk
c=IN IP4 192.168.93.102
b=AS:380
t=0 0
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 7076 RTP/SAVP 96 97 98 99 0 8 101 100 102
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:97 SILK/16000
a=rtpmap:98 speex/16000
a=fmtp:98 vbr=on
a=rtpmap:99 speex/8000
a=fmtp:99 vbr=on
a=rtpmap:101 telephone-event/48000
a=rtpmap:100 telephone-event/16000
a=rtpmap:102 telephone-event/8000
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:a+yoBUtbPKBYtrMBfjzZsMCYiql5SOxoYUbDFZc3
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:gRAgLfg3vCRKDA5gbaNfpHcGDrwH/GWyy6dnzQe2
a=crypto:3 AES_CM_256_HMAC_SHA1_80 inline:dn9M35kOLue0i/aclkHZGjBFmz6A/GACewZnkf5I
a=crypto:4 AES_CM_256_HMAC_SHA1_32 inline:nbX7w1uUBZShXI5Oui6Otfyw/NHWodUw0kOH2d3f
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/1003 at x.x.x.x Action set(rtp_secure_media=true)
Dialplan: sofia/internal/1003 at x.x.x.x Action export(rtp_secure_media=true)
Dialplan: sofia/internal/1003 at x.x.x.x Absolute Condition [global]
Dialplan: sofia/internal/1003 at x.x.x.x Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/1003 at x.x.x.x Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/1003 at x.x.x.x Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/1003 at x.x.x.x Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [snom-demo-2] destination_number(1010) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [snom-demo-1] destination_number(1010) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [eavesdrop] destination_number(1010) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [eavesdrop] destination_number(1010) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->call_return] continue=false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [call_return] destination_number(1010) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->del-group] continue=false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [del-group] destination_number(1010) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->add-group] continue=false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [add-group] destination_number(1010) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [call-group-simo] destination_number(1010) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [call-group-order] destination_number(1010) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (FAIL) [extension-intercom] destination_number(1010) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/1003 at x.x.x.x Regex (PASS) [Local_Extension] destination_number(1010) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1003 at x.x.x.x Action export(dialed_extension=1010)
Dialplan: sofia/internal/1003 at x.x.x.x Action bind_meta_app(1 b s execute_extension::dx XML features)
Dialplan: sofia/internal/1003 at x.x.x.x Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav)
Dialplan: sofia/internal/1003 at x.x.x.x Action bind_meta_app(3 b s execute_extension::cf XML features)
Dialplan: sofia/internal/1003 at x.x.x.x Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
Dialplan: sofia/internal/1003 at x.x.x.x Action set(ringback=${us-ring})
Dialplan: sofia/internal/1003 at x.x.x.x Action set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/1003 at x.x.x.x Action set(call_timeout=30)
Dialplan: sofia/internal/1003 at x.x.x.x Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/1003 at x.x.x.x Action set(continue_on_fail=true)
Dialplan: sofia/internal/1003 at x.x.x.x Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/1003 at x.x.x.x Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/1003 at x.x.x.x Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})
Dialplan: sofia/internal/1003 at x.x.x.x Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/1003 at x.x.x.x Action hash(insert/${domain_name}-last_dial_ext/global/${uuid})
Dialplan: sofia/internal/1003 at x.x.x.x Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/1003 at x.x.x.x Action bridge(user/${dialed_extension}@${domain_name})
Dialplan: sofia/internal/1003 at x.x.x.x Action answer()
Dialplan: sofia/internal/1003 at x.x.x.x Action sleep(1000)
Dialplan: sofia/internal/1003 at x.x.x.x Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:216 (sofia/internal/1003 at x.x.x.x) State Change CS_ROUTING -> CS_EXECUTE
2015-09-09 10:05:22.140647 [DEBUG] switch_core_session.c:1397 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/1003 at x.x.x.x) State ROUTING going to sleep
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1003 at x.x.x.x) Running State Change CS_EXECUTE
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:535 (sofia/internal/1003 at x.x.x.x) State EXECUTE
2015-09-09 10:05:22.140647 [DEBUG] mod_sofia.c:178 sofia/internal/1003 at x.x.x.x SOFIA EXECUTE
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:258 sofia/internal/1003 at x.x.x.x Standard EXECUTE
EXECUTE sofia/internal/1003 at x.x.x.x set(open=true)
2015-09-09 10:05:22.140647 [DEBUG] mod_dptools.c:1477 sofia/internal/1003 at x.x.x.x SET [open]=[true]
EXECUTE sofia/internal/1003 at x.x.x.x log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING )
2015-09-09 10:05:22.140647 [CRIT] mod_dptools.c:1670 WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING
EXECUTE sofia/internal/1003 at x.x.x.x log(CRIT Open /usr/local/freeswitch/conf/vars.xml and change the default_password.)
2015-09-09 10:05:22.140647 [CRIT] mod_dptools.c:1670 Open /usr/local/freeswitch/conf/vars.xml and change the default_password.
EXECUTE sofia/internal/1003 at x.x.x.x log(CRIT Once changed type 'reloadxml' at the console.)
2015-09-09 10:05:22.140647 [CRIT] mod_dptools.c:1670 Once changed type 'reloadxml' at the console.
EXECUTE sofia/internal/1003 at x.x.x.x log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING )
2015-09-09 10:05:22.140647 [CRIT] mod_dptools.c:1670 WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING
EXECUTE sofia/internal/1003 at x.x.x.x set(rtp_secure_media=true)
2015-09-09 10:05:22.140647 [DEBUG] mod_dptools.c:1477 sofia/internal/1003 at x.x.x.x SET [rtp_secure_media]=[true]
EXECUTE sofia/internal/1003 at x.x.x.x export(rtp_secure_media=true)
2015-09-09 10:05:22.140647 [DEBUG] switch_channel.c:1267 EXPORT (export_vars) [rtp_secure_media]=[true]
EXECUTE sofia/internal/1003 at x.x.x.x hash(insert/x.x.x.x-spymap/1003/47fa445c-56da-11e5-abf5-a53fe62ce2f9)
EXECUTE sofia/internal/1003 at x.x.x.x hash(insert/x.x.x.x-last_dial/1003/1010)
EXECUTE sofia/internal/1003 at x.x.x.x hash(insert/x.x.x.x-last_dial/global/47fa445c-56da-11e5-abf5-a53fe62ce2f9)
EXECUTE sofia/internal/1003 at x.x.x.x export(RFC2822_DATE=Wed, 09 Sep 2015 10:05:22 +0000)
2015-09-09 10:05:22.140647 [DEBUG] switch_channel.c:1267 EXPORT (export_vars) [RFC2822_DATE]=[Wed, 09 Sep 2015 10:05:22 +0000]
EXECUTE sofia/internal/1003 at x.x.x.x export(dialed_extension=1010)
2015-09-09 10:05:22.140647 [DEBUG] switch_channel.c:1267 EXPORT (export_vars) [dialed_extension]=[1010]
EXECUTE sofia/internal/1003 at x.x.x.x bind_meta_app(1 b s execute_extension::dx XML features)
2015-09-09 10:05:22.140647 [INFO] switch_ivr_async.c:3932 Bound B-Leg: *1 execute_extension::dx XML features
EXECUTE sofia/internal/1003 at x.x.x.x bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/1003.2015-09-09-10-05-22.wav)
2015-09-09 10:05:22.140647 [INFO] switch_ivr_async.c:3932 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/1003.2015-09-09-10-05-22.wav
EXECUTE sofia/internal/1003 at x.x.x.x bind_meta_app(3 b s execute_extension::cf XML features)
2015-09-09 10:05:22.140647 [INFO] switch_ivr_async.c:3932 Bound B-Leg: *3 execute_extension::cf XML features
EXECUTE sofia/internal/1003 at x.x.x.x bind_meta_app(4 b s execute_extension::att_xfer XML features)
2015-09-09 10:05:22.140647 [INFO] switch_ivr_async.c:3932 Bound B-Leg: *4 execute_extension::att_xfer XML features
EXECUTE sofia/internal/1003 at x.x.x.x set(ringback=%(2000,4000,440,480))
2015-09-09 10:05:22.140647 [DEBUG] mod_dptools.c:1477 sofia/internal/1003 at x.x.x.x SET [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/internal/1003 at x.x.x.x set(transfer_ringback=local_stream://moh)
2015-09-09 10:05:22.140647 [DEBUG] mod_dptools.c:1477 sofia/internal/1003 at x.x.x.x SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/1003 at x.x.x.x set(call_timeout=30)
2015-09-09 10:05:22.140647 [DEBUG] mod_dptools.c:1477 sofia/internal/1003 at x.x.x.x SET [call_timeout]=[30]
EXECUTE sofia/internal/1003 at x.x.x.x set(hangup_after_bridge=true)
2015-09-09 10:05:22.140647 [DEBUG] mod_dptools.c:1477 sofia/internal/1003 at x.x.x.x SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/1003 at x.x.x.x set(continue_on_fail=true)
2015-09-09 10:05:22.140647 [DEBUG] mod_dptools.c:1477 sofia/internal/1003 at x.x.x.x SET [continue_on_fail]=[true]
EXECUTE sofia/internal/1003 at x.x.x.x hash(insert/x.x.x.x-call_return/1010/1003)
EXECUTE sofia/internal/1003 at x.x.x.x hash(insert/x.x.x.x-last_dial_ext/1010/47fa445c-56da-11e5-abf5-a53fe62ce2f9)
EXECUTE sofia/internal/1003 at x.x.x.x set(called_party_callgroup=techsupport)
2015-09-09 10:05:22.140647 [DEBUG] mod_dptools.c:1477 sofia/internal/1003 at x.x.x.x SET [called_party_callgroup]=[techsupport]
EXECUTE sofia/internal/1003 at x.x.x.x hash(insert/x.x.x.x-last_dial_ext/techsupport/47fa445c-56da-11e5-abf5-a53fe62ce2f9)
EXECUTE sofia/internal/1003 at x.x.x.x hash(insert/x.x.x.x-last_dial_ext/global/47fa445c-56da-11e5-abf5-a53fe62ce2f9)
EXECUTE sofia/internal/1003 at x.x.x.x hash(insert/x.x.x.x-last_dial/techsupport/47fa445c-56da-11e5-abf5-a53fe62ce2f9)
EXECUTE sofia/internal/1003 at x.x.x.x bridge(user/1010 at x.x.x.x)
2015-09-09 10:05:22.140647 [DEBUG] switch_channel.c:1221 sofia/internal/1003 at x.x.x.x EXPORTING[export_vars] [rtp_secure_media]=[true] to event
2015-09-09 10:05:22.140647 [DEBUG] switch_channel.c:1221 sofia/internal/1003 at x.x.x.x EXPORTING[export_vars] [RFC2822_DATE]=[Wed, 09 Sep 2015 10:05:22 +0000] to event
2015-09-09 10:05:22.140647 [DEBUG] switch_channel.c:1221 sofia/internal/1003 at x.x.x.x EXPORTING[export_vars] [dialed_extension]=[1010] to event
2015-09-09 10:05:22.140647 [DEBUG] switch_ivr_originate.c:2101 Parsing global variables
2015-09-09 10:05:22.140647 [DEBUG] switch_channel.c:1221 sofia/internal/1003 at x.x.x.x EXPORTING[export_vars] [rtp_secure_media]=[true] to event
2015-09-09 10:05:22.140647 [DEBUG] switch_channel.c:1221 sofia/internal/1003 at x.x.x.x EXPORTING[export_vars] [RFC2822_DATE]=[Wed, 09 Sep 2015 10:05:22 +0000] to event
2015-09-09 10:05:22.140647 [DEBUG] switch_channel.c:1221 sofia/internal/1003 at x.x.x.x EXPORTING[export_vars] [dialed_extension]=[1010] to event
2015-09-09 10:05:22.140647 [DEBUG] switch_ivr_originate.c:2101 Parsing global variables
2015-09-09 10:05:22.140647 [DEBUG] switch_event.c:1698 Parsing variable [sip_invite_domain]=[x.x.x.x]
2015-09-09 10:05:22.140647 [DEBUG] switch_event.c:1698 Parsing variable [presence_id]=[1010 at x.x.x.x]
2015-09-09 10:05:22.140647 [NOTICE] switch_channel.c:1075 New Channel sofia/internal/1010 at 180.151.83.178:13916 [485d07d6-56da-11e5-ac1a-a53fe62ce2f9]
2015-09-09 10:05:22.140647 [DEBUG] mod_sofia.c:4701 (sofia/internal/1010 at 180.151.83.178:13916) State Change CS_NEW -> CS_INIT
2015-09-09 10:05:22.140647 [DEBUG] switch_core_session.c:1397 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1010 at 180.151.83.178:13916) Running State Change CS_INIT
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/1010 at 180.151.83.178:13916) State INIT
2015-09-09 10:05:22.140647 [DEBUG] mod_sofia.c:87 sofia/internal/1010 at 180.151.83.178:13916 SOFIA INIT
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local audio crypto Key [1 AEAD_AES_256_GCM_8 inline:NZxdLH9gzfkhVqwVhH5vNsKCqr2ZL2q9zmm58qlSlItToqVbwaDneilU+js]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local video crypto Key [1 AEAD_AES_256_GCM_8 inline:7uw9HXkoT5LbBdJAIx6mvnWdy/gANmdQ1rdhGblSftKOJ7XmmqKXwcLZG2k]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local audio crypto Key [2 AEAD_AES_128_GCM_8 inline:ua7aHtrGSUTtDiXrZ0GGBQV788KjFiuLmZTH8g]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local video crypto Key [2 AEAD_AES_128_GCM_8 inline:7eAg8CQyKxxalD3DOHhyw5RhXN3KcBvgDMLckA]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local audio crypto Key [3 AES_CM_256_HMAC_SHA1_80 inline:Z1uAXxMyRlMCgn5nLEN4V/2CKFQpu7WR+2jSAhcUrFEFjCntDm/xtGjKlCYs6g]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local video crypto Key [3 AES_CM_256_HMAC_SHA1_80 inline:VexGkXR2HPxslnQmALYSBgGbvtJyO6LQ+QZzd5SGNabAwuFGF8gvKPMUK4S32Q]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local audio crypto Key [4 AES_CM_192_HMAC_SHA1_80 inline:cW6ndzHiiplj8y8BFe6tlaJWC3F9jApWWJOXZ6lyatZAFGPbAqI]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local video crypto Key [4 AES_CM_192_HMAC_SHA1_80 inline:MOsMk92cXU3us99+4guLRK1aWk5UoveM/hp4eY8Y4ieml3l/oQc]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local audio crypto Key [5 AES_CM_128_HMAC_SHA1_80 inline:yDum29SwW09CG0fKGoM3G4JCWyKC5GoCrpPAPAZG]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local video crypto Key [5 AES_CM_128_HMAC_SHA1_80 inline:4CAf5XYrvryfmUETnCt+/vdoHTCf2Oyon8kjh8yV]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local audio crypto Key [6 AES_CM_256_HMAC_SHA1_32 inline:IktDcfIz+fhT77Pq/H1zHZwOZt/e9wYyFbDxeqhLws8ZJVLB60Y5Cxwhuall7w]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local video crypto Key [6 AES_CM_256_HMAC_SHA1_32 inline:ASCE4Um7ly3qHgmBsV8U826feUJfrIv8cqyR/TMGMbQt7m77I1oO17xbcTRahA]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local audio crypto Key [7 AES_CM_192_HMAC_SHA1_32 inline:cITD1AHsn0mlXOeRNLpdhC+raMZNQ7JOd2ntLdvJDY7hD+5gnOY]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local video crypto Key [7 AES_CM_192_HMAC_SHA1_32 inline:AFzQEnxOGYB9FhMWeMXAiRLB63BcjMl7wdj17oTJuAh87QyeM8E]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local audio crypto Key [8 AES_CM_128_HMAC_SHA1_32 inline:k2mJfkfFoSI57S0wRldCaqJ5o+zEDxI/gn/GoGYz]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local video crypto Key [8 AES_CM_128_HMAC_SHA1_32 inline:w5Qg47gCQyv44qDVkQSdSzvOEr2UuoiLXK7tBTKB]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local audio crypto Key [9 AES_CM_128_NULL_AUTH inline:746pNswmg35Pt7hBimQhSlhCFG97FGfQ1GxXpMgN]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_media.c:965 Set Local video crypto Key [9 AES_CM_128_NULL_AUTH inline:1wY0sYq5HRdoAe9SH+qglTRSGML8o50CmJIwWvpZ]
2015-09-09 10:05:22.140647 [DEBUG] sofia_glue.c:1241 sofia/internal/1010 at 180.151.83.178:13916 sending invite version: 1.4.21 git a223dd0 2015-09-01 20:26:22Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1441764576 1441764577 IN IP4 x.x.x.x
s=FreeSWITCH
c=IN IP4 x.x.x.x
t=0 0
m=audio 28546 RTP/SAVP 96 0 8 9 3 101 13
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=crypto:1 AEAD_AES_256_GCM_8 inline:NZxdLH9gzfkhVqwVhH5vNsKCqr2ZL2q9zmm58qlSlItToqVbwaDneilU+js
a=crypto:2 AEAD_AES_128_GCM_8 inline:ua7aHtrGSUTtDiXrZ0GGBQV788KjFiuLmZTH8g
a=crypto:3 AES_CM_256_HMAC_SHA1_80 inline:Z1uAXxMyRlMCgn5nLEN4V/2CKFQpu7WR+2jSAhcUrFEFjCntDm/xtGjKlCYs6g
a=crypto:4 AES_CM_192_HMAC_SHA1_80 inline:cW6ndzHiiplj8y8BFe6tlaJWC3F9jApWWJOXZ6lyatZAFGPbAqI
a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:yDum29SwW09CG0fKGoM3G4JCWyKC5GoCrpPAPAZG
a=crypto:6 AES_CM_256_HMAC_SHA1_32 inline:IktDcfIz+fhT77Pq/H1zHZwOZt/e9wYyFbDxeqhLws8ZJVLB60Y5Cxwhuall7w
a=crypto:7 AES_CM_192_HMAC_SHA1_32 inline:cITD1AHsn0mlXOeRNLpdhC+raMZNQ7JOd2ntLdvJDY7hD+5gnOY
a=crypto:8 AES_CM_128_HMAC_SHA1_32 inline:k2mJfkfFoSI57S0wRldCaqJ5o+zEDxI/gn/GoGYz
a=crypto:9 AES_CM_128_NULL_AUTH inline:746pNswmg35Pt7hBimQhSlhCFG97FGfQ1GxXpMgN
a=ptime:20
a=sendrecv
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1010 at 180.151.83.178:13916 Standard INIT
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1010 at 180.151.83.178:13916) State Change CS_INIT -> CS_ROUTING
2015-09-09 10:05:22.140647 [DEBUG] switch_core_session.c:1397 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/1010 at 180.151.83.178:13916) State INIT going to sleep
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1010 at 180.151.83.178:13916) Running State Change CS_ROUTING
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/1010 at 180.151.83.178:13916) State ROUTING
2015-09-09 10:05:22.140647 [DEBUG] mod_sofia.c:123 sofia/internal/1010 at 180.151.83.178:13916 SOFIA ROUTING
2015-09-09 10:05:22.140647 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1010 at 180.151.83.178:13916) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2015-09-09 10:05:22.140647 [DEBUG] switch_core_session.c:1397 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/1010 at 180.151.83.178:13916) State ROUTING going to sleep
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1010 at 180.151.83.178:13916) Running State Change CS_CONSUME_MEDIA
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:547 (sofia/internal/1010 at 180.151.83.178:13916) State CONSUME_MEDIA
2015-09-09 10:05:22.140647 [DEBUG] switch_core_state_machine.c:547 (sofia/internal/1010 at 180.151.83.178:13916) State CONSUME_MEDIA going to sleep
send 2508 bytes to tls/[180.151.83.178]:13916 at 10:05:22.161388:
------------------------------------------------------------------------
INVITE sip:1010 at 180.151.83.178:13916;app-id=622464153529;pn-type=google;pn-tok=APA91bFqivAK_KIDpU_6PM0pf0U8rx9DOKm0vhyNRqjE1Dpq_uPRbTbT-BMwxNP5NmEyCMfnKxa-fjEhI2J-lzLkCcfFphO1hL39cE4VNqAnnfDbVeQbvmQ;transport=tls SIP/2.0
Via: SIP/2.0/TLS x.x.x.x:5061;rport;branch=z9hG4bKmHD6cSZUSjtmS
Max-Forwards: 69
From: "Extension 1003" <sip:1003 at x.x.x.x>;tag=8US4KQBjZac2S
To: <sip:1010 at 180.151.83.178:13916;app-id=622464153529;pn-type=google;pn-tok=APA91bFqivAK_KIDpU_6PM0pf0U8rx9DOKm0vhyNRqjE1Dpq_uPRbTbT-BMwxNP5NmEyCMfnKxa-fjEhI2J-lzLkCcfFphO1hL39cE4VNqAnnfDbVeQbvmQ;transport=tls>
Call-ID: 1fbbb0c5-d17d-1233-c292-1293c2c31053
CSeq: 80560497 INVITE
Contact: <sip:mod_sofia at x.x.x.x:5061;transport=tls>
User-Agent: FreeSWITCH-mod_sofia/1.4.21+git~20150901T202622Z~a223dd0236~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, 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: 1176
X-FS-Support: update_display,send_info
Remote-Party-ID: "Extension 1003" <sip:1003 at x.x.x.x>;party=calling;screen=yes;privacy=off
v=0
o=FreeSWITCH 1441764576 1441764577 IN IP4 x.x.x.x
s=FreeSWITCH
c=IN IP4 x.x.x.x
t=0 0
m=audio 28546 RTP/SAVP 96 0 8 9 3 101 13
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=crypto:1 AEAD_AES_256_GCM_8 inline:NZxdLH9gzfkhVqwVhH5vNsKCqr2ZL2q9zmm58qlSlItToqVbwaDneilU+js
a=crypto:2 AEAD_AES_128_GCM_8 inline:ua7aHtrGSUTtDiXrZ0GGBQV788KjFiuLmZTH8g
a=crypto:3 AES_CM_256_HMAC_SHA1_80 inline:Z1uAXxMyRlMCgn5nLEN4V/2CKFQpu7WR+2jSAhcUrFEFjCntDm/xtGjKlCYs6g
a=crypto:4 AES_CM_192_HMAC_SHA1_80 inline:cW6ndzHiiplj8y8BFe6tlaJWC3F9jApWWJOXZ6lyatZAFGPbAqI
a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:yDum29SwW09CG0fKGoM3G4JCWyKC5GoCrpPAPAZG
a=crypto:6 AES_CM_256_HMAC_SHA1_32 inline:IktDcfIz+fhT77Pq/H1zHZwOZt/e9wYyFbDxeqhLws8ZJVLB60Y5Cxwhuall7w
a=crypto:7 AES_CM_192_HMAC_SHA1_32 inline:cITD1AHsn0mlXOeRNLpdhC+raMZNQ7JOd2ntLdvJDY7hD+5gnOY
a=crypto:8 AES_CM_128_HMAC_SHA1_32 inline:k2mJfkfFoSI57S0wRldCaqJ5o+zEDxI/gn/GoGYz
a=crypto:9 AES_CM_128_NULL_AUTH inline:746pNswmg35Pt7hBimQhSlhCFG97FGfQ1GxXpMgN
a=ptime:20
------------------------------------------------------------------------
2015-09-09 10:05:22.160525 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:22.160525 [DEBUG] sofia.c:6634 Channel sofia/internal/1010 at 180.151.83.178:13916 entering state [calling][0]
recv 460 bytes from tls/[180.151.83.178]:13916 at 10:05:22.522342:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/TLS x.x.x.x:5061;rport;branch=z9hG4bKmHD6cSZUSjtmS
From: "Extension 1003" <sip:1003 at x.x.x.x>;tag=8US4KQBjZac2S
To: <sip:1010 at 180.151.83.178:13916;app-id=622464153529;pn-type=google;pn-tok=APA91bFqivAK_KIDpU_6PM0pf0U8rx9DOKm0vhyNRqjE1Dpq_uPRbTbT-BMwxNP5NmEyCMfnKxa-fjEhI2J-lzLkCcfFphO1hL39cE4VNqAnnfDbVeQbvmQ;transport=tls>
Call-ID: 1fbbb0c5-d17d-1233-c292-1293c2c31053
CSeq: 80560497 INVITE
Content-Length: 0
------------------------------------------------------------------------
recv 559 bytes from tls/[180.151.83.178]:13916 at 10:05:23.464035:
------------------------------------------------------------------------
SIP/2.0 180 Ringing
Via: SIP/2.0/TLS x.x.x.x:5061;rport;branch=z9hG4bKmHD6cSZUSjtmS
From: "Extension 1003" <sip:1003 at x.x.x.x>;tag=8US4KQBjZac2S
To: <sip:1010 at 180.151.83.178:13916;app-id=622464153529;pn-type=google;pn-tok=APA91bFqivAK_KIDpU_6PM0pf0U8rx9DOKm0vhyNRqjE1Dpq_uPRbTbT-BMwxNP5NmEyCMfnKxa-fjEhI2J-lzLkCcfFphO1hL39cE4VNqAnnfDbVeQbvmQ;transport=tls>;tag=ezLC2Tx
Call-ID: 1fbbb0c5-d17d-1233-c292-1293c2c31053
CSeq: 80560497 INVITE
User-Agent: LinphoneAndroid/2.4.1-28-g98516d9 (belle-sip/1.4.1)
Supported: outbound
Content-Length: 0
------------------------------------------------------------------------
2015-09-09 10:05:23.460465 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:23.460465 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:23.460465 [DEBUG] sofia.c:6634 Channel sofia/internal/1010 at 180.151.83.178:13916 entering state [proceeding][180]
2015-09-09 10:05:23.460465 [NOTICE] sofia.c:6736 Ring-Ready sofia/internal/1010 at 180.151.83.178:13916!
2015-09-09 10:05:23.460465 [DEBUG] switch_channel.c:3297 (sofia/internal/1010 at 180.151.83.178:13916) Callstate Change DOWN -> RINGING
2015-09-09 10:05:23.480461 [INFO] switch_ivr_originate.c:1193 Sending early media
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:1228 looking for crypto suite [AEAD_AES_256_GCM_8] in [1 AES_CM_128_HMAC_SHA1_80 inline:a+yoBUtbPKBYtrMBfjzZsMCYiql5SOxoYUbDFZc3]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:1228 looking for crypto suite [AEAD_AES_128_GCM_8] in [1 AES_CM_128_HMAC_SHA1_80 inline:a+yoBUtbPKBYtrMBfjzZsMCYiql5SOxoYUbDFZc3]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:1228 looking for crypto suite [AES_CM_256_HMAC_SHA1_80] in [1 AES_CM_128_HMAC_SHA1_80 inline:a+yoBUtbPKBYtrMBfjzZsMCYiql5SOxoYUbDFZc3]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:1228 looking for crypto suite [AES_CM_192_HMAC_SHA1_80] in [1 AES_CM_128_HMAC_SHA1_80 inline:a+yoBUtbPKBYtrMBfjzZsMCYiql5SOxoYUbDFZc3]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:1228 looking for crypto suite [AES_CM_128_HMAC_SHA1_80] in [1 AES_CM_128_HMAC_SHA1_80 inline:a+yoBUtbPKBYtrMBfjzZsMCYiql5SOxoYUbDFZc3]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:1233 Found suite AES_CM_128_HMAC_SHA1_80
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:1299 Set Remote Key [1 AES_CM_128_HMAC_SHA1_80 inline:a+yoBUtbPKBYtrMBfjzZsMCYiql5SOxoYUbDFZc3]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:965 Set Local audio crypto Key [1 AES_CM_128_HMAC_SHA1_80 inline:44c6ZMEyLHkmecAZKJf7Nf8hAPMQhA4rubdYPr2/]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [opus:96:48000:20:0:1]/[opus:116:48000:20:0:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3734 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [opus:96:48000:20:0:1]/[G722:9:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [opus:96:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [opus:96:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [opus:96:48000:20:0:1]/[GSM:3:8000:20:13200:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [SILK:97:16000:20:0:1]/[opus:116:48000:20:0:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [SILK:97:16000:20:0:1]/[G722:9:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [SILK:97:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [SILK:97:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [SILK:97:16000:20:0:1]/[GSM:3:8000:20:13200:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [speex:98:16000:20:0:1]/[opus:116:48000:20:0:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [speex:98:16000:20:0:1]/[G722:9:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [speex:98:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [speex:98:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [speex:98:16000:20:0:1]/[GSM:3:8000:20:13200:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [speex:99:8000:20:0:1]/[opus:116:48000:20:0:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [speex:99:8000:20:0:1]/[G722:9:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [speex:99:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [speex:99:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [speex:99:8000:20:0:1]/[GSM:3:8000:20:13200:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3734 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3734 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3595 Set telephone-event payload to 101
2015-09-09 10:05:23.480461 [DEBUG] mod_opus.c:289 Opus encoder set bitrate to local settings [-1000bps]
2015-09-09 10:05:23.480461 [DEBUG] mod_opus.c:289 Opus encoder set bitrate to local settings [-1000bps]
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:2506 Set Codec sofia/internal/1003 at x.x.x.x opus/48000 20 ms 960 samples 0 bits 1 channels
2015-09-09 10:05:23.480461 [DEBUG] switch_core_codec.c:111 sofia/internal/1003 at x.x.x.x Original read codec set to opus:116
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:3942 Set 2833 dtmf send/recv payload to 101
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:5178 AUDIO RTP [sofia/internal/1003 at x.x.x.x] y.y.y.y port 18344 -> 192.168.93.102 port 7076 codec: 96 ms: 20
2015-09-09 10:05:23.480461 [DEBUG] switch_rtp.c:3579 Starting timer [soft] 960 bytes per 20ms
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:5476 Set 2833 dtmf send payload to 101
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:5482 Set 2833 dtmf receive payload to 101
2015-09-09 10:05:23.480461 [DEBUG] switch_core_media.c:5504 sofia/internal/1003 at x.x.x.x Set rtp dtmf delay to 40
2015-09-09 10:05:23.480461 [INFO] switch_rtp.c:3394 Activating Audio Secure RTP SEND
2015-09-09 10:05:23.480461 [INFO] switch_rtp.c:3372 Activating Audio Secure RTP RECV
2015-09-09 10:05:23.480461 [DEBUG] switch_core_sqldb.c:2599 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2015-09-09 10:05:23.480461 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1003 at x.x.x.x!
2015-09-09 10:05:23.480461 [DEBUG] switch_core_sqldb.c:2599 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2015-09-09 10:05:23.480461 [DEBUG] switch_channel.c:3419 (sofia/internal/1003 at x.x.x.x) Callstate Change RINGING -> EARLY
2015-09-09 10:05:23.480461 [DEBUG] mod_sofia.c:2268 Ring SDP:
v=0
o=FreeSWITCH 1441774779 1441774780 IN IP4 x.x.x.x
s=FreeSWITCH
c=IN IP4 x.x.x.x
t=0 0
m=audio 18344 RTP/SAVP 96 101
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:44c6ZMEyLHkmecAZKJf7Nf8hAPMQhA4rubdYPr2/
2015-09-09 10:05:23.480461 [DEBUG] switch_core_session.c:913 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:23.480461 [DEBUG] switch_ivr_originate.c:1250 Raw Codec Activation Success L16 at 48000hz 1 channel 20ms
2015-09-09 10:05:23.480461 [DEBUG] switch_core_codec.c:221 sofia/internal/1003 at x.x.x.x Push codec L16:100
2015-09-09 10:05:23.480461 [DEBUG] switch_ivr_originate.c:1318 Play Ringback Tone [%(2000,4000,440,480)]
send 1237 bytes to tls/[180.151.83.178]:63093 at 10:05:23.495220:
------------------------------------------------------------------------
SIP/2.0 183 Session Progress
Via: SIP/2.0/TLS 192.168.93.102:45556;branch=z9hG4bK.cZ3vY0uWP;rport=63093;received=180.151.83.178
From: <sip:1003 at x.x.x.x>;tag=hKZC8L27Q
To: <sip:1010 at x.x.x.x>;tag=7j0Bjvte21NFe
Call-ID: BbPYZv5Bca
CSeq: 21 INVITE
Contact: <sip:1010 at x.x.x.x:5061;transport=tls>
User-Agent: FreeSWITCH-mod_sofia/1.4.21+git~20150901T202622Z~a223dd0236~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, 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: 336
Remote-Party-ID: "1010" <sip:1010 at x.x.x.x>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1441774779 1441774780 IN IP4 x.x.x.x
s=FreeSWITCH
c=IN IP4 x.x.x.x
t=0 0
m=audio 18344 RTP/SAVP 96 101
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:44c6ZMEyLHkmecAZKJf7Nf8hAPMQhA4rubdYPr2/
------------------------------------------------------------------------
2015-09-09 10:05:23.480461 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:23.500460 [DEBUG] sofia.c:6634 Channel sofia/internal/1003 at x.x.x.x entering state [early][183]
2015-09-09 10:05:25.080465 [INFO] switch_rtp.c:5867 Auto Changing port from 192.168.93.102:7076 to 180.151.83.178:41804
recv 1098 bytes from tls/[180.151.83.178]:13916 at 10:05:25.857085:
------------------------------------------------------------------------
SIP/2.0 200 Ok
Via: SIP/2.0/TLS x.x.x.x:5061;rport;branch=z9hG4bKmHD6cSZUSjtmS
From: "Extension 1003" <sip:1003 at x.x.x.x>;tag=8US4KQBjZac2S
To: <sip:1010 at 180.151.83.178:13916;app-id=622464153529;pn-type=google;pn-tok=APA91bFqivAK_KIDpU_6PM0pf0U8rx9DOKm0vhyNRqjE1Dpq_uPRbTbT-BMwxNP5NmEyCMfnKxa-fjEhI2J-lzLkCcfFphO1hL39cE4VNqAnnfDbVeQbvmQ;transport=tls>;tag=ezLC2Tx
Call-ID: 1fbbb0c5-d17d-1233-c292-1293c2c31053
CSeq: 80560497 INVITE
User-Agent: LinphoneAndroid/2.4.1-28-g98516d9 (belle-sip/1.4.1)
Supported: outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Contact: <sip:1010 at 180.151.83.178:13916;transport=tls>;+sip.instance="<urn:uuid:b8e75e87-d0ef-4254-adb6-79366476c784>"
Content-Type: application/sdp
Content-Length: 300
v=0
o=1010 2282 1220 IN IP4 192.168.93.111
s=Talk
c=IN IP4 192.168.93.111
b=AS:380
t=0 0
m=audio 7076 RTP/SAVP 96 0 8 101
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:101 telephone-event/8000
a=crypto:3 AES_CM_256_HMAC_SHA1_80 inline:7xYnuvUnDG18O3SS73sJH0aTo5Tpa4jyiTH40x0U
------------------------------------------------------------------------
2015-09-09 10:05:25.840464 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:25.840464 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:25.860464 [DEBUG] sofia.c:6634 Channel sofia/internal/1010 at 180.151.83.178:13916 entering state [completing][200]
2015-09-09 10:05:25.860464 [DEBUG] sofia.c:6644 Remote SDP:
v=0
o=1010 2282 1220 IN IP4 192.168.93.111
s=Talk
c=IN IP4 192.168.93.111
b=AS:380
t=0 0
m=audio 7076 RTP/SAVP 96 0 8 101
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:101 telephone-event/8000
a=crypto:3 AES_CM_256_HMAC_SHA1_80 inline:7xYnuvUnDG18O3SS73sJH0aTo5Tpa4jyiTH40x0U
send 582 bytes to tls/[180.151.83.178]:13916 at 10:05:25.861580:
------------------------------------------------------------------------
ACK sip:1010 at 180.151.83.178:13916;transport=tls SIP/2.0
Via: SIP/2.0/TLS x.x.x.x:5061;rport;branch=z9hG4bKNt6yemgZpUg7m
Max-Forwards: 70
From: "Extension 1003" <sip:1003 at x.x.x.x>;tag=8US4KQBjZac2S
To: <sip:1010 at 180.151.83.178:13916;app-id=622464153529;pn-type=google;pn-tok=APA91bFqivAK_KIDpU_6PM0pf0U8rx9DOKm0vhyNRqjE1Dpq_uPRbTbT-BMwxNP5NmEyCMfnKxa-fjEhI2J-lzLkCcfFphO1hL39cE4VNqAnnfDbVeQbvmQ;transport=tls>;tag=ezLC2Tx
Call-ID: 1fbbb0c5-d17d-1233-c292-1293c2c31053
CSeq: 80560497 ACK
Contact: <sip:mod_sofia at x.x.x.x:5061;transport=tls>
Content-Length: 0
------------------------------------------------------------------------
2015-09-09 10:05:25.860464 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:25.860464 [DEBUG] sofia.c:6634 Channel sofia/internal/1010 at 180.151.83.178:13916 entering state [ready][200]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:1228 looking for crypto suite [AEAD_AES_256_GCM_8] in [3 AES_CM_256_HMAC_SHA1_80 inline:7xYnuvUnDG18O3SS73sJH0aTo5Tpa4jyiTH40x0U]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:1228 looking for crypto suite [AEAD_AES_128_GCM_8] in [3 AES_CM_256_HMAC_SHA1_80 inline:7xYnuvUnDG18O3SS73sJH0aTo5Tpa4jyiTH40x0U]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:1228 looking for crypto suite [AES_CM_256_HMAC_SHA1_80] in [3 AES_CM_256_HMAC_SHA1_80 inline:7xYnuvUnDG18O3SS73sJH0aTo5Tpa4jyiTH40x0U]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:1233 Found suite AES_CM_256_HMAC_SHA1_80
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:1299 Set Remote Key [3 AES_CM_256_HMAC_SHA1_80 inline:7xYnuvUnDG18O3SS73sJH0aTo5Tpa4jyiTH40x0U]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [opus:96:48000:20:0:1]/[opus:116:48000:20:0:2]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3734 Audio Codec Compare [opus:116:48000:20:0:2] ++++ is saved as a match
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [opus:96:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [opus:96:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [opus:96:48000:20:0:1]/[opus:116:48000:20:0:1]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3734 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [opus:96:48000:20:0:1]/[G722:9:8000:20:64000:1]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [opus:96:48000:20:0:1]/[GSM:3:8000:20:13200:1]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:2]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3734 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:2]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3734 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3595 Set telephone-event payload to 101
2015-09-09 10:05:25.860464 [DEBUG] mod_opus.c:289 Opus encoder set bitrate to local settings [-1000bps]
2015-09-09 10:05:25.860464 [DEBUG] mod_opus.c:289 Opus encoder set bitrate to local settings [-1000bps]
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:2506 Set Codec sofia/internal/1010 at 180.151.83.178:13916 opus/48000 20 ms 960 samples 0 bits 1 channels
2015-09-09 10:05:25.860464 [DEBUG] switch_core_codec.c:111 sofia/internal/1010 at 180.151.83.178:13916 Original read codec set to opus:116
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:3933 Set 2833 dtmf send payload to 101
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:5178 AUDIO RTP [sofia/internal/1010 at 180.151.83.178:13916] y.y.y.y port 28546 -> 192.168.93.111 port 7076 codec: 96 ms: 20
2015-09-09 10:05:25.860464 [DEBUG] switch_rtp.c:3579 Starting timer [soft] 960 bytes per 20ms
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:5476 Set 2833 dtmf send payload to 101
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:5482 Set 2833 dtmf receive payload to 101
2015-09-09 10:05:25.860464 [DEBUG] switch_core_media.c:5504 sofia/internal/1010 at 180.151.83.178:13916 Set rtp dtmf delay to 40
2015-09-09 10:05:25.860464 [INFO] switch_rtp.c:3394 Activating Audio Secure RTP SEND
2015-09-09 10:05:25.860464 [INFO] switch_rtp.c:3372 Activating Audio Secure RTP RECV
2015-09-09 10:05:25.860464 [DEBUG] switch_core_sqldb.c:2599 Secure Type: srtp:sdes:AES_CM_256_HMAC_SHA1_80
2015-09-09 10:05:25.860464 [DEBUG] switch_core_sqldb.c:2599 Secure Type: srtp:sdes:AES_CM_256_HMAC_SHA1_80
2015-09-09 10:05:25.860464 [DEBUG] switch_channel.c:3657 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:25.860464 [NOTICE] sofia.c:7501 Channel [sofia/internal/1010 at 180.151.83.178:13916] has been answered
2015-09-09 10:05:25.860464 [DEBUG] switch_channel.c:3711 (sofia/internal/1010 at 180.151.83.178:13916) Callstate Change RINGING -> ACTIVE
2015-09-09 10:05:25.860464 [DEBUG] switch_core_codec.c:246 sofia/internal/1003 at x.x.x.x Restore previous codec opus:116.
2015-09-09 10:05:25.860464 [DEBUG] mod_sofia.c:780 Local SDP sofia/internal/1003 at x.x.x.x:
v=0
o=FreeSWITCH 1441774779 1441774781 IN IP4 x.x.x.x
s=FreeSWITCH
c=IN IP4 x.x.x.x
t=0 0
m=audio 18344 RTP/SAVP 96 101
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:44c6ZMEyLHkmecAZKJf7Nf8hAPMQhA4rubdYPr2/
2015-09-09 10:05:25.860464 [DEBUG] switch_core_session.c:913 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
send 1207 bytes to tls/[180.151.83.178]:63093 at 10:05:25.876054:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/TLS 192.168.93.102:45556;branch=z9hG4bK.cZ3vY0uWP;rport=63093;received=180.151.83.178
From: <sip:1003 at x.x.x.x>;tag=hKZC8L27Q
To: <sip:1010 at x.x.x.x>;tag=7j0Bjvte21NFe
Call-ID: BbPYZv5Bca
CSeq: 21 INVITE
Contact: <sip:1010 at x.x.x.x:5061;transport=tls>
User-Agent: FreeSWITCH-mod_sofia/1.4.21+git~20150901T202622Z~a223dd0236~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, 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: 336
Remote-Party-ID: "Outbound Call" <sip:1010 at x.x.x.x>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1441774779 1441774780 IN IP4 x.x.x.x
s=FreeSWITCH
c=IN IP4 x.x.x.x
t=0 0
m=audio 18344 RTP/SAVP 96 101
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:44c6ZMEyLHkmecAZKJf7Nf8hAPMQhA4rubdYPr2/
------------------------------------------------------------------------
2015-09-09 10:05:25.860464 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:25.860464 [NOTICE] switch_ivr_originate.c:3523 Channel [sofia/internal/1003 at x.x.x.x] has been answered
2015-09-09 10:05:25.860464 [DEBUG] switch_channel.c:3711 (sofia/internal/1003 at x.x.x.x) Callstate Change EARLY -> ACTIVE
2015-09-09 10:05:25.860464 [DEBUG] sofia.c:6634 Channel sofia/internal/1003 at x.x.x.x entering state [completed][200]
2015-09-09 10:05:25.860464 [DEBUG] switch_ivr_originate.c:3581 Originate Resulted in Success: [sofia/internal/1010 at 180.151.83.178:13916]
2015-09-09 10:05:25.860464 [DEBUG] switch_ivr_originate.c:3581 Originate Resulted in Success: [sofia/internal/1010 at 180.151.83.178:13916]
2015-09-09 10:05:25.882975 [DEBUG] switch_core_session.c:913 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:25.882975 [DEBUG] switch_core_session.c:913 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:25.882975 [DEBUG] switch_ivr_bridge.c:1468 (sofia/internal/1010 at 180.151.83.178:13916) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2015-09-09 10:05:25.882975 [DEBUG] switch_core_session.c:1397 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:25.882975 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1010 at 180.151.83.178:13916) Running State Change CS_EXCHANGE_MEDIA
2015-09-09 10:05:25.882975 [DEBUG] switch_core_state_machine.c:538 (sofia/internal/1010 at 180.151.83.178:13916) State EXCHANGE_MEDIA
2015-09-09 10:05:25.882975 [DEBUG] mod_sofia.c:594 SOFIA EXCHANGE_MEDIA
2015-09-09 10:05:25.882975 [DEBUG] switch_rtp.c:5894 Correct ip/port confirmed.
2015-09-09 10:05:25.882975 [DEBUG] mod_opus.c:289 Opus encoder set bitrate to local settings [-1000bps]
send 1207 bytes to tls/[180.151.83.178]:63093 at 10:05:26.379657:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/TLS 192.168.93.102:45556;branch=z9hG4bK.cZ3vY0uWP;rport=63093;received=180.151.83.178
From: <sip:1003 at x.x.x.x>;tag=hKZC8L27Q
To: <sip:1010 at x.x.x.x>;tag=7j0Bjvte21NFe
Call-ID: BbPYZv5Bca
CSeq: 21 INVITE
Contact: <sip:1010 at x.x.x.x:5061;transport=tls>
User-Agent: FreeSWITCH-mod_sofia/1.4.21+git~20150901T202622Z~a223dd0236~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, 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: 336
Remote-Party-ID: "Outbound Call" <sip:1010 at x.x.x.x>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1441774779 1441774780 IN IP4 x.x.x.x
s=FreeSWITCH
c=IN IP4 x.x.x.x
t=0 0
m=audio 18344 RTP/SAVP 96 101
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:44c6ZMEyLHkmecAZKJf7Nf8hAPMQhA4rubdYPr2/
------------------------------------------------------------------------
recv 536 bytes from tls/[180.151.83.178]:63093 at 10:05:26.825971:
------------------------------------------------------------------------
ACK sip:1010 at x.x.x.x:5061;transport=tls SIP/2.0
Via: SIP/2.0/TLS 192.168.93.102:45556;rport;branch=z9hG4bK.Tek3oSUVA
From: <sip:1003 at x.x.x.x>;tag=hKZC8L27Q
To: <sip:1010 at x.x.x.x>;tag=7j0Bjvte21NFe
CSeq: 21 ACK
Call-ID: BbPYZv5Bca
Max-Forwards: 70
Proxy-Authorization: Digest realm="x.x.x.x", nonce="47fa5ad2-56da-11e5-abf6-a53fe62ce2f9", algorithm=MD5, username="1003", uri="sip:1010 at x.x.x.x", response="7051af6f556408074ede39d53ff582c2", cnonce="faaa8515", nc=00000001, qop=auth
Content-Length: 0
------------------------------------------------------------------------
2015-09-09 10:05:26.820469 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:26.820469 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:26.820469 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:26.820469 [DEBUG] sofia.c:6634 Channel sofia/internal/1003 at x.x.x.x entering state [ready][200]
2015-09-09 10:05:26.820469 [DEBUG] switch_core_session.c:979 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:26.820469 [DEBUG] switch_core_session.c:979 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
recv 536 bytes from tls/[180.151.83.178]:63093 at 10:05:27.098382:
------------------------------------------------------------------------
ACK sip:1010 at x.x.x.x:5061;transport=tls SIP/2.0
Via: SIP/2.0/TLS 192.168.93.102:45556;branch=z9hG4bK.Tek3oSUVA;rport
From: <sip:1003 at x.x.x.x>;tag=hKZC8L27Q
To: <sip:1010 at x.x.x.x>;tag=7j0Bjvte21NFe
CSeq: 21 ACK
Call-ID: BbPYZv5Bca
Max-Forwards: 70
Proxy-Authorization: Digest realm="x.x.x.x", nonce="47fa5ad2-56da-11e5-abf6-a53fe62ce2f9", algorithm=MD5, username="1003", uri="sip:1010 at x.x.x.x", response="7051af6f556408074ede39d53ff582c2", cnonce="faaa8515", nc=00000001, qop=auth
Content-Length: 0
------------------------------------------------------------------------
recv 566 bytes from tls/[180.151.83.178]:13916 at 10:05:56.602820:
------------------------------------------------------------------------
BYE sip:mod_sofia at x.x.x.x:5061;transport=tls SIP/2.0
Via: SIP/2.0/TLS 192.168.93.111:43713;branch=z9hG4bK.5hPjwbARP;rport
From: <sip:1010 at 180.151.83.178;app-id=622464153529;pn-type=google;pn-tok=APA91bFqivAK_KIDpU_6PM0pf0U8rx9DOKm0vhyNRqjE1Dpq_uPRbTbT-BMwxNP5NmEyCMfnKxa-fjEhI2J-lzLkCcfFphO1hL39cE4VNqAnnfDbVeQbvmQ>;tag=ezLC2Tx
To: "Extension 1003" <sip:1003 at x.x.x.x>;tag=8US4KQBjZac2S
CSeq: 111 BYE
Call-ID: 1fbbb0c5-d17d-1233-c292-1293c2c31053
Max-Forwards: 70
User-Agent: LinphoneAndroid/2.4.1-28-g98516d9 (belle-sip/1.4.1)
Content-Length: 0
------------------------------------------------------------------------
2015-09-09 10:05:56.600460 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:56.600460 [NOTICE] sofia.c:952 Hangup sofia/internal/1010 at 180.151.83.178:13916 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2015-09-09 10:05:56.600460 [DEBUG] switch_channel.c:3242 Send signal sofia/internal/1010 at 180.151.83.178:13916 [KILL]
2015-09-09 10:05:56.600460 [DEBUG] switch_core_session.c:1397 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
send 693 bytes to tls/[180.151.83.178]:13916 at 10:05:56.606104:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/TLS 192.168.93.111:43713;branch=z9hG4bK.5hPjwbARP;rport=13916;received=180.151.83.178
From: <sip:1010 at 180.151.83.178;app-id=622464153529;pn-type=google;pn-tok=APA91bFqivAK_KIDpU_6PM0pf0U8rx9DOKm0vhyNRqjE1Dpq_uPRbTbT-BMwxNP5NmEyCMfnKxa-fjEhI2J-lzLkCcfFphO1hL39cE4VNqAnnfDbVeQbvmQ>;tag=ezLC2Tx
To: "Extension 1003" <sip:1003 at x.x.x.x>;tag=8US4KQBjZac2S
Call-ID: 1fbbb0c5-d17d-1233-c292-1293c2c31053
CSeq: 111 BYE
User-Agent: FreeSWITCH-mod_sofia/1.4.21+git~20150901T202622Z~a223dd0236~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Content-Length: 0
------------------------------------------------------------------------
2015-09-09 10:05:56.600460 [DEBUG] switch_ivr_bridge.c:660 BRIDGE THREAD DONE [sofia/internal/1010 at 180.151.83.178:13916]
2015-09-09 10:05:56.600460 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:538 (sofia/internal/1010 at 180.151.83.178:13916) State EXCHANGE_MEDIA going to sleep
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1010 at 180.151.83.178:13916) Running State Change CS_HANGUP
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:735 (sofia/internal/1010 at 180.151.83.178:13916) Callstate Change ACTIVE -> HANGUP
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:737 (sofia/internal/1010 at 180.151.83.178:13916) State HANGUP
2015-09-09 10:05:56.600460 [DEBUG] mod_sofia.c:413 Channel sofia/internal/1010 at 180.151.83.178:13916 hanging up, cause: NORMAL_CLEARING
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1010 at 180.151.83.178:13916 Standard HANGUP, cause: NORMAL_CLEARING
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:737 (sofia/internal/1010 at 180.151.83.178:13916) State HANGUP going to sleep
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/1010 at 180.151.83.178:13916) State Change CS_HANGUP -> CS_REPORTING
2015-09-09 10:05:56.600460 [DEBUG] switch_core_session.c:1397 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1010 at 180.151.83.178:13916) Running State Change CS_REPORTING
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:823 (sofia/internal/1010 at 180.151.83.178:13916) State REPORTING
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:104 sofia/internal/1010 at 180.151.83.178:13916 Standard REPORTING, cause: NORMAL_CLEARING
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:823 (sofia/internal/1010 at 180.151.83.178:13916) State REPORTING going to sleep
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:498 (sofia/internal/1010 at 180.151.83.178:13916) State Change CS_REPORTING -> CS_DESTROY
2015-09-09 10:05:56.600460 [DEBUG] switch_core_session.c:1397 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:56.600460 [DEBUG] switch_core_session.c:1624 Session 2 (sofia/internal/1010 at 180.151.83.178:13916) Locked, Waiting on external entities
2015-09-09 10:05:56.600460 [DEBUG] switch_ivr_bridge.c:579 sofia/internal/1010 at 180.151.83.178:13916 ending bridge by request from write function
2015-09-09 10:05:56.600460 [DEBUG] switch_ivr_bridge.c:660 BRIDGE THREAD DONE [sofia/internal/1003 at x.x.x.x]
2015-09-09 10:05:56.600460 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/internal/1010 at 180.151.83.178:13916 [BREAK]
2015-09-09 10:05:56.600460 [DEBUG] switch_core_session.c:913 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:56.600460 [NOTICE] switch_ivr_bridge.c:1611 Hangup sofia/internal/1003 at x.x.x.x [CS_EXECUTE] [NORMAL_CLEARING]
2015-09-09 10:05:56.600460 [DEBUG] switch_channel.c:3242 Send signal sofia/internal/1003 at x.x.x.x [KILL]
2015-09-09 10:05:56.600460 [DEBUG] switch_core_session.c:1397 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:56.600460 [NOTICE] switch_core_session.c:1642 Session 2 (sofia/internal/1010 at 180.151.83.178:13916) Ended
2015-09-09 10:05:56.600460 [NOTICE] switch_core_session.c:1646 Close Channel sofia/internal/1010 at 180.151.83.178:13916 [CS_DESTROY]
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:626 (sofia/internal/1010 at 180.151.83.178:13916) Running State Change CS_DESTROY
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:636 (sofia/internal/1010 at 180.151.83.178:13916) State DESTROY
2015-09-09 10:05:56.600460 [DEBUG] mod_sofia.c:323 sofia/internal/1010 at 180.151.83.178:13916 SOFIA DESTROY
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:111 sofia/internal/1010 at 180.151.83.178:13916 Standard DESTROY
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:636 (sofia/internal/1010 at 180.151.83.178:13916) State DESTROY going to sleep
2015-09-09 10:05:56.600460 [DEBUG] switch_core_session.c:2903 sofia/internal/1003 at x.x.x.x skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:535 (sofia/internal/1003 at x.x.x.x) State EXECUTE going to sleep
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1003 at x.x.x.x) Running State Change CS_HANGUP
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:735 (sofia/internal/1003 at x.x.x.x) Callstate Change ACTIVE -> HANGUP
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:737 (sofia/internal/1003 at x.x.x.x) State HANGUP
2015-09-09 10:05:56.600460 [DEBUG] mod_sofia.c:407 sofia/internal/1003 at x.x.x.x Overriding SIP cause 480 with 200 from the other leg
2015-09-09 10:05:56.600460 [DEBUG] mod_sofia.c:413 Channel sofia/internal/1003 at x.x.x.x hanging up, cause: NORMAL_CLEARING
2015-09-09 10:05:56.600460 [DEBUG] mod_sofia.c:465 Sending BYE to sofia/internal/1003 at x.x.x.x
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1003 at x.x.x.x Standard HANGUP, cause: NORMAL_CLEARING
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:737 (sofia/internal/1003 at x.x.x.x) State HANGUP going to sleep
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/1003 at x.x.x.x) State Change CS_HANGUP -> CS_REPORTING
2015-09-09 10:05:56.600460 [DEBUG] switch_core_session.c:1397 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1003 at x.x.x.x) Running State Change CS_REPORTING
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:823 (sofia/internal/1003 at x.x.x.x) State REPORTING
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:104 sofia/internal/1003 at x.x.x.x Standard REPORTING, cause: NORMAL_CLEARING
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:823 (sofia/internal/1003 at x.x.x.x) State REPORTING going to sleep
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:498 (sofia/internal/1003 at x.x.x.x) State Change CS_REPORTING -> CS_DESTROY
2015-09-09 10:05:56.600460 [DEBUG] switch_core_session.c:1397 Send signal sofia/internal/1003 at x.x.x.x [BREAK]
2015-09-09 10:05:56.600460 [DEBUG] switch_core_session.c:1624 Session 1 (sofia/internal/1003 at x.x.x.x) Locked, Waiting on external entities
2015-09-09 10:05:56.600460 [NOTICE] switch_core_session.c:1642 Session 1 (sofia/internal/1003 at x.x.x.x) Ended
2015-09-09 10:05:56.600460 [NOTICE] switch_core_session.c:1646 Close Channel sofia/internal/1003 at x.x.x.x [CS_DESTROY]
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:626 (sofia/internal/1003 at x.x.x.x) Running State Change CS_DESTROY
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:636 (sofia/internal/1003 at x.x.x.x) State DESTROY
2015-09-09 10:05:56.600460 [DEBUG] mod_sofia.c:323 sofia/internal/1003 at x.x.x.x SOFIA DESTROY
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:111 sofia/internal/1003 at x.x.x.x Standard DESTROY
2015-09-09 10:05:56.600460 [DEBUG] switch_core_state_machine.c:636 (sofia/internal/1003 at x.x.x.x) State DESTROY going to sleep
send 569 bytes to tls/[180.151.83.178]:63093 at 10:05:56.617659:
------------------------------------------------------------------------
BYE sip:1003 at 180.151.83.178:63093;transport=tls SIP/2.0
Via: SIP/2.0/TLS x.x.x.x:5061;rport;branch=z9hG4bKp3ZQgF12K46Sg
Max-Forwards: 70
From: <sip:1010 at x.x.x.x>;tag=7j0Bjvte21NFe
To: <sip:1003 at x.x.x.x>;tag=hKZC8L27Q
Call-ID: BbPYZv5Bca
CSeq: 80560514 BYE
User-Agent: FreeSWITCH-mod_sofia/1.4.21+git~20150901T202622Z~a223dd0236~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Reason: Q.850;cause=16;text="NORMAL_CLEARING"
Content-Length: 0
------------------------------------------------------------------------
recv 326 bytes from tls/[180.151.83.178]:63093 at 10:05:57.406495:
------------------------------------------------------------------------
SIP/2.0 200 Ok
Via: SIP/2.0/TLS x.x.x.x:5061;rport;branch=z9hG4bKp3ZQgF12K46Sg
From: <sip:1010 at x.x.x.x>;tag=7j0Bjvte21NFe
To: <sip:1003 at x.x.x.x>;tag=hKZC8L27Q
Call-ID: BbPYZv5Bca
CSeq: 80560514 BYE
User-Agent: LinphoneAndroid/2.4.1-28-g98516d9 (belle-sip/1.4.1)
Supported: outbound
Content-Length: 0
--------------------
Join us at ClueCon 2016 Aug 8-12, 2016
More information about the FreeSWITCH-users
mailing list