localhost*CLI> 

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: MWM5OTQyNzQ3Njk2MzYwMGJmMDcyNmU2M2JkMDM5OTI. (Checking From) --From tag 5b7c8211 --To-tag   
[2014-09-28 10:57:40] DEBUG[2033]: acl.c:979 ast_ouraddrfor: For destination '192.168.1.41', our source address is '192.168.1.33'.
[2014-09-28 10:57:40] DEBUG[2033]: chan_sip.c:3881 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.1.33:5060
[2014-09-28 10:57:40] DEBUG[2033]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.41:5060' into...
[2014-09-28 10:57:40] DEBUG[2033]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.41' and port '5060'.
[2014-09-28 10:57:40] DEBUG[2033]: chan_sip.c:8638 sip_alloc: Allocating new SIP dialog for MWM5OTQyNzQ3Njk2MzYwMGJmMDcyNmU2M2JkMDM5OTI. - INVITE (No RTP)
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:28202 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: sip/reqresp_parser.c:1607 parse_sip_options: Begin: parsing SIP "Supported: replaces, norefersub, extended-refer, X-cisco-serviceuri"
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: sip/reqresp_parser.c:1623 parse_sip_options: Found SIP option: -replaces-
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: sip/reqresp_parser.c:1631 parse_sip_options: Matched SIP option: replaces
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: sip/reqresp_parser.c:1623 parse_sip_options: Found SIP option: -norefersub-
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: sip/reqresp_parser.c:1631 parse_sip_options: Matched SIP option: norefersub
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: sip/reqresp_parser.c:1623 parse_sip_options: Found SIP option: -extended-refer-
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: sip/reqresp_parser.c:1659 parse_sip_options: Found no match for SIP option: extended-refer (Please file bug report!)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: sip/reqresp_parser.c:1623 parse_sip_options: Found SIP option: -X-cisco-serviceuri-
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: sip/reqresp_parser.c:1657 parse_sip_options: Found private SIP option, not supported: X-cisco-serviceuri
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.41:5060' into...
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.41' and port '5060'.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.33' into...
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:3724 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.41:5060

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: MWM5OTQyNzQ3Njk2MzYwMGJmMDcyNmU2M2JkMDM5OTI. (Checking From) --From tag 5b7c8211 --To-tag as11077242  

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:28202 handle_incoming: **** Received ACK (6) - Command in SIP ACK

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:4416 __sip_ack: Stopping retransmission on 'MWM5OTQyNzQ3Njk2MzYwMGJmMDcyNmU2M2JkMDM5OTI.' of Response 1: Match Found

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: MWM5OTQyNzQ3Njk2MzYwMGJmMDcyNmU2M2JkMDM5OTI. (Checking From) --From tag 5b7c8211 --To-tag   
[2014-09-28 10:57:40] DEBUG[2033]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.33' into...
[2014-09-28 10:57:40] DEBUG[2033]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.
[2014-09-28 10:57:40] DEBUG[2033]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.33' into...
[2014-09-28 10:57:40] DEBUG[2033]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:28202 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.41:5060' into...
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.41' and port '5060'.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.33' into...
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0xb740f064'
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: res_rtp_asterisk.c:2140 ast_rtp_new: Allocated port 16702 for RTP instance '0xb740f064'
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.33' into...
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0xb740f064' is setup and ready to go
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: res_rtp_asterisk.c:4280 ast_rtp_prop_set: Setup RTCP on RTP instance '0xb740f064'
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:5586 do_setnat: Setting NAT on RTP to On
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:9926 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:9926 process_sdp: Processing session-level SDP o=Zoiper_user 0 0 IN IP4 192.168.1.41... OK.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:9926 process_sdp: Processing session-level SDP s=Zoiper_session... UNSUPPORTED OR FAILED.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.41' into...
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.41' and port ''.

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:9926 process_sdp: Processing session-level SDP c=IN IP4 192.168.1.41... OK.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:9926 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 3 based on m type on 0xb6428e40
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0xb6428e40
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0xb6428e40
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0xb6428e40
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: res_rtp_asterisk.c:4336 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb740f064'
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0xb6428e40 to 0xb740f210
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 3 from 0xb6428e40 to 0xb740f210
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0xb6428e40 to 0xb740f210
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0xb6428e40 to 0xb740f210
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: res_rtp_asterisk.c:4246 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0xb740f064'
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:10650 process_sdp: We're settling with these formats: (gsm|ulaw|alaw)
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:25574 handle_request_invite: Checking SIP call limits for device 1111111111
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:6531 update_call_counter: Updating call counter for incoming call
[2014-09-28 10:57:40] DEBUG[1989]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 1111111111
[2014-09-28 10:57:40] DEBUG[1989]: chan_sip.c:29647 sip_devicestate: Checking device state for peer 1111111111
[2014-09-28 10:57:40] DEBUG[1989]: devicestate.c:467 do_state_change: Changing state for SIP/1111111111 - state 2 (In use)
[2014-09-28 10:57:40] DEBUG[1989]: devicestate.c:442 devstate_event: device 'SIP/1111111111' state '2'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2071]: app_queue.c:1872 handle_statechange: Device 'SIP/1111111111' changed to state '2' (In use) but we don't care because they're not a member of any queue.

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[1991]: devicestate.c:340 _ast_device_state: Checking if I can find provider for "Custom" - number: DND1111111111

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.33' into...

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[1991]: devicestate.c:417 getproviderstate: Checking provider SLA with Custom

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[1991]: devicestate.c:417 getproviderstate: Checking provider Meetme with Custom

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.33' into...

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[1991]: devicestate.c:417 getproviderstate: Checking provider Custom with Custom

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[1991]: db.c:376 db_get_common: Unable to find key 'DND1111111111' in family 'CustomDevstate'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: ExtensionStatus

Privilege: call,all

Exten: 1111111111

Context: ext-local

Hint: SIP/1111111111&Custom:DND1111111111,CustomPresence:1111111111

Status: 1





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[1991]: app_queue.c:1974 extension_state_cb: Extension '1111111111@ext-local' changed to state '2' (In use) but we don't care because they're not a member of any queue.

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[1981]: res_odbc.c:1058 odbc_release_obj2: odbc_release_obj2(0x8c67a1c) called (obj->txf = (nil))

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newchannel

Privilege: call,all

Channel: SIP/1111111111-00000004

ChannelState: 0

ChannelStateDesc: Down

CallerIDNum: 1111111111

CallerIDName: 1111111111

AccountCode: 

Exten: 73333333333

Context: from-internal

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:7813 sip_new: *** Our native formats are (ulaw) 

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:7814 sip_new: *** Joint capabilities are (gsm|ulaw|alaw) 

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:7815 sip_new: *** Our capabilities are (gsm|ulaw|alaw|g729) 

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:7816 sip_new: *** AST_CODEC_CHOOSE formats are ulaw 

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:7844 sip_new: This channel will not be able to handle video.

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: SIPURI

Value: sip:1111111111@192.168.1.41:5060

Uniqueid: 1411873060.4




