Core debug was OFF and is now 5.
[2015-12-29 22:10:58] DEBUG[1786]: chan_sip.c:9178 __find_call: = Looking for  Call ID: 0_3669211333@172.16.8.41 (Checking From) --From tag 1698527837 --To-tag
[2015-12-29 22:10:58] DEBUG[1786]: acl.c:946 ast_ouraddrfor: For destination '172.16.8.41', our source address is '172.16.10.173'.
[2015-12-29 22:10:58] DEBUG[1786]: chan_sip.c:3866 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 172.16.10.173:5060
[2015-12-29 22:10:58] DEBUG[1786]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '172.16.8.41:5060' into...
[2015-12-29 22:10:58] DEBUG[1786]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '172.16.8.41' and port '5060'.
[2015-12-29 22:10:58] DEBUG[1786]: chan_sip.c:8765 __sip_alloc: Allocating new SIP dialog for 0_3669211333@172.16.8.41 - INVITE (No RTP)
[2015-12-29 22:10:58] DEBUG[1786][C-0000000b]: chan_sip.c:28034 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[2015-12-29 22:10:58] DEBUG[1786][C-0000000b]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '172.16.8.41:5060' into...
[2015-12-29 22:10:58] DEBUG[1786][C-0000000b]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '172.16.8.41' and port '5060'.
[2015-12-29 22:10:58] DEBUG[1786][C-0000000b]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '172.16.10.173:5060' into...
[2015-12-29 22:10:58] DEBUG[1786][C-0000000b]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '172.16.10.173' and port ''.
[2015-12-29 22:10:58] DEBUG[1786][C-0000000b]: chan_sip.c:3709 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 172.16.8.41:5060
[2015-12-29 22:10:58] DEBUG[1786]: chan_sip.c:9178 __find_call: = Looking for  Call ID: 0_3669211333@172.16.8.41 (Checking From) --From tag 1698527837 --To-tag as6366c1d8
[2015-12-29 22:10:58] DEBUG[1786][C-0000000b]: chan_sip.c:28034 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[2015-12-29 22:10:58] DEBUG[1786][C-0000000b]: chan_sip.c:4406 __sip_ack: Stopping retransmission on '0_3669211333@172.16.8.41' of Response 1: Match Found
[2015-12-29 22:10:59] DEBUG[1786]: chan_sip.c:9178 __find_call: = Looking for  Call ID: 0_3669211333@172.16.8.41 (Checking From) --From tag 1698527837 --To-tag
[2015-12-29 22:10:59] DEBUG[1786]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '172.16.10.173:5060' into...
[2015-12-29 22:10:59] DEBUG[1786]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '172.16.10.173' and port '5060'.
[2015-12-29 22:10:59] DEBUG[1786]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '172.16.10.173:5060' into...
[2015-12-29 22:10:59] DEBUG[1786]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '172.16.10.173' and port '5060'.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:28034 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '172.16.8.41:5060' into...
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '172.16.8.41' and port '5060'.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '172.16.10.173:5060' into...
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '172.16.10.173' and port ''.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: rtp_engine.c:429 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x142dbc8'
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: res_rtp_asterisk.c:2532 ast_rtp_new: Allocated port 17124 for RTP instance '0x142dbc8'
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: rtp_engine.c:438 ast_rtp_instance_new: RTP instance '0x142dbc8' is setup and ready to go
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: res_rtp_asterisk.c:4766 ast_rtp_prop_set: Setup RTCP on RTP instance '0x142dbc8'
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:5602 do_setnat: Setting NAT on RTP to Off
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:10026 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:10026 process_sdp: Processing session-level SDP o=- 20011 20011 IN IP4 172.16.8.41... OK.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:10026 process_sdp: Processing session-level SDP s=SDP data... UNSUPPORTED OR FAILED.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '172.16.8.41' into...
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '172.16.8.41' and port ''.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:10026 process_sdp: Processing session-level SDP c=IN IP4 172.16.8.41... OK.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:10026 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7f193bc3e350
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f193bc3e350
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f193bc3e350
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 18 based on m type on 0x7f193bc3e350
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f193bc3e350
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: res_rtp_asterisk.c:4822 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x142dbc8'
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x1b6b810) from 0x7f193bc3e350 to 0x142dd90
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x1454f40) from 0x7f193bc3e350 to 0x142dd90
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 9 (0x1ae1e70) from 0x7f193bc3e350 to 0x142dd90
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 18 (0x1afc0c0) from 0x7f193bc3e350 to 0x142dd90
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x2b69b20) from 0x7f193bc3e350 to 0x142dd90
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: res_rtp_asterisk.c:4732 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x142dbc8'
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:10771 process_sdp: We're settling with these formats: (ulaw|alaw)
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:25613 handle_request_invite: Checking SIP call limits for device 1101
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:6559 update_call_counter: Updating call counter for incoming call
[2015-12-29 22:10:59] DEBUG[566]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for SIP - 1101
[2015-12-29 22:10:59] DEBUG[566]: chan_sip.c:29535 sip_devicestate: Checking device state for peer 1101
[2015-12-29 22:10:59] DEBUG[566]: devicestate.c:473 do_state_change: Changing state for SIP/1101 - state 2 (In use)
[2015-12-29 22:10:59] DEBUG[1047]: devicestate.c:364 _ast_device_state: Checking if I can find provider for "Custom" - number: DND1101
[2015-12-29 22:10:59] DEBUG[1047]: devicestate.c:453 getproviderstate: Checking provider Custom with Custom
[2015-12-29 22:10:59] DEBUG[1047]: db.c:376 db_get_common: Unable to find key 'DND1101' in family 'CustomDevstate'
[2015-12-29 22:10:59] DEBUG[1047]: app_queue.c:2458 extension_state_cb: Extension '1101@ext-local' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2015-12-29 22:10:59] DEBUG[1047]: devicestate.c:364 _ast_device_state: Checking if I can find provider for "Custom" - number: DND1101
[2015-12-29 22:10:59] DEBUG[1047]: devicestate.c:453 getproviderstate: Checking provider Custom with Custom
[2015-12-29 22:10:59] DEBUG[1047]: db.c:376 db_get_common: Unable to find key 'DND1101' in family 'CustomDevstate'
[2015-12-29 22:10:59] DEBUG[1047]: app_queue.c:2458 extension_state_cb: Extension '*801101@ext-local' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2015-12-29 22:10:59] DEBUG[1805]: app_queue.c:2383 device_state_cb: Device 'SIP/1101' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '172.16.10.173:5060' into...
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '172.16.10.173' and port ''.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '172.16.10.173:5060' into...
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '172.16.10.173' and port ''.
[2015-12-29 22:10:59] DEBUG[511]: threadpool.c:508 grow: Increasing threadpool stasis-core's size by 1
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:7927 sip_new: *** Our native formats are (ulaw)
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:7928 sip_new: *** Joint capabilities are (ulaw|alaw)
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:7929 sip_new: *** Our capabilities are (ulaw|alaw|gsm|g726)
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:7930 sip_new: *** AST_CODEC_CHOOSE formats are ulaw
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:7958 sip_new: This channel will not be able to handle video.
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:25817 handle_request_invite: SIP/1101-00000016: New call is still down.... Trying...
[2015-12-29 22:10:59] DEBUG[1786][C-0000000b]: chan_sip.c:3709 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 172.16.8.41:5060
[2015-12-29 22:10:59] DEBUG[566]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for SIP - 1101
[2015-12-29 22:10:59] DEBUG[566]: chan_sip.c:29535 sip_devicestate: Checking device state for peer 1101
[2015-12-29 22:10:59] DEBUG[566]: devicestate.c:473 do_state_change: Changing state for SIP/1101 - state 2 (In use)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Macro'
    -- Executing [1107@from-internal:1] Macro("SIP/1101-00000016", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'UNIQUEID' is '1451416259.22'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:1] Set("SIP/1101-00000016", "TOUCH_MONITOR=1451416259.22") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'AMPUSER' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'AMPUSER' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function IF(1?1101:) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:2] Set("SIP/1101-00000016", "AMPUSER=1101") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'CHANNEL' (from 'CHANNEL}' len 7)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'CHANNEL' is 'SIP/1101-00000016'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CUT(CHANNEL,@,2) result is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'AMPUSERCIDNAME' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function LEN() result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-user-callerid:3] GotoIf("SIP/1101-00000016", "0?report") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:11917 pbx_builtin_gotoif: Not taking any branch
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: GotoIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-user-callerid:4] ExecIf("SIP/1101-00000016", "1?Set(REALCALLERIDNUM=1101)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'REALCALLERIDNUM:1:2' (from 'REALCALLERIDNUM:1:2}" = ""' len 19)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function CALLERID(number) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function DB(DEVICE/1101/user) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:5] Set("SIP/1101-00000016", "AMPUSER=1101") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-user-callerid:6] GotoIf("SIP/1101-00000016", "0?limit") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:11917 pbx_builtin_gotoif: Not taking any branch
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: GotoIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1101/cidname) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:7] Set("SIP/1101-00000016", "AMPUSERCIDNAME=TEST 123") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSERCIDNAME' is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-user-callerid:8] GotoIf("SIP/1101-00000016", "0?report") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:11917 pbx_builtin_gotoif: Not taking any branch
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: GotoIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG2' is 'EXTERNAL'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function DB_EXISTS(AMPUSER/1101/cidnum) result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DB_RESULT' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function IF(0?1101:1101) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:9] Set("SIP/1101-00000016", "AMPUSERCID=1101") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: db.c:376 db_get_common: Unable to find key '1101/dialopts' in family 'AMPUSER'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function DB_EXISTS(AMPUSER/1101/dialopts) result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DB_RESULT' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_OPTIONS' is 'Ttr'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function IF(0?1101:Ttr) result is 'Ttr'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:10] Set("SIP/1101-00000016", "__DIAL_OPTIONS=Ttr") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSERCIDNAME' is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSERCID' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:11] Set("SIP/1101-00000016", "CALLERID(all)="TEST 123" <1101>") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function LEN(1101) result is '4'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function DB_EXISTS(AMPUSER/1101/concurrency_limit) result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1101/concurrency_limit) result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function GROUP_COUNT(1101@concurrency_limit) result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1101/concurrency_limit) result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-user-callerid:12] GotoIf("SIP/1101-00000016", "0?limit") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:11917 pbx_builtin_gotoif: Not taking any branch
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: GotoIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function LEN(1101) result is '4'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-user-callerid:13] ExecIf("SIP/1101-00000016", "1?Set(GROUP(concurrency_limit)=1101)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}"="LIMIT" & ${LEN(${AMPUSER})}' len 4)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'LEN(${AMPUSER})' (from 'LEN(${AMPUSER})}' len 15)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER})' len 7)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function LEN(1101) result is '4'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER})' len 7)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-user-callerid:14] GotoIf("SIP/1101-00000016", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,27)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: GotoIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:27] Set("SIP/1101-00000016", "CALLERID(number)=1101") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(name) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:28] Set("SIP/1101-00000016", "CALLERID(name)=TEST 123") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:29] Set("SIP/1101-00000016", "CDR(cnum)=1101") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(name) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:30] Set("SIP/1101-00000016", "CDR(cnam)=TEST 123") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'CHANNEL(language)' (from 'CHANNEL(language)}' len 17)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function CHANNEL(language) result is 'en'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function MASTER_CHANNEL(CHANNEL(language)) result is 'en'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-user-callerid:31] Set("SIP/1101-00000016", "CHANNEL(language)=en") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EXTEN' is '1107'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Gosub'
    -- Executing [1107@from-internal:2] Gosub("SIP/1101-00000016", "sub-record-check,s,1(out,1107,dontcare)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_stack.c:606 gosub_exec: Channel SIP/1101-00000016 has no datastore, so we're allocating one.
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_stack.c:648 gosub_exec: Setting 'ARG1' to 'out'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_stack.c:648 gosub_exec: Setting 'ARG2' to '1107'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_stack.c:648 gosub_exec: Setting 'ARG3' to 'dontcare'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'FROMEXTEN' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function LEN() result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@sub-record-check:1] GotoIf("SIP/1101-00000016", "0?initialized") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:11917 pbx_builtin_gotoif: Not taking any branch
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:2] Set("SIP/1101-00000016", "__REC_STATUS=INITIALIZED") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EPOCH' is '1451416259'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:3] Set("SIP/1101-00000016", "NOW=1451416259") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'NOW' is '1451416259'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function STRFTIME(1451416259,,%d) result is '29'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:4] Set("SIP/1101-00000016", "__DAY=29") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'NOW' is '1451416259'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function STRFTIME(1451416259,,%m) result is '12'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:5] Set("SIP/1101-00000016", "__MONTH=12") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'NOW' is '1451416259'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function STRFTIME(1451416259,,%Y) result is '2015'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:6] Set("SIP/1101-00000016", "__YEAR=2015") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'YEAR' is '2015'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'MONTH' is '12'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DAY' is '29'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'NOW' is '1451416259'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function STRFTIME(1451416259,,%H%M%S) result is '221059'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:7] Set("SIP/1101-00000016", "__TIMESTR=20151229-221059") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function LEN(1101) result is '4'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '4'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function LEN(1101) result is '4'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '4'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function IF(4?1101:unknown) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function IF(4?1101:1101) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:8] Set("SIP/1101-00000016", "__FROMEXTEN=1101") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'MIXMON_FORMAT' is 'wav'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'MIXMON_FORMAT' is 'wav'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function IF(0?WAV:wav) result is 'wav'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:9] Set("SIP/1101-00000016", "__MON_FMT=wav") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@sub-record-check:10] NoOp("SIP/1101-00000016", "Recordings initialized") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG3' is 'dontcare'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function LEN(dontcare) result is '8'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@sub-record-check:11] ExecIf("SIP/1101-00000016", "0?Set(ARG3=dontcare)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'REC_POLICY_MODE' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@sub-record-check:12] Set("SIP/1101-00000016", "REC_POLICY_MODE_SAVE=") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'BLINDTRANSFER' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'ATTENDEDTRANSFER' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@sub-record-check:13] ExecIf("SIP/1101-00000016", "0?Set(REC_STATUS=NO)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'out'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function LEN(out) result is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@sub-record-check:14] GotoIf("SIP/1101-00000016", "3?checkaction") in new stack
    -- Goto (sub-record-check,s,17)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'out'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function DIALPLAN_EXISTS(sub-record-check,out) result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'out'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@sub-record-check:17] GotoIf("SIP/1101-00000016", "1?sub-record-check,out,1") in new stack
    -- Goto (sub-record-check,out,1)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'FROMEXTEN' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG2' is '1107'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp'
    -- Executing [out@sub-record-check:1] NoOp("SIP/1101-00000016", "Outbound Recording Check from 1101 to 1107") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'FROMEXTEN' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1101/recording/out/external) result is 'dontcare'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [out@sub-record-check:2] Set("SIP/1101-00000016", "RECMODE=dontcare") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'RECMODE' is 'dontcare'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function LEN(dontcare) result is '8'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'RECMODE' is 'dontcare'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [out@sub-record-check:3] ExecIf("SIP/1101-00000016", "1?Goto(routewins)") in new stack
    -- Goto (sub-record-check,out,7)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG3' is 'dontcare'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG2' is '1107'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Gosub'
    -- Executing [out@sub-record-check:7] Gosub("SIP/1101-00000016", "recordcheck,1(dontcare,out,1107)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_stack.c:648 gosub_exec: Setting 'ARG1' to 'dontcare'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_stack.c:648 gosub_exec: Setting 'ARG2' to 'out'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_stack.c:648 gosub_exec: Setting 'ARG3' to '1107'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'dontcare'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp'
    -- Executing [recordcheck@sub-record-check:1] NoOp("SIP/1101-00000016", "Starting recording check against dontcare") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is 'dontcare'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Goto'
    -- Executing [recordcheck@sub-record-check:2] Goto("SIP/1101-00000016", "dontcare") in new stack
    -- Goto (sub-record-check,recordcheck,3)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Return'
    -- Executing [recordcheck@sub-record-check:3] Return("SIP/1101-00000016", "") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Return'
    -- Executing [out@sub-record-check:8] Return("SIP/1101-00000016", "") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'MOHCLASS' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'MOHCLASS' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function IF(1?default:) result is 'default'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [1107@from-internal:3] Set("SIP/1101-00000016", "MOHCLASS=default") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [1107@from-internal:4] Set("SIP/1101-00000016", "_NODEST=") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EXTEN' is '1107'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Macro'
    -- Executing [1107@from-internal:5] Macro("SIP/1101-00000016", "dialout-trunk,3,1107,,off") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-dialout-trunk:1] Set("SIP/1101-00000016", "DIAL_TRUNK=3") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG3' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: db.c:376 db_get_common: Unable to find key '1101/pinless' in family 'AMPUSER'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: func_db.c:151 function_db_read: DB: AMPUSER/1101/pinless not found in database.
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1101/pinless) result is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GosubIf'
    -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/1101-00000016", "0?sub-pincheck,s,1()") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: GosubIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'ARG3' (from 'ARG3}" != ""' len 4)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG3' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/pinless)' (from 'DB(AMPUSER/${AMPUSER}/pinless)}" != "NOPASSWD"' len 30)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/pinless)' len 7)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: db.c:376 db_get_common: Unable to find key '1101/pinless' in family 'AMPUSER'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: func_db.c:151 function_db_read: DB: AMPUSER/1101/pinless not found in database.
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function DB(AMPUSER/1101/pinless) result is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'OUTDISABLE_3' is 'off'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/1101-00000016", "0?disabletrunk,1") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:11917 pbx_builtin_gotoif: Not taking any branch
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: GotoIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG2' is '1107'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-dialout-trunk:4] Set("SIP/1101-00000016", "DIAL_NUMBER=1107") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_OPTIONS' is 'Ttr'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-dialout-trunk:5] Set("SIP/1101-00000016", "DIAL_TRUNK_OPTIONS=Ttr") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-dialout-trunk:6] Set("SIP/1101-00000016", "OUTBOUND_GROUP=OUT_3") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'OUTMAXCHANS_3' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/1101-00000016", "1?nomax") in new stack
    -- Goto (macro-dialout-trunk,s,9)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: GotoIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'INTRACOMPANYROUTE' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/1101-00000016", "0?skipoutcid") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:11917 pbx_builtin_gotoif: Not taking any branch
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: GotoIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: db.c:376 db_get_common: Unable to find key '3/dialopts' in family 'TRUNK'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function DB_EXISTS(TRUNK/3/dialopts) result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DB_RESULT' is 'dontcare'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'TRUNK_OPTIONS' is 'Tt'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function IF(0?dontcare:Tt) result is 'Tt'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-dialout-trunk:10] Set("SIP/1101-00000016", "DIAL_TRUNK_OPTIONS=Tt") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Macro'
    -- Executing [s@macro-dialout-trunk:11] Macro("SIP/1101-00000016", "outbound-callerid,3") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'CALLINGNAMEPRES_SV' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'CALLINGNAMEPRES_SV' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/1101-00000016", "0?Set(CALLERPRES(name-pres)=)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'CALLINGNAMEPRES_SV' (from 'CALLINGNAMEPRES_SV}" != ""' len 18)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'CALLINGNAMEPRES_SV' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'CALLINGNAMEPRES_SV' (from 'CALLINGNAMEPRES_SV})' len 18)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'CALLINGNAMEPRES_SV' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'CALLINGNUMPRES_SV' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'CALLINGNUMPRES_SV' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/1101-00000016", "0?Set(CALLERPRES(num-pres)=)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'CALLINGNUMPRES_SV' (from 'CALLINGNUMPRES_SV}" != ""' len 17)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'CALLINGNUMPRES_SV' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'CALLINGNUMPRES_SV' (from 'CALLINGNUMPRES_SV})' len 17)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'CALLINGNUMPRES_SV' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-outbound-callerid:3] ExecIf("SIP/1101-00000016", "0?Set(REALCALLERIDNUM=1101)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'REALCALLERIDNUM:1:2' (from 'REALCALLERIDNUM:1:2}" = ""' len 19)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function CALLERID(number) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'KEEPCID' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'OUTKEEPCID_3' is 'off'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-outbound-callerid:4] GotoIf("SIP/1101-00000016", "1?normcid") in new stack
    -- Goto (macro-outbound-callerid,s,7)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: GotoIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1101/outboundcid) result is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-outbound-callerid:7] Set("SIP/1101-00000016", "USEROUTCID=") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function DB(DEVICE/1101/emergency_cid) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-outbound-callerid:8] Set("SIP/1101-00000016", "EMERGENCYCID=TEST 123") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'OUTCID_3' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-outbound-callerid:9] Set("SIP/1101-00000016", "TRUNKOUTCID=") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'EMERGENCYROUTE' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'EMERGENCYCID' is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-outbound-callerid:10] GotoIf("SIP/1101-00000016", "1?trunkcid") in new stack
    -- Goto (macro-outbound-callerid,s,15)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: GotoIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'TRUNKOUTCID' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function LEN() result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'TRUNKOUTCID' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/1101-00000016", "0?Set(CALLERID(all)=)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'LEN(${TRUNKOUTCID})' (from 'LEN(${TRUNKOUTCID})} != 0' len 19)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'TRUNKOUTCID' (from 'TRUNKOUTCID})' len 11)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'TRUNKOUTCID' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function LEN() result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'TRUNKOUTCID' (from 'TRUNKOUTCID})' len 11)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'TRUNKOUTCID' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'USEROUTCID' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function LEN() result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'USEROUTCID' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-outbound-callerid:16] ExecIf("SIP/1101-00000016", "0?Set(CALLERID(all)=)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'LEN(${USEROUTCID})' (from 'LEN(${USEROUTCID})} != 0' len 18)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'USEROUTCID' (from 'USEROUTCID})' len 10)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'USEROUTCID' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function LEN() result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'USEROUTCID' (from 'USEROUTCID})' len 10)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'USEROUTCID' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function LEN() result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_3' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function LEN() result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_3' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function LEN() result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_3' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function IF(1?:) result is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-outbound-callerid:17] ExecIf("SIP/1101-00000016", "0?Set(CALLERID(all)=)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'LEN(${TRUNKCIDOVERRIDE})' (from 'LEN(${TRUNKCIDOVERRIDE})} != 0 | ${LEN(${FORCEDOUTCID_${ARG1}})} != 0' len 24)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'TRUNKCIDOVERRIDE' (from 'TRUNKCIDOVERRIDE})' len 16)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function LEN() result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'LEN(${FORCEDOUTCID_${ARG1}})' (from 'LEN(${FORCEDOUTCID_${ARG1}})} != 0' len 28)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'FORCEDOUTCID_${ARG1}' (from 'FORCEDOUTCID_${ARG1}})' len 20)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}' len 4)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_3' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function LEN() result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'IF($[${LEN(${FORCEDOUTCID_${ARG1}})}=0]?${TRUNKCIDOVERRIDE}:${FORCEDOUTCID_${ARG1}})' (from 'IF($[${LEN(${FORCEDOUTCID_${ARG1}})}=0]?${TRUNKCIDOVERRIDE}:${FORCEDOUTCID_${ARG1}})})' len 84)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'LEN(${FORCEDOUTCID_${ARG1}})' (from 'LEN(${FORCEDOUTCID_${ARG1}})}=0' len 28)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'FORCEDOUTCID_${ARG1}' (from 'FORCEDOUTCID_${ARG1}})' len 20)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}' len 4)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_3' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function LEN() result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'TRUNKCIDOVERRIDE' (from 'TRUNKCIDOVERRIDE}:${FORCEDOUTCID_${ARG1}})' len 16)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'FORCEDOUTCID_${ARG1}' (from 'FORCEDOUTCID_${ARG1}})' len 20)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}' len 4)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG1' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_3' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function IF(1?:) result is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(name) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-outbound-callerid:18] ExecIf("SIP/1101-00000016", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'CALLERID(name)' (from 'CALLERID(name)}"="hidden"' len 14)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function CALLERID(name) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(name) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-outbound-callerid:19] ExecIf("SIP/1101-00000016", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'CALLERID(name)' (from 'CALLERID(name)}"="hidden"' len 14)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function CALLERID(name) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-outbound-callerid:20] Set("SIP/1101-00000016", "CDR(outbound_cnum)=1101") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(name) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-outbound-callerid:21] Set("SIP/1101-00000016", "CDR(outbound_cnam)=TEST 123") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Macro
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'PREFIX_TRUNK_3' is '2'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GosubIf'
    -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/1101-00000016", "1?sub-flp-3,s,1()") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: GosubIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'PREFIX_TRUNK_${DIAL_TRUNK}' (from 'PREFIX_TRUNK_${DIAL_TRUNK}}" != ""' len 26)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'DIAL_TRUNK' (from 'DIAL_TRUNK}' len 10)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'PREFIX_TRUNK_3' is '2'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'DIAL_TRUNK' (from 'DIAL_TRUNK},s,1()' len 10)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:454 _macro_exec: Incrementing gosub_level
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '1107'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: func_strings.c:973 regex: FUNCTION REGEX (^[0-9][0-9][0-9]$)(1107)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function REGEX("^[0-9][0-9][0-9]$" 1107) result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@sub-flp-3:1] ExecIf("SIP/1101-00000016", "0?Return()") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'REGEX("^[0-9][0-9][0-9]$" ${DIAL_NUMBER})' (from 'REGEX("^[0-9][0-9][0-9]$" ${DIAL_NUMBER})} = 1' len 41)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'DIAL_NUMBER' (from 'DIAL_NUMBER})' len 11)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '1107'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: func_strings.c:973 regex: FUNCTION REGEX (^[0-9][0-9][0-9]$)(1107)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function REGEX("^[0-9][0-9][0-9]$" 1107) result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '1107'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: func_strings.c:973 regex: FUNCTION REGEX (^[0-9][0-9][0-9][0-9]$)(1107)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function REGEX("^[0-9][0-9][0-9][0-9]$" 1107) result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@sub-flp-3:2] ExecIf("SIP/1101-00000016", "1?Return()") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'REGEX("^[0-9][0-9][0-9][0-9]$" ${DIAL_NUMBER})' (from 'REGEX("^[0-9][0-9][0-9][0-9]$" ${DIAL_NUMBER})} = 1' len 46)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'DIAL_NUMBER' (from 'DIAL_NUMBER})' len 11)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '1107'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: func_strings.c:973 regex: FUNCTION REGEX (^[0-9][0-9][0-9][0-9]$)(1107)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function REGEX("^[0-9][0-9][0-9][0-9]$" 1107) result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'OUTPREFIX_3' is ''
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '1107'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-dialout-trunk:13] Set("SIP/1101-00000016", "OUTNUM=1107") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'OUT_3' (from 'OUT_3}' len 5)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'OUT_3' is 'SIP/test'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CUT(OUT_3,:,1) result is 'SIP/test'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-dialout-trunk:14] Set("SIP/1101-00000016", "custom=SIP/test") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'FORCE_CONFIRM' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/1101-00000016", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'MOHCLASS' (from 'MOHCLASS}"!="default" & "${MOHCLASS}"!="" & "${FORCE_CONFIRM}"="" ' len 8)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'MOHCLASS' (from 'MOHCLASS}"!="" & "${FORCE_CONFIRM}"="" ' len 8)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'FORCE_CONFIRM' (from 'FORCE_CONFIRM}"="" ' len 13)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'FORCE_CONFIRM' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'MOHCLASS' (from 'MOHCLASS})${DIAL_TRUNK_OPTIONS})' len 8)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'DIAL_TRUNK_OPTIONS' (from 'DIAL_TRUNK_OPTIONS})' len 18)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'FORCE_CONFIRM' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/1101-00000016", "0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'FORCE_CONFIRM' (from 'FORCE_CONFIRM}"!="" ' len 13)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'FORCE_CONFIRM' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'DIAL_TRUNK_OPTIONS' (from 'DIAL_TRUNK_OPTIONS}M(confirm))' len 18)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Macro'
    -- Executing [s@macro-dialout-trunk:17] Macro("SIP/1101-00000016", "dialout-trunk-predial-hook,") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'MacroExit'
    -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/1101-00000016", "") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Macro
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'PREDIAL_HOOK_RET' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/1101-00000016", "0?bypass,1") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:11917 pbx_builtin_gotoif: Not taking any branch
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: GotoIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1101/cidname) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '1107'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/1101-00000016", "1?Set(CONNECTEDLINE(num,i)=1107)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/cidname)' (from 'DB(AMPUSER/${AMPUSER}/cidname)}" != ""' len 30)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/cidname)' len 7)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function DB(AMPUSER/1101/cidname) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'DIAL_NUMBER' (from 'DIAL_NUMBER})' len 11)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '1107'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1101/cidname) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(name) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/1101-00000016", "1?Set(CONNECTEDLINE(name,i)=CID:1101)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/cidname)' (from 'DB(AMPUSER/${AMPUSER}/cidname)}" != ""' len 30)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/cidname)' len 7)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function DB(AMPUSER/1101/cidname) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'CALLERID(name)' (from 'CALLERID(name)}"!="hidden"' len 14)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function CALLERID(name) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function CALLERID(number) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1101/cidname) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(name) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-dialout-trunk:21] ExecIf("SIP/1101-00000016", "0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)1101)") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: ExecIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/cidname)' (from 'DB(AMPUSER/${AMPUSER}/cidname)}" != ""' len 30)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/cidname)' len 7)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function DB(AMPUSER/1101/cidname) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '1'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'CALLERID(name)' (from 'CALLERID(name)}"="hidden"' len 14)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function CALLERID(name) result is 'TEST 123'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4676 ast_str_substitute_variables_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4584 ast_str_substitute_variables_full: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4618 ast_str_substitute_variables_full: Function CALLERID(number) result is '1101'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'custom' is 'SIP/test'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dialout-trunk:22] GotoIf("SIP/1101-00000016", "0?customtrunk") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:11917 pbx_builtin_gotoif: Not taking any branch
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: GotoIf
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'OUT_3' is 'SIP/test'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'OUTNUM' is '1107'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '3'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3782 ast_str_retrieve_variable: Result of 'OUT_3_SUFFIX' is NULL
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'TRUNK_RING_TIMER' is '300'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Dial'
    -- Executing [s@macro-dialout-trunk:23] Dial("SIP/1101-00000016", "SIP/test/1107,300,Tt") in new stack
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: chan_sip.c:29641 sip_request_call: Asked to create a SIP channel with formats: (ulaw)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: chan_sip.c:8765 __sip_alloc: Allocating new SIP dialog for 61733bac25c18bcc227ffb0f224043ce@127.0.1.1:5060 - INVITE (No RTP)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: rtp_engine.c:429 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f1979433008'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: res_rtp_asterisk.c:2532 ast_rtp_new: Allocated port 19280 for RTP instance '0x7f1979433008'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: rtp_engine.c:438 ast_rtp_instance_new: RTP instance '0x7f1979433008' is setup and ready to go
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: res_rtp_asterisk.c:4766 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f1979433008'
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: chan_sip.c:5602 do_setnat: Setting NAT on RTP to On
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: acl.c:946 ast_ouraddrfor: For destination '172.16.15.196', our source address is '172.16.10.173'.
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: chan_sip.c:3866 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 172.16.10.173:5060
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: chan_sip.c:5602 do_setnat: Setting NAT on RTP to On
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: chan_sip.c:8550 change_callid_pvt: SIP call-id changed from '61733bac25c18bcc227ffb0f224043ce@127.0.1.1:5060' to '668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060'
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: chan_sip.c:7927 sip_new: *** Our native formats are (ulaw)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: chan_sip.c:7928 sip_new: *** Joint capabilities are (ulaw)
failed to extend from 64 to 98
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: chan_sip.c:7929 sip_new: *** Our capabilities are (ulaw|alaw|gsm|g726|g723|g726aal2|adpcm|slin|slin|slin|slin|)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: chan_sip.c:7930 sip_new: *** AST_CODEC_CHOOSE formats are ulaw
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: chan_sip.c:7932 sip_new: *** Our preferred formats from the incoming channel are (ulaw)
[2015-12-29 22:10:59] DEBUG[6695][C-0000000b]: chan_sip.c:7958 sip_new: This channel will not be able to handle video.
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: channel_internal_api.c:933 ast_channel_callid_set: Channel Call ID changing from [C-0000000b] to [C-0000000b]
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: channel.c:6463 ast_channel_inherit_variables: Inheriting variable NODEST from SIP/1101-00000016 to SIP/test-00000017.
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: channel.c:6463 ast_channel_inherit_variables: Inheriting variable __MON_FMT from SIP/1101-00000016 to SIP/test-00000017.
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: channel.c:6463 ast_channel_inherit_variables: Inheriting variable __FROMEXTEN from SIP/1101-00000016 to SIP/test-00000017.
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: channel.c:6463 ast_channel_inherit_variables: Inheriting variable __TIMESTR from SIP/1101-00000016 to SIP/test-00000017.
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: channel.c:6463 ast_channel_inherit_variables: Inheriting variable __YEAR from SIP/1101-00000016 to SIP/test-00000017.
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: channel.c:6463 ast_channel_inherit_variables: Inheriting variable __MONTH from SIP/1101-00000016 to SIP/test-00000017.
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: channel.c:6463 ast_channel_inherit_variables: Inheriting variable __DAY from SIP/1101-00000016 to SIP/test-00000017.
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: channel.c:6463 ast_channel_inherit_variables: Inheriting variable __REC_STATUS from SIP/1101-00000016 to SIP/test-00000017.
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: channel.c:6463 ast_channel_inherit_variables: Inheriting variable __DIAL_OPTIONS from SIP/1101-00000016 to SIP/test-00000017.
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:6242 sip_call: Outgoing Call for 1107
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:6559 update_call_counter: Updating call counter for outgoing call
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:13170 add_sdp: This call needs video offers, but there's no video support enabled!
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:13185 add_sdp: This call needs text offers, but there's no text support enabled !
failed to extend from 64 to 98
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:13192 add_sdp: ** Our capability: (ulaw|alaw|gsm|g726|g723|g726aal2|adpcm|slin|slin|slin|slin|) Video flag: False Text flag: False
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:13193 add_sdp: ** Our prefcodec: (ulaw)
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:13363 add_sdp: -- Done with adding codecs to SDP
failed to extend from 64 to 98
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:13566 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw|gsm|g726|g723|g726aal2|adpcm|slin|slin|slin|slin|)
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:3352 initialize_initreq: Initializing initreq for method INVITE - callid 668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:3709 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 172.16.15.196:5060
[2015-12-29 22:11:00] DEBUG[1786]: chan_sip.c:9178 __find_call: = Looking for  Call ID: 668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060 (Checking To) --From tag as37a9ec90 --To-tag as50a22ac1
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:4368 __sip_ack: Acked pending invite 102
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:4406 __sip_ack: Stopping retransmission on '668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060' of Request 102: Match Found
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:22944 handle_response_invite: SIP response 401 to standard invite
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:3709 __sip_xmit: Trying to put 'ACK sip:110' onto UDP socket destined for 172.16.15.196:5060
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:22121 do_proxy_auth: Auth attempt 1 on INVITE
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:13170 add_sdp: This call needs video offers, but there's no video support enabled!
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:13185 add_sdp: This call needs text offers, but there's no text support enabled !
failed to extend from 64 to 98
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:13192 add_sdp: ** Our capability: (ulaw|alaw|gsm|g726|g723|g726aal2|adpcm|slin|slin|slin|slin|) Video flag: False Text flag: False
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:13193 add_sdp: ** Our prefcodec: (ulaw)
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:13363 add_sdp: -- Done with adding codecs to SDP
failed to extend from 64 to 98
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:13566 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw|gsm|g726|g723|g726aal2|adpcm|slin|slin|slin|slin|)
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:3709 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 172.16.15.196:5060
[2015-12-29 22:11:00] DEBUG[1786]: chan_sip.c:9178 __find_call: = Looking for  Call ID: 668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060 (Checking To) --From tag as37a9ec90 --To-tag
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:4447 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060' Request 103: Found
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:22944 handle_response_invite: SIP response 100 to standard invite
[2015-12-29 22:11:00] DEBUG[1786]: chan_sip.c:9178 __find_call: = Looking for  Call ID: 668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060 (Checking To) --From tag as37a9ec90 --To-tag as5811c0b3
    -- Called SIP/test/1107
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:4447 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060' Request 103: Found
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:22944 handle_response_invite: SIP response 180 to standard invite
[2015-12-29 22:11:00] DEBUG[566]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for SIP - test
[2015-12-29 22:11:00] DEBUG[566]: chan_sip.c:29535 sip_devicestate: Checking device state for peer test
[2015-12-29 22:11:00] DEBUG[566]: devicestate.c:473 do_state_change: Changing state for SIP/test - state 1 (Not in use)
[2015-12-29 22:11:00] DEBUG[1786]: chan_sip.c:9178 __find_call: = Looking for  Call ID: 668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060 (Checking To) --From tag as37a9ec90 --To-tag as5811c0b3
    -- SIP/test-00000017 is ringing
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: rtp_engine.c:1303 ast_rtp_instance_early_bridge: Setting early bridge SDP of 'SIP/1101-00000016' with that of 'SIP/test-00000017'
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:3709 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for 172.16.8.41:5060
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:4447 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060' Request 103: Found
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:22944 handle_response_invite: SIP response 180 to standard invite
    -- SIP/test-00000017 is ringing
