[Home]

Summary:ASTERISK-29427: Queue in round robin is not ringing agents for the correct amount of time
Reporter:Leandro Dardini (ldardini)Labels:
Date Opened:2021-05-12 17:47:29Date Closed:2021-05-17 07:36:42
Priority:MinorRegression?
Status:Closed/CompleteComponents:Applications/app_queue
Versions:16.17.0 Frequency of
Occurrence		Frequent
Related
Issues:
Environment:CentOS 6 64bitAttachments:
Description:I have a queue realtime in round robin configuration, trying to ring a large number of agents. After few days of usage, the queue is starting to report wrong times for the ring time of agents, terminating to ring an agent before the configured timeout.

Here is an example of the result of the calls and timeout.
{noformat}
# grep C-000057d7 /var/log/asterisk/full.0 | grep app_queue.c
[2021-05-12 16:30:44] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-002-NFR-128708@fromotherpbx/n
[2021-05-12 16:31:05] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-002-NFR-128708@fromotherpbx-00004c01;1 is busy
[2021-05-12 16:31:05] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 21000 ms
[2021-05-12 16:31:05] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-006-NFR-128710@fromotherpbx/n
[2021-05-12 16:31:06] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-006-NFR-128710@fromotherpbx-00004c02;1 is busy
[2021-05-12 16:31:06] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 1000 ms
[2021-05-12 16:31:06] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-000-NFR-129142@fromotherpbx/n
[2021-05-12 16:31:07] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-000-NFR-129142@fromotherpbx-00004c03;1 is ringing
[2021-05-12 16:31:09] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 25000 ms
{noformat}

_In this last attempt, the queue cancelled the call to the agent thinking 25 seconds are passed, but only 3 seconds are passed_

{noformat}
[2021-05-12 16:31:10] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-000-NFR-129142@fromotherpbx/n
[2021-05-12 16:31:12] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-000-NFR-129142@fromotherpbx-00004c04;1 is ringing
[2021-05-12 16:31:35] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 25000 ms
[2021-05-12 16:31:36] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-002-NFR-128708@fromotherpbx/n
[2021-05-12 16:31:57] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-002-NFR-128708@fromotherpbx-00004c05;1 is busy
[2021-05-12 16:31:57] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 21000 ms
[2021-05-12 16:31:57] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-006-NFR-128710@fromotherpbx/n
[2021-05-12 16:32:01] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 25000 ms
{noformat}

_Again, after an agent refused a call, it seems the timer is not reset correctly and only the remaining time is used for the next agent_

{noformat}
[2021-05-12 16:32:02] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-000-NFR-129142@fromotherpbx/n
[2021-05-12 16:32:03] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-000-NFR-129142@fromotherpbx-00004c07;1 is ringing
[2021-05-12 16:32:27] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 25000 ms
[2021-05-12 16:32:28] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-002-NFR-128708@fromotherpbx/n
[2021-05-12 16:32:48] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-002-NFR-128708@fromotherpbx-00004c08;1 is busy
[2021-05-12 16:32:48] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 20000 ms
[2021-05-12 16:32:48] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-006-NFR-128710@fromotherpbx/n
[2021-05-12 16:32:53] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 25000 ms
{noformat}

_Yes, it seems exactly the time not spent by the previous agent is used for the next agent, without resetting the agent timeout_

{noformat}
[2021-05-12 16:32:54] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-000-NFR-129142@fromotherpbx/n
[2021-05-12 16:32:54] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-000-NFR-129142@fromotherpbx-00004c11;1 is ringing
[2021-05-12 16:33:19] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 25000 ms
[2021-05-12 16:33:20] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-002-NFR-128708@fromotherpbx/n
[2021-05-12 16:33:41] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-002-NFR-128708@fromotherpbx-00004c19;1 is busy
[2021-05-12 16:33:41] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 21000 ms
[2021-05-12 16:33:41] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-006-NFR-128710@fromotherpbx/n
[2021-05-12 16:33:45] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 25000 ms
{noformat}

_Another time, same issue_

{noformat}
[2021-05-12 16:33:46] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-000-NFR-129142@fromotherpbx/n
[2021-05-12 16:33:47] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-000-NFR-129142@fromotherpbx-00004c1b;1 is ringing
[2021-05-12 16:34:11] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 25000 ms
[2021-05-12 16:34:12] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-002-NFR-128708@fromotherpbx/n
[2021-05-12 16:34:33] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-002-NFR-128708@fromotherpbx-00004c1c;1 is busy
[2021-05-12 16:34:33] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 21000 ms
[2021-05-12 16:34:33] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-006-NFR-128710@fromotherpbx/n
[2021-05-12 16:34:37] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-006-NFR-128710@fromotherpbx-00004c1d;1 is ringing
[2021-05-12 16:34:37] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 25000 ms
[2021-05-12 16:34:38] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-000-NFR-129142@fromotherpbx/n
[2021-05-12 16:34:39] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-000-NFR-129142@fromotherpbx-00004c1e;1 is ringing
[2021-05-12 16:35:03] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 25000 ms
[2021-05-12 16:35:04] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-002-NFR-128708@fromotherpbx/n
[2021-05-12 16:35:24] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-002-NFR-128708@fromotherpbx-00004c1f;1 is busy
[2021-05-12 16:35:24] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 20000 ms
[2021-05-12 16:35:24] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-006-NFR-128710@fromotherpbx/n
[2021-05-12 16:35:29] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-006-NFR-128710@fromotherpbx-00004c20;1 is ringing
[2021-05-12 16:35:29] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 25000 ms
[2021-05-12 16:35:30] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-000-NFR-129142@fromotherpbx/n
[2021-05-12 16:35:31] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-000-NFR-129142@fromotherpbx-00004c21;1 is ringing
[2021-05-12 16:35:55] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 25000 ms
[2021-05-12 16:35:56] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-002-NFR-128708@fromotherpbx/n
[2021-05-12 16:36:17] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-002-NFR-128708@fromotherpbx-00004c27;1 is busy
[2021-05-12 16:36:17] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 21000 ms
[2021-05-12 16:36:17] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-006-NFR-128710@fromotherpbx/n
[2021-05-12 16:36:21] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-006-NFR-128710@fromotherpbx-00004c28;1 is ringing
[2021-05-12 16:36:21] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 25000 ms
[2021-05-12 16:36:22] VERBOSE[28439][C-000057d7] app_queue.c: Called Local/AG-000-NFR-129142@fromotherpbx/n
[2021-05-12 16:36:23] VERBOSE[28439][C-000057d7] app_queue.c: Local/AG-000-NFR-129142@fromotherpbx-00004c29;1 is ringing
[2021-05-12 16:36:44] VERBOSE[28439][C-000057d7] app_queue.c: Nobody picked up in 22000 ms
{noformat}

