+OK Global siptrace on recv 739 bytes from tcp/[45.55.163.124]:5060 at 22:11:16.771020: ------------------------------------------------------------------------ INVITE sip:gw+GVGW@freeswitch.example.com:5080;transport=tcp;gw=GVGW SIP/2.0 Max-Forwards: 19 Via: SIP/2.0/TCP 45.55.163.124:5060;alias;rport;branch=z9hG4bK1059959625 From: "TULSA, OK" ;tag=916891763 To: Call-ID: 1538561599@45.55.163.124 CSeq: 644 INVITE User-Agent: GVGW Contact: Allow: ACK, INVITE, BYE, CANCEL, REGISTER, REFER, OPTIONS, INFO Content-Type: application/sdp Content-Length: 208 v=0 o=yate 1501391476 1501391476 IN IP4 45.55.163.124 s=SIP Call c=IN IP4 45.55.163.124 t=0 0 m=audio 28740 RTP/AVP 0 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 ------------------------------------------------------------------------ 2017-07-29 22:11:16.762439 [NOTICE] switch_channel.c:1104 New Channel sofia/external/9185330000@45.55.163.124 [83ec6834-74e5-11e7-b772-c1f435f54e69] 2017-07-29 22:11:16.762439 [DEBUG] switch_core_state_machine.c:584 (sofia/external/9185330000@45.55.163.124) Running State Change CS_NEW (Cur 1 Tot 182) 2017-07-29 22:11:16.762439 [DEBUG] sofia.c:10067 sofia/external/9185330000@45.55.163.124 receiving invite from 45.55.163.124:5060 version: 1.9.0 git 144d373 2017-07-28 23:05:50Z 32bit 2017-07-29 22:11:16.762439 [DEBUG] sofia.c:7283 Channel sofia/external/9185330000@45.55.163.124 entering state [received][100] 2017-07-29 22:11:16.762439 [DEBUG] sofia.c:7293 Remote SDP: v=0 o=yate 1501391476 1501391476 IN IP4 45.55.163.124 s=SIP Call c=IN IP4 45.55.163.124 t=0 0 m=audio 28740 RTP/AVP 0 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 2017-07-29 22:11:16.762439 [DEBUG] sofia.c:7685 (sofia/external/9185330000@45.55.163.124) State Change CS_NEW -> CS_INIT 2017-07-29 22:11:16.762439 [DEBUG] switch_core_state_machine.c:603 (sofia/external/9185330000@45.55.163.124) State NEW 2017-07-29 22:11:16.762439 [DEBUG] switch_core_state_machine.c:584 (sofia/external/9185330000@45.55.163.124) Running State Change CS_INIT (Cur 1 Tot 182) 2017-07-29 22:11:16.762439 [DEBUG] switch_core_state_machine.c:627 (sofia/external/9185330000@45.55.163.124) State INIT 2017-07-29 22:11:16.762439 [DEBUG] mod_sofia.c:93 sofia/external/9185330000@45.55.163.124 SOFIA INIT 2017-07-29 22:11:16.762439 [DEBUG] switch_core_state_machine.c:40 sofia/external/9185330000@45.55.163.124 Standard INIT 2017-07-29 22:11:16.762439 [DEBUG] switch_core_state_machine.c:48 (sofia/external/9185330000@45.55.163.124) State Change CS_INIT -> CS_ROUTING 2017-07-29 22:11:16.762439 [DEBUG] switch_core_state_machine.c:627 (sofia/external/9185330000@45.55.163.124) State INIT going to sleep 2017-07-29 22:11:16.762439 [DEBUG] switch_core_state_machine.c:584 (sofia/external/9185330000@45.55.163.124) Running State Change CS_ROUTING (Cur 1 Tot 182) 2017-07-29 22:11:16.762439 [DEBUG] switch_channel.c:2249 (sofia/external/9185330000@45.55.163.124) Callstate Change DOWN -> RINGING 2017-07-29 22:11:16.762439 [DEBUG] switch_core_state_machine.c:643 (sofia/external/9185330000@45.55.163.124) State ROUTING 2017-07-29 22:11:16.762439 [DEBUG] mod_sofia.c:154 sofia/external/9185330000@45.55.163.124 SOFIA ROUTING 2017-07-29 22:11:16.762439 [DEBUG] switch_core_state_machine.c:236 sofia/external/9185330000@45.55.163.124 Standard ROUTING 2017-07-29 22:11:16.762439 [INFO] mod_dialplan_xml.c:637 Processing TULSA, OK <9185330000>->12130000000 in context public send 380 bytes to tcp/[45.55.163.124]:5060 at 22:11:16.779170: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/TCP 45.55.163.124:5060;alias;rport=5060;branch=z9hG4bK1059959625 From: "TULSA, OK" ;tag=916891763 To: Call-ID: 1538561599@45.55.163.124 CSeq: 644 INVITE User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170728T230550Z~144d3733cf~32bit Content-Length: 0 ------------------------------------------------------------------------ Dialplan: sofia/external/9185330000@45.55.163.124 parsing [public->unloop] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [public->outside_call] continue=true Dialplan: sofia/external/9185330000@45.55.163.124 Absolute Condition [outside_call] Dialplan: sofia/external/9185330000@45.55.163.124 Action set(outside_call=true) Dialplan: sofia/external/9185330000@45.55.163.124 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/external/9185330000@45.55.163.124 parsing [public->call_debug] continue=true Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/9185330000@45.55.163.124 parsing [public->public_extensions] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [public_extensions] destination_number(12130000000) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [public->public_did] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [public_did] destination_number(12130000000) =~ /^15123330880$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [public->public_did] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [public_did] destination_number(12130000000) =~ /^17023024016$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [public->public_did] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [public_did] destination_number(12130000000) =~ /^883510009027723$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [public->public_did] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [public_did] destination_number(12130000000) =~ /^\+12109412600$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [public->public_did] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (PASS) [public_did] destination_number(12130000000) =~ /^12130000000$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 Action set(domain_name=192.168.0.137) Dialplan: sofia/external/9185330000@45.55.163.124 Action transfer(2600 XML default) 2017-07-29 22:11:16.762439 [DEBUG] switch_core_state_machine.c:286 (sofia/external/9185330000@45.55.163.124) State Change CS_ROUTING -> CS_EXECUTE 2017-07-29 22:11:16.762439 [DEBUG] switch_core_state_machine.c:643 (sofia/external/9185330000@45.55.163.124) State ROUTING going to sleep 2017-07-29 22:11:16.762439 [DEBUG] switch_core_state_machine.c:584 (sofia/external/9185330000@45.55.163.124) Running State Change CS_EXECUTE (Cur 1 Tot 182) 2017-07-29 22:11:16.762439 [DEBUG] switch_core_state_machine.c:650 (sofia/external/9185330000@45.55.163.124) State EXECUTE 2017-07-29 22:11:16.762439 [DEBUG] mod_sofia.c:209 sofia/external/9185330000@45.55.163.124 SOFIA EXECUTE 2017-07-29 22:11:16.762439 [DEBUG] switch_core_state_machine.c:328 sofia/external/9185330000@45.55.163.124 Standard EXECUTE EXECUTE sofia/external/9185330000@45.55.163.124 set(outside_call=true) 2017-07-29 22:11:16.782603 [DEBUG] mod_dptools.c:1588 SET sofia/external/9185330000@45.55.163.124 [outside_call]=[true] EXECUTE sofia/external/9185330000@45.55.163.124 export(RFC2822_DATE=Sat, 29 Jul 2017 22:11:16 -0700) 2017-07-29 22:11:16.782603 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Sat, 29 Jul 2017 22:11:16 -0700] EXECUTE sofia/external/9185330000@45.55.163.124 set(domain_name=192.168.0.137) 2017-07-29 22:11:16.782603 [DEBUG] mod_dptools.c:1588 SET sofia/external/9185330000@45.55.163.124 [domain_name]=[192.168.0.137] EXECUTE sofia/external/9185330000@45.55.163.124 transfer(2600 XML default) 2017-07-29 22:11:16.782603 [DEBUG] switch_ivr.c:2194 (sofia/external/9185330000@45.55.163.124) State Change CS_EXECUTE -> CS_ROUTING 2017-07-29 22:11:16.782603 [NOTICE] switch_ivr.c:2201 Transfer sofia/external/9185330000@45.55.163.124 to XML[2600@default] 2017-07-29 22:11:16.782603 [DEBUG] switch_core_state_machine.c:650 (sofia/external/9185330000@45.55.163.124) State EXECUTE going to sleep 2017-07-29 22:11:16.782603 [DEBUG] switch_core_state_machine.c:584 (sofia/external/9185330000@45.55.163.124) Running State Change CS_ROUTING (Cur 1 Tot 182) 2017-07-29 22:11:16.782603 [DEBUG] switch_core_state_machine.c:643 (sofia/external/9185330000@45.55.163.124) State ROUTING 2017-07-29 22:11:16.782603 [DEBUG] mod_sofia.c:145 Call appears to be already acknowledged 2017-07-29 22:11:16.782603 [DEBUG] mod_sofia.c:154 sofia/external/9185330000@45.55.163.124 SOFIA ROUTING 2017-07-29 22:11:16.782603 [DEBUG] switch_core_state_machine.c:236 sofia/external/9185330000@45.55.163.124 Standard ROUTING 2017-07-29 22:11:16.782603 [INFO] mod_dialplan_xml.c:637 Processing TULSA, OK <9185330000>->2600 in context default Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->unloop] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->tod_example] continue=true Dialplan: sofia/external/9185330000@45.55.163.124 Date/TimeMatch (FAIL) [tod_example] break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->holiday_example] continue=true Dialplan: sofia/external/9185330000@45.55.163.124 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->global-intercept] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [global-intercept] destination_number(2600) =~ /^886$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->group-intercept] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [group-intercept] destination_number(2600) =~ /^\*8$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->intercept-ext] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [intercept-ext] destination_number(2600) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->redial] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [redial] destination_number(2600) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->global] continue=true Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [global] ${default_password}() =~ /^1234$/ break=never Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never Dialplan: sofia/external/9185330000@45.55.163.124 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [global] ${switch_r_sdp}(v=0 o=yate 1501391476 1501391476 IN IP4 45.55.163.124 s=SIP Call c=IN IP4 45.55.163.124 t=0 0 m=audio 28740 RTP/AVP 0 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never Dialplan: sofia/external/9185330000@45.55.163.124 Absolute Condition [global] Dialplan: sofia/external/9185330000@45.55.163.124 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: sofia/external/9185330000@45.55.163.124 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/external/9185330000@45.55.163.124 Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: sofia/external/9185330000@45.55.163.124 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->snom-demo-2] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [snom-demo-2] destination_number(2600) =~ /^9001$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->snom-demo-1] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [snom-demo-1] destination_number(2600) =~ /^9000$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->eavesdrop] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [eavesdrop] destination_number(2600) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->eavesdrop] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [eavesdrop] destination_number(2600) =~ /^779$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->call_return] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [call_return] destination_number(2600) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->del-group] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [del-group] destination_number(2600) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->add-group] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [add-group] destination_number(2600) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->call-group-simo] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [call-group-simo] destination_number(2600) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->call-group-order] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [call-group-order] destination_number(2600) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->extension-intercom] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (FAIL) [extension-intercom] destination_number(2600) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 parsing [default->Local_Extension] continue=false Dialplan: sofia/external/9185330000@45.55.163.124 Regex (PASS) [Local_Extension] destination_number(2600) =~ /^(26[01][0-9]|phone|mobile)$/ break=on-false Dialplan: sofia/external/9185330000@45.55.163.124 Action export(dialed_extension=2600) Dialplan: sofia/external/9185330000@45.55.163.124 Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: sofia/external/9185330000@45.55.163.124 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/external/9185330000@45.55.163.124 Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: sofia/external/9185330000@45.55.163.124 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) Dialplan: sofia/external/9185330000@45.55.163.124 Action set(ringback=${us-ring}) Dialplan: sofia/external/9185330000@45.55.163.124 Action set(transfer_ringback=local_stream://moh) Dialplan: sofia/external/9185330000@45.55.163.124 Action set(call_timeout=30) Dialplan: sofia/external/9185330000@45.55.163.124 Action set(hangup_after_bridge=true) Dialplan: sofia/external/9185330000@45.55.163.124 Action set(continue_on_fail=true) Dialplan: sofia/external/9185330000@45.55.163.124 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/external/9185330000@45.55.163.124 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/external/9185330000@45.55.163.124 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/external/9185330000@45.55.163.124 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) Dialplan: sofia/external/9185330000@45.55.163.124 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) Dialplan: sofia/external/9185330000@45.55.163.124 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: sofia/external/9185330000@45.55.163.124 Action bridge(user/${user_data(${destination_number}@${domain_name} attr id)}) Dialplan: sofia/external/9185330000@45.55.163.124 Action answer() Dialplan: sofia/external/9185330000@45.55.163.124 Action sleep(1000) Dialplan: sofia/external/9185330000@45.55.163.124 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 2017-07-29 22:11:16.782603 [DEBUG] switch_core_state_machine.c:286 (sofia/external/9185330000@45.55.163.124) State Change CS_ROUTING -> CS_EXECUTE 2017-07-29 22:11:16.782603 [DEBUG] switch_core_state_machine.c:643 (sofia/external/9185330000@45.55.163.124) State ROUTING going to sleep 2017-07-29 22:11:16.782603 [DEBUG] switch_core_state_machine.c:584 (sofia/external/9185330000@45.55.163.124) Running State Change CS_EXECUTE (Cur 1 Tot 182) 2017-07-29 22:11:16.782603 [DEBUG] switch_core_state_machine.c:650 (sofia/external/9185330000@45.55.163.124) State EXECUTE 2017-07-29 22:11:16.782603 [DEBUG] mod_sofia.c:209 sofia/external/9185330000@45.55.163.124 SOFIA EXECUTE 2017-07-29 22:11:16.782603 [DEBUG] switch_core_state_machine.c:328 sofia/external/9185330000@45.55.163.124 Standard EXECUTE EXECUTE sofia/external/9185330000@45.55.163.124 hash(insert/192.168.0.137-spymap/9185330000/83ec6834-74e5-11e7-b772-c1f435f54e69) EXECUTE sofia/external/9185330000@45.55.163.124 hash(insert/192.168.0.137-last_dial/9185330000/2600) EXECUTE sofia/external/9185330000@45.55.163.124 hash(insert/192.168.0.137-last_dial/global/83ec6834-74e5-11e7-b772-c1f435f54e69) EXECUTE sofia/external/9185330000@45.55.163.124 export(RFC2822_DATE=Sat, 29 Jul 2017 22:11:16 -0700) 2017-07-29 22:11:16.802469 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Sat, 29 Jul 2017 22:11:16 -0700] EXECUTE sofia/external/9185330000@45.55.163.124 export(dialed_extension=2600) 2017-07-29 22:11:16.802469 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[2600] EXECUTE sofia/external/9185330000@45.55.163.124 bind_meta_app(1 b s execute_extension::dx XML features) 2017-07-29 22:11:16.802469 [INFO] switch_ivr_async.c:4260 Bound B-Leg: *1 execute_extension::dx XML features EXECUTE sofia/external/9185330000@45.55.163.124 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/9185330000.2017-07-29-22-11-16.wav) 2017-07-29 22:11:16.802469 [INFO] switch_ivr_async.c:4260 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/9185330000.2017-07-29-22-11-16.wav EXECUTE sofia/external/9185330000@45.55.163.124 bind_meta_app(3 b s execute_extension::cf XML features) 2017-07-29 22:11:16.802469 [INFO] switch_ivr_async.c:4260 Bound B-Leg: *3 execute_extension::cf XML features EXECUTE sofia/external/9185330000@45.55.163.124 bind_meta_app(4 b s execute_extension::att_xfer XML features) 2017-07-29 22:11:16.802469 [INFO] switch_ivr_async.c:4260 Bound B-Leg: *4 execute_extension::att_xfer XML features EXECUTE sofia/external/9185330000@45.55.163.124 set(ringback=%(2000,4000,440,480)) 2017-07-29 22:11:16.802469 [DEBUG] mod_dptools.c:1588 SET sofia/external/9185330000@45.55.163.124 [ringback]=[%(2000,4000,440,480)] EXECUTE sofia/external/9185330000@45.55.163.124 set(transfer_ringback=local_stream://moh) 2017-07-29 22:11:16.802469 [DEBUG] mod_dptools.c:1588 SET sofia/external/9185330000@45.55.163.124 [transfer_ringback]=[local_stream://moh] EXECUTE sofia/external/9185330000@45.55.163.124 set(call_timeout=30) 2017-07-29 22:11:16.802469 [DEBUG] mod_dptools.c:1588 SET sofia/external/9185330000@45.55.163.124 [call_timeout]=[30] EXECUTE sofia/external/9185330000@45.55.163.124 set(hangup_after_bridge=true) 2017-07-29 22:11:16.822454 [DEBUG] mod_dptools.c:1588 SET sofia/external/9185330000@45.55.163.124 [hangup_after_bridge]=[true] EXECUTE sofia/external/9185330000@45.55.163.124 set(continue_on_fail=true) 2017-07-29 22:11:16.822454 [DEBUG] mod_dptools.c:1588 SET sofia/external/9185330000@45.55.163.124 [continue_on_fail]=[true] EXECUTE sofia/external/9185330000@45.55.163.124 hash(insert/192.168.0.137-call_return/2600/9185330000) EXECUTE sofia/external/9185330000@45.55.163.124 hash(insert/192.168.0.137-last_dial_ext/2600/83ec6834-74e5-11e7-b772-c1f435f54e69) EXECUTE sofia/external/9185330000@45.55.163.124 set(called_party_callgroup=homephone) 2017-07-29 22:11:16.822454 [DEBUG] mod_dptools.c:1588 SET sofia/external/9185330000@45.55.163.124 [called_party_callgroup]=[homephone] EXECUTE sofia/external/9185330000@45.55.163.124 hash(insert/192.168.0.137-last_dial_ext/homephone/83ec6834-74e5-11e7-b772-c1f435f54e69) EXECUTE sofia/external/9185330000@45.55.163.124 hash(insert/192.168.0.137-last_dial_ext/global/83ec6834-74e5-11e7-b772-c1f435f54e69) EXECUTE sofia/external/9185330000@45.55.163.124 hash(insert/192.168.0.137-last_dial/homephone/83ec6834-74e5-11e7-b772-c1f435f54e69) EXECUTE sofia/external/9185330000@45.55.163.124 bridge(user/2600) 2017-07-29 22:11:16.822454 [DEBUG] switch_channel.c:1250 sofia/external/9185330000@45.55.163.124 EXPORTING[export_vars] [RFC2822_DATE]=[Sat, 29 Jul 2017 22:11:16 -0700] to event 2017-07-29 22:11:16.822454 [DEBUG] switch_channel.c:1250 sofia/external/9185330000@45.55.163.124 EXPORTING[export_vars] [RFC2822_DATE]=[Sat, 29 Jul 2017 22:11:16 -0700] to event 2017-07-29 22:11:16.822454 [DEBUG] switch_channel.c:1250 sofia/external/9185330000@45.55.163.124 EXPORTING[export_vars] [dialed_extension]=[2600] to event 2017-07-29 22:11:16.822454 [DEBUG] switch_ivr_originate.c:2147 Parsing global variables 2017-07-29 22:11:16.842465 [DEBUG] switch_channel.c:1250 sofia/external/9185330000@45.55.163.124 EXPORTING[export_vars] [RFC2822_DATE]=[Sat, 29 Jul 2017 22:11:16 -0700] to event 2017-07-29 22:11:16.842465 [DEBUG] switch_channel.c:1250 sofia/external/9185330000@45.55.163.124 EXPORTING[export_vars] [RFC2822_DATE]=[Sat, 29 Jul 2017 22:11:16 -0700] to event 2017-07-29 22:11:16.842465 [DEBUG] switch_channel.c:1250 sofia/external/9185330000@45.55.163.124 EXPORTING[export_vars] [dialed_extension]=[2600] to event 2017-07-29 22:11:16.842465 [DEBUG] switch_ivr_originate.c:2147 Parsing global variables 2017-07-29 22:11:16.842465 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/2600@192.168.0.12 [83f80248-74e5-11e7-b792-c1f435f54e69] 2017-07-29 22:11:16.842465 [DEBUG] mod_sofia.c:5026 (sofia/internal/2600@192.168.0.12) State Change CS_NEW -> CS_INIT 2017-07-29 22:11:16.842465 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/2600@192.168.0.12) Running State Change CS_INIT (Cur 2 Tot 183) 2017-07-29 22:11:16.842465 [NOTICE] switch_ivr_originate.c:2856 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED] 2017-07-29 22:11:16.842465 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/2600@192.168.0.12) State INIT 2017-07-29 22:11:16.842465 [DEBUG] mod_sofia.c:93 sofia/internal/2600@192.168.0.12 SOFIA INIT 2017-07-29 22:11:16.842465 [DEBUG] sofia_glue.c:1298 sofia/internal/2600@192.168.0.12 sending invite version: 1.9.0 git 144d373 2017-07-28 23:05:50Z 32bit Local SDP: v=0 o=FreeSWITCH 1501362548 1501362549 IN IP4 192.168.0.137 s=FreeSWITCH c=IN IP4 192.168.0.137 t=0 0 m=audio 28928 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv 2017-07-29 22:11:16.842465 [DEBUG] switch_core_state_machine.c:40 sofia/internal/2600@192.168.0.12 Standard INIT 2017-07-29 22:11:16.842465 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/2600@192.168.0.12) State Change CS_INIT -> CS_ROUTING 2017-07-29 22:11:16.842465 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/2600@192.168.0.12) State INIT going to sleep send 1172 bytes to udp/[192.168.0.12]:5060 at 22:11:16.857963: ------------------------------------------------------------------------ INVITE sip:2600@192.168.0.12 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.137;rport;branch=z9hG4bKvc62ggQ4p5B2B Max-Forwards: 17 From: "TULSA, OK" ;tag=gBDSptpK0j5cS To: Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5 CSeq: 110359674 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170728T230550Z~144d3733cf~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 222 X-FS-Support: update_display,send_info 2017-07-29 22:11:16.842465 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/2600@192.168.0.12) Running State Change CS_ROUTING (Cur 2 Tot 183) Remote-Party-ID: "TULSA, OK" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1501362548 1501362549 IN IP4 192.168.0.137 s=FreeSWITCH c=IN IP4 192.168.0.137 t=0 0 m=audio 28928 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2017-07-29 22:11:16.842465 [DEBUG] sofia.c:7283 Channel sofia/internal/2600@192.168.0.12 entering state [calling][0] 2017-07-29 22:11:16.842465 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/2600@192.168.0.12) State ROUTING 2017-07-29 22:11:16.842465 [DEBUG] mod_sofia.c:154 sofia/internal/2600@192.168.0.12 SOFIA ROUTING 2017-07-29 22:11:16.842465 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/2600@192.168.0.12) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2017-07-29 22:11:16.842465 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/2600@192.168.0.12) State ROUTING going to sleep 2017-07-29 22:11:16.842465 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/2600@192.168.0.12) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 183) 2017-07-29 22:11:16.842465 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/2600@192.168.0.12) State CONSUME_MEDIA 2017-07-29 22:11:16.842465 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/2600@192.168.0.12) State CONSUME_MEDIA going to sleep recv 414 bytes from udp/[192.168.0.12]:5060 at 22:11:16.874674: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.0.137;rport;branch=z9hG4bKvc62ggQ4p5B2B From: "TULSA, OK" ;tag=gBDSptpK0j5cS To: "jungle boogie" ;tag=1C93D4ED-1D331DFE CSeq: 110359674 INVITE Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5 Contact: User-Agent: PolycomVVX-VVX_410-UA/5.5.1.12442 Accept-Language: en Content-Length: 0 ------------------------------------------------------------------------ recv 451 bytes from udp/[192.168.0.12]:5060 at 22:11:16.970617: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.0.137;rport;branch=z9hG4bKvc62ggQ4p5B2B From: "TULSA, OK" ;tag=gBDSptpK0j5cS To: "jungle boogie" ;tag=1C93D4ED-1D331DFE CSeq: 110359674 INVITE Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5 Contact: User-Agent: PolycomVVX-VVX_410-UA/5.5.1.12442 Allow-Events: conference,talk,hold Accept-Language: en Content-Length: 0 ------------------------------------------------------------------------ 2017-07-29 22:11:16.962452 [DEBUG] sofia.c:7283 Channel sofia/internal/2600@192.168.0.12 entering state [proceeding][180] 2017-07-29 22:11:16.962452 [NOTICE] sofia.c:7391 Ring-Ready sofia/internal/2600@192.168.0.12! 2017-07-29 22:11:16.982477 [DEBUG] switch_channel.c:3354 (sofia/internal/2600@192.168.0.12) Callstate Change DOWN -> RINGING 2017-07-29 22:11:16.982477 [INFO] switch_ivr_originate.c:1220 Sending early media 2017-07-29 22:11:16.982477 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-07-29 22:11:16.982477 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-07-29 22:11:16.982477 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-07-29 22:11:16.982477 [DEBUG] switch_core_media.c:5170 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-07-29 22:11:16.982477 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-07-29 22:11:16.982477 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1] 2017-07-29 22:11:16.982477 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1] 2017-07-29 22:11:16.982477 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1] 2017-07-29 22:11:16.982477 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1] 2017-07-29 22:11:16.982477 [DEBUG] switch_core_media.c:5031 Set telephone-event payload to 101@8000 2017-07-29 22:11:16.982477 [DEBUG] switch_core_media.c:3430 Set Codec sofia/external/9185330000@45.55.163.124 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2017-07-29 22:11:16.982477 [DEBUG] switch_core_codec.c:111 sofia/external/9185330000@45.55.163.124 Original read codec set to PCMU:0 2017-07-29 22:11:16.982477 [DEBUG] switch_core_media.c:5374 Set telephone-event payload to 101@8000 2017-07-29 22:11:16.982477 [DEBUG] switch_core_media.c:5432 sofia/external/9185330000@45.55.163.124 Set 2833 dtmf send payload to 101 recv payload to 101 2017-07-29 22:11:17.122542 [DEBUG] switch_nat.c:508 mapped public port 22720 protocol UDP to localport 22720 2017-07-29 22:11:17.122542 [DEBUG] switch_core_media.c:8149 AUDIO RTP [sofia/external/9185330000@45.55.163.124] 192.168.0.137 port 22720 -> 45.55.163.124 port 28740 codec: 0 ms: 20 2017-07-29 22:11:17.122542 [DEBUG] switch_rtp.c:4164 Starting timer [soft] 160 bytes per 20ms 2017-07-29 22:11:17.122542 [DEBUG] switch_core_media.c:8452 sofia/external/9185330000@45.55.163.124 Set 2833 dtmf send payload to 101 2017-07-29 22:11:17.122542 [DEBUG] switch_core_media.c:8459 sofia/external/9185330000@45.55.163.124 Set 2833 dtmf receive payload to 101 2017-07-29 22:11:17.122542 [DEBUG] switch_core_media.c:8482 sofia/external/9185330000@45.55.163.124 Set rtp dtmf delay to 40 2017-07-29 22:11:17.122542 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/9185330000@45.55.163.124! 2017-07-29 22:11:17.122542 [DEBUG] switch_channel.c:3482 (sofia/external/9185330000@45.55.163.124) Callstate Change RINGING -> EARLY 2017-07-29 22:11:17.122542 [DEBUG] switch_core_media.c:8132 Audio params are unchanged for sofia/external/9185330000@45.55.163.124. 2017-07-29 22:11:17.122542 [DEBUG] mod_sofia.c:2512 Ring SDP: v=0 o=FreeSWITCH 1501368757 1501368758 IN IP4 freeswitch.example.com s=FreeSWITCH c=IN IP4 freeswitch.example.com t=0 0 m=audio 22720 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv 2017-07-29 22:11:17.122542 [DEBUG] switch_ivr_originate.c:1278 Raw Codec Activation Success L16@8000hz 1 channel 20ms 2017-07-29 22:11:17.122542 [DEBUG] switch_core_codec.c:223 sofia/external/9185330000@45.55.163.124 Push codec L16:100 2017-07-29 22:11:17.122542 [DEBUG] switch_ivr_originate.c:1347 Play Ringback Tone [%(2000,4000,440,480)] send 1064 bytes to tcp/[45.55.163.124]:5060 at 22:11:17.137745: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/TCP 45.55.163.124:5060;alias;rport=5060;branch=z9hG4bK1059959625 From: "TULSA, OK" ;tag=916891763 To: ;tag=SNgK5vtHUKjtj Call-ID: 1538561599@45.55.163.124 CSeq: 644 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170728T230550Z~144d3733cf~32bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 232 Remote-Party-ID: "12130000000" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1501368757 1501368758 IN IP4 freeswitch.example.com s=FreeSWITCH c=IN IP4 freeswitch.example.com t=0 0 m=audio 22720 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2017-07-29 22:11:17.142459 [DEBUG] sofia.c:7283 Channel sofia/external/9185330000@45.55.163.124 entering state [early][183] recv 792 bytes from udp/[192.168.0.12]:5060 at 22:11:19.123125: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.137;rport;branch=z9hG4bKvc62ggQ4p5B2B From: "TULSA, OK" ;tag=gBDSptpK0j5cS To: "jungle boogie" ;tag=1C93D4ED-1D331DFE CSeq: 110359674 INVITE Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER Supported: replaces,100rel User-Agent: PolycomVVX-VVX_410-UA/5.5.1.12442 Allow-Events: conference,talk,hold Accept-Language: en Content-Type: application/sdp Content-Length: 187 v=0 o=- 1501391478 1501391478 IN IP4 192.168.0.12 s=Polycom IP Phone c=IN IP4 192.168.0.12 t=0 0 m=audio 2244 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 ------------------------------------------------------------------------ 2017-07-29 22:11:19.122439 [DEBUG] sofia.c:7283 Channel sofia/internal/2600@192.168.0.12 entering state [completing][200] 2017-07-29 22:11:19.122439 [DEBUG] sofia.c:7293 Remote SDP: v=0 o=- 1501391478 1501391478 IN IP4 192.168.0.12 s=Polycom IP Phone c=IN IP4 192.168.0.12 t=0 0 m=audio 2244 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 send 372 bytes to udp/[192.168.0.12]:5060 at 22:11:19.134098: ------------------------------------------------------------------------ ACK sip:2600@192.168.0.12 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.137;rport;branch=z9hG4bKXNZUjB87Ke2mQ Max-Forwards: 70 From: "TULSA, OK" ;tag=gBDSptpK0j5cS To: ;tag=1C93D4ED-1D331DFE Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5 CSeq: 110359674 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ 2017-07-29 22:11:19.122439 [DEBUG] sofia.c:7283 Channel sofia/internal/2600@192.168.0.12 entering state [ready][200] 2017-07-29 22:11:19.122439 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-07-29 22:11:19.122439 [DEBUG] switch_core_media.c:5170 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-07-29 22:11:19.122439 [DEBUG] switch_core_media.c:5031 Set telephone-event payload to 101@8000 2017-07-29 22:11:19.122439 [DEBUG] switch_core_media.c:3430 Set Codec sofia/internal/2600@192.168.0.12 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2017-07-29 22:11:19.122439 [DEBUG] switch_core_codec.c:111 sofia/internal/2600@192.168.0.12 Original read codec set to PCMU:0 2017-07-29 22:11:19.122439 [DEBUG] switch_core_media.c:5374 Set telephone-event payload to 101@8000 2017-07-29 22:11:19.122439 [DEBUG] switch_core_media.c:5432 sofia/internal/2600@192.168.0.12 Set 2833 dtmf send payload to 101 recv payload to 101 2017-07-29 22:11:19.122439 [DEBUG] switch_core_media.c:8149 AUDIO RTP [sofia/internal/2600@192.168.0.12] 192.168.0.137 port 28928 -> 192.168.0.12 port 2244 codec: 0 ms: 20 2017-07-29 22:11:19.122439 [DEBUG] switch_rtp.c:4164 Starting timer [soft] 160 bytes per 20ms 2017-07-29 22:11:19.122439 [DEBUG] switch_core_media.c:8452 sofia/internal/2600@192.168.0.12 Set 2833 dtmf send payload to 101 2017-07-29 22:11:19.122439 [DEBUG] switch_core_media.c:8459 sofia/internal/2600@192.168.0.12 Set 2833 dtmf receive payload to 101 2017-07-29 22:11:19.122439 [DEBUG] switch_core_media.c:8482 sofia/internal/2600@192.168.0.12 Set rtp dtmf delay to 40 2017-07-29 22:11:19.142477 [NOTICE] sofia.c:8419 Channel [sofia/internal/2600@192.168.0.12] has been answered 2017-07-29 22:11:19.142477 [DEBUG] switch_core_codec.c:248 sofia/external/9185330000@45.55.163.124 Restore previous codec PCMU:0. 2017-07-29 22:11:19.142477 [DEBUG] switch_core_media.c:8132 Audio params are unchanged for sofia/external/9185330000@45.55.163.124. 2017-07-29 22:11:19.142477 [DEBUG] mod_sofia.c:881 Local SDP sofia/external/9185330000@45.55.163.124: v=0 o=FreeSWITCH 1501368757 1501368759 IN IP4 freeswitch.example.com s=FreeSWITCH c=IN IP4 freeswitch.example.com t=0 0 m=audio 22720 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv send 1020 bytes to tcp/[45.55.163.124]:5060 at 22:11:19.149180: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 45.55.163.124:5060;alias;rport=5060;branch=z9hG4bK1059959625 From: "TULSA, OK" ;tag=916891763 To: ;tag=SNgK5vtHUKjtj Call-ID: 1538561599@45.55.163.124 CSeq: 644 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170728T230550Z~144d3733cf~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 232 Remote-Party-ID: "Outbound Call" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1501368757 1501368758 IN IP4 freeswitch.example.com s=FreeSWITCH c=IN IP4 freeswitch.example.com t=0 0 m=audio 22720 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2017-07-29 22:11:19.142477 [NOTICE] switch_ivr_originate.c:3652 Channel [sofia/external/9185330000@45.55.163.124] has been answered 2017-07-29 22:11:19.142477 [DEBUG] switch_channel.c:3781 (sofia/internal/2600@192.168.0.12) Callstate Change RINGING -> ACTIVE 2017-07-29 22:11:19.142477 [DEBUG] switch_channel.c:3781 (sofia/external/9185330000@45.55.163.124) Callstate Change EARLY -> ACTIVE 2017-07-29 22:11:19.142477 [DEBUG] sofia.c:7283 Channel sofia/external/9185330000@45.55.163.124 entering state [completed][200] 2017-07-29 22:11:19.142477 [DEBUG] switch_ivr_originate.c:3710 Originate Resulted in Success: [sofia/internal/2600@192.168.0.12] 2017-07-29 22:11:19.162461 [DEBUG] switch_ivr_originate.c:3710 Originate Resulted in Success: [sofia/internal/2600@192.168.0.12] 2017-07-29 22:11:19.162461 [DEBUG] switch_ivr_bridge.c:1744 (sofia/internal/2600@192.168.0.12) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2017-07-29 22:11:19.162461 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/2600@192.168.0.12) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 183) 2017-07-29 22:11:19.162461 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/2600@192.168.0.12) State EXCHANGE_MEDIA 2017-07-29 22:11:19.162461 [DEBUG] mod_sofia.c:645 SOFIA EXCHANGE_MEDIA recv 436 bytes from tcp/[45.55.163.124]:5060 at 22:11:19.267307: ------------------------------------------------------------------------ ACK sip:gw+GVGW@freeswitch.example.com:5080;transport=udp SIP/2.0 Via: SIP/2.0/TCP 45.55.163.124:5060;alias;rport;branch=z9hG4bK973542075 From: "TULSA, OK" ;tag=916891763 To: ;tag=SNgK5vtHUKjtj Call-ID: 1538561599@45.55.163.124 CSeq: 644 ACK Max-Forwards: 19 Contact: User-Agent: GVGW Content-Length: 0 ------------------------------------------------------------------------ 2017-07-29 22:11:19.262445 [DEBUG] switch_rtp.c:7338 Correct audio ip/port confirmed. 2017-07-29 22:11:19.282554 [DEBUG] sofia.c:7283 Channel sofia/external/9185330000@45.55.163.124 entering state [ready][200] send 932 bytes to udp/[192.168.0.12]:5060 at 22:11:19.301092: ------------------------------------------------------------------------ UPDATE sip:2600@192.168.0.12 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.137;rport;branch=z9hG4bKyyrmm6rBHQr7j Max-Forwards: 70 From: "TULSA, OK" ;tag=gBDSptpK0j5cS To: ;tag=1C93D4ED-1D331DFE Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5 CSeq: 110359675 UPDATE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170728T230550Z~144d3733cf~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Type: application/sdp Content-Disposition: session Content-Length: 222 P-Asserted-Identity: "TULSA, OK" <9185330000> v=0 o=FreeSWITCH 1501362548 1501362549 IN IP4 192.168.0.137 s=FreeSWITCH c=IN IP4 192.168.0.137 t=0 0 m=audio 28928 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2017-07-29 22:11:19.302474 [DEBUG] sofia.c:7283 Channel sofia/internal/2600@192.168.0.12 entering state [calling][0] recv 630 bytes from udp/[192.168.0.12]:5060 at 22:11:19.320683: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.137;rport;branch=z9hG4bKyyrmm6rBHQr7j From: "TULSA, OK" ;tag=gBDSptpK0j5cS To: "jungle boogie" ;tag=1C93D4ED-1D331DFE CSeq: 110359675 UPDATE Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5 Contact: User-Agent: PolycomVVX-VVX_410-UA/5.5.1.12442 Accept-Language: en Content-Type: application/sdp Content-Length: 187 v=0 o=- 1501391478 1501391478 IN IP4 192.168.0.12 s=Polycom IP Phone c=IN IP4 192.168.0.12 t=0 0 m=audio 2244 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 ------------------------------------------------------------------------ 2017-07-29 22:11:19.322471 [DEBUG] sofia.c:7283 Channel sofia/internal/2600@192.168.0.12 entering state [ready][200] 2017-07-29 22:11:19.322471 [DEBUG] sofia.c:7290 Duplicate SDP v=0 o=- 1501391478 1501391478 IN IP4 192.168.0.12 s=Polycom IP Phone c=IN IP4 192.168.0.12 t=0 0 m=audio 2244 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 2017-07-29 22:11:19.342497 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-07-29 22:11:19.342497 [DEBUG] switch_core_media.c:5170 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-07-29 22:11:19.342497 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-07-29 22:11:19.342497 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-07-29 22:11:19.342497 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-07-29 22:11:19.342497 [DEBUG] switch_core_media.c:5031 Set telephone-event payload to 101@8000 2017-07-29 22:11:19.342497 [DEBUG] switch_core_media.c:5374 Set telephone-event payload to 101@8000 2017-07-29 22:11:19.342497 [DEBUG] switch_core_media.c:5432 sofia/internal/2600@192.168.0.12 Set 2833 dtmf send payload to 101 recv payload to 101 2017-07-29 22:11:19.342497 [DEBUG] sofia.c:8262 Processing updated SDP 2017-07-29 22:11:19.342497 [DEBUG] switch_core_media.c:8132 Audio params are unchanged for sofia/internal/2600@192.168.0.12. recv 487 bytes from tcp/[45.55.163.124]:5060 at 22:11:19.506054: ------------------------------------------------------------------------ BYE sip:gw+GVGW@freeswitch.example.com:5080;transport=udp SIP/2.0 Call-ID: 1538561599@45.55.163.124 From: ;tag=916891763 To: ;tag=SNgK5vtHUKjtj P-RTP-Stat: PS=0,OS=0,PR=108,OR=17280,PL=0 Via: SIP/2.0/TCP 45.55.163.124:5060;alias;rport;branch=z9hG4bK198276461 CSeq: 645 BYE User-Agent: GVGW Max-Forwards: 70 Allow: ACK, INVITE, BYE, CANCEL, REGISTER, REFER, OPTIONS, INFO Content-Length: 0 ------------------------------------------------------------------------ 2017-07-29 22:11:19.522526 [NOTICE] sofia.c:1079 Hangup sofia/external/9185330000@45.55.163.124 [CS_EXECUTE] [NORMAL_CLEARING] send 502 bytes to tcp/[45.55.163.124]:5060 at 22:11:19.535354: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 45.55.163.124:5060;alias;rport=5060;branch=z9hG4bK198276461 From: ;tag=916891763 To: ;tag=SNgK5vtHUKjtj Call-ID: 1538561599@45.55.163.124 CSeq: 645 BYE User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170728T230550Z~144d3733cf~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2017-07-29 22:11:19.522526 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/external/9185330000@45.55.163.124] 2017-07-29 22:11:19.522526 [DEBUG] switch_ivr_bridge.c:825 sofia/external/9185330000@45.55.163.124 ending bridge by request from write function 2017-07-29 22:11:19.542459 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/internal/2600@192.168.0.12] 2017-07-29 22:11:19.542459 [NOTICE] switch_ivr_bridge.c:1034 Hangup sofia/internal/2600@192.168.0.12 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/2600@192.168.0.12) State EXCHANGE_MEDIA going to sleep 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/2600@192.168.0.12) Running State Change CS_HANGUP (Cur 2 Tot 183) 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/2600@192.168.0.12) Callstate Change ACTIVE -> HANGUP 2017-07-29 22:11:19.542459 [DEBUG] switch_ivr_bridge.c:1843 sofia/internal/2600@192.168.0.12 skip receive message [TRANSFER] (channel is hungup already) 2017-07-29 22:11:19.542459 [DEBUG] switch_ivr_bridge.c:1846 sofia/external/9185330000@45.55.163.124 skip receive message [TRANSFER] (channel is hungup already) 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/2600@192.168.0.12) State HANGUP 2017-07-29 22:11:19.542459 [DEBUG] mod_sofia.c:443 sofia/internal/2600@192.168.0.12 Overriding SIP cause 480 with 200 from the other leg 2017-07-29 22:11:19.542459 [DEBUG] mod_sofia.c:449 Channel sofia/internal/2600@192.168.0.12 hanging up, cause: NORMAL_CLEARING 2017-07-29 22:11:19.542459 [DEBUG] switch_core_session.c:2885 sofia/external/9185330000@45.55.163.124 skip receive message [PHONE_EVENT] (channel is hungup already) 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:650 (sofia/external/9185330000@45.55.163.124) State EXECUTE going to sleep 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:584 (sofia/external/9185330000@45.55.163.124) Running State Change CS_HANGUP (Cur 2 Tot 183) 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:850 (sofia/external/9185330000@45.55.163.124) Callstate Change ACTIVE -> HANGUP 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:852 (sofia/external/9185330000@45.55.163.124) State HANGUP 2017-07-29 22:11:19.542459 [DEBUG] mod_sofia.c:449 Channel sofia/external/9185330000@45.55.163.124 hanging up, cause: NORMAL_CLEARING 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:60 sofia/external/9185330000@45.55.163.124 Standard HANGUP, cause: NORMAL_CLEARING 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:852 (sofia/external/9185330000@45.55.163.124) State HANGUP going to sleep 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:619 (sofia/external/9185330000@45.55.163.124) State Change CS_HANGUP -> CS_REPORTING 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:584 (sofia/external/9185330000@45.55.163.124) Running State Change CS_REPORTING (Cur 2 Tot 183) 2017-07-29 22:11:19.542459 [DEBUG] mod_sofia.c:502 Sending BYE to sofia/internal/2600@192.168.0.12 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:60 sofia/internal/2600@192.168.0.12 Standard HANGUP, cause: NORMAL_CLEARING 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/2600@192.168.0.12) State HANGUP going to sleep 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:938 (sofia/external/9185330000@45.55.163.124) State REPORTING 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/2600@192.168.0.12) State Change CS_HANGUP -> CS_REPORTING send 640 bytes to udp/[192.168.0.12]:5060 at 22:11:19.554862: ------------------------------------------------------------------------ BYE sip:2600@192.168.0.12 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.137;rport;branch=z9hG4bKZ7HDp19ee0ete Max-Forwards: 70 From: "TULSA, OK" ;tag=gBDSptpK0j5cS To: ;tag=1C93D4ED-1D331DFE Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5 CSeq: 110359676 BYE User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170728T230550Z~144d3733cf~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 P-RTP-Stat: PS=0,OS=0,PR=108,OR=17280,PL=0 ------------------------------------------------------------------------ 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/2600@192.168.0.12) Running State Change CS_REPORTING (Cur 2 Tot 183) 2017-07-29 22:11:19.542459 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/2600@192.168.0.12) State REPORTING recv 407 bytes from udp/[192.168.0.12]:5060 at 22:11:19.570575: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.137;rport;branch=z9hG4bKZ7HDp19ee0ete From: "TULSA, OK" ;tag=gBDSptpK0j5cS To: "jungle boogie" ;tag=1C93D4ED-1D331DFE CSeq: 110359676 BYE Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5 Contact: User-Agent: PolycomVVX-VVX_410-UA/5.5.1.12442 Accept-Language: en Content-Length: 0 ------------------------------------------------------------------------ 2017-07-29 22:11:19.582509 [DEBUG] mod_cdr_sqlite.c:102 Writing SQL to DB: INSERT INTO cdr VALUES ("TULSA, OK","9185330000","2600","default","2017-07-29 22:11:16","2017-07-29 22:11:19", "2017-07-29 22:11:19",3, 0, 0,"NORMAL_CLEARING","83f80248-74e5-11e7-b792-c1f435f54e69","","2600","PCMU","PCMU", "send_bye","9185330000","homephone","ANSWER") 2017-07-29 22:11:19.582509 [DEBUG] switch_core_state_machine.c:174 sofia/internal/2600@192.168.0.12 Standard REPORTING, cause: NORMAL_CLEARING 2017-07-29 22:11:19.582509 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/2600@192.168.0.12) State REPORTING going to sleep 2017-07-29 22:11:19.582509 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/2600@192.168.0.12) State Change CS_REPORTING -> CS_DESTROY 2017-07-29 22:11:19.582509 [DEBUG] switch_core_session.c:1713 Session 183 (sofia/internal/2600@192.168.0.12) Locked, Waiting on external entities 2017-07-29 22:11:19.582509 [NOTICE] switch_core_session.c:1731 Session 183 (sofia/internal/2600@192.168.0.12) Ended 2017-07-29 22:11:19.582509 [NOTICE] switch_core_session.c:1735 Close Channel sofia/internal/2600@192.168.0.12 [CS_DESTROY] 2017-07-29 22:11:19.582509 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/2600@192.168.0.12) Running State Change CS_DESTROY (Cur 1 Tot 183) 2017-07-29 22:11:19.582509 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/2600@192.168.0.12) State DESTROY 2017-07-29 22:11:19.582509 [DEBUG] mod_sofia.c:354 sofia/internal/2600@192.168.0.12 SOFIA DESTROY 2017-07-29 22:11:19.582509 [DEBUG] switch_core_state_machine.c:181 sofia/internal/2600@192.168.0.12 Standard DESTROY 2017-07-29 22:11:19.582509 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/2600@192.168.0.12) State DESTROY going to sleep 2017-07-29 22:11:19.582509 [DEBUG] mod_cdr_sqlite.c:102 Writing SQL to DB: INSERT INTO cdr VALUES ("TULSA, OK","9185330000","2600","default","2017-07-29 22:11:16","2017-07-29 22:11:19", "2017-07-29 22:11:19",3, 0, 0,"NORMAL_CLEARING","83ec6834-74e5-11e7-b772-c1f435f54e69","83f80248-74e5-11e7-b792-c1f435f54e69","","PCMU","PCMU", "recv_bye","9185330000","","ANSWER") 2017-07-29 22:11:19.582509 [DEBUG] switch_core_state_machine.c:174 sofia/external/9185330000@45.55.163.124 Standard REPORTING, cause: NORMAL_CLEARING 2017-07-29 22:11:19.582509 [DEBUG] switch_core_state_machine.c:938 (sofia/external/9185330000@45.55.163.124) State REPORTING going to sleep 2017-07-29 22:11:19.582509 [DEBUG] switch_core_state_machine.c:610 (sofia/external/9185330000@45.55.163.124) State Change CS_REPORTING -> CS_DESTROY 2017-07-29 22:11:19.582509 [DEBUG] switch_core_session.c:1713 Session 182 (sofia/external/9185330000@45.55.163.124) Locked, Waiting on external entities 2017-07-29 22:11:19.582509 [NOTICE] switch_core_session.c:1731 Session 182 (sofia/external/9185330000@45.55.163.124) Ended 2017-07-29 22:11:19.582509 [NOTICE] switch_core_session.c:1735 Close Channel sofia/external/9185330000@45.55.163.124 [CS_DESTROY] 2017-07-29 22:11:19.602490 [DEBUG] switch_core_state_machine.c:741 (sofia/external/9185330000@45.55.163.124) Running State Change CS_DESTROY (Cur 0 Tot 183) 2017-07-29 22:11:19.602490 [DEBUG] switch_core_state_machine.c:751 (sofia/external/9185330000@45.55.163.124) State DESTROY 2017-07-29 22:11:19.602490 [DEBUG] mod_sofia.c:354 sofia/external/9185330000@45.55.163.124 SOFIA DESTROY 2017-07-29 22:11:19.662461 [DEBUG] switch_nat.c:568 unmapped public port 22720 protocol UDP to localport 22720 2017-07-29 22:11:19.742470 [DEBUG] switch_core_state_machine.c:181 sofia/external/9185330000@45.55.163.124 Standard DESTROY 2017-07-29 22:11:19.742470 [DEBUG] switch_core_state_machine.c:751 (sofia/external/9185330000@45.55.163.124) State DESTROY going to sleep