[Freeswitch-users] No audio in inbound call for android apprtc (webrtc)

Mon Dec 2 18:27:04 MSK 2013

I using freeswitch webrtc version (1.4) and webrtc android (apprtc) and
jssip.
In that when i make call from android apprtc to jssip, i have audio both way
and its fine .
but when i make call from jssip to android apprtc , i am not having audio.
in android libjingel i can see log that timing out Stun ping. i checked in
freeswitch server using tcpdump freeswitch getting rtp packet from android
but freeswitch didn`t send any rtp packet to android. freeswitch and jssip
have rtp packet flow in both way.

jssip -> android apprtc (invite in android logcat)
-------------------------

  o=FreeSWITCH 1385973198 1385973199 IN IP4 xx.xx.xx.xx
s=FreeSWITCH
c=IN IP4 xx.xx.xx.xx
t=0 0
a=sendrecv
a=msid-semantic: WMS UlOyQ5IJeQTym7lcjsHwF8OVnhalote9
m=audio 20966 RTP/SAVPF 0 8 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fingerprint:sha-256
91:9E:50:FA:2E:A5:8E:02:41:1E:FC:A5:8A:B0:0C:1F:98:1F:1B:49:BB:D6:44:A8:E1:01:EA:82:7C:B6:59:1D
a=rtcp-mux
a=rtcp:20966 IN IP4 xx.xx.xx.xx
a=ssrc:2057333412 cname:FTymO6VTNEh0Ct3L
a=ssrc:2057333412 msid:UlOyQ5IJeQTym7lcjsHwF8OVnhalote9 a0
a=ssrc:2057333412 mslabel:UlOyQ5IJeQTym7lcjsHwF8OVnhalote9
a=ssrc:2057333412 label:UlOyQ5IJeQTym7lcjsHwF8OVnhalote9a0
a=ice-ufrag:LB8hzN2MU3Y9n38T
a=ice-pwd:Mw5qtQa7liXOBQpd
a=candidate:6185949872 1 udp 659136 xx.xx.xx.xx 20966 typ host generation 0
a=candidate:6185949872 2 udp 659136 xx.xx.xx.xx 20966 typ host generation 0
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:bY3YaWkQ5/2oKz9gEKtNKKF8ovPs7nIVWIUmHzuF
a=ptime:20

jssip <-- android apprtc (200 ok in android logcat)
-------------------------

 v=0
o=- 439041227922934440 2 IN IP4 127.0.0.1
s=-
t=0 0
a=msid-semantic: WMS
m=audio 15144 RTP/SAVPF 0 8 13 101
c=IN IP4 115.111.5.34
a=rtcp:1 IN IP4 0.0.0.0
a=candidate:622902765 1 udp 2113937151 xx.xx.xx.xx 35848 typ host generation
0
a=candidate:1739408229 1 udp 1845501695 115.111.5.34 15144 typ srflx raddr
xx.xx.xx.xx rport 35848 generation 0
a=candidate:1805861149 1 tcp 1509957375 xx.xx.xx.xx 56537 typ host
generation 0
a=ice-ufrag:smxJUV1NajVUJMij
a=ice-pwd:bNv1nkF5MB2MTQGUGtCKxt5U
a=mid:audio
a=sendrecv
a=rtcp-mux
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:jdpxXuVNsf3V9gIQr+bcmzPO1Z+3gUzwkImHP/fL
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:13 CN/8000
a=rtpmap:101 telephone-event/8000
a=candidate:622902765 1 udp 2113937151 xx.xx.xx.xx 35848 typ host generation
0
a=candidate:1739408229 1 udp 1845501695 xx.xx.xx.xx 15144 typ srflx raddr
xx.xx.xx.xx rport 35848 generation 0
a=candidate:1805861149 1 tcp 1509957375 xx.xx.xx.xx 56537 typ host
generation 0

freeswitch log for call from jssip to android
-------------------------------------------------

2013-12-02 15:11:49.078540 [NOTICE] switch_channel.c:1055 New Channel
sofia/internal/111998 at xx.xx.xx.xx [b474f6b8-113f-4208-aa4e-b3c270be9c16]
2013-12-02 15:11:49.078540 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:49.078540 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:49.078540 [DEBUG] switch_core_state_machine.c:467
(sofia/internal/111998 at xx.xx.xx.xx) Running State Change CS_NEW
2013-12-02 15:11:49.078540 [DEBUG] switch_core_state_machine.c:485
(sofia/internal/111998 at xx.xx.xx.xx) State NEW
2013-12-02 15:11:49.098544 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:49.098544 [DEBUG] sofia.c:1816 detaching session
b474f6b8-113f-4208-aa4e-b3c270be9c16
2013-12-02 15:11:49.638540 [DEBUG] sofia.c:1908 Re-attaching to session
b474f6b8-113f-4208-aa4e-b3c270be9c16
2013-12-02 15:11:49.638540 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:49.638540 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:49.658540 [DEBUG] sofia.c:9117 Setting NAT mode based on
websockets
2013-12-02 15:11:49.658540 [DEBUG] sofia.c:5861 Channel
sofia/internal/111998 at xx.xx.xx.xx entering state [received][100]
2013-12-02 15:11:49.658540 [DEBUG] sofia.c:5871 Remote SDP:
v=0
o=- 7956339218042656413 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE audio
a=msid-semantic: WMS M7kcmbQB5jHLGFt0kHsc02lJG5UNnWJUd3ur
m=audio 52606 RTP/SAVPF 111 103 104 0 8 106 105 13 126
c=IN IP4 xx.xx.xx.xx
a=rtpmap:111 opus/48000/2
a=fmtp:111 minptime=10
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
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:52606 IN IP4 xx.xx.xx.xx
a=candidate:3052889280 1 udp 2113937151 10.4.5.177 63907 typ host generation
0
a=candidate:3052889280 2 udp 2113937151 10.4.5.177 63907 typ host generation
0
a=candidate:4218722352 1 tcp 1509957375 10.4.5.177 0 typ host generation 0
a=candidate:4218722352 2 tcp 1509957375 10.4.5.177 0 typ host generation 0
a=candidate:1456923180 1 udp 1845501695 xx.xx.xx.xx 52606 typ srflx raddr
10.4.5.177 rport 63907 generation 0
a=candidate:1456923180 2 udp 1845501695 xx.xx.xx.xx 52606 typ srflx raddr
10.4.5.177 rport 63907 generation 0
a=ice-ufrag:fNi6w7SNINs91kf1
a=ice-pwd:xi64ann1iU6AYNvBh9m9bLVl
a=ice-options:google-ice
a=fingerprint:sha-256
E7:B9:4B:22:20:C9:67:BD:FE:B2:5A:01:17:F4:6B:3A:C4:04:20:53:C2:0A:F0:5C:98:22:4D:C9:C8:60:14:EB
a=setup:actpass
a=mid:audio
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=rtcp-mux
a=crypto:0 AES_CM_128_HMAC_SHA1_32
inline:os2etUzJazzxo5/mG0SMitAVZrSUdxFIDgxr1dK8
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:WVqrcslWrYWs1a8DDUI4/ahkq0xJ6FweRd/0xJZr
a=maxptime:60
a=ssrc:2810925229 cname:Vkbzh4QSGqv02wU4
a=ssrc:2810925229 msid:M7kcmbQB5jHLGFt0kHsc02lJG5UNnWJUd3ur
M7kcmbQB5jHLGFt0kHsc02lJG5UNnWJUd3ura0
a=ssrc:2810925229 mslabel:M7kcmbQB5jHLGFt0kHsc02lJG5UNnWJUd3ur
a=ssrc:2810925229 label:M7kcmbQB5jHLGFt0kHsc02lJG5UNnWJUd3ura0

2013-12-02 15:11:49.658540 [DEBUG] sofia.c:6116
(sofia/internal/111998 at xx.xx.xx.xx) State Change CS_NEW -> CS_INIT
2013-12-02 15:11:49.658540 [DEBUG] switch_core_session.c:1374 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:467
(sofia/internal/111998 at xx.xx.xx.xx) Running State Change CS_INIT
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:506
(sofia/internal/111998 at xx.xx.xx.xx) State INIT
2013-12-02 15:11:49.658540 [DEBUG] mod_sofia.c:87
sofia/internal/111998 at xx.xx.xx.xx SOFIA INIT
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:40
sofia/internal/111998 at xx.xx.xx.xx Standard INIT
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:48
(sofia/internal/111998 at xx.xx.xx.xx) State Change CS_INIT -> CS_ROUTING
2013-12-02 15:11:49.658540 [DEBUG] switch_core_session.c:1374 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:506
(sofia/internal/111998 at xx.xx.xx.xx) State INIT going to sleep
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:467
(sofia/internal/111998 at xx.xx.xx.xx) Running State Change CS_ROUTING
2013-12-02 15:11:49.658540 [DEBUG] switch_channel.c:2178
(sofia/internal/111998 at xx.xx.xx.xx) Callstate Change DOWN -> RINGING
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:522
(sofia/internal/111998 at xx.xx.xx.xx) State ROUTING
2013-12-02 15:11:49.658540 [DEBUG] mod_sofia.c:123
sofia/internal/111998 at xx.xx.xx.xx SOFIA ROUTING
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:164
sofia/internal/111998 at xx.xx.xx.xx Standard ROUTING
2013-12-02 15:11:49.658540 [INFO] mod_dialplan_xml.c:558 Processing 111998
<111998>->111999 in context default
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->tod_example]
continue=true
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Date/Time Match (PASS)
[tod_example] break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action set(open=true) 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->holiday_example] continue=true
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Date/TimeMatch (FAIL)
[holiday_example] break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->global-intercept] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [global-intercept]
destination_number(111999) =~ /^886$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->group-intercept] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [group-intercept]
destination_number(111999) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->intercept-ext]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [intercept-ext]
destination_number(111999) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->redial]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [redial]
destination_number(111999) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->global]
continue=true
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [global]
${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [global]
${rtp_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/
break=never
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (PASS) [global]
${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/
break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (PASS) [global]
${switch_r_sdp}(v=0
o=- 7956339218042656413 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE audio
a=msid-semantic: WMS M7kcmbQB5jHLGFt0kHsc02lJG5UNnWJUd3ur
m=audio 52606 RTP/SAVPF 111 103 104 0 8 106 105 13 126
c=IN IP4 xx.xx.xx.xx
a=rtpmap:111 opus/48000/2
a=fmtp:111 minptime=10
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
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:52606 IN IP4 xx.xx.xx.xx
a=candidate:3052889280 1 udp 2113937151 10.4.5.177 63907 typ host generation
0
a=candidate:3052889280 2 udp 2113937151 10.4.5.177 63907 typ host generation
0
a=candidate:4218722352 1 tcp 1509957375 10.4.5.177 0 typ host generation 0
a=candidate:4218722352 2 tcp 1509957375 10.4.5.177 0 typ host generation 0
a=candidate:1456923180 1 udp 1845501695 xx.xx.xx.xx 52606 typ srflx raddr
10.4.5.177 rport 63907 generation 0
a=candidate:1456923180 2 udp 1845501695 xx.xx.xx.xx 52606 typ srflx raddr
10.4.5.177 rport 63907 generation 0
a=ice-ufrag:fNi6w7SNINs91kf1
a=ice-pwd:xi64ann1iU6AYNvBh9m9bLVl
a=ice-options:google-ice
a=fingerprint:sha-256
E7:B9:4B:22:20:C9:67:BD:FE:B2:5A:01:17:F4:6B:3A:C4:04:20:53:C2:0A:F0:5C:98:22:4D:C9:C8:60:14:EB
a=setup:actpass
a=mid:audio
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=rtcp-mux
a=crypto:0 AES_CM_128_HMAC_SHA1_32
inline:os2etUzJazzxo5/mG0SMitAVZrSUdxFIDgxr1dK8
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:WVqrcslWrYWs1a8DDUI4/ahkq0xJ6FweRd/0xJZr
a=maxptime:60
a=ssrc:2810925229 cname:Vkbzh4QSGqv02wU4
a=ssrc:2810925229 msid:M7kcmbQB5jHLGFt0kHsc02lJG5UNnWJUd3ur
M7kcmbQB5jHLGFt0kHsc02lJG5UNnWJUd3ura0
a=ssrc:2810925229 mslabel:M7kcmbQB5jHLGFt0kHsc02lJG5UNnWJUd3ur
a=ssrc:2810925229 label:M7kcmbQB5jHLGFt0kHsc02lJG5UNnWJUd3ura0
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action
set(rtp_secure_media=true) 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Absolute Condition [global]
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action
hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action
hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action
hash(insert/${domain_name}-last_dial/global/${uuid}) 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action
export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->snom-demo-2]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [snom-demo-2]
destination_number(111999) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->snom-demo-1]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [snom-demo-1]
destination_number(111999) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->eavesdrop]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [eavesdrop]
destination_number(111999) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->eavesdrop]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [eavesdrop]
destination_number(111999) =~ /^779$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->call_return]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [call_return]
destination_number(111999) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->del-group]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [del-group]
destination_number(111999) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->add-group]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [add-group]
destination_number(111999) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->call-group-simo] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [call-group-simo]
destination_number(111999) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->call-group-order] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [call-group-order]
destination_number(111999) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->extension-intercom] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL)
[extension-intercom] destination_number(111999) =~ /^8(10[01][0-9])$/
break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->Local_Extension] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [Local_Extension]
destination_number(111999) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->Local_Extension_Skinny] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL)
[Local_Extension_Skinny] destination_number(111999) =~ /^(11[01][0-9])$/
break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->group_dial_sales] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [group_dial_sales]
destination_number(111999) =~ /^2000$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->group_dial_support] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL)
[group_dial_support] destination_number(111999) =~ /^2001$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->group_dial_billing] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL)
[group_dial_billing] destination_number(111999) =~ /^2002$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->operator]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [operator]
destination_number(111999) =~ /^(operator|0)$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->vmain]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [vmain]
destination_number(111999) =~ /^vmain$|^4000$|^\*98$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->sip_uri]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [sip_uri]
destination_number(111999) =~ /^sip:(.*)$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->nb_conferences] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [nb_conferences]
destination_number(111999) =~ /^(30\d{2})$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->wb_conferences] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [wb_conferences]
destination_number(111999) =~ /^(31\d{2})$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->uwb_conferences] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [uwb_conferences]
destination_number(111999) =~ /^(32\d{2})$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->cdquality_conferences] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL)
[cdquality_conferences] destination_number(111999) =~ /^(33\d{2})$/
break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->freeswitch_public_conf_via_sip] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL)
[freeswitch_public_conf_via_sip] destination_number(111999) =~
/^9(888|8888|1616|3232)$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->mad_boss_intercom] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [mad_boss_intercom]
destination_number(111999) =~ /^0911$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->mad_boss_intercom] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [mad_boss_intercom]
destination_number(111999) =~ /^0912$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->mad_boss]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [mad_boss]
destination_number(111999) =~ /^0913$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->ivr_demo]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [ivr_demo]
destination_number(111999) =~ /^5000$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->dynamic_conference] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL)
[dynamic_conference] destination_number(111999) =~ /^5001$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->rtp_multicast_page] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL)
[rtp_multicast_page] destination_number(111999) =~ /^pagegroup$|^7243$/
break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->park]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [park]
destination_number(111999) =~ /^5900$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->unpark]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [unpark]
destination_number(111999) =~ /^5901$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->valet_park]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [valet_park]
destination_number(111999) =~ /^(6000)$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->valet_park]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [valet_park]
destination_number(111999) =~ /^(60\d[1-9])$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->park]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (PASS) [park]
source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [park]
destination_number(111999) =~ /park\+(\d+)/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->unpark]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (PASS) [unpark]
source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [unpark]
destination_number(111999) =~ /^parking$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->park]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (PASS) [park]
source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [park]
destination_number(111999) =~ /callpark/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->unpark]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (PASS) [unpark]
source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [unpark]
destination_number(111999) =~ /pickup/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->wait]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [wait]
destination_number(111999) =~ /^wait$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->fax_receive]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [fax_receive]
destination_number(111999) =~ /^9178$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->fax_transmit]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [fax_transmit]
destination_number(111999) =~ /^9179$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->ringback_180]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [ringback_180]
destination_number(111999) =~ /^9180$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->ringback_183_uk_ring] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL)
[ringback_183_uk_ring] destination_number(111999) =~ /^9181$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->ringback_183_music_ring] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL)
[ringback_183_music_ring] destination_number(111999) =~ /^9182$/
break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->ringback_post_answer_uk_ring] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL)
[ringback_post_answer_uk_ring] destination_number(111999) =~ /^9183$/
break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->ringback_post_answer_music] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL)
[ringback_post_answer_music] destination_number(111999) =~ /^9184$/
break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->ClueCon]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [ClueCon]
destination_number(111999) =~ /^9191$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->show_info]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [show_info]
destination_number(111999) =~ /^9192$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->video_record]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [video_record]
destination_number(111999) =~ /^9193$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->video_playback] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [video_playback]
destination_number(111999) =~ /^9194$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->delay_echo]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [delay_echo]
destination_number(111999) =~ /^9195$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->echo]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [echo]
destination_number(111999) =~ /^9196$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->milliwatt]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [milliwatt]
destination_number(111999) =~ /^9197$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->tone_stream]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [tone_stream]
destination_number(111999) =~ /^9198$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->zrtp_enrollement] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [zrtp_enrollement]
destination_number(111999) =~ /^9787$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->hold_music]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [hold_music]
destination_number(111999) =~ /^9664$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->laugh break]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [laugh break]
destination_number(111999) =~ /^9386$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->101]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [101]
destination_number(111999) =~ /^101$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->pizza_demo]
continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [pizza_demo]
destination_number(111999) =~ /^(pizza|74992)$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->Talking Clock
Time] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [Talking Clock
Time] destination_number(111999) =~ /^9170$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->Talking Clock
Date] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [Talking Clock
Date] destination_number(111999) =~ /^9171$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->Talking Clock
Date and Time] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [Talking Clock Date
and Time] destination_number(111999) =~ /^9172$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->local2.example.com] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (PASS)
[local2.example.com] ${toll_allow}(domestic,international,local) =~ /local/
break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL)
[local2.example.com] destination_number(111999) =~ /^(\d{7})$/
break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->domestic2.example.com] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (PASS)
[domestic2.example.com] ${toll_allow}(domestic,international,local) =~
/domestic/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL)
[domestic2.example.com] destination_number(111999) =~ /^(\d{1})$/
break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->international2.example.com] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (PASS)
[international2.example.com] ${toll_allow}(domestic,international,local) =~
/international/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL)
[international2.example.com] destination_number(111999) =~ /^(011\d+)$/
break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing [default->bandwidth.com
Outbound 9.10d] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL) [bandwidth.com
Outbound 9.10d] destination_number(111999) =~ /^\+1(\d{10})$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->Outbound_Extension_custom] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (FAIL)
[Outbound_Extension_custom] destination_number(111999) =~ /^1(\d{10})$/
break=never
Dialplan: sofia/internal/111998 at xx.xx.xx.xx parsing
[default->Local_Extension_custom] continue=false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Regex (PASS)
[Local_Extension_custom] destination_number(111999) =~
/^([19][0129][0-9][0-9][0-9][0-9]?)$/ break=on-false
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action
export(nolocal:absolute_codec_string=PCMU,PCMA) 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action export(media_webrtc=true) 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action
export(dialed_extension=111999) 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action set(ringback=${us-ring}) 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action
set(transfer_ringback=local_stream://moh) 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action set(call_timeout=30) 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action
set(hangup_after_bridge=true) 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action
set(continue_on_fail=true) 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action
bridge(user/${dialed_extension}@${domain_name}) 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action answer() 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action sleep(1000) 
Dialplan: sofia/internal/111998 at xx.xx.xx.xx Action
bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:214
(sofia/internal/111998 at xx.xx.xx.xx) State Change CS_ROUTING -> CS_EXECUTE
2013-12-02 15:11:49.658540 [DEBUG] switch_core_session.c:1374 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:522
(sofia/internal/111998 at xx.xx.xx.xx) State ROUTING going to sleep
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:467
(sofia/internal/111998 at xx.xx.xx.xx) Running State Change CS_EXECUTE
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:529
(sofia/internal/111998 at xx.xx.xx.xx) State EXECUTE
2013-12-02 15:11:49.658540 [DEBUG] mod_sofia.c:178
sofia/internal/111998 at xx.xx.xx.xx SOFIA EXECUTE
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:256
sofia/internal/111998 at xx.xx.xx.xx Standard EXECUTE
EXECUTE sofia/internal/111998 at xx.xx.xx.xx set(open=true)
2013-12-02 15:11:49.658540 [DEBUG] mod_dptools.c:1402
sofia/internal/111998 at xx.xx.xx.xx SET [open]=[true]
EXECUTE sofia/internal/111998 at xx.xx.xx.xx set(rtp_secure_media=true)
2013-12-02 15:11:49.658540 [DEBUG] mod_dptools.c:1402
sofia/internal/111998 at xx.xx.xx.xx SET [rtp_secure_media]=[true]
EXECUTE sofia/internal/111998 at xx.xx.xx.xx
hash(insert/10.188.136.13-spymap/111998/b474f6b8-113f-4208-aa4e-b3c270be9c16)
EXECUTE sofia/internal/111998 at xx.xx.xx.xx
hash(insert/10.188.136.13-last_dial/111998/111999)
EXECUTE sofia/internal/111998 at xx.xx.xx.xx
hash(insert/10.188.136.13-last_dial/global/b474f6b8-113f-4208-aa4e-b3c270be9c16)
EXECUTE sofia/internal/111998 at xx.xx.xx.xx export(RFC2822_DATE=Mon, 02 Dec
2013 15:11:49 +0000)
2013-12-02 15:11:49.658540 [DEBUG] switch_channel.c:1247 EXPORT
(export_vars) [RFC2822_DATE]=[Mon, 02 Dec 2013 15:11:49 +0000]
EXECUTE sofia/internal/111998 at xx.xx.xx.xx
export(nolocal:absolute_codec_string=PCMU,PCMA)
2013-12-02 15:11:49.658540 [DEBUG] switch_channel.c:1247 EXPORT
(export_vars) (REMOTE ONLY) [absolute_codec_string]=[PCMU,PCMA]
EXECUTE sofia/internal/111998 at xx.xx.xx.xx export(media_webrtc=true)
2013-12-02 15:11:49.658540 [DEBUG] switch_channel.c:1247 EXPORT
(export_vars) [media_webrtc]=[true]
EXECUTE sofia/internal/111998 at xx.xx.xx.xx export(dialed_extension=111999)
2013-12-02 15:11:49.658540 [DEBUG] switch_channel.c:1247 EXPORT
(export_vars) [dialed_extension]=[111999]
EXECUTE sofia/internal/111998 at xx.xx.xx.xx set(ringback=%(2000,4000,440,480))
2013-12-02 15:11:49.658540 [DEBUG] mod_dptools.c:1402
sofia/internal/111998 at xx.xx.xx.xx SET [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/internal/111998 at xx.xx.xx.xx
set(transfer_ringback=local_stream://moh)
2013-12-02 15:11:49.658540 [DEBUG] mod_dptools.c:1402
sofia/internal/111998 at xx.xx.xx.xx SET
[transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/111998 at xx.xx.xx.xx set(call_timeout=30)
2013-12-02 15:11:49.658540 [DEBUG] mod_dptools.c:1402
sofia/internal/111998 at xx.xx.xx.xx SET [call_timeout]=[30]
EXECUTE sofia/internal/111998 at xx.xx.xx.xx set(hangup_after_bridge=true)
2013-12-02 15:11:49.658540 [DEBUG] mod_dptools.c:1402
sofia/internal/111998 at xx.xx.xx.xx SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/111998 at xx.xx.xx.xx set(continue_on_fail=true)
2013-12-02 15:11:49.658540 [DEBUG] mod_dptools.c:1402
sofia/internal/111998 at xx.xx.xx.xx SET [continue_on_fail]=[true]
EXECUTE sofia/internal/111998 at xx.xx.xx.xx bridge(user/111999 at 10.188.136.13)
2013-12-02 15:11:49.658540 [DEBUG] switch_channel.c:1201
sofia/internal/111998 at xx.xx.xx.xx EXPORTING[export_vars]
[RFC2822_DATE]=[Mon, 02 Dec 2013 15:11:49 +0000] to event
2013-12-02 15:11:49.658540 [DEBUG] switch_channel.c:1201
sofia/internal/111998 at xx.xx.xx.xx EXPORTING[export_vars]
[absolute_codec_string]=[PCMU,PCMA] to event
2013-12-02 15:11:49.658540 [DEBUG] switch_channel.c:1201
sofia/internal/111998 at xx.xx.xx.xx EXPORTING[export_vars]
[media_webrtc]=[true] to event
2013-12-02 15:11:49.658540 [DEBUG] switch_channel.c:1201
sofia/internal/111998 at xx.xx.xx.xx EXPORTING[export_vars]
[dialed_extension]=[111999] to event
2013-12-02 15:11:49.658540 [DEBUG] switch_ivr_originate.c:2070 Parsing
global variables
2013-12-02 15:11:49.658540 [DEBUG] switch_channel.c:1201
sofia/internal/111998 at xx.xx.xx.xx EXPORTING[export_vars]
[RFC2822_DATE]=[Mon, 02 Dec 2013 15:11:49 +0000] to event
2013-12-02 15:11:49.658540 [DEBUG] switch_channel.c:1201
sofia/internal/111998 at xx.xx.xx.xx EXPORTING[export_vars]
[absolute_codec_string]=[PCMU,PCMA] to event
2013-12-02 15:11:49.658540 [DEBUG] switch_channel.c:1201
sofia/internal/111998 at xx.xx.xx.xx EXPORTING[export_vars]
[media_webrtc]=[true] to event
2013-12-02 15:11:49.658540 [DEBUG] switch_channel.c:1201
sofia/internal/111998 at xx.xx.xx.xx EXPORTING[export_vars]
[dialed_extension]=[111999] to event
2013-12-02 15:11:49.658540 [DEBUG] switch_ivr_originate.c:2070 Parsing
global variables
2013-12-02 15:11:49.658540 [DEBUG] switch_event.c:1680 Parsing variable
[sip_invite_domain]=[10.188.136.13]
2013-12-02 15:11:49.658540 [DEBUG] switch_event.c:1680 Parsing variable
[presence_id]=[111999 at 10.188.136.13]
2013-12-02 15:11:49.658540 [NOTICE] switch_channel.c:1055 New Channel
sofia/internal/sip:111999 at xx.xx.xx.xx:48336
[9417c8d2-78e4-47cf-8c22-1718cbd744ba]
2013-12-02 15:11:49.658540 [DEBUG] mod_sofia.c:4429
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State Change CS_NEW -> CS_INIT
2013-12-02 15:11:49.658540 [DEBUG] switch_core_session.c:1374 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:467
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) Running State Change CS_INIT
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:506
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State INIT
2013-12-02 15:11:49.658540 [DEBUG] mod_sofia.c:87
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 SOFIA INIT
2013-12-02 15:11:49.658540 [DEBUG] switch_core_media.c:866 Set Local Key [1
AES_CM_128_HMAC_SHA1_80 inline:woQ+Cv8cMzy2AcEgTaPMNHWVUBq5M1JgIbdd/rWY]
2013-12-02 15:11:49.658540 [DEBUG] switch_core_media.c:866 Set Local Key [1
AES_CM_128_HMAC_SHA1_80 inline:8eNzTa4apnPAZcK2707EPIAUR/Z85E6WcnwhM24H]
2013-12-02 15:11:49.658540 [DEBUG] switch_core_media.c:5921 JAMES WAS HERE :
isendrecv .
2013-12-02 15:11:49.658540 [DEBUG] sofia_glue.c:1196
sip:111999 at xx.xx.xx.xx:48336;transpo;lr;ovid=c5ab5428 Setting proxy route to
sofia/internal/sip:111999 at xx.xx.xx.xx:48336
2013-12-02 15:11:49.658540 [DEBUG] sofia_glue.c:1225 Local SDP:
v=0
o=FreeSWITCH 1385966477 1385966478 IN IP4 xx.xx.xx.xx
s=FreeSWITCH
c=IN IP4 xx.xx.xx.xx
t=0 0
a=sendrecv
a=msid-semantic: WMS yltseQwRXjj4V9bL1UFJklt5Y8F6ME9a
m=audio 30632 RTP/SAVPF 0 8 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fingerprint:sha-256
91:9E:50:FA:2E:A5:8E:02:41:1E:FC:A5:8A:B0:0C:1F:98:1F:1B:49:BB:D6:44:A8:E1:01:EA:82:7C:B6:59:1D
a=rtcp-mux
a=rtcp:30632 IN IP4 xx.xx.xx.xx
a=ssrc:2057233717 cname:QssU8OBWYLQJKRkC
a=ssrc:2057233717 msid:yltseQwRXjj4V9bL1UFJklt5Y8F6ME9a a0
a=ssrc:2057233717 mslabel:yltseQwRXjj4V9bL1UFJklt5Y8F6ME9a
a=ssrc:2057233717 label:yltseQwRXjj4V9bL1UFJklt5Y8F6ME9aa0
a=ice-ufrag:CQbM1vIQtdM6IM6o
a=ice-pwd:4p833AQSbxrMeCeH
a=candidate:7396588577 1 udp 659136 xx.xx.xx.xx 30632 typ host generation 0
a=candidate:7396588577 2 udp 659136 xx.xx.xx.xx 30632 typ host generation 0
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:woQ+Cv8cMzy2AcEgTaPMNHWVUBq5M1JgIbdd/rWY
a=ptime:20

2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:40
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 Standard INIT
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:48
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State Change CS_INIT ->
CS_ROUTING
2013-12-02 15:11:49.658540 [DEBUG] switch_core_session.c:1374 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:506
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State INIT going to sleep
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:467
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) Running State Change
CS_ROUTING
2013-12-02 15:11:49.658540 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:522
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State ROUTING
2013-12-02 15:11:49.658540 [DEBUG] mod_sofia.c:123
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 SOFIA ROUTING
2013-12-02 15:11:49.658540 [DEBUG] switch_ivr_originate.c:67
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State Change CS_ROUTING ->
CS_CONSUME_MEDIA
2013-12-02 15:11:49.658540 [DEBUG] switch_core_session.c:1374 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:522
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State ROUTING going to sleep
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:467
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) Running State Change
CS_CONSUME_MEDIA
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:541
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State CONSUME_MEDIA
2013-12-02 15:11:49.658540 [DEBUG] switch_core_state_machine.c:541
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State CONSUME_MEDIA going to
sleep
2013-12-02 15:11:49.658540 [DEBUG] sofia.c:5861 Channel
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 entering state [calling][0]
2013-12-02 15:11:50.478540 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:11:50.478540 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:11:50.498554 [DEBUG] sofia.c:5861 Channel
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 entering state [proceeding][180]
2013-12-02 15:11:50.498554 [DEBUG] sofia.c:5871 Remote SDP:
v=0
o=- 751491027366329237 2 IN IP4 127.0.0.1
s=-
t=0 0
a=msid-semantic: WMS
m=audio 15561 RTP/SAVPF 0 8 13 101
c=IN IP4 xx.xx.xx.xx
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:13 CN/8000
a=rtpmap:101 telephone-event/8000
a=rtcp:1 IN IP4 0.0.0.0
a=candidate:622902765 1 udp 2113937151 xx.xx.xx.xx 41736 typ host generation
0
a=candidate:1805861149 1 tcp 1509957375 xx.xx.xx.xx 49160 typ host
generation 0
a=candidate:1739408229 1 udp 1845501695 xx.xx.xx.xx 15561 typ srflx raddr
xx.xx.xx.xx rport 41736 generation 0
a=ice-ufrag:mbtnHm5KfkZqEDnI
a=ice-pwd:nA2j+Sq8+sF/DnCRucATdnDd
a=mid:audio
a=rtcp-mux
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:sULSASTq8o0rKq0N+g5LHr4bCcdMFXHsXjQ5ijLK
a=candidate:622902765 1 udp 2113937151 xx.xx.xx.xx 41736 typ host generation
0
a=candidate:1805861149 1 tcp 1509957375 xx.xx.xx.xx 49160 typ host
generation 0
a=candidate:1739408229 1 udp 1845501695 xx.xx.xx.xx 15561 typ srflx raddr
xx.xx.xx.xx rport 41736 generation 0

2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:1065 Set Remote Key
[1 AES_CM_128_HMAC_SHA1_80 inline:sULSASTq8o0rKq0N+g5LHr4bCcdMFXHsXjQ5ijLK]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3213 Audio Codec
Compare [PCMU:0:8000:20:64000] ++++ is saved as a match
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [PCMU:0:8000:20:64000]/[PCMA:8:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3213 Audio Codec
Compare [PCMA:8:8000:20:64000] ++++ is saved as a match
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3085 Set
telephone-event payload to 101
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:2123 Set Codec
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 PCMU/8000 20 ms 160 samples
64000 bits
2013-12-02 15:11:50.498554 [DEBUG] switch_core_codec.c:111
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 Original read codec set to
PCMU:0
2013-12-02 15:11:50.498554 [WARNING] switch_core_media.c:2324 NO candidate
ACL defined, Defaulting to wan.auto
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:2348 Checking
Candidate cid: 1 proto: udp type: host addr: xx.xx.xx.xx:41736
2013-12-02 15:11:50.498554 [NOTICE] switch_core_media.c:2362 Save audio
Candidate cid: 1 proto: udp type: host addr: xx.xx.xx.xx:41736
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:2348 Checking
Candidate cid: 1 proto: udp type: srflx addr: xx.xx.xx.xx:15561
2013-12-02 15:11:50.498554 [NOTICE] switch_core_media.c:2357 Choose audio
Candidate cid: 1 proto: udp type: srflx addr: xx.xx.xx.xx:15561
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:2348 Checking
Candidate cid: 1 proto: udp type: host addr: xx.xx.xx.xx:41736
2013-12-02 15:11:50.498554 [NOTICE] switch_core_media.c:2362 Save audio
Candidate cid: 1 proto: udp type: host addr: xx.xx.xx.xx:41736
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:2348 Checking
Candidate cid: 1 proto: udp type: srflx addr: xx.xx.xx.xx:15561
2013-12-02 15:11:50.498554 [NOTICE] switch_core_media.c:2362 Save audio
Candidate cid: 1 proto: udp type: srflx addr: xx.xx.xx.xx:15561
2013-12-02 15:11:50.498554 [NOTICE] switch_core_media.c:2451 No audio RTCP
candidate found; defaulting to the same as RTP [xx.xx.xx.xx:15561]
2013-12-02 15:11:50.498554 [NOTICE] switch_core_media.c:2486 setting remote
audio ice addr to xx.xx.xx.xx:15561 based on candidate
2013-12-02 15:11:50.498554 [NOTICE] switch_core_media.c:2506 setting remote
rtcp audio addr to xx.xx.xx.xx:15561 based on candidate
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3382 Set 2833 dtmf
send payload to 101
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:4563 AUDIO RTP
[sofia/internal/sip:111999 at xx.xx.xx.xx:48336] 10.188.136.13 port 30632 ->
xx.xx.xx.xx port 15561 codec: 0 ms: 20
2013-12-02 15:11:50.498554 [DEBUG] switch_rtp.c:3047 Starting timer [soft]
160 bytes per 20ms
2013-12-02 15:11:50.498554 [INFO] switch_core_media.c:4732 Activating Audio
ICE
2013-12-02 15:11:50.498554 [NOTICE] switch_rtp.c:3474 Activating RTP audio
ICE: mbtnHm5KfkZqEDnI:CQbM1vIQtdM6IM6o xx.xx.xx.xx:15561
2013-12-02 15:11:50.498554 [INFO] switch_core_media.c:4775 Activating RTCP
PORT 15561
2013-12-02 15:11:50.498554 [DEBUG] switch_rtp.c:3378 RTCP send rate is:
10000 and packet rate is: 20000 Remote Port: 15561
2013-12-02 15:11:50.498554 [DEBUG] switch_rtp.c:1907 Setting RTCP remote
addr to xx.xx.xx.xx:15561
2013-12-02 15:11:50.498554 [INFO] switch_core_media.c:4783 Skipping RTCP ICE
(Same as RTP)
2013-12-02 15:11:50.498554 [INFO] switch_rtp.c:2634 Activate RTP/RTCP audio
DTLS server
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:4907 Set 2833 dtmf
send payload to 101
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:4913 Set 2833 dtmf
receive payload to 101
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:4941 Set comfort
noise payload to 13
2013-12-02 15:11:50.498554 [INFO] switch_rtp.c:2868 Activating Audio Secure
RTP SEND
2013-12-02 15:11:50.498554 [INFO] switch_rtp.c:2846 Activating Audio Secure
RTP RECV
2013-12-02 15:11:50.498554 [DEBUG] switch_core_sqldb.c:2357 Secure Type:
srtp:dtls:AES_CM_128_HMAC_SHA1_80
2013-12-02 15:11:50.498554 [DEBUG] switch_core_sqldb.c:2357 Secure Type:
srtp:dtls:AES_CM_128_HMAC_SHA1_80
2013-12-02 15:11:50.498554 [NOTICE] sofia_media.c:92 Pre-Answer
sofia/internal/sip:111999 at xx.xx.xx.xx:48336!
2013-12-02 15:11:50.498554 [DEBUG] switch_channel.c:3400 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:50.498554 [DEBUG] switch_channel.c:3404
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) Callstate Change DOWN -> EARLY
2013-12-02 15:11:50.498554 [WARNING] switch_channel.c:3338 rtp_secure_media
invalid in this context.
2013-12-02 15:11:50.498554 [INFO] switch_ivr_originate.c:3482 Sending early
media
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [opus:111:48000:60:0]/[G722:9:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [opus:111:48000:60:0]/[GSM:3:8000:20:13200]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [opus:111:48000:60:0]/[PCMU:0:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [opus:111:48000:60:0]/[PCMA:8:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [ISAC:103:16000:30:32000]/[G722:9:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [ISAC:103:16000:30:32000]/[GSM:3:8000:20:13200]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [ISAC:103:16000:30:32000]/[PCMU:0:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [ISAC:103:16000:30:32000]/[PCMA:8:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [ISAC:104:32000:30:32000]/[G722:9:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [ISAC:104:32000:30:32000]/[GSM:3:8000:20:13200]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [ISAC:104:32000:30:32000]/[PCMU:0:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [ISAC:104:32000:30:32000]/[PCMA:8:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [PCMU:0:8000:60:64000]/[G722:9:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [PCMU:0:8000:60:64000]/[GSM:3:8000:20:13200]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [PCMU:0:8000:60:64000]/[PCMU:0:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3213 Audio Codec
Compare [PCMU:0:8000:20:64000] ++++ is saved as a match
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [PCMU:0:8000:60:64000]/[PCMA:8:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [PCMA:8:8000:60:64000]/[G722:9:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [PCMA:8:8000:60:64000]/[GSM:3:8000:20:13200]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [PCMA:8:8000:60:64000]/[PCMU:0:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [PCMA:8:8000:60:64000]/[PCMA:8:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3213 Audio Codec
Compare [PCMA:8:8000:20:64000] ++++ is saved as a match
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [CN:105:16000:60:0]/[G722:9:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [CN:105:16000:60:0]/[GSM:3:8000:20:13200]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [CN:105:16000:60:0]/[PCMU:0:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [CN:105:16000:60:0]/[PCMA:8:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [CN:13:8000:60:0]/[G722:9:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [CN:13:8000:60:0]/[GSM:3:8000:20:13200]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [CN:13:8000:60:0]/[PCMU:0:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3159 Audio Codec
Compare [CN:13:8000:60:0]/[PCMA:8:8000:20:64000]
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3085 Set
telephone-event payload to 126
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:2123 Set Codec
sofia/internal/111998 at xx.xx.xx.xx PCMU/8000 20 ms 160 samples 64000 bits
2013-12-02 15:11:50.498554 [DEBUG] switch_core_codec.c:111
sofia/internal/111998 at xx.xx.xx.xx Original read codec set to PCMU:0
2013-12-02 15:11:50.498554 [WARNING] switch_core_media.c:2324 NO candidate
ACL defined, Defaulting to wan.auto
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:2348 Checking
Candidate cid: 1 proto: udp type: host addr: 10.4.5.177:63907
2013-12-02 15:11:50.498554 [NOTICE] switch_core_media.c:2362 Save audio
Candidate cid: 1 proto: udp type: host addr: 10.4.5.177:63907
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:2348 Checking
Candidate cid: 2 proto: udp type: host addr: 10.4.5.177:63907
2013-12-02 15:11:50.498554 [NOTICE] switch_core_media.c:2362 Save audio
Candidate cid: 2 proto: udp type: host addr: 10.4.5.177:63907
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:2348 Checking
Candidate cid: 1 proto: udp type: srflx addr: xx.xx.xx.xx:52606
2013-12-02 15:11:50.498554 [NOTICE] switch_core_media.c:2357 Choose audio
Candidate cid: 1 proto: udp type: srflx addr: xx.xx.xx.xx:52606
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:2348 Checking
Candidate cid: 2 proto: udp type: srflx addr: xx.xx.xx.xx:52606
2013-12-02 15:11:50.498554 [NOTICE] switch_core_media.c:2357 Choose audio
Candidate cid: 2 proto: udp type: srflx addr: xx.xx.xx.xx:52606
2013-12-02 15:11:50.498554 [NOTICE] switch_core_media.c:2486 setting remote
audio ice addr to xx.xx.xx.xx:52606 based on candidate
2013-12-02 15:11:50.498554 [NOTICE] switch_core_media.c:2506 setting remote
rtcp audio addr to xx.xx.xx.xx:52606 based on candidate
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:3391 Set 2833 dtmf
send/recv payload to 126
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:4563 AUDIO RTP
[sofia/internal/111998 at xx.xx.xx.xx] 10.188.136.13 port 24380 -> xx.xx.xx.xx
port 52606 codec: 0 ms: 20
2013-12-02 15:11:50.498554 [DEBUG] switch_rtp.c:3047 Starting timer [soft]
160 bytes per 20ms
2013-12-02 15:11:50.498554 [INFO] switch_core_media.c:4732 Activating Audio
ICE
2013-12-02 15:11:50.498554 [NOTICE] switch_rtp.c:3474 Activating RTP audio
ICE: fNi6w7SNINs91kf1:0S3OyzuzaWuRVSio xx.xx.xx.xx:52606
2013-12-02 15:11:50.498554 [INFO] switch_core_media.c:4775 Activating RTCP
PORT 52606
2013-12-02 15:11:50.498554 [DEBUG] switch_rtp.c:3378 RTCP send rate is:
10000 and packet rate is: 20000 Remote Port: 52606
2013-12-02 15:11:50.498554 [DEBUG] switch_rtp.c:1907 Setting RTCP remote
addr to xx.xx.xx.xx:52606
2013-12-02 15:11:50.498554 [INFO] switch_core_media.c:4783 Skipping RTCP ICE
(Same as RTP)
2013-12-02 15:11:50.498554 [INFO] switch_rtp.c:2634 Activate RTP/RTCP audio
DTLS client
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:4907 Set 2833 dtmf
send payload to 126
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:4913 Set 2833 dtmf
receive payload to 126
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:4941 Set comfort
noise payload to 106
2013-12-02 15:11:50.498554 [NOTICE] sofia_media.c:92 Pre-Answer
sofia/internal/111998 at xx.xx.xx.xx!
2013-12-02 15:11:50.498554 [DEBUG] switch_channel.c:3404
(sofia/internal/111998 at xx.xx.xx.xx) Callstate Change RINGING -> EARLY
2013-12-02 15:11:50.498554 [DEBUG] switch_core_media.c:5921 JAMES WAS HERE :
isendrecv .
2013-12-02 15:11:50.498554 [DEBUG] mod_sofia.c:2092 Ring SDP:
v=0
o=FreeSWITCH 1385972730 1385972731 IN IP4 xx.xx.xx.xx
s=FreeSWITCH
c=IN IP4 xx.xx.xx.xx
t=0 0
a=sendrecv
a=msid-semantic: WMS TD8yxg3hg5iVXt7spI8oXPFPaKB5R9yA
m=audio 24380 RTP/SAVPF 0 126 106
a=rtpmap:0 PCMU/8000
a=rtpmap:126 telephone-event/8000
a=rtpmap:106 CN/8000
a=ptime:20
a=fingerprint:sha-256
91:9E:50:FA:2E:A5:8E:02:41:1E:FC:A5:8A:B0:0C:1F:98:1F:1B:49:BB:D6:44:A8:E1:01:EA:82:7C:B6:59:1D
a=rtcp-mux
a=rtcp:24380 IN IP4 xx.xx.xx.xx
a=ssrc:1855925413 cname:CxZZDS7JOgvBzsUP
a=ssrc:1855925413 msid:TD8yxg3hg5iVXt7spI8oXPFPaKB5R9yA a0
a=ssrc:1855925413 mslabel:TD8yxg3hg5iVXt7spI8oXPFPaKB5R9yA
a=ssrc:1855925413 label:TD8yxg3hg5iVXt7spI8oXPFPaKB5R9yAa0
a=ice-ufrag:0S3OyzuzaWuRVSio
a=ice-pwd:f7eJQbiuiEVHWGnN
a=candidate:2103413470 1 udp 659136 xx.xx.xx.xx 24380 typ host generation 0

2013-12-02 15:11:50.498554 [DEBUG] switch_core_session.c:894 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:50.498554 [DEBUG] switch_ivr_originate.c:3533 Originate
Resulted in Success: [sofia/internal/sip:111999 at xx.xx.xx.xx:48336]
2013-12-02 15:11:50.518541 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:50.518541 [DEBUG] sofia.c:5861 Channel
sofia/internal/111998 at xx.xx.xx.xx entering state [early][183]
2013-12-02 15:11:50.518541 [DEBUG] switch_ivr_originate.c:3533 Originate
Resulted in Success: [sofia/internal/sip:111999 at xx.xx.xx.xx:48336]
2013-12-02 15:11:50.518541 [DEBUG] switch_core_session.c:894 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:11:50.518541 [DEBUG] switch_core_session.c:894 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:50.518541 [DEBUG] switch_ivr_bridge.c:1440
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State Change CS_CONSUME_MEDIA
-> CS_EXCHANGE_MEDIA
2013-12-02 15:11:50.518541 [DEBUG] switch_core_session.c:1374 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:11:50.518541 [DEBUG] switch_core_state_machine.c:467
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) Running State Change
CS_EXCHANGE_MEDIA
2013-12-02 15:11:50.518541 [DEBUG] switch_core_state_machine.c:532
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State EXCHANGE_MEDIA
2013-12-02 15:11:50.518541 [DEBUG] mod_sofia.c:592 SOFIA EXCHANGE_MEDIA
2013-12-02 15:11:54.378535 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:11:54.378535 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:11:54.398589 [DEBUG] sofia.c:5861 Channel
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 entering state [completing][200]
2013-12-02 15:11:54.398589 [DEBUG] sofia.c:5868 Duplicate SDP
v=0
o=- 751491027366329237 2 IN IP4 127.0.0.1
s=-
t=0 0
a=msid-semantic: WMS
m=audio 15561 RTP/SAVPF 0 8 13 101
c=IN IP4 xx.xx.xx.xx
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:13 CN/8000
a=rtpmap:101 telephone-event/8000
a=rtcp:1 IN IP4 0.0.0.0
a=candidate:622902765 1 udp 2113937151 xx.xx.xx.xx 41736 typ host generation
0
a=candidate:1805861149 1 tcp 1509957375 xx.xx.xx.xx 49160 typ host
generation 0
a=candidate:1739408229 1 udp 1845501695 xx.xx.xx.xx 15561 typ srflx raddr
xx.xx.xx.xx rport 41736 generation 0
a=ice-ufrag:mbtnHm5KfkZqEDnI
a=ice-pwd:nA2j+Sq8+sF/DnCRucATdnDd
a=mid:audio
a=rtcp-mux
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:sULSASTq8o0rKq0N+g5LHr4bCcdMFXHsXjQ5ijLK
a=candidate:622902765 1 udp 2113937151 xx.xx.xx.xx 41736 typ host generation
0
a=candidate:1805861149 1 tcp 1509957375 xx.xx.xx.xx 49160 typ host
generation 0
a=candidate:1739408229 1 udp 1845501695 xx.xx.xx.xx 15561 typ srflx raddr
xx.xx.xx.xx rport 41736 generation 0

2013-12-02 15:11:54.398589 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:11:54.398589 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:11:54.418547 [DEBUG] sofia.c:5861 Channel
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 entering state [ready][200]
2013-12-02 15:11:54.418547 [DEBUG] switch_channel.c:3639 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:54.418547 [NOTICE] sofia.c:6586 Channel
[sofia/internal/sip:111999 at xx.xx.xx.xx:48336] has been answered
2013-12-02 15:11:54.418547 [DEBUG] switch_channel.c:3685
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) Callstate Change EARLY ->
ACTIVE
2013-12-02 15:11:54.418547 [DEBUG] switch_core_media.c:5921 JAMES WAS HERE :
isendrecv .
2013-12-02 15:11:54.418547 [DEBUG] mod_sofia.c:775 Local SDP
sofia/internal/111998 at xx.xx.xx.xx:
v=0
o=FreeSWITCH 1385972730 1385972732 IN IP4 xx.xx.xx.xx
s=FreeSWITCH
c=IN IP4 xx.xx.xx.xx
t=0 0
a=sendrecv
a=msid-semantic: WMS TD8yxg3hg5iVXt7spI8oXPFPaKB5R9yA
m=audio 24380 RTP/SAVPF 0 126 106
a=rtpmap:0 PCMU/8000
a=rtpmap:126 telephone-event/8000
a=rtpmap:106 CN/8000
a=ptime:20
a=fingerprint:sha-256
91:9E:50:FA:2E:A5:8E:02:41:1E:FC:A5:8A:B0:0C:1F:98:1F:1B:49:BB:D6:44:A8:E1:01:EA:82:7C:B6:59:1D
a=rtcp-mux
a=rtcp:24380 IN IP4 xx.xx.xx.xx
a=ssrc:1855925413 cname:CxZZDS7JOgvBzsUP
a=ssrc:1855925413 msid:TD8yxg3hg5iVXt7spI8oXPFPaKB5R9yA a0
a=ssrc:1855925413 mslabel:TD8yxg3hg5iVXt7spI8oXPFPaKB5R9yA
a=ssrc:1855925413 label:TD8yxg3hg5iVXt7spI8oXPFPaKB5R9yAa0
a=ice-ufrag:0S3OyzuzaWuRVSio
a=ice-pwd:f7eJQbiuiEVHWGnN
a=candidate:2702679747 1 udp 659136 xx.xx.xx.xx 24380 typ host generation 0

2013-12-02 15:11:54.418547 [DEBUG] switch_core_session.c:894 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:54.418547 [NOTICE] switch_ivr_bridge.c:484 Channel
[sofia/internal/111998 at xx.xx.xx.xx] has been answered
2013-12-02 15:11:54.418547 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:54.418547 [DEBUG] switch_channel.c:3685
(sofia/internal/111998 at xx.xx.xx.xx) Callstate Change EARLY -> ACTIVE
2013-12-02 15:11:54.418547 [DEBUG] sofia.c:5861 Channel
sofia/internal/111998 at xx.xx.xx.xx entering state [completed][200]
2013-12-02 15:11:54.698537 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:54.698537 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:54.698537 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:54.698537 [DEBUG] sofia.c:5861 Channel
sofia/internal/111998 at xx.xx.xx.xx entering state [ready][200]
2013-12-02 15:11:54.698537 [DEBUG] switch_core_session.c:956 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:11:54.698537 [DEBUG] switch_core_session.c:956 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:11:58.198537 [INFO] switch_rtp.c:2449 Changing audio DTLS
state from HANDSHAKE to SETUP
2013-12-02 15:11:58.198537 [INFO] switch_rtp.c:2368 audio Fingerprint
Verified.
2013-12-02 15:11:58.198537 [INFO] switch_rtp.c:2868 Activating Audio Secure
RTP SEND
2013-12-02 15:11:58.198537 [INFO] switch_rtp.c:2846 Activating Audio Secure
RTP RECV
2013-12-02 15:11:58.198537 [INFO] switch_rtp.c:2408 Changing audio DTLS
state from SETUP to READY
2013-12-02 15:11:58.198537 [DEBUG] switch_core_sqldb.c:2357 Secure Type:
srtp:dtls:AES_CM_128_HMAC_SHA1_80
2013-12-02 15:11:58.198537 [DEBUG] switch_core_sqldb.c:2357 Secure Type:
srtp:dtls:AES_CM_128_HMAC_SHA1_80
2013-12-02 15:12:33.938558 [ERR] switch_rtp.c:718 No audio stun for a long
time!
2013-12-02 15:13:04.218537 [ERR] switch_rtp.c:718 No audio stun for a long
time!
2013-12-02 15:13:23.978537 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:13:23.978537 [NOTICE] sofia.c:715 Hangup
sofia/internal/111998 at xx.xx.xx.xx [CS_EXECUTE] [NORMAL_CLEARING]
2013-12-02 15:13:23.978537 [DEBUG] switch_channel.c:3211 Send signal
sofia/internal/111998 at xx.xx.xx.xx [KILL]
2013-12-02 15:13:23.978537 [DEBUG] switch_core_session.c:1374 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:13:23.978537 [DEBUG] switch_ivr_bridge.c:647 BRIDGE THREAD
DONE [sofia/internal/111998 at xx.xx.xx.xx]
2013-12-02 15:13:23.978537 [DEBUG] switch_ivr_bridge.c:672 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:13:23.998540 [DEBUG] switch_ivr_bridge.c:647 BRIDGE THREAD
DONE [sofia/internal/sip:111999 at xx.xx.xx.xx:48336]
2013-12-02 15:13:23.998540 [DEBUG] switch_ivr_bridge.c:672 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:13:23.998540 [NOTICE] switch_ivr_bridge.c:735 Hangup
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [CS_EXCHANGE_MEDIA]
[NORMAL_CLEARING]
2013-12-02 15:13:23.998540 [DEBUG] switch_channel.c:3211 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [KILL]
2013-12-02 15:13:23.998540 [DEBUG] switch_core_session.c:1374 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:532
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State EXCHANGE_MEDIA going to
sleep
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:467
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) Running State Change CS_HANGUP
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:730
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State HANGUP
2013-12-02 15:13:23.998540 [DEBUG] mod_sofia.c:407
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 Overriding SIP cause 480 with
200 from the other leg
2013-12-02 15:13:23.998540 [DEBUG] mod_sofia.c:413 Channel
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 hanging up, cause:
NORMAL_CLEARING
2013-12-02 15:13:23.998540 [DEBUG] mod_sofia.c:465 Sending BYE to
sofia/internal/sip:111999 at xx.xx.xx.xx:48336
2013-12-02 15:13:23.998540 [DEBUG] switch_ivr_bridge.c:1538
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 skip receive message [UNBRIDGE]
(channel is hungup already)
2013-12-02 15:13:23.998540 [DEBUG] switch_ivr_bridge.c:1541
sofia/internal/111998 at xx.xx.xx.xx skip receive message [UNBRIDGE] (channel
is hungup already)
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:58
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 Standard HANGUP, cause:
NORMAL_CLEARING
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:730
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State HANGUP going to sleep
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:743
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) Callstate Change ACTIVE ->
HANGUP
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:498
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State Change CS_HANGUP ->
CS_REPORTING
2013-12-02 15:13:23.998540 [DEBUG] switch_core_session.c:1374 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:13:23.998540 [DEBUG] switch_core_session.c:2843
sofia/internal/111998 at xx.xx.xx.xx skip receive message
[APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:529
(sofia/internal/111998 at xx.xx.xx.xx) State EXECUTE going to sleep
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:467
(sofia/internal/111998 at xx.xx.xx.xx) Running State Change CS_HANGUP
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:467
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) Running State Change
CS_REPORTING
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:815
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State REPORTING
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:102
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 Standard REPORTING, cause:
NORMAL_CLEARING
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:815
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State REPORTING going to sleep
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:730
(sofia/internal/111998 at xx.xx.xx.xx) State HANGUP
2013-12-02 15:13:23.998540 [DEBUG] mod_sofia.c:413 Channel
sofia/internal/111998 at xx.xx.xx.xx hanging up, cause: NORMAL_CLEARING
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:492
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State Change CS_REPORTING ->
CS_DESTROY
2013-12-02 15:13:23.998540 [DEBUG] switch_core_session.c:1374 Send signal
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [BREAK]
2013-12-02 15:13:23.998540 [DEBUG] switch_core_session.c:1582 Session 47
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) Locked, Waiting on external
entities
2013-12-02 15:13:23.998540 [NOTICE] switch_core_session.c:1600 Session 47
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) Ended
2013-12-02 15:13:23.998540 [NOTICE] switch_core_session.c:1604 Close Channel
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 [CS_DESTROY]
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:617
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) Callstate Change HANGUP ->
DOWN
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:620
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) Running State Change
CS_DESTROY
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:58
sofia/internal/111998 at xx.xx.xx.xx Standard HANGUP, cause: NORMAL_CLEARING
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:730
(sofia/internal/111998 at xx.xx.xx.xx) State HANGUP going to sleep
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:630
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State DESTROY
2013-12-02 15:13:23.998540 [DEBUG] mod_sofia.c:323
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 SOFIA DESTROY
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:743
(sofia/internal/111998 at xx.xx.xx.xx) Callstate Change ACTIVE -> HANGUP
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:109
sofia/internal/sip:111999 at xx.xx.xx.xx:48336 Standard DESTROY
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:630
(sofia/internal/sip:111999 at xx.xx.xx.xx:48336) State DESTROY going to sleep
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:498
(sofia/internal/111998 at xx.xx.xx.xx) State Change CS_HANGUP -> CS_REPORTING
2013-12-02 15:13:23.998540 [DEBUG] switch_core_session.c:1374 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:467
(sofia/internal/111998 at xx.xx.xx.xx) Running State Change CS_REPORTING
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:815
(sofia/internal/111998 at xx.xx.xx.xx) State REPORTING
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:102
sofia/internal/111998 at xx.xx.xx.xx Standard REPORTING, cause: NORMAL_CLEARING
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:815
(sofia/internal/111998 at xx.xx.xx.xx) State REPORTING going to sleep
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:492
(sofia/internal/111998 at xx.xx.xx.xx) State Change CS_REPORTING -> CS_DESTROY
2013-12-02 15:13:23.998540 [DEBUG] switch_core_session.c:1374 Send signal
sofia/internal/111998 at xx.xx.xx.xx [BREAK]
2013-12-02 15:13:23.998540 [DEBUG] switch_core_session.c:1582 Session 46
(sofia/internal/111998 at xx.xx.xx.xx) Locked, Waiting on external entities
2013-12-02 15:13:23.998540 [NOTICE] switch_core_session.c:1600 Session 46
(sofia/internal/111998 at xx.xx.xx.xx) Ended
2013-12-02 15:13:23.998540 [NOTICE] switch_core_session.c:1604 Close Channel
sofia/internal/111998 at xx.xx.xx.xx [CS_DESTROY]
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:617
(sofia/internal/111998 at xx.xx.xx.xx) Callstate Change HANGUP -> DOWN
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:620
(sofia/internal/111998 at xx.xx.xx.xx) Running State Change CS_DESTROY
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:630
(sofia/internal/111998 at xx.xx.xx.xx) State DESTROY
2013-12-02 15:13:23.998540 [DEBUG] mod_sofia.c:323
sofia/internal/111998 at xx.xx.xx.xx SOFIA DESTROY
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:109
sofia/internal/111998 at xx.xx.xx.xx Standard DESTROY
2013-12-02 15:13:23.998540 [DEBUG] switch_core_state_machine.c:630
(sofia/internal/111998 at xx.xx.xx.xx) State DESTROY going to sleep

--
View this message in context: http://freeswitch-users.2379917.n2.nabble.com/No-audio-in-inbound-call-for-android-apprtc-webrtc-tp7596014.html
Sent from the freeswitch-users mailing list archive at Nabble.com.