[Freeswitch-users] Call failed with mod_verto

bhavik patel bhavikpatel14388 at gmail.com
Thu Mar 3 10:09:27 MSK 2016


Hi All,

I have Freeswitch-1.6.5 running on Debian-8.2.

I want to use mod_verto for webrtc and followed steps mentioned at
https://freeswitch.org/confluence/display/FREESWITCH/mod_verto.
But calls are not working.

Outbound call fails with NORMAL_TEMPORARY_FAILURE.

When make inbound call it rings at destination and drops as soon as it
answer.

Here i am attaching logs for both type of calls.

Let me know if you require anything else from my end.



Thanks
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20160303/4dc49707/attachment-0001.html 
-------------- next part --------------
2016-03-03 07:46:12.710903 [ALERT] mod_verto.c:1365 READ x.x.x.47:53413 [{
	"jsonrpc":	"2.0",
	"method":	"verto.invite",
	"params":	{
		"sdp":	"v=0\r\no=- 6994444900162466811 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE audio\r\na=msid-semantic: WMS DjCUvVuYkcSSyzcDTHurGoyKwvu2rUtjU6eM\r\nm=audio 45441 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 126\r\nc=IN IP4 x.x.x.47\r\na=rtcp:34074 IN IP4 x.x.x.47\r\na=candidate:4106396162 1 udp 2122260223 192.168.1.39 45441 typ host generation 0\r\na=candidate:4106396162 2 udp 2122260222 192.168.1.39 34074 typ host generation 0\r\na=candidate:3124846322 1 tcp 1518280447 192.168.1.39 0 typ host tcptype active generation 0\r\na=candidate:3124846322 2 tcp 1518280446 192.168.1.39 0 typ host tcptype active generation 0\r\na=candidate:47373270 2 udp 1686052606 x.x.x.47 34074 typ srflx raddr 192.168.1.39 rport 34074 generation 0\r\na=candidate:47373270 1 udp 1686052607 x.x.x.47 45441 typ srflx raddr 192.168.1.39 rport 45441 generation 0\r\na=ice-ufrag:vhxQy5vdlAll+tmy\r\na=ice-pwd:VyA/8l9Dnx3mCkiFQ25qARKJ\r\na=fingerprint:sha-256 42:22:F0:A4:63:91:9F:F5:8F:55:94:8C:6C:10:77:EB:2A:C3:74:FC:F5:D5:FC:B1:AB:AF:4E:FD:69:F2:9B:5A\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; useinbandfec=1; stereo=1\r\na=rtpmap:103 ISAC/16000\r\na=rtpmap:104 ISAC/32000\r\na=rtpmap:9 G722/8000\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:4109156413 cname:YDTR1R8FHDG9qb2V\r\na=ssrc:4109156413 msid:DjCUvVuYkcSSyzcDTHurGoyKwvu2rUtjU6eM 675477fc-8790-43bb-af5e-a4faf5298a0e\r\na=ssrc:4109156413 mslabel:DjCUvVuYkcSSyzcDTHurGoyKwvu2rUtjU6eM\r\na=ssrc:4109156413 label:675477fc-8790-43bb-af5e-a4faf5298a0e\r\n",
		"dialogParams":	{
			"useVideo":	false,
			"useStereo":	true,
			"screenShare":	false,
			"useCamera":	"any",
			"useMic":	"any",
			"useSpeak":	"any",
			"tag":	"webcam",
			"localTag":	null,
			"login":	"456456 at x.x.x.91",
			"videoParams":	{
				"minWidth":	"1280",
				"minHeight":	"720",
				"minFrameRate":	30
			},
			"destination_number":	"xxxxxxxxx30",
			"caller_id_name":	"FreeSWITCH User",
			"caller_id_number":	"456456",
			"callID":	"25d59fdb-0aae-dd50-e15d-2a8ccef6bc64",
			"remote_caller_id_name":	"Outbound Call",
			"remote_caller_id_number":	"xxxxxxxxx30"
		},
		"sessid":	"c1ad8c94-e597-77f7-6818-8510c872ab35"
	},
	"id":	23
}]
2016-03-03 07:46:12.710903 [DEBUG] mod_rtc.c:389 () State Change CS_NEW -> CS_INIT
2016-03-03 07:46:12.710903 [DEBUG] switch_core_session.c:613 N/A set UUID=25d59fdb-0aae-dd50-e15d-2a8ccef6bc64
2016-03-03 07:46:12.710903 [NOTICE] switch_channel.c:1091 New Channel verto.rtc/xxxxxxxxx30 [25d59fdb-0aae-dd50-e15d-2a8ccef6bc64]
2016-03-03 07:46:12.810902 [DEBUG] mod_verto.c:3553 Remote SDP verto.rtc/xxxxxxxxx30:
v=0
o=- 6994444900162466811 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE audio
a=msid-semantic: WMS DjCUvVuYkcSSyzcDTHurGoyKwvu2rUtjU6eM
m=audio 45441 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 126
c=IN IP4 x.x.x.47
a=rtcp:34074 IN IP4 x.x.x.47
a=candidate:4106396162 1 udp 2122260223 192.168.1.39 45441 typ host generation 0
a=candidate:4106396162 2 udp 2122260222 192.168.1.39 34074 typ host generation 0
a=candidate:3124846322 1 tcp 1518280447 192.168.1.39 0 typ host tcptype active generation 0
a=candidate:3124846322 2 tcp 1518280446 192.168.1.39 0 typ host tcptype active generation 0
a=candidate:47373270 2 udp 1686052606 x.x.x.47 34074 typ srflx raddr 192.168.1.39 rport 34074 generation 0
a=candidate:47373270 1 udp 1686052607 x.x.x.47 45441 typ srflx raddr 192.168.1.39 rport 45441 generation 0
a=ice-ufrag:vhxQy5vdlAll+tmy
a=ice-pwd:VyA/8l9Dnx3mCkiFQ25qARKJ
a=fingerprint:sha-256 42:22:F0:A4:63:91:9F:F5:8F:55:94:8C:6C:10:77:EB:2A:C3:74:FC:F5:D5:FC:B1:AB:AF:4E:FD:69:F2:9B:5A
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; useinbandfec=1; stereo=1
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
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:4109156413 cname:YDTR1R8FHDG9qb2V
a=ssrc:4109156413 msid:DjCUvVuYkcSSyzcDTHurGoyKwvu2rUtjU6eM 675477fc-8790-43bb-af5e-a4faf5298a0e
a=ssrc:4109156413 mslabel:DjCUvVuYkcSSyzcDTHurGoyKwvu2rUtjU6eM
a=ssrc:4109156413 label:675477fc-8790-43bb-af5e-a4faf5298a0e