[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: SIPDOMAIN

Value: 192.168.1.33

Uniqueid: 1411873060.4




[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: SIPCALLID

Value: MWM5OTQyNzQ3Njk2MzYwMGJmMDcyNmU2M2JkMDM5OTI.

Uniqueid: 1411873060.4




[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: ChannelUpdate

Privilege: system,all

Channel: SIP/1111111111-00000004

Uniqueid: 1411873060.4

Channeltype: SIP

SIPcallid: MWM5OTQyNzQ3Njk2MzYwMGJmMDcyNmU2M2JkMDM5OTI.

SIPfullcontact: sip:1111111111@192.168.1.41:5060;rinstance=48c502938e12c8f3;transport=UDP




[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:16212 build_route: build_route: Contact hop: <sip:1111111111@192.168.1.41:5060;transport=UDP>
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:25770 handle_request_invite: SIP/1111111111-00000004: New call is still down.... Trying... 
[2014-09-28 10:57:40] DEBUG[2033][C-00000002]: chan_sip.c:3724 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.41:5060
[2014-09-28 10:57:40] DEBUG[1989]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 1111111111
[2014-09-28 10:57:40] DEBUG[1989]: chan_sip.c:29647 sip_devicestate: Checking device state for peer 1111111111
[2014-09-28 10:57:40] DEBUG[1989]: devicestate.c:467 do_state_change: Changing state for SIP/1111111111 - state 2 (In use)
[2014-09-28 10:57:40] DEBUG[1989]: devicestate.c:442 devstate_event: device 'SIP/1111111111' state '2'
[2014-09-28 10:57:40] DEBUG[2071]: app_queue.c:1872 handle_statechange: Device 'SIP/1111111111' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2014-09-28 10:57:40] DEBUG[1991]: devicestate.c:340 _ast_device_state: Checking if I can find provider for "Custom" - number: DND1111111111
[2014-09-28 10:57:40] DEBUG[1991]: devicestate.c:417 getproviderstate: Checking provider SLA with Custom
[2014-09-28 10:57:40] DEBUG[1991]: devicestate.c:417 getproviderstate: Checking provider Meetme with Custom
[2014-09-28 10:57:40] DEBUG[1991]: devicestate.c:417 getproviderstate: Checking provider Custom with Custom
[2014-09-28 10:57:40] DEBUG[1991]: db.c:376 db_get_common: Unable to find key 'DND1111111111' in family 'CustomDevstate'
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newstate

Privilege: call,all

Channel: SIP/1111111111-00000004

ChannelState: 4

ChannelStateDesc: Ring

CallerIDNum: 1111111111

CallerIDName: 1111111111

ConnectedLineNum: 

ConnectedLineName: 

Uniqueid: 1411873060.4




[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Macro'
    -- Executing [73333333333@from-internal:1] Macro("SIP/1111111111-00000004", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: from-internal

Extension: 73333333333

Priority: 1

Application: Macro

AppData: user-callerid,LIMIT,EXTERNAL,

Uniqueid: 1411873060.4




[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_EXTEN

Value: 73333333333

Uniqueid: 1411873060.4




[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_CONTEXT

Value: from-internal

Uniqueid: 1411873060.4




[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_PRIORITY

Value: 1

Uniqueid: 1411873060.4




[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: ARG1

Value: LIMIT

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: ARG2

Value: EXTERNAL

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: ARG3

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'UNIQUEID' is '1411873060.4'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:1] Set("SIP/1111111111-00000004", "TOUCH_MONITOR=1411873060.4") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 1

Application: Set

AppData: TOUCH_MONITOR=1411873060.4

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: TOUCH_MONITOR

Value: 1411873060.4

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'AMPUSER' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'AMPUSER' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(1?1111111111:) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:2] Set("SIP/1111111111-00000004", "AMPUSER=1111111111") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 2

Application: Set

AppData: AMPUSER=1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: AMPUSER

Value: 1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CHANNEL' (from 'CHANNEL}' len 7)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'CHANNEL' is 'SIP/1111111111-00000004'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CUT(CHANNEL,@,2) result is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'AMPUSERCIDNAME' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:3] GotoIf("SIP/1111111111-00000004", "0?report") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 3

Application: GotoIf

AppData: 0?report

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GotoIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:4] ExecIf("SIP/1111111111-00000004", "1?Set(REALCALLERIDNUM=1111111111)") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 4

Application: ExecIf

AppData: 1?Set(REALCALLERIDNUM=1111111111)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: REALCALLERIDNUM

Value: 1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'REALCALLERIDNUM:1:2' (from 'REALCALLERIDNUM:1:2}" = ""' len 19)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function CALLERID(number) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: 1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(DEVICE/1111111111/user) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:5] Set("SIP/1111111111-00000004", "AMPUSER=1111111111") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 5

Application: Set

AppData: AMPUSER=1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: AMPUSER

Value: 1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:6] GotoIf("SIP/1111111111-00000004", "0?limit") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 6

Application: GotoIf

AppData: 0?limit

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GotoIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: 1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/cidname) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:7] Set("SIP/1111111111-00000004", "AMPUSERCIDNAME=1111111111") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 7

Application: Set

AppData: AMPUSERCIDNAME=1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: AMPUSERCIDNAME

Value: 1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSERCIDNAME' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:8] GotoIf("SIP/1111111111-00000004", "0?report") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 8

Application: GotoIf

AppData: 0?report

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GotoIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is 'EXTERNAL'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: 1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB_EXISTS(AMPUSER/1111111111/cidnum) result is '1'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DB_RESULT' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(0?1111111111:1111111111) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:9] Set("SIP/1111111111-00000004", "AMPUSERCID=1111111111") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 9

Application: Set

AppData: AMPUSERCID=1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: AMPUSERCID

Value: 1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: db.c:376 db_get_common: Unable to find key '1111111111/dialopts' in family 'AMPUSER'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB_EXISTS(AMPUSER/1111111111/dialopts) result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DB_RESULT' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_OPTIONS' is 'Ttr'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(0?1111111111:Ttr) result is 'Ttr'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:10] Set("SIP/1111111111-00000004", "__DIAL_OPTIONS=Ttr") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 10

Application: Set

AppData: __DIAL_OPTIONS=Ttr

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: __DIAL_OPTIONS

Value: Ttr

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSERCIDNAME' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSERCID' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:11] Set("SIP/1111111111-00000004", "CALLERID(all)="1111111111" <1111111111>") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 11

Application: Set

AppData: CALLERID(all)="1111111111" <1111111111>

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: NewCallerid

Privilege: call,all

Channel: SIP/1111111111-00000004

CallerIDNum: 1111111111

CallerIDName: 1111111111

Uniqueid: 1411873060.4

CID-CallingPres: 0 (Presentation Allowed, Not Screened)





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN(1111111111) result is '10'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: 3

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/concurrency_limit) result is '3'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function GROUP_COUNT(1111111111@concurrency_limit) result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: 3

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/concurrency_limit) result is '3'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:12] GotoIf("SIP/1111111111-00000004", "0?limit") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 12

Application: GotoIf

AppData: 0?limit

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GotoIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN(1111111111) result is '10'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:13] ExecIf("SIP/1111111111-00000004", "1?Set(GROUP(concurrency_limit)=1111111111)") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 13

Application: ExecIf

AppData: 1?Set(GROUP(concurrency_limit)=1111111111)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}"="LIMIT" & ${LEN(${AMPUSER})}' len 4)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'LEN(${AMPUSER})' (from 'LEN(${AMPUSER})}' len 15)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER})' len 7)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN(1111111111) result is '10'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER})' len 7)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: generic

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/ccss/cc_agent_policy) result is 'generic'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN(generic) result is '7'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: generic

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/ccss/cc_agent_policy) result is 'generic'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '7'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MACRO_CONTEXT' is 'from-internal'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(dnid) result is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GosubIf'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:14] GosubIf("SIP/1111111111-00000004", "7?sub-ccss,s,1(from-internal,73333333333)") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 14

Application: GosubIf

AppData: 7?sub-ccss,s,1(from-internal,73333333333)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_stack.c:579 gosub_exec: Channel SIP/1111111111-00000004 has no datastore, so we're allocating one.

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: LOCAL(ARG1)

Value: from-internal

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_stack.c:621 gosub_exec: Setting 'ARG1' to 'from-internal'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: LOCAL(ARG2)

Value: 73333333333

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_stack.c:621 gosub_exec: Setting 'ARG2' to '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: LOCAL(ARGC)

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GosubIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'LEN(${DB(AMPUSER/${AMPUSER}/ccss/cc_agent_policy)})' (from 'LEN(${DB(AMPUSER/${AMPUSER}/ccss/cc_agent_policy)})} & "${DB(AMPUSER/${AMPUSER}/ccss/cc_agent_policy)}" != "never"' len 51)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/ccss/cc_agent_policy)' (from 'DB(AMPUSER/${AMPUSER}/ccss/cc_agent_policy)})' len 43)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/ccss/cc_agent_policy)' len 7)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: generic

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function DB(AMPUSER/1111111111/ccss/cc_agent_policy) result is 'generic'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN(generic) result is '7'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/ccss/cc_agent_policy)' (from 'DB(AMPUSER/${AMPUSER}/ccss/cc_agent_policy)}" != "never"' len 43)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/ccss/cc_agent_policy)' len 7)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: generic

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function DB(AMPUSER/1111111111/ccss/cc_agent_policy) result is 'generic'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '7'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'MACRO_CONTEXT' (from 'MACRO_CONTEXT},${CALLERID(dnid)})' len 13)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MACRO_CONTEXT' is 'from-internal'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CALLERID(dnid)' (from 'CALLERID(dnid)})' len 14)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function CALLERID(dnid) result is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:449 _macro_exec: Incrementing gosub_level

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'CCSS_SETUP' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@sub-ccss:1] ExecIf("SIP/1111111111-00000004", "0?Return()") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-ccss

Extension: s

Priority: 1

Application: ExecIf

AppData: 0?Return()

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'LEN(${CCSS_SETUP})' (from 'LEN(${CCSS_SETUP})}' len 18)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CCSS_SETUP' (from 'CCSS_SETUP})' len 10)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'CCSS_SETUP' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@sub-ccss:2] Set("SIP/1111111111-00000004", "CCSS_SETUP=TRUE") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-ccss

Extension: s

Priority: 2

Application: Set

AppData: CCSS_SETUP=TRUE

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: CCSS_SETUP

Value: TRUE

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: db.c:376 db_get_common: Unable to find key '73333333333/ccss/cc_monitor_policy' in family 'AMPUSER'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: func_db.c:151 function_db_read: DB: AMPUSER/73333333333/ccss/cc_monitor_policy not found in database.

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/73333333333/ccss/cc_monitor_policy) result is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'from-internal'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'from-internal'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GosubIf'

localhost*CLI> 
    -- Executing [s@sub-ccss:3] GosubIf("SIP/1111111111-00000004", "0?monitor_config,1(from-internal,73333333333):monitor_default,1(from-internal,73333333333)") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-ccss

Extension: s

Priority: 3

Application: GosubIf

AppData: 0?monitor_config,1(from-internal,73333333333):monitor_default,1(from-internal,73333333333)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: LOCAL(ARG1)

Value: from-internal

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_stack.c:621 gosub_exec: Setting 'ARG1' to 'from-internal'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: LOCAL(ARG2)

Value: 73333333333

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_stack.c:621 gosub_exec: Setting 'ARG2' to '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: LOCAL(ARGC)

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GosubIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'LEN(${DB(AMPUSER/${ARG2}/ccss/cc_monitor_policy)})' (from 'LEN(${DB(AMPUSER/${ARG2}/ccss/cc_monitor_policy)})}' len 50)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${ARG2}/ccss/cc_monitor_policy)' (from 'DB(AMPUSER/${ARG2}/ccss/cc_monitor_policy)})' len 42)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ARG2' (from 'ARG2}/ccss/cc_monitor_policy)' len 4)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: db.c:376 db_get_common: Unable to find key '73333333333/ccss/cc_monitor_policy' in family 'AMPUSER'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: func_db.c:151 function_db_read: DB: AMPUSER/73333333333/ccss/cc_monitor_policy not found in database.

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function DB(AMPUSER/73333333333/ccss/cc_monitor_policy) result is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1},${ARG2}):monitor_default,1(${ARG1},${ARG2})' len 4)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'from-internal'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ARG2' (from 'ARG2}):monitor_default,1(${ARG1},${ARG2})' len 4)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1},${ARG2})' len 4)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'from-internal'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ARG2' (from 'ARG2})' len 4)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:454 _macro_exec: Incrementing gosub_level

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: db.c:376 db_get_common: Unable to find key '73333333333/cidname' in family 'AMPUSER'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: func_db.c:151 function_db_read: DB: AMPUSER/73333333333/cidname not found in database.

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/73333333333/cidname) result is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [monitor_default@sub-ccss:1] GotoIf("SIP/1111111111-00000004", "0?is_exten") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-ccss

