-
Type:
Bug
-
Status: Closed
-
Priority:
Minor
-
Resolution: Fixed
-
Affects Version/s: None
-
Fix Version/s: None
-
Component/s: Announcements, IVR
-
Labels:None
-
ToDo:
in new freepbx server using asterisk 13.4.0, inbound goes to tc, which plays announcement followed by IVR, once announcement is played there is about a 1 second delay before caller hears the IVR recording. This is NOT happening in another FreePBX Server running asterisk 11.18.0
it's the CDR(disposition) check
CALL TO (AFFECTED) NEW SERVER:
sip1-server*CLI> agi set debug on
AGI Debugging Enabled
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
-- Executing [1xxxxxxxxxx@from-trunk:1] Set("SIP/P2490268487-00001d1f", "__FROM_DID=1xxxxxxxxxx") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:2] Set("SIP/P2490268487-00001d1f", "CIDSFSCHEME=YmFzZV9CYXJvblRFTA==") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:3] AGI("SIP/P2490268487-00001d1f", "/var/www/html/admin/modules/superfecta/agi/superfecta.agi") in new stack
-- Launched AGI Script /var/www/html/admin/modules/superfecta/agi/superfecta.agi
<SIP/P2490268487-00001d1f>AGI Tx >> agi_request: /var/www/html/admin/modules/superfecta/agi/superfecta.agi
<SIP/P2490268487-00001d1f>AGI Tx >> agi_channel: SIP/P2490268487-00001d1f
<SIP/P2490268487-00001d1f>AGI Tx >> agi_language: en
<SIP/P2490268487-00001d1f>AGI Tx >> agi_type: SIP
<SIP/P2490268487-00001d1f>AGI Tx >> agi_uniqueid: 1437401292.152062
<SIP/P2490268487-00001d1f>AGI Tx >> agi_version: 13.4.0
<SIP/P2490268487-00001d1f>AGI Tx >> agi_callerid: 6479962769
<SIP/P2490268487-00001d1f>AGI Tx >> agi_calleridname: NAME .
<SIP/P2490268487-00001d1f>AGI Tx >> agi_callingpres: 0
<SIP/P2490268487-00001d1f>AGI Tx >> agi_callingani2: 0
<SIP/P2490268487-00001d1f>AGI Tx >> agi_callington: 0
<SIP/P2490268487-00001d1f>AGI Tx >> agi_callingtns: 0
<SIP/P2490268487-00001d1f>AGI Tx >> agi_dnid: 1xxxxxxxxxx
<SIP/P2490268487-00001d1f>AGI Tx >> agi_rdnis: unknown
<SIP/P2490268487-00001d1f>AGI Tx >> agi_context: from-trunk
<SIP/P2490268487-00001d1f>AGI Tx >> agi_extension: 1xxxxxxxxxx
<SIP/P2490268487-00001d1f>AGI Tx >> agi_priority: 3
<SIP/P2490268487-00001d1f>AGI Tx >> agi_enhanced: 0.0
<SIP/P2490268487-00001d1f>AGI Tx >> agi_accountcode:
<SIP/P2490268487-00001d1f>AGI Tx >> agi_threadid: 140040218642176
<SIP/P2490268487-00001d1f>AGI Tx >>
<SIP/P2490268487-00001d1f>AGI Rx << VERBOSE "CID Superfecta is Answering the Channel" 1
/var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta is Answering the Channel
<SIP/P2490268487-00001d1f>AGI Tx >> 200 result=1
<SIP/P2490268487-00001d1f>AGI Rx << GET VARIABLE CIDSFSCHEME
<SIP/P2490268487-00001d1f>AGI Tx >> 200 result=1 (YmFzZV9CYXJvblRFTA==)
<SIP/P2490268487-00001d1f>AGI Rx << VERBOSE "CID Superfecta: Scheme is BaronTEL" 1
/var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: Scheme is BaronTEL
<SIP/P2490268487-00001d1f>AGI Tx >> 200 result=1
<SIP/P2490268487-00001d1f>AGI Rx << VERBOSE "CID Superfecta: The DID passed from Asterisk is: 1xxxxxxxxxx" 1
/var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: The DID passed from Asterisk is: 1xxxxxxxxxx
<SIP/P2490268487-00001d1f>AGI Tx >> 200 result=1
<SIP/P2490268487-00001d1f>AGI Rx << VERBOSE "CID Superfecta: The number passed from Asterisk is: 6479962769" 1
/var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: The number passed from Asterisk is: 6479962769
<SIP/P2490268487-00001d1f>AGI Tx >> 200 result=1
<SIP/P2490268487-00001d1f>AGI Rx << VERBOSE "CID Superfecta: The CID name passed from Asterisk is: NAME ." 1
/var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: The CID name passed from Asterisk is: NAME .
<SIP/P2490268487-00001d1f>AGI Tx >> 200 result=1
<SIP/P2490268487-00001d1f>AGI Rx << VERBOSE "CID Superfecta: Executing Scheme.." 1
/var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: Executing Scheme..
<SIP/P2490268487-00001d1f>AGI Tx >> 200 result=1
<SIP/P2490268487-00001d1f>AGI Rx << VERBOSE "Converting result to UTF-8" 1
/var/www/html/admin/modules/superfecta/agi/superfecta.agi: Converting result to UTF-8
<SIP/P2490268487-00001d1f>AGI Tx >> 200 result=1
<SIP/P2490268487-00001d1f>AGI Rx << VERBOSE "CID Superfecta: CID Determined to be: 'NAME .'" 1
/var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: CID Determined to be: 'NAME .'
<SIP/P2490268487-00001d1f>AGI Tx >> 200 result=1
<SIP/P2490268487-00001d1f>AGI Rx << VERBOSE "CID Superfecta: Attempting to set lookupcid" 1
/var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: Attempting to set lookupcid
<SIP/P2490268487-00001d1f>AGI Tx >> 200 result=1
<SIP/P2490268487-00001d1f>AGI Rx << SET VARIABLE lookupcid "NAME ."
<SIP/P2490268487-00001d1f>AGI Tx >> 200 result=1
<SIP/P2490268487-00001d1f>AGI Rx << GET VARIABLE lookupcid
<SIP/P2490268487-00001d1f>AGI Tx >> 200 result=1 (NAME .)
<SIP/P2490268487-00001d1f>AGI Rx << VERBOSE "CID Superfecta: Success!" 1
/var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: Success!
<SIP/P2490268487-00001d1f>AGI Tx >> 200 result=1
-- <SIP/P2490268487-00001d1f>AGI Script /var/www/html/admin/modules/superfecta/agi/superfecta.agi completed, returning 0
-- Executing [1xxxxxxxxxx@from-trunk:4] Set("SIP/P2490268487-00001d1f", "CALLERID(name)=NAME .") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:5] Gosub("SIP/P2490268487-00001d1f", "sub-record-check,s,1(in,1xxxxxxxxxx,dontcare)") in new stack
-- Executing [s@sub-record-check:1] GotoIf("SIP/P2490268487-00001d1f", "0?initialized") in new stack
-- Executing [s@sub-record-check:2] Set("SIP/P2490268487-00001d1f", "__REC_STATUS=INITIALIZED") in new stack
-- Executing [s@sub-record-check:3] Set("SIP/P2490268487-00001d1f", "NOW=1437401292") in new stack
-- Executing [s@sub-record-check:4] Set("SIP/P2490268487-00001d1f", "__DAY=20") in new stack
-- Executing [s@sub-record-check:5] Set("SIP/P2490268487-00001d1f", "__MONTH=07") in new stack
-- Executing [s@sub-record-check:6] Set("SIP/P2490268487-00001d1f", "__YEAR=2015") in new stack
-- Executing [s@sub-record-check:7] Set("SIP/P2490268487-00001d1f", "__TIMESTR=20150720-100812") in new stack
-- Executing [s@sub-record-check:8] Set("SIP/P2490268487-00001d1f", "__FROMEXTEN=unknown") in new stack
-- Executing [s@sub-record-check:9] Set("SIP/P2490268487-00001d1f", "__MON_FMT=wav") in new stack
-- Executing [s@sub-record-check:10] NoOp("SIP/P2490268487-00001d1f", "Recordings initialized") in new stack
-- Executing [s@sub-record-check:11] ExecIf("SIP/P2490268487-00001d1f", "0?Set(ARG3=dontcare)") in new stack
-- Executing [s@sub-record-check:12] Set("SIP/P2490268487-00001d1f", "REC_POLICY_MODE_SAVE=") in new stack
-- Executing [s@sub-record-check:13] ExecIf("SIP/P2490268487-00001d1f", "0?Set(REC_STATUS=NO)") in new stack
-- Executing [s@sub-record-check:14] GotoIf("SIP/P2490268487-00001d1f", "2?checkaction") in new stack
-- Goto (sub-record-check,s,17)
-- Executing [s@sub-record-check:17] GotoIf("SIP/P2490268487-00001d1f", "1?sub-record-check,in,1") in new stack
-- Goto (sub-record-check,in,1)
-- Executing [in@sub-record-check:1] NoOp("SIP/P2490268487-00001d1f", "Inbound Recording Check to 1xxxxxxxxxx") in new stack
-- Executing [in@sub-record-check:2] Set("SIP/P2490268487-00001d1f", "FROMEXTEN=unknown") in new stack
-- Executing [in@sub-record-check:3] ExecIf("SIP/P2490268487-00001d1f", "10?Set(FROMEXTEN=6479962769)") in new stack
-- Executing [in@sub-record-check:4] Gosub("SIP/P2490268487-00001d1f", "recordcheck,1(dontcare,in,1xxxxxxxxxx)") in new stack
-- Executing [recordcheck@sub-record-check:1] NoOp("SIP/P2490268487-00001d1f", "Starting recording check against dontcare") in new stack
-- Executing [recordcheck@sub-record-check:2] Goto("SIP/P2490268487-00001d1f", "dontcare") in new stack
-- Goto (sub-record-check,recordcheck,3)
-- Executing [recordcheck@sub-record-check:3] Return("SIP/P2490268487-00001d1f", "") in new stack
-- Executing [in@sub-record-check:5] Return("SIP/P2490268487-00001d1f", "") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:6] Gosub("SIP/P2490268487-00001d1f", "app-blacklist-check,s,1()") in new stack
-- Executing [s@app-blacklist-check:1] GotoIf("SIP/P2490268487-00001d1f", "0?blacklisted") in new stack
-- Executing [s@app-blacklist-check:2] Set("SIP/P2490268487-00001d1f", "CALLED_BLACKLIST=1") in new stack
-- Executing [s@app-blacklist-check:3] Return("SIP/P2490268487-00001d1f", "") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:7] Set("SIP/P2490268487-00001d1f", "CDR(did)=1xxxxxxxxxx") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:8] ExecIf("SIP/P2490268487-00001d1f", "0 ?Set(CALLERID(name)=6479962769)") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:9] Set("SIP/P2490268487-00001d1f", "CHANNEL(musicclass)=Piano") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:10] Set("SIP/P2490268487-00001d1f", "__MOHCLASS=Piano") in new stack
[2015-07-20 10:08:12] WARNING[14744][C-000030b3]: func_channel.c:596 func_channel_read: Unknown or unavailable item requested: 'reversecharge'
-- Executing [1xxxxxxxxxx@from-trunk:11] GotoIf("SIP/P2490268487-00001d1f", "0?macro-hangupcall") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:12] Set("SIP/P2490268487-00001d1f", "__CALLINGPRES_SV=allowed_not_screened") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:13] Set("SIP/P2490268487-00001d1f", "CALLERPRES()=allowed_not_screened") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:14] Goto("SIP/P2490268487-00001d1f", "timeconditions,15,1") in new stack
-- Goto (timeconditions,15,1)
-- Executing [15@timeconditions:1] Set("SIP/P2490268487-00001d1f", "DB(TC/15/INUSESTATE)=INUSE") in new stack
-- Executing [15@timeconditions:2] Set("SIP/P2490268487-00001d1f", "DB(TC/15/NOT_INUSESTATE)=NOT_INUSE") in new stack
-- Executing [15@timeconditions:3] GotoIfTime("SIP/P2490268487-00001d1f", "08:00-11:59,mon-sat,*,*?truestate") in new stack
-- Goto (timeconditions,15,12)
-- Executing [15@timeconditions:12] GotoIf("SIP/P2490268487-00001d1f", "0?falsegoto") in new stack
-- Executing [15@timeconditions:13] ExecIf("SIP/P2490268487-00001d1f", "0?Set(DB(TC/15)=)") in new stack
-- Executing [15@timeconditions:14] Set("SIP/P2490268487-00001d1f", "DEVICE_STATE(Custom:TC15)=NOT_INUSE") in new stack
-- Executing [15@timeconditions:15] ExecIf("SIP/P2490268487-00001d1f", "0?Set(NOT_INUSE)") in new stack
-- Executing [15@timeconditions:16] GotoIf("SIP/P2490268487-00001d1f", "1?app-announcement-4,s,1") in new stack
-- Goto (app-announcement-4,s,1)
-- Executing [s@app-announcement-4:1] GotoIf("SIP/P2490268487-00001d1f", "0?begin") in new stack
-- Executing [s@app-announcement-4:2] Answer("SIP/P2490268487-00001d1f", "") in new stack
> 0x7f5e109b9520 -- Probation passed - setting RTP source address to 64.34.181.47:13834
*+-- Executing [s@app-announcement-4:3] Wait("SIP/P2490268487-00001d1f", "1") in new stack+*
-- SIP/P2490268487-00001d1e answered SIP/125-00001d1d
-- Executing [s@macro-setmusic:1] Set("SIP/P2490268487-00001d1e", "CHANNEL(musicclass)=none") in new stack
-- Channel SIP/125-00001d1d joined 'simple_bridge' basic-bridge <78af678d-fb48-4990-9a42-d53708400be4>
-- Channel SIP/P2490268487-00001d1e joined 'simple_bridge' basic-bridge <78af678d-fb48-4990-9a42-d53708400be4>
> 0x7f5e1099b020 -- Probation passed - setting RTP source address to 216.191.150.202:11400
> 0x7f5de5241380 -- Probation passed - setting RTP source address to 64.34.181.47:14980
> 0x7f5e1099b020 -- Probation passed - setting RTP source address to 216.191.150.202:11400
-- Executing [s@app-announcement-4:4] NoOp("SIP/P2490268487-00001d1f", "Playing announcement Good Morning Open") in new stack
-- Executing [s@app-announcement-4:5] Playback("SIP/P2490268487-00001d1f", "custom/goodmorning1,noanswer") in new stack
-- <SIP/P2490268487-00001d1f> Playing 'custom/goodmorning1.slin' (language 'en')
-- Executing [s@app-announcement-4:6] Goto("SIP/P2490268487-00001d1f", "ivr-1,s,1") in new stack
-- Goto (ivr-1,s,1)
-- Executing [s@ivr-1:1] Set("SIP/P2490268487-00001d1f", "_IVR_CONTEXT_ivr-1=") in new stack
-- Executing [s@ivr-1:2] Set("SIP/P2490268487-00001d1f", "_IVR_CONTEXT=ivr-1") in new stack
-- Executing [s@ivr-1:3] Set("SIP/P2490268487-00001d1f", "__IVR_RETVM=") in new stack
-- Executing [s@ivr-1:4] GotoIf("SIP/P2490268487-00001d1f", "0?skip") in new stack
-- Executing [s@ivr-1:5] Answer("SIP/P2490268487-00001d1f", "") in new stack
-- Executing [s@ivr-1:6] Wait("SIP/P2490268487-00001d1f", "1") in new stack
-- Executing [s@ivr-1:7] Set("SIP/P2490268487-00001d1f", "IVR_MSG=custom/main-greeting1") in new stack
-- Executing [s@ivr-1:8] Set("SIP/P2490268487-00001d1f", "TIMEOUT(digit)=3") in new stack
-- Digit timeout set to 3.000
-- Executing [s@ivr-1:9] ExecIf("SIP/P2490268487-00001d1f", "1?Background(custom/main-greeting1)") in new stack
-- <SIP/P2490268487-00001d1f> Playing 'custom/main-greeting1.slin' (language 'en')
sip1-server*CLI> agi set debug off
========================================================================
========================================================================
CALL TO (NON AFFECTED) OLDER SERVER:
server21*CLI> agi set debug on
AGI Debugging Enabled
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
-- Executing [1xxxxxxxxxx@from-trunk:1] Set("SIP/P2490266539-00000236", "__FROM_DID=1xxxxxxxxxx") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:2] Gosub("SIP/P2490266539-00000236", "sub-record-check,s,1(in,1xxxxxxxxxx,dontcare)") in new stack
-- Executing [s@sub-record-check:1] GotoIf("SIP/P2490266539-00000236", "0?initialized") in new stack
-- Executing [s@sub-record-check:2] Set("SIP/P2490266539-00000236", "__REC_STATUS=INITIALIZED") in new stack
-- Executing [s@sub-record-check:3] Set("SIP/P2490266539-00000236", "NOW=1437403154") in new stack
-- Executing [s@sub-record-check:4] Set("SIP/P2490266539-00000236", "__DAY=20") in new stack
-- Executing [s@sub-record-check:5] Set("SIP/P2490266539-00000236", "__MONTH=07") in new stack
-- Executing [s@sub-record-check:6] Set("SIP/P2490266539-00000236", "__YEAR=2015") in new stack
-- Executing [s@sub-record-check:7] Set("SIP/P2490266539-00000236", "__TIMESTR=20150720-103914") in new stack
-- Executing [s@sub-record-check:8] Set("SIP/P2490266539-00000236", "__FROMEXTEN=unknown") in new stack
-- Executing [s@sub-record-check:9] Set("SIP/P2490266539-00000236", "__MON_FMT=wav") in new stack
-- Executing [s@sub-record-check:10] NoOp("SIP/P2490266539-00000236", "Recordings initialized") in new stack
-- Executing [s@sub-record-check:11] ExecIf("SIP/P2490266539-00000236", "0?Set(ARG3=dontcare)") in new stack
-- Executing [s@sub-record-check:12] Set("SIP/P2490266539-00000236", "REC_POLICY_MODE_SAVE=") in new stack
-- Executing [s@sub-record-check:13] ExecIf("SIP/P2490266539-00000236", "0?Set(REC_STATUS=NO)") in new stack
-- Executing [s@sub-record-check:14] GotoIf("SIP/P2490266539-00000236", "2?checkaction") in new stack
-- Goto (sub-record-check,s,17)
-- Executing [s@sub-record-check:17] GotoIf("SIP/P2490266539-00000236", "1?sub-record-check,in,1") in new stack
-- Goto (sub-record-check,in,1)
-- Executing [in@sub-record-check:1] NoOp("SIP/P2490266539-00000236", "Inbound Recording Check to 1xxxxxxxxxx") in new stack
-- Executing [in@sub-record-check:2] Set("SIP/P2490266539-00000236", "FROMEXTEN=unknown") in new stack
-- Executing [in@sub-record-check:3] ExecIf("SIP/P2490266539-00000236", "10?Set(FROMEXTEN=xxx2761)") in new stack
-- Executing [in@sub-record-check:4] Gosub("SIP/P2490266539-00000236", "recordcheck,1(dontcare,in,1xxxxxxxxxx)") in new stack
-- Executing [recordcheck@sub-record-check:1] NoOp("SIP/P2490266539-00000236", "Starting recording check against dontcare") in new stack
-- Executing [recordcheck@sub-record-check:2] Goto("SIP/P2490266539-00000236", "dontcare") in new stack
-- Goto (sub-record-check,recordcheck,3)
-- Executing [recordcheck@sub-record-check:3] Return("SIP/P2490266539-00000236", "") in new stack
-- Executing [in@sub-record-check:5] Return("SIP/P2490266539-00000236", "") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:3] Gosub("SIP/P2490266539-00000236", "app-blacklist-check,s,1()") in new stack
-- Executing [s@app-blacklist-check:1] GotoIf("SIP/P2490266539-00000236", "0?check-blocked") in new stack
-- Executing [s@app-blacklist-check:2] GotoIf("SIP/P2490266539-00000236", "0?check-blocked") in new stack
-- Executing [s@app-blacklist-check:3] GotoIf("SIP/P2490266539-00000236", "0?check-blocked:check") in new stack
-- Goto (app-blacklist-check,s,5)
-- Executing [s@app-blacklist-check:5] GotoIf("SIP/P2490266539-00000236", "0?blacklisted") in new stack
-- Executing [s@app-blacklist-check:6] Set("SIP/P2490266539-00000236", "CALLED_BLACKLIST=1") in new stack
-- Executing [s@app-blacklist-check:7] Return("SIP/P2490266539-00000236", "") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:4] Set("SIP/P2490266539-00000236", "CDR(did)=1xxxxxxxxxx") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:5] ExecIf("SIP/P2490266539-00000236", "0 ?Set(CALLERID(name)=xxx2761)") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:6] Set("SIP/P2490266539-00000236", "CHANNEL(musicclass)=piano") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:7] Set("SIP/P2490266539-00000236", "__MOHCLASS=piano") in new stack
[2015-07-20 10:39:14] WARNING[30830][C-000043c9]: func_channel.c:538 func_channel_read: Unknown or unavailable item requested: 'reversecharge'
-- Executing [1xxxxxxxxxx@from-trunk:8] GotoIf("SIP/P2490266539-00000236", "0?macro-hangupcall") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:9] Macro("SIP/P2490266539-00000236", "privacy-mgr,2,10") in new stack
-- Executing [s@macro-privacy-mgr:1] Set("SIP/P2490266539-00000236", "KEEPCID=xxx2761") in new stack
-- Executing [s@macro-privacy-mgr:2] Set("SIP/P2490266539-00000236", "TESTCID=6479962770.000000") in new stack
-- Executing [s@macro-privacy-mgr:3] ExecIf("SIP/P2490266539-00000236", "0?Set(CALLERID(num)=)") in new stack
-- Executing [s@macro-privacy-mgr:4] PrivacyManager("SIP/P2490266539-00000236", "2,10") in new stack
-- CallerID number present: Skipping
-- Executing [s@macro-privacy-mgr:5] GotoIf("SIP/P2490266539-00000236", "0?fail") in new stack
-- Executing [s@macro-privacy-mgr:6] GosubIf("SIP/P2490266539-00000236", "1?app-blacklist-check,s,1()") in new stack
-- Executing [s@app-blacklist-check:1] GotoIf("SIP/P2490266539-00000236", "0?check-blocked") in new stack
-- Executing [s@app-blacklist-check:2] GotoIf("SIP/P2490266539-00000236", "0?check-blocked") in new stack
-- Executing [s@app-blacklist-check:3] GotoIf("SIP/P2490266539-00000236", "0?check-blocked:check") in new stack
-- Goto (app-blacklist-check,s,5)
-- Executing [s@app-blacklist-check:5] GotoIf("SIP/P2490266539-00000236", "0?blacklisted") in new stack
-- Executing [s@app-blacklist-check:6] Set("SIP/P2490266539-00000236", "CALLED_BLACKLIST=1") in new stack
-- Executing [s@app-blacklist-check:7] Return("SIP/P2490266539-00000236", "") in new stack
-- Executing [s@macro-privacy-mgr:7] Set("SIP/P2490266539-00000236", "CALLERID(num-pres)=allowed_passed_screen") in new stack
-- Executing [s@macro-privacy-mgr:8] MacroExit("SIP/P2490266539-00000236", "") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:10] Macro("SIP/P2490266539-00000236", "prepend-cid,SERVARIS:") in new stack
-- Executing [s@macro-prepend-cid:1] GotoIf("SIP/P2490266539-00000236", "1?REPCID") in new stack
-- Goto (macro-prepend-cid,s,5)
-- Executing [s@macro-prepend-cid:5] Set("SIP/P2490266539-00000236", "_RGPREFIX=SERVARIS:") in new stack
-- Executing [s@macro-prepend-cid:6] Set("SIP/P2490266539-00000236", "CALLERID(name)=SERVARIS:LANNY .") in new stack
-- Executing [1xxxxxxxxxx@from-trunk:11] Goto("SIP/P2490266539-00000236", "timeconditions,17,1") in new stack
-- Goto (timeconditions,17,1)
-- Executing [17@timeconditions:1] Set("SIP/P2490266539-00000236", "DB(TC/17/INUSESTATE)=INUSE") in new stack
-- Executing [17@timeconditions:2] Set("SIP/P2490266539-00000236", "DB(TC/17/NOT_INUSESTATE)=NOT_INUSE") in new stack
-- Executing [17@timeconditions:3] GotoIfTime("SIP/P2490266539-00000236", "00:00-05:59,sun-sat,*,*?truestate") in new stack
-- Executing [17@timeconditions:4] GotoIf("SIP/P2490266539-00000236", "0?truegoto") in new stack
-- Executing [17@timeconditions:5] ExecIf("SIP/P2490266539-00000236", "0?Set(DB(TC/17)=)") in new stack
-- Executing [17@timeconditions:6] Set("SIP/P2490266539-00000236", "DEVICE_STATE(Custom:TC17)=INUSE") in new stack
-- Executing [17@timeconditions:7] ExecIf("SIP/P2490266539-00000236", "0?Set(NOT_INUSE)") in new stack
-- Executing [17@timeconditions:8] GotoIf("SIP/P2490266539-00000236", "1?timeconditions,7,1") in new stack
-- Goto (timeconditions,7,1)
-- Executing [7@timeconditions:1] Set("SIP/P2490266539-00000236", "DB(TC/7/INUSESTATE)=INUSE") in new stack
-- Executing [7@timeconditions:2] Set("SIP/P2490266539-00000236", "DB(TC/7/NOT_INUSESTATE)=NOT_INUSE") in new stack
-- Executing [7@timeconditions:3] GotoIfTime("SIP/P2490266539-00000236", "06:00-11:59,sun-sat,*,*?truestate") in new stack
-- Goto (timeconditions,7,12)
-- Executing [7@timeconditions:12] GotoIf("SIP/P2490266539-00000236", "0?falsegoto") in new stack
-- Executing [7@timeconditions:13] ExecIf("SIP/P2490266539-00000236", "0?Set(DB(TC/7)=)") in new stack
-- Executing [7@timeconditions:14] Set("SIP/P2490266539-00000236", "DEVICE_STATE(Custom:TC7)=NOT_INUSE") in new stack
-- Executing [7@timeconditions:15] ExecIf("SIP/P2490266539-00000236", "0?Set(NOT_INUSE)") in new stack
-- Executing [7@timeconditions:16] GotoIf("SIP/P2490266539-00000236", "1?app-announcement-3,s,1") in new stack
-- Goto (app-announcement-3,s,1)
-- Executing [s@app-announcement-3:1] GotoIf("SIP/P2490266539-00000236", "0?begin") in new stack
-- Executing [s@app-announcement-3:2] Answer("SIP/P2490266539-00000236", "") in new stack
> 0x7fdd18117a40 -- Probation passed - setting RTP source address to 64.34.181.47:11712
-- Executing [s@app-announcement-3:3] Wait("SIP/P2490266539-00000236", "1") in new stack
-- Executing [s@app-announcement-3:4] NoOp("SIP/P2490266539-00000236", "Playing announcement sound-good-morning") in new stack
-- Executing [s@app-announcement-3:5] Playback("SIP/P2490266539-00000236", "custom/good-morning,noanswer") in new stack
-- <SIP/P2490266539-00000236> Playing 'custom/good-morning.slin' (language 'en')
-- Executing [s@app-announcement-3:6] Goto("SIP/P2490266539-00000236", "ivr-8,s,1") in new stack
-- Goto (ivr-8,s,1)
-- Executing [s@ivr-8:1] Set("SIP/P2490266539-00000236", "TIMEOUT_LOOPCOUNT=0") in new stack
-- Executing [s@ivr-8:2] Set("SIP/P2490266539-00000236", "INVALID_LOOPCOUNT=0") in new stack
-- Executing [s@ivr-8:3] Set("SIP/P2490266539-00000236", "_IVR_CONTEXT_ivr-8=") in new stack
-- Executing [s@ivr-8:4] Set("SIP/P2490266539-00000236", "_IVR_CONTEXT=ivr-8") in new stack
-- Executing [s@ivr-8:5] Set("SIP/P2490266539-00000236", "__IVR_RETVM=") in new stack
-- Executing [s@ivr-8:6] GotoIf("SIP/P2490266539-00000236", "1?skip") in new stack
-- Goto (ivr-8,s,9)
-- Executing [s@ivr-8:9] Set("SIP/P2490266539-00000236", "IVR_MSG=custom/sound-main-greet") in new stack
-- Executing [s@ivr-8:10] Set("SIP/P2490266539-00000236", "TIMEOUT(digit)=3") in new stack
-- Digit timeout set to 3.000
-- Executing [s@ivr-8:11] ExecIf("SIP/P2490266539-00000236", "1?Background(custom/sound-main-greet)") in new stack
-- <SIP/P2490266539-00000236> Playing 'custom/sound-main-greet.slin' (language 'en')
server21*CLI> agi set debug off