[Home]

Summary:ASTERISK-13635: [patch] After a caller is processed by app_queue the queue_log logs the hangup as TRANSFER
Reporter:David Brillert (aragon)Labels:
Date Opened:2009-02-23 19:26:13.000-0600Date Closed:2011-04-07 13:09:49
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Applications/app_queue
Versions:Frequency of
Occurrence
Related
Issues:
causesASTERISK-23730 [patch] Blind transfers are not logged into queue_log
is related toASTERISK-17658 [patch] [regression] Blind transfers from queue are not logged into queue_log correctly
Environment:Attachments:( 0) queue-log-xfer-fix1.diff
( 1) queue-sales-context-equal-commzilla-aa-mainmenu.txt
( 2) queue-sales-context-null.txt
Description:I'm using agent callback and not channel_agent

In this example ext 222 dials *850 to enter a test queue and ext 233 (agent 1) answers the call. Then 222 hangs up.
But my queue_log logs the hangup reason as TRANSFER instead of COMPLETEAGENT or COMPLETECALLER

I think I am using revision 173594

****** ADDITIONAL INFORMATION ******

Here is the CLI of the call and the last message indicates the disconnect reason as hangup but the queue_log shows the disconnect reason as transfer

Executing [s@commzilla-application-acd-family:10] Set("SIP/222-08c46a60", "__ACD_TO_OUTGOING=1") in new stack
   -- Executing [s@commzilla-application-acd-family:11] Set("SIP/222-08c46a60", "CHANNEL(musicclass)=default") in new stack
   -- Executing [s@commzilla-application-acd-family:12] Set("SIP/222-08c46a60", "__ALLOW_TRANSFER=twk") in new stack
   -- Executing [s@commzilla-application-acd-family:13] Set("SIP/222-08c46a60", "CALLERID(name)=family:WiFi") in new stack
   -- Executing [s@commzilla-application-acd-family:14] Queue("SIP/222-08c46a60", "commzilla-family|tH|||300|") in new stack
   -- Started music on hold, class 'default', on SIP/222-08c46a60
   -- Called Local/233@commzilla-agent/n
   -- Executing [233@commzilla-agent:1] NoCDR("Local/233@commzilla-agent-692a,2", "") in new stack
   -- Executing [233@commzilla-agent:2] Set("Local/233@commzilla-agent-692a,2", "DND=") in new stack
   -- Executing [233@commzilla-agent:3] GotoIf("Local/233@commzilla-agent-692a,2", "0?20") in new stack
   -- Executing [233@commzilla-agent:4] Set("Local/233@commzilla-agent-692a,2", "OutOffice=") in new stack
   -- Executing [233@commzilla-agent:5] GotoIf("Local/233@commzilla-agent-692a,2", "0?20") in new stack
   -- Executing [233@commzilla-agent:6] Set("Local/233@commzilla-agent-692a,2", "GROUPCOUNT=0") in new stack
   -- Executing [233@commzilla-agent:7] Set("Local/233@commzilla-agent-692a,2", "AGENTMAXCALL=") in new stack
   -- Executing [233@commzilla-agent:8] GotoIf("Local/233@commzilla-agent-692a,2", "1?9:10") in new stack
   -- Goto (commzilla-agent,233,9)
   -- Executing [233@commzilla-agent:9] Set("Local/233@commzilla-agent-692a,2", "AGENTMAXCALL=1") in new stack
   -- Executing [233@commzilla-agent:10] GotoIf("Local/233@commzilla-agent-692a,2", "0?20") in new stack
   -- Executing [233@commzilla-agent:11] GotoIf("Local/233@commzilla-agent-692a,2", "1?14") in new stack
   -- Goto (commzilla-agent,233,14)
   -- Executing [233@commzilla-agent:14] Set("Local/233@commzilla-agent-692a,2", "OUTBOUND_GROUP_ONCE=233@INCOMING") in new stack
   -- Executing [233@commzilla-agent:15] Set("Local/233@commzilla-agent-692a,2", "DB(commzilla/wrapup/233/lastcall)=1235437538.32") in new stack
   -- Executing [233@commzilla-agent:16] Goto("Local/233@commzilla-agent-692a,2", "commzilla-local-devices|233|1") in new stack
   -- Goto (commzilla-local-devices,233,1)
   -- Executing [233@commzilla-local-devices:1] Set("Local/233@commzilla-agent-692a,2", "DB(commzilla/wrapup/233/lastcall)=1235437538.32") in new stack
   -- Executing [233@commzilla-local-devices:2] Dial("Local/233@commzilla-agent-692a,2", "SIP/233||twk") in new stack
Extension Changed 233[commzilla-local] new state Ringing for Notify User 300
Extension Changed 233[commzilla-local] new state Ringing for Notify User 220
   -- Called 233
   -- SIP/233-08cff938 is ringing
   -- Local/233@commzilla-agent-692a,1 is ringing
   -- SIP/233-08cff938 is ringing
   -- SIP/233-08cff938 is ringing
   -- SIP/233-08cff938 answered Local/233@commzilla-agent-692a,2
