localhost*CLI> 

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: ZTZjOWM3MDNiMjEwOGEwYTY5ZWZkNzQ1YzQwMzk3ZjA. (Checking From) --From tag 99382d3d --To-tag   
[2014-09-28 10:16:39] 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:16:39] DEBUG[2033]: chan_sip.c:3881 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.1.33:5060
[2014-09-28 10:16:39] DEBUG[2033]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.41:5060' into...
[2014-09-28 10:16:39] DEBUG[2033]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.41' and port '5060'.
[2014-09-28 10:16:39] DEBUG[2033]: chan_sip.c:8638 sip_alloc: Allocating new SIP dialog for ZTZjOWM3MDNiMjEwOGEwYTY5ZWZkNzQ1YzQwMzk3ZjA. - INVITE (No RTP)
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:28202 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: sip/reqresp_parser.c:1607 parse_sip_options: Begin: parsing SIP "Supported: replaces, norefersub, extended-refer, X-cisco-serviceuri"
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: sip/reqresp_parser.c:1623 parse_sip_options: Found SIP option: -replaces-
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: sip/reqresp_parser.c:1631 parse_sip_options: Matched SIP option: replaces
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: sip/reqresp_parser.c:1623 parse_sip_options: Found SIP option: -norefersub-
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: sip/reqresp_parser.c:1631 parse_sip_options: Matched SIP option: norefersub

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: sip/reqresp_parser.c:1623 parse_sip_options: Found SIP option: -extended-refer-

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: 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:16:39] DEBUG[2033][C-00000001]: sip/reqresp_parser.c:1623 parse_sip_options: Found SIP option: -X-cisco-serviceuri-

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: sip/reqresp_parser.c:1657 parse_sip_options: Found private SIP option, not supported: X-cisco-serviceuri

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.41:5060' into...

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.41' and port '5060'.

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

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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: 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:16:39] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: ZTZjOWM3MDNiMjEwOGEwYTY5ZWZkNzQ1YzQwMzk3ZjA. (Checking From) --From tag 99382d3d --To-tag as4633b217  

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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:4416 __sip_ack: Stopping retransmission on 'ZTZjOWM3MDNiMjEwOGEwYTY5ZWZkNzQ1YzQwMzk3ZjA.' of Response 1: Match Found

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: ZTZjOWM3MDNiMjEwOGEwYTY5ZWZkNzQ1YzQwMzk3ZjA. (Checking From) --From tag 99382d3d --To-tag   
[2014-09-28 10:16:39] DEBUG[2033]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.33' into...
[2014-09-28 10:16:39] DEBUG[2033]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.
[2014-09-28 10:16:39] DEBUG[2033]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.33' into...
[2014-09-28 10:16:39] DEBUG[2033]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:28202 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.41:5060' into...
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.41' and port '5060'.
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.33' into...
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0xb740f0cc'
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: res_rtp_asterisk.c:2140 ast_rtp_new: Allocated port 14158 for RTP instance '0xb740f0cc'

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

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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0xb740f0cc' is setup and ready to go

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: res_rtp_asterisk.c:4280 ast_rtp_prop_set: Setup RTCP on RTP instance '0xb740f0cc'

localhost*CLI> 
  == Using SIP RTP TOS bits 184

localhost*CLI> 
  == Using SIP RTP CoS mark 5

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:5586 do_setnat: Setting NAT on RTP to On

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:9926 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:9926 process_sdp: Processing session-level SDP o=Zoiper_user 0 0 IN IP4 192.168.1.41... OK.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:9926 process_sdp: Processing session-level SDP s=Zoiper_session... UNSUPPORTED OR FAILED.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.41' into...

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.41' and port ''.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:9926 process_sdp: Processing session-level SDP c=IN IP4 192.168.1.41... OK.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:9926 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 3 based on m type on 0xb6428e40

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0xb6428e40

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0xb6428e40

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0xb6428e40

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: res_rtp_asterisk.c:4336 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb740f0cc'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0xb6428e40 to 0xb740f278

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 3 from 0xb6428e40 to 0xb740f278

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0xb6428e40 to 0xb740f278

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0xb6428e40 to 0xb740f278

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: res_rtp_asterisk.c:4246 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0xb740f0cc'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:10650 process_sdp: We're settling with these formats: (gsm|ulaw|alaw)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:25574 handle_request_invite: Checking SIP call limits for device 1111111111

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:6531 update_call_counter: Updating call counter for incoming call

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[1989]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 1111111111

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[1989]: chan_sip.c:29647 sip_devicestate: Checking device state for peer 1111111111

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[1989]: devicestate.c:467 do_state_change: Changing state for SIP/1111111111 - state 2 (In use)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[1989]: devicestate.c:442 devstate_event: device 'SIP/1111111111' state '2'

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

localhost*CLI> 
[2014-09-28 10:16:39] 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:16:39] DEBUG[2033][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.

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

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

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

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

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

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

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

localhost*CLI> 
[2014-09-28 10:16:39] 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:16:39] 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:16:39] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newchannel

Privilege: call,all

Channel: SIP/1111111111-00000002

ChannelState: 0

ChannelStateDesc: Down

CallerIDNum: 1111111111

CallerIDName: 1111111111

AccountCode: 

Exten: 79999999999

Context: from-internal

Uniqueid: 1411870599.2





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

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

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

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

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: SIPURI

Value: sip:1111111111@192.168.1.41:5060

Uniqueid: 1411870599.2





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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: SIPDOMAIN

Value: 192.168.1.33

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: SIPCALLID

Value: ZTZjOWM3MDNiMjEwOGEwYTY5ZWZkNzQ1YzQwMzk3ZjA.

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: ChannelUpdate

Privilege: system,all

Channel: SIP/1111111111-00000002

Uniqueid: 1411870599.2

Channeltype: SIP

SIPcallid: ZTZjOWM3MDNiMjEwOGEwYTY5ZWZkNzQ1YzQwMzk3ZjA.

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





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:16212 build_route: build_route: Contact hop: <sip:1111111111@192.168.1.41:5060;transport=UDP>

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:25770 handle_request_invite: SIP/1111111111-00000002: New call is still down.... Trying... 

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2033][C-00000001]: chan_sip.c:3724 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.41:5060

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[1989]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 1111111111

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[1989]: chan_sip.c:29647 sip_devicestate: Checking device state for peer 1111111111

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[1989]: devicestate.c:467 do_state_change: Changing state for SIP/1111111111 - state 2 (In use)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[1989]: devicestate.c:442 devstate_event: device 'SIP/1111111111' state '2'

localhost*CLI> 
[2014-09-28 10:16:39] 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:16:39] DEBUG[1991]: devicestate.c:340 _ast_device_state: Checking if I can find provider for "Custom" - number: DND1111111111

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

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

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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newstate

Privilege: call,all

Channel: SIP/1111111111-00000002

ChannelState: 4

ChannelStateDesc: Ring

CallerIDNum: 1111111111

CallerIDName: 1111111111

ConnectedLineNum: 

ConnectedLineName: 

Uniqueid: 1411870599.2





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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Macro'

localhost*CLI> 
    -- Executing [79999999999@from-internal:1] Macro("SIP/1111111111-00000002", "user-callerid,LIMIT,EXTERNAL,") in new stack

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: from-internal

Extension: 79999999999

Priority: 1

Application: Macro

AppData: user-callerid,LIMIT,EXTERNAL,

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_EXTEN

Value: 79999999999

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_CONTEXT

Value: from-internal

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_PRIORITY

Value: 1

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: ARG1

Value: LIMIT

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: ARG2

Value: EXTERNAL

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: ARG3

Value: 

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'UNIQUEID' is '1411870599.2'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 1

Application: Set

AppData: TOUCH_MONITOR=1411870599.2

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: TOUCH_MONITOR

Value: 1411870599.2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'AMPUSER' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'AMPUSER' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(1?1111111111:) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 2

Application: Set