Extension: monitor_default

Priority: 1

Application: GotoIf

AppData: 0?is_exten

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GotoIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'StackPop'

localhost*CLI> 
    -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/1111111111-00000004", "") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-ccss

Extension: monitor_default

Priority: 2

Application: StackPop

AppData: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: StackPop

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:462 _macro_exec: Decrementing gosub_level

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Return'

localhost*CLI> 
    -- Executing [monitor_default@sub-ccss:3] Return("SIP/1111111111-00000004", "FALSE") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-ccss

Extension: monitor_default

Priority: 3

Application: Return

AppData: FALSE

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: GOSUB_RETVAL

Value: FALSE

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Return

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:459 _macro_exec: Decrementing gosub_level

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/language) result is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/language) result is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:15] ExecIf("SIP/1111111111-00000004", "0?Set(CHANNEL(language)=)") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 15

Application: ExecIf

AppData: 0?Set(CHANNEL(language)=)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/language)' (from 'DB(AMPUSER/${AMPUSER}/language)}" != ""' len 31)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/language)' len 7)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function DB(AMPUSER/1111111111/language) result is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/language)' (from 'DB(AMPUSER/${AMPUSER}/language)})' len 31)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/language)' len 7)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function DB(AMPUSER/1111111111/language) result is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:16] GotoIf("SIP/1111111111-00000004", "1?continue") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 16

Application: GotoIf

AppData: 1?continue

Uniqueid: 1411873060.4





localhost*CLI> 
    -- Goto (macro-user-callerid,s,30)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GotoIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:30] Set("SIP/1111111111-00000004", "CALLERID(number)=1111111111") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 30

Application: Set

AppData: CALLERID(number)=1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(name) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:31] Set("SIP/1111111111-00000004", "CALLERID(name)=1111111111") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 31

Application: Set

AppData: CALLERID(name)=1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:32] Set("SIP/1111111111-00000004", "CDR(cnum)=1111111111") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 32

Application: Set

AppData: CDR(cnum)=1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(name) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:33] Set("SIP/1111111111-00000004", "CDR(cnam)=1111111111") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 33

Application: Set

AppData: CDR(cnam)=1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CHANNEL(language)' (from 'CHANNEL(language)}' len 17)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function CHANNEL(language) result is 'ru_gsm'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function MASTER_CHANNEL(CHANNEL(language)) result is 'ru_gsm'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-user-callerid:34] Set("SIP/1111111111-00000004", "CHANNEL(language)=ru_gsm") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-user-callerid

Extension: s

Priority: 34

Application: Set

AppData: CHANNEL(language)=ru_gsm

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 0

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'CALLEE_ACCOUNCODE' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'CALLEE_ACCOUNCODE' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [73333333333@from-internal:2] ExecIf("SIP/1111111111-00000004", "0 ?Set(CDR(accountcode)=)") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: from-internal

Extension: 73333333333

Priority: 2

Application: ExecIf

AppData: 0 ?Set(CDR(accountcode)=)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'MOHCLASS' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'MOHCLASS' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(1?default:) result is 'default'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [73333333333@from-internal:3] Set("SIP/1111111111-00000004", "MOHCLASS=default") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: from-internal

Extension: 73333333333

Priority: 3

Application: Set

AppData: MOHCLASS=default

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MOHCLASS

Value: default

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [73333333333@from-internal:4] Set("SIP/1111111111-00000004", "_NODEST=") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: from-internal

Extension: 73333333333

Priority: 4

Application: Set

AppData: _NODEST=

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: _NODEST

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'EXTEN' is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Gosub'

localhost*CLI> 
    -- Executing [73333333333@from-internal:5] Gosub("SIP/1111111111-00000004", "sub-record-check,s,1(out,73333333333,)") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: from-internal

Extension: 73333333333

Priority: 5

Application: Gosub

AppData: sub-record-check,s,1(out,73333333333,)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: LOCAL(ARG1)

Value: out

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_stack.c:621 gosub_exec: Setting 'ARG1' to 'out'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: LOCAL(ARG2)

Value: 73333333333

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_stack.c:621 gosub_exec: Setting 'ARG2' to '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: LOCAL(ARG3)

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_stack.c:621 gosub_exec: Setting 'ARG3' to ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: LOCAL(ARGC)

Value: 3

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'REC_POLICY_MODE' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@sub-record-check:1] Set("SIP/1111111111-00000004", "REC_POLICY_MODE_SAVE=") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: s

Priority: 1

Application: Set

AppData: REC_POLICY_MODE_SAVE=

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: REC_POLICY_MODE_SAVE

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'BLINDTRANSFER' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [s@sub-record-check:2] GotoIf("SIP/1111111111-00000004", "1?check") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: s

Priority: 2

Application: GotoIf

AppData: 1?check

Uniqueid: 1411873060.4





localhost*CLI> 
    -- Goto (sub-record-check,s,7)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MIXMON_FORMAT' is 'wav'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MIXMON_FORMAT' is 'wav'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(0?WAV:wav) result is 'wav'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@sub-record-check:7] Set("SIP/1111111111-00000004", "__MON_FMT=wav") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: s

Priority: 7

Application: Set

AppData: __MON_FMT=wav

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: __MON_FMT

Value: wav

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'REC_STATUS' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [s@sub-record-check:8] GotoIf("SIP/1111111111-00000004", "1?next") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: s

Priority: 8

Application: GotoIf

AppData: 1?next

Uniqueid: 1411873060.4





localhost*CLI> 
    -- Goto (sub-record-check,s,11)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'out'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN(out) result is '3'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@sub-record-check:11] ExecIf("SIP/1111111111-00000004", "0?Return()") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: s

Priority: 11

Application: ExecIf

AppData: 0?Return()

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'REC_POLICY_MODE' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG3' is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG3' is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@sub-record-check:12] ExecIf("SIP/1111111111-00000004", "0?Set(__REC_POLICY_MODE=)") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: s

Priority: 12

Application: ExecIf

AppData: 0?Set(__REC_POLICY_MODE=)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'REC_STATUS' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'out'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [s@sub-record-check:13] GotoIf("SIP/1111111111-00000004", "0?out,1") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: s

Priority: 13

Application: GotoIf

AppData: 0?out,1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@sub-record-check:14] Set("SIP/1111111111-00000004", "__REC_STATUS=INITIALIZED") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: s

Priority: 14

Application: Set

AppData: __REC_STATUS=INITIALIZED

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: __REC_STATUS

Value: INITIALIZED

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'EPOCH' is '1411873060'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@sub-record-check:15] Set("SIP/1111111111-00000004", "NOW=1411873060") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: s

Priority: 15

Application: Set

AppData: NOW=1411873060

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: NOW

Value: 1411873060

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'NOW' is '1411873060'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function STRFTIME(1411873060,,%d) result is '28'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@sub-record-check:16] Set("SIP/1111111111-00000004", "__DAY=28") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: s

Priority: 16

Application: Set

AppData: __DAY=28

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: __DAY

Value: 28

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'NOW' is '1411873060'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function STRFTIME(1411873060,,%m) result is '09'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@sub-record-check:17] Set("SIP/1111111111-00000004", "__MONTH=09") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: s

Priority: 17

Application: Set

AppData: __MONTH=09

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: __MONTH

Value: 09

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'NOW' is '1411873060'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function STRFTIME(1411873060,,%Y) result is '2014'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@sub-record-check:18] Set("SIP/1111111111-00000004", "__YEAR=2014") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: s

Priority: 18

Application: Set

AppData: __YEAR=2014

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: __YEAR

Value: 2014

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'YEAR' is '2014'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MONTH' is '09'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DAY' is '28'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'NOW' is '1411873060'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function STRFTIME(1411873060,,%H%M%S) result is '105740'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@sub-record-check:19] Set("SIP/1111111111-00000004", "__TIMESTR=20140928-105740") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: s

Priority: 19

Application: Set

AppData: __TIMESTR=20140928-105740

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: __TIMESTR

Value: 20140928-105740

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN(1111111111) result is '10'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '10'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN(1111111111) result is '10'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '10'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(10?1111111111:unknown) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(10?1111111111:1111111111) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@sub-record-check:20] Set("SIP/1111111111-00000004", "__FROMEXTEN=1111111111") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: s

Priority: 20

Application: Set

AppData: __FROMEXTEN=1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: __FROMEXTEN

Value: 1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'out'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FROMEXTEN' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'TIMESTR' is '20140928-105740'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'UNIQUEID' is '1411873060.4'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@sub-record-check:21] Set("SIP/1111111111-00000004", "__CALLFILENAME=out-73333333333-1111111111-20140928-105740-1411873060.4") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: s

Priority: 21

Application: Set

AppData: __CALLFILENAME=out-73333333333-1111111111-20140928-105740-1411873060.4

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: __CALLFILENAME

Value: out-73333333333-1111111111-20140928-105740-1411873060.4

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'out'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Goto'

localhost*CLI> 
    -- Executing [s@sub-record-check:22] Goto("SIP/1111111111-00000004", "out,1") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: s

Priority: 22

Application: Goto

AppData: out,1

Uniqueid: 1411873060.4





