------------------------------------------------------------------------ INVITE sip:18003799180@10.31.1.5:5070 SIP/2.0 Record-Route: Record-Route: Max-Forwards: 67 Session-Expires: 7200;refresher=uac Min-SE: 600 Supported: timer, 100rel To: From: ;tag=3708710826-841185 P-Asserted-Identity: Call-ID: 45872803-3708710826-841179@msc1.382COM.COM CSeq: 1 INVITE Allow: CANCEL, ACK, INVITE, BYE, OPTIONS, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE, MESSAGE, PUBLISH Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK11ab.8fd8cbf6d75cec349558389bb71d4c60.0 Via: SIP/2.0/UDP 64.125.111.10:5060;rport=5060;branch=z9hG4bKff4ba30d164e547a34c7adac5db6677c Contact: Expires: 180 Allow-Events: telephone-event Content-Type: application/sdp Accept: application/sdp Content-Length: 260 X-AUTH-IP: 64.125.111.10 v=0 o=msc1 1018 686 IN IP4 64.125.111.10 s=sip call c=IN IP4 69.87.154.208 t=0 0 m=audio 17262 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 ------------------------------------------------------------------------ send 532 bytes to udp/[10.15.7.7]:5060 at 21:27:06.922343: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK11ab.8fd8cbf6d75cec349558389bb71d4c60.0 Via: SIP/2.0/UDP 64.125.111.10:5060;rport=5060;branch=z9hG4bKff4ba30d164e547a34c7adac5db6677c Record-Route: Record-Route: From: ;tag=3708710826-841185 To: Call-ID: 45872803-3708710826-841179@msc1.382COM.COM CSeq: 1 INVITE Content-Length: 0 ------------------------------------------------------------------------ 2017-07-10 21:27:06.908959 [NOTICE] switch_channel.c:1104 New Channel sofia/inbound/9712751300@64.125.111.10 [2b04f60c-4eea-4516-b079-2772d3fd681f] 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_NEW (Cur 1 Tot 29) 2017-07-10 21:27:06.908959 [DEBUG] sofia.c:9837 sofia/inbound/9712751300@64.125.111.10 receiving invite from 10.15.7.7:5060 version: 1.6.18 git 3da0ad0 2017-06-28 17:17:04Z 64bit 2017-07-10 21:27:06.908959 [DEBUG] sofia.c:7048 Channel sofia/inbound/9712751300@64.125.111.10 entering state [received][100] 2017-07-10 21:27:06.908959 [DEBUG] sofia.c:7058 Remote SDP: v=0 o=msc1 1018 686 IN IP4 64.125.111.10 s=sip call c=IN IP4 69.87.154.208 t=0 0 m=audio 17262 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1] 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1] 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1] 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4361 Set telephone-event payload to 101@8000 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:3057 Set Codec sofia/inbound/9712751300@64.125.111.10 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2017-07-10 21:27:06.908959 [DEBUG] switch_core_codec.c:111 sofia/inbound/9712751300@64.125.111.10 Original read codec set to PCMU:0 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4704 Set telephone-event payload to 101@8000 2017-07-10 21:27:06.908959 [DEBUG] switch_core_media.c:4763 sofia/inbound/9712751300@64.125.111.10 Set 2833 dtmf send payload to 101 recv payload to 101 2017-07-10 21:27:06.908959 [DEBUG] sofia.c:7471 (sofia/inbound/9712751300@64.125.111.10) State Change CS_NEW -> CS_INIT 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:603 (sofia/inbound/9712751300@64.125.111.10) State NEW 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_INIT (Cur 1 Tot 29) 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:627 (sofia/inbound/9712751300@64.125.111.10) State INIT 2017-07-10 21:27:06.908959 [DEBUG] mod_sofia.c:90 sofia/inbound/9712751300@64.125.111.10 SOFIA INIT 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:40 sofia/inbound/9712751300@64.125.111.10 Standard INIT 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:48 (sofia/inbound/9712751300@64.125.111.10) State Change CS_INIT -> CS_ROUTING 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:627 (sofia/inbound/9712751300@64.125.111.10) State INIT going to sleep 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_ROUTING (Cur 1 Tot 29) 2017-07-10 21:27:06.908959 [DEBUG] switch_channel.c:2249 (sofia/inbound/9712751300@64.125.111.10) Callstate Change DOWN -> RINGING 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:643 (sofia/inbound/9712751300@64.125.111.10) State ROUTING 2017-07-10 21:27:06.908959 [DEBUG] mod_sofia.c:143 sofia/inbound/9712751300@64.125.111.10 SOFIA ROUTING 2017-07-10 21:27:06.908959 [DEBUG] switch_core_state_machine.c:236 sofia/inbound/9712751300@64.125.111.10 Standard ROUTING 2017-07-10 21:27:06.908959 [INFO] mod_dialplan_xml.c:637 Processing 9712751300 <9712751300>->18003799180 in context public Dialplan: sofia/inbound/9712751300@64.125.111.10 parsing [public->UNKNOWN] continue=false Dialplan: sofia/inbound/9712751300@64.125.111.10 Absolute Condition [UNKNOWN] Dialplan: sofia/inbound/9712751300@64.125.111.10 Action set(telnyx_uuid=8646b9cf-65b6-11e7-a6aa-02420a1f010f) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(telnyx_session_uuid=8646bcd1-65b6-11e7-8f37-02420a1f010f) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(e164_cld=+18003799180) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(e164_cli=+19712751300) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(counterparty_a=382com) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(counterparty_b=telnyx) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(on_net=false) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(nolocal:connection_id=306330846174905419) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(nolocal:user_type=public-api) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(nolocal:user_id=127) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(nolocal:tags=) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(nolocal:usage_payment_method=pay-per-minute) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(user_data={"origination": {"user_id": "127", "tn_type": "TF", "tags": [], "DID": "+18003799180", "user_type": "public-api", "connection_id": "306330846174905419", "tn": "+18003799180"}}) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(planned=true) Dialplan: sofia/inbound/9712751300@64.125.111.10 Absolute Condition [UNKNOWN] Dialplan: sofia/inbound/9712751300@64.125.111.10 Action unset(sip_h_X-FS-Support) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action ring_ready() Dialplan: sofia/inbound/9712751300@64.125.111.10 Action set(call_timeout=600) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action set(continue_on_fail=false) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action export(sip_cid_type=pid) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action set(sip_copy_multipart=false) Dialplan: sofia/inbound/9712751300@64.125.111.10 Action bridge({local_var_clobber=true,originate_continue_on_timeout=true,sip_invite_domain=sip.telnyx.com,origination_caller_id_number=19712751300}[leg_timeout=300,leg_progress_timeout=5,orig_auth=ip-authentication,absolute_codec_string=^^:G722:PCMU:PCMA:G729:OPUS,sip_execute_on_image='t38_gateway self nocng',fax_enable_t38=true,sip_h_X-USE-UDP=1,ip_port=54.165.139.136:5061,sip_h_X-KIBP=10.15.7.7,telnyx_uuid=864a5a7a-65b6-11e7-8c94-02420a1f010f]sofia/priv-external-compact/222218003799180@54.165.139.136:5061;fs_path=sip%3A10.15.7.7%3A5060%3Btransport%3DUDP) 2017-07-10 21:27:06.948913 [DEBUG] switch_core_state_machine.c:286 (sofia/inbound/9712751300@64.125.111.10) State Change CS_ROUTING -> CS_EXECUTE 2017-07-10 21:27:06.948913 [DEBUG] switch_core_state_machine.c:643 (sofia/inbound/9712751300@64.125.111.10) State ROUTING going to sleep 2017-07-10 21:27:06.948913 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_EXECUTE (Cur 1 Tot 29) 2017-07-10 21:27:06.948913 [DEBUG] switch_core_state_machine.c:650 (sofia/inbound/9712751300@64.125.111.10) State EXECUTE 2017-07-10 21:27:06.948913 [DEBUG] mod_sofia.c:198 sofia/inbound/9712751300@64.125.111.10 SOFIA EXECUTE 2017-07-10 21:27:06.948913 [DEBUG] switch_core_state_machine.c:328 sofia/inbound/9712751300@64.125.111.10 Standard EXECUTE EXECUTE sofia/inbound/9712751300@64.125.111.10 set(telnyx_uuid=8646b9cf-65b6-11e7-a6aa-02420a1f010f) 2017-07-10 21:27:06.948913 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/9712751300@64.125.111.10 [telnyx_uuid]=[8646b9cf-65b6-11e7-a6aa-02420a1f010f] EXECUTE sofia/inbound/9712751300@64.125.111.10 export(telnyx_session_uuid=8646bcd1-65b6-11e7-8f37-02420a1f010f) 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [telnyx_session_uuid]=[8646bcd1-65b6-11e7-8f37-02420a1f010f] EXECUTE sofia/inbound/9712751300@64.125.111.10 export(e164_cld=+18003799180) 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [e164_cld]=[+18003799180] EXECUTE sofia/inbound/9712751300@64.125.111.10 export(e164_cli=+19712751300) 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [e164_cli]=[+19712751300] EXECUTE sofia/inbound/9712751300@64.125.111.10 export(counterparty_a=382com) 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [counterparty_a]=[382com] EXECUTE sofia/inbound/9712751300@64.125.111.10 export(counterparty_b=telnyx) 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [counterparty_b]=[telnyx] EXECUTE sofia/inbound/9712751300@64.125.111.10 export(on_net=false) 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [on_net]=[false] EXECUTE sofia/inbound/9712751300@64.125.111.10 export(nolocal:connection_id=306330846174905419) 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [connection_id]=[306330846174905419] EXECUTE sofia/inbound/9712751300@64.125.111.10 export(nolocal:user_type=public-api) 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [user_type]=[public-api] EXECUTE sofia/inbound/9712751300@64.125.111.10 export(nolocal:user_id=127) 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [user_id]=[127] EXECUTE sofia/inbound/9712751300@64.125.111.10 export(nolocal:tags=) 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [tags]=[UNDEF] EXECUTE sofia/inbound/9712751300@64.125.111.10 export(nolocal:usage_payment_method=pay-per-minute) 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [usage_payment_method]=[pay-per-minute] EXECUTE sofia/inbound/9712751300@64.125.111.10 export(user_data={"origination": {"user_id": "127", "tn_type": "TF", "tags": [], "DID": "+18003799180", "user_type": "public-api", "connection_id": "306330846174905419", "tn": "+18003799180"}}) 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [user_data]=[{"origination": {"user_id": "127", "tn_type": "TF", "tags": [], "DID": "+18003799180", "user_type": "public-api", "connection_id": "306330846174905419", "tn": "+18003799180"}}] EXECUTE sofia/inbound/9712751300@64.125.111.10 export(planned=true) 2017-07-10 21:27:06.948913 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [planned]=[true] EXECUTE sofia/inbound/9712751300@64.125.111.10 unset(sip_h_X-FS-Support) 2017-07-10 21:27:06.968912 [DEBUG] mod_dptools.c:1675 UNSET [sip_h_X-FS-Support] EXECUTE sofia/inbound/9712751300@64.125.111.10 ring_ready() 2017-07-10 21:27:06.968912 [NOTICE] mod_sofia.c:2273 Ring-Ready sofia/inbound/9712751300@64.125.111.10! send 778 bytes to udp/[10.15.7.7]:5060 at 21:27:06.969610: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK11ab.8fd8cbf6d75cec349558389bb71d4c60.0 Via: SIP/2.0/UDP 64.125.111.10:5060;rport=5060;branch=z9hG4bKff4ba30d164e547a34c7adac5db6677c Record-Route: Record-Route: From: ;tag=3708710826-841185 To: ;tag=DpSK0jS771cjD Call-ID: 45872803-3708710826-841179@msc1.382COM.COM CSeq: 1 INVITE Contact: Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY Supported: path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ 2017-07-10 21:27:06.968912 [DEBUG] sofia.c:7048 Channel sofia/inbound/9712751300@64.125.111.10 entering state [early][180] 2017-07-10 21:27:06.968912 [NOTICE] mod_dptools.c:1028 Ring Ready sofia/inbound/9712751300@64.125.111.10! EXECUTE sofia/inbound/9712751300@64.125.111.10 set(call_timeout=600) 2017-07-10 21:27:06.968912 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/9712751300@64.125.111.10 [call_timeout]=[600] EXECUTE sofia/inbound/9712751300@64.125.111.10 set(continue_on_fail=false) 2017-07-10 21:27:06.968912 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/9712751300@64.125.111.10 [continue_on_fail]=[false] EXECUTE sofia/inbound/9712751300@64.125.111.10 export(sip_cid_type=pid) 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [sip_cid_type]=[pid] EXECUTE sofia/inbound/9712751300@64.125.111.10 set(sip_copy_multipart=false) 2017-07-10 21:27:06.968912 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/9712751300@64.125.111.10 [sip_copy_multipart]=[false] EXECUTE sofia/inbound/9712751300@64.125.111.10 bridge({local_var_clobber=true,originate_continue_on_timeout=true,sip_invite_domain=sip.telnyx.com,origination_caller_id_number=19712751300}[leg_timeout=300,leg_progress_timeout=5,orig_auth=ip-authentication,absolute_codec_string=^^:G722:PCMU:PCMA:G729:OPUS,sip_execute_on_image='t38_gateway self nocng',fax_enable_t38=true,sip_h_X-USE-UDP=1,ip_port=54.165.139.136:5061,sip_h_X-KIBP=10.15.7.7,telnyx_uuid=864a5a7a-65b6-11e7-8c94-02420a1f010f]sofia/priv-external-compact/222218003799180@54.165.139.136:5061;fs_path=sip%3A10.15.7.7%3A5060%3Btransport%3DUDP) 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [telnyx_session_uuid]=[8646bcd1-65b6-11e7-8f37-02420a1f010f] to event 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [e164_cld]=[+18003799180] to event 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [e164_cli]=[+19712751300] to event 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [counterparty_a]=[382com] to event 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [counterparty_b]=[telnyx] to event 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [on_net]=[false] to event 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [connection_id]=[306330846174905419] to event 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [user_type]=[public-api] to event 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [user_id]=[127] to event 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [usage_payment_method]=[pay-per-minute] to event 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [user_data]=[{"origination": {"user_id": "127", "tn_type": "TF", "tags": [], "DID": "+18003799180", "user_type": "public-api", "connection_id": "306330846174905419", "tn": "+18003799180"}}] to event 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [planned]=[true] to event 2017-07-10 21:27:06.968912 [DEBUG] switch_channel.c:1250 sofia/inbound/9712751300@64.125.111.10 EXPORTING[export_vars] [sip_cid_type]=[pid] to event 2017-07-10 21:27:06.968912 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2017-07-10 21:27:06.968912 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables 2017-07-10 21:27:06.968912 [NOTICE] switch_channel.c:1104 New Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 [79a7fdc3-c238-4fad-b6be-0cd418866fca] 2017-07-10 21:27:06.968912 [DEBUG] mod_sofia.c:4819 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State Change CS_NEW -> CS_INIT 2017-07-10 21:27:06.968912 [DEBUG] switch_ivr_originate.c:2963 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Setting leg timeout to 300 2017-07-10 21:27:06.968912 [DEBUG] switch_ivr_originate.c:2972 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Setting leg progress timeout to 5 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:584 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_INIT (Cur 2 Tot 30) 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:627 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State INIT 2017-07-10 21:27:06.968912 [DEBUG] mod_sofia.c:90 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 SOFIA INIT 2017-07-10 21:27:06.968912 [DEBUG] sofia_glue.c:1264 sip:10.15.7.7:5060;transport=UDP Setting proxy route to sofia/priv-external-compact/222218003799180@54.165.139.136:5061 2017-07-10 21:27:06.968912 [DEBUG] sofia_glue.c:1295 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 sending invite version: 1.6.18 git 3da0ad0 2017-06-28 17:17:04Z 64bit Local SDP: v=0 o=Telnyx 1499696646 1499696647 IN IP4 64.16.249.20 s=Telnyx c=IN IP4 64.16.249.20 t=0 0 m=audio 25380 RTP/AVP 9 0 8 18 102 101 103 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 a=rtcp-mux a=rtcp:25380 IN IP4 64.16.249.20 a=fmtp:18 annexb=no a=ptime:20 a=sendrecv 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:40 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Standard INIT 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:48 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State Change CS_INIT -> CS_ROUTING 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:627 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State INIT going to sleep 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:584 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_ROUTING (Cur 2 Tot 30) 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:643 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State ROUTING 2017-07-10 21:27:06.968912 [DEBUG] mod_sofia.c:143 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 SOFIA ROUTING 2017-07-10 21:27:06.968912 [DEBUG] switch_ivr_originate.c:67 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:643 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State ROUTING going to sleep 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:584 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 30) send 1224 bytes to udp/[10.15.7.7]:5060 at 21:27:06.973842: ------------------------------------------------------------------------ INVITE sip:222218003799180@54.165.139.136:5061 SIP/2.0 v:SIP/2.0/UDP 10.31.1.5:5082;rport;branch=z9hG4bKD9aQ57eB0XZ9c Route:;transport=UDP Max-Forwards:66 f:"9712751300";tag=K8ptv8N0N6gvD t: i:5dab431b-e059-1235-0baf-02420a1f0105 CSeq:109524949 INVITE m: Allow:INVITE,ACK,BYE,CANCEL,OPTIONS,MESSAGE,INFO,UPDATE,NOTIFY k:timer,path,replaces u:talk,hold,conference,refer Privacy:none 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:662 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State CONSUME_MEDIA c:application/sdp 2017-07-10 21:27:06.968912 [DEBUG] switch_core_state_machine.c:662 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State CONSUME_MEDIA going to sleep Content-Disposition:session l:552 X-USE-UDP:1 X-KIBP:10.15.7.7 P-Asserted-Identity:"9712751300" v=0 o=Telnyx 1499696646 1499696647 IN IP4 64.16.249.20 s=Telnyx c=IN IP4 64.16.249.20 t=0 0 m=audio 25380 RTP/AVP 9 0 8 18 102 101 103 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 a=rtcp-mux a=rtcp:25380 IN IP4 64.16.249.20 a=ptime:20 ------------------------------------------------------------------------ 2017-07-10 21:27:06.968912 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [calling][0] recv 351 bytes from udp/[10.15.7.7]:5060 at 21:27:07.128010: ------------------------------------------------------------------------ SIP/2.0 100 Telnyx trying v:SIP/2.0/UDP 10.31.1.5:5082;rport=5082;branch=z9hG4bKD9aQ57eB0XZ9c;received=10.31.1.5 f:"9712751300";tag=K8ptv8N0N6gvD t: i:5dab431b-e059-1235-0baf-02420a1f0105 CSeq:109524949 INVITE Server: kamailio (4.4.5 (x86_64/linux)) Content-Length: 0 ------------------------------------------------------------------------ recv 1135 bytes from udp/[10.15.7.7]:5060 at 21:27:07.200444: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.31.1.5:5082;received=10.31.1.5;rport=5082;branch=z9hG4bKD9aQ57eB0XZ9c Record-Route: Record-Route: From: "9712751300";tag=K8ptv8N0N6gvD To: ;tag=as1c8c2222 Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105 CSeq: 109524949 INVITE Server: Asterisk PBX 13.16.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Type: application/sdp Require: timer Content-Length: 394 v=0 o=root 209604850 209604850 IN IP4 54.165.139.136 s=Asterisk PBX 13.16.0 c=IN IP4 54.165.139.136 t=0 0 m=audio 17476 RTP/AVP 18 9 8 0 102 101 a=rtpmap:18 G729/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:102 opus/48000/2 a=fmtp:102 maxaveragebitrate=30000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:20 a=sendrecv ------------------------------------------------------------------------ 2017-07-10 21:27:07.188913 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [completing][200] 2017-07-10 21:27:07.188913 [DEBUG] sofia.c:7058 Remote SDP: v=0 o=root 209604850 209604850 IN IP4 54.165.139.136 s=Asterisk PBX 13.16.0 c=IN IP4 54.165.139.136 t=0 0 m=audio 17476 RTP/AVP 18 9 8 0 102 101 a=rtpmap:18 G729/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:102 opus/48000/2 a=fmtp:102 maxaveragebitrate=30000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:20 send 460 bytes to udp/[10.15.7.7]:5060 at 21:27:07.201367: ------------------------------------------------------------------------ ACK sip:222218003799180@54.165.139.136:5061 SIP/2.0 v:SIP/2.0/UDP 10.31.1.5:5082;rport;branch=z9hG4bKej4F72ZeX6Nvr Route:, Max-Forwards:70 f:"9712751300";tag=K8ptv8N0N6gvD t:;tag=as1c8c2222 i:5dab431b-e059-1235-0baf-02420a1f0105 CSeq:109524949 ACK m: l:0 ------------------------------------------------------------------------ 2017-07-10 21:27:07.188913 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [ready][200] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G722:9:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [opus:102:48000:20:0:1]/[G722:9:8000:20:64000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [opus:102:48000:20:0:1]/[PCMU:0:8000:20:64000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [opus:102:48000:20:0:1]/[PCMA:8:8000:20:64000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [opus:102:48000:20:0:1]/[G729:18:8000:20:8000:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [opus:102:48000:20:0:1]/[opus:116:48000:20:0:1] 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4361 Set telephone-event payload to 101@8000 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:3057 Set Codec sofia/priv-external-compact/222218003799180@54.165.139.136:5061 G729/8000 20 ms 160 samples 8000 bits 1 channels 2017-07-10 21:27:07.188913 [DEBUG] switch_core_codec.c:111 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Original read codec set to G729:18 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4704 Set telephone-event payload to 101@8000 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:4763 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Set 2833 dtmf send payload to 101 recv payload to 101 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:6874 AUDIO RTP [sofia/priv-external-compact/222218003799180@54.165.139.136:5061] 64.16.249.20 port 25380 -> 54.165.139.136 port 17476 codec: 18 ms: 20 2017-07-10 21:27:07.188913 [DEBUG] switch_rtp.c:4112 Starting timer [soft] 160 bytes per 20ms 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:7094 Activating RTCP PORT 0 2017-07-10 21:27:07.188913 [DEBUG] switch_rtp.c:4508 RTCP send rate is: 10000 and packet rate is: 20000 Remote Port: 17477 2017-07-10 21:27:07.188913 [DEBUG] switch_rtp.c:2568 Setting RTCP remote addr to 54.165.139.136:17477 2 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:7175 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Set 2833 dtmf send payload to 101 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:7182 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Set 2833 dtmf receive payload to 101 2017-07-10 21:27:07.188913 [DEBUG] switch_core_media.c:7205 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Set rtp dtmf delay to 40 2017-07-10 21:27:07.188913 [NOTICE] sofia.c:8182 Channel [sofia/priv-external-compact/222218003799180@54.165.139.136:5061] has been answered 2017-07-10 21:27:07.188913 [DEBUG] switch_channel.c:3773 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Callstate Change DOWN -> ACTIVE 2017-07-10 21:27:07.208941 [DEBUG] switch_core_media.c:6874 AUDIO RTP [sofia/inbound/9712751300@64.125.111.10] 64.16.249.20 port 30698 -> 69.87.154.208 port 17262 codec: 0 ms: 20 2017-07-10 21:27:07.208941 [DEBUG] switch_rtp.c:4112 Starting timer [soft] 160 bytes per 20ms 2017-07-10 21:27:07.208941 [DEBUG] switch_core_media.c:7094 Activating RTCP PORT 0 2017-07-10 21:27:07.208941 [DEBUG] switch_rtp.c:4508 RTCP send rate is: 10000 and packet rate is: 20000 Remote Port: 17263 2017-07-10 21:27:07.208941 [DEBUG] switch_rtp.c:2568 Setting RTCP remote addr to 69.87.154.208:17263 2 2017-07-10 21:27:07.208941 [DEBUG] switch_core_media.c:7175 sofia/inbound/9712751300@64.125.111.10 Set 2833 dtmf send payload to 101 2017-07-10 21:27:07.208941 [DEBUG] switch_core_media.c:7182 sofia/inbound/9712751300@64.125.111.10 Set 2833 dtmf receive payload to 101 2017-07-10 21:27:07.208941 [DEBUG] switch_core_media.c:7205 sofia/inbound/9712751300@64.125.111.10 Set rtp dtmf delay to 40 2017-07-10 21:27:07.208941 [DEBUG] mod_sofia.c:850 Local SDP sofia/inbound/9712751300@64.125.111.10: v=0 o=FreeSWITCH 1499691329 1499691330 IN IP4 64.16.249.20 s=FreeSWITCH c=IN IP4 64.16.249.20 t=0 0 m=audio 30698 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=fmtp:18 annexb=no a=ptime:20 a=sendrecv a=rtcp:30699 IN IP4 64.16.249.20 2017-07-10 21:27:07.208941 [NOTICE] switch_ivr_originate.c:3647 Channel [sofia/inbound/9712751300@64.125.111.10] has been answered send 1065 bytes to udp/[10.15.7.7]:5060 at 21:27:07.216217: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK11ab.8fd8cbf6d75cec349558389bb71d4c60.0 Via: SIP/2.0/UDP 64.125.111.10:5060;rport=5060;branch=z9hG4bKff4ba30d164e547a34c7adac5db6677c Record-Route: Record-Route: From: ;tag=3708710826-841185 To: ;tag=DpSK0jS771cjD Call-ID: 45872803-3708710826-841179@msc1.382COM.COM CSeq: 1 INVITE Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY Supported: path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 254 v=0 o=FreeSWITCH 1499691329 1499691330 IN IP4 64.16.249.20 s=FreeSWITCH c=IN IP4 64.16.249.20 t=0 0 m=audio 30698 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=rtcp:30699 IN IP4 64.16.249.20 ------------------------------------------------------------------------ 2017-07-10 21:27:07.208941 [DEBUG] switch_channel.c:3773 (sofia/inbound/9712751300@64.125.111.10) Callstate Change RINGING -> ACTIVE 2017-07-10 21:27:07.208941 [DEBUG] sofia.c:7048 Channel sofia/inbound/9712751300@64.125.111.10 entering state [completed][200] 2017-07-10 21:27:07.208941 [DEBUG] switch_ivr_originate.c:3705 Originate Resulted in Success: [sofia/priv-external-compact/222218003799180@54.165.139.136:5061] 2017-07-10 21:27:07.208941 [DEBUG] switch_ivr_bridge.c:1614 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2017-07-10 21:27:07.208941 [DEBUG] switch_core_state_machine.c:584 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 30) 2017-07-10 21:27:07.208941 [DEBUG] switch_core_state_machine.c:653 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State EXCHANGE_MEDIA 2017-07-10 21:27:07.208941 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA recv 653 bytes from udp/[10.15.7.7]:5060 at 21:27:07.504009: ------------------------------------------------------------------------ ACK sip:18003799180@10.31.1.5:5070 SIP/2.0 Max-Forwards: 67 To: ;tag=DpSK0jS771cjD From: ;tag=3708710826-841185 Call-ID: 45872803-3708710826-841179@msc1.382COM.COM CSeq: 1 ACK Allow: CANCEL, ACK, INVITE, BYE, OPTIONS, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE, MESSAGE, PUBLISH Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK11ab.3f3d30898355e8148c15f6dcf09d5b7a.0 Via: SIP/2.0/UDP 64.125.111.10:5060;rport=5060;branch=z9hG4bK617eeab2961a3b98cdb2e083812a0f07 Contact: Allow-Events: telephone-event Content-Length: 0 ------------------------------------------------------------------------ 2017-07-10 21:27:07.508949 [DEBUG] sofia.c:7048 Channel sofia/inbound/9712751300@64.125.111.10 entering state [ready][200] 2017-07-10 21:27:07.668947 [DEBUG] switch_rtp.c:1888 rtcp_stats_init: audio ssrc[139244306] base_seq[13517] 2017-07-10 21:27:07.688950 [DEBUG] switch_rtp.c:7272 Correct audio ip/port confirmed. 2017-07-10 21:27:07.688950 [DEBUG] switch_rtp.c:7272 Correct audio ip/port confirmed. 2017-07-10 21:27:07.708913 [DEBUG] switch_rtp.c:1888 rtcp_stats_init: audio ssrc[368286416] base_seq[44715] 2017-07-10 21:27:08.748952 [DEBUG] switch_rtp.c:6722 Correct audio RTCP ip/port confirmed. recv 1021 bytes from udp/[10.15.7.7]:5060 at 21:27:10.701903: ------------------------------------------------------------------------ INVITE sip:mod_sofia@10.31.1.5:5082 SIP/2.0 Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK3171.72f7c3785f532d4e1676884afe18e88f.0 Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK42e59504;rport=5061 Max-Forwards: 69 From: ;tag=as1c8c2222 To: "9712751300";tag=K8ptv8N0N6gvD Contact: Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105 CSeq: 102 INVITE User-Agent: Asterisk PBX 13.16.0 Session-Expires: 1800;refresher=uac Min-SE: 90 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 274 v=0 o=root 209604850 209604851 IN IP4 54.165.139.136 s=Asterisk PBX 13.16.0 c=IN IP4 54.165.139.136 t=0 0 m=image 4827 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxDatagram:1400 a=T38FaxUdpEC:t38UDPRedundancy ------------------------------------------------------------------------ send 402 bytes to udp/[10.15.7.7]:5060 at 21:27:10.702244: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK3171.72f7c3785f532d4e1676884afe18e88f.0 Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK42e59504;rport=5061 From: ;tag=as1c8c2222 To: "9712751300";tag=K8ptv8N0N6gvD Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105 CSeq: 102 INVITE l:0 ------------------------------------------------------------------------ 2017-07-10 21:27:10.708921 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [received][100] 2017-07-10 21:27:10.708921 [DEBUG] sofia.c:7058 Remote SDP: v=0 o=root 209604850 209604851 IN IP4 54.165.139.136 s=Asterisk PBX 13.16.0 c=IN IP4 54.165.139.136 t=0 0 m=image 4827 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxDatagram:1400 a=T38FaxUdpEC:t38UDPRedundancy EXECUTE sofia/priv-external-compact/222218003799180@54.165.139.136:5061 t38_gateway(self nocng) 2017-07-10 21:27:10.708921 [DEBUG] mod_spandsp_fax.c:2080 sofia/inbound/9712751300@64.125.111.10 starting gateway mode to sofia/priv-external-compact/222218003799180@54.165.139.136:5061 2017-07-10 21:27:10.708921 [DEBUG] mod_spandsp_fax.c:2098 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State Change CS_EXCHANGE_MEDIA -> CS_RESET 2017-07-10 21:27:10.708921 [DEBUG] mod_spandsp_fax.c:2101 (sofia/inbound/9712751300@64.125.111.10) State Change CS_EXECUTE -> CS_RESET 2017-07-10 21:27:10.708921 [DEBUG] switch_core_media.c:4037 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 T38 ACCEPT on request 2017-07-10 21:27:10.708921 [DEBUG] switch_core_media.c:4142 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 T38 IS POSSIBLE on request 2017-07-10 21:27:10.728914 [DEBUG] switch_ivr_bridge.c:706 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 ending bridge by request from write function 2017-07-10 21:27:10.728914 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/inbound/9712751300@64.125.111.10] 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:650 (sofia/inbound/9712751300@64.125.111.10) State EXECUTE going to sleep 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_RESET (Cur 2 Tot 30) 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:646 (sofia/inbound/9712751300@64.125.111.10) State RESET 2017-07-10 21:27:10.728914 [DEBUG] mod_sofia.c:161 sofia/inbound/9712751300@64.125.111.10 SOFIA RESET 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:2040 (sofia/inbound/9712751300@64.125.111.10) State Change CS_RESET -> CS_CONSUME_MEDIA 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:646 (sofia/inbound/9712751300@64.125.111.10) State RESET going to sleep 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 30) 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:662 (sofia/inbound/9712751300@64.125.111.10) State CONSUME_MEDIA 2017-07-10 21:27:10.728914 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/priv-external-compact/222218003799180@54.165.139.136:5061] 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:653 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State EXCHANGE_MEDIA going to sleep 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:584 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_RESET (Cur 2 Tot 30) 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:646 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State RESET 2017-07-10 21:27:10.728914 [DEBUG] mod_sofia.c:161 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 SOFIA RESET 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:2042 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State Change CS_RESET -> CS_SOFT_EXECUTE 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:646 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State RESET going to sleep 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:584 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_SOFT_EXECUTE (Cur 2 Tot 30) 2017-07-10 21:27:10.728914 [DEBUG] switch_core_state_machine.c:656 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State SOFT_EXECUTE 2017-07-10 21:27:10.728914 [DEBUG] mod_sofia.c:637 SOFIA SOFT_EXECUTE 2017-07-10 21:27:10.728914 [WARNING] mod_spandsp_fax.c:1138 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 already has T.38 data 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1040 T38 SDP Origin = root 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1041 T38FaxVersion = 0 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1042 T38MaxBitRate = 14400 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1043 T38FaxFillBitRemoval = 0 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1044 T38FaxTranscodingMMR = 0 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1045 T38FaxTranscodingJBIG = 0 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1046 T38FaxRateManagement = 'transferredTCF' 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1047 T38FaxMaxBuffer = 500 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1048 T38FaxMaxDatagram = 1400 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1049 T38FaxUdpEC = 't38UDPRedundancy' 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1050 T38VendorInfo = '' 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1051 ip = '54.165.139.136' 2017-07-10 21:27:10.728914 [DEBUG] mod_spandsp_fax.c:1053 port = 4827 2017-07-10 21:27:10.728914 [DEBUG] switch_core_media.c:9755 IMAGE UDPTL CHANGING DEST TO: [54.165.139.136:4827] 2017-07-10 21:27:10.728914 [DEBUG] switch_core_media.c:9385 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 image media sdp: v=0 o=Telnyx 1499696646 1499696648 IN IP4 64.16.249.20 s=Telnyx c=IN IP4 64.16.249.20 t=0 0 m=image 25380 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:500 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy 2017-07-10 21:27:10.728914 [DEBUG] switch_core_media.c:9746 Remote address:port [54.165.139.136:4827] has not changed. send 913 bytes to udp/[10.15.7.7]:5060 at 21:27:10.744303: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK3171.72f7c3785f532d4e1676884afe18e88f.0 Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK42e59504;rport=5061 From: ;tag=as1c8c2222 To: "9712751300";tag=K8ptv8N0N6gvD Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105 CSeq: 102 INVITE m: Accept:application/sdp Allow:INVITE,ACK,BYE,CANCEL,OPTIONS,MESSAGE,INFO,UPDATE,NOTIFY Require:timer k:timer,path,replaces x:1800;refresher=uac c:application/sdp Content-Disposition:session l:283 v=0 o=Telnyx 1499696646 1499696648 IN IP4 64.16.249.20 s=Telnyx c=IN IP4 64.16.249.20 t=0 0 m=image 25380 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:500 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy ------------------------------------------------------------------------ 2017-07-10 21:27:10.728914 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [completed][200] 2017-07-10 21:27:10.748914 [DEBUG] mod_spandsp_fax.c:1886 Raw read codec activation Success L16 20000 2017-07-10 21:27:10.748914 [DEBUG] switch_core_codec.c:223 sofia/inbound/9712751300@64.125.111.10 Push codec L16:100 2017-07-10 21:27:10.748914 [DEBUG] mod_spandsp_fax.c:1903 Raw write codec activation Success L16 2017-07-10 21:27:10.908951 [DEBUG] switch_rtp.c:7272 Correct audio ip/port confirmed. recv 539 bytes from udp/[10.15.7.7]:5060 at 21:27:10.968706: ------------------------------------------------------------------------ ACK sip:mod_sofia@10.31.1.5:5082 SIP/2.0 Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK3171.24f09dce17b0209fb1f79f3b1c212d86.0 Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK7359fa10;rport=5061 Max-Forwards: 69 From: ;tag=as1c8c2222 To: "9712751300";tag=K8ptv8N0N6gvD Contact: Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105 CSeq: 102 ACK User-Agent: Asterisk PBX 13.16.0 Content-Length: 0 ------------------------------------------------------------------------ 2017-07-10 21:27:10.968952 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [ready][200] recv 1212 bytes from udp/[10.15.7.7]:5060 at 21:27:18.189771: ------------------------------------------------------------------------ INVITE sip:18003799180@10.31.1.5:5070 SIP/2.0 Max-Forwards: 67 Session-Expires: 7200;refresher=uas Min-SE: 1800 Supported: timer, 100rel To: ;tag=DpSK0jS771cjD From: ;tag=3708710826-841185 P-Asserted-Identity: Call-ID: 45872803-3708710826-841179@msc1.382COM.COM CSeq: 2 INVITE Allow: CANCEL, ACK, INVITE, BYE, OPTIONS, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE, MESSAGE, PUBLISH Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bKe0ab.5beba73224a631d3b2129355986b58d2.0 Via: SIP/2.0/UDP 64.125.111.10:5060;rport=5060;branch=z9hG4bK89e5399d5dc0785adf1c92fe13857f4b Contact: Expires: 180 Allow-Events: telephone-event Content-Type: application/sdp Accept: application/sdp Content-Length: 351 v=0 o=msc1 1018 687 IN IP4 64.125.111.10 s=sip call c=IN IP4 69.87.154.208 t=0 0 m=image 17262 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:200 a=T38FaxMaxDatagram:320 a=T38FaxUdpEC:t38UDPRedundancy ------------------------------------------------------------------------ send 420 bytes to udp/[10.15.7.7]:5060 at 21:27:18.190175: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bKe0ab.5beba73224a631d3b2129355986b58d2.0 Via: SIP/2.0/UDP 64.125.111.10:5060;rport=5060;branch=z9hG4bK89e5399d5dc0785adf1c92fe13857f4b From: ;tag=3708710826-841185 To: ;tag=DpSK0jS771cjD Call-ID: 45872803-3708710826-841179@msc1.382COM.COM CSeq: 2 INVITE Content-Length: 0 ------------------------------------------------------------------------ 2017-07-10 21:27:18.188950 [DEBUG] sofia.c:7048 Channel sofia/inbound/9712751300@64.125.111.10 entering state [received][100] 2017-07-10 21:27:18.188950 [DEBUG] sofia.c:7058 Remote SDP: v=0 o=msc1 1018 687 IN IP4 64.125.111.10 s=sip call c=IN IP4 69.87.154.208 t=0 0 m=image 17262 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:200 a=T38FaxMaxDatagram:320 a=T38FaxUdpEC:t38UDPRedundancy 2017-07-10 21:27:18.188950 [DEBUG] switch_core_media.c:4024 sofia/inbound/9712751300@64.125.111.10 T38 REFUSE on request 2017-07-10 21:27:18.188950 [DEBUG] sofia.c:7971 Reinvite resulted in codec negotiation failure. send 558 bytes to udp/[10.15.7.7]:5060 at 21:27:18.196396: ------------------------------------------------------------------------ SIP/2.0 488 Not Acceptable Here Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bKe0ab.5beba73224a631d3b2129355986b58d2.0 Via: SIP/2.0/UDP 64.125.111.10:5060;rport=5060;branch=z9hG4bK89e5399d5dc0785adf1c92fe13857f4b From: ;tag=3708710826-841185 To: ;tag=DpSK0jS771cjD Call-ID: 45872803-3708710826-841179@msc1.382COM.COM CSeq: 2 INVITE Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY Supported: path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2017-07-10 21:27:18.208922 [DEBUG] sofia.c:7041 Channel sofia/inbound/9712751300@64.125.111.10 skipping state [ready][488] recv 364 bytes from udp/[10.15.7.7]:5060 at 21:27:18.350221: ------------------------------------------------------------------------ ACK sip:18003799180@10.31.1.5:5070 SIP/2.0 Max-Forwards: 67 To: ;tag=DpSK0jS771cjD From: ;tag=3708710826-841185 Call-ID: 45872803-3708710826-841179@msc1.382COM.COM CSeq: 2 ACK Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bKe0ab.5beba73224a631d3b2129355986b58d2.0 Content-Length: 0 ------------------------------------------------------------------------ send 449 bytes to udp/[50.97.255.73]:5060 at 21:28:00.216831: ------------------------------------------------------------------------ OPTIONS sip:50.97.255.73;transport=udp SIP/2.0 Via: SIP/2.0/UDP 64.16.249.20:5072;rport;branch=z9hG4bK8gZgUgpj8F4cF Max-Forwards: 70 From: ;tag=8Nr5Zg1ZXK0jH To: Call-ID: 7d678335-e059-1235-0baf-02420a1f0105 CSeq: 109524526 OPTIONS Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ send 452 bytes to udp/[184.172.33.74]:5060 at 21:28:00.217054: ------------------------------------------------------------------------ OPTIONS sip:184.172.33.74;transport=udp SIP/2.0 Via: SIP/2.0/UDP 64.16.249.20:5072;rport;branch=z9hG4bK9Sr9vB7N5rtZa Max-Forwards: 70 From: ;tag=9yHy1Bj3tvp5c To: Call-ID: 7d678cd0-e059-1235-0baf-02420a1f0105 CSeq: 109524527 OPTIONS Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ recv 332 bytes from udp/[184.172.33.74]:5060 at 21:28:00.330779: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 64.16.249.20:5072;rport=5072;branch=z9hG4bK9Sr9vB7N5rtZa From: ;tag=9yHy1Bj3tvp5c To: ;tag=61ca04ab316dd595563aff0006b39e03.cecd Call-ID: 7d678cd0-e059-1235-0baf-02420a1f0105 CSeq: 109524527 OPTIONS Server: Telnyx v4.5-PRODUCTION.177 Content-Length: 0 ------------------------------------------------------------------------ recv 330 bytes from udp/[50.97.255.73]:5060 at 21:28:00.361679: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 64.16.249.20:5072;rport=5072;branch=z9hG4bK8gZgUgpj8F4cF From: ;tag=8Nr5Zg1ZXK0jH To: ;tag=8dec4f3770a90d58c5e7e223daf3aecc.bcb5 Call-ID: 7d678335-e059-1235-0baf-02420a1f0105 CSeq: 109524526 OPTIONS Server: Telnyx v4.5-PRODUCTION.177 Content-Length: 0 ------------------------------------------------------------------------ recv 1141 bytes from udp/[10.15.7.7]:5060 at 21:28:01.348690: ------------------------------------------------------------------------ INVITE sip:mod_sofia@10.31.1.5:5082 SIP/2.0 Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK4171.63ef3e0cc8d31370a0f485c8f5a38a9a.0 Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK7b8f90cd;rport=5061 Max-Forwards: 69 From: ;tag=as1c8c2222 To: "9712751300";tag=K8ptv8N0N6gvD Contact: Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105 CSeq: 103 INVITE User-Agent: Asterisk PBX 13.16.0 Session-Expires: 1800;refresher=uac Min-SE: 90 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 394 v=0 o=root 209604850 209604852 IN IP4 54.165.139.136 s=Asterisk PBX 13.16.0 c=IN IP4 54.165.139.136 t=0 0 m=audio 17476 RTP/AVP 18 9 8 0 102 101 a=rtpmap:18 G729/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:102 opus/48000/2 a=fmtp:102 maxaveragebitrate=30000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:20 a=sendrecv ------------------------------------------------------------------------ send 402 bytes to udp/[10.15.7.7]:5060 at 21:28:01.349057: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK4171.63ef3e0cc8d31370a0f485c8f5a38a9a.0 Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK7b8f90cd;rport=5061 From: ;tag=as1c8c2222 To: "9712751300";tag=K8ptv8N0N6gvD Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105 CSeq: 103 INVITE l:0 ------------------------------------------------------------------------ 2017-07-10 21:28:01.348956 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [received][100] 2017-07-10 21:28:01.348956 [DEBUG] sofia.c:7058 Remote SDP: v=0 o=root 209604850 209604852 IN IP4 54.165.139.136 s=Asterisk PBX 13.16.0 c=IN IP4 54.165.139.136 t=0 0 m=audio 17476 RTP/AVP 18 9 8 0 102 101 a=rtpmap:18 G729/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:102 opus/48000/2 a=fmtp:102 maxaveragebitrate=30000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:20 send 913 bytes to udp/[10.15.7.7]:5060 at 21:28:01.350772: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK4171.63ef3e0cc8d31370a0f485c8f5a38a9a.0 Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK7b8f90cd;rport=5061 From: ;tag=as1c8c2222 To: "9712751300";tag=K8ptv8N0N6gvD Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105 CSeq: 103 INVITE m: Accept:application/sdp Allow:INVITE,ACK,BYE,CANCEL,OPTIONS,MESSAGE,INFO,UPDATE,NOTIFY Require:timer k:timer,path,replaces x:1800;refresher=uac c:application/sdp Content-Disposition:session l:283 v=0 o=Telnyx 1499696646 1499696648 IN IP4 64.16.249.20 s=Telnyx c=IN IP4 64.16.249.20 t=0 0 m=image 25380 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:500 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy ------------------------------------------------------------------------ 2017-07-10 21:28:01.348956 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [completed][200] recv 539 bytes from udp/[10.15.7.7]:5060 at 21:28:01.575235: ------------------------------------------------------------------------ ACK sip:mod_sofia@10.31.1.5:5082 SIP/2.0 Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK4171.5e38420ad3c2bd3f52d1b69cedbaf396.0 Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK24f79e47;rport=5061 Max-Forwards: 69 From: ;tag=as1c8c2222 To: "9712751300";tag=K8ptv8N0N6gvD Contact: Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105 CSeq: 103 ACK User-Agent: Asterisk PBX 13.16.0 Content-Length: 0 ------------------------------------------------------------------------ recv 560 bytes from udp/[10.15.7.7]:5060 at 21:28:01.575353: ------------------------------------------------------------------------ BYE sip:mod_sofia@10.31.1.5:5082 SIP/2.0 Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK1171.ee969f78348ab7369993261c93571443.0 Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK18ba4499;rport=5061 Max-Forwards: 69 From: ;tag=as1c8c2222 To: "9712751300";tag=K8ptv8N0N6gvD Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105 CSeq: 104 BYE User-Agent: Asterisk PBX 13.16.0 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 ------------------------------------------------------------------------ 2017-07-10 21:28:01.568955 [DEBUG] sofia.c:7048 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 entering state [ready][200] 2017-07-10 21:28:01.568955 [NOTICE] sofia.c:1012 Hangup sofia/priv-external-compact/222218003799180@54.165.139.136:5061 [CS_SOFT_EXECUTE] [NORMAL_CLEARING] 2017-07-10 21:28:01.568955 [WARNING] mod_spandsp_fax.c:1767 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Premature exit while negotiating (1) 2017-07-10 21:28:01.568955 [DEBUG] mod_spandsp_fax.c:1789 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 skip receive message [UNBRIDGE] (channel is hungup already) 2017-07-10 21:28:01.568955 [NOTICE] mod_spandsp_fax.c:1791 Hangup sofia/inbound/9712751300@64.125.111.10 [CS_CONSUME_MEDIA] [NORMAL_CLEARING] send 482 bytes to udp/[10.15.7.7]:5060 at 21:28:01.577772: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.15.7.7;branch=z9hG4bK1171.ee969f78348ab7369993261c93571443.0 Via: SIP/2.0/UDP 54.165.139.136:5061;received=54.165.139.136;branch=z9hG4bK18ba4499;rport=5061 From: ;tag=as1c8c2222 To: "9712751300";tag=K8ptv8N0N6gvD Call-ID: 5dab431b-e059-1235-0baf-02420a1f0105 CSeq: 104 BYE Allow:INVITE,ACK,BYE,CANCEL,OPTIONS,MESSAGE,INFO,UPDATE,NOTIFY k:timer,path,replaces l:0 ------------------------------------------------------------------------ 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:656 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State SOFT_EXECUTE going to sleep 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:584 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_HANGUP (Cur 2 Tot 30) 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:850 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Callstate Change ACTIVE -> HANGUP 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:852 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State HANGUP 2017-07-10 21:28:01.568955 [DEBUG] mod_sofia.c:438 Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 hanging up, cause: NORMAL_CLEARING 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:60 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Standard HANGUP, cause: NORMAL_CLEARING 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:852 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State HANGUP going to sleep 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:619 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State Change CS_HANGUP -> CS_REPORTING 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:584 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_REPORTING (Cur 2 Tot 30) 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:938 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State REPORTING 2017-07-10 21:28:01.568955 [INFO] mod_json_cdr.c:271 Process [79a7fdc3-c238-4fad-b6be-0cd418866fca.cdr.json] 2017-07-10 21:28:01.568955 [INFO] mod_json_cdr.c:275 Log to disk [/var/log/freeswitch/json_cdr/79a7fdc3-c238-4fad-b6be-0cd418866fca.cdr.json] 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:174 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Standard REPORTING, cause: NORMAL_CLEARING 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:938 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State REPORTING going to sleep 2017-07-10 21:28:01.568955 [DEBUG] switch_core_state_machine.c:610 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State Change CS_REPORTING -> CS_DESTROY 2017-07-10 21:28:01.568955 [DEBUG] switch_core_session.c:1665 Session 30 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Locked, Waiting on external entities 2017-07-10 21:28:01.588947 [DEBUG] mod_spandsp_fax.c:1988 sofia/inbound/9712751300@64.125.111.10 skip receive message [UNBRIDGE] (channel is hungup already) 2017-07-10 21:28:01.588947 [DEBUG] switch_core_codec.c:248 sofia/inbound/9712751300@64.125.111.10 Restore previous codec PCMU:0. 2017-07-10 21:28:01.588947 [NOTICE] switch_core_session.c:1683 Session 30 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Ended 2017-07-10 21:28:01.588947 [NOTICE] switch_core_session.c:1687 Close Channel sofia/priv-external-compact/222218003799180@54.165.139.136:5061 [CS_DESTROY] 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:662 (sofia/inbound/9712751300@64.125.111.10) State CONSUME_MEDIA going to sleep 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_HANGUP (Cur 1 Tot 30) 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:741 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) Running State Change CS_DESTROY (Cur 1 Tot 30) 2017-07-10 21:28:01.588947 [DEBUG] switch_ivr.c:217 sofia/inbound/9712751300@64.125.111.10 skip receive message [AUDIO_SYNC] (channel is hungup already) 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:850 (sofia/inbound/9712751300@64.125.111.10) Callstate Change ACTIVE -> HANGUP 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:751 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State DESTROY 2017-07-10 21:28:01.588947 [DEBUG] mod_sofia.c:343 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 SOFIA DESTROY 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:852 (sofia/inbound/9712751300@64.125.111.10) State HANGUP 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:181 sofia/priv-external-compact/222218003799180@54.165.139.136:5061 Standard DESTROY 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:751 (sofia/priv-external-compact/222218003799180@54.165.139.136:5061) State DESTROY going to sleep 2017-07-10 21:28:01.588947 [DEBUG] mod_sofia.c:432 sofia/inbound/9712751300@64.125.111.10 Overriding SIP cause 480 with 200 from the other leg 2017-07-10 21:28:01.588947 [DEBUG] mod_sofia.c:438 Channel sofia/inbound/9712751300@64.125.111.10 hanging up, cause: NORMAL_CLEARING 2017-07-10 21:28:01.588947 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/inbound/9712751300@64.125.111.10 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:60 sofia/inbound/9712751300@64.125.111.10 Standard HANGUP, cause: NORMAL_CLEARING 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:852 (sofia/inbound/9712751300@64.125.111.10) State HANGUP going to sleep 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:619 (sofia/inbound/9712751300@64.125.111.10) State Change CS_HANGUP -> CS_REPORTING 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_REPORTING (Cur 1 Tot 30) send 623 bytes to udp/[10.15.7.7]:5060 at 21:28:01.595926: ------------------------------------------------------------------------ BYE sip:9712751300@64.125.111.10:5060 SIP/2.0 Via: SIP/2.0/UDP 10.31.1.5:5070;rport;branch=z9hG4bK0N0BF0DKZXFFQ 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:938 (sofia/inbound/9712751300@64.125.111.10) State REPORTING Route: Route: Max-Forwards: 70 From: ;tag=DpSK0jS771cjD To: ;tag=3708710826-841185 Call-ID: 45872803-3708710826-841179@msc1.382COM.COM CSeq: 109524976 BYE Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY Supported: path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 ------------------------------------------------------------------------ 2017-07-10 21:28:01.588947 [INFO] mod_json_cdr.c:271 Process [a_2b04f60c-4eea-4516-b079-2772d3fd681f.cdr.json] 2017-07-10 21:28:01.588947 [INFO] mod_json_cdr.c:275 Log to disk [/var/log/freeswitch/json_cdr/a_2b04f60c-4eea-4516-b079-2772d3fd681f.cdr.json] 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:174 sofia/inbound/9712751300@64.125.111.10 Standard REPORTING, cause: NORMAL_CLEARING 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:938 (sofia/inbound/9712751300@64.125.111.10) State REPORTING going to sleep 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:610 (sofia/inbound/9712751300@64.125.111.10) State Change CS_REPORTING -> CS_DESTROY 2017-07-10 21:28:01.588947 [DEBUG] switch_core_session.c:1665 Session 29 (sofia/inbound/9712751300@64.125.111.10) Locked, Waiting on external entities 2017-07-10 21:28:01.588947 [NOTICE] switch_core_session.c:1683 Session 29 (sofia/inbound/9712751300@64.125.111.10) Ended 2017-07-10 21:28:01.588947 [NOTICE] switch_core_session.c:1687 Close Channel sofia/inbound/9712751300@64.125.111.10 [CS_DESTROY] 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:741 (sofia/inbound/9712751300@64.125.111.10) Running State Change CS_DESTROY (Cur 0 Tot 30) 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:751 (sofia/inbound/9712751300@64.125.111.10) State DESTROY 2017-07-10 21:28:01.588947 [DEBUG] mod_sofia.c:343 sofia/inbound/9712751300@64.125.111.10 SOFIA DESTROY 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:181 sofia/inbound/9712751300@64.125.111.10 Standard DESTROY 2017-07-10 21:28:01.588947 [DEBUG] switch_core_state_machine.c:751 (sofia/inbound/9712751300@64.125.111.10) State DESTROY going to sleep recv 522 bytes from udp/[10.15.7.7]:5060 at 21:28:01.900749: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.31.1.5:5070;received=10.31.1.5;rport=5070;branch=z9hG4bK0N0BF0DKZXFFQ To: ;tag=3708710826-841185 From: ;tag=DpSK0jS771cjD Call-ID: 45872803-3708710826-841179@msc1.382COM.COM CSeq: 109524976 BYE Allow: CANCEL, ACK, INVITE, BYE, OPTIONS, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE, MESSAGE, PUBLISH Contact: Reason: Q.850;cause=16 Content-Length: 0 ------------------------------------------------------------------------