6 thoughts on - Asterisk 13.12.2 : Strange Queue Behaviour

• 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.

• 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@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@CallFromQueue:1]
  NoOp(“Local/mysip692@CallFromQueue-0000081a;2”, “”) in new stack
  [Nov 21 16:23:56] app_queue.c: Called Local/mysip692@CallFromQueue
  [Nov 21 16:23:56] pbx.c: Executing [mysip692@CallFromQueue:2]
  NoOp(“Local/mysip692@CallFromQueue-0000081a;2”, “exten = mysip692”) in new stack
  [Nov 21 16:23:56] pbx.c: Executing [mysip692@CallFromQueue:3]
  Dial(“Local/mysip692@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@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
  [Nov 21 16:23:55] bridge_channel.c: Channel SIP/mysip-00004e6a left
  ‘native_rtp’ basic-bridge

  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.

  Kind regards.

  J.

• 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.

• 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@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@CallFromQueue:1]
  NoOp(“Local/mysip517@CallFromQueue-00000447;2”, “”) in new stack
  [Nov 22 11:27:10] VERBOSE[1992][C-00000898] app_queue.c: Called Local/mysip517@CallFromQueue
  [Nov 22 11:27:10] VERBOSE[2063][C-00000898] pbx.c: Executing
  [mysip517@CallFromQueue:2]
  NoOp(“Local/mysip517@CallFromQueue-00000447;2”, “exten = mysip517”) in new stack
  [Nov 22 11:27:10] VERBOSE[2063][C-00000898] pbx.c: Executing
  [mysip517@CallFromQueue:3]
  Dial(“Local/mysip517@CallFromQueue-00000447;2”, “SIP/mysip517”) in new stack

  [Nov 22 11:27:10] VERBOSE[2064][C-00000898] pbx.c: Executing
  [mysip467@CallFromQueue:1]
  NoOp(“Local/mysip467@CallFromQueue-00000448;2”, “”) in new stack
  [Nov 22 11:27:10] VERBOSE[1992][C-00000898] app_queue.c: Called Local/mysip467@CallFromQueue
  [Nov 22 11:27:10] VERBOSE[2064][C-00000898] pbx.c: Executing
  [mysip467@CallFromQueue:2]
  NoOp(“Local/mysip467@CallFromQueue-00000448;2”, “exten = mysip467”) in new stack
  [Nov 22 11:27:10] VERBOSE[2064][C-00000898] pbx.c: Executing
  [mysip467@CallFromQueue:3]
  Dial(“Local/mysip467@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@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@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@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@CallFromQueue:1]
  NoOp(“Local/mysip517@CallFromQueue-0000046c;2”, “”) in new stack
  [Nov 22 11:33:05] VERBOSE[6703][C-000008e0] app_queue.c: Called Local/mysip517@CallFromQueue
  [Nov 22 11:33:05] VERBOSE[6751][C-000008e0] pbx.c: Executing
  [mysip517@CallFromQueue:2]
  NoOp(“Local/mysip517@CallFromQueue-0000046c;2”, “exten = mysip517”) in new stack
  [Nov 22 11:33:05] VERBOSE[6751][C-000008e0] pbx.c: Executing
  [mysip517@CallFromQueue:3]
  Dial(“Local/mysip517@CallFromQueue-0000046c;2”, “SIP/mysip517”) in new stack

  [Nov 22 11:33:05] VERBOSE[6752][C-000008e0] pbx.c: Executing
  [mysip467@CallFromQueue:1]
  NoOp(“Local/mysip467@CallFromQueue-0000046d;2”, “”) in new stack
  [Nov 22 11:33:05] VERBOSE[6703][C-000008e0] app_queue.c: Called Local/mysip467@CallFromQueue
  [Nov 22 11:33:05] VERBOSE[6752][C-000008e0] pbx.c: Executing
  [mysip467@CallFromQueue:2]
  NoOp(“Local/mysip467@CallFromQueue-0000046d;2”, “exten = mysip467”) in new stack
  [Nov 22 11:33:05] VERBOSE[6752][C-000008e0] pbx.c: Executing
  [mysip467@CallFromQueue:3]
  Dial(“Local/mysip467@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@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@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@CallFromQueue:4]
  Hangup(“Local/mysip467@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@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@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@CallFromQueue:1]
  NoOp(“Local/mysip517@CallFromQueue-00000472;2”, “”) in new stack
  [Nov 22 11:33:30] VERBOSE[7081][C-000008e7] app_queue.c: Called Local/mysip517@CallFromQueue
  [Nov 22 11:33:30] VERBOSE[7129][C-000008e7] pbx.c: Executing
  [mysip517@CallFromQueue:2]
  NoOp(“Local/mysip517@CallFromQueue-00000472;2”, “exten = mysip517”) in new stack
  [Nov 22 11:33:30] VERBOSE[7129][C-000008e7] pbx.c: Executing
  [mysip517@CallFromQueue:3]
  Dial(“Local/mysip517@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@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.

• Hello

  I did a call with my queue member mysip517 and now this one is also no longer being called by the Queue application. So I can reproduce this bug every time again and again.

  Now my dialplan just hangs at the Queue application :

  [Nov 22 13:52:16] — Executing [queue@pbx-routing:15]
  Queue(“SIP/incoming-0000001c”, “myqueue1,,,,30,,,”) in new stack
  [Nov 22 13:52:16] — Started music on hold, class ‘default’, on channel ‘SIP/incoming-0000001c’

  (nothing happens further, we just sit 30 seconds inside the queue)

  I’ve generated debug output :

  …
  [Nov 22 13:52:27] DEBUG[27577][C-00000007] audiohook.c: Write factory
  0x11b56e8 was pretty quick last time, waiting for them.
  [Nov 22 13:52:27] DEBUG[27577][C-00000007] audiohook.c: Write factory
  0x11b56e8 was pretty quick last time, waiting for them.
  [Nov 22 13:52:27] DEBUG[27577][C-00000007] audiohook.c: Write factory
  0x11b56e8 was pretty quick last time, waiting for them.
  [Nov 22 13:52:27] DEBUG[27577][C-00000007] audiohook.c: Write factory
  0x11b56e8 was pretty quick last time, waiting for them.
  [Nov 22 13:52:27] DEBUG[27577][C-00000007] audiohook.c: Write factory
  0x11b56e8 was pretty quick last time, waiting for them.
  [Nov 22 13:52:27] DEBUG[27577][C-00000007] audiohook.c: Write factory
  0x11b56e8 was pretty quick last time, waiting for them.
  [Nov 22 13:52:27] DEBUG[27577][C-00000007] audiohook.c: Write factory
  0x11b56e8 was pretty quick last time, waiting for them.
  [Nov 22 13:52:27] DEBUG[27577][C-00000007] audiohook.c: Write factory
  0x11b56e8 was pretty quick last time, waiting for them.
  [Nov 22 13:52:27] DEBUG[27577][C-00000007] audiohook.c: Write factory
  0x11b56e8 was pretty quick last time, waiting for them.
  [Nov 22 13:52:27] DEBUG[27577][C-00000007] audiohook.c: Write factory
  0x11b56e8 was pretty quick last time, waiting for them.
  [Nov 22 13:52:27] DEBUG[27563][C-00000007] app_queue.c: There is 1
  available member.
  [Nov 22 13:52:27] DEBUG[27563][C-00000007] app_queue.c: It’s our turn
  (SIP/incoming-0000001c).
  [Nov 22 13:52:27] DEBUG[27563][C-00000007] app_queue.c:
  SIP/incoming-0000001c is trying to call a queue member.
  [Nov 22 13:52:27] DEBUG[27563][C-00000007] app_queue.c: (Parallel)
  Trying ‘Local/mysip467@CallFromQueue’ with metric 0
  [Nov 22 13:52:27] DEBUG[27563][C-00000007] app_queue.c:
  Local/mysip467@CallFromQueue has another call trying, can’t receive call
  [Nov 22 13:52:27] DEBUG[27563][C-00000007] app_queue.c: (Parallel)
  Trying ‘Local/mysip517@CallFromQueue’ with metric 0
  [Nov 22 13:52:27] DEBUG[27563][C-00000007] app_queue.c:
  Local/mysip517@CallFromQueue has another call trying, can’t receive call
  [Nov 22 13:52:27] DEBUG[27563][C-00000007] app_queue.c: (Parallel)
  Trying ‘Local/mysip440@CallFromQueue’ with metric 0
  [Nov 22 13:52:27] DEBUG[27563][C-00000007] app_queue.c:
  Local/mysip440@CallFromQueue has another call trying, can’t receive call
  [Nov 22 13:52:27] DEBUG[27563][C-00000007] app_queue.c: Nobody left to try ringing in queue
  [Nov 22 13:52:27] DEBUG[27563][C-00000007] app_queue.c: Everyone is busy at this time
  [Nov 22 13:52:27] DEBUG[27563][C-00000007] res_config_mysql.c: MySQL
  RealTime: Connection okay.
  [Nov 22 13:52:27] DEBUG[27563][C-00000007] res_config_mysql.c: MySQL
  RealTime: Retrieve SQL: SELECT * FROM queue_members WHERE interface LIKE
  ‘%’ AND queue_name = ‘myqueue1’ ORDER BY interface
  [Nov 22 13:52:27] DEBUG[27577][C-00000007] audiohook.c: Write factory
  0x11b56e8 was pretty quick last time, waiting for them.
  [Nov 22 13:52:27] DEBUG[27577][C-00000007] audiohook.c: Write factory
  0x11b56e8 was pretty quick last time, waiting for them.
  [Nov 22 13:52:27] DEBUG[27577][C-00000007] audiohook.c: Write factory
  0x11b56e8 was pretty quick last time, waiting for them.
  [Nov 22 13:52:27] DEBUG[27577][C-00000007] audiohook.c: Write factory
  0x11b56e8 was pretty quick last time, waiting for them.
  …

  Should a file a bug report on the tracker ??

  Kind regards

  J.