localhost*CLI> 
    -- Goto (sub-record-check,out,1)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'REC_POLICY_MODE' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FROMEXTEN' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: dontcare

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/recording/out/external) result is 'dontcare'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [out@sub-record-check:1] ExecIf("SIP/1111111111-00000004", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: out

Priority: 1

Application: ExecIf

AppData: 1?Set(__REC_POLICY_MODE=dontcare)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: __REC_POLICY_MODE

Value: dontcare

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REC_POLICY_MODE' is 'dontcare'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FROMEXTEN' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GosubIf'

localhost*CLI> 
    -- Executing [out@sub-record-check:2] GosubIf("SIP/1111111111-00000004", "0?record,1(exten,73333333333,1111111111)") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: out

Priority: 2

Application: GosubIf

AppData: 0?record,1(exten,73333333333,1111111111)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Return'

localhost*CLI> 
    -- Executing [out@sub-record-check:3] Return("SIP/1111111111-00000004", "") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: sub-record-check

Extension: out

Priority: 3

Application: Return

AppData: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: GOSUB_RETVAL

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'EXTEN' is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Macro'

localhost*CLI> 
    -- Executing [73333333333@from-internal:6] Macro("SIP/1111111111-00000004", "dialout-trunk,4,73333333333,,off") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: from-internal

Extension: 73333333333

Priority: 6

Application: Macro

AppData: dialout-trunk,4,73333333333,,off

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_EXTEN

Value: 73333333333

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_CONTEXT

Value: from-internal

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_PRIORITY

Value: 6

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: ARG1

Value: 4

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: ARG2

Value: 73333333333

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: ARG3

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: ARG4

Value: off

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:1] Set("SIP/1111111111-00000004", "DIAL_TRUNK=4") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 1

Application: Set

AppData: DIAL_TRUNK=4

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DIAL_TRUNK

Value: 4

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG3' is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: db.c:376 db_get_common: Unable to find key '1111111111/pinless' in family 'AMPUSER'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: func_db.c:151 function_db_read: DB: AMPUSER/1111111111/pinless not found in database.

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/pinless) result is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GosubIf'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/1111111111-00000004", "0?sub-pincheck,s,1()") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 2

Application: GosubIf

AppData: 0?sub-pincheck,s,1()

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GosubIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ARG3' (from 'ARG3}" != ""' len 4)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG3' is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/pinless)' (from 'DB(AMPUSER/${AMPUSER}/pinless)}" != "NOPASSWD"' len 30)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/pinless)' len 7)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: db.c:376 db_get_common: Unable to find key '1111111111/pinless' in family 'AMPUSER'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: func_db.c:151 function_db_read: DB: AMPUSER/1111111111/pinless not found in database.

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function DB(AMPUSER/1111111111/pinless) result is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUTDISABLE_4' is 'off'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/1111111111-00000004", "0?disabletrunk,1") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 3

Application: GotoIf

AppData: 0?disabletrunk,1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GotoIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:4] Set("SIP/1111111111-00000004", "DIAL_NUMBER=73333333333") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 4

Application: Set

AppData: DIAL_NUMBER=73333333333

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DIAL_NUMBER

Value: 73333333333

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_OPTIONS' is 'Ttr'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:5] Set("SIP/1111111111-00000004", "DIAL_TRUNK_OPTIONS=Ttr") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 5

Application: Set

AppData: DIAL_TRUNK_OPTIONS=Ttr

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DIAL_TRUNK_OPTIONS

Value: Ttr

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:6] Set("SIP/1111111111-00000004", "OUTBOUND_GROUP=OUT_4") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 6

Application: Set

AppData: OUTBOUND_GROUP=OUT_4

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: OUTBOUND_GROUP

Value: OUT_4

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUTMAXCHANS_4' is '10'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/1111111111-00000004", "0?nomax") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 7

Application: GotoIf

AppData: 0?nomax

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GotoIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function GROUP_COUNT(OUT_4) result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUTMAXCHANS_4' is '10'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:8] GotoIf("SIP/1111111111-00000004", "0?chanfull") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 8

Application: GotoIf

AppData: 0?chanfull

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GotoIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'INTRACOMPANYROUTE' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/1111111111-00000004", "0?skipoutcid") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 9

Application: GotoIf

AppData: 0?skipoutcid

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GotoIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: db.c:376 db_get_common: Unable to find key '4/dialopts' in family 'TRUNK'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB_EXISTS(TRUNK/4/dialopts) result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DB_RESULT' is 'dontcare'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'TRUNK_OPTIONS' is 'Tt'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(0?dontcare:Tt) result is 'Tt'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:10] Set("SIP/1111111111-00000004", "DIAL_TRUNK_OPTIONS=Tt") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 10

Application: Set

AppData: DIAL_TRUNK_OPTIONS=Tt

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DIAL_TRUNK_OPTIONS

Value: Tt

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Macro'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:11] Macro("SIP/1111111111-00000004", "outbound-callerid,4") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 11

Application: Macro

AppData: outbound-callerid,4

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_EXTEN

Value: s

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_CONTEXT

Value: macro-dialout-trunk

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_PRIORITY

Value: 11

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: ARG1

Value: 4

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'CALLINGPRES_SV' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'CALLINGPRES_SV' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/1111111111-00000004", "0?Set(CALLERPRES()=)") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-outbound-callerid

Extension: s

Priority: 1

Application: ExecIf

AppData: 0?Set(CALLERPRES()=)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CALLINGPRES_SV' (from 'CALLINGPRES_SV}" != ""' len 14)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'CALLINGPRES_SV' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CALLINGPRES_SV' (from 'CALLINGPRES_SV})' len 14)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'CALLINGPRES_SV' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/1111111111-00000004", "0?Set(REALCALLERIDNUM=1111111111)") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-outbound-callerid

Extension: s

Priority: 2

Application: ExecIf

AppData: 0?Set(REALCALLERIDNUM=1111111111)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'REALCALLERIDNUM:1:2' (from 'REALCALLERIDNUM:1:2}" = ""' len 19)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function CALLERID(number) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'KEEPCID' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUTKEEPCID_4' is 'off'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/1111111111-00000004", "1?normcid") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-outbound-callerid

Extension: s

Priority: 3

Application: GotoIf

AppData: 1?normcid

Uniqueid: 1411873060.4





localhost*CLI> 
    -- Goto (macro-outbound-callerid,s,6)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GotoIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/outboundcid) result is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-outbound-callerid:6] Set("SIP/1111111111-00000004", "USEROUTCID=") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-outbound-callerid

Extension: s

Priority: 6

Application: Set

AppData: USEROUTCID=

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: USEROUTCID

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: db.c:376 db_get_common: Unable to find key '1111111111/emergency_cid' in family 'DEVICE'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: func_db.c:151 function_db_read: DB: DEVICE/1111111111/emergency_cid not found in database.

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(DEVICE/1111111111/emergency_cid) result is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-outbound-callerid:7] Set("SIP/1111111111-00000004", "EMERGENCYCID=") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-outbound-callerid

Extension: s

Priority: 7

Application: Set

AppData: EMERGENCYCID=

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: EMERGENCYCID

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUTCID_4' is 'XXXXXXXXXX'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-outbound-callerid:8] Set("SIP/1111111111-00000004", "TRUNKOUTCID=XXXXXXXXXX") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-outbound-callerid

Extension: s

Priority: 8

Application: Set

AppData: TRUNKOUTCID=XXXXXXXXXX

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: TRUNKOUTCID

Value: XXXXXXXXXX

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'EMERGENCYROUTE' is NULL

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'EMERGENCYCID' is ''

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/1111111111-00000004", "1?trunkcid") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-outbound-callerid

Extension: s

Priority: 9

Application: GotoIf

AppData: 1?trunkcid

Uniqueid: 1411873060.4





localhost*CLI> 
    -- Goto (macro-outbound-callerid,s,14)

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GotoIf

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'TRUNKOUTCID' is 'XXXXXXXXXX'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN(XXXXXXXXXX) result is '10'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'TRUNKOUTCID' is 'XXXXXXXXXX'

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/1111111111-00000004", "1?Set(CALLERID(all)=XXXXXXXXXX)") in new stack

localhost*CLI> 
[2014-09-28 10:57:40] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-outbound-callerid

Extension: s

Priority: 14

Application: ExecIf

AppData: 1?Set(CALLERID(all)=XXXXXXXXXX)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: NewCallerid

Privilege: call,all

Channel: SIP/1111111111-00000004

CallerIDNum: XXXXXXXXXX

CallerIDName: 

Uniqueid: 1411873060.4

CID-CallingPres: 0 (Presentation Allowed, Not Screened)





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'LEN(${TRUNKOUTCID})' (from 'LEN(${TRUNKOUTCID})} != 0' len 19)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'TRUNKOUTCID' (from 'TRUNKOUTCID})' len 11)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'TRUNKOUTCID' is 'XXXXXXXXXX'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN(XXXXXXXXXX) result is '10'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'TRUNKOUTCID' (from 'TRUNKOUTCID})' len 11)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'TRUNKOUTCID' is 'XXXXXXXXXX'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'USEROUTCID' is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'USEROUTCID' is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/1111111111-00000004", "0?Set(CALLERID(all)=)") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-outbound-callerid

Extension: s

Priority: 15

Application: ExecIf

AppData: 0?Set(CALLERID(all)=)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'LEN(${USEROUTCID})' (from 'LEN(${USEROUTCID})} != 0' len 18)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'USEROUTCID' (from 'USEROUTCID})' len 10)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'USEROUTCID' is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'USEROUTCID' (from 'USEROUTCID})' len 10)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'USEROUTCID' is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is NULL

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_4' is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_4' is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is NULL

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_4' is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(1?:) result is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-outbound-callerid:16] ExecIf("SIP/1111111111-00000004", "0?Set(CALLERID(all)=)") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-outbound-callerid

Extension: s

Priority: 16

Application: ExecIf