Extension Changed 233[commzilla-local] new state InUse for Notify User 300
Extension Changed 233[commzilla-local] new state InUse for Notify User 220
   -- Local/233@commzilla-agent-692a,1 answered SIP/222-08c46a60
   -- Stopped music on hold on SIP/222-08c46a60
   -- Executing [h@commzilla-application-acd-family:1] Goto("SIP/222-08c46a60", "all-hangup|s|1") in new stack
   -- Goto (all-hangup,s,1)
   -- Executing [s@all-hangup:1] GotoIf("SIP/222-08c46a60", "0?all-faxnotify|s|1:2") in new stack
   -- Goto (all-hangup,s,2)
   -- Executing [s@all-hangup:2] ResetCDR("SIP/222-08c46a60", "w") in new stack
   -- Executing [s@all-hangup:3] NoCDR("SIP/222-08c46a60", "") in new stack
   -- Executing [s@all-hangup:4] System("SIP/222-08c46a60", "/var/www/scopserv/telephony/scripts/billing/cdr.sh 1235437529.30") in new stack
 == Spawn extension (all-hangup, s, 14) exited non-zero on 'SIP/222-08c46a60'
 == Spawn extension (commzilla-local-devices, 233, 2) exited non-zero on 'Local/233@commzilla-agent-692a,2'
Extension Changed 222[commzilla-local] new state Idle for Notify User 300
Extension Changed 222[commzilla-local] new state Idle for Notify User 220
Extension Changed 233[commzilla-local] new state Idle for Notify User 300
Extension Changed 233[commzilla-local] new state Idle for Notify User 220
Really destroying SIP dialog '2dec617e5bec0f1844b375176a2da10e@192.168.192.1' Method: INVITE

cat queue_log
1235379739|NONE|NONE|NONE|CONFIGRELOAD|
1235401044|NONE|NONE|NONE|CONFIGRELOAD|
1235426085|NONE|NONE|NONE|QUEUESTART|
1235427633|NONE|NONE|NONE|QUEUESTART|
1235428219|NONE|NONE|NONE|QUEUESTART|
1235437390|NONE|NONE|NONE|CONFIGRELOAD|
1235437446|1235437437.25|commzilla-family|NONE|ENTERQUEUE||222
1235437463|1235437458.26|NONE|Agent/1|AGENTCALLBACKLOGIN|Local/233@commzilla-agent/n
1235437463|1235437458.26|commzilla-family|Local/233@commzilla-agent/n|ADDMEMBER|
1235437476|1235437437.25|commzilla-family|Local/233@commzilla-agent/n|CONNECT|30|1235437473.27
1235437479|1235437437.25|commzilla-family|Local/233@commzilla-agent/n|TRANSFER|s|all-hangup|30|3
1235437538|1235437529.30|commzilla-family|NONE|ENTERQUEUE||222
1235437540|1235437529.30|commzilla-family|Local/233@commzilla-agent/n|CONNECT|2|1235437538.31
1235437551|1235437529.30|commzilla-family|Local/233@commzilla-agent/n|TRANSFER|s|all-hangup|2|11

I think this is odd behavior possibly resulting from recent changes to h extension and possibly revision 172030

Comments:By: David Brillert (aragon) 2009-02-23 19:33:10.000-0600

I just retested this problem on revision 178108 with same results
By: David Brillert (aragon) 2009-02-23 20:06:45.000-0600

I think this problem was introduced in one of these revisions
172030 or 174885
By: Joel Vandal (jvandal) 2009-02-24 09:33:52.000-0600

I also think that this can be related to 172030.

174885 is a problem related to Macro and I don't think this apply to queue.
By: David Brillert (aragon) 2009-02-26 09:59:33.000-0600

The problem isn't service affecting so I opened it as minor but its bunging up all my Call Center statistics.  I hope this bug will be assigned to a developer soon.  I cannot upgrade Asterisk on any other sites until this issue is resolved... and I wouldn't want to see this problem turn up in 1.4.24 when it is released to the masses.


By: David Brillert (aragon) 2009-03-03 08:07:39.000-0600

Hi,

Given that this issue was probably introduced by revision 172030 and this revision was written by murf perhaps this bug report could at least be assigned to murf...
This problem is really starting to affect a lot of my customers; and there appears to be no way of compensating for this regression in my dial plan.
I'm stuck in a permanent hold pattern before I can upgrade any call center customers to any Asterisk version including revision 172030. This hurts because there was a lot of work done here to fix call park and transfer segfaults and I really that code too...
Naturally I am willing to test any patches and have access to a few development systems for testing.

Here are the details on revision 172030
I believe it is the 5. in the list that is causing the regression.
Unfortunately this is making my call center reports useless because all answered then hangups are documented as "TRANSFER" in the /var/log/asterisk/queue_log

Revision 172030 - Directory Listing
Modified Wed Jan 28 18:51:16 2009 UTC (4 weeks, 5 days ago) by murf

This patch fixes h-exten running misbehavior in manager-redirected
situations.

What it does:
1. A new Flag value is defined in include/asterisk/channel.h,
AST_FLAG_BRIDGE_HANGUP_DONT, which used as a messenge to the
bridge hangup exten code not to run the h-exten there (nor
publish the bridge cdr there). It will done at the pbx-loop
level instead.
2. In the manager Redirect code, I set this flag on the channel
if the channel has a non-null pbx pointer. I did the same for the
second (chan2) channel, which gets run if name2 is set...
and the first succeeds.
3. I restored the ending of the cdr for the pbx loop h-exten
running code. Don't know why it was removed in the first place.
4. The first attempt at the fix for this bug was to place code
  directly in the async_goto routine, which was called from a
  large number of places, and could affect a large number of
  cases, so I tested that fix against a fair number of transfer
  scenarios, both with and without the patch. In the process,
  I saw that putting the fix in async_goto seemed not to affect
  any of the blind or attended scenarios, but still, I was
  was highly concerned that some other scenarios I had not tested
  might be negatively impacted, so I refined the patch to
  its current scope, and jmls tested both. In the process, tho,
  I saw that blind xfers in one situation, when the one-touch
  blind-xfer feature is used by the peer, we got strange
  h-exten behavior.  So, I  inserted code to swap CDRs and
  to set the HANGUP_DONT field, to get uniform behavior.