[2015-12-29 22:11:00] DEBUG[1786]: chan_sip.c:9178 __find_call: = Looking for  Call ID: 668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060 (Checking To) --From tag as37a9ec90 --To-tag as5811c0b3
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: rtp_engine.c:1303 ast_rtp_instance_early_bridge: Setting early bridge SDP of 'SIP/1101-00000016' with that of 'SIP/test-00000017'
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: res_rtp_asterisk.c:4386 ast_rtp_read: 0x7f19794d1780 -- Probation learning mode pass with source address 172.16.15.196:15732
       > 0x7f19794d1780 -- Probation passed - setting RTP source address to 172.16.15.196:15732
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: res_rtp_asterisk.c:4822 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f1979433008'
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:8370 sip_rtp_read: Oooh, format changed to alaw
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: channel.c:5495 set_format: Channel SIP/test-00000017 setting read format path: alaw -> ulaw
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: channel.c:5495 set_format: Channel SIP/test-00000017 setting write format path: ulaw -> alaw
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:4447 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060' Request 103: Found
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:22944 handle_response_invite: SIP response 183 to standard invite
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10026 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10026 process_sdp: Processing session-level SDP o=root 475415851 475415851 IN IP4 172.16.15.196... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10026 process_sdp: Processing session-level SDP s=Asterisk PBX 11.10.2... UNSUPPORTED OR FAILED.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '172.16.15.196' into...
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '172.16.15.196' and port ''.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10026 process_sdp: Processing session-level SDP c=IN IP4 172.16.15.196... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10026 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 18 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 4 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 112 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 5 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 7 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 110 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 97 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 111 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 102 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 115 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 116 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 117 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 10 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 118 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 119 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f193bc3e300
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:4 G723/8000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=fmtp:4 annexa=no... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:112 AAL2-G726-32/8000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:5 DVI4/8000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:7 LPC/8000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:110 speex/8000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:97 iLBC/8000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=fmtp:97 mode=30... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:111 G726-32/8000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:102 G7221/16000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=fmtp:102 bitrate=32000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:115 G7221/32000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=fmtp:115 bitrate=48000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:116 G719/48000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=fmtp:116 bitrate=64000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:117 speex/16000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:10 L16/8000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:118 L16/16000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:119 speex/32000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10481 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: res_rtp_asterisk.c:4822 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f1979433008'
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x2e54cc0) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 3 (0x14532f0) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 4 (0x31d1580) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 5 (0x31d1600) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 7 (0x2f0aa20) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x31f6600) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 9 (0x1456cc0) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 10 (0x31e5940) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 18 (0x1454a10) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 97 (0x1456c80) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x31e5a00) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 102 (0x1456d40) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 110 (0x2f0aa60) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 111 (0x2f0aaa0) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 112 (0x31d15c0) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 115 (0x31e58c0) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 116 (0x31e5900) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 117 (0x1456d00) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 118 (0x31e5980) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: rtp_engine.c:633 ast_rtp_codecs_payloads_copy: Copying payload 119 (0x31e59c0) from 0x7f193bc3e300 to 0x7f19794331d0
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: res_rtp_asterisk.c:4732 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f1979433008'
failed to extend from 64 to 101
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10771 process_sdp: We're settling with these formats: (ulaw|alaw|gsm|g726|g723|g726aal2|adpcm|slin|slin|lpc10|g729|)
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: chan_sip.c:10778 process_sdp: We have an owner, now see if we need to change this call
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: channel.c:5495 set_format: Channel SIP/test-00000017 setting read format path: ulaw -> ulaw
[2015-12-29 22:11:00] DEBUG[1786][C-0000000b]: channel.c:5495 set_format: Channel SIP/test-00000017 setting write format path: ulaw -> ulaw
    -- SIP/test-00000017 is making progress passing it to SIP/1101-00000016
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: rtp_engine.c:1303 ast_rtp_instance_early_bridge: Setting early bridge SDP of 'SIP/1101-00000016' with that of 'SIP/test-00000017'
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:13680 transmit_response_with_sdp: Setting framing from config on incoming call
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:13192 add_sdp: ** Our capability: (ulaw|alaw) Video flag: True Text flag: True
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:13193 add_sdp: ** Our prefcodec: (nothing)
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:13363 add_sdp: -- Done with adding codecs to SDP
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:13566 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw)
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:3709 __sip_xmit: Trying to put 'SIP/2.0 183' onto UDP socket destined for 172.16.8.41:5060
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: res_rtp_asterisk.c:4386 ast_rtp_read: 0x7f19794d1780 -- Probation learning mode pass with source address 172.16.15.196:15732
       > 0x7f19794d1780 -- Probation passed - setting RTP source address to 172.16.15.196:15732
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: chan_sip.c:8370 sip_rtp_read: Oooh, format changed to alaw
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: channel.c:5495 set_format: Channel SIP/test-00000017 setting read format path: alaw -> ulaw
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: channel.c:5495 set_format: Channel SIP/test-00000017 setting write format path: ulaw -> alaw
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: res_rtp_asterisk.c:3470 ast_rtp_write: Ooh, format changed from none to ulaw
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: res_rtp_asterisk.c:3315 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x142dbc8'
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: res_rtp_asterisk.c:4386 ast_rtp_read: 0x1427c60 -- Probation learning mode pass with source address 172.16.8.41:11802
       > 0x1427c60 -- Probation passed - setting RTP source address to 172.16.8.41:11802