Comments:By: Asterisk Team (asteriskteam) 2021-05-12 17:47:30.766-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. Please note that log messages and other files should not be sent to the Sangoma Asterisk Team unless explicitly asked for. All files should be placed on this issue in a sanitized fashion as needed.

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.

Please note that by submitting data, code, or documentation to Sangoma through JIRA, you accept the Terms of Use present at [https://www.asterisk.org/terms-of-use/|https://www.asterisk.org/terms-of-use/].
By: Joshua C. Colp (jcolp) 2021-05-12 18:26:01.637-0500

Are you able to reproduce this without using realtime?
By: Leandro Dardini (ldardini) 2021-05-14 09:13:50.599-0500

Yes. I was able to reproduce the exact weird timeout also with a minimalistic queue configuration:

{quote}
[test]
strategy=rrmemory
member => Local/AG-000-NF-28931@fromotherpbx
member => Local/AG-000-NF-1701@fromotherpbx
{quote}

{quote}
[2021-05-14 15:47:11] VERBOSE[21688][C-00025d92] app_queue.c: Called Local/AG-000-NF-1701@fromotherpbx
[2021-05-14 15:47:11] VERBOSE[21688][C-00025d92] app_queue.c: Local/AG-000-NF-1701@fromotherpbx-00000040;1 is ringing
[2021-05-14 15:47:18] VERBOSE[21688][C-00025d92] app_queue.c: Local/AG-000-NF-1701@fromotherpbx-00000040;1 is busy
[2021-05-14 15:47:18] VERBOSE[21688][C-00025d92] app_queue.c: Nobody picked up in 7000 ms
[2021-05-14 15:47:18] VERBOSE[21688][C-00025d92] app_queue.c: Called Local/AG-000-NF-28931@fromotherpbx
[2021-05-14 15:47:19] VERBOSE[21688][C-00025d92] app_queue.c: Local/AG-000-NF-28931@fromotherpbx-00000041;1 is ringing
[2021-05-14 15:47:26] VERBOSE[21688][C-00025d92] app_queue.c: Nobody picked up in 15000 ms
[2021-05-14 15:47:31] VERBOSE[21688][C-00025d92] app_queue.c: Called Local/AG-000-NF-1701@fromotherpbx
[2021-05-14 15:47:32] VERBOSE[21688][C-00025d92] app_queue.c: Local/AG-000-NF-1701@fromotherpbx-00000042;1 is ringing
[2021-05-14 15:47:40] VERBOSE[21688][C-00025d92] app_queue.c: Local/AG-000-NF-1701@fromotherpbx-00000042;1 is busy
[2021-05-14 15:47:40] VERBOSE[21688][C-00025d92] app_queue.c: Nobody picked up in 9000 ms
[2021-05-14 15:47:40] VERBOSE[21688][C-00025d92] app_queue.c: Called Local/AG-000-NF-28931@fromotherpbx
[2021-05-14 15:47:41] VERBOSE[21688][C-00025d92] app_queue.c: Local/AG-000-NF-28931@fromotherpbx-00000043;1 is ringing
[2021-05-14 15:47:46] VERBOSE[21688][C-00025d92] app_queue.c: Nobody picked up in 15000 ms
{quote}

The problem seems to be connected with the "timeoutrestart" option. If I set the option to "yes", then this problem doesn't happen, neither in realtime nor static.

By: Benjamin Keith Ford (bford) 2021-05-14 09:46:16.222-0500

I think the behavior here is correct according to the docs in queues.conf:
{code}
; If timeoutrestart is set to yes, then the timeout for an agent to answer is
; reset if a BUSY or CONGESTION is received.  This can be useful if agents
; are able to cancel a call with reject or similar.
{code}
However, the log message printed out is misleading once it reaches that final amount of time, reporting the overall duration and not the duration that it ringed the last time.
By: Leandro Dardini (ldardini) 2021-05-14 12:35:17.879-0500

The message is for sure misleading, but the behaviour is not correct. If agent A lets the phone ring for 5 seconds and then press the "reject" key, why ring agent B less than the amount of time configured?
By: George Joseph (gjoseph) 2021-05-14 13:02:30.127-0500

How are you setting the timeout?  In queues.conf, via the Queue() application or both?
What is timeoutpriority set to?

Depending on how your options are set, the timeout may be from the caller's perspective, not the agents.
See the QUEUE TIMING OPTION section of the queues.conf.sample file.
If you get the behavior you want with timeoutrestart set to yes then that's the answer.


By: Leandro Dardini (ldardini) 2021-05-16 10:06:36.605-0500

Good, that is good for me. I will use the timeoutrestart to get the behavior I need.