AppData: AMPUSER=1111111111

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: AMPUSER

Value: 1111111111

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CHANNEL' (from 'CHANNEL}' len 7)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'CHANNEL' is 'SIP/1111111111-00000002'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CUT(CHANNEL,@,2) result is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'AMPUSERCIDNAME' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 3

Application: GotoIf

AppData: 0?report

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GotoIf

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 4

Application: ExecIf

AppData: 1?Set(REALCALLERIDNUM=1111111111)

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: REALCALLERIDNUM

Value: 1111111111

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: ExecIf

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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function CALLERID(number) result is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: 1111111111

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(DEVICE/1111111111/user) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 5

Application: Set

AppData: AMPUSER=1111111111

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: AMPUSER

Value: 1111111111

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 6

Application: GotoIf

AppData: 0?limit

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GotoIf

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: 1111111111

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/cidname) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 7

Application: Set

AppData: AMPUSERCIDNAME=1111111111

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: AMPUSERCIDNAME

Value: 1111111111

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSERCIDNAME' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 8

Application: GotoIf

AppData: 0?report

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GotoIf

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is 'EXTERNAL'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: 1111111111

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB_EXISTS(AMPUSER/1111111111/cidnum) result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DB_RESULT' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(0?1111111111:1111111111) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 9

Application: Set

AppData: AMPUSERCID=1111111111

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: AMPUSERCID

Value: 1111111111

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: db.c:376 db_get_common: Unable to find key '1111111111/dialopts' in family 'AMPUSER'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB_EXISTS(AMPUSER/1111111111/dialopts) result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DB_RESULT' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_OPTIONS' is 'Ttr'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(0?1111111111:Ttr) result is 'Ttr'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 10

Application: Set

AppData: __DIAL_OPTIONS=Ttr

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: __DIAL_OPTIONS

Value: Ttr

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSERCIDNAME' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSERCID' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 11

Application: Set

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

Uniqueid: 1411870599.2





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

Privilege: call,all

Channel: SIP/1111111111-00000002

CallerIDNum: 1111111111

CallerIDName: 1111111111

Uniqueid: 1411870599.2

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





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN(1111111111) result is '10'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: 3

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/concurrency_limit) result is '3'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function GROUP_COUNT(1111111111@concurrency_limit) result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: 3

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/concurrency_limit) result is '3'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 12

Application: GotoIf

AppData: 0?limit

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GotoIf

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN(1111111111) result is '10'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 13

Application: ExecIf

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

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: ExecIf

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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'LEN(${AMPUSER})' (from 'LEN(${AMPUSER})}' len 15)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER})' len 7)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN(1111111111) result is '10'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER})' len 7)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: generic

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN(generic) result is '7'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: generic

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '7'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MACRO_CONTEXT' is 'from-internal'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(dnid) result is '79999999999'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GosubIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 14

Application: GosubIf

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

Uniqueid: 1411870599.2





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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: LOCAL(ARG1)

Value: from-internal

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_stack.c:621 gosub_exec: Setting 'ARG1' to 'from-internal'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: LOCAL(ARG2)

Value: 79999999999

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_stack.c:621 gosub_exec: Setting 'ARG2' to '79999999999'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: LOCAL(ARGC)

Value: 2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GosubIf

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/ccss/cc_agent_policy)' len 7)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: generic

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN(generic) result is '7'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/ccss/cc_agent_policy)' len 7)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: generic

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '7'

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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MACRO_CONTEXT' is 'from-internal'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CALLERID(dnid)' (from 'CALLERID(dnid)})' len 14)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function CALLERID(dnid) result is '79999999999'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:449 _macro_exec: Incrementing gosub_level

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'CCSS_SETUP' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-ccss

Extension: s

Priority: 1

Application: ExecIf

AppData: 0?Return()

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'LEN(${CCSS_SETUP})' (from 'LEN(${CCSS_SETUP})}' len 18)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CCSS_SETUP' (from 'CCSS_SETUP})' len 10)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'CCSS_SETUP' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-ccss

Extension: s

Priority: 2

Application: Set

AppData: CCSS_SETUP=TRUE

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: CCSS_SETUP

Value: TRUE

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '79999999999'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: db.c:376 db_get_common: Unable to find key '79999999999/ccss/cc_monitor_policy' in family 'AMPUSER'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: func_db.c:151 function_db_read: DB: AMPUSER/79999999999/ccss/cc_monitor_policy not found in database.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/79999999999/ccss/cc_monitor_policy) result is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'from-internal'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '79999999999'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'from-internal'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '79999999999'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GosubIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-ccss

Extension: s

Priority: 3

Application: GosubIf

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

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: LOCAL(ARG1)

Value: from-internal

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_stack.c:621 gosub_exec: Setting 'ARG1' to 'from-internal'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: LOCAL(ARG2)

Value: 79999999999

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_stack.c:621 gosub_exec: Setting 'ARG2' to '79999999999'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: LOCAL(ARGC)

Value: 2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GosubIf

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ARG2' (from 'ARG2}/ccss/cc_monitor_policy)' len 4)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '79999999999'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: db.c:376 db_get_common: Unable to find key '79999999999/ccss/cc_monitor_policy' in family 'AMPUSER'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: func_db.c:151 function_db_read: DB: AMPUSER/79999999999/ccss/cc_monitor_policy not found in database.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function DB(AMPUSER/79999999999/ccss/cc_monitor_policy) result is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'from-internal'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '79999999999'

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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'from-internal'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ARG2' (from 'ARG2})' len 4)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '79999999999'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:454 _macro_exec: Incrementing gosub_level

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '79999999999'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: db.c:376 db_get_common: Unable to find key '79999999999/cidname' in family 'AMPUSER'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: func_db.c:151 function_db_read: DB: AMPUSER/79999999999/cidname not found in database.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/79999999999/cidname) result is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-ccss

Extension: monitor_default

Priority: 1

Application: GotoIf

AppData: 0?is_exten

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GotoIf

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'StackPop'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-ccss

Extension: monitor_default

Priority: 2

Application: StackPop

AppData: 

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: StackPop

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:462 _macro_exec: Decrementing gosub_level

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Return'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-ccss

Extension: monitor_default

Priority: 3

Application: Return

AppData: FALSE

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: GOSUB_RETVAL

Value: FALSE

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Return

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:459 _macro_exec: Decrementing gosub_level

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: 

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/language) result is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: 

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/language) result is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 15

Application: ExecIf

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

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/language)' len 7)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: 

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function DB(AMPUSER/1111111111/language) result is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/language)' len 7)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: 

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function DB(AMPUSER/1111111111/language) result is ''

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 16

Application: GotoIf

AppData: 1?continue

Uniqueid: 1411870599.2





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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GotoIf

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 30

Application: Set

AppData: CALLERID(number)=1111111111

Uniqueid: 1411870599.2





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

Privilege: call,all

Channel: SIP/1111111111-00000002

CallerIDNum: 1111111111

CallerIDName: 1111111111

Uniqueid: 1411870599.2

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





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(name) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 31

Application: Set

AppData: CALLERID(name)=1111111111

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 32

Application: Set

AppData: CDR(cnum)=1111111111

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(name) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 33

Application: Set

AppData: CDR(cnam)=1111111111

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CHANNEL(language)' (from 'CHANNEL(language)}' len 17)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function CHANNEL(language) result is 'ru_gsm'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function MASTER_CHANNEL(CHANNEL(language)) result is 'ru_gsm'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-user-callerid

Extension: s

Priority: 34

Application: Set

AppData: CHANNEL(language)=ru_gsm

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 0

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'CALLEE_ACCOUNCODE' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'CALLEE_ACCOUNCODE' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: from-internal

Extension: 79999999999

Priority: 2

Application: ExecIf

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

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'MOHCLASS' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'MOHCLASS' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(1?default:) result is 'default'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: from-internal

Extension: 79999999999

Priority: 3

Application: Set