2016-03-03 07:46:12.810902 [ALERT] mod_verto.c:604 WRITE x.x.x.47:53413 [{
	"jsonrpc":	"2.0",
	"id":	23,
	"result":	{
		"message":	"CALL CREATED",
		"callID":	"25d59fdb-0aae-dd50-e15d-2a8ccef6bc64",
		"sessid":	"c1ad8c94-e597-77f7-6818-8510c872ab35"
	}
}]
2016-03-03 07:46:12.810902 [DEBUG] switch_core_state_machine.c:473 (verto.rtc/xxxxxxxxx30) Running State Change CS_INIT
2016-03-03 07:46:12.810902 [DEBUG] switch_core_state_machine.c:516 (verto.rtc/xxxxxxxxx30) State INIT
2016-03-03 07:46:12.810902 [DEBUG] switch_core_state_machine.c:40 verto.rtc/xxxxxxxxx30 Standard INIT
2016-03-03 07:46:12.810902 [DEBUG] switch_core_state_machine.c:48 (verto.rtc/xxxxxxxxx30) State Change CS_INIT -> CS_ROUTING
2016-03-03 07:46:12.810902 [DEBUG] switch_core_state_machine.c:516 (verto.rtc/xxxxxxxxx30) State INIT going to sleep
2016-03-03 07:46:12.810902 [DEBUG] switch_core_state_machine.c:473 (verto.rtc/xxxxxxxxx30) Running State Change CS_ROUTING
2016-03-03 07:46:12.810902 [DEBUG] switch_channel.c:2239 (verto.rtc/xxxxxxxxx30) Callstate Change DOWN -> RINGING
2016-03-03 07:46:12.810902 [DEBUG] switch_core_state_machine.c:532 (verto.rtc/xxxxxxxxx30) State ROUTING
2016-03-03 07:46:12.810902 [DEBUG] mod_rtc.c:89 verto.rtc/xxxxxxxxx30 RTC ROUTING
2016-03-03 07:46:12.810902 [DEBUG] switch_core_state_machine.c:166 verto.rtc/xxxxxxxxx30 Standard ROUTING
2016-03-03 07:46:12.810902 [INFO] mod_dialplan_xml.c:637 Processing FreeSWITCH User <456456>->xxxxxxxxx30 in context default
Dialplan: verto.rtc/xxxxxxxxx30 parsing [default->] continue=false
Dialplan: verto.rtc/xxxxxxxxx30 Regex (PASS) [] destination_number(xxxxxxxxx30) =~ // break=on-false
Dialplan: verto.rtc/xxxxxxxxx30 Action set(callstart=2016-03-03 05:46:12) 
Dialplan: verto.rtc/xxxxxxxxx30 Action set(call_processed=internal) 
Dialplan: verto.rtc/xxxxxxxxx30 Action set(originated_destination_number=xxxxxxxxx30) 
Dialplan: verto.rtc/xxxxxxxxx30 Action set(hangup_after_bridge=true) 
Dialplan: verto.rtc/xxxxxxxxx30 Action set(fax_enable_t38=true) 
Dialplan: verto.rtc/xxxxxxxxx30 Action set(fax_enable_t38_request=true) 
Dialplan: verto.rtc/xxxxxxxxx30 Action export(t38_passthru=true) 
Dialplan: verto.rtc/xxxxxxxxx30 Action set(call_direction=inbound) 
Dialplan: verto.rtc/xxxxxxxxx30 Action set(calltype=DID) 
Dialplan: verto.rtc/xxxxxxxxx30 Action sched_hangup(+6000 allotted_timeout) 
Dialplan: verto.rtc/xxxxxxxxx30 Action export(rtp_append_audio_sdp=a=fmtp:18 annexb=no) 
Dialplan: verto.rtc/xxxxxxxxx30 Action set(effective_destination_number=xxxxxxxxx30) 
Dialplan: verto.rtc/xxxxxxxxx30 Action limit(db xxxxxxxxx30 db_xxxxxxxxx30 3) 
Dialplan: verto.rtc/xxxxxxxxx30 Action set(hangup_after_bridge=true) 
Dialplan: verto.rtc/xxxxxxxxx30 Action set(continue_on_fail=true) 
Dialplan: verto.rtc/xxxxxxxxx30 Action export(absolute_codec_string=opus,G729,PCMA,PCMU) 
Dialplan: verto.rtc/xxxxxxxxx30 Action bridge({sip_invite_to_uri=<sip:xxxxxxx4444 at x.x.x.109:5062,sip_invite_req_uri=sip:xxxxxxx4444 at x.x.x.109:5062}sofia/default/sip:xxxxxxx4444 at x.x.x.109:5062;fs_path=sip%3Ax.x.x.91%3Blr%3Breceived%3Dsip%3Ax.x.x.109%3A5062) 
Dialplan: verto.rtc/xxxxxxxxx30 Action set(did_number=xxxxxxxxx30) 
Dialplan: verto.rtc/xxxxxxxxx30 Action set(dialed_user=xxxxxxx4444) 
2016-03-03 07:46:12.930846 [DEBUG] switch_core_state_machine.c:216 (verto.rtc/xxxxxxxxx30) State Change CS_ROUTING -> CS_EXECUTE
2016-03-03 07:46:12.930846 [DEBUG] switch_core_state_machine.c:532 (verto.rtc/xxxxxxxxx30) State ROUTING going to sleep
2016-03-03 07:46:12.930846 [DEBUG] switch_core_state_machine.c:473 (verto.rtc/xxxxxxxxx30) Running State Change CS_EXECUTE
2016-03-03 07:46:12.930846 [DEBUG] switch_core_state_machine.c:539 (verto.rtc/xxxxxxxxx30) State EXECUTE
2016-03-03 07:46:12.930846 [DEBUG] mod_rtc.c:120 verto.rtc/xxxxxxxxx30 RTC EXECUTE
2016-03-03 07:46:12.930846 [DEBUG] switch_core_state_machine.c:258 verto.rtc/xxxxxxxxx30 Standard EXECUTE
EXECUTE verto.rtc/xxxxxxxxx30 set(callstart=2016-03-03 05:46:12)
2016-03-03 07:46:12.930846 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx30 [callstart]=[2016-03-03 05:46:12]
EXECUTE verto.rtc/xxxxxxxxx30 set(call_processed=internal)
2016-03-03 07:46:12.930846 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx30 [call_processed]=[internal]
EXECUTE verto.rtc/xxxxxxxxx30 set(originated_destination_number=xxxxxxxxx30)
2016-03-03 07:46:12.930846 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx30 [originated_destination_number]=[xxxxxxxxx30]
EXECUTE verto.rtc/xxxxxxxxx30 set(hangup_after_bridge=true)
2016-03-03 07:46:12.930846 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx30 [hangup_after_bridge]=[true]
EXECUTE verto.rtc/xxxxxxxxx30 set(fax_enable_t38=true)
2016-03-03 07:46:12.930846 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx30 [fax_enable_t38]=[true]
EXECUTE verto.rtc/xxxxxxxxx30 set(fax_enable_t38_request=true)
2016-03-03 07:46:12.930846 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx30 [fax_enable_t38_request]=[true]
EXECUTE verto.rtc/xxxxxxxxx30 export(t38_passthru=true)
2016-03-03 07:46:12.930846 [DEBUG] switch_channel.c:1283 EXPORT (export_vars) [t38_passthru]=[true]
EXECUTE verto.rtc/xxxxxxxxx30 set(call_direction=inbound)
2016-03-03 07:46:12.930846 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx30 [call_direction]=[inbound]
EXECUTE verto.rtc/xxxxxxxxx30 set(calltype=DID)
2016-03-03 07:46:12.930846 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx30 [calltype]=[DID]
EXECUTE verto.rtc/xxxxxxxxx30 sched_hangup(+6000 allotted_timeout)
2016-03-03 07:46:12.930846 [DEBUG] switch_scheduler.c:249 Added task 103 switch_ivr_schedule_hangup (25d59fdb-0aae-dd50-e15d-2a8ccef6bc64) to run at 1456989972
EXECUTE verto.rtc/xxxxxxxxx30 export(rtp_append_audio_sdp=a=fmtp:18 annexb=no)
2016-03-03 07:46:12.930846 [DEBUG] switch_channel.c:1283 EXPORT (export_vars) [rtp_append_audio_sdp]=[a=fmtp:18 annexb=no]
EXECUTE verto.rtc/xxxxxxxxx30 set(effective_destination_number=xxxxxxxxx30)
2016-03-03 07:46:12.930846 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx30 [effective_destination_number]=[xxxxxxxxx30]
EXECUTE verto.rtc/xxxxxxxxx30 limit(db xxxxxxxxx30 db_xxxxxxxxx30 3)
2016-03-03 07:46:12.930846 [DEBUG] switch_limit.c:126 incr called: xxxxxxxxx30_db_xxxxxxxxx30 max:3, interval:0
2016-03-03 07:46:12.930846 [DEBUG] mod_db.c:194 Usage for xxxxxxxxx30_db_xxxxxxxxx30 is now 1/3
EXECUTE verto.rtc/xxxxxxxxx30 set(hangup_after_bridge=true)
2016-03-03 07:46:12.930846 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx30 [hangup_after_bridge]=[true]
EXECUTE verto.rtc/xxxxxxxxx30 set(continue_on_fail=true)
2016-03-03 07:46:12.930846 [DEBUG] mod_dptools.c:1498 SET verto.rtc/xxxxxxxxx30 [continue_on_fail]=[true]
EXECUTE verto.rtc/xxxxxxxxx30 export(absolute_codec_string=opus,G729,PCMA,PCMU)
2016-03-03 07:46:12.930846 [DEBUG] switch_channel.c:1283 EXPORT (export_vars) [absolute_codec_string]=[opus,G729,PCMA,PCMU]
EXECUTE verto.rtc/xxxxxxxxx30 bridge({sip_invite_to_uri=<sip:xxxxxxx4444 at x.x.x.109:5062,sip_invite_req_uri=sip:xxxxxxx4444 at x.x.x.109:5062}sofia/default/sip:xxxxxxx4444 at x.x.x.109:5062;fs_path=sip%3Ax.x.x.91%3Blr%3Breceived%3Dsip%3Ax.x.x.109%3A5062)
2016-03-03 07:46:12.930846 [DEBUG] switch_channel.c:1237 verto.rtc/xxxxxxxxx30 EXPORTING[export_vars] [t38_passthru]=[true] to event
2016-03-03 07:46:12.930846 [DEBUG] switch_channel.c:1237 verto.rtc/xxxxxxxxx30 EXPORTING[export_vars] [rtp_append_audio_sdp]=[a=fmtp:18 annexb=no] to event
2016-03-03 07:46:12.930846 [DEBUG] switch_channel.c:1237 verto.rtc/xxxxxxxxx30 EXPORTING[export_vars] [absolute_codec_string]=[opus,G729,PCMA,PCMU] to event
2016-03-03 07:46:12.930846 [DEBUG] switch_ivr_originate.c:2127 Parsing global variables
2016-03-03 07:46:12.930846 [NOTICE] switch_channel.c:1091 New Channel sofia/default/xxxxxxx4444 at x.x.x.109:5062 [4b4a0e3b-30cd-4b37-b0df-cc5bf693b7e6]
2016-03-03 07:46:12.930846 [DEBUG] mod_sofia.c:4765 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State Change CS_NEW -> CS_INIT
2016-03-03 07:46:12.930846 [DEBUG] switch_core_state_machine.c:473 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) Running State Change CS_INIT
2016-03-03 07:46:12.930846 [DEBUG] switch_core_state_machine.c:516 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State INIT
2016-03-03 07:46:12.930846 [DEBUG] mod_sofia.c:88 sofia/default/xxxxxxx4444 at x.x.x.109:5062 SOFIA INIT
2016-03-03 07:46:12.930846 [DEBUG] sofia_glue.c:1228 sip:x.x.x.91;lr;received=sip:x.x.x.109:5062 Setting proxy route to sofia/default/xxxxxxx4444 at x.x.x.109:5062
2016-03-03 07:46:12.930846 [DEBUG] sofia_glue.c:1257 sofia/default/xxxxxxx4444 at x.x.x.109:5062 sending invite version: 1.6.5  64bit
Local SDP:
v=0
o=FreeSWITCH 1456954140 1456954141 IN IP4 x.x.x.88
s=FreeSWITCH
c=IN IP4 x.x.x.88
t=0 0
m=audio 29832 RTP/AVP 111 18 8 0 102 101
a=rtpmap:111 opus/48000/2
a=fmtp:111 minptime=10; useinbandfec=1; stereo=1
a=rtpmap:18 G729/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:102 telephone-event/48000
a=fmtp:102 0-16
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=fmtp:18 annexb=no
a=ptime:20
a=sendrecv

