Queue call: not wanted transfer to another extension

Hello,

I’m experiencing a strange behaviour in some queue calls. After 7 minutes talking, the call suddenly is hanged up and then the call is transfered to another random extension. Next you can see what happens in log.
I can’t understand the spawn line when de first call hangs up.

[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [1707@ext-queues:10] Queue(“SIP/GatewaySIP-000262a6”, “1707,t,custom/tienes_llamada,90”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] res_musiconhold.c: – Started music on hold, class ‘espera-28042016’, on SIP/GatewaySIP-000262a6
[Jun 21 16:25:45] VERBOSE[29107] app_queue.c: – Called SIP/698
[Jun 21 16:25:45] VERBOSE[29107] app_queue.c: – SIP/698-000262b4 is ringing
[Jun 21 16:25:45] VERBOSE[29107] app_queue.c: – SIP/698-000262b4 answered SIP/GatewaySIP-000262a6
[Jun 21 16:25:49] VERBOSE[29107] res_musiconhold.c: – Stopped music on hold on SIP/GatewaySIP-000262a6
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: == Spawn extension (from-agente, 345, 1) exited non-zero on ‘SIP/GatewaySIP-000262a6’
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [345@from-agente:1] ExecIf(“SIP/GatewaySIP-000262a6”, “0?Set(__RINGTIMER=0)”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [345@from-agente:2] Macro(“SIP/GatewaySIP-000262a6”, “exten-vm,novm,345,0,0,0”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:42] Dial(“SIP/GatewaySIP-000262a6”, “SIP/345,M(auto-blkvm)”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] app_dial.c: – Called SIP/345
[Jun 21 16:32:19] VERBOSE[29107] app_dial.c: – SIP/345-0002644e is ringing
[Jun 21 16:32:19] VERBOSE[29107] app_dial.c: – SIP/345-0002644e answered SIP/GatewaySIP-000262a6

You haven’t got sufficient logging, but I think the called party initiated a SIP transfer.

Yes, I supposed it too, but the users that receive this calls are not allowed to do transfers,
I’ve listened the call recording and it is suddenly hanged up, the called party doesn’t tell to calling party that will be transfered. Next you can find the complete call log.

[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [942027720@from-pstn:1] Set(“SIP/GatewaySIP-000262a6”, “__FROM_DID=942027720”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [942027720@from-pstn:2] Gosub(“SIP/GatewaySIP-000262a6”, “app-blacklist-check,s,1”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@app-blacklist-check:1] GotoIf(“SIP/GatewaySIP-000262a6”, “0?check-blocked”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@app-blacklist-check:2] GotoIf(“SIP/GatewaySIP-000262a6”, “0?check-blocked”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@app-blacklist-check:3] GotoIf(“SIP/GatewaySIP-000262a6”, “0?check-blocked:check”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Goto (app-blacklist-check,s,5)
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@app-blacklist-check:5] GotoIf(“SIP/GatewaySIP-000262a6”, “0?blacklisted”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@app-blacklist-check:6] Set(“SIP/GatewaySIP-000262a6”, “CALLED_BLACKLIST=1”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@app-blacklist-check:7] Return(“SIP/GatewaySIP-000262a6”, “”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [942027720@from-pstn:3] ExecIf(“SIP/GatewaySIP-000262a6”, “0 ?Set(CALLERID(name)=675807459)”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [942027720@from-pstn:4] Set(“SIP/GatewaySIP-000262a6”, “__CALLINGPRES_SV=allowed_not_screened”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [942027720@from-pstn:5] Set(“SIP/GatewaySIP-000262a6”, “CALLERPRES()=allowed_not_screened”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [942027720@from-pstn:6] Goto(“SIP/GatewaySIP-000262a6”, “from-internal-custom,9980,1”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Goto (from-internal-custom,9980,1)
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [9980@from-internal-custom:1] Set(“SIP/GatewaySIP-000262a6”, “SPYGROUP=8850”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [9980@from-internal-custom:2] Goto(“SIP/GatewaySIP-000262a6”, “timeconditions,14,1”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Goto (timeconditions,14,1)
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [14@timeconditions:1] GotoIfTime(“SIP/GatewaySIP-000262a6”, “09:00-23:59,mon-sat,1-31,jan-dec?truestate”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Goto (timeconditions,14,8)
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [14@timeconditions:8] GotoIf(“SIP/GatewaySIP-000262a6”, “0?falsegoto”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [14@timeconditions:9] ExecIf(“SIP/GatewaySIP-000262a6”, “0?Set(DB(TC/14)=)”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [14@timeconditions:10] GotoIf(“SIP/GatewaySIP-000262a6”, “1?ext-queues,1707,1”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Goto (ext-queues,1707,1)
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [1707@ext-queues:1] Macro(“SIP/GatewaySIP-000262a6”, “user-callerid,”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:1] Set(“SIP/GatewaySIP-000262a6”, “AMPUSER=675807459”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:2] GotoIf(“SIP/GatewaySIP-000262a6”, “0?report”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:3] ExecIf(“SIP/GatewaySIP-000262a6”, “1?Set(REALCALLERIDNUM=675807459)”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:4] Set(“SIP/GatewaySIP-000262a6”, “AMPUSER=”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:5] Set(“SIP/GatewaySIP-000262a6”, “AMPUSERCIDNAME=”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:6] GotoIf(“SIP/GatewaySIP-000262a6”, “1?report”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Goto (macro-user-callerid,s,13)
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:13] GotoIf(“SIP/GatewaySIP-000262a6”, “0?continue”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:14] Set(“SIP/GatewaySIP-000262a6”, “__TTL=64”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:15] GotoIf(“SIP/GatewaySIP-000262a6”, “1?continue”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Goto (macro-user-callerid,s,26)
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:26] Set(“SIP/GatewaySIP-000262a6”, “CALLERID(number)=675807459”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:27] Set(“SIP/GatewaySIP-000262a6”, “CALLERID(name)=675807459”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:28] Set(“SIP/GatewaySIP-000262a6”, “CHANNEL(language)=es”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [1707@ext-queues:2] Answer(“SIP/GatewaySIP-000262a6”, “”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [1707@ext-queues:3] Macro(“SIP/GatewaySIP-000262a6”, “blkvm-set,reset”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@macro-blkvm-set:1] ExecIf(“SIP/GatewaySIP-000262a6”, “1?Set(__BLKVM_CHANNEL=SIP/GatewaySIP-000262a6)”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@macro-blkvm-set:2] Set(“SIP/GatewaySIP-000262a6”, “SHARED(BLKVM,SIP/GatewaySIP-000262a6)=TRUE”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@macro-blkvm-set:3] Set(“SIP/GatewaySIP-000262a6”, “GOSUB_RETVAL=TRUE”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [s@macro-blkvm-set:4] MacroExit(“SIP/GatewaySIP-000262a6”, “”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [1707@ext-queues:4] ExecIf(“SIP/GatewaySIP-000262a6”, “1?Set(_DIAL_OPTIONS=M(auto-blkvm))”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [1707@ext-queues:5] Set(“SIP/GatewaySIP-000262a6”, “__NODEST=1707”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [1707@ext-queues:6] Set(“SIP/GatewaySIP-000262a6”, “MONITOR_FILENAME=/var/spool/asterisk/monitor/q1707-20160621-162534-1466519134.209216”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [1707@ext-queues:7] Set(“SIP/GatewaySIP-000262a6”, “MONITOR_OPTIONS=b”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [1707@ext-queues:8] Set(“SIP/GatewaySIP-000262a6”, “__MOHCLASS=espera-28042016”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [1707@ext-queues:9] Set(“SIP/GatewaySIP-000262a6”, “__CWIGNORE=TRUE”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] pbx.c: – Executing [1707@ext-queues:10] Queue(“SIP/GatewaySIP-000262a6”, “1707,t,custom/tienes_llamada,90”) in new stack
[Jun 21 16:25:34] VERBOSE[29107] res_musiconhold.c: – Started music on hold, class ‘espera-28042016’, on SIP/GatewaySIP-000262a6
[Jun 21 16:25:45] VERBOSE[29107] netsock2.c: == Using SIP RTP TOS bits 184
[Jun 21 16:25:45] VERBOSE[29107] netsock2.c: == Using SIP RTP CoS mark 5
[Jun 21 16:25:45] VERBOSE[29107] app_queue.c: – Called SIP/698
[Jun 21 16:25:45] VERBOSE[29107] app_queue.c: – SIP/698-000262b4 is ringing
[Jun 21 16:25:45] VERBOSE[29107] app_queue.c: – SIP/698-000262b4 answered SIP/GatewaySIP-000262a6
[Jun 21 16:25:45] VERBOSE[29107] file.c: – <SIP/698-000262b4> Playing ‘custom/tienes_llamada.slin’ (language ‘es’)
[Jun 21 16:25:49] VERBOSE[29107] res_musiconhold.c: – Stopped music on hold on SIP/GatewaySIP-000262a6
[Jun 21 16:25:49] DEBUG[29107] channel.c: setting peeraccount to T429 for SIP/698-000262b4 from data on channel SIP/GatewaySIP-000262a6
[Jun 21 16:25:49] DEBUG[29107] channel.c: setting peeraccount to T429 for SIP/GatewaySIP-000262a6 from data on channel SIP/698-000262b4
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: == Spawn extension (from-agente, 345, 1) exited non-zero on ‘SIP/GatewaySIP-000262a6’
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [345@from-agente:1] ExecIf(“SIP/GatewaySIP-000262a6”, “0?Set(__RINGTIMER=0)”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [345@from-agente:2] Macro(“SIP/GatewaySIP-000262a6”, “exten-vm,novm,345,0,0,0”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-exten-vm:1] Macro(“SIP/GatewaySIP-000262a6”, “user-callerid,”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:1] Set(“SIP/GatewaySIP-000262a6”, “AMPUSER=675807459”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:2] GotoIf(“SIP/GatewaySIP-000262a6”, “0?report”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:3] ExecIf(“SIP/GatewaySIP-000262a6”, “0?Set(REALCALLERIDNUM=675807459)”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:4] Set(“SIP/GatewaySIP-000262a6”, “AMPUSER=”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:5] Set(“SIP/GatewaySIP-000262a6”, “AMPUSERCIDNAME=”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:6] GotoIf(“SIP/GatewaySIP-000262a6”, “1?report”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Goto (macro-user-callerid,s,13)
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:13] GotoIf(“SIP/GatewaySIP-000262a6”, “0?continue”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:14] Set(“SIP/GatewaySIP-000262a6”, “__TTL=63”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:15] GotoIf(“SIP/GatewaySIP-000262a6”, “1?continue”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Goto (macro-user-callerid,s,26)
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:26] Set(“SIP/GatewaySIP-000262a6”, “CALLERID(number)=675807459”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:27] Set(“SIP/GatewaySIP-000262a6”, “CALLERID(name)=675807459”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-user-callerid:28] Set(“SIP/GatewaySIP-000262a6”, “CHANNEL(language)=es”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-exten-vm:2] Set(“SIP/GatewaySIP-000262a6”, “RingGroupMethod=none”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-exten-vm:3] Set(“SIP/GatewaySIP-000262a6”, “__EXTTOCALL=345”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-exten-vm:4] Set(“SIP/GatewaySIP-000262a6”, “__PICKUPMARK=345”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-exten-vm:5] Set(“SIP/GatewaySIP-000262a6”, “RT=”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-exten-vm:6] Macro(“SIP/GatewaySIP-000262a6”, “record-enable,345,IN”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-record-enable:1] GotoIf(“SIP/GatewaySIP-000262a6”, “1?check”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Goto (macro-record-enable,s,4)
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-record-enable:4] ExecIf(“SIP/GatewaySIP-000262a6”, “0?MacroExit()”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-record-enable:5] GotoIf(“SIP/GatewaySIP-000262a6”, “0?Group:OUT”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Goto (macro-record-enable,s,14)
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-record-enable:14] GotoIf(“SIP/GatewaySIP-000262a6”, “1?IN”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Goto (macro-record-enable,s,18)
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-record-enable:18] ExecIf(“SIP/GatewaySIP-000262a6”, “1?MacroExit()”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-exten-vm:7] Macro(“SIP/GatewaySIP-000262a6”, “dial-one,M(auto-blkvm),345”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:1] Set(“SIP/GatewaySIP-000262a6”, “DEXTEN=345”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:2] Set(“SIP/GatewaySIP-000262a6”, “DIALSTATUS_CW=”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:3] GosubIf(“SIP/GatewaySIP-000262a6”, “0?screen,1”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:4] GosubIf(“SIP/GatewaySIP-000262a6”, “0?cf,1”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:5] GotoIf(“SIP/GatewaySIP-000262a6”, “1?skip1”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Goto (macro-dial-one,s,8)
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:8] GotoIf(“SIP/GatewaySIP-000262a6”, “0?nodial”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:9] GotoIf(“SIP/GatewaySIP-000262a6”, “0?continue”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:10] Set(“SIP/GatewaySIP-000262a6”, “EXTHASCW=”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:11] GotoIf(“SIP/GatewaySIP-000262a6”, “1?next1:cwinusebusy”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Goto (macro-dial-one,s,12)
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:12] GotoIf(“SIP/GatewaySIP-000262a6”, “0?docfu:skip3”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Goto (macro-dial-one,s,16)
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:16] GotoIf(“SIP/GatewaySIP-000262a6”, “1?next2:continue”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Goto (macro-dial-one,s,17)
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:17] GotoIf(“SIP/GatewaySIP-000262a6”, “1?continue”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Goto (macro-dial-one,s,25)
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:25] GotoIf(“SIP/GatewaySIP-000262a6”, “0?nodial”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:26] GosubIf(“SIP/GatewaySIP-000262a6”, “1?dstring,1:dlocal,1”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [dstring@macro-dial-one:1] Set(“SIP/GatewaySIP-000262a6”, “DSTRING=”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [dstring@macro-dial-one:2] Set(“SIP/GatewaySIP-000262a6”, “DEVICES=345”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [dstring@macro-dial-one:3] ExecIf(“SIP/GatewaySIP-000262a6”, “0?Return()”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [dstring@macro-dial-one:4] ExecIf(“SIP/GatewaySIP-000262a6”, “0?Set(DEVICES=45)”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [dstring@macro-dial-one:5] Set(“SIP/GatewaySIP-000262a6”, “LOOPCNT=1”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [dstring@macro-dial-one:6] Set(“SIP/GatewaySIP-000262a6”, “ITER=1”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [dstring@macro-dial-one:7] Set(“SIP/GatewaySIP-000262a6”, “THISDIAL=SIP/345”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [dstring@macro-dial-one:8] GosubIf(“SIP/GatewaySIP-000262a6”, “1?zap2dahdi,1”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [zap2dahdi@macro-dial-one:1] ExecIf(“SIP/GatewaySIP-000262a6”, “0?Return()”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [zap2dahdi@macro-dial-one:2] Set(“SIP/GatewaySIP-000262a6”, “NEWDIAL=”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [zap2dahdi@macro-dial-one:3] Set(“SIP/GatewaySIP-000262a6”, “LOOPCNT2=1”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [zap2dahdi@macro-dial-one:4] Set(“SIP/GatewaySIP-000262a6”, “ITER2=1”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [zap2dahdi@macro-dial-one:5] Set(“SIP/GatewaySIP-000262a6”, “THISPART2=SIP/345”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [zap2dahdi@macro-dial-one:6] ExecIf(“SIP/GatewaySIP-000262a6”, “0?Set(THISPART2=DAHDI/345)”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [zap2dahdi@macro-dial-one:7] Set(“SIP/GatewaySIP-000262a6”, “NEWDIAL=SIP/345&”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [zap2dahdi@macro-dial-one:8] Set(“SIP/GatewaySIP-000262a6”, “ITER2=2”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [zap2dahdi@macro-dial-one:9] GotoIf(“SIP/GatewaySIP-000262a6”, “0?begin2”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [zap2dahdi@macro-dial-one:10] Set(“SIP/GatewaySIP-000262a6”, “THISDIAL=SIP/345”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [zap2dahdi@macro-dial-one:11] Return(“SIP/GatewaySIP-000262a6”, “”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [dstring@macro-dial-one:9] Set(“SIP/GatewaySIP-000262a6”, “DSTRING=SIP/345&”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [dstring@macro-dial-one:10] Set(“SIP/GatewaySIP-000262a6”, “ITER=2”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [dstring@macro-dial-one:11] GotoIf(“SIP/GatewaySIP-000262a6”, “0?begin”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [dstring@macro-dial-one:12] Set(“SIP/GatewaySIP-000262a6”, “DSTRING=SIP/345”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [dstring@macro-dial-one:13] Return(“SIP/GatewaySIP-000262a6”, “”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:27] GotoIf(“SIP/GatewaySIP-000262a6”, “0?nodial”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:28] GotoIf(“SIP/GatewaySIP-000262a6”, “0?skiptrace”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:29] GosubIf(“SIP/GatewaySIP-000262a6”, “1?ctset,1:ctclear,1”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [ctset@macro-dial-one:1] Set(“SIP/GatewaySIP-000262a6”, “DB(CALLTRACE/345)=675807459”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [ctset@macro-dial-one:2] Return(“SIP/GatewaySIP-000262a6”, “”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:30] Set(“SIP/GatewaySIP-000262a6”, “D_OPTIONS=M(auto-blkvm)”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:31] ExecIf(“SIP/GatewaySIP-000262a6”, “0?SIPAddHeader(Alert-Info: )”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:32] ExecIf(“SIP/GatewaySIP-000262a6”, “0?SIPAddHeader()”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:33] ExecIf(“SIP/GatewaySIP-000262a6”, “1?Set(CHANNEL(musicclass)=espera-28042016)”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:34] GosubIf(“SIP/GatewaySIP-000262a6”, “0?qwait,1”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:35] Set(“SIP/GatewaySIP-000262a6”, “__CWIGNORE=TRUE”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:36] Set(“SIP/GatewaySIP-000262a6”, “__KEEPCID=TRUE”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:37] GotoIf(“SIP/GatewaySIP-000262a6”, “0?usegoto,1”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:38] GotoIf(“SIP/GatewaySIP-000262a6”, “1?godial”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Goto (macro-dial-one,s,42)
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-dial-one:42] Dial(“SIP/GatewaySIP-000262a6”, “SIP/345,M(auto-blkvm)”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] netsock2.c: == Using SIP RTP TOS bits 184
[Jun 21 16:32:19] VERBOSE[29107] netsock2.c: == Using SIP RTP CoS mark 5
[Jun 21 16:32:19] VERBOSE[29107] app_dial.c: – Called SIP/345
[Jun 21 16:32:19] VERBOSE[29107] app_dial.c: – SIP/345-0002644e is ringing
[Jun 21 16:32:19] VERBOSE[29107] app_dial.c: – SIP/345-0002644e answered SIP/GatewaySIP-000262a6
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-auto-blkvm:1] Set(“SIP/345-0002644e”, “__MACRO_RESULT=”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-auto-blkvm:2] Macro(“SIP/345-0002644e”, “blkvm-clr,”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-blkvm-clr:1] Set(“SIP/345-0002644e”, “SHARED(BLKVM,SIP/GatewaySIP-000262a6)=”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-blkvm-clr:2] Set(“SIP/345-0002644e”, “GOSUB_RETVAL=”) in new stack
[Jun 21 16:32:19] VERBOSE[29107] pbx.c: – Executing [s@macro-blkvm-clr:3] MacroExit(“SIP/345-0002644e”, “”) in new stack
[Jun 21 16:32:20] VERBOSE[29107] pbx.c: – Executing [s@macro-auto-blkvm:3] ExecIf(“SIP/345-0002644e”, “0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=345)”) in new stack
[Jun 21 16:32:20] VERBOSE[29107] pbx.c: – Executing [s@macro-auto-blkvm:4] ExecIf(“SIP/345-0002644e”, “0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=345)”) in new stack
[Jun 21 16:32:20] DEBUG[29107] channel.c: setting peeraccount to RM129 for SIP/345-0002644e from data on channel SIP/GatewaySIP-000262a6
[Jun 21 16:32:20] DEBUG[29107] channel.c: changing peeraccount from T429 to RM129 on SIP/GatewaySIP-000262a6 to match channel SIP/345-0002644e
[Jun 21 16:32:32] VERBOSE[29107] pbx.c: – Executing [h@macro-dial-one:1] Macro(“SIP/GatewaySIP-000262a6”, “hangupcall,”) in new stack
[Jun 21 16:32:32] VERBOSE[29107] pbx.c: – Executing [s@macro-hangupcall:1] GotoIf(“SIP/GatewaySIP-000262a6”, “1?theend”) in new stack
[Jun 21 16:32:32] VERBOSE[29107] pbx.c: – Goto (macro-hangupcall,s,3)
[Jun 21 16:32:32] VERBOSE[29107] pbx.c: – Executing [s@macro-hangupcall:3] Hangup(“SIP/GatewaySIP-000262a6”, “”) in new stack
[Jun 21 16:32:32] VERBOSE[29107] app_macro.c: == Spawn extension (macro-hangupcall, s, 3) exited non-zero on ‘SIP/GatewaySIP-000262a6’ in macro ‘hangupcall’
[Jun 21 16:32:32] VERBOSE[29107] features.c: == Spawn extension (macro-dial-one, h, 1) exited non-zero on ‘SIP/GatewaySIP-000262a6’
[Jun 21 16:32:32] VERBOSE[29107] app_macro.c: == Spawn extension (macro-dial-one, s, 42) exited non-zero on ‘SIP/GatewaySIP-000262a6’ in macro ‘dial-one’
[Jun 21 16:32:32] VERBOSE[29107] app_macro.c: == Spawn extension (macro-exten-vm, s, 7) exited non-zero on ‘SIP/GatewaySIP-000262a6’ in macro ‘exten-vm’
[Jun 21 16:32:32] VERBOSE[29107] pbx.c: == Spawn extension (from-agente, 345, 2) exited non-zero on ‘SIP/GatewaySIP-000262a6’

As a hint, I can say that the first call in the log has no entry in Master.csv as if never has existed. The total amount of time of the first call is added to the second call in Master.csv entry.
I tried to do a normal transfer, and both calls are registered in Master.csv.

You need a higher verbosity and possibly debug logging enabled. You may need sip debugging enabled.

Note that debugging FreePBX logs is always a pain as we don’t know the fine details of its dial plan or AGI scripts.

Yes, I know what Freepbx logs are. I’ll try to do some pcaps, but I think that the issue is done internally by asterisk, I don’t know if it’s a queue or a Freepbx dialplan problem.
Maybe you can answer a general questiona about CDR, do you know what asterisk application calls it? When the CDR is written? when extension h is called?

Thanks in advance,

What I can’t understant is why, if the calling party (SIP/GatewaySIP-000262a6) was talking with user 698,(SIP/698-000262b4 answered SIP/GatewaySIP-000262a6) after 7 minutes the call hangs up with this spawn message (Spawn extension (from-agente, 345, 1), why 345? 345 is another user who has no relation with 698.
And why after this Spawn message, the call continues trough the dialplan (Executing [345@from-agente:1])?

Hello,

Another example. A call enters in a queue, the call is hanged up and then the call is redirected to another random extension.

[Jun 29 20:09:35] VERBOSE[5276] pbx.c: – Executing [1707@ext-queues:10] Queue(“SIP/GatewaySIP-00062f64”, “1707,t,custom/tienes_llamada,90”) in new stack
[Jun 29 20:09:35] VERBOSE[5276] res_musiconhold.c: – Started music on hold, class ‘espera-24062016’, on SIP/GatewaySIP-00062f64
[Jun 29 20:10:00] VERBOSE[5276] res_musiconhold.c: – Stopped music on hold on SIP/GatewaySIP-00062f64
[Jun 29 20:10:00] VERBOSE[5276] pbx.c: == Spawn extension (from-agente, 616, 1) exited non-zero on ‘SIP/GatewaySIP-00062f64’
[Jun 29 20:10:00] VERBOSE[5276] pbx.c: – Executing [616@from-agente:1] ExecIf(“SIP/GatewaySIP-00062f64”, “0?Set(__RINGTIMER=0)”) in new stack
[Jun 29 20:10:00] VERBOSE[5276] pbx.c: – Executing [616@from-agente:2] Macro(“SIP/GatewaySIP-00062f64”, “exten-vm,novm,616,0,0,0”) in new stack

In queue_log we can see that the call is registered as ABANDON, why the call continues through the dialplan?

1467223775|1467223775.562287|1707|NONE|ENTERQUEUE||619153518|2
1467223800|1467223775.562287|1707|NONE|ABANDON|1|2|25

Regards,