Queue not working - fails over to a voicemail as expected

I created a Queue named 400. I added static extension to the queue. The queue is access from the IVR, press 1 for sales etc etc. The queue rings for the end user but none of the extension actually ring. After the timeout it rolls over to a voicemail.

The log show the queue does something but I havent a clue what the log is telling me. Can anyone help please?

– Executing [s@ivr-2:7] Answer(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “”) in new stack
> 0x7fde38f77da0 – Probation passed - setting RTP source address to 67.231.4.102:27084
– Executing [s@ivr-2:8] Wait(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “1”) in new stack
– Executing [s@ivr-2:9] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “IVR_MSG=custom/mmas-mainmenu”) in new stack
– Executing [s@ivr-2:10] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “TIMEOUT(digit)=3”) in new stack
– Digit timeout set to 3.000
– Executing [s@ivr-2:11] ExecIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “1?Background(custom/mmas-mainmenu)”) in new stack
– <SIP/fpbx-1-fyCauIrNpsJg-0000159d> Playing ‘custom/mmas-mainmenu.slin’ (language ‘en’)
– Executing [1@ivr-2:1] Goto(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “ext-queues,400,1”) in new stack
– Goto (ext-queues,400,1)
– Executing [400@ext-queues:1] Macro(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “user-callerid,”) in new stack
– Executing [s@macro-user-callerid:1] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “TOUCH_MONITOR=1464905915.42493”) in new stack
– Executing [s@macro-user-callerid:2] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “AMPUSER=17758889999”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “0?report”) in new stack
– Executing [s@macro-user-callerid:4] ExecIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “1?Set(REALCALLERIDNUM=17758889999)”) in new stack
– Executing [s@macro-user-callerid:5] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “AMPUSER=”) in new stack
– Executing [s@macro-user-callerid:6] GotoIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “0?limit”) in new stack
– Executing [s@macro-user-callerid:7] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “AMPUSERCIDNAME=”) in new stack
– Executing [s@macro-user-callerid:8] GotoIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “1?report”) in new stack
– Goto (macro-user-callerid,s,15)
– Executing [s@macro-user-callerid:15] GotoIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:16] ExecIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “1?Set(__CALLEE_ACCOUNCODE=)”) in new stack
– Executing [s@macro-user-callerid:17] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “__TTL=64”) in new stack
– Executing [s@macro-user-callerid:18] GotoIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,29)
– Executing [s@macro-user-callerid:29] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “CALLERID(number)=17758889999”) in new stack
– Executing [s@macro-user-callerid:30] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “CALLERID(name)=Wilson MARK”) in new stack
– Executing [s@macro-user-callerid:31] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “CDR(cnum)=17758889999”) in new stack
– Executing [s@macro-user-callerid:32] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “CDR(cnam)=Wilson MARK”) in new stack
– Executing [s@macro-user-callerid:33] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “CHANNEL(language)=en”) in new stack
– Executing [400@ext-queues:2] Answer(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “”) in new stack
– Executing [400@ext-queues:3] Macro(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “blkvm-set,reset”) in new stack
– Executing [s@macro-blkvm-set:1] ExecIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “1?Set(__BLKVM_CHANNEL=SIP/fpbx-1-fyCauIrNpsJg-0000159d)”) in new stack
– Executing [s@macro-blkvm-set:2] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “SHARED(BLKVM,SIP/fpbx-1-fyCauIrNpsJg-0000159d)=TRUE”) in new stack
– Executing [s@macro-blkvm-set:3] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “GOSUB_RETVAL=TRUE”) in new stack
– Executing [s@macro-blkvm-set:4] MacroExit(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “”) in new stack
– Executing [400@ext-queues:4] ExecIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “1?Set(_DIAL_OPTIONS=TtrM(auto-blkvm))”) in new stack
– Executing [400@ext-queues:5] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “__NODEST=400”) in new stack
– Executing [400@ext-queues:6] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “QCIDPP=Sales:”) in new stack
– Executing [400@ext-queues:7] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “VQ_CIDPP=”) in new stack
– Executing [400@ext-queues:8] ExecIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “1?Macro(prepend-cid,Sales:)”) in new stack
– Executing [s@macro-prepend-cid:1] GotoIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “1?REPCID”) in new stack
– Goto (macro-prepend-cid,s,5)
– Executing [s@macro-prepend-cid:5] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “_RGPREFIX=Sales:”) in new stack
– Executing [s@macro-prepend-cid:6] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “CALLERID(name)=Sales:Wilson MARK”) in new stack
– Executing [400@ext-queues:9] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “QAINFO=”) in new stack
– Executing [400@ext-queues:10] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “VQ_AINFO=”) in new stack
– Executing [400@ext-queues:11] ExecIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “0?Set(__ALERT_INFO=)”) in new stack
– Executing [400@ext-queues:12] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “QJOINMSG=”) in new stack
– Executing [400@ext-queues:13] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “VQ_JOINMSG=”) in new stack
– Executing [400@ext-queues:14] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “QRINGOPTS=r”) in new stack
– Executing [400@ext-queues:15] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “QRETRY=”) in new stack
– Executing [400@ext-queues:16] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “VQ_RETRY=”) in new stack
– Executing [400@ext-queues:17] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “QOPTIONS=tr”) in new stack
– Executing [400@ext-queues:18] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “VQ_OPTIONS=”) in new stack
– Executing [400@ext-queues:19] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “QGOSUB=”) in new stack
– Executing [400@ext-queues:20] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “VQ_GOSUB=”) in new stack
– Executing [400@ext-queues:21] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “QAGI=”) in new stack
– Executing [400@ext-queues:22] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “VQ_AGI=”) in new stack
– Executing [400@ext-queues:23] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “QRULE=”) in new stack
– Executing [400@ext-queues:24] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “VQ_RULE=”) in new stack
– Executing [400@ext-queues:25] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “QPOSITION=”) in new stack
– Executing [400@ext-queues:26] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “VQ_POSITION=”) in new stack
– Executing [400@ext-queues:27] Gosub(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “sub-record-check,s,1(q,400,dontcare)”) in new stack
– Executing [s@sub-record-check:1] GotoIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “0?initialized”) in new stack
– Executing [s@sub-record-check:2] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “__REC_STATUS=INITIALIZED”) in new stack
– Executing [s@sub-record-check:3] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “NOW=1464905924”) in new stack
– Executing [s@sub-record-check:4] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “__DAY=02”) in new stack
– Executing [s@sub-record-check:5] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “__MONTH=06”) in new stack
– Executing [s@sub-record-check:6] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “__YEAR=2016”) in new stack
– Executing [s@sub-record-check:7] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “__TIMESTR=20160602-151844”) in new stack
– Executing [s@sub-record-check:8] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “__FROMEXTEN=17758889999”) in new stack
– Executing [s@sub-record-check:9] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “__MON_FMT=wav”) in new stack
– Executing [s@sub-record-check:10] NoOp(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “Recordings initialized”) in new stack
– Executing [s@sub-record-check:11] ExecIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “0?Set(ARG3=dontcare)”) in new stack
– Executing [s@sub-record-check:12] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “REC_POLICY_MODE_SAVE=”) in new stack
– Executing [s@sub-record-check:13] ExecIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “0?Set(REC_STATUS=NO)”) in new stack
– Executing [s@sub-record-check:14] GotoIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “1?checkaction”) in new stack
– Goto (sub-record-check,s,17)
– Executing [s@sub-record-check:17] GotoIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “0?sub-record-check,q,1”) in new stack
– Executing [s@sub-record-check:18] NoOp(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “Generic q Recording Check - 17758889999 400”) in new stack
– Executing [s@sub-record-check:19] Gosub(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “recordcheck,1(dontcare,q,400)”) in new stack
– Executing [recordcheck@sub-record-check:1] NoOp(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “Starting recording check against dontcare”) in new stack
– Executing [recordcheck@sub-record-check:2] Goto(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “dontcare”) in new stack
– Goto (sub-record-check,recordcheck,3)
– Executing [recordcheck@sub-record-check:3] Return(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “”) in new stack
– Executing [s@sub-record-check:20] Return(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “”) in new stack
– Executing [400@ext-queues:28] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “__CWIGNORE=TRUE”) in new stack
– Executing [400@ext-queues:29] ExecIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “0?Playback(, )”) in new stack
– Executing [400@ext-queues:30] QueueLog(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “400,1464905915.42493,NONE,DID,7758514488”) in new stack
– Executing [400@ext-queues:31] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “QAANNOUNCE=”) in new stack
– Executing [400@ext-queues:32] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “VQ_AANNOUNCE=”) in new stack
– Executing [400@ext-queues:33] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “QMOH=”) in new stack
– Executing [400@ext-queues:34] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “VQ_MOH=”) in new stack
– Executing [400@ext-queues:35] ExecIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “0?Set(__MOHCLASS=)”) in new stack
– Executing [400@ext-queues:36] ExecIf(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “0?Set(CHANNEL(musicclass)=)”) in new stack
– Executing [400@ext-queues:37] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “QMAXWAIT=16”) in new stack
– Executing [400@ext-queues:38] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “VQ_MAXWAIT=”) in new stack
– Executing [400@ext-queues:39] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “QUEUENUM=400”) in new stack
– Executing [400@ext-queues:40] Set(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “QUEUEJOINTIME=1464905924”) in new stack
– Executing [400@ext-queues:41] Queue(“SIP/fpbx-1-fyCauIrNpsJg-0000159d”, “400,tr,16,”) in new stack
– Called Local/269@from-queue/n
– Executing [269@from-queue:1] Set(“Local/269@from-queue-0000019c;2”, “QAGENT=269”) in new stack
– Executing [269@from-queue:2] Goto(“Local/269@from-queue-0000019c;2”, “400,1”) in new stack
– Goto (from-queue,400,1)
– Executing [400@from-queue:1] Goto(“Local/269@from-queue-0000019c;2”, “from-internal,269,1”) in new stack
– Goto (from-internal,269,1)
– Executing [269@from-internal:1] GotoIf(“Local/269@from-queue-0000019c;2”, “0?ext-local,269,1”) in new stack
– Executing [269@from-internal:2] Macro(“Local/269@from-queue-0000019c;2”, “user-callerid,”) in new stack
– Executing [s@macro-user-callerid:1] Set(“Local/269@from-queue-0000019c;2”, “TOUCH_MONITOR=1464905924.42499”) in new stack
– Executing [s@macro-user-callerid:2] Set(“Local/269@from-queue-0000019c;2”, “AMPUSER=17758889999”) in new stack
– Called Local/394@from-queue/n
– Executing [s@macro-user-callerid:3] GotoIf(“Local/269@from-queue-0000019c;2”, “1?report”) in new stack
– Goto (macro-user-callerid,s,15)
– Executing [s@macro-user-callerid:15] GotoIf(“Local/269@from-queue-0000019c;2”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:16] ExecIf(“Local/269@from-queue-0000019c;2”, “1?Set(__CALLEE_ACCOUNCODE=)”) in new stack
– Executing [s@macro-user-callerid:17] Set(“Local/269@from-queue-0000019c;2”, “__TTL=63”) in new stack
– Executing [s@macro-user-callerid:18] GotoIf(“Local/269@from-queue-0000019c;2”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,29)
– Executing [s@macro-user-callerid:29] Set(“Local/269@from-queue-0000019c;2”, “CALLERID(number)=17758889999”) in new stack
– Executing [s@macro-user-callerid:30] Set(“Local/269@from-queue-0000019c;2”, “CALLERID(name)=Sales:Wilson MARK”) in new stack
– Executing [394@from-queue:1] Set(“Local/394@from-queue-0000019d;2”, “QAGENT=394”) in new stack
– Executing [394@from-queue:2] Goto(“Local/394@from-queue-0000019d;2”, “400,1”) in new stack
– Goto (from-queue,400,1)
– Executing [400@from-queue:1] Goto(“Local/394@from-queue-0000019d;2”, “from-internal,394,1”) in new stack
– Goto (from-internal,394,1)
– Called Local/255@from-queue/n
– Executing [394@from-internal:1] GotoIf(“Local/394@from-queue-0000019d;2”, “0?ext-local,394,1”) in new stack
– Executing [394@from-internal:2] Macro(“Local/394@from-queue-0000019d;2”, “user-callerid,”) in new stack
– Executing [s@macro-user-callerid:31] Set(“Local/269@from-queue-0000019c;2”, “CDR(cnum)=17758889999”) in new stack
– Executing [s@macro-user-callerid:32] Set(“Local/269@from-queue-0000019c;2”, “CDR(cnam)=Sales:Wilson MARK”) in new stack
– Executing [s@macro-user-callerid:1] Set(“Local/394@from-queue-0000019d;2”, “TOUCH_MONITOR=1464905924.42503”) in new stack
– Executing [s@macro-user-callerid:2] Set(“Local/394@from-queue-0000019d;2”, “AMPUSER=17758889999”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“Local/394@from-queue-0000019d;2”, “1?report”) in new stack
– Goto (macro-user-callerid,s,15)
– Executing [s@macro-user-callerid:15] GotoIf(“Local/394@from-queue-0000019d;2”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:16] ExecIf(“Local/394@from-queue-0000019d;2”, “1?Set(__CALLEE_ACCOUNCODE=)”) in new stack
– Called Local/225@from-queue/n
– Executing [s@macro-user-callerid:33] Set(“Local/269@from-queue-0000019c;2”, “CHANNEL(language)=en”) in new stack
– Executing [269@from-internal:3] Set(“Local/269@from-queue-0000019c;2”, “DIAL_OPTIONS=TtrM(auto-blkvm)I”) in new stack
– Executing [269@from-internal:4] Set(“Local/269@from-queue-0000019c;2”, “CONNECTEDLINE(num,i)=269”) in new stack
– Executing [269@from-internal:5] Gosub(“Local/269@from-queue-0000019c;2”, “sub-presencestate-display,s,1(269)”) in new stack
– Executing [s@sub-presencestate-display:1] Goto(“Local/269@from-queue-0000019c;2”, “state-not_set,1”) in new stack
– Goto (sub-presencestate-display,state-not_set,1)
– Executing [state-not_set@sub-presencestate-display:1] Set(“Local/269@from-queue-0000019c;2”, “PRESENCESTATE_DISPLAY=”) in new stack
– Executing [state-not_set@sub-presencestate-display:2] Return(“Local/269@from-queue-0000019c;2”, “”) in new stack
– Executing [269@from-internal:6] Set(“Local/269@from-queue-0000019c;2”, “CONNECTEDLINE(name)=Mark Wilson Desk”) in new stack
– Executing [269@from-internal:7] Set(“Local/269@from-queue-0000019c;2”, “FM_DIALSTATUS=NOT_INUSE”) in new stack
– Executing [269@from-internal:8] Set(“Local/269@from-queue-0000019c;2”, “__EXTTOCALL=269”) in new stack
– Executing [255@from-queue:1] Set(“Local/255@from-queue-0000019e;2”, “QAGENT=255”) in new stack
– Executing [255@from-queue:2] Goto(“Local/255@from-queue-0000019e;2”, “400,1”) in new stack
– Goto (from-queue,400,1)
– Executing [400@from-queue:1] Goto(“Local/255@from-queue-0000019e;2”, “from-internal,255,1”) in new stack
– Goto (from-internal,255,1)
– Executing [255@from-internal:1] GotoIf(“Local/255@from-queue-0000019e;2”, “0?ext-local,255,1”) in new stack

