testasterisk11*CLI> core set verbose 5
Set remote console verbosity to 5
testasterisk11*CLI> core set debug 5
Core debug was 0 and is now 5
[Aug 23 14:03:12] DEBUG[12530]: chan_sip.c:8698 find_call: = Looking for  Call ID: 86d10c81-b785cb89@172.16.19.5 (Checking From) --From tag 421cd82119737469o0 --To-tag
[Aug 23 14:03:12] DEBUG[12530]: logger.c:1285 ast_create_callid: CALL_ID [C-00000000] created by thread.
[Aug 23 14:03:12] DEBUG[12530]: acl.c:979 ast_ouraddrfor: For destination '172.16.19.5', our source address is '172.16.19.1'.
[Aug 23 14:03:12] DEBUG[12530]: chan_sip.c:3739 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 172.16.19.1:5060
[Aug 23 14:03:12] DEBUG[12530]: chan_sip.c:8329 sip_alloc: Allocating new SIP dialog for 86d10c81-b785cb89@172.16.19.5 - INVITE (No RTP)
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:27223 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: sip/reqresp_parser.c:1550 parse_sip_options: Begin: parsing SIP "Supported: replaces"
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: sip/reqresp_parser.c:1566 parse_sip_options: Found SIP option: -replaces-
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: sip/reqresp_parser.c:1574 parse_sip_options: Matched SIP option: replaces
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.5:5060' into...
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.5' and port '5060'.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into...
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:3582 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 172.16.19.5:5060
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: logger.c:1337 ast_callid_threadassoc_remove: Call_ID [C-00000000] being removed from thread.
[Aug 23 14:03:12] DEBUG[12530]: chan_sip.c:8698 find_call: = Looking for  Call ID: 86d10c81-b785cb89@172.16.19.5 (Checking From) --From tag 421cd82119737469o0 --To-tag as7d84ff55
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:27223 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:4274 __sip_ack: Stopping retransmission on '86d10c81-b785cb89@172.16.19.5' of Response 101: Match Found
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: logger.c:1337 ast_callid_threadassoc_remove: Call_ID [C-00000000] being removed from thread.
[Aug 23 14:03:12] DEBUG[12530]: chan_sip.c:8698 find_call: = Looking for  Call ID: 86d10c81-b785cb89@172.16.19.5 (Checking From) --From tag 421cd82119737469o0 --To-tag
[Aug 23 14:03:12] DEBUG[12530]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into...
[Aug 23 14:03:12] DEBUG[12530]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''.
[Aug 23 14:03:12] DEBUG[12530]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into...
[Aug 23 14:03:12] DEBUG[12530]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:27223 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.5:5060' into...
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.5' and port '5060'.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into...
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fa174078cc8'
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: res_rtp_asterisk.c:1171 ast_rtp_new: Allocated port 19116 for RTP instance '0x7fa174078cc8'
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.11.78' into...
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.11.78' and port ''.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into...
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x7fa174078cc8' is setup and ready to go
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: res_rtp_asterisk.c:3269 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fa174078cc8'
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.11.78' into...
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.11.78' and port ''.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into...
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''.
  == Using SIP RTP CoS mark 5
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:5401 do_setnat: Setting NAT on RTP to Off
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP o=- 435095 435095 IN IP4 172.16.19.5... UNSUPPORTED OR FAILED.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.5' into...
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.5' and port ''.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP c=IN IP4 172.16.19.5... OK.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7fa17a164ff0
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 2 based on m type on 0x7fa17a164ff0
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x7fa17a164ff0
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 9 based on m type on 0x7fa17a164ff0
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 18 based on m type on 0x7fa17a164ff0
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 96 based on m type on 0x7fa17a164ff0
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 97 based on m type on 0x7fa17a164ff0
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 98 based on m type on 0x7fa17a164ff0
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7fa17a164ff0
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729a/8000... OK.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:641 ast_rtp_codecs_payloads_unset: Unsetting payload 96 on 0x7fa17a164ff0
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:96 G726-40/8000... UNSUPPORTED OR FAILED.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:641 ast_rtp_codecs_payloads_unset: Unsetting payload 97 on 0x7fa17a164ff0
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:97 G726-24/8000... UNSUPPORTED OR FAILED.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:641 ast_rtp_codecs_payloads_unset: Unsetting payload 98 on 0x7fa17a164ff0
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:98 G726-16/8000... UNSUPPORTED OR FAILED.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=ptime:30... OK.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: res_rtp_asterisk.c:3314 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fa174078cc8'
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x7fa17a164ff0 to 0x7fa174078e90
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 2 from 0x7fa17a164ff0 to 0x7fa174078e90
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x7fa17a164ff0 to 0x7fa174078e90
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 9 from 0x7fa17a164ff0 to 0x7fa174078e90
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 18 from 0x7fa17a164ff0 to 0x7fa174078e90
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7fa17a164ff0 to 0x7fa174078e90
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: res_rtp_asterisk.c:3235 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7fa174078cc8'
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:10215 process_sdp: We're settling with these formats: (ulaw|g722)
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:24506 handle_request_invite: Checking SIP call limits for device C89C1D6E74DC
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:6281 update_call_counter: Updating call counter for incoming call
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into...
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - C89C1D6E74DC
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''.
[Aug 23 14:03:12] DEBUG[12522]: chan_sip.c:28667 sip_devicestate: Checking device state for peer C89C1D6E74DC
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into...
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:460 do_state_change: Changing state for SIP/C89C1D6E74DC - state 2 (In use)
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''.
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:440 devstate_event: device 'SIP/C89C1D6E74DC' state '2'
[Aug 23 14:03:12] DEBUG[12540]: app_queue.c:1685 handle_statechange: Device 'SIP/C89C1D6E74DC' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Aug 23 14:03:12] DEBUG[12524]: app_queue.c:1787 extension_state_cb: Extension '306@hints' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Aug 23 14:03:12] DEBUG[12524]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.2:5060' into...
[Aug 23 14:03:12] DEBUG[12524]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.2' and port '5060'.
[Aug 23 14:03:12] DEBUG[12524]: chan_sip.c:3582 __sip_xmit: Trying to put 'NOTIFY sip:' onto UDP socket destined for 172.16.19.2:5060
  == Extension Changed 306[hints] new state InUse for Notify User 649EF376CA25
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:7517 sip_new: *** Our native formats are (g722)
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:7518 sip_new: *** Joint capabilities are (ulaw|g722)
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:7519 sip_new: *** Our capabilities are (gsm|ulaw|g722)
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:7520 sip_new: *** AST_CODEC_CHOOSE formats are g722
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:7548 sip_new: This channel will not be able to handle video.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:15515 build_route: build_route: Contact hop: "MetaLINK" <sip:C89C1D6E74DC@172.16.19.5:5060>
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:24813 handle_request_invite: SIP/C89C1D6E74DC-00000000: New call is still down.... Trying...
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:3582 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 172.16.19.5:5060
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - C89C1D6E74DC
[Aug 23 14:03:12] DEBUG[12522]: chan_sip.c:28667 sip_devicestate: Checking device state for peer C89C1D6E74DC
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:460 do_state_change: Changing state for SIP/C89C1D6E74DC - state 2 (In use)
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:440 devstate_event: device 'SIP/C89C1D6E74DC' state '2'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: logger.c:1337 ast_callid_threadassoc_remove: Call_ID [C-00000000] being removed from thread.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'NoOp'
    -- Executing [398@hotdesk:1] NoOp("SIP/C89C1D6E74DC-00000000", "") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'CHANNEL' (from 'CHANNEL}' len 7)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'CHANNEL' is 'SIP/C89C1D6E74DC-00000000'
