Queue call: not wanted transfer to another extension

Santi · June 27, 2016, 11:01am

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

david551 · June 27, 2016, 11:11am

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

Santi · June 27, 2016, 11:27am

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

Santi · June 27, 2016, 11:33am

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.

david551 · June 27, 2016, 12:37pm

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.

Santi · June 27, 2016, 1:57pm

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,

Santi · June 29, 2016, 11:37am

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])?

Santi · June 30, 2016, 8:03am

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,

Topic		Replies	Views
Call drops when i transfer from queue Asterisk Support	3	381	July 20, 2011
Queue (randomly) does not transfer call to extensions Asterisk Support	1	441	October 2, 2014
Probably site specific call xfer problem Asterisk Support	5	221	September 7, 2010
Call drops when queue transfers call to operator Asterisk Support	2	528	May 24, 2020
Transferred Calls Lost Asterisk Support	3	232	January 14, 2006

Queue call: not wanted transfer to another extension

Related topics