[Freeswitch-users] doesn't send INVITE to callee with TLS on FreeSWITCH
Herold Park
heroldpark at gmail.com
Mon Oct 6 12:05:13 MSD 2014
In the FreeSWITCH-1.4.8, i have setup SRTP with TLS.
1. caller - FreeSWITCH - callee Handshake is good.
2. Freeswitch receive TLS(include SIP/SDP - INVITE) from caller,
and then it MUST send TLS(include SIP/SDP - INVITE) to callee. But
Freeswitch doesn't forward TLS(SIP/SDP - INVITE) to callee.
3. SIP/SDP message show good at Freeswitch log.
What's wrong or missing something ? Please help me.
Message ----
freeswitch at internal> 2014-10-06 17:03:17.908850 [NOTICE]
switch_channel.c:1055 New Channel
sofia/internal/1003 at 192.168.1.15:5061
[8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8]
2014-10-06 17:03:17.908850 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:17.908850 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:17.908850 [DEBUG] switch_core_state_machine.c:474
(sofia/internal/1003 at 192.168.1.15:5061) Running State Change CS_NEW
2014-10-06 17:03:17.928869 [DEBUG] sofia.c:8590
sofia/internal/1003 at 192.168.1.15:5061 receiving invite from
192.168.1.33:4738 version: 1.4.8 64bit
2014-10-06 17:03:17.928869 [DEBUG] sofia.c:8757 IP 192.168.1.33
Rejected by acl "domains". Falling back to Digest auth.
2014-10-06 17:03:17.928869 [DEBUG] switch_core_state_machine.c:493
(sofia/internal/1003 at 192.168.1.15:5061) State NEW
2014-10-06 17:03:17.948910 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:17.948910 [DEBUG] sofia.c:2068 detaching session
8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8
2014-10-06 17:03:18.048881 [DEBUG] sofia.c:2175 Re-attaching to
session 8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8
2014-10-06 17:03:18.048881 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:18.048881 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:18.068869 [DEBUG] sofia.c:8590
sofia/internal/1003 at 192.168.1.15:5061 receiving invite from
192.168.1.33:4738 version: 1.4.8 64bit
2014-10-06 17:03:18.068869 [DEBUG] sofia.c:8757 IP 192.168.1.33
Rejected by acl "domains". Falling back to Digest auth.
2014-10-06 17:03:18.068869 [DEBUG] sofia.c:6408 Channel
sofia/internal/1003 at 192.168.1.15:5061 entering state [received][100]
2014-10-06 17:03:18.068869 [DEBUG] sofia.c:6418 Remote SDP:
v=0
o=LGEIPP 18947 18948 IN IP4 192.168.1.33
s=SIP Call
c=IN IP4 192.168.1.33
t=0 0
m=audio 23000 RTP/SAVP 8 0 18 111
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:111 X-nt-inforeq/8000
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:s2sm1JOsV7VwZN+qxPt3guw1XPeBf0ooRZ9bG3/L
m=audio 23000 RTP/AVP 8 0 18 111
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:111 X-nt-inforeq/8000
2014-10-06 17:03:18.068869 [DEBUG] sofia.c:6486 gntel
sofia_handle_sip_i_state() callstate=5
2014-10-06 17:03:18.068869 [DEBUG] sofia.c:6652 gntel
sofia_handle_sip_i_state() crypto=AES_CM_128_HMAC_SHA1_80
2014-10-06 17:03:18.068869 [DEBUG] sofia.c:6693
(sofia/internal/1003 at 192.168.1.15:5061) State Change CS_NEW -> CS_INIT
2014-10-06 17:03:18.068869 [DEBUG] switch_core_session.c:1387 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:474
(sofia/internal/1003 at 192.168.1.15:5061) Running State Change CS_INIT
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:514
(sofia/internal/1003 at 192.168.1.15:5061) State INIT
2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:87
sofia/internal/1003 at 192.168.1.15:5061 SOFIA INIT
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:40
sofia/internal/1003 at 192.168.1.15:5061 Standard INIT
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:48
(sofia/internal/1003 at 192.168.1.15:5061) State Change CS_INIT ->
CS_ROUTING
2014-10-06 17:03:18.068869 [DEBUG] switch_core_session.c:1387 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:514
(sofia/internal/1003 at 192.168.1.15:5061) State INIT going to sleep
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:474
(sofia/internal/1003 at 192.168.1.15:5061) Running State Change
CS_ROUTING
2014-10-06 17:03:18.068869 [DEBUG] switch_channel.c:2184
(sofia/internal/1003 at 192.168.1.15:5061) Callstate Change DOWN ->
RINGING
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:530
(sofia/internal/1003 at 192.168.1.15:5061) State ROUTING
2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:123
sofia/internal/1003 at 192.168.1.15:5061 SOFIA ROUTING
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:166
sofia/internal/1003 at 192.168.1.15:5061 Standard ROUTING
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:190
gntel ==> switch_core_standard_on_routing()
2014-10-06 17:03:18.068869 [INFO] mod_dialplan_xml.c:558 Processing
1003 <1003>->1004 in context default
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->unloop] continue=false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (PASS) [unloop]
${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (FAIL) [unloop]
${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->tod_example] continue=true
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Date/Time Match (PASS)
[tod_example] break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action set(open=true)
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->holiday_example] continue=true
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Date/TimeMatch (FAIL)
[holiday_example] break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->global-intercept] continue=false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (FAIL)
[global-intercept] destination_number(1004) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->group-intercept] continue=false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (FAIL)
[group-intercept] destination_number(1004) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->intercept-ext] continue=false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (FAIL)
[intercept-ext] destination_number(1004) =~ /^\*\*(\d+)$/
break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->redial] continue=false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (FAIL) [redial]
destination_number(1004) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->global] continue=true
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (FAIL) [global]
${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (PASS) [global]
${rtp_has_crypto}(AES_CM_128_HMAC_SHA1_80) =~
/^(AES_CM_128_HMAC_SHA1_80|ARIA_CM_128_HMAC_SHA1_80)$/ break=never
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
set(rtp_secure_media=true)
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
export(rtp_secure_media=true)
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (PASS) [global]
${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED
NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (PASS) [global]
${switch_r_sdp}(v=0
o=LGEIPP 18947 18948 IN IP4 192.168.1.33
s=SIP Call
c=IN IP4 192.168.1.33
t=0 0
m=audio 23000 RTP/SAVP 8 0 18 111
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:111 X-nt-inforeq/8000
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:s2sm1JOsV7VwZN+qxPt3guw1XPeBf0ooRZ9bG3/L
m=audio 23000 RTP/AVP 8 0 18 111
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:111 X-nt-inforeq/8000
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80|ARIA_CM_128_HMAC_SHA1_80)/
break=never
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
set(rtp_secure_media=true)
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Absolute Condition [global]
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->snom-demo-2] continue=false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (FAIL)
[snom-demo-2] destination_number(1004) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->snom-demo-1] continue=false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (FAIL)
[snom-demo-1] destination_number(1004) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->eavesdrop] continue=false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (FAIL)
[eavesdrop] destination_number(1004) =~ /^88(\d{4})$|^\*0(.*)$/
break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->eavesdrop] continue=false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (FAIL)
[eavesdrop] destination_number(1004) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->call_return] continue=false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (FAIL)
[call_return] destination_number(1004) =~ /^\*69$|^869$|^lcr$/
break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->del-group] continue=false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (FAIL)
[del-group] destination_number(1004) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->add-group] continue=false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (FAIL)
[add-group] destination_number(1004) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->call-group-simo] continue=false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (FAIL)
[call-group-simo] destination_number(1004) =~ /^82(\d{2})$/
break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->call-group-order] continue=false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (FAIL)
[call-group-order] destination_number(1004) =~ /^83(\d{2})$/
break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->extension-intercom] continue=false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (FAIL)
[extension-intercom] destination_number(1004) =~ /^8(10[01][0-9])$/
break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 parsing
[default->Local_Extension] continue=false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Regex (PASS)
[Local_Extension] destination_number(1004) =~ /^(10[01][0-9])$/
break=on-false
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
export(dialed_extension=1004)
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action bind_meta_app(1
b s execute_extension::dx XML features)
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action bind_meta_app(2
b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav)
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action bind_meta_app(3
b s execute_extension::cf XML features)
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action bind_meta_app(4
b s execute_extension::att_xfer XML features)
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action set(ringback=${us-ring})
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action set(call_timeout=30)
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
set(hangup_after_bridge=true)
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
set(continue_on_fail=true)
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name}
var callgroup)})
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
hash(insert/${domain_name}-last_dial_ext/global/${uuid})
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
bridge(user/${dialed_extension}@${domain_name})
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action answer()
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action sleep(1000)
Dialplan: sofia/internal/1003 at 192.168.1.15:5061 Action
bridge(loopback/app=voicemail:default ${domain_name}
${dialed_extension})
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:218
(sofia/internal/1003 at 192.168.1.15:5061) State Change CS_ROUTING ->
CS_EXECUTE
2014-10-06 17:03:18.068869 [DEBUG] switch_core_session.c:1387 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:530
(sofia/internal/1003 at 192.168.1.15:5061) State ROUTING going to sleep
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:474
(sofia/internal/1003 at 192.168.1.15:5061) Running State Change
CS_EXECUTE
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:537
(sofia/internal/1003 at 192.168.1.15:5061) State EXECUTE
2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:178
sofia/internal/1003 at 192.168.1.15:5061 SOFIA EXECUTE
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:260
sofia/internal/1003 at 192.168.1.15:5061 Standard EXECUTE
EXECUTE sofia/internal/1003 at 192.168.1.15:5061 set(open=true)
2014-10-06 17:03:18.068869 [DEBUG] mod_dptools.c:1435
sofia/internal/1003 at 192.168.1.15:5061 SET [open]=[true]
EXECUTE sofia/internal/1003 at 192.168.1.15:5061 set(rtp_secure_media=true)
2014-10-06 17:03:18.068869 [DEBUG] mod_dptools.c:1435
sofia/internal/1003 at 192.168.1.15:5061 SET [rtp_secure_media]=[true]
EXECUTE sofia/internal/1003 at 192.168.1.15:5061 export(rtp_secure_media=true)
2014-10-06 17:03:18.068869 [DEBUG] switch_channel.c:1247 EXPORT
(export_vars) [rtp_secure_media]=[true]
EXECUTE sofia/internal/1003 at 192.168.1.15:5061 set(rtp_secure_media=true)
2014-10-06 17:03:18.068869 [DEBUG] mod_dptools.c:1435
sofia/internal/1003 at 192.168.1.15:5061 SET [rtp_secure_media]=[true]
EXECUTE sofia/internal/1003 at 192.168.1.15:5061
hash(insert/192.168.1.15-spymap/1003/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8)
EXECUTE sofia/internal/1003 at 192.168.1.15:5061
hash(insert/192.168.1.15-last_dial/1003/1004)
EXECUTE sofia/internal/1003 at 192.168.1.15:5061
hash(insert/192.168.1.15-last_dial/global/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8)
EXECUTE sofia/internal/1003 at 192.168.1.15:5061 export(RFC2822_DATE=Mon,
06 Oct 2014 17:03:18 +0900)
2014-10-06 17:03:18.068869 [DEBUG] switch_channel.c:1247 EXPORT
(export_vars) [RFC2822_DATE]=[Mon, 06 Oct 2014 17:03:18 +0900]
EXECUTE sofia/internal/1003 at 192.168.1.15:5061 export(dialed_extension=1004)
2014-10-06 17:03:18.068869 [DEBUG] switch_channel.c:1247 EXPORT
(export_vars) [dialed_extension]=[1004]
EXECUTE sofia/internal/1003 at 192.168.1.15:5061 bind_meta_app(1 b s
execute_extension::dx XML features)
2014-10-06 17:03:18.068869 [INFO] switch_ivr_async.c:3661 Bound B-Leg:
*1 execute_extension::dx XML features
EXECUTE sofia/internal/1003 at 192.168.1.15:5061 bind_meta_app(2 b s
record_session::/usr/local/freeswitch/recordings/1003.2014-10-06-17-03-18.wav)
2014-10-06 17:03:18.068869 [INFO] switch_ivr_async.c:3661 Bound B-Leg:
*2 record_session::/usr/local/freeswitch/recordings/1003.2014-10-06-17-03-18.wav
EXECUTE sofia/internal/1003 at 192.168.1.15:5061 bind_meta_app(3 b s
execute_extension::cf XML features)
2014-10-06 17:03:18.068869 [INFO] switch_ivr_async.c:3661 Bound B-Leg:
*3 execute_extension::cf XML features
EXECUTE sofia/internal/1003 at 192.168.1.15:5061 bind_meta_app(4 b s
execute_extension::att_xfer XML features)
2014-10-06 17:03:18.068869 [INFO] switch_ivr_async.c:3661 Bound B-Leg:
*4 execute_extension::att_xfer XML features
EXECUTE sofia/internal/1003 at 192.168.1.15:5061 set(ringback=%(2000,4000,440,480))
2014-10-06 17:03:18.068869 [DEBUG] mod_dptools.c:1435
sofia/internal/1003 at 192.168.1.15:5061 SET
[ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/internal/1003 at 192.168.1.15:5061
set(transfer_ringback=local_stream://moh)
2014-10-06 17:03:18.068869 [DEBUG] mod_dptools.c:1435
sofia/internal/1003 at 192.168.1.15:5061 SET
[transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/1003 at 192.168.1.15:5061 set(call_timeout=30)
2014-10-06 17:03:18.068869 [DEBUG] mod_dptools.c:1435
sofia/internal/1003 at 192.168.1.15:5061 SET [call_timeout]=[30]
EXECUTE sofia/internal/1003 at 192.168.1.15:5061 set(hangup_after_bridge=true)
2014-10-06 17:03:18.068869 [DEBUG] mod_dptools.c:1435
sofia/internal/1003 at 192.168.1.15:5061 SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/1003 at 192.168.1.15:5061 set(continue_on_fail=true)
2014-10-06 17:03:18.068869 [DEBUG] mod_dptools.c:1435
sofia/internal/1003 at 192.168.1.15:5061 SET [continue_on_fail]=[true]
EXECUTE sofia/internal/1003 at 192.168.1.15:5061
hash(insert/192.168.1.15-call_return/1004/1003)
EXECUTE sofia/internal/1003 at 192.168.1.15:5061
hash(insert/192.168.1.15-last_dial_ext/1004/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8)
EXECUTE sofia/internal/1003 at 192.168.1.15:5061
set(called_party_callgroup=techsupport)
2014-10-06 17:03:18.068869 [DEBUG] mod_dptools.c:1435
sofia/internal/1003 at 192.168.1.15:5061 SET
[called_party_callgroup]=[techsupport]
EXECUTE sofia/internal/1003 at 192.168.1.15:5061
hash(insert/192.168.1.15-last_dial_ext/techsupport/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8)
EXECUTE sofia/internal/1003 at 192.168.1.15:5061
hash(insert/192.168.1.15-last_dial_ext/global/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8)
EXECUTE sofia/internal/1003 at 192.168.1.15:5061
hash(insert/192.168.1.15-last_dial/techsupport/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8)
EXECUTE sofia/internal/1003 at 192.168.1.15:5061 bridge(user/1004 at 192.168.1.15)
2014-10-06 17:03:18.068869 [DEBUG] switch_channel.c:1201
sofia/internal/1003 at 192.168.1.15:5061 EXPORTING[export_vars]
[rtp_secure_media]=[true] to event
2014-10-06 17:03:18.068869 [DEBUG] switch_channel.c:1201
sofia/internal/1003 at 192.168.1.15:5061 EXPORTING[export_vars]
[RFC2822_DATE]=[Mon, 06 Oct 2014 17:03:18 +0900] to event
2014-10-06 17:03:18.068869 [DEBUG] switch_channel.c:1201
sofia/internal/1003 at 192.168.1.15:5061 EXPORTING[export_vars]
[dialed_extension]=[1004] to event
2014-10-06 17:03:18.068869 [DEBUG] switch_ivr_originate.c:2080 Parsing
global variables
2014-10-06 17:03:18.068869 [DEBUG] switch_channel.c:1201
sofia/internal/1003 at 192.168.1.15:5061 EXPORTING[export_vars]
[rtp_secure_media]=[true] to event
2014-10-06 17:03:18.068869 [DEBUG] switch_channel.c:1201
sofia/internal/1003 at 192.168.1.15:5061 EXPORTING[export_vars]
[RFC2822_DATE]=[Mon, 06 Oct 2014 17:03:18 +0900] to event
2014-10-06 17:03:18.068869 [DEBUG] switch_channel.c:1201
sofia/internal/1003 at 192.168.1.15:5061 EXPORTING[export_vars]
[dialed_extension]=[1004] to event
2014-10-06 17:03:18.068869 [DEBUG] switch_ivr_originate.c:2080 Parsing
global variables
2014-10-06 17:03:18.068869 [DEBUG] switch_event.c:1688 Parsing
variable [sip_invite_domain]=[192.168.1.15]
2014-10-06 17:03:18.068869 [DEBUG] switch_event.c:1688 Parsing
variable [presence_id]=[1004 at 192.168.1.15]
2014-10-06 17:03:18.068869 [NOTICE] switch_channel.c:1055 New Channel
sofia/internal/sip:1004 at 192.168.1.34:5061
[d495cbf0-0bc6-4f85-9696-7ff4a9a8eab3]
2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:4586
(sofia/internal/sip:1004 at 192.168.1.34:5061) State Change CS_NEW ->
CS_INIT
2014-10-06 17:03:18.068869 [DEBUG] switch_core_session.c:1387 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:4656 [zrtp_passthru]
Setting a-leg inherit_codec=true
2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:4659 [zrtp_passthru]
Setting b-leg absolute_codec_string='PCMA at 8000h@20i at 64000b,PCMU at 8000h@20i at 64000b,PCMA at 8000h@20i at 64000b,PCMU at 8000h@20i at 64000b'
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:474
(sofia/internal/sip:1004 at 192.168.1.34:5061) Running State Change
CS_INIT
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:514
(sofia/internal/sip:1004 at 192.168.1.34:5061) State INIT
2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:87
sofia/internal/sip:1004 at 192.168.1.34:5061 SOFIA INIT
2014-10-06 17:03:18.068869 [DEBUG] switch_core_media.c:1317 gntel
switch_core_session_check_outgoing_crypto() start
2014-10-06 17:03:18.068869 [DEBUG] switch_core_media.c:938 gntel
switch_core_session_check_outgoing_crypto()
crypto=AES_CM_128_HMAC_SHA1_80
2014-10-06 17:03:18.068869 [DEBUG] switch_core_media.c:947 Set Local
audio crypto Key [3 AES_CM_128_HMAC_SHA1_80
inline:dwyUtiR/+dNuBBrGKSVs8BEY4ydM8fsjoI+qLcS8]
2014-10-06 17:03:18.068869 [DEBUG] switch_core_media.c:938 gntel
switch_core_session_check_outgoing_crypto()
crypto=AES_CM_128_HMAC_SHA1_80
2014-10-06 17:03:18.068869 [DEBUG] switch_core_media.c:947 Set Local
video crypto Key [3 AES_CM_128_HMAC_SHA1_80
inline:IyjDuhOjUtgO7BN3Yvx6TDTjufxP6DKvz6wMw/eR]
2014-10-06 17:03:18.068869 [DEBUG] sofia_glue.c:1226
sofia/internal/sip:1004 at 192.168.1.34:5061 sending invite version:
1.4.8 64bit
Local SDP:
v=0
o=FreeSWITCH 1412564222 1412564223 IN IP4 192.168.1.15
s=FreeSWITCH
c=IN IP4 192.168.1.15
t=0 0
m=audio 18376 RTP/SAVP 8 0 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=crypto:3 AES_CM_128_HMAC_SHA1_80
inline:dwyUtiR/+dNuBBrGKSVs8BEY4ydM8fsjoI+qLcS8
a=ptime:20
a=sendrecv
2014-10-06 17:03:18.068869 [DEBUG] sofia_glue.c:1230 sofia_use_soa=1
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:40
sofia/internal/sip:1004 at 192.168.1.34:5061 Standard INIT
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:48
(sofia/internal/sip:1004 at 192.168.1.34:5061) State Change CS_INIT ->
CS_ROUTING
2014-10-06 17:03:18.068869 [DEBUG] switch_core_session.c:1387 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:514
(sofia/internal/sip:1004 at 192.168.1.34:5061) State INIT going to sleep
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:474
(sofia/internal/sip:1004 at 192.168.1.34:5061) Running State Change
CS_ROUTING
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:530
(sofia/internal/sip:1004 at 192.168.1.34:5061) State ROUTING
2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:123
sofia/internal/sip:1004 at 192.168.1.34:5061 SOFIA ROUTING
2014-10-06 17:03:18.068869 [DEBUG] switch_ivr_originate.c:67
(sofia/internal/sip:1004 at 192.168.1.34:5061) State Change CS_ROUTING ->
CS_CONSUME_MEDIA
2014-10-06 17:03:18.068869 [DEBUG] switch_core_session.c:1387 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:530
(sofia/internal/sip:1004 at 192.168.1.34:5061) State ROUTING going to
sleep
2014-10-06 17:03:18.088801 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:18.088801 [DEBUG] switch_core_state_machine.c:474
(sofia/internal/sip:1004 at 192.168.1.34:5061) Running State Change
CS_CONSUME_MEDIA
2014-10-06 17:03:18.088801 [DEBUG] sofia.c:6408 Channel
sofia/internal/sip:1004 at 192.168.1.34:5061 entering state [calling][0]
2014-10-06 17:03:18.088801 [DEBUG] sofia.c:6486 gntel
sofia_handle_sip_i_state() callstate=2
2014-10-06 17:03:18.088801 [DEBUG] switch_core_state_machine.c:549
(sofia/internal/sip:1004 at 192.168.1.34:5061) State CONSUME_MEDIA
2014-10-06 17:03:18.088801 [DEBUG] switch_core_state_machine.c:549
(sofia/internal/sip:1004 at 192.168.1.34:5061) State CONSUME_MEDIA going
to sleep
2014-10-06 17:03:18.428881 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:18.428881 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:18.428881 [DEBUG] sofia.c:6408 Channel
sofia/internal/sip:1004 at 192.168.1.34:5061 entering state
[proceeding][180]
2014-10-06 17:03:18.428881 [DEBUG] sofia.c:6486 gntel
sofia_handle_sip_i_state() callstate=3
2014-10-06 17:03:18.428881 [NOTICE] sofia.c:6499 Ring-Ready
sofia/internal/sip:1004 at 192.168.1.34:5061!
2014-10-06 17:03:18.428881 [DEBUG] switch_channel.c:3278
(sofia/internal/sip:1004 at 192.168.1.34:5061) Callstate Change DOWN ->
RINGING
2014-10-06 17:03:18.448789 [INFO] switch_ivr_originate.c:1192 Sending
early media
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:1199 gntel
switch_core_session_check_incoming_crypto() start
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:1214 looking
for crypto suite [AES_CM_256_HMAC_SHA1_80] in [1
AES_CM_128_HMAC_SHA1_80
inline:s2sm1JOsV7VwZN+qxPt3guw1XPeBf0ooRZ9bG3/L]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:1214 looking
for crypto suite [AES_CM_192_HMAC_SHA1_80] in [1
AES_CM_128_HMAC_SHA1_80
inline:s2sm1JOsV7VwZN+qxPt3guw1XPeBf0ooRZ9bG3/L]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:1214 looking
for crypto suite [AES_CM_128_HMAC_SHA1_80] in [1
AES_CM_128_HMAC_SHA1_80
inline:s2sm1JOsV7VwZN+qxPt3guw1XPeBf0ooRZ9bG3/L]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:1219 Found
suite AES_CM_128_HMAC_SHA1_80
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:1285 Set Remote
Key [1 AES_CM_128_HMAC_SHA1_80
inline:s2sm1JOsV7VwZN+qxPt3guw1XPeBf0ooRZ9bG3/L]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:947 Set Local
audio crypto Key [1 AES_CM_128_HMAC_SHA1_80
inline:ayoE/4XxfpL8K74wxpjvrRlWqaDG/c4Mq2POEPYR]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3565 Audio
Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3565 Audio
Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [G729:18:8000:20:8000:1]/[GSM:3:8000:20:13200:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [X-nt-inforeq:111:8000:20:0:1]/[opus:116:48000:20:0:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [X-nt-inforeq:111:8000:20:0:1]/[G722:9:8000:20:64000:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [X-nt-inforeq:111:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [X-nt-inforeq:111:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [X-nt-inforeq:111:8000:20:0:1]/[GSM:3:8000:20:13200:1]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:2385 Set Codec
sofia/internal/1003 at 192.168.1.15:5061 PCMA/8000 20 ms 160 samples
64000 bits 1 channels
2014-10-06 17:03:18.448789 [DEBUG] switch_core_codec.c:111
sofia/internal/1003 at 192.168.1.15:5061 Original read codec set to
PCMA:8
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:3769 No 2833 in
SDP. Disable 2833 dtmf and switch to INFO
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:4976 AUDIO RTP
[sofia/internal/1003 at 192.168.1.15:5061] 192.168.1.15 port 24802 ->
192.168.1.33 port 23000 codec: 8 ms: 20
2014-10-06 17:03:18.448789 [DEBUG] switch_rtp.c:3399 Starting timer
[soft] 160 bytes per 20ms
2014-10-06 17:03:18.448789 [DEBUG] switch_core_media.c:1065 gntel
switch_core_session_apply_crypto() start
2014-10-06 17:03:18.448789 [INFO] switch_rtp.c:3217 Activating Audio
Secure RTP SEND
2014-10-06 17:03:18.448789 [INFO] switch_rtp.c:3195 Activating Audio
Secure RTP RECV
2014-10-06 17:03:18.448789 [DEBUG] switch_core_sqldb.c:2568 Secure
Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2014-10-06 17:03:18.448789 [DEBUG] switch_core_sqldb.c:2568 Secure
Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2014-10-06 17:03:18.448789 [NOTICE] sofia_media.c:94 Pre-Answer
sofia/internal/1003 at 192.168.1.15:5061!
2014-10-06 17:03:18.448789 [DEBUG] switch_channel.c:3400
(sofia/internal/1003 at 192.168.1.15:5061) Callstate Change RINGING ->
EARLY
2014-10-06 17:03:18.448789 [DEBUG] mod_sofia.c:2243 Ring SDP:
v=0
o=FreeSWITCH 1412557796 1412557797 IN IP4 192.168.1.15
s=FreeSWITCH
c=IN IP4 192.168.1.15
t=0 0
m=audio 24802 RTP/SAVP 8
a=rtpmap:8 PCMA/8000
a=ptime:20
a=sendrecv
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:ayoE/4XxfpL8K74wxpjvrRlWqaDG/c4Mq2POEPYR
2014-10-06 17:03:18.448789 [DEBUG] switch_core_session.c:907 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:18.448789 [DEBUG] switch_ivr_originate.c:1249 Raw
Codec Activation Success L16 at 8000hz 1 channel 20ms
2014-10-06 17:03:18.448789 [DEBUG] switch_core_codec.c:221
sofia/internal/1003 at 192.168.1.15:5061 Push codec L16:70
2014-10-06 17:03:18.448789 [DEBUG] switch_ivr_originate.c:1317 Play
Ringback Tone [%(2000,4000,440,480)]
2014-10-06 17:03:18.448789 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:18.468814 [DEBUG] sofia.c:6408 Channel
sofia/internal/1003 at 192.168.1.15:5061 entering state [early][183]
2014-10-06 17:03:18.468814 [DEBUG] sofia.c:6486 gntel
sofia_handle_sip_i_state() callstate=6
2014-10-06 17:03:18.788879 [DEBUG] switch_rtp.c:5659 Correct ip/port confirmed.
2014-10-06 17:03:20.708849 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:20.708849 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:20.708849 [DEBUG] sofia.c:6408 Channel
sofia/internal/sip:1004 at 192.168.1.34:5061 entering state
[completing][200]
2014-10-06 17:03:20.708849 [DEBUG] sofia.c:6418 Remote SDP:
v=0
o=LGEIPP 20106 20106 IN IP4 192.168.1.34
s=SIP Call
c=IN IP4 192.168.1.34
t=0 0
m=audio 23000 RTP/SAVP 8 111
a=rtpmap:8 PCMA/8000
a=rtpmap:111 X-nt-inforeq/8000
a=crypto:3 AES_CM_128_HMAC_SHA1_80
inline:xvzk27T4cmpIE/lqFAhHsbL24AVNiw/d0shTCp/B
2014-10-06 17:03:20.708849 [DEBUG] sofia.c:6486 gntel
sofia_handle_sip_i_state() callstate=4
2014-10-06 17:03:20.708849 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:20.708849 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:20.708849 [DEBUG] sofia.c:6408 Channel
sofia/internal/sip:1004 at 192.168.1.34:5061 entering state [ready][200]
2014-10-06 17:03:20.708849 [DEBUG] sofia.c:6486 gntel
sofia_handle_sip_i_state() callstate=8
2014-10-06 17:03:20.708849 [DEBUG] switch_core_media.c:1199 gntel
switch_core_session_check_incoming_crypto() start
2014-10-06 17:03:20.708849 [DEBUG] switch_core_media.c:1214 looking
for crypto suite [AES_CM_256_HMAC_SHA1_80] in [3
AES_CM_128_HMAC_SHA1_80
inline:xvzk27T4cmpIE/lqFAhHsbL24AVNiw/d0shTCp/B]
2014-10-06 17:03:20.708849 [DEBUG] switch_core_media.c:1214 looking
for crypto suite [AES_CM_192_HMAC_SHA1_80] in [3
AES_CM_128_HMAC_SHA1_80
inline:xvzk27T4cmpIE/lqFAhHsbL24AVNiw/d0shTCp/B]
2014-10-06 17:03:20.708849 [DEBUG] switch_core_media.c:1214 looking
for crypto suite [AES_CM_128_HMAC_SHA1_80] in [3
AES_CM_128_HMAC_SHA1_80
inline:xvzk27T4cmpIE/lqFAhHsbL24AVNiw/d0shTCp/B]
2014-10-06 17:03:20.708849 [DEBUG] switch_core_media.c:1219 Found
suite AES_CM_128_HMAC_SHA1_80
2014-10-06 17:03:20.708849 [DEBUG] switch_core_media.c:1285 Set Remote
Key [3 AES_CM_128_HMAC_SHA1_80
inline:xvzk27T4cmpIE/lqFAhHsbL24AVNiw/d0shTCp/B]
2014-10-06 17:03:20.708849 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2014-10-06 17:03:20.708849 [DEBUG] switch_core_media.c:3565 Audio
Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2014-10-06 17:03:20.708849 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2014-10-06 17:03:20.708849 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [X-nt-inforeq:111:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2014-10-06 17:03:20.708849 [DEBUG] switch_core_media.c:3510 Audio
Codec Compare [X-nt-inforeq:111:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2014-10-06 17:03:20.708849 [DEBUG] switch_core_media.c:2385 Set Codec
sofia/internal/sip:1004 at 192.168.1.34:5061 PCMA/8000 20 ms 160 samples
64000 bits 1 channels
2014-10-06 17:03:20.708849 [DEBUG] switch_core_codec.c:111
sofia/internal/sip:1004 at 192.168.1.34:5061 Original read codec set to
PCMA:8
2014-10-06 17:03:20.708849 [DEBUG] switch_core_media.c:3769 No 2833 in
SDP. Disable 2833 dtmf and switch to INFO
2014-10-06 17:03:20.708849 [DEBUG] switch_core_media.c:4976 AUDIO RTP
[sofia/internal/sip:1004 at 192.168.1.34:5061] 192.168.1.15 port 18376 ->
192.168.1.34 port 23000 codec: 8 ms: 20
2014-10-06 17:03:20.708849 [DEBUG] switch_rtp.c:3399 Starting timer
[soft] 160 bytes per 20ms
2014-10-06 17:03:20.708849 [DEBUG] switch_core_media.c:1065 gntel
switch_core_session_apply_crypto() start
2014-10-06 17:03:20.708849 [INFO] switch_rtp.c:3217 Activating Audio
Secure RTP SEND
2014-10-06 17:03:20.708849 [INFO] switch_rtp.c:3195 Activating Audio
Secure RTP RECV
2014-10-06 17:03:20.708849 [DEBUG] switch_core_sqldb.c:2568 Secure
Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2014-10-06 17:03:20.708849 [DEBUG] switch_core_sqldb.c:2568 Secure
Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2014-10-06 17:03:20.708849 [DEBUG] switch_channel.c:3636 Send signal
sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:20.708849 [NOTICE] sofia.c:7256 Channel
[sofia/internal/sip:1004 at 192.168.1.34:5061] has been answered
2014-10-06 17:03:20.708849 [DEBUG] switch_channel.c:3690
(sofia/internal/sip:1004 at 192.168.1.34:5061) Callstate Change RINGING
-> ACTIVE
2014-10-06 17:03:20.728814 [DEBUG] switch_core_codec.c:246
sofia/internal/1003 at 192.168.1.15:5061 Restore previous codec PCMA:8.
2014-10-06 17:03:20.728814 [DEBUG] mod_sofia.c:780 Local SDP
sofia/internal/1003 at 192.168.1.15:5061:
v=0
o=FreeSWITCH 1412557796 1412557798 IN IP4 192.168.1.15
s=FreeSWITCH
c=IN IP4 192.168.1.15
t=0 0
m=audio 24802 RTP/SAVP 8
a=rtpmap:8 PCMA/8000
a=ptime:20
a=sendrecv
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:ayoE/4XxfpL8K74wxpjvrRlWqaDG/c4Mq2POEPYR
2014-10-06 17:03:20.728814 [DEBUG] switch_core_session.c:907 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:20.728814 [NOTICE] switch_ivr_originate.c:3495
Channel [sofia/internal/1003 at 192.168.1.15:5061] has been answered
2014-10-06 17:03:20.728814 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:20.728814 [DEBUG] switch_channel.c:3690
(sofia/internal/1003 at 192.168.1.15:5061) Callstate Change EARLY ->
ACTIVE
2014-10-06 17:03:20.728814 [DEBUG] sofia.c:6408 Channel
sofia/internal/1003 at 192.168.1.15:5061 entering state [completed][200]
2014-10-06 17:03:20.728814 [DEBUG] sofia.c:6486 gntel
sofia_handle_sip_i_state() callstate=7
2014-10-06 17:03:20.728814 [DEBUG] switch_ivr_originate.c:3553
Originate Resulted in Success:
[sofia/internal/sip:1004 at 192.168.1.34:5061]
2014-10-06 17:03:20.728814 [DEBUG] switch_ivr_originate.c:3553
Originate Resulted in Success:
[sofia/internal/sip:1004 at 192.168.1.34:5061]
2014-10-06 17:03:20.728814 [DEBUG] switch_core_session.c:907 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:20.728814 [DEBUG] switch_core_session.c:907 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:20.728814 [DEBUG] switch_ivr_bridge.c:1465
(sofia/internal/sip:1004 at 192.168.1.34:5061) State Change
CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2014-10-06 17:03:20.728814 [DEBUG] switch_core_session.c:1387 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:20.728814 [DEBUG] switch_core_state_machine.c:474
(sofia/internal/sip:1004 at 192.168.1.34:5061) Running State Change
CS_EXCHANGE_MEDIA
2014-10-06 17:03:20.728814 [DEBUG] switch_core_state_machine.c:540
(sofia/internal/sip:1004 at 192.168.1.34:5061) State EXCHANGE_MEDIA
2014-10-06 17:03:20.728814 [DEBUG] mod_sofia.c:592 SOFIA EXCHANGE_MEDIA
2014-10-06 17:03:20.828861 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:20.828861 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:20.828861 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:20.848864 [DEBUG] sofia.c:6408 Channel
sofia/internal/1003 at 192.168.1.15:5061 entering state [ready][200]
2014-10-06 17:03:20.848864 [DEBUG] sofia.c:6486 gntel
sofia_handle_sip_i_state() callstate=8
2014-10-06 17:03:20.848864 [DEBUG] switch_core_session.c:969 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:20.848864 [DEBUG] switch_core_session.c:969 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:20.968851 [DEBUG] switch_rtp.c:5659 Correct ip/port confirmed.
2014-10-06 17:03:22.908880 [DEBUG] switch_core_session.c:1052 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:22.908880 [NOTICE] sofia.c:947 Hangup
sofia/internal/sip:1004 at 192.168.1.34:5061 [CS_EXCHANGE_MEDIA]
[NORMAL_CLEARING]
2014-10-06 17:03:22.908880 [DEBUG] switch_channel.c:3222 Send signal
sofia/internal/sip:1004 at 192.168.1.34:5061 [KILL]
2014-10-06 17:03:22.908880 [DEBUG] switch_core_session.c:1387 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:22.908880 [DEBUG] switch_ivr_bridge.c:660 BRIDGE
THREAD DONE [sofia/internal/sip:1004 at 192.168.1.34:5061]
2014-10-06 17:03:22.908880 [DEBUG] switch_ivr_bridge.c:690 Send signal
sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:22.908880 [DEBUG] switch_core_state_machine.c:540
(sofia/internal/sip:1004 at 192.168.1.34:5061) State EXCHANGE_MEDIA going
to sleep
2014-10-06 17:03:22.908880 [DEBUG] switch_core_state_machine.c:474
(sofia/internal/sip:1004 at 192.168.1.34:5061) Running State Change
CS_HANGUP
2014-10-06 17:03:22.908880 [DEBUG] switch_core_state_machine.c:737
(sofia/internal/sip:1004 at 192.168.1.34:5061) Callstate Change ACTIVE ->
HANGUP
2014-10-06 17:03:22.908880 [DEBUG] switch_core_state_machine.c:739
(sofia/internal/sip:1004 at 192.168.1.34:5061) State HANGUP
2014-10-06 17:03:22.908880 [DEBUG] mod_sofia.c:413 Channel
sofia/internal/sip:1004 at 192.168.1.34:5061 hanging up, cause:
NORMAL_CLEARING
2014-10-06 17:03:22.908880 [DEBUG] switch_core_state_machine.c:60
sofia/internal/sip:1004 at 192.168.1.34:5061 Standard HANGUP, cause:
NORMAL_CLEARING
2014-10-06 17:03:22.908880 [DEBUG] switch_core_state_machine.c:739
(sofia/internal/sip:1004 at 192.168.1.34:5061) State HANGUP going to
sleep
2014-10-06 17:03:22.908880 [DEBUG] switch_core_state_machine.c:506
(sofia/internal/sip:1004 at 192.168.1.34:5061) State Change CS_HANGUP ->
CS_REPORTING
2014-10-06 17:03:22.908880 [DEBUG] switch_core_session.c:1387 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:22.908880 [DEBUG] switch_core_state_machine.c:474
(sofia/internal/sip:1004 at 192.168.1.34:5061) Running State Change
CS_REPORTING
2014-10-06 17:03:22.908880 [DEBUG] switch_core_state_machine.c:825
(sofia/internal/sip:1004 at 192.168.1.34:5061) State REPORTING
2014-10-06 17:03:22.908880 [DEBUG] switch_core_state_machine.c:104
sofia/internal/sip:1004 at 192.168.1.34:5061 Standard REPORTING, cause:
NORMAL_CLEARING
2014-10-06 17:03:22.908880 [DEBUG] switch_core_state_machine.c:825
(sofia/internal/sip:1004 at 192.168.1.34:5061) State REPORTING going to
sleep
2014-10-06 17:03:22.908880 [DEBUG] switch_core_state_machine.c:500
(sofia/internal/sip:1004 at 192.168.1.34:5061) State Change CS_REPORTING
-> CS_DESTROY
2014-10-06 17:03:22.908880 [DEBUG] switch_core_session.c:1387 Send
signal sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:22.908880 [DEBUG] switch_core_session.c:1614 Session
2 (sofia/internal/sip:1004 at 192.168.1.34:5061) Locked, Waiting on
external entities
2014-10-06 17:03:22.928833 [DEBUG] switch_ivr_bridge.c:579
sofia/internal/sip:1004 at 192.168.1.34:5061 ending bridge by request
from write function
2014-10-06 17:03:22.928833 [DEBUG] switch_ivr_bridge.c:660 BRIDGE
THREAD DONE [sofia/internal/1003 at 192.168.1.15:5061]
2014-10-06 17:03:22.928833 [DEBUG] switch_ivr_bridge.c:690 Send signal
sofia/internal/sip:1004 at 192.168.1.34:5061 [BREAK]
2014-10-06 17:03:22.928833 [DEBUG] switch_core_session.c:907 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:22.928833 [NOTICE] switch_ivr_bridge.c:1608 Hangup
sofia/internal/1003 at 192.168.1.15:5061 [CS_EXECUTE] [NORMAL_CLEARING]
2014-10-06 17:03:22.928833 [DEBUG] switch_channel.c:3222 Send signal
sofia/internal/1003 at 192.168.1.15:5061 [KILL]
2014-10-06 17:03:22.928833 [DEBUG] switch_core_session.c:1387 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:22.928833 [NOTICE] switch_core_session.c:1632 Session
2 (sofia/internal/sip:1004 at 192.168.1.34:5061) Ended
2014-10-06 17:03:22.928833 [NOTICE] switch_core_session.c:1636 Close
Channel sofia/internal/sip:1004 at 192.168.1.34:5061 [CS_DESTROY]
2014-10-06 17:03:22.928833 [DEBUG] switch_core_session.c:2887
sofia/internal/1003 at 192.168.1.15:5061 skip receive message
[APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:537
(sofia/internal/1003 at 192.168.1.15:5061) State EXECUTE going to sleep
2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:474
(sofia/internal/1003 at 192.168.1.15:5061) Running State Change CS_HANGUP
2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:628
(sofia/internal/sip:1004 at 192.168.1.34:5061) Running State Change
CS_DESTROY
2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:737
(sofia/internal/1003 at 192.168.1.15:5061) Callstate Change ACTIVE ->
HANGUP
2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:638
(sofia/internal/sip:1004 at 192.168.1.34:5061) State DESTROY
2014-10-06 17:03:22.928833 [DEBUG] mod_sofia.c:323
sofia/internal/sip:1004 at 192.168.1.34:5061 SOFIA DESTROY
2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:111
sofia/internal/sip:1004 at 192.168.1.34:5061 Standard DESTROY
2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:638
(sofia/internal/sip:1004 at 192.168.1.34:5061) State DESTROY going to
sleep
2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:739
(sofia/internal/1003 at 192.168.1.15:5061) State HANGUP
2014-10-06 17:03:22.928833 [DEBUG] mod_sofia.c:407
sofia/internal/1003 at 192.168.1.15:5061 Overriding SIP cause 480 with
200 from the other leg
2014-10-06 17:03:22.928833 [DEBUG] mod_sofia.c:413 Channel
sofia/internal/1003 at 192.168.1.15:5061 hanging up, cause:
NORMAL_CLEARING
2014-10-06 17:03:22.928833 [DEBUG] mod_sofia.c:465 Sending BYE to
sofia/internal/1003 at 192.168.1.15:5061
2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:60
sofia/internal/1003 at 192.168.1.15:5061 Standard HANGUP, cause:
NORMAL_CLEARING
2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:739
(sofia/internal/1003 at 192.168.1.15:5061) State HANGUP going to sleep
2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:506
(sofia/internal/1003 at 192.168.1.15:5061) State Change CS_HANGUP ->
CS_REPORTING
2014-10-06 17:03:22.928833 [DEBUG] switch_core_session.c:1387 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:474
(sofia/internal/1003 at 192.168.1.15:5061) Running State Change
CS_REPORTING
2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:825
(sofia/internal/1003 at 192.168.1.15:5061) State REPORTING
2014-10-06 17:03:22.948827 [DEBUG] switch_core_state_machine.c:104
sofia/internal/1003 at 192.168.1.15:5061 Standard REPORTING, cause:
NORMAL_CLEARING
2014-10-06 17:03:22.948827 [DEBUG] switch_core_state_machine.c:825
(sofia/internal/1003 at 192.168.1.15:5061) State REPORTING going to sleep
2014-10-06 17:03:22.948827 [DEBUG] switch_core_state_machine.c:500
(sofia/internal/1003 at 192.168.1.15:5061) State Change CS_REPORTING ->
CS_DESTROY
2014-10-06 17:03:22.948827 [DEBUG] switch_core_session.c:1387 Send
signal sofia/internal/1003 at 192.168.1.15:5061 [BREAK]
2014-10-06 17:03:22.948827 [DEBUG] switch_core_session.c:1614 Session
1 (sofia/internal/1003 at 192.168.1.15:5061) Locked, Waiting on external
entities
2014-10-06 17:03:22.948827 [NOTICE] switch_core_session.c:1632 Session
1 (sofia/internal/1003 at 192.168.1.15:5061) Ended
2014-10-06 17:03:22.948827 [NOTICE] switch_core_session.c:1636 Close
Channel sofia/internal/1003 at 192.168.1.15:5061 [CS_DESTROY]
2014-10-06 17:03:22.948827 [DEBUG] switch_core_state_machine.c:628
(sofia/internal/1003 at 192.168.1.15:5061) Running State Change
CS_DESTROY
2014-10-06 17:03:22.948827 [DEBUG] switch_core_state_machine.c:638
(sofia/internal/1003 at 192.168.1.15:5061) State DESTROY
2014-10-06 17:03:22.948827 [DEBUG] mod_sofia.c:323
sofia/internal/1003 at 192.168.1.15:5061 SOFIA DESTROY
2014-10-06 17:03:22.948827 [DEBUG] switch_core_state_machine.c:111
sofia/internal/1003 at 192.168.1.15:5061 Standard DESTROY
2014-10-06 17:03:22.948827 [DEBUG] switch_core_state_machine.c:638
(sofia/internal/1003 at 192.168.1.15:5061) State DESTROY going to sleep
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20141006/959829cf/attachment-0001.html
Join us at ClueCon 2016 Aug 8-12, 2016
More information about the FreeSWITCH-users
mailing list