Queue Issues... extensions ring but don't pick up

Hi Folks,

FreePBX 2.9.0.12
Asterisk 1.8.12.0

The issue I’m experiencing takes place with both SIP and IAX trunks. What happens is that I have inbound calls routed to an IVR and then some options go to Queues, ie. 1 sales and 2 support.

When the calls get in queue and the extension rings, the extension picks up but with no audio and the call is actually still in the queue so it really doesn’t pick up the call itself.

I have provided some output for your review and any suggestions/comments.

Thanks in advance for any help!

-- Executing [[email protected]:10] Set("SIP/8003-00000050", "DIAL_TRUNK_OPTIONS=") in new stack
-- Executing [[email protected]:11] Macro("SIP/8003-00000050", "outbound-callerid,7") in new stack
-- Executing [[email protected]:1] ExecIf("SIP/8003-00000050", "0?Set(CALLERPRES()=)") in new stack
-- Executing [[email protected]:2] ExecIf("SIP/8003-00000050", "0?Set(REALCALLERIDNUM=8003)") in new stack
-- Executing [[email protected]:3] GotoIf("SIP/8003-00000050", "1?normcid") in new stack
-- Goto (macro-outbound-callerid,s,6)
-- Executing [[email protected]:6] Set("SIP/8003-00000050", "USEROUTCID="TEST" <5555555555>") in new stack
-- Executing [[email protected]:7] Set("SIP/8003-00000050", "EMERGENCYCID=") in new stack
-- Executing [[email protected]:8] Set("SIP/8003-00000050", "TRUNKOUTCID="TEST 2" <4444444444>") in new stack
-- Executing [[email protected]:9] GotoIf("SIP/8003-00000050", "1?trunkcid") in new stack
-- Goto (macro-outbound-callerid,s,12)
-- Executing [[email protected]:12] ExecIf("SIP/8003-00000050", "1?Set(CALLERID(all)="TEST 2" <4444444444>)") in new stack
-- Executing [[email protected]:13] ExecIf("SIP/8003-00000050", "1?Set(CALLERID(all)="TEST" <55555555557>)") in new stack
-- Executing [[email protected]:14] ExecIf("SIP/8003-00000050", "0?Set(CALLERID(all)=)") in new stack
-- Executing [[email protected]:15] ExecIf("SIP/8003-00000050", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
-- Executing [[email protected]:12] GosubIf("SIP/8003-00000050", "0?sub-flp-7,s,1") in new stack
-- Executing [[email protected]:13] Set("SIP/8003-00000050", "OUTNUM=4444444444") in new stack
-- Executing [[email protected]:14] Set("SIP/8003-00000050", "custom=IAX2/4444444444") in new stack
-- Executing [[email protected]:15] ExecIf("SIP/8003-00000050", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default))") in new stack
-- Executing [[email protected]:16] ExecIf("SIP/8003-00000050", "0?Set(DIAL_TRUNK_OPTIONS=M(confirm))") in new stack
-- Executing [[email protected]:17] Macro("SIP/8003-00000050", "dialout-trunk-predial-hook,") in new stack
-- Executing [[email protected]:1] MacroExit("SIP/8003-00000050", "") in new stack
-- Executing [[email protected]:18] GotoIf("SIP/8003-00000050", "0?bypass,1") in new stack
-- Executing [[email protected]:19] GotoIf("SIP/8003-00000050", "0?customtrunk") in new stack
-- Executing [[email protected]:20] Dial("SIP/8003-00000050", "IAX2/4444444444/4444444444,300,") in new stack
-- Called IAX2/4444444444/4444444444
-- Call accepted by 209.217.198.158 (format ulaw)
-- Format for call is ulaw
-- Accepting AUTHENTICATED call from 209.217.198.158:
   > requested format = ulaw,
   > requested prefs = (ulaw|gsm),
   > actual format = ulaw,
   > host prefs = (ulaw),
   > priority = mine