[Aug 23 14:03:12] DEBUG[12540]: app_queue.c:1685 handle_statechange: Device 'SIP/C89C1D6E74DC' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is 'C89C1D6E74DC-00000000'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Set'
    -- Executing [398@hotdesk:2] Set("SIP/C89C1D6E74DC-00000000", "LOCATION=C89C1D6E74DC-00000000") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'LOCATION' (from 'LOCATION}' len 8)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'LOCATION' is 'C89C1D6E74DC-00000000'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is 'C89C1D6E74DC'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Set'
    -- Executing [398@hotdesk:3] Set("SIP/C89C1D6E74DC-00000000", "LOCATION=C89C1D6E74DC") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'LOCATION' is 'C89C1D6E74DC'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}'' len 4)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is 'C89C1D6E74DC'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:619 acf_odbc_read: Got collength of 9 and maxcol of 19 for column 'extension' (offset 0)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:667 acf_odbc_read: Got coldata of '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:691 acf_odbc_read: buf is now set to '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:693 acf_odbc_read: buf is now set to '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x145e6c8) called (obj->txf = (nil))
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Set'
    -- Executing [398@hotdesk:4] Set("SIP/C89C1D6E74DC-00000000", "WHO=303") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is '0'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4306 pbx_substitute_variables_helper_full: Expression result is '0'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'EXTEN' is '398'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [398@hotdesk:5] GotoIf("SIP/C89C1D6E74DC-00000000", "0?internal,398,1") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:11309 pbx_builtin_gotoif: Not taking any branch
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1} FROM ast_hotdesk WHERE extension = '${ARG2}'' len 4)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is 'cid_name'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'ARG2' (from 'ARG2}'' len 4)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG2' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:619 acf_odbc_read: Got collength of 8 and maxcol of 65535 for column 'cid_name' (offset 0)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:667 acf_odbc_read: Got coldata of 'Test User 3'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:691 acf_odbc_read: buf is now set to 'Test User 3'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:693 acf_odbc_read: buf is now set to 'Test User 3'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x145e6c8) called (obj->txf = (nil))
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is 'Test User 3'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Set'
    -- Executing [398@hotdesk:6] Set("SIP/C89C1D6E74DC-00000000", "303_CID_NAME=Test User 3") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1} FROM ast_hotdesk WHERE extension = '${ARG2}'' len 4)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is 'cid_number'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'ARG2' (from 'ARG2}'' len 4)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG2' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:619 acf_odbc_read: Got collength of 10 and maxcol of 10 for column 'cid_number' (offset 0)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:667 acf_odbc_read: Got coldata of '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:691 acf_odbc_read: buf is now set to '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:693 acf_odbc_read: buf is now set to '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x145e6c8) called (obj->txf = (nil))
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Set'
    -- Executing [398@hotdesk:7] Set("SIP/C89C1D6E74DC-00000000", "303_CID_NUMBER=303") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1} FROM ast_hotdesk WHERE extension = '${ARG2}'' len 4)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is 'defaultcontext'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'ARG2' (from 'ARG2}'' len 4)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG2' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:619 acf_odbc_read: Got collength of 14 and maxcol of 50 for column 'defaultcontext' (offset 0)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:667 acf_odbc_read: Got coldata of 'metalink'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:691 acf_odbc_read: buf is now set to 'metalink'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:693 acf_odbc_read: buf is now set to 'metalink'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x145e6c8) called (obj->txf = (nil))
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is 'metalink'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Set'
    -- Executing [398@hotdesk:8] Set("SIP/C89C1D6E74DC-00000000", "303_OUTBOUND_CONTEXT=metalink") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1} FROM ast_hotdesk WHERE extension = '${ARG2}'' len 4)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is 'vmcontext'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'ARG2' (from 'ARG2}'' len 4)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG2' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:619 acf_odbc_read: Got collength of 9 and maxcol of 50 for column 'vmcontext' (offset 0)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:667 acf_odbc_read: Got coldata of 'metalink'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:691 acf_odbc_read: buf is now set to 'metalink'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: func_odbc.c:693 acf_odbc_read: buf is now set to 'metalink'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x145e6c8) called (obj->txf = (nil))
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is 'metalink'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Set'
    -- Executing [398@hotdesk:9] Set("SIP/C89C1D6E74DC-00000000", "303_VMCONTEXT=metalink") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Gosub'
    -- Executing [398@hotdesk:10] Gosub("SIP/C89C1D6E74DC-00000000", "blf-begincall,s,1(303,INUSE)") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: app_stack.c:578 gosub_exec: Channel SIP/C89C1D6E74DC-00000000 has no datastore, so we're allocating one.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: app_stack.c:620 gosub_exec: Setting 'ARG1' to '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: app_stack.c:620 gosub_exec: Setting 'ARG2' to 'INUSE'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Verbose'
    -- Executing [s@blf-begincall:1] Verbose("SIP/C89C1D6E74DC-00000000", ""Beginning of Call - set BLF Custom Device state"") in new stack
