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

Asterisk Bug Tracker noreply at bugs.digium.com
Tue Dec 22 14:17:26 CST 2009 

A NOTE has been added to this issue. 
====================================================================== 
https://issues.asterisk.org/view.php?id=15609 
====================================================================== 
Reported By:                aragon
Assigned To:                tilghman
====================================================================== 
Project:                    Asterisk
Issue ID:                   15609
Category:                   Core/Channels
Reproducibility:            have not tried
Severity:                   block
Priority:                   normal
Status:                     assigned
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-22 14:17 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...
====================================================================== 

---------------------------------------------------------------------- 
 (0115675) aragon (reporter) - 2009-12-22 14:17
 https://issues.asterisk.org/view.php?id=15609#c115675 
---------------------------------------------------------------------- 
tilghman: I ran under Valgrind for a few minutes and almost immediately got
the warnings.  They have moved from hangup to when we execute into the acd
queue.

 -- Executing [5000 at customer-siptrunk-incoming:21]
GotoIf("SIP/siptrunk-00000007", "0?22:24") in new stack
  == Parsing '/etc/asterisk/manager.conf': Found
    -- Goto (customer-siptrunk-incoming,5000,24)
    -- Executing [5000 at customer-siptrunk-incoming:24]
Set("SIP/siptrunk-00000007", "__INCOMINGLINE=1") in new stack
    -- Executing [5000 at customer-siptrunk-incoming:4]
Set("SIP/siptrunk-00000008", "CHANNEL(musicclass)=default") in new stack
    -- Executing [5000 at customer-siptrunk-incoming:25]
GotoIf("SIP/siptrunk-00000007", "0?26:27") in new stack
    -- Executing [5000 at customer-siptrunk-incoming:5]
NoOp("SIP/siptrunk-00000008", ""INCOMING CALL FROM CALLER ID: 1027
(1027)"") in new stack
    -- Executing [5000 at customer-siptrunk-incoming:6]
Set("SIP/siptrunk-00000008", "__INCOMING_DNIS=5000") in new stack
  == Parsing '/etc/asterisk/manager.conf': Found
    -- Goto (customer-siptrunk-incoming,5000,27)
    -- Executing [5000 at customer-siptrunk-incoming:27]
GotoIf("SIP/siptrunk-00000007", "0?28:29") in new stack
    -- Executing [5000 at customer-siptrunk-incoming:7]
Set("SIP/siptrunk-00000008", "CALLERID(dnid)=5000") in new stack
    -- Goto (customer-siptrunk-incoming,5000,29)
    -- Executing [5000 at customer-siptrunk-incoming:29]
GotoIf("SIP/siptrunk-00000007", "0?30:31") in new stack
[Dec 22 14:57:19] ERROR[23231]: utils.c:966 ast_carefulwrite: write()
returned error: Broken pipe
    -- Executing [5000 at customer-siptrunk-incoming:8]
Set("SIP/siptrunk-00000008", "CDR(userfield)=5000") in new stack
    -- Goto (customer-siptrunk-incoming,5000,31)
    -- Executing [5000 at customer-siptrunk-incoming:31]
GotoIf("SIP/siptrunk-00000007", "0?32:33") in new stack
    -- Executing [5000 at customer-siptrunk-incoming:9]
Goto("SIP/siptrunk-00000008", "20") in new stack
    -- Goto (customer-siptrunk-incoming,5000,33)
    -- Executing [5000 at customer-siptrunk-incoming:33]
Set("SIP/siptrunk-00000007", "CHANNEL(language)=en") in new stack
    -- Goto (customer-siptrunk-incoming,5000,20)
    -- Executing [5000 at customer-siptrunk-incoming:20]
AGI("SIP/siptrunk-00000008",
"/var/www/scopserv/telephony/scripts/agi/fixcidname.php") in new stack
  == Parsing '/etc/asterisk/manager.conf': Found
    -- Executing [5000 at customer-siptrunk-incoming:34]
Set("SIP/siptrunk-00000007", "QUEUE_PRIO=0") in new stack
    -- Executing [5000 at customer-siptrunk-incoming:35]
Gosub("SIP/siptrunk-00000007",
"default-application-acd-queues-new-english|s|1") in new stack
[Dec 22 14:57:21] ERROR[23234]: utils.c:966 ast_carefulwrite: write()
returned error: Broken pipe
    -- Executing [s at default-application-acd-queues-new-english:1]
Set("SIP/siptrunk-00000007", "AUDIOHOOK_INHERIT(MixMonitor)=yes") in new
stack
  == Parsing '/etc/asterisk/manager.conf':     -- Launched AGI Script
