2016-02-17 13:47:25.637398 [NOTICE] mod_cdr_csv.c:123 Rotated CDR logfile /usr/local/freeswitch/var/log/freeswitch/cdr-csv/Master.csv 2016-02-17 13:47:25.637398 [NOTICE] mod_logfile.c:213 New log started. recv 864 bytes from udp/[66.166.9.194]:39164 at 13:47:27.794790: ------------------------------------------------------------------------ INVITE sip:1001@216.209.211.222 SIP/2.0 Via: SIP/2.0/UDP 10.0.1.12:40886;branch=z9hG4bK281160191;rport From: ;tag=243846933 To: Call-ID: 930817686-40886-5@BA.A.B.BC CSeq: 40 INVITE Contact: Max-Forwards: 70 User-Agent: Grandstream Wave/IOS 1.0.19 Privacy: none P-Preferred-Identity: Supported: replaces, path, timer, eventlist Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE Content-Type: application/sdp Accept: application/sdp, application/dtmf-relay Content-Length: 230 v=0 o=1000 8000 8000 IN IP4 10.0.1.12 s=SIP Call c=IN IP4 10.0.1.12 t=0 0 m=audio 10270 RTP/AVP 0 8 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=ptime:20 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ send 310 bytes to udp/[66.166.9.194]:39164 at 13:47:27.795559: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.1.12:40886;branch=z9hG4bK281160191;rport=39164;received=66.166.9.194 From: ;tag=243846933 To: Call-ID: 930817686-40886-5@BA.A.B.BC CSeq: 40 INVITE User-Agent: FreeSWITCH-mod_sofia/1.6.6~64bit Content-Length: 0 ------------------------------------------------------------------------ 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.777377 [NOTICE] switch_channel.c:1101 New Channel sofia/internal/1000@216.209.211.222 [4008c053-8780-4987-b84f-010b67013bda] 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.777377 [DEBUG] switch_core_state_machine.c:473 (sofia/internal/1000@216.209.211.222) Running State Change CS_NEW 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.777377 [DEBUG] sofia.c:9248 sofia/internal/1000@216.209.211.222 receiving invite from 66.166.9.194:39164 version: 1.6.6 64bit 2016-02-17 13:47:27.777377 [DEBUG] sofia.c:9415 IP 66.166.9.194 Rejected by acl "domains". Falling back to Digest auth. 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.797388 [DEBUG] switch_core_state_machine.c:492 (sofia/internal/1000@216.209.211.222) State NEW send 814 bytes to udp/[66.166.9.194]:39164 at 13:47:27.798293: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.0.1.12:40886;branch=z9hG4bK281160191;rport=39164;received=66.166.9.194 From: ;tag=243846933 To: ;tag=Drpp4yp9j1X2m Call-ID: 930817686-40886-5@BA.A.B.BC CSeq: 40 INVITE User-Agent: FreeSWITCH-mod_sofia/1.6.6~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="216.209.211.222", nonce="696ccc87-c214-4a8a-870f-7e3d69ca016d", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ 2016-02-17 13:47:27.797388 [DEBUG] sofia.c:2147 detaching session 4008c053-8780-4987-b84f-010b67013bda recv 267 bytes from udp/[66.166.9.194]:39164 at 13:47:27.843925: ------------------------------------------------------------------------ ACK sip:1001@216.209.211.222 SIP/2.0 Via: SIP/2.0/UDP 10.0.1.12:40886;branch=z9hG4bK281160191;rport From: ;tag=243846933 To: ;tag=Drpp4yp9j1X2m Call-ID: 930817686-40886-5@BA.A.B.BC CSeq: 40 ACK Content-Length: 0 ------------------------------------------------------------------------ recv 1111 bytes from udp/[66.166.9.194]:39164 at 13:47:27.860855: ------------------------------------------------------------------------ INVITE sip:1001@216.209.211.222 SIP/2.0 Via: SIP/2.0/UDP 10.0.1.12:40886;branch=z9hG4bK1578402832;rport From: ;tag=243846933 To: Call-ID: 930817686-40886-5@BA.A.B.BC CSeq: 41 INVITE Contact: Proxy-Authorization: Digest username="1000", realm="216.209.211.222", nonce="696ccc87-c214-4a8a-870f-7e3d69ca016d", uri="sip:1001@216.209.211.222", response="73ea6df6242e1f2e5cc6e4d6bad9be3e", algorithm=MD5, cnonce="15059615", qop=auth, nc=00000006 Max-Forwards: 70 User-Agent: Grandstream Wave/IOS 1.0.19 Privacy: none P-Preferred-Identity: Supported: replaces, path, timer, eventlist Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE Content-Type: application/sdp Accept: application/sdp, application/dtmf-relay Content-Length: 230 v=0 o=1000 8000 8000 IN IP4 10.0.1.12 s=SIP Call c=IN IP4 10.0.1.12 t=0 0 m=audio 10270 RTP/AVP 0 8 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=ptime:20 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ send 311 bytes to udp/[66.166.9.194]:39164 at 13:47:27.862041: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.1.12:40886;branch=z9hG4bK1578402832;rport=39164;received=66.166.9.194 From: ;tag=243846933 To: Call-ID: 930817686-40886-5@BA.A.B.BC CSeq: 41 INVITE User-Agent: FreeSWITCH-mod_sofia/1.6.6~64bit Content-Length: 0 ------------------------------------------------------------------------ 2016-02-17 13:47:27.857368 [DEBUG] sofia.c:2255 Re-attaching to session 4008c053-8780-4987-b84f-010b67013bda 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] sofia.c:9248 sofia/internal/1000@216.209.211.222 receiving invite from 66.166.9.194:39164 version: 1.6.6 64bit 2016-02-17 13:47:27.877397 [DEBUG] sofia.c:9415 IP 66.166.9.194 Rejected by acl "domains". Falling back to Digest auth. 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] sofia.c:10549 Setting NAT mode based on nat.auto 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] sofia.c:6760 Channel sofia/internal/1000@216.209.211.222 entering state [received][100] 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] sofia.c:6770 Remote SDP: 4008c053-8780-4987-b84f-010b67013bda v=0 4008c053-8780-4987-b84f-010b67013bda o=1000 8000 8000 IN IP4 10.0.1.12 4008c053-8780-4987-b84f-010b67013bda s=SIP Call 4008c053-8780-4987-b84f-010b67013bda c=IN IP4 10.0.1.12 4008c053-8780-4987-b84f-010b67013bda t=0 0 4008c053-8780-4987-b84f-010b67013bda m=audio 10270 RTP/AVP 0 8 101 4008c053-8780-4987-b84f-010b67013bda a=rtpmap:0 PCMU/8000 4008c053-8780-4987-b84f-010b67013bda a=rtpmap:8 PCMA/8000 4008c053-8780-4987-b84f-010b67013bda a=rtpmap:101 telephone-event/8000 4008c053-8780-4987-b84f-010b67013bda a=fmtp:101 0-15 4008c053-8780-4987-b84f-010b67013bda a=ptime:20 4008c053-8780-4987-b84f-010b67013bda 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] sofia.c:7125 (sofia/internal/1000@216.209.211.222) State Change CS_NEW -> CS_INIT 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] switch_core_state_machine.c:473 (sofia/internal/1000@216.209.211.222) Running State Change CS_INIT 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] switch_core_state_machine.c:516 (sofia/internal/1000@216.209.211.222) State INIT 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] mod_sofia.c:88 sofia/internal/1000@216.209.211.222 SOFIA INIT 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1000@216.209.211.222 Standard INIT 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1000@216.209.211.222) State Change CS_INIT -> CS_ROUTING 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] switch_core_state_machine.c:516 (sofia/internal/1000@216.209.211.222) State INIT going to sleep 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] switch_core_state_machine.c:473 (sofia/internal/1000@216.209.211.222) Running State Change CS_ROUTING 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] switch_channel.c:2247 (sofia/internal/1000@216.209.211.222) Callstate Change DOWN -> RINGING 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] switch_core_state_machine.c:532 (sofia/internal/1000@216.209.211.222) State ROUTING 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] mod_sofia.c:141 sofia/internal/1000@216.209.211.222 SOFIA ROUTING 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] switch_core_state_machine.c:166 sofia/internal/1000@216.209.211.222 Standard ROUTING 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [INFO] mod_dialplan_xml.c:637 Processing 1000 <1000>->1001 in context default 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->unloop] continue=false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->tod_example] continue=true 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Date/Time Match (PASS) [tod_example] break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action set(open=true) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->holiday_example] continue=true 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Date/TimeMatch (FAIL) [holiday_example] break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->global-intercept] continue=false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [global-intercept] destination_number(1001) =~ /^886$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->group-intercept] continue=false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [group-intercept] destination_number(1001) =~ /^\*8$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->intercept-ext] continue=false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [intercept-ext] destination_number(1001) =~ /^\*\*(\d+)$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->redial] continue=false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [redial] destination_number(1001) =~ /^(redial|870)$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->global] continue=true 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [global] ${default_password}(qwerty@123$) =~ /^1234$/ break=never 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [global] ${switch_r_sdp}(v=0 4008c053-8780-4987-b84f-010b67013bda o=1000 8000 8000 IN IP4 10.0.1.12 4008c053-8780-4987-b84f-010b67013bda s=SIP Call 4008c053-8780-4987-b84f-010b67013bda c=IN IP4 10.0.1.12 4008c053-8780-4987-b84f-010b67013bda t=0 0 4008c053-8780-4987-b84f-010b67013bda m=audio 10270 RTP/AVP 0 8 101 4008c053-8780-4987-b84f-010b67013bda a=rtpmap:0 PCMU/8000 4008c053-8780-4987-b84f-010b67013bda a=rtpmap:8 PCMA/8000 4008c053-8780-4987-b84f-010b67013bda a=rtpmap:101 telephone-event/8000 4008c053-8780-4987-b84f-010b67013bda a=fmtp:101 0-15 4008c053-8780-4987-b84f-010b67013bda a=ptime:20 4008c053-8780-4987-b84f-010b67013bda ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Absolute Condition [global] 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action hash(insert/${domain_name}-last_dial/global/${uuid}) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->snom-demo-2] continue=false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [snom-demo-2] destination_number(1001) =~ /^9001$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->snom-demo-1] continue=false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [snom-demo-1] destination_number(1001) =~ /^9000$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->eavesdrop] continue=false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->eavesdrop] continue=false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^779$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->call_return] continue=false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [call_return] destination_number(1001) =~ /^\*69$|^869$|^lcr$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->del-group] continue=false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [del-group] destination_number(1001) =~ /^80(\d{2})$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->add-group] continue=false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [add-group] destination_number(1001) =~ /^81(\d{2})$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->call-group-simo] continue=false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [call-group-simo] destination_number(1001) =~ /^82(\d{2})$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->call-group-order] continue=false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [call-group-order] destination_number(1001) =~ /^83(\d{2})$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->extension-intercom] continue=false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (FAIL) [extension-intercom] destination_number(1001) =~ /^8(10[01][0-9])$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 parsing [default->Local_Extension] continue=false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Regex (PASS) [Local_Extension] destination_number(1001) =~ /^(10[01][0-9])$/ break=on-false 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action export(dialed_extension=1001) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action bind_meta_app(1 b s execute_extension::dx XML features) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/var/lib/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action bind_meta_app(3 b s execute_extension::cf XML features) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action set(ringback=${us-ring}) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action set(transfer_ringback=local_stream://moh) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action set(call_timeout=30) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action set(hangup_after_bridge=true) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action set(continue_on_fail=true) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action bridge(user/${dialed_extension}@${domain_name}) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action answer() 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action sleep(1000) 4008c053-8780-4987-b84f-010b67013bda Dialplan: sofia/internal/1000@216.209.211.222 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] switch_core_state_machine.c:216 (sofia/internal/1000@216.209.211.222) State Change CS_ROUTING -> CS_EXECUTE 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] switch_core_state_machine.c:532 (sofia/internal/1000@216.209.211.222) State ROUTING going to sleep 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] switch_core_state_machine.c:473 (sofia/internal/1000@216.209.211.222) Running State Change CS_EXECUTE 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] switch_core_state_machine.c:539 (sofia/internal/1000@216.209.211.222) State EXECUTE 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] mod_sofia.c:196 sofia/internal/1000@216.209.211.222 SOFIA EXECUTE 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] switch_core_state_machine.c:258 sofia/internal/1000@216.209.211.222 Standard EXECUTE 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 set(open=true) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] mod_dptools.c:1498 SET sofia/internal/1000@216.209.211.222 [open]=[true] 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 hash(insert/216.209.211.222-spymap/1000/4008c053-8780-4987-b84f-010b67013bda) 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 hash(insert/216.209.211.222-last_dial/1000/1001) 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 hash(insert/216.209.211.222-last_dial/global/4008c053-8780-4987-b84f-010b67013bda) 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 export(RFC2822_DATE=Wed, 17 Feb 2016 13:47:27 -0800) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] switch_channel.c:1293 EXPORT (export_vars) [RFC2822_DATE]=[Wed, 17 Feb 2016 13:47:27 -0800] 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 export(dialed_extension=1001) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] switch_channel.c:1293 EXPORT (export_vars) [dialed_extension]=[1001] 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 bind_meta_app(1 b s execute_extension::dx XML features) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [INFO] switch_ivr_async.c:4152 Bound B-Leg: *1 execute_extension::dx XML features 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 bind_meta_app(2 b s record_session::/usr/local/freeswitch/var/lib/freeswitch/recordings/1000.2016-02-17-13-47-27.wav) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [INFO] switch_ivr_async.c:4152 Bound B-Leg: *2 record_session::/usr/local/freeswitch/var/lib/freeswitch/recordings/1000.2016-02-17-13-47-27.wav 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 bind_meta_app(3 b s execute_extension::cf XML features) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [INFO] switch_ivr_async.c:4152 Bound B-Leg: *3 execute_extension::cf XML features 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 bind_meta_app(4 b s execute_extension::att_xfer XML features) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [INFO] switch_ivr_async.c:4152 Bound B-Leg: *4 execute_extension::att_xfer XML features 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 set(ringback=%(2000,4000,440,480)) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] mod_dptools.c:1498 SET sofia/internal/1000@216.209.211.222 [ringback]=[%(2000,4000,440,480)] 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 set(transfer_ringback=local_stream://moh) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] mod_dptools.c:1498 SET sofia/internal/1000@216.209.211.222 [transfer_ringback]=[local_stream://moh] 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 set(call_timeout=30) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] mod_dptools.c:1498 SET sofia/internal/1000@216.209.211.222 [call_timeout]=[30] 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 set(hangup_after_bridge=true) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.877397 [DEBUG] mod_dptools.c:1498 SET sofia/internal/1000@216.209.211.222 [hangup_after_bridge]=[true] 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 set(continue_on_fail=true) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.897386 [DEBUG] mod_dptools.c:1498 SET sofia/internal/1000@216.209.211.222 [continue_on_fail]=[true] 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 hash(insert/216.209.211.222-call_return/1001/1000) 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 hash(insert/216.209.211.222-last_dial_ext/1001/4008c053-8780-4987-b84f-010b67013bda) 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 set(called_party_callgroup=techsupport) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.897386 [DEBUG] mod_dptools.c:1498 SET sofia/internal/1000@216.209.211.222 [called_party_callgroup]=[techsupport] 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 hash(insert/216.209.211.222-last_dial_ext/techsupport/4008c053-8780-4987-b84f-010b67013bda) 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 hash(insert/216.209.211.222-last_dial_ext/global/4008c053-8780-4987-b84f-010b67013bda) 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 hash(insert/216.209.211.222-last_dial/techsupport/4008c053-8780-4987-b84f-010b67013bda) 4008c053-8780-4987-b84f-010b67013bda EXECUTE sofia/internal/1000@216.209.211.222 bridge(user/1001@216.209.211.222) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.897386 [DEBUG] switch_channel.c:1247 sofia/internal/1000@216.209.211.222 EXPORTING[export_vars] [RFC2822_DATE]=[Wed, 17 Feb 2016 13:47:27 -0800] to event 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.897386 [DEBUG] switch_channel.c:1247 sofia/internal/1000@216.209.211.222 EXPORTING[export_vars] [dialed_extension]=[1001] to event 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.897386 [DEBUG] switch_ivr_originate.c:2128 Parsing global variables 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.897386 [DEBUG] switch_channel.c:1247 sofia/internal/1000@216.209.211.222 EXPORTING[export_vars] [RFC2822_DATE]=[Wed, 17 Feb 2016 13:47:27 -0800] to event 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.897386 [DEBUG] switch_channel.c:1247 sofia/internal/1000@216.209.211.222 EXPORTING[export_vars] [dialed_extension]=[1001] to event 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:27.897386 [DEBUG] switch_ivr_originate.c:2128 Parsing global variables 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [NOTICE] switch_channel.c:1101 New Channel sofia/internal/1001@10.0.1.2:40886 [15df2523-1e92-49ca-bf21-bbf07d51c29e] 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] mod_sofia.c:4776 (sofia/internal/1001@10.0.1.2:40886) State Change CS_NEW -> CS_INIT 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] switch_core_state_machine.c:473 (sofia/internal/1001@10.0.1.2:40886) Running State Change CS_INIT 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] switch_core_state_machine.c:516 (sofia/internal/1001@10.0.1.2:40886) State INIT 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] mod_sofia.c:88 sofia/internal/1001@10.0.1.2:40886 SOFIA INIT 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] sofia_glue.c:1228 sip:1001@66.166.9.194:41958 Setting proxy route to sofia/internal/1001@10.0.1.2:40886 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] sofia_glue.c:1257 sofia/internal/1001@10.0.1.2:40886 sending invite version: 1.6.6 64bit 15df2523-1e92-49ca-bf21-bbf07d51c29e Local SDP: 15df2523-1e92-49ca-bf21-bbf07d51c29e v=0 15df2523-1e92-49ca-bf21-bbf07d51c29e o=FreeSWITCH 1455713039 1455713040 IN IP4 216.209.211.222 15df2523-1e92-49ca-bf21-bbf07d51c29e s=FreeSWITCH 15df2523-1e92-49ca-bf21-bbf07d51c29e c=IN IP4 216.209.211.222 15df2523-1e92-49ca-bf21-bbf07d51c29e t=0 0 15df2523-1e92-49ca-bf21-bbf07d51c29e m=audio 32608 RTP/AVP 0 8 101 15df2523-1e92-49ca-bf21-bbf07d51c29e a=rtpmap:0 PCMU/8000 15df2523-1e92-49ca-bf21-bbf07d51c29e a=rtpmap:8 PCMA/8000 15df2523-1e92-49ca-bf21-bbf07d51c29e a=rtpmap:101 telephone-event/8000 15df2523-1e92-49ca-bf21-bbf07d51c29e a=fmtp:101 0-16 15df2523-1e92-49ca-bf21-bbf07d51c29e a=ptime:20 15df2523-1e92-49ca-bf21-bbf07d51c29e a=sendrecv 15df2523-1e92-49ca-bf21-bbf07d51c29e 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1001@10.0.1.2:40886 Standard INIT 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1001@10.0.1.2:40886) State Change CS_INIT -> CS_ROUTING 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] switch_core_state_machine.c:516 (sofia/internal/1001@10.0.1.2:40886) State INIT going to sleep 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] switch_core_state_machine.c:473 (sofia/internal/1001@10.0.1.2:40886) Running State Change CS_ROUTING 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] switch_core_state_machine.c:532 (sofia/internal/1001@10.0.1.2:40886) State ROUTING 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] mod_sofia.c:141 sofia/internal/1001@10.0.1.2:40886 SOFIA ROUTING send 1185 bytes to udp/[66.166.9.194]:41958 at 13:47:27.912034: ------------------------------------------------------------------------ 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1001@10.0.1.2:40886) State Change CS_ROUTING -> CS_CONSUME_MEDIA INVITE sip:1001@10.0.1.2:40886 SIP/2.0 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] switch_core_state_machine.c:532 (sofia/internal/1001@10.0.1.2:40886) State ROUTING going to sleep Via: SIP/2.0/UDP 216.209.211.222;rport;branch=z9hG4bK38Xat6Z71UHUN Route: Max-Forwards: 69 From: "Extension 1000" ;tag=Fa977mrgDKa8B To: Call-ID: e124e149-5062-1234-9bb4-c6827b410b7a CSeq: 87536759 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.6~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Privacy: none Content-Type: application/sdp Content-Disposition: session Content-Length: 246 X-FS-Support: update_display,send_info P-Asserted-Identity: "Extension 1000" v=0 o=FreeSWITCH 1455713039 1455713040 IN IP4 216.209.211.222 s=FreeSWITCH c=IN IP4 216.209.211.222 t=0 0 m=audio 32608 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-16 a=ptime:20 ------------------------------------------------------------------------ 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] switch_core_state_machine.c:473 (sofia/internal/1001@10.0.1.2:40886) Running State Change CS_CONSUME_MEDIA 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] sofia.c:6760 Channel sofia/internal/1001@10.0.1.2:40886 entering state [calling][0] 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] switch_core_state_machine.c:551 (sofia/internal/1001@10.0.1.2:40886) State CONSUME_MEDIA 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:27.897386 [DEBUG] switch_core_state_machine.c:551 (sofia/internal/1001@10.0.1.2:40886) State CONSUME_MEDIA going to sleep recv 450 bytes from udp/[66.166.9.194]:41958 at 13:47:28.028660: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 216.209.211.222;rport=5060;branch=z9hG4bK38Xat6Z71UHUN From: "Extension 1000" ;tag=Fa977mrgDKa8B To: Call-ID: e124e149-5062-1234-9bb4-c6827b410b7a CSeq: 87536759 INVITE Supported: replaces, path, eventlist User-Agent: Grandstream Wave/IOS 1.0.19 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE Content-Length: 0 ------------------------------------------------------------------------ recv 535 bytes from udp/[66.166.9.194]:41958 at 13:47:28.036530: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 216.209.211.222;rport=5060;branch=z9hG4bK38Xat6Z71UHUN From: "Extension 1000" ;tag=Fa977mrgDKa8B To: ;tag=2072085022 Call-ID: e124e149-5062-1234-9bb4-c6827b410b7a CSeq: 87536759 INVITE Contact: Supported: replaces, path, timer, eventlist User-Agent: Grandstream Wave/IOS 1.0.19 Allow-Events: talk, hold Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE Content-Length: 0 ------------------------------------------------------------------------ 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:28.037389 [DEBUG] sofia.c:6760 Channel sofia/internal/1001@10.0.1.2:40886 entering state [proceeding][180] 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:28.037389 [NOTICE] sofia.c:6862 Ring-Ready sofia/internal/1001@10.0.1.2:40886! 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:28.037389 [DEBUG] switch_channel.c:3340 (sofia/internal/1001@10.0.1.2:40886) Callstate Change DOWN -> RINGING 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [INFO] switch_ivr_originate.c:1216 Sending early media 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:4161 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:4161 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:4161 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:4216 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:4161 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:4161 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:4161 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:4161 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:4161 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:4216 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:4077 Set telephone-event payload to 101@8000 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:2906 Set Codec sofia/internal/1000@216.209.211.222 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_codec.c:111 sofia/internal/1000@216.209.211.222 Original read codec set to PCMU:0 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:4429 Set telephone-event payload to 101@8000 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:4485 sofia/internal/1000@216.209.211.222 Set 2833 dtmf send payload to 101 recv payload to 101 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:6033 AUDIO RTP [sofia/internal/1000@216.209.211.222] 216.209.211.222 port 25166 -> 10.0.1.12 port 10270 codec: 0 ms: 20 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_rtp.c:3802 Starting timer [soft] 160 bytes per 20ms 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:1939 Setting Jitterbuffer to 60ms (3 frames) (50 max frames) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:6332 sofia/internal/1000@216.209.211.222 Set 2833 dtmf send payload to 101 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:6339 sofia/internal/1000@216.209.211.222 Set 2833 dtmf receive payload to 101 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [DEBUG] switch_core_media.c:6362 sofia/internal/1000@216.209.211.222 Set rtp dtmf delay to 40 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.037389 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1000@216.209.211.222! 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.057400 [DEBUG] switch_channel.c:3468 (sofia/internal/1000@216.209.211.222) Callstate Change RINGING -> EARLY 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.057400 [DEBUG] mod_sofia.c:2330 Ring SDP: 4008c053-8780-4987-b84f-010b67013bda v=0 4008c053-8780-4987-b84f-010b67013bda o=FreeSWITCH 1455720482 1455720483 IN IP4 216.209.211.222 4008c053-8780-4987-b84f-010b67013bda s=FreeSWITCH 4008c053-8780-4987-b84f-010b67013bda c=IN IP4 216.209.211.222 4008c053-8780-4987-b84f-010b67013bda t=0 0 4008c053-8780-4987-b84f-010b67013bda m=audio 25166 RTP/AVP 0 101 4008c053-8780-4987-b84f-010b67013bda a=rtpmap:0 PCMU/8000 4008c053-8780-4987-b84f-010b67013bda a=rtpmap:101 telephone-event/8000 4008c053-8780-4987-b84f-010b67013bda a=fmtp:101 0-16 4008c053-8780-4987-b84f-010b67013bda a=ptime:20 4008c053-8780-4987-b84f-010b67013bda a=sendrecv 4008c053-8780-4987-b84f-010b67013bda 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.057400 [DEBUG] switch_ivr_originate.c:1274 Raw Codec Activation Success L16@8000hz 1 channel 20ms 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.057400 [DEBUG] switch_core_codec.c:221 sofia/internal/1000@216.209.211.222 Push codec L16:100 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.057400 [DEBUG] switch_ivr_originate.c:1343 Play Ringback Tone [%(2000,4000,440,480)] send 1072 bytes to udp/[66.166.9.194]:39164 at 13:47:28.060325: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 10.0.1.12:40886;branch=z9hG4bK1578402832;rport=39164;received=66.166.9.194 From: ;tag=243846933 To: ;tag=e1FF6S7cgamNg Call-ID: 930817686-40886-5@BA.A.B.BC CSeq: 41 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.6~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: 222 P-Asserted-Identity: "1001" v=0 o=FreeSWITCH 1455720482 1455720483 IN IP4 216.209.211.222 s=FreeSWITCH c=IN IP4 216.209.211.222 t=0 0 m=audio 25166 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.077397 [DEBUG] sofia.c:6760 Channel sofia/internal/1000@216.209.211.222 entering state [early][183] 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:28.817431 [INFO] switch_rtp.c:6616 Auto Changing audio port from 10.0.1.12:10270 to 66.166.9.194:38124 recv 767 bytes from udp/[66.166.9.194]:41958 at 13:47:30.718270: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 216.209.211.222;rport=5060;branch=z9hG4bK38Xat6Z71UHUN From: "Extension 1000" ;tag=Fa977mrgDKa8B To: ;tag=2072085022 Call-ID: e124e149-5062-1234-9bb4-c6827b410b7a CSeq: 87536759 INVITE Contact: Supported: replaces, path, timer, eventlist User-Agent: Grandstream Wave/IOS 1.0.19 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE Content-Type: application/sdp Content-Length: 228 v=0 o=1001 8001 8000 IN IP4 10.0.1.2 s=SIP Call c=IN IP4 10.0.1.2 t=0 0 m=audio 35544 RTP/AVP 0 8 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=ptime:20 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] sofia.c:6760 Channel sofia/internal/1001@10.0.1.2:40886 entering state [completing][200] 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] sofia.c:6770 Remote SDP: 15df2523-1e92-49ca-bf21-bbf07d51c29e v=0 15df2523-1e92-49ca-bf21-bbf07d51c29e o=1001 8001 8000 IN IP4 10.0.1.2 15df2523-1e92-49ca-bf21-bbf07d51c29e s=SIP Call 15df2523-1e92-49ca-bf21-bbf07d51c29e c=IN IP4 10.0.1.2 15df2523-1e92-49ca-bf21-bbf07d51c29e t=0 0 15df2523-1e92-49ca-bf21-bbf07d51c29e m=audio 35544 RTP/AVP 0 8 101 15df2523-1e92-49ca-bf21-bbf07d51c29e a=rtpmap:0 PCMU/8000 15df2523-1e92-49ca-bf21-bbf07d51c29e a=rtpmap:8 PCMA/8000 15df2523-1e92-49ca-bf21-bbf07d51c29e a=rtpmap:101 telephone-event/8000 15df2523-1e92-49ca-bf21-bbf07d51c29e a=fmtp:101 0-15 15df2523-1e92-49ca-bf21-bbf07d51c29e a=ptime:20 15df2523-1e92-49ca-bf21-bbf07d51c29e send 367 bytes to udp/[66.166.9.194]:41958 at 13:47:30.723049: ------------------------------------------------------------------------ ACK sip:1001@10.0.1.2:40886 SIP/2.0 Via: SIP/2.0/UDP 216.209.211.222;rport;branch=z9hG4bK4HQ3U1gBZ47DH Max-Forwards: 70 From: "Extension 1000" ;tag=Fa977mrgDKa8B To: ;tag=2072085022 Call-ID: e124e149-5062-1234-9bb4-c6827b410b7a CSeq: 87536759 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] sofia.c:6760 Channel sofia/internal/1001@10.0.1.2:40886 entering state [ready][200] 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_core_media.c:4161 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_core_media.c:4216 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_core_media.c:4161 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_core_media.c:4161 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_core_media.c:4161 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_core_media.c:4216 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_core_media.c:4077 Set telephone-event payload to 101@8000 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_core_media.c:2906 Set Codec sofia/internal/1001@10.0.1.2:40886 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_core_codec.c:111 sofia/internal/1001@10.0.1.2:40886 Original read codec set to PCMU:0 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_core_media.c:4429 Set telephone-event payload to 101@8000 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_core_media.c:4485 sofia/internal/1001@10.0.1.2:40886 Set 2833 dtmf send payload to 101 recv payload to 101 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_core_media.c:6033 AUDIO RTP [sofia/internal/1001@10.0.1.2:40886] 216.209.211.222 port 32608 -> 10.0.1.2 port 35544 codec: 0 ms: 20 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_rtp.c:3802 Starting timer [soft] 160 bytes per 20ms 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_core_media.c:1939 Setting Jitterbuffer to 60ms (3 frames) (50 max frames) 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_core_media.c:6332 sofia/internal/1001@10.0.1.2:40886 Set 2833 dtmf send payload to 101 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_core_media.c:6339 sofia/internal/1001@10.0.1.2:40886 Set 2833 dtmf receive payload to 101 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_core_media.c:6362 sofia/internal/1001@10.0.1.2:40886 Set rtp dtmf delay to 40 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [NOTICE] sofia.c:7724 Channel [sofia/internal/1001@10.0.1.2:40886] has been answered 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.717395 [DEBUG] switch_channel.c:3767 (sofia/internal/1001@10.0.1.2:40886) Callstate Change RINGING -> ACTIVE 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:30.737383 [DEBUG] switch_core_codec.c:246 sofia/internal/1000@216.209.211.222 Restore previous codec PCMU:0. 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:30.737383 [DEBUG] mod_sofia.c:799 Local SDP sofia/internal/1000@216.209.211.222: 4008c053-8780-4987-b84f-010b67013bda v=0 4008c053-8780-4987-b84f-010b67013bda o=FreeSWITCH 1455720482 1455720484 IN IP4 216.209.211.222 4008c053-8780-4987-b84f-010b67013bda s=FreeSWITCH 4008c053-8780-4987-b84f-010b67013bda c=IN IP4 216.209.211.222 4008c053-8780-4987-b84f-010b67013bda t=0 0 4008c053-8780-4987-b84f-010b67013bda m=audio 25166 RTP/AVP 0 101 4008c053-8780-4987-b84f-010b67013bda a=rtpmap:0 PCMU/8000 4008c053-8780-4987-b84f-010b67013bda a=rtpmap:101 telephone-event/8000 4008c053-8780-4987-b84f-010b67013bda a=fmtp:101 0-16 4008c053-8780-4987-b84f-010b67013bda a=ptime:20 4008c053-8780-4987-b84f-010b67013bda a=sendrecv 4008c053-8780-4987-b84f-010b67013bda 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:30.737383 [NOTICE] switch_ivr_originate.c:3550 Channel [sofia/internal/1000@216.209.211.222] has been answered send 1094 bytes to udp/[66.166.9.194]:39164 at 13:47:30.743468: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.1.12:40886;branch=z9hG4bK1578402832;rport=39164;received=66.166.9.194 From: ;tag=243846933 To: ;tag=e1FF6S7cgamNg Call-ID: 930817686-40886-5@BA.A.B.BC CSeq: 41 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.6~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Require: timer Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Session-Expires: 120;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 222 P-Asserted-Identity: "Outbound Call" v=0 o=FreeSWITCH 1455720482 1455720483 IN IP4 216.209.211.222 s=FreeSWITCH c=IN IP4 216.209.211.222 t=0 0 m=audio 25166 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:30.737383 [DEBUG] switch_channel.c:3767 (sofia/internal/1000@216.209.211.222) Callstate Change EARLY -> ACTIVE 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:30.737383 [DEBUG] sofia.c:6760 Channel sofia/internal/1000@216.209.211.222 entering state [completed][200] 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:30.737383 [DEBUG] switch_ivr_originate.c:3608 Originate Resulted in Success: [sofia/internal/1001@10.0.1.2:40886] 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:30.737383 [DEBUG] switch_ivr_originate.c:3608 Originate Resulted in Success: [sofia/internal/1001@10.0.1.2:40886] 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.737383 [DEBUG] switch_core_media.c:9156 sofia/internal/1001@10.0.1.2:40886 PAUSE Jitterbuffer 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:30.737383 [DEBUG] switch_core_media.c:9156 sofia/internal/1000@216.209.211.222 PAUSE Jitterbuffer 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.737383 [DEBUG] switch_ivr_bridge.c:1591 (sofia/internal/1001@10.0.1.2:40886) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.737383 [DEBUG] switch_core_state_machine.c:473 (sofia/internal/1001@10.0.1.2:40886) Running State Change CS_EXCHANGE_MEDIA 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.737383 [DEBUG] switch_core_state_machine.c:542 (sofia/internal/1001@10.0.1.2:40886) State EXCHANGE_MEDIA 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:30.737383 [DEBUG] mod_sofia.c:613 SOFIA EXCHANGE_MEDIA 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:30.757403 [DEBUG] switch_rtp.c:6654 Correct audio ip/port confirmed. send 1094 bytes to udp/[66.166.9.194]:39164 at 13:47:31.244642: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.1.12:40886;branch=z9hG4bK1578402832;rport=39164;received=66.166.9.194 From: ;tag=243846933 To: ;tag=e1FF6S7cgamNg Call-ID: 930817686-40886-5@BA.A.B.BC CSeq: 41 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.6~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Require: timer Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Session-Expires: 120;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 222 P-Asserted-Identity: "Outbound Call" v=0 o=FreeSWITCH 1455720482 1455720483 IN IP4 216.209.211.222 s=FreeSWITCH c=IN IP4 216.209.211.222 t=0 0 m=audio 25166 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ recv 764 bytes from udp/[66.166.9.194]:39164 at 13:47:31.321742: ------------------------------------------------------------------------ ACK sip:1001@216.209.211.222:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.0.1.12:40886;branch=z9hG4bK145924562;rport From: ;tag=243846933 To: ;tag=e1FF6S7cgamNg Call-ID: 930817686-40886-5@BA.A.B.BC CSeq: 41 ACK Contact: Proxy-Authorization: Digest username="1000", realm="216.209.211.222", nonce="696ccc87-c214-4a8a-870f-7e3d69ca016d", uri="sip:1001@216.209.211.222", response="73ea6df6242e1f2e5cc6e4d6bad9be3e", algorithm=MD5, cnonce="15059615", qop=auth, nc=00000006 Max-Forwards: 70 Supported: replaces, path, timer, eventlist User-Agent: Grandstream Wave/IOS 1.0.19 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE Content-Length: 0 ------------------------------------------------------------------------ recv 764 bytes from udp/[66.166.9.194]:39164 at 13:47:31.327208: ------------------------------------------------------------------------ ACK sip:1001@216.209.211.222:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.0.1.12:40886;branch=z9hG4bK145924562;rport From: ;tag=243846933 To: ;tag=e1FF6S7cgamNg Call-ID: 930817686-40886-5@BA.A.B.BC CSeq: 41 ACK Contact: Proxy-Authorization: Digest username="1000", realm="216.209.211.222", nonce="696ccc87-c214-4a8a-870f-7e3d69ca016d", uri="sip:1001@216.209.211.222", response="73ea6df6242e1f2e5cc6e4d6bad9be3e", algorithm=MD5, cnonce="15059615", qop=auth, nc=00000006 Max-Forwards: 70 Supported: replaces, path, timer, eventlist User-Agent: Grandstream Wave/IOS 1.0.19 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE Content-Length: 0 ------------------------------------------------------------------------ 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:31.317425 [DEBUG] sofia.c:6760 Channel sofia/internal/1000@216.209.211.222 entering state [ready][200] 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:31.517381 [INFO] switch_rtp.c:6616 Auto Changing audio port from 10.0.1.2:35544 to 66.166.9.194:46630 recv 519 bytes from udp/[66.166.9.194]:39164 at 13:47:37.588043: ------------------------------------------------------------------------ BYE sip:1001@216.209.211.222:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.0.1.12:40886;branch=z9hG4bK1092657280;rport From: ;tag=243846933 To: ;tag=e1FF6S7cgamNg Call-ID: 930817686-40886-5@BA.A.B.BC CSeq: 42 BYE Contact: Max-Forwards: 70 Supported: replaces, path, timer, eventlist User-Agent: Grandstream Wave/IOS 1.0.19 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE Content-Length: 0 ------------------------------------------------------------------------ 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [NOTICE] sofia.c:952 Hangup sofia/internal/1000@216.209.211.222 [CS_EXECUTE] [NORMAL_CLEARING] send 466 bytes to udp/[66.166.9.194]:39164 at 13:47:37.598615: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.1.12:40886;branch=z9hG4bK1092657280;rport=39164;received=66.166.9.194 From: ;tag=243846933 To: ;tag=e1FF6S7cgamNg Call-ID: 930817686-40886-5@BA.A.B.BC CSeq: 42 BYE User-Agent: FreeSWITCH-mod_sofia/1.6.6~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_ivr_bridge.c:778 BRIDGE THREAD DONE [sofia/internal/1000@216.209.211.222] 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_ivr_bridge.c:699 sofia/internal/1000@216.209.211.222 ending bridge by request from write function 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_ivr_bridge.c:778 BRIDGE THREAD DONE [sofia/internal/1001@10.0.1.2:40886] 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [NOTICE] switch_ivr_bridge.c:881 Hangup sofia/internal/1001@10.0.1.2:40886 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:542 (sofia/internal/1001@10.0.1.2:40886) State EXCHANGE_MEDIA going to sleep 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:473 (sofia/internal/1001@10.0.1.2:40886) Running State Change CS_HANGUP 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/1001@10.0.1.2:40886) Callstate Change ACTIVE -> HANGUP 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_ivr_bridge.c:1689 sofia/internal/1001@10.0.1.2:40886 skip receive message [UNBRIDGE] (channel is hungup already) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_ivr_bridge.c:1692 sofia/internal/1000@216.209.211.222 skip receive message [UNBRIDGE] (channel is hungup already) 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1001@10.0.1.2:40886) State HANGUP 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] mod_sofia.c:425 sofia/internal/1001@10.0.1.2:40886 Overriding SIP cause 480 with 200 from the other leg 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] mod_sofia.c:431 Channel sofia/internal/1001@10.0.1.2:40886 hanging up, cause: NORMAL_CLEARING 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_session.c:2796 sofia/internal/1000@216.209.211.222 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:539 (sofia/internal/1000@216.209.211.222) State EXECUTE going to sleep 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:473 (sofia/internal/1000@216.209.211.222) Running State Change CS_HANGUP 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/1000@216.209.211.222) Callstate Change ACTIVE -> HANGUP 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1000@216.209.211.222) State HANGUP 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] mod_sofia.c:431 Channel sofia/internal/1000@216.209.211.222 hanging up, cause: NORMAL_CLEARING 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] mod_sofia.c:484 Sending BYE to sofia/internal/1001@10.0.1.2:40886 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1001@10.0.1.2:40886 Standard HANGUP, cause: NORMAL_CLEARING 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1001@10.0.1.2:40886) State HANGUP going to sleep 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:508 (sofia/internal/1001@10.0.1.2:40886) State Change CS_HANGUP -> CS_REPORTING send 559 bytes to udp/[66.166.9.194]:41958 at 13:47:37.609113: ------------------------------------------------------------------------ BYE sip:1001@10.0.1.2:40886 SIP/2.0 Via: SIP/2.0/UDP 216.209.211.222;rport;branch=z9hG4bK5tgvXv1evDy0c Max-Forwards: 70 From: "Extension 1000" ;tag=Fa977mrgDKa8B To: ;tag=2072085022 Call-ID: e124e149-5062-1234-9bb4-c6827b410b7a CSeq: 87536760 BYE15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:473 (sofia/internal/1001@10.0.1.2:40886) Running State Change CS_REPORTING User-Agent: FreeSWITCH-mod_sofia/1.6.6~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 ------------------------------------------------------------------------ 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:827 (sofia/internal/1001@10.0.1.2:40886) State REPORTING 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:104 sofia/internal/1001@10.0.1.2:40886 Standard REPORTING, cause: NORMAL_CLEARING 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:827 (sofia/internal/1001@10.0.1.2:40886) State REPORTING going to sleep 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1001@10.0.1.2:40886) State Change CS_REPORTING -> CS_DESTROY 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_session.c:1646 Session 7 (sofia/internal/1001@10.0.1.2:40886) Locked, Waiting on external entities 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [NOTICE] switch_core_session.c:1664 Session 7 (sofia/internal/1001@10.0.1.2:40886) Ended 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [NOTICE] switch_core_session.c:1668 Close Channel sofia/internal/1001@10.0.1.2:40886 [CS_DESTROY] 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1000@216.209.211.222 Standard HANGUP, cause: NORMAL_CLEARING 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1000@216.209.211.222) State HANGUP going to sleep 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:508 (sofia/internal/1000@216.209.211.222) State Change CS_HANGUP -> CS_REPORTING 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:630 (sofia/internal/1001@10.0.1.2:40886) Running State Change CS_DESTROY 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1001@10.0.1.2:40886) State DESTROY 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] mod_sofia.c:341 sofia/internal/1001@10.0.1.2:40886 SOFIA DESTROY 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:473 (sofia/internal/1000@216.209.211.222) Running State Change CS_REPORTING 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:111 sofia/internal/1001@10.0.1.2:40886 Standard DESTROY 15df2523-1e92-49ca-bf21-bbf07d51c29e 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1001@10.0.1.2:40886) State DESTROY going to sleep 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:827 (sofia/internal/1000@216.209.211.222) State REPORTING 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:104 sofia/internal/1000@216.209.211.222 Standard REPORTING, cause: NORMAL_CLEARING 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:827 (sofia/internal/1000@216.209.211.222) State REPORTING going to sleep 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1000@216.209.211.222) State Change CS_REPORTING -> CS_DESTROY 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_session.c:1646 Session 6 (sofia/internal/1000@216.209.211.222) Locked, Waiting on external entities 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [NOTICE] switch_core_session.c:1664 Session 6 (sofia/internal/1000@216.209.211.222) Ended 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [NOTICE] switch_core_session.c:1668 Close Channel sofia/internal/1000@216.209.211.222 [CS_DESTROY] 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:630 (sofia/internal/1000@216.209.211.222) Running State Change CS_DESTROY 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1000@216.209.211.222) State DESTROY 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] mod_sofia.c:341 sofia/internal/1000@216.209.211.222 SOFIA DESTROY 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:111 sofia/internal/1000@216.209.211.222 Standard DESTROY 4008c053-8780-4987-b84f-010b67013bda 2016-02-17 13:47:37.597418 [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1000@216.209.211.222) State DESTROY going to sleep recv 501 bytes from udp/[66.166.9.194]:41958 at 13:47:37.651003: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 216.209.211.222;rport=5060;branch=z9hG4bK5tgvXv1evDy0c From: "Extension 1000" ;tag=Fa977mrgDKa8B To: ;tag=2072085022 Call-ID: e124e149-5062-1234-9bb4-c6827b410b7a CSeq: 87536760 BYE Contact: Supported: replaces, path, timer, eventlist User-Agent: Grandstream Wave/IOS 1.0.19 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE Content-Length: 0 ------------------------------------------------------------------------ 2016-02-17 13:47:41.537380 [NOTICE] mod_cdr_csv.c:123 Rotated CDR logfile /usr/local/freeswitch/var/log/freeswitch/cdr-csv/1000.csv 2016-02-17 13:47:41.537380 [NOTICE] mod_cdr_csv.c:123 Rotated CDR logfile /usr/local/freeswitch/var/log/freeswitch/cdr-csv/Master.csv