[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Feb 19 01:04:14] DEBUG[8899][C-00008973] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, timer"
[Feb 19 01:04:14] DEBUG[8899][C-00008973] sip/reqresp_parser.c: Found SIP option: -replaces-
[Feb 19 01:04:14] DEBUG[8899][C-00008973] sip/reqresp_parser.c: Matched SIP option: replaces
[Feb 19 01:04:14] DEBUG[8899][C-00008973] sip/reqresp_parser.c: Found SIP option: -timer-
[Feb 19 01:04:14] DEBUG[8899][C-00008973] sip/reqresp_parser.c: Matched SIP option: timer
[Feb 19 01:04:14] DEBUG[8899][C-00008973] netsock2.c: Splitting '[trunk.ip]:5060' into...
[Feb 19 01:04:14] DEBUG[8899][C-00008973] netsock2.c: ...host '[trunk.ip]' and port '5060'.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] netsock2.c: Splitting '[trunk.ip]' into...
[Feb 19 01:04:14] DEBUG[8899][C-00008973] netsock2.c: ...host '[trunk.ip]' and port ''.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '[caller_num]' AND host = 'dynamic'
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '[caller_num]'
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE host = '[trunk.ip]' AND callbackextension = '[callee_num]' AND port = '5060'
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE host = '[trunk.ip]' AND port = '5060'
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE ipaddr = '[trunk.ip]' AND port = '5060'
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE host = '[trunk.ip]' AND insecure LIKE '%port%' ORDER BY host
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE ipaddr = '[trunk.ip]' ORDER BY ipaddr
[Feb 19 01:04:14] DEBUG[8899][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb00c11ab08'
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_rtp_asterisk.c: Allocated port 24330 for RTP instance '0x7fb00c11ab08'
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:24330 (24330) for RTP instance '0x7fb00c11ab08'
[Feb 19 01:04:14] DEBUG[8899][C-00008973] pjsip: 	icess0x7fb00c0 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:14] DEBUG[8899][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:14] DEBUG[8899][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] pjsip: 	icess0x7fb00c0 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:24330, base=[ast.srv.ip]:24330, prio=0x7effffff (2130706431)
[Feb 19 01:04:14] DEBUG[8899][C-00008973] rtp_engine.c: RTP instance '0x7fb00c11ab08' is setup and ready to go
[Feb 19 01:04:14] DEBUG[8899][C-00008973] pjsip: 	icess0x7fb00c0 Destroying ICE session 0x7fb00c0b3178
[Feb 19 01:04:14] DEBUG[8899][C-00008973] pjsip: 	stuse0x7fb00c0 STUN session 0x7fb00c08a818 destroy request, ref_cnt=4
[Feb 19 01:04:14] DEBUG[8899][C-00008973] pjsip: 	stuse0x7fb00c0 STUN session 0x7fb00c007c28 destroy request, ref_cnt=3
[Feb 19 01:04:14] DEBUG[8899][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb00c0b3178 destroyed
[Feb 19 01:04:14] DEBUG[8899][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb00c08a818 destroyed
[Feb 19 01:04:14] DEBUG[8899][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb00c007c28 destroyed
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb00c11ab08'
[Feb 19 01:04:14] VERBOSE[8899][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Setting NAT on RTP to Off
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Processing session-level SDP o=root 1464918821 1464918821 IN IP4 [trunk.ip]... OK.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Processing session-level SDP s=Asterisk PBX 1.8.32.1... UNSUPPORTED OR FAILED.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] netsock2.c: Splitting '[trunk.ip]' into...
[Feb 19 01:04:14] DEBUG[8899][C-00008973] netsock2.c: ...host '[trunk.ip]' and port ''.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Processing session-level SDP c=IN IP4 [trunk.ip]... OK.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7fb000142180
[Feb 19 01:04:14] DEBUG[8899][C-00008973] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fb000142180
[Feb 19 01:04:14] DEBUG[8899][C-00008973] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7fb000142180
[Feb 19 01:04:14] DEBUG[8899][C-00008973] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7fb000142180
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb00c11ab08'
[Feb 19 01:04:14] DEBUG[8899][C-00008973] rtp_engine.c: Copying payload 0 (0x7fb00c0e3720) from 0x7fb000142180 to 0x7fb00c11acd0
[Feb 19 01:04:14] DEBUG[8899][C-00008973] rtp_engine.c: Copying payload 8 (0x7fb00c0ceb60) from 0x7fb000142180 to 0x7fb00c11acd0
[Feb 19 01:04:14] DEBUG[8899][C-00008973] rtp_engine.c: Copying payload 18 (0x7fb00c089a10) from 0x7fb000142180 to 0x7fb00c11acd0
[Feb 19 01:04:14] DEBUG[8899][C-00008973] rtp_engine.c: Copying payload 101 (0x7fb00c08f2c0) from 0x7fb000142180 to 0x7fb00c11acd0
[Feb 19 01:04:14] DEBUG[8899][C-00008973] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fb00c11ab08'
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: We're settling with these formats: (alaw|ulaw)
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Checking SIP call limits for device 
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Updating call counter for incoming call
[Feb 19 01:04:14] DEBUG[8899][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:14] DEBUG[8899][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] netsock2.c: Splitting '[trunk.ip]' into...
[Feb 19 01:04:14] DEBUG[8899][C-00008973] netsock2.c: ...host '[trunk.ip]' and port ''.
[Feb 19 01:04:14] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [TRUNK_NAME]
[Feb 19 01:04:14] DEBUG[8870] chan_sip.c: Checking device state for peer [TRUNK_NAME]
[Feb 19 01:04:14] DEBUG[8870] devicestate.c: Changing state for SIP/[TRUNK_NAME] - state 2 (In use)
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Incoming INVITE with 'timer' option supported
[Feb 19 01:04:14] DEBUG[8928] app_queue.c: Device 'SIP/[TRUNK_NAME]' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Feb 19 01:04:14] VERBOSE[8873] cdr.c: 0x7fb03001be68 - Created CDR for channel SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:14] VERBOSE[8873] cdr.c: 0x7fb03001be68 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state NONE to Single
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: *** Our native formats are (alaw) 
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: *** Joint capabilities are (alaw|ulaw) 
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw 
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:14] DEBUG[8899][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:14] DEBUG[8899][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: SIP/[TRUNK_NAME]-0001f8dd: New call is still down.... Trying... 
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for [trunk.ip]:5060
[Feb 19 01:04:14] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [TRUNK_NAME]
[Feb 19 01:04:14] DEBUG[8870] chan_sip.c: Checking device state for peer [TRUNK_NAME]
[Feb 19 01:04:14] DEBUG[8870] devicestate.c: Changing state for SIP/[TRUNK_NAME] - state 2 (In use)
###############################################
SOME DIALPLAN STUFF OMITTED HERE
###############################################
[Feb 19 01:04:14] DEBUG[6569][C-00008973] pbx.c: Launching 'Answer'
[Feb 19 01:04:14] VERBOSE[8873] cdr.c: 0x7fb03001be68 - Set answered time to 1455829454.271882
[Feb 19 01:04:14] DEBUG[6569][C-00008973] chan_sip.c: SIP answering channel: SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:14] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting the marker bit due to a source update
[Feb 19 01:04:14] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [TRUNK_NAME]
[Feb 19 01:04:14] DEBUG[8870] chan_sip.c: Checking device state for peer [TRUNK_NAME]
[Feb 19 01:04:14] DEBUG[8870] devicestate.c: Changing state for SIP/[TRUNK_NAME] - state 2 (In use)
[Feb 19 01:04:14] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (alaw|ulaw) Video flag: True Text flag: True
[Feb 19 01:04:14] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (nothing) 
[Feb 19 01:04:14] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:14] DEBUG[6569][C-00008973] chan_sip.c: Setting framing on incoming call: 20
[Feb 19 01:04:14] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (alaw|ulaw)
[Feb 19 01:04:14] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for [trunk.ip]:5060
[Feb 19 01:04:14] DEBUG[6569][C-00008973] chan_sip.c: Session timer started: 19 - 698a1c3a6a67ad7e5dc218d678a63b32@[trunk.ip]:5060 900000ms
[Feb 19 01:04:14] DEBUG[8899] chan_sip.c: = Looking for  Call ID: 698a1c3a6a67ad7e5dc218d678a63b32@[trunk.ip]:5060 (Checking From) --From tag as53ffb64f --To-tag as3ddb9411  
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Feb 19 01:04:14] DEBUG[8899][C-00008973] chan_sip.c: Stopping retransmission on '698a1c3a6a67ad7e5dc218d678a63b32@[trunk.ip]:5060' of Response 102: Match Found
[Feb 19 01:04:14] DEBUG[6569][C-00008973] res_rtp_asterisk.c: 0x7fb00c03bef0 -- Probation learning mode pass with source address [trunk.ip]:14768
[Feb 19 01:04:14] DEBUG[6569][C-00008973] chan_sip.c: Oooh, format changed to ulaw
[Feb 19 01:04:14] DEBUG[6569][C-00008973] channel.c: Channel SIP/[TRUNK_NAME]-0001f8dd setting read format path: ulaw -> alaw
[Feb 19 01:04:14] DEBUG[6569][C-00008973] channel.c: Channel SIP/[TRUNK_NAME]-0001f8dd setting write format path: alaw -> ulaw
[Feb 19 01:04:14] DEBUG[6569][C-00008973] pbx.c: Launching 'Wait'
###############################################
SOME DIALPLAN STUFF OMITTED HERE
###############################################
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pbx.c: Launching 'Queue'
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] pbx.c: Executing [s@[COMPANY_NAME]_IVR:71] Queue("SIP/[TRUNK_NAME]-0001f8dd", "[COMPANY_NAME]") in new stack
[Feb 19 01:04:30] DEBUG[6569][C-00008973] app_queue.c: queue: [COMPANY_NAME], options: , url: , announce: , timeout: , agi: , macro: , gosub: , rule: , position: 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] app_queue.c: NO QUEUE_PRIO variable found. Using default.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] app_queue.c: queue: [COMPANY_NAME], expires: 0, priority: 0
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM queues WHERE name = '[COMPANY_NAME]'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM queue_members WHERE interface LIKE '%' AND queue_name = '[COMPANY_NAME]' ORDER BY interface
[Feb 19 01:04:30] DEBUG[6569][C-00008973] app_queue.c: min-announce-frequency=30 for queue '[COMPANY_NAME]'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-418 is available.
[Feb 19 01:04:30] DEBUG[8928] app_queue.c: Device 'Queue:[COMPANY_NAME]_avail' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] app_queue.c: Queue '[COMPANY_NAME]' Join, Channel 'SIP/[TRUNK_NAME]-0001f8dd', Position '1'
[Feb 19 01:04:30] DEBUG[8928] app_queue.c: Device 'Queue:[COMPANY_NAME]' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:30.681419', '', '', '1', '[caller_num]', '', 'ENTERQUEUE', 'NONE', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] res_musiconhold.c: Started music on hold, class '[COMPANY_NAME]', on channel 'SIP/[TRUNK_NAME]-0001f8dd'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Feb 19 01:04:30] DEBUG[6569][C-00008973] app_queue.c: There is 1 available member.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] app_queue.c: It's our turn (SIP/[TRUNK_NAME]-0001f8dd).
[Feb 19 01:04:30] DEBUG[6569][C-00008973] app_queue.c: SIP/[TRUNK_NAME]-0001f8dd is trying to call a queue member.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] app_queue.c: Trying 'SIP/[COMPANY_NAME]-418' with metric 0
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Allocating new SIP dialog for 1c901ffe78ef6d421c629bc2222fcfb4@[::1]:5060 - INVITE (No RTP)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Allocated port 25666 for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:25666 (25666) for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:30] DEBUG[6569][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:30] DEBUG[6569][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:25666, base=[ast.srv.ip]:25666, prio=0x7effffff (2130706431)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] rtp_engine.c: RTP instance '0x7fb05c0108d8' is setup and ready to go
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Destroying ICE session 0x7fb05c09c588
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c1 STUN session 0x7fb05c2c9bf8 destroy request, ref_cnt=4
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c062de8 destroy request, ref_cnt=3
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb05c09c588 destroyed
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c2c9bf8 destroyed
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c062de8 destroyed
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:30] DEBUG[6569][C-00008973] acl.c: For destination '[office.ip]', our source address is '[ast.srv.ip]'.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[6569][C-00008973] netsock2.c: Splitting '192.168.240.210:5073' into...
[Feb 19 01:04:30] DEBUG[6569][C-00008973] netsock2.c: ...host '192.168.240.210' and port '5073'.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: NAT detected for 192.168.240.210 / [office.ip]
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: SIP call-id changed from '1c901ffe78ef6d421c629bc2222fcfb4@[::1]:5060' to '6f351feb065e13d169a579a3076b13d5@[ast.srv.ip]:5061'
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Created CDR for channel SIP/[COMPANY_NAME]-418-0001f8de
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Transitioning CDR for SIP/[COMPANY_NAME]-418-0001f8de from state NONE to Single
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** Our native formats are (ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** Joint capabilities are (ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:30] DEBUG[6569][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 19 01:04:30] DEBUG[6569][C-00008973] channel_internal_api.c: Channel Call ID changing from [C-00008973] to [C-00008973]
[Feb 19 01:04:30] DEBUG[8899] chan_sip.c: Destroying SIP dialog 42b3643b5dff5cea09d1dc410fbffbf2@[ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Outgoing Call for [COMPANY_NAME]-418
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-418
[Feb 19 01:04:30] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-418
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-418 - state 6 (Ringing)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (ulaw|g722|alaw) Video flag: False Text flag: False
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (ulaw) 
[Feb 19 01:04:30] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-418' changed to state '6' (Ringing)
[Feb 19 01:04:30] DEBUG[8928] app_queue.c: Device 'Queue:[COMPANY_NAME]_avail' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] sdp_srtp.c: local_key64 KAESybndPtbglPEtlYBvJkbAW7EOF3LlxZTNM+KA len 40
[Feb 19 01:04:30] DEBUG[6569][C-00008973] sdp_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:KAESybndPtbglPEtlYBvJkbAW7EOF3LlxZTNM+KA
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722|alaw)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Initializing initreq for method INVITE - callid 6f351feb065e13d169a579a3076b13d5@[ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'INVITE sip:' onto TLS socket destined for [office.ip]:5073
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: Dial Begin message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-418-0001f8de: 1455829470.00696809
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] app_queue.c: Called SIP/[COMPANY_NAME]-418
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb03001be68 - Processing Dial Begin message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-418-0001f8de
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb03001be68 - Updated Party A SIP/[TRUNK_NAME]-0001f8dd snapshot
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb03001be68 - Updated Party B SIP/[COMPANY_NAME]-418-0001f8de snapshot
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb03001be68 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Single to Dial
[Feb 19 01:04:30] DEBUG[6569][C-00008973] channel.c: Channel SIP/[TRUNK_NAME]-0001f8dd setting write format path: slin16 -> ulaw
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_musiconhold.c: SIP/[TRUNK_NAME]-0001f8dd Opened file 0 '/var/lib/asterisk/moh/[COMPANY_NAME]/Billy Vaughn - Pearly Shell'
[Feb 19 01:04:30] DEBUG[23724] chan_sip.c: = Looking for  Call ID: 6f351feb065e13d169a579a3076b13d5@[ast.srv.ip]:5061 (Checking To) --From tag as2bca756c --To-tag   
[Feb 19 01:04:30] DEBUG[23724][C-00008973] chan_sip.c: SIP response 100 to standard invite
[Feb 19 01:04:30] DEBUG[23724] chan_sip.c: = Looking for  Call ID: 6f351feb065e13d169a579a3076b13d5@[ast.srv.ip]:5061 (Checking To) --From tag as2bca756c --To-tag d17727b963a111eai0  
[Feb 19 01:04:30] VERBOSE[23724][C-00008973] chan_sip.c: Got SIP response 486 "Busy Here" back from [office.ip]:5073
[Feb 19 01:04:30] DEBUG[23724][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:30] DEBUG[23724][C-00008973] chan_sip.c: Trying to put 'ACK sip:moz' onto TLS socket destined for [office.ip]:5073
[Feb 19 01:04:30] DEBUG[23724][C-00008973] chan_sip.c: Setting SIP_ALREADYGONE on dialog 6f351feb065e13d169a579a3076b13d5@[ast.srv.ip]:5061
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-418-0001f8de is busy
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: Dial End message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-418-0001f8de: 1455829470.00765664
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb03001be68 - Processing Dial End message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-418-0001f8de
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] app_queue.c: Nobody picked up in 0 ms
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb03001be68 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Dial to Finalized
[Feb 19 01:04:30] DEBUG[8873] cdr.c: Finalized CDR for SIP/[TRUNK_NAME]-0001f8dd - start 1455829454.257546 answer 1455829454.271882 end 1455829470.765697 dispo BUSY
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:30.765737', '', '', '', '', '0', 'RINGNOANSWER', 'SIP/[COMPANY_NAME]-418', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:30] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[COMPANY_NAME]-418-0001f8de'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[COMPANY_NAME]-418-0001f8de, SIP callid 6f351feb065e13d169a579a3076b13d5@[ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-418
[Feb 19 01:04:30] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-418
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-418 - state 1 (Not in use)
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Transitioning CDR for SIP/[COMPANY_NAME]-418-0001f8de from state Single to Finalized
[Feb 19 01:04:30] DEBUG[8873] cdr.c: Finalized CDR for SIP/[COMPANY_NAME]-418-0001f8de - start 1455829470.696558 answer 0.000000 end 1455829470.773088 dispo BUSY
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Beginning finalize/dispatch for SIP/[COMPANY_NAME]-418-0001f8de
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Dispatching CDR for Party A SIP/[COMPANY_NAME]-418-0001f8de, Party B <none>
[Feb 19 01:04:30] DEBUG[8873] cdr.c: CDR for SIP/[COMPANY_NAME]-418-0001f8de is dialed and has no Party B; discarding
[Feb 19 01:04:30] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-418' changed to state '1' (Not in use)
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-418
[Feb 19 01:04:30] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-418
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-418 - state 1 (Not in use)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] app_queue.c: Trying 'SIP/[COMPANY_NAME]-419' with metric 1
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Allocating new SIP dialog for 08403a5938e193f95a050f7d65e8c88f@[::1]:5060 - INVITE (No RTP)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Allocated port 29440 for RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:29440 (29440) for RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:30] DEBUG[6569][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:30] DEBUG[6569][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:29440, base=[ast.srv.ip]:29440, prio=0x7effffff (2130706431)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] rtp_engine.c: RTP instance '0x7fb05c14f6a8' is setup and ready to go
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Destroying ICE session 0x7fb05c09c588
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c2c9bf8 destroy request, ref_cnt=4
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c1ce2b8 destroy request, ref_cnt=3
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb05c09c588 destroyed
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c2c9bf8 destroyed
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c1ce2b8 destroyed
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:30] DEBUG[6569][C-00008973] acl.c: For destination '[office.ip]', our source address is '[ast.srv.ip]'.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[6569][C-00008973] netsock2.c: Splitting '192.168.240.208:5074' into...
[Feb 19 01:04:30] DEBUG[6569][C-00008973] netsock2.c: ...host '192.168.240.208' and port '5074'.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: NAT detected for 192.168.240.208 / [office.ip]
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: SIP call-id changed from '08403a5938e193f95a050f7d65e8c88f@[::1]:5060' to '1e4c506011a2fce27f6afc94555c0e4d@[ast.srv.ip]:5061'
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Created CDR for channel SIP/[COMPANY_NAME]-419-0001f8df
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Transitioning CDR for SIP/[COMPANY_NAME]-419-0001f8df from state NONE to Single
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** Our native formats are (ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** Joint capabilities are (ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:30] DEBUG[6569][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 19 01:04:30] DEBUG[6569][C-00008973] channel_internal_api.c: Channel Call ID changing from [C-00008973] to [C-00008973]
[Feb 19 01:04:30] DEBUG[8899] chan_sip.c: Destroying SIP dialog 6f351feb065e13d169a579a3076b13d5@[ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[8899] rtp_engine.c: Destroyed RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Outgoing Call for [COMPANY_NAME]-419
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-419
[Feb 19 01:04:30] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-419
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-419 - state 6 (Ringing)
[Feb 19 01:04:30] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-419' changed to state '6' (Ringing)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (ulaw|g722|alaw) Video flag: False Text flag: False
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] sdp_srtp.c: local_key64 nQAE3JvP/T30mtFhYiHRsTAyh4sqLp1kGMcPbYrl len 40
[Feb 19 01:04:30] DEBUG[6569][C-00008973] sdp_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:nQAE3JvP/T30mtFhYiHRsTAyh4sqLp1kGMcPbYrl
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722|alaw)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Initializing initreq for method INVITE - callid 1e4c506011a2fce27f6afc94555c0e4d@[ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'INVITE sip:' onto TLS socket destined for [office.ip]:5074
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: Dial Begin message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-419-0001f8df: 1455829470.00773930
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] app_queue.c: Called SIP/[COMPANY_NAME]-419
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030014e88 - Created CDR for channel SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030014e88 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state NONE to Single
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030014e88 - Set answered time to 1455829470.773944
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030014e88 - Updated Party A SIP/[TRUNK_NAME]-0001f8dd snapshot
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030014e88 - Updated Party B SIP/[COMPANY_NAME]-419-0001f8df snapshot
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030014e88 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Single to Dial
[Feb 19 01:04:30] DEBUG[23717] chan_sip.c: = Looking for  Call ID: 1e4c506011a2fce27f6afc94555c0e4d@[ast.srv.ip]:5061 (Checking To) --From tag as59c43d25 --To-tag   
[Feb 19 01:04:30] DEBUG[23717][C-00008973] chan_sip.c: SIP response 100 to standard invite
[Feb 19 01:04:30] DEBUG[23717] chan_sip.c: = Looking for  Call ID: 1e4c506011a2fce27f6afc94555c0e4d@[ast.srv.ip]:5061 (Checking To) --From tag as59c43d25 --To-tag 34390fdcc440b6i0  
[Feb 19 01:04:30] VERBOSE[23717][C-00008973] chan_sip.c: Got SIP response 486 "Busy Here" back from [office.ip]:5074
[Feb 19 01:04:30] DEBUG[23717][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:30] DEBUG[23717][C-00008973] chan_sip.c: Trying to put 'ACK sip:moz' onto TLS socket destined for [office.ip]:5074
[Feb 19 01:04:30] DEBUG[23717][C-00008973] chan_sip.c: Setting SIP_ALREADYGONE on dialog 1e4c506011a2fce27f6afc94555c0e4d@[ast.srv.ip]:5061
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-419-0001f8df is busy
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] app_queue.c: Nobody picked up in 0 ms
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: Dial End message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-419-0001f8df: 1455829470.00819339
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030014e88 - Processing Dial End message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-419-0001f8df
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030014e88 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Dial to Finalized
[Feb 19 01:04:30] DEBUG[8873] cdr.c: Finalized CDR for SIP/[TRUNK_NAME]-0001f8dd - start 1455829470.773944 answer 1455829470.773944 end 1455829470.819380 dispo BUSY
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:30.819396', '', '', '', '', '0', 'RINGNOANSWER', 'SIP/[COMPANY_NAME]-419', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:30] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[COMPANY_NAME]-419-0001f8df'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[COMPANY_NAME]-419-0001f8df, SIP callid 1e4c506011a2fce27f6afc94555c0e4d@[ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-419
[Feb 19 01:04:30] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-419
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-419 - state 1 (Not in use)
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Transitioning CDR for SIP/[COMPANY_NAME]-419-0001f8df from state Single to Finalized
[Feb 19 01:04:30] DEBUG[8873] cdr.c: Finalized CDR for SIP/[COMPANY_NAME]-419-0001f8df - start 1455829470.773528 answer 0.000000 end 1455829470.829577 dispo BUSY
[Feb 19 01:04:30] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-419' changed to state '1' (Not in use)
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Beginning finalize/dispatch for SIP/[COMPANY_NAME]-419-0001f8df
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Dispatching CDR for Party A SIP/[COMPANY_NAME]-419-0001f8df, Party B <none>
[Feb 19 01:04:30] DEBUG[8873] cdr.c: CDR for SIP/[COMPANY_NAME]-419-0001f8df is dialed and has no Party B; discarding
[Feb 19 01:04:30] DEBUG[6569][C-00008973] app_queue.c: Trying 'SIP/[COMPANY_NAME]-420' with metric 2
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-419
[Feb 19 01:04:30] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-419
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-419 - state 1 (Not in use)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Allocating new SIP dialog for 3d87a0fe2512d5914cd5452860dac961@[::1]:5060 - INVITE (No RTP)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb05c05f2d8'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Allocated port 26592 for RTP instance '0x7fb05c05f2d8'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:26592 (26592) for RTP instance '0x7fb05c05f2d8'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:30] DEBUG[6569][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:30] DEBUG[6569][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:26592, base=[ast.srv.ip]:26592, prio=0x7effffff (2130706431)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] rtp_engine.c: RTP instance '0x7fb05c05f2d8' is setup and ready to go
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Destroying ICE session 0x7fb05c09c588
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c2c9bf8 destroy request, ref_cnt=4
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c1 STUN session 0x7fb05c0acb08 destroy request, ref_cnt=3
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb05c09c588 destroyed
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c2c9bf8 destroyed
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c0acb08 destroyed
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb05c05f2d8'
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:30] DEBUG[6569][C-00008973] acl.c: For destination '[office.ip]', our source address is '[ast.srv.ip]'.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[6569][C-00008973] netsock2.c: Splitting '192.168.240.209:5062' into...
[Feb 19 01:04:30] DEBUG[6569][C-00008973] netsock2.c: ...host '192.168.240.209' and port '5062'.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: NAT detected for 192.168.240.209 / [office.ip]
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: SIP call-id changed from '3d87a0fe2512d5914cd5452860dac961@[::1]:5060' to '3aafee691f77cb1d4e03fcd562e0933d@[ast.srv.ip]:5061'
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030028708 - Created CDR for channel SIP/[COMPANY_NAME]-420-0001f8e0
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030028708 - Transitioning CDR for SIP/[COMPANY_NAME]-420-0001f8e0 from state NONE to Single
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** Our native formats are (ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** Joint capabilities are (ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:30] DEBUG[6569][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 19 01:04:30] DEBUG[6569][C-00008973] channel_internal_api.c: Channel Call ID changing from [C-00008973] to [C-00008973]
[Feb 19 01:04:30] DEBUG[8899] chan_sip.c: Destroying SIP dialog 1e4c506011a2fce27f6afc94555c0e4d@[ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[8899] rtp_engine.c: Destroyed RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Outgoing Call for [COMPANY_NAME]-420
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-420
[Feb 19 01:04:30] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-420
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-420 - state 6 (Ringing)
[Feb 19 01:04:30] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-420' changed to state '6' (Ringing)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (ulaw|g722|alaw) Video flag: False Text flag: False
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] sdp_srtp.c: local_key64 3PYKWUJEmsC0ZAYC0teGaqZaJuwkvk3HrKsw1+9Y len 40
[Feb 19 01:04:30] DEBUG[6569][C-00008973] sdp_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:3PYKWUJEmsC0ZAYC0teGaqZaJuwkvk3HrKsw1+9Y
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722|alaw)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Initializing initreq for method INVITE - callid 3aafee691f77cb1d4e03fcd562e0933d@[ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'INVITE sip:' onto TLS socket destined for [office.ip]:5062
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] app_queue.c: Called SIP/[COMPANY_NAME]-420
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: Dial Begin message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-420-0001f8e0: 1455829470.00830270
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030004a58 - Created CDR for channel SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030004a58 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state NONE to Single
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030004a58 - Set answered time to 1455829470.830287
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030004a58 - Updated Party A SIP/[TRUNK_NAME]-0001f8dd snapshot
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030004a58 - Updated Party B SIP/[COMPANY_NAME]-420-0001f8e0 snapshot
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030004a58 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Single to Dial
##################################################
SOME PROBABLY UNRELATED DEBUG DATA REMOVED HERE
##################################################
[Feb 19 01:04:30] DEBUG[23726] chan_sip.c: = Looking for  Call ID: 3aafee691f77cb1d4e03fcd562e0933d@[ast.srv.ip]:5061 (Checking To) --From tag as63b69235 --To-tag   
[Feb 19 01:04:30] DEBUG[23726][C-00008973] chan_sip.c: SIP response 100 to standard invite
[Feb 19 01:04:30] DEBUG[23726] chan_sip.c: = Looking for  Call ID: 3aafee691f77cb1d4e03fcd562e0933d@[ast.srv.ip]:5061 (Checking To) --From tag as63b69235 --To-tag 156a27e5d9c82f6ai0  
[Feb 19 01:04:30] VERBOSE[23726][C-00008973] chan_sip.c: Got SIP response 486 "Busy Here" back from [office.ip]:5062
[Feb 19 01:04:30] DEBUG[23726][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c05f2d8'
[Feb 19 01:04:30] DEBUG[23726][C-00008973] chan_sip.c: Trying to put 'ACK sip:moz' onto TLS socket destined for [office.ip]:5062
[Feb 19 01:04:30] DEBUG[23726][C-00008973] chan_sip.c: Setting SIP_ALREADYGONE on dialog 3aafee691f77cb1d4e03fcd562e0933d@[ast.srv.ip]:5061
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-420-0001f8e0 is busy
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: Dial End message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-420-0001f8e0: 1455829470.00881168
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] app_queue.c: Nobody picked up in 0 ms
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030004a58 - Processing Dial End message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-420-0001f8e0
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030004a58 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Dial to Finalized
[Feb 19 01:04:30] DEBUG[8873] cdr.c: Finalized CDR for SIP/[TRUNK_NAME]-0001f8dd - start 1455829470.830286 answer 1455829470.830287 end 1455829470.881200 dispo BUSY
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:30.881240', '', '', '', '', '0', 'RINGNOANSWER', 'SIP/[COMPANY_NAME]-420', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:30] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[COMPANY_NAME]-420-0001f8e0'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[COMPANY_NAME]-420-0001f8e0, SIP callid 3aafee691f77cb1d4e03fcd562e0933d@[ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c05f2d8'
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-420
[Feb 19 01:04:30] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-420
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-420 - state 1 (Not in use)
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030028708 - Transitioning CDR for SIP/[COMPANY_NAME]-420-0001f8e0 from state Single to Finalized
[Feb 19 01:04:30] DEBUG[8873] cdr.c: Finalized CDR for SIP/[COMPANY_NAME]-420-0001f8e0 - start 1455829470.830003 answer 0.000000 end 1455829470.889634 dispo BUSY
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030028708 - Beginning finalize/dispatch for SIP/[COMPANY_NAME]-420-0001f8e0
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030028708 - Dispatching CDR for Party A SIP/[COMPANY_NAME]-420-0001f8e0, Party B <none>
[Feb 19 01:04:30] DEBUG[8873] cdr.c: CDR for SIP/[COMPANY_NAME]-420-0001f8e0 is dialed and has no Party B; discarding
[Feb 19 01:04:30] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-420' changed to state '1' (Not in use)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] app_queue.c: Trying 'SIP/[COMPANY_NAME]-421' with metric 3
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-420
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Feb 19 01:04:30] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-420
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-420 - state 1 (Not in use)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Allocating new SIP dialog for 323cc2686b9227f922d7d92855cc42ed@[::1]:5060 - INVITE (No RTP)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Allocated port 29058 for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:29058 (29058) for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:30] DEBUG[6569][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:30] DEBUG[6569][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:29058, base=[ast.srv.ip]:29058, prio=0x7effffff (2130706431)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] rtp_engine.c: RTP instance '0x7fb05c0108d8' is setup and ready to go
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Destroying ICE session 0x7fb05c09c588
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c1 STUN session 0x7fb05c2c9bf8 destroy request, ref_cnt=4
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c023928 destroy request, ref_cnt=3
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb05c09c588 destroyed
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c2c9bf8 destroyed
[Feb 19 01:04:30] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c023928 destroyed
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:30] DEBUG[6569][C-00008973] acl.c: For destination '[office.ip]', our source address is '[ast.srv.ip]'.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[6569][C-00008973] netsock2.c: Splitting '192.168.240.207:5060' into...
[Feb 19 01:04:30] DEBUG[6569][C-00008973] netsock2.c: ...host '192.168.240.207' and port '5060'.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: NAT detected for 192.168.240.207 / [office.ip]
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: SIP call-id changed from '323cc2686b9227f922d7d92855cc42ed@[::1]:5060' to '2e4aacb76091847b2f9578196a999b30@[ast.srv.ip]:5061'
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030000c58 - Created CDR for channel SIP/[COMPANY_NAME]-421-0001f8e1
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030000c58 - Transitioning CDR for SIP/[COMPANY_NAME]-421-0001f8e1 from state NONE to Single
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** Our native formats are (ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** Joint capabilities are (ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:30] DEBUG[6569][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 19 01:04:30] DEBUG[6569][C-00008973] channel_internal_api.c: Channel Call ID changing from [C-00008973] to [C-00008973]
[Feb 19 01:04:30] DEBUG[8899] chan_sip.c: Destroying SIP dialog 028ceba612fe5a83138fe5782aab894b@[ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[8899] chan_sip.c: Destroying SIP dialog 3aafee691f77cb1d4e03fcd562e0933d@[ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[8899] rtp_engine.c: Destroyed RTP instance '0x7fb05c05f2d8'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Outgoing Call for [COMPANY_NAME]-421
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-421
[Feb 19 01:04:30] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-421
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-421 - state 6 (Ringing)
[Feb 19 01:04:30] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-421' changed to state '6' (Ringing)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (ulaw|g722|alaw) Video flag: False Text flag: False
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (ulaw) 
[Feb 19 01:04:30] DEBUG[6569][C-00008973] sdp_srtp.c: local_key64 K48bNfgbJiFHRmI6thuEmC0SIhqLswKCIYw5Ci2V len 40
[Feb 19 01:04:30] DEBUG[6569][C-00008973] sdp_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:K48bNfgbJiFHRmI6thuEmC0SIhqLswKCIYw5Ci2V
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722|alaw)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Initializing initreq for method INVITE - callid 2e4aacb76091847b2f9578196a999b30@[ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'INVITE sip:' onto TLS socket destined for [office.ip]:27493
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] app_queue.c: Called SIP/[COMPANY_NAME]-421
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: Dial Begin message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-421-0001f8e1: 1455829470.00890251
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030005298 - Created CDR for channel SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030005298 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state NONE to Single
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030005298 - Set answered time to 1455829470.890268
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030005298 - Updated Party A SIP/[TRUNK_NAME]-0001f8dd snapshot
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030005298 - Updated Party B SIP/[COMPANY_NAME]-421-0001f8e1 snapshot
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030005298 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Single to Dial
[Feb 19 01:04:30] DEBUG[23714] chan_sip.c: = Looking for  Call ID: 2e4aacb76091847b2f9578196a999b30@[ast.srv.ip]:5061 (Checking To) --From tag as55c743f1 --To-tag   
[Feb 19 01:04:30] DEBUG[23714][C-00008973] chan_sip.c: SIP response 100 to standard invite
[Feb 19 01:04:30] DEBUG[23714] chan_sip.c: = Looking for  Call ID: 2e4aacb76091847b2f9578196a999b30@[ast.srv.ip]:5061 (Checking To) --From tag as55c743f1 --To-tag fca68fc88e789dai0  
[Feb 19 01:04:30] VERBOSE[23714][C-00008973] chan_sip.c: Got SIP response 486 "Busy Here" back from [office.ip]:27493
[Feb 19 01:04:30] DEBUG[23714][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:30] DEBUG[23714][C-00008973] chan_sip.c: Trying to put 'ACK sip:moz' onto TLS socket destined for [office.ip]:27493
[Feb 19 01:04:30] DEBUG[23714][C-00008973] chan_sip.c: Setting SIP_ALREADYGONE on dialog 2e4aacb76091847b2f9578196a999b30@[ast.srv.ip]:5061
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-421-0001f8e1 is busy
[Feb 19 01:04:30] VERBOSE[6569][C-00008973] app_queue.c: Nobody picked up in 0 ms
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: Dial End message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-421-0001f8e1: 1455829470.00924027
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030005298 - Processing Dial End message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-421-0001f8e1
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030005298 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Dial to Finalized
[Feb 19 01:04:30] DEBUG[8873] cdr.c: Finalized CDR for SIP/[TRUNK_NAME]-0001f8dd - start 1455829470.890268 answer 1455829470.890268 end 1455829470.924069 dispo BUSY
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:30.924085', '', '', '', '', '0', 'RINGNOANSWER', 'SIP/[COMPANY_NAME]-421', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:30] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[COMPANY_NAME]-421-0001f8e1'
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[COMPANY_NAME]-421-0001f8e1, SIP callid 2e4aacb76091847b2f9578196a999b30@[ast.srv.ip]:5061
[Feb 19 01:04:30] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-421
[Feb 19 01:04:30] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-421
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-421 - state 1 (Not in use)
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030000c58 - Transitioning CDR for SIP/[COMPANY_NAME]-421-0001f8e1 from state Single to Finalized
[Feb 19 01:04:30] DEBUG[8873] cdr.c: Finalized CDR for SIP/[COMPANY_NAME]-421-0001f8e1 - start 1455829470.889998 answer 0.000000 end 1455829470.931510 dispo BUSY
[Feb 19 01:04:30] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-421' changed to state '1' (Not in use)
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030000c58 - Beginning finalize/dispatch for SIP/[COMPANY_NAME]-421-0001f8e1
[Feb 19 01:04:30] VERBOSE[8873] cdr.c: 0x7fb030000c58 - Dispatching CDR for Party A SIP/[COMPANY_NAME]-421-0001f8e1, Party B <none>
[Feb 19 01:04:30] DEBUG[8873] cdr.c: CDR for SIP/[COMPANY_NAME]-421-0001f8e1 is dialed and has no Party B; discarding
[Feb 19 01:04:30] DEBUG[6569][C-00008973] app_queue.c: Nobody left to try ringing in queue
[Feb 19 01:04:30] DEBUG[6569][C-00008973] app_queue.c: Everyone is busy at this time
[Feb 19 01:04:30] DEBUG[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-418 is available.
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-421
[Feb 19 01:04:30] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-421
[Feb 19 01:04:30] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-421 - state 1 (Not in use)
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:30] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM queue_members WHERE interface LIKE '%' AND queue_name = '[COMPANY_NAME]' ORDER BY interface
##################################################
SOME PROBABLY UNRELATED DEBUG DATA REMOVED HERE
##################################################
[Feb 19 01:04:35] DEBUG[6569][C-00008973] app_queue.c: There is 1 available member.
[Feb 19 01:04:35] DEBUG[6569][C-00008973] app_queue.c: It's our turn (SIP/[TRUNK_NAME]-0001f8dd).
[Feb 19 01:04:35] VERBOSE[6569][C-00008973] res_musiconhold.c: Stopped music on hold on SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:35] DEBUG[6569][C-00008973] channel.c: Channel SIP/[TRUNK_NAME]-0001f8dd setting write format path: alaw -> ulaw
[Feb 19 01:04:35] DEBUG[6569][C-00008973] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 19 01:04:35] DEBUG[6569][C-00008973] channel.c: Channel SIP/[TRUNK_NAME]-0001f8dd setting write format path: slin16 -> ulaw
[Feb 19 01:04:35] DEBUG[6569][C-00008973] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Feb 19 01:04:35] VERBOSE[6569][C-00008973] file.c: <SIP/[TRUNK_NAME]-0001f8dd> Playing 'queue-youarenext.slin16' (language 'ka/[COMPANY_NAME]')
##################################################
SOME PROBABLY UNRELATED DEBUG DATA REMOVED HERE
##################################################
[Feb 19 01:04:39] DEBUG[6569][C-00008973] channel.c: Scheduling timer at (1333 requested / 1000 actual) timer ticks per second
[Feb 19 01:04:39] DEBUG[6569][C-00008973] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 19 01:04:39] DEBUG[6569][C-00008973] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 19 01:04:39] DEBUG[6569][C-00008973] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 19 01:04:39] DEBUG[6569][C-00008973] channel.c: Channel SIP/[TRUNK_NAME]-0001f8dd setting write format path: alaw -> ulaw
[Feb 19 01:04:39] VERBOSE[6569][C-00008973] app_queue.c: Told SIP/[TRUNK_NAME]-0001f8dd in [COMPANY_NAME] their queue position (which was 1)
[Feb 19 01:04:39] DEBUG[6569][C-00008973] channel.c: Channel SIP/[TRUNK_NAME]-0001f8dd setting write format path: slin16 -> ulaw
[Feb 19 01:04:39] DEBUG[6569][C-00008973] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Feb 19 01:04:39] VERBOSE[6569][C-00008973] file.c: <SIP/[TRUNK_NAME]-0001f8dd> Playing 'queue-thank-you-stay-on-the-line.slin16' (language 'ka/[COMPANY_NAME]')
[Feb 19 01:04:39] DEBUG[6571] threadpool.c: Worker thread idle timeout reached. Dying.
[Feb 19 01:04:39] DEBUG[8858] threadpool.c: Destroying worker thread 32505
##################################################
SOME PROBABLY UNRELATED DEBUG DATA REMOVED HERE
##################################################
[Feb 19 01:04:42] DEBUG[6569][C-00008973] channel.c: Scheduling timer at (75 requested / 75 actual) timer ticks per second
[Feb 19 01:04:42] DEBUG[9158] chan_sip.c: = Looking for  Call ID: 4a1c279434f327955bf59c870943a111@[ast.srv.ip]:5061 (Checking To) --From tag as0a73daa9 --To-tag 85921d5d40a7f895i0  
[Feb 19 01:04:42] DEBUG[6569][C-00008973] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 19 01:04:42] DEBUG[6569][C-00008973] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 19 01:04:42] DEBUG[6569][C-00008973] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 19 01:04:42] DEBUG[6569][C-00008973] channel.c: Channel SIP/[TRUNK_NAME]-0001f8dd setting write format path: alaw -> ulaw
[Feb 19 01:04:42] VERBOSE[6569][C-00008973] res_musiconhold.c: Started music on hold, class '[COMPANY_NAME]', on channel 'SIP/[TRUNK_NAME]-0001f8dd'
[Feb 19 01:04:42] DEBUG[6569][C-00008973] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Feb 19 01:04:42] DEBUG[6569][C-00008973] app_queue.c: SIP/[TRUNK_NAME]-0001f8dd is trying to call a queue member.
[Feb 19 01:04:42] DEBUG[6569][C-00008973] app_queue.c: Trying 'SIP/[COMPANY_NAME]-418' with metric 0
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Allocating new SIP dialog for 01fa68021a2932592792a7044df68831@[::1]:5060 - INVITE (No RTP)
[Feb 19 01:04:42] DEBUG[6569][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:42] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Allocated port 27940 for RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:42] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:27940 (27940) for RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:42] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:42] DEBUG[6569][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:42] DEBUG[6569][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:42] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:27940, base=[ast.srv.ip]:27940, prio=0x7effffff (2130706431)
[Feb 19 01:04:42] DEBUG[6569][C-00008973] rtp_engine.c: RTP instance '0x7fb05c14f6a8' is setup and ready to go
[Feb 19 01:04:42] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Destroying ICE session 0x7fb05c09c588
[Feb 19 01:04:42] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c1 STUN session 0x7fb05c1e7a48 destroy request, ref_cnt=4
[Feb 19 01:04:42] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c2c9bf8 destroy request, ref_cnt=3
[Feb 19 01:04:42] DEBUG[6569][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb05c09c588 destroyed
[Feb 19 01:04:42] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c1e7a48 destroyed
[Feb 19 01:04:42] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c2c9bf8 destroyed
[Feb 19 01:04:42] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:42] VERBOSE[6569][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:42] DEBUG[6569][C-00008973] acl.c: For destination '[office.ip]', our source address is '[ast.srv.ip]'.
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:42] DEBUG[6569][C-00008973] netsock2.c: Splitting '192.168.240.210:5073' into...
[Feb 19 01:04:42] DEBUG[6569][C-00008973] netsock2.c: ...host '192.168.240.210' and port '5073'.
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: NAT detected for 192.168.240.210 / [office.ip]
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: SIP call-id changed from '01fa68021a2932592792a7044df68831@[::1]:5060' to '65e02d6162b79ecd60a48ad043895a07@[ast.srv.ip]:5061'
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: *** Our native formats are (ulaw) 
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: *** Joint capabilities are (ulaw) 
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030004e98 - Created CDR for channel SIP/[COMPANY_NAME]-418-0001f8e2
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030004e98 - Transitioning CDR for SIP/[COMPANY_NAME]-418-0001f8e2 from state NONE to Single
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:42] DEBUG[6569][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:42] DEBUG[6569][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 19 01:04:42] DEBUG[8899] chan_sip.c: Destroying SIP dialog 4a1c279434f327955bf59c870943a111@[ast.srv.ip]:5061
[Feb 19 01:04:42] DEBUG[6569][C-00008973] channel_internal_api.c: Channel Call ID changing from [C-00008973] to [C-00008973]
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Outgoing Call for [COMPANY_NAME]-418
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:42] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-418
[Feb 19 01:04:42] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-418
[Feb 19 01:04:42] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-418 - state 6 (Ringing)
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (ulaw|g722|alaw) Video flag: False Text flag: False
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (ulaw) 
[Feb 19 01:04:42] DEBUG[6569][C-00008973] sdp_srtp.c: local_key64 52ZEMRyZ8THKzuz0+iiVjECFKHVRPCGeUpT0+VGs len 40
[Feb 19 01:04:42] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-418' changed to state '6' (Ringing)
[Feb 19 01:04:42] DEBUG[6569][C-00008973] sdp_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:52ZEMRyZ8THKzuz0+iiVjECFKHVRPCGeUpT0+VGs
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722|alaw)
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Initializing initreq for method INVITE - callid 65e02d6162b79ecd60a48ad043895a07@[ast.srv.ip]:5061
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'INVITE sip:' onto TLS socket destined for [office.ip]:5073
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: Dial Begin message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-418-0001f8e2: 1455829482.00828658
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030028b08 - Created CDR for channel SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030028b08 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state NONE to Single
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030028b08 - Set answered time to 1455829482.828675
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030028b08 - Updated Party A SIP/[TRUNK_NAME]-0001f8dd snapshot
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030028b08 - Updated Party B SIP/[COMPANY_NAME]-418-0001f8e2 snapshot
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030028b08 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Single to Dial
[Feb 19 01:04:42] VERBOSE[6569][C-00008973] app_queue.c: Called SIP/[COMPANY_NAME]-418
[Feb 19 01:04:42] DEBUG[6569][C-00008973] channel.c: Channel SIP/[TRUNK_NAME]-0001f8dd setting write format path: slin16 -> ulaw
[Feb 19 01:04:42] DEBUG[6569][C-00008973] res_musiconhold.c: SIP/[TRUNK_NAME]-0001f8dd Opened file 0 '/var/lib/asterisk/moh/[COMPANY_NAME]/Billy Vaughn - Pearly Shell'
##################################################
SOME PROBABLY UNRELATED DEBUG DATA REMOVED HERE
##################################################
[Feb 19 01:04:42] VERBOSE[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-418-0001f8e2 is busy
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: Dial End message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-418-0001f8e2: 1455829482.00922146
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030028b08 - Processing Dial End message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-418-0001f8e2
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030028b08 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Dial to Finalized
[Feb 19 01:04:42] VERBOSE[6569][C-00008973] app_queue.c: Nobody picked up in 0 ms
[Feb 19 01:04:42] DEBUG[8873] cdr.c: Finalized CDR for SIP/[TRUNK_NAME]-0001f8dd - start 1455829482.828675 answer 1455829482.828675 end 1455829482.922190 dispo BUSY
[Feb 19 01:04:42] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:42] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:42.922227', '', '', '', '', '0', 'RINGNOANSWER', 'SIP/[COMPANY_NAME]-418', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:42] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:42] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[COMPANY_NAME]-418-0001f8e2'
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[COMPANY_NAME]-418-0001f8e2, SIP callid 65e02d6162b79ecd60a48ad043895a07@[ast.srv.ip]:5061
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:42] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:42] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-418
[Feb 19 01:04:42] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-418
[Feb 19 01:04:42] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-418 - state 1 (Not in use)
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030004e98 - Transitioning CDR for SIP/[COMPANY_NAME]-418-0001f8e2 from state Single to Finalized
[Feb 19 01:04:42] DEBUG[8873] cdr.c: Finalized CDR for SIP/[COMPANY_NAME]-418-0001f8e2 - start 1455829482.828384 answer 0.000000 end 1455829482.932635 dispo BUSY
[Feb 19 01:04:42] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-418' changed to state '1' (Not in use)
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030004e98 - Beginning finalize/dispatch for SIP/[COMPANY_NAME]-418-0001f8e2
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030004e98 - Dispatching CDR for Party A SIP/[COMPANY_NAME]-418-0001f8e2, Party B <none>
[Feb 19 01:04:42] DEBUG[8873] cdr.c: CDR for SIP/[COMPANY_NAME]-418-0001f8e2 is dialed and has no Party B; discarding
[Feb 19 01:04:42] DEBUG[6569][C-00008973] app_queue.c: Trying 'SIP/[COMPANY_NAME]-419' with metric 1
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Feb 19 01:04:42] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-418
[Feb 19 01:04:42] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-418
[Feb 19 01:04:42] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-418 - state 1 (Not in use)
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Allocating new SIP dialog for 01b0fe0e45aa31fd675ed25b70a662f0@[::1]:5060 - INVITE (No RTP)
[Feb 19 01:04:42] DEBUG[6569][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:42] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Allocated port 23012 for RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:42] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:23012 (23012) for RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:42] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:42] DEBUG[6569][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:42] DEBUG[6569][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:42] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:23012, base=[ast.srv.ip]:23012, prio=0x7effffff (2130706431)
[Feb 19 01:04:42] DEBUG[6569][C-00008973] rtp_engine.c: RTP instance '0x7fb05c1729b8' is setup and ready to go
[Feb 19 01:04:42] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Destroying ICE session 0x7fb05c09c588
[Feb 19 01:04:42] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c1 STUN session 0x7fb05c1e7a48 destroy request, ref_cnt=4
[Feb 19 01:04:42] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c0447f8 destroy request, ref_cnt=3
[Feb 19 01:04:42] DEBUG[6569][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb05c09c588 destroyed
[Feb 19 01:04:42] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c1e7a48 destroyed
[Feb 19 01:04:42] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c0447f8 destroyed
[Feb 19 01:04:42] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:42] VERBOSE[6569][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:42] DEBUG[6569][C-00008973] acl.c: For destination '[office.ip]', our source address is '[ast.srv.ip]'.
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:42] DEBUG[6569][C-00008973] netsock2.c: Splitting '192.168.240.208:5074' into...
[Feb 19 01:04:42] DEBUG[6569][C-00008973] netsock2.c: ...host '192.168.240.208' and port '5074'.
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: NAT detected for 192.168.240.208 / [office.ip]
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: SIP call-id changed from '01b0fe0e45aa31fd675ed25b70a662f0@[::1]:5060' to '39f635c544abf8525534a0214d5cddb8@[ast.srv.ip]:5061'
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030028708 - Created CDR for channel SIP/[COMPANY_NAME]-419-0001f8e3
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030028708 - Transitioning CDR for SIP/[COMPANY_NAME]-419-0001f8e3 from state NONE to Single
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: *** Our native formats are (ulaw) 
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: *** Joint capabilities are (ulaw) 
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:42] DEBUG[6569][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:42] DEBUG[6569][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 19 01:04:42] DEBUG[6569][C-00008973] channel_internal_api.c: Channel Call ID changing from [C-00008973] to [C-00008973]
[Feb 19 01:04:42] DEBUG[8899] chan_sip.c: Destroying SIP dialog 1eaefd0144eaf1f934e6c5ea053fcbbc@[ast.srv.ip]:5061
[Feb 19 01:04:42] DEBUG[8899] chan_sip.c: Destroying SIP dialog 65e02d6162b79ecd60a48ad043895a07@[ast.srv.ip]:5061
[Feb 19 01:04:42] DEBUG[8899] rtp_engine.c: Destroyed RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Outgoing Call for [COMPANY_NAME]-419
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:42] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-419
[Feb 19 01:04:42] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-419
[Feb 19 01:04:42] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-419 - state 6 (Ringing)
[Feb 19 01:04:42] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-419' changed to state '6' (Ringing)
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (ulaw|g722|alaw) Video flag: False Text flag: False
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (ulaw) 
[Feb 19 01:04:42] DEBUG[6569][C-00008973] sdp_srtp.c: local_key64 jPnwaNdG9DmY4EmOOMz6lgDku4yFYhY6OZOQpPSp len 40
[Feb 19 01:04:42] DEBUG[6569][C-00008973] sdp_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:jPnwaNdG9DmY4EmOOMz6lgDku4yFYhY6OZOQpPSp
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722|alaw)
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Initializing initreq for method INVITE - callid 39f635c544abf8525534a0214d5cddb8@[ast.srv.ip]:5061
[Feb 19 01:04:42] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'INVITE sip:' onto TLS socket destined for [office.ip]:5074
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: Dial Begin message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-419-0001f8e3: 1455829482.00933374
[Feb 19 01:04:42] VERBOSE[6569][C-00008973] app_queue.c: Called SIP/[COMPANY_NAME]-419
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030000c58 - Created CDR for channel SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030000c58 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state NONE to Single
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030000c58 - Set answered time to 1455829482.933388
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030000c58 - Updated Party A SIP/[TRUNK_NAME]-0001f8dd snapshot
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030000c58 - Updated Party B SIP/[COMPANY_NAME]-419-0001f8e3 snapshot
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030000c58 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Single to Dial
[Feb 19 01:04:42] DEBUG[23717] chan_sip.c: = Looking for  Call ID: 39f635c544abf8525534a0214d5cddb8@[ast.srv.ip]:5061 (Checking To) --From tag as6e0a84a1 --To-tag   
[Feb 19 01:04:42] DEBUG[23717][C-00008973] chan_sip.c: SIP response 100 to standard invite
[Feb 19 01:04:42] DEBUG[23717] chan_sip.c: = Looking for  Call ID: 39f635c544abf8525534a0214d5cddb8@[ast.srv.ip]:5061 (Checking To) --From tag as6e0a84a1 --To-tag 34390fdcc440b6i0  
[Feb 19 01:04:42] VERBOSE[23717][C-00008973] chan_sip.c: Got SIP response 486 "Busy Here" back from [office.ip]:5074
[Feb 19 01:04:42] DEBUG[23717][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:42] DEBUG[23717][C-00008973] chan_sip.c: Trying to put 'ACK sip:moz' onto TLS socket destined for [office.ip]:5074
[Feb 19 01:04:42] DEBUG[23717][C-00008973] chan_sip.c: Setting SIP_ALREADYGONE on dialog 39f635c544abf8525534a0214d5cddb8@[ast.srv.ip]:5061
[Feb 19 01:04:42] VERBOSE[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-419-0001f8e3 is busy
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: Dial End message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-419-0001f8e3: 1455829482.00995209
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030000c58 - Processing Dial End message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-419-0001f8e3
[Feb 19 01:04:42] VERBOSE[6569][C-00008973] app_queue.c: Nobody picked up in 0 ms
[Feb 19 01:04:42] VERBOSE[8873] cdr.c: 0x7fb030000c58 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Dial to Finalized
[Feb 19 01:04:42] DEBUG[8873] cdr.c: Finalized CDR for SIP/[TRUNK_NAME]-0001f8dd - start 1455829482.933388 answer 1455829482.933388 end 1455829482.995262 dispo BUSY
[Feb 19 01:04:42] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:42] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:42.995301', '', '', '', '', '0', 'RINGNOANSWER', 'SIP/[COMPANY_NAME]-419', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:43] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[COMPANY_NAME]-419-0001f8e3'
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[COMPANY_NAME]-419-0001f8e3, SIP callid 39f635c544abf8525534a0214d5cddb8@[ast.srv.ip]:5061
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:43] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-419
[Feb 19 01:04:43] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-419
[Feb 19 01:04:43] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-419 - state 1 (Not in use)
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb030028708 - Transitioning CDR for SIP/[COMPANY_NAME]-419-0001f8e3 from state Single to Finalized
[Feb 19 01:04:43] DEBUG[8873] cdr.c: Finalized CDR for SIP/[COMPANY_NAME]-419-0001f8e3 - start 1455829482.933096 answer 0.000000 end 1455829483.005893 dispo BUSY
[Feb 19 01:04:43] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-419' changed to state '1' (Not in use)
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb030028708 - Beginning finalize/dispatch for SIP/[COMPANY_NAME]-419-0001f8e3
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb030028708 - Dispatching CDR for Party A SIP/[COMPANY_NAME]-419-0001f8e3, Party B <none>
[Feb 19 01:04:43] DEBUG[8873] cdr.c: CDR for SIP/[COMPANY_NAME]-419-0001f8e3 is dialed and has no Party B; discarding
[Feb 19 01:04:43] DEBUG[6569][C-00008973] app_queue.c: Trying 'SIP/[COMPANY_NAME]-420' with metric 2
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Feb 19 01:04:43] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-419
[Feb 19 01:04:43] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-419
[Feb 19 01:04:43] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-419 - state 1 (Not in use)
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Allocating new SIP dialog for 029890331813f688140fd459418624fb@[::1]:5060 - INVITE (No RTP)
[Feb 19 01:04:43] DEBUG[6569][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Allocated port 24714 for RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:24714 (24714) for RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:43] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:43] DEBUG[6569][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:43] DEBUG[6569][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:43] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:24714, base=[ast.srv.ip]:24714, prio=0x7effffff (2130706431)
[Feb 19 01:04:43] DEBUG[6569][C-00008973] rtp_engine.c: RTP instance '0x7fb05c14f6a8' is setup and ready to go
[Feb 19 01:04:43] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Destroying ICE session 0x7fb05c09c588
[Feb 19 01:04:43] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c1 STUN session 0x7fb05c1e7a48 destroy request, ref_cnt=4
[Feb 19 01:04:43] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c1ce2b8 destroy request, ref_cnt=3
[Feb 19 01:04:43] DEBUG[6569][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb05c09c588 destroyed
[Feb 19 01:04:43] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c1e7a48 destroyed
[Feb 19 01:04:43] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c1ce2b8 destroyed
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:43] VERBOSE[6569][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:43] DEBUG[6569][C-00008973] acl.c: For destination '[office.ip]', our source address is '[ast.srv.ip]'.
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:43] DEBUG[6569][C-00008973] netsock2.c: Splitting '192.168.240.209:5062' into...
[Feb 19 01:04:43] DEBUG[6569][C-00008973] netsock2.c: ...host '192.168.240.209' and port '5062'.
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: NAT detected for 192.168.240.209 / [office.ip]
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: SIP call-id changed from '029890331813f688140fd459418624fb@[::1]:5060' to '432c18c725a479864350bbd31793b827@[ast.srv.ip]:5061'
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb0300132a8 - Created CDR for channel SIP/[COMPANY_NAME]-420-0001f8e4
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb0300132a8 - Transitioning CDR for SIP/[COMPANY_NAME]-420-0001f8e4 from state NONE to Single
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: *** Our native formats are (ulaw) 
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: *** Joint capabilities are (ulaw) 
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:43] DEBUG[6569][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:43] DEBUG[6569][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 19 01:04:43] DEBUG[6569][C-00008973] channel_internal_api.c: Channel Call ID changing from [C-00008973] to [C-00008973]
[Feb 19 01:04:43] DEBUG[8899] chan_sip.c: Destroying SIP dialog 39f635c544abf8525534a0214d5cddb8@[ast.srv.ip]:5061
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Outgoing Call for [COMPANY_NAME]-420
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:43] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-420
[Feb 19 01:04:43] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-420
[Feb 19 01:04:43] DEBUG[8899] rtp_engine.c: Destroyed RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:43] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-420 - state 6 (Ringing)
[Feb 19 01:04:43] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-420' changed to state '6' (Ringing)
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (ulaw|g722|alaw) Video flag: False Text flag: False
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (ulaw) 
[Feb 19 01:04:43] DEBUG[6569][C-00008973] sdp_srtp.c: local_key64 Pos9K9PErqzadMrnPAPFhqfbEsVFuRW5UF2oVsMM len 40
[Feb 19 01:04:43] DEBUG[6569][C-00008973] sdp_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:Pos9K9PErqzadMrnPAPFhqfbEsVFuRW5UF2oVsMM
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722|alaw)
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Initializing initreq for method INVITE - callid 432c18c725a479864350bbd31793b827@[ast.srv.ip]:5061
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'INVITE sip:' onto TLS socket destined for [office.ip]:5062
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: Dial Begin message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-420-0001f8e4: 1455829483.00006643
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Created CDR for channel SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state NONE to Single
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Set answered time to 1455829483.006671
[Feb 19 01:04:43] VERBOSE[6569][C-00008973] app_queue.c: Called SIP/[COMPANY_NAME]-420
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Updated Party A SIP/[TRUNK_NAME]-0001f8dd snapshot
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Updated Party B SIP/[COMPANY_NAME]-420-0001f8e4 snapshot
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Single to Dial
[Feb 19 01:04:43] DEBUG[23726] chan_sip.c: = Looking for  Call ID: 432c18c725a479864350bbd31793b827@[ast.srv.ip]:5061 (Checking To) --From tag as1743619a --To-tag   
[Feb 19 01:04:43] DEBUG[23726][C-00008973] chan_sip.c: SIP response 100 to standard invite
[Feb 19 01:04:43] DEBUG[23726] chan_sip.c: = Looking for  Call ID: 432c18c725a479864350bbd31793b827@[ast.srv.ip]:5061 (Checking To) --From tag as1743619a --To-tag 156a27e5d9c82f6ai0  
[Feb 19 01:04:43] VERBOSE[23726][C-00008973] chan_sip.c: Got SIP response 486 "Busy Here" back from [office.ip]:5062
[Feb 19 01:04:43] DEBUG[23726][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:43] DEBUG[23726][C-00008973] chan_sip.c: Trying to put 'ACK sip:moz' onto TLS socket destined for [office.ip]:5062
[Feb 19 01:04:43] DEBUG[23726][C-00008973] chan_sip.c: Setting SIP_ALREADYGONE on dialog 432c18c725a479864350bbd31793b827@[ast.srv.ip]:5061
[Feb 19 01:04:43] VERBOSE[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-420-0001f8e4 is busy
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: Dial End message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-420-0001f8e4: 1455829483.00089074
[Feb 19 01:04:43] VERBOSE[6569][C-00008973] app_queue.c: Nobody picked up in 0 ms
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Processing Dial End message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-420-0001f8e4
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb03001c468 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Dial to Finalized
[Feb 19 01:04:43] DEBUG[8873] cdr.c: Finalized CDR for SIP/[TRUNK_NAME]-0001f8dd - start 1455829483.006671 answer 1455829483.006671 end 1455829483.089120 dispo BUSY
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:43.089129', '', '', '', '', '0', 'RINGNOANSWER', 'SIP/[COMPANY_NAME]-420', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:43] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[COMPANY_NAME]-420-0001f8e4'
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[COMPANY_NAME]-420-0001f8e4, SIP callid 432c18c725a479864350bbd31793b827@[ast.srv.ip]:5061
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:43] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-420
[Feb 19 01:04:43] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-420
[Feb 19 01:04:43] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-420 - state 1 (Not in use)
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb0300132a8 - Transitioning CDR for SIP/[COMPANY_NAME]-420-0001f8e4 from state Single to Finalized
[Feb 19 01:04:43] DEBUG[8873] cdr.c: Finalized CDR for SIP/[COMPANY_NAME]-420-0001f8e4 - start 1455829483.006345 answer 0.000000 end 1455829483.099286 dispo BUSY
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb0300132a8 - Beginning finalize/dispatch for SIP/[COMPANY_NAME]-420-0001f8e4
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb0300132a8 - Dispatching CDR for Party A SIP/[COMPANY_NAME]-420-0001f8e4, Party B <none>
[Feb 19 01:04:43] DEBUG[8873] cdr.c: CDR for SIP/[COMPANY_NAME]-420-0001f8e4 is dialed and has no Party B; discarding
[Feb 19 01:04:43] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-420' changed to state '1' (Not in use)
[Feb 19 01:04:43] DEBUG[6569][C-00008973] app_queue.c: Trying 'SIP/[COMPANY_NAME]-421' with metric 3
[Feb 19 01:04:43] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-420
[Feb 19 01:04:43] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-420
[Feb 19 01:04:43] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-420 - state 1 (Not in use)
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Allocating new SIP dialog for 4855a0db19bec8831cc7f56c6851b332@[::1]:5060 - INVITE (No RTP)
[Feb 19 01:04:43] DEBUG[6569][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Allocated port 21494 for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:21494 (21494) for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:43] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:43] DEBUG[6569][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:43] DEBUG[6569][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:43] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:21494, base=[ast.srv.ip]:21494, prio=0x7effffff (2130706431)
[Feb 19 01:04:43] DEBUG[6569][C-00008973] rtp_engine.c: RTP instance '0x7fb05c0108d8' is setup and ready to go
[Feb 19 01:04:43] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Destroying ICE session 0x7fb05c09c588
[Feb 19 01:04:43] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c1 STUN session 0x7fb05c1e7a48 destroy request, ref_cnt=4
[Feb 19 01:04:43] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c0acb08 destroy request, ref_cnt=3
[Feb 19 01:04:43] DEBUG[6569][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb05c09c588 destroyed
[Feb 19 01:04:43] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c1e7a48 destroyed
[Feb 19 01:04:43] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c0acb08 destroyed
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:43] VERBOSE[6569][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:43] DEBUG[6569][C-00008973] acl.c: For destination '[office.ip]', our source address is '[ast.srv.ip]'.
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:43] DEBUG[6569][C-00008973] netsock2.c: Splitting '192.168.240.207:5060' into...
[Feb 19 01:04:43] DEBUG[6569][C-00008973] netsock2.c: ...host '192.168.240.207' and port '5060'.
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: NAT detected for 192.168.240.207 / [office.ip]
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: SIP call-id changed from '4855a0db19bec8831cc7f56c6851b332@[::1]:5060' to '78ea3a3c3705ed487422b0c44a6eef6c@[ast.srv.ip]:5061'
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb030004e98 - Created CDR for channel SIP/[COMPANY_NAME]-421-0001f8e5
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb030004e98 - Transitioning CDR for SIP/[COMPANY_NAME]-421-0001f8e5 from state NONE to Single
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: *** Our native formats are (ulaw) 
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: *** Joint capabilities are (ulaw) 
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:43] DEBUG[6569][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:43] DEBUG[6569][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 19 01:04:43] DEBUG[6569][C-00008973] channel_internal_api.c: Channel Call ID changing from [C-00008973] to [C-00008973]
[Feb 19 01:04:43] DEBUG[8899] chan_sip.c: Destroying SIP dialog 432c18c725a479864350bbd31793b827@[ast.srv.ip]:5061
[Feb 19 01:04:43] DEBUG[8899] rtp_engine.c: Destroyed RTP instance '0x7fb05c14f6a8'
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Outgoing Call for [COMPANY_NAME]-421
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:43] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-421
[Feb 19 01:04:43] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-421
[Feb 19 01:04:43] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-421 - state 6 (Ringing)
[Feb 19 01:04:43] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-421' changed to state '6' (Ringing)
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (ulaw|g722|alaw) Video flag: False Text flag: False
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (ulaw) 
[Feb 19 01:04:43] DEBUG[6569][C-00008973] sdp_srtp.c: local_key64 8ii3xzdk6auc0KDpIqS6iH69TzZ0Ev2TwsoJyyvT len 40
[Feb 19 01:04:43] DEBUG[6569][C-00008973] sdp_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:8ii3xzdk6auc0KDpIqS6iH69TzZ0Ev2TwsoJyyvT
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722|alaw)
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Initializing initreq for method INVITE - callid 78ea3a3c3705ed487422b0c44a6eef6c@[ast.srv.ip]:5061
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'INVITE sip:' onto TLS socket destined for [office.ip]:27493
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: Dial Begin message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-421-0001f8e5: 1455829483.00100002
[Feb 19 01:04:43] VERBOSE[6569][C-00008973] app_queue.c: Called SIP/[COMPANY_NAME]-421
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb030028708 - Created CDR for channel SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb030028708 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state NONE to Single
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb030028708 - Set answered time to 1455829483.100017
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb030028708 - Updated Party A SIP/[TRUNK_NAME]-0001f8dd snapshot
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb030028708 - Updated Party B SIP/[COMPANY_NAME]-421-0001f8e5 snapshot
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb030028708 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Single to Dial
[Feb 19 01:04:43] DEBUG[23714] chan_sip.c: = Looking for  Call ID: 78ea3a3c3705ed487422b0c44a6eef6c@[ast.srv.ip]:5061 (Checking To) --From tag as301b8a92 --To-tag   
[Feb 19 01:04:43] DEBUG[23714][C-00008973] chan_sip.c: SIP response 100 to standard invite
[Feb 19 01:04:43] DEBUG[23714] chan_sip.c: = Looking for  Call ID: 78ea3a3c3705ed487422b0c44a6eef6c@[ast.srv.ip]:5061 (Checking To) --From tag as301b8a92 --To-tag fca68fc88e789dai0  
[Feb 19 01:04:43] VERBOSE[23714][C-00008973] chan_sip.c: Got SIP response 486 "Busy Here" back from [office.ip]:27493
[Feb 19 01:04:43] DEBUG[23714][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:43] DEBUG[23714][C-00008973] chan_sip.c: Trying to put 'ACK sip:moz' onto TLS socket destined for [office.ip]:27493
[Feb 19 01:04:43] DEBUG[23714][C-00008973] chan_sip.c: Setting SIP_ALREADYGONE on dialog 78ea3a3c3705ed487422b0c44a6eef6c@[ast.srv.ip]:5061
[Feb 19 01:04:43] VERBOSE[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-421-0001f8e5 is busy
[Feb 19 01:04:43] VERBOSE[6569][C-00008973] app_queue.c: Nobody picked up in 0 ms
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: Dial End message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-421-0001f8e5: 1455829483.00170178
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb030028708 - Processing Dial End message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-421-0001f8e5
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb030028708 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Dial to Finalized
[Feb 19 01:04:43] DEBUG[8873] cdr.c: Finalized CDR for SIP/[TRUNK_NAME]-0001f8dd - start 1455829483.100017 answer 1455829483.100017 end 1455829483.170220 dispo BUSY
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:43.170224', '', '', '', '', '0', 'RINGNOANSWER', 'SIP/[COMPANY_NAME]-421', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:43] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[COMPANY_NAME]-421-0001f8e5'
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[COMPANY_NAME]-421-0001f8e5, SIP callid 78ea3a3c3705ed487422b0c44a6eef6c@[ast.srv.ip]:5061
[Feb 19 01:04:43] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:43] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-421
[Feb 19 01:04:43] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-421
[Feb 19 01:04:43] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-421 - state 1 (Not in use)
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb030004e98 - Transitioning CDR for SIP/[COMPANY_NAME]-421-0001f8e5 from state Single to Finalized
[Feb 19 01:04:43] DEBUG[8873] cdr.c: Finalized CDR for SIP/[COMPANY_NAME]-421-0001f8e5 - start 1455829483.099749 answer 0.000000 end 1455829483.180949 dispo BUSY
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb030004e98 - Beginning finalize/dispatch for SIP/[COMPANY_NAME]-421-0001f8e5
[Feb 19 01:04:43] VERBOSE[8873] cdr.c: 0x7fb030004e98 - Dispatching CDR for Party A SIP/[COMPANY_NAME]-421-0001f8e5, Party B <none>
[Feb 19 01:04:43] DEBUG[8873] cdr.c: CDR for SIP/[COMPANY_NAME]-421-0001f8e5 is dialed and has no Party B; discarding
[Feb 19 01:04:43] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-421' changed to state '1' (Not in use)
[Feb 19 01:04:43] DEBUG[6569][C-00008973] app_queue.c: Nobody left to try ringing in queue
[Feb 19 01:04:43] DEBUG[6569][C-00008973] app_queue.c: Everyone is busy at this time
[Feb 19 01:04:43] DEBUG[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-418 is available.
[Feb 19 01:04:43] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-421
[Feb 19 01:04:43] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-421
[Feb 19 01:04:43] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-421 - state 1 (Not in use)
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:43] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM queue_members WHERE interface LIKE '%' AND queue_name = '[COMPANY_NAME]' ORDER BY interface
##################################################
SOME PROBABLY UNRELATED DEBUG DATA REMOVED HERE
##################################################
[Feb 19 01:04:48] DEBUG[6569][C-00008973] app_queue.c: There is 1 available member.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] app_queue.c: It's our turn (SIP/[TRUNK_NAME]-0001f8dd).
[Feb 19 01:04:48] DEBUG[6569][C-00008973] app_queue.c: SIP/[TRUNK_NAME]-0001f8dd is trying to call a queue member.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] app_queue.c: Trying 'SIP/[COMPANY_NAME]-418' with metric 0
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Allocating new SIP dialog for 3e8b9d953d1dcc3563f452161ea5eb7a@[::1]:5060 - INVITE (No RTP)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Allocated port 21256 for RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:21256 (21256) for RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:48] DEBUG[6569][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:48] DEBUG[6569][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:21256, base=[ast.srv.ip]:21256, prio=0x7effffff (2130706431)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] rtp_engine.c: RTP instance '0x7fb05c1729b8' is setup and ready to go
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Destroying ICE session 0x7fb05c09c588
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c1 STUN session 0x7fb05c062de8 destroy request, ref_cnt=4
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c1e7a48 destroy request, ref_cnt=3
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb05c09c588 destroyed
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c062de8 destroyed
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c1e7a48 destroyed
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:48] VERBOSE[6569][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:48] DEBUG[6569][C-00008973] acl.c: For destination '[office.ip]', our source address is '[ast.srv.ip]'.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[6569][C-00008973] netsock2.c: Splitting '192.168.240.210:5073' into...
[Feb 19 01:04:48] DEBUG[6569][C-00008973] netsock2.c: ...host '192.168.240.210' and port '5073'.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: NAT detected for 192.168.240.210 / [office.ip]
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: SIP call-id changed from '3e8b9d953d1dcc3563f452161ea5eb7a@[::1]:5060' to '7680c3e76f2cf5cb0534f72d42085552@[ast.srv.ip]:5061'
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029008 - Created CDR for channel SIP/[COMPANY_NAME]-418-0001f8e6
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** Our native formats are (ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** Joint capabilities are (ulaw) 
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029008 - Transitioning CDR for SIP/[COMPANY_NAME]-418-0001f8e6 from state NONE to Single
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:48] DEBUG[6569][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 19 01:04:48] DEBUG[6569][C-00008973] channel_internal_api.c: Channel Call ID changing from [C-00008973] to [C-00008973]
[Feb 19 01:04:48] DEBUG[8899] chan_sip.c: Destroying SIP dialog 792f9f19392ce911139b49d60bcd7c7c@[ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Outgoing Call for [COMPANY_NAME]-418
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-418
[Feb 19 01:04:48] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-418
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-418 - state 6 (Ringing)
[Feb 19 01:04:48] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-418' changed to state '6' (Ringing)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (ulaw|g722|alaw) Video flag: False Text flag: False
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] sdp_srtp.c: local_key64 kwZ7eD5K/iQOmgKM307b2sJzom+ql9YlhIju8GU8 len 40
[Feb 19 01:04:48] DEBUG[6569][C-00008973] sdp_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:kwZ7eD5K/iQOmgKM307b2sJzom+ql9YlhIju8GU8
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722|alaw)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Initializing initreq for method INVITE - callid 7680c3e76f2cf5cb0534f72d42085552@[ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'INVITE sip:' onto TLS socket destined for [office.ip]:5073
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: Dial Begin message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-418-0001f8e6: 1455829488.00182168
[Feb 19 01:04:48] VERBOSE[6569][C-00008973] app_queue.c: Called SIP/[COMPANY_NAME]-418
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029448 - Created CDR for channel SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029448 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state NONE to Single
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029448 - Set answered time to 1455829488.182184
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029448 - Updated Party A SIP/[TRUNK_NAME]-0001f8dd snapshot
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029448 - Updated Party B SIP/[COMPANY_NAME]-418-0001f8e6 snapshot
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029448 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Single to Dial
##################################################
SOME PROBABLY UNRELATED DEBUG DATA REMOVED HERE
##################################################
[Feb 19 01:04:48] VERBOSE[23724][C-00008973] chan_sip.c: Got SIP response 486 "Busy Here" back from [office.ip]:5073
[Feb 19 01:04:48] DEBUG[23724][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:48] DEBUG[23724][C-00008973] chan_sip.c: Trying to put 'ACK sip:moz' onto TLS socket destined for [office.ip]:5073
[Feb 19 01:04:48] DEBUG[23724][C-00008973] chan_sip.c: Setting SIP_ALREADYGONE on dialog 7680c3e76f2cf5cb0534f72d42085552@[ast.srv.ip]:5061
[Feb 19 01:04:48] VERBOSE[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-418-0001f8e6 is busy
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: Dial End message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-418-0001f8e6: 1455829488.00333121
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029448 - Processing Dial End message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-418-0001f8e6
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029448 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Dial to Finalized
[Feb 19 01:04:48] VERBOSE[6569][C-00008973] app_queue.c: Nobody picked up in 0 ms
[Feb 19 01:04:48] DEBUG[8873] cdr.c: Finalized CDR for SIP/[TRUNK_NAME]-0001f8dd - start 1455829488.182184 answer 1455829488.182184 end 1455829488.333161 dispo BUSY
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:48.333192', '', '', '', '', '0', 'RINGNOANSWER', 'SIP/[COMPANY_NAME]-418', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:48] DEBUG[10105] chan_sip.c: = Looking for  Call ID: 22773839-d5ec35e6@192.168.5.136 (Checking From) --From tag 3f756fb5d1c90ad8o0 --To-tag   
##################################################
SOME PROBABLY UNRELATED DEBUG DATA REMOVED HERE
##################################################
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:48] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[COMPANY_NAME]-418-0001f8e6'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[COMPANY_NAME]-418-0001f8e6, SIP callid 7680c3e76f2cf5cb0534f72d42085552@[ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-418
[Feb 19 01:04:48] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-418
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-418 - state 1 (Not in use)
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029008 - Transitioning CDR for SIP/[COMPANY_NAME]-418-0001f8e6 from state Single to Finalized
[Feb 19 01:04:48] DEBUG[8873] cdr.c: Finalized CDR for SIP/[COMPANY_NAME]-418-0001f8e6 - start 1455829488.181902 answer 0.000000 end 1455829488.358101 dispo BUSY
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029008 - Beginning finalize/dispatch for SIP/[COMPANY_NAME]-418-0001f8e6
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029008 - Dispatching CDR for Party A SIP/[COMPANY_NAME]-418-0001f8e6, Party B <none>
[Feb 19 01:04:48] DEBUG[8873] cdr.c: CDR for SIP/[COMPANY_NAME]-418-0001f8e6 is dialed and has no Party B; discarding
[Feb 19 01:04:48] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-418' changed to state '1' (Not in use)
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-418
[Feb 19 01:04:48] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-418
[Feb 19 01:04:48] DEBUG[6569][C-00008973] app_queue.c: Trying 'SIP/[COMPANY_NAME]-419' with metric 1
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-418 - state 1 (Not in use)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Allocating new SIP dialog for 1c633cb857aae06f4e76969764d0f424@[::1]:5060 - INVITE (No RTP)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Allocated port 28454 for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:28454 (28454) for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:48] DEBUG[6569][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:48] DEBUG[6569][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:28454, base=[ast.srv.ip]:28454, prio=0x7effffff (2130706431)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] rtp_engine.c: RTP instance '0x7fb05c0108d8' is setup and ready to go
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Destroying ICE session 0x7fb05c09c588
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c062de8 destroy request, ref_cnt=4
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c023928 destroy request, ref_cnt=3
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb05c09c588 destroyed
[Feb 19 01:04:48] DEBUG[10105] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c062de8 destroyed
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c023928 destroyed
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:48] VERBOSE[6569][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:48] DEBUG[10105] chan_sip.c: SIP call-id changed from '403d1baa7303bdee0bc2ebf37e71a7ff@[::1]:5060' to '5ee1ee8d33eec79f7ff00b2e1e27003c@[ast.srv.ip]:5061'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] acl.c: For destination '[office.ip]', our source address is '[ast.srv.ip]'.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[6569][C-00008973] netsock2.c: Splitting '192.168.240.208:5074' into...
[Feb 19 01:04:48] DEBUG[6569][C-00008973] netsock2.c: ...host '192.168.240.208' and port '5074'.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: NAT detected for 192.168.240.208 / [office.ip]
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:48] DEBUG[10105] chan_sip.c: Initializing initreq for method OPTIONS - callid 5ee1ee8d33eec79f7ff00b2e1e27003c@[ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: SIP call-id changed from '1c633cb857aae06f4e76969764d0f424@[::1]:5060' to '03fa866f0414b3b76a0b07ca7494749c@[ast.srv.ip]:5061'
##################################################
SOME PROBABLY UNRELATED DEBUG DATA REMOVED HERE
##################################################
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03002a088 - Created CDR for channel SIP/[COMPANY_NAME]-419-0001f8e7
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03002a088 - Transitioning CDR for SIP/[COMPANY_NAME]-419-0001f8e7 from state NONE to Single
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** Our native formats are (ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** Joint capabilities are (ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:48] DEBUG[6569][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
##################################################
SOME PROBABLY UNRELATED DEBUG DATA REMOVED HERE
##################################################
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Outgoing Call for [COMPANY_NAME]-419
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-419
[Feb 19 01:04:48] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-419
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-419 - state 6 (Ringing)
[Feb 19 01:04:48] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-419' changed to state '6' (Ringing)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (ulaw|g722|alaw) Video flag: False Text flag: False
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] sdp_srtp.c: local_key64 S8Beo9WLiWELRMXENrsCHclnZjguRj1IrRoUyXsv len 40
[Feb 19 01:04:48] DEBUG[6569][C-00008973] sdp_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:S8Beo9WLiWELRMXENrsCHclnZjguRj1IrRoUyXsv
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722|alaw)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Initializing initreq for method INVITE - callid 03fa866f0414b3b76a0b07ca7494749c@[ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'INVITE sip:' onto TLS socket destined for [office.ip]:5074
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: Dial Begin message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-419-0001f8e7: 1455829488.00358787
[Feb 19 01:04:48] VERBOSE[6569][C-00008973] app_queue.c: Called SIP/[COMPANY_NAME]-419
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb0300132a8 - Created CDR for channel SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb0300132a8 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state NONE to Single
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb0300132a8 - Set answered time to 1455829488.358803
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb0300132a8 - Updated Party A SIP/[TRUNK_NAME]-0001f8dd snapshot
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb0300132a8 - Updated Party B SIP/[COMPANY_NAME]-419-0001f8e7 snapshot
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb0300132a8 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Single to Dial
##################################################
SOME PROBABLY UNRELATED DEBUG DATA REMOVED HERE
##################################################
[Feb 19 01:04:48] VERBOSE[23717][C-00008973] chan_sip.c: Got SIP response 486 "Busy Here" back from [office.ip]:5074
[Feb 19 01:04:48] DEBUG[23717][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:48] DEBUG[23717][C-00008973] chan_sip.c: Trying to put 'ACK sip:moz' onto TLS socket destined for [office.ip]:5074
[Feb 19 01:04:48] DEBUG[23717][C-00008973] chan_sip.c: Setting SIP_ALREADYGONE on dialog 03fa866f0414b3b76a0b07ca7494749c@[ast.srv.ip]:5061
[Feb 19 01:04:48] VERBOSE[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-419-0001f8e7 is busy
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: Dial End message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-419-0001f8e7: 1455829488.00435285
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb0300132a8 - Processing Dial End message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-419-0001f8e7
[Feb 19 01:04:48] VERBOSE[6569][C-00008973] app_queue.c: Nobody picked up in 0 ms
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb0300132a8 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Dial to Finalized
[Feb 19 01:04:48] DEBUG[8873] cdr.c: Finalized CDR for SIP/[TRUNK_NAME]-0001f8dd - start 1455829488.358803 answer 1455829488.358803 end 1455829488.435327 dispo BUSY
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:48.435363', '', '', '', '', '0', 'RINGNOANSWER', 'SIP/[COMPANY_NAME]-419', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:48] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[COMPANY_NAME]-419-0001f8e7'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[COMPANY_NAME]-419-0001f8e7, SIP callid 03fa866f0414b3b76a0b07ca7494749c@[ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-419
[Feb 19 01:04:48] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-419
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-419 - state 1 (Not in use)
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03002a088 - Transitioning CDR for SIP/[COMPANY_NAME]-419-0001f8e7 from state Single to Finalized
[Feb 19 01:04:48] DEBUG[8873] cdr.c: Finalized CDR for SIP/[COMPANY_NAME]-419-0001f8e7 - start 1455829488.358488 answer 0.000000 end 1455829488.441479 dispo BUSY
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03002a088 - Beginning finalize/dispatch for SIP/[COMPANY_NAME]-419-0001f8e7
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03002a088 - Dispatching CDR for Party A SIP/[COMPANY_NAME]-419-0001f8e7, Party B <none>
[Feb 19 01:04:48] DEBUG[8873] cdr.c: CDR for SIP/[COMPANY_NAME]-419-0001f8e7 is dialed and has no Party B; discarding
[Feb 19 01:04:48] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-419' changed to state '1' (Not in use)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] app_queue.c: Trying 'SIP/[COMPANY_NAME]-420' with metric 2
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-419
[Feb 19 01:04:48] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-419
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-419 - state 1 (Not in use)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Allocating new SIP dialog for 1d942eaf77e461be7b0ce54b702e2df7@[::1]:5060 - INVITE (No RTP)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb05c0d1108'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Allocated port 26000 for RTP instance '0x7fb05c0d1108'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:26000 (26000) for RTP instance '0x7fb05c0d1108'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:48] DEBUG[6569][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:48] DEBUG[6569][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:26000, base=[ast.srv.ip]:26000, prio=0x7effffff (2130706431)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] rtp_engine.c: RTP instance '0x7fb05c0d1108' is setup and ready to go
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Destroying ICE session 0x7fb05c09c588
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c1 STUN session 0x7fb05c062de8 destroy request, ref_cnt=4
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c0447f8 destroy request, ref_cnt=3
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb05c09c588 destroyed
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c062de8 destroyed
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c0447f8 destroyed
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb05c0d1108'
[Feb 19 01:04:48] VERBOSE[6569][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:48] DEBUG[6569][C-00008973] acl.c: For destination '[office.ip]', our source address is '[ast.srv.ip]'.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[6569][C-00008973] netsock2.c: Splitting '192.168.240.209:5062' into...
[Feb 19 01:04:48] DEBUG[6569][C-00008973] netsock2.c: ...host '192.168.240.209' and port '5062'.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: NAT detected for 192.168.240.209 / [office.ip]
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: SIP call-id changed from '1d942eaf77e461be7b0ce54b702e2df7@[::1]:5060' to '70f7c3491197a22a5dc0e3d809bce2df@[ast.srv.ip]:5061'
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030019918 - Created CDR for channel SIP/[COMPANY_NAME]-420-0001f8e8
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030019918 - Transitioning CDR for SIP/[COMPANY_NAME]-420-0001f8e8 from state NONE to Single
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** Our native formats are (ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** Joint capabilities are (ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:48] DEBUG[6569][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 19 01:04:48] DEBUG[6569][C-00008973] channel_internal_api.c: Channel Call ID changing from [C-00008973] to [C-00008973]
[Feb 19 01:04:48] DEBUG[8899] chan_sip.c: Destroying SIP dialog 5ee1ee8d33eec79f7ff00b2e1e27003c@[ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[8899] chan_sip.c: Destroying SIP dialog 03fa866f0414b3b76a0b07ca7494749c@[ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Outgoing Call for [COMPANY_NAME]-420
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:48] DEBUG[8899] rtp_engine.c: Destroyed RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-420
[Feb 19 01:04:48] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-420
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-420 - state 6 (Ringing)
[Feb 19 01:04:48] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-420' changed to state '6' (Ringing)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (ulaw|g722|alaw) Video flag: False Text flag: False
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] sdp_srtp.c: local_key64 Kwe6kz/QBB+Q5ZdDFSWYI3S4PkxxiKHnvzQlcemT len 40
[Feb 19 01:04:48] DEBUG[6569][C-00008973] sdp_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:Kwe6kz/QBB+Q5ZdDFSWYI3S4PkxxiKHnvzQlcemT
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722|alaw)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Initializing initreq for method INVITE - callid 70f7c3491197a22a5dc0e3d809bce2df@[ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'INVITE sip:' onto TLS socket destined for [office.ip]:5062
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: Dial Begin message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-420-0001f8e8: 1455829488.00442273
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029c88 - Created CDR for channel SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:48] VERBOSE[6569][C-00008973] app_queue.c: Called SIP/[COMPANY_NAME]-420
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029c88 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state NONE to Single
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029c88 - Set answered time to 1455829488.442289
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029c88 - Updated Party A SIP/[TRUNK_NAME]-0001f8dd snapshot
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029c88 - Updated Party B SIP/[COMPANY_NAME]-420-0001f8e8 snapshot
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029c88 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Single to Dial
[Feb 19 01:04:48] DEBUG[23726] chan_sip.c: = Looking for  Call ID: 70f7c3491197a22a5dc0e3d809bce2df@[ast.srv.ip]:5061 (Checking To) --From tag as427c27f7 --To-tag   
[Feb 19 01:04:48] DEBUG[23726][C-00008973] chan_sip.c: SIP response 100 to standard invite
[Feb 19 01:04:48] DEBUG[23726] chan_sip.c: = Looking for  Call ID: 70f7c3491197a22a5dc0e3d809bce2df@[ast.srv.ip]:5061 (Checking To) --From tag as427c27f7 --To-tag 156a27e5d9c82f6ai0  
[Feb 19 01:04:48] VERBOSE[23726][C-00008973] chan_sip.c: Got SIP response 486 "Busy Here" back from [office.ip]:5062
[Feb 19 01:04:48] DEBUG[23726][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c0d1108'
[Feb 19 01:04:48] DEBUG[23726][C-00008973] chan_sip.c: Trying to put 'ACK sip:moz' onto TLS socket destined for [office.ip]:5062
[Feb 19 01:04:48] DEBUG[23726][C-00008973] chan_sip.c: Setting SIP_ALREADYGONE on dialog 70f7c3491197a22a5dc0e3d809bce2df@[ast.srv.ip]:5061
[Feb 19 01:04:48] VERBOSE[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-420-0001f8e8 is busy
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: Dial End message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-420-0001f8e8: 1455829488.00519156
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029c88 - Processing Dial End message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-420-0001f8e8
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030029c88 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Dial to Finalized
[Feb 19 01:04:48] DEBUG[8873] cdr.c: Finalized CDR for SIP/[TRUNK_NAME]-0001f8dd - start 1455829488.442288 answer 1455829488.442289 end 1455829488.519200 dispo BUSY
[Feb 19 01:04:48] VERBOSE[6569][C-00008973] app_queue.c: Nobody picked up in 0 ms
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:48.519245', '', '', '', '', '0', 'RINGNOANSWER', 'SIP/[COMPANY_NAME]-420', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:48] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[COMPANY_NAME]-420-0001f8e8'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[COMPANY_NAME]-420-0001f8e8, SIP callid 70f7c3491197a22a5dc0e3d809bce2df@[ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c0d1108'
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-420
[Feb 19 01:04:48] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-420
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-420 - state 1 (Not in use)
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030019918 - Transitioning CDR for SIP/[COMPANY_NAME]-420-0001f8e8 from state Single to Finalized
[Feb 19 01:04:48] DEBUG[8873] cdr.c: Finalized CDR for SIP/[COMPANY_NAME]-420-0001f8e8 - start 1455829488.442006 answer 0.000000 end 1455829488.524664 dispo BUSY
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030019918 - Beginning finalize/dispatch for SIP/[COMPANY_NAME]-420-0001f8e8
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb030019918 - Dispatching CDR for Party A SIP/[COMPANY_NAME]-420-0001f8e8, Party B <none>
[Feb 19 01:04:48] DEBUG[8873] cdr.c: CDR for SIP/[COMPANY_NAME]-420-0001f8e8 is dialed and has no Party B; discarding
[Feb 19 01:04:48] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-420' changed to state '1' (Not in use)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] app_queue.c: Trying 'SIP/[COMPANY_NAME]-421' with metric 3
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-420
[Feb 19 01:04:48] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-420
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-420 - state 1 (Not in use)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Allocating new SIP dialog for 575ac53c5dd4d94c7803ac11758adc45@[::1]:5060 - INVITE (No RTP)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Allocated port 27456 for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:27456 (27456) for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:48] DEBUG[6569][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:48] DEBUG[6569][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:27456, base=[ast.srv.ip]:27456, prio=0x7effffff (2130706431)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] rtp_engine.c: RTP instance '0x7fb05c0108d8' is setup and ready to go
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Destroying ICE session 0x7fb05c09c588
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c1 STUN session 0x7fb05c062de8 destroy request, ref_cnt=4
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c1ce2b8 destroy request, ref_cnt=3
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb05c09c588 destroyed
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c062de8 destroyed
[Feb 19 01:04:48] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c1ce2b8 destroyed
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:48] VERBOSE[6569][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:48] DEBUG[6569][C-00008973] acl.c: For destination '[office.ip]', our source address is '[ast.srv.ip]'.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[6569][C-00008973] netsock2.c: Splitting '192.168.240.207:5060' into...
[Feb 19 01:04:48] DEBUG[6569][C-00008973] netsock2.c: ...host '192.168.240.207' and port '5060'.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: NAT detected for 192.168.240.207 / [office.ip]
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: SIP call-id changed from '575ac53c5dd4d94c7803ac11758adc45@[::1]:5060' to '446c944a221ab527060af600059b464e@[ast.srv.ip]:5061'
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03002a088 - Created CDR for channel SIP/[COMPANY_NAME]-421-0001f8e9
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03002a088 - Transitioning CDR for SIP/[COMPANY_NAME]-421-0001f8e9 from state NONE to Single
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** Our native formats are (ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** Joint capabilities are (ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:48] DEBUG[6569][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 19 01:04:48] DEBUG[6569][C-00008973] channel_internal_api.c: Channel Call ID changing from [C-00008973] to [C-00008973]
[Feb 19 01:04:48] DEBUG[8899] chan_sip.c: Destroying SIP dialog 70f7c3491197a22a5dc0e3d809bce2df@[ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[8899] rtp_engine.c: Destroyed RTP instance '0x7fb05c0d1108'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Outgoing Call for [COMPANY_NAME]-421
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-421
[Feb 19 01:04:48] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-421
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-421 - state 6 (Ringing)
[Feb 19 01:04:48] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-421' changed to state '6' (Ringing)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (ulaw|g722|alaw) Video flag: False Text flag: False
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (ulaw) 
[Feb 19 01:04:48] DEBUG[6569][C-00008973] sdp_srtp.c: local_key64 34gFXS28SXdh7QGBQO8HgRPxnNnwxKf8NxuOkcXC len 40
[Feb 19 01:04:48] DEBUG[6569][C-00008973] sdp_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:34gFXS28SXdh7QGBQO8HgRPxnNnwxKf8NxuOkcXC
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722|alaw)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Initializing initreq for method INVITE - callid 446c944a221ab527060af600059b464e@[ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'INVITE sip:' onto TLS socket destined for [office.ip]:27493
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: Dial Begin message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-421-0001f8e9: 1455829488.00525317
[Feb 19 01:04:48] VERBOSE[6569][C-00008973] app_queue.c: Called SIP/[COMPANY_NAME]-421
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03001a158 - Created CDR for channel SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03001a158 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state NONE to Single
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03001a158 - Set answered time to 1455829488.525331
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03001a158 - Updated Party A SIP/[TRUNK_NAME]-0001f8dd snapshot
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03001a158 - Updated Party B SIP/[COMPANY_NAME]-421-0001f8e9 snapshot
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03001a158 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Single to Dial
[Feb 19 01:04:48] DEBUG[23714] chan_sip.c: = Looking for  Call ID: 446c944a221ab527060af600059b464e@[ast.srv.ip]:5061 (Checking To) --From tag as2d2f6a1e --To-tag   
[Feb 19 01:04:48] DEBUG[23714][C-00008973] chan_sip.c: SIP response 100 to standard invite
[Feb 19 01:04:48] DEBUG[23714] chan_sip.c: = Looking for  Call ID: 446c944a221ab527060af600059b464e@[ast.srv.ip]:5061 (Checking To) --From tag as2d2f6a1e --To-tag fca68fc88e789dai0  
[Feb 19 01:04:48] VERBOSE[23714][C-00008973] chan_sip.c: Got SIP response 486 "Busy Here" back from [office.ip]:27493
[Feb 19 01:04:48] DEBUG[23714][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:48] DEBUG[23714][C-00008973] chan_sip.c: Trying to put 'ACK sip:moz' onto TLS socket destined for [office.ip]:27493
[Feb 19 01:04:48] DEBUG[23714][C-00008973] chan_sip.c: Setting SIP_ALREADYGONE on dialog 446c944a221ab527060af600059b464e@[ast.srv.ip]:5061
[Feb 19 01:04:48] VERBOSE[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-421-0001f8e9 is busy
[Feb 19 01:04:48] VERBOSE[6569][C-00008973] app_queue.c: Nobody picked up in 0 ms
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: Dial End message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-421-0001f8e9: 1455829488.00590049
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03001a158 - Processing Dial End message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-421-0001f8e9
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03001a158 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Dial to Finalized
[Feb 19 01:04:48] DEBUG[8873] cdr.c: Finalized CDR for SIP/[TRUNK_NAME]-0001f8dd - start 1455829488.525331 answer 1455829488.525331 end 1455829488.590091 dispo BUSY
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:48.590104', '', '', '', '', '0', 'RINGNOANSWER', 'SIP/[COMPANY_NAME]-421', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:48] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[COMPANY_NAME]-421-0001f8e9'
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[COMPANY_NAME]-421-0001f8e9, SIP callid 446c944a221ab527060af600059b464e@[ast.srv.ip]:5061
[Feb 19 01:04:48] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-421
[Feb 19 01:04:48] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-421
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-421 - state 1 (Not in use)
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03002a088 - Transitioning CDR for SIP/[COMPANY_NAME]-421-0001f8e9 from state Single to Finalized
[Feb 19 01:04:48] DEBUG[8873] cdr.c: Finalized CDR for SIP/[COMPANY_NAME]-421-0001f8e9 - start 1455829488.525079 answer 0.000000 end 1455829488.599842 dispo BUSY
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03002a088 - Beginning finalize/dispatch for SIP/[COMPANY_NAME]-421-0001f8e9
[Feb 19 01:04:48] VERBOSE[8873] cdr.c: 0x7fb03002a088 - Dispatching CDR for Party A SIP/[COMPANY_NAME]-421-0001f8e9, Party B <none>
[Feb 19 01:04:48] DEBUG[8873] cdr.c: CDR for SIP/[COMPANY_NAME]-421-0001f8e9 is dialed and has no Party B; discarding
[Feb 19 01:04:48] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-421' changed to state '1' (Not in use)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] app_queue.c: Nobody left to try ringing in queue
[Feb 19 01:04:48] DEBUG[6569][C-00008973] app_queue.c: Everyone is busy at this time
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-421
[Feb 19 01:04:48] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-421
[Feb 19 01:04:48] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-421 - state 1 (Not in use)
[Feb 19 01:04:48] DEBUG[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-418 is available.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:48] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM queue_members WHERE interface LIKE '%' AND queue_name = '[COMPANY_NAME]' ORDER BY interface
##################################################
SOME PROBABLY UNRELATED DEBUG DATA REMOVED HERE
##################################################
[Feb 19 01:04:53] DEBUG[6569][C-00008973] app_queue.c: There is 1 available member.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] app_queue.c: It's our turn (SIP/[TRUNK_NAME]-0001f8dd).
[Feb 19 01:04:53] DEBUG[6569][C-00008973] app_queue.c: SIP/[TRUNK_NAME]-0001f8dd is trying to call a queue member.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] app_queue.c: Trying 'SIP/[COMPANY_NAME]-418' with metric 0
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Allocating new SIP dialog for 3a4c312354160443062fde3f006b6b93@[::1]:5060 - INVITE (No RTP)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Allocated port 27610 for RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:27610 (27610) for RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:53] DEBUG[6569][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:53] DEBUG[6569][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:27610, base=[ast.srv.ip]:27610, prio=0x7effffff (2130706431)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] rtp_engine.c: RTP instance '0x7fb05c1729b8' is setup and ready to go
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Destroying ICE session 0x7fb05c09c588
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c1 STUN session 0x7fb05c2c9bf8 destroy request, ref_cnt=4
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c062de8 destroy request, ref_cnt=3
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb05c09c588 destroyed
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c2c9bf8 destroyed
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c062de8 destroyed
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:53] VERBOSE[6569][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:53] DEBUG[6569][C-00008973] acl.c: For destination '[office.ip]', our source address is '[ast.srv.ip]'.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:53] DEBUG[6569][C-00008973] netsock2.c: Splitting '192.168.240.210:5073' into...
[Feb 19 01:04:53] DEBUG[6569][C-00008973] netsock2.c: ...host '192.168.240.210' and port '5073'.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: NAT detected for 192.168.240.210 / [office.ip]
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: SIP call-id changed from '3a4c312354160443062fde3f006b6b93@[::1]:5060' to '3058a5d436c4b5af0c6137240a0c7f9c@[ast.srv.ip]:5061'
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030019918 - Created CDR for channel SIP/[COMPANY_NAME]-418-0001f8ea
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** Our native formats are (ulaw) 
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030019918 - Transitioning CDR for SIP/[COMPANY_NAME]-418-0001f8ea from state NONE to Single
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** Joint capabilities are (ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:53] DEBUG[6569][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 19 01:04:53] DEBUG[6569][C-00008973] channel_internal_api.c: Channel Call ID changing from [C-00008973] to [C-00008973]
[Feb 19 01:04:53] DEBUG[8899] chan_sip.c: Destroying SIP dialog 345265126e6cf3f768588d77444d6c35@[ast.srv.ip]:5061
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Outgoing Call for [COMPANY_NAME]-418
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-418
[Feb 19 01:04:53] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-418
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-418 - state 6 (Ringing)
[Feb 19 01:04:53] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-418' changed to state '6' (Ringing)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (ulaw|g722|alaw) Video flag: False Text flag: False
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] sdp_srtp.c: local_key64 6POU4T7od0ggW7CniiLhnbCm7U7tO6qIlrOkxtbP len 40
[Feb 19 01:04:53] DEBUG[6569][C-00008973] sdp_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:6POU4T7od0ggW7CniiLhnbCm7U7tO6qIlrOkxtbP
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722|alaw)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Initializing initreq for method INVITE - callid 3058a5d436c4b5af0c6137240a0c7f9c@[ast.srv.ip]:5061
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'INVITE sip:' onto TLS socket destined for [office.ip]:5073
[Feb 19 01:04:53] VERBOSE[6569][C-00008973] app_queue.c: Called SIP/[COMPANY_NAME]-418
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: Dial Begin message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-418-0001f8ea: 1455829493.00601014
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001a998 - Created CDR for channel SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001a998 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state NONE to Single
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001a998 - Set answered time to 1455829493.601031
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001a998 - Updated Party A SIP/[TRUNK_NAME]-0001f8dd snapshot
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001a998 - Updated Party B SIP/[COMPANY_NAME]-418-0001f8ea snapshot
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001a998 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Single to Dial
[Feb 19 01:04:53] DEBUG[23724] chan_sip.c: = Looking for  Call ID: 3058a5d436c4b5af0c6137240a0c7f9c@[ast.srv.ip]:5061 (Checking To) --From tag as63407f06 --To-tag   
[Feb 19 01:04:53] DEBUG[23724][C-00008973] chan_sip.c: SIP response 100 to standard invite
[Feb 19 01:04:53] DEBUG[23724] chan_sip.c: = Looking for  Call ID: 3058a5d436c4b5af0c6137240a0c7f9c@[ast.srv.ip]:5061 (Checking To) --From tag as63407f06 --To-tag d17727b963a111eai0  
[Feb 19 01:04:53] VERBOSE[23724][C-00008973] chan_sip.c: Got SIP response 486 "Busy Here" back from [office.ip]:5073
[Feb 19 01:04:53] DEBUG[23724][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:53] DEBUG[23724][C-00008973] chan_sip.c: Trying to put 'ACK sip:moz' onto TLS socket destined for [office.ip]:5073
[Feb 19 01:04:53] DEBUG[23724][C-00008973] chan_sip.c: Setting SIP_ALREADYGONE on dialog 3058a5d436c4b5af0c6137240a0c7f9c@[ast.srv.ip]:5061
[Feb 19 01:04:53] VERBOSE[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-418-0001f8ea is busy
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: Dial End message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-418-0001f8ea: 1455829493.00672194
[Feb 19 01:04:53] VERBOSE[6569][C-00008973] app_queue.c: Nobody picked up in 0 ms
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001a998 - Processing Dial End message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-418-0001f8ea
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001a998 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Dial to Finalized
[Feb 19 01:04:53] DEBUG[8873] cdr.c: Finalized CDR for SIP/[TRUNK_NAME]-0001f8dd - start 1455829493.601031 answer 1455829493.601031 end 1455829493.672246 dispo BUSY
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:53.672284', '', '', '', '', '0', 'RINGNOANSWER', 'SIP/[COMPANY_NAME]-418', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:53] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[COMPANY_NAME]-418-0001f8ea'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[COMPANY_NAME]-418-0001f8ea, SIP callid 3058a5d436c4b5af0c6137240a0c7f9c@[ast.srv.ip]:5061
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-418
[Feb 19 01:04:53] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-418
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-418 - state 1 (Not in use)
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030019918 - Transitioning CDR for SIP/[COMPANY_NAME]-418-0001f8ea from state Single to Finalized
[Feb 19 01:04:53] DEBUG[8873] cdr.c: Finalized CDR for SIP/[COMPANY_NAME]-418-0001f8ea - start 1455829493.600737 answer 0.000000 end 1455829493.690304 dispo BUSY
[Feb 19 01:04:53] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-418' changed to state '1' (Not in use)
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030019918 - Beginning finalize/dispatch for SIP/[COMPANY_NAME]-418-0001f8ea
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030019918 - Dispatching CDR for Party A SIP/[COMPANY_NAME]-418-0001f8ea, Party B <none>
[Feb 19 01:04:53] DEBUG[8873] cdr.c: CDR for SIP/[COMPANY_NAME]-418-0001f8ea is dialed and has no Party B; discarding
[Feb 19 01:04:53] DEBUG[6569][C-00008973] app_queue.c: Trying 'SIP/[COMPANY_NAME]-419' with metric 1
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-418
[Feb 19 01:04:53] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-418
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-418 - state 1 (Not in use)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Allocating new SIP dialog for 7b2ff22b562976c60206733d4ead4548@[::1]:5060 - INVITE (No RTP)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb05c06b948'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Allocated port 26506 for RTP instance '0x7fb05c06b948'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:26506 (26506) for RTP instance '0x7fb05c06b948'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:53] DEBUG[6569][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:53] DEBUG[6569][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:26506, base=[ast.srv.ip]:26506, prio=0x7effffff (2130706431)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] rtp_engine.c: RTP instance '0x7fb05c06b948' is setup and ready to go
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Destroying ICE session 0x7fb05c09c588
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c1 STUN session 0x7fb05c2c9bf8 destroy request, ref_cnt=4
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c0acb08 destroy request, ref_cnt=3
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb05c09c588 destroyed
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c2c9bf8 destroyed
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c0acb08 destroyed
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb05c06b948'
[Feb 19 01:04:53] VERBOSE[6569][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:53] DEBUG[6569][C-00008973] acl.c: For destination '[office.ip]', our source address is '[ast.srv.ip]'.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:53] DEBUG[6569][C-00008973] netsock2.c: Splitting '192.168.240.208:5074' into...
[Feb 19 01:04:53] DEBUG[6569][C-00008973] netsock2.c: ...host '192.168.240.208' and port '5074'.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: NAT detected for 192.168.240.208 / [office.ip]
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: SIP call-id changed from '7b2ff22b562976c60206733d4ead4548@[::1]:5060' to '62747be871aad2b94f1b1e0b1bddd6ac@[ast.srv.ip]:5061'
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001ad98 - Created CDR for channel SIP/[COMPANY_NAME]-419-0001f8eb
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001ad98 - Transitioning CDR for SIP/[COMPANY_NAME]-419-0001f8eb from state NONE to Single
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** Our native formats are (ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** Joint capabilities are (ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:53] DEBUG[6569][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 19 01:04:53] DEBUG[6569][C-00008973] channel_internal_api.c: Channel Call ID changing from [C-00008973] to [C-00008973]
[Feb 19 01:04:53] DEBUG[8899] chan_sip.c: Destroying SIP dialog 3058a5d436c4b5af0c6137240a0c7f9c@[ast.srv.ip]:5061
[Feb 19 01:04:53] DEBUG[8899] rtp_engine.c: Destroyed RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Outgoing Call for [COMPANY_NAME]-419
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-419
[Feb 19 01:04:53] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-419
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-419 - state 6 (Ringing)
[Feb 19 01:04:53] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-419' changed to state '6' (Ringing)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (ulaw|g722|alaw) Video flag: False Text flag: False
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] sdp_srtp.c: local_key64 boUxG/RgGdMZYrNtJyr5liuszTN7DpCVcx25FZd1 len 40
[Feb 19 01:04:53] DEBUG[6569][C-00008973] sdp_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:boUxG/RgGdMZYrNtJyr5liuszTN7DpCVcx25FZd1
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722|alaw)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Initializing initreq for method INVITE - callid 62747be871aad2b94f1b1e0b1bddd6ac@[ast.srv.ip]:5061
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'INVITE sip:' onto TLS socket destined for [office.ip]:5074
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: Dial Begin message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-419-0001f8eb: 1455829493.00691025
[Feb 19 01:04:53] VERBOSE[6569][C-00008973] app_queue.c: Called SIP/[COMPANY_NAME]-419
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001a558 - Created CDR for channel SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001a558 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state NONE to Single
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001a558 - Set answered time to 1455829493.691043
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001a558 - Updated Party A SIP/[TRUNK_NAME]-0001f8dd snapshot
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001a558 - Updated Party B SIP/[COMPANY_NAME]-419-0001f8eb snapshot
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001a558 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Single to Dial
[Feb 19 01:04:53] DEBUG[23717] chan_sip.c: = Looking for  Call ID: 62747be871aad2b94f1b1e0b1bddd6ac@[ast.srv.ip]:5061 (Checking To) --From tag as4ddf785b --To-tag   
[Feb 19 01:04:53] DEBUG[23717][C-00008973] chan_sip.c: SIP response 100 to standard invite
[Feb 19 01:04:53] DEBUG[23717] chan_sip.c: = Looking for  Call ID: 62747be871aad2b94f1b1e0b1bddd6ac@[ast.srv.ip]:5061 (Checking To) --From tag as4ddf785b --To-tag 34390fdcc440b6i0  
[Feb 19 01:04:53] VERBOSE[23717][C-00008973] chan_sip.c: Got SIP response 486 "Busy Here" back from [office.ip]:5074
[Feb 19 01:04:53] DEBUG[23717][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c06b948'
[Feb 19 01:04:53] DEBUG[23717][C-00008973] chan_sip.c: Trying to put 'ACK sip:moz' onto TLS socket destined for [office.ip]:5074
[Feb 19 01:04:53] DEBUG[23717][C-00008973] chan_sip.c: Setting SIP_ALREADYGONE on dialog 62747be871aad2b94f1b1e0b1bddd6ac@[ast.srv.ip]:5061
[Feb 19 01:04:53] VERBOSE[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-419-0001f8eb is busy
[Feb 19 01:04:53] VERBOSE[6569][C-00008973] app_queue.c: Nobody picked up in 0 ms
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: Dial End message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-419-0001f8eb: 1455829493.00765230
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001a558 - Processing Dial End message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-419-0001f8eb
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001a558 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Dial to Finalized
[Feb 19 01:04:53] DEBUG[8873] cdr.c: Finalized CDR for SIP/[TRUNK_NAME]-0001f8dd - start 1455829493.691043 answer 1455829493.691043 end 1455829493.765277 dispo BUSY
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:53.765287', '', '', '', '', '0', 'RINGNOANSWER', 'SIP/[COMPANY_NAME]-419', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:53] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[COMPANY_NAME]-419-0001f8eb'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[COMPANY_NAME]-419-0001f8eb, SIP callid 62747be871aad2b94f1b1e0b1bddd6ac@[ast.srv.ip]:5061
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c06b948'
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-419
[Feb 19 01:04:53] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-419
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-419 - state 1 (Not in use)
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001ad98 - Transitioning CDR for SIP/[COMPANY_NAME]-419-0001f8eb from state Single to Finalized
[Feb 19 01:04:53] DEBUG[8873] cdr.c: Finalized CDR for SIP/[COMPANY_NAME]-419-0001f8eb - start 1455829493.690774 answer 0.000000 end 1455829493.775189 dispo BUSY
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001ad98 - Beginning finalize/dispatch for SIP/[COMPANY_NAME]-419-0001f8eb
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001ad98 - Dispatching CDR for Party A SIP/[COMPANY_NAME]-419-0001f8eb, Party B <none>
[Feb 19 01:04:53] DEBUG[8873] cdr.c: CDR for SIP/[COMPANY_NAME]-419-0001f8eb is dialed and has no Party B; discarding
[Feb 19 01:04:53] DEBUG[6569][C-00008973] app_queue.c: Trying 'SIP/[COMPANY_NAME]-420' with metric 2
[Feb 19 01:04:53] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-419' changed to state '1' (Not in use)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-419
[Feb 19 01:04:53] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-419
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-419 - state 1 (Not in use)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Allocating new SIP dialog for 2daac53326c23c096050e0ea54aeae42@[::1]:5060 - INVITE (No RTP)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Allocated port 21580 for RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:21580 (21580) for RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c1 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:53] DEBUG[6569][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:53] DEBUG[6569][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c1 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:21580, base=[ast.srv.ip]:21580, prio=0x7effffff (2130706431)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] rtp_engine.c: RTP instance '0x7fb05c1729b8' is setup and ready to go
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c1 Destroying ICE session 0x7fb05c121a78
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c1 STUN session 0x7fb05c2c9bf8 destroy request, ref_cnt=4
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c023928 destroy request, ref_cnt=3
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb05c121a78 destroyed
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c2c9bf8 destroyed
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c023928 destroyed
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:53] VERBOSE[6569][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:53] DEBUG[6569][C-00008973] acl.c: For destination '[office.ip]', our source address is '[ast.srv.ip]'.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:53] DEBUG[6569][C-00008973] netsock2.c: Splitting '192.168.240.209:5062' into...
[Feb 19 01:04:53] DEBUG[6569][C-00008973] netsock2.c: ...host '192.168.240.209' and port '5062'.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: NAT detected for 192.168.240.209 / [office.ip]
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: SIP call-id changed from '2daac53326c23c096050e0ea54aeae42@[::1]:5060' to '08ccb39e6d2cffb403b1337929c4b8f2@[ast.srv.ip]:5061'
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001ad98 - Created CDR for channel SIP/[COMPANY_NAME]-420-0001f8ec
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** Our native formats are (ulaw) 
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001ad98 - Transitioning CDR for SIP/[COMPANY_NAME]-420-0001f8ec from state NONE to Single
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** Joint capabilities are (ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:53] DEBUG[6569][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 19 01:04:53] DEBUG[8899] chan_sip.c: Destroying SIP dialog 62747be871aad2b94f1b1e0b1bddd6ac@[ast.srv.ip]:5061
[Feb 19 01:04:53] DEBUG[8899] rtp_engine.c: Destroyed RTP instance '0x7fb05c06b948'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] channel_internal_api.c: Channel Call ID changing from [C-00008973] to [C-00008973]
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Outgoing Call for [COMPANY_NAME]-420
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-420
[Feb 19 01:04:53] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-420
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-420 - state 6 (Ringing)
[Feb 19 01:04:53] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-420' changed to state '6' (Ringing)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (ulaw|g722|alaw) Video flag: False Text flag: False
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] sdp_srtp.c: local_key64 6jYyUH6CLydAQ1lfaWz1A3lgF0PkwzMn3EiP5xj4 len 40
[Feb 19 01:04:53] DEBUG[6569][C-00008973] sdp_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:6jYyUH6CLydAQ1lfaWz1A3lgF0PkwzMn3EiP5xj4
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722|alaw)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Initializing initreq for method INVITE - callid 08ccb39e6d2cffb403b1337929c4b8f2@[ast.srv.ip]:5061
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'INVITE sip:' onto TLS socket destined for [office.ip]:5062
[Feb 19 01:04:53] VERBOSE[6569][C-00008973] app_queue.c: Called SIP/[COMPANY_NAME]-420
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: Dial Begin message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-420-0001f8ec: 1455829493.00775848
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030007e88 - Created CDR for channel SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030007e88 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state NONE to Single
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030007e88 - Set answered time to 1455829493.775864
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030007e88 - Updated Party A SIP/[TRUNK_NAME]-0001f8dd snapshot
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030007e88 - Updated Party B SIP/[COMPANY_NAME]-420-0001f8ec snapshot
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030007e88 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Single to Dial
[Feb 19 01:04:53] DEBUG[23726] chan_sip.c: = Looking for  Call ID: 08ccb39e6d2cffb403b1337929c4b8f2@[ast.srv.ip]:5061 (Checking To) --From tag as1daa5e00 --To-tag   
[Feb 19 01:04:53] DEBUG[23726][C-00008973] chan_sip.c: SIP response 100 to standard invite
[Feb 19 01:04:53] DEBUG[23726] chan_sip.c: = Looking for  Call ID: 08ccb39e6d2cffb403b1337929c4b8f2@[ast.srv.ip]:5061 (Checking To) --From tag as1daa5e00 --To-tag 156a27e5d9c82f6ai0  
[Feb 19 01:04:53] VERBOSE[23726][C-00008973] chan_sip.c: Got SIP response 486 "Busy Here" back from [office.ip]:5062
[Feb 19 01:04:53] DEBUG[23726][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:53] DEBUG[23726][C-00008973] chan_sip.c: Trying to put 'ACK sip:moz' onto TLS socket destined for [office.ip]:5062
[Feb 19 01:04:53] DEBUG[23726][C-00008973] chan_sip.c: Setting SIP_ALREADYGONE on dialog 08ccb39e6d2cffb403b1337929c4b8f2@[ast.srv.ip]:5061
[Feb 19 01:04:53] VERBOSE[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-420-0001f8ec is busy
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: Dial End message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-420-0001f8ec: 1455829493.00849093
[Feb 19 01:04:53] VERBOSE[6569][C-00008973] app_queue.c: Nobody picked up in 0 ms
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030007e88 - Processing Dial End message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-420-0001f8ec
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030007e88 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Dial to Finalized
[Feb 19 01:04:53] DEBUG[8873] cdr.c: Finalized CDR for SIP/[TRUNK_NAME]-0001f8dd - start 1455829493.775864 answer 1455829493.775864 end 1455829493.849148 dispo BUSY
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:53.849175', '', '', '', '', '0', 'RINGNOANSWER', 'SIP/[COMPANY_NAME]-420', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:53] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[COMPANY_NAME]-420-0001f8ec'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[COMPANY_NAME]-420-0001f8ec, SIP callid 08ccb39e6d2cffb403b1337929c4b8f2@[ast.srv.ip]:5061
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-420
[Feb 19 01:04:53] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-420
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-420 - state 1 (Not in use)
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001ad98 - Transitioning CDR for SIP/[COMPANY_NAME]-420-0001f8ec from state Single to Finalized
[Feb 19 01:04:53] DEBUG[8873] cdr.c: Finalized CDR for SIP/[COMPANY_NAME]-420-0001f8ec - start 1455829493.775566 answer 0.000000 end 1455829493.858542 dispo BUSY
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001ad98 - Beginning finalize/dispatch for SIP/[COMPANY_NAME]-420-0001f8ec
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001ad98 - Dispatching CDR for Party A SIP/[COMPANY_NAME]-420-0001f8ec, Party B <none>
[Feb 19 01:04:53] DEBUG[8873] cdr.c: CDR for SIP/[COMPANY_NAME]-420-0001f8ec is dialed and has no Party B; discarding
[Feb 19 01:04:53] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-420' changed to state '1' (Not in use)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] app_queue.c: Trying 'SIP/[COMPANY_NAME]-421' with metric 3
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-420
[Feb 19 01:04:53] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-420
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Asked to create a SIP channel with formats: (ulaw)
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-420 - state 1 (Not in use)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Allocating new SIP dialog for 483ad2cd4851aff004cc849802096d89@[::1]:5060 - INVITE (No RTP)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Allocated port 22500 for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:22500 (22500) for RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 ICE session created, comp_cnt=2, role is Unknown agent
[Feb 19 01:04:53] DEBUG[6569][C-00008973] netsock2.c: Splitting '[ast.srv.ip]' into...
[Feb 19 01:04:53] DEBUG[6569][C-00008973] netsock2.c: ...host '[ast.srv.ip]' and port ''.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Candidate 0 added: comp_id=1, type=host, foundation=H505387c6, addr=[ast.srv.ip]:22500, base=[ast.srv.ip]:22500, prio=0x7effffff (2130706431)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] rtp_engine.c: RTP instance '0x7fb05c0108d8' is setup and ready to go
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	icess0x7fb05c0 Destroying ICE session 0x7fb05c0c8908
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c1 STUN session 0x7fb05c2c9bf8 destroy request, ref_cnt=4
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	stuse0x7fb05c0 STUN session 0x7fb05c0447f8 destroy request, ref_cnt=3
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	 ice_session.c ICE session 0x7fb05c0c8908 destroyed
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c2c9bf8 destroyed
[Feb 19 01:04:53] DEBUG[6569][C-00008973] pjsip: 	stun_session.c STUN session 0x7fb05c0447f8 destroyed
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:53] VERBOSE[6569][C-00008973] netsock2.c: Using SIP RTP CoS mark 5
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:53] DEBUG[6569][C-00008973] acl.c: For destination '[office.ip]', our source address is '[ast.srv.ip]'.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Setting AST_TRANSPORT_TLS with address [ast.srv.ip]:5061
[Feb 19 01:04:53] DEBUG[6569][C-00008973] netsock2.c: Splitting '192.168.240.207:5060' into...
[Feb 19 01:04:53] DEBUG[6569][C-00008973] netsock2.c: ...host '192.168.240.207' and port '5060'.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: NAT detected for 192.168.240.207 / [office.ip]
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Setting NAT on RTP to On
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: SIP call-id changed from '483ad2cd4851aff004cc849802096d89@[::1]:5060' to '10f29ad41e920c892c869d3c44171282@[ast.srv.ip]:5061'
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001ad98 - Created CDR for channel SIP/[COMPANY_NAME]-421-0001f8ed
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001ad98 - Transitioning CDR for SIP/[COMPANY_NAME]-421-0001f8ed from state NONE to Single
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** Our native formats are (ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** Joint capabilities are (ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** Our capabilities are (g722|alaw|ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: This channel will not be able to handle video.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Feb 19 01:04:53] DEBUG[6569][C-00008973] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Feb 19 01:04:53] DEBUG[6569][C-00008973] channel_internal_api.c: Channel Call ID changing from [C-00008973] to [C-00008973]
[Feb 19 01:04:53] DEBUG[8899] chan_sip.c: Destroying SIP dialog 08ccb39e6d2cffb403b1337929c4b8f2@[ast.srv.ip]:5061
[Feb 19 01:04:53] DEBUG[8899] rtp_engine.c: Destroyed RTP instance '0x7fb05c1729b8'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Outgoing Call for [COMPANY_NAME]-421
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-421
[Feb 19 01:04:53] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-421
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-421 - state 6 (Ringing)
[Feb 19 01:04:53] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-421' changed to state '6' (Ringing)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: ** Our capability: (ulaw|g722|alaw) Video flag: False Text flag: False
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: ** Our prefcodec: (ulaw) 
[Feb 19 01:04:53] DEBUG[6569][C-00008973] sdp_srtp.c: local_key64 8iEt244AMGPjiRmkjJkuVWuBvduRPpWxeTriU9dm len 40
[Feb 19 01:04:53] DEBUG[6569][C-00008973] sdp_srtp.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:8iEt244AMGPjiRmkjJkuVWuBvduRPpWxeTriU9dm
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: -- Done with adding codecs to SDP
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|g722|alaw)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Initializing initreq for method INVITE - callid 10f29ad41e920c892c869d3c44171282@[ast.srv.ip]:5061
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Trying to put 'INVITE sip:' onto TLS socket destined for [office.ip]:27493
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: Dial Begin message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-421-0001f8ed: 1455829493.00859191
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030019d18 - Created CDR for channel SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:53] VERBOSE[6569][C-00008973] app_queue.c: Called SIP/[COMPANY_NAME]-421
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030019d18 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state NONE to Single
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030019d18 - Set answered time to 1455829493.859205
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030019d18 - Updated Party A SIP/[TRUNK_NAME]-0001f8dd snapshot
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030019d18 - Updated Party B SIP/[COMPANY_NAME]-421-0001f8ed snapshot
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030019d18 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Single to Dial
[Feb 19 01:04:53] DEBUG[23714] chan_sip.c: = Looking for  Call ID: 10f29ad41e920c892c869d3c44171282@[ast.srv.ip]:5061 (Checking To) --From tag as18f23a1e --To-tag   
[Feb 19 01:04:53] DEBUG[23714][C-00008973] chan_sip.c: SIP response 100 to standard invite
[Feb 19 01:04:53] DEBUG[23714] chan_sip.c: = Looking for  Call ID: 10f29ad41e920c892c869d3c44171282@[ast.srv.ip]:5061 (Checking To) --From tag as18f23a1e --To-tag fca68fc88e789dai0  
[Feb 19 01:04:53] VERBOSE[23714][C-00008973] chan_sip.c: Got SIP response 486 "Busy Here" back from [office.ip]:27493
[Feb 19 01:04:53] DEBUG[23714][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:53] DEBUG[23714][C-00008973] chan_sip.c: Trying to put 'ACK sip:moz' onto TLS socket destined for [office.ip]:27493
[Feb 19 01:04:53] DEBUG[23714][C-00008973] chan_sip.c: Setting SIP_ALREADYGONE on dialog 10f29ad41e920c892c869d3c44171282@[ast.srv.ip]:5061
[Feb 19 01:04:53] VERBOSE[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-421-0001f8ed is busy
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: Dial End message for SIP/[TRUNK_NAME]-0001f8dd, SIP/[COMPANY_NAME]-421-0001f8ed: 1455829493.00931111
[Feb 19 01:04:53] VERBOSE[6569][C-00008973] app_queue.c: Nobody picked up in 0 ms
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030019d18 - Processing Dial End message for channel SIP/[TRUNK_NAME]-0001f8dd, peer SIP/[COMPANY_NAME]-421-0001f8ed
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb030019d18 - Transitioning CDR for SIP/[TRUNK_NAME]-0001f8dd from state Dial to Finalized
[Feb 19 01:04:53] DEBUG[8873] cdr.c: Finalized CDR for SIP/[TRUNK_NAME]-0001f8dd - start 1455829493.859205 answer 1455829493.859205 end 1455829493.931158 dispo BUSY
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:53.931195', '', '', '', '', '0', 'RINGNOANSWER', 'SIP/[COMPANY_NAME]-421', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:53] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[COMPANY_NAME]-421-0001f8ed'
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[COMPANY_NAME]-421-0001f8ed, SIP callid 10f29ad41e920c892c869d3c44171282@[ast.srv.ip]:5061
[Feb 19 01:04:53] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for outgoing call
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb05c0108d8'
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-421
[Feb 19 01:04:53] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-421
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-421 - state 1 (Not in use)
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001ad98 - Transitioning CDR for SIP/[COMPANY_NAME]-421-0001f8ed from state Single to Finalized
[Feb 19 01:04:53] DEBUG[8873] cdr.c: Finalized CDR for SIP/[COMPANY_NAME]-421-0001f8ed - start 1455829493.858927 answer 0.000000 end 1455829493.942038 dispo BUSY
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001ad98 - Beginning finalize/dispatch for SIP/[COMPANY_NAME]-421-0001f8ed
[Feb 19 01:04:53] VERBOSE[8873] cdr.c: 0x7fb03001ad98 - Dispatching CDR for Party A SIP/[COMPANY_NAME]-421-0001f8ed, Party B <none>
[Feb 19 01:04:53] DEBUG[8873] cdr.c: CDR for SIP/[COMPANY_NAME]-421-0001f8ed is dialed and has no Party B; discarding
[Feb 19 01:04:53] DEBUG[8928] app_queue.c: Device 'SIP/[COMPANY_NAME]-421' changed to state '1' (Not in use)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] app_queue.c: Nobody left to try ringing in queue
[Feb 19 01:04:53] DEBUG[6569][C-00008973] app_queue.c: Everyone is busy at this time
[Feb 19 01:04:53] DEBUG[6569][C-00008973] app_queue.c: SIP/[COMPANY_NAME]-418 is available.
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [COMPANY_NAME]-421
[Feb 19 01:04:53] DEBUG[8870] chan_sip.c: Checking device state for peer [COMPANY_NAME]-421
[Feb 19 01:04:53] DEBUG[8870] devicestate.c: Changing state for SIP/[COMPANY_NAME]-421 - state 1 (Not in use)
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:53] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM queue_members WHERE interface LIKE '%' AND queue_name = '[COMPANY_NAME]' ORDER BY interface
##################################################
SOME PROBABLY UNRELATED DEBUG DATA REMOVED HERE
##################################################
[Feb 19 01:04:55] DEBUG[8899][C-00008973] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[Feb 19 01:04:55] DEBUG[8899][C-00008973] netsock2.c: Splitting '[trunk.ip]:5060' into...
[Feb 19 01:04:55] DEBUG[8899][C-00008973] netsock2.c: ...host '[trunk.ip]' and port '5060'.
[Feb 19 01:04:55] DEBUG[8899][C-00008973] chan_sip.c: Setting SIP_ALREADYGONE on dialog 698a1c3a6a67ad7e5dc218d678a63b32@[trunk.ip]:5060
[Feb 19 01:04:55] DEBUG[8899][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb00c11ab08'
[Feb 19 01:04:55] DEBUG[8899][C-00008973] chan_sip.c: Session timer stopped: 19 - 698a1c3a6a67ad7e5dc218d678a63b32@[trunk.ip]:5060
[Feb 19 01:04:55] DEBUG[8899][C-00008973] chan_sip.c: Received bye, issuing owner hangup
[Feb 19 01:04:55] DEBUG[8899][C-00008973] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for [trunk.ip]:5060
[Feb 19 01:04:55] DEBUG[8899] chan_sip.c: Destroying SIP dialog 298866a91fda791c6b0186d66dd098dc@[ast.srv.ip]:5061
[Feb 19 01:04:55] VERBOSE[6569][C-00008973] res_musiconhold.c: Stopped music on hold on SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:55] DEBUG[6569][C-00008973] channel.c: Channel SIP/[TRUNK_NAME]-0001f8dd setting write format path: alaw -> ulaw
[Feb 19 01:04:55] DEBUG[6569][C-00008973] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Feb 19 01:04:55] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:55] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT INTO queue_log (`time`, `data5`, `data4`, `data3`, `data2`, `data1`, `event`, `agent`, `queuename`, `callid`) VALUES ('2016-02-19 01:04:55.144019', '', '', '25', '1', '1', 'ABANDON', 'NONE', '[COMPANY_NAME]', '1455829454.129259')
[Feb 19 01:04:55] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log, id: 0
[Feb 19 01:04:55] DEBUG[6569][C-00008973] app_queue.c: Queue '[COMPANY_NAME]' Leave, Channel 'SIP/[TRUNK_NAME]-0001f8dd'
[Feb 19 01:04:55] DEBUG[8928] app_queue.c: Device 'Queue:[COMPANY_NAME]' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Feb 19 01:04:55] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Connection okay.
[Feb 19 01:04:55] DEBUG[6569][C-00008973] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM queues WHERE name = '[COMPANY_NAME]'
[Feb 19 01:04:55] DEBUG[6569][C-00008973] pbx.c: Spawn extension ([COMPANY_NAME]_IVR,s,71) exited non-zero on 'SIP/[TRUNK_NAME]-0001f8dd'
[Feb 19 01:04:55] VERBOSE[6569][C-00008973] pbx.c: Spawn extension ([COMPANY_NAME]_IVR, s, 71) exited non-zero on 'SIP/[TRUNK_NAME]-0001f8dd'
[Feb 19 01:04:55] DEBUG[6569][C-00008973] channel.c: Soft-Hanging (0x10) up channel 'SIP/[TRUNK_NAME]-0001f8dd'
[Feb 19 01:04:55] DEBUG[6569][C-00008973] channel.c: Hanging up channel 'SIP/[TRUNK_NAME]-0001f8dd'
[Feb 19 01:04:55] DEBUG[6569][C-00008973] chan_sip.c: Hangup call SIP/[TRUNK_NAME]-0001f8dd, SIP callid 698a1c3a6a67ad7e5dc218d678a63b32@[trunk.ip]:5060
[Feb 19 01:04:55] DEBUG[6569][C-00008973] chan_sip.c: Updating call counter for incoming call
[Feb 19 01:04:55] DEBUG[6569][C-00008973] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fb00c11ab08'
[Feb 19 01:04:55] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [TRUNK_NAME]
[Feb 19 01:04:55] DEBUG[8870] chan_sip.c: Checking device state for peer [TRUNK_NAME]
[Feb 19 01:04:55] DEBUG[8870] devicestate.c: Changing state for SIP/[TRUNK_NAME] - state 1 (Not in use)
[Feb 19 01:04:55] DEBUG[8928] app_queue.c: Device 'SIP/[TRUNK_NAME]' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Feb 19 01:04:55] VERBOSE[8873] cdr.c: 0x7fb03001be68 - Beginning finalize/dispatch for SIP/[TRUNK_NAME]-0001f8dd
[Feb 19 01:04:55] VERBOSE[8873] cdr.c: 0x7fb03001be68 - Dispatching CDR for Party A SIP/[TRUNK_NAME]-0001f8dd, Party B SIP/[COMPANY_NAME]-418-0001f8de
[Feb 19 01:04:55] DEBUG[8870] devicestate.c: No provider found, checking channel drivers for SIP - [TRUNK_NAME]
[Feb 19 01:04:55] DEBUG[8870] chan_sip.c: Checking device state for peer [TRUNK_NAME]
[Feb 19 01:04:55] DEBUG[8870] devicestate.c: Changing state for SIP/[TRUNK_NAME] - state 1 (Not in use)
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: Inserting a CDR record.
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`accountcode`,`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`peeraccount`,`sequence`) VALUES ('[acc_code]','[caller_num]','s','[COMPANY_NAME]_IVR','\"[caller_num]\" <[caller_num]>','SIP/[TRUNK_NAME]-0001f8dd','SIP/[COMPANY_NAME]-418-0001f8de','Queue','[COMPANY_NAME]','2016-02-19 01:04:14','2016-02-19 01:04:14','2016-02-19 01:04:30','16','16','BUSY','DOCUMENTATION','1455829454.129259','1455829454.129259','[COMPANY_NAME]-418','208550')
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: Inserting a CDR record.
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`accountcode`,`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`peeraccount`,`sequence`) VALUES ('[acc_code]','[caller_num]','s','[COMPANY_NAME]_IVR','\"[caller_num]\" <[caller_num]>','SIP/[TRUNK_NAME]-0001f8dd','SIP/[COMPANY_NAME]-419-0001f8df','Queue','[COMPANY_NAME]','2016-02-19 01:04:30','2016-02-19 01:04:30','2016-02-19 01:04:30','0','0','BUSY','DOCUMENTATION','1455829454.129259','1455829454.129259','[COMPANY_NAME]-419','208553')
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: Inserting a CDR record.
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`accountcode`,`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`peeraccount`,`sequence`) VALUES ('[acc_code]','[caller_num]','s','[COMPANY_NAME]_IVR','\"[caller_num]\" <[caller_num]>','SIP/[TRUNK_NAME]-0001f8dd','SIP/[COMPANY_NAME]-420-0001f8e0','Queue','[COMPANY_NAME]','2016-02-19 01:04:30','2016-02-19 01:04:30','2016-02-19 01:04:30','0','0','BUSY','DOCUMENTATION','1455829454.129259','1455829454.129259','[COMPANY_NAME]-420','208555')
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: Inserting a CDR record.
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`accountcode`,`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`peeraccount`,`sequence`) VALUES ('[acc_code]','[caller_num]','s','[COMPANY_NAME]_IVR','\"[caller_num]\" <[caller_num]>','SIP/[TRUNK_NAME]-0001f8dd','SIP/[COMPANY_NAME]-421-0001f8e1','Queue','[COMPANY_NAME]','2016-02-19 01:04:30','2016-02-19 01:04:30','2016-02-19 01:04:30','0','0','BUSY','DOCUMENTATION','1455829454.129259','1455829454.129259','[COMPANY_NAME]-421','208557')
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: Inserting a CDR record.
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`accountcode`,`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`peeraccount`,`sequence`) VALUES ('[acc_code]','[caller_num]','s','[COMPANY_NAME]_IVR','\"[caller_num]\" <[caller_num]>','SIP/[TRUNK_NAME]-0001f8dd','SIP/[COMPANY_NAME]-418-0001f8e2','Queue','[COMPANY_NAME]','2016-02-19 01:04:42','2016-02-19 01:04:42','2016-02-19 01:04:42','0','0','BUSY','DOCUMENTATION','1455829454.129259','1455829454.129259','[COMPANY_NAME]-418','208559')
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: Inserting a CDR record.
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`accountcode`,`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`peeraccount`,`sequence`) VALUES ('[acc_code]','[caller_num]','s','[COMPANY_NAME]_IVR','\"[caller_num]\" <[caller_num]>','SIP/[TRUNK_NAME]-0001f8dd','SIP/[COMPANY_NAME]-419-0001f8e3','Queue','[COMPANY_NAME]','2016-02-19 01:04:42','2016-02-19 01:04:42','2016-02-19 01:04:42','0','0','BUSY','DOCUMENTATION','1455829454.129259','1455829454.129259','[COMPANY_NAME]-419','208561')
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: Inserting a CDR record.
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`accountcode`,`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`peeraccount`,`sequence`) VALUES ('[acc_code]','[caller_num]','s','[COMPANY_NAME]_IVR','\"[caller_num]\" <[caller_num]>','SIP/[TRUNK_NAME]-0001f8dd','SIP/[COMPANY_NAME]-420-0001f8e4','Queue','[COMPANY_NAME]','2016-02-19 01:04:43','2016-02-19 01:04:43','2016-02-19 01:04:43','0','0','BUSY','DOCUMENTATION','1455829454.129259','1455829454.129259','[COMPANY_NAME]-420','208563')
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: Inserting a CDR record.
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`accountcode`,`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`peeraccount`,`sequence`) VALUES ('[acc_code]','[caller_num]','s','[COMPANY_NAME]_IVR','\"[caller_num]\" <[caller_num]>','SIP/[TRUNK_NAME]-0001f8dd','SIP/[COMPANY_NAME]-421-0001f8e5','Queue','[COMPANY_NAME]','2016-02-19 01:04:43','2016-02-19 01:04:43','2016-02-19 01:04:43','0','0','BUSY','DOCUMENTATION','1455829454.129259','1455829454.129259','[COMPANY_NAME]-421','208565')
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: Inserting a CDR record.
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`accountcode`,`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`peeraccount`,`sequence`) VALUES ('[acc_code]','[caller_num]','s','[COMPANY_NAME]_IVR','\"[caller_num]\" <[caller_num]>','SIP/[TRUNK_NAME]-0001f8dd','SIP/[COMPANY_NAME]-418-0001f8e6','Queue','[COMPANY_NAME]','2016-02-19 01:04:48','2016-02-19 01:04:48','2016-02-19 01:04:48','0','0','BUSY','DOCUMENTATION','1455829454.129259','1455829454.129259','[COMPANY_NAME]-418','208567')
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: Inserting a CDR record.
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`accountcode`,`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`peeraccount`,`sequence`) VALUES ('[acc_code]','[caller_num]','s','[COMPANY_NAME]_IVR','\"[caller_num]\" <[caller_num]>','SIP/[TRUNK_NAME]-0001f8dd','SIP/[COMPANY_NAME]-419-0001f8e7','Queue','[COMPANY_NAME]','2016-02-19 01:04:48','2016-02-19 01:04:48','2016-02-19 01:04:48','0','0','BUSY','DOCUMENTATION','1455829454.129259','1455829454.129259','[COMPANY_NAME]-419','208569')
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: Inserting a CDR record.
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`accountcode`,`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`peeraccount`,`sequence`) VALUES ('[acc_code]','[caller_num]','s','[COMPANY_NAME]_IVR','\"[caller_num]\" <[caller_num]>','SIP/[TRUNK_NAME]-0001f8dd','SIP/[COMPANY_NAME]-420-0001f8e8','Queue','[COMPANY_NAME]','2016-02-19 01:04:48','2016-02-19 01:04:48','2016-02-19 01:04:48','0','0','BUSY','DOCUMENTATION','1455829454.129259','1455829454.129259','[COMPANY_NAME]-420','208571')
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: Inserting a CDR record.
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`accountcode`,`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`peeraccount`,`sequence`) VALUES ('[acc_code]','[caller_num]','s','[COMPANY_NAME]_IVR','\"[caller_num]\" <[caller_num]>','SIP/[TRUNK_NAME]-0001f8dd','SIP/[COMPANY_NAME]-421-0001f8e9','Queue','[COMPANY_NAME]','2016-02-19 01:04:48','2016-02-19 01:04:48','2016-02-19 01:04:48','0','0','BUSY','DOCUMENTATION','1455829454.129259','1455829454.129259','[COMPANY_NAME]-421','208573')
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: Inserting a CDR record.
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`accountcode`,`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`peeraccount`,`sequence`) VALUES ('[acc_code]','[caller_num]','s','[COMPANY_NAME]_IVR','\"[caller_num]\" <[caller_num]>','SIP/[TRUNK_NAME]-0001f8dd','SIP/[COMPANY_NAME]-418-0001f8ea','Queue','[COMPANY_NAME]','2016-02-19 01:04:53','2016-02-19 01:04:53','2016-02-19 01:04:53','0','0','BUSY','DOCUMENTATION','1455829454.129259','1455829454.129259','[COMPANY_NAME]-418','208575')
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: Inserting a CDR record.
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`accountcode`,`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`peeraccount`,`sequence`) VALUES ('[acc_code]','[caller_num]','s','[COMPANY_NAME]_IVR','\"[caller_num]\" <[caller_num]>','SIP/[TRUNK_NAME]-0001f8dd','SIP/[COMPANY_NAME]-419-0001f8eb','Queue','[COMPANY_NAME]','2016-02-19 01:04:53','2016-02-19 01:04:53','2016-02-19 01:04:53','0','0','BUSY','DOCUMENTATION','1455829454.129259','1455829454.129259','[COMPANY_NAME]-419','208577')
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: Inserting a CDR record.
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`accountcode`,`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`peeraccount`,`sequence`) VALUES ('[acc_code]','[caller_num]','s','[COMPANY_NAME]_IVR','\"[caller_num]\" <[caller_num]>','SIP/[TRUNK_NAME]-0001f8dd','SIP/[COMPANY_NAME]-420-0001f8ec','Queue','[COMPANY_NAME]','2016-02-19 01:04:53','2016-02-19 01:04:53','2016-02-19 01:04:53','0','0','BUSY','DOCUMENTATION','1455829454.129259','1455829454.129259','[COMPANY_NAME]-420','208579')
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: Inserting a CDR record.
[Feb 19 01:04:55] DEBUG[8873] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`accountcode`,`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`peeraccount`,`sequence`) VALUES ('[acc_code]','[caller_num]','s','[COMPANY_NAME]_IVR','\"[caller_num]\" <[caller_num]>','SIP/[TRUNK_NAME]-0001f8dd','SIP/[COMPANY_NAME]-421-0001f8ed','Queue','[COMPANY_NAME]','2016-02-19 01:04:53','2016-02-19 01:04:53','2016-02-19 01:04:53','0','0','BUSY','DOCUMENTATION','1455829454.129259','1455829454.129259','[COMPANY_NAME]-421','208581')