Queue Break Out IVR accouncement not being played

FS_Arci · September 11, 2015, 4:08pm

Hello Community,

I have a Queue for incoming calls which uses a IVR Break Out Menu - In the drop-down menu I selected an IVR that has an announcement and one one-digit option which redirects the call to VM. Other options in the break-out-IVR are disabled or set to 0.
The queue rings for 40 seconds and the Repeat Frequency for that IVR Break Out Menu is set to 15 seconds.

The issue is that the announcement from the Break Out-selected IVR is not being played at all.

Version Info:
FreePBX Distro - SHMZ release 6.5 (Final)
Asterisk 11.13.0
FreePBX 2.11.0.43

Here is the queue from /etc/asterisk/queues_additional.conf - Looks good to me, has the periodic-announce-frequency and the context and the periodic-announce.

    [605]
    announce-frequency=0
    announce-holdtime=no
    announce-position=no
    autofill=no
    autopause=no
    autopausebusy=no
    autopausedelay=0
    autopauseunavail=no
    eventmemberstatus=yes
    eventwhencalled=yes
    joinempty=yes
    leavewhenempty=no
    maxlen=10
    memberdelay=0
    monitor-type=mixmonitor
    penaltymemberslimit=0
    periodic-announce-frequency=15
    queue-callswaiting=silence/1
    queue-thereare=silence/1
    queue-youarenext=silence/1
    reportholdtime=no
    retry=0
    ringinuse=yes
    servicelevel=60
    strategy=ringall
    timeout=40
    timeoutpriority=app
    timeoutrestart=no
    weight=0
    wrapuptime=0
    context=ivr-12
    periodic-announce=custom/fs2-agents_busy
    member=Local/185@from-queue/n,0,MY NAME,hint:185@ext-local

Here is the Break-Out-IVR from /etc/asterisk/extensions_additional.conf

[ivr-12] ; Break-out
include => ivr-12-custom
exten => s,1,Set(_IVR_CONTEXT_${CONTEXT}=${IVR_CONTEXT})
exten => s,n,Set(_IVR_CONTEXT=${CONTEXT})
exten => s,n,Set(__IVR_RETVM=)
exten => s,n,GotoIf($["${CDR(disposition)}" = "ANSWERED"]?skip)
exten => s,n,Answer
exten => s,n,Wait(1)
exten => s,n(skip),Set(IVR_MSG=custom/fs2-agents_busy)
exten => s,n(start),Set(TIMEOUT(digit)=3)
exten => s,n,ExecIf($["${IVR_MSG}" != ""]?Background(${IVR_MSG}))
exten => s,n,WaitExten(0,)

exten => 1,1,Macro(blkvm-clr,)
exten => 1,n,Set(__NODEST=)
exten => 1,n(ivrsel-1),Goto(ivr-11,s,1)

exten => i,1(final),Goto(app-blackhole,hangup,1)

exten => t,1(final),Goto(app-blackhole,hangup,1)

exten => return,1,Set(_IVR_CONTEXT=${CONTEXT})
exten => return,n,Set(_IVR_CONTEXT_${CONTEXT}=${IVR_CONTEXT_${CONTEXT}})
exten => return,n,Set(IVR_MSG=custom/fs2-agents_busy)
exten => return,n,Goto(s,start)

exten => h,1,Hangup

exten => hang,1,Playback(vm-goodbye)
exten => hang,n,Hangup

Any suggestions greatly appreciated.

FS_Arci · September 11, 2015, 4:12pm