[2015-12-29 22:11:00] DEBUG[6695][C-0000000b]: res_rtp_asterisk.c:3470 ast_rtp_write: Ooh, format changed from none to alaw
[2015-12-29 22:11:03] DEBUG[1786]: chan_sip.c:9178 __find_call: = Looking for  Call ID: 668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060 (Checking To) --From tag as37a9ec90 --To-tag as5811c0b3
[2015-12-29 22:11:03] DEBUG[1786][C-0000000b]: chan_sip.c:4368 __sip_ack: Acked pending invite 103
[2015-12-29 22:11:03] DEBUG[1786][C-0000000b]: chan_sip.c:4406 __sip_ack: Stopping retransmission on '668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060' of Request 103: Match Found
    -- Got SIP response 503 "Service Unavailable" back from 172.16.15.196:5060
[2015-12-29 22:11:03] DEBUG[1786][C-0000000b]: res_rtp_asterisk.c:4822 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f1979433008'
[2015-12-29 22:11:03] DEBUG[1786][C-0000000b]: chan_sip.c:3709 __sip_xmit: Trying to put 'ACK sip:110' onto UDP socket destined for 172.16.15.196:5060
[2015-12-29 22:11:03] DEBUG[1786][C-0000000b]: chan_sip.c:3365 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060
    -- SIP/test-00000017 is circuit-busy