Beginning of Call - set BLF Custom Device state
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is '0'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG2' is 'INUSE'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Verbose'
    -- Executing [s@blf-begincall:2] Verbose("SIP/C89C1D6E74DC-00000000", "Updating: 303 Calls: 0 Status: INUSE") in new stack
Updating: 303 Calls: 0 Status: INUSE
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG2' is 'INUSE'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4306 pbx_substitute_variables_helper_full: Expression result is '0'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is '0'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4306 pbx_substitute_variables_helper_full: Expression result is '0'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@blf-begincall:3] ExecIf("SIP/C89C1D6E74DC-00000000", "0?ExecIf(0?Set(DEVICE_STATE(Custom:303)=RINGINUSE):Set(DEVICE_STATE(Custom:303)=RINGING)):Set(DEVICE_STATE(Custom:303)=INUSE)") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: devicestate.c:440 devstate_event: device 'Custom:303' state '2'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Set'
    -- Executing [s@blf-begincall:4] Set("SIP/C89C1D6E74DC-00000000", "GROUP(activecalls)=303") in new stack
[Aug 23 14:03:12] DEBUG[12540]: app_queue.c:1683 handle_statechange: Device 'Custom:303' changed to state '2' (In use)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Set'
    -- Executing [s@blf-begincall:5] Set("SIP/C89C1D6E74DC-00000000", "CHANNEL(hangup_handler_wipe)=blf-endcall,s,1(303)") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: app_stack.c:486 expand_gosub_args: Gosub args:blf-endcall,s,1(303) new_args:blf-endcall,s,1(303)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Return'
    -- Executing [s@blf-begincall:6] Return("SIP/C89C1D6E74DC-00000000", "") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of '303_CID_NAME' is 'Test User 3'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Set'
    -- Executing [398@hotdesk:11] Set("SIP/C89C1D6E74DC-00000000", "CALLERID(name)=Test User 3") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of '303_CID_NUMBER' is '303'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Set'
    -- Executing [398@hotdesk:12] Set("SIP/C89C1D6E74DC-00000000", "CALLERID(num)=303") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'EXTEN' is '398'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Goto'
    -- Executing [398@hotdesk:13] Goto("SIP/C89C1D6E74DC-00000000", "users,398,1") in new stack
    -- Goto (users,398,1)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Verbose'
    -- Executing [398@users:1] Verbose("SIP/C89C1D6E74DC-00000000", "2,Page all phones") in new stack
  == Page all phones
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'SIPAddHeader'
    -- Executing [398@users:2] SIPAddHeader("SIP/C89C1D6E74DC-00000000", "Call-Info: <sip:172.16.19.1>;answer-after=0") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Page'
    -- Executing [398@users:3] Page("SIP/C89C1D6E74DC-00000000", "SIP/649EF376CA25&SIP/C89C1D6E74DC&SIP/649EF376C820,s,10") in new stack
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:28767 sip_request_call: Asked to create a SIP channel with formats: (g722)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:8329 sip_alloc: Allocating new SIP dialog for 78fb16bb0cdf4ae54c003dd47632acba@172.16.11.78:5060 - INVITE (No RTP)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fa12002b168'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:1171 ast_rtp_new: Allocated port 13384 for RTP instance '0x7fa12002b168'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.11.78' into...
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.11.78' and port ''.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into...
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x7fa12002b168' is setup and ready to go
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:3269 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fa12002b168'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.11.78' into...
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.11.78' and port ''.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into...
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''.
  == Using SIP RTP CoS mark 5
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:5401 do_setnat: Setting NAT on RTP to Off
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: acl.c:979 ast_ouraddrfor: For destination '172.16.19.2', our source address is '172.16.19.1'.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:3739 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 172.16.19.1:5060
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:7517 sip_new: *** Our native formats are (g722)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:7518 sip_new: *** Joint capabilities are (g722)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:7519 sip_new: *** Our capabilities are (gsm|ulaw|g722)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:7520 sip_new: *** AST_CODEC_CHOOSE formats are g722
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:7522 sip_new: *** Our preferred formats from the incoming channel are (g722)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:7548 sip_new: This channel will not be able to handle video.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel_internal_api.c:860 ast_channel_callid_set: Channel Call ID changing from [C-00000000] to [C-00000000]
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6442 ast_channel_inherit_variables: Copying hard-transferable variable SIPADDHEADER01.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable GOSUB_RETVAL.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable 303_VMCONTEXT.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable ~ODBCFIELDS~.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable ODBCSTATUS.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable ODBCROWS.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable 303_OUTBOUND_CONTEXT.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable 303_CID_NUMBER.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable 303_CID_NAME.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable WHO.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable LOCATION.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable SIPURI.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:5971 sip_call: Outgoing Call for 649EF376CA25
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:6281 update_call_counter: Updating call counter for outgoing call
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 649EF376CA25
[Aug 23 14:03:12] DEBUG[12522]: chan_sip.c:28667 sip_devicestate: Checking device state for peer 649EF376CA25
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:460 do_state_change: Changing state for SIP/649EF376CA25 - state 6 (Ringing)
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:440 devstate_event: device 'SIP/649EF376CA25' state '6'
[Aug 23 14:03:12] DEBUG[12530]: chan_sip.c:8698 find_call: = Looking for  Call ID: 22b613df-cf0a60f1@172.16.19.2 (Checking To) --From tag as59586e23 --To-tag f98ca4b0fab9649d
[Aug 23 14:03:12] DEBUG[12530]: chan_sip.c:4236 __sip_ack: Acked pending invite 104
[Aug 23 14:03:12] DEBUG[12530]: chan_sip.c:4274 __sip_ack: Stopping retransmission on '22b613df-cf0a60f1@172.16.19.2' of Request 104: Match Found
[Aug 23 14:03:12] DEBUG[12540]: app_queue.c:1685 handle_statechange: Device 'SIP/649EF376CA25' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Aug 23 14:03:12] DEBUG[12524]: app_queue.c:1787 extension_state_cb: Extension '304@hints' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:12477 add_sdp: ** Our capability: (gsm|ulaw|g722) Video flag: False Text flag: False
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:12478 add_sdp: ** Our prefcodec: (g722)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:12607 add_sdp: -- Done with adding codecs to SDP
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:12806 add_sdp: Done building SDP. Settling with this capability: (gsm|ulaw|g722)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:3225 initialize_initreq: Initializing initreq for method INVITE - callid 7be90c7e1eba1caf08a2fec9628e47d2@172.16.19.1:5060
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:3582 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 172.16.19.2:5060
    -- Called 649EF376CA25
