recv 1232 bytes from udp/[10.15.13.13]:5060 at 22:02:43.312909: ------------------------------------------------------------------------ INVITE sip:3126225728@10.15.13.7:5070;transport=UDP SIP/2.0 Record-Route: Record-Route: Via: SIP/2.0/UDP 10.15.13.13;branch=z9hG4bK0de.8ccb2f858976fc7bf495773e29244c3a.0 Via: SIP/2.0/UDP 192.76.120.192:21060;rport=62080;received=50.247.144.29;branch=z9hG4bK-d8754z-4b8cd507b20b7e9f-1---d8754z- Max-Forwards: 69 Contact: To: From: ;tag=d88d4646 Call-ID: ZjdkMTE3ZTM0ODkwNzRmMjdlYzU4M2UxNDMwNzhjODU. CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Content-Type: application/sdp Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri User-Agent: Z 3.3.25608 r25552 Allow-Events: presence, kpml Content-Length: 244 X-AUTH-IP: 50.247.144.29 v=0 o=Z 0 0 IN IP4 192.76.120.192 s=Z c=IN IP4 192.76.120.192 t=0 0 m=audio 25685 RTP/AVP 3 110 8 0 98 101 a=rtpmap:110 speex/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv ------------------------------------------------------------------------ send 559 bytes to udp/[10.15.13.13]:5060 at 22:02:43.313200: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.15.13.13;branch=z9hG4bK0de.8ccb2f858976fc7bf495773e29244c3a.0 Via: SIP/2.0/UDP 192.76.120.192:21060;rport=62080;received=50.247.144.29;branch=z9hG4bK-d8754z-4b8cd507b20b7e9f-1---d8754z- Record-Route: Record-Route: From: ;tag=d88d4646 To: Call-ID: ZjdkMTE3ZTM0ODkwNzRmMjdlYzU4M2UxNDMwNzhjODU. CSeq: 1 INVITE Content-Length: 0 ------------------------------------------------------------------------ 2017-09-25 22:02:43.312818 [NOTICE] switch_channel.c:1104 New Channel sofia/inbound/testramon3@siplab5.telnyx.com [873e7e53-d676-4628-b19f-d1f02c4dd6d7] 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/testramon3@siplab5.telnyx.com) Running State Change CS_NEW (Cur 1 Tot 6) 2017-09-25 22:02:43.312818 [DEBUG] sofia.c:9837 sofia/inbound/testramon3@siplab5.telnyx.com receiving invite from 10.15.13.13:5060 version: 1.6.18 git 3da0ad0 2017-06-28 17:17:04Z 64bit 2017-09-25 22:02:43.312818 [DEBUG] sofia.c:7048 Channel sofia/inbound/testramon3@siplab5.telnyx.com entering state [received][100] 2017-09-25 22:02:43.312818 [DEBUG] sofia.c:7058 Remote SDP: v=0 o=Z 0 0 IN IP4 192.76.120.192 s=Z c=IN IP4 192.76.120.192 t=0 0 m=audio 25685 RTP/AVP 3 110 8 0 98 101 a=rtpmap:110 speex/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 2017-09-25 22:02:43.312818 [DEBUG] sofia.c:7450 (sofia/inbound/testramon3@siplab5.telnyx.com) State Change CS_NEW -> CS_INIT 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:603 (sofia/inbound/testramon3@siplab5.telnyx.com) State NEW 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/testramon3@siplab5.telnyx.com) Running State Change CS_INIT (Cur 1 Tot 6) 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:627 (sofia/inbound/testramon3@siplab5.telnyx.com) State INIT 2017-09-25 22:02:43.312818 [DEBUG] mod_sofia.c:90 sofia/inbound/testramon3@siplab5.telnyx.com SOFIA INIT 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:40 sofia/inbound/testramon3@siplab5.telnyx.com Standard INIT 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:48 (sofia/inbound/testramon3@siplab5.telnyx.com) State Change CS_INIT -> CS_ROUTING 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:627 (sofia/inbound/testramon3@siplab5.telnyx.com) State INIT going to sleep 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/testramon3@siplab5.telnyx.com) Running State Change CS_ROUTING (Cur 1 Tot 6) 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:2249 (sofia/inbound/testramon3@siplab5.telnyx.com) Callstate Change DOWN -> RINGING 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:643 (sofia/inbound/testramon3@siplab5.telnyx.com) State ROUTING 2017-09-25 22:02:43.312818 [DEBUG] mod_sofia.c:143 sofia/inbound/testramon3@siplab5.telnyx.com SOFIA ROUTING 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:236 sofia/inbound/testramon3@siplab5.telnyx.com Standard ROUTING 2017-09-25 22:02:43.312818 [INFO] mod_dialplan_xml.c:637 Processing testramon3 ->3126225728 in context public Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com parsing [public->UNKNOWN] continue=false Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Absolute Condition [UNKNOWN] Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action set(telnyx_uuid=7a9b5111-a23a-11e7-8b5e-02420a0f0d25) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action export(telnyx_session_uuid=7a9ce357-a23a-11e7-8747-02420a0f0d25) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action export(e164_cld=+13126225728) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action export(e164_cli=+17739850363) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action export(counterparty_a=telnyx) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action export(counterparty_b=sippy) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action export(on_net=false) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action set(connection_id=268876107514644154) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action set(user_id=174) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action set(user_type=public-api) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action set(tags=) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action set(routing_group=US-DCA) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action set(outbound_profile_id=268876471479568060) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action set(usage_payment_method=flat-rate) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action export(user_data={"termination": {"user_id": "174", "connection_id": "268876107514644154", "outbound_profile_id": "268876471479568060", "user_type": "public-api", "tn": "+13126225728", "call_type": "conversational"}}) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action export(planned=true) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Absolute Condition [UNKNOWN] Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action unset(sip_h_X-FS-Support) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action set(call_timeout=600) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action set(continue_on_fail=GATEWAY_DOWN,41) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action set(hangup_after_bridge=true) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action set(rtp_secure_media_inbound=true) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action set(refuse_t38=true) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action export(sip_cid_type=pid) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action bridge({local_var_clobber=true,sip_execute_on_image='t38_gateway self nocng',fax_enable_t38=true,sip_invite_domain=sip.telnyx.com,origination_caller_id_number=+17739850363}[telnyx_uuid=7ad0abfa-a23a-11e7-8596-02420a0f0d25]sofia/gateway/184.172.33.74/13126225728) Dialplan: sofia/inbound/testramon3@siplab5.telnyx.com Action bridge({local_var_clobber=true,sip_execute_on_image='t38_gateway self nocng',fax_enable_t38=true,sip_invite_domain=sip.telnyx.com,origination_caller_id_number=+17739850363}[telnyx_uuid=7ad0ae21-a23a-11e7-8b51-02420a0f0d25]sofia/gateway/50.97.255.73/13126225728) 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:286 (sofia/inbound/testramon3@siplab5.telnyx.com) State Change CS_ROUTING -> CS_EXECUTE 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:643 (sofia/inbound/testramon3@siplab5.telnyx.com) State ROUTING going to sleep 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/testramon3@siplab5.telnyx.com) Running State Change CS_EXECUTE (Cur 1 Tot 6) 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:650 (sofia/inbound/testramon3@siplab5.telnyx.com) State EXECUTE 2017-09-25 22:02:43.312818 [DEBUG] mod_sofia.c:198 sofia/inbound/testramon3@siplab5.telnyx.com SOFIA EXECUTE 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:328 sofia/inbound/testramon3@siplab5.telnyx.com Standard EXECUTE EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com set(telnyx_uuid=7a9b5111-a23a-11e7-8b5e-02420a0f0d25) 2017-09-25 22:02:43.312818 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/testramon3@siplab5.telnyx.com [telnyx_uuid]=[7a9b5111-a23a-11e7-8b5e-02420a0f0d25] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com export(telnyx_session_uuid=7a9ce357-a23a-11e7-8747-02420a0f0d25) 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [telnyx_session_uuid]=[7a9ce357-a23a-11e7-8747-02420a0f0d25] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com export(e164_cld=+13126225728) 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [e164_cld]=[+13126225728] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com export(e164_cli=+17739850363) 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [e164_cli]=[+17739850363] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com export(counterparty_a=telnyx) 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [counterparty_a]=[telnyx] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com export(counterparty_b=sippy) 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [counterparty_b]=[sippy] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com export(on_net=false) 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [on_net]=[false] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com set(connection_id=268876107514644154) 2017-09-25 22:02:43.312818 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/testramon3@siplab5.telnyx.com [connection_id]=[268876107514644154] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com set(user_id=174) 2017-09-25 22:02:43.312818 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/testramon3@siplab5.telnyx.com [user_id]=[174] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com set(user_type=public-api) 2017-09-25 22:02:43.312818 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/testramon3@siplab5.telnyx.com [user_type]=[public-api] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com set(tags=) 2017-09-25 22:02:43.312818 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/testramon3@siplab5.telnyx.com [tags]=[UNDEF] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com set(routing_group=US-DCA) 2017-09-25 22:02:43.312818 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/testramon3@siplab5.telnyx.com [routing_group]=[US-DCA] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com set(outbound_profile_id=268876471479568060) 2017-09-25 22:02:43.312818 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/testramon3@siplab5.telnyx.com [outbound_profile_id]=[268876471479568060] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com set(usage_payment_method=flat-rate) 2017-09-25 22:02:43.312818 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/testramon3@siplab5.telnyx.com [usage_payment_method]=[flat-rate] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com export(user_data={"termination": {"user_id": "174", "connection_id": "268876107514644154", "outbound_profile_id": "268876471479568060", "user_type": "public-api", "tn": "+13126225728", "call_type": "conversational"}}) 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [user_data]=[{"termination": {"user_id": "174", "connection_id": "268876107514644154", "outbound_profile_id": "268876471479568060", "user_type": "public-api", "tn": "+13126225728", "call_type": "conversational"}}] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com export(planned=true) 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [planned]=[true] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com unset(sip_h_X-FS-Support) 2017-09-25 22:02:43.312818 [DEBUG] mod_dptools.c:1675 UNSET [sip_h_X-FS-Support] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com set(call_timeout=600) 2017-09-25 22:02:43.312818 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/testramon3@siplab5.telnyx.com [call_timeout]=[600] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com set(continue_on_fail=GATEWAY_DOWN,41) 2017-09-25 22:02:43.312818 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/testramon3@siplab5.telnyx.com [continue_on_fail]=[GATEWAY_DOWN,41] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com set(hangup_after_bridge=true) 2017-09-25 22:02:43.312818 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/testramon3@siplab5.telnyx.com [hangup_after_bridge]=[true] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com set(rtp_secure_media_inbound=true) 2017-09-25 22:02:43.312818 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/testramon3@siplab5.telnyx.com [rtp_secure_media_inbound]=[true] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com set(refuse_t38=true) 2017-09-25 22:02:43.312818 [DEBUG] mod_dptools.c:1530 SET sofia/inbound/testramon3@siplab5.telnyx.com [refuse_t38]=[true] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com export(sip_cid_type=pid) 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [sip_cid_type]=[pid] EXECUTE sofia/inbound/testramon3@siplab5.telnyx.com bridge({local_var_clobber=true,sip_execute_on_image='t38_gateway self nocng',fax_enable_t38=true,sip_invite_domain=sip.telnyx.com,origination_caller_id_number=+17739850363}[telnyx_uuid=7ad0abfa-a23a-11e7-8596-02420a0f0d25]sofia/gateway/184.172.33.74/13126225728) 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1250 sofia/inbound/testramon3@siplab5.telnyx.com EXPORTING[export_vars] [telnyx_session_uuid]=[7a9ce357-a23a-11e7-8747-02420a0f0d25] to event 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1250 sofia/inbound/testramon3@siplab5.telnyx.com EXPORTING[export_vars] [e164_cld]=[+13126225728] to event 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1250 sofia/inbound/testramon3@siplab5.telnyx.com EXPORTING[export_vars] [e164_cli]=[+17739850363] to event 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1250 sofia/inbound/testramon3@siplab5.telnyx.com EXPORTING[export_vars] [counterparty_a]=[telnyx] to event 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1250 sofia/inbound/testramon3@siplab5.telnyx.com EXPORTING[export_vars] [counterparty_b]=[sippy] to event 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1250 sofia/inbound/testramon3@siplab5.telnyx.com EXPORTING[export_vars] [on_net]=[false] to event 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1250 sofia/inbound/testramon3@siplab5.telnyx.com EXPORTING[export_vars] [user_data]=[{"termination": {"user_id": "174", "connection_id": "268876107514644154", "outbound_profile_id": "268876471479568060", "user_type": "public-api", "tn": "+13126225728", "call_type": "conversational"}}] to event 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1250 sofia/inbound/testramon3@siplab5.telnyx.com EXPORTING[export_vars] [planned]=[true] to event 2017-09-25 22:02:43.312818 [DEBUG] switch_channel.c:1250 sofia/inbound/testramon3@siplab5.telnyx.com EXPORTING[export_vars] [sip_cid_type]=[pid] to event 2017-09-25 22:02:43.312818 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2017-09-25 22:02:43.312818 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables 2017-09-25 22:02:43.312818 [NOTICE] switch_channel.c:1104 New Channel sofia/pstn/13126225728 [27887a5e-b7dc-4358-9f8f-480475051756] 2017-09-25 22:02:43.312818 [DEBUG] mod_sofia.c:4819 (sofia/pstn/13126225728) State Change CS_NEW -> CS_INIT 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:584 (sofia/pstn/13126225728) Running State Change CS_INIT (Cur 2 Tot 7) 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:627 (sofia/pstn/13126225728) State INIT 2017-09-25 22:02:43.312818 [DEBUG] mod_sofia.c:90 sofia/pstn/13126225728 SOFIA INIT 2017-09-25 22:02:43.312818 [DEBUG] sofia_glue.c:1295 sofia/pstn/13126225728 sending invite version: 1.6.18 git 3da0ad0 2017-06-28 17:17:04Z 64bit Local SDP: v=0 o=Telnyx 1506359647 1506359648 IN IP4 64.16.248.234 s=Telnyx c=IN IP4 64.16.248.234 t=0 0 m=audio 17316 RTP/AVP 8 0 18 9 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=fmtp:18 annexb=no a=ptime:20 a=sendrecv 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:40 sofia/pstn/13126225728 Standard INIT 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:48 (sofia/pstn/13126225728) State Change CS_INIT -> CS_ROUTING 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:627 (sofia/pstn/13126225728) State INIT going to sleep send 1027 bytes to udp/[184.172.33.74]:5060 at 22:02:43.326503: ------------------------------------------------------------------------ INVITE sip:13126225728@184.172.33.74 SIP/2.0 Via: SIP/2.0/UDP 64.16.248.234:5072;rport;branch=z9hG4bK4aeXDUpgFatFB Max-Forwards: 68 From: "testramon3" ;tag=4mpUe8gev3Qvg To: Call-ID: 18d792ca-1ce0-1236-4092-02420a0f0d07 CSeq: 112852417 INVITE Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Privacy: none Content-Type: application/sdp Content-Disposition: session Content-Length: 309 P-Asserted-Identity: "testramon3" v=0 o=Telnyx 1506359647 1506359648 IN IP4 64.16.248.234 s=Telnyx c=IN IP4 64.16.248.234 t=0 0 m=audio 17316 RTP/AVP 8 0 18 9 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:584 (sofia/pstn/13126225728) Running State Change CS_ROUTING (Cur 2 Tot 7) a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2017-09-25 22:02:43.312818 [DEBUG] sofia.c:7048 Channel sofia/pstn/13126225728 entering state [calling][0] 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:643 (sofia/pstn/13126225728) State ROUTING 2017-09-25 22:02:43.312818 [DEBUG] mod_sofia.c:143 sofia/pstn/13126225728 SOFIA ROUTING 2017-09-25 22:02:43.312818 [DEBUG] switch_ivr_originate.c:67 (sofia/pstn/13126225728) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:643 (sofia/pstn/13126225728) State ROUTING going to sleep 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:584 (sofia/pstn/13126225728) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 7) 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:662 (sofia/pstn/13126225728) State CONSUME_MEDIA 2017-09-25 22:02:43.312818 [DEBUG] switch_core_state_machine.c:662 (sofia/pstn/13126225728) State CONSUME_MEDIA going to sleep recv 365 bytes from udp/[184.172.33.74]:5060 at 22:02:43.364261: ------------------------------------------------------------------------ SIP/2.0 100 trying -- your call is important to us Via: SIP/2.0/UDP 64.16.248.234:5072;rport=5072;branch=z9hG4bK4aeXDUpgFatFB From: "testramon3" ;tag=4mpUe8gev3Qvg To: Call-ID: 18d792ca-1ce0-1236-4092-02420a0f0d07 CSeq: 112852417 INVITE Server: Telnyx v4.5-PRODUCTION.177 Content-Length: 0 ------------------------------------------------------------------------ recv 702 bytes from udp/[184.172.33.74]:5060 at 22:02:44.774567: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 64.16.248.234:5072;branch=z9hG4bK4aeXDUpgFatFB;rport=5072 Record-Route: From: testramon3 ;tag=4mpUe8gev3Qvg To: ;tag=c613cdda97dddf0164a86dcbc1be18e4 Call-ID: 18d792ca-1ce0-1236-4092-02420a0f0d07 CSeq: 112852417 INVITE Server: Telnyx v4.5-PRODUCTION.177 Content-Length: 234 Content-Type: application/sdp v=0 o=Sonus_UAC 616243 154874 IN IP4 67.231.1.112 s=SIP Media Capabilities c=IN IP4 67.231.1.79 t=0 0 m=audio 28162 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv a=ptime:20 ------------------------------------------------------------------------ 2017-09-25 22:02:44.772782 [DEBUG] sofia.c:7048 Channel sofia/pstn/13126225728 entering state [proceeding][183] 2017-09-25 22:02:44.772782 [DEBUG] sofia.c:7058 Remote SDP: v=0 o=Sonus_UAC 616243 154874 IN IP4 67.231.1.112 s=SIP Media Capabilities c=IN IP4 67.231.1.79 t=0 0 m=audio 28162 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4361 Set telephone-event payload to 101@8000 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:3057 Set Codec sofia/pstn/13126225728 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2017-09-25 22:02:44.772782 [DEBUG] switch_core_codec.c:111 sofia/pstn/13126225728 Original read codec set to PCMU:0 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4704 Set telephone-event payload to 101@8000 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4763 sofia/pstn/13126225728 Set 2833 dtmf send payload to 101 recv payload to 101 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:6874 AUDIO RTP [sofia/pstn/13126225728] 64.16.248.234 port 17316 -> 67.231.1.79 port 28162 codec: 0 ms: 20 2017-09-25 22:02:44.772782 [DEBUG] switch_rtp.c:4112 Starting timer [soft] 160 bytes per 20ms 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:7175 sofia/pstn/13126225728 Set 2833 dtmf send payload to 101 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:7182 sofia/pstn/13126225728 Set 2833 dtmf receive payload to 101 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:7205 sofia/pstn/13126225728 Set rtp dtmf delay to 40 2017-09-25 22:02:44.772782 [NOTICE] sofia_media.c:92 Pre-Answer sofia/pstn/13126225728! 2017-09-25 22:02:44.772782 [DEBUG] switch_channel.c:3474 (sofia/pstn/13126225728) Callstate Change DOWN -> EARLY 2017-09-25 22:02:44.772782 [INFO] switch_ivr_originate.c:3654 Sending early media 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G729:18:8000:20:8000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [speex:110:8000:20:0:1]/[G722:9:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMU:0:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMA:8:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [speex:110:8000:20:0:1]/[G729:18:8000:20:8000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [speex:110:8000:20:0:1]/[opus:116:48000:20:0:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4500 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [iLBC:98:8000:30:0:1]/[G722:9:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [iLBC:98:8000:30:0:1]/[PCMU:0:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [iLBC:98:8000:30:0:1]/[PCMA:8:8000:20:64000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [iLBC:98:8000:30:0:1]/[G729:18:8000:20:8000:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4445 Audio Codec Compare [iLBC:98:8000:30:0:1]/[opus:116:48000:20:0:1] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4361 Set telephone-event payload to 101@8000 2017-09-25 22:02:44.772782 [WARNING] switch_core_media.c:4518 Crypto not negotiated but required. 2017-09-25 22:02:44.772782 [DEBUG] switch_core_media.c:4763 sofia/inbound/testramon3@siplab5.telnyx.com Set 2833 dtmf send payload to 101 recv payload to 101 2017-09-25 22:02:44.772782 [ERR] mod_sofia.c:2343 CODEC NEGOTIATION ERROR. SDP: v=0 o=Z 0 0 IN IP4 192.76.120.192 s=Z c=IN IP4 192.76.120.192 t=0 0 m=audio 25685 RTP/AVP 3 110 8 0 98 101 a=rtpmap:110 speex/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 2017-09-25 22:02:44.772782 [NOTICE] switch_channel.c:3515 Hangup sofia/inbound/testramon3@siplab5.telnyx.com [CS_EXECUTE] [INCOMPATIBLE_DESTINATION] 2017-09-25 22:02:44.772782 [DEBUG] switch_ivr_originate.c:3661 sofia/inbound/testramon3@siplab5.telnyx.com Media Establishment Failed. 2017-09-25 22:02:44.772782 [NOTICE] switch_ivr_originate.c:3663 Hangup sofia/pstn/13126225728 [CS_CONSUME_MEDIA] [INCOMPATIBLE_DESTINATION] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:584 (sofia/pstn/13126225728) Running State Change CS_HANGUP (Cur 2 Tot 7) 2017-09-25 22:02:44.772782 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 88 [INCOMPATIBLE_DESTINATION] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:850 (sofia/pstn/13126225728) Callstate Change EARLY -> HANGUP 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:852 (sofia/pstn/13126225728) State HANGUP 2017-09-25 22:02:44.772782 [DEBUG] mod_sofia.c:438 Channel sofia/pstn/13126225728 hanging up, cause: INCOMPATIBLE_DESTINATION 2017-09-25 22:02:44.772782 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/pstn/13126225728 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:60 sofia/pstn/13126225728 Standard HANGUP, cause: INCOMPATIBLE_DESTINATION 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:852 (sofia/pstn/13126225728) State HANGUP going to sleep 2017-09-25 22:02:44.772782 [INFO] mod_dptools.c:3418 Originate Failed. Cause: INCOMPATIBLE_DESTINATION 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:619 (sofia/pstn/13126225728) State Change CS_HANGUP -> CS_REPORTING 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:584 (sofia/pstn/13126225728) Running State Change CS_REPORTING (Cur 2 Tot 7) send 392 bytes to udp/[184.172.33.74]:5060 at 22:02:44.791017: ------------------------------------------------------------------------ CANCEL sip:13126225728@184.172.33.74 SIP/2.0 Via: SIP/2.0/UDP 64.16.248.234:5072;rport;branch=z9hG4bK4aeXDUpgFatFB Max-Forwards: 68 From: "testramon3" ;tag=4mpUe8gev3Qvg To: Call-ID: 18d792ca-1ce0-1236-4092-02420a0f0d07 CSeq: 112852417 CANCEL Reason: Q.850;cause=88;text="INCOMPATIBLE_DESTINATION" Content-Length: 0 ------------------------------------------------------------------------ 2017-09-25 22:02:44.772782 [DEBUG] switch_core_session.c:2815 sofia/inbound/testramon3@siplab5.telnyx.com skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:938 (sofia/pstn/13126225728) State REPORTING 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:650 (sofia/inbound/testramon3@siplab5.telnyx.com) State EXECUTE going to sleep 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/testramon3@siplab5.telnyx.com) Running State Change CS_HANGUP (Cur 2 Tot 7) 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:850 (sofia/inbound/testramon3@siplab5.telnyx.com) Callstate Change RINGING -> HANGUP 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:852 (sofia/inbound/testramon3@siplab5.telnyx.com) State HANGUP 2017-09-25 22:02:44.772782 [DEBUG] mod_sofia.c:438 Channel sofia/inbound/testramon3@siplab5.telnyx.com hanging up, cause: INCOMPATIBLE_DESTINATION 2017-09-25 22:02:44.772782 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 488 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:60 sofia/inbound/testramon3@siplab5.telnyx.com Standard HANGUP, cause: INCOMPATIBLE_DESTINATION 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:852 (sofia/inbound/testramon3@siplab5.telnyx.com) State HANGUP going to sleep 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:619 (sofia/inbound/testramon3@siplab5.telnyx.com) State Change CS_HANGUP -> CS_REPORTING 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:584 (sofia/inbound/testramon3@siplab5.telnyx.com) Running State Change CS_REPORTING (Cur 2 Tot 7) 2017-09-25 22:02:44.772782 [INFO] mod_json_cdr.c:271 Process [27887a5e-b7dc-4358-9f8f-480475051756.cdr.json] 2017-09-25 22:02:44.772782 [INFO] mod_json_cdr.c:275 Log to disk [/var/log/freeswitch/json_cdr/27887a5e-b7dc-4358-9f8f-480475051756.cdr.json] send 720 bytes to udp/[10.15.13.13]:5060 at 22:02:44.791446: ------------------------------------------------------------------------ SIP/2.0 488 Not Acceptable Here Via: SIP/2.0/UDP 10.15.13.13;branch=z9hG4bK0de.8ccb2f858976fc7bf495773e29244c3a.0 Via: SIP/2.0/UDP 192.76.120.192:21060;rport=62080;received=50.247.144.29;branch=z9hG4bK-d8754z-4b8cd507b20b7e9f-1---d8754z- Max-Forwards: 69 From: ;tag=d88d4646 To: ;tag=46586Ue29U5KN Call-ID: ZjdkMTE3ZTM0ODkwNzRmMjdlYzU4M2UxNDMwNzhjODU. 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:938 (sofia/inbound/testramon3@siplab5.telnyx.com) State REPORTING CSeq: 1 INVITE Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY Supported: path, replaces Allow-Events: talk, hold, conference, refer Reason: Q.850;cause=88;text="INCOMPATIBLE_DESTINATION" Content-Length: 0 ------------------------------------------------------------------------ 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:174 sofia/pstn/13126225728 Standard REPORTING, cause: INCOMPATIBLE_DESTINATION 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:938 (sofia/pstn/13126225728) State REPORTING going to sleep 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:610 (sofia/pstn/13126225728) State Change CS_REPORTING -> CS_DESTROY 2017-09-25 22:02:44.772782 [DEBUG] switch_core_session.c:1665 Session 7 (sofia/pstn/13126225728) Locked, Waiting on external entities 2017-09-25 22:02:44.772782 [NOTICE] switch_core_session.c:1683 Session 7 (sofia/pstn/13126225728) Ended 2017-09-25 22:02:44.772782 [NOTICE] switch_core_session.c:1687 Close Channel sofia/pstn/13126225728 [CS_DESTROY] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:741 (sofia/pstn/13126225728) Running State Change CS_DESTROY (Cur 1 Tot 7) 2017-09-25 22:02:44.772782 [INFO] mod_json_cdr.c:271 Process [a_873e7e53-d676-4628-b19f-d1f02c4dd6d7.cdr.json] 2017-09-25 22:02:44.772782 [INFO] mod_json_cdr.c:275 Log to disk [/var/log/freeswitch/json_cdr/a_873e7e53-d676-4628-b19f-d1f02c4dd6d7.cdr.json] recv 391 bytes from udp/[10.15.13.13]:5060 at 22:02:44.791978: ------------------------------------------------------------------------ ACK sip:3126225728@10.15.13.7:5070;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 10.15.13.13;branch=z9hG4bK0de.8ccb2f858976fc7bf495773e29244c3a.0 Max-Forwards: 69 To: ;tag=46586Ue29U5KN From: ;tag=d88d4646 Call-ID: ZjdkMTE3ZTM0ODkwNzRmMjdlYzU4M2UxNDMwNzhjODU. CSeq: 1 ACK Content-Length: 0 ------------------------------------------------------------------------ 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:174 sofia/inbound/testramon3@siplab5.telnyx.com Standard REPORTING, cause: INCOMPATIBLE_DESTINATION 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:938 (sofia/inbound/testramon3@siplab5.telnyx.com) State REPORTING going to sleep 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:751 (sofia/pstn/13126225728) State DESTROY 2017-09-25 22:02:44.772782 [DEBUG] mod_sofia.c:343 sofia/pstn/13126225728 SOFIA DESTROY 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:181 sofia/pstn/13126225728 Standard DESTROY 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:751 (sofia/pstn/13126225728) State DESTROY going to sleep 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:610 (sofia/inbound/testramon3@siplab5.telnyx.com) State Change CS_REPORTING -> CS_DESTROY 2017-09-25 22:02:44.772782 [DEBUG] switch_core_session.c:1665 Session 6 (sofia/inbound/testramon3@siplab5.telnyx.com) Locked, Waiting on external entities 2017-09-25 22:02:44.772782 [NOTICE] switch_core_session.c:1683 Session 6 (sofia/inbound/testramon3@siplab5.telnyx.com) Ended 2017-09-25 22:02:44.772782 [NOTICE] switch_core_session.c:1687 Close Channel sofia/inbound/testramon3@siplab5.telnyx.com [CS_DESTROY] 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:741 (sofia/inbound/testramon3@siplab5.telnyx.com) Running State Change CS_DESTROY (Cur 0 Tot 7) 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:751 (sofia/inbound/testramon3@siplab5.telnyx.com) State DESTROY 2017-09-25 22:02:44.772782 [DEBUG] mod_sofia.c:343 sofia/inbound/testramon3@siplab5.telnyx.com SOFIA DESTROY 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:181 sofia/inbound/testramon3@siplab5.telnyx.com Standard DESTROY 2017-09-25 22:02:44.772782 [DEBUG] switch_core_state_machine.c:751 (sofia/inbound/testramon3@siplab5.telnyx.com) State DESTROY going to sleep