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

Thu Aug 13 08:50:38 CDT 2009

A NOTE has been added to this issue. 
====================================================================== 
https://issues.asterisk.org/view.php?id=15609 
====================================================================== 
Reported By:                aragon
Assigned To:                
====================================================================== 
Project:                    Asterisk
Issue ID:                   15609
Category:                   Core/Channels
Reproducibility:            have not tried
Severity:                   minor
Priority:                   normal
Status:                     acknowledged
Asterisk Version:           SVN 
Regression:                 No 
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-08-13 08:50 CDT
====================================================================== 
Summary:                    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)
=== -------------------------------------------------------------------

====================================================================== 

---------------------------------------------------------------------- 
 (0108999) aragon (reporter) - 2009-08-13 08:50
 https://issues.asterisk.org/view.php?id=15609#c108999 
---------------------------------------------------------------------- 
I turned off locks.
Here is some CLI with debug enabled and I will try to get a text file
uploaded with core show locks and simultaneous gdb output when there is an
autoservice lock within the hour.

[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] DEBUG[15758]: app_queue.c:2448 is_our_turn: There are 0
available members.
[Aug 13 09:47:28] DEBUG[15758]: app_queue.c:2466 is_our_turn: It's not our
turn (SIP/siptrunk-088e7130).
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] DEBUG[15754]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3144, ms is 413
[Aug 13 09:47:28] DEBUG[15811]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3176, ms is 417
[Aug 13 09:47:28] DEBUG[15636]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3160, ms is 415
[Aug 13 09:47:28] DEBUG[15479]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3200, ms is 420
[Aug 13 09:47:28] DEBUG[15903]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3184, ms is 418
[Aug 13 09:47:28] DEBUG[15651]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3208, ms is 421
[Aug 13 09:47:28] DEBUG[15641]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3192, ms is 419
[Aug 13 09:47:28] DEBUG[15636]: app_queue.c:2448 is_our_turn: There are 0
available members.
[Aug 13 09:47:28] DEBUG[15636]: app_queue.c:2466 is_our_turn: It's not our
turn (SIP/siptrunk-0889bd18).
[Aug 13 09:47:28] DEBUG[15764]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3200, ms is 420
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] DEBUG[15902]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3216, ms is 422
[Aug 13 09:47:28] DEBUG[15899]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3248, ms is 426
[Aug 13 09:47:28] DEBUG[15492]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3224, ms is 423
[Aug 13 09:47:28] DEBUG[15696]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3256, ms is 427
[Aug 13 09:47:28] DEBUG[15901]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3256, ms is 427
[Aug 13 09:47:28] DEBUG[15645]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3256, ms is 427
[Aug 13 09:47:28] DEBUG[15900]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3272, ms is 429
[Aug 13 09:47:28] DEBUG[15759]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3280, ms is 430
[Aug 13 09:47:28] DEBUG[15484]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3296, ms is 432
[Aug 13 09:47:28] DEBUG[15642]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3296, ms is 432
[Aug 13 09:47:28] DEBUG[15657]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3328, ms is 436
[Aug 13 09:47:28] DEBUG[15758]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3320, ms is 435
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] DEBUG[15653]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3328, ms is 436
[Aug 13 09:47:28] DEBUG[15766]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3352, ms is 439
[Aug 13 09:47:28] DEBUG[15752]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3384, ms is 443
[Aug 13 09:47:28] DEBUG[15698]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3384, ms is 443
[Aug 13 09:47:28] DEBUG[15904]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3416, ms is 447
[Aug 13 09:47:28] DEBUG[15760]: rtp.c:2712 ast_rtp_raw_write: Difference
is 3440, ms is 450
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] DEBUG[15408]: rtp.c:923 ast_rtcp_read: Got RTCP report
of 64 bytes
fireworx*CLI> core show locks
fireworx*CLI>
=======================================================================
=== Currently Held Locks ==============================================
=======================================================================
===
=== <file> <line num> <function> <lock name> <lock addr> (times locked)
===
=== Thread ID: 3051977616 (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 0x819d4e8 (1)
=== --- ---> Locked Here: autoservice.c line 89 (autoservice_run)
=== -------------------------------------------------------------------
===
=======================================================================

[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] DEBUG[15492]: app_queue.c:2448 is_our_turn: There are 0
available members.
[Aug 13 09:47:28] DEBUG[15492]: app_queue.c:2466 is_our_turn: It's not our
turn (SIP/siptrunk-089cdf50).
[Aug 13 09:47:28] WARNING[15052]: channel.c:951 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1610 at default-agent-2b17,1
[Aug 13 09:47:28] DEBUG[15904]: app_queue.c:2448 is_our_turn: There are 0
available members.
[Aug 13 09:47:28] DEBUG[15904]: app_queue.c:2466 is_our_turn: It's not our
turn (SIP/siptrunk-b5d6eba8).
[Aug 13 09:47:28] DEBUG[15903]: app_queue.c:2448 is_our_turn: There are 0
available members.
[Aug 13 09:47:28] DEBUG[15903]: app_queue.c:2466 is_our_turn: It's not our
turn (SIP/siptrunk-b5d67300). 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2009-08-13 08:50 aragon         Note Added: 0108999                          
======================================================================