AppData: MOHCLASS=default

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MOHCLASS

Value: default

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: from-internal

Extension: 79999999999

Priority: 4

Application: Set

AppData: _NODEST=

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: _NODEST

Value: 

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'EXTEN' is '79999999999'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Gosub'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: from-internal

Extension: 79999999999

Priority: 5

Application: Gosub

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

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: LOCAL(ARG1)

Value: out

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_stack.c:621 gosub_exec: Setting 'ARG1' to 'out'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: LOCAL(ARG2)

Value: 79999999999

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_stack.c:621 gosub_exec: Setting 'ARG2' to '79999999999'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: LOCAL(ARG3)

Value: 

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_stack.c:621 gosub_exec: Setting 'ARG3' to ''

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: LOCAL(ARGC)

Value: 3

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'REC_POLICY_MODE' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: s

Priority: 1

Application: Set

AppData: REC_POLICY_MODE_SAVE=

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: REC_POLICY_MODE_SAVE

Value: 

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'BLINDTRANSFER' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: s

Priority: 2

Application: GotoIf

AppData: 1?check

Uniqueid: 1411870599.2





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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MIXMON_FORMAT' is 'wav'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MIXMON_FORMAT' is 'wav'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(0?WAV:wav) result is 'wav'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: s

Priority: 7

Application: Set

AppData: __MON_FMT=wav

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: __MON_FMT

Value: wav

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'REC_STATUS' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: s

Priority: 8

Application: GotoIf

AppData: 1?next

Uniqueid: 1411870599.2





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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'out'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN(out) result is '3'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: s

Priority: 11

Application: ExecIf

AppData: 0?Return()

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'REC_POLICY_MODE' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG3' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG3' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: s

Priority: 12

Application: ExecIf

AppData: 0?Set(__REC_POLICY_MODE=)

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'REC_STATUS' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'out'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: s

Priority: 13

Application: GotoIf

AppData: 0?out,1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: s

Priority: 14

Application: Set

AppData: __REC_STATUS=INITIALIZED

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: __REC_STATUS

Value: INITIALIZED

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'EPOCH' is '1411870599'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: s

Priority: 15

Application: Set

AppData: NOW=1411870599

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: NOW

Value: 1411870599

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'NOW' is '1411870599'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function STRFTIME(1411870599,,%d) result is '28'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: s

Priority: 16

Application: Set

AppData: __DAY=28

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: __DAY

Value: 28

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'NOW' is '1411870599'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function STRFTIME(1411870599,,%m) result is '09'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: s

Priority: 17

Application: Set

AppData: __MONTH=09

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: __MONTH

Value: 09

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'NOW' is '1411870599'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function STRFTIME(1411870599,,%Y) result is '2014'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: s

Priority: 18

Application: Set

AppData: __YEAR=2014

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: __YEAR

Value: 2014

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'YEAR' is '2014'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MONTH' is '09'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DAY' is '28'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'NOW' is '1411870599'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function STRFTIME(1411870599,,%H%M%S) result is '101639'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: s

Priority: 19

Application: Set

AppData: __TIMESTR=20140928-101639

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: __TIMESTR

Value: 20140928-101639

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN(1111111111) result is '10'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '10'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN(1111111111) result is '10'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '10'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(10?1111111111:unknown) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(10?1111111111:1111111111) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: s

Priority: 20

Application: Set

AppData: __FROMEXTEN=1111111111

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: __FROMEXTEN

Value: 1111111111

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'out'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '79999999999'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FROMEXTEN' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'TIMESTR' is '20140928-101639'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'UNIQUEID' is '1411870599.2'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@sub-record-check:21] Set("SIP/1111111111-00000002", "__CALLFILENAME=out-79999999999-1111111111-20140928-101639-1411870599.2") in new stack

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: s

Priority: 21

Application: Set

AppData: __CALLFILENAME=out-79999999999-1111111111-20140928-101639-1411870599.2

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: __CALLFILENAME

Value: out-79999999999-1111111111-20140928-101639-1411870599.2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is 'out'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Goto'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: s

Priority: 22

Application: Goto

AppData: out,1

Uniqueid: 1411870599.2





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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'REC_POLICY_MODE' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FROMEXTEN' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: dontcare

Uniqueid: 1411870599.2





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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: out

Priority: 1

Application: ExecIf

AppData: 1?Set(__REC_POLICY_MODE=dontcare)

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: __REC_POLICY_MODE

Value: dontcare

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REC_POLICY_MODE' is 'dontcare'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '79999999999'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FROMEXTEN' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GosubIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: out

Priority: 2

Application: GosubIf

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

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Return'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: sub-record-check

Extension: out

Priority: 3

Application: Return

AppData: 

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: GOSUB_RETVAL

Value: 

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'EXTEN' is '79999999999'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Macro'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: from-internal

Extension: 79999999999

Priority: 6

Application: Macro

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

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_EXTEN

Value: 79999999999

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_CONTEXT

Value: from-internal

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_PRIORITY

Value: 6

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: ARG1

Value: 4

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: ARG2

Value: 79999999999

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: ARG3

Value: 

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: ARG4

Value: off

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 1

Application: Set

AppData: DIAL_TRUNK=4

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DIAL_TRUNK

Value: 4

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG3' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: db.c:376 db_get_common: Unable to find key '1111111111/pinless' in family 'AMPUSER'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: func_db.c:151 function_db_read: DB: AMPUSER/1111111111/pinless not found in database.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/pinless) result is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GosubIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 2

Application: GosubIf

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

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GosubIf

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ARG3' (from 'ARG3}" != ""' len 4)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG3' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/pinless)' len 7)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: db.c:376 db_get_common: Unable to find key '1111111111/pinless' in family 'AMPUSER'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: func_db.c:151 function_db_read: DB: AMPUSER/1111111111/pinless not found in database.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function DB(AMPUSER/1111111111/pinless) result is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUTDISABLE_4' is 'off'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 3

Application: GotoIf

AppData: 0?disabletrunk,1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GotoIf

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG2' is '79999999999'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 4

Application: Set

AppData: DIAL_NUMBER=79999999999

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DIAL_NUMBER

Value: 79999999999

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_OPTIONS' is 'Ttr'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 5

Application: Set

AppData: DIAL_TRUNK_OPTIONS=Ttr

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DIAL_TRUNK_OPTIONS

Value: Ttr

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 6

Application: Set

AppData: OUTBOUND_GROUP=OUT_4

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: OUTBOUND_GROUP

Value: OUT_4

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUTMAXCHANS_4' is '10'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 7

Application: GotoIf

AppData: 0?nomax

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GotoIf

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function GROUP_COUNT(OUT_4) result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUTMAXCHANS_4' is '10'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 8

Application: GotoIf

AppData: 0?chanfull

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GotoIf

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'INTRACOMPANYROUTE' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 9

Application: GotoIf

AppData: 0?skipoutcid

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GotoIf

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: db.c:376 db_get_common: Unable to find key '4/dialopts' in family 'TRUNK'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB_EXISTS(TRUNK/4/dialopts) result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DB_RESULT' is 'dontcare'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'TRUNK_OPTIONS' is 'Tt'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(0?dontcare:Tt) result is 'Tt'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 10

Application: Set

AppData: DIAL_TRUNK_OPTIONS=Tt

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DIAL_TRUNK_OPTIONS

Value: Tt

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Macro'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 11

Application: Macro

AppData: outbound-callerid,4

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_EXTEN

Value: s

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_CONTEXT

Value: macro-dialout-trunk

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_PRIORITY

Value: 11

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: ARG1

Value: 4

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'CALLINGPRES_SV' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'CALLINGPRES_SV' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-outbound-callerid

Extension: s

Priority: 1

Application: ExecIf

AppData: 0?Set(CALLERPRES()=)

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CALLINGPRES_SV' (from 'CALLINGPRES_SV}" != ""' len 14)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'CALLINGPRES_SV' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CALLINGPRES_SV' (from 'CALLINGPRES_SV})' len 14)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'CALLINGPRES_SV' is NULL

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-outbound-callerid

