+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" <sip:9185330000@45.55.163.124>;tag=916891763
To: <sip:gw+GVGW@freeswitch.example.com:5080;transport=tcp;gw=GVGW>
Call-ID: 1538561599@45.55.163.124
CSeq: 644 INVITE
User-Agent: GVGW
Contact: <sip:9185330000@45.55.163.124:5060>
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" <sip:9185330000@45.55.163.124>;tag=916891763
To: <sip:gw+GVGW@freeswitch.example.com:5080;transport=tcp;gw=GVGW>
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" <sip:9185330000@192.168.0.137>;tag=gBDSptpK0j5cS
To: <sip:2600@192.168.0.12>
Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5
CSeq: 110359674 INVITE
Contact: <sip:mod_sofia@192.168.0.137:5060>
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" <sip:9185330000@192.168.0.137>;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" <sip:9185330000@192.168.0.137>;tag=gBDSptpK0j5cS
To: "jungle boogie" <sip:2600@192.168.0.12>;tag=1C93D4ED-1D331DFE
CSeq: 110359674 INVITE
Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5
Contact: <sip:2600@192.168.0.12>
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" <sip:9185330000@192.168.0.137>;tag=gBDSptpK0j5cS
To: "jungle boogie" <sip:2600@192.168.0.12>;tag=1C93D4ED-1D331DFE
CSeq: 110359674 INVITE
Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5
Contact: <sip:2600@192.168.0.12>
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" <sip:9185330000@45.55.163.124>;tag=916891763
To: <sip:gw+GVGW@freeswitch.example.com:5080;transport=tcp;gw=GVGW>;tag=SNgK5vtHUKjtj
Call-ID: 1538561599@45.55.163.124
CSeq: 644 INVITE
Contact: <sip:gw+GVGW@freeswitch.example.com:5080;transport=udp>
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" <sip:12130000000@freeswitch.example.com>;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" <sip:9185330000@192.168.0.137>;tag=gBDSptpK0j5cS
To: "jungle boogie" <sip:2600@192.168.0.12>;tag=1C93D4ED-1D331DFE
CSeq: 110359674 INVITE
Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5
Contact: <sip:2600@192.168.0.12>
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" <sip:9185330000@192.168.0.137>;tag=gBDSptpK0j5cS
To: <sip:2600@192.168.0.12>;tag=1C93D4ED-1D331DFE
Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5
CSeq: 110359674 ACK
Contact: <sip:mod_sofia@192.168.0.137:5060>
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" <sip:9185330000@45.55.163.124>;tag=916891763
To: <sip:gw+GVGW@freeswitch.example.com:5080;transport=tcp;gw=GVGW>;tag=SNgK5vtHUKjtj
Call-ID: 1538561599@45.55.163.124
CSeq: 644 INVITE
Contact: <sip:gw+GVGW@freeswitch.example.com:5080;transport=udp>
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" <sip:2600@freeswitch.example.com>;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" <sip:9185330000@45.55.163.124>;tag=916891763
To: <sip:gw+GVGW@freeswitch.example.com:5080;transport=tcp;gw=GVGW>;tag=SNgK5vtHUKjtj
Call-ID: 1538561599@45.55.163.124
CSeq: 644 ACK
Max-Forwards: 19
Contact: <sip:9185330000@45.55.163.124:5060>
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" <sip:9185330000@192.168.0.137>;tag=gBDSptpK0j5cS
To: <sip:2600@192.168.0.12>;tag=1C93D4ED-1D331DFE
Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5
CSeq: 110359675 UPDATE
Contact: <sip:mod_sofia@192.168.0.137:5060>
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" <sip:9185330000@192.168.0.137>;tag=gBDSptpK0j5cS
To: "jungle boogie" <sip:2600@192.168.0.12>;tag=1C93D4ED-1D331DFE
CSeq: 110359675 UPDATE
Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5
Contact: <sip:2600@192.168.0.12>
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: <sip:9185330000@45.55.163.124>;tag=916891763
To: <sip:gw+GVGW@freeswitch.example.com:5080;transport=tcp;gw=GVGW>;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: <sip:9185330000@45.55.163.124>;tag=916891763
To: <sip:gw+GVGW@freeswitch.example.com:5080;transport=tcp;gw=GVGW>;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" <sip:9185330000@192.168.0.137>;tag=gBDSptpK0j5cS
To: <sip:2600@192.168.0.12>;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" <sip:9185330000@192.168.0.137>;tag=gBDSptpK0j5cS
To: "jungle boogie" <sip:2600@192.168.0.12>;tag=1C93D4ED-1D331DFE
CSeq: 110359676 BYE
Call-ID: 5b57784a-ef88-1235-0696-b827eb21ced5
Contact: <sip:2600@192.168.0.12>
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