Call from Queue and forward to voice mail problem

Can anybody tell why my call below is failing?

My extensions receives a queue call. When it is ringing I don’t answer at the phone itself, but use a pickup option in FOP2, i.e. I click on an icon and the server sends an intercom call to my extension, which auto answers and is then being connected to the calling party.

That all works, but once I am connected and I want to transfer the call using the voice mail direct dial prefix, the call just hangs up.
If my extension wasn’t dialed via the intercom call, but I picked it up manually, everything is fine.
Maybe the contexts are getting messed up in the process.

Any ideas?
I know this all sounds a bit tricky.

-- Executing [5320@from-internal:1] Macro("IAX2/5318-9189", "user-callerid,") in new stack
-- Executing [s@macro-user-callerid:1] Set("IAX2/5318-9189", "TOUCH_MONITOR=1427825253.188") in new stack
-- Executing [s@macro-user-callerid:2] Set("IAX2/5318-9189", "AMPUSER=5318") in new stack
-- Executing [s@macro-user-callerid:3] GotoIf("IAX2/5318-9189", "0?report") in new stack
-- Executing [s@macro-user-callerid:4] ExecIf("IAX2/5318-9189", "1?Set(REALCALLERIDNUM=5318)") in new stack
-- Executing [s@macro-user-callerid:5] Set("IAX2/5318-9189", "AMPUSER=5318") in new stack
-- Executing [s@macro-user-callerid:6] GotoIf("IAX2/5318-9189", "0?limit") in new stack
-- Executing [s@macro-user-callerid:7] Set("IAX2/5318-9189", "AMPUSERCIDNAME=Johann Mobile") in new stack
-- Executing [s@macro-user-callerid:8] GotoIf("IAX2/5318-9189", "0?report") in new stack
-- Executing [s@macro-user-callerid:9] Set("IAX2/5318-9189", "AMPUSERCID=5318") in new stack
-- Executing [s@macro-user-callerid:10] Set("IAX2/5318-9189", "__DIAL_OPTIONS=Ttr") in new stack
-- Executing [s@macro-user-callerid:11] Set("IAX2/5318-9189", "CALLERID(all)="Johann Mobile" <5318>") in new stack
-- Executing [s@macro-user-callerid:12] GotoIf("IAX2/5318-9189", "0?limit") in new stack
-- Executing [s@macro-user-callerid:13] ExecIf("IAX2/5318-9189", "0?Set(GROUP(concurrency_limit)=5318)") in new stack
-- Executing [s@macro-user-callerid:14] GosubIf("IAX2/5318-9189", "7?sub-ccss,s,1(from-internal,5320)") in new stack
-- Executing [s@sub-ccss:1] ExecIf("IAX2/5318-9189", "0?Return()") in new stack
-- Executing [s@sub-ccss:2] Set("IAX2/5318-9189", "CCSS_SETUP=TRUE") in new stack
-- Executing [s@sub-ccss:3] GosubIf("IAX2/5318-9189", "0?monitor_config,1(from-internal,5320):monitor_default,1(from-internal,5320)") in new stack
-- Executing [monitor_default@sub-ccss:1] GotoIf("IAX2/5318-9189", "0?is_exten") in new stack
-- Executing [monitor_default@sub-ccss:2] StackPop("IAX2/5318-9189", "") in new stack
-- Executing [monitor_default@sub-ccss:3] Return("IAX2/5318-9189", "FALSE") in new stack
-- Executing [s@macro-user-callerid:15] ExecIf("IAX2/5318-9189", "1?Set(CHANNEL(language)=5313)") in new stack
-- Executing [s@macro-user-callerid:16] GotoIf("IAX2/5318-9189", "0?continue") in new stack
-- Executing [s@macro-user-callerid:17] ExecIf("IAX2/5318-9189", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
-- Executing [s@macro-user-callerid:18] Set("IAX2/5318-9189", "__TTL=64") in new stack
-- Executing [s@macro-user-callerid:19] GotoIf("IAX2/5318-9189", "1?continue") in new stack
-- Goto (macro-user-callerid,s,30)
-- Executing [s@macro-user-callerid:30] Set("IAX2/5318-9189", "CALLERID(number)=5318") in new stack
-- Executing [s@macro-user-callerid:31] Set("IAX2/5318-9189", "CALLERID(name)=Johann Mobile") in new stack
-- Executing [s@macro-user-callerid:32] Set("IAX2/5318-9189", "CDR(cnum)=5318") in new stack
-- Executing [s@macro-user-callerid:33] Set("IAX2/5318-9189", "CDR(cnam)=Johann Mobile") in new stack
-- Executing [s@macro-user-callerid:34] Set("IAX2/5318-9189", "CHANNEL(language)=5313") in new stack
-- Executing [5320@from-internal:2] Answer("IAX2/5318-9189", "") in new stack

== Extension Changed 5318[ext-local] new state InUse for Notify User 5312
– Executing [5320@from-internal:3] Macro(“IAX2/5318-9189”, “blkvm-set,reset”) in new stack
– Executing [s@macro-blkvm-set:1] ExecIf(“IAX2/5318-9189”, “1?Set(__BLKVM_CHANNEL=IAX2/5318-9189)”) in new stack
– Executing [s@macro-blkvm-set:2] Set(“IAX2/5318-9189”, “SHARED(BLKVM,IAX2/5318-9189)=TRUE”) in new stack
– Executing [s@macro-blkvm-set:3] Set(“IAX2/5318-9189”, “GOSUB_RETVAL=TRUE”) in new stack
– Executing [s@macro-blkvm-set:4] MacroExit(“IAX2/5318-9189”, “”) in new stack
– Executing [5320@from-internal:4] ExecIf(“IAX2/5318-9189”, “1?Set(_DIAL_OPTIONS=TtrM(auto-blkvm))”) in new stack
– Executing [5320@from-internal:5] Set(“IAX2/5318-9189”, “__NODEST=5320”) in new stack
– Executing [5320@from-internal:6] Set(“IAX2/5318-9189”, “QCIDPP=”) in new stack
– Executing [5320@from-internal:7] Set(“IAX2/5318-9189”, “VQ_CIDPP=”) in new stack
– Executing [5320@from-internal:8] ExecIf(“IAX2/5318-9189”, “0?Macro(prepend-cid,)”) in new stack
– Executing [5320@from-internal:9] Set(“IAX2/5318-9189”, “QAINFO=”) in new stack
– Executing [5320@from-internal:10] Set(“IAX2/5318-9189”, “VQ_AINFO=”) in new stack
– Executing [5320@from-internal:11] ExecIf(“IAX2/5318-9189”, “0?Set(__ALERT_INFO=)”) in new stack
– Executing [5320@from-internal:12] Set(“IAX2/5318-9189”, “QJOINMSG=”) in new stack
– Executing [5320@from-internal:13] Set(“IAX2/5318-9189”, “VQ_JOINMSG=”) in new stack
– Executing [5320@from-internal:14] Set(“IAX2/5318-9189”, “QRETRY=”) in new stack
– Executing [5320@from-internal:15] Set(“IAX2/5318-9189”, “VQ_RETRY=”) in new stack
– Executing [5320@from-internal:16] Set(“IAX2/5318-9189”, “QOPTIONS=t”) in new stack
– Executing [5320@from-internal:17] Set(“IAX2/5318-9189”, “VQ_OPTIONS=”) in new stack
– Executing [5320@from-internal:18] Set(“IAX2/5318-9189”, “QGOSUB=”) in new stack
– Executing [5320@from-internal:19] Set(“IAX2/5318-9189”, “VQ_GOSUB=”) in new stack
– Executing [5320@from-internal:20] Set(“IAX2/5318-9189”, “QAGI=”) in new stack
– Executing [5320@from-internal:21] Set(“IAX2/5318-9189”, “VQ_AGI=”) in new stack
– Executing [5320@from-internal:22] Set(“IAX2/5318-9189”, “QRULE=”) in new stack
– Executing [5320@from-internal:23] Set(“IAX2/5318-9189”, “VQ_RULE=”) in new stack
– Executing [5320@from-internal:24] Set(“IAX2/5318-9189”, “QPOSITION=”) in new stack
– Executing [5320@from-internal:25] Set(“IAX2/5318-9189”, “VQ_POSITION=”) in new stack
– Executing [5320@from-internal:26] Gosub(“IAX2/5318-9189”, “sub-record-check,s,1(q,5320,dontcare)”) in new stack
– Executing [s@sub-record-check:1] GotoIf(“IAX2/5318-9189”, “0?initialized”) in new stack
– Executing [s@sub-record-check:2] Set(“IAX2/5318-9189”, “__REC_STATUS=INITIALIZED”) in new stack
– Executing [s@sub-record-check:3] Set(“IAX2/5318-9189”, “NOW=1427825254”) in new stack
– Executing [s@sub-record-check:4] Set(“IAX2/5318-9189”, “__DAY=31”) in new stack
– Executing [s@sub-record-check:5] Set(“IAX2/5318-9189”, “__MONTH=03”) in new stack
– Executing [s@sub-record-check:6] Set(“IAX2/5318-9189”, “__YEAR=2015”) in new stack
– Executing [s@sub-record-check:7] Set(“IAX2/5318-9189”, “__TIMESTR=20150331-140734”) in new stack
– Executing [s@sub-record-check:8] Set(“IAX2/5318-9189”, “__FROMEXTEN=5318”) in new stack
– Executing [s@sub-record-check:9] Set(“IAX2/5318-9189”, “__MON_FMT=wav”) in new stack
– Executing [s@sub-record-check:10] NoOp(“IAX2/5318-9189”, “Recordings initialized”) in new stack
– Executing [s@sub-record-check:11] ExecIf(“IAX2/5318-9189”, “0?Set(ARG3=dontcare)”) in new stack
– Executing [s@sub-record-check:12] Set(“IAX2/5318-9189”, “REC_POLICY_MODE_SAVE=”) in new stack
– Executing [s@sub-record-check:13] ExecIf(“IAX2/5318-9189”, “0?Set(REC_STATUS=NO)”) in new stack
– Executing [s@sub-record-check:14] GotoIf(“IAX2/5318-9189”, “1?checkaction”) in new stack
– Goto (sub-record-check,s,17)
– Executing [s@sub-record-check:17] GotoIf(“IAX2/5318-9189”, “0?sub-record-check,q,1”) in new stack
– Executing [s@sub-record-check:18] NoOp(“IAX2/5318-9189”, “Generic q Recording Check - 5318 5320”) in new stack
– Executing [s@sub-record-check:19] Gosub(“IAX2/5318-9189”, “recordcheck,1(dontcare,q,5320)”) in new stack
– Executing [recordcheck@sub-record-check:1] NoOp(“IAX2/5318-9189”, “Starting recording check against dontcare”) in new stack
– Executing [recordcheck@sub-record-check:2] Goto(“IAX2/5318-9189”, “dontcare”) in new stack
– Goto (sub-record-check,recordcheck,3)
– Executing [recordcheck@sub-record-check:3] Return(“IAX2/5318-9189”, “”) in new stack
– Executing [s@sub-record-check:20] Return(“IAX2/5318-9189”, “”) in new stack
– Executing [5320@from-internal:27] Set(“IAX2/5318-9189”, “__CWIGNORE=TRUE”) in new stack
– Executing [5320@from-internal:28] ExecIf(“IAX2/5318-9189”, “0?Playback(, )”) in new stack
– Executing [5320@from-internal:29] QueueLog(“IAX2/5318-9189”, “5320,1427825253.188,NONE,DID,”) in new stack
– Executing [5320@from-internal:30] Set(“IAX2/5318-9189”, “QAANNOUNCE=”) in new stack
– Executing [5320@from-internal:31] Set(“IAX2/5318-9189”, “VQ_AANNOUNCE=”) in new stack
– Executing [5320@from-internal:32] Set(“IAX2/5318-9189”, “QMOH=”) in new stack
– Executing [5320@from-internal:33] Set(“IAX2/5318-9189”, “VQ_MOH=”) in new stack
– Executing [5320@from-internal:34] ExecIf(“IAX2/5318-9189”, “0?Set(__MOHCLASS=)”) in new stack
– Executing [5320@from-internal:35] ExecIf(“IAX2/5318-9189”, “0?Set(CHANNEL(musicclass)=)”) in new stack
– Executing [5320@from-internal:36] Set(“IAX2/5318-9189”, “QMAXWAIT=”) in new stack
– Executing [5320@from-internal:37] Set(“IAX2/5318-9189”, “VQ_MAXWAIT=”) in new stack
– Executing [5320@from-internal:38] Set(“IAX2/5318-9189”, “QUEUENUM=5320”) in new stack
– Executing [5320@from-internal:39] Set(“IAX2/5318-9189”, “QUEUEJOINTIME=1427825254”) in new stack
– Executing [5320@from-internal:40] Queue(“IAX2/5318-9189”, “5320,t,”) in new stack
– Started music on hold, class ‘default’, on IAX2/5318-9189
– Called Local/5313@from-queue/n
– Executing [5313@from-queue:1] Set(“Local/5313@from-queue-00000024;2”, “QAGENT=5313”) in new stack
– Executing [5313@from-queue:2] Goto(“Local/5313@from-queue-00000024;2”, “5320,1”) in new stack
– Goto (from-queue,5320,1)
– Executing [5320@from-queue:1] Goto(“Local/5313@from-queue-00000024;2”, “from-internal,5313,1”) in new stack
– Goto (from-internal,5313,1)
– Executing [5313@from-internal:1] GotoIf(“Local/5313@from-queue-00000024;2”, “0?ext-local,5313,1”) in new stack
– Executing [5313@from-internal:2] Macro(“Local/5313@from-queue-00000024;2”, “user-callerid,”) in new stack
– Executing [s@macro-user-callerid:1] Set(“Local/5313@from-queue-00000024;2”, “TOUCH_MONITOR=1427825254.190”) in new stack
– Executing [s@macro-user-callerid:2] Set(“Local/5313@from-queue-00000024;2”, “AMPUSER=5318”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“Local/5313@from-queue-00000024;2”, “1?report”) in new stack
– Goto (macro-user-callerid,s,16)
– Executing [s@macro-user-callerid:16] GotoIf(“Local/5313@from-queue-00000024;2”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:17] ExecIf(“Local/5313@from-queue-00000024;2”, “1?Set(__CALLEE_ACCOUNCODE=)”) in new stack
– Executing [s@macro-user-callerid:18] Set(“Local/5313@from-queue-00000024;2”, “__TTL=63”) in new stack
– Executing [s@macro-user-callerid:19] GotoIf(“Local/5313@from-queue-00000024;2”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,30)
– Executing [s@macro-user-callerid:30] Set(“Local/5313@from-queue-00000024;2”, “CALLERID(number)=5318”) in new stack
– Executing [s@macro-user-callerid:31] Set(“Local/5313@from-queue-00000024;2”, “CALLERID(name)=Johann Mobile”) in new stack
– Executing [s@macro-user-callerid:32] Set(“Local/5313@from-queue-00000024;2”, “CDR(cnum)=5318”) in new stack
– Executing [s@macro-user-callerid:33] Set(“Local/5313@from-queue-00000024;2”, “CDR(cnam)=Johann Mobile”) in new stack
– Executing [s@macro-user-callerid:34] Set(“Local/5313@from-queue-00000024;2”, “CHANNEL(language)=5313”) in new stack
– Executing [5313@from-internal:3] Set(“Local/5313@from-queue-00000024;2”, “DIAL_OPTIONS=TtrM(auto-blkvm)I”) in new stack
– Executing [5313@from-internal:4] Set(“Local/5313@from-queue-00000024;2”, “CONNECTEDLINE(num,i)=5313”) in new stack
– Executing [5313@from-internal:5] Gosub(“Local/5313@from-queue-00000024;2”, “sub-presencestate-display,s,1(5313)”) in new stack
[2015-03-31 14:07:34] WARNING[31924][C-00000037]: func_presencestate.c:132 presence_read: PRESENCE_STATE unknown
– Executing [s@sub-presencestate-display:1] Goto(“Local/5313@from-queue-00000024;2”, “state-,1”) in new stack
– Goto (sub-presencestate-display,state-,1)
– Executing [state-@sub-presencestate-display:1] Set(“Local/5313@from-queue-00000024;2”, “PRESENCESTATE_DISPLAY=”) in new stack
– Executing [state-@sub-presencestate-display:2] Return(“Local/5313@from-queue-00000024;2”, “”) in new stack
– Executing [5313@from-internal:6] Set(“Local/5313@from-queue-00000024;2”, “CONNECTEDLINE(name)=Johann Remote Office”) in new stack
– Local/5313@from-queue-00000024;1 connected line has changed. Saving it until answer for IAX2/5318-9189
– Executing [5313@from-internal:7] Set(“Local/5313@from-queue-00000024;2”, “FM_DIALSTATUS=NOT_INUSE”) in new stack
– Executing [5313@from-internal:8] Set(“Local/5313@from-queue-00000024;2”, “__EXTTOCALL=5313”) in new stack
– Executing [5313@from-internal:9] Set(“Local/5313@from-queue-00000024;2”, “__PICKUPMARK=5313”) in new stack
– Executing [5313@from-internal:10] Macro(“Local/5313@from-queue-00000024;2”, “blkvm-setifempty,”) in new stack
– Executing [s@macro-blkvm-setifempty:1] GotoIf(“Local/5313@from-queue-00000024;2”, “0?init”) in new stack
– Executing [s@macro-blkvm-setifempty:2] Set(“Local/5313@from-queue-00000024;2”, “GOSUB_RETVAL=TRUE”) in new stack
– Executing [s@macro-blkvm-setifempty:3] MacroExit(“Local/5313@from-queue-00000024;2”, “”) in new stack
– Executing [5313@from-internal:11] GotoIf(“Local/5313@from-queue-00000024;2”, “1?skipov”) in new stack
– Goto (from-internal,5313,14)
– Executing [5313@from-internal:14] Set(“Local/5313@from-queue-00000024;2”, “RRNODEST=5320”) in new stack
– Executing [5313@from-internal:15] Set(“Local/5313@from-queue-00000024;2”, “__NODEST=5313”) in new stack
– Executing [5313@from-internal:16] GosubIf(“Local/5313@from-queue-00000024;2”, “0?sub-fmsetcid,s,1()”) in new stack
– Executing [5313@from-internal:17] Set(“Local/5313@from-queue-00000024;2”, “RecordMethod=Group”) in new stack
– Executing [5313@from-internal:18] Gosub(“Local/5313@from-queue-00000024;2”, “sub-record-check,s,1(exten,5313,)”) in new stack
– Executing [s@sub-record-check:1] GotoIf(“Local/5313@from-queue-00000024;2”, “4?initialized”) in new stack
– Goto (sub-record-check,s,10)
– Executing [s@sub-record-check:10] NoOp(“Local/5313@from-queue-00000024;2”, “Recordings initialized”) in new stack
– Executing [s@sub-record-check:11] ExecIf(“Local/5313@from-queue-00000024;2”, “0?Set(ARG3=dontcare)”) in new stack
– Executing [s@sub-record-check:12] Set(“Local/5313@from-queue-00000024;2”, “REC_POLICY_MODE_SAVE=”) in new stack
– Executing [s@sub-record-check:13] ExecIf(“Local/5313@from-queue-00000024;2”, “0?Set(REC_STATUS=NO)”) in new stack
– Executing [s@sub-record-check:14] GotoIf(“Local/5313@from-queue-00000024;2”, “5?checkaction”) in new stack
– Goto (sub-record-check,s,17)
– Executing [s@sub-record-check:17] GotoIf(“Local/5313@from-queue-00000024;2”, “1?sub-record-check,exten,1”) in new stack
– Goto (sub-record-check,exten,1)
– Executing [exten@sub-record-check:1] NoOp(“Local/5313@from-queue-00000024;2”, “Exten Recording Check between 5318 and 5313”) in new stack
– Executing [exten@sub-record-check:2] Set(“Local/5313@from-queue-00000024;2”, “CALLTYPE=internal”) in new stack
– Executing [exten@sub-record-check:3] ExecIf(“Local/5313@from-queue-00000024;2”, “0?Set(CALLTYPE=)”) in new stack
– Executing [exten@sub-record-check:4] Set(“Local/5313@from-queue-00000024;2”, “CALLEE=dontcare”) in new stack
– Executing [exten@sub-record-check:5] ExecIf(“Local/5313@from-queue-00000024;2”, “0?Set(CALLEE=dontcare)”) in new stack
– Executing [exten@sub-record-check:6] GotoIf(“Local/5313@from-queue-00000024;2”, “0?callee”) in new stack
– Executing [exten@sub-record-check:7] GotoIf(“Local/5313@from-queue-00000024;2”, “1?caller”) in new stack
– Goto (sub-record-check,exten,13)
– Executing [exten@sub-record-check:13] Set(“Local/5313@from-queue-00000024;2”, “RECMODE=dontcare”) in new stack
– Executing [exten@sub-record-check:14] ExecIf(“Local/5313@from-queue-00000024;2”, “0?Set(RECMODE=dontcare)”) in new stack
– Executing [exten@sub-record-check:15] ExecIf(“Local/5313@from-queue-00000024;2”, “1?Set(RECMODE=dontcare)”) in new stack
– Executing [exten@sub-record-check:16] Gosub(“Local/5313@from-queue-00000024;2”, “recordcheck,1(dontcare,internal,5313)”) in new stack
– Executing [recordcheck@sub-record-check:1] NoOp(“Local/5313@from-queue-00000024;2”, “Starting recording check against dontcare”) in new stack
– Executing [recordcheck@sub-record-check:2] Goto(“Local/5313@from-queue-00000024;2”, “dontcare”) in new stack
– Goto (sub-record-check,recordcheck,3)
– Executing [recordcheck@sub-record-check:3] Return(“Local/5313@from-queue-00000024;2”, “”) in new stack
– Executing [exten@sub-record-check:17] Return(“Local/5313@from-queue-00000024;2”, “”) in new stack
– Executing [5313@from-internal:19] Set(“Local/5313@from-queue-00000024;2”, “RingGroupMethod=ringallv2”) in new stack
– Executing [5313@from-internal:20] Set(“Local/5313@from-queue-00000024;2”, “_FMGRP=5313”) in new stack
– Executing [5313@from-internal:21] GotoIf(“Local/5313@from-queue-00000024;2”, “0?doconfirm”) in new stack
– Executing [5313@from-internal:22] Macro(“Local/5313@from-queue-00000024;2”, “dial,18,TtrM(auto-blkvm)I,5313”) in new stack
– Executing [s@macro-dial:1] GotoIf(“Local/5313@from-queue-00000024;2”, “1?dial”) in new stack
– Goto (macro-dial,s,3)
– Executing [s@macro-dial:3] AGI(“Local/5313@from-queue-00000024;2”, “dialparties.agi”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
dialparties.agi: Starting New Dialparties.agi
dialparties.agi: Caller ID name is ‘Johann Mobile’ number is '5318’
dialparties.agi: Methodology of ring is ‘ringallv2’
– dialparties.agi: Added extension 5313 to extension map
> dialparties.agi: got fmgrp_prering: 2, fmgrp_grptime: 18
> dialparties.agi: fmgrp_totalprering: 20
> dialparties.agi: found extension in pre-ring and array
> dialparties.agi: ringallv2 ring times: REALPRERING: 20, PRERING: 2
– dialparties.agi: Extension 5313 cf is disabled
– dialparties.agi: Extension 5313 do not disturb is disabled
> dialparties.agi: extnum 5313 has: cw: 0; hascfb: 0 [] hascfu: 0 []
dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
dialparties.agi: Extension 5313 has ExtensionState: 0
– dialparties.agi: Checking CW and CFB status for extension 5313
– dialparties.agi: dbset CALLTRACE/5313 to 5318
– dialparties.agi: Filtered ARG3: 5313
> dialparties.agi: NODEST: 5313 blkvm enabled macro already in dialopts: TtrM(auto-blkvm)I
> dialparties.agi: NODEST: 5313 blkvm enabled macro already in dialopts: TtrM(auto-blkvm)I
– <Local/5313@from-queue-00000024;2>AGI Script dialparties.agi completed, returning 0
– Executing [s@macro-dial:7] Dial(“Local/5313@from-queue-00000024;2”, “SIP/5313,20,TtrM(auto-blkvm)I”) in new stack
== Using SIP VIDEO TOS bits 136
== Using SIP VIDEO CoS mark 6
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
– Called SIP/5313
– Local/5313@from-queue-00000024;1 is ringing
– Connected line update to Local/5313@from-queue-00000024;2 prevented.
== Extension Changed 5313[ext-local] new state Ringing for Notify User 5312
– SIP/5313-0000004d is ringing
== Extension Changed 5313[ext-local] new state Ringing for Notify User 5312 (queued)
– Local/5313@from-queue-00000024;1 is ringing
– Stopped music on hold on IAX2/5318-9189
== Spawn extension (macro-dial, s, 7) exited non-zero on ‘Local/5313@from-queue-00000024;2’ in macro ‘dial’
== Spawn extension (from-internal, 5313, 22) exited non-zero on ‘Local/5313@from-queue-00000024;2’
– Executing [h@from-internal:1] Hangup(“Local/5313@from-queue-00000024;2”, “”) in new stack
== Spawn extension (from-internal, h, 1) exited non-zero on ‘Local/5313@from-queue-00000024;2’
== Spawn extension (from-internal, *805313, 1) exited non-zero on ‘IAX2/5318-9189’
– Executing [*805313@from-internal:1] Goto(“IAX2/5318-9189”, “ext-intercom,*805313,1”) in new stack
– Goto (ext-intercom,*805313,1)
– Executing [*805313@ext-intercom:1] Macro(“IAX2/5318-9189”, “user-callerid,”) in new stack
== Extension Changed 5313[ext-local] new state Idle for Notify User 5312
– Executing [s@macro-user-callerid:1] Set(“IAX2/5318-9189”, “TOUCH_MONITOR=1427825253.188”) in new stack
– Executing [s@macro-user-callerid:2] Set(“IAX2/5318-9189”, “AMPUSER=5318”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“IAX2/5318-9189”, “13?report”) in new stack
– Goto (macro-user-callerid,s,16)
– Executing [s@macro-user-callerid:16] GotoIf(“IAX2/5318-9189”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:17] ExecIf(“IAX2/5318-9189”, “1?Set(__CALLEE_ACCOUNCODE=)”) in new stack
– Executing [s@macro-user-callerid:18] Set(“IAX2/5318-9189”, “__TTL=63”) in new stack
– Executing [s@macro-user-callerid:19] GotoIf(“IAX2/5318-9189”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,30)
– Executing [s@macro-user-callerid:30] Set(“IAX2/5318-9189”, “CALLERID(number)=5318”) in new stack
– Executing [s@macro-user-callerid:31] Set(“IAX2/5318-9189”, “CALLERID(name)=Johann Mobile”) in new stack
– Executing [s@macro-user-callerid:32] Set(“IAX2/5318-9189”, “CDR(cnum)=5318”) in new stack
– Executing [s@macro-user-callerid:33] Set(“IAX2/5318-9189”, “CDR(cnam)=Johann Mobile”) in new stack
– Executing [s@macro-user-callerid:34] Set(“IAX2/5318-9189”, “CHANNEL(language)=5313”) in new stack
– Executing [*805313@ext-intercom:2] Set(“IAX2/5318-9189”, “dialnumber=5313”) in new stack
– Executing [*805313@ext-intercom:3] Set(“IAX2/5318-9189”, “INTERCOM_CALL=TRUE”) in new stack
– Executing [*805313@ext-intercom:4] Gosub(“IAX2/5318-9189”, “sub-record-check,s,1(exten,5313)”) in new stack
– Executing [s@sub-record-check:1] GotoIf(“IAX2/5318-9189”, “4?initialized”) in new stack
– Executing [dummy@fop2-dummy:1] Answer(“Local/dummy@fop2-dummy-00000025;2”, “”) in new stack
> Channel Local/dummy@fop2-dummy-00000025;1 was answered.
– Goto (sub-record-check,s,10)
– Executing [s@sub-record-check:10] NoOp(“IAX2/5318-9189”, “Recordings initialized”) in new stack
– Executing [s@sub-record-check:11] ExecIf(“IAX2/5318-9189”, “0?Set(ARG3=dontcare)”) in new stack
– Executing [s@sub-record-check:12] Set(“IAX2/5318-9189”, “REC_POLICY_MODE_SAVE=”) in new stack
– Executing [s@sub-record-check:13] ExecIf(“IAX2/5318-9189”, “0?Set(REC_STATUS=NO)”) in new stack
– Executing [s@sub-record-check:14] GotoIf(“IAX2/5318-9189”, “5?checkaction”) in new stack
– Goto (sub-record-check,s,17)
> Launching QueueLog(5320,1427825253.188,NONE,NOTABANDON,0,0,0) on Local/dummy@fop2-dummy-00000025;1
– Executing [s@sub-record-check:17] GotoIf(“IAX2/5318-9189”, “1?sub-record-check,exten,1”) in new stack
– Goto (sub-record-check,exten,1)
– Executing [exten@sub-record-check:1] NoOp(“IAX2/5318-9189”, “Exten Recording Check between 5318 and 5313”) in new stack
– Executing [exten@sub-record-check:2] Set(“IAX2/5318-9189”, “CALLTYPE=internal”) in new stack
== Spawn extension (fop2-dummy, dummy, 1) exited non-zero on ‘Local/dummy@fop2-dummy-00000025;2’
– Executing [exten@sub-record-check:3] ExecIf(“IAX2/5318-9189”, “0?Set(CALLTYPE=)”) in new stack
– Executing [exten@sub-record-check:4] Set(“IAX2/5318-9189”, “CALLEE=dontcare”) in new stack
– Executing [exten@sub-record-check:5] ExecIf(“IAX2/5318-9189”, “0?Set(CALLEE=dontcare)”) in new stack
– Executing [exten@sub-record-check:6] GotoIf(“IAX2/5318-9189”, “0?callee”) in new stack
– Executing [exten@sub-record-check:7] GotoIf(“IAX2/5318-9189”, “1?caller”) in new stack
– Goto (sub-record-check,exten,13)
– Executing [exten@sub-record-check:13] Set(“IAX2/5318-9189”, “RECMODE=dontcare”) in new stack
– Executing [exten@sub-record-check:14] ExecIf(“IAX2/5318-9189”, “0?Set(RECMODE=dontcare)”) in new stack
– Executing [exten@sub-record-check:15] ExecIf(“IAX2/5318-9189”, “1?Set(RECMODE=dontcare)”) in new stack
– Executing [exten@sub-record-check:16] Gosub(“IAX2/5318-9189”, “recordcheck,1(dontcare,internal,5313)”) in new stack
– Executing [recordcheck@sub-record-check:1] NoOp(“IAX2/5318-9189”, “Starting recording check against dontcare”) in new stack
– Executing [recordcheck@sub-record-check:2] Goto(“IAX2/5318-9189”, “dontcare”) in new stack
– Goto (sub-record-check,recordcheck,3)
– Executing [recordcheck@sub-record-check:3] Return(“IAX2/5318-9189”, “”) in new stack
– Executing [exten@sub-record-check:17] Return(“IAX2/5318-9189”, “”) in new stack
– Executing [*805313@ext-intercom:5] GotoIf(“IAX2/5318-9189”, “0?end”) in new stack
– Executing [*805313@ext-intercom:6] GotoIf(“IAX2/5318-9189”, “0?end”) in new stack
– Executing [*805313@ext-intercom:7] GotoIf(“IAX2/5318-9189”, “0?allow”) in new stack
– Executing [*805313@ext-intercom:8] GotoIf(“IAX2/5318-9189”, “0?nointercom”) in new stack
– Executing [*805313@ext-intercom:9] GotoIf(“IAX2/5318-9189”, “0?nointercom”) in new stack
– Executing [*805313@ext-intercom:10] Set(“IAX2/5318-9189”, “DEVICES=5313”) in new stack
– Executing [*805313@ext-intercom:11] GotoIf(“IAX2/5318-9189”, “0?end”) in new stack
– Executing [*805313@ext-intercom:12] Set(“IAX2/5318-9189”, “OVERRIDE=force”) in new stack
– Executing [*805313@ext-intercom:13] Set(“IAX2/5318-9189”, “LOOPCNT=1”) in new stack
– Executing [*805313@ext-intercom:14] Set(“IAX2/5318-9189”, “_SIPURI=”) in new stack
– Executing [*805313@ext-intercom:15] Set(“IAX2/5318-9189”, “_ALERTINFO=Ring Answer”) in new stack
– Executing [*805313@ext-intercom:16] Set(“IAX2/5318-9189”, “_CALLINFO=;answer-after=0”) in new stack
– Executing [*805313@ext-intercom:17] Set(“IAX2/5318-9189”, “_SIPURI=intercom=true”) in new stack
– Executing [*805313@ext-intercom:18] Set(“IAX2/5318-9189”, “_DTIME=5”) in new stack
– Executing [*805313@ext-intercom:19] Set(“IAX2/5318-9189”, “_ANSWERMACRO=”) in new stack
– Executing [*805313@ext-intercom:20] GotoIf(“IAX2/5318-9189”, “0?pagemode”) in new stack
– Executing [*805313@ext-intercom:21] Macro(“IAX2/5318-9189”, “autoanswer,5313”) in new stack
– Executing [s@macro-autoanswer:1] GotoIf(“IAX2/5318-9189”, “0?knowndial”) in new stack
– Executing [s@macro-autoanswer:2] Set(“IAX2/5318-9189”, “DEVICE=SIP/5313”) in new stack
– Executing [s@macro-autoanswer:3] GotoIf(“IAX2/5318-9189”, “0?dopjsip”) in new stack
– Executing [s@macro-autoanswer:4] Set(“IAX2/5318-9189”, “KNOWNDIAL=SIP/5313”) in new stack
– Executing [s@macro-autoanswer:5] Goto(“IAX2/5318-9189”, “knowndial”) in new stack
– Goto (macro-autoanswer,s,19)
– Executing [s@macro-autoanswer:19] Set(“IAX2/5318-9189”, “DIAL=SIP/5313”) in new stack
– Executing [s@macro-autoanswer:20] ExecIf(“IAX2/5318-9189”, “0?Set(DIAL=DAHDI/5313)”) in new stack
– Executing [s@macro-autoanswer:21] GotoIf(“IAX2/5318-9189”, “0?macro”) in new stack
– Executing [s@macro-autoanswer:22] Set(“IAX2/5318-9189”, “USERAGENT=Yealink SIP-T20P 9.73.0.40”) in new stack
– Executing [s@macro-autoanswer:23] ExecIf(“IAX2/5318-9189”, “0?Set(USERAGENT=)”) in new stack
– Executing [s@macro-autoanswer:24] ExecIf(“IAX2/5318-9189”, “0?Set(CALLINFO=sip:broadworks.net;answer-after=0)”) in new stack
– Executing [s@macro-autoanswer:25] ExecIf(“IAX2/5318-9189”, “0?Set(ALERTINFO=Intercom)”) in new stack
– Executing [s@macro-autoanswer:26] ExecIf(“IAX2/5318-9189”, “0?Set(ALERTINFO=info=Auto Answer)”) in new stack
– Executing [s@macro-autoanswer:27] ExecIf(“IAX2/5318-9189”, “0?Set(ALERTINFO=ring-answer)”) in new stack
– Executing [s@macro-autoanswer:28] ExecIf(“IAX2/5318-9189”, “1?Set(__SIP_URI_OPTIONS=intercom=true)”) in new stack
– Executing [*805313@ext-intercom:22] Set(“IAX2/5318-9189”, “_DOPTIONS=A(beep)b(autoanswer^s^1(Ring Answer,;answer-after=0))”) in new stack
– Executing [*805313@ext-intercom:23] ChanIsAvail(“IAX2/5318-9189”, “SIP/5313,s”) in new stack
== Using SIP VIDEO TOS bits 136
== Using SIP VIDEO CoS mark 6
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
– Executing [*805313@ext-intercom:24] ExecIf(“IAX2/5318-9189”, “0?Set(AVAILORIGCHAN=SIP/5313)”) in new stack
– Executing [*805313@ext-intercom:25] GotoIf(“IAX2/5318-9189”, “1?continue”) in new stack
– Goto (ext-intercom,*805313,30)
– Executing [*805313@ext-intercom:30] NoOp(“IAX2/5318-9189”, “Continuing with page”) in new stack
– Executing [*805313@ext-intercom:31] GotoIf(“IAX2/5318-9189”, “0?godial”) in new stack
– Executing [*805313@ext-intercom:32] Set(“IAX2/5318-9189”, “CONNECTEDLINE(name,i)=Johann Remote Office”) in new stack
– Executing [*805313@ext-intercom:33] Set(“IAX2/5318-9189”, “CONNECTEDLINE(num)=5313”) in new stack
– Executing [*805313@ext-intercom:34] Dial(“IAX2/5318-9189”, “SIP/5313,5,IA(beep)b(autoanswer^s^1(Ring Answer,;answer-after=0))”) in new stack
== Using SIP VIDEO TOS bits 136
== Using SIP VIDEO CoS mark 6
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
– SIP/5313-0000004f Internal Gosub(autoanswer,s,1(Ring Answer,;answer-after=0)) start
– Executing [s@autoanswer:1] GosubIf(“SIP/5313-0000004f”, “1?addheader,1(Alert-Info,Ring Answer)”) in new stack
– Executing [addheader@autoanswer:1] SIPAddHeader(“SIP/5313-0000004f”, “Alert-Info: Ring Answer”) in new stack
– Executing [addheader@autoanswer:2] Set(“SIP/5313-0000004f”, “PJSIP_HEADER(add,Alert-Info)=Ring Answer”) in new stack
[2015-03-31 14:07:37] ERROR[31923][C-00000037]: pbx.c:4387 ast_func_write: Function PJSIP_HEADER not registered
– Executing [addheader@autoanswer:3] Return(“SIP/5313-0000004f”, “”) in new stack
– Executing [s@autoanswer:2] GosubIf(“SIP/5313-0000004f”, “1?addheader,1(Call-Info,;answer-after=0)”) in new stack
– Executing [addheader@autoanswer:1] SIPAddHeader(“SIP/5313-0000004f”, “Call-Info: ;answer-after=0”) in new stack
– Executing [addheader@autoanswer:2] Set(“SIP/5313-0000004f”, “PJSIP_HEADER(add,Call-Info)=;answer-after=0”) in new stack
[2015-03-31 14:07:37] ERROR[31923][C-00000037]: pbx.c:4387 ast_func_write: Function PJSIP_HEADER not registered
– Executing [addheader@autoanswer:3] Return(“SIP/5313-0000004f”, “”) in new stack
– Executing [s@autoanswer:3] Return(“SIP/5313-0000004f”, “”) in new stack
== Spawn extension (from-internal, *805313, 1) exited non-zero on ‘SIP/5313-0000004f’
– SIP/5313-0000004f Internal Gosub(autoanswer,s,1(Ring Answer,;answer-after=0)) complete GOSUB_RETVAL=
– Called SIP/5313
== Extension Changed 5313[ext-local] new state Ringing for Notify User 5312 (queued)
– Connected line update to IAX2/5318-9189 prevented.
== Extension Changed 5313[ext-local] new state Ringing for Notify User 5312 (queued)
– SIP/5313-0000004f is ringing
== Extension Changed 5313[ext-local] new state Ringing for Notify User 5312 (queued)
[2015-03-31 14:07:38] WARNING[12251][C-00000037]: chan_sip.c:10220 process_sdp: Ignoring video stream offer because port number is zero
== Extension Changed 5313[ext-local] new state InUse for Notify User 5312 (queued)
– Connected line update to IAX2/5318-9189 prevented.
– SIP/5313-0000004f answered IAX2/5318-9189
– <SIP/5313-0000004f> Playing ‘beep.gsm’ (language ‘en’)
> 0x7fc8f4037850 – Probation passed - setting RTP source address to 95.123.123.65:1826
== Extension Changed 5313[ext-local] new state Idle for Notify User 5312 (queued)
== Spawn extension (from-internal, #22517, 1) exited non-zero on ‘IAX2/5318-9189’
– Executing [#22517@from-internal:1] Macro(“IAX2/5318-9189”, “vm,2517,DIRECTDIAL,”) in new stack
– Executing [s@macro-vm:1] Macro(“IAX2/5318-9189”, “user-callerid,SKIPTTL”) in new stack
– Executing [s@macro-user-callerid:1] Set(“IAX2/5318-9189”, “TOUCH_MONITOR=1427825253.188”) in new stack
– Executing [s@macro-user-callerid:2] Set(“IAX2/5318-9189”, “AMPUSER=5318”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“IAX2/5318-9189”, “13?report”) in new stack
– Goto (macro-user-callerid,s,16)
– Executing [s@macro-user-callerid:16] GotoIf(“IAX2/5318-9189”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,30)
– Executing [s@macro-user-callerid:30] Set(“IAX2/5318-9189”, “CALLERID(number)=5318”) in new stack
– Executing [s@macro-user-callerid:31] Set(“IAX2/5318-9189”, “CALLERID(name)=Johann Mobile”) in new stack
– Executing [s@macro-user-callerid:32] Set(“IAX2/5318-9189”, “CDR(cnum)=5318”) in new stack
– Executing [s@macro-user-callerid:33] Set(“IAX2/5318-9189”, “CDR(cnam)=Johann Mobile”) in new stack
– Executing [s@macro-user-callerid:34] Set(“IAX2/5318-9189”, “CHANNEL(language)=5313”) in new stack
– Executing [s@macro-vm:2] Set(“IAX2/5318-9189”, “VMGAIN=g(12)”) in new stack
– Executing [s@macro-vm:3] Macro(“IAX2/5318-9189”, “blkvm-check,”) in new stack
– Executing [s@macro-blkvm-check:1] Set(“IAX2/5318-9189”, “GOSUB_RETVAL=TRUE”) in new stack
– Executing [s@macro-blkvm-check:2] ExecIf(“IAX2/5318-9189”, “0?Set(GOSUB_RETVAL=TRUE)”) in new stack
– Executing [s@macro-blkvm-check:3] MacroExit(“IAX2/5318-9189”, “”) in new stack
– Executing [s@macro-vm:4] GotoIf(“IAX2/5318-9189”, “0?vmx,1”) in new stack
– Executing [s@macro-vm:5] Hangup(“IAX2/5318-9189”, “”) in new stack
== Spawn extension (macro-vm, s, 5) exited non-zero on ‘IAX2/5318-9189’ in macro ‘vm’
== Spawn extension (from-internal, #22517, 1) exited non-zero on ‘IAX2/5318-9189’
– Executing [h@from-internal:1] Hangup(“IAX2/5318-9189”, “”) in new stack
== Spawn extension (from-internal, h, 1) exited non-zero on ‘IAX2/5318-9189’
– Hungup ‘IAX2/5318-9189’
== Extension Changed 5318[ext-local] new state Idle for Notify User 5312

You need to ask the person who wrote the dialplan. It is too complex to debug in a reasonable time from cold.