/var/www/scopserv/telephony/scripts/agi/fixcidname.php
    -- Executing [s at default-application-acd-queues-new-english:2]
NoOp("SIP/siptrunk-00000007", ""=== START QUEUE
(default-queues-new-english) ==="") in new stack
Found
  == Parsing '/etc/asterisk/manager.conf':   == Parsing
'/etc/asterisk/manager.conf': Found
Found
    -- Executing [s at default-application-acd-queues-new-english:3]
Set("SIP/siptrunk-00000007", "__QUEUENAME=default-queues-new-english") in
new stack
Really destroying SIP dialog
'3618b2963c524fc64ccf79b6729c4c93 at 192.168.30.165' Method: OPTIONS
Really destroying SIP dialog
'3b4740201d56bbc868121ef21568d466 at 192.168.30.165' Method: OPTIONS
[Dec 22 14:57:24] WARNING[22889]: channel.c:954 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1609 at default-agent-2b0b,1
[Dec 22 14:57:24] WARNING[22889]: channel.c:954 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1609 at default-agent-2b0b,1
[Dec 22 14:57:24] WARNING[22889]: channel.c:954 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1609 at default-agent-2b0b,1
[Dec 22 14:57:24] WARNING[22889]: channel.c:954 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1609 at default-agent-2b0b,1
[Dec 22 14:57:24] WARNING[22889]: channel.c:954 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1609 at default-agent-2b0b,1
[Dec 22 14:57:24] WARNING[22889]: channel.c:954 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1609 at default-agent-2b0b,1
[Dec 22 14:57:24] WARNING[22889]: channel.c:954 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1609 at default-agent-2b0b,1
[Dec 22 14:57:24] WARNING[22889]: channel.c:954 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1609 at default-agent-2b0b,1
[Dec 22 14:57:24] WARNING[22889]: channel.c:954 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1609 at default-agent-2b0b,1
[Dec 22 14:57:24] WARNING[22889]: channel.c:954 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1609 at default-agent-2b0b,1
[Dec 22 14:57:24] WARNING[22889]: channel.c:954 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1609 at default-agent-2b0b,1
[Dec 22 14:57:24] WARNING[22889]: channel.c:954 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1609 at default-agent-2b0b,1
[Dec 22 14:57:24] WARNING[22889]: channel.c:954 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1609 at default-agent-2b0b,1
[Dec 22 14:57:24] WARNING[22889]: channel.c:954 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1609 at default-agent-2b0b,1
[Dec 22 14:57:24] WARNING[22889]: channel.c:954 __ast_queue_frame:
Exceptionally long voice queue length queuing to
Local/1609 at default-agent-2b0b,1
[Dec 22 14:57:24] WARNING[22889]: channel.c:954 __ast_queue_frame: Really
destroying SIP dialog '0ed6424822a86f7a5f52c5826bca5316 at 192.168.30.165'
Method: OPTIONS
Exceptionally long voice queue length queuing to
Local/1609 at default-agent-2b0b,1
Really destroying SIP dialog
'1ccc3d0a11832a280f62a2ef708bdf49 at 192.168.30.165' Method: OPTIONS
Really destroying SIP dialog
'1fef18144edb808a420b622b19e54031 at 192.168.30.165' Method: OPTIONS
Really destroying SIP dialog
'5350a10157e2fcf914f6df1305a90789 at 192.168.30.165' Method: OPTIONS
Really destroying SIP dialog
'17f9a54b1764839305372b0f4d8e9464 at 192.168.30.165' Method: OPTIONS
Really destroying SIP dialog
'110823d747584bb809e1d76e31977351 at 192.168.30.165' Method: OPTIONS
Really destroying SIP dialog
'5dbc4e6626b1711b26c5aeb50c1dce47 at 192.168.30.165' Method: OPTIONS
Really destroying SIP dialog
'58b4c0725d26934602124c6f0114a4dc at 192.168.30.165' Method: OPTIONS
Really destroying SIP dialog
'0fd17fd07bc174c86814ddab7e14e8fb at 192.168.30.165' Method: OPTIONS
Really destroying SIP dialog
'6a91b07703d7cdff179f43f46c924b44 at 192.168.30.165' Method: OPTIONS
Really destroying SIP dialog
'08f276a25ee8fbcd7b3d56a662378b48 at 192.168.30.165' Method: OPTIONS 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2009-12-22 14:17 aragon         Note Added: 0115675                          
======================================================================

More information about the asterisk-bugs mailing list