2016-03-03 08:01:52.810916 [ALERT] mod_verto.c:1365 READ x.x.x.47:45905 [{ "jsonrpc": "2.0", "method": "verto.invite", "params": { "sdp": "v=0\r\no=- 6394623381710128159 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE audio\r\na=msid-semantic: WMS CL1gc0JpOcppsQ0KwbVTGs1EX0ooFmPQp4yc\r\nm=audio 52550 RTP/SAVPF 111 103 104 0 8 106 105 13 126\r\nc=IN IP4 x.x.x.47\r\na=rtcp:52550 IN IP4 x.x.x.47\r\na=candidate:2608808550 1 udp 2122260223 192.168.1.33 52550 typ host generation 0\r\na=candidate:2608808550 2 udp 2122260223 192.168.1.33 52550 typ host generation 0\r\na=candidate:3590110870 1 tcp 1518280447 192.168.1.33 0 typ host tcptype active generation 0\r\na=candidate:3590110870 2 tcp 1518280447 192.168.1.33 0 typ host tcptype active generation 0\r\na=candidate:1836006322 1 udp 1686052607 x.x.x.47 52550 typ srflx raddr 192.168.1.33 rport 52550 generation 0\r\na=candidate:1836006322 2 udp 1686052607 x.x.x.47 52550 typ srflx raddr 192.168.1.33 rport 52550 generation 0\r\na=ice-ufrag:g/XzIwk/FmJyN58u\r\na=ice-pwd:LIaaZisCkhtq5VHrFloGF8Zf\r\na=ice-options:google-ice\r\na=fingerprint:sha-256 D2:2D:74:F4:FF:10:85:48:FE:C6:B9:76:30:B9:06:B1:75:7C:C2:28:1E:CD:01:D5:9E:38:22:5E:AE:91:D7:3C\r\na=setup:actpass\r\na=mid:audio\r\na=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level\r\na=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time\r\na=sendrecv\r\na=rtcp-mux\r\na=rtpmap:111 opus/48000/2\r\na=fmtp:111 minptime=10; stereo=1\r\na=rtpmap:103 ISAC/16000\r\na=rtpmap:104 ISAC/32000\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:106 CN/32000\r\na=rtpmap:105 CN/16000\r\na=rtpmap:13 CN/8000\r\na=rtpmap:126 telephone-event/8000\r\na=maxptime:60\r\na=ssrc:2908524814 cname:zrTZ84hefkswtwKu\r\na=ssrc:2908524814 msid:CL1gc0JpOcppsQ0KwbVTGs1EX0ooFmPQp4yc 97fae677-74be-4b0a-b226-675b82268309\r\na=ssrc:2908524814 mslabel:CL1gc0JpOcppsQ0KwbVTGs1EX0ooFmPQp4yc\r\na=ssrc:2908524814 label:97fae677-74be-4b0a-b226-675b82268309\r\n", "dialogParams": { "useVideo": false, "useStereo": true, "screenShare": false, "useCamera": "any", "useMic": "any", "useSpeak": "any", "tag": "webcam", "localTag": null, "login": "789789@x.x.x.91", "videoParams": { "minWidth": "1280", "minHeight": "720", "minFrameRate": 30 }, "destination_number": "xxxxxxxxx65", "caller_id_name": "xxxxxxxxx30", "caller_id_number": "xxxxxxxxx30", "callID": "e5e502f3-53ad-879e-bcf6-8e8ac38cbb98", "remote_caller_id_name": "Outbound Call", "remote_caller_id_number": "xxxxxxxxx65" }, "sessid": "9b3c8df0-00fc-9860-b7b6-60186ddd5071" }, "id": 56 }] 2016-03-03 08:01:52.810916 [DEBUG] mod_rtc.c:389 () State Change CS_NEW -> CS_INIT 2016-03-03 08:01:52.810916 [DEBUG] switch_core_session.c:613 N/A set UUID=e5e502f3-53ad-879e-bcf6-8e8ac38cbb98 2016-03-03 08:01:52.810916 [NOTICE] switch_channel.c:1091 New Channel verto.rtc/xxxxxxxxx65 [e5e502f3-53ad-879e-bcf6-8e8ac38cbb98] 2016-03-03 08:01:52.930847 [DEBUG] mod_verto.c:3553 Remote SDP verto.rtc/xxxxxxxxx65: v=0 o=- 6394623381710128159 2 IN IP4 127.0.0.1 s=- t=0 0 a=group:BUNDLE audio a=msid-semantic: WMS CL1gc0JpOcppsQ0KwbVTGs1EX0ooFmPQp4yc m=audio 52550 RTP/SAVPF 111 103 104 0 8 106 105 13 126 c=IN IP4 x.x.x.47 a=rtcp:52550 IN IP4 x.x.x.47 a=candidate:2608808550 1 udp 2122260223 192.168.1.33 52550 typ host generation 0 a=candidate:2608808550 2 udp 2122260223 192.168.1.33 52550 typ host generation 0 a=candidate:3590110870 1 tcp 1518280447 192.168.1.33 0 typ host tcptype active generation 0 a=candidate:3590110870 2 tcp 1518280447 192.168.1.33 0 typ host tcptype active generation 0 a=candidate:1836006322 1 udp 1686052607 x.x.x.47 52550 typ srflx raddr 192.168.1.33 rport 52550 generation 0 a=candidate:1836006322 2 udp 1686052607 x.x.x.47 52550 typ srflx raddr 192.168.1.33 rport 52550 generation 0 a=ice-ufrag:g/XzIwk/FmJyN58u a=ice-pwd:LIaaZisCkhtq5VHrFloGF8Zf a=ice-options:google-ice a=fingerprint:sha-256 D2:2D:74:F4:FF:10:85:48:FE:C6:B9:76:30:B9:06:B1:75:7C:C2:28:1E:CD:01:D5:9E:38:22:5E:AE:91:D7:3C a=setup:actpass a=mid:audio a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time a=sendrecv a=rtcp-mux a=rtpmap:111 opus/48000/2 a=fmtp:111 minptime=10; stereo=1 a=rtpmap:103 ISAC/16000 a=rtpmap:104 ISAC/32000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:106 CN/32000 a=rtpmap:105 CN/16000 a=rtpmap:13 CN/8000 a=rtpmap:126 telephone-event/8000 a=maxptime:60 a=ssrc:2908524814 cname:zrTZ84hefkswtwKu a=ssrc:2908524814 msid:CL1gc0JpOcppsQ0KwbVTGs1EX0ooFmPQp4yc 97fae677-74be-4b0a-b226-675b82268309 a=ssrc:2908524814 mslabel:CL1gc0JpOcppsQ0KwbVTGs1EX0ooFmPQp4yc a=ssrc:2908524814 label:97fae677-74be-4b0a-b226-675b82268309 2016-03-03 08:01:52.930847 [ALERT] mod_verto.c:604 WRITE x.x.x.47:45905 [{ "jsonrpc": "2.0", "id": 56, "result": { "message": "CALL CREATED", "callID": "e5e502f3-53ad-879e-bcf6-8e8ac38cbb98", "sessid": "9b3c8df0-00fc-9860-b7b6-60186ddd5071" } }] 2016-03-03 08:01:52.930847 [DEBUG] switch_core_state_machine.c:473 (verto.rtc/xxxxxxxxx65) Running State Change CS_INIT 2016-03-03 08:01:52.930847 [DEBUG] switch_core_state_machine.c:516 (verto.rtc/xxxxxxxxx65) State INIT 2016-03-03 08:01:52.930847 [DEBUG] switch_core_state_machine.c:40 verto.rtc/xxxxxxxxx65 Standard INIT 2016-03-03 08:01:52.930847 [DEBUG] switch_core_state_machine.c:48 (verto.rtc/xxxxxxxxx65) State Change CS_INIT -> CS_ROUTING 2016-03-03 08:01:52.930847 [DEBUG] switch_core_state_machine.c:516 (verto.rtc/xxxxxxxxx65) State INIT going to sleep 2016-03-03 08:01:52.930847 [DEBUG] switch_core_state_machine.c:473 (verto.rtc/xxxxxxxxx65) Running State Change CS_ROUTING 2016-03-03 08:01:52.930847 [DEBUG] switch_channel.c:2239 (verto.rtc/xxxxxxxxx65) Callstate Change DOWN -> RINGING 2016-03-03 08:01:52.930847 [DEBUG] switch_core_state_machine.c:532 (verto.rtc/xxxxxxxxx65) State ROUTING 2016-03-03 08:01:52.930847 [DEBUG] mod_rtc.c:89 verto.rtc/xxxxxxxxx65 RTC ROUTING 2016-03-03 08:01:52.930847 [DEBUG] switch_core_state_machine.c:166 verto.rtc/xxxxxxxxx65 Standard ROUTING 2016-03-03 08:01:52.930847 [INFO] mod_dialplan_xml.c:637 Processing xxxxxxxxx30 ->xxxxxxxxx65 in context default Dialplan: verto.rtc/xxxxxxxxx65 parsing [default->] continue=false Dialplan: verto.rtc/xxxxxxxxx65 Regex (PASS) [] destination_number(xxxxxxxxx65) =~ // break=on-false Dialplan: verto.rtc/xxxxxxxxx65 Action set(callstart=2016-03-03 06:01:53) Dialplan: verto.rtc/xxxxxxxxx65 Action set(call_processed=internal) Dialplan: verto.rtc/xxxxxxxxx65 Action set(originated_destination_number=xxxxxxxxx65) Dialplan: verto.rtc/xxxxxxxxx65 Action set(hangup_after_bridge=true) Dialplan: verto.rtc/xxxxxxxxx65 Action set(continue_on_fail=true) Dialplan: verto.rtc/xxxxxxxxx65 Action set(fax_enable_t38=true) Dialplan: verto.rtc/xxxxxxxxx65 Action set(fax_enable_t38_request=true) Dialplan: verto.rtc/xxxxxxxxx65 Action export(t38_passthru=true) Dialplan: verto.rtc/xxxxxxxxx65 Action set(absolute_codec_string='^^G729:PCMA:PCMU:opus') Dialplan: verto.rtc/xxxxxxxxx65 Action limit_execute(db Demo_xxxxxxxxx30 gw_Demo_xxxxxxxxx30 4 bridge {absolute_codec_string='^^G729:PCMA:PCMU:opus'}sofia/gateway/Demo_xxxxxxxxx30/xxxxxxxxx65) Dialplan: verto.rtc/xxxxxxxxx65 Action set(effective_destination_number=xxxxxxxxx65) Dialplan: verto.rtc/xxxxxxxxx65 Action set(absolute_codec_string='^^G729:PCMA:PCMU:opus') Dialplan: verto.rtc/xxxxxxxxx65 Action limit_execute(db Demo_xxxxxxxxx30 gw_Demo_xxxxxxxxx30 4 bridge {absolute_codec_string='^^G729:PCMA:PCMU:opus'}sofia/gateway/Demo_xxxxxxxxx30/xxxxxxxxx65) 2016-03-03 08:01:53.030847 [DEBUG] switch_core_state_machine.c:216 (verto.rtc/xxxxxxxxx65) State Change CS_ROUTING -> CS_EXECUTE 2016-03-03 08:01:53.030847 [DEBUG] switch_core_state_machine.c:532 (verto.rtc/xxxxxxxxx65) State ROUTING going to sleep 2016-03-03 08:01:53.030847 [DEBUG] switch_core_state_machine.c:473 (verto.rtc/xxxxxxxxx65) Running State Change CS_EXECUTE 2016-03-03 08:01:53.030847 [DEBUG] switch_core_state_machine.c:539 (verto.rtc/xxxxxxxxx65) State EXECUTE 2016-03-03 08:01:53.030847 [DEBUG] mod_rtc.c:120 verto.rtc/xxxxxxxxx65 RTC EXECUTE 2016-03-03 08:01:53.030847 [DEBUG] switch_core_state_machine.c:258 verto.rtc/xxxxxxxxx65 Standard EXECUTE EXECUTE verto.rtc/xxxxxxxxx65 set(callstart=2016-03-03 06:01:53) 2016-03-03 08:01:53.030847 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx65 [callstart]=[2016-03-03 06:01:53] EXECUTE verto.rtc/xxxxxxxxx65 set(call_processed=internal) 2016-03-03 08:01:53.030847 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx65 [call_processed]=[internal] EXECUTE verto.rtc/xxxxxxxxx65 set(originated_destination_number=xxxxxxxxx65) 2016-03-03 08:01:53.030847 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx65 [originated_destination_number]=[xxxxxxxxx65] EXECUTE verto.rtc/xxxxxxxxx65 set(hangup_after_bridge=true) 2016-03-03 08:01:53.030847 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx65 [hangup_after_bridge]=[true] EXECUTE verto.rtc/xxxxxxxxx65 set(continue_on_fail=true) 2016-03-03 08:01:53.030847 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx65 [continue_on_fail]=[true] EXECUTE verto.rtc/xxxxxxxxx65 set(fax_enable_t38=true) 2016-03-03 08:01:53.030847 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx65 [fax_enable_t38]=[true] EXECUTE verto.rtc/xxxxxxxxx65 set(fax_enable_t38_request=true) 2016-03-03 08:01:53.030847 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx65 [fax_enable_t38_request]=[true] EXECUTE verto.rtc/xxxxxxxxx65 export(t38_passthru=true) 2016-03-03 08:01:53.030847 [DEBUG] switch_channel.c:1283 EXPORT (export_vars) [t38_passthru]=[true] EXECUTE verto.rtc/xxxxxxxxx65 set(call_direction=outbound) 2016-03-03 08:01:53.030847 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx65 [call_direction]=[outbound] EXECUTE verto.rtc/xxxxxxxxx65 set(calltype=STANDARD) 2016-03-03 08:01:53.030847 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx65 [calltype]=[STANDARD] EXECUTE verto.rtc/xxxxxxxxx65 sched_hangup(+1440 allotted_timeout) 2016-03-03 08:01:53.030847 [DEBUG] switch_scheduler.c:249 Added task 107 switch_ivr_schedule_hangup (e5e502f3-53ad-879e-bcf6-8e8ac38cbb98) to run at 1456986353 EXECUTE verto.rtc/xxxxxxxxx65 set(absolute_codec_string='^^G729:PCMA:PCMU:opus') 2016-03-03 08:01:53.050843 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx65 [absolute_codec_string]=['^^G729:PCMA:PCMU:opus'] EXECUTE verto.rtc/xxxxxxxxx65 limit_execute(db Demo_xxxxxxxxx30 gw_Demo_xxxxxxxxx30 4 bridge {absolute_codec_string='^^G729:PCMA:PCMU:opus'}sofia/gateway/Demo_xxxxxxxxx30/xxxxxxxxx65) 2016-03-03 08:01:53.050843 [DEBUG] switch_limit.c:126 incr called: Demo_xxxxxxxxx30_gw_Demo_xxxxxxxxx30 max:4, interval:0 2016-03-03 08:01:53.050843 [DEBUG] mod_db.c:194 Usage for Demo_xxxxxxxxx30_gw_Demo_xxxxxxxxx30 is now 1/4 EXECUTE verto.rtc/xxxxxxxxx65 bridge({absolute_codec_string=^^G729:PCMA:PCMU:opus}sofia/gateway/Demo_xxxxxxxxx30/xxxxxxxxx65) 2016-03-03 08:01:53.050843 [DEBUG] switch_channel.c:1237 verto.rtc/xxxxxxxxx65 EXPORTING[export_vars] [t38_passthru]=[true] to event 2016-03-03 08:01:53.050843 [DEBUG] switch_ivr_originate.c:2127 Parsing global variables 2016-03-03 08:01:53.050843 [NOTICE] switch_channel.c:1091 New Channel sofia/default/xxxxxxxxx65 [de7384fd-8cf3-4b25-ab09-6d029f6b3c28] 2016-03-03 08:01:53.050843 [DEBUG] mod_sofia.c:4765 (sofia/default/xxxxxxxxx65) State Change CS_NEW -> CS_INIT 2016-03-03 08:01:53.050843 [DEBUG] switch_core_state_machine.c:473 (sofia/default/xxxxxxxxx65) Running State Change CS_INIT 2016-03-03 08:01:53.050843 [DEBUG] switch_core_state_machine.c:516 (sofia/default/xxxxxxxxx65) State INIT 2016-03-03 08:01:53.050843 [DEBUG] mod_sofia.c:88 sofia/default/xxxxxxxxx65 SOFIA INIT 2016-03-03 08:01:53.050843 [DEBUG] sofia_glue.c:1228 sip:x.x.x.91 Setting proxy route to sofia/default/xxxxxxxxx65 2016-03-03 08:01:53.050843 [DEBUG] sofia_glue.c:1257 sofia/default/xxxxxxxxx65 sending invite version: 1.6.5 64bit Local SDP: v=0 o=FreeSWITCH 1456966735 1456966736 IN IP4 x.x.x.88 s=FreeSWITCH c=IN IP4 x.x.x.88 t=0 0 2016-03-03 08:01:53.050843 [DEBUG] switch_core_state_machine.c:40 sofia/default/xxxxxxxxx65 Standard INIT 2016-03-03 08:01:53.050843 [DEBUG] switch_core_state_machine.c:48 (sofia/default/xxxxxxxxx65) State Change CS_INIT -> CS_ROUTING 2016-03-03 08:01:53.050843 [DEBUG] switch_core_state_machine.c:516 (sofia/default/xxxxxxxxx65) State INIT going to sleep 2016-03-03 08:01:53.050843 [DEBUG] switch_core_state_machine.c:473 (sofia/default/xxxxxxxxx65) Running State Change CS_ROUTING 2016-03-03 08:01:53.050843 [DEBUG] sofia.c:6750 Channel sofia/default/xxxxxxxxx65 entering state [calling][0] 2016-03-03 08:01:53.050843 [DEBUG] switch_core_state_machine.c:532 (sofia/default/xxxxxxxxx65) State ROUTING 2016-03-03 08:01:53.050843 [DEBUG] mod_sofia.c:141 sofia/default/xxxxxxxxx65 SOFIA ROUTING 2016-03-03 08:01:53.050843 [DEBUG] switch_ivr_originate.c:67 (sofia/default/xxxxxxxxx65) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2016-03-03 08:01:53.050843 [DEBUG] switch_core_state_machine.c:532 (sofia/default/xxxxxxxxx65) State ROUTING going to sleep 2016-03-03 08:01:53.050843 [DEBUG] switch_core_state_machine.c:473 (sofia/default/xxxxxxxxx65) Running State Change CS_CONSUME_MEDIA 2016-03-03 08:01:53.050843 [DEBUG] switch_core_state_machine.c:551 (sofia/default/xxxxxxxxx65) State CONSUME_MEDIA 2016-03-03 08:01:53.050843 [DEBUG] switch_core_state_machine.c:551 (sofia/default/xxxxxxxxx65) State CONSUME_MEDIA going to sleep 2016-03-03 08:01:53.070844 [DEBUG] sofia.c:6750 Channel sofia/default/xxxxxxxxx65 entering state [terminated][400] 2016-03-03 08:01:53.070844 [NOTICE] sofia.c:7769 Hangup sofia/default/xxxxxxxxx65 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE] 2016-03-03 08:01:53.070844 [DEBUG] switch_ivr_originate.c:3750 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE] 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:473 (sofia/default/xxxxxxxxx65) Running State Change CS_HANGUP 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:739 (sofia/default/xxxxxxxxx65) Callstate Change DOWN -> HANGUP 2016-03-03 08:01:53.070844 [INFO] mod_dptools.c:3379 Originate Failed. Cause: NORMAL_TEMPORARY_FAILURE 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:741 (sofia/default/xxxxxxxxx65) State HANGUP 2016-03-03 08:01:53.070844 [DEBUG] mod_sofia.c:431 Channel sofia/default/xxxxxxxxx65 hanging up, cause: NORMAL_TEMPORARY_FAILURE 2016-03-03 08:01:53.070844 [INFO] mod_dptools.c:4602 immediately releasing 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:60 sofia/default/xxxxxxxxx65 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:741 (sofia/default/xxxxxxxxx65) State HANGUP going to sleep 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:508 (sofia/default/xxxxxxxxx65) State Change CS_HANGUP -> CS_REPORTING 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:473 (sofia/default/xxxxxxxxx65) Running State Change CS_REPORTING 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:827 (sofia/default/xxxxxxxxx65) State REPORTING EXECUTE verto.rtc/xxxxxxxxx65 set(effective_destination_number=xxxxxxxxx65) 2016-03-03 08:01:53.070844 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx65 [effective_destination_number]=[xxxxxxxxx65] EXECUTE verto.rtc/xxxxxxxxx65 set(absolute_codec_string='^^G729:PCMA:PCMU:opus') 2016-03-03 08:01:53.070844 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx65 [absolute_codec_string]=['^^G729:PCMA:PCMU:opus'] EXECUTE verto.rtc/xxxxxxxxx65 limit_execute(db Demo_xxxxxxxxx30 gw_Demo_xxxxxxxxx30 4 bridge {absolute_codec_string='^^G729:PCMA:PCMU:opus'}sofia/gateway/Demo_xxxxxxxxx30/xxxxxxxxx65) 2016-03-03 08:01:53.070844 [DEBUG] switch_limit.c:126 incr called: Demo_xxxxxxxxx30_gw_Demo_xxxxxxxxx30 max:4, interval:0 2016-03-03 08:01:53.070844 [DEBUG] mod_db.c:194 Usage for Demo_xxxxxxxxx30_gw_Demo_xxxxxxxxx30 is now 1/4 EXECUTE verto.rtc/xxxxxxxxx65 bridge({absolute_codec_string=^^G729:PCMA:PCMU:opus}sofia/gateway/Demo_xxxxxxxxx30/xxxxxxxxx65) 2016-03-03 08:01:53.070844 [DEBUG] switch_channel.c:1237 verto.rtc/xxxxxxxxx65 EXPORTING[export_vars] [t38_passthru]=[true] to event 2016-03-03 08:01:53.070844 [DEBUG] switch_ivr_originate.c:2127 Parsing global variables 2016-03-03 08:01:53.070844 [NOTICE] switch_channel.c:1091 New Channel sofia/default/xxxxxxxxx65 [d197e1e0-daa2-45a0-88ac-a25c34802252] 2016-03-03 08:01:53.070844 [DEBUG] mod_sofia.c:4765 (sofia/default/xxxxxxxxx65) State Change CS_NEW -> CS_INIT 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:473 (sofia/default/xxxxxxxxx65) Running State Change CS_INIT 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:516 (sofia/default/xxxxxxxxx65) State INIT 2016-03-03 08:01:53.070844 [DEBUG] mod_sofia.c:88 sofia/default/xxxxxxxxx65 SOFIA INIT 2016-03-03 08:01:53.070844 [DEBUG] sofia_glue.c:1228 sip:x.x.x.91 Setting proxy route to sofia/default/xxxxxxxxx65 2016-03-03 08:01:53.070844 [DEBUG] sofia_glue.c:1257 sofia/default/xxxxxxxxx65 sending invite version: 1.6.5 64bit Local SDP: v=0 o=FreeSWITCH 1456966619 1456966620 IN IP4 x.x.x.88 s=FreeSWITCH c=IN IP4 x.x.x.88 t=0 0 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:40 sofia/default/xxxxxxxxx65 Standard INIT 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:48 (sofia/default/xxxxxxxxx65) State Change CS_INIT -> CS_ROUTING 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:516 (sofia/default/xxxxxxxxx65) State INIT going to sleep 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:473 (sofia/default/xxxxxxxxx65) Running State Change CS_ROUTING 2016-03-03 08:01:53.070844 [DEBUG] sofia.c:6750 Channel sofia/default/xxxxxxxxx65 entering state [calling][0] 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:532 (sofia/default/xxxxxxxxx65) State ROUTING 2016-03-03 08:01:53.070844 [DEBUG] mod_sofia.c:141 sofia/default/xxxxxxxxx65 SOFIA ROUTING 2016-03-03 08:01:53.070844 [DEBUG] switch_ivr_originate.c:67 (sofia/default/xxxxxxxxx65) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:532 (sofia/default/xxxxxxxxx65) State ROUTING going to sleep 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:473 (sofia/default/xxxxxxxxx65) Running State Change CS_CONSUME_MEDIA 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:551 (sofia/default/xxxxxxxxx65) State CONSUME_MEDIA 2016-03-03 08:01:53.070844 [DEBUG] switch_core_state_machine.c:551 (sofia/default/xxxxxxxxx65) State CONSUME_MEDIA going to sleep 2016-03-03 08:01:53.090844 [DEBUG] sofia.c:6750 Channel sofia/default/xxxxxxxxx65 entering state [terminated][400] 2016-03-03 08:01:53.090844 [NOTICE] sofia.c:7769 Hangup sofia/default/xxxxxxxxx65 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE] 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:473 (sofia/default/xxxxxxxxx65) Running State Change CS_HANGUP 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:739 (sofia/default/xxxxxxxxx65) Callstate Change DOWN -> HANGUP 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:741 (sofia/default/xxxxxxxxx65) State HANGUP 2016-03-03 08:01:53.090844 [DEBUG] mod_sofia.c:431 Channel sofia/default/xxxxxxxxx65 hanging up, cause: NORMAL_TEMPORARY_FAILURE 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:60 sofia/default/xxxxxxxxx65 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:741 (sofia/default/xxxxxxxxx65) State HANGUP going to sleep 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:508 (sofia/default/xxxxxxxxx65) State Change CS_HANGUP -> CS_REPORTING 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:473 (sofia/default/xxxxxxxxx65) Running State Change CS_REPORTING 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:827 (sofia/default/xxxxxxxxx65) State REPORTING 2016-03-03 08:01:53.090844 [DEBUG] switch_ivr_originate.c:3750 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE] 2016-03-03 08:01:53.090844 [INFO] mod_dptools.c:3379 Originate Failed. Cause: NORMAL_TEMPORARY_FAILURE 2016-03-03 08:01:53.090844 [INFO] mod_dptools.c:4602 immediately releasing 2016-03-03 08:01:53.090844 [NOTICE] switch_core_state_machine.c:315 verto.rtc/xxxxxxxxx65 has executed the last dialplan instruction, hanging up. 2016-03-03 08:01:53.090844 [NOTICE] switch_core_state_machine.c:317 Hangup verto.rtc/xxxxxxxxx65 [CS_EXECUTE] [NORMAL_CLEARING] 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:539 (verto.rtc/xxxxxxxxx65) State EXECUTE going to sleep 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:473 (verto.rtc/xxxxxxxxx65) Running State Change CS_HANGUP 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:739 (verto.rtc/xxxxxxxxx65) Callstate Change RINGING -> HANGUP 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:741 (verto.rtc/xxxxxxxxx65) State HANGUP 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:60 verto.rtc/xxxxxxxxx65 Standard HANGUP, cause: NORMAL_CLEARING 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:741 (verto.rtc/xxxxxxxxx65) State HANGUP going to sleep 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:508 (verto.rtc/xxxxxxxxx65) State Change CS_HANGUP -> CS_REPORTING 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:473 (verto.rtc/xxxxxxxxx65) Running State Change CS_REPORTING 2016-03-03 08:01:53.090844 [DEBUG] switch_core_state_machine.c:827 (verto.rtc/xxxxxxxxx65) State REPORTING 2016-03-03 08:01:53.130881 [ALERT] mod_verto.c:604 WRITE x.x.x.47:45905 [{ "jsonrpc": "2.0", "id": 77, "method": "verto.bye", "params": { "callID": "e5e502f3-53ad-879e-bcf6-8e8ac38cbb98", "causeCode": 16, "cause": "NORMAL_CLEARING" } }] 2016-03-03 08:01:53.330850 [DEBUG] switch_core_state_machine.c:104 sofia/default/xxxxxxxxx65 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2016-03-03 08:01:53.330850 [DEBUG] switch_core_state_machine.c:827 (sofia/default/xxxxxxxxx65) State REPORTING going to sleep 2016-03-03 08:01:53.330850 [DEBUG] switch_core_state_machine.c:499 (sofia/default/xxxxxxxxx65) State Change CS_REPORTING -> CS_DESTROY 2016-03-03 08:01:53.330850 [DEBUG] switch_core_session.c:1646 Session 224 (sofia/default/xxxxxxxxx65) Locked, Waiting on external entities 2016-03-03 08:01:53.330850 [NOTICE] switch_core_session.c:1664 Session 224 (sofia/default/xxxxxxxxx65) Ended 2016-03-03 08:01:53.330850 [NOTICE] switch_core_session.c:1668 Close Channel sofia/default/xxxxxxxxx65 [CS_DESTROY] 2016-03-03 08:01:53.330850 [DEBUG] switch_core_state_machine.c:630 (sofia/default/xxxxxxxxx65) Running State Change CS_DESTROY 2016-03-03 08:01:53.330850 [DEBUG] switch_core_state_machine.c:640 (sofia/default/xxxxxxxxx65) State DESTROY 2016-03-03 08:01:53.330850 [DEBUG] mod_sofia.c:341 sofia/default/xxxxxxxxx65 SOFIA DESTROY 2016-03-03 08:01:53.330850 [DEBUG] switch_core_state_machine.c:111 sofia/default/xxxxxxxxx65 Standard DESTROY 2016-03-03 08:01:53.330850 [DEBUG] switch_core_state_machine.c:640 (sofia/default/xxxxxxxxx65) State DESTROY going to sleep 2016-03-03 08:01:53.350903 [DEBUG] switch_core_state_machine.c:104 sofia/default/xxxxxxxxx65 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2016-03-03 08:01:53.350903 [DEBUG] switch_core_state_machine.c:827 (sofia/default/xxxxxxxxx65) State REPORTING going to sleep 2016-03-03 08:01:53.350903 [DEBUG] switch_core_state_machine.c:499 (sofia/default/xxxxxxxxx65) State Change CS_REPORTING -> CS_DESTROY 2016-03-03 08:01:53.350903 [DEBUG] switch_core_session.c:1646 Session 225 (sofia/default/xxxxxxxxx65) Locked, Waiting on external entities 2016-03-03 08:01:53.350903 [NOTICE] switch_core_session.c:1664 Session 225 (sofia/default/xxxxxxxxx65) Ended 2016-03-03 08:01:53.350903 [NOTICE] switch_core_session.c:1668 Close Channel sofia/default/xxxxxxxxx65 [CS_DESTROY] 2016-03-03 08:01:53.350903 [DEBUG] switch_core_state_machine.c:630 (sofia/default/xxxxxxxxx65) Running State Change CS_DESTROY 2016-03-03 08:01:53.350903 [DEBUG] switch_core_state_machine.c:640 (sofia/default/xxxxxxxxx65) State DESTROY 2016-03-03 08:01:53.350903 [DEBUG] mod_sofia.c:341 sofia/default/xxxxxxxxx65 SOFIA DESTROY 2016-03-03 08:01:53.350903 [DEBUG] switch_core_state_machine.c:111 sofia/default/xxxxxxxxx65 Standard DESTROY 2016-03-03 08:01:53.350903 [DEBUG] switch_core_state_machine.c:640 (sofia/default/xxxxxxxxx65) State DESTROY going to sleep 2016-03-03 08:01:53.370882 [DEBUG] switch_core_state_machine.c:104 verto.rtc/xxxxxxxxx65 Standard REPORTING, cause: NORMAL_CLEARING 2016-03-03 08:01:53.370882 [DEBUG] switch_core_state_machine.c:827 (verto.rtc/xxxxxxxxx65) State REPORTING going to sleep 2016-03-03 08:01:53.370882 [DEBUG] switch_core_state_machine.c:499 (verto.rtc/xxxxxxxxx65) State Change CS_REPORTING -> CS_DESTROY 2016-03-03 08:01:53.370882 [DEBUG] switch_core_session.c:1646 Session 223 (verto.rtc/xxxxxxxxx65) Locked, Waiting on external entities 2016-03-03 08:01:53.370882 [NOTICE] switch_core_session.c:1664 Session 223 (verto.rtc/xxxxxxxxx65) Ended 2016-03-03 08:01:53.370882 [NOTICE] switch_core_session.c:1668 Close Channel verto.rtc/xxxxxxxxx65 [CS_DESTROY] 2016-03-03 08:01:53.370882 [DEBUG] switch_core_state_machine.c:630 (verto.rtc/xxxxxxxxx65) Running State Change CS_DESTROY 2016-03-03 08:01:53.370882 [DEBUG] switch_core_state_machine.c:640 (verto.rtc/xxxxxxxxx65) State DESTROY 2016-03-03 08:01:53.370882 [DEBUG] mod_rtc.c:132 verto.rtc/xxxxxxxxx65 RTC DESTROY 2016-03-03 08:01:53.370882 [DEBUG] switch_core_state_machine.c:111 verto.rtc/xxxxxxxxx65 Standard DESTROY 2016-03-03 08:01:53.370882 [DEBUG] switch_core_state_machine.c:640 (verto.rtc/xxxxxxxxx65) State DESTROY going to sleep 2016-03-03 08:01:53.490915 [ALERT] mod_verto.c:1365 READ x.x.x.47:45905 [{ "jsonrpc": "2.0", "method": "verto.bye", "params": { "dialogParams": { "useVideo": false, "useStereo": true, "screenShare": false, "useCamera": "any", "useMic": "any", "useSpeak": "any", "tag": "webcam", "localTag": null, "login": "789789@x.x.x.91", "videoParams": { "minWidth": "1280", "minHeight": "720", "minFrameRate": 30 }, "destination_number": "xxxxxxxxx65", "caller_id_name": "xxxxxxxxx30", "caller_id_number": "xxxxxxxxx30", "callID": "e5e502f3-53ad-879e-bcf6-8e8ac38cbb98", "remote_caller_id_name": "Outbound Call", "remote_caller_id_number": "xxxxxxxxx65" }, "sessid": "9b3c8df0-00fc-9860-b7b6-60186ddd5071" }, "id": 57 }] 2016-03-03 08:01:53.490915 [ALERT] mod_verto.c:604 WRITE x.x.x.47:45905 [{ "jsonrpc": "2.0", "id": 57, "error": { "callID": "e5e502f3-53ad-879e-bcf6-8e8ac38cbb98", "message": "CALL DOES NOT EXIST", "code": -32002 } }] 2016-03-03 08:01:53.510839 [ALERT] mod_verto.c:1365 READ x.x.x.47:45905 [{ "jsonrpc": "2.0", "id": 77, "result": { "method": "verto.bye" } }] 2016-03-03 08:01:53.550886 [DEBUG] switch_scheduler.c:144 Deleting task 107 switch_ivr_schedule_hangup (e5e502f3-53ad-879e-bcf6-8e8ac38cbb98)