[2015-12-29 22:11:03] DEBUG[696]: cdr.c:1276 cdr_object_finalize: Finalized CDR for SIP/1101-00000016 - start 1451416259.059473 answer 0.000000 end 1451416263.765721 dispo FAILED
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: channel.c:2682 ast_hangup: Hanging up channel 'SIP/test-00000017'
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: chan_sip.c:6942 sip_hangup: Hangup call SIP/test-00000017, SIP callid 668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: res_rtp_asterisk.c:4822 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f1979433008'
[2015-12-29 22:11:03] DEBUG[696]: cdr.c:1276 cdr_object_finalize: Finalized CDR for SIP/test-00000017 - start 1451416259.993234 answer 0.000000 end 1451416263.773408 dispo FAILED
[2015-12-29 22:11:03] DEBUG[696]: cdr.c:1104 cdr_object_create_public_records: CDR for SIP/test-00000017 is dialed and has no Party B; discarding
[2015-12-29 22:11:03] DEBUG[566]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for SIP - test
[2015-12-29 22:11:03] DEBUG[566]: chan_sip.c:29535 sip_devicestate: Checking device state for peer test
[2015-12-29 22:11:03] DEBUG[566]: devicestate.c:473 do_state_change: Changing state for SIP/test - state 1 (Not in use)
  == Everyone is busy/congested at this time (1:0/1/0)
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: app_dial.c:3092 dial_exec_full: Exiting with DIALSTATUS=CONGESTION.
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Dial
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIALSTATUS' is 'CONGESTION'
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'HANGUPCAUSE' is '34'
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@macro-dialout-trunk:24] NoOp("SIP/1101-00000016", "Dial failed for some reason with DIALSTATUS = CONGESTION and HANGUPCAUSE = 34") in new stack
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Noop
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'ARG4' is 'off'
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIALSTATUS' is 'CONGESTION'
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-dialout-trunk:25] GotoIf("SIP/1101-00000016", "0?continue,1:s-CONGESTION,1") in new stack
    -- Goto (macro-dialout-trunk,s-CONGESTION,1)
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: GotoIf
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'HANGUPCAUSE' is '34'
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function ISNULL(34) result is '0'
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:4887 pbx_substitute_variables_helper_full: Expression result is '0'
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'HANGUPCAUSE' is '34'
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:4818 pbx_substitute_variables_helper_full: Function IF(0?0:34) result is '34'
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [s-CONGESTION@macro-dialout-trunk:1] Set("SIP/1101-00000016", "RC=34") in new stack
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'RC' is '34'
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Goto'
    -- Executing [s-CONGESTION@macro-dialout-trunk:2] Goto("SIP/1101-00000016", "34,1") in new stack
    -- Goto (macro-dialout-trunk,34,1)
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Goto
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Goto'
    -- Executing [34@macro-dialout-trunk:1] Goto("SIP/1101-00000016", "continue,1") in new stack
    -- Goto (macro-dialout-trunk,continue,1)
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Goto
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'DIALSTATUS' is 'CONGESTION'
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'HANGUPCAUSE' is '34'
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'NoOp'
    -- Executing [continue@macro-dialout-trunk:1] NoOp("SIP/1101-00000016", "TRUNK Dial failed due to CONGESTION HANGUPCAUSE: 34 - failing through to other trunks") in new stack
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Noop
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:3785 ast_str_retrieve_variable: Result of 'AMPUSER' is '1101'
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Set'
    -- Executing [continue@macro-dialout-trunk:2] Set("SIP/1101-00000016", "CALLERID(number)=1101") in new stack
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: app_macro.c:439 _macro_exec: Executed application: Set
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Macro'
    -- Executing [1107@from-internal:6] Macro("SIP/1101-00000016", "outisbusy,") in new stack
