------------------------------------------------------------------------ recv 1515 bytes from udp/[10.0.9.55]:5060 at 12:09:19.660430: ------------------------------------------------------------------------ INVITE sip:12134237681@office.nga911.com:15080 SIP/2.0 Record-Route: Record-Route: Record-Route: Record-Route: Via: SIP/2.0/UDP 10.0.9.55;branch=z9hG4bKe4ed.f1b16c318b2e697ff3f6ab8cd3140aa7.0;i=1 Via: SIP/2.0/TCP 192.76.120.10;branch=z9hG4bKe4ed.97ce71cee4cf5300aa275a07d41c3eac.0;i=cec v:SIP/2.0/TCP 10.15.12.4:5082;received=10.15.12.4;rport=55742;branch=z9hG4bKvNceaS2aFHjNr Max-Forwards:44 f:"Sergey Safarov";tag=a1QtHc31jj5XH t: i:17fab07d-716b-1236-7a88-02420a0f0c04 CSeq:117500215 INVITE m: Allow:INVITE,ACK,BYE,CANCEL,OPTIONS,MESSAGE,INFO,UPDATE,NOTIFY k:timer,path,replaces u:talk,hold,conference,refer Privacy:none c:application/sdp Content-Disposition:session l:333 P-Asserted-Identity:"Sergey Safarov" X-AUTH-IP: 192.76.120.10 X-AUTH-PORT: 36831 v=0 o=Telnyx 1515647013 1515647014 IN IP4 64.16.248.242 s=Telnyx c=IN IP4 64.16.248.242 t=0 0 m=audio 25546 RTP/AVP 9 0 8 18 101 13 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:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 ------------------------------------------------------------------------ send 865 bytes to udp/[10.0.9.55]:5060 at 12:09:19.660679: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.9.55;branch=z9hG4bKe4ed.f1b16c318b2e697ff3f6ab8cd3140aa7.0;i=1 Via: SIP/2.0/TCP 192.76.120.10;branch=z9hG4bKe4ed.97ce71cee4cf5300aa275a07d41c3eac.0;i=cec v:SIP/2.0/TCP 10.15.12.4:5082;received=10.15.12.4;rport=55742;branch=z9hG4bKvNceaS2aFHjNr Record-Route: Record-Route: Record-Route: Record-Route: f:"Sergey Safarov";tag=a1QtHc31jj5XH t: i:17fab07d-716b-1236-7a88-02420a0f0c04 CSeq:117500215 INVITE User-Agent: FreeSWITCH-mod_sofia/1.6.19+git-20171224T074649Z~f858a27ad1~64bit Content-Length: 0 ------------------------------------------------------------------------ 2018-01-11 12:09:19.655466 [NOTICE] switch_channel.c:1104 New Channel sofia/external-kamailio/12013992990@sip.telnyx.com [5e07cf5b-2b87-4075-8430-34de18f707c4] 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:584 (sofia/external-kamailio/12013992990@sip.telnyx.com) Running State Change CS_NEW (Cur 2 Tot 356) 2018-01-11 12:09:19.655466 [DEBUG] sofia.c:9873 sofia/external-kamailio/12013992990@sip.telnyx.com receiving invite from 10.0.9.55:5060 version: 1.6.19+git git f858a27 2017-12-24 07:46:49Z 64bit 2018-01-11 12:09:19.655466 [DEBUG] sofia.c:7084 Channel sofia/external-kamailio/12013992990@sip.telnyx.com entering state [received][100] 2018-01-11 12:09:19.655466 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=Telnyx 1515647013 1515647014 IN IP4 64.16.248.242 s=Telnyx c=IN IP4 64.16.248.242 t=0 0 m=audio 25546 RTP/AVP 9 0 8 18 101 13 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:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 2018-01-11 12:09:19.655466 [DEBUG] sofia.c:7486 (sofia/external-kamailio/12013992990@sip.telnyx.com) State Change CS_NEW -> CS_INIT 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:603 (sofia/external-kamailio/12013992990@sip.telnyx.com) State NEW 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:584 (sofia/external-kamailio/12013992990@sip.telnyx.com) Running State Change CS_INIT (Cur 2 Tot 356) 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:627 (sofia/external-kamailio/12013992990@sip.telnyx.com) State INIT 2018-01-11 12:09:19.655466 [DEBUG] mod_sofia.c:90 sofia/external-kamailio/12013992990@sip.telnyx.com SOFIA INIT 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:40 sofia/external-kamailio/12013992990@sip.telnyx.com Standard INIT 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:48 (sofia/external-kamailio/12013992990@sip.telnyx.com) State Change CS_INIT -> CS_ROUTING 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:627 (sofia/external-kamailio/12013992990@sip.telnyx.com) State INIT going to sleep 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:584 (sofia/external-kamailio/12013992990@sip.telnyx.com) Running State Change CS_ROUTING (Cur 2 Tot 356) 2018-01-11 12:09:19.655466 [DEBUG] switch_channel.c:2249 (sofia/external-kamailio/12013992990@sip.telnyx.com) Callstate Change DOWN -> RINGING 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:643 (sofia/external-kamailio/12013992990@sip.telnyx.com) State ROUTING 2018-01-11 12:09:19.655466 [DEBUG] mod_sofia.c:143 sofia/external-kamailio/12013992990@sip.telnyx.com SOFIA ROUTING 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:236 sofia/external-kamailio/12013992990@sip.telnyx.com Standard ROUTING 2018-01-11 12:09:19.655466 [INFO] mod_dialplan_xml.c:637 Processing Sergey Safarov <12013992990>->12134237681 in context e911 Dialplan: sofia/external-kamailio/12013992990@sip.telnyx.com parsing [e911->911] continue=false Dialplan: sofia/external-kamailio/12013992990@sip.telnyx.com Regex (PASS) [911] destination_number(12134237681) =~ /^1(\d{10})$/ break=on-false Dialplan: sofia/external-kamailio/12013992990@sip.telnyx.com Action set(sip_nat_detected=false) Dialplan: sofia/external-kamailio/12013992990@sip.telnyx.com Action python(dialplan) 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:286 (sofia/external-kamailio/12013992990@sip.telnyx.com) State Change CS_ROUTING -> CS_EXECUTE 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:643 (sofia/external-kamailio/12013992990@sip.telnyx.com) State ROUTING going to sleep 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:584 (sofia/external-kamailio/12013992990@sip.telnyx.com) Running State Change CS_EXECUTE (Cur 2 Tot 356) 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:650 (sofia/external-kamailio/12013992990@sip.telnyx.com) State EXECUTE 2018-01-11 12:09:19.655466 [DEBUG] mod_sofia.c:198 sofia/external-kamailio/12013992990@sip.telnyx.com SOFIA EXECUTE 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:328 sofia/external-kamailio/12013992990@sip.telnyx.com Standard EXECUTE EXECUTE sofia/external-kamailio/12013992990@sip.telnyx.com set(sip_nat_detected=false) 2018-01-11 12:09:19.655466 [DEBUG] mod_dptools.c:1548 SET sofia/external-kamailio/12013992990@sip.telnyx.com [sip_nat_detected]=[false] EXECUTE sofia/external-kamailio/12013992990@sip.telnyx.com python(dialplan) 2018-01-11 12:09:19.655466 [NOTICE] mod_python.c:212 Invoking py module: dialplan 2018-01-11 12:09:19.655466 [DEBUG] mod_python.c:283 Call python script 2018-01-11 12:09:19.655466 [DEBUG] switch_cpp.cpp:1112 sofia/external-kamailio/12013992990@sip.telnyx.com destroy/unlink session from object EXECUTE sofia/external-kamailio/12013992990@sip.telnyx.com info() 2018-01-11 12:09:19.655466 [INFO] mod_dptools.c:1761 CHANNEL_DATA: Channel-State: [CS_EXECUTE] Channel-Call-State: [RINGING] Channel-State-Number: [4] Channel-Name: [sofia/external-kamailio/12013992990@sip.telnyx.com] Unique-ID: [5e07cf5b-2b87-4075-8430-34de18f707c4] Call-Direction: [inbound] Presence-Call-Direction: [inbound] Channel-HIT-Dialplan: [true] Channel-Call-UUID: [5e07cf5b-2b87-4075-8430-34de18f707c4] Answer-State: [ringing] Caller-Direction: [inbound] Caller-Logical-Direction: [inbound] Caller-Username: [12013992990] Caller-Dialplan: [XML] Caller-Caller-ID-Name: [Sergey Safarov] Caller-Caller-ID-Number: [12013992990] Caller-Orig-Caller-ID-Name: [Sergey Safarov] Caller-Orig-Caller-ID-Number: [12013992990] Caller-Network-Addr: [10.0.9.55] Caller-ANI: [12013992990] Caller-Destination-Number: [12134237681] Caller-Unique-ID: [5e07cf5b-2b87-4075-8430-34de18f707c4] Caller-Source: [mod_sofia] Caller-Context: [e911] Caller-Channel-Name: [sofia/external-kamailio/12013992990@sip.telnyx.com] Caller-Profile-Index: [1] Caller-Profile-Created-Time: [1515672559655466] Caller-Channel-Created-Time: [1515672559655466] Caller-Channel-Answered-Time: [0] Caller-Channel-Progress-Time: [0] Caller-Channel-Progress-Media-Time: [0] Caller-Channel-Hangup-Time: [0] Caller-Channel-Transfer-Time: [0] Caller-Channel-Resurrect-Time: [0] Caller-Channel-Bridged-Time: [0] Caller-Channel-Last-Hold: [0] Caller-Channel-Hold-Accum: [0] Caller-Screen-Bit: [true] Caller-Privacy-Hide-Name: [false] Caller-Privacy-Hide-Number: [false] variable_direction: [inbound] variable_uuid: [5e07cf5b-2b87-4075-8430-34de18f707c4] variable_session_id: [356] variable_sip_from_user: [12013992990] variable_sip_from_uri: [12013992990@sip.telnyx.com] variable_sip_from_host: [sip.telnyx.com] variable_video_media_flow: [sendrecv] variable_audio_media_flow: [sendrecv] variable_channel_name: [sofia/external-kamailio/12013992990@sip.telnyx.com] variable_sip_call_id: [17fab07d-716b-1236-7a88-02420a0f0c04] variable_ep_codec_string: [mod_spandsp.G722@8000h@20i@64000b,CORE_PCM_MODULE.PCMU@8000h@20i@64000b,CORE_PCM_MODULE.PCMA@8000h@20i@64000b] variable_sip_local_network_addr: [10.0.9.50] variable_sip_network_ip: [10.0.9.55] variable_sip_network_port: [5060] variable_sip_invite_stamp: [1515672559655466] variable_sip_received_ip: [10.0.9.55] variable_sip_received_port: [5060] variable_sip_via_protocol: [udp] variable_sip_from_user_stripped: [12013992990] variable_sip_from_tag: [a1QtHc31jj5XH] variable_sofia_profile_name: [external-kamailio] variable_recovery_profile_name: [external-kamailio] variable_sip_P-Asserted-Identity: [12013992990] variable_sip_cid_type: [pid] variable_sip_invite_route_uri: [,,,] variable_sip_invite_record_route: [,,,] variable_sip_full_via: [SIP/2.0/UDP 10.0.9.55;branch=z9hG4bKe4ed.f1b16c318b2e697ff3f6ab8cd3140aa7.0;i=1,SIP/2.0/TCP 192.76.120.10;branch=z9hG4bKe4ed.97ce71cee4cf5300aa275a07d41c3eac.0;i=cec,SIP/2.0/TCP 10.15.12.4:5082;received=10.15.12.4;rport=55742;branch=z9hG4bKvNceaS2aFHjNr] variable_sip_recover_via: [SIP/2.0/UDP 10.0.9.55;branch=z9hG4bKe4ed.f1b16c318b2e697ff3f6ab8cd3140aa7.0;i=1,SIP/2.0/TCP 192.76.120.10;branch=z9hG4bKe4ed.97ce71cee4cf5300aa275a07d41c3eac.0;i=cec,SIP/2.0/TCP 10.15.12.4:5082;received=10.15.12.4;rport=55742;branch=z9hG4bKvNceaS2aFHjNr] variable_sip_from_display: [Sergey Safarov] variable_sip_full_from: ["Sergey Safarov" ;tag=a1QtHc31jj5XH] variable_sip_full_to: [] variable_sip_allow: [INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, NOTIFY] variable_sip_req_user: [12134237681] variable_sip_req_port: [15080] variable_sip_req_uri: [12134237681@office.nga911.com:15080] variable_sip_req_host: [office.nga911.com] variable_sip_to_user: [12134237681] variable_sip_to_port: [15080] variable_sip_to_uri: [12134237681@office.nga911.com:15080] variable_sip_to_host: [office.nga911.com] variable_sip_contact_params: [alias=10.15.12.4~55742~2] variable_sip_contact_user: [mod_sofia] variable_sip_contact_port: [5082] variable_sip_contact_uri: [mod_sofia@10.15.12.4:5082] variable_sip_contact_host: [10.15.12.4] variable_rtp_use_codec_string: [OPUS,G722,PCMU,PCMA,VP8] variable_sip_via_host: [10.0.9.55] variable_max_forwards: [44] variable_sip_Privacy: [none] variable_sip_h_X-AUTH-IP: [192.76.120.10] variable_sip_h_X-AUTH-PORT: [36831] variable_switch_r_sdp: [v=0 o=Telnyx 1515647013 1515647014 IN IP4 64.16.248.242 s=Telnyx c=IN IP4 64.16.248.242 t=0 0 m=audio 25546 RTP/AVP 9 0 8 18 101 13 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:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 ] variable_endpoint_disposition: [DELAYED NEGOTIATION] variable_DP_MATCH: [ARRAY::12134237681|:2134237681] variable_call_uuid: [5e07cf5b-2b87-4075-8430-34de18f707c4] variable_sip_nat_detected: [false] variable_current_application: [info] 2018-01-11 12:09:19.655466 [NOTICE] switch_core_session.c:1683 Session 354 (sofia/external-kamailio/12013992990@sip.telnyx.com) Ended 2018-01-11 12:09:19.655466 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external-kamailio/12013992990@sip.telnyx.com [CS_DESTROY] 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:741 (sofia/external-kamailio/12013992990@sip.telnyx.com) Running State Change CS_DESTROY (Cur 1 Tot 356) 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:751 (sofia/external-kamailio/12013992990@sip.telnyx.com) State DESTROY 2018-01-11 12:09:19.655466 [DEBUG] mod_sofia.c:343 sofia/external-kamailio/12013992990@sip.telnyx.com SOFIA DESTROY 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:181 sofia/external-kamailio/12013992990@sip.telnyx.com Standard DESTROY 2018-01-11 12:09:19.655466 [DEBUG] switch_core_state_machine.c:751 (sofia/external-kamailio/12013992990@sip.telnyx.com) State DESTROY going to sleep 2018-01-11 12:09:19.895537 [INFO] switch_cpp.cpp:1365 token: eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJzdWIiOjEyOCwiaXNzIjoiaHR0cHM6Ly9jc3AubmdhOTExLmNvbS9nZWFyX2FwaS9hdXRoZW50aWNhdGUiLCJpYXQiOjE1MTU2NzI1NTksImV4cCI6MTUxNTczMjU1OSwibmJmIjoxNTE1NjcyNTU5LCJqdGkiOiJzeDRJNm9BV2RqWDZ3elg1In0.qirCUoGn5nm7Ubf4WSytFX9Aq7AelXS98rUMPtyz2HY 2018-01-11 12:09:19.895537 [DEBUG] switch_cpp.cpp:745 CoreSession::setVariable('csp_token', 'eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJzdWIiOjEyOCwiaXNzIjoiaHR0cHM6Ly9jc3AubmdhOTExLmNvbS9nZWFyX2FwaS9hdXRoZW50aWNhdGUiLCJpYXQiOjE1MTU2NzI1NTksImV4cCI6MTUxNTczMjU1OSwibmJmIjoxNTE1NjcyNTU5LCJqdGkiOiJzeDRJNm9BV2RqWDZ3elg1In0.qirCUoGn5nm7Ubf4WSytFX9Aq7AelXS98rUMPtyz2HY') 2018-01-11 12:09:20.115447 [INFO] switch_cpp.cpp:1365 esinetEntryRoutes url: http://csp.nga911.com/api/ esinetEntryRoutes/entry/12134237681 2018-01-11 12:09:20.115447 [INFO] switch_cpp.cpp:1365 esinetEntryRoutes: {u'message': u'Entry Route retrieval failed.', u'data': [], u'success': False} 2018-01-11 12:09:20.115447 [DEBUG] switch_core_session.c:2647 Application playback Requires media! pre_answering channel sofia/external-kamailio/12013992990@sip.telnyx.com 2018-01-11 12:09:20.115447 [INFO] switch_core_session.c:2649 Sending early media 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:3061 Set Codec sofia/external-kamailio/12013992990@sip.telnyx.com G722/8000 20 ms 160 samples 64000 bits 1 channels 2018-01-11 12:09:20.115447 [DEBUG] switch_core_codec.c:111 sofia/external-kamailio/12013992990@sip.telnyx.com Original read codec set to G722:9 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:4767 sofia/external-kamailio/12013992990@sip.telnyx.com Set 2833 dtmf send payload to 101 recv payload to 101 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/external-kamailio/12013992990@sip.telnyx.com] 172.18.0.12 port 18352 -> 64.16.248.242 port 25546 codec: 9 ms: 20 2018-01-11 12:09:20.115447 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:7180 sofia/external-kamailio/12013992990@sip.telnyx.com Set 2833 dtmf send payload to 101 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:7187 sofia/external-kamailio/12013992990@sip.telnyx.com Set 2833 dtmf receive payload to 101 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:7210 sofia/external-kamailio/12013992990@sip.telnyx.com Set rtp dtmf delay to 40 2018-01-11 12:09:20.115447 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external-kamailio/12013992990@sip.telnyx.com! 2018-01-11 12:09:20.115447 [DEBUG] switch_channel.c:3474 (sofia/external-kamailio/12013992990@sip.telnyx.com) Callstate Change RINGING -> EARLY 2018-01-11 12:09:20.115447 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/external-kamailio/12013992990@sip.telnyx.com. 2018-01-11 12:09:20.115447 [DEBUG] mod_sofia.c:2364 Ring SDP: v=0 o=FreeSWITCH 1515654208 1515654209 IN IP4 34.214.12.24 s=FreeSWITCH c=IN IP4 34.214.12.24 t=0 0 m=audio 18352 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv EXECUTE sofia/external-kamailio/12013992990@sip.telnyx.com playback(error) 2018-01-11 12:09:20.115447 [ERR] mod_native_file.c:74 Error opening /usr/share/freeswitch/sounds/en/us/callie/error.G722 send 1502 bytes to udp/[10.0.9.55]:5060 at 12:09:20.121044: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 10.0.9.55;branch=z9hG4bKe4ed.f1b16c318b2e697ff3f6ab8cd3140aa7.0;i=1 Via: SIP/2.0/TCP 192.76.120.10;branch=z9hG4bKe4ed.97ce71cee4cf5300aa275a07d41c3eac.0;i=cec v:SIP/2.0/TCP 10.15.12.4:5082;received=10.15.12.4;rport=55742;branch=z9hG4bKvNceaS2aFHjNr Record-Route: Record-Route: Record-Route: Record-Route: f:"Sergey Safarov";tag=a1QtHc31jj5XH To: ;tag=jHa17jcp7XrtH i:17fab07d-716b-1236-7a88-02420a0f0c04 CSeq:117500215 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.19+git-20171224T074649Z~f858a27ad1~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 220 P-Asserted-Identity: "12134237681" v=0 o=FreeSWITCH 1515654208 1515654209 IN IP4 34.214.12.24 s=FreeSWITCH c=IN IP4 34.214.12.24 t=0 0 m=audio 18352 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2018-01-11 12:09:20.115447 [ERR] mod_sndfile.c:204 Error Opening File [/usr/share/freeswitch/sounds/en/us/callie/error.wav] [System error : No such file or directory.] 2018-01-11 12:09:20.115447 [DEBUG] sofia.c:7084 Channel sofia/external-kamailio/12013992990@sip.telnyx.com entering state [early][183] 2018-01-11 12:09:20.115447 [DEBUG] mod_python.c:286 Finished calling python script 2018-01-11 12:09:20.115447 [NOTICE] switch_core_state_machine.c:385 sofia/external-kamailio/12013992990@sip.telnyx.com has executed the last dialplan instruction, hanging up. 2018-01-11 12:09:20.115447 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/external-kamailio/12013992990@sip.telnyx.com [CS_EXECUTE] [NORMAL_CLEARING] 2018-01-11 12:09:20.115447 [DEBUG] switch_core_state_machine.c:650 (sofia/external-kamailio/12013992990@sip.telnyx.com) State EXECUTE going to sleep 2018-01-11 12:09:20.115447 [DEBUG] switch_core_state_machine.c:584 (sofia/external-kamailio/12013992990@sip.telnyx.com) Running State Change CS_HANGUP (Cur 1 Tot 356) 2018-01-11 12:09:20.115447 [DEBUG] switch_core_state_machine.c:850 (sofia/external-kamailio/12013992990@sip.telnyx.com) Callstate Change EARLY -> HANGUP 2018-01-11 12:09:20.115447 [DEBUG] switch_core_state_machine.c:852 (sofia/external-kamailio/12013992990@sip.telnyx.com) State HANGUP 2018-01-11 12:09:20.115447 [DEBUG] mod_sofia.c:438 Channel sofia/external-kamailio/12013992990@sip.telnyx.com hanging up, cause: NORMAL_CLEARING 2018-01-11 12:09:20.115447 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 480 2018-01-11 12:09:20.115447 [DEBUG] switch_core_state_machine.c:60 sofia/external-kamailio/12013992990@sip.telnyx.com Standard HANGUP, cause: NORMAL_CLEARING 2018-01-11 12:09:20.115447 [DEBUG] switch_core_state_machine.c:852 (sofia/external-kamailio/12013992990@sip.telnyx.com) State HANGUP going to sleep 2018-01-11 12:09:20.115447 [DEBUG] switch_core_state_machine.c:619 (sofia/external-kamailio/12013992990@sip.telnyx.com) State Change CS_HANGUP -> CS_REPORTING 2018-01-11 12:09:20.115447 [DEBUG] switch_core_state_machine.c:584 (sofia/external-kamailio/12013992990@sip.telnyx.com) Running State Change CS_REPORTING (Cur 1 Tot 356) send 910 bytes to udp/[10.0.9.55]:5060 at 12:09:20.121884: ------------------------------------------------------------------------ SIP/2.0 480 Temporarily Unavailable Via: SIP/2.0/UDP 10.0.9.55;branch=z9hG4bKe4ed.f1b16c318b2e697ff3f6ab8cd3140aa7.0;i=1 Via: SIP/2.0/TCP 192.76.120.10;branch=z9hG4bKe4ed.97ce71cee4cf5300aa275a07d41c3eac.0;i=cec v:SIP/2.0/TCP 10.15.12.4:5082;received=10.15.12.4;rport=55742;branch=z9hG4bKvNceaS2aFHjNr Max-Forwards: 44 f:"Sergey Safarov";tag=a1QtHc31jj5XH To: ;tag=jHa17jcp7XrtH i:17fab07d-716b-1236-7a88-02420a0f0c04 CSeq:117500215 INVITE User-Agent: FreeSWITCH-mod_sofia/1.6.19+git-20171224T074649Z~f858a27ad1~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 P-Asserted-Identity: "12134237681" ------------------------------------------------------------------------ 2018-01-11 12:09:20.115447 [DEBUG] switch_core_state_machine.c:938 (sofia/external-kamailio/12013992990@sip.telnyx.com) State REPORTING recv 359 bytes from udp/[10.0.9.55]:5060 at 12:09:20.122573: ------------------------------------------------------------------------ ACK sip:12134237681@office.nga911.com:15080 SIP/2.0 Via: SIP/2.0/UDP 10.0.9.55;branch=z9hG4bKe4ed.f1b16c318b2e697ff3f6ab8cd3140aa7.0;i=1 Max-Forwards:44 f:"Sergey Safarov";tag=a1QtHc31jj5XH To: ;tag=jHa17jcp7XrtH i:17fab07d-716b-1236-7a88-02420a0f0c04 CSeq:117500215 ACK l: 0 ------------------------------------------------------------------------ 2018-01-11 12:09:20.375470 [ERR] mod_xml_cdr.c:395 Got error [500] posting to web server [https://csp.nga911.com/call/LogXML] 2018-01-11 12:09:20.375470 [ERR] mod_xml_cdr.c:402 Retry will be with url [https://csp.nga911.com/call/LogXML] 2018-01-11 12:09:22.725466 [NOTICE] sofia_reg.c:448 Registering kazoo send 822 bytes to udp/[52.42.195.203]:5060 at 12:09:22.745610: ------------------------------------------------------------------------ REGISTER sip:node1.nga911.com;transport=udp SIP/2.0 Via: SIP/2.0/UDP 52.24.72.57:5080;rport;branch=z9hG4bK86raX05cQ8gae Max-Forwards: 70 From: ;tag=8XQ4Za3H2tD8g To: Call-ID: 1268c844-60be-4a27-9325-bb3155eec8af CSeq: 117500202 REGISTER Contact: Expires: 30 User-Agent: FreeSWITCH-mod_sofia/1.6.19+git-20171224T074649Z~f858a27ad1~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Authorization: Digest username="queries1", realm="node1.nga911.com", nonce="WldU3FpXU7Ca5zf6SMinI2t36d3oUXlW", algorithm=MD5, uri="sip:node1.nga911.com;transport=udp", response="21e4c96c435809ed68656ef92732a1c7" Content-Length: 0 ------------------------------------------------------------------------ recv 440 bytes from udp/[52.42.195.203]:5060 at 12:09:22.767369: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 52.24.72.57:5080;rport=5080;branch=z9hG4bK86raX05cQ8gae;received=34.214.12.24 From: ;tag=8XQ4Za3H2tD8g To: ;tag=bdded40c8142006f90af49be63d6cf32-6b23 Call-ID: 1268c844-60be-4a27-9325-bb3155eec8af CSeq: 117500202 REGISTER Contact: ;expires=300 Supported: outbound Content-Length: 0 ------------------------------------------------------------------------ 2018-01-11 12:09:22.765513 [DEBUG] sofia_reg.c:2435 Changing expire time to 300 by request of proxy sip:node1.nga911.com 2018-01-11 12:09:22.845469 [ERR] mod_xml_cdr.c:395 Got error [500] posting to web server [https://csp.nga911.com/call/LogXML] 2018-01-11 12:09:22.845469 [ERR] mod_xml_cdr.c:402 Retry will be with url [https://csp.nga911.com/call/LogXML] 2018-01-11 12:09:25.065472 [ERR] mod_xml_cdr.c:395 Got error [500] posting to web server [https://csp.nga911.com/call/LogXML] 2018-01-11 12:09:25.065472 [ERR] mod_xml_cdr.c:402 Retry will be with url [https://csp.nga911.com/call/LogXML] 2018-01-11 12:09:27.355470 [ERR] mod_xml_cdr.c:395 Got error [500] posting to web server [https://csp.nga911.com/call/LogXML] 2018-01-11 12:09:27.355470 [ERR] mod_xml_cdr.c:402 Retry will be with url [https://csp.nga911.com/call/LogXML] 2018-01-11 12:09:27.355470 [ERR] mod_xml_cdr.c:418 Unable to post to web server, writing to file 2018-01-11 12:09:27.355470 [DEBUG] switch_core_state_machine.c:174 sofia/external-kamailio/12013992990@sip.telnyx.com Standard REPORTING, cause: NORMAL_CLEARING 2018-01-11 12:09:27.355470 [DEBUG] switch_core_state_machine.c:938 (sofia/external-kamailio/12013992990@sip.telnyx.com) State REPORTING going to sleep 2018-01-11 12:09:27.355470 [DEBUG] switch_core_state_machine.c:610 (sofia/external-kamailio/12013992990@sip.telnyx.com) State Change CS_REPORTING -> CS_DESTROY 2018-01-11 12:09:27.355470 [DEBUG] switch_core_session.c:1665 Session 356 (sofia/external-kamailio/12013992990@sip.telnyx.com) Locked, Waiting on external entities recv 326 bytes from udp/[10.0.9.54]:5060 at 12:09:28.413832: ------------------------------------------------------------------------ OPTIONS sip:10.0.9.50:12000 SIP/2.0 Via: SIP/2.0/UDP 10.0.9.54;branch=z9hG4bKae87.00980432000000000000000000000000.0 To: From: ;tag=dd842359c3d1f52b828bb146259eb8e4-8608 CSeq: 10 OPTIONS Call-ID: 60ec4ccf27887dd6-105@10.0.9.54 Max-Forwards: 70