[2016-05-18 17:13:28] Asterisk 13.9.1 built by root @ raspbx on a armv7l running Linux on 2016-05-18 13:49:53 UTC
[2016-05-18 17:13:32] DEBUG[2899] threadpool.c: Worker thread idle timeout reached. Dying.
[2016-05-18 17:13:32] DEBUG[2893] threadpool.c: Destroying worker thread 4
[2016-05-18 17:13:32] DEBUG[2979] threadpool.c: Worker thread idle timeout reached. Dying.
[2016-05-18 17:13:32] DEBUG[2893] threadpool.c: Destroying worker thread 14
[2016-05-18 17:13:32] DEBUG[2896] threadpool.c: Worker thread idle timeout reached. Dying.
[2016-05-18 17:13:32] DEBUG[2978] threadpool.c: Worker thread idle timeout reached. Dying.
[2016-05-18 17:13:32] DEBUG[2893] threadpool.c: Destroying worker thread 2
[2016-05-18 17:13:32] DEBUG[2893] threadpool.c: Destroying worker thread 13
[2016-05-18 17:13:32] DEBUG[2897] threadpool.c: Worker thread idle timeout reached. Dying.
[2016-05-18 17:13:32] DEBUG[2893] threadpool.c: Destroying worker thread 3
[2016-05-18 17:13:32] DEBUG[2976] threadpool.c: Worker thread idle timeout reached. Dying.
[2016-05-18 17:13:32] DEBUG[2893] threadpool.c: Destroying worker thread 12
[2016-05-18 17:13:32] DEBUG[2895] threadpool.c: Worker thread idle timeout reached. Dying.
[2016-05-18 17:13:32] DEBUG[2893] threadpool.c: Destroying worker thread 1
[2016-05-18 17:13:32] DEBUG[2894] threadpool.c: Worker thread idle timeout reached. Dying.
[2016-05-18 17:13:32] DEBUG[2893] threadpool.c: Destroying worker thread 0
[2016-05-18 17:13:39] DEBUG[2963] res_pjsip_registrar_expire.c: Woke up at 1463584419  Interval: 30
[2016-05-18 17:13:39] DEBUG[2963] res_pjsip_registrar_expire.c: Expiring 0 contacts