[Aug 23 14:03:12] DEBUG[13340][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:28767 sip_request_call: Asked to create a SIP channel with formats: (g722)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:8329 sip_alloc: Allocating new SIP dialog for 032ce3920a80a4937929c31b146bd1e0@172.16.11.78:5060 - INVITE (No RTP)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fa12005c758'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:1171 ast_rtp_new: Allocated port 11918 for RTP instance '0x7fa12005c758'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.11.78' into...
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.11.78' and port ''.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into...
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x7fa12005c758' is setup and ready to go
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:3269 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fa12005c758'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.11.78' into...
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.11.78' and port ''.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into...
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''.
  == Using SIP RTP CoS mark 5
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:5401 do_setnat: Setting NAT on RTP to Off
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: acl.c:979 ast_ouraddrfor: For destination '172.16.19.3', our source address is '172.16.19.1'.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:3739 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 172.16.19.1:5060
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:7517 sip_new: *** Our native formats are (g722)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:7518 sip_new: *** Joint capabilities are (g722)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:7519 sip_new: *** Our capabilities are (gsm|ulaw|g722)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:7520 sip_new: *** AST_CODEC_CHOOSE formats are g722
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:7522 sip_new: *** Our preferred formats from the incoming channel are (g722)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:7548 sip_new: This channel will not be able to handle video.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel_internal_api.c:860 ast_channel_callid_set: Channel Call ID changing from [C-00000000] to [C-00000000]
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6442 ast_channel_inherit_variables: Copying hard-transferable variable SIPADDHEADER01.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable GOSUB_RETVAL.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable 303_VMCONTEXT.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable ~ODBCFIELDS~.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable ODBCSTATUS.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable ODBCROWS.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable 303_OUTBOUND_CONTEXT.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable 303_CID_NUMBER.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable 303_CID_NAME.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable WHO.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable LOCATION.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable SIPURI.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:5971 sip_call: Outgoing Call for 649EF376C820
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:6281 update_call_counter: Updating call counter for outgoing call
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 649EF376C820
[Aug 23 14:03:12] DEBUG[12522]: chan_sip.c:28667 sip_devicestate: Checking device state for peer 649EF376C820
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:460 do_state_change: Changing state for SIP/649EF376C820 - state 6 (Ringing)
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:440 devstate_event: device 'SIP/649EF376C820' state '6'
[Aug 23 14:03:12] DEBUG[12540]: app_queue.c:1685 handle_statechange: Device 'SIP/649EF376C820' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Aug 23 14:03:12] DEBUG[12524]: app_queue.c:1787 extension_state_cb: Extension '305@hints' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:12477 add_sdp: ** Our capability: (gsm|ulaw|g722) Video flag: False Text flag: False
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:12478 add_sdp: ** Our prefcodec: (g722)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:12607 add_sdp: -- Done with adding codecs to SDP
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:12806 add_sdp: Done building SDP. Settling with this capability: (gsm|ulaw|g722)
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:3225 initialize_initreq: Initializing initreq for method INVITE - callid 0a73a24866b634302851d18b63f43959@172.16.19.1:5060
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: chan_sip.c:3582 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 172.16.19.3:5060
    -- Called 649EF376C820
