*CLI> core set verbose 9
Verbosity is at least 9
**CLI> core set debug 9
Core debug was 0 and is now 9
*CLI>   == Using TOS bits 0
  == Using CoS mark 0
  == Using TOS bits 0
  == Using CoS mark 0
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:2945 do_setnat: Setting NAT on RTP to On
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:2950 do_setnat: Setting NAT on VRTP to On
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:4781 sip_alloc: Allocating new SIP dialog for bc3ab832ec015b66@YnJhaW4uaG9tZXNvZnQubG9jYWw. - INVITE (With RTP)
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:15670 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:2945 do_setnat: Setting NAT on RTP to On
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:2950 do_setnat: Setting NAT on VRTP to On
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:4847 find_call: = Found Their Call ID: bc3ab832ec015b66@YnJhaW4uaG9tZXNvZnQubG9jYWw. Their Tag c7134d5f Our tag: as04207bc1
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:15670 handle_request: **** Received ACK (6) - Command in SIP ACK
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:2289 __sip_ack: Stopping retransmission on 'bc3ab832ec015b66@YnJhaW4uaG9tZXNvZnQubG9jYWw.' of Response 1: Match Found
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:4847 find_call: = Found Their Call ID: bc3ab832ec015b66@YnJhaW4uaG9tZXNvZnQubG9jYWw. Their Tag c7134d5f Our tag: as04207bc1
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:15670 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:2945 do_setnat: Setting NAT on RTP to On
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:2950 do_setnat: Setting NAT on VRTP to On
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:5663 process_sdp: T38 state changed to 0 on channel <none>
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:5754 process_sdp: We're settling with these formats: 0x8 (alaw)
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:14354 handle_request_invite: Checking SIP call limits for device 100
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:3413 update_call_counter: Updating call counter for incoming call
[May 25 20:34:15] DEBUG[21863]: frame.c:1157 ast_codec_choose: Could not find preferred codec - Going for the best codec
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:4235 sip_new: *** Our native formats are 0x8 (alaw)
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:4236 sip_new: *** Joint capabilities are 0x8 (alaw)
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:4237 sip_new: *** Our capabilities are 0x1c000e (gsm|ulaw|alaw|h261|h263|h263p)
[May 25 20:34:15] DEBUG[21863]: frame.c:1157 ast_codec_choose: Could not find preferred codec - Going for the best codec
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:4238 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:4268 sip_new: This channel will not be able to handle video.
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:8664 build_route: build_route: Contact hop: <sip:100@192.168.1.2:8304>
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:14429 handle_request_invite: SIP/100-08203fa0: New call is still down.... Trying...
[May 25 20:34:15] DEBUG[21863]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/100-08203fa0
[May 25 20:34:15] DEBUG[21863]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 100-08203fa0
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:16273 sip_devicestate: Checking device state for peer 100-08203fa0
[May 25 20:34:15] DEBUG[21863]: pbx.c:1733 pbx_extension_helper: Launching 'Goto'
    -- Executing [2221@from-internal:1] Goto("SIP/100-08203fa0", "testmacros|123|1") in new stack
    -- Goto (testmacros,123,1)
[May 25 20:34:15] DEBUG[21863]: pbx.c:1733 pbx_extension_helper: Launching 'Gosub'
    -- Executing [123@testmacros:1] Gosub("SIP/100-08203fa0", "test-macros|s|1(10|"test")") in new stack
[May 25 20:34:15] DEBUG[21863]: app_stack.c:214 gosub_exec: Channel SIP/100-08203fa0 has no datastore, so we're allocating one.
[May 25 20:34:15] DEBUG[21863]: app_stack.c:263 gosub_exec: Setting 'ARG1' to '10'
[May 25 20:34:15] DEBUG[21863]: app_stack.c:263 gosub_exec: Setting 'ARG2' to 'test'
[May 25 20:34:15] DEBUG[21863]: pbx.c:1733 pbx_extension_helper: Launching 'Set'
    -- Executing [s@test-macros:1] Set("SIP/100-08203fa0", "var1=10") in new stack
