recv 796 bytes from udp/[183.82.203.220]:23502 at 12:34:12.381923: ------------------------------------------------------------------------ INVITE sip:1000@159.89.163.195:5020 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.4:64343;branch=z9hG4bK-524287-1---f7a8f15b6eab5e05;rport Max-Forwards: 70 Contact: To: From: "1000";tag=e2818c43 Call-ID: 92627YjA3OTQ1NGE2MmZlZmI1NDNkNzhlNTcyODM4ZjU5MWQ CSeq: 1 INVITE Allow: SUBSCRIBE, NOTIFY, INVITE, ACK, CANCEL, BYE, REFER, INFO, OPTIONS, MESSAGE Content-Type: application/sdp Supported: replaces User-Agent: X-Lite release 5.3.2 stamp 92627 Content-Length: 207 v=0 o=- 13185394425892273 1 IN IP4 192.168.1.4 s=X-Lite release 5.3.2 stamp 92627 c=IN IP4 192.168.1.4 t=0 0 m=audio 64120 RTP/AVP 0 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv ------------------------------------------------------------------------ 2018-10-30 12:34:12.374828 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1000@159.89.163.195:5020 [b518fc28-5c14-4367-9326-94767a8e0783] 2018-10-30 12:34:12.374828 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@159.89.163.195:5020) Running State Change CS_NEW (Cur 1 Tot 24) 2018-10-30 12:34:12.374828 [DEBUG] sofia.c:10080 sofia/internal/1000@159.89.163.195:5020 receiving invite from 183.82.203.220:23502 version: 1.8.2 git a98a958 2018-09-26 17:55:25Z 64bit 2018-10-30 12:34:12.374828 [DEBUG] sofia.c:10251 IP 183.82.203.220 Rejected by acl "domains". Falling back to Digest auth. send 907 bytes to udp/[183.82.203.220]:23502 at 12:34:12.382884: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.4:64343;branch=z9hG4bK-524287-1---f7a8f15b6eab5e05;rport=23502;received=183.82.203.220 From: "1000";tag=e2818c43 To: ;tag=FZp4N5p5B3trK Call-ID: 92627YjA3OTQ1NGE2MmZlZmI1NDNkNzhlNTcyODM4ZjU5MWQ CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.8.2+git~20180926T175525Z~a98a958ac3~64bit Accept: application/sdp 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 Proxy-Authenticate: Digest realm="159.89.163.195", nonce="3d21ebdb-1f85-4cfa-b808-5ebb75c487ff", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ 2018-10-30 12:34:12.374828 [DEBUG] sofia.c:2413 detaching session b518fc28-5c14-4367-9326-94767a8e0783 2018-10-30 12:34:12.374828 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1000@159.89.163.195:5020) State NEW recv 349 bytes from udp/[183.82.203.220]:23502 at 12:34:12.410143: ------------------------------------------------------------------------ ACK sip:1000@159.89.163.195:5020 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.4:64343;branch=z9hG4bK-524287-1---f7a8f15b6eab5e05;rport Max-Forwards: 70 To: ;tag=FZp4N5p5B3trK From: "1000";tag=e2818c43 Call-ID: 92627YjA3OTQ1NGE2MmZlZmI1NDNkNzhlNTcyODM4ZjU5MWQ CSeq: 1 ACK Content-Length: 0 ------------------------------------------------------------------------ recv 1065 bytes from udp/[183.82.203.220]:23502 at 12:34:12.412418: ------------------------------------------------------------------------ INVITE sip:1000@159.89.163.195:5020 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.4:64343;branch=z9hG4bK-524287-1---ad06303728d3f229;rport Max-Forwards: 70 Contact: To: From: "1000";tag=e2818c43 Call-ID: 92627YjA3OTQ1NGE2MmZlZmI1NDNkNzhlNTcyODM4ZjU5MWQ CSeq: 2 INVITE Allow: SUBSCRIBE, NOTIFY, INVITE, ACK, CANCEL, BYE, REFER, INFO, OPTIONS, MESSAGE Content-Type: application/sdp Proxy-Authorization: Digest username="1000",realm="159.89.163.195",nonce="3d21ebdb-1f85-4cfa-b808-5ebb75c487ff",uri="sip:1000@159.89.163.195:5020",response="51408f634a6b75ba28e86588ed92fb0e",cnonce="b2f918df319453bb78cab0b218f67280",nc=00000001,qop=auth,algorithm=MD5 Supported: replaces User-Agent: X-Lite release 5.3.2 stamp 92627 Content-Length: 207 v=0 o=- 13185394425892273 1 IN IP4 192.168.1.4 s=X-Lite release 5.3.2 stamp 92627 c=IN IP4 192.168.1.4 t=0 0 m=audio 64120 RTP/AVP 0 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv ------------------------------------------------------------------------ 2018-10-30 12:34:12.404804 [DEBUG] sofia.c:2522 Re-attaching to session b518fc28-5c14-4367-9326-94767a8e0783 2018-10-30 12:34:12.414811 [DEBUG] sofia.c:10080 sofia/internal/1000@159.89.163.195:5020 receiving invite from 183.82.203.220:23502 version: 1.8.2 git a98a958 2018-09-26 17:55:25Z 64bit 2018-10-30 12:34:12.414811 [DEBUG] sofia.c:10251 IP 183.82.203.220 Rejected by acl "domains". Falling back to Digest auth. 2018-10-30 12:34:12.414811 [DEBUG] sofia.c:11388 Setting NAT mode based on nat.auto 2018-10-30 12:34:12.414811 [DEBUG] sofia.c:7291 Channel sofia/internal/1000@159.89.163.195:5020 entering state [received][100] 2018-10-30 12:34:12.414811 [DEBUG] sofia.c:7301 Remote SDP: v=0 o=- 13185394425892273 1 IN IP4 192.168.1.4 s=X-Lite release 5.3.2 stamp 92627 c=IN IP4 192.168.1.4 t=0 0 m=audio 64120 RTP/AVP 0 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 2018-10-30 12:34:12.414811 [DEBUG] sofia.c:7695 (sofia/internal/1000@159.89.163.195:5020) State Change CS_NEW -> CS_INIT 2018-10-30 12:34:12.414811 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@159.89.163.195:5020) Running State Change CS_INIT (Cur 1 Tot 24) 2018-10-30 12:34:12.414811 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1000@159.89.163.195:5020) State INIT 2018-10-30 12:34:12.414811 [DEBUG] mod_sofia.c:93 sofia/internal/1000@159.89.163.195:5020 SOFIA INIT 2018-10-30 12:34:12.414811 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1000@159.89.163.195:5020 Standard INIT 2018-10-30 12:34:12.414811 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1000@159.89.163.195:5020) State Change CS_INIT -> CS_ROUTING 2018-10-30 12:34:12.414811 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1000@159.89.163.195:5020) State INIT going to sleep 2018-10-30 12:34:12.414811 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@159.89.163.195:5020) Running State Change CS_ROUTING (Cur 1 Tot 24) 2018-10-30 12:34:12.414811 [DEBUG] switch_channel.c:2249 (sofia/internal/1000@159.89.163.195:5020) Callstate Change DOWN -> RINGING 2018-10-30 12:34:12.414811 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1000@159.89.163.195:5020) State ROUTING send 402 bytes to udp/[183.82.203.220]:23502 at 12:34:12.424720: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.4:64343;branch=z9hG4bK-524287-1---ad06303728d3f229;rport=23502;received=183.82.203.220 From: "1000";tag=e2818c43 To: Call-ID: 92627YjA3OTQ1NGE2MmZlZmI1NDNkNzhlNTcyODM4ZjU5MWQ CSeq: 2 INVITE User-Agent: FreeSWITCH-mod_sofia/1.8.2+git~20180926T175525Z~a98a958ac3~64bit Content-Length: 0 ------------------------------------------------------------------------ 2018-10-30 12:34:12.424808 [DEBUG] mod_sofia.c:154 sofia/internal/1000@159.89.163.195:5020 SOFIA ROUTING 2018-10-30 12:34:12.424808 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1000@159.89.163.195:5020 Standard ROUTING 2018-10-30 12:34:12.424808 [INFO] mod_dialplan_xml.c:637 Processing 1000 <1000>->1000 in context default Dialplan: sofia/internal/1000@159.89.163.195:5020 parsing [default->ee634e42-e806-4e15-9abe-969d09a3eb33] continue=false Dialplan: sofia/internal/1000@159.89.163.195:5020 Regex (PASS) [ee634e42-e806-4e15-9abe-969d09a3eb33] destination_number(1000) =~ /^1000$/ break=on-false Dialplan: sofia/internal/1000@159.89.163.195:5020 Action clear_digit_action(all) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action export(bind_digit_digit_timeout=200) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action unset(sip_h_X-Weave-DC) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action unset(sip_h_X-Loop-Data) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action unset(sip_h_X-Weave-External) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action unset(sip_h_X-Weave-Internal) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action unset(sip_h_X-Weave-Outbound) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action export(weave_domain=dev-scott) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action export(w_domain=dev-scott.getweave.io) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action export(selected_carrier=twilio) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_log=true) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_direction=inbound) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_dialed_number=8017970178) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_caller_name=Weave ) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_caller_number=7164186158) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_auto_sms_webhook_url=http://admin-api.client:8000/portal/v1/phones/missedcall) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_auto_sms_webhook_key=4G7tEQa0CQB8XlXs-JkdiP3AFRBT3pIrG-hm0k1GK4QZMBzMM4) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action limit(hash dev-scott.getweave.io inbound 10 inbound_exceeded) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(w_cdr_originator=7164186158) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(w_cdr_destination=8017970178) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(w_cdr_direction=inbound) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(w_call_direction=inbound) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(RECORD_STEREO=true) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(media_bug_answer_req=true) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(recording_follow_transfer=true) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(record_post_process_exec_app=bgsystem:curl -d '/temp_recordings/dev-scott_2018-10-30_ee634e42-e806-4e15-9abe-969d09a3eb33.mp3' 'http:///pub?topic=CallRecording') Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(execute_on_answer=record_session /temp_recordings/dev-scott_2018-10-30_ee634e42-e806-4e15-9abe-969d09a3eb33.mp3) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action export(location_id=94472cd8-2b1c-4b44-94fe-9708c2bd739d) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(weave_lookup_number=${caller_id_number}) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(continue_on_fail=true) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(hangup_after_bridge=true) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(hold_music=local_stream://moh) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(temp_hold_music=local_stream://moh) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_slug=dev-scott) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(generated_channel_id_eschmidbauer02_dev-scott=1a9b5231-e815-4aba-900d-ecf1089e848f) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_sip_id_eschmidbauer02_dev-scott=44ea632a-a36d-4f3e-b2cc-5272065d1d09) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_sip_name_eschmidbauer02_dev-scott=eschmidbauer02) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(generated_channel_id_eschmidbauer01_dev-scott=8f00162e-9926-4f19-a078-b88487aa6e58) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_sip_id_eschmidbauer01_dev-scott=126385ac-5c42-4b20-bc64-0eec19733a42) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_sip_name_eschmidbauer01_dev-scott=E-VVX400) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(generated_channel_id_xlite_dev-scott=f60035e5-788e-4acd-9d86-18f19ae75dec) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_sip_id_xlite_dev-scott=4073da9c-2359-4f2b-ae75-7fc06748ba78) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_sip_name_xlite_dev-scott=xlite) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(generated_channel_id_eschmidbauer03_dev-scott=f403f20c-cb2e-40f9-bde5-d1ad9e10616b) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_sip_id_eschmidbauer03_dev-scott=1fa6d75e-765e-4110-a8e1-13f7df9275c0) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_sip_name_eschmidbauer03_dev-scott=vvx500) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(generated_channel_id_testline05_dev-scott=3573a9a4-b04e-4ab1-92e8-dfaa401c1b85) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_sip_id_testline05_dev-scott=1b112711-e324-484a-bbc5-f17564d26935) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(cdr_sip_name_testline05_dev-scott=testline05) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(mobile_app=eschmidbauer01;xlite) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action set(desk_phone=eschmidbauer02;eschmidbauer03;testline05) Dialplan: sofia/internal/1000@159.89.163.195:5020 Action bridge({origination_uuid=14a8bd6f-af2e-4b1d-8d18-bd59d863387f}user/1003@${domain_name}) 2018-10-30 12:34:12.424808 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1000@159.89.163.195:5020) State Change CS_ROUTING -> CS_EXECUTE 2018-10-30 12:34:12.424808 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1000@159.89.163.195:5020) State ROUTING going to sleep 2018-10-30 12:34:12.424808 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@159.89.163.195:5020) Running State Change CS_EXECUTE (Cur 1 Tot 24) 2018-10-30 12:34:12.424808 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1000@159.89.163.195:5020) State EXECUTE 2018-10-30 12:34:12.424808 [DEBUG] mod_sofia.c:209 sofia/internal/1000@159.89.163.195:5020 SOFIA EXECUTE 2018-10-30 12:34:12.424808 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1000@159.89.163.195:5020 Standard EXECUTE EXECUTE sofia/internal/1000@159.89.163.195:5020 clear_digit_action(all) EXECUTE sofia/internal/1000@159.89.163.195:5020 export(bind_digit_digit_timeout=200) 2018-10-30 12:34:12.424808 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [bind_digit_digit_timeout]=[200] EXECUTE sofia/internal/1000@159.89.163.195:5020 unset(sip_h_X-Weave-DC) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1743 UNSET [sip_h_X-Weave-DC] EXECUTE sofia/internal/1000@159.89.163.195:5020 unset(sip_h_X-Loop-Data) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1743 UNSET [sip_h_X-Loop-Data] EXECUTE sofia/internal/1000@159.89.163.195:5020 unset(sip_h_X-Weave-External) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1743 UNSET [sip_h_X-Weave-External] EXECUTE sofia/internal/1000@159.89.163.195:5020 unset(sip_h_X-Weave-Internal) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1743 UNSET [sip_h_X-Weave-Internal] EXECUTE sofia/internal/1000@159.89.163.195:5020 unset(sip_h_X-Weave-Outbound) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1743 UNSET [sip_h_X-Weave-Outbound] EXECUTE sofia/internal/1000@159.89.163.195:5020 export(weave_domain=dev-scott) 2018-10-30 12:34:12.424808 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [weave_domain]=[dev-scott] EXECUTE sofia/internal/1000@159.89.163.195:5020 export(w_domain=dev-scott.getweave.io) 2018-10-30 12:34:12.424808 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [w_domain]=[dev-scott.getweave.io] EXECUTE sofia/internal/1000@159.89.163.195:5020 export(selected_carrier=twilio) 2018-10-30 12:34:12.424808 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [selected_carrier]=[twilio] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_log=true) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_log]=[true] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_direction=inbound) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_direction]=[inbound] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_dialed_number=8017970178) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_dialed_number]=[8017970178] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_caller_name=Weave ) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_caller_name]=[Weave ] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_caller_number=7164186158) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_caller_number]=[7164186158] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_auto_sms_webhook_url=http://admin-api.client:8000/portal/v1/phones/missedcall) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_auto_sms_webhook_url]=[http://admin-api.client:8000/portal/v1/phones/missedcall] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_auto_sms_webhook_key=4G7tEQa0CQB8XlXs-JkdiP3AFRBT3pIrG-hm0k1GK4QZMBzMM4) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_auto_sms_webhook_key]=[4G7tEQa0CQB8XlXs-JkdiP3AFRBT3pIrG-hm0k1GK4QZMBzMM4] EXECUTE sofia/internal/1000@159.89.163.195:5020 limit(hash dev-scott.getweave.io inbound 10 inbound_exceeded) 2018-10-30 12:34:12.424808 [DEBUG] switch_limit.c:126 incr called: dev-scott.getweave.io_inbound max:10, interval:0 2018-10-30 12:34:12.424808 [DEBUG] mod_hash.c:196 Usage for dev-scott.getweave.io_inbound is now 1/10 EXECUTE sofia/internal/1000@159.89.163.195:5020 set(w_cdr_originator=7164186158) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [w_cdr_originator]=[7164186158] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(w_cdr_destination=8017970178) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [w_cdr_destination]=[8017970178] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(w_cdr_direction=inbound) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [w_cdr_direction]=[inbound] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(w_call_direction=inbound) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [w_call_direction]=[inbound] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(RECORD_STEREO=true) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [RECORD_STEREO]=[true] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(media_bug_answer_req=true) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [media_bug_answer_req]=[true] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(recording_follow_transfer=true) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [recording_follow_transfer]=[true] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(record_post_process_exec_app=bgsystem:curl -d '/temp_recordings/dev-scott_2018-10-30_ee634e42-e806-4e15-9abe-969d09a3eb33.mp3' 'http:///pub?topic=CallRecording') 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [record_post_process_exec_app]=[bgsystem:curl -d '/temp_recordings/dev-scott_2018-10-30_ee634e42-e806-4e15-9abe-969d09a3eb33.mp3' 'http:///pub?topic=CallRecording'] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(execute_on_answer=record_session /temp_recordings/dev-scott_2018-10-30_ee634e42-e806-4e15-9abe-969d09a3eb33.mp3) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [execute_on_answer]=[record_session /temp_recordings/dev-scott_2018-10-30_ee634e42-e806-4e15-9abe-969d09a3eb33.mp3] EXECUTE sofia/internal/1000@159.89.163.195:5020 export(location_id=94472cd8-2b1c-4b44-94fe-9708c2bd739d) 2018-10-30 12:34:12.424808 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [location_id]=[94472cd8-2b1c-4b44-94fe-9708c2bd739d] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(weave_lookup_number=1000) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [weave_lookup_number]=[1000] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(continue_on_fail=true) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [continue_on_fail]=[true] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(hangup_after_bridge=true) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [hangup_after_bridge]=[true] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(hold_music=local_stream://moh) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [hold_music]=[local_stream://moh] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(temp_hold_music=local_stream://moh) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [temp_hold_music]=[local_stream://moh] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_slug=dev-scott) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_slug]=[dev-scott] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(generated_channel_id_eschmidbauer02_dev-scott=1a9b5231-e815-4aba-900d-ecf1089e848f) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [generated_channel_id_eschmidbauer02_dev-scott]=[1a9b5231-e815-4aba-900d-ecf1089e848f] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_sip_id_eschmidbauer02_dev-scott=44ea632a-a36d-4f3e-b2cc-5272065d1d09) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_sip_id_eschmidbauer02_dev-scott]=[44ea632a-a36d-4f3e-b2cc-5272065d1d09] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_sip_name_eschmidbauer02_dev-scott=eschmidbauer02) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_sip_name_eschmidbauer02_dev-scott]=[eschmidbauer02] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(generated_channel_id_eschmidbauer01_dev-scott=8f00162e-9926-4f19-a078-b88487aa6e58) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [generated_channel_id_eschmidbauer01_dev-scott]=[8f00162e-9926-4f19-a078-b88487aa6e58] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_sip_id_eschmidbauer01_dev-scott=126385ac-5c42-4b20-bc64-0eec19733a42) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_sip_id_eschmidbauer01_dev-scott]=[126385ac-5c42-4b20-bc64-0eec19733a42] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_sip_name_eschmidbauer01_dev-scott=E-VVX400) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_sip_name_eschmidbauer01_dev-scott]=[E-VVX400] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(generated_channel_id_xlite_dev-scott=f60035e5-788e-4acd-9d86-18f19ae75dec) 2018-10-30 12:34:12.424808 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [generated_channel_id_xlite_dev-scott]=[f60035e5-788e-4acd-9d86-18f19ae75dec] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_sip_id_xlite_dev-scott=4073da9c-2359-4f2b-ae75-7fc06748ba78) 2018-10-30 12:34:12.434805 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_sip_id_xlite_dev-scott]=[4073da9c-2359-4f2b-ae75-7fc06748ba78] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_sip_name_xlite_dev-scott=xlite) 2018-10-30 12:34:12.434805 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_sip_name_xlite_dev-scott]=[xlite] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(generated_channel_id_eschmidbauer03_dev-scott=f403f20c-cb2e-40f9-bde5-d1ad9e10616b) 2018-10-30 12:34:12.434805 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [generated_channel_id_eschmidbauer03_dev-scott]=[f403f20c-cb2e-40f9-bde5-d1ad9e10616b] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_sip_id_eschmidbauer03_dev-scott=1fa6d75e-765e-4110-a8e1-13f7df9275c0) 2018-10-30 12:34:12.434805 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_sip_id_eschmidbauer03_dev-scott]=[1fa6d75e-765e-4110-a8e1-13f7df9275c0] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_sip_name_eschmidbauer03_dev-scott=vvx500) 2018-10-30 12:34:12.434805 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_sip_name_eschmidbauer03_dev-scott]=[vvx500] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(generated_channel_id_testline05_dev-scott=3573a9a4-b04e-4ab1-92e8-dfaa401c1b85) 2018-10-30 12:34:12.434805 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [generated_channel_id_testline05_dev-scott]=[3573a9a4-b04e-4ab1-92e8-dfaa401c1b85] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_sip_id_testline05_dev-scott=1b112711-e324-484a-bbc5-f17564d26935) 2018-10-30 12:34:12.434805 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_sip_id_testline05_dev-scott]=[1b112711-e324-484a-bbc5-f17564d26935] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(cdr_sip_name_testline05_dev-scott=testline05) 2018-10-30 12:34:12.434805 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [cdr_sip_name_testline05_dev-scott]=[testline05] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(mobile_app=eschmidbauer01;xlite) 2018-10-30 12:34:12.434805 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [mobile_app]=[eschmidbauer01;xlite] EXECUTE sofia/internal/1000@159.89.163.195:5020 set(desk_phone=eschmidbauer02;eschmidbauer03;testline05) 2018-10-30 12:34:12.434805 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1000@159.89.163.195:5020 [desk_phone]=[eschmidbauer02;eschmidbauer03;testline05] EXECUTE sofia/internal/1000@159.89.163.195:5020 bridge({origination_uuid=14a8bd6f-af2e-4b1d-8d18-bd59d863387f}user/1003@159.89.163.195) 2018-10-30 12:34:12.434805 [DEBUG] switch_channel.c:1250 sofia/internal/1000@159.89.163.195:5020 EXPORTING[export_vars] [bind_digit_digit_timeout]=[200] to event 2018-10-30 12:34:12.434805 [DEBUG] switch_channel.c:1250 sofia/internal/1000@159.89.163.195:5020 EXPORTING[export_vars] [weave_domain]=[dev-scott] to event 2018-10-30 12:34:12.434805 [DEBUG] switch_channel.c:1250 sofia/internal/1000@159.89.163.195:5020 EXPORTING[export_vars] [w_domain]=[dev-scott.getweave.io] to event 2018-10-30 12:34:12.434805 [DEBUG] switch_channel.c:1250 sofia/internal/1000@159.89.163.195:5020 EXPORTING[export_vars] [selected_carrier]=[twilio] to event 2018-10-30 12:34:12.434805 [DEBUG] switch_channel.c:1250 sofia/internal/1000@159.89.163.195:5020 EXPORTING[export_vars] [location_id]=[94472cd8-2b1c-4b44-94fe-9708c2bd739d] to event 2018-10-30 12:34:12.434805 [DEBUG] switch_ivr_originate.c:2204 Parsing global variables 2018-10-30 12:34:12.434805 [DEBUG] switch_channel.c:1250 sofia/internal/1000@159.89.163.195:5020 EXPORTING[export_vars] [bind_digit_digit_timeout]=[200] to event 2018-10-30 12:34:12.434805 [DEBUG] switch_channel.c:1250 sofia/internal/1000@159.89.163.195:5020 EXPORTING[export_vars] [weave_domain]=[dev-scott] to event 2018-10-30 12:34:12.434805 [DEBUG] switch_channel.c:1250 sofia/internal/1000@159.89.163.195:5020 EXPORTING[export_vars] [w_domain]=[dev-scott.getweave.io] to event 2018-10-30 12:34:12.434805 [DEBUG] switch_channel.c:1250 sofia/internal/1000@159.89.163.195:5020 EXPORTING[export_vars] [selected_carrier]=[twilio] to event 2018-10-30 12:34:12.434805 [DEBUG] switch_channel.c:1250 sofia/internal/1000@159.89.163.195:5020 EXPORTING[export_vars] [location_id]=[94472cd8-2b1c-4b44-94fe-9708c2bd739d] to event 2018-10-30 12:34:12.434805 [DEBUG] switch_ivr_originate.c:2204 Parsing global variables 2018-10-30 12:34:12.434805 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1003@183.82.203.220:23585 [14a8bd6f-af2e-4b1d-8d18-bd59d863387f] 2018-10-30 12:34:12.434805 [DEBUG] mod_sofia.c:5028 (sofia/internal/1003@183.82.203.220:23585) State Change CS_NEW -> CS_INIT 2018-10-30 12:34:12.434805 [DEBUG] switch_core_session.c:641 sofia/internal/1003@183.82.203.220:23585 set UUID=14a8bd6f-af2e-4b1d-8d18-bd59d863387f 2018-10-30 12:34:12.434805 [NOTICE] switch_ivr_originate.c:2944 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED] 2018-10-30 12:34:12.434805 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@183.82.203.220:23585) Running State Change CS_INIT (Cur 2 Tot 25) 2018-10-30 12:34:12.434805 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1003@183.82.203.220:23585) State INIT 2018-10-30 12:34:12.434805 [DEBUG] mod_sofia.c:93 sofia/internal/1003@183.82.203.220:23585 SOFIA INIT 2018-10-30 12:34:12.434805 [DEBUG] sofia_glue.c:1299 sofia/internal/1003@183.82.203.220:23585 sending invite version: 1.8.2 git a98a958 2018-09-26 17:55:25Z 64bit Local SDP: v=0 o=FreeSWITCH 1540898872 1540898873 IN IP4 159.89.163.195 s=FreeSWITCH c=IN IP4 159.89.163.195 t=0 0 m=audio 21980 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 1287 bytes to tcp/[183.82.203.220]:23585 at 12:34:12.440692: ------------------------------------------------------------------------ INVITE sip:1003@183.82.203.220:23585;transport=TCP;rinstance=eff915fadb99c0b0 SIP/2.0 Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKZj8KD3vXjaQ9p Max-Forwards: 69 From: "Extension 1000" ;tag=HH9NSUrc6m7Xa To: Call-ID: db3d7dda-570c-1237-2b97-528373432f88 CSeq: 130124362 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.8.2+git~20180926T175525Z~a98a958ac3~64bit 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: 224 X-FS-Support: update_display,send_info Remote-Party-ID: "Extension 1000" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1540898872 1540898873 IN IP4 159.89.163.195 s=FreeSWITCH c=IN IP4 159.89.163.195 t=0 0 m=audio 21980 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2018-10-30 12:34:12.434805 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1003@183.82.203.220:23585 Standard INIT 2018-10-30 12:34:12.434805 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1003@183.82.203.220:23585) State Change CS_INIT -> CS_ROUTING 2018-10-30 12:34:12.434805 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1003@183.82.203.220:23585) State INIT going to sleep 2018-10-30 12:34:12.434805 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@183.82.203.220:23585) Running State Change CS_ROUTING (Cur 2 Tot 25) 2018-10-30 12:34:12.434805 [DEBUG] sofia.c:7291 Channel sofia/internal/1003@183.82.203.220:23585 entering state [calling][0] 2018-10-30 12:34:12.434805 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1003@183.82.203.220:23585) State ROUTING 2018-10-30 12:34:12.434805 [DEBUG] mod_sofia.c:154 sofia/internal/1003@183.82.203.220:23585 SOFIA ROUTING 2018-10-30 12:34:12.434805 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1003@183.82.203.220:23585) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2018-10-30 12:34:12.434805 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1003@183.82.203.220:23585) State ROUTING going to sleep 2018-10-30 12:34:12.434805 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@183.82.203.220:23585) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 25) 2018-10-30 12:34:12.434805 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1003@183.82.203.220:23585) State CONSUME_MEDIA 2018-10-30 12:34:12.434805 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1003@183.82.203.220:23585) State CONSUME_MEDIA going to sleep recv 324 bytes from tcp/[183.82.203.220]:23585 at 12:34:13.118462: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKZj8KD3vXjaQ9p To: From: "Extension 1000" ;tag=HH9NSUrc6m7Xa Call-ID: db3d7dda-570c-1237-2b97-528373432f88 CSeq: 130124362 INVITE Content-Length: 0 ------------------------------------------------------------------------ recv 529 bytes from tcp/[183.82.203.220]:23585 at 12:34:13.928711: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKZj8KD3vXjaQ9p Contact: To: ;tag=435b9221 From: "Extension 1000" ;tag=HH9NSUrc6m7Xa Call-ID: db3d7dda-570c-1237-2b97-528373432f88 CSeq: 130124362 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE User-Agent: Zoiper rv2.8.109 Allow-Events: presence, kpml, talk Content-Length: 0 ------------------------------------------------------------------------ 2018-10-30 12:34:13.924820 [DEBUG] sofia.c:7291 Channel sofia/internal/1003@183.82.203.220:23585 entering state [proceeding][180] 2018-10-30 12:34:13.924820 [NOTICE] sofia.c:7401 Ring-Ready sofia/internal/1003@183.82.203.220:23585! 2018-10-30 12:34:13.924820 [DEBUG] switch_channel.c:3354 (sofia/internal/1003@183.82.203.220:23585) Callstate Change DOWN -> RINGING send 903 bytes to udp/[183.82.203.220]:23502 at 12:34:13.946352: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.4:64343;branch=z9hG4bK-524287-1---ad06303728d3f229;rport=23502;received=183.82.203.220 From: "1000";tag=e2818c43 To: ;tag=g8FXQ0788BHBF Call-ID: 92627YjA3OTQ1NGE2MmZlZmI1NDNkNzhlNTcyODM4ZjU5MWQ CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.8.2+git~20180926T175525Z~a98a958ac3~64bit Accept: application/sdp 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-Length: 0 Remote-Party-ID: "1000" ;party=calling;privacy=off;screen=no ------------------------------------------------------------------------ 2018-10-30 12:34:13.944813 [NOTICE] mod_sofia.c:2419 Ring-Ready sofia/internal/1000@159.89.163.195:5020! 2018-10-30 12:34:13.944813 [DEBUG] sofia.c:7291 Channel sofia/internal/1000@159.89.163.195:5020 entering state [early][180] 2018-10-30 12:34:13.944813 [NOTICE] switch_ivr_originate.c:553 Ring Ready sofia/internal/1000@159.89.163.195:5020! recv 802 bytes from tcp/[183.82.203.220]:23585 at 12:34:16.919063: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKZj8KD3vXjaQ9p Contact: To: ;tag=435b9221 From: "Extension 1000" ;tag=HH9NSUrc6m7Xa Call-ID: db3d7dda-570c-1237-2b97-528373432f88 CSeq: 130124362 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Content-Type: application/sdp User-Agent: Zoiper rv2.8.109 Allow-Events: presence, kpml, talk Content-Length: 245 v=0 o=Zoiper 0 2 IN IP4 183.82.203.220 s=Zoiper c=IN IP4 183.82.203.220 t=0 0 m=audio 24215 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv ------------------------------------------------------------------------ 2018-10-30 12:34:16.914819 [DEBUG] sofia.c:7291 Channel sofia/internal/1003@183.82.203.220:23585 entering state [completing][200] 2018-10-30 12:34:16.914819 [DEBUG] sofia.c:7301 Remote SDP: v=0 o=Zoiper 0 2 IN IP4 183.82.203.220 s=Zoiper c=IN IP4 183.82.203.220 t=0 0 m=audio 24215 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 2018-10-30 12:34:16.914819 [NOTICE] sofia.c:7304 Pre-Answer sofia/internal/1003@183.82.203.220:23585! 2018-10-30 12:34:16.914819 [DEBUG] switch_channel.c:3482 (sofia/internal/1003@183.82.203.220:23585) Callstate Change RINGING -> EARLY send 441 bytes to udp/[183.82.203.220]:23581 at 12:34:16.921025: ------------------------------------------------------------------------ ACK sip:1003@183.82.203.220:23581 SIP/2.0 Via: SIP/2.0/UDP 159.89.163.195:5020;rport;branch=z9hG4bK0U1cFyD1FKDvj Max-Forwards: 70 From: "Extension 1000" ;tag=HH9NSUrc6m7Xa To: ;tag=435b9221 Call-ID: db3d7dda-570c-1237-2b97-528373432f88 CSeq: 130124362 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ 2018-10-30 12:34:16.914819 [DEBUG] sofia.c:7291 Channel sofia/internal/1003@183.82.203.220:23585 entering state [ready][200] 2018-10-30 12:34:16.914819 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-10-30 12:34:16.914819 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2018-10-30 12:34:16.914819 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1] 2018-10-30 12:34:16.914819 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-10-30 12:34:16.914819 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000 2018-10-30 12:34:16.914819 [DEBUG] switch_core_media.c:3781 Set Codec sofia/internal/1003@183.82.203.220:23585 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2018-10-30 12:34:16.914819 [DEBUG] switch_core_codec.c:111 sofia/internal/1003@183.82.203.220:23585 Original read codec set to PCMU:0 2018-10-30 12:34:16.914819 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000 2018-10-30 12:34:16.914819 [DEBUG] switch_core_media.c:5795 sofia/internal/1003@183.82.203.220:23585 Set 2833 dtmf send payload to 101 recv payload to 101 2018-10-30 12:34:16.914819 [DEBUG] switch_core_media.c:8511 AUDIO RTP [sofia/internal/1003@183.82.203.220:23585] 159.89.163.195 port 21980 -> 183.82.203.220 port 24215 codec: 0 ms: 20 2018-10-30 12:34:16.914819 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 160 bytes per 20ms 2018-10-30 12:34:16.914819 [DEBUG] switch_core_media.c:8815 sofia/internal/1003@183.82.203.220:23585 Set 2833 dtmf send payload to 101 2018-10-30 12:34:16.914819 [DEBUG] switch_core_media.c:8822 sofia/internal/1003@183.82.203.220:23585 Set 2833 dtmf receive payload to 101 2018-10-30 12:34:16.914819 [DEBUG] switch_core_media.c:8845 sofia/internal/1003@183.82.203.220:23585 Set rtp dtmf delay to 40 2018-10-30 12:34:16.914819 [NOTICE] sofia.c:8429 Channel [sofia/internal/1003@183.82.203.220:23585] has been answered 2018-10-30 12:34:16.924812 [DEBUG] switch_channel.c:3781 (sofia/internal/1003@183.82.203.220:23585) Callstate Change EARLY -> ACTIVE 2018-10-30 12:34:16.934820 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2018-10-30 12:34:16.934820 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-10-30 12:34:16.934820 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-10-30 12:34:16.934820 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2018-10-30 12:34:16.934820 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-10-30 12:34:16.934820 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000 2018-10-30 12:34:16.934820 [DEBUG] switch_core_media.c:3781 Set Codec sofia/internal/1000@159.89.163.195:5020 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2018-10-30 12:34:16.934820 [DEBUG] switch_core_codec.c:111 sofia/internal/1000@159.89.163.195:5020 Original read codec set to PCMU:0 2018-10-30 12:34:16.934820 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000 2018-10-30 12:34:16.934820 [DEBUG] switch_core_media.c:5795 sofia/internal/1000@159.89.163.195:5020 Set 2833 dtmf send payload to 101 recv payload to 101 2018-10-30 12:34:16.934820 [DEBUG] switch_core_media.c:8511 AUDIO RTP [sofia/internal/1000@159.89.163.195:5020] 159.89.163.195 port 20662 -> 192.168.1.4 port 64120 codec: 0 ms: 20 2018-10-30 12:34:16.934820 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 160 bytes per 20ms 2018-10-30 12:34:16.934820 [DEBUG] switch_core_media.c:8815 sofia/internal/1000@159.89.163.195:5020 Set 2833 dtmf send payload to 101 2018-10-30 12:34:16.934820 [DEBUG] switch_core_media.c:8822 sofia/internal/1000@159.89.163.195:5020 Set 2833 dtmf receive payload to 101 2018-10-30 12:34:16.934820 [DEBUG] switch_core_media.c:8845 sofia/internal/1000@159.89.163.195:5020 Set rtp dtmf delay to 40 2018-10-30 12:34:16.934820 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1000@159.89.163.195:5020! 2018-10-30 12:34:16.934820 [DEBUG] switch_channel.c:3482 (sofia/internal/1000@159.89.163.195:5020) Callstate Change RINGING -> EARLY 2018-10-30 12:34:16.934820 [DEBUG] switch_core_media.c:8494 Audio params are unchanged for sofia/internal/1000@159.89.163.195:5020. 2018-10-30 12:34:16.934820 [DEBUG] mod_sofia.c:881 Local SDP sofia/internal/1000@159.89.163.195:5020: v=0 o=FreeSWITCH 1540900194 1540900195 IN IP4 159.89.163.195 s=FreeSWITCH c=IN IP4 159.89.163.195 t=0 0 m=audio 20662 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 1205 bytes to udp/[183.82.203.220]:23502 at 12:34:16.940321: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.4:64343;branch=z9hG4bK-524287-1---ad06303728d3f229;rport=23502;received=183.82.203.220 From: "1000";tag=e2818c43 To: ;tag=g8FXQ0788BHBF Call-ID: 92627YjA3OTQ1NGE2MmZlZmI1NDNkNzhlNTcyODM4ZjU5MWQ CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.8.2+git~20180926T175525Z~a98a958ac3~64bit 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 Session-Expires: 120;refresher=uas Content-Type: application/sdp Content-Disposition: session Content-Length: 224 Remote-Party-ID: "Outbound Call" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1540900194 1540900195 IN IP4 159.89.163.195 s=FreeSWITCH c=IN IP4 159.89.163.195 t=0 0 m=audio 20662 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2018-10-30 12:34:16.934820 [DEBUG] sofia.c:7291 Channel sofia/internal/1000@159.89.163.195:5020 entering state [completed][200] 2018-10-30 12:34:16.934820 [NOTICE] switch_ivr_originate.c:3740 Channel [sofia/internal/1000@159.89.163.195:5020] has been answered EXECUTE sofia/internal/1000@159.89.163.195:5020 record_session(/temp_recordings/dev-scott_2018-10-30_ee634e42-e806-4e15-9abe-969d09a3eb33.mp3) 2018-10-30 12:34:16.934820 [ERR] switch_core_file.c:301 Invalid file format [mp3] for [/temp_recordings/dev-scott_2018-10-30_ee634e42-e806-4e15-9abe-969d09a3eb33.mp3]! 2018-10-30 12:34:16.934820 [ERR] switch_ivr_async.c:2737 Error opening /temp_recordings/dev-scott_2018-10-30_ee634e42-e806-4e15-9abe-969d09a3eb33.mp3 2018-10-30 12:34:16.934820 [DEBUG] switch_channel.c:3781 (sofia/internal/1000@159.89.163.195:5020) Callstate Change EARLY -> ACTIVE 2018-10-30 12:34:16.934820 [DEBUG] switch_ivr_originate.c:3798 Originate Resulted in Success: [sofia/internal/1003@183.82.203.220:23585] 2018-10-30 12:34:16.934820 [DEBUG] switch_ivr_originate.c:3798 Originate Resulted in Success: [sofia/internal/1003@183.82.203.220:23585] 2018-10-30 12:34:16.944808 [DEBUG] switch_ivr_bridge.c:1782 (sofia/internal/1003@183.82.203.220:23585) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2018-10-30 12:34:16.944808 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@183.82.203.220:23585) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 25) 2018-10-30 12:34:16.944808 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1003@183.82.203.220:23585) State EXCHANGE_MEDIA 2018-10-30 12:34:16.944808 [DEBUG] mod_sofia.c:645 SOFIA EXCHANGE_MEDIA 2018-10-30 12:34:17.014814 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed. recv 478 bytes from udp/[183.82.203.220]:23502 at 12:34:17.056268: ------------------------------------------------------------------------ ACK sip:1000@159.89.163.195:5020;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.1.4:64343;branch=z9hG4bK-524287-1---2a69633807c6d734;rport Max-Forwards: 70 Contact: To: ;tag=g8FXQ0788BHBF From: "1000";tag=e2818c43 Call-ID: 92627YjA3OTQ1NGE2MmZlZmI1NDNkNzhlNTcyODM4ZjU5MWQ CSeq: 2 ACK User-Agent: X-Lite release 5.3.2 stamp 92627 Content-Length: 0 ------------------------------------------------------------------------ 2018-10-30 12:34:17.054818 [DEBUG] sofia.c:7291 Channel sofia/internal/1000@159.89.163.195:5020 entering state [ready][200] 2018-10-30 12:34:17.274823 [INFO] switch_rtp.c:7510 Auto Changing audio port from 192.168.1.4:64120 to 183.82.203.220:24218 recv 802 bytes from tcp/[183.82.203.220]:23585 at 12:34:17.342705: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKZj8KD3vXjaQ9p Contact: To: ;tag=435b9221 From: "Extension 1000" ;tag=HH9NSUrc6m7Xa Call-ID: db3d7dda-570c-1237-2b97-528373432f88 CSeq: 130124362 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Content-Type: application/sdp User-Agent: Zoiper rv2.8.109 Allow-Events: presence, kpml, talk Content-Length: 245 v=0 o=Zoiper 0 2 IN IP4 183.82.203.220 s=Zoiper c=IN IP4 183.82.203.220 t=0 0 m=audio 24215 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv ------------------------------------------------------------------------ send 441 bytes to udp/[183.82.203.220]:23581 at 12:34:17.342834: ------------------------------------------------------------------------ ACK sip:1003@183.82.203.220:23581 SIP/2.0 Via: SIP/2.0/UDP 159.89.163.195:5020;rport;branch=z9hG4bK0U1cFyD1FKDvj Max-Forwards: 70 From: "Extension 1000" ;tag=HH9NSUrc6m7Xa To: ;tag=435b9221 Call-ID: db3d7dda-570c-1237-2b97-528373432f88 CSeq: 130124362 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ recv 802 bytes from tcp/[183.82.203.220]:23585 at 12:34:18.346737: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKZj8KD3vXjaQ9p Contact: To: ;tag=435b9221 From: "Extension 1000" ;tag=HH9NSUrc6m7Xa Call-ID: db3d7dda-570c-1237-2b97-528373432f88 CSeq: 130124362 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Content-Type: application/sdp User-Agent: Zoiper rv2.8.109 Allow-Events: presence, kpml, talk Content-Length: 245 v=0 o=Zoiper 0 2 IN IP4 183.82.203.220 s=Zoiper c=IN IP4 183.82.203.220 t=0 0 m=audio 24215 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv ------------------------------------------------------------------------ send 441 bytes to udp/[183.82.203.220]:23581 at 12:34:18.346849: ------------------------------------------------------------------------ ACK sip:1003@183.82.203.220:23581 SIP/2.0 Via: SIP/2.0/UDP 159.89.163.195:5020;rport;branch=z9hG4bK0U1cFyD1FKDvj Max-Forwards: 70 From: "Extension 1000" ;tag=HH9NSUrc6m7Xa To: ;tag=435b9221 Call-ID: db3d7dda-570c-1237-2b97-528373432f88 CSeq: 130124362 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ recv 802 bytes from tcp/[183.82.203.220]:23585 at 12:34:20.345601: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKZj8KD3vXjaQ9p Contact: To: ;tag=435b9221 From: "Extension 1000" ;tag=HH9NSUrc6m7Xa Call-ID: db3d7dda-570c-1237-2b97-528373432f88 CSeq: 130124362 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Content-Type: application/sdp User-Agent: Zoiper rv2.8.109 Allow-Events: presence, kpml, talk Content-Length: 245 v=0 o=Zoiper 0 2 IN IP4 183.82.203.220 s=Zoiper c=IN IP4 183.82.203.220 t=0 0 m=audio 24215 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv ------------------------------------------------------------------------ send 441 bytes to udp/[183.82.203.220]:23581 at 12:34:20.345717: ------------------------------------------------------------------------ ACK sip:1003@183.82.203.220:23581 SIP/2.0 Via: SIP/2.0/UDP 159.89.163.195:5020;rport;branch=z9hG4bK0U1cFyD1FKDvj Max-Forwards: 70 From: "Extension 1000" ;tag=HH9NSUrc6m7Xa To: ;tag=435b9221 Call-ID: db3d7dda-570c-1237-2b97-528373432f88 CSeq: 130124362 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ recv 802 bytes from tcp/[183.82.203.220]:23585 at 12:34:24.347363: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TCP 159.89.163.195:5020;branch=z9hG4bKZj8KD3vXjaQ9p Contact: To: ;tag=435b9221 From: "Extension 1000" ;tag=HH9NSUrc6m7Xa Call-ID: db3d7dda-570c-1237-2b97-528373432f88 CSeq: 130124362 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Content-Type: application/sdp User-Agent: Zoiper rv2.8.109 Allow-Events: presence, kpml, talk Content-Length: 245 v=0 o=Zoiper 0 2 IN IP4 183.82.203.220 s=Zoiper c=IN IP4 183.82.203.220 t=0 0 m=audio 24215 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv ------------------------------------------------------------------------ send 441 bytes to udp/[183.82.203.220]:23581 at 12:34:24.347512: ------------------------------------------------------------------------ ACK sip:1003@183.82.203.220:23581 SIP/2.0 Via: SIP/2.0/UDP 159.89.163.195:5020;rport;branch=z9hG4bK0U1cFyD1FKDvj Max-Forwards: 70 From: "Extension 1000" ;tag=HH9NSUrc6m7Xa To: ;tag=435b9221 Call-ID: db3d7dda-570c-1237-2b97-528373432f88 CSeq: 130124362 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ freeswitch@shashi> ...