[Aug 23 14:03:12] DEBUG[13341][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:2052 ast_rtp_write: Ooh, format changed from unknown to g722
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:2087 ast_rtp_write: Created smoother: format: g722 ms: 20 len: 160
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:1947 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x7fa174078cc8'
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: channel.c:3545 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second
    -- <SIP/C89C1D6E74DC-00000000> Playing 'beep.g722' (language 'en')
[Aug 23 14:03:12] DEBUG[12530]: chan_sip.c:8698 find_call: = Looking for  Call ID: 7be90c7e1eba1caf08a2fec9628e47d2@172.16.19.1:5060 (Checking To) --From tag as5d56c402 --To-tag
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:4315 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7be90c7e1eba1caf08a2fec9628e47d2@172.16.19.1:5060' Request 102: Found
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:21715 handle_response_invite: SIP response 100 to standard invite
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: logger.c:1337 ast_callid_threadassoc_remove: Call_ID [C-00000000] being removed from thread.
[Aug 23 14:03:12] DEBUG[12530]: chan_sip.c:8698 find_call: = Looking for  Call ID: 0a73a24866b634302851d18b63f43959@172.16.19.1:5060 (Checking To) --From tag as6d3ff7e1 --To-tag
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:4315 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0a73a24866b634302851d18b63f43959@172.16.19.1:5060' Request 102: Found
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:21715 handle_response_invite: SIP response 100 to standard invite
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: logger.c:1337 ast_callid_threadassoc_remove: Call_ID [C-00000000] being removed from thread.
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug 23 14:03:12] DEBUG[13338][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update
[Aug 23 14:03:12] DEBUG[12530]: chan_sip.c:8698 find_call: = Looking for  Call ID: 7be90c7e1eba1caf08a2fec9628e47d2@172.16.19.1:5060 (Checking To) --From tag as5d56c402 --To-tag 1c81caac162eabbei0
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:4236 __sip_ack: Acked pending invite 102
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:4274 __sip_ack: Stopping retransmission on '7be90c7e1eba1caf08a2fec9628e47d2@172.16.19.1:5060' of Request 102: Match Found
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:21715 handle_response_invite: SIP response 200 to standard invite
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP o=- 435195 435195 IN IP4 172.16.19.2... UNSUPPORTED OR FAILED.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.2' into...
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.2' and port ''.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP c=IN IP4 172.16.19.2... OK.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7fa17a164ee0
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7fa17a164ee0
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=ptime:30... OK.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: res_rtp_asterisk.c:3314 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fa12002b168'
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x7fa17a164ee0 to 0x7fa12002b330
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7fa17a164ee0 to 0x7fa12002b330
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: res_rtp_asterisk.c:3235 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7fa12002b168'
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:10215 process_sdp: We're settling with these formats: (ulaw)
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:10222 process_sdp: We have an owner, now see if we need to change this call
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: channel.c:5301 set_format: Set channel SIP/649EF376CA25-00000001 to read format g722
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: channel.c:5301 set_format: Set channel SIP/649EF376CA25-00000001 to write format g722
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:6281 update_call_counter: Updating call counter for outgoing call
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:15515 build_route: build_route: Contact hop: "MetaLINK" <sip:649EF376CA25@172.16.19.2:5060>
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 649EF376CA25
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.2:5060' into...
[Aug 23 14:03:12] DEBUG[12522]: chan_sip.c:28667 sip_devicestate: Checking device state for peer 649EF376CA25
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.2' and port '5060'.
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:460 do_state_change: Changing state for SIP/649EF376CA25 - state 2 (In use)
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:440 devstate_event: device 'SIP/649EF376CA25' state '2'
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.2:5060' into...
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.2' and port '5060'.
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: chan_sip.c:3582 __sip_xmit: Trying to put 'ACK sip:649' onto UDP socket destined for 172.16.19.2:5060
[Aug 23 14:03:12] DEBUG[12530][C-00000000]: logger.c:1337 ast_callid_threadassoc_remove: Call_ID [C-00000000] being removed from thread.
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 649EF376CA25
[Aug 23 14:03:12] DEBUG[12540]: app_queue.c:1685 handle_statechange: Device 'SIP/649EF376CA25' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Aug 23 14:03:12] DEBUG[12522]: chan_sip.c:28667 sip_devicestate: Checking device state for peer 649EF376CA25
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:460 do_state_change: Changing state for SIP/649EF376CA25 - state 2 (In use)
[Aug 23 14:03:12] DEBUG[12522]: devicestate.c:440 devstate_event: device 'SIP/649EF376CA25' state '2'
[Aug 23 14:03:12] DEBUG[12524]: app_queue.c:1787 extension_state_cb: Extension '304@hints' changed to state '2' (In use) but we don't care because they're not a member of any queue.
testasterisk11*CLI>
Disconnected from Asterisk server
Executing last minute cleanups
Asterisk cleanly ending (0).
Asterisk ending (0).