[asterisk-bugs] [Asterisk 0015609]: 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:                
====================================================================== 
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-12 15:31 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)
=== -------------------------------------------------------------------


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

---------------------------------------------------------------------- 
 (0108973) aragon (reporter) - 2009-08-12 15:31
 https://issues.asterisk.org/view.php?id=15609#c108973 
---------------------------------------------------------------------- 
OK I enabled debug to console and this just spams the CLI so bad I cannot
issue any commands.
Same lines over and over ad nausem.

[Aug 12 16:21:47] DEBUG[19046]: channel.c:4998 __ast_channel_unlock:
::::==== Unlocking AST channel SIP/siptrunk-09fea1b8
[Aug 12 16:21:47] DEBUG[19046]: channel.c:5019 __ast_channel_unlock:
::::==== Channel SIP/siptrunk-09fea1b8 was unlocked
[Aug 12 16:21:47] DEBUG[19046]: channel.c:5077 __ast_channel_trylock:
====:::: Trying to lock AST channel SIP/siptrunk-09fea1b8
[Aug 12 16:21:47] DEBUG[19046]: channel.c:5088 __ast_channel_trylock:
:::=== Now have 1 locks (recursive)
[Aug 12 16:21:47] DEBUG[19046]: channel.c:5091 __ast_channel_trylock:
::::==== Channel SIP/siptrunk-09fea1b8 was locked

Every so often I see something a little different.

nlocking AST channel SIP/siptrunk-b4546790
[Aug 12 16:21:46] DEBUG[19705]: channel.c:5019 __ast_channel_unlock: [Aug
12 16:21:47] NOTICE[23647]: chan_sip.c:13163 handle_response_peerpoke: Peer
'1671' is now Reachable. (622ms / 2000ms)
[Aug 12 16:21:47] DEBUG[23647]: devicestate.c:302
ast_device_state_changed_literal: Notification of state change to be queued
on device/channel SIP/1671
[Aug 12 16:21:47] DEBUG[23647]: chan_sip.c:2258 __sip_ack: Stopping
retransmission on '0d26e45e50b8438a2f2f8f4a586cab75 at 192.168.30.165' of
Request 102: Match Found

[Aug 12 16:21:47] DEBUG[23647]: devicestate.c:302
ast_device_state_changed_literal: Notification of state change to be queued
on device/channel SIP/1616

[Aug 12 16:21:46] DEBUG[23647]: channel.c:5095 __ast_channel_trylock:
::::==== Channel SIP/siptrunk-b4504708 failed to lock. Not waiting
around...

[Aug 12 16:21:43] DEBUG[19730]: rtp.c:2712 ast_rtp_raw_write: Difference
is 1312, ms is 184 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2009-08-12 15:31 aragon         Note Added: 0108973                          
======================================================================