[Home]

Summary:ASTERISK-28952: Queue wrapuptime sometimes not respected (based on stale lastcall time)
Reporter:Walter Doekes (wdoekes)Labels:
Date Opened:2020-06-15 06:20:58Date Closed:2020-06-17 09:16:22
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Applications/app_queue
Versions:13.34.0 Frequency of
Occurrence		Constant
Related
Issues:
Environment:Attachments:
Description:Possibly related to ASTERISK-22589, we've also been seeing issues with wrapuptime not being respected.

In our case -- we're also using realtime -- the issue appears to be the following:

- try_calling() creates a list of potential members (Agents)
- it copies the current state from the members to the callattempt linked list
- ring_one() is fed the list
- if the strategy is _not_ ringall, the members are tried sequentially
- ring_entry() dials a member
- member does not pick up
- ring_entry() dials another member
- before dialing, can_ring_entry() checks whether member->lastcall is more recent than wrapuptime seconds ago
- if wrapuptime has not been reached, it skips this member and moves onto the next

In our case, the callattempt-list is populated with both in-use and not-in-use members. This is no problem, as can_ring_entry() checks both the inuse state and the wrapuptime.

However: if the callattempt-list was created _before_ the inuse member ends the call, but the attempt is first made _after_ the hangup, can_ring_entry() checks _old_ data:

- call1: MemberX has call (is inuse)
- call2: NewCaller calls into queue, callattempt is made with currently available lastcall times
- call2: MemberY is tried
- call1: MemberX ends call, stores "lastcall" time in member (but not in callattempt)
- call2: MemberX is tried (checks stale "lastcall" time from callattempt)

That last one _should be_:

- call2: MemberX is skipped, after checking "lastcall" on member struct

h3. History

