recv 1094 bytes from udp/[10.23.154.63]:6060 at 12:34:02.546373: ------------------------------------------------------------------------ INVITE sip:62987%23401077@10.23.154.100:6060 SIP/2.0 Via: SIP/2.0/UDP 10.23.154.63:6060;branch=z9hG4bKe129742e55e6 From: "IT, Юрьев Сергей" ;tag=193729~27154efa-6325-45a2-9e47-67e5d9302ebc-237774854 To: Date: Fri, 07 Oct 2016 09:34:02 GMT Call-ID: 2d3d2680-7f716c0a-c20e-3f40000a@10.23.154.63 Supported: 100rel,timer,resource-priority,replaces Min-SE: 1800 User-Agent: Cisco-CP7942G/9.3.1 Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY CSeq: 101 INVITE Expires: 180 Allow-Events: presence, kpml Supported: X-cisco-srtp-fallback,X-cisco-original-called Call-Info: ;method="NOTIFY;Event=telephone-event;Duration=500" Cisco-Guid: 0758982272-0000065536-0000045237-1061158922 Session-Expires: 1800 P-Asserted-Identity: "IT, Юрьев Сергей" Remote-Party-ID: "IT, Юрьев Сергей" ;party=calling;screen=yes;privacy=off Contact: Max-Forwards: 69 Content-Length: 0 ------------------------------------------------------------------------ send 407 bytes to udp/[10.23.154.63]:6060 at 12:34:02.546642: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.23.154.63:6060;branch=z9hG4bKe129742e55e6 From: "IT, Юрьев Сергей" ;tag=193729~27154efa-6325-45a2-9e47-67e5d9302ebc-237774854 To: Call-ID: 2d3d2680-7f716c0a-c20e-3f40000a@10.23.154.63 CSeq: 101 INVITE User-Agent: FreeSWITCH-mod_sofia/1.7.0+git~20160707T165535Z~be13536ac9~64bit Content-Length: 0 ------------------------------------------------------------------------ 2016-10-07 12:34:02.527575 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/12550@10.23.154.63 [2d3d2680-7f716c0a-c20e-3f40000a@10.23.154.63] 2016-10-07 12:34:02.527575 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/12550@10.23.154.63) Running State Change CS_NEW 2016-10-07 12:34:02.527575 [DEBUG] sofia.c:9519 sofia/internal/12550@10.23.154.63 receiving invite from 10.23.154.63:6060 version: 1.7.0 git be13536 2016-07-07 16:55:35Z 64bit 2016-10-07 12:34:02.527575 [DEBUG] sofia.c:9631 IP 10.23.154.63 Approved by acl "internal_unauth[]". Access Granted. 2016-10-07 12:34:02.527575 [DEBUG] sofia.c:6937 Channel sofia/internal/12550@10.23.154.63 entering state [received][100] 2016-10-07 12:34:02.527575 [DEBUG] sofia.c:7432 (sofia/internal/12550@10.23.154.63) State Change CS_NEW -> CS_INIT 2016-10-07 12:34:02.527575 [DEBUG] switch_core_state_machine.c:562 (sofia/internal/12550@10.23.154.63) State NEW 2016-10-07 12:34:02.527575 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/12550@10.23.154.63) Running State Change CS_INIT 2016-10-07 12:34:02.527575 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/12550@10.23.154.63) State INIT 2016-10-07 12:34:02.527575 [DEBUG] mod_sofia.c:90 sofia/internal/12550@10.23.154.63 SOFIA INIT 2016-10-07 12:34:02.527575 [DEBUG] switch_core_state_machine.c:40 sofia/internal/12550@10.23.154.63 Standard INIT 2016-10-07 12:34:02.527575 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/12550@10.23.154.63) State Change CS_INIT -> CS_ROUTING 2016-10-07 12:34:02.527575 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/12550@10.23.154.63) State INIT going to sleep 2016-10-07 12:34:02.527575 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/12550@10.23.154.63) Running State Change CS_ROUTING 2016-10-07 12:34:02.527575 [DEBUG] switch_channel.c:2249 (sofia/internal/12550@10.23.154.63) Callstate Change DOWN -> RINGING 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/12550@10.23.154.63) State ROUTING 2016-10-07 12:34:02.547569 [DEBUG] mod_sofia.c:143 sofia/internal/12550@10.23.154.63 SOFIA ROUTING 2016-10-07 12:34:02.547569 [ERR] mod_xml_radius.c:933 Result of true match: 10.23.154.100 == ^8\.8\.8\.8 2016-10-07 12:34:02.547569 [INFO] mod_xml_radius.c:986 mod_xml_radius: Accounting Start success 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:236 sofia/internal/12550@10.23.154.63 Standard ROUTING 2016-10-07 12:34:02.547569 [INFO] mod_dialplan_xml.c:637 Processing IT, Юрьев Сергей <12550>->62987#401077 in context public Dialplan: sofia/internal/12550@10.23.154.63 parsing [public->common_variables] continue=true Dialplan: sofia/internal/12550@10.23.154.63 Absolute Condition [common_variables] Dialplan: sofia/internal/12550@10.23.154.63 Action set(default_language=en) Dialplan: sofia/internal/12550@10.23.154.63 parsing [public->call_debug] continue=true Dialplan: sofia/internal/12550@10.23.154.63 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/12550@10.23.154.63 parsing [public->gateway_inbound] continue=false Dialplan: sofia/internal/12550@10.23.154.63 Regex (FAIL) [gateway_inbound] ${target_context}() =~ /^[a-z]/ break=on-false Dialplan: sofia/internal/12550@10.23.154.63 parsing [public->from_mts-tascom] continue=false Dialplan: sofia/internal/12550@10.23.154.63 Regex (FAIL) [from_mts-tascom] network_addr(10.23.154.63) =~ /^82\.204\.25[45]/ break=on-false Dialplan: sofia/internal/12550@10.23.154.63 parsing [public->from_partner] continue=false Dialplan: sofia/internal/12550@10.23.154.63 Regex (FAIL) [from_partner] network_addr(10.23.154.63) =~ /^172\.17\.2\.3$/ break=on-false Dialplan: sofia/internal/12550@10.23.154.63 parsing [public->from_cucm] continue=false Dialplan: sofia/internal/12550@10.23.154.63 Regex (PASS) [from_cucm] network_addr(10.23.154.63) =~ /^10\.23\.154\.6[1-6]$/ break=on-false Dialplan: sofia/internal/12550@10.23.154.63 Action export(suppress_cng=true) Dialplan: sofia/internal/12550@10.23.154.63 Action transfer(${destination_number} XML internal) 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/12550@10.23.154.63) State Change CS_ROUTING -> CS_EXECUTE 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/12550@10.23.154.63) State ROUTING going to sleep 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/12550@10.23.154.63) Running State Change CS_EXECUTE 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:609 (sofia/internal/12550@10.23.154.63) State EXECUTE 2016-10-07 12:34:02.547569 [DEBUG] mod_sofia.c:198 sofia/internal/12550@10.23.154.63 SOFIA EXECUTE 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:328 sofia/internal/12550@10.23.154.63 Standard EXECUTE EXECUTE sofia/internal/12550@10.23.154.63 set(default_language=en) 2016-10-07 12:34:02.547569 [DEBUG] mod_dptools.c:1519 SET sofia/internal/12550@10.23.154.63 [default_language]=[en] EXECUTE sofia/internal/12550@10.23.154.63 export(suppress_cng=true) 2016-10-07 12:34:02.547569 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [suppress_cng]=[true] EXECUTE sofia/internal/12550@10.23.154.63 transfer(62987#401077 XML internal) 2016-10-07 12:34:02.547569 [DEBUG] switch_ivr.c:2160 (sofia/internal/12550@10.23.154.63) State Change CS_EXECUTE -> CS_ROUTING 2016-10-07 12:34:02.547569 [NOTICE] switch_ivr.c:2167 Transfer sofia/internal/12550@10.23.154.63 to XML[62987#401077@internal] 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:609 (sofia/internal/12550@10.23.154.63) State EXECUTE going to sleep 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/12550@10.23.154.63) Running State Change CS_ROUTING 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/12550@10.23.154.63) State ROUTING 2016-10-07 12:34:02.547569 [DEBUG] mod_sofia.c:143 sofia/internal/12550@10.23.154.63 SOFIA ROUTING 2016-10-07 12:34:02.547569 [ERR] mod_xml_radius.c:933 Result of true match: 10.23.154.100 == ^8\.8\.8\.8 2016-10-07 12:34:02.547569 [INFO] mod_xml_radius.c:986 mod_xml_radius: Accounting Start success 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:236 sofia/internal/12550@10.23.154.63 Standard ROUTING 2016-10-07 12:34:02.547569 [INFO] mod_dialplan_xml.c:637 Processing IT, Юрьев Сергей <12550>->62987#401077 in context internal Dialplan: sofia/internal/12550@10.23.154.63 parsing [internal->common_variables] continue=true Dialplan: sofia/internal/12550@10.23.154.63 Absolute Condition [common_variables] Dialplan: sofia/internal/12550@10.23.154.63 Action set(default_language=en) Dialplan: sofia/internal/12550@10.23.154.63 parsing [internal->call_debug] continue=true Dialplan: sofia/internal/12550@10.23.154.63 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/12550@10.23.154.63 parsing [internal->mts_tascom] continue=false Dialplan: sofia/internal/12550@10.23.154.63 Regex (FAIL) [mts_tascom] destination_number(62987#401077) =~ /^(17[0-5]\d\d)$/ break=on-false Dialplan: sofia/internal/12550@10.23.154.63 parsing [internal->cucm] continue=false Dialplan: sofia/internal/12550@10.23.154.63 Regex (FAIL) [cucm] destination_number(62987#401077) =~ /^17[0-5]\d\d$/ break=on-true Dialplan: sofia/internal/12550@10.23.154.63 Regex (FAIL) [cucm] destination_number(62987#401077) =~ /^(?:1700#)?([1245678]\d{4}$|04\d{2,3}|555)$/ break=on-false Dialplan: sofia/internal/12550@10.23.154.63 parsing [internal->partner] continue=false Dialplan: sofia/internal/12550@10.23.154.63 Regex (PASS) [partner] destination_number(62987#401077) =~ /^62987#(\d+)$/ break=on-false Dialplan: sofia/internal/12550@10.23.154.63 Action set(hangup_after_bridge=true) Dialplan: sofia/internal/12550@10.23.154.63 Action set(inherit_codec=true) Dialplan: sofia/internal/12550@10.23.154.63 Action export(origination_callee_id_name=partner) Dialplan: sofia/internal/12550@10.23.154.63 Action set(effective_caller_id_name=_undef_) Dialplan: sofia/internal/12550@10.23.154.63 Action bridge(sofia/gateway/partner/401077) 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/12550@10.23.154.63) State Change CS_ROUTING -> CS_EXECUTE 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/12550@10.23.154.63) State ROUTING going to sleep 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/12550@10.23.154.63) Running State Change CS_EXECUTE 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:609 (sofia/internal/12550@10.23.154.63) State EXECUTE 2016-10-07 12:34:02.547569 [DEBUG] mod_sofia.c:198 sofia/internal/12550@10.23.154.63 SOFIA EXECUTE 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:328 sofia/internal/12550@10.23.154.63 Standard EXECUTE EXECUTE sofia/internal/12550@10.23.154.63 set(default_language=en) 2016-10-07 12:34:02.547569 [DEBUG] mod_dptools.c:1519 SET sofia/internal/12550@10.23.154.63 [default_language]=[en] EXECUTE sofia/internal/12550@10.23.154.63 set(hangup_after_bridge=true) 2016-10-07 12:34:02.547569 [DEBUG] mod_dptools.c:1519 SET sofia/internal/12550@10.23.154.63 [hangup_after_bridge]=[true] EXECUTE sofia/internal/12550@10.23.154.63 set(inherit_codec=true) 2016-10-07 12:34:02.547569 [DEBUG] mod_dptools.c:1519 SET sofia/internal/12550@10.23.154.63 [inherit_codec]=[true] EXECUTE sofia/internal/12550@10.23.154.63 export(origination_callee_id_name=partner) 2016-10-07 12:34:02.547569 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[partner] EXECUTE sofia/internal/12550@10.23.154.63 set(effective_caller_id_name=_undef_) 2016-10-07 12:34:02.547569 [DEBUG] mod_dptools.c:1519 SET sofia/internal/12550@10.23.154.63 [effective_caller_id_name]=[_undef_] EXECUTE sofia/internal/12550@10.23.154.63 bridge(sofia/gateway/partner/401077) 2016-10-07 12:34:02.547569 [DEBUG] switch_channel.c:1250 sofia/internal/12550@10.23.154.63 EXPORTING[export_vars] [suppress_cng]=[true] to event 2016-10-07 12:34:02.547569 [DEBUG] switch_channel.c:1250 sofia/internal/12550@10.23.154.63 EXPORTING[export_vars] [origination_callee_id_name]=[partner] to event 2016-10-07 12:34:02.547569 [DEBUG] switch_ivr_originate.c:2127 Parsing global variables 2016-10-07 12:34:02.547569 [NOTICE] switch_channel.c:1104 New Channel sofia/external/401077 [7ae98307-febf-4184-b5aa-9ed8efbeb0df] 2016-10-07 12:34:02.547569 [DEBUG] mod_sofia.c:4758 (sofia/external/401077) State Change CS_NEW -> CS_INIT 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:543 (sofia/external/401077) Running State Change CS_INIT 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:586 (sofia/external/401077) State INIT 2016-10-07 12:34:02.547569 [DEBUG] mod_sofia.c:90 sofia/external/401077 SOFIA INIT 2016-10-07 12:34:02.547569 [DEBUG] sofia_glue.c:1249 sofia/external/401077 sending invite version: 1.7.0 git be13536 2016-07-07 16:55:35Z 64bit Local SDP: v=0 o=FreeSWITCH 1475802844 1475802845 IN IP4 83.y.y.y s=FreeSWITCH c=IN IP4 83.y.y.y t=0 0 m=audio 29998 RTP/AVP 18 8 0 102 3 101 a=rtpmap:18 G729/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:102 iLBC/8000 a=fmtp:102 mode=30 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv send 1107 bytes to tcp/[172.17.2.3]:6060 at 12:34:02.556030: ------------------------------------------------------------------------ INVITE sip:401077@172.17.2.3:6060;transport=tcp SIP/2.0 Via: SIP/2.0/TCP 83.y.y.y:6060;rport;branch=z9hG4bKc8Ht2Kp31H71K Max-Forwards: 67 From: ;tag=7yF4v9SvF0KNK To: Call-ID: 0628366d-0714-1235-a38f-00505692d797 CSeq: 97580357 INVITE Contact: User-Agent: ES FS SBC Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 345 X-FS-Support: update_display,send_info Remote-Party-ID: ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1475802844 1475802845 IN IP4 83.y.y.y s=FreeSWITCH c=IN IP4 83.y.y.y t=0 0 m=audio 29998 RTP/AVP 18 8 0 102 3 101 a=rtpmap:18 G729/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:102 iLBC/8000 a=fmtp:102 mode=30 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:40 sofia/external/401077 Standard INIT 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:48 (sofia/external/401077) State Change CS_INIT -> CS_ROUTING 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:586 (sofia/external/401077) State INIT going to sleep 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:543 (sofia/external/401077) Running State Change CS_ROUTING 2016-10-07 12:34:02.547569 [DEBUG] sofia.c:6937 Channel sofia/external/401077 entering state [calling][0] 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:602 (sofia/external/401077) State ROUTING 2016-10-07 12:34:02.547569 [DEBUG] mod_sofia.c:143 sofia/external/401077 SOFIA ROUTING 2016-10-07 12:34:02.547569 [DEBUG] switch_ivr_originate.c:67 (sofia/external/401077) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2016-10-07 12:34:02.547569 [ERR] mod_xml_radius.c:933 Result of true match: 172.17.2.3:6060 == ^8\.8\.8\.8 2016-10-07 12:34:02.547569 [INFO] mod_xml_radius.c:986 mod_xml_radius: Accounting Start success 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:602 (sofia/external/401077) State ROUTING going to sleep 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:543 (sofia/external/401077) Running State Change CS_CONSUME_MEDIA 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:621 (sofia/external/401077) State CONSUME_MEDIA 2016-10-07 12:34:02.547569 [DEBUG] switch_core_state_machine.c:621 (sofia/external/401077) State CONSUME_MEDIA going to sleep recv 302 bytes from tcp/[172.17.2.3]:6060 at 12:34:02.573853: ------------------------------------------------------------------------ SIP/2.0 100 Trying From: ;tag=7yF4v9SvF0KNK To: Call-ID: 0628366d-0714-1235-a38f-00505692d797 CSeq: 97580357 INVITE Via: SIP/2.0/TCP 83.y.y.y:6060;branch=z9hG4bKc8Ht2Kp31H71K Server: Avaya CM/R016x.03.0.124.0 Content-Length: 0 ------------------------------------------------------------------------ recv 769 bytes from tcp/[172.17.2.3]:6060 at 12:34:02.578066: ------------------------------------------------------------------------ SIP/2.0 180 Ringing From: ;tag=7yF4v9SvF0KNK To: ;tag=06c11229d9ee614675724fb1600 Call-ID: 0628366d-0714-1235-a38f-00505692d797 CSeq: 97580357 INVITE Via: SIP/2.0/TCP 83.y.y.y:6060;branch=z9hG4bKc8Ht2Kp31H71K Supported: histinfo,join,replaces,sdp-anat,timer Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,INFO,UPDATE Contact: Accept-Language: uk Record-Route: Server: Avaya CM/R016x.03.0.124.0 Content-Type: application/sdp Content-Length: 180 v=0 o=- 1475832842 2 IN IP4 172.17.2.3 s=- c=IN IP4 172.17.2.4 b=AS:64 t=0 0 m=audio 2308 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=ptime:20 ------------------------------------------------------------------------ 2016-10-07 12:34:02.567566 [DEBUG] sofia.c:6937 Channel sofia/external/401077 entering state [proceeding][180] 2016-10-07 12:34:02.567566 [DEBUG] sofia.c:6947 Remote SDP: v=0 o=- 1475832842 2 IN IP4 172.17.2.3 s=- c=IN IP4 172.17.2.4 b=AS:64 t=0 0 m=audio 2308 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=ptime:20 recv 946 bytes from tcp/[172.17.2.3]:6060 at 12:34:05.214055: ------------------------------------------------------------------------ SIP/2.0 200 OK From: ;tag=7yF4v9SvF0KNK To: ;tag=06c11229d9ee614675724fb1600 Call-ID: 0628366d-0714-1235-a38f-00505692d797 CSeq: 97580357 INVITE Via: SIP/2.0/TCP 83.y.y.y:6060;branch=z9hG4bKc8Ht2Kp31H71K Supported: histinfo,join,replaces,sdp-anat,timer Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,INFO,UPDATE Contact: "Unk" Accept-Language: uk P-Asserted-Identity: "Unk" Record-Route: Require: timer Server: Avaya CM/R016x.03.0.124.0 Session-Expires: 1200;refresher=uas Content-Type: application/sdp Content-Length: 180 v=0 o=- 1475832842 2 IN IP4 172.17.2.3 s=- c=IN IP4 172.17.2.4 b=AS:64 t=0 0 m=audio 2308 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=ptime:20 ------------------------------------------------------------------------ 2016-10-07 12:34:05.207572 [INFO] sofia.c:1255 sofia/external/401077 Update Callee ID to "Unk" <401077> 2016-10-07 12:34:05.207572 [DEBUG] sofia.c:6937 Channel sofia/external/401077 entering state [completing][200] 2016-10-07 12:34:05.207572 [DEBUG] sofia.c:6944 Duplicate SDP v=0 o=- 1475832842 2 IN IP4 172.17.2.3 s=- c=IN IP4 172.17.2.4 b=AS:64 t=0 0 m=audio 2308 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=ptime:20 send 475 bytes to tcp/[172.17.2.3]:6060 at 12:34:05.214933: ------------------------------------------------------------------------ ACK sip:401077@172.17.2.3:6060;transport=tcp SIP/2.0 Via: SIP/2.0/TCP 83.y.y.y:6060;rport;branch=z9hG4bKDHBK4e76ytXmF Route: Max-Forwards: 70 From: ;tag=7yF4v9SvF0KNK To: ;tag=06c11229d9ee614675724fb1600 Call-ID: 0628366d-0714-1235-a38f-00505692d797 CSeq: 97580357 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ 2016-10-07 12:34:05.207572 [DEBUG] sofia.c:6937 Channel sofia/external/401077 entering state [ready][200] 2016-10-07 12:34:05.207572 [DEBUG] switch_core_media.c:4373 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2016-10-07 12:34:05.207572 [DEBUG] switch_core_media.c:4373 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2016-10-07 12:34:05.207572 [DEBUG] switch_core_media.c:4428 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2016-10-07 12:34:05.207572 [DEBUG] switch_core_media.c:4373 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2016-10-07 12:34:05.207572 [DEBUG] switch_core_media.c:4373 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[iLBC:97:8000:30:13330:1] 2016-10-07 12:34:05.207572 [DEBUG] switch_core_media.c:4373 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2016-10-07 12:34:05.207572 [DEBUG] switch_core_media.c:4289 Set telephone-event payload to 101@8000 2016-10-07 12:34:05.207572 [DEBUG] switch_core_media.c:3086 Set Codec sofia/external/401077 PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2016-10-07 12:34:05.207572 [DEBUG] switch_core_codec.c:111 sofia/external/401077 Original read codec set to PCMA:8 2016-10-07 12:34:05.207572 [DEBUG] switch_core_media.c:4642 Set telephone-event payload to 101@8000 2016-10-07 12:34:05.207572 [DEBUG] switch_core_media.c:4701 sofia/external/401077 Set 2833 dtmf send payload to 101 recv payload to 101 2016-10-07 12:34:05.207572 [DEBUG] switch_core_media.c:6508 AUDIO RTP [sofia/external/401077] 83.y.y.y port 29998 -> 172.17.2.4 port 2308 codec: 8 ms: 20 2016-10-07 12:34:05.207572 [DEBUG] switch_rtp.c:3832 Starting timer [soft] 160 bytes per 20ms 2016-10-07 12:34:05.207572 [DEBUG] switch_core_media.c:6807 sofia/external/401077 Set 2833 dtmf send payload to 101 2016-10-07 12:34:05.207572 [DEBUG] switch_core_media.c:6814 sofia/external/401077 Set 2833 dtmf receive payload to 101 2016-10-07 12:34:05.207572 [DEBUG] switch_core_media.c:6837 sofia/external/401077 Set rtp dtmf delay to 40 2016-10-07 12:34:05.207572 [NOTICE] sofia.c:7969 Channel [sofia/external/401077] has been answered 2016-10-07 12:34:05.207572 [DEBUG] switch_channel.c:3770 (sofia/external/401077) Callstate Change DOWN -> ACTIVE 2016-10-07 12:34:05.207572 [DEBUG] switch_ivr_originate.c:410 Setting codec string on sofia/internal/12550@10.23.154.63 to PCMA@8000h@20i send 966 bytes to udp/[10.23.154.63]:6060 at 12:34:05.223126: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.23.154.63:6060;branch=z9hG4bKe129742e55e6 From: "IT, Юрьев Сергей" ;tag=193729~27154efa-6325-45a2-9e47-67e5d9302ebc-237774854 To: ;tag=01pQ6Fe4jj5rQ Call-ID: 2d3d2680-7f716c0a-c20e-3f40000a@10.23.154.63 CSeq: 101 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.7.0+git~20160707T165535Z~be13536ac9~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, PRACK, NOTIFY Require: timer Supported: precondition, 100rel, timer, path, replaces Allow-Events: talk, hold, conference, refer Session-Expires: 1800;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 180 v=0 o=- 1475832842 2 IN IP4 172.17.2.3 s=- c=IN IP4 172.17.2.4 b=AS:64 t=0 0 m=audio 2308 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=ptime:20 ------------------------------------------------------------------------ 2016-10-07 12:34:05.207572 [DEBUG] mod_sofia.c:762 3PCC-PROXY, Sent a 200 OK, waiting for ACK 2016-10-07 12:34:05.207572 [DEBUG] sofia.c:6937 Channel sofia/internal/12550@10.23.154.63 entering state [completed][200] recv 706 bytes from udp/[10.23.154.63]:6060 at 12:34:05.226757: ------------------------------------------------------------------------ ACK sip:mod_sofia@10.23.154.100:6060 SIP/2.0 Via: SIP/2.0/UDP 10.23.154.63:6060;branch=z9hG4bKe12a126dba3 From: "IT, Юрьев Сергей" ;tag=193729~27154efa-6325-45a2-9e47-67e5d9302ebc-237774854 To: ;tag=01pQ6Fe4jj5rQ Date: Fri, 07 Oct 2016 09:34:02 GMT Call-ID: 2d3d2680-7f716c0a-c20e-3f40000a@10.23.154.63 Max-Forwards: 70 CSeq: 101 ACK Allow-Events: presence, kpml Content-Type: application/sdp Content-Length: 221 v=0 o=CiscoSystemsCCM-SIP 193729 1 IN IP4 10.23.154.63 s=SIP Call c=IN IP4 10.228.8.167 b=AS:64 t=0 0 m=audio 17284 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=ptime:20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ 2016-10-07 12:34:05.227567 [DEBUG] sofia.c:6937 Channel sofia/internal/12550@10.23.154.63 entering state [ready][200] 2016-10-07 12:34:05.227567 [DEBUG] sofia.c:6947 Remote SDP: v=0 o=CiscoSystemsCCM-SIP 193729 1 IN IP4 10.23.154.63 s=SIP Call c=IN IP4 10.228.8.167 b=AS:64 t=0 0 m=audio 17284 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2016-10-07 12:34:05.227567 [DEBUG] switch_core_media.c:4373 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2016-10-07 12:34:05.227567 [DEBUG] switch_core_media.c:4428 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2016-10-07 12:34:05.227567 [DEBUG] switch_core_media.c:4289 Set telephone-event payload to 101@8000 2016-10-07 12:34:05.227567 [DEBUG] switch_core_media.c:3086 Set Codec sofia/internal/12550@10.23.154.63 PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2016-10-07 12:34:05.227567 [DEBUG] switch_core_codec.c:111 sofia/internal/12550@10.23.154.63 Original read codec set to PCMA:8 2016-10-07 12:34:05.227567 [DEBUG] switch_core_media.c:4642 Set telephone-event payload to 101@8000 2016-10-07 12:34:05.227567 [DEBUG] switch_core_media.c:4701 sofia/internal/12550@10.23.154.63 Set 2833 dtmf send payload to 101 recv payload to 101 2016-10-07 12:34:05.227567 [DEBUG] switch_core_media.c:6508 AUDIO RTP [sofia/internal/12550@10.23.154.63] 10.23.154.100 port 29956 -> 10.228.8.167 port 17284 codec: 8 ms: 20 2016-10-07 12:34:05.227567 [DEBUG] switch_rtp.c:3832 Starting timer [soft] 160 bytes per 20ms 2016-10-07 12:34:05.227567 [DEBUG] switch_core_media.c:6807 sofia/internal/12550@10.23.154.63 Set 2833 dtmf send payload to 101 2016-10-07 12:34:05.227567 [DEBUG] switch_core_media.c:6814 sofia/internal/12550@10.23.154.63 Set 2833 dtmf receive payload to 101 2016-10-07 12:34:05.227567 [DEBUG] switch_core_media.c:6837 sofia/internal/12550@10.23.154.63 Set rtp dtmf delay to 40 2016-10-07 12:34:05.227567 [NOTICE] sofia.c:7969 Channel [sofia/internal/12550@10.23.154.63] has been answered 2016-10-07 12:34:05.227567 [DEBUG] switch_channel.c:3770 (sofia/internal/12550@10.23.154.63) Callstate Change RINGING -> ACTIVE 2016-10-07 12:34:05.227567 [DEBUG] sofia.c:7978 3PCC-PROXY, Got my ACK 2016-10-07 12:34:05.227567 [DEBUG] mod_sofia.c:780 3PCC-PROXY, Done waiting for ACK 2016-10-07 12:34:05.227567 [DEBUG] switch_ivr_originate.c:3607 Originate Resulted in Success: [sofia/external/401077] 2016-10-07 12:34:05.227567 [DEBUG] switch_ivr_bridge.c:1599 (sofia/external/401077) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2016-10-07 12:34:05.227567 [DEBUG] switch_core_state_machine.c:543 (sofia/external/401077) Running State Change CS_EXCHANGE_MEDIA 2016-10-07 12:34:05.227567 [DEBUG] switch_core_state_machine.c:612 (sofia/external/401077) State EXCHANGE_MEDIA 2016-10-07 12:34:05.227567 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA 2016-10-07 12:34:05.267571 [DEBUG] switch_rtp.c:6711 Correct audio ip/port confirmed. recv 555 bytes from udp/[10.23.154.63]:6060 at 12:34:12.247720: ------------------------------------------------------------------------ BYE sip:mod_sofia@10.23.154.100:6060 SIP/2.0 Via: SIP/2.0/UDP 10.23.154.63:6060;branch=z9hG4bKe12c62a97be8 From: "IT, Юрьев Сергей" ;tag=193729~27154efa-6325-45a2-9e47-67e5d9302ebc-237774854 To: ;tag=01pQ6Fe4jj5rQ Date: Fri, 07 Oct 2016 09:34:02 GMT Call-ID: 2d3d2680-7f716c0a-c20e-3f40000a@10.23.154.63 User-Agent: Cisco-CP7942G/9.3.1 Max-Forwards: 70 P-Asserted-Identity: "IT, Юрьев Сергей" CSeq: 102 BYE Reason: Q.850;cause=16 Content-Length: 0 ------------------------------------------------------------------------ 2016-10-07 12:34:12.247582 [NOTICE] sofia.c:988 Hangup sofia/internal/12550@10.23.154.63 [CS_EXECUTE] [NORMAL_CLEARING] send 554 bytes to udp/[10.23.154.63]:6060 at 12:34:12.250153: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.23.154.63:6060;branch=z9hG4bKe12c62a97be8 From: "IT, Юрьев Сергей" ;tag=193729~27154efa-6325-45a2-9e47-67e5d9302ebc-237774854 To: ;tag=01pQ6Fe4jj5rQ Call-ID: 2d3d2680-7f716c0a-c20e-3f40000a@10.23.154.63 CSeq: 102 BYE User-Agent: FreeSWITCH-mod_sofia/1.7.0+git~20160707T165535Z~be13536ac9~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, PRACK, NOTIFY Supported: precondition, 100rel, timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2016-10-07 12:34:12.247582 [DEBUG] switch_ivr_bridge.c:785 BRIDGE THREAD DONE [sofia/internal/12550@10.23.154.63] 2016-10-07 12:34:12.247582 [DEBUG] switch_ivr_bridge.c:706 sofia/internal/12550@10.23.154.63 ending bridge by request from write function 2016-10-07 12:34:12.247582 [DEBUG] switch_ivr_bridge.c:785 BRIDGE THREAD DONE [sofia/external/401077] 2016-10-07 12:34:12.247582 [NOTICE] switch_ivr_bridge.c:889 Hangup sofia/external/401077 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:612 (sofia/external/401077) State EXCHANGE_MEDIA going to sleep 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:543 (sofia/external/401077) Running State Change CS_HANGUP 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:809 (sofia/external/401077) Callstate Change ACTIVE -> HANGUP 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:811 (sofia/external/401077) State HANGUP 2016-10-07 12:34:12.247582 [DEBUG] mod_sofia.c:432 sofia/external/401077 Overriding SIP cause 480 with 200 from the other leg 2016-10-07 12:34:12.247582 [DEBUG] mod_sofia.c:438 Channel sofia/external/401077 hanging up, cause: NORMAL_CLEARING 2016-10-07 12:34:12.247582 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/external/401077 send 551 bytes to tcp/[172.17.2.3]:6060 at 12:34:12.256689: ------------------------------------------------------------------------ BYE sip:401077@172.17.2.3:6060;transport=tcp SIP/2.0 Via: SIP/2.0/TCP 83.y.y.y:6060;rport;branch=z9hG4bKet4B69Qav3K7a Route: Max-Forwards: 70 From: ;tag=7yF4v9SvF0KNK To: ;tag=06c11229d9ee614675724fb1600 Call-ID: 0628366d-0714-1235-a38f-00505692d797 CSeq: 97580358 BYE User-Agent: ES FS SBC Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY Supported: timer, path, replaces Reason: Q.850;cause=16 Content-Length: 0 ------------------------------------------------------------------------ 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:60 sofia/external/401077 Standard HANGUP, cause: NORMAL_CLEARING 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:811 (sofia/external/401077) State HANGUP going to sleep 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:578 (sofia/external/401077) State Change CS_HANGUP -> CS_REPORTING 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:543 (sofia/external/401077) Running State Change CS_REPORTING 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:897 (sofia/external/401077) State REPORTING 2016-10-07 12:34:12.247582 [ERR] mod_xml_radius.c:933 Result of true match: 172.17.2.3 == ^8\.8\.8\.8 2016-10-07 12:34:12.247582 [DEBUG] switch_ivr_bridge.c:1697 sofia/external/401077 skip receive message [UNBRIDGE] (channel is hungup already) 2016-10-07 12:34:12.247582 [DEBUG] switch_ivr_bridge.c:1700 sofia/internal/12550@10.23.154.63 skip receive message [UNBRIDGE] (channel is hungup already) 2016-10-07 12:34:12.247582 [DEBUG] switch_core_session.c:2797 sofia/internal/12550@10.23.154.63 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:609 (sofia/internal/12550@10.23.154.63) State EXECUTE going to sleep 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/12550@10.23.154.63) Running State Change CS_HANGUP 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:809 (sofia/internal/12550@10.23.154.63) Callstate Change ACTIVE -> HANGUP 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/12550@10.23.154.63) State HANGUP 2016-10-07 12:34:12.247582 [DEBUG] mod_sofia.c:438 Channel sofia/internal/12550@10.23.154.63 hanging up, cause: NORMAL_CLEARING 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:60 sofia/internal/12550@10.23.154.63 Standard HANGUP, cause: NORMAL_CLEARING 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:811 (sofia/internal/12550@10.23.154.63) State HANGUP going to sleep 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/12550@10.23.154.63) State Change CS_HANGUP -> CS_REPORTING 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/12550@10.23.154.63) Running State Change CS_REPORTING 2016-10-07 12:34:12.247582 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/12550@10.23.154.63) State REPORTING 2016-10-07 12:34:12.247582 [ERR] mod_xml_radius.c:933 Result of true match: 10.23.154.100 == ^8\.8\.8\.8 2016-10-07 12:34:12.247582 [INFO] mod_xml_radius.c:1044 mod_xml_radius: Accounting Stop success 2016-10-07 12:34:12.247582 [INFO] mod_xml_radius.c:1044 mod_xml_radius: Accounting Stop success recv 327 bytes from tcp/[172.17.2.3]:6060 at 12:34:12.292046: ------------------------------------------------------------------------ SIP/2.0 200 OK From: ;tag=7yF4v9SvF0KNK To: ;tag=06c11229d9ee614675724fb1600 Call-ID: 0628366d-0714-1235-a38f-00505692d797 CSeq: 97580358 BYE Via: SIP/2.0/TCP 83.y.y.y:6060;branch=z9hG4bKet4B69Qav3K7a Server: Avaya CM/R016x.03.0.124.0 Content-Length: 0 ------------------------------------------------------------------------ 2016-10-07 12:34:12.327578 [DEBUG] switch_core_state_machine.c:174 sofia/external/401077 Standard REPORTING, cause: NORMAL_CLEARING 2016-10-07 12:34:12.327578 [DEBUG] switch_core_state_machine.c:897 (sofia/external/401077) State REPORTING going to sleep 2016-10-07 12:34:12.327578 [DEBUG] switch_core_state_machine.c:569 (sofia/external/401077) State Change CS_REPORTING -> CS_DESTROY 2016-10-07 12:34:12.327578 [DEBUG] switch_core_session.c:1647 Session 8722 (sofia/external/401077) Locked, Waiting on external entities 2016-10-07 12:34:12.327578 [NOTICE] switch_core_session.c:1665 Session 8722 (sofia/external/401077) Ended 2016-10-07 12:34:12.327578 [NOTICE] switch_core_session.c:1669 Close Channel sofia/external/401077 [CS_DESTROY] 2016-10-07 12:34:12.327578 [DEBUG] switch_core_state_machine.c:700 (sofia/external/401077) Running State Change CS_DESTROY 2016-10-07 12:34:12.327578 [DEBUG] switch_core_state_machine.c:710 (sofia/external/401077) State DESTROY 2016-10-07 12:34:12.327578 [DEBUG] mod_sofia.c:343 sofia/external/401077 SOFIA DESTROY 2016-10-07 12:34:12.327578 [DEBUG] switch_core_state_machine.c:181 sofia/external/401077 Standard DESTROY 2016-10-07 12:34:12.327578 [DEBUG] switch_core_state_machine.c:710 (sofia/external/401077) State DESTROY going to sleep 2016-10-07 12:34:12.367587 [DEBUG] switch_core_state_machine.c:174 sofia/internal/12550@10.23.154.63 Standard REPORTING, cause: NORMAL_CLEARING 2016-10-07 12:34:12.367587 [DEBUG] switch_core_state_machine.c:897 (sofia/internal/12550@10.23.154.63) State REPORTING going to sleep 2016-10-07 12:34:12.367587 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/12550@10.23.154.63) State Change CS_REPORTING -> CS_DESTROY 2016-10-07 12:34:12.367587 [DEBUG] switch_core_session.c:1647 Session 8721 (sofia/internal/12550@10.23.154.63) Locked, Waiting on external entities 2016-10-07 12:34:12.367587 [NOTICE] switch_core_session.c:1665 Session 8721 (sofia/internal/12550@10.23.154.63) Ended 2016-10-07 12:34:12.367587 [NOTICE] switch_core_session.c:1669 Close Channel sofia/internal/12550@10.23.154.63 [CS_DESTROY] 2016-10-07 12:34:12.367587 [DEBUG] switch_core_state_machine.c:700 (sofia/internal/12550@10.23.154.63) Running State Change CS_DESTROY 2016-10-07 12:34:12.367587 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/12550@10.23.154.63) State DESTROY 2016-10-07 12:34:12.367587 [DEBUG] mod_sofia.c:343 sofia/internal/12550@10.23.154.63 SOFIA DESTROY 2016-10-07 12:34:12.367587 [DEBUG] switch_core_state_machine.c:181 sofia/internal/12550@10.23.154.63 Standard DESTROY 2016-10-07 12:34:12.367587 [DEBUG] switch_core_state_machine.c:710 (sofia/internal/12550@10.23.154.63) State DESTROY going to sleep