2016-03-03 07:46:12.930846 [DEBUG] switch_core_state_machine.c:40 sofia/default/xxxxxxx4444 at x.x.x.109:5062 Standard INIT
2016-03-03 07:46:12.930846 [DEBUG] switch_core_state_machine.c:48 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State Change CS_INIT -> CS_ROUTING
2016-03-03 07:46:12.930846 [DEBUG] switch_core_state_machine.c:516 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State INIT going to sleep
2016-03-03 07:46:12.930846 [DEBUG] switch_core_state_machine.c:473 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) Running State Change CS_ROUTING
2016-03-03 07:46:12.930846 [DEBUG] sofia.c:6750 Channel sofia/default/xxxxxxx4444 at x.x.x.109:5062 entering state [calling][0]
2016-03-03 07:46:12.930846 [DEBUG] switch_core_state_machine.c:532 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State ROUTING
2016-03-03 07:46:12.930846 [DEBUG] mod_sofia.c:141 sofia/default/xxxxxxx4444 at x.x.x.109:5062 SOFIA ROUTING
2016-03-03 07:46:12.930846 [DEBUG] switch_ivr_originate.c:67 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2016-03-03 07:46:12.930846 [DEBUG] switch_core_state_machine.c:532 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State ROUTING going to sleep
2016-03-03 07:46:12.930846 [DEBUG] switch_core_state_machine.c:473 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) Running State Change CS_CONSUME_MEDIA
2016-03-03 07:46:12.930846 [DEBUG] switch_core_state_machine.c:551 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State CONSUME_MEDIA
2016-03-03 07:46:12.930846 [DEBUG] switch_core_state_machine.c:551 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State CONSUME_MEDIA going to sleep
2016-03-03 07:46:13.050889 [DEBUG] sofia.c:6750 Channel sofia/default/xxxxxxx4444 at x.x.x.109:5062 entering state [proceeding][180]
2016-03-03 07:46:13.050889 [NOTICE] sofia.c:6852 Ring-Ready sofia/default/xxxxxxx4444 at x.x.x.109:5062!
2016-03-03 07:46:13.050889 [DEBUG] switch_channel.c:3332 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) Callstate Change DOWN -> RINGING
2016-03-03 07:46:13.070897 [NOTICE] switch_ivr_originate.c:528 Ring Ready verto.rtc/xxxxxxxxx30!
2016-03-03 07:46:13.070897 [NOTICE] switch_ivr_originate.c:528 Ring-Ready verto.rtc/xxxxxxxxx30!
2016-03-03 07:46:17.770920 [DEBUG] sofia.c:6750 Channel sofia/default/xxxxxxx4444 at x.x.x.109:5062 entering state [completing][200]
2016-03-03 07:46:17.770920 [DEBUG] sofia.c:6760 Remote SDP:
v=0
o=- 20012 20012 IN IP4 x.x.x.109
s=SDP data
c=IN IP4 x.x.x.109
t=0 0
m=audio 11782 RTP/AVP 18 102
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:102 telephone-event/8000
a=fmtp:102 0-15
a=ptime:20

