[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-09 15:20 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...
====================================================================== 

---------------------------------------------------------------------- 
 (0115003) aragon (reporter) - 2009-12-09 15:20
 https://issues.asterisk.org/view.php?id=15609#c115003 
---------------------------------------------------------------------- 
warnings appear if there is corruption in mysql cdr table.
warnings disappear if we do mysqlcheck -A -r to repair the cdr table.
jvandal added mysqlcheck -A -r to crond at 2 minutes after the hour which
explains warnings I mentioned in previous post.
So now I have a method to reproduce the warnings by manually running
mysqlcheck -A -r

Here is what I know now:
Manually invoking mysqlcheck -A -r will spike the CPU and create massive
warnings. Also SIP peers become unreachable due to qualify delays.
That could be a result of the high CPU or some locking (I don't know which
if either).
Normal CPU load is 2.0 (busy test system processing approx 15 cps).
during scopserv.cdr optimization CPU climbs to 3.9
during scopserv-ivr optimization CPU climbs to 7
during other database optimizations CPU is normal and no warnings.

I can't read source code etc... but if certain Asterisk revisions are
reverted we don't have any problems.  So the question now is how can a
database optimization of some cdr and ivr data tables freeze up app_queue
with these warnings and cause qualify timeouts?
If the cdr database was corrupt then the warnings occurred during hangups
and that is when we try to write to cdr.  I could also reproduce on a
corrupt cdr database with database show.
So what is the relationship between the cdr data and ast_carefulwrite and
ast_frisolate? 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2009-12-09 15:20 aragon         Note Added: 0115003                          
======================================================================