Ticket Navigation

Ticket #2696 (closed Bugs: invalid)

Opened 10 months ago

Last modified 10 months ago

Answered call transferred by queue member drops when goes to voicemail

Reported by:	awells	Assigned to:
Priority:	major	Milestone:	2.5
Component:	Queues	Version:	2.4-branch
Keywords:	queue transfer voicemail drop hangup blockvm	Cc:
Confirmation:	Unreviewed	SVN Revision (if applicable):
Backend Engine:	Asterisk 1.4.x	Backend Engine Version:

Description

Similar to http://freepbx.org/trac/ticket/2687

Call flow: Caller ==> Queue ==> Answered by queue member ==> member transfers call to another extension ==> extension rings, no answer ==> asterisk hangs up

I see "CAME FROM: 575 - Blocking VM cause of key:" show up in the logs.

Log snip:

[Feb 18 17:43:53] DEBUG[6651] app_macro.c: Executed application: GotoIf
[Feb 18 17:43:53] WARNING[6651] func_db.c: DB requires an argument, DB(<family>/<key>)
[Feb 18 17:43:53] VERBOSE[6651] logger.c:     -- Executing [s@macro-vm:4] NoOp("SIP/8.x.x.146-009652b0", "CAME FROM: 565 - Blocking VM cause of key: ") in new stack
[Feb 18 17:43:53] DEBUG[6651] app_macro.c: Executed application: Noop
[Feb 18 17:43:53] DEBUG[6651] app_macro.c: Executed application: Macro
[Feb 18 17:43:53] VERBOSE[6651] logger.c:     -- Executing [8954@from-internal:2] Hangup("SIP/8.x.x.146-009652b0", "") in new stack
[Feb 18 17:43:53] VERBOSE[6651] logger.c:   == Spawn extension (from-internal, 8954, 2) exited non-zero on 'SIP/8.x.x.146-009652b0'

I think that this line:

Feb 18 17:43:53] WARNING[6651] func_db.c: DB requires an argument, DB(<family>/<key>)

may be it trying to delete the BLOCKVM flag but a typo/bug is preventing it from doing that.

I hope this is helpful, it is difficult for me to get log snips. This system has such high call volume that we have to set verbosity to 0 or the disk activity causes voice quality problems.

Change History

02/20/08 21:05:53 changed by awells

