[asterisk-bugs] [JIRA] (ASTERISK-26133) Queue members receive multiple calls

Tue Jun 21 10:52:57 CDT 2016

Richard Miller created ASTERISK-26133:
-----------------------------------------

             Summary: Queue members receive multiple calls
                 Key: ASTERISK-26133
                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-26133
             Project: Asterisk
          Issue Type: Bug
      Security Level: None
          Components: Applications/app_queue
    Affects Versions: 13.9.1, 11.22.0
            Reporter: Richard Miller

Issue ASTERISK-16115 was considered closed by
https://gerrit.asterisk.org/#/c/2677/
https://gerrit.asterisk.org/#/c/2679/
for versions 13.9 and 11.22

However, multiple calls are still happening occasionally.  I have determined the cause.  I will upload the patch to the issue tracker first.  The same fix applies to both versions 11 and 13.  I will post the fix to gerrit once I have figured out how to use it.

In the troubleshooting, I adjusted the debug level of many of the calls to ast_debug() because there was just way too much output with "core set debug 1 app_queue".  Should I include those changes when posting the fix?

The intent of the above patches was to keep track of which agents had a call pending, then clear the pending status when a device state change event arrives.  What is causing the problem is that with some SIP clients, there are multiple events firing.

This is the scenario.  A call ends for an agent and the device is no longer in use.  A queue entry finds that there is now an agent available, then dials that member.  Before the call begins ringing, a second device state event from the prior call ending arrives showing that the device is not in use.  That event clears the call pending state, so the next one in queue gets dispatched and finds the same agent is available.  This is more likely to happen when the agent is at a remote location so there is more latency than when they are on the same local area network as the Asterisk server.

I must say that I am not satisfied with the implementation of this fix.  Prior to the above patches, there was already in place a "callattempt" structure that can be probably be used for call coordination.  A lot of the contention arbitration is done at the time the call is placed.  I want to move a lot of that logic earlier to where the queue entry determines if it is next to go.  That will also make it easier to implement cross-queue servicing of calls with the longest hold time.  See the following issues which are still marked as being open:
https://issues.asterisk.org/jira/browse/ASTERISK-17570
https://issues.asterisk.org/jira/browse/ASTERISK-17732

Here is the log information that I used to determine the problem.

[06-16 15:11:02.636] DEBUG[8432] app_queue.c: Device 'SIP/6347' changed to state '1' (Not in use)
[06-16 15:11:02.663] DEBUG[10586][C-00000790] app_queue.c: There is 1 available member.
[06-16 15:11:02.663] DEBUG[10586][C-00000790] app_queue.c: It's our turn (SIP/L3CO811-00000db7).
[06-16 15:11:02.663] DEBUG[10586][C-00000790] app_queue.c: SIP/L3CO811-00000db7 is trying to call a queue member.
[06-16 15:11:02.664] DEBUG[10586][C-00000790] app_queue.c: Trying 'SIP/6347' with metric 1000000
[06-16 15:11:02.664] DEBUG[10586][C-00000790] app_queue.c: Found matching member SIP/6347 in queue 'xxxxx'
[06-16 15:11:02.665] VERBOSE[10586][C-00000790] netsock2.c: [06-16 15:11:02.665]   == Using SIP RTP TOS bits 184
[06-16 15:11:02.665] VERBOSE[10586][C-00000790] netsock2.c: [06-16 15:11:02.665]   == Using SIP RTP CoS mark 5
[06-16 15:11:02.665] VERBOSE[10586][C-00000790] app_queue.c: [06-16 15:11:02.665]     -- Called SIP/6347

*********** this is the event that causes the problem ************************
[06-16 15:11:02.669] DEBUG[8432] app_queue.c: Device 'SIP/6347' changed to state '1' (Not in use)

[06-16 15:11:02.688] DEBUG[10744][C-00000794] app_queue.c: There is 1 available member.
[06-16 15:11:02.688] DEBUG[10744][C-00000794] app_queue.c: It's our turn (SIP/L3CO811-00000dbe).
[06-16 15:11:02.688] DEBUG[10744][C-00000794] app_queue.c: SIP/L3CO811-00000dbe is trying to call a queue member.
[06-16 15:11:02.689] DEBUG[10744][C-00000794] app_queue.c: Trying 'SIP/6347' with metric 1000000
[06-16 15:11:02.689] DEBUG[10744][C-00000794] app_queue.c: Found matching member SIP/6347 in queue 'xxxxx'
[06-16 15:11:02.690] VERBOSE[10744][C-00000794] netsock2.c: [06-16 15:11:02.690]   == Using SIP RTP TOS bits 184
[06-16 15:11:02.690] VERBOSE[10744][C-00000794] netsock2.c: [06-16 15:11:02.690]   == Using SIP RTP CoS mark 5
[06-16 15:11:02.690] VERBOSE[10744][C-00000794] app_queue.c: [06-16 15:11:02.690]     -- Called SIP/6347
[06-16 15:11:02.706] DEBUG[8432] app_queue.c: Device 'SIP/6347' changed to state '6' (Ringing)
[06-16 15:11:02.823] DEBUG[8432] app_queue.c: Device 'SIP/6347' changed to state '6' (Ringing)
[06-16 15:11:02.828] DEBUG[8432] app_queue.c: Device 'SIP/6347' changed to state '6' (Ringing)
[06-16 15:11:02.828] VERBOSE[10586][C-00000790] app_queue.c: [06-16 15:11:02.828]     -- SIP/6347-00000dcb is ringing
[06-16 15:11:02.828] VERBOSE[10586][C-00000790] res_musiconhold.c: [06-16 15:11:02.828]     -- Stopped music on hold on SIP/L3CO811-00000db7
[06-16 15:11:02.953] VERBOSE[10744][C-00000794] app_queue.c: [06-16 15:11:02.953]     -- SIP/6347-00000dcc is ringing
[06-16 15:11:02.953] VERBOSE[10744][C-00000794] res_musiconhold.c: [06-16 15:11:02.953]     -- Stopped music on hold on SIP/L3CO811-00000dbe

Also the "Found matching member" debug message is showing a different queue than the one being serviced.

--
This message was sent by Atlassian JIRA
(v6.2#6252)