Extension: s

Priority: 2

Application: ExecIf

AppData: 0?Set(REALCALLERIDNUM=1111111111)

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: ExecIf

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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function CALLERID(number) result is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'KEEPCID' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUTKEEPCID_4' is 'off'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-outbound-callerid

Extension: s

Priority: 3

Application: GotoIf

AppData: 1?normcid

Uniqueid: 1411870599.2





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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GotoIf

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: 

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/outboundcid) result is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-outbound-callerid

Extension: s

Priority: 6

Application: Set

AppData: USEROUTCID=

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: USEROUTCID

Value: 

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: db.c:376 db_get_common: Unable to find key '1111111111/emergency_cid' in family 'DEVICE'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: func_db.c:151 function_db_read: DB: DEVICE/1111111111/emergency_cid not found in database.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(DEVICE/1111111111/emergency_cid) result is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-outbound-callerid

Extension: s

Priority: 7

Application: Set

AppData: EMERGENCYCID=

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: EMERGENCYCID

Value: 

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUTCID_4' is 'XXXXXXXXXX'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-outbound-callerid

Extension: s

Priority: 8

Application: Set

AppData: TRUNKOUTCID=XXXXXXXXXX

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: TRUNKOUTCID

Value: XXXXXXXXXX

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'EMERGENCYROUTE' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'EMERGENCYCID' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-outbound-callerid

Extension: s

Priority: 9

Application: GotoIf

AppData: 1?trunkcid

Uniqueid: 1411870599.2





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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GotoIf

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'TRUNKOUTCID' is 'XXXXXXXXXX'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN(XXXXXXXXXX) result is '10'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'TRUNKOUTCID' is 'XXXXXXXXXX'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-outbound-callerid

Extension: s

Priority: 14

Application: ExecIf

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

Uniqueid: 1411870599.2





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

Privilege: call,all

Channel: SIP/1111111111-00000002

CallerIDNum: XXXXXXXXXX

CallerIDName: 

Uniqueid: 1411870599.2

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





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: ExecIf

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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'TRUNKOUTCID' (from 'TRUNKOUTCID})' len 11)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'TRUNKOUTCID' is 'XXXXXXXXXX'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN(XXXXXXXXXX) result is '10'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'TRUNKOUTCID' (from 'TRUNKOUTCID})' len 11)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'TRUNKOUTCID' is 'XXXXXXXXXX'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'USEROUTCID' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'USEROUTCID' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-outbound-callerid

Extension: s

Priority: 15

Application: ExecIf

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

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: ExecIf

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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'USEROUTCID' (from 'USEROUTCID})' len 10)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'USEROUTCID' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'USEROUTCID' (from 'USEROUTCID})' len 10)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'USEROUTCID' is ''

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_4' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_4' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_4' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function IF(1?:) result is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-outbound-callerid

Extension: s

Priority: 16

Application: ExecIf

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

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'TRUNKCIDOVERRIDE' (from 'TRUNKCIDOVERRIDE})' len 16)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'FORCEDOUTCID_${ARG1}' (from 'FORCEDOUTCID_${ARG1}})' len 20)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}' len 4)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_4' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'FORCEDOUTCID_${ARG1}' (from 'FORCEDOUTCID_${ARG1}})' len 20)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}' len 4)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_4' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function LEN() result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'TRUNKCIDOVERRIDE' (from 'TRUNKCIDOVERRIDE}:${FORCEDOUTCID_${ARG1}})' len 16)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'FORCEDOUTCID_${ARG1}' (from 'FORCEDOUTCID_${ARG1}})' len 20)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}' len 4)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'ARG1' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_4' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function IF(1?:) result is ''

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(name) result is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-outbound-callerid

Extension: s

Priority: 17

Application: ExecIf

AppData: 0?Set(CALLERPRES()=prohib_passed_screen)

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'CALLERID(name)' (from 'CALLERID(name)}"="hidden"' len 14)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function CALLERID(name) result is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(num) result is 'XXXXXXXXXX'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-outbound-callerid:18] Set("SIP/1111111111-00000002", "CDR(outbound_cnum)=XXXXXXXXXX") in new stack

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-outbound-callerid

Extension: s

Priority: 18

Application: Set

AppData: CDR(outbound_cnum)=XXXXXXXXXX

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(name) result is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-outbound-callerid:19] Set("SIP/1111111111-00000002", "CDR(outbound_cnam)=") in new stack

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-outbound-callerid

Extension: s

Priority: 19

Application: Set

AppData: CDR(outbound_cnam)=

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: ARG1

Value: 4

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_EXTEN

Value: 79999999999

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_CONTEXT

Value: from-internal

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_PRIORITY

Value: 6

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Macro

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'PREFIX_TRUNK_4' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GosubIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 12

Application: GosubIf

AppData: 0?sub-flp-4,s,1()

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GosubIf

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DIAL_TRUNK' (from 'DIAL_TRUNK}' len 10)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'PREFIX_TRUNK_4' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DIAL_TRUNK' (from 'DIAL_TRUNK},s,1()' len 10)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUTPREFIX_4' is ''

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '79999999999'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:13] Set("SIP/1111111111-00000002", "OUTNUM=79999999999") in new stack

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 13

Application: Set

AppData: OUTNUM=79999999999

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: OUTNUM

Value: 79999999999

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'OUT_4' (from 'OUT_4}' len 5)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUT_4' is 'SIP/sip_out'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CUT(OUT_4,:,1) result is 'SIP/sip_out'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Set'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:14] Set("SIP/1111111111-00000002", "custom=SIP/sip_out") in new stack

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 14

Application: Set

AppData: custom=SIP/sip_out

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: custom

Value: SIP/sip_out

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Set

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'FORCE_CONFIRM' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/1111111111-00000002", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)") in new stack

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 15

Application: ExecIf

AppData: 0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'MOHCLASS' (from 'MOHCLASS}"!="default" & "${MOHCLASS}"!="" & "${FORCE_CONFIRM}"="" ' len 8)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'MOHCLASS' (from 'MOHCLASS}"!="" & "${FORCE_CONFIRM}"="" ' len 8)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'FORCE_CONFIRM' (from 'FORCE_CONFIRM}"="" ' len 13)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'FORCE_CONFIRM' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'MOHCLASS' (from 'MOHCLASS})${DIAL_TRUNK_OPTIONS})' len 8)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DIAL_TRUNK_OPTIONS' (from 'DIAL_TRUNK_OPTIONS})' len 18)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'FORCE_CONFIRM' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/1111111111-00000002", "0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))") in new stack

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 16

Application: ExecIf

AppData: 0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'FORCE_CONFIRM' (from 'FORCE_CONFIRM}"!="" ' len 13)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'FORCE_CONFIRM' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Macro'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:17] Macro("SIP/1111111111-00000002", "dialout-trunk-predial-hook,") in new stack

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 17

Application: Macro

AppData: dialout-trunk-predial-hook,

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_EXTEN

Value: s

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_CONTEXT

Value: macro-dialout-trunk

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_PRIORITY

Value: 17

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: ARG1

Value: 

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 2

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'MacroExit'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/1111111111-00000002", "") in new stack

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk-predial-hook

Extension: s

Priority: 1

Application: MacroExit

AppData: 

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: ARG1

Value: 4

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_EXTEN

Value: 79999999999

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_CONTEXT

Value: from-internal

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_PRIORITY

Value: 6

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: Macro

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3668 ast_str_retrieve_variable: Result of 'PREDIAL_HOOK_RET' is NULL

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 18

Application: GotoIf

AppData: 0?bypass,1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GotoIf

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: 1111111111

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/cidname) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '79999999999'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/1111111111-00000002", "1?Set(CONNECTEDLINE(num,i)=79999999999)") in new stack

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 19

Application: ExecIf