5. I added code to the bridge to obey the HANGUP_DONT flag,
  skipping both publishing the bridge CDR, and running
  the h-exten; they will be done at the pbx-loop (higher)
  level instead.
6. I removed all the debug logs from the patch before committing.
7. I moved the AUTOLOOP set/reset in the h-exten code in res_features
  so it's only done if the h-exten is going to be run. A very
  minor performance improvement, but technically correct.


(closes issue ASTERISK-13367)
Reported by: jmls
Patches:
     14241_redirect_no_bridgeCDR_or_h_exten_via_transfer uploaded by murf (license 17)
Tested by: murf, jmls


By: David Brillert (aragon) 2009-03-04 10:17:53.000-0600

I found the cause of this.

The call is logged as a transfer if "Single Digit Key Press: =AA

Single Digit Key Press: = NONE
Logs disconnect reason correctly

The 'Single Key Press' option will set on queue.conf :
[default-sales]
music                          =  default
strategy                       =  rrmemory
servicelevel                   =  30
context                        =  default-aa-servicemainmenubutton1englishsubmenu
timeout                        =  15
retry                          =  5
maxlen                         =  0
weight                         =  0
reportholdtime                 =  no
reportwaitcall                 =  no
memberdelay                    =  0
timeoutrestart                 =  no
autofill                       =  yes
autopause                      =  no
ringinuse                      =  no
setinterfacevar                =  yes
wrapuptime                     =  
joinempty                      =  yes
leavewhenempty                 =  no
eventwhencalled                =  vars
eventmemberstatus              =  yes
queue-youarenext               =  queue-youarenext
queue-thereare                 =  queue-thereare
queue-callswaiting             =  queue-callswaiting
queue-holdtime                 =  queue-holdtime
queue-minutes                  =  queue-minutes
queue-seconds                  =  queue-seconds
queue-thankyou                 =  queue-thankyou
queue-lessthan                 =  queue-less-than

but I don't think problem is with the 'ivr menu' but with a bug on app_queue.c