AppData: 0?Set(CALLERID(all)=)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'LEN(${TRUNKCIDOVERRIDE})' (from 'LEN(${TRUNKCIDOVERRIDE})} != 0 | ${LEN(${FORCEDOUTCID_${ARG1}})} != 0' len 24)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'TRUNKCIDOVERRIDE' (from 'TRUNKCIDOVERRIDE})' len 16)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is NULL

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'LEN(${FORCEDOUTCID_${ARG1}})' (from 'LEN(${FORCEDOUTCID_${ARG1}})} != 0' len 28)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'FORCEDOUTCID_${ARG1}' (from 'FORCEDOUTCID_${ARG1}})' len 20)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}' len 4)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_4' is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 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)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'LEN(${FORCEDOUTCID_${ARG1}})' (from 'LEN(${FORCEDOUTCID_${ARG1}})}=0' len 28)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'FORCEDOUTCID_${ARG1}' (from 'FORCEDOUTCID_${ARG1}})' len 20)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}' len 4)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_4' is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'TRUNKCIDOVERRIDE' (from 'TRUNKCIDOVERRIDE}:${FORCEDOUTCID_${ARG1}})' len 16)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is NULL

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'FORCEDOUTCID_${ARG1}' (from 'FORCEDOUTCID_${ARG1}})' len 20)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}' len 4)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_4' is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function IF(1?:) result is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(name) result is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-outbound-callerid:17] ExecIf("SIP/1111111111-00000004", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-outbound-callerid

Extension: s

Priority: 17

Application: ExecIf

AppData: 0?Set(CALLERPRES()=prohib_passed_screen)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CALLERID(name)' (from 'CALLERID(name)}"="hidden"' len 14)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function CALLERID(name) result is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(num) result is 'XXXXXXXXXX'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-outbound-callerid:18] Set("SIP/1111111111-00000004", "CDR(outbound_cnum)=XXXXXXXXXX") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-outbound-callerid

Extension: s

Priority: 18

Application: Set

AppData: CDR(outbound_cnum)=XXXXXXXXXX

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(name) result is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-outbound-callerid:19] Set("SIP/1111111111-00000004", "CDR(outbound_cnam)=") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-outbound-callerid

Extension: s

Priority: 19

Application: Set

AppData: CDR(outbound_cnam)=

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: ARG1

Value: 4

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_EXTEN

Value: 73333333333

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_CONTEXT

Value: from-internal

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_PRIORITY

Value: 6

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Macro

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'PREFIX_TRUNK_4' is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GosubIf'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/1111111111-00000004", "0?sub-flp-4,s,1()") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 12

Application: GosubIf

AppData: 0?sub-flp-4,s,1()

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GosubIf

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'PREFIX_TRUNK_${DIAL_TRUNK}' (from 'PREFIX_TRUNK_${DIAL_TRUNK}}" != ""' len 26)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DIAL_TRUNK' (from 'DIAL_TRUNK}' len 10)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'PREFIX_TRUNK_4' is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DIAL_TRUNK' (from 'DIAL_TRUNK},s,1()' len 10)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUTPREFIX_4' is ''

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:13] Set("SIP/1111111111-00000004", "OUTNUM=73333333333") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 13

Application: Set

AppData: OUTNUM=73333333333

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: OUTNUM

Value: 73333333333

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'OUT_4' (from 'OUT_4}' len 5)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUT_4' is 'SIP/sip_out'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CUT(OUT_4,:,1) result is 'SIP/sip_out'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:14] Set("SIP/1111111111-00000004", "custom=SIP/sip_out") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 14

Application: Set

AppData: custom=SIP/sip_out

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: custom

Value: SIP/sip_out

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Set

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'FORCE_CONFIRM' is NULL

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/1111111111-00000004", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 15

Application: ExecIf

AppData: 0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'MOHCLASS' (from 'MOHCLASS}"!="default" & "${MOHCLASS}"!="" & "${FORCE_CONFIRM}"="" ' len 8)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'MOHCLASS' (from 'MOHCLASS}"!="" & "${FORCE_CONFIRM}"="" ' len 8)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'FORCE_CONFIRM' (from 'FORCE_CONFIRM}"="" ' len 13)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'FORCE_CONFIRM' is NULL

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'MOHCLASS' (from 'MOHCLASS})${DIAL_TRUNK_OPTIONS})' len 8)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DIAL_TRUNK_OPTIONS' (from 'DIAL_TRUNK_OPTIONS})' len 18)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'FORCE_CONFIRM' is NULL

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/1111111111-00000004", "0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 16

Application: ExecIf

AppData: 0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'FORCE_CONFIRM' (from 'FORCE_CONFIRM}"!="" ' len 13)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'FORCE_CONFIRM' is NULL

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DIAL_TRUNK_OPTIONS' (from 'DIAL_TRUNK_OPTIONS}M(confirm))' len 18)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Macro'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:17] Macro("SIP/1111111111-00000004", "dialout-trunk-predial-hook,") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 17

Application: Macro

AppData: dialout-trunk-predial-hook,

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_EXTEN

Value: s

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_CONTEXT

Value: macro-dialout-trunk

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_PRIORITY

Value: 17

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: ARG1

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'MacroExit'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/1111111111-00000004", "") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk-predial-hook

Extension: s

Priority: 1

Application: MacroExit

AppData: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: ARG1

Value: 4

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_EXTEN

Value: 73333333333

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_CONTEXT

Value: from-internal

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_PRIORITY

Value: 6

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: Macro

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3668 ast_str_retrieve_variable: Result of 'PREDIAL_HOOK_RET' is NULL

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/1111111111-00000004", "0?bypass,1") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 18

Application: GotoIf

AppData: 0?bypass,1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GotoIf

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: 1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/cidname) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/1111111111-00000004", "1?Set(CONNECTEDLINE(num,i)=73333333333)") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 19

Application: ExecIf

AppData: 1?Set(CONNECTEDLINE(num,i)=73333333333)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/cidname)' (from 'DB(AMPUSER/${AMPUSER}/cidname)}" != ""' len 30)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/cidname)' len 7)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: 1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function DB(AMPUSER/1111111111/cidname) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DIAL_NUMBER' (from 'DIAL_NUMBER})' len 11)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: 1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/cidname) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(number) result is 'XXXXXXXXXX'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/1111111111-00000004", "1?Set(CONNECTEDLINE(name,i)=CID:XXXXXXXXXX)") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 20

Application: ExecIf

AppData: 1?Set(CONNECTEDLINE(name,i)=CID:XXXXXXXXXX)

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/cidname)' (from 'DB(AMPUSER/${AMPUSER}/cidname)}" != ""' len 30)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/cidname)' len 7)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DB_RESULT

Value: 1111111111

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function DB(AMPUSER/1111111111/cidname) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4516 ast_str_substitute_variables_full: Function CALLERID(number) result is 'XXXXXXXXXX'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'custom' is 'SIP/sip_out'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/1111111111-00000004", "0?customtrunk") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 21

Application: GotoIf

AppData: 0?customtrunk

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: app_macro.c:434 _macro_exec: Executed application: GotoIf

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUT_4' is 'SIP/sip_out'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUTNUM' is '73333333333'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'TRUNK_RING_TIMER' is '300'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Dial'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:22] Dial("SIP/1111111111-00000004", "SIP/sip_out/73333333333,300,Tt") in new stack

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: macro-dialout-trunk

Extension: s

Priority: 22

Application: Dial

AppData: SIP/sip_out/73333333333,300,Tt

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DIALSTATUS

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DIALEDPEERNUMBER

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DIALEDPEERNAME

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: ANSWEREDTIME

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DIALEDTIME

Value: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:29752 sip_request_call: Asked to create a SIP channel with formats: (ulaw)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:8638 sip_alloc: Allocating new SIP dialog for 255379b04e7f190f46c1b55f29e015d4@[::1]:5060 - INVITE (No RTP)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0xb74bf8dc'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: res_rtp_asterisk.c:2140 ast_rtp_new: Allocated port 15906 for RTP instance '0xb74bf8dc'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.33' into...

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0xb74bf8dc' is setup and ready to go

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: res_rtp_asterisk.c:4280 ast_rtp_prop_set: Setup RTCP on RTP instance '0xb74bf8dc'

localhost*CLI> 
  == Using SIP RTP TOS bits 184

localhost*CLI> 
  == Using SIP RTP CoS mark 5

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:5586 do_setnat: Setting NAT on RTP to On

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:8427 change_callid_pvt: SIP call-id changed from '255379b04e7f190f46c1b55f29e015d4@[::1]:5060' to '255379b04e7f190f46c1b55f29e015d4@sipnet.ru'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: acl.c:979 ast_ouraddrfor: For destination '212.53.40.40', our source address is '192.168.1.33'.

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:3881 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.1.33:5060

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:5586 do_setnat: Setting NAT on RTP to On

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:8427 change_callid_pvt: SIP call-id changed from '255379b04e7f190f46c1b55f29e015d4@sipnet.ru' to '0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[1981]: res_odbc.c:1058 odbc_release_obj2: odbc_release_obj2(0x8c67a1c) called (obj->txf = (nil))

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newchannel

Privilege: call,all

Channel: SIP/sip_out-00000005

ChannelState: 0

ChannelStateDesc: Down

CallerIDNum: 

CallerIDName: 

AccountCode: 

Exten: 

Context: from-trunk-sip-sip_out

Uniqueid: 1411873061.5





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:7813 sip_new: *** Our native formats are (g729) 

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:7814 sip_new: *** Joint capabilities are (nothing) 

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:7815 sip_new: *** Our capabilities are (alaw|g729) 

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:7816 sip_new: *** AST_CODEC_CHOOSE formats are g729 

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:7818 sip_new: *** Our preferred formats from the incoming channel are (ulaw) 

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:7844 sip_new: This channel will not be able to handle video.

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/sip_out-00000005

Variable: SIPCALLID

Value: 0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru

Uniqueid: 1411873061.5





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: ChannelUpdate

Privilege: system,all

Channel: SIP/sip_out-00000005

Uniqueid: 1411873061.5

Channeltype: SIP

SIPcallid: 0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru

SIPfullcontact: 





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: ChannelUpdate

Privilege: system,all

Channel: SIP/sip_out-00000005

Channeltype: SIP

SIPcallid: 0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru

SIPfullcontact: 

Peername: sip_out





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: channel_internal_api.c:882 ast_channel_callid_set: Channel Call ID changing from [C-00000002] to [C-00000002]

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/sip_out-00000005

Variable: DIALEDPEERNUMBER

Value: sip_out/73333333333