AppData: 1?Set(CONNECTEDLINE(num,i)=79999999999)

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/cidname)' len 7)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: 1111111111

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function DB(AMPUSER/1111111111/cidname) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'DIAL_NUMBER' (from 'DIAL_NUMBER})' len 11)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '79999999999'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: 1111111111

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function DB(AMPUSER/1111111111/cidname) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '1'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4715 pbx_substitute_variables_helper_full: Function CALLERID(number) result is 'XXXXXXXXXX'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'ExecIf'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/1111111111-00000002", "1?Set(CONNECTEDLINE(name,i)=CID:XXXXXXXXXX)") in new stack

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 20

Application: ExecIf

AppData: 1?Set(CONNECTEDLINE(name,i)=CID:XXXXXXXXXX)

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: ExecIf

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: pbx.c:4482 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/cidname)' len 7)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'AMPUSER' is '1111111111'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DB_RESULT

Value: 1111111111

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function DB(AMPUSER/1111111111/cidname) result is '1111111111'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4574 ast_str_substitute_variables_full: Expression result is '1'

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

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4516 ast_str_substitute_variables_full: Function CALLERID(number) result is 'XXXXXXXXXX'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'custom' is 'SIP/sip_out'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is '0'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'GotoIf'

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

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 21

Application: GotoIf

AppData: 0?customtrunk

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:11836 pbx_builtin_gotoif: Not taking any branch

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: app_macro.c:434 _macro_exec: Executed application: GotoIf

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 1

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '4'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUT_4' is 'SIP/sip_out'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'OUTNUM' is '79999999999'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'TRUNK_RING_TIMER' is '300'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:3671 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Dial'

localhost*CLI> 
    -- Executing [s@macro-dialout-trunk:22] Dial("SIP/1111111111-00000002", "SIP/sip_out/79999999999,300,Tt") in new stack

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: macro-dialout-trunk

Extension: s

Priority: 22

Application: Dial

AppData: SIP/sip_out/79999999999,300,Tt

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DIALSTATUS

Value: 

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DIALEDPEERNUMBER

Value: 

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DIALEDPEERNAME

Value: 

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: ANSWEREDTIME

Value: 

Uniqueid: 1411870599.2





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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DIALEDTIME

Value: 

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:29752 sip_request_call: Asked to create a SIP channel with formats: (ulaw)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:8638 sip_alloc: Allocating new SIP dialog for 3f8de6f96bafa2351ca279bd2842b222@[::1]:5060 - INVITE (No RTP)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0xb74c420c'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: res_rtp_asterisk.c:2140 ast_rtp_new: Allocated port 11632 for RTP instance '0xb74c420c'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.33' into...

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0xb74c420c' is setup and ready to go

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: res_rtp_asterisk.c:4280 ast_rtp_prop_set: Setup RTCP on RTP instance '0xb74c420c'

localhost*CLI> 
  == Using SIP RTP TOS bits 184

localhost*CLI> 
  == Using SIP RTP CoS mark 5

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:5586 do_setnat: Setting NAT on RTP to On

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:8427 change_callid_pvt: SIP call-id changed from '3f8de6f96bafa2351ca279bd2842b222@[::1]:5060' to '3f8de6f96bafa2351ca279bd2842b222@sipnet.ru'

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[3965][C-00000001]: chan_sip.c:3881 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.1.33:5060

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:5586 do_setnat: Setting NAT on RTP to On

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:8427 change_callid_pvt: SIP call-id changed from '3f8de6f96bafa2351ca279bd2842b222@sipnet.ru' to '31c02e0866e468474ef24b897a0e5624@sipnet.ru'

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

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

Privilege: call,all

Channel: SIP/sip_out-00000003

ChannelState: 0

ChannelStateDesc: Down

CallerIDNum: 

CallerIDName: 

AccountCode: 

Exten: 

Context: from-trunk-sip-sip_out

Uniqueid: 1411870599.3





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:7813 sip_new: *** Our native formats are (g729) 

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:7814 sip_new: *** Joint capabilities are (nothing) 

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:7815 sip_new: *** Our capabilities are (alaw|g729) 

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:7816 sip_new: *** AST_CODEC_CHOOSE formats are g729 

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:7818 sip_new: *** Our preferred formats from the incoming channel are (ulaw) 

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:7844 sip_new: This channel will not be able to handle video.

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

Privilege: dialplan,all

Channel: SIP/sip_out-00000003

Variable: SIPCALLID

Value: 31c02e0866e468474ef24b897a0e5624@sipnet.ru

Uniqueid: 1411870599.3





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: ChannelUpdate

Privilege: system,all

Channel: SIP/sip_out-00000003

Uniqueid: 1411870599.3

Channeltype: SIP

SIPcallid: 31c02e0866e468474ef24b897a0e5624@sipnet.ru

SIPfullcontact: 





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: ChannelUpdate

Privilege: system,all

Channel: SIP/sip_out-00000003

Channeltype: SIP

SIPcallid: 31c02e0866e468474ef24b897a0e5624@sipnet.ru

SIPfullcontact: 

Peername: sip_out





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: channel_internal_api.c:882 ast_channel_callid_set: Channel Call ID changing from [C-00000001] to [C-00000001]

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

Privilege: dialplan,all

Channel: SIP/sip_out-00000003

Variable: DIALEDPEERNUMBER

Value: sip_out/79999999999

Uniqueid: 1411870599.3





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable REC_POLICY_MODE from SIP/1111111111-00000002 to SIP/sip_out-00000003.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable CALLFILENAME from SIP/1111111111-00000002 to SIP/sip_out-00000003.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable FROMEXTEN from SIP/1111111111-00000002 to SIP/sip_out-00000003.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable TIMESTR from SIP/1111111111-00000002 to SIP/sip_out-00000003.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable YEAR from SIP/1111111111-00000002 to SIP/sip_out-00000003.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable MONTH from SIP/1111111111-00000002 to SIP/sip_out-00000003.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable DAY from SIP/1111111111-00000002 to SIP/sip_out-00000003.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable REC_STATUS from SIP/1111111111-00000002 to SIP/sip_out-00000003.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable MON_FMT from SIP/1111111111-00000002 to SIP/sip_out-00000003.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: channel.c:6541 ast_channel_inherit_variables: Inheriting variable NODEST from SIP/1111111111-00000002 to SIP/sip_out-00000003.

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: channel.c:6549 ast_channel_inherit_variables: Inheriting variable DIAL_OPTIONS from SIP/1111111111-00000002 to SIP/sip_out-00000003.

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

Privilege: call,all

Channel: SIP/sip_out-00000003

CallerIDNum: 79999999999

CallerIDName: CID:XXXXXXXXXX

Uniqueid: 1411870599.3

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





localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:6207 sip_call: Outgoing Call for 79999999999

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:6531 update_call_counter: Updating call counter for outgoing call

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:13088 add_sdp: ** Our capability: (alaw|g729) Video flag: False Text flag: False

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:13089 add_sdp: ** Our prefcodec: (ulaw) 

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:13225 add_sdp: -- Done with adding codecs to SDP

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:13420 add_sdp: Done building SDP. Settling with this capability: (alaw|g729)

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: chan_sip.c:3367 initialize_initreq: Initializing initreq for method INVITE - callid 31c02e0866e468474ef24b897a0e5624@sipnet.ru

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: 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:16:39] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Dial

Privilege: call,all

SubEvent: Begin

Channel: SIP/1111111111-00000002

Destination: SIP/sip_out-00000003

CallerIDNum: XXXXXXXXXX

CallerIDName: <unknown>

ConnectedLineNum: 79999999999

ConnectedLineName: CID:XXXXXXXXXX

UniqueID: 1411870599.2

DestUniqueID: 1411870599.3

Dialstring: sip_out/79999999999





