recv 817 bytes from udp/[192.168.1.33]:5060 at 14:45:58.514350: ------------------------------------------------------------------------ INVITE sip:9186******73@127.0.0.1;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.33:5060;branch=z9hG4bK1202;rport From: "8005" ;tag=3cd16e0589b326696 To: Call-ID: 3cd16e0589b39777@192.168.1.33 CSeq: 2081 INVITE Contact: "8005" Max-Forwards: 70 User-Agent: SIPUA Expires: 120 Supported: 100rel P-Preferred-Identity: "8005" Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, UPDATE, PRACK Content-Type: application/sdp Content-Length: 206 v=0 o=8005 20000001 31 IN IP4 192.168.1.33 s=A call c=IN IP4 192.168.1.33 t=0 0 m=audio 10000 RTP/AVP 18 0 8 a=rtpmap:18 G729/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=ptime:20 a=sendrecv ------------------------------------------------------------------------ send 359 bytes to udp/[192.168.1.33]:5060 at 14:45:58.514671: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.33:5060;branch=z9hG4bK1202;rport=5060 From: "8005" ;tag=3cd16e0589b326696 To: Call-ID: 3cd16e0589b39777@192.168.1.33 CSeq: 2081 INVITE User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20141220T224621Z~0a0b9262b4~64bit Content-Length: 0 ------------------------------------------------------------------------ 2017-04-14 14:45:58.512503 [NOTICE] switch_channel.c:1055 New Channel sofia/internal/8005@127.0.0.1 [044e242e-20de-11e7-ba33-f7c335f7649a] 2017-04-14 14:45:58.512503 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:45:58.512503 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:45:58.512503 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/8005@127.0.0.1) Running State Change CS_NEW 2017-04-14 14:45:58.512503 [DEBUG] sofia.c:8834 sofia/internal/8005@127.0.0.1 receiving invite from 192.168.1.33:5060 version: 1.5.15b git 0a0b926 2014-12-20 22:46:21Z 64bit 2017-04-14 14:45:58.512503 [DEBUG] sofia.c:9001 IP 192.168.1.33 Rejected by acl "domains". Falling back to Digest auth. 2017-04-14 14:45:58.512503 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/8005@127.0.0.1) State NEW send 859 bytes to udp/[192.168.1.33]:5060 at 14:45:58.515399: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.33:5060;branch=z9hG4bK1202;rport=5060 From: "8005" ;tag=3cd16e0589b326696 To: ;tag=1Zmp3ej28685B Call-ID: 3cd16e0589b39777@192.168.1.33 CSeq: 2081 INVITE User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20141220T224621Z~0a0b9262b4~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="127.0.0.1", nonce="044e2e1a-20de-11e7-ba34-f7c335f7649a", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ 2017-04-14 14:45:58.512503 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:45:58.512503 [DEBUG] sofia.c:2067 detaching session 044e242e-20de-11e7-ba33-f7c335f7649a recv 320 bytes from udp/[192.168.1.33]:5060 at 14:45:58.535989: ------------------------------------------------------------------------ ACK sip:9186******73@127.0.0.1;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.33:5060;branch=z9hG4bK1202;rport From: "8005" ;tag=3cd16e0589b326696 To: ;tag=1Zmp3ej28685B Call-ID: 3cd16e0589b39777@192.168.1.33 CSeq: 2081 ACK Content-Length: 0 ------------------------------------------------------------------------ recv 1051 bytes from udp/[192.168.1.33]:5060 at 14:45:58.537349: ------------------------------------------------------------------------ INVITE sip:9186******73@127.0.0.1;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.33:5060;branch=z9hG4bK19726;rport From: "8005" ;tag=3cd16e0589b326696 To: Call-ID: 3cd16e0589b39777@192.168.1.33 CSeq: 2082 INVITE Contact: "8005" Proxy-Authorization: Digest username="8005", realm="127.0.0.1", nonce="044e2e1a-20de-11e7-ba34-f7c335f7649a", uri="sip:127.0.0.1", response="901c2c5bf4cd4b618c9d52a03ce07108", algorithm=MD5, cnonce="000010cc", qop=auth, nc=00000001 Max-Forwards: 70 User-Agent: SIPUA Expires: 120 Supported: 100rel P-Preferred-Identity: "8005" Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, UPDATE, PRACK Content-Type: application/sdp Content-Length: 206 v=0 o=8005 20000001 31 IN IP4 192.168.1.33 s=A call c=IN IP4 192.168.1.33 t=0 0 m=audio 10000 RTP/AVP 18 0 8 a=rtpmap:18 G729/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=ptime:20 a=sendrecv ------------------------------------------------------------------------ send 360 bytes to udp/[192.168.1.33]:5060 at 14:45:58.537639: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.33:5060;branch=z9hG4bK19726;rport=5060 From: "8005" ;tag=3cd16e0589b326696 To: Call-ID: 3cd16e0589b39777@192.168.1.33 CSeq: 2082 INVITE User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20141220T224621Z~0a0b9262b4~64bit Content-Length: 0 ------------------------------------------------------------------------ 2017-04-14 14:45:58.532512 [DEBUG] sofia.c:2175 Re-attaching to session 044e242e-20de-11e7-ba33-f7c335f7649a 2017-04-14 14:45:58.532512 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:45:58.532512 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:45:58.552511 [DEBUG] sofia.c:8834 sofia/internal/8005@127.0.0.1 receiving invite from 192.168.1.33:5060 version: 1.5.15b git 0a0b926 2014-12-20 22:46:21Z 64bit 2017-04-14 14:45:58.552511 [DEBUG] sofia.c:9001 IP 192.168.1.33 Rejected by acl "domains". Falling back to Digest auth. 2017-04-14 14:45:58.552511 [DEBUG] sofia.c:6614 Channel sofia/internal/8005@127.0.0.1 entering state [received][100] 2017-04-14 14:45:58.552511 [DEBUG] sofia.c:6624 Remote SDP: v=0 o=8005 20000001 31 IN IP4 192.168.1.33 s=A call c=IN IP4 192.168.1.33 t=0 0 m=audio 10000 RTP/AVP 18 0 8 a=rtpmap:18 G729/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=ptime:20 2017-04-14 14:45:58.552511 [DEBUG] sofia.c:6890 (sofia/internal/8005@127.0.0.1) State Change CS_NEW -> CS_INIT 2017-04-14 14:45:58.552511 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/8005@127.0.0.1) Running State Change CS_INIT 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/8005@127.0.0.1) State INIT 2017-04-14 14:45:58.552511 [DEBUG] mod_sofia.c:87 sofia/internal/8005@127.0.0.1 SOFIA INIT 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:40 sofia/internal/8005@127.0.0.1 Standard INIT 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/8005@127.0.0.1) State Change CS_INIT -> CS_ROUTING 2017-04-14 14:45:58.552511 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/8005@127.0.0.1) State INIT going to sleep 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/8005@127.0.0.1) Running State Change CS_ROUTING 2017-04-14 14:45:58.552511 [DEBUG] switch_channel.c:2184 (sofia/internal/8005@127.0.0.1) Callstate Change DOWN -> RINGING 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/8005@127.0.0.1) State ROUTING 2017-04-14 14:45:58.552511 [DEBUG] mod_sofia.c:123 sofia/internal/8005@127.0.0.1 SOFIA ROUTING 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:166 sofia/internal/8005@127.0.0.1 Standard ROUTING 2017-04-14 14:45:58.552511 [INFO] mod_dialplan_xml.c:635 Processing 8005 <8005>->9186******73 in context default Dialplan: sofia/internal/8005@127.0.0.1 parsing [default->tod_example] continue=true Dialplan: sofia/internal/8005@127.0.0.1 Date/Time Match (PASS) [tod_example] break=on-true Dialplan: sofia/internal/8005@127.0.0.1 Action set(open=true) Dialplan: sofia/internal/8005@127.0.0.1 parsing [default->holiday_example] continue=true Dialplan: sofia/internal/8005@127.0.0.1 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/internal/8005@127.0.0.1 parsing [default->Local_Extension] continue=false Dialplan: sofia/internal/8005@127.0.0.1 Regex (FAIL) [Local_Extension] destination_number(9186******73) =~ /^[18]0\d{2}$/ break=on-false Dialplan: sofia/internal/8005@127.0.0.1 parsing [default->call_out3] continue=false Dialplan: sofia/internal/8005@127.0.0.1 Regex (PASS) [call_out3] destination_number(9186******73) =~ /^9(\d+)$/ break=on-false Dialplan: sofia/internal/8005@127.0.0.1 Action log(INFO ${sip_from_user}) Dialplan: sofia/internal/8005@127.0.0.1 Action bridge({originion_caller_id_name=${outbound_caller_id_number},origination_caller_id_number=${outbound_caller_id_number}}sofia/external/186******73@192.168.1.101) 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:216 (sofia/internal/8005@127.0.0.1) State Change CS_ROUTING -> CS_EXECUTE 2017-04-14 14:45:58.552511 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/8005@127.0.0.1) State ROUTING going to sleep 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/8005@127.0.0.1) Running State Change CS_EXECUTE 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:535 (sofia/internal/8005@127.0.0.1) State EXECUTE 2017-04-14 14:45:58.552511 [DEBUG] mod_sofia.c:178 sofia/internal/8005@127.0.0.1 SOFIA EXECUTE 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:258 sofia/internal/8005@127.0.0.1 Standard EXECUTE EXECUTE sofia/internal/8005@127.0.0.1 set(open=true) 2017-04-14 14:45:58.552511 [DEBUG] mod_dptools.c:1435 sofia/internal/8005@127.0.0.1 SET [open]=[true] EXECUTE sofia/internal/8005@127.0.0.1 log(INFO 8005) 2017-04-14 14:45:58.552511 [INFO] mod_dptools.c:1628 8005 EXECUTE sofia/internal/8005@127.0.0.1 bridge({originion_caller_id_name=0000000000,origination_caller_id_number=0000000000}sofia/external/186******73@192.168.1.101) 2017-04-14 14:45:58.552511 [DEBUG] switch_ivr_originate.c:2103 Parsing global variables 2017-04-14 14:45:58.552511 [DEBUG] switch_event.c:1688 Parsing variable [originion_caller_id_name]=[0000000000] 2017-04-14 14:45:58.552511 [DEBUG] switch_event.c:1688 Parsing variable [origination_caller_id_number]=[0000000000] 2017-04-14 14:45:58.552511 [NOTICE] switch_channel.c:1055 New Channel sofia/external/186******73@192.168.1.101 [0454d666-20de-11e7-ba3c-f7c335f7649a] 2017-04-14 14:45:58.552511 [DEBUG] mod_sofia.c:4627 (sofia/external/186******73@192.168.1.101) State Change CS_NEW -> CS_INIT 2017-04-14 14:45:58.552511 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/186******73@192.168.1.101 [BREAK] 2017-04-14 14:45:58.552511 [DEBUG] mod_sofia.c:4697 [zrtp_passthru] Setting a-leg inherit_codec=true 2017-04-14 14:45:58.552511 [DEBUG] mod_sofia.c:4700 [zrtp_passthru] Setting b-leg absolute_codec_string='PCMU@8000h@20i@64000b,PCMA@8000h@20i@64000b' 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:472 (sofia/external/186******73@192.168.1.101) Running State Change CS_INIT 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:512 (sofia/external/186******73@192.168.1.101) State INIT 2017-04-14 14:45:58.552511 [DEBUG] mod_sofia.c:87 sofia/external/186******73@192.168.1.101 SOFIA INIT 2017-04-14 14:45:58.552511 [DEBUG] sofia_glue.c:1232 sofia/external/186******73@192.168.1.101 sending invite version: 1.5.15b git 0a0b926 2014-12-20 22:46:21Z 64bit Local SDP: v=0 o=FreeSWITCH 1492122818 1492122819 IN IP4 192.168.1.246 s=FreeSWITCH c=IN IP4 192.168.1.246 t=0 0 m=audio 29540 RTP/AVP 0 8 101 13 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:40 sofia/external/186******73@192.168.1.101 Standard INIT 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:48 (sofia/external/186******73@192.168.1.101) State Change CS_INIT -> CS_ROUTING 2017-04-14 14:45:58.552511 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/186******73@192.168.1.101 [BREAK] 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:512 (sofia/external/186******73@192.168.1.101) State INIT going to sleep send 1068 bytes to udp/[192.168.1.101]:5060 at 14:45:58.559681: ------------------------------------------------------------------------ INVITE sip:186******73@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.246:5080;rport;branch=z9hG4bKrSSavg44NcDQN Max-Forwards: 69 From: "Extension 8005" ;tag=SygvtFjSyD4Hg To: Call-ID: dbb3399b-9b80-1235-b997-000bab7a8683 CSeq: 105740115 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20141220T224621Z~0a0b9262b4~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Privacy: none Content-Type: application/sdp Content-Disposition: session Content-Length: 249 X-FS-Support: update_display,send_info P-Asserted-Identity: "Extension 8005" v=0 o=FreeSWITCH 1492122818 1492122819 IN IP4 192.168.1.246 s=FreeSWITCH c=IN IP4 192.168.1.246 t=0 0 m=audio 29540 RTP/AVP 0 8 101 13 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2017-04-14 14:45:58.552511 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/186******73@192.168.1.101 [BREAK] 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:472 (sofia/external/186******73@192.168.1.101) Running State Change CS_ROUTING 2017-04-14 14:45:58.552511 [DEBUG] sofia.c:6614 Channel sofia/external/186******73@192.168.1.101 entering state [calling][0] 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:528 (sofia/external/186******73@192.168.1.101) State ROUTING 2017-04-14 14:45:58.552511 [DEBUG] mod_sofia.c:123 sofia/external/186******73@192.168.1.101 SOFIA ROUTING 2017-04-14 14:45:58.552511 [DEBUG] switch_ivr_originate.c:67 (sofia/external/186******73@192.168.1.101) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2017-04-14 14:45:58.552511 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/186******73@192.168.1.101 [BREAK] 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:528 (sofia/external/186******73@192.168.1.101) State ROUTING going to sleep 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:472 (sofia/external/186******73@192.168.1.101) Running State Change CS_CONSUME_MEDIA 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:547 (sofia/external/186******73@192.168.1.101) State CONSUME_MEDIA 2017-04-14 14:45:58.552511 [DEBUG] switch_core_state_machine.c:547 (sofia/external/186******73@192.168.1.101) State CONSUME_MEDIA going to sleep recv 319 bytes from udp/[192.168.1.101]:5060 at 14:45:58.585924: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.246:5080;rport=5080;branch=z9hG4bKrSSavg44NcDQN From: "Extension 8005" ;tag=SygvtFjSyD4Hg To: Call-ID: dbb3399b-9b80-1235-b997-000bab7a8683 CSeq: 105740115 INVITE User-Agent: Gateway Content-Length: 0 ------------------------------------------------------------------------ recv 630 bytes from udp/[192.168.1.101]:5060 at 14:46:01.560002: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.246:5080;rport=5080;branch=z9hG4bKrSSavg44NcDQN From: "Extension 8005" ;tag=SygvtFjSyD4Hg To: ;tag=3271950963 Call-ID: dbb3399b-9b80-1235-b997-000bab7a8683 CSeq: 105740115 INVITE Contact: User-Agent: Gateway Content-Type: application/sdp Content-Length: 218 v=0 o=- 65 66 IN IP4 192.168.1.101 s=Gateway c=IN IP4 192.168.1.101 t=0 0 m=audio 50000 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv ------------------------------------------------------------------------ 2017-04-14 14:46:01.552506 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/186******73@192.168.1.101 [BREAK] 2017-04-14 14:46:01.552506 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/186******73@192.168.1.101 [BREAK] 2017-04-14 14:46:01.552506 [DEBUG] sofia.c:6614 Channel sofia/external/186******73@192.168.1.101 entering state [completing][200] 2017-04-14 14:46:01.552506 [DEBUG] sofia.c:6624 Remote SDP: v=0 o=- 65 66 IN IP4 192.168.1.101 s=Gateway c=IN IP4 192.168.1.101 t=0 0 m=audio 50000 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 send 396 bytes to udp/[192.168.1.101]:5060 at 14:46:01.560851: ------------------------------------------------------------------------ ACK sip:186******73@192.168.1.101:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.246:5080;rport;branch=z9hG4bKS2j3XBN8jN39g Max-Forwards: 70 From: "Extension 8005" ;tag=SygvtFjSyD4Hg To: ;tag=3271950963 Call-ID: dbb3399b-9b80-1235-b997-000bab7a8683 CSeq: 105740115 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ 2017-04-14 14:46:01.552506 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/186******73@192.168.1.101 [BREAK] 2017-04-14 14:46:01.552506 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/186******73@192.168.1.101 [BREAK] 2017-04-14 14:46:01.552506 [DEBUG] sofia.c:6614 Channel sofia/external/186******73@192.168.1.101 entering state [ready][200] 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:3682 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:3682 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:3543 Set telephone-event payload to 101 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:2473 Set Codec sofia/external/186******73@192.168.1.101 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2017-04-14 14:46:01.552506 [DEBUG] switch_core_codec.c:111 sofia/external/186******73@192.168.1.101 Original read codec set to PCMU:0 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:3881 Set 2833 dtmf send payload to 101 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:5141 AUDIO RTP [sofia/external/186******73@192.168.1.101] 192.168.1.246 port 29540 -> 192.168.1.101 port 50000 codec: 0 ms: 20 2017-04-14 14:46:01.552506 [DEBUG] switch_rtp.c:3548 Starting timer [soft] 160 bytes per 20ms 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:5439 Set 2833 dtmf send payload to 101 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:5445 Set 2833 dtmf receive payload to 101 2017-04-14 14:46:01.552506 [DEBUG] switch_channel.c:3635 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:46:01.552506 [NOTICE] sofia.c:7475 Channel [sofia/external/186******73@192.168.1.101] has been answered 2017-04-14 14:46:01.552506 [DEBUG] switch_channel.c:3689 (sofia/external/186******73@192.168.1.101) Callstate Change DOWN -> ACTIVE 2017-04-14 14:46:01.552506 [DEBUG] switch_ivr_originate.c:412 Setting codec string on sofia/internal/8005@127.0.0.1 to PCMU@8000h@20i 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:3682 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:3627 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:2473 Set Codec sofia/internal/8005@127.0.0.1 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2017-04-14 14:46:01.552506 [DEBUG] switch_core_codec.c:111 sofia/internal/8005@127.0.0.1 Original read codec set to PCMU:0 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:3903 No 2833 in SDP. Disable 2833 dtmf and switch to INFO 2017-04-14 14:46:01.552506 [DEBUG] switch_core_media.c:5141 AUDIO RTP [sofia/internal/8005@127.0.0.1] 192.168.1.246 port 22532 -> 192.168.1.33 port 10000 codec: 0 ms: 20 2017-04-14 14:46:01.552506 [DEBUG] switch_rtp.c:3548 Starting timer [soft] 160 bytes per 20ms 2017-04-14 14:46:01.552506 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/8005@127.0.0.1! 2017-04-14 14:46:01.552506 [DEBUG] switch_channel.c:3399 (sofia/internal/8005@127.0.0.1) Callstate Change RINGING -> EARLY 2017-04-14 14:46:01.552506 [DEBUG] mod_sofia.c:780 Local SDP sofia/internal/8005@127.0.0.1: v=0 o=FreeSWITCH 1492129829 1492129830 IN IP4 192.168.1.246 s=FreeSWITCH c=IN IP4 192.168.1.246 t=0 0 m=audio 22532 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 a=sendrecv 2017-04-14 14:46:01.552506 [DEBUG] switch_core_session.c:908 Send signal sofia/internal/8005@127.0.0.1 [BREAK] send 1071 bytes to udp/[192.168.1.33]:5060 at 14:46:01.566374: ------------------------------------------------------------------------ 2017-04-14 14:46:01.552506 [NOTICE] switch_ivr_originate.c:3522 Channel [sofia/internal/8005@127.0.0.1] has been answered SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.33:5060;branch=z9hG4bK19726;rport=5060 From: "8005" ;tag=3cd16e0589b326696 To: ;tag=28DF59255FZrQ Call-ID: 3cd16e0589b39777@192.168.1.33 CSeq: 2082 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20141220T224621Z~0a0b9262b4~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 166 P-Asserted-Identity: "Outbound Call" v=0 o=FreeSWITCH 1492129829 1492129830 IN IP4 192.168.1.246 s=FreeSWITCH c=IN IP4 192.168.1.246 t=0 0 m=audio 22532 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 ------------------------------------------------------------------------ 2017-04-14 14:46:01.552506 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:46:01.552506 [DEBUG] switch_channel.c:3689 (sofia/internal/8005@127.0.0.1) Callstate Change EARLY -> ACTIVE 2017-04-14 14:46:01.552506 [DEBUG] sofia.c:6614 Channel sofia/internal/8005@127.0.0.1 entering state [completed][200] 2017-04-14 14:46:01.552506 [DEBUG] switch_ivr_originate.c:3580 Originate Resulted in Success: [sofia/external/186******73@192.168.1.101] 2017-04-14 14:46:01.552506 [DEBUG] switch_core_session.c:908 Send signal sofia/external/186******73@192.168.1.101 [BREAK] 2017-04-14 14:46:01.552506 [DEBUG] switch_core_session.c:908 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:46:01.552506 [DEBUG] switch_ivr_bridge.c:1465 (sofia/external/186******73@192.168.1.101) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2017-04-14 14:46:01.552506 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/186******73@192.168.1.101 [BREAK] 2017-04-14 14:46:01.552506 [DEBUG] switch_core_state_machine.c:472 (sofia/external/186******73@192.168.1.101) Running State Change CS_EXCHANGE_MEDIA 2017-04-14 14:46:01.552506 [DEBUG] switch_core_state_machine.c:538 (sofia/external/186******73@192.168.1.101) State EXCHANGE_MEDIA 2017-04-14 14:46:01.552506 [DEBUG] mod_sofia.c:594 SOFIA EXCHANGE_MEDIA recv 376 bytes from udp/[192.168.1.33]:5060 at 14:46:01.576230: ------------------------------------------------------------------------ ACK sip:9186******73@117.185.49.89:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.1.33:5060;rport;branch=z9hG4bK27697;rport From: "8005" ;tag=3cd16e0589b326696 To: ;tag=28DF59255FZrQ Call-ID: 3cd16e0589b39777@192.168.1.33 CSeq: 2082 ACK Max-Forwards: 70 User-Agent: SIPUA Content-Length: 0 ------------------------------------------------------------------------ 2017-04-14 14:46:01.572513 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:46:01.572513 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:46:01.572513 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:46:01.592514 [DEBUG] sofia.c:6614 Channel sofia/internal/8005@127.0.0.1 entering state [ready][200] 2017-04-14 14:46:01.592514 [DEBUG] switch_core_session.c:970 Send signal sofia/external/186******73@192.168.1.101 [BREAK] 2017-04-14 14:46:01.592514 [DEBUG] switch_core_session.c:970 Send signal sofia/internal/8005@127.0.0.1 [BREAK] recv 414 bytes from udp/[192.168.1.101]:5060 at 14:46:06.867652: ------------------------------------------------------------------------ BYE sip:mod_sofia@192.168.1.246:5080 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.101:5060;branch=z9hG4bK3093601659;rport From: ;tag=3271950963 To: "Extension 8005" ;tag=SygvtFjSyD4Hg Call-ID: dbb3399b-9b80-1235-b997-000bab7a8683 CSeq: 105740116 BYE Contact: Max-Forwards: 70 User-Agent: Gateway Content-Length: 0 ------------------------------------------------------------------------ 2017-04-14 14:46:06.852505 [DEBUG] switch_core_session.c:1053 Send signal sofia/external/186******73@192.168.1.101 [BREAK] 2017-04-14 14:46:06.872505 [NOTICE] sofia.c:952 Hangup sofia/external/186******73@192.168.1.101 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2017-04-14 14:46:06.872505 [DEBUG] switch_channel.c:3222 Send signal sofia/external/186******73@192.168.1.101 [KILL] 2017-04-14 14:46:06.872505 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/186******73@192.168.1.101 [BREAK] send 507 bytes to udp/[192.168.1.101]:5060 at 14:46:06.873375: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.101:5060;branch=z9hG4bK3093601659;rport=5060 From: ;tag=3271950963 To: "Extension 8005" ;tag=SygvtFjSyD4Hg Call-ID: dbb3399b-9b80-1235-b997-000bab7a8683 CSeq: 105740116 BYE User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20141220T224621Z~0a0b9262b4~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2017-04-14 14:46:06.872505 [DEBUG] switch_ivr_bridge.c:660 BRIDGE THREAD DONE [sofia/external/186******73@192.168.1.101] 2017-04-14 14:46:06.872505 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:46:06.872505 [DEBUG] switch_core_state_machine.c:538 (sofia/external/186******73@192.168.1.101) State EXCHANGE_MEDIA going to sleep 2017-04-14 14:46:06.872505 [DEBUG] switch_core_state_machine.c:472 (sofia/external/186******73@192.168.1.101) Running State Change CS_HANGUP 2017-04-14 14:46:06.872505 [DEBUG] switch_core_state_machine.c:735 (sofia/external/186******73@192.168.1.101) Callstate Change ACTIVE -> HANGUP 2017-04-14 14:46:06.872505 [DEBUG] switch_core_state_machine.c:737 (sofia/external/186******73@192.168.1.101) State HANGUP 2017-04-14 14:46:06.872505 [DEBUG] mod_sofia.c:413 Channel sofia/external/186******73@192.168.1.101 hanging up, cause: NORMAL_CLEARING 2017-04-14 14:46:06.872505 [DEBUG] switch_core_state_machine.c:60 sofia/external/186******73@192.168.1.101 Standard HANGUP, cause: NORMAL_CLEARING 2017-04-14 14:46:06.872505 [DEBUG] switch_core_state_machine.c:737 (sofia/external/186******73@192.168.1.101) State HANGUP going to sleep 2017-04-14 14:46:06.872505 [DEBUG] switch_core_state_machine.c:504 (sofia/external/186******73@192.168.1.101) State Change CS_HANGUP -> CS_REPORTING 2017-04-14 14:46:06.872505 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/186******73@192.168.1.101 [BREAK] 2017-04-14 14:46:06.872505 [DEBUG] switch_core_state_machine.c:472 (sofia/external/186******73@192.168.1.101) Running State Change CS_REPORTING 2017-04-14 14:46:06.872505 [DEBUG] switch_core_state_machine.c:823 (sofia/external/186******73@192.168.1.101) State REPORTING 2017-04-14 14:46:06.872505 [DEBUG] switch_core_state_machine.c:104 sofia/external/186******73@192.168.1.101 Standard REPORTING, cause: NORMAL_CLEARING 2017-04-14 14:46:06.872505 [DEBUG] switch_core_state_machine.c:823 (sofia/external/186******73@192.168.1.101) State REPORTING going to sleep 2017-04-14 14:46:06.872505 [DEBUG] switch_core_state_machine.c:498 (sofia/external/186******73@192.168.1.101) State Change CS_REPORTING -> CS_DESTROY 2017-04-14 14:46:06.872505 [DEBUG] switch_core_session.c:1388 Send signal sofia/external/186******73@192.168.1.101 [BREAK] 2017-04-14 14:46:06.872505 [DEBUG] switch_core_session.c:1615 Session 204 (sofia/external/186******73@192.168.1.101) Locked, Waiting on external entities 2017-04-14 14:46:06.892515 [DEBUG] switch_ivr_bridge.c:660 BRIDGE THREAD DONE [sofia/internal/8005@127.0.0.1] 2017-04-14 14:46:06.892515 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/external/186******73@192.168.1.101 [BREAK] 2017-04-14 14:46:06.892515 [DEBUG] switch_core_session.c:908 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:46:06.892515 [NOTICE] switch_core_session.c:1633 Session 204 (sofia/external/186******73@192.168.1.101) Ended 2017-04-14 14:46:06.892515 [NOTICE] switch_core_session.c:1637 Close Channel sofia/external/186******73@192.168.1.101 [CS_DESTROY] 2017-04-14 14:46:06.892515 [NOTICE] switch_core_state_machine.c:315 sofia/internal/8005@127.0.0.1 has executed the last dialplan instruction, hanging up. 2017-04-14 14:46:06.892515 [NOTICE] switch_core_state_machine.c:317 Hangup sofia/internal/8005@127.0.0.1 [CS_EXECUTE] [NORMAL_CLEARING] 2017-04-14 14:46:06.892515 [DEBUG] switch_channel.c:3222 Send signal sofia/internal/8005@127.0.0.1 [KILL] 2017-04-14 14:46:06.892515 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:535 (sofia/internal/8005@127.0.0.1) State EXECUTE going to sleep 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/8005@127.0.0.1) Running State Change CS_HANGUP 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:735 (sofia/internal/8005@127.0.0.1) Callstate Change ACTIVE -> HANGUP 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:626 (sofia/external/186******73@192.168.1.101) Running State Change CS_DESTROY 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:737 (sofia/internal/8005@127.0.0.1) State HANGUP 2017-04-14 14:46:06.892515 [DEBUG] mod_sofia.c:407 sofia/internal/8005@127.0.0.1 Overriding SIP cause 480 with 200 from the other leg 2017-04-14 14:46:06.892515 [DEBUG] mod_sofia.c:413 Channel sofia/internal/8005@127.0.0.1 hanging up, cause: NORMAL_CLEARING 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:636 (sofia/external/186******73@192.168.1.101) State DESTROY 2017-04-14 14:46:06.892515 [DEBUG] mod_sofia.c:323 sofia/external/186******73@192.168.1.101 SOFIA DESTROY 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:111 sofia/external/186******73@192.168.1.101 Standard DESTROY 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:636 (sofia/external/186******73@192.168.1.101) State DESTROY going to sleep 2017-04-14 14:46:06.892515 [DEBUG] mod_sofia.c:465 Sending BYE to sofia/internal/8005@127.0.0.1 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:60 sofia/internal/8005@127.0.0.1 Standard HANGUP, cause: NORMAL_CLEARING 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:737 (sofia/internal/8005@127.0.0.1) State HANGUP going to sleep 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/8005@127.0.0.1) State Change CS_HANGUP -> CS_REPORTING 2017-04-14 14:46:06.892515 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/8005@127.0.0.1) Running State Change CS_REPORTING send 608 bytes to udp/[192.168.1.33]:5060 at 14:46:06.894485: ------------------------------------------------------------------------ BYE sip:8005@192.168.1.33:5060 SIP/2.0 Via: SIP/2.0/UDP 117.185.49.89;rport;branch=z9hG4bKmZcQ8DSKtpD0Q Max-Forwards: 70 From: ;tag=28DF59255FZrQ To: "8005" ;tag=3cd16e0589b326696 Call-ID: 3cd16e0589b39777@192.168.1.33 CSeq: 105740119 BYE User-Agent: FreeSWITCH-mod_sofia/1.5.15b+git~20141220T224621Z~0a0b9262b4~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 ------------------------------------------------------------------------ 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:823 (sofia/internal/8005@127.0.0.1) State REPORTING 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:104 sofia/internal/8005@127.0.0.1 Standard REPORTING, cause: NORMAL_CLEARING 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:823 (sofia/internal/8005@127.0.0.1) State REPORTING going to sleep 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:498 (sofia/internal/8005@127.0.0.1) State Change CS_REPORTING -> CS_DESTROY 2017-04-14 14:46:06.892515 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/8005@127.0.0.1 [BREAK] 2017-04-14 14:46:06.892515 [DEBUG] switch_core_session.c:1615 Session 203 (sofia/internal/8005@127.0.0.1) Locked, Waiting on external entities 2017-04-14 14:46:06.892515 [NOTICE] switch_core_session.c:1633 Session 203 (sofia/internal/8005@127.0.0.1) Ended 2017-04-14 14:46:06.892515 [NOTICE] switch_core_session.c:1637 Close Channel sofia/internal/8005@127.0.0.1 [CS_DESTROY] 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:626 (sofia/internal/8005@127.0.0.1) Running State Change CS_DESTROY 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:636 (sofia/internal/8005@127.0.0.1) State DESTROY 2017-04-14 14:46:06.892515 [DEBUG] mod_sofia.c:323 sofia/internal/8005@127.0.0.1 SOFIA DESTROY 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:111 sofia/internal/8005@127.0.0.1 Standard DESTROY 2017-04-14 14:46:06.892515 [DEBUG] switch_core_state_machine.c:636 (sofia/internal/8005@127.0.0.1) State DESTROY going to sleep recv 369 bytes from udp/[192.168.1.33]:5060 at 14:46:06.906296: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 117.185.49.89;rport=5060;branch=z9hG4bKmZcQ8DSKtpD0Q;received=192.168.1.246 From: ;tag=28DF59255FZrQ To: "8005" ;tag=3cd16e0589b326696 Call-ID: 3cd16e0589b39777@192.168.1.33 CSeq: 105740119 BYE Contact: "8005" Content-Length: 0 ------------------------------------------------------------------------