[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