-- Executing [[email protected]:1] Set("IAX2/4444444444-2474", "__FROM_DID=4444444444") in new stack
-- Executing [[email protected]:2] Gosub("IAX2/4444444444-2474", "app-blacklist-check,s,1") in new stack
-- Executing [[email protected]:1] GotoIf("IAX2/4444444444-2474", "0?blacklisted") in new stack
-- Executing [[email protected]:2] Set("IAX2/4444444444-2474", "CALLED_BLACKLIST=1") in new stack
-- Executing [[email protected]:3] Return("IAX2/4444444444-2474", "") in new stack
-- Executing [[email protected]:3] ExecIf("IAX2/4444444444-2474", "0 ?Set(CALLERID(name)=5555555555)") in new stack
-- Executing [[email protected]:4] Set("IAX2/4444444444-2474", "__CALLINGPRES_SV=allowed_not_screened") in new stack
-- Executing [[email protected]:5] Set("IAX2/4444444444-2474", "CALLERPRES()=allowed_not_screened") in new stack
-- Executing [[email protected]:6] Goto("IAX2/4444444444-2474", "ivr-4,s,1") in new stack
-- Goto (ivr-4,s,1)
-- Executing [[email protected]:1] Set("IAX2/4444444444-2474", "MSG=custom/iml-ivr-main") in new stack
-- Executing [[email protected]:2] Set("IAX2/4444444444-2474", "LOOPCOUNT=0") in new stack
-- Executing [[email protected]:3] Set("IAX2/4444444444-2474", "__DIR-CONTEXT=") in new stack
-- Executing [[email protected]:4] Set("IAX2/4444444444-2474", "_IVR_CONTEXT_ivr-4=") in new stack
-- Executing [[email protected]:5] Set("IAX2/4444444444-2474", "_IVR_CONTEXT=ivr-4") in new stack
-- Executing [[email protected]:6] GotoIf("IAX2/4164790469-2474", "0?begin") in new stack
-- Executing [[email protected]:7] Answer("IAX2/4444444444-2474", "") in new stack
-- Executing [[email protected]:8] Wait("IAX2/4444444444-2474", "1") in new stack
-- IAX2/4444444444-13012 answered SIP/8003-00000050
-- Executing [[email protected]:9] Set("IAX2/4444444444", "TIMEOUT(digit)=3") in new stack
-- Digit timeout set to 3.000
-- Executing [[email protected]:10] Set("IAX2/4444444444-2474", "TIMEOUT(response)=10") in new stack
-- Response timeout set to 10.000
-- Executing [[email protected]:11] Set("IAX2/4444444444-2474", "__IVR_RETVM=") in new stack
-- Executing [[email protected]:12] ExecIf("IAX2/4444444444-2474", "1?Background(custom/iml-ivr-main)") in new stack
-- <IAX2/4444444444-2474> Playing 'custom/iml-ivr-main.slin' (language 'en')
-- Registered SIP '8002' at 99.229.244.3:53408
-- Executing [[email protected]:1] Macro("IAX2/4444444444-2474", "blkvm-clr,") in new stack
-- Executing [[email protected]:1] Set("IAX2/4444444444-2474", "SHARED(BLKVM,)=") in new stack
-- Executing [[email protected]:2] Set("IAX2/4444444444-2474", "GOSUB_RETVAL=") in new stack
-- Executing [[email protected]:3] MacroExit("IAX2/4444444444-2474", "") in new stack
-- Executing [[email protected]:2] Set("IAX2/4444444444-2474", "__NODEST=") in new stack
-- Executing [[email protected]:3] Goto("IAX2/4444444444-2474", "ext-queues,666,1") in new stack
-- Goto (ext-queues,666,1)
-- Executing [[email protected]:1] Macro("IAX2/4444444444-2474", "user-callerid,") in new stack
-- Executing [[email protected]:1] Set("IAX2/4444444444-2474", "AMPUSER=5555555555") in new stack
-- Executing [[email protected]:2] GotoIf("IAX2/4444444444-2474", "0?report") in new stack
-- Executing [[email protected]:3] ExecIf("IAX2/4444444444-2474", "1?Set(REALCALLERIDNUM=5555555555)") in new stack
-- Executing [[email protected]:4] Set("IAX2/4444444444-2474", "AMPUSER=") in new stack
-- Executing [[email protected]:5] Set("IAX2/4444444444-2474", "AMPUSERCIDNAME=") in new stack
-- Executing [[email protected]:6] GotoIf("IAX2/4444444444-2474", "1?report") in new stack
-- Goto (macro-user-callerid,s,12)
-- Executing [[email protected]:12] GotoIf("IAX2/4444444444-2474", "0?continue") in new stack
-- Executing [[email protected]:13] Set("IAX2/4444444444-2474", "__TTL=64") in new stack
-- Executing [[email protected]:14] GotoIf("IAX2/4444444444-2474", "1?continue") in new stack
-- Goto (macro-user-callerid,s,25)
-- Executing [[email protected]:25] Set("IAX2/4444444444-2474", "CALLERID(number)=9054994227") in new stack
-- Executing [[email protected]:26] Set("IAX2/4444444444-2474", "CALLERID(name)=M TANG FONG") in new stack
-- Executing [[email protected]:27] Set("IAX2/4444444444-2474", "CHANNEL(language)=en") in new stack
-- Executing [[email protected]:2] Answer("IAX2/4444444444-2474", "") in new stack
-- Executing [[email protected]:3] Macro("IAX2/4444444444-2474", "blkvm-set,reset") in new stack
-- Executing [[email protected]:1] ExecIf("IAX2/4444444444-2474", "1?Set(__BLKVM_CHANNEL=IAX2/4444444444-2474)") in new stack
-- Executing [[email protected]:2] Set("IAX2/4444444444-2474", "SHARED(BLKVM,IAX2/4444444444-2474)=TRUE") in new stack
-- Executing [[email protected]:3] Set("IAX2/4444444444-2474", "GOSUB_RETVAL=TRUE") in new stack
-- Executing [[email protected]:4] MacroExit("IAX2/4444444444-2474", "") in new stack
-- Executing [[email protected]:4] ExecIf("IAX2/4444444444-2474", "1?Set(_DIAL_OPTIONS=trM(auto-blkvm))") in new stack
-- Executing [[email protected]:5] Set("IAX2/4444444444-2474", "__NODEST=666") in new stack
-- Executing [[email protected]:6] Set("IAX2/4444444444-2474", "MONITOR_FILENAME=/var/spool/asterisk/monitor/q666-20120531-085412-1338468846.105") in new stack
-- Executing [[email protected]:7] Queue("IAX2/4444444444-2474", "666,t,,") in new stack
-- Started music on hold, class 'default', on IAX2/4444444444-2474
-- Executing [[email protected]:1] Set("Local/[email protected];2", "QAGENT=8002") in new stack
-- Executing [[email protected]:2] Goto("Local/[email protected];2", "666,1") in new stack
-- Goto (from-queue,666,1)
-- Executing [[email protected]:1] Goto("Local/[email protected];2", "from-internal,8002,1") in new stack
-- Goto (from-internal,8002,1)
-- Executing [[email protected]:1] ExecIf("Local/[email protected];2", "0?Set(__RINGTIMER=0)") in new stack
-- Executing [[email protected]:2] Macro("Local/[email protected];2", "exten-vm,8002,8002,0,0,0") in new stack
-- Executing [[email protected]:1] Macro("Local/[email protected];2", "user-callerid,") in new stack
-- Executing [[email protected]:1] Set("Local/[email protected];2", "AMPUSER=5555555555") in new stack
-- Executing [[email protected]:2] GotoIf("Local/[email protected];2", "1?report") in new stack
-- Goto (macro-user-callerid,s,12)
-- Executing [[email protected]:12] GotoIf("Local/[email protected];2", "0?continue") in new stack
-- Executing [[email protected]:13] Set("Local/[email protected];2", "__TTL=63") in new stack
-- Executing [[email protected]:14] GotoIf("Local/[email protected];2", "1?continue") in new stack
-- Goto (macro-user-callerid,s,25)
-- Executing [[email protected]:25] Set("Local/[email protected];2", "CALLERID(number)=5555555555") in new stack
-- Executing [[email protected]:26] Set("Local/[email protected];2", "CALLERID(name)=TEST") in new stack
-- Executing [[email protected]:27] Set("Local/[email protected];2", "CHANNEL(language)=en") in new stack
-- Executing [[email protected]:2] Set("Local/[email protected];2", "RingGroupMethod=none") in new stack
-- Executing [[email protected]:3] Set("Local/[email protected];2", "__EXTTOCALL=8002") in new stack
-- Executing [[email protected]:4] Set("Local/[email protected];2", "__PICKUPMARK=8002") in new stack
-- Executing [[email protected]:5] Set("Local/[email protected];2", "RT=15") in new stack
-- Executing [[email protected]:6] Macro("Local/[email protected];2", "record-enable,8002,IN") in new stack
-- Executing [[email protected]:1] GotoIf("Local/[email protected];2", "1?check") in new stack
-- Goto (macro-record-enable,s,4)
-- Executing [[email protected]:4] ExecIf("Local/[email protected];2", "0?MacroExit()") in new stack
-- Executing [[email protected]:5] GotoIf("Local/[email protected];2", "0?Group:OUT") in new stack
-- Goto (macro-record-enable,s,14)
-- Executing [[email protected]:14] GotoIf("Local/[email protected];2", "1?IN") in new stack
-- Goto (macro-record-enable,s,18)
-- Executing [[email protected]:18] ExecIf("Local/[email protected];2", "1?MacroExit()") in new stack
-- Executing [[email protected]:7] Macro("Local/[email protected];2", "dial-one,15,trM(auto-blkvm),8002") in new stack
-- Executing [[email protected]:1] Set("Local/[email protected];2", "DEXTEN=8002") in new stack
-- Executing [[email protected]:2] Set("Local/[email protected];2", "DIALSTATUS_CW=") in new stack
-- Executing [[email protected]:3] GosubIf("Local/[email protected];2", "0?screen,1") in new stack
-- Executing [[email protected]:4] GosubIf("Local/[email protected];2", "0?cf,1") in new stack
-- Executing [[email protected]:5] GotoIf("Local/[email protected];2", "1?skip1") in new stack
-- Goto (macro-dial-one,s,8)
-- Executing [[email protected]:8] GotoIf("Local/[email protected];2", "0?nodial") in new stack
-- Executing [[email protected]:9] GotoIf("Local/[email protected];2", "0?continue") in new stack
-- Executing [[email protected]:10] Set("Local/[email protected];2", "EXTHASCW=ENABLED") in new stack
-- Executing [[email protected]:11] GotoIf("Local/[email protected];2", "0?next1:cwinusebusy") in new stack
-- Goto (macro-dial-one,s,23)
-- Executing [[email protected]:23] GotoIf("Local/[email protected];2", "1?next3:continue") in new stack
-- Goto (macro-dial-one,s,24)
-- Executing [[email protected]:24] ExecIf("Local/[email protected];2", "1?Set(DIALSTATUS_CW=BUSY)") in new stack
-- Executing [[email protected]:25] GotoIf("Local/[email protected];2", "0?nodial") in new stack
-- Executing [[email protected]:26] GosubIf("Local/[email protected];2", "1?dstring,1:dlocal,1") in new stack
-- Executing [[email protected]:1] Set("Local/[email protected];2", "DSTRING=") in new stack
-- Executing [[email protected]:2] Set("Local/[email protected];2", "DEVICES=8002") in new stack
-- Executing [[email protected]:3] ExecIf("Local/[email protected];2", "0?Return()") in new stack
-- Executing [[email protected]:4] ExecIf("Local/[email protected];2", "0?Set(DEVICES=002)") in new stack
-- Executing [[email protected]:5] Set("Local/[email protected];2", "LOOPCNT=1") in new stack
-- Executing [[email protected]:6] Set("Local/[email protected];2", "ITER=1") in new stack
-- Executing [[email protected]:7] Set("Local/[email protected];2", "THISDIAL=SIP/8002") in new stack
-- Executing [[email protected]:8] GosubIf("Local/[email protected];2", "1?zap2dahdi,1") in new stack
-- Executing [[email protected]:1] ExecIf("Local/[email protected];2", "0?Return()") in new stack
-- Executing [[email protected]:2] Set("Local/[email protected];2", "NEWDIAL=") in new stack
-- Executing [[email protected]:3] Set("Local/[email protected];2", "LOOPCNT2=1") in new stack
-- Executing [[email protected]:4] Set("Local/[email protected];2", "ITER2=1") in new stack
-- Executing [[email protected]:5] Set("Local/[email protected];2", "THISPART2=SIP/8002") in new stack
-- Executing [[email protected]:6] ExecIf("Local/[email protected];2", "0?Set(THISPART2=DAHDI/8002)") in new stack
-- Executing [[email protected]:7] Set("Local/[email protected];2", "NEWDIAL=SIP/8002&") in new stack
-- Executing [[email protected]:8] Set("Local/[email protected];2", "ITER2=2") in new stack
-- Executing [[email protected]:9] GotoIf("Local/[email protected];2", "0?begin2") in new stack
-- Executing [[email protected]:10] Set("Local/[email protected];2", "THISDIAL=SIP/8002") in new stack
-- Executing [[email protected]:11] Return("Local/[email protected];2", "") in new stack
-- Executing [[email protected]:9] Set("Local/[email protected];2", "DSTRING=SIP/8002&") in new stack
-- Executing [[email protected]:10] Set("Local/[email protected];2", "ITER=2") in new stack
-- Executing [[email protected]:11] GotoIf("Local/[email protected];2", "0?begin") in new stack
-- Executing [[email protected]:12] Set("Local/[email protected];2", "DSTRING=SIP/8002") in new stack
-- Executing [[email protected]:13] Return("Local/[email protected];2", "") in new stack
-- Executing [[email protected]:27] GotoIf("Local/[email protected];2", "0?nodial") in new stack
-- Executing [[email protected]:28] GotoIf("Local/[email protected];2", "0?skiptrace") in new stack
-- Executing [[email protected]:29] GosubIf("Local/[email protected];2", "1?ctset,1:ctclear,1") in new stack
-- Executing [[email protected]:1] Set("Local/[email protected];2", "DB(CALLTRACE/8002)=9054994227") in new stack
-- Executing [[email protected]:2] Return("Local/[email protected];2", "") in new stack
-- Executing [[email protected]:30] Set("Local/[email protected];2", "D_OPTIONS=trM(auto-blkvm)") in new stack
-- Executing [[email protected]:31] ExecIf("Local/[email protected];2", "0?SIPAddHeader(Alert-Info: )") in new stack
-- Executing [[email protected]:32] ExecIf("Local/[email protected];2", "0?SIPAddHeader()") in new stack
-- Executing [[email protected]:33] ExecIf("Local/[email protected];2", "0?Set(CHANNEL(musicclass)=)") in new stack
-- Executing [[email protected]:34] GosubIf("Local/[email protected];2", "0?qwait,1") in new stack
-- Executing [[email protected]:35] Set("Local/[email protected];2", "__CWIGNORE=") in new stack
-- Executing [[email protected]:36] Set("Local/[email protected];2", "__KEEPCID=TRUE") in new stack
-- Executing [[email protected]:37] GotoIf("Local/[email protected];2", "0?usegoto,1") in new stack
-- Executing [[email protected]:38] GotoIf("Local/[email protected];2", "1?godial") in new stack
-- Goto (macro-dial-one,s,42)
-- Executing [[email protected]:42] Dial("Local/[email protected];2", "SIP/8002,15,trM(auto-blkvm)") in new stack

== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
– Called SIP/8002
– Local/[email protected];1 is ringing
– Local/[email protected];1 connected line has changed. Saving it until answer for IAX2/4444444444-2474
– Local/[email protected];1 connected line has changed. Saving it until answer for IAX2/4444444444-2474
– SIP/8002-00000051 is ringing
– Local/[email protected];1 is ringing
– SIP/8002-00000051 is ringing
– SIP/8002-00000051 answered Local/[email protected];2
– Executing [[email protected]:1] Set(“SIP/8002-00000051”, “__MACRO_RESULT=”) in new stack
– Executing [[email protected]:2] Macro(“SIP/8002-00000051”, “blkvm-clr,”) in new stack
– Executing [[email protected]:1] Set(“SIP/8002-00000051”, “SHARED(BLKVM,IAX2/4444444444-2474)=”) in new stack
– Executing [[email protected]:2] Set(“SIP/8002-00000051”, “GOSUB_RETVAL=”) in new stack
– Executing [[email protected]:3] MacroExit(“SIP/8002-00000051”, “”) in new stack
– Executing [[email protected]:3] ExecIf(“SIP/8002-00000051”, “0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=8002)”) in new stack
– Executing [[email protected]:4] ExecIf(“SIP/8002-00000051”, “0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=Sales)”) in new stack
– Local/[email protected];1 connected line has changed. Saving it until answer for IAX2/4444444444-2474
– Nobody picked up in 15000 ms
– Executing [[email protected]:1] Macro(“SIP/8003-00000050”, "hangupcal
– Executing [[email protected]:1] GotoIf(“SIP/8003-00000050”, “1?theend”)
– Goto (macro-hangupcall,s,3)
– Executing [[email protected]:3] Hangup(“SIP/8003-00000050”, “”) in new s
== Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/8003-00000
== Spawn extension (macro-dialout-trunk, h, 1) exited non-zero on 'SIP/8003-00
– Hungup ‘IAX2/4444444444-13012’
== Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'SIP/8003-0
== Spawn extension (from-internal, 4444444444, 5) exited non-zero on 'SIP/8003
– Stopped music on hold on IAX2/4444444444-2474
== Spawn extension (ext-queues, 666, 7) exited non-zero on 'IAX2/4444444444-24
– Executing [[email protected]:1] Macro(“IAX2/4444444444-2474”, “hangupcall,”) i
– Executing [[email protected]:1] GotoIf(“IAX2/4444444444-2474”, "1?theend
– Goto (macro-hangupcall,s,3)
– Executing [[email protected]:3] Hangup(“IAX2/4444444444-2474”, “”) in ne
== Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'IAX2/4444444444
== Spawn extension (ext-queues, h, 1) exited non-zero on 'IAX2/4444444444-2474
– Hungup ‘IAX2/4164790469-2474’
[May 31 08:54:34] NOTICE[31704]: chan_sip.c:26193 sip_poke_noanswer: Peer 'voipm
– Registered SIP ‘8002’ at 97.217.234.3:5062
[May 31 08:54:41] WARNING[31704]: chan_sip.c:3873 __sip_autodestruct: Autodestru
[May 31 08:54:44] NOTICE[31704]: chan_sip.c:20794 handle_response_peerpoke: Peer

Still trying to resolve this issue and actually surprised I haven’t received any feedback yet. I have since upgraded to FreePBX 2.10.0.8 and was hoping that this might resolve the issue with the conference module updated as well.

I’m wondering if the fact that I don’t have DAHDI and ztdummy installed have anything to do with it?

Thanks,

Chris