Below a log from a call that replicates the problem - it rings, doesn’t play break out ivr recording every 15 secs.

  == Extension Changed 185[ext-local] new state InUse for Notify User 180
    -- Executing [931@from-internal:1] NoOp("SIP/185-00001900", "Running miscapp 2: FS TEST 931") in new stack
    -- Executing [931@from-internal:2] Macro("SIP/185-00001900", "user-callerid,") in new stack
    -- Executing [s@macro-user-callerid:1] Set("SIP/185-00001900", "TOUCH_MONITOR=1441984298.11683") in new stack
    -- Executing [s@macro-user-callerid:2] Set("SIP/185-00001900", "AMPUSER=185") in new stack
    -- Executing [s@macro-user-callerid:3] GotoIf("SIP/185-00001900", "0?report") in new stack
    -- Executing [s@macro-user-callerid:4] ExecIf("SIP/185-00001900", "1?Set(REALCALLERIDNUM=185)") in new stack
    -- Executing [s@macro-user-callerid:5] Set("SIP/185-00001900", "AMPUSER=185") in new stack
    -- Executing [s@macro-user-callerid:6] GotoIf("SIP/185-00001900", "0?limit") in new stack
    -- Executing [s@macro-user-callerid:7] Set("SIP/185-00001900", "AMPUSERCIDNAME=MY NAME") in new stack
    -- Executing [s@macro-user-callerid:8] GotoIf("SIP/185-00001900", "0?report") in new stack
    -- Executing [s@macro-user-callerid:9] Set("SIP/185-00001900", "AMPUSERCID=185") in new stack
    -- Executing [s@macro-user-callerid:10] Set("SIP/185-00001900", "__DIAL_OPTIONS=tTr") in new stack
    -- Executing [s@macro-user-callerid:11] Set("SIP/185-00001900", "CALLERID(all)="MY NAME" <185>") in new stack
    -- Executing [s@macro-user-callerid:12] GotoIf("SIP/185-00001900", "0?limit") in new stack
    -- Executing [s@macro-user-callerid:13] ExecIf("SIP/185-00001900", "0?Set(GROUP(concurrency_limit)=185)") in new stack
    -- Executing [s@macro-user-callerid:14] ExecIf("SIP/185-00001900", "0?Set(CHANNEL(language)=)") in new stack
    -- Executing [s@macro-user-callerid:15] GosubIf("SIP/185-00001900", "7?sub-ccss,s,1(from-internal,931)") in new stack
    -- Executing [s@sub-ccss:1] ExecIf("SIP/185-00001900", "0?Return()") in new stack
    -- Executing [s@sub-ccss:2] Set("SIP/185-00001900", "CCSS_SETUP=TRUE") in new stack
    -- Executing [s@sub-ccss:3] GosubIf("SIP/185-00001900", "0?monitor_config,1(from-internal,931):monitor_default,1(from-internal,931)") in new stack
    -- Executing [monitor_default@sub-ccss:1] GotoIf("SIP/185-00001900", "0?is_exten") in new stack
    -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/185-00001900", "") in new stack
    -- Executing [monitor_default@sub-ccss:3] Return("SIP/185-00001900", "FALSE") in new stack
    -- Executing [s@macro-user-callerid:16] GotoIf("SIP/185-00001900", "0?continue") in new stack
    -- Executing [s@macro-user-callerid:17] Set("SIP/185-00001900", "__TTL=64") in new stack
    -- Executing [s@macro-user-callerid:18] GotoIf("SIP/185-00001900", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,29)
    -- Executing [s@macro-user-callerid:29] Set("SIP/185-00001900", "CALLERID(number)=185") in new stack
    -- Executing [s@macro-user-callerid:30] Set("SIP/185-00001900", "CALLERID(name)=MY NAME") in new stack
    -- Executing [s@macro-user-callerid:31] Set("SIP/185-00001900", "CDR(cnum)=185") in new stack
    -- Executing [s@macro-user-callerid:32] Set("SIP/185-00001900", "CDR(cnam)=MY NAME") in new stack
    -- Executing [s@macro-user-callerid:33] Set("SIP/185-00001900", "CHANNEL(language)=en") in new stack
    -- Executing [931@from-internal:3] Goto("SIP/185-00001900", "ivr-10,s,1") in new stack
    -- Goto (ivr-10,s,1)
    -- Executing [s@ivr-10:1] Set("SIP/185-00001900", "TIMEOUT_LOOPCOUNT=0") in new stack
    -- Executing [s@ivr-10:2] Set("SIP/185-00001900", "INVALID_LOOPCOUNT=0") in new stack
    -- Executing [s@ivr-10:3] Set("SIP/185-00001900", "_IVR_CONTEXT_ivr-10=") in new stack
    -- Executing [s@ivr-10:4] Set("SIP/185-00001900", "_IVR_CONTEXT=ivr-10") in new stack
    -- Executing [s@ivr-10:5] Set("SIP/185-00001900", "__IVR_RETVM=") in new stack
    -- Executing [s@ivr-10:6] GotoIf("SIP/185-00001900", "0?skip") in new stack
    -- Executing [s@ivr-10:7] Answer("SIP/185-00001900", "") in new stack
       > [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,userfield) VALUES ('ANSWER',{ts '2015-09-11 10:11:38'},'MY NAME','185','185','','931','s','ivr-10','SIP/185-00001900','Answer','',3,'','1441984298.11683','1441984298.11683','','','')]
       > 0x7f16c01f77a0 -- Probation passed - setting RTP source address to 83.5.238.95:3000
    -- Executing [s@ivr-10:8] Wait("SIP/185-00001900", "1") in new stack
       > 0x7f16c01f77a0 -- Probation passed - setting RTP source address to 83.5.238.95:3000
    -- Executing [s@ivr-10:9] Set("SIP/185-00001900", "IVR_MSG=custom/fs-main_greeting") in new stack
    -- Executing [s@ivr-10:10] Set("SIP/185-00001900", "TIMEOUT(digit)=3") in new stack
    -- Digit timeout set to 3.000
    -- Executing [s@ivr-10:11] ExecIf("SIP/185-00001900", "1?Background(custom/fs-main_greeting)") in new stack
    -- <SIP/185-00001900> Playing 'custom/fs-main_greeting.slin' (language 'en')
  == CDR updated on SIP/185-00001900
    -- Executing [1@ivr-10:1] Goto("SIP/185-00001900", "timeconditions,7,1") in new stack
    -- Goto (timeconditions,7,1)
    -- Executing [7@timeconditions:1] GotoIfTime("SIP/185-00001900", "*,mon-fri,*,*?truestate") in new stack
    -- Goto (timeconditions,7,8)
    -- Executing [7@timeconditions:8] GotoIf("SIP/185-00001900", "0?falsegoto") in new stack
    -- Executing [7@timeconditions:9] ExecIf("SIP/185-00001900", "0?Set(DB(TC/7)=)") in new stack
    -- Executing [7@timeconditions:10] GotoIf("SIP/185-00001900", "1?timeconditions,8,1") in new stack
    -- Goto (timeconditions,8,1)
    -- Executing [8@timeconditions:1] GotoIfTime("SIP/185-00001900", "06:00-16:59,*,*,*?truestate") in new stack
    -- Goto (timeconditions,8,8)
    -- Executing [8@timeconditions:8] GotoIf("SIP/185-00001900", "0?falsegoto") in new stack
    -- Executing [8@timeconditions:9] ExecIf("SIP/185-00001900", "0?Set(DB(TC/8)=)") in new stack
    -- Executing [8@timeconditions:10] GotoIf("SIP/185-00001900", "1?ext-queues,605,1") in new stack
    -- Goto (ext-queues,605,1)
    -- Executing [605@ext-queues:1] Macro("SIP/185-00001900", "user-callerid,") in new stack
    -- Executing [s@macro-user-callerid:1] Set("SIP/185-00001900", "TOUCH_MONITOR=1441984298.11683") in new stack
    -- Executing [s@macro-user-callerid:2] Set("SIP/185-00001900", "AMPUSER=185") in new stack
    -- Executing [s@macro-user-callerid:3] GotoIf("SIP/185-00001900", "18?report") in new stack
    -- Goto (macro-user-callerid,s,16)
    -- Executing [s@macro-user-callerid:16] GotoIf("SIP/185-00001900", "0?continue") in new stack
    -- Executing [s@macro-user-callerid:17] Set("SIP/185-00001900", "__TTL=63") in new stack
    -- Executing [s@macro-user-callerid:18] GotoIf("SIP/185-00001900", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,29)
    -- Executing [s@macro-user-callerid:29] Set("SIP/185-00001900", "CALLERID(number)=185") in new stack
    -- Executing [s@macro-user-callerid:30] Set("SIP/185-00001900", "CALLERID(name)=MY NAME") in new stack
    -- Executing [s@macro-user-callerid:31] Set("SIP/185-00001900", "CDR(cnum)=185") in new stack
    -- Executing [s@macro-user-callerid:32] Set("SIP/185-00001900", "CDR(cnam)=MY NAME") in new stack
    -- Executing [s@macro-user-callerid:33] Set("SIP/185-00001900", "CHANNEL(language)=en") in new stack
    -- Executing [605@ext-queues:2] Answer("SIP/185-00001900", "") in new stack
       > [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,userfield) VALUES ('ANSWER',{ts '2015-09-11 10:11:43'},'MY NAME','185','185','','931','605','ext-queues','SIP/185-00001900','Answer','',3,'','1441984298.11683','1441984298.11683','','','')]
    -- Executing [605@ext-queues:3] Macro("SIP/185-00001900", "blkvm-set,reset") in new stack
    -- Executing [s@macro-blkvm-set:1] ExecIf("SIP/185-00001900", "1?Set(__BLKVM_CHANNEL=SIP/185-00001900)") in new stack
    -- Executing [s@macro-blkvm-set:2] Set("SIP/185-00001900", "SHARED(BLKVM,SIP/185-00001900)=TRUE") in new stack
    -- Executing [s@macro-blkvm-set:3] Set("SIP/185-00001900", "GOSUB_RETVAL=TRUE") in new stack
    -- Executing [s@macro-blkvm-set:4] MacroExit("SIP/185-00001900", "") in new stack
    -- Executing [605@ext-queues:4] ExecIf("SIP/185-00001900", "1?Set(_DIAL_OPTIONS=tTrM(auto-blkvm))") in new stack
    -- Executing [605@ext-queues:5] Set("SIP/185-00001900", "__NODEST=605") in new stack
    -- Executing [605@ext-queues:6] Set("SIP/185-00001900", "QCIDPP=SUPP:") in new stack
    -- Executing [605@ext-queues:7] Set("SIP/185-00001900", "VQ_CIDPP=") in new stack
    -- Executing [605@ext-queues:8] ExecIf("SIP/185-00001900", "1?Macro(prepend-cid,SUPP:)") in new stack
    -- Executing [s@macro-prepend-cid:1] GotoIf("SIP/185-00001900", "1?REPCID") in new stack
    -- Goto (macro-prepend-cid,s,5)
    -- Executing [s@macro-prepend-cid:5] Set("SIP/185-00001900", "_RGPREFIX=SUPP:") in new stack
    -- Executing [s@macro-prepend-cid:6] Set("SIP/185-00001900", "CALLERID(name)=SUPP:MY NAME") in new stack
    -- Executing [605@ext-queues:9] Set("SIP/185-00001900", "QAINFO=") in new stack
    -- Executing [605@ext-queues:10] Set("SIP/185-00001900", "VQ_AINFO=") in new stack
    -- Executing [605@ext-queues:11] ExecIf("SIP/185-00001900", "0?Set(__ALERT_INFO=)") in new stack
    -- Executing [605@ext-queues:12] Set("SIP/185-00001900", "QJOINMSG=") in new stack
    -- Executing [605@ext-queues:13] Set("SIP/185-00001900", "VQ_JOINMSG=") in new stack
    -- Executing [605@ext-queues:14] Set("SIP/185-00001900", "QMOH=") in new stack
    -- Executing [605@ext-queues:15] Set("SIP/185-00001900", "VQ_MOH=") in new stack
    -- Executing [605@ext-queues:16] ExecIf("SIP/185-00001900", "0?Set(__MOHCLASS=)") in new stack
    -- Executing [605@ext-queues:17] ExecIf("SIP/185-00001900", "0?Set(CHANNEL(musicclass)=)") in new stack
    -- Executing [605@ext-queues:18] Set("SIP/185-00001900", "QRETRY=n") in new stack
    -- Executing [605@ext-queues:19] Set("SIP/185-00001900", "VQ_RETRY=") in new stack
    -- Executing [605@ext-queues:20] Set("SIP/185-00001900", "QOPTIONS=tn") in new stack
    -- Executing [605@ext-queues:21] Set("SIP/185-00001900", "VQ_OPTIONS=") in new stack
    -- Executing [605@ext-queues:22] Set("SIP/185-00001900", "QGOSUB=") in new stack
    -- Executing [605@ext-queues:23] Set("SIP/185-00001900", "VQ_GOSUB=") in new stack
    -- Executing [605@ext-queues:24] Set("SIP/185-00001900", "QAGI=") in new stack
    -- Executing [605@ext-queues:25] Set("SIP/185-00001900", "VQ_AGI=") in new stack
    -- Executing [605@ext-queues:26] Set("SIP/185-00001900", "QRULE=") in new stack
    -- Executing [605@ext-queues:27] Set("SIP/185-00001900", "VQ_RULE=") in new stack
    -- Executing [605@ext-queues:28] Set("SIP/185-00001900", "QPOSITION=") in new stack
    -- Executing [605@ext-queues:29] Set("SIP/185-00001900", "VQ_POSITION=") in new stack
    -- Executing [605@ext-queues:30] Set("SIP/185-00001900", "__MIXMON_FORMAT=wav") in new stack
    -- Executing [605@ext-queues:31] Gosub("SIP/185-00001900", "sub-record-check,s,1(q,605,always)") in new stack
    -- Executing [s@sub-record-check:1] Set("SIP/185-00001900", "REC_POLICY_MODE_SAVE=") in new stack
    -- Executing [s@sub-record-check:2] GotoIf("SIP/185-00001900", "1?check") in new stack
    -- Goto (sub-record-check,s,7)
    -- Executing [s@sub-record-check:7] Set("SIP/185-00001900", "__MON_FMT=wav") in new stack
    -- Executing [s@sub-record-check:8] GotoIf("SIP/185-00001900", "1?next") in new stack
    -- Goto (sub-record-check,s,11)
    -- Executing [s@sub-record-check:11] ExecIf("SIP/185-00001900", "0?Return()") in new stack
    -- Executing [s@sub-record-check:12] ExecIf("SIP/185-00001900", "1?Set(__REC_POLICY_MODE=always)") in new stack
    -- Executing [s@sub-record-check:13] GotoIf("SIP/185-00001900", "0?q,1") in new stack
    -- Executing [s@sub-record-check:14] Set("SIP/185-00001900", "__REC_STATUS=INITIALIZED") in new stack
    -- Executing [s@sub-record-check:15] Set("SIP/185-00001900", "NOW=1441984303") in new stack
    -- Executing [s@sub-record-check:16] Set("SIP/185-00001900", "__DAY=11") in new stack
    -- Executing [s@sub-record-check:17] Set("SIP/185-00001900", "__MONTH=09") in new stack
    -- Executing [s@sub-record-check:18] Set("SIP/185-00001900", "__YEAR=2015") in new stack
    -- Executing [s@sub-record-check:19] Set("SIP/185-00001900", "__TIMESTR=20150911-101143") in new stack
    -- Executing [s@sub-record-check:20] Set("SIP/185-00001900", "__FROMEXTEN=185") in new stack
    -- Executing [s@sub-record-check:21] Set("SIP/185-00001900", "__CALLFILENAME=q-605-185-20150911-101143-1441984298.11683") in new stack
    -- Executing [s@sub-record-check:22] Goto("SIP/185-00001900", "q,1") in new stack
    -- Goto (sub-record-check,q,1)
    -- Executing [q@sub-record-check:1] GosubIf("SIP/185-00001900", "1?recq,1(q,605,185)") in new stack
    -- Executing [recq@sub-record-check:1] Set("SIP/185-00001900", "AUDIOHOOK_INHERIT(MixMonitor)=yes") in new stack
    -- Executing [recq@sub-record-check:2] Set("SIP/185-00001900", "MONITOR_FILENAME=2015/09/11/q-605-185-20150911-101143-1441984298.11683") in new stack
    -- Executing [recq@sub-record-check:3] MixMonitor("SIP/185-00001900", "2015/09/11/q-605-185-20150911-101143-1441984298.11683.wav,,") in new stack
    -- Executing [recq@sub-record-check:4] Set("SIP/185-00001900", "__REC_STATUS=RECORDING") in new stack
    -- Executing [recq@sub-record-check:5] Set("SIP/185-00001900", "CDR(recordingfile)=q-605-185-20150911-101143-1441984298.11683.wav") in new stack
    -- Executing [recq@sub-record-check:6] Return("SIP/185-00001900", "") in new stack
    -- Executing [q@sub-record-check:2] Return("SIP/185-00001900", "") in new stack
    -- Executing [605@ext-queues:32] ExecIf("SIP/185-00001900", "0?Playback(, )") in new stack
    -- Executing [605@ext-queues:33] QueueLog("SIP/185-00001900", "605,1441984298.11683,NONE,DID,") in new stack
    -- Executing [605@ext-queues:34] Set("SIP/185-00001900", "QAANNOUNCE=") in new stack
    -- Executing [605@ext-queues:35] Set("SIP/185-00001900", "VQ_AANNOUNCE=") in new stack
    -- Executing [605@ext-queues:36] Set("SIP/185-00001900", "QMAXWAIT=180") in new stack
    -- Executing [605@ext-queues:37] Set("SIP/185-00001900", "VQ_MAXWAIT=") in new stack
    -- Executing [605@ext-queues:38] Set("SIP/185-00001900", "QUEUENUM=605") in new stack
    -- Executing [605@ext-queues:39] Set("SIP/185-00001900", "QUEUEJOINTIME=1441984303") in new stack
    -- Executing [605@ext-queues:40] Queue("SIP/185-00001900", "605,tn,,,180,,,,,") in new stack
    -- Started music on hold, class 'default', on SIP/185-00001900
       > [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,userfield) VALUES ('CHAN_START',{ts '2015-09-11 10:11:43'},'','','','','','185','from-queue','Local/185@from-queue-00000a4b;1','','',3,'','1441984303.11684','1441984298.11683','','','')]
       > [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,userfield) VALUES ('CHAN_START',{ts '2015-09-11 10:11:43'},'','','','','','185','from-queue','Local/185@from-queue-00000a4b;2','','',3,'','1441984303.11685','1441984298.11683','','','')]
    -- Called Local/185@from-queue/n
    -- LazyMembers debugging - Numbusies: 0, Nummems: 0
  == Begin MixMonitor Recording SIP/185-00001900
    -- Executing [185@from-queue:1] Set("Local/185@from-queue-00000a4b;2", "QAGENT=185") in new stack
    -- Executing [185@from-queue:2] Goto("Local/185@from-queue-00000a4b;2", "605,1") in new stack
    -- Goto (from-queue,605,1)
    -- Executing [605@from-queue:1] Goto("Local/185@from-queue-00000a4b;2", "from-internal,185,1") in new stack
    -- Goto (from-internal,185,1)
    -- Executing [185@from-internal:1] GotoIf("Local/185@from-queue-00000a4b;2", "1?ext-local,185,1") in new stack
    -- Goto (ext-local,185,1)
    -- Executing [185@ext-local:1] Set("Local/185@from-queue-00000a4b;2", "__RINGTIMER=40") in new stack
    -- Executing [185@ext-local:2] Macro("Local/185@from-queue-00000a4b;2", "exten-vm,185,185,0,0,0") in new stack
    -- Executing [s@macro-exten-vm:1] Macro("Local/185@from-queue-00000a4b;2", "user-callerid,") in new stack
    -- Executing [s@macro-user-callerid:1] Set("Local/185@from-queue-00000a4b;2", "TOUCH_MONITOR=1441984303.11685") in new stack
    -- Executing [s@macro-user-callerid:2] Set("Local/185@from-queue-00000a4b;2", "AMPUSER=185") in new stack
    -- Executing [s@macro-user-callerid:3] GotoIf("Local/185@from-queue-00000a4b;2", "1?report") in new stack
    -- Goto (macro-user-callerid,s,16)
    -- Executing [s@macro-user-callerid:16] GotoIf("Local/185@from-queue-00000a4b;2", "0?continue") in new stack
    -- Executing [s@macro-user-callerid:17] Set("Local/185@from-queue-00000a4b;2", "__TTL=62") in new stack
    -- Executing [s@macro-user-callerid:18] GotoIf("Local/185@from-queue-00000a4b;2", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,29)
    -- Executing [s@macro-user-callerid:29] Set("Local/185@from-queue-00000a4b;2", "CALLERID(number)=185") in new stack
    -- Executing [s@macro-user-callerid:30] Set("Local/185@from-queue-00000a4b;2", "CALLERID(name)=SUPP:MY NAME") in new stack
    -- Executing [s@macro-user-callerid:31] Set("Local/185@from-queue-00000a4b;2", "CDR(cnum)=185") in new stack
    -- Executing [s@macro-user-callerid:32] Set("Local/185@from-queue-00000a4b;2", "CDR(cnam)=SUPP:MY NAME") in new stack
    -- Executing [s@macro-user-callerid:33] Set("Local/185@from-queue-00000a4b;2", "CHANNEL(language)=en") in new stack
    -- Executing [s@macro-exten-vm:2] Set("Local/185@from-queue-00000a4b;2", "RingGroupMethod=none") in new stack
    -- Executing [s@macro-exten-vm:3] Set("Local/185@from-queue-00000a4b;2", "__EXTTOCALL=185") in new stack
    -- Executing [s@macro-exten-vm:4] Set("Local/185@from-queue-00000a4b;2", "__PICKUPMARK=185") in new stack
    -- Executing [s@macro-exten-vm:5] Set("Local/185@from-queue-00000a4b;2", "RT=40") in new stack
    -- Executing [s@macro-exten-vm:6] Gosub("Local/185@from-queue-00000a4b;2", "sub-record-check,s,1(exten,185,)") in new stack
    -- Executing [s@sub-record-check:1] Set("Local/185@from-queue-00000a4b;2", "REC_POLICY_MODE_SAVE=always") in new stack
    -- Executing [s@sub-record-check:2] GotoIf("Local/185@from-queue-00000a4b;2", "1?check") in new stack
    -- Goto (sub-record-check,s,7)
    -- Executing [s@sub-record-check:7] Set("Local/185@from-queue-00000a4b;2", "__MON_FMT=wav") in new stack
    -- Executing [s@sub-record-check:8] GotoIf("Local/185@from-queue-00000a4b;2", "0?next") in new stack
    -- Executing [s@sub-record-check:9] Set("Local/185@from-queue-00000a4b;2", "CDR(recordingfile)=q-605-185-20150911-101143-1441984298.11683.wav") in new stack
    -- Executing [s@sub-record-check:10] Return("Local/185@from-queue-00000a4b;2", "") in new stack
    -- Executing [s@macro-exten-vm:7] GotoIf("Local/185@from-queue-00000a4b;2", "1?macrodial") in new stack
    -- Goto (macro-exten-vm,s,13)
    -- Executing [s@macro-exten-vm:13] GosubIf("Local/185@from-queue-00000a4b;2", "0?clrheader,1()") in new stack
    -- Executing [s@macro-exten-vm:14] Macro("Local/185@from-queue-00000a4b;2", "dial-one,40,tTrM(auto-blkvm),185") in new stack
    -- Executing [s@macro-dial-one:1] Set("Local/185@from-queue-00000a4b;2", "DEXTEN=185") in new stack
    -- Executing [s@macro-dial-one:2] Set("Local/185@from-queue-00000a4b;2", "DIALSTATUS_CW=") in new stack
    -- Executing [s@macro-dial-one:3] GosubIf("Local/185@from-queue-00000a4b;2", "0?screen,1()") in new stack
    -- Executing [s@macro-dial-one:4] GosubIf("Local/185@from-queue-00000a4b;2", "0?cf,1()") in new stack
    -- Executing [s@macro-dial-one:5] GotoIf("Local/185@from-queue-00000a4b;2", "1?skip1") in new stack
    -- Goto (macro-dial-one,s,8)
    -- Executing [s@macro-dial-one:8] GotoIf("Local/185@from-queue-00000a4b;2", "0?nodial") in new stack
    -- Executing [s@macro-dial-one:9] GotoIf("Local/185@from-queue-00000a4b;2", "0?continue") in new stack
    -- Executing [s@macro-dial-one:10] Set("Local/185@from-queue-00000a4b;2", "EXTHASCW=ENABLED") in new stack
    -- Executing [s@macro-dial-one:11] GotoIf("Local/185@from-queue-00000a4b;2", "0?next1:cwinusebusy") in new stack
    -- Goto (macro-dial-one,s,23)
    -- Executing [s@macro-dial-one:23] GotoIf("Local/185@from-queue-00000a4b;2", "1?next3:continue") in new stack
    -- Goto (macro-dial-one,s,24)
    -- Executing [s@macro-dial-one:24] ExecIf("Local/185@from-queue-00000a4b;2", "1?Set(DIALSTATUS_CW=BUSY)") in new stack
    -- Executing [s@macro-dial-one:25] GotoIf("Local/185@from-queue-00000a4b;2", "0?nodial") in new stack
    -- Executing [s@macro-dial-one:26] GosubIf("Local/185@from-queue-00000a4b;2", "1?dstring,1():dlocal,1()") in new stack
    -- Executing [dstring@macro-dial-one:1] Set("Local/185@from-queue-00000a4b;2", "DSTRING=") in new stack
    -- Executing [dstring@macro-dial-one:2] Set("Local/185@from-queue-00000a4b;2", "DEVICES=185") in new stack
    -- Executing [dstring@macro-dial-one:3] ExecIf("Local/185@from-queue-00000a4b;2", "0?Return()") in new stack
    -- Executing [dstring@macro-dial-one:4] ExecIf("Local/185@from-queue-00000a4b;2", "0?Set(DEVICES=85)") in new stack
    -- Executing [dstring@macro-dial-one:5] Set("Local/185@from-queue-00000a4b;2", "LOOPCNT=1") in new stack
    -- Executing [dstring@macro-dial-one:6] Set("Local/185@from-queue-00000a4b;2", "ITER=1") in new stack
    -- Executing [dstring@macro-dial-one:7] Set("Local/185@from-queue-00000a4b;2", "THISDIAL=SIP/185") in new stack
    -- Executing [dstring@macro-dial-one:8] GosubIf("Local/185@from-queue-00000a4b;2", "1?zap2dahdi,1()") in new stack
    -- Executing [zap2dahdi@macro-dial-one:1] ExecIf("Local/185@from-queue-00000a4b;2", "0?Return()") in new stack
    -- Executing [zap2dahdi@macro-dial-one:2] Set("Local/185@from-queue-00000a4b;2", "NEWDIAL=") in new stack
    -- Executing [zap2dahdi@macro-dial-one:3] Set("Local/185@from-queue-00000a4b;2", "LOOPCNT2=1") in new stack
    -- Executing [zap2dahdi@macro-dial-one:4] Set("Local/185@from-queue-00000a4b;2", "ITER2=1") in new stack
    -- Executing [zap2dahdi@macro-dial-one:5] Set("Local/185@from-queue-00000a4b;2", "THISPART2=SIP/185") in new stack
    -- Executing [zap2dahdi@macro-dial-one:6] ExecIf("Local/185@from-queue-00000a4b;2", "0?Set(THISPART2=DAHDI/185)") in new stack
    -- Executing [zap2dahdi@macro-dial-one:7] Set("Local/185@from-queue-00000a4b;2", "NEWDIAL=SIP/185&") in new stack
    -- Executing [zap2dahdi@macro-dial-one:8] Set("Local/185@from-queue-00000a4b;2", "ITER2=2") in new stack
    -- Executing [zap2dahdi@macro-dial-one:9] GotoIf("Local/185@from-queue-00000a4b;2", "0?begin2") in new stack
    -- Executing [zap2dahdi@macro-dial-one:10] Set("Local/185@from-queue-00000a4b;2", "THISDIAL=SIP/185") in new stack
    -- Executing [zap2dahdi@macro-dial-one:11] Return("Local/185@from-queue-00000a4b;2", "") in new stack
    -- Executing [dstring@macro-dial-one:9] Set("Local/185@from-queue-00000a4b;2", "DSTRING=SIP/185&") in new stack
    -- Executing [dstring@macro-dial-one:10] Set("Local/185@from-queue-00000a4b;2", "ITER=2") in new stack
    -- Executing [dstring@macro-dial-one:11] GotoIf("Local/185@from-queue-00000a4b;2", "0?begin") in new stack
    -- Executing [dstring@macro-dial-one:12] Set("Local/185@from-queue-00000a4b;2", "DSTRING=SIP/185") in new stack
    -- Executing [dstring@macro-dial-one:13] Return("Local/185@from-queue-00000a4b;2", "") in new stack
    -- Executing [s@macro-dial-one:27] GotoIf("Local/185@from-queue-00000a4b;2", "0?nodial") in new stack
    -- Executing [s@macro-dial-one:28] GotoIf("Local/185@from-queue-00000a4b;2", "0?skiptrace") in new stack
    -- Executing [s@macro-dial-one:29] GosubIf("Local/185@from-queue-00000a4b;2", "1?ctset,1():ctclear,1()") in new stack
    -- Executing [ctset@macro-dial-one:1] Set("Local/185@from-queue-00000a4b;2", "DB(CALLTRACE/185)=185") in new stack
    -- Executing [ctset@macro-dial-one:2] Return("Local/185@from-queue-00000a4b;2", "") in new stack
    -- Executing [s@macro-dial-one:30] Set("Local/185@from-queue-00000a4b;2", "D_OPTIONS=tTrM(auto-blkvm)") in new stack
    -- Executing [s@macro-dial-one:31] ExecIf("Local/185@from-queue-00000a4b;2", "0?SIPAddHeader(Alert-Info: )") in new stack
    -- Executing [s@macro-dial-one:32] ExecIf("Local/185@from-queue-00000a4b;2", "0?SIPAddHeader()") in new stack
    -- Executing [s@macro-dial-one:33] ExecIf("Local/185@from-queue-00000a4b;2", "0?Set(CHANNEL(musicclass)=)") in new stack
    -- Executing [s@macro-dial-one:34] GosubIf("Local/185@from-queue-00000a4b;2", "0?qwait,1()") in new stack
    -- Executing [s@macro-dial-one:35] Set("Local/185@from-queue-00000a4b;2", "__CWIGNORE=") in new stack
    -- Executing [s@macro-dial-one:36] Set("Local/185@from-queue-00000a4b;2", "__KEEPCID=TRUE") in new stack
    -- Executing [s@macro-dial-one:37] GotoIf("Local/185@from-queue-00000a4b;2", "0?usegoto,1") in new stack
    -- Executing [s@macro-dial-one:38] GotoIf("Local/185@from-queue-00000a4b;2", "0?godial") in new stack
    -- Executing [s@macro-dial-one:39] Gosub("Local/185@from-queue-00000a4b;2", "sub-presencestate-display,s,1(185)") in new stack
