[Freeswitch-users] WebRTC slow connection time

Adam Ben-Ayoun adam.ben.ayoun1 at gmail.com
Fri May 8 20:14:45 MSD 2015


I am probably missing something, we do use 80/443 for TCP/TLS for
signalling. My thinking is that media will use UDP which can be restricted.

On 8 May 2015 at 19:09, Victor Medina <victor.medina at cibersys.com> wrote:

> What are the chalenges of putting the internal channel on 80(tcp) and
> 443(tls)? (besides the obvious things of having to deal with a server
> running under a privileged ports)
>
> 2015-05-08 11:28 GMT-04:30 Giovanni Maruzzelli <gmaruzz at gmail.com>:
>
>
>> Btw, that (accomodating clients that only do tcp 80/443) is the biggest
>> and almost unique reason of Skype success...
>>
>> sent from my mobile,
>> Giovanni Maruzzelli
>> cell: +39 347 266 56 18
>> On May 8, 2015 5:53 PM, "Adam Ben-Ayoun" <adam.ben.ayoun1 at gmail.com>
>> wrote:
>>
>>> Is there an easier way to deal with clients which can only do TCP on
>>> port 443/80 for example?
>>>
>>> On 8 May 2015 at 18:40, Adam Ben-Ayoun <adam.ben.ayoun1 at gmail.com>
>>> wrote:
>>>
>>>> I am using TURN as a TCP fallback (when UDP is blocked).
>>>>
>>>> On 8 May 2015 at 18:34, Michael Jerris <mike at jerris.com> wrote:
>>>>
>>>>> If you have freeswitch on a public address, why would you ever use
>>>>> TURN?
>>>>>
>>>>> On May 8, 2015, at 4:27 AM, Adam Ben-Ayoun <adam.ben.ayoun1 at gmail.com>
>>>>> wrote:
>>>>>
>>>>> Hi guys,
>>>>>
>>>>> I am using Freeswitch from master (month old). I tried several WebRTC
>>>>> clients (my own test app on Android and sipml5) and on certain WiFi's I am
>>>>> getting connection time up to 35 seconds when using STUN and TURN servers.
>>>>> Also, when I am using TURN and STUN, Freeswitch chooses the TURN candidate
>>>>> although as far as connectivity, when I am not using STUN and TURN I am
>>>>> connecting successfully after ~2 seconds (so no real need for TURN).
>>>>> Attaching the SIP trace from Freeswitch:
>>>>>
>>>>> nua.c:575 nua_set_params() nua: nua_set_params: entering
>>>>> nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params
>>>>> nua.c:575 nua_set_params() nua: nua_set_params: entering
>>>>> nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params
>>>>> nua.c:575 nua_set_params() nua: nua_set_params: entering
>>>>> nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params
>>>>> nua.c:575 nua_set_params() nua: nua_set_params: entering
>>>>> nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params
>>>>> nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params
>>>>> nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params:
>>>>> entering
>>>>> nua.c:575 nua_set_params() nua: nua_set_params: entering
>>>>> nua_stack.c:529 nua_signal() nua((nil)): sent signal r_set_params
>>>>> soa.c:403 soa_set_params() soa_set_params(static::0x7fe17c001930, ...)
>>>>> called
>>>>> nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK
>>>>> nua_stack.c:359 nua_application_event() nua: nua_application_event:
>>>>> entering
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params
>>>>> nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params:
>>>>> entering
>>>>> soa.c:403 soa_set_params() soa_set_params(static::0x7fe18c001930, ...)
>>>>> called
>>>>> nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params
>>>>> nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params:
>>>>> entering
>>>>> nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK
>>>>> soa.c:403 soa_set_params() soa_set_params(static::0x7fe17c001930, ...)
>>>>> called
>>>>> nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK
>>>>> nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params
>>>>> nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params:
>>>>> entering
>>>>> soa.c:403 soa_set_params() soa_set_params(static::0x7fe184001930, ...)
>>>>> called
>>>>> nua_stack.c:359 nua_application_event() nua: nua_application_event:
>>>>> entering
>>>>> nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> nua_stack.c:359 nua_application_event() nua: nua_application_event:
>>>>> entering
>>>>> nua_stack.c:569 nua_stack_signal() nua((nil)): recv signal r_set_params
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params:
>>>>> entering
>>>>> soa.c:403 soa_set_params() soa_set_params(static::0x7fe188001930, ...)
>>>>> called
>>>>> nua_stack.c:271 nua_stack_event() nua((nil)): event r_set_params 200 OK
>>>>> nua_stack.c:359 nua_application_event() nua: nua_application_event:
>>>>> entering
>>>>> nua_stack.c:359 nua_application_event() nua: nua_application_event:
>>>>> entering
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> tport.c:2773 tport_wakeup() tport_wakeup(0x7fe17c0d4ba0): events IN
>>>>> tport.c:2864 tport_recv_event() tport_recv_event(0x7fe17c0d4ba0)
>>>>> tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7fe17c0d4ba0) msg
>>>>> 0x7fe17c089c50 from (ws/82.166.84.247:53645) has 2598 bytes, veclen =
>>>>> 1
>>>>> recv 2598 bytes from ws/[82.166.84.247]:53645 at 08:21:30.468866:
>>>>>
>>>>>  ------------------------------------------------------------------------
>>>>>    INVITE sip:991234 at aaaa SIP/2.0
>>>>>    Via: SIP/2.0/WS
>>>>> df7jal23ls0d.invalid;branch=z9hG4bKml28I3BsDokxOyXDaHfSBPW94I6MO4HK;rport
>>>>>    From: "asdasda"<sip:1000 at xxx.xxx.xxx.xxx>;tag=THvNqRR9fmMzKb6JP9hp
>>>>>    To: <sip:991234 at aaaa>
>>>>>    Contact: "asdasda"<
>>>>> sip:1000 at df7jal23ls0d.invalid;rtcweb-breaker=no;click2call=no;transport=ws
>>>>> >;+g.oma.sip-im;language="en,fr"
>>>>>    Call-ID: fa0bf4d8-2037-a467-61fd-4f78e9746fbe
>>>>>    CSeq: 28092 INVITE
>>>>>    Content-Type: application/sdp
>>>>>    Content-Length: 2039
>>>>>    Max-Forwards: 70
>>>>>    User-Agent: IM-client/OMA1.0 sipML5-v1.2015.03.18
>>>>>    Organization: Doubango Telecom
>>>>>
>>>>>    v=0
>>>>>    o=- 3843427479443760600 2 IN IP4 127.0.0.1
>>>>>    s=Doubango Telecom - chrome
>>>>>    t=0 0
>>>>>    a=group:BUNDLE audio
>>>>>    a=msid-semantic: WMS QqT0ePCaEFzZ3vHeaMToEsTZan1K2F3O3czm
>>>>>    m=audio 58209 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 126
>>>>>    c=IN IP4 130.211.78.35
>>>>>    a=rtcp:58209 IN IP4 130.211.78.35
>>>>>    a=candidate:2162125114 1 udp 2122260223 10.0.0.10 63888 typ host
>>>>> generation 0
>>>>>    a=candidate:2162125114 2 udp 2122260223 10.0.0.10 63888 typ host
>>>>> generation 0
>>>>>    a=candidate:3260192690 1 udp 1686052607 82.166.84.247 63888 typ
>>>>> srflx raddr 10.0.0.10 rport 63888 generation 0
>>>>>    a=candidate:3260192690 2 udp 1686052607 82.166.84.247 63888 typ
>>>>> srflx raddr 10.0.0.10 rport 63888 generation 0
>>>>>    a=candidate:3462174154 1 tcp 1518280447 10.0.0.10 0 typ host
>>>>> tcptype active generation 0
>>>>>    a=candidate:3462174154 2 tcp 1518280447 10.0.0.10 0 typ host
>>>>> tcptype active generation 0
>>>>>    a=candidate:3098925784 1 udp 25108223 130.211.78.35 58209 typ
>>>>> relay raddr 82.166.84.247 rport 53792 generation 0
>>>>>    a=candidate:3098925784 2 udp 25108223 130.211.78.35 58209 typ
>>>>> relay raddr 82.166.84.247 rport 53792 generation 0
>>>>>    a=ice-ufrag:EDo5kr308/TXhitG
>>>>>    a=ice-pwd:3HWj7s5L/1g2BwIrjJNPnubB
>>>>>    a=ice-options:google-ice
>>>>>    a=fingerprint:sha-256
>>>>> 2D:92:8B:F0:BD:9C:C3:85:9F:B6:32:4C:B9:73:38:AD:82:1A:D3:02:F5:D8:7B:9E:0E:D4:86:FB:A7:DF:E1:C6
>>>>>    a=setup:actpass
>>>>>    a=mid:audio
>>>>>    a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
>>>>>    a=extmap:3
>>>>> http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
>>>>>    a=sendrecv
>>>>>    a=rtcp-mux
>>>>>    a=rtpmap:111 opus/48000/2
>>>>>    a=fmtp:111 minptime=10; useinbandfec=1
>>>>>    a=rtpmap:103 ISAC/16000
>>>>>    a=rtpmap:104 ISAC/32000
>>>>>    a=rtpmap:9 G722/8000
>>>>>    a=rtpmap:0 PCMU/8000
>>>>>    a=rtpmap:8 PCMA/8000
>>>>>    a=rtpmap:106 CN/32000
>>>>>    a=rtpmap:105 CN/16000
>>>>>    a=rtpmap:13 CN/8000
>>>>>    a=rtpmap:126 telephone-event/8000
>>>>>    a=maxptime:60
>>>>>    a=ssrc:4099543579 cname:X6JZwCe/LeIJBOws
>>>>>    a=ssrc:4099543579 msid:QqT0ePCaEFzZ3vHeaMToEsTZan1K2F3O3czm
>>>>> b8082781-4098-4ac5-8c96-2848d2e9e7e4
>>>>>    a=ssrc:4099543579 mslabel:QqT0ePCaEFzZ3vHeaMToEsTZan1K2F3O3czm
>>>>>    a=ssrc:4099543579 label:b8082781-4098-4ac5-8c96-2848d2e9e7e4
>>>>>
>>>>>  ------------------------------------------------------------------------
>>>>> tport.c:3023 tport_deliver() tport_deliver(0x7fe17c0d4ba0): msg
>>>>> 0x7fe17c089c50 (2598 bytes) from ws/82.166.84.247:53645/sip next=(nil)
>>>>> nta.c:2880 agent_recv_request() nta: received INVITE sip:991234 at aaaa
>>>>> SIP/2.0 (CSeq 28092)
>>>>> nta.c:3174 agent_check_request_via() nta: Via check:
>>>>> received=82.166.84.247
>>>>> nta.c:3085 agent_recv_request() nta: INVITE (28092) going to a default
>>>>> leg
>>>>> nta.c:1350 set_timeout() nta: timer set to 2000 ms
>>>>> nua_server.c:102 nua_stack_process_request() nua:
>>>>> nua_stack_process_request: entering
>>>>> nua_stack.c:899 nh_create() nua: nh_create: entering
>>>>> nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
>>>>> nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params:
>>>>> entering
>>>>> soa.c:280 soa_clone() soa_clone(static::0x7fe17c001930,
>>>>> 0x7fe17c001130, 0x7fe17c0cf210) called
>>>>> soa.c:403 soa_set_params() soa_set_params(static::0x7fe17c0bf4d0, ...)
>>>>> called
>>>>> nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7fe17c04a2e0)
>>>>> soa.c:1302 soa_init_offer_answer()
>>>>> soa_init_offer_answer(static::0x7fe17c0bf4d0) called
>>>>> soa.c:1171 soa_set_remote_sdp()
>>>>> soa_set_remote_sdp(static::0x7fe17c0bf4d0, (nil), 0x7fe17c0be55f, 2039)
>>>>> called
>>>>> nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fe17c0cf210): adding
>>>>> session usage
>>>>> tport.c:3257 tport_tsend() tport_tsend(0x7fe17c0d4ba0) tpn = WS/
>>>>> 82.166.84.247:53645
>>>>> tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec
>>>>> 0x7fe17c0d4d90 0x7fe17c0190a0 140 (140)
>>>>> tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec
>>>>> 0x7fe17c0d4d90 0x7fe17c0be3ab 86 (86)
>>>>> tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec
>>>>> 0x7fe17c0d4d90 0x7fe17c0be480 67 (67)
>>>>> tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec
>>>>> 0x7fe17c0d4d90 0x7fe17c01912c 101 (101)
>>>>> tport.c:3594 tport_vsend() tport_vsend(0x7fe17c0d4ba0): 394 bytes of
>>>>> 394 to ws/82.166.84.247:53645
>>>>> tport.c:3492 tport_send_msg() tport_vsend returned 394
>>>>> send 394 bytes to ws/[82.166.84.247]:53645 at 08:21:30.469343:
>>>>>
>>>>>  ------------------------------------------------------------------------
>>>>>    SIP/2.0 100 Trying
>>>>>    Via: SIP/2.0/WS
>>>>> df7jal23ls0d.invalid;branch=z9hG4bKml28I3BsDokxOyXDaHfSBPW94I6MO4HK;rport=53645;received=82.166.84.247
>>>>>    From: "asdasda"<sip:1000 at xxx.xxx.xxx.xxx>;tag=THvNqRR9fmMzKb6JP9hp
>>>>>    To: <sip:991234 at aaaa>
>>>>>    Call-ID: fa0bf4d8-2037-a467-61fd-4f78e9746fbe
>>>>>    CSeq: 28092 INVITE
>>>>>    User-Agent:
>>>>> FreeSWITCH-mod_sofia/1.5.15b+git~20150423T043308Z~b01352c133~64bit
>>>>>    Content-Length: 0
>>>>>
>>>>>
>>>>>  ------------------------------------------------------------------------
>>>>> tport.c:2296 tport_set_secondary_timer() tport(0x7fe17c0d4ba0): reset
>>>>> timer
>>>>> nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (28092)
>>>>> nua_stack.c:271 nua_stack_event() nua(0x7fe17c0cf210): event i_invite
>>>>> 100 Trying
>>>>> nua_session.c:4139 signal_call_state_change() nua(0x7fe17c0cf210):
>>>>> call state changed: init -> received, received offer
>>>>> soa.c:1098 soa_get_remote_sdp()
>>>>> soa_get_remote_sdp(static::0x7fe17c0bf4d0, [0x7fe1aa7b35d8],
>>>>> [0x7fe1aa7b35e0], [(nil)]) called
>>>>> nua_stack.c:271 nua_stack_event() nua(0x7fe17c0cf210): event i_state
>>>>> 100 Trying
>>>>> nua_stack.c:359 nua_application_event() nua: nua_application_event:
>>>>> entering
>>>>> tport.c:2296 tport_set_secondary_timer() tport(0x7fe17c0d4ba0): reset
>>>>> timer
>>>>> nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
>>>>> 2015-05-08 08:21:30.467711 [NOTICE] switch_channel.c:1075 New Channel
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx
>>>>> [3ac3c622-f55b-11e4-a447-7d37723461ed]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_session.c:1061 Send
>>>>> signal sofia/internal/1000 at xxx.xxx.xxx.xxx [BREAK]
>>>>> nua_stack.c:359 nua_application_event() nua: nua_application_event:
>>>>> entering
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_session.c:1061 Send
>>>>> signal sofia/internal/1000 at xxx.xxx.xxx.xxx [BREAK]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_state_machine.c:472 (
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx) Running State Change CS_NEW
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] sofia.c:8848
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx receiving invite from
>>>>> 82.166.84.247:53645 version: 1.5.15b git b01352c 2015-04-23 04:33:08Z
>>>>> 64bit
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] sofia.c:8960 IP 82.166.84.247
>>>>> Approved by acl "domains[]". Access Granted.
>>>>> nua.c:610 nua_set_hparams() nua: nua_set_hparams: entering
>>>>> nua.c:610 nua_set_hparams() nua: nua_r_set_params with invalid handle
>>>>> (nil)
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] sofia.c:10113 Setting NAT mode
>>>>> based on via received
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] sofia.c:6627 Channel
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx entering state [received][100]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] sofia.c:6637 Remote SDP:
>>>>> v=0
>>>>> o=- 3843427479443760600 2 IN IP4 127.0.0.1
>>>>> s=Doubango Telecom - chrome
>>>>> t=0 0
>>>>> a=group:BUNDLE audio
>>>>> a=msid-semantic: WMS QqT0ePCaEFzZ3vHeaMToEsTZan1K2F3O3czm
>>>>> m=audio 58209 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 126
>>>>> c=IN IP4 130.211.78.35
>>>>> a=rtpmap:111 opus/48000/2
>>>>> a=fmtp:111 minptime=10; useinbandfec=1
>>>>> a=rtpmap:103 ISAC/16000
>>>>> a=rtpmap:104 ISAC/32000
>>>>> a=rtpmap:9 G722/8000
>>>>> a=rtpmap:0 PCMU/8000
>>>>> a=rtpmap:8 PCMA/8000
>>>>> a=rtpmap:106 CN/32000
>>>>> a=rtpmap:105 CN/16000
>>>>> a=rtpmap:13 CN/8000
>>>>> a=rtpmap:126 telephone-event/8000
>>>>> a=rtcp:58209 IN IP4 130.211.78.35
>>>>> a=candidate:2162125114 1 udp 2122260223 10.0.0.10 63888 typ host
>>>>> generation 0
>>>>> a=candidate:2162125114 2 udp 2122260223 10.0.0.10 63888 typ host
>>>>> generation 0
>>>>> a=candidate:3260192690 1 udp 1686052607 82.166.84.247 63888 typ srflx
>>>>> raddr 10.0.0.10 rport 63888 generation 0
>>>>> a=candidate:3260192690 2 udp 1686052607 82.166.84.247 63888 typ srflx
>>>>> raddr 10.0.0.10 rport 63888 generation 0
>>>>> a=candidate:3462174154 1 tcp 1518280447 10.0.0.10 0 typ host tcptype
>>>>> active generation 0
>>>>> a=candidate:3462174154 2 tcp 1518280447 10.0.0.10 0 typ host tcptype
>>>>> active generation 0
>>>>> a=candidate:3098925784 1 udp 25108223 130.211.78.35 58209 typ relay
>>>>> raddr 82.166.84.247 rport 53792 generation 0
>>>>> a=candidate:3098925784 2 udp 25108223 130.211.78.35 58209 typ relay
>>>>> raddr 82.166.84.247 rport 53792 generation 0
>>>>> a=ice-ufrag:EDo5kr308/TXhitG
>>>>> a=ice-pwd:3HWj7s5L/1g2BwIrjJNPnubB
>>>>> a=ice-options:google-ice
>>>>> a=fingerprint:sha-256
>>>>> 2D:92:8B:F0:BD:9C:C3:85:9F:B6:32:4C:B9:73:38:AD:82:1A:D3:02:F5:D8:7B:9E:0E:D4:86:FB:A7:DF:E1:C6
>>>>> a=setup:actpass
>>>>> a=mid:audio
>>>>> a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
>>>>> a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
>>>>> a=rtcp-mux
>>>>> a=maxptime:60
>>>>> a=ssrc:4099543579 cname:X6JZwCe/LeIJBOws
>>>>> a=ssrc:4099543579 msid:QqT0ePCaEFzZ3vHeaMToEsTZan1K2F3O3czm
>>>>> b8082781-4098-4ac5-8c96-2848d2e9e7e4
>>>>> a=ssrc:4099543579 mslabel:QqT0ePCaEFzZ3vHeaMToEsTZan1K2F3O3czm
>>>>> a=ssrc:4099543579 label:b8082781-4098-4ac5-8c96-2848d2e9e7e4
>>>>>
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] sofia.c:6903 (
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx) State Change CS_NEW -> CS_INIT
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_session.c:1396 Send
>>>>> signal sofia/internal/1000 at xxx.xxx.xxx.xxx [BREAK]
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_state_machine.c:491 (
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx) State NEW
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_state_machine.c:472 (
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx) Running State Change CS_INIT
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_state_machine.c:512 (
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx) State INIT
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] mod_sofia.c:87
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx SOFIA INIT
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_state_machine.c:40
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx Standard INIT
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_state_machine.c:48 (
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx) State Change CS_INIT ->
>>>>> CS_ROUTING
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_session.c:1396 Send
>>>>> signal sofia/internal/1000 at xxx.xxx.xxx.xxx [BREAK]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_state_machine.c:512 (
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx) State INIT going to sleep
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_state_machine.c:472 (
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx) Running State Change CS_ROUTING
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_channel.c:2204 (
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx) Callstate Change DOWN -> RINGING
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_state_machine.c:528 (
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx) State ROUTING
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] mod_sofia.c:123
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx SOFIA ROUTING
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_state_machine.c:166
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx Standard ROUTING
>>>>> 2015-05-08 08:21:30.467711 [INFO] mod_dialplan_xml.c:635 Processing
>>>>> asdasda <1000>->991234 in context public
>>>>> Dialplan: sofia/internal/1000 at xxx.xxx.xxx.xxx parsing
>>>>> [public->cdquality_conferences_with_api] continue=false
>>>>> Dialplan: sofia/internal/1000 at xxx.xxx.xxx.xxx Regex (FAIL)
>>>>> [cdquality_conferences_with_api] destination_number(991234) =~
>>>>> /^(75\d{4,36})$/ break=on-false
>>>>> Dialplan: sofia/internal/1000 at xxx.xxx.xxx.xxx parsing
>>>>> [public->test_conferences] continue=false
>>>>> Dialplan: sofia/internal/1000 at xxx.xxx.xxx.xxx Regex (PASS)
>>>>> [test_conferences] destination_number(991234) =~ /^(99\d{4,36})$/
>>>>> break=on-false
>>>>> Dialplan: sofia/internal/1000 at xxx.xxx.xxx.xxx Action answer()
>>>>> Dialplan: sofia/internal/1000 at xxx.xxx.xxx.xxx Action
>>>>> conference(991234-${domain_name}@test)
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_state_machine.c:216 (
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx) State Change CS_ROUTING ->
>>>>> CS_EXECUTE
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_session.c:1396 Send
>>>>> signal sofia/internal/1000 at xxx.xxx.xxx.xxx [BREAK]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_state_machine.c:528 (
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx) State ROUTING going to sleep
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_state_machine.c:472 (
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx) Running State Change CS_EXECUTE
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_state_machine.c:535 (
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx) State EXECUTE
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] mod_sofia.c:178
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx SOFIA EXECUTE
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_state_machine.c:258
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx Standard EXECUTE
>>>>> EXECUTE sofia/internal/1000 at xxx.xxx.xxx.xxx answer()
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [opus:111:48000:60:0:1]/[opus:116:48000:20:0:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3701 Bah
>>>>> HUMBUG! Sticking with opus at 48000h@20i
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3727 Audio
>>>>> Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [opus:111:48000:60:0:1]/[PCMU:0:8000:20:64000:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [opus:111:48000:60:0:1]/[PCMA:8:8000:20:64000:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [ISAC:103:16000:30:32000:1]/[opus:116:48000:20:0:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [ISAC:103:16000:30:32000:1]/[PCMU:0:8000:20:64000:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [ISAC:103:16000:30:32000:1]/[PCMA:8:8000:20:64000:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [ISAC:104:32000:30:32000:1]/[opus:116:48000:20:0:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [ISAC:104:32000:30:32000:1]/[PCMU:0:8000:20:64000:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [ISAC:104:32000:30:32000:1]/[PCMA:8:8000:20:64000:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [G722:9:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [G722:9:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [PCMU:0:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3701 Bah
>>>>> HUMBUG! Sticking with PCMU at 8000h@20i
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3727 Audio
>>>>> Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [PCMU:0:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [PCMA:8:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [PCMA:8:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3701 Bah
>>>>> HUMBUG! Sticking with PCMA at 8000h@20i
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3727 Audio
>>>>> Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [CN:105:16000:60:0:1]/[opus:116:48000:20:0:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [CN:105:16000:60:0:1]/[PCMU:0:8000:20:64000:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [CN:105:16000:60:0:1]/[PCMA:8:8000:20:64000:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [CN:13:8000:60:0:1]/[opus:116:48000:20:0:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [CN:13:8000:60:0:1]/[PCMU:0:8000:20:64000:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3672 Audio
>>>>> Codec Compare [CN:13:8000:60:0:1]/[PCMA:8:8000:20:64000:1]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3588 Set
>>>>> telephone-event payload to 126
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] mod_opus.c:289 Opus encoder set
>>>>> bitrate to local settings [-1000bps]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] mod_opus.c:289 Opus encoder set
>>>>> bitrate to local settings [-1000bps]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:2507 Set Codec
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx opus/48000 20 ms 960 samples 0
>>>>> bits 1 channels
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_codec.c:111
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx Original read codec set to
>>>>> opus:116
>>>>> 2015-05-08 08:21:30.467711 [WARNING] switch_core_media.c:2791 NO
>>>>> candidate ACL defined, Defaulting to wan.auto
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:2815 Checking
>>>>> Candidate cid: 1 proto: udp type: host addr: 10.0.0.10:63888
>>>>> 2015-05-08 08:21:30.467711 [NOTICE] switch_core_media.c:2829 Save
>>>>> audio Candidate cid: 1 proto: udp type: host addr: 10.0.0.10:63888
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:2815 Checking
>>>>> Candidate cid: 2 proto: udp type: host addr: 10.0.0.10:63888
>>>>> 2015-05-08 08:21:30.467711 [NOTICE] switch_core_media.c:2829 Save
>>>>> audio Candidate cid: 2 proto: udp type: host addr: 10.0.0.10:63888
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:2815 Checking
>>>>> Candidate cid: 1 proto: udp type: srflx addr: 82.166.84.247:63888
>>>>> 2015-05-08 08:21:30.467711 [NOTICE] switch_core_media.c:2824 Choose
>>>>> audio Candidate cid: 1 proto: udp type: srflx addr:
>>>>> 82.166.84.247:63888
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:2815 Checking
>>>>> Candidate cid: 2 proto: udp type: srflx addr: 82.166.84.247:63888
>>>>> 2015-05-08 08:21:30.467711 [NOTICE] switch_core_media.c:2824 Choose
>>>>> audio Candidate cid: 2 proto: udp type: srflx addr:
>>>>> 82.166.84.247:63888
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:2815 Checking
>>>>> Candidate cid: 1 proto: udp type: relay addr: 130.211.78.35:58209
>>>>> 2015-05-08 08:21:30.467711 [NOTICE] switch_core_media.c:2829 Save
>>>>> audio Candidate cid: 1 proto: udp type: relay addr:
>>>>> 130.211.78.35:58209
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:2815 Checking
>>>>> Candidate cid: 2 proto: udp type: relay addr: 130.211.78.35:58209
>>>>> 2015-05-08 08:21:30.467711 [NOTICE] switch_core_media.c:2829 Save
>>>>> audio Candidate cid: 2 proto: udp type: relay addr:
>>>>> 130.211.78.35:58209
>>>>> 2015-05-08 08:21:30.467711 [NOTICE] switch_core_media.c:2953 setting
>>>>> remote audio ice addr to 82.166.84.247:63888 based on candidate
>>>>> 2015-05-08 08:21:30.467711 [NOTICE] switch_core_media.c:2978 setting
>>>>> remote rtcp audio addr to 82.166.84.247:63888 based on candidate
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:3935 Set 2833
>>>>> dtmf send/recv payload to 126
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:5171 AUDIO RTP [
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx] 172.30.0.219 port 19864 ->
>>>>> 82.166.84.247 port 63888 codec: 111 ms: 20
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_rtp.c:3559 Starting timer
>>>>> [soft] 960 bytes per 20ms
>>>>> 2015-05-08 08:21:30.467711 [INFO] switch_core_media.c:5345 Activating
>>>>> Audio ICE
>>>>> 2015-05-08 08:21:30.467711 [NOTICE] switch_rtp.c:4009 Activating RTP
>>>>> audio ICE: EDo5kr308/TXhitG:v9QogVGvZ8jGwYIi 82.166.84.247:63888
>>>>> 2015-05-08 08:21:30.467711 [INFO] switch_core_media.c:5388 Activating
>>>>> RTCP PORT 63888
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_rtp.c:3909 RTCP send rate
>>>>> is: 10000 and packet rate is: 20000 Remote Port: 63888
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_rtp.c:2349 Setting RTCP
>>>>> remote addr to 82.166.84.247:63888
>>>>> 2015-05-08 08:21:30.467711 [INFO] switch_core_media.c:5396 Skipping
>>>>> RTCP ICE (Same as RTP)
>>>>> 2015-05-08 08:21:30.467711 [INFO] switch_rtp.c:3101 Activate RTP/RTCP
>>>>> audio DTLS client
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:5469 Set 2833
>>>>> dtmf send payload to 126
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:5475 Set 2833
>>>>> dtmf receive payload to 126
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_media.c:5503 Set
>>>>> comfort noise payload to 106
>>>>> 2015-05-08 08:21:30.467711 [NOTICE] sofia_media.c:92 Pre-Answer
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx!
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_channel.c:3419 (
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx) Callstate Change RINGING -> EARLY
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] mod_sofia.c:780 Local SDP
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx:
>>>>> v=0
>>>>> o=FreeSWITCH 1431053426 1431053427 IN IP4 xxx.xxx.xxx.xxx
>>>>> s=FreeSWITCH
>>>>> c=IN IP4 xxx.xxx.xxx.xxx
>>>>> t=0 0
>>>>> a=msid-semantic: WMS tycfgLW7xb89okfsdKHP3gespdCXRxPb
>>>>> m=audio 19864 UDP/TLS/RTP/SAVPF 111 126 106
>>>>> a=rtpmap:111 opus/48000/2
>>>>> a=fmtp:111 useinbandfec=1; minptime=10
>>>>> a=rtpmap:126 telephone-event/8000
>>>>> a=rtpmap:106 CN/8000
>>>>> a=ptime:20
>>>>> a=sendrecv
>>>>> a=fingerprint:sha-256
>>>>> 83:F4:57:6D:F9:40:C7:E8:28:6D:59:AE:5F:08:23:3E:9E:17:1E:2F:D8:A9:D5:E7:DB:13:92:B5:DE:4A:66:CA
>>>>> a=rtcp-mux
>>>>> a=rtcp:19864 IN IP4 xxx.xxx.xxx.xxx
>>>>> a=ssrc:3914469578 cname:VRh1s3ZQ5XPj8UCb
>>>>> a=ssrc:3914469578 msid:tycfgLW7xb89okfsdKHP3gespdCXRxPb a0
>>>>> a=ssrc:3914469578 mslabel:tycfgLW7xb89okfsdKHP3gespdCXRxPb
>>>>> a=ssrc:3914469578 label:tycfgLW7xb89okfsdKHP3gespdCXRxPba0
>>>>> a=ice-ufrag:v9QogVGvZ8jGwYIi
>>>>> a=ice-pwd:FP9YIYEDMjNL4fNpftDlfaH5
>>>>> a=candidate:8233794353 1 udp 659136 xxx.xxx.xxx.xxx 19864 typ host
>>>>> generation 0
>>>>>
>>>>> nua.c:879 nua_respond() nua: nua_respond: entering
>>>>> nua_stack.c:529 nua_signal() nua(0x7fe17c0cf210): sent signal r_respond
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_session.c:912 Send
>>>>> signal sofia/internal/1000 at xxx.xxx.xxx.xxx [BREAK]
>>>>> nua_stack.c:573 nua_stack_signal() nua(0x7fe17c0cf210): recv signal
>>>>> r_respond 200 OK
>>>>> nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params:
>>>>> entering
>>>>> soa.c:403 soa_set_params() soa_set_params(static::0x7fe17c0bf4d0, ...)
>>>>> called
>>>>> soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fe17c0bf4d0,
>>>>> (nil), 0x7fe190041d31, -1) called
>>>>> soa.c:890 soa_set_capability_sdp()
>>>>> soa_set_capability_sdp(static::0x7fe17c0bf4d0, (nil), 0x7fe190041d31, -1)
>>>>> called
>>>>> 2015-05-08 08:21:30.467711 [NOTICE] mod_dptools.c:1292 Channel [
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx] has been answered
>>>>> nua_session.c:2320 nua_invite_server_respond() nua:
>>>>> nua_invite_server_respond: entering
>>>>> soa.c:1515 soa_generate_answer()
>>>>> soa_generate_answer(static::0x7fe17c0bf4d0) called
>>>>> soa_static.c:1146 offer_answer_step()
>>>>> soa_static_offer_answer_action(0x7fe17c0bf4d0, soa_generate_answer): called
>>>>> soa_static.c:1187 offer_answer_step() soa_static(0x7fe17c0bf4d0,
>>>>> soa_generate_answer): generating local description
>>>>> soa_static.c:1228 offer_answer_step() soa_static(0x7fe17c0bf4d0,
>>>>> soa_generate_answer): upgrade with remote description
>>>>> soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fe1aa7b1a30,
>>>>> 0x7fe17c026ac0, ""): called
>>>>> soa_static.c:1444 offer_answer_step() soa_static(0x7fe17c0bf4d0,
>>>>> soa_generate_answer): storing local description
>>>>> soa.c:1730 soa_activate() soa_activate(static::0x7fe17c0bf4d0, (nil))
>>>>> called
>>>>> soa.c:1270 soa_get_local_sdp()
>>>>> soa_get_local_sdp(static::0x7fe17c0bf4d0, [(nil)], [0x7fe1aa7b3b58],
>>>>> [0x7fe1aa7b3b54]) called
>>>>> tport.c:3257 tport_tsend() tport_tsend(0x7fe17c0d4ba0) tpn = WS/
>>>>> 82.166.84.247:53645
>>>>> tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec
>>>>> 0x7fe17c0d4d90 0x7fe17c0c5560 136 (136)
>>>>> tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec
>>>>> 0x7fe17c0d4d90 0x7fe17c0be3ab 63 (63)
>>>>> tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec
>>>>> 0x7fe17c0d4d90 0x7fe17c0c55e8 41 (41)
>>>>> tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec
>>>>> 0x7fe17c0d4d90 0x7fe17c0be480 67 (67)
>>>>> tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec
>>>>> 0x7fe17c0d4d90 0x7fe17c0c5611 631 (631)
>>>>> tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec
>>>>> 0x7fe17c0d4d90 0x7fe17c0d3020 864 (864)
>>>>> tport.c:3594 tport_vsend() tport_vsend(0x7fe17c0d4ba0): 1802 bytes of
>>>>> 1802 to ws/82.166.84.247:53645
>>>>> tport.c:3492 tport_send_msg() tport_vsend returned 1802
>>>>> send 1802 bytes to ws/[82.166.84.247]:53645 at 08:21:30.479618:
>>>>>
>>>>>  ------------------------------------------------------------------------
>>>>>    SIP/2.0 200 OK
>>>>>    Via: SIP/2.0/WS
>>>>> df7jal23ls0d.invalid;branch=z9hG4bKml28I3BsDokxOyXDaHfSBPW94I6MO4HK;rport=53645;received=82.166.84.247
>>>>>    From: "asdasda"<sip:1000 at xxx.xxx.xxx.xxx>;tag=THvNqRR9fmMzKb6JP9hp
>>>>>    To: <sip:991234 at aaaa>;tag=73aKc8ZegaUHr
>>>>>    Call-ID: fa0bf4d8-2037-a467-61fd-4f78e9746fbe
>>>>>    CSeq: 28092 INVITE
>>>>>    Contact: <sip:991234 at xxx.xxx.xxx.xxx:5060;transport=udp>
>>>>>    User-Agent:
>>>>> FreeSWITCH-mod_sofia/1.5.15b+git~20150423T043308Z~b01352c133~64bit
>>>>>    Accept: application/sdp
>>>>>    Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE,
>>>>> REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
>>>>>    Supported: 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: 864
>>>>>    Remote-Party-ID: "991234" <sip:991234 at aaaa
>>>>> >;party=calling;privacy=off;screen=no
>>>>>
>>>>>    v=0
>>>>>    o=FreeSWITCH 1431053426 1431053427 IN IP4 xxx.xxx.xxx.xxx
>>>>>    s=FreeSWITCH
>>>>>    c=IN IP4 xxx.xxx.xxx.xxx
>>>>>    t=0 0
>>>>>    a=msid-semantic: WMS tycfgLW7xb89okfsdKHP3gespdCXRxPb
>>>>>    m=audio 19864 UDP/TLS/RTP/SAVPF 111 126 106
>>>>>    a=rtpmap:111 opus/48000/2
>>>>>    a=fmtp:111 useinbandfec=1; minptime=10
>>>>>    a=rtpmap:126 telephone-event/8000
>>>>>    a=rtpmap:106 CN/8000
>>>>>    a=ptime:20
>>>>>    a=fingerprint:sha-256
>>>>> 83:F4:57:6D:F9:40:C7:E8:28:6D:59:AE:5F:08:23:3E:9E:17:1E:2F:D8:A9:D5:E7:DB:13:92:B5:DE:4A:66:CA
>>>>>    a=rtcp-mux
>>>>>    a=rtcp:19864 IN IP4 xxx.xxx.xxx.xxx
>>>>>    a=ssrc:3914469578 cname:VRh1s3ZQ5XPj8UCb
>>>>>    a=ssrc:3914469578 msid:tycfgLW7xb89okfsdKHP3gespdCXRxPb a0
>>>>>    a=ssrc:3914469578 mslabel:tycfgLW7xb89okfsdKHP3gespdCXRxPb
>>>>>    a=ssrc:3914469578 label:tycfgLW7xb89okfsdKHP3gespdCXRxPba0
>>>>>    a=ice-ufrag:v9QogVGvZ8jGwYIi
>>>>>    a=ice-pwd:FP9YIYEDMjNL4fNpftDlfaH5
>>>>>    a=candidate:8233794353 1 udp 659136 xxx.xxx.xxx.xxx 19864 typ host
>>>>> generation 0
>>>>>
>>>>>  ------------------------------------------------------------------------
>>>>> tport.c:2296 tport_set_secondary_timer() tport(0x7fe17c0d4ba0): reset
>>>>> timer
>>>>> nta.c:6791 incoming_reply() nta: sent 200 OK for INVITE (28092)
>>>>> nta.c:1348 set_timeout() nta: timer shortened to 500 ms
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_channel.c:3711 (
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx) Callstate Change EARLY -> ACTIVE
>>>>> nua_session.c:4139 signal_call_state_change() nua(0x7fe17c0cf210):
>>>>> call state changed: received -> completed, sent answer
>>>>> soa.c:1270 soa_get_local_sdp()
>>>>> soa_get_local_sdp(static::0x7fe17c0bf4d0, [0x7fe1aa7b3c48],
>>>>> [0x7fe1aa7b3c50], [(nil)]) called
>>>>> soa.c:616 soa_get_params() soa_get_params(static::0x7fe17c0bf4d0, ...)
>>>>> called
>>>>> nua_stack.c:271 nua_stack_event() nua(0x7fe17c0cf210): event i_state
>>>>> 200 OK
>>>>> nua_stack.c:359 nua_application_event() nua: nua_application_event:
>>>>> entering
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_session.c:1061 Send
>>>>> signal sofia/internal/1000 at xxx.xxx.xxx.xxx [BREAK]
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] sofia.c:6627 Channel
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx entering state [completed][200]
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> EXECUTE sofia/internal/1000 at xxx.xxx.xxx.xxx
>>>>> conference(991234-172.30.0.219 at test)
>>>>> 2015-05-08 08:21:30.467711 [INFO] mod_conference.c:10364 using channel
>>>>> sound prefix: /usr/local/freeswitch/sounds/en/us/callie
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] mod_conference.c:8991 Raw Codec
>>>>> Activation Success L16 at 48000hz 1 channel 20ms
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] mod_conference.c:9037 Raw Codec
>>>>> Activation Success L16 at 16000hz 1 channel 20ms
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_codec.c:221
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx Push codec L16:100
>>>>> 2015-05-08 08:21:30.467711 [INFO] mod_conference.c:10967
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx binding '0' to 'mute'
>>>>> 2015-05-08 08:21:30.467711 [INFO] switch_ivr_async.c:212 Digit parser
>>>>> mod_conference: Setting realm to 'conf'
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_ivr_async.c:321 Digit parser
>>>>> mod_conference: binding 0/conf/0 callback: 0x7fe1a92764e0 data:
>>>>> 0x7fe19010b8e0
>>>>> 2015-05-08 08:21:30.467711 [INFO] mod_conference.c:10967
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx binding '*' to 'deaf mute'
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_ivr_async.c:321 Digit parser
>>>>> mod_conference: binding */conf/0 callback: 0x7fe1a92764e0 data:
>>>>> 0x7fe19010b910
>>>>> 2015-05-08 08:21:30.467711 [INFO] mod_conference.c:10967
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx binding '9' to 'energy up'
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_ivr_async.c:321 Digit parser
>>>>> mod_conference: binding 9/conf/0 callback: 0x7fe1a92764e0 data:
>>>>> 0x7fe19010b940
>>>>> 2015-05-08 08:21:30.467711 [INFO] mod_conference.c:10967
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx binding '8' to 'energy equ'
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_ivr_async.c:321 Digit parser
>>>>> mod_conference: binding 8/conf/0 callback: 0x7fe1a92764e0 data:
>>>>> 0x7fe19010b970
>>>>> 2015-05-08 08:21:30.467711 [INFO] mod_conference.c:10967
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx binding '7' to 'energy dn'
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_ivr_async.c:321 Digit parser
>>>>> mod_conference: binding 7/conf/0 callback: 0x7fe1a92764e0 data:
>>>>> 0x7fe19010b9a0
>>>>> 2015-05-08 08:21:30.467711 [INFO] mod_conference.c:10967
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx binding '3' to 'vol talk up'
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_ivr_async.c:321 Digit parser
>>>>> mod_conference: binding 3/conf/0 callback: 0x7fe1a92764e0 data:
>>>>> 0x7fe19010b9d0
>>>>> 2015-05-08 08:21:30.467711 [INFO] mod_conference.c:10967
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx binding '2' to 'vol talk zero'
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_ivr_async.c:321 Digit parser
>>>>> mod_conference: binding 2/conf/0 callback: 0x7fe1a92764e0 data:
>>>>> 0x7fe19010ba00
>>>>> 2015-05-08 08:21:30.467711 [INFO] mod_conference.c:10967
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx binding '1' to 'vol talk dn'
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_ivr_async.c:321 Digit parser
>>>>> mod_conference: binding 1/conf/0 callback: 0x7fe1a92764e0 data:
>>>>> 0x7fe19010ba30
>>>>> 2015-05-08 08:21:30.467711 [INFO] mod_conference.c:10967
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx binding '6' to 'vol listen up'
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_ivr_async.c:321 Digit parser
>>>>> mod_conference: binding 6/conf/0 callback: 0x7fe1a92764e0 data:
>>>>> 0x7fe19010ba60
>>>>> 2015-05-08 08:21:30.467711 [INFO] mod_conference.c:10967
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx binding '5' to 'vol listen zero'
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_ivr_async.c:321 Digit parser
>>>>> mod_conference: binding 5/conf/0 callback: 0x7fe1a92764e0 data:
>>>>> 0x7fe19010ba90
>>>>> 2015-05-08 08:21:30.467711 [INFO] mod_conference.c:10967
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx binding '4' to 'vol listen dn'
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_ivr_async.c:321 Digit parser
>>>>> mod_conference: binding 4/conf/0 callback: 0x7fe1a92764e0 data:
>>>>> 0x7fe19010bac0
>>>>> 2015-05-08 08:21:30.467711 [INFO] mod_conference.c:10967
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx binding '#' to 'hangup'
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_ivr_async.c:321 Digit parser
>>>>> mod_conference: binding #/conf/0 callback: 0x7fe1a92764e0 data:
>>>>> 0x7fe19010baf0
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] switch_core_session.c:912 Send
>>>>> signal sofia/internal/1000 at xxx.xxx.xxx.xxx [BREAK]
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] mod_conference.c:4765 Setup timer
>>>>> soft success interval: 20  samples: 960
>>>>> 2015-05-08 08:21:30.467711 [DEBUG] mod_conference.c:3043 Setup timer
>>>>> success interval: 30  samples: 480
>>>>> 2015-05-08 08:21:30.507713 [DEBUG] mod_local_stream.c:498 Opening
>>>>> Stream [moh/16000] 16000hz
>>>>> 2015-05-08 08:21:30.507713 [NOTICE] switch_core_io.c:1261 Activating
>>>>> write resampler
>>>>> tport.c:2773 tport_wakeup() tport_wakeup(0x7fe17c0d4ba0): events IN
>>>>> tport.c:2864 tport_recv_event() tport_recv_event(0x7fe17c0d4ba0)
>>>>> tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7fe17c0d4ba0) msg
>>>>> 0x7fe17c0c6ab0 from (ws/82.166.84.247:53645) has 550 bytes, veclen = 1
>>>>> recv 550 bytes from ws/[82.166.84.247]:53645 at 08:21:30.662998:
>>>>>
>>>>>  ------------------------------------------------------------------------
>>>>>    ACK sip:991234 at xxx.xxx.xxx.xxx:5060;transport=udp SIP/2.0
>>>>>    Via: SIP/2.0/WS
>>>>> df7jal23ls0d.invalid;branch=z9hG4bK30nT8FwJ3EqSVIbdgFvT;rport
>>>>>    From: "asdasda"<sip:1000 at xxx.xxx.xxx.xxx>;tag=THvNqRR9fmMzKb6JP9hp
>>>>>    To: <sip:991234 at aaaa>;tag=73aKc8ZegaUHr
>>>>>    Contact: "asdasda"<
>>>>> sip:1000 at df7jal23ls0d.invalid;rtcweb-breaker=no;click2call=no;transport=ws
>>>>> >;+g.oma.sip-im;language="en,fr"
>>>>>    Call-ID: fa0bf4d8-2037-a467-61fd-4f78e9746fbe
>>>>>    CSeq: 28092 ACK
>>>>>    Content-Length: 0
>>>>>    Max-Forwards: 70
>>>>>    User-Agent: IM-client/OMA1.0 sipML5-v1.2015.03.18
>>>>>    Organization: Doubango Telecom
>>>>>
>>>>>
>>>>>  ------------------------------------------------------------------------
>>>>> tport.c:3023 tport_deliver() tport_deliver(0x7fe17c0d4ba0): msg
>>>>> 0x7fe17c0c6ab0 (550 bytes) from ws/82.166.84.247:53645/sip next=(nil)
>>>>> nta.c:2880 agent_recv_request() nta: received ACK
>>>>> sip:991234 at xxx.xxx.xxx.xxx:5060;transport=udp SIP/2.0 (CSeq 28092)
>>>>> nta.c:3174 agent_check_request_via() nta: Via check:
>>>>> received=82.166.84.247
>>>>> nta.c:3019 agent_recv_request() nta: ACK (28092) is going to INVITE
>>>>> (28092)
>>>>> nua_session.c:2569 process_ack_or_cancel() nua: process_ack_or_cancel:
>>>>> entering
>>>>> soa.c:1214 soa_clear_remote_sdp()
>>>>> soa_clear_remote_sdp(static::0x7fe17c0bf4d0) called
>>>>> nua_stack.c:271 nua_stack_event() nua(0x7fe17c0cf210): event i_ack 200
>>>>> OK
>>>>> nua_session.c:4139 signal_call_state_change() nua(0x7fe17c0cf210):
>>>>> call state changed: completed -> ready
>>>>> nua_stack.c:271 nua_stack_event() nua(0x7fe17c0cf210): event i_state
>>>>> 200 OK
>>>>> nua_stack.c:271 nua_stack_event() nua(0x7fe17c0cf210): event i_active
>>>>> 200 Call active
>>>>> nta.c:5744 incoming_free() nta: incoming_free(0x7fe17c024090)
>>>>> tport.c:2296 tport_set_secondary_timer() tport(0x7fe17c0d4ba0): reset
>>>>> timer
>>>>> nua_stack.c:359 nua_application_event() nua: nua_application_event:
>>>>> entering
>>>>> 2015-05-08 08:21:30.647708 [DEBUG] switch_core_session.c:1061 Send
>>>>> signal sofia/internal/1000 at xxx.xxx.xxx.xxx [BREAK]
>>>>> nua_stack.c:359 nua_application_event() nua: nua_application_event:
>>>>> entering
>>>>> 2015-05-08 08:21:30.647708 [DEBUG] switch_core_session.c:1061 Send
>>>>> signal sofia/internal/1000 at xxx.xxx.xxx.xxx [BREAK]
>>>>> nua_stack.c:359 nua_application_event() nua: nua_application_event:
>>>>> entering
>>>>> 2015-05-08 08:21:30.647708 [DEBUG] switch_core_session.c:1061 Send
>>>>> signal sofia/internal/1000 at xxx.xxx.xxx.xxx [BREAK]
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> 2015-05-08 08:21:30.667707 [DEBUG] sofia.c:6627 Channel
>>>>> sofia/internal/1000 at xxx.xxx.xxx.xxx entering state [ready][200]
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>> nta.c:1289 agent_timer() nta: timer not set
>>>>> 2015-05-08 08:21:48.307689 [NOTICE] switch_rtp.c:1133 Auto Changing
>>>>> stun/rtp/dtls port from 82.166.84.247:63888 to 130.211.78.35:58209
>>>>> 2015-05-08 08:22:02.047711 [INFO] switch_rtp.c:2924 Changing audio
>>>>> DTLS state from HANDSHAKE to SETUP
>>>>> 2015-05-08 08:22:02.047711 [INFO] switch_rtp.c:2832 audio Fingerprint
>>>>> Verified.
>>>>> 2015-05-08 08:22:02.047711 [INFO] switch_rtp.c:3374 Activating Audio
>>>>> Secure RTP SEND
>>>>> 2015-05-08 08:22:02.047711 [INFO] switch_rtp.c:3352 Activating Audio
>>>>> Secure RTP RECV
>>>>> 2015-05-08 08:22:02.047711 [INFO] switch_rtp.c:2872 Changing audio
>>>>> DTLS state from SETUP to READY
>>>>> 2015-05-08 08:22:02.047711 [DEBUG] switch_core_sqldb.c:2599 Secure
>>>>> Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80
>>>>> 2015-05-08 08:22:02.047711 [DEBUG] switch_core_sqldb.c:2599 Secure
>>>>> Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80
>>>>> 2015-05-08 08:22:02.087708 [DEBUG] switch_rtp.c:1937 rtcp_stats_init:
>>>>> ssrc[-195423717] base_seq[29507]
>>>>>
>>>>> Notice that the INVITE was received at 08:21:30 while DTLS was READY
>>>>> at 2015-05-08 08:22:02 which means that it took 32 seconds to voice. Again,
>>>>> if I am not using TURN/STUN, the whole process is pretty quick (2 seconds).
>>>>>
>>>>> Also, notice:
>>>>> 2015-05-08 08:21:48.307689 [NOTICE] switch_rtp.c:1133 Auto Changing
>>>>> stun/rtp/dtls port from 82.166.84.247:63888 to 130.211.78.35:58209
>>>>>
>>>>> Which means that the media is relayed via the TURN server (TURN server
>>>>> IP is 130.211.78.35)...
>>>>>
>>>>> Any idea?
>>>>>
>>>>> Thanks,
>>>>> Adam
>>>>>
>>>>>
>>>>>
>>>>> _________________________________________________________________________
>>>>> Professional FreeSWITCH Consulting Services:
>>>>> consulting at freeswitch.org
>>>>> http://www.freeswitchsolutions.com
>>>>>
>>>>> Official FreeSWITCH Sites
>>>>> http://www.freeswitch.org
>>>>> http://confluence.freeswitch.org
>>>>> http://www.cluecon.com
>>>>>
>>>>> FreeSWITCH-users mailing list
>>>>> FreeSWITCH-users at lists.freeswitch.org
>>>>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>>>>> UNSUBSCRIBE:
>>>>> http://lists.freeswitch.org/mailman/options/freeswitch-users
>>>>> http://www.freeswitch.org
>>>>>
>>>>
>>>>
>>>
>>> _________________________________________________________________________
>>> Professional FreeSWITCH Consulting Services:
>>> consulting at freeswitch.org
>>> http://www.freeswitchsolutions.com
>>>
>>> Official FreeSWITCH Sites
>>> http://www.freeswitch.org
>>> http://confluence.freeswitch.org
>>> http://www.cluecon.com
>>>
>>> FreeSWITCH-users mailing list
>>> FreeSWITCH-users at lists.freeswitch.org
>>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>>> http://www.freeswitch.org
>>>
>>
>> _________________________________________________________________________
>> Professional FreeSWITCH Consulting Services:
>> consulting at freeswitch.org
>> http://www.freeswitchsolutions.com
>>
>> Official FreeSWITCH Sites
>> http://www.freeswitch.org
>> http://confluence.freeswitch.org
>> http://www.cluecon.com
>>
>> FreeSWITCH-users mailing list
>> FreeSWITCH-users at lists.freeswitch.org
>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>> http://www.freeswitch.org
>>
>
>
>
> --
>
>
>
> Víctor E. Medina M.
> Platform Architect / Chief Infrastructure
> +58424 291 4561
> BB #79A8AFA2
> @VMCibersys
>
>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at freeswitch.org
> http://www.freeswitchsolutions.com
>
> Official FreeSWITCH Sites
> http://www.freeswitch.org
> http://confluence.freeswitch.org
> http://www.cluecon.com
>
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20150508/3ea78023/attachment-0001.html 


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