and goes on for several more pages all look the same

This doesnt look right:

asterisk -rx "queue show 400"
400 has 0 calls (max unlimited) in ‘ringall’ strategy (2s holdtime, 73s talktime), W:0, C:2, A:14, SL:100.0% within 60s
Members:
Flavio Garcia (Local/234@from-queue/n from hint:234@ext-local) (ringinuse enabled) (Unavailable) has taken no calls yet
Enrique (Local/392@from-queue/n from hint:392@ext-local) (ringinuse enabled) (Not in use) has taken no calls yet
Johnny Jackson C (Local/355@from-queue/n from hint:355@ext-local) (ringinuse enabled) (Unavailable) has taken no calls yet
Matt Ellison (Local/262@from-queue/n from hint:262@ext-local) (ringinuse enabled) (Not in use) has taken no calls yet
Austin Price (Local/227@from-queue/n from hint:227@ext-local) (ringinuse enabled) (Unavailable) has taken no calls yet
Andre Logan (Local/225@from-queue/n from hint:225@ext-local) (ringinuse enabled) (Not in use) has taken no calls yet
Johnny Jackson (Local/255@from-queue/n from hint:255@ext-local) (ringinuse enabled) (Unavailable) has taken no calls yet
Johnny (Local/394@from-queue/n from hint:394@ext-local) (ringinuse enabled) (Not in use) has taken no calls yet
Mark Worsnop Desk (Local/269@from-queue/n from hint:269@ext-local) (ringinuse enabled) (Not in use) has taken no calls yet
No Callers

From logs, it seems agent was picked up but call does not get transfer to that agent.
Can you try to change strategy from ringall to leastfewest or something else. Also give a try to remove failover destination and see if the call reaches the agent.