Uniqueid: 1411873061.5





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable REC_POLICY_MODE from SIP/1111111111-00000004 to SIP/sip_out-00000005.

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable CALLFILENAME from SIP/1111111111-00000004 to SIP/sip_out-00000005.

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable FROMEXTEN from SIP/1111111111-00000004 to SIP/sip_out-00000005.

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable TIMESTR from SIP/1111111111-00000004 to SIP/sip_out-00000005.

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable YEAR from SIP/1111111111-00000004 to SIP/sip_out-00000005.

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable MONTH from SIP/1111111111-00000004 to SIP/sip_out-00000005.

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable DAY from SIP/1111111111-00000004 to SIP/sip_out-00000005.

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable REC_STATUS from SIP/1111111111-00000004 to SIP/sip_out-00000005.

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable MON_FMT from SIP/1111111111-00000004 to SIP/sip_out-00000005.

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: channel.c:6541 ast_channel_inherit_variables: Inheriting variable NODEST from SIP/1111111111-00000004 to SIP/sip_out-00000005.

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable DIAL_OPTIONS from SIP/1111111111-00000004 to SIP/sip_out-00000005.

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: NewCallerid

Privilege: call,all

Channel: SIP/sip_out-00000005

CallerIDNum: 73333333333

CallerIDName: CID:XXXXXXXXXX

Uniqueid: 1411873061.5

CID-CallingPres: 0 (Presentation Allowed, Not Screened)





localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:6207 sip_call: Outgoing Call for 73333333333

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:6531 update_call_counter: Updating call counter for outgoing call

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:13088 add_sdp: ** Our capability: (alaw|g729) Video flag: False Text flag: False

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:13089 add_sdp: ** Our prefcodec: (ulaw) 

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:13225 add_sdp: -- Done with adding codecs to SDP

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:13420 add_sdp: Done building SDP. Settling with this capability: (alaw|g729)

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:3367 initialize_initreq: Initializing initreq for method INVITE - callid 0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: chan_sip.c:3724 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 212.53.40.40:5060

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Dial

Privilege: call,all

SubEvent: Begin

Channel: SIP/1111111111-00000004

Destination: SIP/sip_out-00000005

CallerIDNum: XXXXXXXXXX

CallerIDName: <unknown>

ConnectedLineNum: 73333333333

ConnectedLineName: CID:XXXXXXXXXX

UniqueID: 1411873060.4

DestUniqueID: 1411873061.5

Dialstring: sip_out/73333333333





localhost*CLI> 
    -- Called SIP/sip_out/73333333333

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: channel.c:5405 set_format: Set channel SIP/sip_out-00000005 to read format slin

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: channel.c:5405 set_format: Set channel SIP/1111111111-00000004 to write format slin

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: channel.c:5405 set_format: Set channel SIP/1111111111-00000004 to read format slin

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[4735][C-00000002]: channel.c:5405 set_format: Set channel SIP/sip_out-00000005 to write format slin

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:5254 process_message: Running action 'Command'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2033]: chan_sip.c:3988 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #656)) 
[2014-09-28 10:57:41] DEBUG[2033]: chan_sip.c:3724 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 212.53.40.40:5060

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2392]: manager.c:5254 process_message: Running action 'Command'

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru (Checking To) --From tag as293b23d7 --To-tag   
[2014-09-28 10:57:41] DEBUG[2033][C-00000002]: chan_sip.c:4457 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru' Request 102: Found

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2033][C-00000002]: chan_sip.c:22624 handle_response_invite: SIP response 100 to standard invite

localhost*CLI> 
[2014-09-28 10:57:41] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru (Checking To) --From tag as293b23d7 --To-tag 1E1F27CA  
[2014-09-28 10:57:41] DEBUG[2033][C-00000002]: chan_sip.c:4378 __sip_ack: Acked pending invite 102
[2014-09-28 10:57:41] DEBUG[2033][C-00000002]: chan_sip.c:4416 __sip_ack: Stopping retransmission on '0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru' of Request 102: Match Found
[2014-09-28 10:57:41] DEBUG[2033][C-00000002]: chan_sip.c:22624 handle_response_invite: SIP response 401 to standard invite
[2014-09-28 10:57:41] DEBUG[2033][C-00000002]: chan_sip.c:3724 __sip_xmit: Trying to put 'ACK sip:739' onto UDP socket destined for 212.53.40.40:5060
[2014-09-28 10:57:41] DEBUG[2033][C-00000002]: chan_sip.c:21736 do_proxy_auth: Auth attempt 1 on INVITE
[2014-09-28 10:57:41] DEBUG[2033][C-00000002]: chan_sip.c:13088 add_sdp: ** Our capability: (alaw|g729) Video flag: False Text flag: False
[2014-09-28 10:57:41] DEBUG[2033][C-00000002]: chan_sip.c:13089 add_sdp: ** Our prefcodec: (ulaw) 
[2014-09-28 10:57:41] DEBUG[2033][C-00000002]: chan_sip.c:13225 add_sdp: -- Done with adding codecs to SDP
[2014-09-28 10:57:41] DEBUG[2033][C-00000002]: chan_sip.c:13420 add_sdp: Done building SDP. Settling with this capability: (alaw|g729)
[2014-09-28 10:57:41] DEBUG[2033][C-00000002]: chan_sip.c:3724 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 212.53.40.40:5060

localhost*CLI> 
[2014-09-28 10:57:42] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru (Checking To) --From tag as293b23d7 --To-tag 1E1F27CA  
[2014-09-28 10:57:42] DEBUG[2033][C-00000002]: chan_sip.c:4416 __sip_ack: Stopping retransmission on '0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru' of Request 102: Match Not Found
[2014-09-28 10:57:42] DEBUG[2033][C-00000002]: chan_sip.c:3724 __sip_xmit: Trying to put 'ACK sip:739' onto UDP socket destined for 212.53.40.40:5060

localhost*CLI> 
[2014-09-28 10:57:42] DEBUG[2033]: chan_sip.c:3988 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #658)) 

localhost*CLI> 
[2014-09-28 10:57:42] DEBUG[2033]: chan_sip.c:3724 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 212.53.40.40:5060

localhost*CLI> 
[2014-09-28 10:57:42] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru (Checking To) --From tag as293b23d7 --To-tag   
[2014-09-28 10:57:42] DEBUG[2033][C-00000002]: chan_sip.c:4457 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru' Request 103: Found

localhost*CLI> 
[2014-09-28 10:57:42] DEBUG[2033][C-00000002]: chan_sip.c:22624 handle_response_invite: SIP response 100 to standard invite

localhost*CLI> 
[2014-09-28 10:57:43] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru (Checking To) --From tag as293b23d7 --To-tag   

localhost*CLI> 
[2014-09-28 10:57:43] DEBUG[2033][C-00000002]: chan_sip.c:4457 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru' Request 103: Found

localhost*CLI> 
[2014-09-28 10:57:43] DEBUG[2033][C-00000002]: chan_sip.c:22624 handle_response_invite: SIP response 100 to standard invite

localhost*CLI> 
[2014-09-28 10:57:44] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru (Checking To) --From tag as293b23d7 --To-tag DFB12ECA-26028-4068354E_kmbdctj-EF93  

localhost*CLI> 
[2014-09-28 10:57:44] DEBUG[2033][C-00000002]: chan_sip.c:4457 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru' Request 103: Found

localhost*CLI> 
[2014-09-28 10:57:44] DEBUG[2033][C-00000002]: chan_sip.c:22624 handle_response_invite: SIP response 180 to standard invite

localhost*CLI> 
[2014-09-28 10:57:44] DEBUG[2033][C-00000002]: chan_sip.c:16175 build_route: build_route: Record-Route hop: <sip:11311-192.168.40.71.dialog.cgatepro;lr>
[2014-09-28 10:57:44] DEBUG[2033][C-00000002]: chan_sip.c:16175 build_route: build_route: Record-Route hop: <sip:192.168.40.71:5060;lr>
[2014-09-28 10:57:44] DEBUG[2033][C-00000002]: chan_sip.c:16175 build_route: build_route: Record-Route hop: <sip:212.53.40.40:5060;lr>

localhost*CLI> 
[2014-09-28 10:57:44] DEBUG[1989]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - sip_out

localhost*CLI> 
[2014-09-28 10:57:44] DEBUG[1989]: chan_sip.c:29647 sip_devicestate: Checking device state for peer sip_out

localhost*CLI> 
[2014-09-28 10:57:44] DEBUG[1989]: devicestate.c:467 do_state_change: Changing state for SIP/sip_out - state 1 (Not in use)

localhost*CLI> 
[2014-09-28 10:57:44] DEBUG[1989]: devicestate.c:442 devstate_event: device 'SIP/sip_out' state '1'

localhost*CLI> 
[2014-09-28 10:57:44] DEBUG[2071]: app_queue.c:1872 handle_statechange: Device 'SIP/sip_out' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.

localhost*CLI> 
[2014-09-28 10:57:44] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newstate

Privilege: call,all

Channel: SIP/sip_out-00000005

ChannelState: 5

ChannelStateDesc: Ringing

CallerIDNum: 73333333333

CallerIDName: CID:XXXXXXXXXX

ConnectedLineNum: XXXXXXXXXX

ConnectedLineName: 

Uniqueid: 1411873061.5





localhost*CLI> 
    -- SIP/sip_out-00000005 is ringing

localhost*CLI> 
[2014-09-28 10:57:44] DEBUG[4735][C-00000002]: rtp_engine.c:1821 ast_rtp_instance_early_bridge: Setting early bridge SDP of 'SIP/1111111111-00000004' with that of 'SIP/sip_out-00000005'

