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:04:50] DEBUG[13416]: chan_sip.c:8698 find_call: = Looking for Call ID: ccbf9cb3-b76c4f49@172.16.19.5 (Checking From) --From tag 62e24dabce6492b1o0 --To-tag [Aug 23 14:04:50] DEBUG[13416]: logger.c:1285 ast_create_callid: CALL_ID [C-00000000] created by thread. [Aug 23 14:04:50] DEBUG[13416]: acl.c:979 ast_ouraddrfor: For destination '172.16.19.5', our source address is '172.16.19.1'. [Aug 23 14:04:50] DEBUG[13416]: chan_sip.c:3739 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 172.16.19.1:5060 [Aug 23 14:04:50] DEBUG[13416]: chan_sip.c:8329 sip_alloc: Allocating new SIP dialog for ccbf9cb3-b76c4f49@172.16.19.5 - INVITE (No RTP) [Aug 23 14:04:50] DEBUG[13416][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:27223 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Aug 23 14:04:50] DEBUG[13416][C-00000000]: sip/reqresp_parser.c:1550 parse_sip_options: Begin: parsing SIP "Supported: replaces" [Aug 23 14:04:50] DEBUG[13416][C-00000000]: sip/reqresp_parser.c:1566 parse_sip_options: Found SIP option: -replaces- [Aug 23 14:04:50] DEBUG[13416][C-00000000]: sip/reqresp_parser.c:1574 parse_sip_options: Matched SIP option: replaces [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.5:5060' into... [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.5' and port '5060'. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into... [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''. [Aug 23 14:04:50] DEBUG[13416][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:04:50] DEBUG[13416][C-00000000]: logger.c:1337 ast_callid_threadassoc_remove: Call_ID [C-00000000] being removed from thread. [Aug 23 14:04:50] DEBUG[13416]: chan_sip.c:8698 find_call: = Looking for Call ID: ccbf9cb3-b76c4f49@172.16.19.5 (Checking From) --From tag 62e24dabce6492b1o0 --To-tag as1739a784 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:27223 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:4274 __sip_ack: Stopping retransmission on 'ccbf9cb3-b76c4f49@172.16.19.5' of Response 101: Match Found [Aug 23 14:04:50] DEBUG[13416][C-00000000]: logger.c:1337 ast_callid_threadassoc_remove: Call_ID [C-00000000] being removed from thread. [Aug 23 14:04:50] DEBUG[13416]: chan_sip.c:8698 find_call: = Looking for Call ID: ccbf9cb3-b76c4f49@172.16.19.5 (Checking From) --From tag 62e24dabce6492b1o0 --To-tag [Aug 23 14:04:50] DEBUG[13416]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into... [Aug 23 14:04:50] DEBUG[13416]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''. [Aug 23 14:04:50] DEBUG[13416]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into... [Aug 23 14:04:50] DEBUG[13416]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:27223 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.5:5060' into... [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.5' and port '5060'. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into... [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fb2e801c5c8' [Aug 23 14:04:50] DEBUG[13416][C-00000000]: res_rtp_asterisk.c:1171 ast_rtp_new: Allocated port 14948 for RTP instance '0x7fb2e801c5c8' [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.11.78' into... [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.11.78' and port ''. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into... [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x7fb2e801c5c8' is setup and ready to go [Aug 23 14:04:50] DEBUG[13416][C-00000000]: res_rtp_asterisk.c:3269 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fb2e801c5c8' [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.11.78' into... [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.11.78' and port ''. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into... [Aug 23 14:04:50] DEBUG[13416][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:04:50] DEBUG[13416][C-00000000]: chan_sip.c:5401 do_setnat: Setting NAT on RTP to Off [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP o=- 444897 444897 IN IP4 172.16.19.5... UNSUPPORTED OR FAILED. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.5' into... [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.5' and port ''. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP c=IN IP4 172.16.19.5... OK. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7fb30c19eff0 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 2 based on m type on 0x7fb30c19eff0 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x7fb30c19eff0 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 9 based on m type on 0x7fb30c19eff0 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 18 based on m type on 0x7fb30c19eff0 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 96 based on m type on 0x7fb30c19eff0 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 97 based on m type on 0x7fb30c19eff0 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 98 based on m type on 0x7fb30c19eff0 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7fb30c19eff0 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729a/8000... OK. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:641 ast_rtp_codecs_payloads_unset: Unsetting payload 96 on 0x7fb30c19eff0 [Aug 23 14:04:50] DEBUG[13416][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:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:641 ast_rtp_codecs_payloads_unset: Unsetting payload 97 on 0x7fb30c19eff0 [Aug 23 14:04:50] DEBUG[13416][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:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:641 ast_rtp_codecs_payloads_unset: Unsetting payload 98 on 0x7fb30c19eff0 [Aug 23 14:04:50] DEBUG[13416][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:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=ptime:30... OK. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: res_rtp_asterisk.c:3314 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fb2e801c5c8' [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x7fb30c19eff0 to 0x7fb2e801c790 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 2 from 0x7fb30c19eff0 to 0x7fb2e801c790 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x7fb30c19eff0 to 0x7fb2e801c790 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 9 from 0x7fb30c19eff0 to 0x7fb2e801c790 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 18 from 0x7fb30c19eff0 to 0x7fb2e801c790 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7fb30c19eff0 to 0x7fb2e801c790 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: res_rtp_asterisk.c:3235 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7fb2e801c5c8' [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:10215 process_sdp: We're settling with these formats: (ulaw|g722) [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:24506 handle_request_invite: Checking SIP call limits for device C89C1D6E74DC [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:6281 update_call_counter: Updating call counter for incoming call [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into... [Aug 23 14:04:50] DEBUG[13408]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - C89C1D6E74DC [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''. [Aug 23 14:04:50] DEBUG[13408]: chan_sip.c:28667 sip_devicestate: Checking device state for peer C89C1D6E74DC [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into... [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''. [Aug 23 14:04:50] DEBUG[13408]: devicestate.c:460 do_state_change: Changing state for SIP/C89C1D6E74DC - state 2 (In use) [Aug 23 14:04:50] DEBUG[13408]: devicestate.c:440 devstate_event: device 'SIP/C89C1D6E74DC' state '2' [Aug 23 14:04:50] DEBUG[13426]: 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:04:50] DEBUG[13410]: 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:04:50] DEBUG[13416][C-00000000]: chan_sip.c:7517 sip_new: *** Our native formats are (g722) [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:7518 sip_new: *** Joint capabilities are (ulaw|g722) [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:7519 sip_new: *** Our capabilities are (gsm|ulaw|g722) [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:7520 sip_new: *** AST_CODEC_CHOOSE formats are g722 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:7548 sip_new: This channel will not be able to handle video. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:15515 build_route: build_route: Contact hop: "MetaLINK" [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:24813 handle_request_invite: SIP/C89C1D6E74DC-00000000: New call is still down.... Trying... [Aug 23 14:04:50] DEBUG[13416][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:04:50] DEBUG[13408]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - C89C1D6E74DC [Aug 23 14:04:50] DEBUG[13408]: chan_sip.c:28667 sip_devicestate: Checking device state for peer C89C1D6E74DC [Aug 23 14:04:50] DEBUG[13408]: devicestate.c:460 do_state_change: Changing state for SIP/C89C1D6E74DC - state 2 (In use) [Aug 23 14:04:50] DEBUG[13408]: devicestate.c:440 devstate_event: device 'SIP/C89C1D6E74DC' state '2' [Aug 23 14:04:50] DEBUG[13416][C-00000000]: logger.c:1337 ast_callid_threadassoc_remove: Call_ID [C-00000000] being removed from thread. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'NoOp' -- Executing [398@hotdesk:1] NoOp("SIP/C89C1D6E74DC-00000000", "") in new stack [Aug 23 14:04:50] DEBUG[13426]: 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:04:50] DEBUG[13500][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'CHANNEL' (from 'CHANNEL}' len 7) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'CHANNEL' is 'SIP/C89C1D6E74DC-00000000' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is 'C89C1D6E74DC-00000000' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'LOCATION' (from 'LOCATION}' len 8) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'LOCATION' is 'C89C1D6E74DC-00000000' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is 'C89C1D6E74DC' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'LOCATION' is 'C89C1D6E74DC' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}'' len 4) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is 'C89C1D6E74DC' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: func_odbc.c:667 acf_odbc_read: Got coldata of '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: func_odbc.c:691 acf_odbc_read: buf is now set to '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: func_odbc.c:693 acf_odbc_read: buf is now set to '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x118aad8) called (obj->txf = (nil)) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is '303' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is '0' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4306 pbx_substitute_variables_helper_full: Expression result is '0' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'EXTEN' is '398' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:11309 pbx_builtin_gotoif: Not taking any branch [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is 'cid_name' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'ARG2' (from 'ARG2}'' len 4) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG2' is '303' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: func_odbc.c:667 acf_odbc_read: Got coldata of 'Test User 3' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: func_odbc.c:691 acf_odbc_read: buf is now set to 'Test User 3' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: func_odbc.c:693 acf_odbc_read: buf is now set to 'Test User 3' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x118aad8) called (obj->txf = (nil)) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is 'Test User 3' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is 'cid_number' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'ARG2' (from 'ARG2}'' len 4) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG2' is '303' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: func_odbc.c:667 acf_odbc_read: Got coldata of '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: func_odbc.c:691 acf_odbc_read: buf is now set to '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: func_odbc.c:693 acf_odbc_read: buf is now set to '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x118aad8) called (obj->txf = (nil)) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is '303' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is 'defaultcontext' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'ARG2' (from 'ARG2}'' len 4) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG2' is '303' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: func_odbc.c:667 acf_odbc_read: Got coldata of 'metalink' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: func_odbc.c:691 acf_odbc_read: buf is now set to 'metalink' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: func_odbc.c:693 acf_odbc_read: buf is now set to 'metalink' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x118aad8) called (obj->txf = (nil)) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is 'metalink' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is 'vmcontext' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4005 ast_str_substitute_variables_full: Evaluating 'ARG2' (from 'ARG2}'' len 4) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG2' is '303' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: func_odbc.c:667 acf_odbc_read: Got coldata of 'metalink' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: func_odbc.c:691 acf_odbc_read: buf is now set to 'metalink' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: func_odbc.c:693 acf_odbc_read: buf is now set to 'metalink' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x118aad8) called (obj->txf = (nil)) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is 'metalink' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: app_stack.c:578 gosub_exec: Channel SIP/C89C1D6E74DC-00000000 has no datastore, so we're allocating one. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: app_stack.c:620 gosub_exec: Setting 'ARG1' to '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: app_stack.c:620 gosub_exec: Setting 'ARG2' to 'INUSE' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is '0' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG2' is 'INUSE' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG2' is 'INUSE' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4306 pbx_substitute_variables_helper_full: Expression result is '0' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4238 pbx_substitute_variables_helper_full: Function result is '0' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4306 pbx_substitute_variables_helper_full: Expression result is '0' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is '303' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: devicestate.c:440 devstate_event: device 'Custom:303' state '2' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is '303' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'ARG1' is '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Set' [Aug 23 14:04:50] DEBUG[13426]: app_queue.c:1683 handle_statechange: Device 'Custom:303' changed to state '2' (In use) -- Executing [s@blf-begincall:5] Set("SIP/C89C1D6E74DC-00000000", "CHANNEL(hangup_handler_wipe)=blf-endcall,s,1(303)") in new stack [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of '303_CID_NAME' is 'Test User 3' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'WHO' is '303' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of '303_CID_NUMBER' is '303' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:3419 ast_str_retrieve_variable: Result of 'EXTEN' is '398' [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'SIPAddHeader' -- Executing [398@users:2] SIPAddHeader("SIP/C89C1D6E74DC-00000000", "Call-Info: ;answer-after=0") in new stack [Aug 23 14:04:50] DEBUG[13500][C-00000000]: pbx.c:4410 pbx_extension_helper: Launching 'Page' -- Executing [398@users:3] Page("SIP/C89C1D6E74DC-00000000", "SIP/649EF376CA25&SIP/649EF376C820,s,10") in new stack [Aug 23 14:04:50] DEBUG[13500][C-00000000]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 649EF376CA25 [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:28667 sip_devicestate: Checking device state for peer 649EF376CA25 [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:28767 sip_request_call: Asked to create a SIP channel with formats: (g722) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:8329 sip_alloc: Allocating new SIP dialog for 125d2bba475985f17cffbaf53df19b20@172.16.11.78:5060 - INVITE (No RTP) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fb29402b178' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:1171 ast_rtp_new: Allocated port 19708 for RTP instance '0x7fb29402b178' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.11.78' into... [Aug 23 14:04:50] DEBUG[13500][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.11.78' and port ''. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into... [Aug 23 14:04:50] DEBUG[13500][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x7fb29402b178' is setup and ready to go [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:3269 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fb29402b178' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.11.78' into... [Aug 23 14:04:50] DEBUG[13500][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.11.78' and port ''. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into... [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: chan_sip.c:5401 do_setnat: Setting NAT on RTP to Off [Aug 23 14:04:50] DEBUG[13500][C-00000000]: acl.c:979 ast_ouraddrfor: For destination '172.16.19.2', our source address is '172.16.19.1'. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:3739 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 172.16.19.1:5060 [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:7517 sip_new: *** Our native formats are (g722) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:7518 sip_new: *** Joint capabilities are (g722) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:7519 sip_new: *** Our capabilities are (gsm|ulaw|g722) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:7520 sip_new: *** AST_CODEC_CHOOSE formats are g722 [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:7522 sip_new: *** Our preferred formats from the incoming channel are (g722) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:7548 sip_new: This channel will not be able to handle video. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel_internal_api.c:860 ast_channel_callid_set: Channel Call ID changing from [C-00000000] to [C-00000000] [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6442 ast_channel_inherit_variables: Copying hard-transferable variable SIPADDHEADER01. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable GOSUB_RETVAL. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable 303_VMCONTEXT. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable ~ODBCFIELDS~. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable ODBCSTATUS. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable ODBCROWS. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable 303_OUTBOUND_CONTEXT. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable 303_CID_NUMBER. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable 303_CID_NAME. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable WHO. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable LOCATION. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable SIPURI. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:5971 sip_call: Outgoing Call for 649EF376CA25 [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:6281 update_call_counter: Updating call counter for outgoing call [Aug 23 14:04:50] DEBUG[13408]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 649EF376CA25 [Aug 23 14:04:50] DEBUG[13408]: chan_sip.c:28667 sip_devicestate: Checking device state for peer 649EF376CA25 [Aug 23 14:04:50] DEBUG[13408]: devicestate.c:460 do_state_change: Changing state for SIP/649EF376CA25 - state 6 (Ringing) [Aug 23 14:04:50] DEBUG[13408]: devicestate.c:440 devstate_event: device 'SIP/649EF376CA25' state '6' [Aug 23 14:04:50] DEBUG[13426]: 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:04:50] DEBUG[13410]: 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:04:50] DEBUG[13500][C-00000000]: chan_sip.c:12477 add_sdp: ** Our capability: (gsm|ulaw|g722) Video flag: False Text flag: False [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:12478 add_sdp: ** Our prefcodec: (g722) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:12607 add_sdp: -- Done with adding codecs to SDP [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:12806 add_sdp: Done building SDP. Settling with this capability: (gsm|ulaw|g722) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:3225 initialize_initreq: Initializing initreq for method INVITE - callid 441df4834e44c0ed7238291903ec2fe0@172.16.19.1:5060 [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 649EF376C820 [Aug 23 14:04:50] DEBUG[13502][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:28667 sip_devicestate: Checking device state for peer 649EF376C820 [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:28767 sip_request_call: Asked to create a SIP channel with formats: (g722) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:8329 sip_alloc: Allocating new SIP dialog for 365406a51beac6154001ed314ac034e9@172.16.11.78:5060 - INVITE (No RTP) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fb29405d788' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:1171 ast_rtp_new: Allocated port 19648 for RTP instance '0x7fb29405d788' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.11.78' into... [Aug 23 14:04:50] DEBUG[13500][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.11.78' and port ''. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into... [Aug 23 14:04:50] DEBUG[13500][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.1' and port ''. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x7fb29405d788' is setup and ready to go [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:3269 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fb29405d788' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.11.78' into... [Aug 23 14:04:50] DEBUG[13500][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.11.78' and port ''. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.1' into... [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13500][C-00000000]: chan_sip.c:5401 do_setnat: Setting NAT on RTP to Off [Aug 23 14:04:50] DEBUG[13500][C-00000000]: acl.c:979 ast_ouraddrfor: For destination '172.16.19.3', our source address is '172.16.19.1'. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:3739 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 172.16.19.1:5060 [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:7517 sip_new: *** Our native formats are (g722) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:7518 sip_new: *** Joint capabilities are (g722) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:7519 sip_new: *** Our capabilities are (gsm|ulaw|g722) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:7520 sip_new: *** AST_CODEC_CHOOSE formats are g722 [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:7522 sip_new: *** Our preferred formats from the incoming channel are (g722) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:7548 sip_new: This channel will not be able to handle video. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel_internal_api.c:860 ast_channel_callid_set: Channel Call ID changing from [C-00000000] to [C-00000000] [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6442 ast_channel_inherit_variables: Copying hard-transferable variable SIPADDHEADER01. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable GOSUB_RETVAL. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable 303_VMCONTEXT. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable ~ODBCFIELDS~. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable ODBCSTATUS. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable ODBCROWS. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable 303_OUTBOUND_CONTEXT. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable 303_CID_NUMBER. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable 303_CID_NAME. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable WHO. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable LOCATION. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:6446 ast_channel_inherit_variables: Not copying variable SIPURI. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:5971 sip_call: Outgoing Call for 649EF376C820 [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:6281 update_call_counter: Updating call counter for outgoing call [Aug 23 14:04:50] DEBUG[13408]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 649EF376C820 [Aug 23 14:04:50] DEBUG[13408]: chan_sip.c:28667 sip_devicestate: Checking device state for peer 649EF376C820 [Aug 23 14:04:50] DEBUG[13408]: devicestate.c:460 do_state_change: Changing state for SIP/649EF376C820 - state 6 (Ringing) [Aug 23 14:04:50] DEBUG[13408]: devicestate.c:440 devstate_event: device 'SIP/649EF376C820' state '6' [Aug 23 14:04:50] DEBUG[13426]: 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:04:50] DEBUG[13410]: 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:04:50] DEBUG[13500][C-00000000]: chan_sip.c:12477 add_sdp: ** Our capability: (gsm|ulaw|g722) Video flag: False Text flag: False [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:12478 add_sdp: ** Our prefcodec: (g722) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:12607 add_sdp: -- Done with adding codecs to SDP [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:12806 add_sdp: Done building SDP. Settling with this capability: (gsm|ulaw|g722) [Aug 23 14:04:50] DEBUG[13500][C-00000000]: chan_sip.c:3225 initialize_initreq: Initializing initreq for method INVITE - callid 04d565fb6c266b5f623fe6ea01724d8b@172.16.19.1:5060 [Aug 23 14:04:50] DEBUG[13500][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:04:50] DEBUG[13503][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:2052 ast_rtp_write: Ooh, format changed from unknown to g722 [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:2087 ast_rtp_write: Created smoother: format: g722 ms: 20 len: 160 [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:1947 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x7fb2e801c5c8' [Aug 23 14:04:50] DEBUG[13500][C-00000000]: channel.c:3545 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- Playing 'beep.g722' (language 'en') [Aug 23 14:04:50] DEBUG[13416]: chan_sip.c:8698 find_call: = Looking for Call ID: 441df4834e44c0ed7238291903ec2fe0@172.16.19.1:5060 (Checking To) --From tag as46679f0b --To-tag [Aug 23 14:04:50] DEBUG[13416][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:4315 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '441df4834e44c0ed7238291903ec2fe0@172.16.19.1:5060' Request 102: Found [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:21715 handle_response_invite: SIP response 100 to standard invite [Aug 23 14:04:50] DEBUG[13416][C-00000000]: logger.c:1337 ast_callid_threadassoc_remove: Call_ID [C-00000000] being removed from thread. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 23 14:04:50] DEBUG[13416]: chan_sip.c:8698 find_call: = Looking for Call ID: 04d565fb6c266b5f623fe6ea01724d8b@172.16.19.1:5060 (Checking To) --From tag as70dd8e7b --To-tag [Aug 23 14:04:50] DEBUG[13416][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:4315 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '04d565fb6c266b5f623fe6ea01724d8b@172.16.19.1:5060' Request 102: Found [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:21715 handle_response_invite: SIP response 100 to standard invite [Aug 23 14:04:50] DEBUG[13416][C-00000000]: logger.c:1337 ast_callid_threadassoc_remove: Call_ID [C-00000000] being removed from thread. [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 23 14:04:50] DEBUG[13500][C-00000000]: res_rtp_asterisk.c:1507 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 23 14:04:50] DEBUG[13416]: chan_sip.c:8698 find_call: = Looking for Call ID: 441df4834e44c0ed7238291903ec2fe0@172.16.19.1:5060 (Checking To) --From tag as46679f0b --To-tag 1c3105733d1bfdedi0 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: logger.c:1315 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:4236 __sip_ack: Acked pending invite 102 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:4274 __sip_ack: Stopping retransmission on '441df4834e44c0ed7238291903ec2fe0@172.16.19.1:5060' of Request 102: Match Found [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:21715 handle_response_invite: SIP response 200 to standard invite [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP o=- 444997 444997 IN IP4 172.16.19.2... UNSUPPORTED OR FAILED. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.2' into... [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.2' and port ''. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP c=IN IP4 172.16.19.2... OK. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9566 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7fb30c19eee0 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7fb30c19eee0 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=ptime:30... OK. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:9953 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [Aug 23 14:04:50] DEBUG[13416][C-00000000]: res_rtp_asterisk.c:3314 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fb29402b178' [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x7fb30c19eee0 to 0x7fb29402b340 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7fb30c19eee0 to 0x7fb29402b340 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: res_rtp_asterisk.c:3235 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7fb29402b178' [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:10215 process_sdp: We're settling with these formats: (ulaw) [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:10222 process_sdp: We have an owner, now see if we need to change this call [Aug 23 14:04:50] DEBUG[13416][C-00000000]: channel.c:5301 set_format: Set channel SIP/649EF376CA25-00000001 to read format g722 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: channel.c:5301 set_format: Set channel SIP/649EF376CA25-00000001 to write format g722 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:6281 update_call_counter: Updating call counter for outgoing call [Aug 23 14:04:50] DEBUG[13416][C-00000000]: chan_sip.c:15515 build_route: build_route: Contact hop: "MetaLINK" [Aug 23 14:04:50] DEBUG[13408]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 649EF376CA25 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.2:5060' into... [Aug 23 14:04:50] DEBUG[13408]: chan_sip.c:28667 sip_devicestate: Checking device state for peer 649EF376CA25 [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.2' and port '5060'. [Aug 23 14:04:50] DEBUG[13408]: devicestate.c:460 do_state_change: Changing state for SIP/649EF376CA25 - state 2 (In use) [Aug 23 14:04:50] DEBUG[13408]: devicestate.c:440 devstate_event: device 'SIP/649EF376CA25' state '2' [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.19.2:5060' into... [Aug 23 14:04:50] DEBUG[13416][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.19.2' and port '5060'. [Aug 23 14:04:50] DEBUG[13416][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:04:50] DEBUG[13416][C-00000000]: logger.c:1337 ast_callid_threadassoc_remove: Call_ID [C-00000000] being removed from thread. [Aug 23 14:04:50] DEBUG[13408]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 649EF376CA25 -- SIP/649EF376CA25-00000001 answered testasterisk11*CLI> Disconnected from Asterisk server Executing last minute cleanups Asterisk cleanly ending (0).