localhost*CLI> 
    -- Called SIP/sip_out/79999999999

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: channel.c:5405 set_format: Set channel SIP/sip_out-00000003 to read format slin

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: channel.c:5405 set_format: Set channel SIP/1111111111-00000002 to write format slin

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: channel.c:5405 set_format: Set channel SIP/1111111111-00000002 to read format slin

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[3965][C-00000001]: channel.c:5405 set_format: Set channel SIP/sip_out-00000003 to write format slin

localhost*CLI> 
[2014-09-28 10:16:39] DEBUG[2392]: manager.c:5254 process_message: Running action 'Command'

localhost*CLI> 
[2014-09-28 10:16:40] DEBUG[2033]: chan_sip.c:3988 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #440)) 
[2014-09-28 10:16:40] 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:16:40] DEBUG[2392]: manager.c:5254 process_message: Running action 'Command'

localhost*CLI> 
[2014-09-28 10:16:40] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 31c02e0866e468474ef24b897a0e5624@sipnet.ru (Checking To) --From tag as58e45b75 --To-tag   
[2014-09-28 10:16:40] DEBUG[2033][C-00000001]: chan_sip.c:4457 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '31c02e0866e468474ef24b897a0e5624@sipnet.ru' Request 102: Found
[2014-09-28 10:16:40] DEBUG[2033][C-00000001]: chan_sip.c:22624 handle_response_invite: SIP response 100 to standard invite
[2014-09-28 10:16:40] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 31c02e0866e468474ef24b897a0e5624@sipnet.ru (Checking To) --From tag as58e45b75 --To-tag BCF2E5C5  
[2014-09-28 10:16:40] DEBUG[2033][C-00000001]: chan_sip.c:4378 __sip_ack: Acked pending invite 102
[2014-09-28 10:16:40] DEBUG[2033][C-00000001]: chan_sip.c:4416 __sip_ack: Stopping retransmission on '31c02e0866e468474ef24b897a0e5624@sipnet.ru' of Request 102: Match Found
[2014-09-28 10:16:40] DEBUG[2033][C-00000001]: chan_sip.c:22624 handle_response_invite: SIP response 401 to standard invite
[2014-09-28 10:16:40] DEBUG[2033][C-00000001]: chan_sip.c:3724 __sip_xmit: Trying to put 'ACK sip:791' onto UDP socket destined for 212.53.40.40:5060
[2014-09-28 10:16:40] DEBUG[2033][C-00000001]: chan_sip.c:21736 do_proxy_auth: Auth attempt 1 on INVITE
[2014-09-28 10:16:40] DEBUG[2033][C-00000001]: chan_sip.c:13088 add_sdp: ** Our capability: (alaw|g729) Video flag: False Text flag: False
[2014-09-28 10:16:40] DEBUG[2033][C-00000001]: chan_sip.c:13089 add_sdp: ** Our prefcodec: (ulaw) 
[2014-09-28 10:16:40] DEBUG[2033][C-00000001]: chan_sip.c:13225 add_sdp: -- Done with adding codecs to SDP
[2014-09-28 10:16:40] DEBUG[2033][C-00000001]: chan_sip.c:13420 add_sdp: Done building SDP. Settling with this capability: (alaw|g729)
[2014-09-28 10:16:40] DEBUG[2033][C-00000001]: 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:16:40] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 31c02e0866e468474ef24b897a0e5624@sipnet.ru (Checking To) --From tag as58e45b75 --To-tag BCF2E5C5  
[2014-09-28 10:16:40] DEBUG[2033][C-00000001]: chan_sip.c:4416 __sip_ack: Stopping retransmission on '31c02e0866e468474ef24b897a0e5624@sipnet.ru' of Request 102: Match Not Found
[2014-09-28 10:16:40] DEBUG[2033][C-00000001]: chan_sip.c:3724 __sip_xmit: Trying to put 'ACK sip:791' onto UDP socket destined for 212.53.40.40:5060

localhost*CLI> 
[2014-09-28 10:16:40] DEBUG[2033]: chan_sip.c:3988 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #442)) 

localhost*CLI> 
[2014-09-28 10:16:40] 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:16:41] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 31c02e0866e468474ef24b897a0e5624@sipnet.ru (Checking To) --From tag as58e45b75 --To-tag   

localhost*CLI> 
[2014-09-28 10:16:41] DEBUG[2033][C-00000001]: chan_sip.c:4457 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '31c02e0866e468474ef24b897a0e5624@sipnet.ru' Request 103: Found

localhost*CLI> 
[2014-09-28 10:16:41] DEBUG[2033][C-00000001]: chan_sip.c:22624 handle_response_invite: SIP response 100 to standard invite

localhost*CLI> 
[2014-09-28 10:16:41] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 31c02e0866e468474ef24b897a0e5624@sipnet.ru (Checking To) --From tag as58e45b75 --To-tag   

localhost*CLI> 
[2014-09-28 10:16:41] DEBUG[2033][C-00000001]: chan_sip.c:4457 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '31c02e0866e468474ef24b897a0e5624@sipnet.ru' Request 103: Found

localhost*CLI> 
[2014-09-28 10:16:41] DEBUG[2033][C-00000001]: chan_sip.c:22624 handle_response_invite: SIP response 100 to standard invite

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 31c02e0866e468474ef24b897a0e5624@sipnet.ru (Checking To) --From tag as58e45b75 --To-tag B23B8799-628988-D5673946_kmbdctn-EF93  

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:4457 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '31c02e0866e468474ef24b897a0e5624@sipnet.ru' Request 103: Found

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:22624 handle_response_invite: SIP response 180 to standard invite

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:16175 build_route: build_route: Record-Route hop: <sip:337323-192.168.40.75.dialog.cgatepro;lr>

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:16175 build_route: build_route: Record-Route hop: <sip:192.168.40.75:5060;lr>

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:16175 build_route: build_route: Record-Route hop: <sip:212.53.40.40:5060;lr>

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Newstate

Privilege: call,all

Channel: SIP/sip_out-00000003

ChannelState: 5

ChannelStateDesc: Ringing

CallerIDNum: 79999999999

CallerIDName: CID:XXXXXXXXXX

ConnectedLineNum: XXXXXXXXXX

ConnectedLineName: 

Uniqueid: 1411870599.3





localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:9926 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:9926 process_sdp: Processing session-level SDP o=CGPLeg628988 1744802818 872401410 IN IP4 212.53.40.75... OK.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:9926 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '212.53.40.75' into...

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '212.53.40.75' and port ''.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:9926 process_sdp: Processing session-level SDP c=IN IP4 212.53.40.75... OK.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:9926 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 18 based on m type on 0xb6428d70

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0xb6428d70

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '212.53.40.75' into...

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '212.53.40.75' and port ''.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP c=IN IP4 212.53.40.75... OK.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=ice-pwd:B7FC0051D58A1B5F72D2B9A2... OK.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=ice-ufrag:pf0131018... OK.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:10379 process_sdp: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED OR FAILED.

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: res_rtp_asterisk.c:4336 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb74c420c'

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 18 from 0xb6428d70 to 0xb74c43b8

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0xb6428d70 to 0xb74c43b8

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: res_rtp_asterisk.c:4246 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0xb74c420c'

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:10650 process_sdp: We're settling with these formats: (g729)

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[2033][C-00000001]: chan_sip.c:10657 process_sdp: We have an owner, now see if we need to change this call

localhost*CLI> 
    -- SIP/sip_out-00000003 is ringing

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: rtp_engine.c:1821 ast_rtp_instance_early_bridge: Setting early bridge SDP of 'SIP/1111111111-00000002' with that of 'SIP/sip_out-00000003'

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: 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> 
    -- SIP/sip_out-00000003 is making progress passing it to SIP/1111111111-00000002

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: rtp_engine.c:1821 ast_rtp_instance_early_bridge: Setting early bridge SDP of 'SIP/1111111111-00000002' with that of 'SIP/sip_out-00000003'
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: chan_sip.c:13534 transmit_response_with_sdp: Setting framing from config on incoming call
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: chan_sip.c:13088 add_sdp: ** Our capability: (gsm|ulaw|alaw) Video flag: True Text flag: True

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: chan_sip.c:13089 add_sdp: ** Our prefcodec: (nothing) 
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: chan_sip.c:13225 add_sdp: -- Done with adding codecs to SDP

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: chan_sip.c:13420 add_sdp: Done building SDP. Settling with this capability: (gsm|ulaw|alaw)

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: chan_sip.c:3724 __sip_xmit: Trying to put 'SIP/2.0 183' onto UDP socket destined for 192.168.1.41:5060

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[1989]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - sip_out

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[1989]: chan_sip.c:29647 sip_devicestate: Checking device state for peer sip_out

