[asterisk-bugs] [Asterisk 0015609]: [patch] WARNING[23025]: channel.c:952 __ast_queue_frame: Exceptionally long voice queue length queuing to Local

[Asterisk Bug Tracker]

A NOTE has been added to this issue. 
====================================================================== 
https://issues.asterisk.org/view.php?id=15609 
====================================================================== 
Reported By:                aragon
Assigned To:                russell
====================================================================== 
Project:                    Asterisk
Issue ID:                   15609
Category:                   Core/Channels
Reproducibility:            have not tried
Severity:                   block
Priority:                   normal
Status:                     confirmed
Asterisk Version:           SVN 
JIRA:                       SWP-205 
Regression:                 No 
Reviewboard Link:            
SVN Branch (only for SVN checkouts, not tarball releases):  1.4  
SVN Revision (number only!): 206273 
Request Review:              
====================================================================== 
Date Submitted:             2009-07-29 09:26 CDT
Last Modified:              2009-12-08 14:25 CST
====================================================================== 
Summary:                    [patch] WARNING[23025]: channel.c:952
__ast_queue_frame: Exceptionally long voice queue length queuing to Local
Description: 
Since upgrading to 1.4 SVN 206273 I see LOTS these errors when paging or
when calls are processed by app_queue.  When I see the messages during a
page I don't hear any paging (my Polycom phones continue to ring but no
paging audio).

I have no idea where the message is coming from how to reproduce, or
collect debug information for this specific issue.  I need help to find
root cause.
I think it could be caused by locking in autoservice since I see this lock
every time I see the warning message

=== Currently Held Locks ==============================================
=======================================================================
===
=== <file> <line num> <function> <lock name> <lock addr> (times locked)
===
=== Thread ID: 3057154960 (autoservice_run      started at [  238]
autoservice.c ast_autoservice_start())
=== ---> Waiting for Lock https://issues.asterisk.org/view.php?id=0
(autoservice.c): MUTEX 89 autoservice_run
&(&aslist)->lock 0x81798c8 (1)
=== --- ---> Locked Here: autoservice.c line 89 (autoservice_run)
=== -------------------------------------------------------------------


======================================================================
Relationships       ID      Summary
----------------------------------------------------------------------
duplicate of        0015976 abort in filestream_destructor / ast_fi...
related to          0015109 [patch] Abort by memory allocator, poss...
has duplicate       0015900 Console flood &amp; CPU load 100% when ...
has duplicate       0016096 Exceptionally long voice queue length q...
related to          0015817 crash in local_attended_transfer, likel...
related to          0015845 Crash during attended transfer occurs
related to          0015616 random crashes
related to          0016229 ERROR[24164]: utils.c:966 ast_carefulwr...
related to          0016081 [patch] utils.c:938 ast_carefulwrite: T...
====================================================================== 

---------------------------------------------------------------------- 
 (0114948) aragon (reporter) - 2009-12-08 14:25
 https://issues.asterisk.org/view.php?id=15609#c114948 
---------------------------------------------------------------------- 
Hmmm,
I am getting the warning at 2 minutes after the hour each hour with some
exceptions.
/var/log/asterisk/messages
I get this message
[Dec  7 20:38:06] WARNING[21383] app_queue.c: The device state of this
queue member, Local/1609 at default-agent/n, is still 'Not in Use' when it
probably should not be! Please check UPGRADE.txt for correct configuration
settings.

Then later at 2 minutes after the hour...
Dec  7 21:02:26] WARNING[30286] channel.c: Exceptionally long voice queue
length queuing to Local/1609 at default-agent-2ccf,1
Which keeps spamming the CLI until
[Dec  7 21:02:41] WARNING[30286] channel.c: Exceptionally long voice queue
length queuing to Local/1609 at default-agent-2ccf,1

etc...

show queues
default-queue- has 6 calls (max unlimited) in 'rrmemory' strategy (47s
holdtime), W:0, C:1168, A:5502, SL:0.2% within 10s
   Members: >
      Local/1609 at default-agent/n (dynamic) (In use) has taken 1168 calls
(last was 127 secs ago)
   Callers:
      1. SIP/siptrunk-00001ebc (wait: 1:00, prio: 0)
      2. SIP/siptrunk-00001ebd (wait: 0:55, prio: 0)
      3. SIP/siptrunk-00001ebe (wait: 0:46, prio: 0)
      4. SIP/siptrunk-00001ebf (wait: 0:37, prio: 0)
      5. SIP/siptrunk-00001ec0 (wait: 0:32, prio: 0)
      6. SIP/siptrunk-00001ec1 (wait: 0:09, prio: 0)


1609/1609                  192.168.30.146   D          5060     OK (151
ms)

So agent 1609 is the only logged agent and qualify = yes

Therefore only a logged in use agent appears to be affected by the
warning. And potentially this only happens when SIP extension re-registers
after 3600 second timeout.
I'm going to re-test this with qualify=no for ext 1609 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2009-12-08 14:25 aragon         Note Added: 0114948                          
======================================================================