[May 25 20:34:15] DEBUG[21863]: pbx.c:1733 pbx_extension_helper: Launching 'Set'
    -- Executing [s@test-macros:2] Set("SIP/100-08203fa0", "var2=test") in new stack
[May 25 20:34:15] DEBUG[21863]: pbx.c:1733 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@test-macros:3] NoOp("SIP/100-08203fa0", "EXTEN=s MACRO_EXTEN=") in new stack
[May 25 20:34:15] DEBUG[21863]: pbx.c:1733 pbx_extension_helper: Launching 'Return'
    -- Executing [s@test-macros:4] Return("SIP/100-08203fa0", "") in new stack
[May 25 20:34:15] DEBUG[21863]: pbx.c:1733 pbx_extension_helper: Launching 'Hangup'
    -- Executing [123@testmacros:2] Hangup("SIP/100-08203fa0", "") in new stack
[May 25 20:34:15] DEBUG[21863]: pbx.c:2329 __ast_pbx_run: Spawn extension (testmacros,123,2) exited non-zero on 'SIP/100-08203fa0'
  == Spawn extension (testmacros, 123, 2) exited non-zero on 'SIP/100-08203fa0'
[May 25 20:34:15] DEBUG[21863]: cdr_addon_mysql.c:210 mysql_log: cdr_mysql: inserting a CDR record.
[May 25 20:34:15] DEBUG[21863]: cdr_addon_mysql.c:226 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2007-05-25 20:34:15','\"device\" <100>','100','123','testmacros', 'SIP/100-08203fa0','','Hangup','',0,0,'NO ANSWER',3,'','1180110855.1')
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is '"device" <100>'
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is '100'
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is '123'
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is 'testmacros'
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is 'SIP/100-08203fa0'
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is ''
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is 'Hangup'
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is ''
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is '2007-05-25 20:34:15'
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is ''
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is '2007-05-25 20:34:15'
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is '0'
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is '0'
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER'
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is ''
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is '1180110855.1'
[May 25 20:34:15] DEBUG[21863]: pbx.c:1583 pbx_substitute_variables_helper_full: Function result is ''
[May 25 20:34:15] DEBUG[21863]: channel.c:1663 ast_hangup: Hanging up channel 'SIP/100-08203fa0'
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:3711 sip_hangup: Hangup call SIP/100-08203fa0, SIP callid bc3ab832ec015b66@YnJhaW4uaG9tZXNvZnQubG9jYWw.)
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:3735 sip_hangup: Hanging up channel in state Ring (not UP)
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:3665 hangup_cause2sip: AST hangup cause 16 (no match found in SIP)
[May 25 20:34:15] DEBUG[21863]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/100-08203fa0
[May 25 20:34:15] DEBUG[21863]: devicestate.c:428 do_state_change: Changing state for SIP/100-08203fa0 - state 4 (Invalid)
[May 25 20:34:15] DEBUG[21863]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 100-08203fa0
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:16273 sip_devicestate: Checking device state for peer 100-08203fa0
[May 25 20:34:15] DEBUG[21863]: devicestate.c:428 do_state_change: Changing state for SIP/100-08203fa0 - state 4 (Invalid)
[May 25 20:34:15] DEBUG[21863]: app_queue.c:573 handle_statechange: Device 'SIP/100-08203fa0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[May 25 20:34:15] DEBUG[21863]: app_queue.c:573 handle_statechange: Device 'SIP/100-08203fa0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:4847 find_call: = Found Their Call ID: bc3ab832ec015b66@YnJhaW4uaG9tZXNvZnQubG9jYWw. Their Tag c7134d5f Our tag: as7b919f18
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:15670 handle_request: **** Received ACK (6) - Command in SIP ACK
[May 25 20:34:15] DEBUG[21863]: chan_sip.c:2289 __sip_ack: Stopping retransmission on 'bc3ab832ec015b66@YnJhaW4uaG9tZXNvZnQubG9jYWw.' of Response 2: Match Found