localhost*CLI> 
[2014-09-28 10:16:48] 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:16:48] DEBUG[1989]: devicestate.c:442 devstate_event: device 'SIP/sip_out' state '1'

localhost*CLI> 
[2014-09-28 10:16:48] 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:16:48] DEBUG[3965][C-00000001]: res_rtp_asterisk.c:3914 ast_rtp_read: 0xb74c9160 -- Probation learning mode pass with source address 212.53.40.40:25052

localhost*CLI> 
       > 0xb74c9160 -- Probation passed - setting RTP source address to 212.53.40.40:25052

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: res_rtp_asterisk.c:4336 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb74c420c'

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: res_rtp_asterisk.c:3040 ast_rtp_write: Ooh, format changed from unknown to ulaw

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: res_rtp_asterisk.c:3075 ast_rtp_write: Created smoother: format: ulaw ms: 20 len: 160

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: res_rtp_asterisk.c:2933 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0xb740f0cc'

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: res_rtp_asterisk.c:3914 ast_rtp_read: 0xb74c9160 -- Probation learning mode pass with source address 212.53.40.40:25052

localhost*CLI> 
       > 0xb74c9160 -- Probation passed - setting RTP source address to 212.53.40.40:25052

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: res_rtp_asterisk.c:3914 ast_rtp_read: 0xb744d590 -- Probation learning mode pass with source address 192.168.1.41:8000
       > 0xb744d590 -- Probation passed - setting RTP source address to 192.168.1.41:8000
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: res_rtp_asterisk.c:3040 ast_rtp_write: Ooh, format changed from unknown to g729

localhost*CLI> 
[2014-09-28 10:16:48] DEBUG[3965][C-00000001]: res_rtp_asterisk.c:3075 ast_rtp_write: Created smoother: format: g729 ms: 20 len: 20

localhost*CLI> 
[2014-09-28 10:16:52] DEBUG[3965][C-00000001]: res_rtp_asterisk.c:3517 ast_rtcp_read: Got RTCP report of 76 bytes
[2014-09-28 10:16:52] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: RTCPReceived

Privilege: reporting,all

From: 192.168.1.41:8001

PT: 200(Sender Report)

ReceptionReports: 1

SenderSSRC: 0

FractionLost: 0

PacketsLost: 0

HighestSequence: 51331

SequenceNumberCycles: 0

IAJitter: 0

LastSR: 0.0000000000

DLSR: 0.0000(sec)





localhost*CLI> 
[2014-09-28 10:16:53] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: RTCPSent

Privilege: reporting,all

To: 212.53.40.40:25053

OurSSRC: 308917329

SentNTP: 1411870613.2449321984

SentRTP: 868283104

SentPackets: 248

SentOctets: 4960

ReportBlock:

FractionLost: 0

CumulativeLoss: 0

IAJitter: 0.0018

TheirLastSR: 0

DLSR: 65527.9010 (sec)




[2014-09-28 10:16:53] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: RTCPSent

Privilege: reporting,all

To: 192.168.1.41:8001

OurSSRC: 38673905

SentNTP: 1411870613.2449723392

SentRTP: 818316680

SentPackets: 250

SentOctets: 40000

ReportBlock:

FractionLost: 0

CumulativeLoss: 0

IAJitter: 0.0002

TheirLastSR: 3994192838

DLSR: 1.5060 (sec)





localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: res_rtp_asterisk.c:3517 ast_rtcp_read: Got RTCP report of 76 bytes
[2014-09-28 10:16:56] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: RTCPReceived

Privilege: reporting,all

From: 192.168.1.41:8001

PT: 200(Sender Report)

ReceptionReports: 1

SenderSSRC: 0

FractionLost: 0

PacketsLost: 0

HighestSequence: 51553

SequenceNumberCycles: 0

IAJitter: 0

LastSR: 0.0000000000

DLSR: 0.0000(sec)





localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: ZTZjOWM3MDNiMjEwOGEwYTY5ZWZkNzQ1YzQwMzk3ZjA. (Checking From) --From tag 99382d3d --To-tag   
[2014-09-28 10:16:56] DEBUG[2033]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.33' into...
[2014-09-28 10:16:56] DEBUG[2033]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.
[2014-09-28 10:16:56] DEBUG[2033]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.33' into...
[2014-09-28 10:16:56] DEBUG[2033]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.33' and port ''.
[2014-09-28 10:16:56] DEBUG[2033][C-00000001]: chan_sip.c:28202 handle_incoming: **** Received CANCEL (14) - Command in SIP CANCEL
[2014-09-28 10:16:56] DEBUG[2033][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.1.41:5060' into...
[2014-09-28 10:16:56] DEBUG[2033][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.1.41' and port '5060'.
[2014-09-28 10:16:56] DEBUG[2033][C-00000001]: chan_sip.c:3380 sip_alreadygone: Setting SIP_ALREADYGONE on dialog ZTZjOWM3MDNiMjEwOGEwYTY5ZWZkNzQ1YzQwMzk3ZjA.
[2014-09-28 10:16:56] DEBUG[2033][C-00000001]: chan_sip.c:6531 update_call_counter: Updating call counter for incoming call
[2014-09-28 10:16:56] DEBUG[2033][C-00000001]: res_rtp_asterisk.c:4336 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb740f0cc'
[2014-09-28 10:16:56] DEBUG[2033][C-00000001]: chan_sip.c:3724 __sip_xmit: Trying to put 'SIP/2.0 487' onto UDP socket destined for 192.168.1.41:5060
[2014-09-28 10:16:56] DEBUG[2033][C-00000001]: chan_sip.c:3724 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.41:5060
[2014-09-28 10:16:56] DEBUG[1989]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 1111111111
[2014-09-28 10:16:56] DEBUG[1989]: chan_sip.c:29647 sip_devicestate: Checking device state for peer 1111111111
[2014-09-28 10:16:56] DEBUG[1989]: devicestate.c:467 do_state_change: Changing state for SIP/1111111111 - state 1 (Not in use)
[2014-09-28 10:16:56] DEBUG[1989]: devicestate.c:442 devstate_event: device 'SIP/1111111111' state '1'
[2014-09-28 10:16:56] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: HangupRequest

Privilege: call,all

Channel: SIP/1111111111-00000002

Uniqueid: 1411870599.2




[2014-09-28 10:16:56] 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.
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: channel.c:2840 ast_hangup: Hanging up channel 'SIP/sip_out-00000003'

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: chan_sip.c:6914 sip_hangup: Hangup call SIP/sip_out-00000003, SIP callid 31c02e0866e468474ef24b897a0e5624@sipnet.ru
[2014-09-28 10:16:56] DEBUG[1991]: devicestate.c:340 _ast_device_state: Checking if I can find provider for "Custom" - number: DND1111111111

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

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

localhost*CLI> 
[2014-09-28 10:16:56] 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:16:56] 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:16:56] DEBUG[1981]: res_odbc.c:1058 odbc_release_obj2: odbc_release_obj2(0x8c67a1c) called (obj->txf = (nil))

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: chan_sip.c:6933 sip_hangup: Hanging up channel in state Ringing (not UP)

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: res_rtp_asterisk.c:4336 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb74c420c'

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: chan_sip.c:4457 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '31c02e0866e468474ef24b897a0e5624@sipnet.ru' Request 103: Found

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: chan_sip.c:3724 __sip_xmit: Trying to put 'CANCEL sip:' onto UDP socket destined for 212.53.40.40:5060

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Hangup

