*CLI> core set verbose 9
Verbosity is at least 9
**CLI> core set debug 9
Core debug was 0 and is now 9
*CLI> [May 25 20:30:43] DEBUG[21149]: chan_sip.c:4365 find_call: = No match Their Call ID: a301b112935c6e59@YnJhaW4uaG9tZXNvZnQubG9jYWw. Their Tag 6421d033 Our tag: as52b20cef
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to On
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:2581 do_setnat: Setting NAT on VRTP to On
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for a950782e39774a24@YnJhaW4uaG9tZXNvZnQubG9jYWw. - INVITE (With RTP)
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:14709 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to On
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:2581 do_setnat: Setting NAT on VRTP to On
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:4365 find_call: = Found Their Call ID: a950782e39774a24@YnJhaW4uaG9tZXNvZnQubG9jYWw. Their Tag 89551344 Our tag: as32689ab2
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:14709 handle_request: **** Received ACK (6) - Command in SIP ACK
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:2090 __sip_ack: Stopping retransmission on 'a950782e39774a24@YnJhaW4uaG9tZXNvZnQubG9jYWw.' of Response 1: Match Not Found
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:4365 find_call: = Found Their Call ID: a950782e39774a24@YnJhaW4uaG9tZXNvZnQubG9jYWw. Their Tag 89551344 Our tag: as32689ab2
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:14709 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to On
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:2581 do_setnat: Setting NAT on VRTP to On
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel <none>
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x8 (alaw)
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:13418 handle_request_invite: Checking SIP call limits for device 100
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:3004 update_call_counter: Updating call counter for incoming call
[May 25 20:30:43] DEBUG[21149]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:3806 sip_new: *** Our native formats are 0x8 (alaw)
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0x8 (alaw)
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:3808 sip_new: *** Our capabilities are 0x1c000e (gsm|ulaw|alaw|h261|h263|h263p)
[May 25 20:30:43] DEBUG[21149]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:3832 sip_new: This channel will not be able to handle video.
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:7994 build_route: build_route: Contact hop: <sip:100@192.168.1.2:8304>
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:13492 handle_request_invite: SIP/100-081ea4e8: New call is still down.... Trying...
[May 25 20:30:43] DEBUG[21149]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/100-081ea4e8
[May 25 20:30:43] DEBUG[21216]: pbx.c:1809 pbx_extension_helper: Launching 'Goto'
    -- Executing [2221@from-internal:1] Goto("SIP/100-081ea4e8", "testmacros|123|1") in new stack
    -- Goto (testmacros,123,1)
[May 25 20:30:43] DEBUG[21216]: pbx.c:1809 pbx_extension_helper: Launching 'Macro'
    -- Executing [123@testmacros:1] Macro("SIP/100-081ea4e8", "test-macros|10|"test"") in new stack
[May 25 20:30:43] DEBUG[21216]: pbx.c:1809 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-test-macros:1] Set("SIP/100-081ea4e8", "var1=10") in new stack
[May 25 20:30:43] DEBUG[21216]: app_macro.c:320 _macro_exec: Executed application: Set
[May 25 20:30:43] DEBUG[21216]: pbx.c:1809 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-test-macros:2] Set("SIP/100-081ea4e8", "var2="test"") in new stack
[May 25 20:30:43] DEBUG[21216]: app_macro.c:320 _macro_exec: Executed application: Set
[May 25 20:30:43] DEBUG[21216]: pbx.c:1809 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@macro-test-macros:3] NoOp("SIP/100-081ea4e8", "EXTEN=s MACRO_EXTEN=123") in new stack
[May 25 20:30:43] DEBUG[21216]: app_macro.c:320 _macro_exec: Executed application: noop
[May 25 20:30:43] DEBUG[21216]: pbx.c:1809 pbx_extension_helper: Launching 'Hangup'
    -- Executing [123@testmacros:2] Hangup("SIP/100-081ea4e8", "") in new stack
