2017-06-21 17:15:39.637766 [DEBUG] mod_rtc.c:392 () State Change CS_NEW -> CS_INIT 2017-06-21 17:15:39.637766 [DEBUG] switch_core_session.c:640 N/A set UUID=a3d97826-91a9-51c2-b4e6-549a1e02db53 2017-06-21 17:15:39.637766 [NOTICE] switch_channel.c:1104 New Channel verto.rtc/1007 [a3d97826-91a9-51c2-b4e6-549a1e02db53] 2017-06-21 17:15:39.637766 [DEBUG] mod_verto.c:3728 Remote SDP verto.rtc/1007: v=0 o=- 7530509066109054019 2 IN IP4 127.0.0.1 s=- t=0 0 a=group:BUNDLE audio video a=msid-semantic: WMS Lss2ZdDeasdYftqmPZdHyKL6aPgc8YfCfoHO m=audio 33538 UDP/TLS/RTP/SAVPF 111 103 9 0 8 105 13 110 113 126 c=IN IP4 65.15.69.32 a=rtcp:9 IN IP4 0.0.0.0 a=candidate:356246754 1 udp 2122262783 2600:1005:8102:840c:0:47:ca5d:9a01 55789 typ host generation 0 network-id 1 network-cost 50 a=candidate:2902406287 1 udp 2122194687 192.168.150.144 33538 typ host generation 0 network-id 2 network-cost 10 a=candidate:1538791442 1 tcp 1518283007 2600:1005:8102:840c:0:47:ca5d:9a01 9 typ host tcptype active generation 0 network-id 1 network-cost 50 a=candidate:3308616526 1 udp 1685987071 65.15.69.32 33538 typ srflx raddr 192.168.150.144 rport 33538 generation 0 network-id 2 network-cost 10 a=candidate:3799828607 1 tcp 1518214911 192.168.150.144 9 typ host tcptype active generation 0 network-id 2 network-cost 10 a=ice-ufrag:vS+Q a=ice-pwd:ghVLfUlIZpp2A3rE6FMuQGfz a=fingerprint:sha-256 AB:2B:67:CB:A2:8C:56:3C:5E:B9:29:20:86:FB:2C:BF:4A:A6:01:BD:E1:8C:28:C8:D3:2A:A4:85:59:D2:BF:2F a=setup:actpass a=mid:audio a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=sendrecv a=rtcp-mux a=rtpmap:111 opus/48000/2 a=rtcp-fb:111 transport-cc a=fmtp:111 minptime=10;useinbandfec=1; stereo=1; sprop-stereo=1 a=rtpmap:103 ISAC/16000 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:105 CN/16000 a=rtpmap:13 CN/8000 a=rtpmap:110 telephone-event/48000 a=rtpmap:113 telephone-event/16000 a=rtpmap:126 telephone-event/8000 a=ssrc:2623231321 cname:6rt6aYbfSGZzkR7G a=ssrc:2623231321 msid:Lss2ZdDeasdYftqmPZdHyKL6aPgc8YfCfoHO de62be94-2fa6-4725-9188-4d90dae38bb2 a=ssrc:2623231321 mslabel:Lss2ZdDeasdYftqmPZdHyKL6aPgc8YfCfoHO a=ssrc:2623231321 label:de62be94-2fa6-4725-9188-4d90dae38bb2 m=video 59965 UDP/TLS/RTP/SAVPF 96 98 100 102 127 97 99 101 104 c=IN IP4 65.15.69.32 a=rtcp:9 IN IP4 0.0.0.0 a=candidate:356246754 1 udp 2122262783 2600:1005:8102:840c:0:47:ca5d:9a01 45863 typ host generation 0 network-id 1 network-cost 50 a=candidate:2902406287 1 udp 2122194687 192.168.150.144 59965 typ host generation 0 network-id 2 network-cost 10 a=candidate:1538791442 1 tcp 1518283007 2600:1005:8102:840c:0:47:ca5d:9a01 9 typ host tcptype active generation 0 network-id 1 network-cost 50 a=candidate:3799828607 1 tcp 1518214911 192.168.150.144 9 typ host tcptype active generation 0 network-id 2 network-cost 10 a=candidate:3308616526 1 udp 1685987071 65.15.69.32 59965 typ srflx raddr 192.168.150.144 rport 59965 generation 0 network-id 2 network-cost 10 a=ice-ufrag:vS+Q a=ice-pwd:ghVLfUlIZpp2A3rE6FMuQGfz a=fingerprint:sha-256 AB:2B:67:CB:A2:8C:56:3C:5E:B9:29:20:86:FB:2C:BF:4A:A6:01:BD:E1:8C:28:C8:D3:2A:A4:85:59:D2:BF:2F a=setup:actpass a=mid:video a=extmap:2 urn:ietf:params:rtp-hdrext:toffset a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time a=extmap:4 urn:3gpp:video-orientation a=extmap:5 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01 a=extmap:6 http://www.webrtc.org/experiments/rtp-hdrext/playout-delay a=sendrecv a=rtcp-mux a=rtcp-rsize a=rtpmap:96 VP8/90000 a=rtcp-fb:96 ccm fir a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli a=rtcp-fb:96 goog-remb a=rtcp-fb:96 transport-cc a=rtpmap:98 VP9/90000 a=rtcp-fb:98 ccm fir a=rtcp-fb:98 nack a=rtcp-fb:98 nack pli a=rtcp-fb:98 goog-remb a=rtcp-fb:98 transport-cc a=rtpmap:100 red/90000 a=rtpmap:102 ulpfec/90000 a=rtpmap:127 H264/90000 a=rtcp-fb:127 ccm fir a=rtcp-fb:127 nack a=rtcp-fb:127 nack pli a=rtcp-fb:127 goog-remb a=rtcp-fb:127 transport-cc a=fmtp:127 packetization-mode=1 a=rtpmap:97 rtx/90000 a=fmtp:97 apt=96 a=rtpmap:99 rtx/90000 a=fmtp:99 apt=98 a=rtpmap:101 rtx/90000 a=fmtp:101 apt=100 a=rtpmap:104 rtx/90000 a=fmtp:104 apt=127 a=ssrc-group:FID 3760859939 2102148952 a=ssrc:3760859939 cname:6rt6aYbfSGZzkR7G a=ssrc:3760859939 msid:Lss2ZdDeasdYftqmPZdHyKL6aPgc8YfCfoHO f870fd74-8bd1-44d2-9e1c-9ad50c58f8e4 a=ssrc:3760859939 mslabel:Lss2ZdDeasdYftqmPZdHyKL6aPgc8YfCfoHO a=ssrc:3760859939 label:f870fd74-8bd1-44d2-9e1c-9ad50c58f8e4 a=ssrc:2102148952 cname:6rt6aYbfSGZzkR7G a=ssrc:2102148952 msid:Lss2ZdDeasdYftqmPZdHyKL6aPgc8YfCfoHO f870fd74-8bd1-44d2-9e1c-9ad50c58f8e4 a=ssrc:2102148952 mslabel:Lss2ZdDeasdYftqmPZdHyKL6aPgc8YfCfoHO a=ssrc:2102148952 label:f870fd74-8bd1-44d2-9e1c-9ad50c58f8e4 2017-06-21 17:15:39.637766 [DEBUG] switch_core_state_machine.c:584 (verto.rtc/1007) Running State Change CS_INIT (Cur 1 Tot 23) 2017-06-21 17:15:39.637766 [DEBUG] switch_core_state_machine.c:627 (verto.rtc/1007) State INIT 2017-06-21 17:15:39.637766 [DEBUG] switch_core_state_machine.c:40 verto.rtc/1007 Standard INIT 2017-06-21 17:15:39.637766 [DEBUG] switch_core_state_machine.c:48 (verto.rtc/1007) State Change CS_INIT -> CS_ROUTING 2017-06-21 17:15:39.637766 [DEBUG] switch_core_state_machine.c:627 (verto.rtc/1007) State INIT going to sleep 2017-06-21 17:15:39.637766 [DEBUG] switch_core_state_machine.c:584 (verto.rtc/1007) Running State Change CS_ROUTING (Cur 1 Tot 23) 2017-06-21 17:15:39.637766 [DEBUG] switch_channel.c:2249 (verto.rtc/1007) Callstate Change DOWN -> RINGING 2017-06-21 17:15:39.637766 [DEBUG] switch_core_state_machine.c:643 (verto.rtc/1007) State ROUTING 2017-06-21 17:15:39.637766 [DEBUG] mod_rtc.c:89 verto.rtc/1007 RTC ROUTING 2017-06-21 17:15:39.637766 [DEBUG] switch_core_state_machine.c:236 verto.rtc/1007 Standard ROUTING 2017-06-21 17:15:39.637766 [INFO] mod_dialplan_xml.c:637 Processing Galaxy ->1007 in context default Dialplan: verto.rtc/1007 parsing [default->unloop] continue=false Dialplan: verto.rtc/1007 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: verto.rtc/1007 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: verto.rtc/1007 parsing [default->tod_example] continue=true Dialplan: verto.rtc/1007 Date/Time Match (PASS) [tod_example] break=on-false Dialplan: verto.rtc/1007 Action set(open=true) Dialplan: verto.rtc/1007 parsing [default->holiday_example] continue=true Dialplan: verto.rtc/1007 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: verto.rtc/1007 parsing [default->global-intercept] continue=false Dialplan: verto.rtc/1007 Regex (FAIL) [global-intercept] destination_number(1007) =~ /^886$/ break=on-false Dialplan: verto.rtc/1007 parsing [default->group-intercept] continue=false Dialplan: verto.rtc/1007 Regex (FAIL) [group-intercept] destination_number(1007) =~ /^\*8$/ break=on-false Dialplan: verto.rtc/1007 parsing [default->intercept-ext] continue=false Dialplan: verto.rtc/1007 Regex (FAIL) [intercept-ext] destination_number(1007) =~ /^\*\*(\d+)$/ break=on-false Dialplan: verto.rtc/1007 parsing [default->redial] continue=false Dialplan: verto.rtc/1007 Regex (FAIL) [redial] destination_number(1007) =~ /^(redial|870)$/ break=on-false Dialplan: verto.rtc/1007 parsing [default->global] continue=true Dialplan: verto.rtc/1007 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: verto.rtc/1007 Regex (FAIL) [global] ${default_password}(j0sh3b0sh) =~ /^1234$/ break=never Dialplan: verto.rtc/1007 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 Dialplan: verto.rtc/1007 Regex (FAIL) [global] ${endpoint_disposition}() =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: verto.rtc/1007 parsing [default->snom-demo-2] continue=false Dialplan: verto.rtc/1007 Regex (FAIL) [snom-demo-2] destination_number(1007) =~ /^9001$/ break=on-false Dialplan: verto.rtc/1007 parsing [default->snom-demo-1] continue=false Dialplan: verto.rtc/1007 Regex (FAIL) [snom-demo-1] destination_number(1007) =~ /^9000$/ break=on-false Dialplan: verto.rtc/1007 parsing [default->eavesdrop] continue=false Dialplan: verto.rtc/1007 Regex (FAIL) [eavesdrop] destination_number(1007) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: verto.rtc/1007 parsing [default->eavesdrop] continue=false Dialplan: verto.rtc/1007 Regex (FAIL) [eavesdrop] destination_number(1007) =~ /^779$/ break=on-false Dialplan: verto.rtc/1007 parsing [default->call_return] continue=false Dialplan: verto.rtc/1007 Regex (FAIL) [call_return] destination_number(1007) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: verto.rtc/1007 parsing [default->del-group] continue=false Dialplan: verto.rtc/1007 Regex (FAIL) [del-group] destination_number(1007) =~ /^80(\d{2})$/ break=on-false Dialplan: verto.rtc/1007 parsing [default->add-group] continue=false Dialplan: verto.rtc/1007 Regex (FAIL) [add-group] destination_number(1007) =~ /^81(\d{2})$/ break=on-false Dialplan: verto.rtc/1007 parsing [default->call-group-simo] continue=false Dialplan: verto.rtc/1007 Regex (FAIL) [call-group-simo] destination_number(1007) =~ /^82(\d{2})$/ break=on-false Dialplan: verto.rtc/1007 parsing [default->call-group-order] continue=false Dialplan: verto.rtc/1007 Regex (FAIL) [call-group-order] destination_number(1007) =~ /^83(\d{2})$/ break=on-false Dialplan: verto.rtc/1007 parsing [default->extension-intercom] continue=false Dialplan: verto.rtc/1007 Regex (FAIL) [extension-intercom] destination_number(1007) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: verto.rtc/1007 parsing [default->Local_Extension] continue=false Dialplan: verto.rtc/1007 Regex (PASS) [Local_Extension] destination_number(1007) =~ /^(10[01][0-9])$/ break=on-false Dialplan: verto.rtc/1007 Action export(dialed_extension=1007) Dialplan: verto.rtc/1007 Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: verto.rtc/1007 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) Dialplan: verto.rtc/1007 Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: verto.rtc/1007 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) Dialplan: verto.rtc/1007 Action set(ringback=${us-ring}) Dialplan: verto.rtc/1007 Action set(transfer_ringback=local_stream://moh) Dialplan: verto.rtc/1007 Action set(call_timeout=30) Dialplan: verto.rtc/1007 Action set(hangup_after_bridge=true) Dialplan: verto.rtc/1007 Action set(continue_on_fail=true) Dialplan: verto.rtc/1007 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: verto.rtc/1007 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: verto.rtc/1007 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: verto.rtc/1007 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) Dialplan: verto.rtc/1007 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) Dialplan: verto.rtc/1007 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: verto.rtc/1007 Action bridge(user/${dialed_extension}@${domain_name}) Dialplan: verto.rtc/1007 Action answer() Dialplan: verto.rtc/1007 Action sleep(1000) Dialplan: verto.rtc/1007 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 2017-06-21 17:15:39.637766 [DEBUG] switch_core_state_machine.c:286 (verto.rtc/1007) State Change CS_ROUTING -> CS_EXECUTE 2017-06-21 17:15:39.637766 [DEBUG] switch_core_state_machine.c:643 (verto.rtc/1007) State ROUTING going to sleep 2017-06-21 17:15:39.637766 [DEBUG] switch_core_state_machine.c:584 (verto.rtc/1007) Running State Change CS_EXECUTE (Cur 1 Tot 23) 2017-06-21 17:15:39.637766 [DEBUG] switch_core_state_machine.c:650 (verto.rtc/1007) State EXECUTE 2017-06-21 17:15:39.637766 [DEBUG] mod_rtc.c:120 verto.rtc/1007 RTC EXECUTE 2017-06-21 17:15:39.637766 [DEBUG] switch_core_state_machine.c:328 verto.rtc/1007 Standard EXECUTE EXECUTE verto.rtc/1007 set(open=true) 2017-06-21 17:15:39.637766 [DEBUG] mod_dptools.c:1570 SET verto.rtc/1007 [open]=[true] EXECUTE verto.rtc/1007 export(dialed_extension=1007) 2017-06-21 17:15:39.637766 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[1007] EXECUTE verto.rtc/1007 bind_meta_app(1 b s execute_extension::dx XML features) 2017-06-21 17:15:39.637766 [INFO] switch_ivr_async.c:4260 Bound B-Leg: *1 execute_extension::dx XML features EXECUTE verto.rtc/1007 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/galaxy@joshebosh.com.2017-06-21-17-15-39.wav) 2017-06-21 17:15:39.637766 [INFO] switch_ivr_async.c:4260 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/galaxy@joshebosh.com.2017-06-21-17-15-39.wav EXECUTE verto.rtc/1007 bind_meta_app(3 b s execute_extension::cf XML features) 2017-06-21 17:15:39.637766 [INFO] switch_ivr_async.c:4260 Bound B-Leg: *3 execute_extension::cf XML features EXECUTE verto.rtc/1007 bind_meta_app(4 b s execute_extension::att_xfer XML features) 2017-06-21 17:15:39.637766 [INFO] switch_ivr_async.c:4260 Bound B-Leg: *4 execute_extension::att_xfer XML features EXECUTE verto.rtc/1007 set(ringback=%(2000,4000,440,480)) 2017-06-21 17:15:39.637766 [DEBUG] mod_dptools.c:1570 SET verto.rtc/1007 [ringback]=[%(2000,4000,440,480)] EXECUTE verto.rtc/1007 set(transfer_ringback=local_stream://moh) 2017-06-21 17:15:39.637766 [DEBUG] mod_dptools.c:1570 SET verto.rtc/1007 [transfer_ringback]=[local_stream://moh] EXECUTE verto.rtc/1007 set(call_timeout=30) 2017-06-21 17:15:39.637766 [DEBUG] mod_dptools.c:1570 SET verto.rtc/1007 [call_timeout]=[30] EXECUTE verto.rtc/1007 set(hangup_after_bridge=true) 2017-06-21 17:15:39.637766 [DEBUG] mod_dptools.c:1570 SET verto.rtc/1007 [hangup_after_bridge]=[true] EXECUTE verto.rtc/1007 set(continue_on_fail=true) 2017-06-21 17:15:39.637766 [DEBUG] mod_dptools.c:1570 SET verto.rtc/1007 [continue_on_fail]=[true] EXECUTE verto.rtc/1007 hash(insert/192.168.150.3-call_return/1007/galaxy@joshebosh.com) EXECUTE verto.rtc/1007 hash(insert/192.168.150.3-last_dial_ext/1007/a3d97826-91a9-51c2-b4e6-549a1e02db53) EXECUTE verto.rtc/1007 set(called_party_callgroup=techsupport) 2017-06-21 17:15:39.647735 [DEBUG] mod_dptools.c:1570 SET verto.rtc/1007 [called_party_callgroup]=[techsupport] EXECUTE verto.rtc/1007 hash(insert/192.168.150.3-last_dial_ext/techsupport/a3d97826-91a9-51c2-b4e6-549a1e02db53) EXECUTE verto.rtc/1007 hash(insert/192.168.150.3-last_dial_ext/global/a3d97826-91a9-51c2-b4e6-549a1e02db53) EXECUTE verto.rtc/1007 hash(insert/192.168.150.3-last_dial/techsupport/a3d97826-91a9-51c2-b4e6-549a1e02db53) EXECUTE verto.rtc/1007 bridge(user/1007@192.168.150.3) 2017-06-21 17:15:39.647735 [DEBUG] switch_channel.c:1250 verto.rtc/1007 EXPORTING[export_vars] [dialed_extension]=[1007] to event 2017-06-21 17:15:39.647735 [DEBUG] switch_ivr_originate.c:2147 Parsing global variables 2017-06-21 17:15:39.647735 [DEBUG] switch_channel.c:1250 verto.rtc/1007 EXPORTING[export_vars] [dialed_extension]=[1007] to event 2017-06-21 17:15:39.647735 [DEBUG] switch_ivr_originate.c:2147 Parsing global variables 2017-06-21 17:15:39.647735 [NOTICE] switch_ivr_originate.c:2856 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED] 2017-06-21 17:15:39.647735 [DEBUG] mod_rtc.c:392 () State Change CS_NEW -> CS_INIT 2017-06-21 17:15:39.647735 [NOTICE] switch_channel.c:1104 New Channel verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44 [0ce12d5a-d47c-47d0-9658-8425484ed126] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_state_machine.c:584 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) Running State Change CS_INIT (Cur 2 Tot 24) 2017-06-21 17:15:39.647735 [DEBUG] switch_core_state_machine.c:627 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) State INIT 2017-06-21 17:15:39.647735 [DEBUG] mod_verto.c:2245 Local verto.invite SDP verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44: v=0 o=FreeSWITCH 1498057757 1498057758 IN IP4 192.168.150.3 s=FreeSWITCH c=IN IP4 192.168.150.3 t=0 0 a=msid-semantic: WMS f0Y8vyViEd6NX4vzXJPnPhIT2MTb2sX7 m=audio 21982 RTP/SAVPF 102 9 0 8 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=fingerprint:sha-256 A8:37:47:E9:6B:02:93:D6:06:AF:E4:10:72:A8:44:32:A2:EB:3D:03:E9:48:BC:9B:28:CA:59:4A:A6:B6:02:90 a=setup:actpass a=rtcp-mux a=rtcp:21982 IN IP4 192.168.150.3 a=ssrc:491973651 cname:jL6F9SNEVKhJED8r a=ssrc:491973651 msid:f0Y8vyViEd6NX4vzXJPnPhIT2MTb2sX7 a0 a=ssrc:491973651 mslabel:f0Y8vyViEd6NX4vzXJPnPhIT2MTb2sX7 a=ssrc:491973651 label:f0Y8vyViEd6NX4vzXJPnPhIT2MTb2sX7a0 a=ice-ufrag:cOFSVdBNQlOIDBGN a=ice-pwd:dCidkWH6wOF1iDilhO33RuHy a=candidate:7152099570 1 udp 659136 192.168.150.3 21982 typ host generation 0 a=candidate:7152099570 2 udp 659136 192.168.150.3 21982 typ host generation 0 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv m=video 21984 RTP/SAVPF 96 98 b=AS:1024 a=rtpmap:96 VP8/90000 a=rtpmap:98 VP9/90000 a=sendrecv a=fingerprint:sha-256 A8:37:47:E9:6B:02:93:D6:06:AF:E4:10:72:A8:44:32:A2:EB:3D:03:E9:48:BC:9B:28:CA:59:4A:A6:B6:02:90 a=setup:actpass a=rtcp-mux a=rtcp:21984 IN IP4 192.168.150.3 a=rtcp-fb:96 ccm fir a=rtcp-fb:96 ccm tmmbr a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli a=rtcp-fb:98 ccm fir a=rtcp-fb:98 ccm tmmbr a=rtcp-fb:98 nack a=rtcp-fb:98 nack pli a=ssrc:4037922053 cname:jL6F9SNEVKhJED8r a=ssrc:4037922053 msid:f0Y8vyViEd6NX4vzXJPnPhIT2MTb2sX7 v0 a=ssrc:4037922053 mslabel:f0Y8vyViEd6NX4vzXJPnPhIT2MTb2sX7 a=ssrc:4037922053 label:f0Y8vyViEd6NX4vzXJPnPhIT2MTb2sX7v0 a=ice-ufrag:x0i4hlZdTLhWFx6d a=ice-pwd:Gau9K88xK6XOH3Q4UYZ29P6T a=candidate:9019478234 1 udp 659136 192.168.150.3 21984 typ host generation 0 a=candidate:9019478234 2 udp 659135 192.168.150.3 21984 typ host generation 0 a=end-of-candidates 2017-06-21 17:15:39.647735 [NOTICE] mod_verto.c:2345 Ring-Ready verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44! 2017-06-21 17:15:39.647735 [DEBUG] switch_channel.c:3354 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) Callstate Change DOWN -> RINGING 2017-06-21 17:15:39.647735 [DEBUG] switch_core_state_machine.c:40 verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44 Standard INIT 2017-06-21 17:15:39.647735 [DEBUG] switch_core_state_machine.c:48 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) State Change CS_INIT -> CS_ROUTING 2017-06-21 17:15:39.647735 [DEBUG] switch_core_state_machine.c:627 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) State INIT going to sleep 2017-06-21 17:15:39.647735 [DEBUG] switch_core_state_machine.c:584 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) Running State Change CS_ROUTING (Cur 2 Tot 24) 2017-06-21 17:15:39.647735 [DEBUG] switch_core_state_machine.c:643 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) State ROUTING 2017-06-21 17:15:39.647735 [DEBUG] mod_rtc.c:89 verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44 RTC ROUTING 2017-06-21 17:15:39.647735 [DEBUG] switch_ivr_originate.c:67 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2017-06-21 17:15:39.647735 [DEBUG] switch_core_state_machine.c:643 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) State ROUTING going to sleep 2017-06-21 17:15:39.647735 [DEBUG] switch_core_state_machine.c:584 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 24) 2017-06-21 17:15:39.647735 [DEBUG] switch_core_state_machine.c:662 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) State CONSUME_MEDIA 2017-06-21 17:15:39.647735 [DEBUG] switch_core_state_machine.c:662 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) State CONSUME_MEDIA going to sleep 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5113 Audio Codec Compare [opus:111:48000:20:0:2]/[opus:116:48000:20:0:1] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5168 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5113 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[opus:116:48000:20:0:1] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5113 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5113 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5113 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5113 Audio Codec Compare [CN:105:16000:20:0:1]/[opus:116:48000:20:0:1] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5113 Audio Codec Compare [CN:13:8000:20:0:1]/[opus:116:48000:20:0:1] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5029 Set telephone-event payload to 110@48000 2017-06-21 17:15:39.647735 [DEBUG] mod_opus.c:603 Opus encoder: set bitrate to local settings [120000bps] 2017-06-21 17:15:39.647735 [DEBUG] mod_opus.c:603 Opus encoder: set bitrate to local settings [120000bps] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3428 Set Codec verto.rtc/1007 opus/48000 20 ms 960 samples 0 bits 2 channels 2017-06-21 17:15:39.647735 [DEBUG] switch_core_codec.c:111 verto.rtc/1007 Original read codec set to opus:116 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3852 Drop audio Candidate cid: 1 proto: udp type: host addr: 2600:1005:8102:840c:0:47:ca5d:9a01:55789 (no network path) 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3858 Save audio Candidate cid: 1 proto: udp type: host addr: 192.168.150.144:33538 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3858 Save audio Candidate cid: 1 proto: udp type: srflx addr: 65.15.69.32:33538 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3900 Searching for rtp candidate. 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3905 Choose rtp candidate, index 0, 192.168.150.144:33538 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3678 verto.rtc/1007 choosing family v4 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3916 Choose same candidate, index 0, for rtcp based on rtcp-mux attribute 192.168.150.144:33538 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3963 setting remote audio ice addr to index 0 192.168.150.144:33538 based on candidate 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3998 Setting remote rtcp audio addr to 192.168.150.144:33538 based on candidate 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5372 Set telephone-event payload to 110@48000 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5430 verto.rtc/1007 Set 2833 dtmf send payload to 110 recv payload to 110 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5713 Video Codec Compare [VP8:96]/[VP8:99] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5745 Video Codec Compare [VP8:96] +++ is saved as a match 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5713 Video Codec Compare [VP9:98]/[VP8:99] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5713 Video Codec Compare [red:100]/[VP8:99] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5713 Video Codec Compare [ulpfec:102]/[VP8:99] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5713 Video Codec Compare [H264:127]/[VP8:99] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5713 Video Codec Compare [rtx:97]/[VP8:99] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5713 Video Codec Compare [rtx:99]/[VP8:99] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5713 Video Codec Compare [rtx:101]/[VP8:99] 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:5713 Video Codec Compare [rtx:104]/[VP8:99] 2017-06-21 17:15:39.647735 [DEBUG] switch_vpx.c:631 VPX VER:v1.6.0 VPX_IMAGE_ABI_VERSION:4 VPX_CODEC_ABI_VERSION:7 2017-06-21 17:15:39.647735 [DEBUG] switch_vpx.c:631 VPX VER:v1.6.0 VPX_IMAGE_ABI_VERSION:4 VPX_CODEC_ABI_VERSION:7 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3238 Set VIDEO Codec verto.rtc/1007 VP8/90000 0 ms 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3852 Drop video Candidate cid: 1 proto: udp type: host addr: 2600:1005:8102:840c:0:47:ca5d:9a01:45863 (no network path) 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3858 Save video Candidate cid: 1 proto: udp type: host addr: 192.168.150.144:59965 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3858 Save video Candidate cid: 1 proto: udp type: srflx addr: 65.15.69.32:59965 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3900 Searching for rtp candidate. 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3905 Choose rtp candidate, index 0, 192.168.150.144:59965 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3678 verto.rtc/1007 choosing family v4 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3916 Choose same candidate, index 0, for rtcp based on rtcp-mux attribute 192.168.150.144:59965 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3963 setting remote video ice addr to index 0 192.168.150.144:59965 based on candidate 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:3998 Setting remote rtcp video addr to 192.168.150.144:59965 based on candidate 2017-06-21 17:15:39.647735 [DEBUG] switch_core_media.c:8147 AUDIO RTP [verto.rtc/1007] 192.168.150.3 port 29582 -> 192.168.150.144 port 33538 codec: 111 ms: 20 2017-06-21 17:15:39.647735 [DEBUG] switch_rtp.c:4111 Starting timer [soft] 960 bytes per 20ms 2017-06-21 17:15:39.657741 [INFO] switch_core_media.c:8326 Activating Audio ICE 2017-06-21 17:15:39.657741 [NOTICE] switch_rtp.c:4610 Activating RTP audio ICE: vS+Q:kKrm5u3rLQwOmcC7 192.168.150.144:33538 2017-06-21 17:15:39.657741 [DEBUG] switch_core_media.c:8369 Activating RTCP PORT 33538 2017-06-21 17:15:39.657741 [DEBUG] switch_rtp.c:4507 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 33538 2017-06-21 17:15:39.657741 [INFO] switch_core_media.c:8377 Skipping RTCP ICE (Same as RTP) 2017-06-21 17:15:39.657741 [INFO] switch_rtp.c:3581 Activate RTP/RTCP audio DTLS client 2017-06-21 17:15:39.657741 [INFO] switch_rtp.c:3730 Changing audio DTLS state from OFF to HANDSHAKE 2017-06-21 17:15:39.657741 [DEBUG] switch_core_media.c:2190 Setting Jitterbuffer to 20ms (1 frames) (50 max frames) 2017-06-21 17:15:39.657741 [DEBUG] switch_core_media.c:8450 verto.rtc/1007 Set 2833 dtmf send payload to 110 2017-06-21 17:15:39.657741 [DEBUG] switch_core_media.c:8457 verto.rtc/1007 Set 2833 dtmf receive payload to 110 2017-06-21 17:15:39.657741 [DEBUG] switch_rtp.c:4126 Starting video timer. 2017-06-21 17:15:39.657741 [DEBUG] switch_core_media.c:8975 VIDEO RTP [verto.rtc/1007] 192.168.150.3:25278->192.168.150.144:59965 codec: 96 ms: 0 [SUCCESS] 2017-06-21 17:15:39.657741 [DEBUG] switch_core_media.c:7139 verto.rtc/1007 Starting Video thread 2017-06-21 17:15:39.657741 [DEBUG] switch_core_media.c:7005 verto.rtc/1007 Video thread started. Echo is off 2017-06-21 17:15:39.657741 [INFO] switch_core_media.c:9017 Activating Video ICE 2017-06-21 17:15:39.657741 [NOTICE] switch_rtp.c:4610 Activating RTP video ICE: vS+Q:kAJsrVgVmRRmpVqS 192.168.150.144:59965 2017-06-21 17:15:39.657741 [INFO] switch_core_media.c:9055 Activating VIDEO RTCP PORT 59965 interval 1000 mux 1 2017-06-21 17:15:39.657741 [DEBUG] switch_rtp.c:4507 RTCP send rate is: 1000 and packet rate is: 90000 Remote Port: 59965 2017-06-21 17:15:39.657741 [INFO] switch_core_media.c:9066 Skipping VIDEO RTCP ICE (Same as VIDEO RTP) 2017-06-21 17:15:39.657741 [INFO] switch_rtp.c:3581 Activate RTP/RTCP video DTLS client 2017-06-21 17:15:39.657741 [INFO] switch_rtp.c:3730 Changing video DTLS state from OFF to HANDSHAKE 2017-06-21 17:15:39.657741 [DEBUG] switch_core_media.c:8130 Audio params are unchanged for verto.rtc/1007. 2017-06-21 17:15:39.657741 [DEBUG] switch_core_media.c:8833 Video params are unchanged for verto.rtc/1007. 2017-06-21 17:15:39.657741 [DEBUG] mod_verto.c:2480 Local SDP verto.rtc/1007: v=0 o=FreeSWITCH 1498050157 1498050158 IN IP4 192.168.150.3 s=FreeSWITCH c=IN IP4 192.168.150.3 t=0 0 a=msid-semantic: WMS UoAEqZUQ6TYOaPpDEyuLcvdRvqWfcGPX m=audio 29582 UDP/TLS/RTP/SAVPF 111 110 a=rtpmap:111 opus/48000/2 a=fmtp:111 useinbandfec=1; minptime=10; stereo=1; sprop-stereo=1 a=rtpmap:110 telephone-event/48000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv a=fingerprint:sha-256 A8:37:47:E9:6B:02:93:D6:06:AF:E4:10:72:A8:44:32:A2:EB:3D:03:E9:48:BC:9B:28:CA:59:4A:A6:B6:02:90 a=setup:active a=rtcp-mux a=rtcp:29582 IN IP4 192.168.150.3 a=ice-ufrag:kKrm5u3rLQwOmcC7 a=ice-pwd:iU8dXR5JnBwAnMgxmyJiTDzv a=candidate:0668217445 1 udp 659136 192.168.150.3 29582 typ host generation 0 a=end-of-candidates a=ssrc:558869187 cname:Ufsb5cS1WGFWmVqQ a=ssrc:558869187 msid:UoAEqZUQ6TYOaPpDEyuLcvdRvqWfcGPX a0 a=ssrc:558869187 mslabel:UoAEqZUQ6TYOaPpDEyuLcvdRvqWfcGPX a=ssrc:558869187 label:UoAEqZUQ6TYOaPpDEyuLcvdRvqWfcGPXa0 m=video 25278 UDP/TLS/RTP/SAVPF 96 b=AS:1024 a=rtpmap:96 VP8/90000 a=sendrecv a=fingerprint:sha-256 A8:37:47:E9:6B:02:93:D6:06:AF:E4:10:72:A8:44:32:A2:EB:3D:03:E9:48:BC:9B:28:CA:59:4A:A6:B6:02:90 a=setup:active a=rtcp-mux a=rtcp:25278 IN IP4 192.168.150.3 a=rtcp-fb:96 ccm fir a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli a=ssrc:4104817589 cname:Ufsb5cS1WGFWmVqQ a=ssrc:4104817589 msid:UoAEqZUQ6TYOaPpDEyuLcvdRvqWfcGPX v0 a=ssrc:4104817589 mslabel:UoAEqZUQ6TYOaPpDEyuLcvdRvqWfcGPX a=ssrc:4104817589 label:UoAEqZUQ6TYOaPpDEyuLcvdRvqWfcGPXv0 a=ice-ufrag:kAJsrVgVmRRmpVqS a=ice-pwd:ZfHt3e0MEYkt08MaymtQ7zBk a=candidate:4771692337 1 udp 659136 192.168.150.3 25278 typ host generation 0 a=end-of-candidates 2017-06-21 17:15:39.657741 [NOTICE] switch_ivr_originate.c:1220 Pre-Answer verto.rtc/1007! 2017-06-21 17:15:39.657741 [DEBUG] switch_channel.c:3482 (verto.rtc/1007) Callstate Change RINGING -> EARLY 2017-06-21 17:15:39.657741 [DEBUG] switch_ivr_originate.c:1278 Raw Codec Activation Success L16@48000hz 2 channel 20ms 2017-06-21 17:15:39.657741 [DEBUG] switch_core_codec.c:223 verto.rtc/1007 Push codec L16:100 2017-06-21 17:15:39.657741 [DEBUG] switch_ivr_originate.c:1347 Play Ringback Tone [%(2000,4000,440,480)] 2017-06-21 17:15:39.777738 [NOTICE] switch_vpx.c:406 VPX reset encoder picture from 320x240 to 352x288 1024 BW 2017-06-21 17:15:39.937742 [INFO] switch_rtp.c:3192 Changing audio DTLS state from HANDSHAKE to SETUP 2017-06-21 17:15:39.937742 [INFO] switch_rtp.c:3101 audio Fingerprint Verified. 2017-06-21 17:15:39.937742 [INFO] switch_rtp.c:3915 Activating audio Secure RTP SEND 2017-06-21 17:15:39.937742 [INFO] switch_rtp.c:3893 Activating audio Secure RTP RECV 2017-06-21 17:15:39.937742 [INFO] switch_rtp.c:3141 Changing audio DTLS state from SETUP to READY 2017-06-21 17:15:39.937742 [DEBUG] switch_core_sqldb.c:2617 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80 2017-06-21 17:15:39.937742 [DEBUG] switch_core_sqldb.c:2617 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80 2017-06-21 17:15:39.957766 [INFO] switch_rtp.c:3192 Changing video DTLS state from HANDSHAKE to SETUP 2017-06-21 17:15:39.957766 [INFO] switch_rtp.c:3101 video Fingerprint Verified. 2017-06-21 17:15:39.957766 [INFO] switch_rtp.c:3915 Activating video Secure RTP SEND 2017-06-21 17:15:39.957766 [INFO] switch_rtp.c:3893 Activating video Secure RTP RECV 2017-06-21 17:15:39.957766 [INFO] switch_rtp.c:3141 Changing video DTLS state from SETUP to READY 2017-06-21 17:15:39.957766 [DEBUG] switch_core_sqldb.c:2617 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80 2017-06-21 17:15:39.957766 [DEBUG] switch_core_sqldb.c:2617 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80 2017-06-21 17:15:39.977737 [DEBUG] switch_rtp.c:1887 rtcp_stats_init: audio ssrc[2623231321] base_seq[24332] 2017-06-21 17:15:40.007767 [DEBUG] switch_rtp.c:1887 rtcp_stats_init: video ssrc[3760859939] base_seq[26553] 2017-06-21 17:15:48.207767 [NOTICE] mod_verto.c:2807 Hangup verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44 [CS_CONSUME_MEDIA] [NORMAL_CLEARING] 2017-06-21 17:15:48.207767 [DEBUG] switch_core_state_machine.c:584 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) Running State Change CS_HANGUP (Cur 2 Tot 24) 2017-06-21 17:15:48.207767 [DEBUG] switch_core_state_machine.c:850 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) Callstate Change RINGING -> HANGUP 2017-06-21 17:15:48.207767 [DEBUG] switch_core_state_machine.c:852 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) State HANGUP 2017-06-21 17:15:48.207767 [DEBUG] switch_core_state_machine.c:60 verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44 Standard HANGUP, cause: NORMAL_CLEARING 2017-06-21 17:15:48.207767 [DEBUG] switch_core_state_machine.c:852 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) State HANGUP going to sleep 2017-06-21 17:15:48.207767 [DEBUG] switch_core_state_machine.c:619 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) State Change CS_HANGUP -> CS_REPORTING 2017-06-21 17:15:48.207767 [DEBUG] switch_core_state_machine.c:584 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) Running State Change CS_REPORTING (Cur 2 Tot 24) 2017-06-21 17:15:48.207767 [DEBUG] switch_core_state_machine.c:938 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) State REPORTING 2017-06-21 17:15:48.207767 [DEBUG] switch_core_state_machine.c:174 verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44 Standard REPORTING, cause: NORMAL_CLEARING 2017-06-21 17:15:48.207767 [DEBUG] switch_core_state_machine.c:938 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) State REPORTING going to sleep 2017-06-21 17:15:48.207767 [DEBUG] switch_core_state_machine.c:610 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) State Change CS_REPORTING -> CS_DESTROY 2017-06-21 17:15:48.207767 [DEBUG] switch_core_session.c:1712 Session 24 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) Locked, Waiting on external entities 2017-06-21 17:15:48.217742 [DEBUG] switch_core_codec.c:248 verto.rtc/1007 Restore previous codec opus:116. 2017-06-21 17:15:48.217742 [DEBUG] switch_ivr_originate.c:3853 Originate Resulted in Error Cause: 16 [NORMAL_CLEARING] 2017-06-21 17:15:48.217742 [NOTICE] switch_core_session.c:1730 Session 24 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) Ended 2017-06-21 17:15:48.217742 [NOTICE] switch_core_session.c:1734 Close Channel verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44 [CS_DESTROY] 2017-06-21 17:15:48.217742 [DEBUG] switch_core_state_machine.c:741 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) Running State Change CS_DESTROY (Cur 1 Tot 24) 2017-06-21 17:15:48.217742 [DEBUG] switch_core_state_machine.c:751 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) State DESTROY 2017-06-21 17:15:48.217742 [DEBUG] mod_rtc.c:132 verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44 RTC DESTROY 2017-06-21 17:15:48.217742 [DEBUG] switch_core_state_machine.c:181 verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44 Standard DESTROY 2017-06-21 17:15:48.217742 [DEBUG] switch_core_state_machine.c:751 (verto.rtc/8383c106-bb13-be6d-9916-e9b282d85e44) State DESTROY going to sleep 2017-06-21 17:15:48.217742 [NOTICE] switch_ivr_originate.c:2856 Cannot create outgoing channel of type [user] cause: [NORMAL_CLEARING] 2017-06-21 17:15:48.217742 [DEBUG] switch_ivr_originate.c:3853 Originate Resulted in Error Cause: 16 [NORMAL_CLEARING] 2017-06-21 17:15:48.217742 [INFO] mod_dptools.c:3490 Originate Failed. Cause: NORMAL_CLEARING EXECUTE verto.rtc/1007 answer() 2017-06-21 17:15:48.217742 [NOTICE] mod_dptools.c:1352 Channel [verto.rtc/1007] has been answered 2017-06-21 17:15:48.217742 [DEBUG] switch_channel.c:3781 (verto.rtc/1007) Callstate Change EARLY -> ACTIVE EXECUTE verto.rtc/1007 sleep(1000) 2017-06-21 17:15:48.217742 [DEBUG] switch_ivr.c:195 Codec Activated L16@48000hz 2 channels 20ms EXECUTE verto.rtc/1007 bridge(loopback/app=voicemail:default 192.168.150.3 1007) 2017-06-21 17:15:49.237741 [DEBUG] switch_channel.c:1823 (verto.rtc/1007) Callstate Change ACTIVE -> RING_WAIT 2017-06-21 17:15:49.237741 [DEBUG] switch_channel.c:1250 verto.rtc/1007 EXPORTING[export_vars] [dialed_extension]=[1007] to event 2017-06-21 17:15:49.237741 [DEBUG] switch_ivr_originate.c:2147 Parsing global variables 2017-06-21 17:15:49.237741 [NOTICE] switch_channel.c:1104 New Channel loopback/app=voicemail:default 192.168.150.3 1007-a [b5546862-0122-4007-a276-2bd1c5694d7d] 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:158 loopback/app=voicemail:default 192.168.150.3 1007-a setup codec opus/48000/20 2017-06-21 17:15:49.237741 [DEBUG] mod_opus.c:603 Opus encoder: set bitrate to local settings [72000bps] 2017-06-21 17:15:49.237741 [DEBUG] mod_opus.c:603 Opus encoder: set bitrate to local settings [72000bps] 2017-06-21 17:15:49.237741 [NOTICE] switch_channel.c:1102 Rename Channel loopback/app=voicemail:default 192.168.150.3 1007-a->loopback/voicemail-a [b5546862-0122-4007-a276-2bd1c5694d7d] 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:1176 (loopback/voicemail-a) State Change CS_NEW -> CS_INIT 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_INIT (Cur 2 Tot 25) 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:627 (loopback/voicemail-a) State INIT 2017-06-21 17:15:49.237741 [NOTICE] switch_channel.c:1104 New Channel loopback/voicemail-b [585b3b9c-6cc9-4f40-a00d-3203ccdcaec0] 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:158 loopback/voicemail-b setup codec opus/48000/20 2017-06-21 17:15:49.237741 [DEBUG] mod_opus.c:603 Opus encoder: set bitrate to local settings [72000bps] 2017-06-21 17:15:49.237741 [DEBUG] mod_opus.c:603 Opus encoder: set bitrate to local settings [72000bps] 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:276 (loopback/voicemail-b) State Change CS_NEW -> CS_INIT 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:364 (loopback/voicemail-a) State Change CS_INIT -> CS_ROUTING 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_INIT (Cur 3 Tot 26) 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:627 (loopback/voicemail-a) State INIT going to sleep 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:627 (loopback/voicemail-b) State INIT 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:364 (loopback/voicemail-b) State Change CS_INIT -> CS_ROUTING 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:627 (loopback/voicemail-b) State INIT going to sleep 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_ROUTING (Cur 3 Tot 26) 2017-06-21 17:15:49.237741 [DEBUG] switch_channel.c:2249 (loopback/voicemail-b) Callstate Change DOWN -> RINGING 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_ROUTING (Cur 3 Tot 26) 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:643 (loopback/voicemail-b) State ROUTING 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:396 loopback/voicemail-b CHANNEL ROUTING 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:415 (loopback/voicemail-b) State Change CS_ROUTING -> CS_EXECUTE 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:643 (loopback/voicemail-b) State ROUTING going to sleep 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_EXECUTE (Cur 3 Tot 26) 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:650 (loopback/voicemail-b) State EXECUTE 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:643 (loopback/voicemail-a) State ROUTING 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:438 loopback/voicemail-b CHANNEL EXECUTE 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:396 loopback/voicemail-a CHANNEL ROUTING 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:328 loopback/voicemail-b Standard EXECUTE 2017-06-21 17:15:49.237741 [DEBUG] switch_ivr_originate.c:67 (loopback/voicemail-a) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:643 (loopback/voicemail-a) State ROUTING going to sleep 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_CONSUME_MEDIA (Cur 3 Tot 26) EXECUTE loopback/voicemail-b pre_answer() 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:662 (loopback/voicemail-a) State CONSUME_MEDIA 2017-06-21 17:15:49.237741 [NOTICE] mod_loopback.c:963 Pre-Answer loopback/voicemail-a! 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:663 CHANNEL CONSUME_MEDIA 2017-06-21 17:15:49.237741 [DEBUG] switch_core_state_machine.c:662 (loopback/voicemail-a) State CONSUME_MEDIA going to sleep 2017-06-21 17:15:49.237741 [DEBUG] switch_channel.c:3482 (loopback/voicemail-a) Callstate Change DOWN -> EARLY 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL 2017-06-21 17:15:49.237741 [NOTICE] mod_dptools.c:1395 Pre-Answer loopback/voicemail-b! 2017-06-21 17:15:49.237741 [DEBUG] switch_channel.c:3482 (loopback/voicemail-b) Callstate Change RINGING -> EARLY 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL EXECUTE loopback/voicemail-b voicemail(default 192.168.150.3 1007) 2017-06-21 17:15:49.237741 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL 2017-06-21 17:15:49.247744 [DEBUG] switch_ivr_originate.c:3710 Originate Resulted in Success: [loopback/voicemail-a] 2017-06-21 17:15:49.247744 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL 2017-06-21 17:15:49.247744 [DEBUG] switch_channel.c:2047 (verto.rtc/1007) Callstate Change RING_WAIT -> ACTIVE 2017-06-21 17:15:49.247744 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL 2017-06-21 17:15:49.257739 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL 2017-06-21 17:15:49.257739 [DEBUG] switch_ivr_bridge.c:1744 (loopback/voicemail-a) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2017-06-21 17:15:49.257739 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL 2017-06-21 17:15:49.257739 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_EXCHANGE_MEDIA (Cur 3 Tot 26) 2017-06-21 17:15:49.257739 [DEBUG] switch_core_state_machine.c:653 (loopback/voicemail-a) State EXCHANGE_MEDIA 2017-06-21 17:15:49.257739 [DEBUG] mod_loopback.c:625 CHANNEL LOOPBACK 2017-06-21 17:15:49.267766 [DEBUG] switch_core_media.c:15436 Engaging Write Buffer at 1920 bytes to accommodate 1920->1920 2017-06-21 17:15:49.337742 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] 2017-06-21 17:15:49.347743 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-person.wav] (en:en) 2017-06-21 17:15:49.347743 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL 2017-06-21 17:15:49.347743 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@48000hz 1 channels 20ms 2017-06-21 17:15:49.377742 [DEBUG] switch_core_media.c:15436 Engaging Write Buffer at 3840 bytes to accommodate 3840->3840 2017-06-21 17:15:50.697743 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav 2017-06-21 17:15:50.797743 [DEBUG] switch_ivr_play_say.c:250 Handle say:[1007] (en:en) 2017-06-21 17:15:50.797743 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL 2017-06-21 17:15:50.797743 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@48000hz 1 channels 20ms 2017-06-21 17:15:53.097743 [DEBUG] switch_ivr_play_say.c:1942 done playing file file_string://digits/1.wav!digits/0.wav!digits/0.wav!digits/7.wav 2017-06-21 17:15:53.197743 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-not_available.wav] (en:en) 2017-06-21 17:15:53.197743 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL 2017-06-21 17:15:53.197743 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@48000hz 1 channels 20ms 2017-06-21 17:15:53.287767 [NOTICE] mod_verto.c:2807 Hangup verto.rtc/1007 [CS_EXECUTE] [NORMAL_CLEARING] 2017-06-21 17:15:53.287767 [DEBUG] switch_core_media.c:7106 verto.rtc/1007 Video thread ended 2017-06-21 17:15:53.287767 [DEBUG] switch_ivr_bridge.c:831 verto.rtc/1007 ending bridge by request from read function 2017-06-21 17:15:53.287767 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [verto.rtc/1007] 2017-06-21 17:15:53.287767 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL 2017-06-21 17:15:53.287767 [DEBUG] switch_core_media.c:13746 verto.rtc/1007 skip receive message [DISPLAY] (channel is hungup already) 2017-06-21 17:15:53.297766 [DEBUG] switch_ivr_bridge.c:825 verto.rtc/1007 ending bridge by request from write function 2017-06-21 17:15:53.297766 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [loopback/voicemail-a] 2017-06-21 17:15:53.297766 [NOTICE] switch_ivr_bridge.c:1030 Hangup loopback/voicemail-a [CS_EXCHANGE_MEDIA] [ORIGINATOR_CANCEL] 2017-06-21 17:15:53.297766 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL 2017-06-21 17:15:53.297766 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:653 (loopback/voicemail-a) State EXCHANGE_MEDIA going to sleep 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_HANGUP (Cur 3 Tot 26) 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:850 (loopback/voicemail-a) Callstate Change EARLY -> HANGUP 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:852 (loopback/voicemail-a) State HANGUP 2017-06-21 17:15:53.297766 [DEBUG] mod_loopback.c:550 loopback/voicemail-a CHANNEL HANGUP 2017-06-21 17:15:53.297766 [NOTICE] mod_loopback.c:566 Hangup loopback/voicemail-b [CS_EXECUTE] [ORIGINATOR_CANCEL] 2017-06-21 17:15:53.297766 [DEBUG] switch_ivr_bridge.c:1843 loopback/voicemail-a skip receive message [TRANSFER] (channel is hungup already) 2017-06-21 17:15:53.297766 [DEBUG] switch_ivr_bridge.c:1846 verto.rtc/1007 skip receive message [TRANSFER] (channel is hungup already) 2017-06-21 17:15:53.297766 [DEBUG] switch_core_session.c:2884 verto.rtc/1007 skip receive message [PHONE_EVENT] (channel is hungup already) 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:650 (verto.rtc/1007) State EXECUTE going to sleep 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:584 (verto.rtc/1007) Running State Change CS_HANGUP (Cur 3 Tot 26) 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:850 (verto.rtc/1007) Callstate Change ACTIVE -> HANGUP 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:852 (verto.rtc/1007) State HANGUP 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:60 verto.rtc/1007 Standard HANGUP, cause: NORMAL_CLEARING 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:852 (verto.rtc/1007) State HANGUP going to sleep 2017-06-21 17:15:53.297766 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-not_available.wav 2017-06-21 17:15:53.297766 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL 2017-06-21 17:15:53.297766 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:60 loopback/voicemail-a Standard HANGUP, cause: ORIGINATOR_CANCEL 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:852 (loopback/voicemail-a) State HANGUP going to sleep 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:619 (verto.rtc/1007) State Change CS_HANGUP -> CS_REPORTING 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:619 (loopback/voicemail-a) State Change CS_HANGUP -> CS_REPORTING 2017-06-21 17:15:53.297766 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_REPORTING (Cur 3 Tot 26) 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:584 (verto.rtc/1007) Running State Change CS_REPORTING (Cur 3 Tot 26) 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:938 (loopback/voicemail-a) State REPORTING 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:174 loopback/voicemail-a Standard REPORTING, cause: ORIGINATOR_CANCEL 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:938 (loopback/voicemail-a) State REPORTING going to sleep 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:938 (verto.rtc/1007) State REPORTING 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:174 verto.rtc/1007 Standard REPORTING, cause: NORMAL_CLEARING 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:938 (verto.rtc/1007) State REPORTING going to sleep 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:610 (loopback/voicemail-a) State Change CS_REPORTING -> CS_DESTROY 2017-06-21 17:15:53.297766 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL 2017-06-21 17:15:53.297766 [DEBUG] switch_core_session.c:1712 Session 25 (loopback/voicemail-a) Locked, Waiting on external entities 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:610 (verto.rtc/1007) State Change CS_REPORTING -> CS_DESTROY 2017-06-21 17:15:53.297766 [DEBUG] switch_core_session.c:1712 Session 23 (verto.rtc/1007) Locked, Waiting on external entities 2017-06-21 17:15:53.297766 [NOTICE] switch_core_session.c:1730 Session 23 (verto.rtc/1007) Ended 2017-06-21 17:15:53.297766 [NOTICE] switch_core_session.c:1734 Close Channel verto.rtc/1007 [CS_DESTROY] 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:741 (verto.rtc/1007) Running State Change CS_DESTROY (Cur 2 Tot 26) 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:751 (verto.rtc/1007) State DESTROY 2017-06-21 17:15:53.297766 [DEBUG] mod_rtc.c:132 verto.rtc/1007 RTC DESTROY 2017-06-21 17:15:53.297766 [DEBUG] mod_opus.c:711 Opus decoder stats: Frames[614] PLC[0] FEC[0] 2017-06-21 17:15:53.297766 [DEBUG] mod_opus.c:726 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2017-06-21 17:15:53.297766 [DEBUG] mod_opus.c:711 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2017-06-21 17:15:53.297766 [DEBUG] mod_opus.c:726 Opus encoder stats: Frames[663] Bytes encoded[119516] Encoded length ms[13260] Average encoded bitrate bps[73548] 2017-06-21 17:15:53.297766 [DEBUG] switch_core_session.c:2884 loopback/voicemail-b skip receive message [PHONE_EVENT] (channel is hungup already) 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:650 (loopback/voicemail-b) State EXECUTE going to sleep 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_HANGUP (Cur 2 Tot 26) 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:850 (loopback/voicemail-b) Callstate Change EARLY -> HANGUP 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:852 (loopback/voicemail-b) State HANGUP 2017-06-21 17:15:53.297766 [DEBUG] mod_loopback.c:550 loopback/voicemail-b CHANNEL HANGUP 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:60 loopback/voicemail-b Standard HANGUP, cause: ORIGINATOR_CANCEL 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:852 (loopback/voicemail-b) State HANGUP going to sleep 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:619 (loopback/voicemail-b) State Change CS_HANGUP -> CS_REPORTING 2017-06-21 17:15:53.297766 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL 2017-06-21 17:15:53.297766 [NOTICE] switch_core_session.c:1730 Session 25 (loopback/voicemail-a) Ended 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_REPORTING (Cur 2 Tot 26) 2017-06-21 17:15:53.297766 [NOTICE] switch_core_session.c:1734 Close Channel loopback/voicemail-a [CS_DESTROY] 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:181 verto.rtc/1007 Standard DESTROY 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:751 (verto.rtc/1007) State DESTROY going to sleep 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:938 (loopback/voicemail-b) State REPORTING 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:174 loopback/voicemail-b Standard REPORTING, cause: ORIGINATOR_CANCEL 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:938 (loopback/voicemail-b) State REPORTING going to sleep 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:741 (loopback/voicemail-a) Running State Change CS_DESTROY (Cur 1 Tot 26) 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:610 (loopback/voicemail-b) State Change CS_REPORTING -> CS_DESTROY 2017-06-21 17:15:53.297766 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL 2017-06-21 17:15:53.297766 [DEBUG] switch_core_session.c:1712 Session 26 (loopback/voicemail-b) Locked, Waiting on external entities 2017-06-21 17:15:53.297766 [NOTICE] switch_core_session.c:1730 Session 26 (loopback/voicemail-b) Ended 2017-06-21 17:15:53.297766 [NOTICE] switch_core_session.c:1734 Close Channel loopback/voicemail-b [CS_DESTROY] 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:751 (loopback/voicemail-a) State DESTROY 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:741 (loopback/voicemail-b) Running State Change CS_DESTROY (Cur 0 Tot 26) 2017-06-21 17:15:53.297766 [DEBUG] mod_opus.c:711 Opus decoder stats: Frames[186] PLC[0] FEC[0] 2017-06-21 17:15:53.297766 [DEBUG] mod_opus.c:726 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2017-06-21 17:15:53.297766 [DEBUG] mod_opus.c:711 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2017-06-21 17:15:53.297766 [DEBUG] mod_opus.c:726 Opus encoder stats: Frames[201] Bytes encoded[21583] Encoded length ms[4020] Average encoded bitrate bps[43166] 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:181 loopback/voicemail-a Standard DESTROY 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:751 (loopback/voicemail-a) State DESTROY going to sleep 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:751 (loopback/voicemail-b) State DESTROY 2017-06-21 17:15:53.297766 [DEBUG] mod_opus.c:711 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2017-06-21 17:15:53.297766 [DEBUG] mod_opus.c:726 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0] 2017-06-21 17:15:53.297766 [DEBUG] mod_opus.c:711 Opus decoder stats: Frames[0] PLC[0] FEC[0] 2017-06-21 17:15:53.297766 [DEBUG] mod_opus.c:726 Opus encoder stats: Frames[187] Bytes encoded[23210] Encoded length ms[3740] Average encoded bitrate bps[61893] 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:181 loopback/voicemail-b Standard DESTROY 2017-06-21 17:15:53.297766 [DEBUG] switch_core_state_machine.c:751 (loopback/voicemail-b) State DESTROY going to sleep