Ok, found something new. It seems to only happen if the person initiating the transfer is a dynamic agent in the queue. I just added a debug extension to a queue via the gui and was able to transfer a call just fine. However, once I removed it from the gui, and added it dynamically via the manager, I was unable to transfer the call. Full log snip starting with the extension answering the call below (callerid and ip addresses masked/changed):

    -- Executing [565@ext-queues:17] Queue("SIP/8.x.x.146-ac312340", "565|tr|||30") in new stack
    -- Called sip/8956
    -- Called sip/8966
 Extension Changed 8956 new state Ringing for Notify User 8990
    -- Called sip/8962
    -- Called sip/8959
    -- Called sip/8992
    -- Called sip/8988
    -- Called sip/8954
    -- Called sip/9999
    -- Called sip/8964
    -- Called sip/8960
    -- Called sip/8990
    -- Called sip/8987
    -- SIP/8966-ac0434e0 is ringing
    -- SIP/8992-00cdbf40 is ringing
    -- SIP/8962-0098f330 is ringing
    -- SIP/8990-ac04fea0 is ringing
    -- SIP/9999-c40472c0 is ringing
    -- SIP/8987-ac0541e0 is ringing
    -- SIP/8954-c4076be0 is ringing
    -- SIP/8960-ac04bb60 is ringing
    -- SIP/8988-c8086700 is ringing
    -- SIP/8964-ac047820 is ringing
    -- SIP/8959-00affa50 is ringing
    -- SIP/8956-ac308200 is ringing
    -- SIP/9999-c40472c0 answered SIP/8.x.x.146-ac312340
 Extension Changed 8956 new state Idle for Notify User 8990 
    -- Started music on hold, class 'default', on SIP/8.x.x.146-ac312340
    -- Stopped music on hold on SIP/8.x.x.146-ac312340
  == Spawn extension (from-internal-xfer, 1111, 0) exited non-zero on 'SIP/8.x.x.146-ac312340'
    -- Executing [1111@from-internal-xfer:1] Macro("SIP/8.x.x.146-ac312340", "exten-vm|1111|1111") in new stack
    -- Executing [s@macro-exten-vm:1] Macro("SIP/8.x.x.146-ac312340", "user-callerid") in new stack
    -- Executing [s@macro-user-callerid:1] NoOp("SIP/8.x.x.146-ac312340", "user-callerid: FISH:WIRELESS CALLER 7705555555") in new stack
    -- Executing [s@macro-user-callerid:2] Set("SIP/8.x.x.146-ac312340", "AMPUSER=7705555555") in new stack
    -- Executing [s@macro-user-callerid:3] GotoIf("SIP/8.x.x.146-ac312340", "0?report") in new stack
    -- Executing [s@macro-user-callerid:4] ExecIf("SIP/8.x.x.146-ac312340", "0|Set|REALCALLERIDNUM=7705555555") in new stack
    -- Executing [s@macro-user-callerid:5] NoOp("SIP/8.x.x.146-ac312340", "REALCALLERIDNUM is 7705555555") in new stack
    -- Executing [s@macro-user-callerid:6] Set("SIP/8.x.x.146-ac312340", "AMPUSER=") in new stack
    -- Executing [s@macro-user-callerid:7] Set("SIP/8.x.x.146-ac312340", "AMPUSERCIDNAME=") in new stack
    -- Executing [s@macro-user-callerid:8] GotoIf("SIP/8.x.x.146-ac312340", "1?report") in new stack
    -- Goto (macro-user-callerid,s,13)
    -- Executing [s@macro-user-callerid:13] NoOp("SIP/8.x.x.146-ac312340", "TTL: 63 ARG1: 1111") in new stack
    -- Executing [s@macro-user-callerid:14] GotoIf("SIP/8.x.x.146-ac312340", "0?continue") in new stack
    -- Executing [s@macro-user-callerid:15] Set("SIP/8.x.x.146-ac312340", "__TTL=62") in new stack
    -- Executing [s@macro-user-callerid:16] GotoIf("SIP/8.x.x.146-ac312340", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,23)
    -- Executing [s@macro-user-callerid:23] NoOp("SIP/8.x.x.146-ac312340", "Using CallerID "FISH:WIRELESS CALLER" <7705555555>") in new stack
    -- Executing [s@macro-exten-vm:2] Set("SIP/8.x.x.146-ac312340", "FROMCONTEXT=exten-vm") in new stack
    -- Executing [s@macro-exten-vm:3] Set("SIP/8.x.x.146-ac312340", "VMBOX=1111") in new stack
    -- Executing [s@macro-exten-vm:4] Set("SIP/8.x.x.146-ac312340", "EXTTOCALL=1111") in new stack
    -- Executing [s@macro-exten-vm:5] Set("SIP/8.x.x.146-ac312340", "CFUEXT=") in new stack
    -- Executing [s@macro-exten-vm:6] Set("SIP/8.x.x.146-ac312340", "CFBEXT=") in new stack
    -- Executing [s@macro-exten-vm:7] Set("SIP/8.x.x.146-ac312340", "RT=15") in new stack
    -- Executing [s@macro-exten-vm:8] Macro("SIP/8.x.x.146-ac312340", "record-enable|1111|IN") in new stack
    -- Executing [s@macro-record-enable:1] GotoIf("SIP/8.x.x.146-ac312340", "1?2:4") in new stack
    -- Goto (macro-record-enable,s,2)
    -- Executing [s@macro-record-enable:2] ResetCDR("SIP/8.x.x.146-ac312340", "w") in new stack
    -- Executing [s@macro-record-enable:3] StopMonitor("SIP/8.x.x.146-ac312340", "") in new stack
    -- Executing [s@macro-record-enable:4] AGI("SIP/8.x.x.146-ac312340", "recordingcheck|20080220-235921|1203569926.82653") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
  recordingcheck|20080220-235921|1203569926.82653: Inbound recording not enabled
    -- AGI Script recordingcheck completed, returning 0
    -- Executing [s@macro-record-enable:5] NoOp("SIP/8.x.x.146-ac312340", "No recording needed") in new stack
    -- Executing [s@macro-exten-vm:9] Macro("SIP/8.x.x.146-ac312340", "dial|15|M(auto-blkvm)M(auto-blkvm)|1111") in new stack
    -- Executing [s@macro-dial:1] GotoIf("SIP/8.x.x.146-ac312340", "1?dial") in new stack
    -- Goto (macro-dial,s,3)
    -- Executing [s@macro-dial:3] AGI("SIP/8.x.x.146-ac312340", "dialparties.agi") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
  dialparties.agi: Starting New Dialparties.agi
  == Parsing '/etc/asterisk/manager.conf': Found
  == Parsing '/etc/asterisk/manager_additional.conf': Found
  == Parsing '/etc/asterisk/manager_custom.conf': Found
  == Manager 'admin' logged on from 127.0.0.1
  dialparties.agi: Caller ID name is 'FISH:WIRELESS CALLER' number is '7705555555'
  dialparties.agi: Methodology of ring is  'none'
    --  dialparties.agi: Added extension 1111 to extension map
    --  dialparties.agi: Extension 1111 cf is disabled
    --  dialparties.agi: Extension 1111 do not disturb is disabled
    --  dialparties.agi: dbset CALLTRACE/1111 to 7705555555
    --  dialparties.agi: Filtered ARG3: 1111
  == Manager 'admin' logged off from 127.0.0.1
    -- AGI Script dialparties.agi completed, returning 0
    -- Executing [s@macro-dial:7] Dial("SIP/8.x.x.146-ac312340", "SIP/1111|15|M(auto-blkvm)M(auto-blkvm)") in new stack
  == Everyone is busy/congested at this time (1:0/0/1)
    -- Executing [s@macro-dial:8] Set("SIP/8.x.x.146-ac312340", "DIALSTATUS=CHANUNAVAIL") in new stack
    -- Executing [s@macro-exten-vm:10] Set("SIP/8.x.x.146-ac312340", "SV_DIALSTATUS=CHANUNAVAIL") in new stack
    -- Executing [s@macro-exten-vm:11] GosubIf("SIP/8.x.x.146-ac312340", "0?docfu|1") in new stack
    -- Executing [s@macro-exten-vm:12] GosubIf("SIP/8.x.x.146-ac312340", "0?docfb|1") in new stack
    -- Executing [s@macro-exten-vm:13] Set("SIP/8.x.x.146-ac312340", "DIALSTATUS=CHANUNAVAIL") in new stack
    -- Executing [s@macro-exten-vm:14] NoOp("SIP/8.x.x.146-ac312340", "Voicemail is 1111") in new stack
    -- Executing [s@macro-exten-vm:15] GotoIf("SIP/8.x.x.146-ac312340", "0?s-CHANUNAVAIL|1") in new stack
    -- Executing [s@macro-exten-vm:16] NoOp("SIP/8.x.x.146-ac312340", "Sending to Voicemail box 1111") in new stack
    -- Executing [s@macro-exten-vm:17] Macro("SIP/8.x.x.146-ac312340", "vm|1111|CHANUNAVAIL") in new stack
    -- Executing [s@macro-vm:1] Macro("SIP/8.x.x.146-ac312340", "user-callerid|SKIPTTL") in new stack
    -- Executing [s@macro-user-callerid:1] NoOp("SIP/8.x.x.146-ac312340", "user-callerid: FISH:WIRELESS CALLER 7705555555") in new stack
    -- Executing [s@macro-user-callerid:2] Set("SIP/8.x.x.146-ac312340", "AMPUSER=7705555555") in new stack
    -- Executing [s@macro-user-callerid:3] GotoIf("SIP/8.x.x.146-ac312340", "0?report") in new stack
    -- Executing [s@macro-user-callerid:4] ExecIf("SIP/8.x.x.146-ac312340", "0|Set|REALCALLERIDNUM=7705555555") in new stack
    -- Executing [s@macro-user-callerid:5] NoOp("SIP/8.x.x.146-ac312340", "REALCALLERIDNUM is 7705555555") in new stack
    -- Executing [s@macro-user-callerid:6] Set("SIP/8.x.x.146-ac312340", "AMPUSER=") in new stack
    -- Executing [s@macro-user-callerid:7] Set("SIP/8.x.x.146-ac312340", "AMPUSERCIDNAME=") in new stack
    -- Executing [s@macro-user-callerid:8] GotoIf("SIP/8.x.x.146-ac312340", "1?report") in new stack
    -- Goto (macro-user-callerid,s,13)
    -- Executing [s@macro-user-callerid:13] NoOp("SIP/8.x.x.146-ac312340", "TTL: 62 ARG1: SKIPTTL") in new stack
    -- Executing [s@macro-user-callerid:14] GotoIf("SIP/8.x.x.146-ac312340", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,23)
    -- Executing [s@macro-user-callerid:23] NoOp("SIP/8.x.x.146-ac312340", "Using CallerID "FISH:WIRELESS CALLER" <7705555555>") in new stack
    -- Executing [s@macro-vm:2] Set("SIP/8.x.x.146-ac312340", "VMGAIN=""") in new stack
    -- Executing [s@macro-vm:3] GotoIf("SIP/8.x.x.146-ac312340", "0?vmx|1") in new stack
    -- Executing [s@macro-vm:4] NoOp("SIP/8.x.x.146-ac312340", "CAME FROM: 565 - Blocking VM cause of key: ") in new stack
    -- Executing [1111@from-internal-xfer:2] Hangup("SIP/8.x.x.146-ac312340", "") in new stack
  == Spawn extension (from-internal-xfer, 1111, 2) exited non-zero on 'SIP/8.x.x.146-ac312340'
    -- Executing [h@from-internal-xfer:1] Macro("SIP/8.x.x.146-ac312340", "hangupcall") in new stack
    -- Executing [s@macro-hangupcall:1] ResetCDR("SIP/8.x.x.146-ac312340", "w") in new stack
    -- Executing [s@macro-hangupcall:2] NoCDR("SIP/8.x.x.146-ac312340", "") in new stack
    -- Executing [s@macro-hangupcall:3] GotoIf("SIP/8.x.x.146-ac312340", "1?skiprg") in new stack
    -- Goto (macro-hangupcall,s,6)
    -- Executing [s@macro-hangupcall:6] GotoIf("SIP/8.x.x.146-ac312340", "0?skipblkvm") in new stack
    -- Executing [s@macro-hangupcall:7] NoOp("SIP/8.x.x.146-ac312340", "Cleaning Up Block VM Flag: BLKVM/565/SIP/8.x.x.146-ac312340") in new stack
    -- Executing [s@macro-hangupcall:8] DBdel("SIP/8.x.x.146-ac312340", "BLKVM/565/SIP/8.x.x.146-ac312340") in new stack
    -- DBdel: family=BLKVM, key=565/SIP/8.x.x.146-ac312340
    -- Executing [s@macro-hangupcall:9] GotoIf("SIP/8.x.x.146-ac312340", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,11)
    -- Executing [s@macro-hangupcall:11] Hangup("SIP/8.x.x.146-ac312340", "") in new stack