[May 25 20:30:43] DEBUG[21216]: pbx.c:2407 __ast_pbx_run: Spawn extension (testmacros,123,2) exited non-zero on 'SIP/100-081ea4e8'
  == Spawn extension (testmacros, 123, 2) exited non-zero on 'SIP/100-081ea4e8'
[May 25 20:30:43] DEBUG[21147]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 100
[May 25 20:30:43] DEBUG[21147]: chan_sip.c:15321 sip_devicestate: Checking device state for peer 100
[May 25 20:30:43] DEBUG[21147]: devicestate.c:287 do_state_change: Changing state for SIP/100 - state 1 (Not in use)
[May 25 20:30:43] DEBUG[21147]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 100
[May 25 20:30:43] DEBUG[21147]: chan_sip.c:15321 sip_devicestate: Checking device state for peer 100
[May 25 20:30:43] DEBUG[21147]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 100
[May 25 20:30:43] DEBUG[21147]: chan_sip.c:15321 sip_devicestate: Checking device state for peer 100
[May 25 20:30:43] DEBUG[21216]: cdr_addon_mysql.c:210 mysql_log: cdr_mysql: inserting a CDR record.
[May 25 20:30:43] DEBUG[21216]: 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:30:43','\"device\" <100>','100','123','testmacros', 'SIP/100-081ea4e8','','Hangup','',0,0,'NO ANSWER',3,'','1180110643.3')
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '"device" <100>'
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '100'
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '123'
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'testmacros'
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'SIP/100-081ea4e8'
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is ''
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'Hangup'
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is ''
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '2007-05-25 20:30:43'
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is ''
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '2007-05-25 20:30:43'
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0'
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0'
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER'
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is ''
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '1180110643.3'
[May 25 20:30:43] DEBUG[21216]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is ''
[May 25 20:30:43] DEBUG[21216]: channel.c:1726 ast_hangup: Hanging up channel 'SIP/100-081ea4e8'
[May 25 20:30:43] DEBUG[21216]: chan_sip.c:3313 sip_hangup: Hangup call SIP/100-081ea4e8, SIP callid a950782e39774a24@YnJhaW4uaG9tZXNvZnQubG9jYWw.)
[May 25 20:30:43] DEBUG[21216]: chan_sip.c:3336 sip_hangup: Hanging up channel in state Ring (not UP)
[May 25 20:30:43] DEBUG[21216]: chan_sip.c:3267 hangup_cause2sip: AST hangup cause 16 (no match found in SIP)
[May 25 20:30:43] DEBUG[21216]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/100-081ea4e8
[May 25 20:30:43] DEBUG[21147]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 100
[May 25 20:30:43] DEBUG[21147]: chan_sip.c:15321 sip_devicestate: Checking device state for peer 100
[May 25 20:30:43] DEBUG[21147]: devicestate.c:287 do_state_change: Changing state for SIP/100 - state 1 (Not in use)
[May 25 20:30:43] DEBUG[21147]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 100
[May 25 20:30:43] DEBUG[21147]: chan_sip.c:15321 sip_devicestate: Checking device state for peer 100
[May 25 20:30:43] DEBUG[21147]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 100
[May 25 20:30:43] DEBUG[21147]: chan_sip.c:15321 sip_devicestate: Checking device state for peer 100
[May 25 20:30:43] DEBUG[21217]: app_queue.c:546 changethread: Device 'SIP/100' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[May 25 20:30:43] DEBUG[21218]: app_queue.c:546 changethread: Device 'SIP/100' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:4365 find_call: = Found Their Call ID: a950782e39774a24@YnJhaW4uaG9tZXNvZnQubG9jYWw. Their Tag 89551344 Our tag: as6a6da810
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:14709 handle_request: **** Received ACK (6) - Command in SIP ACK
[May 25 20:30:43] DEBUG[21149]: chan_sip.c:2090 __sip_ack: Stopping retransmission on 'a950782e39774a24@YnJhaW4uaG9tZXNvZnQubG9jYWw.' of Response 2: Match Not Found