[2015-12-29 22:11:03] WARNING[6695][C-0000000b]: app_macro.c:310 _macro_exec: No such context 'macro-outisbusy' for macro 'outisbusy'. Was called by 1107@from-internal
[2015-12-29 22:11:03] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Wait'
    -- Executing [1107@from-internal:7] Wait("SIP/1101-00000016", "1") in new stack
[2015-12-29 22:11:04] DEBUG[1786]: chan_sip.c:6707 sip_destroy: Destroying SIP dialog 668fe1917bbf9a8132fcda2c1ee5285c@172.16.10.173:5060
[2015-12-29 22:11:04] DEBUG[1786]: rtp_engine.c:372 instance_destructor: Destroyed RTP instance '0x7f1979433008'
[2015-12-29 22:11:04] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Congestion'
    -- Executing [1107@from-internal:8] Congestion("SIP/1101-00000016", "20") in new stack
[2015-12-29 22:11:04] DEBUG[6695][C-0000000b]: chan_sip.c:3709 __sip_xmit: Trying to put 'SIP/2.0 503' onto UDP socket destined for 172.16.8.41:5060
[2015-12-29 22:11:04] DEBUG[6695][C-0000000b]: chan_sip.c:3365 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 0_3669211333@172.16.8.41
[2015-12-29 22:11:04] DEBUG[6695][C-0000000b]: channel.c:2533 ast_softhangup_nolock: Soft-Hanging (0x01) up channel 'SIP/1101-00000016'
[2015-12-29 22:11:04] DEBUG[566]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for SIP - 1101
[2015-12-29 22:11:04] DEBUG[566]: chan_sip.c:29535 sip_devicestate: Checking device state for peer 1101
[2015-12-29 22:11:04] DEBUG[566]: devicestate.c:473 do_state_change: Changing state for SIP/1101 - state 2 (In use)
[2015-12-29 22:11:04] DEBUG[6695][C-0000000b]: pbx.c:6640 __ast_pbx_run: Spawn extension (from-internal,1107,8) exited non-zero on 'SIP/1101-00000016'
  == Spawn extension (from-internal, 1107, 8) exited non-zero on 'SIP/1101-00000016'