[2016-05-18 17:13:44] ERROR[2932] res_pjsip.c: Unable to create outbound OPTIONS request to endpoint SFR_Lys_PJ
[2016-05-18 17:13:44] ERROR[2932] res_pjsip/pjsip_options.c: Unable to create request to qualify contact sip:+3399XXXXXXXXXX@ims.mnc010.mcc208.3gppnetwork.org
[2016-05-18 17:14:01] DEBUG[3033] manager.c: Running action 'Login'
[2016-05-18 17:14:02] DEBUG[2934] threadpool.c: Worker thread idle timeout reached. Dying.
[2016-05-18 17:14:02] DEBUG[2935] threadpool.c: Worker thread idle timeout reached. Dying.
[2016-05-18 17:14:02] DEBUG[2930] threadpool.c: Destroying worker thread 7
[2016-05-18 17:14:02] DEBUG[2930] threadpool.c: Destroying worker thread 8
[2016-05-18 17:14:02] DEBUG[2936] threadpool.c: Worker thread idle timeout reached. Dying.
[2016-05-18 17:14:02] DEBUG[2930] threadpool.c: Destroying worker thread 9
[2016-05-18 17:14:05] DEBUG[2938] threadpool.c: Worker thread idle timeout reached. Dying.
[2016-05-18 17:14:05] DEBUG[2892] threadpool.c: Destroying worker thread 11
[2016-05-18 17:14:08] DEBUG[2960] chan_sip.c: Allocating new SIP dialog for 187483a975f3474b2064451a6c566202@127.0.1.1:5061 - OPTIONS (No RTP)
[2016-05-18 17:14:08] DEBUG[2960] acl.c: For destination '192.168.1.93', our source address is '192.168.1.34'.
[2016-05-18 17:14:08] DEBUG[2960] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.34:5061
[2016-05-18 17:14:08] DEBUG[2960] chan_sip.c: SIP call-id changed from '187483a975f3474b2064451a6c566202@127.0.1.1:5061' to '133daced3d5fab4759cf3e2977909e03@192.168.1.34:5061'
[2016-05-18 17:14:08] DEBUG[2960] chan_sip.c: Initializing initreq for method OPTIONS - callid 133daced3d5fab4759cf3e2977909e03@192.168.1.34:5061
[2016-05-18 17:14:08] DEBUG[2960] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.1.93:5061
[2016-05-18 17:14:08] DEBUG[2960] chan_sip.c: Stopping retransmission on '133daced3d5fab4759cf3e2977909e03@192.168.1.34:5061' of Request 102: Match Found
[2016-05-18 17:14:08] DEBUG[2960] chan_sip.c: Destroying SIP dialog 133daced3d5fab4759cf3e2977909e03@192.168.1.34:5061
[2016-05-18 17:14:08] DEBUG[2960] chan_sip.c: Allocating new SIP dialog for 70b38370352d4c243da4792c531c31a8@127.0.1.1:5061 - OPTIONS (No RTP)
[2016-05-18 17:14:08] DEBUG[2960] acl.c: For destination '192.168.1.37', our source address is '192.168.1.34'.
[2016-05-18 17:14:08] DEBUG[2960] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.34:5061
[2016-05-18 17:14:08] DEBUG[2960] chan_sip.c: SIP call-id changed from '70b38370352d4c243da4792c531c31a8@127.0.1.1:5061' to '18b01b2f42669c35553bd71f5a0a8143@192.168.1.34:5061'
[2016-05-18 17:14:08] DEBUG[2960] chan_sip.c: Initializing initreq for method OPTIONS - callid 18b01b2f42669c35553bd71f5a0a8143@192.168.1.34:5061
[2016-05-18 17:14:08] DEBUG[2960] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.1.37:5061
[2016-05-18 17:14:08] DEBUG[2960] chan_sip.c: Stopping retransmission on '18b01b2f42669c35553bd71f5a0a8143@192.168.1.34:5061' of Request 102: Match Found
[2016-05-18 17:14:08] DEBUG[2960] chan_sip.c: Destroying SIP dialog 18b01b2f42669c35553bd71f5a0a8143@192.168.1.34:5061
[2016-05-18 17:14:09] DEBUG[2960] chan_sip.c: Allocating new SIP dialog for 49de6b8f4e9a0927287cee8f2e059b2a@127.0.1.1:5061 - OPTIONS (No RTP)
[2016-05-18 17:14:09] DEBUG[2960] acl.c: For destination '192.168.1.37', our source address is '192.168.1.34'.
[2016-05-18 17:14:09] DEBUG[2960] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.34:5061
[2016-05-18 17:14:09] DEBUG[2960] chan_sip.c: SIP call-id changed from '49de6b8f4e9a0927287cee8f2e059b2a@127.0.1.1:5061' to '3a3ad7ef4eee104360e729a562c612f6@192.168.1.34:5061'
[2016-05-18 17:14:09] DEBUG[2960] chan_sip.c: Initializing initreq for method OPTIONS - callid 3a3ad7ef4eee104360e729a562c612f6@192.168.1.34:5061
[2016-05-18 17:14:09] DEBUG[2960] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.1.37:5061
[2016-05-18 17:14:09] DEBUG[2960] chan_sip.c: Stopping retransmission on '3a3ad7ef4eee104360e729a562c612f6@192.168.1.34:5061' of Request 102: Match Found
[2016-05-18 17:14:09] DEBUG[2960] chan_sip.c: Destroying SIP dialog 3a3ad7ef4eee104360e729a562c612f6@192.168.1.34:5061
[2016-05-18 17:14:09] DEBUG[2937] threadpool.c: Worker thread idle timeout reached. Dying.
[2016-05-18 17:14:09] DEBUG[2963] res_pjsip_registrar_expire.c: Woke up at 1463584449  Interval: 30
[2016-05-18 17:14:09] DEBUG[2892] threadpool.c: Destroying worker thread 10
[2016-05-18 17:14:09] DEBUG[2963] res_pjsip_registrar_expire.c: Expiring 0 contacts