[2015-09-11 10:11:43] WARNING[29110][C-00000991]: func_presencestate.c:132 presence_read: PRESENCE_STATE unknown
[2015-09-11 10:11:43] WARNING[29110][C-00000991]: func_presencestate.c:132 presence_read: PRESENCE_STATE unknown
    -- Executing [s@sub-presencestate-display:1] Goto("Local/185@from-queue-00000a4b;2", "state-,1") in new stack
    -- Goto (sub-presencestate-display,state-,1)
    -- Executing [state-@sub-presencestate-display:1] Set("Local/185@from-queue-00000a4b;2", "PRESENCESTATE_DISPLAY=") in new stack
    -- Executing [state-@sub-presencestate-display:2] Return("Local/185@from-queue-00000a4b;2", "") in new stack
    -- Executing [s@macro-dial-one:40] Set("Local/185@from-queue-00000a4b;2", "CONNECTEDLINE(name,i)=MY NAME") in new stack
    -- Executing [s@macro-dial-one:41] Set("Local/185@from-queue-00000a4b;2", "CONNECTEDLINE(num)=185") in new stack
    -- Local/185@from-queue-00000a4b;1 connected line has changed. Saving it until answer for SIP/185-00001900
    -- Executing [s@macro-dial-one:42] Set("Local/185@from-queue-00000a4b;2", "D_OPTIONS=tTrM(auto-blkvm)I") in new stack
    -- Executing [s@macro-dial-one:43] Dial("Local/185@from-queue-00000a4b;2", "SIP/185,40,tTrM(auto-blkvm)I") in new stack
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
       > [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,userfield) VALUES ('CHAN_START',{ts '2015-09-11 10:11:43'},'MY NAME','185','','','','s','from-internal','SIP/185-00001901','','',3,'','1441984303.11686','1441984298.11683','','','')]
  == Extension Changed 185[ext-local] new state InUse&Ringing for Notify User 130
  == Extension Changed 185[ext-local] new state InUse&Ringing for Notify User 201
  == Extension Changed 185[ext-local] new state InUse&Ringing for Notify User 120
  == Extension Changed 185[ext-local] new state InUse&Ringing for Notify User 110
  == Extension Changed 185[ext-local] new state InUse&Ringing for Notify User 180
    -- Called SIP/185
    -- Local/185@from-queue-00000a4b;1 is ringing
    -- Connected line update to Local/185@from-queue-00000a4b;2 prevented.
    -- SIP/185-00001901 is ringing
  == Extension Changed 185[ext-local] new state InUse&Ringing for Notify User 130
  == Extension Changed 185[ext-local] new state InUse&Ringing for Notify User 201
  == Extension Changed 185[ext-local] new state InUse&Ringing for Notify User 120
  == Extension Changed 185[ext-local] new state InUse&Ringing for Notify User 110
  == Extension Changed 185[ext-local] new state InUse&Ringing for Notify User 180
    -- Local/185@from-queue-00000a4b;1 is ringing
    -- SIP/185-00001901 is ringing
pbx*CLI>
    -- Nobody picked up in 40000 ms

From here, the call goes to Queue’s failover destination.

FS_Arci · October 1, 2015, 1:07pm

I am still experiencing the same problem.
I’ve tried playing with the break-out IVR settings, but nothing seems to work.

I noticed that pressing 1 (the break out option) still works and I can break out and leave a VM (even if the announcement interval time hasn’t passed). The announcement is still not being played.

Any suggestions would be appreciated.

fuiana · May 15, 2018, 2:44pm

After two years I have the same problem, does anyone had found a solution?

Thanks

adtopkek · May 15, 2018, 3:35pm

Work in Freepbx 14 asterisk 13. Upgrade?