if I check this code :

 if (!attended_transfer_occurred(qe->chan)) {
                       struct ast_datastore *tds;
                       if (strcasecmp(oldcontext, qe->chan->context) || strcasecmp(oldexten, qe->chan->exten)) {
                               ast_queue_log(queuename, qe->chan->uniqueid, member->membername, "TRANSFER", "%s|%s|%ld|%ld",....

ok... this is not an attended transfer, so ...
    ahh the context doesn't match the oldcontext ... then this is a TRANSFER call

It report TRANSFER instead of EXITWITHKEY

Also it does not matter if anyone presses DTMF while waiting in queue, simply the fact that Single Digit Key Press= AA is enough to corrupt disconnect reason
By: Joel Vandal (jvandal) 2009-03-04 10:22:17.000-0600

Please note that ' Single Key Press ' option correspond to the 'context=' line on queues.conf
By: David Brillert (aragon) 2009-03-04 18:27:28.000-0600

Well that's it I'm stuck...
I'm pretty sure I have found root cause but I have no programming knowledge and can not write a patch.

Hopefully this bug report will be assigned soon and I can start testing a patch.
By: David Brillert (aragon) 2009-03-09 16:57:20

This is busted because of revision 172020 I'm sure of it.
I cant tell where exactly but probably around line 1681
I'll upload better CLI logs with debug enabled, maybe later tonight.
By: David Brillert (aragon) 2009-03-09 18:17:00

When queue-sales context is null then queue_log is not poisoned with TRANSFER events and ridiculously short call durations

Everything in this CLI and queue_log file appears to be normal

cat /var/log/asterisk/queue_log
1236585727|NONE|NONE|NONE|CONFIGRELOAD|
1236621268|NONE|NONE|NONE|CONFIGRELOAD|
1236639794|NONE|NONE|NONE|CONFIGRELOAD|
1236639967|1236639961.219|NONE|Agent/1|AGENTCALLBACKLOGIN|Local/233@commzilla-agent/n
1236639967|1236639961.219|commzilla-sales|Local/233@commzilla-agent/n|ADDMEMBER|
1236639989|1236639984.220|commzilla-sales|NONE|ENTERQUEUE||222
1236639990|1236639984.220|commzilla-sales|Local/233@commzilla-agent/n|CONNECT|1|1236639989.221
1236639992|1236639984.220|commzilla-sales|Local/233@commzilla-agent/n|COMPLETECALLER|1|2|1
1236640069|1236640064.225|commzilla-sales|NONE|ENTERQUEUE||222
1236640071|1236640064.225|commzilla-sales|Local/233@commzilla-agent/n|CONNECT|2|1236640069.226
1236640074|1236640064.225|commzilla-sales|Local/233@commzilla-agent/n|COMPLETEAGENT|2|3|1
1236640157|1236640152.229|commzilla-sales|NONE|ENTERQUEUE||222
1236640159|1236640152.229|commzilla-sales|Local/233@commzilla-agent/n|CONNECT|2|1236640157.230
1236640161|1236640152.229|commzilla-sales|Local/233@commzilla-agent/n|COMPLETECALLER|2|2|1


[commzilla-sales]
music                          =  default
strategy                       =  rrmemory
servicelevel                   =  45
timeout                        =  20
retry                          =  5
maxlen                         =  0
weight                         =  0
reportholdtime                 =  no
reportwaitcall                 =  no
memberdelay                    =  0
timeoutrestart                 =  no
autofill                       =  yes
autopause                      =  no
ringinuse                      =  no
setinterfacevar                =  yes
wrapuptime                     =  0
joinempty                      =  yes
leavewhenempty                 =  no
eventwhencalled                =  vars
eventmemberstatus              =  yes
periodic-announce-frequency    =  20
periodic-announce              =  custom/0002
monitor-format                 =  wav49
monitor-type                   =  MixMonitor
queue-youarenext               =  queue-youarenext
queue-thereare                 =  queue-thereare
queue-callswaiting             =  queue-callswaiting
queue-holdtime                 =  queue-holdtime
queue-minutes                  =  queue-minutes
queue-seconds                  =  queue-seconds
queue-thankyou                 =  queue-thankyou
queue-lessthan                 =  queue-less-than

Debug CLI output truncated by bug tracker uploading debug info as
queue-sales-contex-null.txt


By: David Brillert (aragon) 2009-03-09 18:23:26

When queue-sales context is not null then queue_log is written with incorrect disconnect cause for every single call and call duration is equal to almost zero seconds.

[commzilla-sales]
music                          =  default
strategy                       =  rrmemory
servicelevel                   =  45
context                        =  commzilla-aa-mainmenu
timeout                        =  20
retry                          =  5
maxlen                         =  0
weight                         =  0
reportholdtime                 =  no
reportwaitcall                 =  no
memberdelay                    =  0
timeoutrestart                 =  no
autofill                       =  yes
autopause                      =  no
ringinuse                      =  no
setinterfacevar                =  yes
wrapuptime                     =  0
joinempty                      =  yes
leavewhenempty                 =  no
eventwhencalled                =  vars
eventmemberstatus              =  yes
periodic-announce-frequency    =  20
periodic-announce              =  custom/0002
monitor-format                 =  wav49
monitor-type                   =  MixMonitor
queue-youarenext               =  queue-youarenext
queue-thereare                 =  queue-thereare
queue-callswaiting             =  queue-callswaiting
queue-holdtime                 =  queue-holdtime
queue-minutes                  =  queue-minutes
queue-seconds                  =  queue-seconds
queue-thankyou                 =  queue-thankyou
queue-lessthan                 =  queue-less-than

cat /var/log/asterisk/queue_log
1236640646|NONE|NONE|NONE|CONFIGRELOAD|
1236640766|1236640761.233|commzilla-sales|NONE|ENTERQUEUE||222
1236640767|1236640761.233|commzilla-sales|Local/233@commzilla-agent/n|CONNECT|1|1236640766.234
1236640770|1236640761.233|commzilla-sales|Local/233@commzilla-agent/n|TRANSFER|s|all-hangup|1|3

My CLI debugs were truncated by bugtracker so uploading as txt file
queue-sales-context-equal-commzilla-aa-mainmenu.txt


By: David Brillert (aragon) 2009-03-09 18:29:44

This bug is starting to cost me a lot of money.
I cannot downgrade because of the serious issues I was having with parking, attended transfer, blind transfer segfaults.  Unfortunately I must use 1.4 SVN Asterisk version.
By: David Brillert (aragon) 2009-03-09 18:35:38

Also I am using state_interface backport but not related IMHO.  I've been using this backport for months
By: David Brillert (aragon) 2009-03-09 18:40:15

This code from 172030 revision appears to be suspect but well beyond my understanding to debug or patch

res_features.c

1511 /* better yet, in a xfer situation, find out why the chan cdr got zapped (pun unintentional) */
1512 bridge_cdr = ast_cdr_alloc(); /* this should be really, really rare/impossible? */
1513 ast_copy_string(bridge_cdr->channel, chan->name, sizeof(bridge_cdr->channel));
1514 ast_copy_string(bridge_cdr->dstchannel, peer->name, sizeof(bridge_cdr->dstchannel));
1515 ast_copy_string(bridge_cdr->uniqueid, chan->uniqueid, sizeof(bridge_cdr->uniqueid));
1516 ast_copy_string(bridge_cdr->lastapp, chan->appl, sizeof(bridge_cdr->lastapp));
1517 ast_copy_string(bridge_cdr->lastdata, chan->data, sizeof(bridge_cdr->lastdata));
1518 ast_cdr_setcid(bridge_cdr, chan);
1519 bridge_cdr->disposition = (chan->_state == AST_STATE_UP) ? AST_CDR_ANSWERED : AST_CDR_NULL;
1520 bridge_cdr->amaflags = chan->amaflags ? chan->amaflags : ast_default_amaflags;
1521 ast_copy_string(bridge_cdr->accountcode, chan->accountcode, sizeof(bridge_cdr->accountcode));
1522 /* Destination information */
1523 ast_copy_string(bridge_cdr->dst, chan->exten, sizeof(bridge_cdr->dst));
1524 ast_copy_string(bridge_cdr->dcontext, chan->context, sizeof(bridge_cdr->dcontext));
1525 if (peer_cdr) {
1526 bridge_cdr->start = peer_cdr->start;
1527 ast_copy_string(bridge_cdr->userfield, peer_cdr->userfield, sizeof(bridge_cdr->userfield));
1528 } else {
1529 ast_cdr_start(bridge_cdr);
1530 }
1531 }
By: David Brillert (aragon) 2009-03-11 10:40:05

Re-tested this morning with fresh install of Asterisk 1.4.24rc1
This behavior is unacceptable
I still get the incorrect data written to /var/log/asterisk/queue_log when /etc/asterisk/queues.conf includes some context for an IVR menu
The purpose of the IVR context is to allow the caller to exit the queue with a keypress
The test procedure is simple
Include an IVR context in queues.conf
Caller dials queue using any technology
Agent answers caller
Agent or caller does hangup
Call is not transfer call and caller does not dial any DTMF
Data in queue_log is useless and incorrect in this scenario

1236785420|1236785411.7|default-sales|NONE|ENTERQUEUE||6010
1236785421|1236785411.7|default-sales|Local/6002@default-agent/n|CONNECT|1|1236785420.8
1236785447|1236785411.7|default-sales|Local/6002@default-agent/n|TRANSFER|s|all-hangup|1|26

Since the call center is billing on completed calls the bad queue_log data makes billing impossible.
By: David Brillert (aragon) 2009-03-12 10:40:45

So we put some additional debug lines into Asterisk 1.4.24rc1 to debug problem.
It execute the hangup ( exten => h, ...) so the context change and the 'logic' on queuelog is broken

   -- SIP/6002-0a402118 is ringing
   -- Local/6002@default-agent-b04a,1 is ringing
   -- SIP/6002-0a402118 answered Local/6002@default-agent-b04a,2
   -- Local/6002@default-agent-b04a,1 answered SIP/6010-0a3fb720
   -- Stopped music on hold on SIP/6010-0a3fb720
 == Spawn extension (default-local-devices, 6002, 2) exited non-zero on 'Local/6002@default-agent-b04a,2'
   -- Executing [h@default-application-acd-sales:1] Goto("SIP/6010-0a3fb720", "all-hangup|s|1") in new stack
   -- Goto (all-hangup,s,1)
   -- Executing [s@all-hangup:1] GotoIf("SIP/6010-0a3fb720", "0?all-faxnotify|s|1:2") in new stack
   -- Goto (all-hangup,s,2)
   -- Executing [s@all-hangup:2] ResetCDR("SIP/6010-0a3fb720", "w") in new stack
   -- Executing [s@all-hangup:3] NoCDR("SIP/6010-0a3fb720", "") in new stack
   -- Executing [s@all-hangup:4] System("SIP/6010-0a3fb720", "/var/www/scopserv/telephony/scripts/billing/cdr.sh 1236871879.4") in new stack
[Mar 12 11:31:33] WARNING[10685]: app_queue.c:3232 try_calling: Old Context: default-application-acd-sales   Chan Context: all-hangup
[Mar 12 11:31:33] WARNING[10685]: app_queue.c:3233 try_calling: Old Exten: s   Chan Exten: s
 == Spawn extension (all-hangup, s, 14) exited non-zero on 'SIP/6010-0a3fb720'
By: Joel Vandal (jvandal) 2009-03-12 11:06:18

Hi,

After some debugging, it look like that when the dialplan execute the hangup extension (that do a Goto on an other context), the qe->chan->context no more match the oldcontext and a TRANSFER event is logged on queue_log.

In our case, we always use 'all-hangup' as hangup context and a simple workaround/hack is to ignore the all-hangup context when doing the verification... absolutely not "beautiful" or "portable" (work only because we only use all-hangup context) but fix all problems and event are 100% correct on queue_log.

Change from :

if (strcasecmp(oldcontext, qe->chan->context) || strcasecmp(oldexten, qe->chan->exten)) {
       
To :

if (strcasecmp("all-hangup", qe->chan->context) && (strcasecmp(oldcontext, qe->chan->context) || strcasecmp(oldexten, qe->chan->exten))) {
By: David Brillert (aragon) 2009-03-12 15:19:12

Yes the hack works quite nicely.

I'll leave this bug report open and use the hack until problem is "officially fixed" with a committed patch.

Thanks go out to jvandal
By: Leif Madsen (lmadsen) 2009-06-10 12:20:05

Assigned to mnicholson as I think he is the most appropriate developer to look into this issue. Thanks!
By: Miguel Molina (coolmig) 2009-06-19 00:13:10

I experienced the same issue when I was testing a dialer which is now into production. After a lot of head crunching I finally got a workaround:

;This context is where the AMI calls are dialed
[dialer-gencall]
exten => _9NXXXXXX,1,NoCDR() ;Don't keep local channel CDRs
exten => _9NXXXXXX,n,Dial(${TRUNK_SALIDA_SIP}/8${EXTEN:1},${TIMEOUT},rto)
exten => _9NXXXXXX,n,Hangup()

;This context is where the outbound connected call is queued
[dialer]
exten => s,1,NoCDR() ;Don't keep local channel CDRs
exten => s,n,Answer()
exten => s,n,Noop(INITIAL UNIQUEID: ${CDR(uniqueid)})
exten => s,n,Wait(0.5) ;(WORKAROUND QUEUE_LOG BUG)
exten => s,n,Noop(FINAL UNIQUEID: ${CDR(uniqueid)})
exten => s,n,Queue(test,h)
exten => s,n,Hangup()

The Wait() workaround makes asterisk "finish" the masquerading process that occurs with the Local channel generated call, when the SIP channel that is dialed is answered and connected to the dialer context (proof of this behavior are the different uniqueid's shown before and after the Wait). This way, for logging purposes, Queue() sees the masqueraded SIP channel info instead of the original Local channel. IMHO, when the Wait() is not there, the masquerading process occurs inside the Queue() application that makes asterisk see a context change or whatever that makes log the call that way. All the calls logged as TRANSFER event with zero duration rendered the information useless.

Your case may be similar, so you can give the workaround a try while the developers look deeper into this. The workaround has been working month and a half and counting.
By: David Brillert (aragon) 2009-06-19 14:09:00

thanks coolmig but the workaround from jvandal has been in production since 2009-03-12 and working nicely.

I'm sure mmicholson will have some patch soon for the rest of the community. He rocks :)
By: Miguel Molina (coolmig) 2009-06-19 14:20:24

That's what I thought some while after posting, but I'm pretty sure the scenario I refer will give clues to mmicholson on why this is happening in both cases.
By: Miguel Molina (coolmig) 2009-06-26 14:56:35

Just curious, are you using realtime queues and queue members or plain static ones?
By: David Brillert (aragon) 2009-06-26 15:07:33

AddQueueMember(${QUEUE}|Local/${PHONE_EXTEN}@${PHONE_CONTEXT}/n|${AGENT_PENALTY}|||${PHONE_CHAN})
By: Matthew Nicholson (mnicholson) 2009-07-10 15:17:30

I cannot reproduce this issue with svn branch 1.4 revision 205877.  I need concise instructions on how to reproduce this.

I looked at the code around that context change check.  I suppose it is possible for the context to change because of a masquerade caused by a local channel.  I will need to look at it some more and reproduce it to understand it enough to fix it though.
By: David Brillert (aragon) 2009-07-12 17:28:36

Mark
To reproduce it is easy enough to set "context" commzilla-aa-mainivr"
Where that context is equal to an IVR menu.
The purpose of that menu is to allow a caller to enter DTMF during wait time to transfer out of queue.

queues.conf
[commzilla-family]
music                          =  default
strategy                       =  rrmemory
servicelevel                   =  45
context                        =  commzilla-aa-mainivr
timeout                        =  20
retry                          =  5
maxlen                         =  0
weight                         =  0
reportholdtime                 =  no
reportwaitcall                 =  no
memberdelay                    =  0
timeoutrestart                 =  no
autofill                       =  yes
autopause                      =  no
ringinuse                      =  no
setinterfacevar                =  yes
wrapuptime                     =  0
joinempty                      =  yes
leavewhenempty                 =  no
eventwhencalled                =  vars
eventmemberstatus              =  yes
periodic-announce-frequency    =  20
periodic-announce              =  custom/0002
monitor-format                 =  wav49
monitor-type                   =  MixMonitor
queue-youarenext               =  queue-youarenext
queue-thereare                 =  queue-thereare
queue-callswaiting             =  queue-callswaiting
queue-holdtime                 =  queue-holdtime
queue-minutes                  =  queue-minutes
queue-seconds                  =  queue-seconds
queue-thankyou                 =  queue-thankyou
queue-lessthan                 =  queue-less-than

extensions-ivr.conf
[commzilla-aa-mainivr]
include         => commzilla-local
exten           => s,1,Answer
exten           => s,2,AGI(/var/www/scopserv/telephony/scripts/agi/ivr.php,3438)
exten           => s,3,Wait(1)
exten           => s,4,Set(__IVRNAME=commzilla-aa-mainivr)
exten           => s,5,Set(TIMEOUT(digit)=3)
exten           => s,6,Set(TIMEOUT(response)=5)
exten           => s,7,Set(CHANNEL(language)=en)
exten           => s,8,Background(custom/0013)
exten           => s,9,NoOp()
exten           => 0,1,AGI(/var/www/scopserv/telephony/scripts/agi/ivr.php,3438,0)
exten           => 0,2,Set(__CALLDIVERT=YES)
exten           => 0,3,Dial(Local/200@commzilla-local/n,,o)
exten           => 0,4,Hangup
exten           => #,1,AGI(/var/www/scopserv/telephony/scripts/agi/ivr.php,3438,pound)
exten           => #,2,Directory(commzilla|commzilla-local-directory|)
exten           => t,1,AGI(/var/www/scopserv/telephony/scripts/agi/ivr.php,3438,none)
exten           => t,2,Set(__CALLDIVERT=YES)
exten           => t,3,Dial(Local/200@commzilla-local/n,,o)
exten           => t,4,Hangup
exten           => i,1,AGI(/var/www/scopserv/telephony/scripts/agi/ivr.php,3438,invalid)
exten           => i,2,Set(__CALLDIVERT=YES)
exten           => i,3,Dial(Local/200@commzilla-local/n,,o)
exten           => i,4,Hangup
exten           => h,1,Goto(all-hangup,s,1)

If I remove the context then the transfer event won't be logged and all works correctly.

queues.conf
[commzilla-family]
music                          =  default
strategy                       =  rrmemory
servicelevel                   =  45
# context                        =  commzilla-aa-mainivr
timeout                        =  20
retry                          =  5
maxlen                         =  0
weight                         =  0
reportholdtime                 =  no
reportwaitcall                 =  no
memberdelay                    =  0
timeoutrestart                 =  no
autofill                       =  yes
autopause                      =  no
ringinuse                      =  no
setinterfacevar                =  yes
wrapuptime                     =  0
joinempty                      =  yes
leavewhenempty                 =  no
eventwhencalled                =  vars
eventmemberstatus              =  yes
periodic-announce-frequency    =  20
periodic-announce              =  custom/0002
monitor-format                 =  wav49
monitor-type                   =  MixMonitor
queue-youarenext               =  queue-youarenext
queue-thereare                 =  queue-thereare
queue-callswaiting             =  queue-callswaiting
queue-holdtime                 =  queue-holdtime
queue-minutes                  =  queue-minutes
queue-seconds                  =  queue-seconds
queue-thankyou                 =  queue-thankyou
queue-lessthan                 =  queue-less-than

jvandal's hack works perfectly to avoid the bad queuelog data (transfer events).
By: Matthew Nicholson (mnicholson) 2009-07-14 13:54:36

I cannot reproduce this bug with this configuration.  Can someone provide a minimal test case to reproduce this bug on the SVN version of branch 1.4?
By: David Brillert (aragon) 2009-07-14 13:59:17

I'll try next week.
My lab is pretty busy waiting for a crash under Valgrind to debug issue 15109
I can't recompile Asterisk right now since I have been waiting for a crash in valgrind since the 8th and I am still waiting.  Also bug ID 15396 is a much higher priority for me right now.
By: David Brillert (aragon) 2009-07-17 13:35:40

I have re-tested with r206273

I still get unwanted transfer event in /var/log/asterisk/queue_log

1247854958|1247854948.0|commzilla-family|NONE|ENTERQUEUE||5555551234
1247854959|1247854948.0|commzilla-family|Local/230@commzilla-agent/n|CONNECT|1|1247854958.1
1247854963|1247854948.0|commzilla-family|Local/230@commzilla-agent/n|TRANSFER|s|all-hangup|1|4

Must not show TRANSFER on queuelog
So I must continue to use jvandal's hack

Here is the required queue_log output with jvandal's hack

1247855646|NONE|NONE|NONE|QUEUESTART|
1247855661|1247855651.0|commzilla-family|NONE|ENTERQUEUE||5555551234
1247855662|1247855651.0|commzilla-family|Local/230@commzilla-agent/n|CONNECT|1|1247855661.1
1247855665|1247855651.0|commzilla-family|Local/230@commzilla-agent/n|COMPLETEAGENT|1|3|1
By: Matthew Nicholson (mnicholson) 2009-07-20 12:05:47

I still need better instructions for reproducing this.
By: David Brillert (aragon) 2009-07-24 11:34:53

What else do you require exactly?
I have attached cli traces from success and failure and dialplan info to reproduce the problem as well as queue_log data.
What else have I missed? Can you be specific?
jvandal has captured the issue in his note...
It looks like the dialplan executes the hangup extension (that does a Goto on an other context), the qe->chan->context no longer matches the oldcontext and a TRANSFER event is logged on queue_log.
In my dial plan the "an other" context is included in queues.conf "context = commzilla-aa-mainivr".  The caller does not dial the mainivr context while in queue but queue_log receives a transfer event anyway.  Commenting out "context = commzilla-aa-mainivr" in queues.conf no longer sends the unwanted transfer event to /var/log/asterisk/queue_log but I need this option so callers can remove themselves from queue and leave a message in a mailbox or transfer to another extension.

Sorry that is the best explanation I can come up with.  Perhaps jvandal can assist further...


By: Matthew Nicholson (mnicholson) 2009-07-28 11:24:48

I have tested multiple variations of 'context=' in queues.conf without encountering this bug.  I will test using a Goto from the 'h' exten.  Basically I am looking for a minimal set of configs (queues.conf, extensions.conf) along with instructions on *exactly* what I need to do to reproduce the bug.

I have tried the queues.conf files posted here and I have tried exiting the queue by pressing a digit.  The queue log has been correct in all of these cases.
By: David Brillert (aragon) 2009-07-28 12:23:19

OK, Just an FYI it is not necessary to press a digit to exit the queue in order to log the transfer event to the queue_log.  The only requirement is the goto step and the inclusion of the ivr context in queues.conf
By: Matthew Nicholson (mnicholson) 2009-07-29 08:39:25

I have been able to reproduce this using a goto in the 'h' exten.  I am working on a fix using the information provided.
By: Matthew Nicholson (mnicholson) 2009-07-29 14:19:35

Please test the patch I just uploaded (queue-log-xfer-fix1.diff).  I should fix the incorrect TRANSFER records.  Also make sure it does not break anything anc cause cases where there should be a TRANSFER record, but there is not.
By: Joel Vandal (jvandal) 2009-07-29 14:37:57

aragon, I will check to provide you an update RPM friday or saturday since I must leave tomorrow for Saudi Arabia.
By: David Brillert (aragon) 2009-07-30 15:17:46

I'll be on vacation for a week but will try to test patch this before I get back.
By: David Brillert (aragon) 2009-08-10 23:57:31

jvandal, I'm back from vacation. Are you able to provide a test rpm to test mnicholson's patch?
By: Joel Vandal (jvandal) 2009-08-11 03:03:35

aragon, not before next week, I'm in Israel (Tel Aviv) for all week.

But ... I highly think it will be a good idea to install SVN on your server and you will be able to manually update/recompile without wait for me to rebuild an RPM package ;) I can also check with you when I'm back in Canada.
By: David Brillert (aragon) 2009-08-12 14:16:30

mnicholson

The .diff works and the queue_log looks normal :D

1250104331|1250104324.7|NONE|Agent/1|AGENTCALLBACKLOGIN|Local/227@default-agent/n
1250104331|1250104324.7|default-family|Local/227@commzilla-agent/n|ADDMEMBER|
1250104342|1250104337.8|default-family|NONE|ENTERQUEUE||99057126386
1250104344|1250104337.8|default-family|Local/227@commzilla-agent/n|CONNECT|2|1250104342.9
1250104346|1250104337.8|default-family|Local/227@commzilla-agent/n|COMPLETEAGENT|2|2|1
By: Digium Subversion (svnbot) 2009-08-12 18:04:28

Repository: asterisk
Revision: 211953

U   branches/1.4/apps/app_queue.c

------------------------------------------------------------------------
r211953 | mnicholson | 2009-08-12 18:04:27 -0500 (Wed, 12 Aug 2009) | 10 lines

This patch adds additional checking when generating queue log TRANSFER events.

The additional checks prevent generation of false TRANSFER events in certain situations.

(closes issue ASTERISK-13635)
Reported by: aragon
Patches:
     queue-log-xfer-fix1.diff uploaded by mnicholson (license 96)
Tested by: aragon, mnicholson

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=211953
By: Digium Subversion (svnbot) 2009-08-12 18:15:00

Repository: asterisk
Revision: 211957

_U  trunk/
U   trunk/apps/app_queue.c

------------------------------------------------------------------------
r211957 | mnicholson | 2009-08-12 18:15:00 -0500 (Wed, 12 Aug 2009) | 17 lines

Merged revisions 211953 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
 r211953 | mnicholson | 2009-08-12 18:04:02 -0500 (Wed, 12 Aug 2009) | 10 lines
 
 This patch adds additional checking when generating queue log TRANSFER events.
 
 The additional checks prevent generation of false TRANSFER events in certain situations.
 
 (closes issue ASTERISK-13635)
 Reported by: aragon
 Patches:
       queue-log-xfer-fix1.diff uploaded by mnicholson (license 96)
 Tested by: aragon, mnicholson
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=211957
By: Digium Subversion (svnbot) 2009-08-12 18:16:44

Repository: asterisk
Revision: 211958

_U  branches/1.6.1/
U   branches/1.6.1/apps/app_queue.c

------------------------------------------------------------------------
r211958 | mnicholson | 2009-08-12 18:16:44 -0500 (Wed, 12 Aug 2009) | 24 lines

Merged revisions 211957 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r211957 | mnicholson | 2009-08-12 18:14:36 -0500 (Wed, 12 Aug 2009) | 17 lines
 
 Merged revisions 211953 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r211953 | mnicholson | 2009-08-12 18:04:02 -0500 (Wed, 12 Aug 2009) | 10 lines
   
   This patch adds additional checking when generating queue log TRANSFER events.
   
   The additional checks prevent generation of false TRANSFER events in certain situations.
   
   (closes issue ASTERISK-13635)
   Reported by: aragon
   Patches:
         queue-log-xfer-fix1.diff uploaded by mnicholson (license 96)
   Tested by: aragon, mnicholson
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=211958
By: Digium Subversion (svnbot) 2009-08-12 18:17:17

Repository: asterisk
Revision: 211959

_U  branches/1.6.2/
U   branches/1.6.2/apps/app_queue.c

------------------------------------------------------------------------
r211959 | mnicholson | 2009-08-12 18:17:17 -0500 (Wed, 12 Aug 2009) | 24 lines

Merged revisions 211957 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r211957 | mnicholson | 2009-08-12 18:14:36 -0500 (Wed, 12 Aug 2009) | 17 lines
 
 Merged revisions 211953 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r211953 | mnicholson | 2009-08-12 18:04:02 -0500 (Wed, 12 Aug 2009) | 10 lines
   
   This patch adds additional checking when generating queue log TRANSFER events.
   
   The additional checks prevent generation of false TRANSFER events in certain situations.
   
   (closes issue ASTERISK-13635)
   Reported by: aragon
   Patches:
         queue-log-xfer-fix1.diff uploaded by mnicholson (license 96)
   Tested by: aragon, mnicholson
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=211959
By: Digium Subversion (svnbot) 2009-08-12 18:17:36

Repository: asterisk
Revision: 211960

_U  branches/1.6.0/
U   branches/1.6.0/apps/app_queue.c

------------------------------------------------------------------------
r211960 | mnicholson | 2009-08-12 18:17:36 -0500 (Wed, 12 Aug 2009) | 24 lines

Merged revisions 211957 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r211957 | mnicholson | 2009-08-12 18:14:36 -0500 (Wed, 12 Aug 2009) | 17 lines
 
 Merged revisions 211953 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r211953 | mnicholson | 2009-08-12 18:04:02 -0500 (Wed, 12 Aug 2009) | 10 lines
   
   This patch adds additional checking when generating queue log TRANSFER events.
   
   The additional checks prevent generation of false TRANSFER events in certain situations.
   
   (closes issue ASTERISK-13635)
   Reported by: aragon
   Patches:
         queue-log-xfer-fix1.diff uploaded by mnicholson (license 96)
   Tested by: aragon, mnicholson
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=211960