Privilege: call,all

Channel: SIP/sip_out-00000003

Uniqueid: 1411870599.3

CallerIDNum: 79999999999

CallerIDName: CID:XXXXXXXXXX

ConnectedLineNum: XXXXXXXXXX

ConnectedLineName: <unknown>

AccountCode: 

Cause: 16

Cause-txt: Normal Clearing





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

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[1989]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - sip_out

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[1989]: chan_sip.c:29647 sip_devicestate: Checking device state for peer sip_out

localhost*CLI> 
[2014-09-28 10:16:56] 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:16:56] DEBUG[1989]: devicestate.c:442 devstate_event: device 'SIP/sip_out' state '1'

localhost*CLI> 
[2014-09-28 10:16:56] 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:16:56] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: VarSet

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: DIALSTATUS

Value: CANCEL

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Dial

Privilege: call,all

SubEvent: End

Channel: SIP/1111111111-00000002

UniqueID: 1411870599.2

DialStatus: CANCEL





localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: app_dial.c:3102 dial_exec_full: Exiting with DIALSTATUS=CANCEL.

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: app_macro.c:428 _macro_exec: Spawn extension (macro-dialout-trunk,s,22) exited non-zero on 'SIP/1111111111-00000002' in macro 'dialout-trunk'

localhost*CLI> 
  == Spawn extension (macro-dialout-trunk, s, 22) exited non-zero on 'SIP/1111111111-00000002' in macro 'dialout-trunk'

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Variable: MACRO_DEPTH

Value: 0

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: pbx.c:6572 __ast_pbx_run: Spawn extension (from-internal,79999999999,6) exited non-zero on 'SIP/1111111111-00000002'

localhost*CLI> 
  == Spawn extension (from-internal, 79999999999, 6) exited non-zero on 'SIP/1111111111-00000002'

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: channel.c:2661 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/1111111111-00000002'

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: SoftHangupRequest

Privilege: call,all

Channel: SIP/1111111111-00000002

Uniqueid: 1411870599.2

Cause: 16





localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: channel.c:2661 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/1111111111-00000002'

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: pbx.c:4883 pbx_extension_helper: Launching 'Hangup'

localhost*CLI> 
    -- Executing [h@from-internal:1] Hangup("SIP/1111111111-00000002", "") in new stack

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

Privilege: dialplan,all

Channel: SIP/1111111111-00000002

Context: from-internal

Extension: h

Priority: 1

Application: Hangup

AppData: 

Uniqueid: 1411870599.2





localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: channel.c:2661 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/1111111111-00000002'

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: pbx.c:6088 ast_pbx_h_exten_run: Spawn extension (from-internal,h,1) exited non-zero on 'SIP/1111111111-00000002'

localhost*CLI> 
  == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/1111111111-00000002'

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

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: channel.c:2840 ast_hangup: Hanging up channel 'SIP/1111111111-00000002'

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: chan_sip.c:6914 sip_hangup: Hangup call SIP/1111111111-00000002, SIP callid ZTZjOWM3MDNiMjEwOGEwYTY5ZWZkNzQ1YzQwMzk3ZjA.

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: res_rtp_asterisk.c:4336 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb740f0cc'

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[2392]: manager.c:4835 match_filter: Examining event:
Event: Hangup

Privilege: call,all

Channel: SIP/1111111111-00000002

Uniqueid: 1411870599.2

CallerIDNum: XXXXXXXXXX

CallerIDName: <unknown>

ConnectedLineNum: 79999999999

ConnectedLineName: CID:XXXXXXXXXX

AccountCode: 

Cause: 16

Cause-txt: Normal Clearing





localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[3965][C-00000001]: res_odbc.c:1058 odbc_release_obj2: odbc_release_obj2(0x8c67a1c) called (obj->txf = (nil))

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

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

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[1989]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 1111111111

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[1989]: chan_sip.c:29647 sip_devicestate: Checking device state for peer 1111111111

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[1989]: devicestate.c:467 do_state_change: Changing state for SIP/1111111111 - state 1 (Not in use)

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[1989]: devicestate.c:442 devstate_event: device 'SIP/1111111111' state '1'

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

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

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

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

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

localhost*CLI> 
[2014-09-28 10:16:56] 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:16:56] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: ZTZjOWM3MDNiMjEwOGEwYTY5ZWZkNzQ1YzQwMzk3ZjA. (Checking From) --From tag 99382d3d --To-tag as7349a631  
[2014-09-28 10:16:56] DEBUG[2033][C-00000001]: chan_sip.c:28202 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[2014-09-28 10:16:56] DEBUG[2033][C-00000001]: chan_sip.c:4416 __sip_ack: Stopping retransmission on 'ZTZjOWM3MDNiMjEwOGEwYTY5ZWZkNzQ1YzQwMzk3ZjA.' of Response 2: Match Found

localhost*CLI> 
[2014-09-28 10:16:56] DEBUG[2033]: chan_sip.c:6679 sip_destroy: Destroying SIP dialog ZTZjOWM3MDNiMjEwOGEwYTY5ZWZkNzQ1YzQwMzk3ZjA.
[2014-09-28 10:16:56] DEBUG[2033]: rtp_engine.c:226 instance_destructor: Destroyed RTP instance '0xb740f0cc'

localhost*CLI> 
[2014-09-28 10:16:57] DEBUG[2033]: chan_sip.c:3988 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #449)) 

localhost*CLI> 
[2014-09-28 10:16:57] DEBUG[2033]: chan_sip.c:3724 __sip_xmit: Trying to put 'CANCEL sip:' onto UDP socket destined for 212.53.40.40:5060

localhost*CLI> 
[2014-09-28 10:16:57] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 31c02e0866e468474ef24b897a0e5624@sipnet.ru (Checking To) --From tag as58e45b75 --To-tag B23B8799-628988-D5673946_kmbdctn-EF93  
[2014-09-28 10:16:57] DEBUG[2033][C-00000001]: chan_sip.c:4378 __sip_ack: Acked pending invite 103
[2014-09-28 10:16:57] DEBUG[2033][C-00000001]: chan_sip.c:4416 __sip_ack: Stopping retransmission on '31c02e0866e468474ef24b897a0e5624@sipnet.ru' of Request 103: Match Found
[2014-09-28 10:16:57] DEBUG[2033][C-00000001]: chan_sip.c:22624 handle_response_invite: SIP response 487 to standard invite
[2014-09-28 10:16:57] DEBUG[2033][C-00000001]: 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:16:57] DEBUG[2033][C-00000001]: chan_sip.c:6531 update_call_counter: Updating call counter for outgoing call

localhost*CLI> 
[2014-09-28 10:16:57] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 31c02e0866e468474ef24b897a0e5624@sipnet.ru (Checking To) --From tag as58e45b75 --To-tag B23B8799-628988-D5673946_kmbdctn-EF93  
[2014-09-28 10:16:57] DEBUG[2033][C-00000001]: chan_sip.c:4416 __sip_ack: Stopping retransmission on '31c02e0866e468474ef24b897a0e5624@sipnet.ru' of Request 103: Match Found

localhost*CLI> 
[2014-09-28 10:16:58] DEBUG[2033]: chan_sip.c:9035 find_call: = Looking for  Call ID: 31c02e0866e468474ef24b897a0e5624@sipnet.ru (Checking To) --From tag as58e45b75 --To-tag B23B8799-628988-D5673946_kmbdctn-EF93  

localhost*CLI> 
[2014-09-28 10:16:58] DEBUG[2033][C-00000001]: chan_sip.c:4416 __sip_ack: Stopping retransmission on '31c02e0866e468474ef24b897a0e5624@sipnet.ru' of Request 103: Match Not Found

localhost*CLI> 