[2015-12-29 22:11:04] DEBUG[6695][C-0000000b]: channel.c:2533 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'SIP/1101-00000016'
[2015-12-29 22:11:04] DEBUG[6695][C-0000000b]: channel.c:2533 ast_softhangup_nolock: Soft-Hanging (0x80) up channel 'SIP/1101-00000016'
[2015-12-29 22:11:04] DEBUG[6695][C-0000000b]: pbx.c:4983 pbx_extension_helper: Launching 'Hangup'
    -- Executing [h@from-internal:1] Hangup("SIP/1101-00000016", "") in new stack
[2015-12-29 22:11:04] DEBUG[6695][C-0000000b]: channel.c:2533 ast_softhangup_nolock: Soft-Hanging (0x20) up channel 'SIP/1101-00000016'
[2015-12-29 22:11:04] DEBUG[6695][C-0000000b]: pbx.c:6209 ast_pbx_h_exten_run: Spawn extension (from-internal,h,1) exited non-zero on 'SIP/1101-00000016'
  == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/1101-00000016'
[2015-12-29 22:11:04] DEBUG[6695][C-0000000b]: channel.c:2682 ast_hangup: Hanging up channel 'SIP/1101-00000016'
[2015-12-29 22:11:04] DEBUG[6695][C-0000000b]: chan_sip.c:6942 sip_hangup: Hangup call SIP/1101-00000016, SIP callid 0_3669211333@172.16.8.41
[2015-12-29 22:11:04] DEBUG[6695][C-0000000b]: chan_sip.c:6559 update_call_counter: Updating call counter for incoming call
[2015-12-29 22:11:04] DEBUG[566]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for SIP - 1101
[2015-12-29 22:11:04] DEBUG[566]: chan_sip.c:29535 sip_devicestate: Checking device state for peer 1101
[2015-12-29 22:11:04] DEBUG[566]: devicestate.c:473 do_state_change: Changing state for SIP/1101 - state 1 (Not in use)
[2015-12-29 22:11:04] DEBUG[1047]: devicestate.c:364 _ast_device_state: Checking if I can find provider for "Custom" - number: DND1101
[2015-12-29 22:11:04] DEBUG[1047]: devicestate.c:453 getproviderstate: Checking provider Custom with Custom
[2015-12-29 22:11:04] DEBUG[1047]: db.c:376 db_get_common: Unable to find key 'DND1101' in family 'CustomDevstate'
[2015-12-29 22:11:04] DEBUG[1047]: app_queue.c:2458 extension_state_cb: Extension '1101@ext-local' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[2015-12-29 22:11:04] DEBUG[1047]: devicestate.c:364 _ast_device_state: Checking if I can find provider for "Custom" - number: DND1101
[2015-12-29 22:11:04] DEBUG[1047]: devicestate.c:453 getproviderstate: Checking provider Custom with Custom
[2015-12-29 22:11:04] DEBUG[1047]: db.c:376 db_get_common: Unable to find key 'DND1101' in family 'CustomDevstate'
[2015-12-29 22:11:04] DEBUG[1047]: app_queue.c:2458 extension_state_cb: Extension '*801101@ext-local' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[2015-12-29 22:11:04] DEBUG[1786]: chan_sip.c:9178 __find_call: = Looking for  Call ID: 0_3669211333@172.16.8.41 (Checking From) --From tag 1698527837 --To-tag as2f681f10
[2015-12-29 22:11:04] DEBUG[1805]: app_queue.c:2383 device_state_cb: Device 'SIP/1101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[2015-12-29 22:11:04] DEBUG[6695][C-0000000b]: res_rtp_asterisk.c:4822 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x142dbc8'
[2015-12-29 22:11:04] DEBUG[1786][C-0000000b]: chan_sip.c:28034 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[2015-12-29 22:11:04] DEBUG[1786][C-0000000b]: chan_sip.c:4406 __sip_ack: Stopping retransmission on '0_3669211333@172.16.8.41' of Response 2: Match Found
[2015-12-29 22:11:04] DEBUG[6695][C-0000000b]: chan_sip.c:6707 sip_destroy: Destroying SIP dialog 0_3669211333@172.16.8.41
[2015-12-29 22:11:04] DEBUG[6695][C-0000000b]: rtp_engine.c:372 instance_destructor: Destroyed RTP instance '0x142dbc8'
[2015-12-29 22:11:04] DEBUG[696]: cdr.c:1276 cdr_object_finalize: Finalized CDR for SIP/1101-00000016 - start 1451416263.796286 answer 0.000000 end 1451416264.899335 dispo FAILED
[2015-12-29 22:11:04] DEBUG[696]: res_config_sqlite.c:827 cdr_handler: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,start,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"TEST 123" <1101>','1101','1107','from-internal','SIP/1101-00000016','SIP/test-00000017','Dial','SIP/test/1107,300,Tt','2015-12-29 22:10:59','2015-12-29 22:11:03','4','0','FAILED','DOCUMENTATION','1451416259.22')
[2015-12-29 22:11:04] DEBUG[566]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for SIP - 1101
[2015-12-29 22:11:04] DEBUG[566]: chan_sip.c:29535 sip_devicestate: Checking device state for peer 1101
[2015-12-29 22:11:04] DEBUG[566]: devicestate.c:473 do_state_change: Changing state for SIP/1101 - state 1 (Not in use)
[2015-12-29 22:11:04] DEBUG[696]: cdr.c:3261 post_cdr: Skipping CDR  for SIP/1101-00000016 since we weren't answered
[2015-12-29 22:11:05] DEBUG[1786]: chan_sip.c:9178 __find_call: = Looking for  Call ID: 5a079236-4c04e388@172.16.14.74 (Checking From) --From tag ef66ff8e70e09610o0 --To-tag
[2015-12-29 22:11:05] DEBUG[1786]: chan_sip.c:28034 handle_incoming: **** Received NOTIFY (4) - Command in SIP NOTIFY
[2015-12-29 22:11:05] DEBUG[1786]: chan_sip.c:3709 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 172.16.14.74:5060
[2015-12-29 22:11:05] DEBUG[1786]: chan_sip.c:4262 __sip_autodestruct: Auto destroying SIP dialog '0_3347691025@172.16.8.41'
[2015-12-29 22:11:05] DEBUG[1786]: chan_sip.c:6707 sip_destroy: Destroying SIP dialog 0_3347691025@172.16.8.41
[2015-12-29 22:11:06] DEBUG[1786]: chan_sip.c:8765 __sip_alloc: Allocating new SIP dialog for 10458bc136b891665ec287c60df517b3@127.0.1.1:5060 - OPTIONS (No RTP)
[2015-12-29 22:11:06] DEBUG[1786]: acl.c:946 ast_ouraddrfor: For destination '172.16.14.74', our source address is '172.16.10.173'.
[2015-12-29 22:11:06] DEBUG[1786]: chan_sip.c:3866 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 172.16.10.173:5060
[2015-12-29 22:11:06] DEBUG[1786]: chan_sip.c:8550 change_callid_pvt: SIP call-id changed from '10458bc136b891665ec287c60df517b3@127.0.1.1:5060' to '481e965a7786883a7ab8f2f67aa783d5@172.16.10.173:5060'
[2015-12-29 22:11:06] DEBUG[1786]: chan_sip.c:3352 initialize_initreq: Initializing initreq for method OPTIONS - callid 481e965a7786883a7ab8f2f67aa783d5@172.16.10.173:5060
[2015-12-29 22:11:06] DEBUG[1786]: chan_sip.c:3709 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.16.14.74:5061
[2015-12-29 22:11:06] DEBUG[1786]: chan_sip.c:9178 __find_call: = Looking for  Call ID: 481e965a7786883a7ab8f2f67aa783d5@172.16.10.173:5060 (Checking To) --From tag as2e1464fe --To-tag 1de7217686789d48i1
[2015-12-29 22:11:06] DEBUG[1786]: chan_sip.c:4406 __sip_ack: Stopping retransmission on '481e965a7786883a7ab8f2f67aa783d5@172.16.10.173:5060' of Request 102: Match Found
[2015-12-29 22:11:06] DEBUG[1786]: chan_sip.c:6707 sip_destroy: Destroying SIP dialog 481e965a7786883a7ab8f2f67aa783d5@172.16.10.173:5060