[asterisk-users] Asterisk 13.12.2 : strange queue behaviour
Jonas Kellens
jonas.kellens at telenet.be
Tue Nov 22 05:11:11 CST 2016
On 21-11-16 19:14, Jonas Kellens wrote:
>
> On 21-11-16 17:20, Matthew Jordan wrote:
>>
>>
>> On Mon, Nov 21, 2016 at 10:05 AM, Jonas Kellens
>> <jonas.kellens at telenet.be <mailto:jonas.kellens at telenet.be>> wrote:
>>
>> On 21-11-16 15:17, Matthew Jordan wrote:
>>>
>>> On Mon, Nov 21, 2016 at 7:05 AM, Jonas Kellens
>>> <jonas.kellens at telenet.be <mailto:jonas.kellens at telenet.be>> wrote:
>>>
>>> Hello
>>>
>>> when using Asterisk version 13.12.2 I notice that it takes
>>> up to 30 seconds (sometimes even longer) for a call queue to
>>> call its members.
>>>
>>> Example 1 :
>>>
>>> [Nov 21 08:17:57] pbx.c: Executing [queue at pbx-routing:15]
>>> Queue("SIP/incoming-00000246", "myqueue1,,,,300,,,") in new
>>> stack
>>> [Nov 21 08:17:57] res_musiconhold.c: Started music on hold,
>>> class 'default', on channel 'SIP/incoming-00000246'
>>>
>>> [Nov 21 08:18:26] pbx.c: Executing
>>> [mysip692 at CallFromQueue:1]
>>> NoOp("Local/mysip692 at CallFromQueue-0000003c;2", "") in new stack
>>> [Nov 21 08:18:26] app_queue.c: Called
>>> Local/mysip692 at CallFromQueue
>>> [Nov 21 08:18:26] pbx.c: Executing
>>> [mysip692 at CallFromQueue:3]
>>> Dial("Local/mysip692 at CallFromQueue-0000003c;2",
>>> "SIP/mysip692") in new stack
>>> [Nov 21 08:18:26] app_dial.c: Called SIP/mysip692
>>>
>>>
>>> Example 2 :
>>>
>>> [Nov 21 08:20:11] pbx.c: Executing [queue at pbx-routing:15]
>>> Queue("SIP/incoming-00000255", "myqueue1,,,,300,,,") in new
>>> stack
>>> [Nov 21 08:20:11] res_musiconhold.c: Started music on hold,
>>> class 'default', on channel 'SIP/incoming-00000255'
>>>
>>> [Nov 21 08:20:45] app_queue.c: Called
>>> Local/mysip692 at CallFromQueue
>>> [Nov 21 08:20:45] pbx.c: Executing
>>> [mysip692 at CallFromQueue:1]
>>> NoOp("Local/mysip692 at CallFromQueue-00000040;2", "") in new stack
>>> [Nov 21 08:20:45] pbx.c: Executing
>>> [mysip692 at CallFromQueue:3]
>>> Dial("Local/mysip692 at CallFromQueue-00000040;2",
>>> "SIP/mysip692") in new stack
>>> [Nov 21 08:20:45] app_dial.c: Called SIP/mysip692
>>>
>>>
>>> I did not see this behaviour in previous Asterisk versions.
>>>
>>> Could this be a bug ?
>>>
>>>
>>> There's not enough information here to know what is preventing
>>> the call from occurring.
>>>
>>> I'd look at a debug log between the caller entering the Queue
>>> and the outbound call being made. That should illustrate what is
>>> causing the delay.
>>>
>>> --
>>> Matthew Jordan
>>
>>
>> Hello
>>
>>
>> and what exactly am I looking for in the debug logs ?
>>
>> I have generated debug output and re-produced the issue.
>>
>>
>> Again 23 seconds before calling the queue member :
>>
>> [Nov 21 16:23:33] pbx.c: Executing [queue at pbx-routing:15]
>> Queue("SIP/incoming-00004e6e", "myqueue1,,,,300,,,") in new stack
>> [Nov 21 16:23:33] res_musiconhold.c: Started music on hold, class
>> 'default', on channel 'SIP/incoming-00004e6e'
>>
>> [Nov 21 16:23:56] pbx.c: Executing [mysip692 at CallFromQueue:1]
>> NoOp("Local/mysip692 at CallFromQueue-0000081a;2", "") in new stack
>> [Nov 21 16:23:56] app_queue.c: Called Local/mysip692 at CallFromQueue
>> [Nov 21 16:23:56] pbx.c: Executing [mysip692 at CallFromQueue:2]
>> NoOp("Local/mysip692 at CallFromQueue-0000081a;2", "exten =
>> mysip692") in new stack
>> [Nov 21 16:23:56] pbx.c: Executing [mysip692 at CallFromQueue:3]
>> Dial("Local/mysip692 at CallFromQueue-0000081a;2", "SIP/mysip692")
>> in new stack
>> [Nov 21 16:23:56] app_dial.c: Called SIP/mysip692
>> [Nov 21 16:23:56] app_dial.c: SIP/mysip692-00004e86 is ringing
>> [Nov 21 16:23:56] app_queue.c:
>> Local/mysip692 at CallFromQueue-0000081a;1 is ringing
>>
>>
>>
>> Could it be that it is because my Queue member 'mysip692' is
>> occupied in another bridge (call) ?
>>
>> This I see in the logs just before the Call Queue starts calling
>> the queue member :
>>
>> [Nov 21 16:23:55] bridge_native_rtp.c: Locally RTP bridged
>> 'SIP/mysip-00004e6a' and 'SIP/incoming-00004e63' in stack
>> [Nov 21 16:23:55] bridge_channel.c: Channel SIP/incoming-00004e63
>> left 'native_rtp' basic-bridge <fed056d3-669a-493d-a4bd-f0d9ab0102a7>
>> [Nov 21 16:23:55] bridge_channel.c: Channel SIP/mysip-00004e6a
>> left 'native_rtp' basic-bridge <fed056d3-669a-493d-a4bd-f0d9ab0102a7>
>>
>>
>> A bit too coincidal, no ?
>>
>> So then it has something to do with the bridging ?
>>
>>
>>
>> I did not have this behaviour in previous Asterisk versions.
>>
>>
>> Those aren't debug logs. Instructions for generating debug
>> information can be found on the wiki:
>>
>> https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information
>>
>> That being said, if the Queue Member is currently busy (which will be
>> denoted by their device state), and you have not configured the Queue
>> to ring the Queue Member while they are busy, then I would expect any
>> new caller to hang out in the Queue until that Member is available.
>>
>> --
>> Matthew Jordan
>
> Hello
>
> indeed no debug log output. Therefore I need to know what to filter
> because there is a lot of information written.
>
> "you have not configured the Queue to ring the Queue Member while they
> are busy"
>
> --> where would I configure this ?
>
> I have in my realtime MySQL tables 'queues' a column 'ringinuse' with
> value 'no'.
>
>
> I would expect that the call does enter the call queue but when the
> member is called there is a 'busy' notification for that member. This
> way the dialplan can continue with the next step.
>
> Now the call 'hangs' at the queue application until this queue()
> command can continue.
>
> Is this normal behaviour in version 13.12.2 ? Personally I prefer the
> previous behaviour of the Queue application.
>
>
>
> Kind regards.
>
> J.
I have more info concerning this bug. It seems that once a member of the
queue can not be reached due to the fact that it is busy in another
call, this queue member is never again being called by the queue
application !
Look at these 3 calls :
Call 1 : both queue members are being called (normal behaviour,
everything is fine)
[Nov 22 11:27:10] VERBOSE[1992][C-00000898] pbx.c: Executing
[queue at pbx-routing:15] Queue("SIP/incoming-0000219f",
"myqueue1,,,,10,,,") in new stack
[Nov 22 11:27:10] VERBOSE[1992][C-00000898] res_musiconhold.c: Started
music on hold, class 'default', on channel 'SIP/incoming-0000219f'
[Nov 22 11:27:10] VERBOSE[2063][C-00000898] pbx.c: Executing
[mysip517 at CallFromQueue:1]
NoOp("Local/mysip517 at CallFromQueue-00000447;2", "") in new stack
[Nov 22 11:27:10] VERBOSE[1992][C-00000898] app_queue.c: Called
Local/mysip517 at CallFromQueue
[Nov 22 11:27:10] VERBOSE[2063][C-00000898] pbx.c: Executing
[mysip517 at CallFromQueue:2]
NoOp("Local/mysip517 at CallFromQueue-00000447;2", "exten = mysip517") in
new stack
[Nov 22 11:27:10] VERBOSE[2063][C-00000898] pbx.c: Executing
[mysip517 at CallFromQueue:3]
Dial("Local/mysip517 at CallFromQueue-00000447;2", "SIP/mysip517") in new stack
[Nov 22 11:27:10] VERBOSE[2064][C-00000898] pbx.c: Executing
[mysip467 at CallFromQueue:1]
NoOp("Local/mysip467 at CallFromQueue-00000448;2", "") in new stack
[Nov 22 11:27:10] VERBOSE[1992][C-00000898] app_queue.c: Called
Local/mysip467 at CallFromQueue
[Nov 22 11:27:10] VERBOSE[2064][C-00000898] pbx.c: Executing
[mysip467 at CallFromQueue:2]
NoOp("Local/mysip467 at CallFromQueue-00000448;2", "exten = mysip467") in
new stack
[Nov 22 11:27:10] VERBOSE[2064][C-00000898] pbx.c: Executing
[mysip467 at CallFromQueue:3]
Dial("Local/mysip467 at CallFromQueue-00000448;2", "SIP/mysip467") in new stack
[Nov 22 11:27:10] VERBOSE[2063][C-00000898] app_dial.c: Called SIP/mysip517
[Nov 22 11:27:10] VERBOSE[2064][C-00000898] app_dial.c: Called SIP/mysip467
[Nov 22 11:27:10] VERBOSE[2063][C-00000898] app_dial.c:
SIP/mysip517-000021a1 is ringing
[Nov 22 11:27:10] VERBOSE[1992][C-00000898] app_queue.c:
Local/mysip517 at CallFromQueue-00000447;1 is ringing
[Nov 22 11:27:11] VERBOSE[2064][C-00000898] app_dial.c:
SIP/mysip467-000021a2 is ringing
[Nov 22 11:27:11] VERBOSE[1992][C-00000898] app_queue.c:
Local/mysip467 at CallFromQueue-00000448;1 is ringing
***************************************************************************************************************************************************
Call 2 : only one member is being called, queue member mysip467 is busy
in another conversation (still normal behaviour, everything is fine)
[Nov 22 11:33:05] VERBOSE[6703][C-000008e0] pbx.c: Executing
[queue at pbx-routing:15] Queue("SIP/incoming-000022bc",
"myqueue1,,,,10,,,") in new stack
[Nov 22 11:33:05] VERBOSE[6703][C-000008e0] res_musiconhold.c: Started
music on hold, class 'default', on channel 'SIP/incoming-000022bc'
[Nov 22 11:33:05] VERBOSE[6751][C-000008e0] pbx.c: Executing
[mysip517 at CallFromQueue:1]
NoOp("Local/mysip517 at CallFromQueue-0000046c;2", "") in new stack
[Nov 22 11:33:05] VERBOSE[6703][C-000008e0] app_queue.c: Called
Local/mysip517 at CallFromQueue
[Nov 22 11:33:05] VERBOSE[6751][C-000008e0] pbx.c: Executing
[mysip517 at CallFromQueue:2]
NoOp("Local/mysip517 at CallFromQueue-0000046c;2", "exten = mysip517") in
new stack
[Nov 22 11:33:05] VERBOSE[6751][C-000008e0] pbx.c: Executing
[mysip517 at CallFromQueue:3]
Dial("Local/mysip517 at CallFromQueue-0000046c;2", "SIP/mysip517") in new stack
[Nov 22 11:33:05] VERBOSE[6752][C-000008e0] pbx.c: Executing
[mysip467 at CallFromQueue:1]
NoOp("Local/mysip467 at CallFromQueue-0000046d;2", "") in new stack
[Nov 22 11:33:05] VERBOSE[6703][C-000008e0] app_queue.c: Called
Local/mysip467 at CallFromQueue
[Nov 22 11:33:05] VERBOSE[6752][C-000008e0] pbx.c: Executing
[mysip467 at CallFromQueue:2]
NoOp("Local/mysip467 at CallFromQueue-0000046d;2", "exten = mysip467") in
new stack
[Nov 22 11:33:05] VERBOSE[6752][C-000008e0] pbx.c: Executing
[mysip467 at CallFromQueue:3]
Dial("Local/mysip467 at CallFromQueue-0000046d;2", "SIP/mysip467") in new stack
[Nov 22 11:33:05] VERBOSE[6751][C-000008e0] app_dial.c: Called SIP/mysip517
[Nov 22 11:33:05] VERBOSE[6752][C-000008e0] app_dial.c: Called SIP/mysip467
[Nov 22 11:33:05] VERBOSE[6751][C-000008e0] app_dial.c:
SIP/mysip517-000022be is ringing
[Nov 22 11:33:05] VERBOSE[6703][C-000008e0] app_queue.c:
Local/mysip517 at CallFromQueue-0000046c;1 is ringing
[Nov 22 11:33:05] VERBOSE[6752][C-000008e0] app_dial.c:
SIP/mysip467-000022bf redirecting info has changed, passing it to
Local/mysip467 at CallFromQueue-0000046d;2
[Nov 22 11:33:05] VERBOSE[6752][C-000008e0] app_dial.c:
SIP/mysip467-000022bf is busy
[Nov 22 11:33:05] VERBOSE[6752][C-000008e0] app_dial.c: Everyone is
busy/congested at this time (1:1/0/0)
[Nov 22 11:33:05] VERBOSE[6752][C-000008e0] pbx.c: Executing
[mysip467 at CallFromQueue:4]
Hangup("Local/mysip467 at CallFromQueue-0000046d;2", "") in new stack
[Nov 22 11:33:05] VERBOSE[6752][C-000008e0] pbx.c: Spawn extension
(CallFromQueue, mysip467, 4) exited non-zero on
'Local/mysip467 at CallFromQueue-0000046d;2'
***************************************************************************************************************************************************
Call 3 : only one member is being called, queue member mysip467 is no
longer in another conversation thus should also be called again (not
normal behaviour)
[Nov 22 11:33:30] VERBOSE[7081][C-000008e7] pbx.c: Executing
[queue at pbx-routing:15] Queue("SIP/incoming-000022d6",
"myqueue1,,,,10,,,") in new stack
[Nov 22 11:33:30] VERBOSE[7081][C-000008e7] res_musiconhold.c: Started
music on hold, class 'default', on channel 'SIP/incoming-000022d6'
[Nov 22 11:33:30] VERBOSE[7129][C-000008e7] pbx.c: Executing
[mysip517 at CallFromQueue:1]
NoOp("Local/mysip517 at CallFromQueue-00000472;2", "") in new stack
[Nov 22 11:33:30] VERBOSE[7081][C-000008e7] app_queue.c: Called
Local/mysip517 at CallFromQueue
[Nov 22 11:33:30] VERBOSE[7129][C-000008e7] pbx.c: Executing
[mysip517 at CallFromQueue:2]
NoOp("Local/mysip517 at CallFromQueue-00000472;2", "exten = mysip517") in
new stack
[Nov 22 11:33:30] VERBOSE[7129][C-000008e7] pbx.c: Executing
[mysip517 at CallFromQueue:3]
Dial("Local/mysip517 at CallFromQueue-00000472;2", "SIP/mysip517") in new stack
[Nov 22 11:33:30] VERBOSE[7129][C-000008e7] app_dial.c: Called SIP/mysip517
[Nov 22 11:33:30] VERBOSE[7129][C-000008e7] app_dial.c:
SIP/mysip517-000022d8 is ringing
[Nov 22 11:33:30] VERBOSE[7081][C-000008e7] app_queue.c:
Local/mysip517 at CallFromQueue-00000472;1 is ringing
(only mysip517 is being called)
***************************************************************************************************************************************************
If a queue member (in my example mysip467) states to the Queue
application that it is busy and can not take a call, it seems that the
Queue application remembers this forever and never again sends a call to
this queue member. Even if the member is available again.
Should a file a bug report on the tracker ??
Kind regards.
J.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20161122/a5ac3015/attachment-0001.html>
More information about the asterisk-users
mailing list