localhost*CLI> 
[2014-09-28 10:57:44] DEBUG[4735][C-00000002]: chan_sip.c:3724 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.1.41:5060

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: MWM5OTQyNzQ3Njk2MzYwMGJmMDcyNmU2M2JkMDM5OTI. (Checking From) --From tag 5b7c8211 --To-tag   

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.33' into...

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.33' into...

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033][C-00000002]: chan_sip.c:28202 handle_incoming: **** Received CANCEL (14) - Command in SIP CANCEL

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.41:5060' into...

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.41' and port '5060'.

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033][C-00000002]: chan_sip.c:3380 sip_alreadygone: Setting SIP_ALREADYGONE on dialog MWM5OTQyNzQ3Njk2MzYwMGJmMDcyNmU2M2JkMDM5OTI.

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033][C-00000002]: chan_sip.c:6531 update_call_counter: Updating call counter for incoming call

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033][C-00000002]: res_rtp_asterisk.c:4336 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb740f064'

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: HangupRequest

Privilege: call,all

Channel: SIP/1111111111-00000004

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033][C-00000002]: chan_sip.c:3724 __sip_xmit: Trying to put 'SIP/2.0 487' onto UDP socket destined for 192.168.1.41:5060

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033][C-00000002]: chan_sip.c:3724 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.41:5060

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1989]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 1111111111

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1989]: chan_sip.c:29647 sip_devicestate: Checking device state for peer 1111111111

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1989]: devicestate.c:467 do_state_change: Changing state for SIP/1111111111 - state 1 (Not in use)

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1989]: devicestate.c:442 devstate_event: device 'SIP/1111111111' state '1'

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[4735][C-00000002]: channel.c:2840 ast_hangup: Hanging up channel 'SIP/sip_out-00000005'

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[4735][C-00000002]: chan_sip.c:6914 sip_hangup: Hangup call SIP/sip_out-00000005, SIP callid 0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[4735][C-00000002]: res_rtp_asterisk.c:4336 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb74bf8dc'

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Hangup

Privilege: call,all

Channel: SIP/sip_out-00000005

Uniqueid: 1411873061.5

CallerIDNum: 73333333333

CallerIDName: CID:XXXXXXXXXX

ConnectedLineNum: XXXXXXXXXX

ConnectedLineName: <unknown>

AccountCode: 

Cause: 16

Cause-txt: Normal Clearing





localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: DIALSTATUS

Value: CANCEL

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1991]: devicestate.c:340 _ast_device_state: Checking if I can find provider for "Custom" - number: DND1111111111

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1991]: devicestate.c:417 getproviderstate: Checking provider SLA with Custom

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1991]: devicestate.c:417 getproviderstate: Checking provider Meetme with Custom

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1991]: devicestate.c:417 getproviderstate: Checking provider Custom with Custom

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2071]: app_queue.c:1872 handle_statechange: Device 'SIP/1111111111' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1991]: db.c:376 db_get_common: Unable to find key 'DND1111111111' in family 'CustomDevstate'

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1991]: app_queue.c:1974 extension_state_cb: Extension '1111111111@ext-local' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: ExtensionStatus

Privilege: call,all

Exten: 1111111111

Context: ext-local

Hint: SIP/1111111111&Custom:DND1111111111,CustomPresence:1111111111

Status: 0





localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1989]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - sip_out

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1989]: chan_sip.c:29647 sip_devicestate: Checking device state for peer sip_out

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1989]: devicestate.c:467 do_state_change: Changing state for SIP/sip_out - state 1 (Not in use)

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1989]: devicestate.c:442 devstate_event: device 'SIP/sip_out' state '1'

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1981]: res_odbc.c:1058 odbc_release_obj2: odbc_release_obj2(0x8c67a1c) called (obj->txf = (nil))

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Dial

Privilege: call,all

SubEvent: End

Channel: SIP/1111111111-00000004

UniqueID: 1411873060.4

DialStatus: CANCEL





localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[4735][C-00000002]: app_dial.c:3102 dial_exec_full: Exiting with DIALSTATUS=CANCEL.

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[4735][C-00000002]: app_macro.c:428 _macro_exec: Spawn extension (macro-dialout-trunk,s,22) exited non-zero on 'SIP/1111111111-00000004' in macro 'dialout-trunk'

localhost*CLI> 
  == Spawn extension (macro-dialout-trunk, s, 22) exited non-zero on 'SIP/1111111111-00000004' in macro 'dialout-trunk'

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Variable: MACRO_DEPTH

Value: 0

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[4735][C-00000002]: pbx.c:6572 __ast_pbx_run: Spawn extension (from-internal,73333333333,6) exited non-zero on 'SIP/1111111111-00000004'

localhost*CLI> 
  == Spawn extension (from-internal, 73333333333, 6) exited non-zero on 'SIP/1111111111-00000004'

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[4735][C-00000002]: channel.c:2661 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/1111111111-00000004'

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: SoftHangupRequest

Privilege: call,all

Channel: SIP/1111111111-00000004

Uniqueid: 1411873060.4

Cause: 16





localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[4735][C-00000002]: channel.c:2661 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/1111111111-00000004'

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[4735][C-00000002]: pbx.c:4883 pbx_extension_helper: Launching 'Hangup'

localhost*CLI> 
    -- Executing [h@from-internal:1] Hangup("SIP/1111111111-00000004", "") in new stack

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[4735][C-00000002]: channel.c:2661 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/1111111111-00000004'

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newexten

Privilege: dialplan,all

Channel: SIP/1111111111-00000004

Context: from-internal

Extension: h

Priority: 1

Application: Hangup

AppData: 

Uniqueid: 1411873060.4





localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[4735][C-00000002]: pbx.c:6088 ast_pbx_h_exten_run: Spawn extension (from-internal,h,1) exited non-zero on 'SIP/1111111111-00000004'

localhost*CLI> 
  == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/1111111111-00000004'

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[4735][C-00000002]: channel.c:2840 ast_hangup: Hanging up channel 'SIP/1111111111-00000004'

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[4735][C-00000002]: chan_sip.c:6914 sip_hangup: Hangup call SIP/1111111111-00000004, SIP callid MWM5OTQyNzQ3Njk2MzYwMGJmMDcyNmU2M2JkMDM5OTI.

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[4735][C-00000002]: res_rtp_asterisk.c:4336 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb740f064'

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Hangup

Privilege: call,all

Channel: SIP/1111111111-00000004

Uniqueid: 1411873060.4

CallerIDNum: XXXXXXXXXX

CallerIDName: <unknown>

ConnectedLineNum: 73333333333

ConnectedLineName: CID:XXXXXXXXXX

AccountCode: 

Cause: 16

Cause-txt: Normal Clearing





localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1981]: res_odbc.c:1058 odbc_release_obj2: odbc_release_obj2(0x8c67a1c) called (obj->txf = (nil))

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2071]: app_queue.c:1872 handle_statechange: Device 'SIP/sip_out' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: MWM5OTQyNzQ3Njk2MzYwMGJmMDcyNmU2M2JkMDM5OTI. (Checking From) --From tag 5b7c8211 --To-tag as7ac1f66b  

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033][C-00000002]: chan_sip.c:28202 handle_incoming: **** Received ACK (6) - Command in SIP ACK

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033][C-00000002]: chan_sip.c:4416 __sip_ack: Stopping retransmission on 'MWM5OTQyNzQ3Njk2MzYwMGJmMDcyNmU2M2JkMDM5OTI.' of Response 2: Match Found

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033]: chan_sip.c:6679 sip_destroy: Destroying SIP dialog MWM5OTQyNzQ3Njk2MzYwMGJmMDcyNmU2M2JkMDM5OTI.

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2033]: rtp_engine.c:226 instance_destructor: Destroyed RTP instance '0xb740f064'

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1981]: res_odbc.c:1058 odbc_release_obj2: odbc_release_obj2(0x8c67a1c) called (obj->txf = (nil))

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[4735][C-00000002]: res_odbc.c:1058 odbc_release_obj2: odbc_release_obj2(0x8c67a1c) called (obj->txf = (nil))

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1989]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 1111111111

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1989]: chan_sip.c:29647 sip_devicestate: Checking device state for peer 1111111111

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1989]: devicestate.c:467 do_state_change: Changing state for SIP/1111111111 - state 1 (Not in use)

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1989]: devicestate.c:442 devstate_event: device 'SIP/1111111111' state '1'

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1981]: res_odbc.c:1058 odbc_release_obj2: odbc_release_obj2(0x8c67a1c) called (obj->txf = (nil))

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1981]: res_odbc.c:1058 odbc_release_obj2: odbc_release_obj2(0x8c67a1c) called (obj->txf = (nil))

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[2071]: app_queue.c:1872 handle_statechange: Device 'SIP/1111111111' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1991]: devicestate.c:340 _ast_device_state: Checking if I can find provider for "Custom" - number: DND1111111111

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1991]: devicestate.c:417 getproviderstate: Checking provider SLA with Custom

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1991]: devicestate.c:417 getproviderstate: Checking provider Meetme with Custom

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1991]: devicestate.c:417 getproviderstate: Checking provider Custom with Custom

localhost*CLI> 
[2014-09-28 10:57:49] DEBUG[1991]: db.c:376 db_get_common: Unable to find key 'DND1111111111' in family 'CustomDevstate'

localhost*CLI> 
[2014-09-28 10:58:33] DEBUG[2033]: chan_sip.c:8638 sip_alloc: Allocating new SIP dialog for 2fda32c240c3bf7f1edf98155bb64571@[::1]:5060 - OPTIONS (No RTP)
[2014-09-28 10:58:33] DEBUG[2033]: acl.c:979 ast_ouraddrfor: For destination '192.168.1.41', our source address is '192.168.1.33'.
[2014-09-28 10:58:33] DEBUG[2033]: chan_sip.c:3881 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.1.33:5060
[2014-09-28 10:58:33] DEBUG[2033]: chan_sip.c:8427 change_callid_pvt: SIP call-id changed from '2fda32c240c3bf7f1edf98155bb64571@[::1]:5060' to '575401271eb850eb1dbd8a822bfad05f@192.168.1.33:5060'
[2014-09-28 10:58:33] DEBUG[2033]: chan_sip.c:3367 initialize_initreq: Initializing initreq for method OPTIONS - callid 575401271eb850eb1dbd8a822bfad05f@192.168.1.33:5060

