[Home]

Summary:ASTERISK-22189: Wrap up time is ignored for queue members who are members in multiple queues
Reporter:Matt Jordan (mjordan)Labels:
Date Opened:2013-07-24 09:45:47Date Closed:2013-08-19 19:12:01
Priority:MajorRegression?Yes
Status:Closed/CompleteComponents:Applications/app_queue
Versions:1.8.23.0 11.3.0 11.4.0 11.5.0 Frequency of
Occurrence
Related
Issues:
is a clone ofASTERISK-24310 CLONE - Wrap up time is ignored for queue members who are members in multiple queues
is related toASTERISK-16115 [patch] problem with ringinuse=no, queue members receive sometimes two calls
is related toASTERISK-19820 wrapuptime is intermittently disregarded for queue calls
is related toASTERISK-22056 Asterisk 11.4.0 : Queue RINGNOANSWER wrong ring time when one of the peer becomes unresponsive
Environment:Attachments:( 0) app_queue-ASTERISK-22189-11.patch
( 1) extensions.conf
( 2) full
( 3) queues.conf
Description:Queue members who happen to be in multiple queues at the same time don't have any wrap up time. This problem appears to have become more prevalent since Asterisk 11.3.0.

This may be related to the backing out of the patch on ASTERISK-16115.

Reported by Tony Lewis of FreePBX.

