Re: [Freeswitch-users] FreeSWITCH-users Digest, Vol 100, Issue 18
sorry, i missed that i watched on the wireshark with certificated key for TLS decryption. FS send TLS packet to the callee, but decrypted SIP/SDP packet doesn't show on the wireshark. freeswitch@internal> sofia status profile internal reg Registrations: ================================================================================================= Call-ID: 3130303300-aabb-709316c9-b4edcbc2199-0-663290f2@192.168.1.33 User: 1003@192.168.1.15 Contact: "1003" <sip:1003@192.168.1.33:5061;transport=TLS> Agent: LG-Ericsson IP8830E v1.1.01scm_1 SN/B40EDCBC2199 Status: Registered(TLS)(unknown) EXP(2014-10-07 09:52:28) EXPSECS(1870) Host: rnd.gntel.com IP: 192.168.1.33 Port: 4738 Auth-User: 1003 Auth-Realm: 192.168.1.15 MWI-Account: 1003@192.168.1.15 Call-ID: 3130303400-aabb-609294e8-b4edcc2f266-0-3831178a@192.168.1.34 User: 1004@192.168.1.15 Contact: "1004" <sip:1004@192.168.1.34:5061;transport=TLS> Agent: LG-Ericsson IP8830E v1.1.01scm_1 SN/B40EDCC2F266 Status: Registered(TLS)(unknown) EXP(2014-10-07 09:53:38) EXPSECS(1940) Host: rnd.gntel.com IP: 192.168.1.34 Port: 4134 Auth-User: 1004 Auth-Realm: 192.168.1.15 MWI-Account: 1004@192.168.1.15 Total items returned: 2 ================================================================================================= 2014-10-06 21:59 GMT+09:00 <freeswitch-users-request@lists.freeswitch.org>:
Send FreeSWITCH-users mailing list submissions to freeswitch-users@lists.freeswitch.org
To subscribe or unsubscribe via the World Wide Web, visit http://lists.freeswitch.org/mailman/listinfo/freeswitch-users or, via email, send a message with subject or body 'help' to freeswitch-users-request@lists.freeswitch.org
You can reach the person managing the list at freeswitch-users-owner@lists.freeswitch.org
When replying, please edit your Subject line so it is more specific than "Re: Contents of FreeSWITCH-users digest..."
Today's Topics:
1. Re: doesn't send INVITE to callee with TLS on FreeSWITCH (Brian West)
---------- 전달된 메시지 ---------- From: Brian West <brian@freeswitch.org> To: FreeSWITCH Users Help <freeswitch-users@lists.freeswitch.org> Cc: Date: Mon, 6 Oct 2014 07:58:35 -0500 Subject: Re: [Freeswitch-users] doesn't send INVITE to callee with TLS on FreeSWITCH 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@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@internal> 2014-10-06 17:03:17.908850 [NOTICE] switch_channel.c:1055 New Channel sofia/internal/1003@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:17.908850 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/1003@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:17.908850 [DEBUG] switch_core_state_machine.c:474 (sofia/internal/1003@192.168.1.15:5061) Running State Change CS_NEW 2014-10-06 17:03:17.928869 [DEBUG] sofia.c:8590 sofia/internal/1003@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@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@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:18.048881 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/1003@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:18.068869 [DEBUG] sofia.c:8590 sofia/internal/1003@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@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@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:474 (sofia/internal/1003@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@192.168.1.15:5061) State INIT 2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:87 sofia/internal/1003@192.168.1.15:5061 SOFIA INIT 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1003@192.168.1.15:5061 Standard INIT 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1003@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:514 (sofia/internal/1003@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@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@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@192.168.1.15:5061) State ROUTING 2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:123 sofia/internal/1003@192.168.1.15:5061 SOFIA ROUTING 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:166 sofia/internal/1003@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@192.168.1.15:5061 parsing [default->unloop] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->tod_example] continue=true Dialplan: sofia/internal/1003@192.168.1.15:5061 Date/Time Match (PASS) [tod_example] break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 Action set(open=true) Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->holiday_example] continue=true Dialplan: sofia/internal/1003@192.168.1.15:5061 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->global-intercept] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [global-intercept] destination_number(1004) =~ /^886$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->group-intercept] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [group-intercept] destination_number(1004) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [intercept-ext] destination_number(1004) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->redial] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [redial] destination_number(1004) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->global] continue=true Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1003@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@192.168.1.15:5061 Action set(rtp_secure_media=true) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action export(rtp_secure_media=true) Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: sofia/internal/1003@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@192.168.1.15:5061 Action set(rtp_secure_media=true) Dialplan: sofia/internal/1003@192.168.1.15:5061 Absolute Condition [global] Dialplan: sofia/internal/1003@192.168.1.15:5061 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->snom-demo-2] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [snom-demo-2] destination_number(1004) =~ /^9001$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->snom-demo-1] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [snom-demo-1] destination_number(1004) =~ /^9000$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [eavesdrop] destination_number(1004) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [eavesdrop] destination_number(1004) =~ /^779$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->call_return] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [call_return] destination_number(1004) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->del-group] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [del-group] destination_number(1004) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->add-group] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [add-group] destination_number(1004) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [call-group-simo] destination_number(1004) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->call-group-order] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [call-group-order] destination_number(1004) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->extension-intercom] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [extension-intercom] destination_number(1004) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->Local_Extension] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (PASS) [Local_Extension] destination_number(1004) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 Action export(dialed_extension=1004) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: sofia/internal/1003@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@192.168.1.15:5061 Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action set(ringback=${us-ring}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action set(transfer_ringback=local_stream://moh) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action set(call_timeout=30) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action set(hangup_after_bridge=true) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action set(continue_on_fail=true) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action bridge(user/${dialed_extension}@${domain_name}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action answer() Dialplan: sofia/internal/1003@192.168.1.15:5061 Action sleep(1000) Dialplan: sofia/internal/1003@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@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:530 (sofia/internal/1003@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@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@192.168.1.15:5061) State EXECUTE 2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:178 sofia/internal/1003@192.168.1.15:5061 SOFIA EXECUTE 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:260 sofia/internal/1003@192.168.1.15:5061 Standard EXECUTE EXECUTE sofia/internal/1003@192.168.1.15:5061 set(open=true) 2014-10-06 17:03:18.068869 [DEBUG] mod_dptools.c:1435 sofia/internal/1003@192.168.1.15:5061 SET [open]=[true] EXECUTE sofia/internal/1003@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@192.168.1.15:5061 SET [rtp_secure_media]=[true] EXECUTE sofia/internal/1003@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@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@192.168.1.15:5061 SET [rtp_secure_media]=[true] EXECUTE sofia/internal/1003@192.168.1.15:5061 hash(insert/192.168.1.15-spymap/1003/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8) EXECUTE sofia/internal/1003@192.168.1.15:5061 hash(insert/192.168.1.15-last_dial/1003/1004) EXECUTE sofia/internal/1003@192.168.1.15:5061 hash(insert/192.168.1.15-last_dial/global/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8) EXECUTE sofia/internal/1003@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@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@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@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@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@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@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@192.168.1.15:5061 SET [ringback]=[%(2000,4000,440,480)] EXECUTE sofia/internal/1003@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@192.168.1.15:5061 SET [transfer_ringback]=[local_stream://moh] EXECUTE sofia/internal/1003@192.168.1.15:5061 set(call_timeout=30) 2014-10-06 17:03:18.068869 [DEBUG] mod_dptools.c:1435 sofia/internal/1003@192.168.1.15:5061 SET [call_timeout]=[30] EXECUTE sofia/internal/1003@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@192.168.1.15:5061 SET [hangup_after_bridge]=[true] EXECUTE sofia/internal/1003@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@192.168.1.15:5061 SET [continue_on_fail]=[true] EXECUTE sofia/internal/1003@192.168.1.15:5061 hash(insert/192.168.1.15-call_return/1004/1003) EXECUTE sofia/internal/1003@192.168.1.15:5061 hash(insert/192.168.1.15-last_dial_ext/1004/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8) EXECUTE sofia/internal/1003@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@192.168.1.15:5061 SET [called_party_callgroup]=[techsupport] EXECUTE sofia/internal/1003@192.168.1.15:5061 hash(insert/192.168.1.15-last_dial_ext/techsupport/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8) EXECUTE sofia/internal/1003@192.168.1.15:5061 hash(insert/192.168.1.15-last_dial_ext/global/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8) EXECUTE sofia/internal/1003@192.168.1.15:5061 hash(insert/192.168.1.15-last_dial/techsupport/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8) EXECUTE sofia/internal/1003@192.168.1.15:5061 bridge(user/1004@192.168.1.15) 2014-10-06 17:03:18.068869 [DEBUG] switch_channel.c:1201 sofia/internal/1003@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@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@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@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@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@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@192.168.1.15] 2014-10-06 17:03:18.068869 [NOTICE] switch_channel.c:1055 New Channel sofia/internal/sip:1004@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@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@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@8000h@20i@64000b,PCMU@8000h@20i@64000b,PCMA@8000h@20i@64000b,PCMU@8000h@20i@64000b' 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:474 (sofia/internal/sip:1004@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@192.168.1.34:5061) State INIT 2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:87 sofia/internal/sip:1004@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@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@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@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:514 (sofia/internal/sip:1004@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@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@192.168.1.34:5061) State ROUTING 2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:123 sofia/internal/sip:1004@192.168.1.34:5061 SOFIA ROUTING 2014-10-06 17:03:18.068869 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/sip:1004@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:530 (sofia/internal/sip:1004@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:18.088801 [DEBUG] switch_core_state_machine.c:474 (sofia/internal/sip:1004@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@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@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@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@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:18.428881 [DEBUG] sofia.c:6408 Channel sofia/internal/sip:1004@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@192.168.1.34:5061! 2014-10-06 17:03:18.428881 [DEBUG] switch_channel.c:3278 (sofia/internal/sip:1004@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@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@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@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@192.168.1.15:5061! 2014-10-06 17:03:18.448789 [DEBUG] switch_channel.c:3400 (sofia/internal/1003@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:18.448789 [DEBUG] switch_ivr_originate.c:1249 Raw Codec Activation Success L16@8000hz 1 channel 20ms 2014-10-06 17:03:18.448789 [DEBUG] switch_core_codec.c:221 sofia/internal/1003@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:18.468814 [DEBUG] sofia.c:6408 Channel sofia/internal/1003@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@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:20.708849 [DEBUG] sofia.c:6408 Channel sofia/internal/sip:1004@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@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:20.708849 [DEBUG] sofia.c:6408 Channel sofia/internal/sip:1004@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@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@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@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:20.708849 [NOTICE] sofia.c:7256 Channel [sofia/internal/sip:1004@192.168.1.34:5061] has been answered 2014-10-06 17:03:20.708849 [DEBUG] switch_channel.c:3690 (sofia/internal/sip:1004@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@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@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:20.728814 [NOTICE] switch_ivr_originate.c:3495 Channel [sofia/internal/1003@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:20.728814 [DEBUG] switch_channel.c:3690 (sofia/internal/1003@192.168.1.15:5061) Callstate Change EARLY -> ACTIVE 2014-10-06 17:03:20.728814 [DEBUG] sofia.c:6408 Channel sofia/internal/1003@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@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@192.168.1.34:5061] 2014-10-06 17:03:20.728814 [DEBUG] switch_core_session.c:907 Send signal sofia/internal/sip:1004@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:20.728814 [DEBUG] switch_core_session.c:907 Send signal sofia/internal/1003@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:20.728814 [DEBUG] switch_ivr_bridge.c:1465 (sofia/internal/sip:1004@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:20.728814 [DEBUG] switch_core_state_machine.c:474 (sofia/internal/sip:1004@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@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:20.828861 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/1003@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:20.828861 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/1003@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:20.848864 [DEBUG] sofia.c:6408 Channel sofia/internal/1003@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:20.848864 [DEBUG] switch_core_session.c:969 Send signal sofia/internal/1003@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:22.908880 [NOTICE] sofia.c:947 Hangup sofia/internal/sip:1004@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@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@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@192.168.1.34:5061] 2014-10-06 17:03:22.908880 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/internal/1003@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:22.908880 [DEBUG] switch_core_state_machine.c:540 (sofia/internal/sip:1004@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@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@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@192.168.1.34:5061) State HANGUP 2014-10-06 17:03:22.908880 [DEBUG] mod_sofia.c:413 Channel sofia/internal/sip:1004@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@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@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@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:22.908880 [DEBUG] switch_core_state_machine.c:474 (sofia/internal/sip:1004@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@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@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@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@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@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@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@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@192.168.1.15:5061] 2014-10-06 17:03:22.928833 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/internal/sip:1004@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:22.928833 [DEBUG] switch_core_session.c:907 Send signal sofia/internal/1003@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:22.928833 [NOTICE] switch_ivr_bridge.c:1608 Hangup sofia/internal/1003@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@192.168.1.15:5061 [KILL] 2014-10-06 17:03:22.928833 [DEBUG] switch_core_session.c:1387 Send signal sofia/internal/1003@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@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@192.168.1.34:5061 [CS_DESTROY] 2014-10-06 17:03:22.928833 [DEBUG] switch_core_session.c:2887 sofia/internal/1003@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@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@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@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@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@192.168.1.34:5061) State DESTROY 2014-10-06 17:03:22.928833 [DEBUG] mod_sofia.c:323 sofia/internal/sip:1004@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@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@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@192.168.1.15:5061) State HANGUP 2014-10-06 17:03:22.928833 [DEBUG] mod_sofia.c:407 sofia/internal/1003@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@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@192.168.1.15:5061 2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1003@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@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@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:474 (sofia/internal/1003@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@192.168.1.15:5061) State REPORTING 2014-10-06 17:03:22.948827 [DEBUG] switch_core_state_machine.c:104 sofia/internal/1003@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@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@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:22.948827 [DEBUG] switch_core_session.c:1614 Session 1 (sofia/internal/1003@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@192.168.1.15:5061) Ended 2014-10-06 17:03:22.948827 [NOTICE] switch_core_session.c:1636 Close Channel sofia/internal/1003@192.168.1.15:5061 [CS_DESTROY] 2014-10-06 17:03:22.948827 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1003@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@192.168.1.15:5061) State DESTROY 2014-10-06 17:03:22.948827 [DEBUG] mod_sofia.c:323 sofia/internal/1003@192.168.1.15:5061 SOFIA DESTROY 2014-10-06 17:03:22.948827 [DEBUG] switch_core_state_machine.c:111 sofia/internal/1003@192.168.1.15:5061 Standard DESTROY 2014-10-06 17:03:22.948827 [DEBUG] switch_core_state_machine.c:638 (sofia/internal/1003@192.168.1.15:5061) State DESTROY going to sleep
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
FreeSWITCH-users mailing list FreeSWITCH-users@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@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
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- 세상은 아름답다.
What you've just said makes no sense, the SDP won't be decrypted, thats kinda the point it holds the SRTP key. On Mon, Oct 6, 2014 at 7:31 PM, Herold Park <heroldpark@gmail.com> wrote:
sorry, i missed that i watched on the wireshark with certificated key for TLS decryption.
FS send TLS packet to the callee, but decrypted SIP/SDP packet doesn't show on the wireshark.
freeswitch@internal> sofia status profile internal reg
Registrations:
================================================================================================= Call-ID: 3130303300-aabb-709316c9-b4edcbc2199-0-663290f2@192.168.1.33 User: 1003@192.168.1.15 Contact: "1003" <sip:1003@192.168.1.33:5061;transport=TLS> Agent: LG-Ericsson IP8830E v1.1.01scm_1 SN/B40EDCBC2199 Status: Registered(TLS)(unknown) EXP(2014-10-07 09:52:28) EXPSECS(1870) Host: rnd.gntel.com IP: 192.168.1.33 Port: 4738 Auth-User: 1003 Auth-Realm: 192.168.1.15 MWI-Account: 1003@192.168.1.15
Call-ID: 3130303400-aabb-609294e8-b4edcc2f266-0-3831178a@192.168.1.34 User: 1004@192.168.1.15 Contact: "1004" <sip:1004@192.168.1.34:5061;transport=TLS> Agent: LG-Ericsson IP8830E v1.1.01scm_1 SN/B40EDCC2F266 Status: Registered(TLS)(unknown) EXP(2014-10-07 09:53:38) EXPSECS(1940) Host: rnd.gntel.com IP: 192.168.1.34 Port: 4134 Auth-User: 1004 Auth-Realm: 192.168.1.15 MWI-Account: 1004@192.168.1.15
Total items returned: 2
=================================================================================================
2014-10-06 21:59 GMT+09:00 <freeswitch-users-request@lists.freeswitch.org> :
Send FreeSWITCH-users mailing list submissions to freeswitch-users@lists.freeswitch.org
To subscribe or unsubscribe via the World Wide Web, visit http://lists.freeswitch.org/mailman/listinfo/freeswitch-users or, via email, send a message with subject or body 'help' to freeswitch-users-request@lists.freeswitch.org
You can reach the person managing the list at freeswitch-users-owner@lists.freeswitch.org
When replying, please edit your Subject line so it is more specific than "Re: Contents of FreeSWITCH-users digest..."
Today's Topics:
1. Re: doesn't send INVITE to callee with TLS on FreeSWITCH (Brian West)
---------- 전달된 메시지 ---------- From: Brian West <brian@freeswitch.org> To: FreeSWITCH Users Help <freeswitch-users@lists.freeswitch.org> Cc: Date: Mon, 6 Oct 2014 07:58:35 -0500 Subject: Re: [Freeswitch-users] doesn't send INVITE to callee with TLS on FreeSWITCH 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@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@internal> 2014-10-06 17:03:17.908850 [NOTICE] switch_channel.c:1055 New Channel sofia/internal/1003@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:17.908850 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/1003@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:17.908850 [DEBUG] switch_core_state_machine.c:474 (sofia/internal/1003@192.168.1.15:5061) Running State Change CS_NEW 2014-10-06 17:03:17.928869 [DEBUG] sofia.c:8590 sofia/internal/1003@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@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@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:18.048881 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/1003@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:18.068869 [DEBUG] sofia.c:8590 sofia/internal/1003@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@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@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:474 (sofia/internal/1003@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@192.168.1.15:5061) State INIT 2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:87 sofia/internal/1003@192.168.1.15:5061 SOFIA INIT 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1003@192.168.1.15:5061 Standard INIT 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1003@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:514 (sofia/internal/1003@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@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@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@192.168.1.15:5061) State ROUTING 2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:123 sofia/internal/1003@192.168.1.15:5061 SOFIA ROUTING 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:166 sofia/internal/1003@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@192.168.1.15:5061 parsing [default->unloop] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->tod_example] continue=true Dialplan: sofia/internal/1003@192.168.1.15:5061 Date/Time Match (PASS) [tod_example] break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 Action set(open=true) Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->holiday_example] continue=true Dialplan: sofia/internal/1003@192.168.1.15:5061 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->global-intercept] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [global-intercept] destination_number(1004) =~ /^886$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->group-intercept] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [group-intercept] destination_number(1004) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [intercept-ext] destination_number(1004) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->redial] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [redial] destination_number(1004) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->global] continue=true Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1003@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@192.168.1.15:5061 Action set(rtp_secure_media=true) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action export(rtp_secure_media=true) Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: sofia/internal/1003@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@192.168.1.15:5061 Action set(rtp_secure_media=true) Dialplan: sofia/internal/1003@192.168.1.15:5061 Absolute Condition [global] Dialplan: sofia/internal/1003@192.168.1.15:5061 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->snom-demo-2] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [snom-demo-2] destination_number(1004) =~ /^9001$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->snom-demo-1] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [snom-demo-1] destination_number(1004) =~ /^9000$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [eavesdrop] destination_number(1004) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [eavesdrop] destination_number(1004) =~ /^779$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->call_return] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [call_return] destination_number(1004) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->del-group] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [del-group] destination_number(1004) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->add-group] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [add-group] destination_number(1004) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [call-group-simo] destination_number(1004) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->call-group-order] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [call-group-order] destination_number(1004) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->extension-intercom] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (FAIL) [extension-intercom] destination_number(1004) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 parsing [default->Local_Extension] continue=false Dialplan: sofia/internal/1003@192.168.1.15:5061 Regex (PASS) [Local_Extension] destination_number(1004) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1003@192.168.1.15:5061 Action export(dialed_extension=1004) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: sofia/internal/1003@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@192.168.1.15:5061 Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action set(ringback=${us-ring}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action set(transfer_ringback=local_stream://moh) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action set(call_timeout=30) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action set(hangup_after_bridge=true) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action set(continue_on_fail=true) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action bridge(user/${dialed_extension}@${domain_name}) Dialplan: sofia/internal/1003@192.168.1.15:5061 Action answer() Dialplan: sofia/internal/1003@192.168.1.15:5061 Action sleep(1000) Dialplan: sofia/internal/1003@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@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:530 (sofia/internal/1003@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@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@192.168.1.15:5061) State EXECUTE 2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:178 sofia/internal/1003@192.168.1.15:5061 SOFIA EXECUTE 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:260 sofia/internal/1003@192.168.1.15:5061 Standard EXECUTE EXECUTE sofia/internal/1003@192.168.1.15:5061 set(open=true) 2014-10-06 17:03:18.068869 [DEBUG] mod_dptools.c:1435 sofia/internal/1003@192.168.1.15:5061 SET [open]=[true] EXECUTE sofia/internal/1003@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@192.168.1.15:5061 SET [rtp_secure_media]=[true] EXECUTE sofia/internal/1003@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@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@192.168.1.15:5061 SET [rtp_secure_media]=[true] EXECUTE sofia/internal/1003@192.168.1.15:5061 hash(insert/192.168.1.15-spymap/1003/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8) EXECUTE sofia/internal/1003@192.168.1.15:5061 hash(insert/192.168.1.15-last_dial/1003/1004) EXECUTE sofia/internal/1003@192.168.1.15:5061 hash(insert/192.168.1.15-last_dial/global/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8) EXECUTE sofia/internal/1003@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@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@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@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@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@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@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@192.168.1.15:5061 SET [ringback]=[%(2000,4000,440,480)] EXECUTE sofia/internal/1003@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@192.168.1.15:5061 SET [transfer_ringback]=[local_stream://moh] EXECUTE sofia/internal/1003@192.168.1.15:5061 set(call_timeout=30) 2014-10-06 17:03:18.068869 [DEBUG] mod_dptools.c:1435 sofia/internal/1003@192.168.1.15:5061 SET [call_timeout]=[30] EXECUTE sofia/internal/1003@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@192.168.1.15:5061 SET [hangup_after_bridge]=[true] EXECUTE sofia/internal/1003@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@192.168.1.15:5061 SET [continue_on_fail]=[true] EXECUTE sofia/internal/1003@192.168.1.15:5061 hash(insert/192.168.1.15-call_return/1004/1003) EXECUTE sofia/internal/1003@192.168.1.15:5061 hash(insert/192.168.1.15-last_dial_ext/1004/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8) EXECUTE sofia/internal/1003@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@192.168.1.15:5061 SET [called_party_callgroup]=[techsupport] EXECUTE sofia/internal/1003@192.168.1.15:5061 hash(insert/192.168.1.15-last_dial_ext/techsupport/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8) EXECUTE sofia/internal/1003@192.168.1.15:5061 hash(insert/192.168.1.15-last_dial_ext/global/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8) EXECUTE sofia/internal/1003@192.168.1.15:5061 hash(insert/192.168.1.15-last_dial/techsupport/8fc8ba3a-23b2-44e5-9cad-71a1a2524eb8) EXECUTE sofia/internal/1003@192.168.1.15:5061 bridge(user/1004@192.168.1.15) 2014-10-06 17:03:18.068869 [DEBUG] switch_channel.c:1201 sofia/internal/1003@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@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@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@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@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@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@192.168.1.15] 2014-10-06 17:03:18.068869 [NOTICE] switch_channel.c:1055 New Channel sofia/internal/sip:1004@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@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@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@8000h@20i@64000b,PCMU@8000h@20i@64000b,PCMA@8000h@20i@64000b,PCMU@8000h@20i@64000b' 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:474 (sofia/internal/sip:1004@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@192.168.1.34:5061) State INIT 2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:87 sofia/internal/sip:1004@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@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@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@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:514 (sofia/internal/sip:1004@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@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@192.168.1.34:5061) State ROUTING 2014-10-06 17:03:18.068869 [DEBUG] mod_sofia.c:123 sofia/internal/sip:1004@192.168.1.34:5061 SOFIA ROUTING 2014-10-06 17:03:18.068869 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/sip:1004@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:18.068869 [DEBUG] switch_core_state_machine.c:530 (sofia/internal/sip:1004@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:18.088801 [DEBUG] switch_core_state_machine.c:474 (sofia/internal/sip:1004@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@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@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@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@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:18.428881 [DEBUG] sofia.c:6408 Channel sofia/internal/sip:1004@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@192.168.1.34:5061! 2014-10-06 17:03:18.428881 [DEBUG] switch_channel.c:3278 (sofia/internal/sip:1004@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@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@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@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@192.168.1.15:5061! 2014-10-06 17:03:18.448789 [DEBUG] switch_channel.c:3400 (sofia/internal/1003@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:18.448789 [DEBUG] switch_ivr_originate.c:1249 Raw Codec Activation Success L16@8000hz 1 channel 20ms 2014-10-06 17:03:18.448789 [DEBUG] switch_core_codec.c:221 sofia/internal/1003@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:18.468814 [DEBUG] sofia.c:6408 Channel sofia/internal/1003@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@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:20.708849 [DEBUG] sofia.c:6408 Channel sofia/internal/sip:1004@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@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:20.708849 [DEBUG] sofia.c:6408 Channel sofia/internal/sip:1004@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@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@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@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:20.708849 [NOTICE] sofia.c:7256 Channel [sofia/internal/sip:1004@192.168.1.34:5061] has been answered 2014-10-06 17:03:20.708849 [DEBUG] switch_channel.c:3690 (sofia/internal/sip:1004@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@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@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:20.728814 [NOTICE] switch_ivr_originate.c:3495 Channel [sofia/internal/1003@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:20.728814 [DEBUG] switch_channel.c:3690 (sofia/internal/1003@192.168.1.15:5061) Callstate Change EARLY -> ACTIVE 2014-10-06 17:03:20.728814 [DEBUG] sofia.c:6408 Channel sofia/internal/1003@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@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@192.168.1.34:5061] 2014-10-06 17:03:20.728814 [DEBUG] switch_core_session.c:907 Send signal sofia/internal/sip:1004@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:20.728814 [DEBUG] switch_core_session.c:907 Send signal sofia/internal/1003@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:20.728814 [DEBUG] switch_ivr_bridge.c:1465 (sofia/internal/sip:1004@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:20.728814 [DEBUG] switch_core_state_machine.c:474 (sofia/internal/sip:1004@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@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:20.828861 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/1003@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:20.828861 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/1003@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:20.848864 [DEBUG] sofia.c:6408 Channel sofia/internal/1003@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:20.848864 [DEBUG] switch_core_session.c:969 Send signal sofia/internal/1003@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:22.908880 [NOTICE] sofia.c:947 Hangup sofia/internal/sip:1004@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@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@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@192.168.1.34:5061] 2014-10-06 17:03:22.908880 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/internal/1003@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:22.908880 [DEBUG] switch_core_state_machine.c:540 (sofia/internal/sip:1004@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@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@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@192.168.1.34:5061) State HANGUP 2014-10-06 17:03:22.908880 [DEBUG] mod_sofia.c:413 Channel sofia/internal/sip:1004@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@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@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@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@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:22.908880 [DEBUG] switch_core_state_machine.c:474 (sofia/internal/sip:1004@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@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@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@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@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@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@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@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@192.168.1.15:5061] 2014-10-06 17:03:22.928833 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/internal/sip:1004@192.168.1.34:5061 [BREAK] 2014-10-06 17:03:22.928833 [DEBUG] switch_core_session.c:907 Send signal sofia/internal/1003@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:22.928833 [NOTICE] switch_ivr_bridge.c:1608 Hangup sofia/internal/1003@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@192.168.1.15:5061 [KILL] 2014-10-06 17:03:22.928833 [DEBUG] switch_core_session.c:1387 Send signal sofia/internal/1003@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@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@192.168.1.34:5061 [CS_DESTROY] 2014-10-06 17:03:22.928833 [DEBUG] switch_core_session.c:2887 sofia/internal/1003@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@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@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@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@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@192.168.1.34:5061) State DESTROY 2014-10-06 17:03:22.928833 [DEBUG] mod_sofia.c:323 sofia/internal/sip:1004@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@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@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@192.168.1.15:5061) State HANGUP 2014-10-06 17:03:22.928833 [DEBUG] mod_sofia.c:407 sofia/internal/1003@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@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@192.168.1.15:5061 2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1003@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@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@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:22.928833 [DEBUG] switch_core_state_machine.c:474 (sofia/internal/1003@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@192.168.1.15:5061) State REPORTING 2014-10-06 17:03:22.948827 [DEBUG] switch_core_state_machine.c:104 sofia/internal/1003@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@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@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@192.168.1.15:5061 [BREAK] 2014-10-06 17:03:22.948827 [DEBUG] switch_core_session.c:1614 Session 1 (sofia/internal/1003@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@192.168.1.15:5061) Ended 2014-10-06 17:03:22.948827 [NOTICE] switch_core_session.c:1636 Close Channel sofia/internal/1003@192.168.1.15:5061 [CS_DESTROY] 2014-10-06 17:03:22.948827 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1003@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@192.168.1.15:5061) State DESTROY 2014-10-06 17:03:22.948827 [DEBUG] mod_sofia.c:323 sofia/internal/1003@192.168.1.15:5061 SOFIA DESTROY 2014-10-06 17:03:22.948827 [DEBUG] switch_core_state_machine.c:111 sofia/internal/1003@192.168.1.15:5061 Standard DESTROY 2014-10-06 17:03:22.948827 [DEBUG] switch_core_state_machine.c:638 (sofia/internal/1003@192.168.1.15:5061) State DESTROY going to sleep
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
FreeSWITCH-users mailing list FreeSWITCH-users@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@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
_______________________________________________ FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- 세상은 아름답다.
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
FreeSWITCH-users mailing list FreeSWITCH-users@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@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
participants (2)
-
Brian West
-
Herold Park