02/20/08 21:22:30 changed by awells

Sorry for so many updates. I have a lull in call traffic right now, so I can collect data. Here's an example from when I added the member from the GUI:

    -- SIP/9999-c8086700 answered Local/9999@from-internal-729a,2
    -- Executing [s@macro-auto-blkvm:1] Set("SIP/9999-c8086700", "__MACRO_RESULT=") in new stack
    -- Executing [s@macro-auto-blkvm:2] Set("SIP/9999-c8086700", "__CWIGNORE=") in new stack
    -- Executing [s@macro-auto-blkvm:3] DBdel("SIP/9999-c8086700", "BLKVM/565/SIP/8.x.x.146-ac2a0da0") in new stack

Notice that the 3 lines after the answered line do not happen whan an agent that was added dynamically answers the call, as evidenced above. I also notice that the dynamic agent's answered line is different:

-- SIP/9999-c8086700 answered Local/9999@from-internal-729a,2

versus

-- SIP/9999-c40472c0 answered SIP/8.x.x.146-ac312340

On a bit of inspiration, I removed my queue member and readded it with Local/9999 rather than SIP/9999, ie:

Action: QueueAdd
Interface: Local/9999
Queue: 565
Penalty: 0
Paused: false

Action: QueueAdd
Interface: SIP/9999
Queue: 565
Penalty: 0
Paused: false

and I am able to transfer calls and have them land in voicemail. Using Local/ causes dialparties to run for each extension in the queue, and the overhead from this worries me. Is there a way for this to work with the agents added as SIP/exten instead of Local/exten?

02/21/08 07:03:06 changed by p_lindheimer

status changed from new to closed.
resolution set to invalid.
milestone changed from Cut Line to 3.0.

Queue's need to be setup as implemented in the GUI with channel local. FreePBX is not designed to be a high volume call center. If the overhead of running it through Channel Local and thus dialparties.agi is too much, either get a more powerful system or yo may be trying to run a high volume call center on a dialplan that is not designed for that.

It needs to run through the Local Channel to ensure that extension's don't drop into voicemail prematurely and that once a call is answered it can subsequently be transfered.

Marking ticket as invalid (really should be worksforme if configured as FreePBX is designed)

Download in other formats:

Development - Get Connected