(*NOTE*: I'll update this issue with some logs/dialplan in a bit)
Comments:By: Matt Jordan (mjordan) 2013-07-26 09:27:43.332-0500

So I thought this would be easy to reproduce. Unfortunately, my first crack at it didn't reproduce it.

{noformat:title=queues.conf}
[sales]
strategy=ringall
announce=sales
musicclass = default
monitor-type=MixMonitor
monitor-format=wav
member => Local/digium01@agents
wrapuptime = 15

[support]
strategy=ringall
announce=support
musicclass = default
member => Local/digium01@agents
timeout = 5
retry = 15
wrapuptime = 30
{noformat}

{noformat:title=extensions.conf}
[default]
exten => 5000,1,NoOp()
exten => 5000,n,Queue(sales)

[agents]
exten => digium01,hint,SIP/digium01
exten => digium01,1,NoOp()
       same => n,Dial(SIP/digium01,15,hHkKtT)
       same => n,Hangup()
{noformat}

In the log snippet below, two calls are made.
# In the first call, SIP/digium02 calls the Queue at 5000. This creates a Local channel that dials SIP/digium01. The two are bridged, talk for a bit, and SIP/digium02 hangs up. The call ends at approximately 09:23:30.
# In the second call, SIP/digium02 calls the Queue at 5000 again. They hang out in the Queue because the only channel member was the Local channel to SIP/digium01 - which implies the wrapup time is being honored for the queue. Note that the time at which SIP/digium01 is dialed by the Local channel agent is 09:23:47, which is 15 seconds from when the second call attempt was made. That might be a little wonky in that the wrapup time probably should have started from when the last call terminated, but since no one was in the queue any more when that happened, the check probably started from when the next call entered the queue. Regardless, wrapup time for the queue was honored.

{noformat:title=messages}
[Jul 26 09:23:19] VERBOSE[26930] config.c:   == Parsing '/etc/asterisk/logger.conf': Found
[Jul 26 09:23:19] VERBOSE[26930] logger.c:  Asterisk Queue Logger restarted
[Jul 26 09:23:22] VERBOSE[26945][C-00000004] netsock2.c:   == Using SIP RTP CoS mark 5
[Jul 26 09:23:22] VERBOSE[27102][C-00000004] pbx.c:     -- Executing [5000@default:1] NoOp("SIP/digium02-00000008", "") in new stack
[Jul 26 09:23:22] VERBOSE[27102][C-00000004] pbx.c:     -- Executing [5000@default:2] Queue("SIP/digium02-00000008", "sales") in new stack
[Jul 26 09:23:22] VERBOSE[27102][C-00000004] res_musiconhold.c:     -- Started music on hold, class 'default', on SIP/digium02-00000008
[Jul 26 09:23:22] VERBOSE[27103][C-00000004] pbx.c:     -- Executing [digium01@agents:1] NoOp("Local/digium01@agents-00000004;2", "") in new stack
[Jul 26 09:23:22] VERBOSE[27103][C-00000004] pbx.c:     -- Executing [digium01@agents:2] Dial("Local/digium01@agents-00000004;2", "SIP/digium01,15,hHkKtT") in new stack
[Jul 26 09:23:22] VERBOSE[27103][C-00000004] netsock2.c:   == Using SIP RTP CoS mark 5
[Jul 26 09:23:22] VERBOSE[27103][C-00000004] app_dial.c:     -- Called SIP/digium01
[Jul 26 09:23:22] VERBOSE[27102][C-00000004] app_queue.c:     -- Local/digium01@agents-00000004;1 connected line has changed. Saving it until answer for SIP/digium02-00000008
[Jul 26 09:23:22] VERBOSE[27102][C-00000004] app_queue.c:     -- Local/digium01@agents-00000004;1 connected line has changed. Saving it until answer for SIP/digium02-00000008
[Jul 26 09:23:22] VERBOSE[27103][C-00000004] app_dial.c:     -- SIP/digium01-00000009 is ringing
[Jul 26 09:23:22] VERBOSE[27102][C-00000004] app_queue.c:     -- Local/digium01@agents-00000004;1 is ringing
[Jul 26 09:23:25] VERBOSE[27102][C-00000004] app_queue.c:     -- Local/digium01@agents-00000004;1 connected line has changed. Saving it until answer for SIP/digium02-00000008
[Jul 26 09:23:25] VERBOSE[27103][C-00000004] app_dial.c:     -- SIP/digium01-00000009 answered Local/digium01@agents-00000004;2
[Jul 26 09:23:25] VERBOSE[27102][C-00000004] app_queue.c:     -- Local/digium01@agents-00000004;1 answered SIP/digium02-00000008
[Jul 26 09:23:25] VERBOSE[27102][C-00000004] res_musiconhold.c:     -- Stopped music on hold on SIP/digium02-00000008
[Jul 26 09:23:25] VERBOSE[27105][C-00000004] app_mixmonitor.c:   == Begin MixMonitor Recording SIP/digium02-00000008
[Jul 26 09:23:25] VERBOSE[27103][C-00000004] pbx.c:   == Spawn extension (agents, digium01, 2) exited non-zero on 'Local/digium01@agents-00000004;2'
[Jul 26 09:23:30] VERBOSE[27102][C-00000004] pbx.c:     -- Executing [h@default:1] NoOp("SIP/digium02-00000008", "") in new stack
[Jul 26 09:23:30] VERBOSE[27102][C-00000004] pbx.c:     -- Executing [h@default:2] Wait("SIP/digium02-00000008", "10") in new stack
[Jul 26 09:23:30] VERBOSE[27102][C-00000004] pbx.c:   == Spawn extension (default, h, 2) exited non-zero on 'SIP/digium02-00000008'
[Jul 26 09:23:30] VERBOSE[27102][C-00000004] pbx.c:   == Spawn extension (default, 5000, 2) exited non-zero on 'SIP/digium02-00000008'
[Jul 26 09:23:30] VERBOSE[27105][C-00000004] app_mixmonitor.c:   == MixMonitor close filestream (mixed)
[Jul 26 09:23:30] VERBOSE[27105][C-00000004] app_mixmonitor.c:   == End MixMonitor Recording SIP/digium02-00000008
[Jul 26 09:23:32] VERBOSE[26945][C-00000005] netsock2.c:   == Using SIP RTP CoS mark 5
[Jul 26 09:23:32] VERBOSE[27107][C-00000005] pbx.c:     -- Executing [5000@default:1] NoOp("SIP/digium02-0000000a", "") in new stack
[Jul 26 09:23:32] VERBOSE[27107][C-00000005] pbx.c:     -- Executing [5000@default:2] Queue("SIP/digium02-0000000a", "sales") in new stack
[Jul 26 09:23:32] VERBOSE[27107][C-00000005] res_musiconhold.c:     -- Started music on hold, class 'default', on SIP/digium02-0000000a
[Jul 26 09:23:47] VERBOSE[27119][C-00000005] pbx.c:     -- Executing [digium01@agents:1] NoOp("Local/digium01@agents-00000005;2", "") in new stack
[Jul 26 09:23:47] VERBOSE[27119][C-00000005] pbx.c:     -- Executing [digium01@agents:2] Dial("Local/digium01@agents-00000005;2", "SIP/digium01,15,hHkKtT") in new stack
[Jul 26 09:23:47] VERBOSE[27119][C-00000005] netsock2.c:   == Using SIP RTP CoS mark 5
[Jul 26 09:23:47] VERBOSE[27119][C-00000005] app_dial.c:     -- Called SIP/digium01
[Jul 26 09:23:47] VERBOSE[27107][C-00000005] app_queue.c:     -- Local/digium01@agents-00000005;1 connected line has changed. Saving it until answer for SIP/digium02-0000000a
[Jul 26 09:23:47] VERBOSE[27107][C-00000005] app_queue.c:     -- Local/digium01@agents-00000005;1 connected line has changed. Saving it until answer for SIP/digium02-0000000a
[Jul 26 09:23:47] VERBOSE[27119][C-00000005] app_dial.c:     -- SIP/digium01-0000000b is ringing
[Jul 26 09:23:47] VERBOSE[27107][C-00000005] app_queue.c:     -- Local/digium01@agents-00000005;1 is ringing
[Jul 26 09:23:50] VERBOSE[27107][C-00000005] app_queue.c:     -- Local/digium01@agents-00000005;1 connected line has changed. Saving it until answer for SIP/digium02-0000000a
[Jul 26 09:23:50] VERBOSE[27119][C-00000005] app_dial.c:     -- SIP/digium01-0000000b answered Local/digium01@agents-00000005;2
[Jul 26 09:23:50] VERBOSE[27107][C-00000005] app_queue.c:     -- Local/digium01@agents-00000005;1 answered SIP/digium02-0000000a
[Jul 26 09:23:50] VERBOSE[27107][C-00000005] res_musiconhold.c:     -- Stopped music on hold on SIP/digium02-0000000a
[Jul 26 09:23:50] VERBOSE[27120][C-00000005] app_mixmonitor.c:   == Begin MixMonitor Recording SIP/digium02-0000000a
[Jul 26 09:23:51] VERBOSE[27119][C-00000005] pbx.c:   == Spawn extension (agents, digium01, 2) exited non-zero on 'Local/digium01@agents-00000005;2'
[Jul 26 09:23:54] VERBOSE[27107][C-00000005] pbx.c:     -- Executing [h@default:1] NoOp("SIP/digium02-0000000a", "") in new stack
[Jul 26 09:23:54] VERBOSE[27107][C-00000005] pbx.c:     -- Executing [h@default:2] Wait("SIP/digium02-0000000a", "10") in new stack
[Jul 26 09:23:54] VERBOSE[27107][C-00000005] pbx.c:   == Spawn extension (default, h, 2) exited non-zero on 'SIP/digium02-0000000a'
[Jul 26 09:23:54] VERBOSE[27107][C-00000005] pbx.c:   == Spawn extension (default, 5000, 2) exited non-zero on 'SIP/digium02-0000000a'
[Jul 26 09:23:54] VERBOSE[27120][C-00000005] app_mixmonitor.c:   == MixMonitor close filestream (mixed)
[Jul 26 09:23:54] VERBOSE[27120][C-00000005] app_mixmonitor.c:   == End MixMonitor Recording SIP/digium02-0000000a
{noformat}


By: Matt Jordan (mjordan) 2013-07-26 09:37:06.251-0500

Tony clarified how to reproduce the problem. You have to call the first Queue, then the second Queue. When that occurs, the wrap up time is ignored. Logs forthcoming.

By: Matt Jordan (mjordan) 2013-07-26 09:41:45.795-0500

Full log attached.

* Call ID C-00000000 is SIP/digium02 calling Queue 5000. Queue member is rung immediately (expected). Call hangs up at 09:38:28.
* Call ID C-00000001 is SIP/digium02 calling Queue 5001. Queue member is rung immediately (error).

By: Matt Jordan (mjordan) 2013-07-26 10:39:52.058-0500

Patch for Asterisk 11 attached - [app_queue-ASTERISK-22189-11.patch|https://issues.asterisk.org/jira/secure/attachment/47866/app_queue-ASTERISK-22189-11.patch]. This fixed the issue locally for me.

This issue should only affect Asterisk 11. It was actually caused by some of the device state modifications for app_queue that were made for Asterisk 11 - and really, by some refactorings that pulled the device state availability for members into a shared location. That routine wasn't properly checking for Queue wrap up times, which means some members were being treated as being available when they weren't (but only down certain code paths). This patch modifies the general {{is_member_available}} routine to also take into account Queue wrap up time.