localhost*CLI> 
[2014-09-28 10:58:33] DEBUG[2033]: chan_sip.c:3724 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.1.41:5060

localhost*CLI> 
[2014-09-28 10:58:33] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 575401271eb850eb1dbd8a822bfad05f@192.168.1.33:5060 (Checking To) --From tag as5901e5ab --To-tag 140d6438  
[2014-09-28 10:58:33] DEBUG[2033]: chan_sip.c:4416 __sip_ack: Stopping retransmission on '575401271eb850eb1dbd8a822bfad05f@192.168.1.33:5060' of Request 102: Match Found

localhost*CLI> 
[2014-09-28 10:58:33] DEBUG[2033]: chan_sip.c:6679 sip_destroy: Destroying SIP dialog 575401271eb850eb1dbd8a822bfad05f@192.168.1.33:5060

localhost*CLI> 
[2014-09-28 10:58:54] DEBUG[2033]: chan_sip.c:3326 registry_addref: SIP Registry sipnet.ru: refcount now 3
[2014-09-28 10:58:54] DEBUG[2033]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'sipnet.ru' into...
[2014-09-28 10:58:54] DEBUG[2033]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'sipnet.ru' and port ''.
[2014-09-28 10:58:54] DEBUG[2033]: dnsmgr.c:164 internal_dnsmgr_lookup: doing dnsmgr_lookup for 'sipnet.ru'
[2014-09-28 10:58:54] DEBUG[2033]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'sipnet.ru' into...
[2014-09-28 10:58:54] DEBUG[2033]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'sipnet.ru' and port ''.

localhost*CLI> 
[2014-09-28 10:58:54] DEBUG[2033]: chan_sip.c:3318 registry_unref: SIP Registry sipnet.ru: refcount now 2

localhost*CLI> 
[2014-09-28 10:58:54] DEBUG[2033]: chan_sip.c:8638 sip_alloc: Allocating new SIP dialog for 6af9a32d7b1eddc16a6dd0cf14ed4bb0@[::1] - REGISTER (No RTP)
[2014-09-28 10:58:54] DEBUG[2033]: chan_sip.c:3326 registry_addref: SIP Registry sipnet.ru: refcount now 3
[2014-09-28 10:58:54] DEBUG[2033]: acl.c:979 ast_ouraddrfor: For destination '212.53.40.40', our source address is '192.168.1.33'.
[2014-09-28 10:58:54] DEBUG[2033]: chan_sip.c:3881 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.1.33:5060
[2014-09-28 10:58:54] DEBUG[2033]: chan_sip.c:3326 registry_addref: SIP Registry sipnet.ru: refcount now 4
[2014-09-28 10:58:54] DEBUG[2033]: chan_sip.c:15267 transmit_register: Scheduled a registration timeout for sipnet.ru id  #665 
[2014-09-28 10:58:54] DEBUG[2033]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'sipnet.ru' into...
[2014-09-28 10:58:54] DEBUG[2033]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'sipnet.ru' and port ''.
[2014-09-28 10:58:54] DEBUG[2033]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'sipnet.ru' into...
[2014-09-28 10:58:54] DEBUG[2033]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'sipnet.ru' and port ''.
[2014-09-28 10:58:54] DEBUG[2033]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'sipnet.ru' into...
[2014-09-28 10:58:54] DEBUG[2033]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'sipnet.ru' and port ''.
[2014-09-28 10:58:54] DEBUG[2033]: chan_sip.c:3367 initialize_initreq: Initializing initreq for method REGISTER - callid 6af9a32d7b1eddc16a6dd0cf14ed4bb0@[::1]
[2014-09-28 10:58:54] DEBUG[2033]: chan_sip.c:15342 transmit_register: REGISTER attempt 1 to x_x_xxx_xxx@sipnet.ru
[2014-09-28 10:58:54] DEBUG[2033]: chan_sip.c:3724 __sip_xmit: Trying to put 'REGISTER si' onto UDP socket destined for 212.53.40.40:5060
[2014-09-28 10:58:54] DEBUG[2033]: chan_sip.c:3318 registry_unref: SIP Registry sipnet.ru: refcount now 3

localhost*CLI> 
[2014-09-28 10:58:54] DEBUG[2033]: chan_sip.c:3988 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #666)) 
[2014-09-28 10:58:54] DEBUG[2033]: chan_sip.c:3724 __sip_xmit: Trying to put 'REGISTER si' onto UDP socket destined for 212.53.40.40:5060

localhost*CLI> 
[2014-09-28 10:58:55] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 6af9a32d7b1eddc16a6dd0cf14ed4bb0@[::1] (Checking To) --From tag as3acd0620 --To-tag 2993218C  
[2014-09-28 10:58:55] DEBUG[2033]: chan_sip.c:4416 __sip_ack: Stopping retransmission on '6af9a32d7b1eddc16a6dd0cf14ed4bb0@[::1]' of Request 179: Match Found
[2014-09-28 10:58:55] DEBUG[2033]: chan_sip.c:23451 handle_response_register: Registration successful
[2014-09-28 10:58:55] DEBUG[2033]: chan_sip.c:23453 handle_response_register: Cancelling timeout 665
[2014-09-28 10:58:55] DEBUG[2033]: chan_sip.c:3318 registry_unref: SIP Registry sipnet.ru: refcount now 2
[2014-09-28 10:58:55] DEBUG[2033]: chan_sip.c:3318 registry_unref: SIP Registry sipnet.ru: refcount now 1
[2014-09-28 10:58:55] DEBUG[2033]: chan_sip.c:3326 registry_addref: SIP Registry sipnet.ru: refcount now 2
[2014-09-28 10:58:55] DEBUG[2033]: chan_sip.c:6679 sip_destroy: Destroying SIP dialog 6af9a32d7b1eddc16a6dd0cf14ed4bb0@[::1]
[2014-09-28 10:58:55] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Registry

Privilege: system,all

ChannelType: SIP

Username: x_x_xxx_xxx

Domain: sipnet.ru

Status: Registered





localhost*CLI> 
[2014-09-28 10:58:55] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 6af9a32d7b1eddc16a6dd0cf14ed4bb0@[::1] (Checking To) --From tag as3acd0620 --To-tag 2993218C  

localhost*CLI> 
[2014-09-28 10:58:55] DEBUG[2033]: chan_sip.c:9193 find_call: That's odd...  Got a response on a call we don't know about. Callid 6af9a32d7b1eddc16a6dd0cf14ed4bb0@[::1]

localhost*CLI> 
[2014-09-28 10:58:55] DEBUG[2033]: chan_sip.c:28478 handle_request_do: Invalid SIP message - rejected , no callid, len 535

localhost*CLI> 
[2014-09-28 10:59:12] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru (Checking To) --From tag as293b23d7 --To-tag DFB12ECA-26028-4068354E_kmbdctj-EF93  
[2014-09-28 10:59:12] DEBUG[2033][C-00000002]: chan_sip.c:4378 __sip_ack: Acked pending invite 103
[2014-09-28 10:59:12] DEBUG[2033][C-00000002]: chan_sip.c:4416 __sip_ack: Stopping retransmission on '0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru' of Request 103: Match Found
[2014-09-28 10:59:12] DEBUG[2033][C-00000002]: chan_sip.c:22624 handle_response_invite: SIP response 487 to standard invite
[2014-09-28 10:59:12] DEBUG[2033][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '212.53.40.40:5060' into...
[2014-09-28 10:59:12] DEBUG[2033][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '212.53.40.40' and port '5060'.
[2014-09-28 10:59:12] DEBUG[2033][C-00000002]: chan_sip.c:3724 __sip_xmit: Trying to put 'ACK sip:sig' onto UDP socket destined for 212.53.40.40:5060
[2014-09-28 10:59:12] DEBUG[2033][C-00000002]: chan_sip.c:6531 update_call_counter: Updating call counter for outgoing call
[2014-09-28 10:59:12] DEBUG[2033][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '212.53.40.40:5060' into...

localhost*CLI> 
[2014-09-28 10:59:12] DEBUG[2033][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '212.53.40.40' and port '5060'.
[2014-09-28 10:59:12] DEBUG[2033][C-00000002]: chan_sip.c:3724 __sip_xmit: Trying to put 'BYE sip:sig' onto UDP socket destined for 212.53.40.40:5060

localhost*CLI> 
[2014-09-28 10:59:12] DEBUG[2033]: chan_sip.c:3988 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #668)) 
[2014-09-28 10:59:12] DEBUG[2033]: chan_sip.c:3724 __sip_xmit: Trying to put 'BYE sip:sig' onto UDP socket destined for 212.53.40.40:5060

localhost*CLI> 
[2014-09-28 10:59:13] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru (Checking To) --From tag as293b23d7 --To-tag DFB12ECA-26028-4068354E_kmbdctj-EF93  
[2014-09-28 10:59:13] DEBUG[2033][C-00000002]: chan_sip.c:4416 __sip_ack: Stopping retransmission on '0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru' of Request 104: Match Found
[2014-09-28 10:59:13] DEBUG[2033]: chan_sip.c:6679 sip_destroy: Destroying SIP dialog 0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru
[2014-09-28 10:59:13] DEBUG[2033]: rtp_engine.c:226 instance_destructor: Destroyed RTP instance '0xb74bf8dc'

localhost*CLI> 
[2014-09-28 10:59:13] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru (Checking To) --From tag as293b23d7 --To-tag DFB12ECA-26028-4068354E_kmbdctj-EF93  

localhost*CLI> 
[2014-09-28 10:59:13] DEBUG[2033]: chan_sip.c:9193 find_call: That's odd...  Got a response on a call we don't know about. Callid 0acfe43f2eaab4c21cd7b1215fc72801@sipnet.ru
[2014-09-28 10:59:13] DEBUG[2033]: chan_sip.c:28478 handle_request_do: Invalid SIP message - rejected , no callid, len 335

localhost*CLI> 