2016-03-03 07:46:17.770920 [DEBUG] sofia.c:6750 Channel sofia/default/xxxxxxx4444 at x.x.x.109:5062 entering state [ready][200]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4182 Bah HUMBUG! Sticking with G729 at 8000h@20i
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4208 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4069 Set telephone-event payload to 102 at 8000
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:2898 Set Codec sofia/default/xxxxxxx4444 at x.x.x.109:5062 G729/8000 20 ms 160 samples 8000 bits 1 channels
2016-03-03 07:46:17.790854 [DEBUG] switch_core_codec.c:111 sofia/default/xxxxxxx4444 at x.x.x.109:5062 Original read codec set to G729:18
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4417 Set telephone-event payload to 102 at 8000
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4473 sofia/default/xxxxxxx4444 at x.x.x.109:5062 Set 2833 dtmf send payload to 102 recv payload to 101
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:6027 AUDIO RTP [sofia/default/xxxxxxx4444 at x.x.x.109:5062] x.x.x.88 port 29832 -> x.x.x.109 port 11782 codec: 18 ms: 20
2016-03-03 07:46:17.790854 [DEBUG] switch_rtp.c:3788 Starting timer [soft] 160 bytes per 20ms
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:6326 sofia/default/xxxxxxx4444 at x.x.x.109:5062 Set 2833 dtmf send payload to 102
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:6333 sofia/default/xxxxxxx4444 at x.x.x.109:5062 Set 2833 dtmf receive payload to 101
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:6356 sofia/default/xxxxxxx4444 at x.x.x.109:5062 Set rtp dtmf delay to 40
2016-03-03 07:46:17.790854 [NOTICE] sofia.c:7714 Channel [sofia/default/xxxxxxx4444 at x.x.x.109:5062] has been answered
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [opus:111:48000:60:0:2]/[opus:116:48000:20:0:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4208 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [opus:111:48000:60:0:2]/[G729:18:8000:20:8000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [opus:111:48000:60:0:2]/[PCMA:8:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [opus:111:48000:60:0:2]/[PCMU:0:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[opus:116:48000:20:0:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[G729:18:8000:20:8000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMA:8:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMU:0:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[opus:116:48000:20:0:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[G729:18:8000:20:8000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMA:8:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMU:0:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [G722:9:8000:60:64000:1]/[opus:116:48000:20:0:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [G722:9:8000:60:64000:1]/[G729:18:8000:20:8000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [G722:9:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [G722:9:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[opus:116:48000:20:0:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[G729:18:8000:20:8000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [PCMU:0:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4208 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[opus:116:48000:20:0:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[G729:18:8000:20:8000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[PCMA:8:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4208 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [PCMA:8:8000:60:64000:1]/[PCMU:0:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [CN:106:32000:60:0:1]/[opus:116:48000:20:0:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [CN:106:32000:60:0:1]/[G729:18:8000:20:8000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [CN:106:32000:60:0:1]/[PCMA:8:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [CN:106:32000:60:0:1]/[PCMU:0:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [CN:105:16000:60:0:1]/[opus:116:48000:20:0:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [CN:105:16000:60:0:1]/[G729:18:8000:20:8000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [CN:105:16000:60:0:1]/[PCMA:8:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [CN:105:16000:60:0:1]/[PCMU:0:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [CN:13:8000:60:0:1]/[opus:116:48000:20:0:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [CN:13:8000:60:0:1]/[G729:18:8000:20:8000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [CN:13:8000:60:0:1]/[PCMA:8:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [CN:13:8000:60:0:1]/[PCMU:0:8000:20:64000:1]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4069 Set telephone-event payload to 126 at 8000
2016-03-03 07:46:17.790854 [DEBUG] mod_opus.c:559 Opus encoder: set bitrate to local settings [120000bps]
2016-03-03 07:46:17.790854 [DEBUG] mod_opus.c:559 Opus encoder: set bitrate to local settings [120000bps]
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:2898 Set Codec verto.rtc/xxxxxxxxx30 opus/48000 20 ms 960 samples 0 bits 2 channels
2016-03-03 07:46:17.790854 [DEBUG] switch_core_codec.c:111 verto.rtc/xxxxxxxxx30 Original read codec set to opus:116
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:3296 Save audio Candidate cid: 1 proto: udp type: host addr: 192.168.1.39:45441
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:3296 Save audio Candidate cid: 2 proto: udp type: host addr: 192.168.1.39:34074
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:3296 Save audio Candidate cid: 2 proto: udp type: srflx addr: x.x.x.47:34074
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:3296 Save audio Candidate cid: 1 proto: udp type: srflx addr: x.x.x.47:45441
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:3336 Searching for rtp candidate.
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:3341 Choose rtp candidate, index 1, x.x.x.47:45441
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:3127 verto.rtc/xxxxxxxxx30 choosing family v4
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:3352 Choose same candidate, index 2, for rtcp based on rtcp-mux attribute x.x.x.47:45441
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:3397 setting remote audio ice addr to index 1 x.x.x.47:45441 based on candidate
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:3418 Setting remote rtcp audio addr to x.x.x.47:45441 based on candidate
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:4473 verto.rtc/xxxxxxxxx30 Set 2833 dtmf send payload to 126 recv payload to 126
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:6027 AUDIO RTP [verto.rtc/xxxxxxxxx30] x.x.x.88 port 23278 -> x.x.x.47 port 45441 codec: 111 ms: 20
2016-03-03 07:46:17.790854 [DEBUG] switch_rtp.c:3788 Starting timer [soft] 960 bytes per 20ms
2016-03-03 07:46:17.790854 [INFO] switch_core_media.c:6202 Activating Audio ICE
2016-03-03 07:46:17.790854 [NOTICE] switch_rtp.c:4270 Activating RTP audio ICE: vhxQy5vdlAll+tmy:GokVq0hjtBlRqdQ7 x.x.x.47:45441
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:6245 Activating RTCP PORT 45441
2016-03-03 07:46:17.790854 [DEBUG] switch_rtp.c:4167 RTCP send rate is: 5000 and packet rate is: 20000 Remote Port: 45441
2016-03-03 07:46:17.790854 [INFO] switch_core_media.c:6253 Skipping RTCP ICE (Same as RTP)
2016-03-03 07:46:17.790854 [INFO] switch_rtp.c:3286 Activate RTP/RTCP audio DTLS client
2016-03-03 07:46:17.790854 [INFO] switch_rtp.c:3415 Changing audio DTLS state from OFF to HANDSHAKE
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:1939 Setting Jitterbuffer to 20ms (1 frames) (50 max frames)
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:6326 verto.rtc/xxxxxxxxx30 Set 2833 dtmf send payload to 126
2016-03-03 07:46:17.790854 [DEBUG] switch_core_media.c:6333 verto.rtc/xxxxxxxxx30 Set 2833 dtmf receive payload to 126
2016-03-03 07:46:17.790854 [DEBUG] mod_verto.c:2437 Local SDP verto.rtc/xxxxxxxxx30:
v=0
o=FreeSWITCH 1456960699 1456960700 IN IP4 x.x.x.88
s=FreeSWITCH
c=IN IP4 x.x.x.88
t=0 0
a=msid-semantic: WMS K2Lv9azp4XMvA3rW1FE1pbPv2CucyZ18
m=audio 23278 UDP/TLS/RTP/SAVPF 111 126
a=rtpmap:111 opus/48000/2
a=fmtp:111 useinbandfec=0; minptime=10; stereo=1
a=rtpmap:126 telephone-event/8000
a=silenceSupp:off - - - -
a=fmtp:18 annexb=no
a=ptime:20
a=sendrecv
a=fingerprint:sha-256 AC:05:AC:85:29:10:9B:21:01:B5:0C:36:78:36:F7:D3:F5:02:2E:DB:B1:7D:85:FE:52:D8:0D:B3:2E:05:F4:B5
a=setup:active
a=rtcp-mux
a=rtcp:23278 IN IP4 x.x.x.88
a=ice-ufrag:GokVq0hjtBlRqdQ7
a=ice-pwd:GaPaULzskjqMkb6QqhCG8JPr
a=candidate:4458760031 1 udp 659136 x.x.x.88 23278 typ host generation 0
a=ssrc:3806209908 cname:RDuRDT6yHJU8CbUt
a=ssrc:3806209908 msid:K2Lv9azp4XMvA3rW1FE1pbPv2CucyZ18 a0
a=ssrc:3806209908 mslabel:K2Lv9azp4XMvA3rW1FE1pbPv2CucyZ18
a=ssrc:3806209908 label:K2Lv9azp4XMvA3rW1FE1pbPv2CucyZ18a0

2016-03-03 07:46:17.790854 [NOTICE] switch_ivr_originate.c:3549 Channel [verto.rtc/xxxxxxxxx30] has been answered
EXECUTE verto.rtc/xxxxxxxxx30 record_session(/var/www/html/recording_files/4/25d59fdb-0aae-dd50-e15d-2a8ccef6bc64.wav)
2016-03-03 07:46:17.810838 [DEBUG] switch_core_media_bug.c:828 Attaching BUG to sofia/default/xxxxxxx4444 at x.x.x.109:5062
2016-03-03 07:46:17.810838 [DEBUG] switch_channel.c:3759 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) Callstate Change RINGING -> ACTIVE
2016-03-03 07:46:17.810838 [DEBUG] switch_core_media_bug.c:828 Attaching BUG to verto.rtc/xxxxxxxxx30
2016-03-03 07:46:17.810838 [DEBUG] switch_channel.c:3759 (verto.rtc/xxxxxxxxx30) Callstate Change RINGING -> ACTIVE
2016-03-03 07:46:17.810838 [DEBUG] switch_ivr_originate.c:3607 Originate Resulted in Success: [sofia/default/xxxxxxx4444 at x.x.x.109:5062]
2016-03-03 07:46:17.810838 [DEBUG] switch_core_media.c:9118 verto.rtc/xxxxxxxxx30 PAUSE Jitterbuffer
2016-03-03 07:46:17.830845 [DEBUG] switch_ivr_bridge.c:1591 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2016-03-03 07:46:17.830845 [DEBUG] switch_core_state_machine.c:473 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) Running State Change CS_EXCHANGE_MEDIA
2016-03-03 07:46:17.830845 [DEBUG] switch_core_state_machine.c:542 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State EXCHANGE_MEDIA
2016-03-03 07:46:17.830845 [DEBUG] mod_sofia.c:613 SOFIA EXCHANGE_MEDIA
2016-03-03 07:46:17.830845 [DEBUG] switch_ivr_async.c:1473 No silence detection configured; assuming start of speech
2016-03-03 07:46:17.830845 [DEBUG] switch_ivr_async.c:1473 No silence detection configured; assuming start of speech
2016-03-03 07:46:17.830845 [ALERT] mod_verto.c:604 WRITE x.x.x.47:53413 [{
	"jsonrpc":	"2.0",
	"id":	68,
	"method":	"verto.answer",
	"params":	{
		"callID":	"25d59fdb-0aae-dd50-e15d-2a8ccef6bc64",
		"sdp":	"v=0\no=FreeSWITCH 1456960699 1456960700 IN IP4 x.x.x.88\ns=FreeSWITCH\nc=IN IP4 x.x.x.88\nt=0 0\na=msid-semantic: WMS K2Lv9azp4XMvA3rW1FE1pbPv2CucyZ18\nm=audio 23278 UDP/TLS/RTP/SAVPF 111 126\na=rtpmap:111 opus/48000/2\na=fmtp:111 useinbandfec=0; minptime=10; stereo=1\na=rtpmap:126 telephone-event/8000\na=silenceSupp:off - - - -\na=fmtp:18 annexb=no\na=ptime:20\na=sendrecv\na=fingerprint:sha-256 AC:05:AC:85:29:10:9B:21:01:B5:0C:36:78:36:F7:D3:F5:02:2E:DB:B1:7D:85:FE:52:D8:0D:B3:2E:05:F4:B5\na=setup:active\na=rtcp-mux\na=rtcp:23278 IN IP4 x.x.x.88\na=ice-ufrag:GokVq0hjtBlRqdQ7\na=ice-pwd:GaPaULzskjqMkb6QqhCG8JPr\na=candidate:4458760031 1 udp 659136 x.x.x.88 23278 typ host generation 0\na=ssrc:3806209908 cname:RDuRDT6yHJU8CbUt\na=ssrc:3806209908 msid:K2Lv9azp4XMvA3rW1FE1pbPv2CucyZ18 a0\na=ssrc:3806209908 mslabel:K2Lv9azp4XMvA3rW1FE1pbPv2CucyZ18\na=ssrc:3806209908 label:K2Lv9azp4XMvA3rW1FE1pbPv2CucyZ18a0\n"
	}
}]
2016-03-03 07:46:17.830845 [ALERT] mod_verto.c:604 WRITE x.x.x.47:53413 [{
	"jsonrpc":	"2.0",
	"id":	69,
	"method":	"verto.display",
	"params":	{
		"callID":	"25d59fdb-0aae-dd50-e15d-2a8ccef6bc64",
		"display_name":	"Outbound Call",
		"display_number":	"xxxxxxx4444",
		"caller_id_name":	"FreeSWITCH User",
		"caller_id_number":	"456456",
		"callee_id_name":	"Outbound Call",
		"callee_id_number":	"xxxxxxx4444",
		"display_direction":	"inbound"
	}
}]
2016-03-03 07:46:17.870900 [DEBUG] sofia.c:6750 Channel sofia/default/xxxxxxx4444 at x.x.x.109:5062 entering state [calling][0]
2016-03-03 07:46:17.950897 [DEBUG] sofia.c:6750 Channel sofia/default/xxxxxxx4444 at x.x.x.109:5062 entering state [ready][200]
2016-03-03 07:46:17.950897 [DEBUG] sofia.c:6760 Remote SDP:
v=0
o=- 20012 20013 IN IP4 x.x.x.109
s=SDP data
c=IN IP4 x.x.x.109
t=0 0
m=audio 11782 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2016-03-03 07:46:17.950897 [DEBUG] switch_core_media.c:3966 Session is connected to a media bug. Re-Negotiation implicitly disabled.
2016-03-03 07:46:17.950897 [DEBUG] switch_core_media.c:4153 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
2016-03-03 07:46:17.950897 [DEBUG] switch_core_media.c:4182 Bah HUMBUG! Sticking with G729 at 8000h@20i
2016-03-03 07:46:17.950897 [DEBUG] switch_core_media.c:4208 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
2016-03-03 07:46:17.950897 [DEBUG] switch_core_media.c:4069 Set telephone-event payload to 101 at 8000
2016-03-03 07:46:17.950897 [DEBUG] switch_core_media.c:4417 Set telephone-event payload to 101 at 8000
2016-03-03 07:46:17.950897 [DEBUG] switch_core_media.c:4473 sofia/default/xxxxxxx4444 at x.x.x.109:5062 Set 2833 dtmf send payload to 101 recv payload to 101
2016-03-03 07:46:17.950897 [DEBUG] sofia.c:7557 Processing updated SDP
2016-03-03 07:46:17.950897 [DEBUG] switch_core_media.c:6010 Audio params are unchanged for sofia/default/xxxxxxx4444 at x.x.x.109:5062.
2016-03-03 07:46:18.130918 [DEBUG] switch_core_io.c:448 Setting BUG Codec G729:18
2016-03-03 07:46:18.130918 [INFO] mod_com_g729.c:164 DECODER LICENSE ALLOCATED--->0x7fd02403a1d0 0x7fd02403a1d8
2016-03-03 07:46:18.130918 [INFO] mod_com_g729.c:171 DECODER CREATED------------->0x7fd02403a1d0 0x7fd02403a1d8
2016-03-03 07:46:18.130918 [INFO] mod_com_g729.c:164 DECODER LICENSE ALLOCATED--->0x7fd03c02c6e8 0x7fd03c02c6f0
2016-03-03 07:46:18.130918 [INFO] mod_com_g729.c:171 DECODER CREATED------------->0x7fd03c02c6e8 0x7fd03c02c6f0
2016-03-03 07:46:18.130918 [NOTICE] switch_core_io.c:1191 Activating write resampler
2016-03-03 07:46:18.210913 [ALERT] mod_verto.c:1365 READ x.x.x.47:53413 [{
	"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":	"456456 at x.x.x.91",
			"videoParams":	{
				"minWidth":	"1280",
				"minHeight":	"720",
				"minFrameRate":	30
			},
			"destination_number":	"xxxxxxxxx30",
			"caller_id_name":	"FreeSWITCH User",
			"caller_id_number":	"456456",
			"callID":	"25d59fdb-0aae-dd50-e15d-2a8ccef6bc64",
			"remote_caller_id_name":	"Outbound Call",
			"remote_caller_id_number":	"xxxxxxxxx30"
		},
		"sessid":	"c1ad8c94-e597-77f7-6818-8510c872ab35"
	},
	"id":	24
}]
2016-03-03 07:46:18.210913 [NOTICE] mod_verto.c:2738 Hangup verto.rtc/xxxxxxxxx30 [CS_EXECUTE] [NORMAL_CLEARING]
2016-03-03 07:46:18.210913 [ALERT] mod_verto.c:604 WRITE x.x.x.47:53413 [{
	"jsonrpc":	"2.0",
	"id":	24,
	"result":	{
		"callID":	"25d59fdb-0aae-dd50-e15d-2a8ccef6bc64",
		"message":	"CALL ENDED",
		"causeCode":	16,
		"cause":	"NORMAL_CLEARING",
		"sessid":	"c1ad8c94-e597-77f7-6818-8510c872ab35"
	}
}]
2016-03-03 07:46:18.210913 [ALERT] mod_verto.c:1365 READ x.x.x.47:53413 [{
	"jsonrpc":	"2.0",
	"id":	69,
	"result":	{
		"method":	"verto.display"
	}
}]
2016-03-03 07:46:18.210913 [DEBUG] switch_ivr_bridge.c:705 verto.rtc/xxxxxxxxx30 ending bridge by request from read function
2016-03-03 07:46:18.210913 [DEBUG] switch_ivr_bridge.c:778 BRIDGE THREAD DONE [verto.rtc/xxxxxxxxx30]
2016-03-03 07:46:18.230880 [DEBUG] switch_ivr_bridge.c:699 verto.rtc/xxxxxxxxx30 ending bridge by request from write function
2016-03-03 07:46:18.230880 [DEBUG] switch_ivr_bridge.c:778 BRIDGE THREAD DONE [sofia/default/xxxxxxx4444 at x.x.x.109:5062]
2016-03-03 07:46:18.230880 [NOTICE] switch_ivr_bridge.c:881 Hangup sofia/default/xxxxxxx4444 at x.x.x.109:5062 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:542 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State EXCHANGE_MEDIA going to sleep
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:473 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) Running State Change CS_HANGUP
2016-03-03 07:46:18.230880 [DEBUG] switch_ivr_bridge.c:1689 sofia/default/xxxxxxx4444 at x.x.x.109:5062 skip receive message [UNBRIDGE] (channel is hungup already)
2016-03-03 07:46:18.230880 [DEBUG] switch_ivr_bridge.c:1692 verto.rtc/xxxxxxxxx30 skip receive message [UNBRIDGE] (channel is hungup already)
2016-03-03 07:46:18.230880 [DEBUG] switch_core_session.c:2796 verto.rtc/xxxxxxxxx30 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:539 (verto.rtc/xxxxxxxxx30) State EXECUTE going to sleep
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:473 (verto.rtc/xxxxxxxxx30) Running State Change CS_HANGUP
2016-03-03 07:46:18.230880 [DEBUG] switch_ivr_async.c:1356 Channel is hung up
2016-03-03 07:46:18.230880 [DEBUG] switch_core_media_bug.c:1118 Removing BUG from verto.rtc/xxxxxxxxx30
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:739 (verto.rtc/xxxxxxxxx30) Callstate Change ACTIVE -> HANGUP
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:741 (verto.rtc/xxxxxxxxx30) State HANGUP
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:60 verto.rtc/xxxxxxxxx30 Standard HANGUP, cause: NORMAL_CLEARING
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:741 (verto.rtc/xxxxxxxxx30) State HANGUP going to sleep
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:508 (verto.rtc/xxxxxxxxx30) State Change CS_HANGUP -> CS_REPORTING
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:473 (verto.rtc/xxxxxxxxx30) Running State Change CS_REPORTING
2016-03-03 07:46:18.230880 [DEBUG] switch_ivr_async.c:1356 Channel is hung up
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:827 (verto.rtc/xxxxxxxxx30) State REPORTING
2016-03-03 07:46:18.230880 [DEBUG] switch_core_media_bug.c:1118 Removing BUG from sofia/default/xxxxxxx4444 at x.x.x.109:5062
2016-03-03 07:46:18.230880 [INFO] mod_com_g729.c:95 DECODER DESTROYED----------->0x7fd02403a1d0 0x7fd02403a1d8
2016-03-03 07:46:18.230880 [INFO] mod_com_g729.c:98 DECODER LICENSE DEALLOCATED->0x7fd02403a1d0 0x7fd02403a1d8
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:739 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) Callstate Change ACTIVE -> HANGUP
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:741 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State HANGUP
2016-03-03 07:46:18.230880 [DEBUG] mod_sofia.c:431 Channel sofia/default/xxxxxxx4444 at x.x.x.109:5062 hanging up, cause: NORMAL_CLEARING
2016-03-03 07:46:18.230880 [DEBUG] mod_sofia.c:484 Sending BYE to sofia/default/xxxxxxx4444 at x.x.x.109:5062
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:60 sofia/default/xxxxxxx4444 at x.x.x.109:5062 Standard HANGUP, cause: NORMAL_CLEARING
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:741 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State HANGUP going to sleep
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:508 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State Change CS_HANGUP -> CS_REPORTING
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:473 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) Running State Change CS_REPORTING
2016-03-03 07:46:18.230880 [DEBUG] switch_core_state_machine.c:827 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State REPORTING
2016-03-03 07:46:18.490846 [DEBUG] switch_core_state_machine.c:104 sofia/default/xxxxxxx4444 at x.x.x.109:5062 Standard REPORTING, cause: NORMAL_CLEARING
2016-03-03 07:46:18.490846 [DEBUG] switch_core_state_machine.c:827 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State REPORTING going to sleep
2016-03-03 07:46:18.490846 [DEBUG] switch_core_state_machine.c:499 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State Change CS_REPORTING -> CS_DESTROY
2016-03-03 07:46:18.490846 [DEBUG] switch_core_session.c:1646 Session 211 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) Locked, Waiting on external entities
2016-03-03 07:46:18.490846 [NOTICE] switch_core_session.c:1664 Session 211 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) Ended
2016-03-03 07:46:18.490846 [NOTICE] switch_core_session.c:1668 Close Channel sofia/default/xxxxxxx4444 at x.x.x.109:5062 [CS_DESTROY]
2016-03-03 07:46:18.490846 [DEBUG] switch_core_state_machine.c:630 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) Running State Change CS_DESTROY
2016-03-03 07:46:18.490846 [DEBUG] switch_core_state_machine.c:640 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State DESTROY
2016-03-03 07:46:18.490846 [DEBUG] mod_sofia.c:341 sofia/default/xxxxxxx4444 at x.x.x.109:5062 SOFIA DESTROY
2016-03-03 07:46:18.490846 [INFO] mod_com_g729.c:95 DECODER DESTROYED----------->0x7fd03c02c6e8 0x7fd03c02c6f0
2016-03-03 07:46:18.490846 [INFO] mod_com_g729.c:98 DECODER LICENSE DEALLOCATED->0x7fd03c02c6e8 0x7fd03c02c6f0
2016-03-03 07:46:18.490846 [DEBUG] switch_core_state_machine.c:111 sofia/default/xxxxxxx4444 at x.x.x.109:5062 Standard DESTROY
2016-03-03 07:46:18.490846 [DEBUG] switch_core_state_machine.c:640 (sofia/default/xxxxxxx4444 at x.x.x.109:5062) State DESTROY going to sleep
2016-03-03 07:46:18.530852 [DEBUG] switch_core_state_machine.c:104 verto.rtc/xxxxxxxxx30 Standard REPORTING, cause: NORMAL_CLEARING
2016-03-03 07:46:18.530852 [DEBUG] switch_core_state_machine.c:827 (verto.rtc/xxxxxxxxx30) State REPORTING going to sleep
2016-03-03 07:46:18.530852 [DEBUG] switch_core_state_machine.c:499 (verto.rtc/xxxxxxxxx30) State Change CS_REPORTING -> CS_DESTROY
2016-03-03 07:46:18.530852 [DEBUG] switch_core_session.c:1646 Session 210 (verto.rtc/xxxxxxxxx30) Locked, Waiting on external entities
2016-03-03 07:46:18.530852 [NOTICE] switch_core_session.c:1664 Session 210 (verto.rtc/xxxxxxxxx30) Ended
2016-03-03 07:46:18.530852 [NOTICE] switch_core_session.c:1668 Close Channel verto.rtc/xxxxxxxxx30 [CS_DESTROY]
2016-03-03 07:46:18.530852 [DEBUG] switch_core_state_machine.c:630 (verto.rtc/xxxxxxxxx30) Running State Change CS_DESTROY
2016-03-03 07:46:18.530852 [DEBUG] switch_core_state_machine.c:640 (verto.rtc/xxxxxxxxx30) State DESTROY
2016-03-03 07:46:18.530852 [DEBUG] mod_rtc.c:132 verto.rtc/xxxxxxxxx30 RTC DESTROY
2016-03-03 07:46:18.530852 [DEBUG] mod_opus.c:661 Opus decoder stats: Frames[0] PLC[0] FEC[0]
2016-03-03 07:46:18.530852 [DEBUG] mod_opus.c:661 Opus decoder stats: Frames[0] PLC[0] FEC[0]
2016-03-03 07:46:18.530852 [DEBUG] switch_core_state_machine.c:111 verto.rtc/xxxxxxxxx30 Standard DESTROY
2016-03-03 07:46:18.530852 [DEBUG] switch_core_state_machine.c:640 (verto.rtc/xxxxxxxxx30) State DESTROY going to sleep
2016-03-03 07:46:18.930898 [DEBUG] switch_scheduler.c:144 Deleting task 103 switch_ivr_schedule_hangup (25d59fdb-0aae-dd50-e15d-2a8ccef6bc64)
-------------- next part --------------
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 at 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 <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 at 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)


Join us at ClueCon 2016 Aug 8-12, 2016
More information about the FreeSWITCH-users mailing list