[Freeswitch-users] doesn't send INVITE to callee with TLS on FreeSWITCH

Mon Oct 6 16:58:35 MSD 2014

What devices are involved? Also your endpoint MUST register its contact
with transport=tls if it cares to get a call back over TLS, remember
FreeSWITCH isn't a proxy, its a b2bua.  Also please don't post logs like
this use pastebin and post those links in your messages.

'sofia status profile internal reg' shows?

On Mon, Oct 6, 2014 at 3:05 AM, Herold Park <heroldpark at gmail.com> wrote:

> 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
>
>
>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at freeswitch.org
> http://www.freeswitchsolutions.com
>
> Official FreeSWITCH Sites
> http://www.freeswitch.org
> http://confluence.freeswitch.org
> http://www.cluecon.com
>
> 
> 
>
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>

-- 

*Brian West*
brian at freeswitch.org

*Twitter: @FreeSWITCH , @briankwest*
http://www.freeswitchbook.com
http://www.freeswitchcookbook.com

*T:*+19184209001 | *F:*+19184209002 | *M:*+1918424WEST (9378)
*iNUM:*+883 5100 1420 9001 | *ISN:*410*543 | *Skype:*briankwest
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20141006/373ef12b/attachment-0001.html 