struct callattempt has always had copies of the lastcall/lastqueue:
{noformat}
commit b140eef0aa186020868aaf4ab663ce2aa38e73c2
Author: Mark Spencer <markster@digium.com>
Date:   Sat Jun 26 16:26:39 2004 +0000

   Implement queue wide wrapuptime (bug #1707)
...
@@ -1019,6 +1028,7 @@ static int try_calling(struct queue_ent *qe, char *options, char *announceoverri
               tmp->member = cur;              /* Never directly dereference!  Could change on reload */
               strncpy(tmp->tech, cur->tech, sizeof(tmp->tech)-1);
               strncpy(tmp->numsubst, cur->loc, sizeof(tmp->numsubst)-1);
+               tmp->lastcall = cur->lastcall;
               /* If we're dialing by extension, look at the extension to know what to dial */
               if ((newnum = strstr(tmp->numsubst, "BYEXTENSION"))) {
                       strncpy(restofit, newnum + strlen("BYEXTENSION"), sizeof(restofit)-1);
{noformat}
We were not allowed to touch the member directly.

This was changed:
{noformat}
commit e5582607460aa9fe8312bdf5b184160b92d90f7b
Author: Tilghman Lesher <tilghman@meg.abyt.es>
Date:   Mon Sep 10 18:32:59 2007 +0000

   Merged revisions 82155 via svnmerge from
   https://origsvn.digium.com/svn/asterisk/branches/1.4
   
   ........
   r82155 | tilghman | 2007-09-10 13:02:02 -0500 (Mon, 10 Sep 2007) | 2 lines
   
   Convert struct member to use refcounts (closes issue #10199)
...
@@ -2601,7 +2620,7 @@ static int try_calling(struct queue_ent *qe, const char *options, char *announce
                       goto out;
               }
               tmp->stillgoing = -1;
-               tmp->member = cur;              /* Never directly dereference!  Could change on reload */
+               tmp->member = cur;
               tmp->oldstatus = cur->status;
               tmp->lastcall = cur->lastcall;
               ast_copy_string(tmp->interface, cur->interface, sizeof(tmp->interface));
{noformat}
And within 4 days that feature was already used:
{noformat}
commit 38460271f20c45350e428b5d3a7cc07989df1b54
Author: Mark Michelson <mmichelson@digium.com>
Date:   Fri Sep 14 18:34:53 2007 +0000

   Merged revisions 82396 via svnmerge from
   https://origsvn.digium.com/svn/asterisk/branches/1.4
   
   ........
   r82396 | mmichelson | 2007-09-14 13:28:36 -0500 (Fri, 14 Sep 2007) | 5 lines
   
   Adding member name field to manager events where they were missing before
   
   (closes issue #10721, reported by snar)
...
@@ -1901,7 +1902,7 @@ static int ring_entry(struct queue_ent *qe, struct callattempt *tmp, int *busies
                                       "Extension: %s\r\n"
                                       "Priority: %d\r\n"
                                       "%s",
-                                       qe->parent->name, tmp->interface, qe->chan->name, tmp->chan->name,
+                                       qe->parent->name, tmp->interface, tmp->member->membername, qe->chan->name, tmp->chan->name,
                                       tmp->chan->cid.cid_num ? tmp->chan->cid.cid_num : "unknown",
                                       tmp->chan->cid.cid_name ? tmp->chan->cid.cid_name : "unknown",
                                       qe->chan->context, qe->chan->exten, qe->chan->priority,
{noformat}
However, the original use of the copied field remained:
{code}
               struct callattempt *tmp;
               struct member *cur;
...
               tmp->lastcall = cur->lastcall;
{code}
As far as I can tell, there is no reason to not query the member directly, and drop the obsolete (and sometimes stale) copies.

h3. Fix

Which would look somewhat like this:
{noformat}
diff --git a/apps/app_queue.c b/apps/app_queue.c
index 3a572efc2d..5d2721bdfc 100644
--- a/apps/app_queue.c
+++ b/apps/app_queue.c
@@ -1443,8 +1443,6 @@ struct callattempt {
struct ast_channel *chan;
char interface[256]; /*!< An Asterisk dial string (not a channel name) */
int metric;
- time_t lastcall;
- struct call_queue *lastqueue;
struct member *member;
/*! Saved connected party info from an AST_CONTROL_CONNECTED_LINE. */
struct ast_party_connected_line connected;
@@ -4236,36 +4234,38 @@ static int member_status_available(int status)
 */
static int can_ring_entry(struct queue_ent *qe, struct callattempt *call)
{
- if (call->member->paused) {
+ struct member *memberp = call->member;
+
+ if (memberp->paused) {
ast_debug(1, "%s paused, can't receive call\n", call->interface);
return 0;
}

- if (!call->member->ringinuse && !member_status_available(call->member->status)) {
+ if (!memberp->ringinuse && !member_status_available(memberp->status)) {
ast_debug(1, "%s not available, can't receive call\n", call->interface);
return 0;
}

- if ((call->lastqueue && call->lastqueue->wrapuptime && (time(NULL) - call->lastcall < call->lastqueue->wrapuptime))
- || (!call->lastqueue && qe->parent->wrapuptime && (time(NULL) - call->lastcall < qe->parent->wrapuptime))) {
+ if ((memberp->lastqueue && memberp->lastqueue->wrapuptime && (time(NULL) - memberp->lastcall < memberp->lastqueue->wrapuptime))
+ || (!memberp->lastqueue && qe->parent->wrapuptime && (time(NULL) - memberp->lastcall < qe->parent->wrapuptime))) {
ast_debug(1, "Wrapuptime not yet expired on queue %s for %s\n",
- (call->lastqueue ? call->lastqueue->name : qe->parent->name),
+ (memberp->lastqueue ? memberp->lastqueue->name : qe->parent->name),
call->interface);
return 0;
}

- if (use_weight && compare_weight(qe->parent, call->member)) {
+ if (use_weight && compare_weight(qe->parent, memberp)) {
ast_debug(1, "Priority queue delaying call to %s:%s\n",
qe->parent->name, call->interface);
return 0;
}

- if (!call->member->ringinuse) {
+ if (!memberp->ringinuse) {
struct member *mem;

ao2_lock(pending_members);

- mem = ao2_find(pending_members, call->member,
+ mem = ao2_find(pending_members, memberp,
 OBJ_SEARCH_OBJECT | OBJ_NOLOCK);
if (mem) {
/*
@@ -4283,8 +4283,8 @@ static int can_ring_entry(struct queue_ent *qe, struct callattempt *call)
* If not found add it to the container so another queue
* won't attempt to call this member at the same time.
*/
- ast_debug(3, "Add %s to pending_members\n", call->member->membername);
- ao2_link(pending_members, call->member);
+ ast_debug(3, "Add %s to pending_members\n", memberp->membername);
+ ao2_link(pending_members, memberp);
ao2_unlock(pending_members);

/*
@@ -4292,10 +4292,10 @@ static int can_ring_entry(struct queue_ent *qe, struct callattempt *call)
* because the device state and extension state callbacks may
* not have updated the status yet.
*/
- if (!member_status_available(get_queue_member_status(call->member))) {
+ if (!member_status_available(get_queue_member_status(memberp))) {
ast_debug(1, "%s actually not available, can't receive call\n",
call->interface);
- pending_members_remove(call->member);
+ pending_members_remove(memberp);
return 0;
}
}
@@ -6638,9 +6638,7 @@ static int try_calling(struct queue_ent *qe, struct ast_flags opts, char **opt_a

tmp->block_connected_update = block_connected_line;
tmp->stillgoing = 1;
- tmp->member = cur;/* Place the reference for cur into callattempt. */
- tmp->lastcall = cur->lastcall;
- tmp->lastqueue = cur->lastqueue;
+ tmp->member = cur; /* Place the reference for cur into callattempt. */
ast_copy_string(tmp->interface, cur->interface, sizeof(tmp->interface));
/* Calculate the metric for the appropriate strategy. */
if (!calc_metric(qe->parent, cur, x++, qe, tmp)) {
{noformat}
Comments:By: Asterisk Team (asteriskteam) 2020-06-15 06:20:59.832-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.
By: Friendly Automation (friendly-automation) 2020-06-17 09:16:25.610-0500

Change 14562 merged by Friendly Automation:
app_queue: Read latest wrapuptime instead of (possibly stale) copy

[https://gerrit.asterisk.org/c/asterisk/+/14562|https://gerrit.asterisk.org/c/asterisk/+/14562]
By: Friendly Automation (friendly-automation) 2020-06-17 09:25:19.021-0500

Change 14582 merged by Friendly Automation:
app_queue: Read latest wrapuptime instead of (possibly stale) copy

[https://gerrit.asterisk.org/c/asterisk/+/14582|https://gerrit.asterisk.org/c/asterisk/+/14582]
By: Friendly Automation (friendly-automation) 2020-06-17 09:25:52.897-0500

Change 14583 merged by Friendly Automation:
app_queue: Read latest wrapuptime instead of (possibly stale) copy

[https://gerrit.asterisk.org/c/asterisk/+/14583|https://gerrit.asterisk.org/c/asterisk/+/14583]
By: Friendly Automation (friendly-automation) 2020-06-17 09:36:20.711-0500

Change 14565 merged by George Joseph:
app_queue: Read latest wrapuptime instead of (possibly stale) copy

[https://gerrit.asterisk.org/c/asterisk/+/14565|https://gerrit.asterisk.org/c/asterisk/+/14565]