Ticket #2696 (closed Bugs: invalid)

Opened 4 years ago

Last modified 4 years 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 23: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 23: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

vs 

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 09: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)