[2016-05-18 17:14:14] DEBUG[2960] acl.c: For destination '192.168.1.37', our source address is '192.168.1.34'.
[2016-05-18 17:14:14] DEBUG[2960] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.34:5061
[2016-05-18 17:14:14] DEBUG[2960] chan_sip.c: Allocating new SIP dialog for 2401c782-76ad00b2-52858b66-c32b074e@192.168.1.37 - INVITE (No RTP)
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces,join,sdp-anat,norefersub,resource-priority,extended-refer,X-cisco-callinfo,X-cisco-serviceuri,X-cisco-escapecodes,X-cisco-service-control,X-cisco-srtp-fallback,X-cisco-mo
nrec,X-cisco-config,X-cisco-sis-6.0.0,X-cisco-xsi-8.5.1"
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found SIP option: -replaces-
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Matched SIP option: replaces
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found SIP option: -join-
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Matched SIP option: join
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found SIP option: -sdp-anat-
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Matched SIP option: sdp-anat
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found SIP option: -norefersub-
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Matched SIP option: norefersub
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found SIP option: -resource-priority-
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Matched SIP option: resource-priority
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found SIP option: -extended-refer-
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found no match for SIP option: extended-refer (Please file bug report!)
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found SIP option: -X-cisco-callinfo-
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found private SIP option, not supported: X-cisco-callinfo
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found SIP option: -X-cisco-serviceuri-
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found private SIP option, not supported: X-cisco-serviceuri
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found SIP option: -X-cisco-escapecodes-
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found private SIP option, not supported: X-cisco-escapecodes
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found SIP option: -X-cisco-service-control-
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found private SIP option, not supported: X-cisco-service-control
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found SIP option: -X-cisco-srtp-fallback-
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found private SIP option, not supported: X-cisco-srtp-fallback
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found SIP option: -X-cisco-monrec-
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found private SIP option, not supported: X-cisco-monrec
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found SIP option: -X-cisco-config-
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found private SIP option, not supported: X-cisco-config
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found SIP option: -X-cisco-sis-6.0.0-
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found private SIP option, not supported: X-cisco-sis-6.0.0
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found SIP option: -X-cisco-xsi-8.5.1-
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] sip/reqresp_parser.c: Found private SIP option, not supported: X-cisco-xsi-8.5.1
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.37:5061
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Stopping retransmission on '2401c782-76ad00b2-52858b66-c32b074e@192.168.1.37' of Response 101: Match Found
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x706a86bc'
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] res_rtp_asterisk.c: Allocated port 15872 for RTP instance '0x706a86bc'
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:15872 (15872) for RTP instance '0x706a86bc'
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] rtp_engine.c: RTP instance '0x706a86bc' is setup and ready to go
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x706a86bc'
[2016-05-18 17:14:14] VERBOSE[2960][C-00000000] netsock2.c: Using SIP RTP TOS bits 184
[2016-05-18 17:14:14] VERBOSE[2960][C-00000000] netsock2.c: Using SIP RTP CoS mark 5
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Setting NAT on RTP to Off
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Processing session-level SDP o=Cisco-SIPUA 2430 0 IN IP4 192.168.1.37... OK.
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED OR FAILED.
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] rtp_engine.c: Setting tx payload type 0 based on m type on 0x70953b1c
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] rtp_engine.c: Setting tx payload type 8 based on m type on 0x70953b1c
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] rtp_engine.c: Setting tx payload type 18 based on m type on 0x70953b1c
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] rtp_engine.c: Setting tx payload type 102 based on m type on 0x70953b1c
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] rtp_engine.c: Setting tx payload type 116 based on m type on 0x70953b1c
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] rtp_engine.c: Setting tx payload type 101 based on m type on 0x70953b1c
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 192.168.1.37... OK.
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK.
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK.
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:102 L16/16000... OK.
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:116 iLBC/8000... OK.
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:116 mode=20... OK.
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x706a86bc'
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] rtp_engine.c: Copying payload 0 (0x706f3b64) from 0x70953b1c to 0x706a8868
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] rtp_engine.c: Copying payload 8 (0x70782fa4) from 0x70953b1c to 0x706a8868
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] rtp_engine.c: Copying payload 18 (0x706b82f4) from 0x70953b1c to 0x706a8868
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] rtp_engine.c: Copying payload 101 (0x706c60bc) from 0x70953b1c to 0x706a8868
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] rtp_engine.c: Copying payload 102 (0x707d4254) from 0x70953b1c to 0x706a8868
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] rtp_engine.c: Copying payload 116 (0x75a0f0a4) from 0x70953b1c to 0x706a8868
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x706a86bc'
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: We're settling with these formats: (ulaw|alaw)
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Checking SIP call limits for device 1003
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Updating call counter for incoming call
[2016-05-18 17:14:14] DEBUG[2905] devicestate.c: No provider found, checking channel drivers for SIP - 1003
[2016-05-18 17:14:14] DEBUG[2905] chan_sip.c: Checking device state for peer 1003
[2016-05-18 17:14:14] DEBUG[2905] devicestate.c: Changing state for SIP/1003 - state 2 (In use)
[2016-05-18 17:14:14] DEBUG[2981] app_queue.c: Device 'SIP/1003' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2016-05-18 17:14:14] DEBUG[2908] app_queue.c: Extension '1003@ext-local' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2016-05-18 17:14:14] DEBUG[2893] threadpool.c: Increasing threadpool stasis-core's size by 1
[2016-05-18 17:14:14] DEBUG[2910] res_odbc.c: Connecting asteriskcdrdb(0x75e0134c)
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: *** Our native formats are (ulaw) 
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: *** Joint capabilities are (ulaw|alaw) 
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: *** Our capabilities are (ulaw|alaw|gsm|g726) 
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw 
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: This channel will not be able to handle video.
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: SIP/1003-00000000: New call is still down.... Trying... 
[2016-05-18 17:14:14] DEBUG[2960][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.37:5061
[2016-05-18 17:14:14] DEBUG[2910] res_odbc.c: res_odbc: Connected to asteriskcdrdb [MySQL-asteriskcdrdb (0x75e0134c)]
[2016-05-18 17:14:14] DEBUG[2905] devicestate.c: No provider found, checking channel drivers for SIP - 1003
[2016-05-18 17:14:14] DEBUG[2905] chan_sip.c: Checking device state for peer 1003
[2016-05-18 17:14:14] DEBUG[2910] cel_odbc.c: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,extra) VALUES ('CHAN_START',{t
s '2016-05-18 17:14:14.969839'},'XXXXXXXXXX','1003','','','','YYYYYYYYYY','from-internal','SIP/1003-00000000','','',3,'','1463584454.0','1463584454.0','','','')]
[2016-05-18 17:14:14] DEBUG[2905] devicestate.c: Changing state for SIP/1003 - state 2 (In use)
[2016-05-18 17:14:14] DEBUG[3036][C-00000000] pbx.c: Launching 'Macro'
[2016-05-18 17:14:14] VERBOSE[3036][C-00000000] pbx.c: Executing [YYYYYYYYYY@from-internal:1] Macro("SIP/1003-00000000", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/1003-00000000", "TOUCH_MONITOR=1463584454.0") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: Set
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '1'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function CALLERID(number) result is '1003'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function IF(1?1003:) result is '1003'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/1003-00000000", "AMPUSER=1003") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: Set
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function CUT(CHANNEL,@,2) result is ''
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function LEN() result is '0'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '0'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'GotoIf'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/1003-00000000", "0?report") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_builtins.c: Not taking any branch
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: GotoIf
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '1'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function CALLERID(number) result is '1003'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'ExecIf'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/1003-00000000", "1?Set(REALCALLERIDNUM=1003)") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: ExecIf
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '0'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function CALLERID(number) result is '1003'
[2016-05-18 17:14:15] DEBUG[2910] res_odbc.c: Releasing ODBC handle 0x75e0134c
[2016-05-18 17:14:15] DEBUG[2910] res_odbc.c: Database handle 0x75e0134c (connection 0x75e02288) deallocated
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function DB(DEVICE/1003/user) result is '1003'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/1003-00000000", "AMPUSER=1003") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: Set
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '0'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'GotoIf'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/1003-00000000", "0?limit") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_builtins.c: Not taking any branch
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: GotoIf
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function DB(AMPUSER/1003/cidname) result is 'XXXXXXXXXX'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/1003-00000000", "AMPUSERCIDNAME=XXXXXXXXXX") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: Set
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '0'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'GotoIf'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("SIP/1003-00000000", "0?report") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_builtins.c: Not taking any branch
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: GotoIf
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function DB_EXISTS(AMPUSER/1003/cidnum) result is '1'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '0'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function IF(0?1003:1003) result is '1003'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:9] Set("SIP/1003-00000000", "AMPUSERCID=1003") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: Set
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] db.c: Unable to find key '1003/dialopts' in family 'AMPUSER'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function DB_EXISTS(AMPUSER/1003/dialopts) result is '0'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '0'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function IF(0?1003:Ttr) result is 'Ttr'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:10] Set("SIP/1003-00000000", "__DIAL_OPTIONS=Ttr") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: Set
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:11] Set("SIP/1003-00000000", "CALLERID(all)="XXXXXXXXXX" <1003>") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: Set
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function LEN(1003) result is '4'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function DB_EXISTS(AMPUSER/1003/concurrency_limit) result is '1'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function DB(AMPUSER/1003/concurrency_limit) result is '3'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function GROUP_COUNT(1003@concurrency_limit) result is '0'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function DB(AMPUSER/1003/concurrency_limit) result is '3'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '0'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'GotoIf'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:12] GotoIf("SIP/1003-00000000", "0?limit") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_builtins.c: Not taking any branch
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: GotoIf
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function LEN(1003) result is '4'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '1'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'ExecIf'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:13] ExecIf("SIP/1003-00000000", "1?Set(GROUP(concurrency_limit)=1003)") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: ExecIf
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function LEN(1003) result is '4'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '1'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '1'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'GotoIf'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:14] GotoIf("SIP/1003-00000000", "1?continue") in new stack
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx_builtins.c: Goto (macro-user-callerid,s,27)
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: GotoIf
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function CALLERID(number) result is '1003'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:27] Set("SIP/1003-00000000", "CALLERID(number)=1003") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: Set
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function CALLERID(name) result is 'XXXXXXXXXX'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:28] Set("SIP/1003-00000000", "CALLERID(name)=XXXXXXXXXX") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: Set
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function CALLERID(num) result is '1003'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:29] Set("SIP/1003-00000000", "CDR(cnum)=1003") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: Set
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function CALLERID(name) result is 'XXXXXXXXXX'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:30] Set("SIP/1003-00000000", "CDR(cnam)=XXXXXXXXXX") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: Set
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function CHANNEL(language) result is 'en'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function MASTER_CHANNEL(CHANNEL(language)) result is 'en'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@macro-user-callerid:31] Set("SIP/1003-00000000", "CHANNEL(language)=en") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_macro.c: Executed application: Set
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Gosub'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [YYYYYYYYYY@from-internal:2] Gosub("SIP/1003-00000000", "sub-record-check,s,1(out,YYYYYYYYYY,dontcare)") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_stack.c: Channel SIP/1003-00000000 has no datastore, so we're allocating one.
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_stack.c: Setting 'ARG1' to 'out'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_stack.c: Setting 'ARG2' to 'YYYYYYYYYY'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_stack.c: Setting 'ARG3' to 'dontcare'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function LEN() result is '0'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '0'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'GotoIf'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/1003-00000000", "0?initialized") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_builtins.c: Not taking any branch
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@sub-record-check:2] Set("SIP/1003-00000000", "__REC_STATUS=INITIALIZED") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@sub-record-check:3] Set("SIP/1003-00000000", "NOW=1463584455") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function STRFTIME(1463584455,,%d) result is '18'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@sub-record-check:4] Set("SIP/1003-00000000", "__DAY=18") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function STRFTIME(1463584455,,%m) result is '05'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@sub-record-check:5] Set("SIP/1003-00000000", "__MONTH=05") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function STRFTIME(1463584455,,%Y) result is '2016'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@sub-record-check:6] Set("SIP/1003-00000000", "__YEAR=2016") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function STRFTIME(1463584455,,%H%M%S) result is '171415'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@sub-record-check:7] Set("SIP/1003-00000000", "__TIMESTR=20160518-171415") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function LEN(1003) result is '4'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '4'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function LEN(1003) result is '4'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '4'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function IF(4?1003:unknown) result is '1003'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function IF(4?1003:1003) result is '1003'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@sub-record-check:8] Set("SIP/1003-00000000", "__FROMEXTEN=1003") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '0'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function IF(0?WAV:wav) result is 'wav'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@sub-record-check:9] Set("SIP/1003-00000000", "__MON_FMT=wav") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'NoOp'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/1003-00000000", "Recordings initialized") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function LEN(dontcare) result is '8'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '0'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'ExecIf'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/1003-00000000", "0?Set(ARG3=dontcare)") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@sub-record-check:12] Set("SIP/1003-00000000", "REC_POLICY_MODE_SAVE=") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '0'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'ExecIf'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/1003-00000000", "0?Set(REC_STATUS=NO)") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function LEN(out) result is '3'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '3'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'GotoIf'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/1003-00000000", "3?checkaction") in new stack
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx_builtins.c: Goto (sub-record-check,s,17)
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function DIALPLAN_EXISTS(sub-record-check,out) result is '1'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '1'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'GotoIf'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/1003-00000000", "1?sub-record-check,out,1") in new stack
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx_builtins.c: Goto (sub-record-check,out,1)
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'NoOp'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [out@sub-record-check:1] NoOp("SIP/1003-00000000", "Outbound Recording Check from 1003 to YYYYYYYYYY") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function DB(AMPUSER/1003/recording/out/external) result is 'dontcare'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [out@sub-record-check:2] Set("SIP/1003-00000000", "RECMODE=dontcare") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function LEN(dontcare) result is '8'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '1'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'ExecIf'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [out@sub-record-check:3] ExecIf("SIP/1003-00000000", "1?Goto(routewins)") in new stack
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx_builtins.c: Goto (sub-record-check,out,7)
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Gosub'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [out@sub-record-check:7] Gosub("SIP/1003-00000000", "recordcheck,1(dontcare,out,YYYYYYYYYY)") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_stack.c: Setting 'ARG1' to 'dontcare'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_stack.c: Setting 'ARG2' to 'out'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] app_stack.c: Setting 'ARG3' to 'YYYYYYYYYY'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'NoOp'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/1003-00000000", "Starting recording check against dontcare") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Goto'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/1003-00000000", "dontcare") in new stack
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Return'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/1003-00000000", "") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Return'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [out@sub-record-check:8] Return("SIP/1003-00000000", "") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Expression result is '1'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx_variables.c: Function IF(1?default:) result is 'default'
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [YYYYYYYYYY@from-internal:3] Set("SIP/1003-00000000", "MOHCLASS=default") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [YYYYYYYYYY@from-internal:4] Set("SIP/1003-00000000", "_NODEST=") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Macro'
[2016-05-18 17:14:15] VERBOSE[3036][C-00000000] pbx.c: Executing [YYYYYYYYYY@from-internal:5] Macro("SIP/1003-00000000", "dialout-trunk,3,YYYYYYYYYY,,off") in new stack
[2016-05-18 17:14:15] DEBUG[3036][C-00000000] pbx.c: Launching 'Set'
[2016-05-18 17:29:19] Asterisk 13.9.1 built by root @ raspbx on a armv7l running Linux on 2016-05-18 13:49:53 UTC