[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 15 15:43:14 CST 2009
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-15 15:43 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 & 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...
======================================================================
----------------------------------------------------------------------
(0115296) aragon (reporter) - 2009-12-15 15:43
https://issues.asterisk.org/view.php?id=15609#c115296
----------------------------------------------------------------------
Here is example debug output when I see ast_carefulwrite dialing into IVR
so I can bypass the queue for a quick test.
I believe the problem is in the background application.
-- Launched AGI Script /var/www/scopserv/telephony/scripts/agi/ivr.php
[Dec 15 16:36:03] NOTICE[26225]: utils.c:938 ast_carefulwrite: Timed out
trying to write
[Dec 15 16:36:03] NOTICE[26225]: utils.c:938 ast_carefulwrite: Timed out
trying to write
-- AGI Script /var/www/scopserv/telephony/scripts/agi/ivr.php
completed, returning 0
[Dec 15 16:36:06] WARNING[26225]: file.c:764 ast_readaudio_callback:
Failed to write frame
-- Executing [h at scm-aa-mainaa:1] Goto("Zap/11-1", "all-hangup|s|1") in
new stack
-- Goto (all-hangup,s,1)
-- Executing [s at all-hangup:1] GotoIf("Zap/11-1",
"0?all-faxnotify|s|1:2") in new stack
-- Goto (all-hangup,s,2)
-- Executing [s at all-hangup:2] ResetCDR("Zap/11-1", "w") in new stack
-- Executing [s at all-hangup:3] NoCDR("Zap/11-1", "") in new stack
-- Executing [s at all-hangup:4] System("Zap/11-1",
"/var/www/scopserv/telephony/scripts/billing/cdr.sh 1260912963.4643") in
new stack
Here is the debug output
[Dec 15 16:27:30] WARNING[17320] file.c: Failed to write frame
[Dec 15 16:27:30] DEBUG[17320] channel.c: Set channel Zap/17-1 to write
format ulaw
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Extension ÿ, priority 0 returned
normally even though call was hung up
[Dec 15 16:27:30] DEBUG[17320] channel.c: Soft-Hanging up channel
'Zap/17-1'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Launching 'Goto'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Expression result is '0'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Expression result is '2'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Launching 'GotoIf'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Launching 'ResetCDR'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is '"private"
<5555555555>'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is '5555555555'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is '4350'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is 'zap-incoming'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is 'Zap/17-1'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is '(null)'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is 'BackGround'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is 'custom/0002'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is '2009-12-15
16:27:26'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is '2009-12-15
16:27:26'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is '2009-12-15
16:27:30'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is '4'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is '4'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is 'ANSWERED'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is 'DOCUMENTATION'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is '_NONE_'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is
'1260912446.4587'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Function result is '4350'
[Dec 15 16:27:30] DEBUG[17320] cdr_addon_mysql.c: cdr_mysql: inserting a
CDR record.
[Dec 15 16:27:30] DEBUG[17320] cdr_addon_mysql.c: cdr_mysql: SQL command
as follows: INSERT INTO cdr_pre
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield)
VALUES ('2009-12-15 16:27:26','\"private\"
<5555555555>','5555555555','4350','zap-incoming',
'Zap/17-1','','BackGround','custom/0002',4,4,'ANSWERED',3,'_NONE_','1260912446.4587','4350')
[Dec 15 16:27:30] DEBUG[17320] cdr_radius.c: Unable to create RADIUS
record. CDR not recorded!
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Launching 'NoCDR'
[Dec 15 16:27:30] DEBUG[17320] pbx.c: Launching 'System'
Issue History
Date Modified Username Field Change
======================================================================
2009-12-15 15:43 aragon Note Added: 0115296
======================================================================
More information about the asterisk-bugs
mailing list