[asterisk-bugs] [Asterisk 0017521]: Brief lagginess on IAX2 channels is fatal

Asterisk Bug Tracker noreply at bugs.digium.com
Mon Jul 5 14:53:47 CDT 2010 

A NOTE has been added to this issue. 
====================================================================== 
https://issues.asterisk.org/view.php?id=17521 
====================================================================== 
Reported By:                jcovert
Assigned To:                
====================================================================== 
Project:                    Asterisk
Issue ID:                   17521
Category:                   Channels/chan_iax2
Reproducibility:            always
Severity:                   major
Priority:                   normal
Status:                     acknowledged
Asterisk Version:           1.6.2.8 
JIRA:                       SWP-1718 
Regression:                 No 
Reviewboard Link:            
SVN Branch (only for SVN checkouts, not tarball releases): N/A 
SVN Revision (number only!):  
Request Review:              
====================================================================== 
Date Submitted:             2010-06-17 10:32 CDT
Last Modified:              2010-07-05 14:53 CDT
====================================================================== 
Summary:                    Brief lagginess on IAX2 channels is fatal
Description: 
The problem reported in issue https://issues.asterisk.org/view.php?id=15609 and
https://issues.asterisk.org/view.php?id=15900 continues:

[Jun 17 09:55:14] WARNING[15579]: channel.c:1044 __ast_queue_frame:
Exceptionally long voice queue length queuing to IAX2/x38-9660
[Jun 17 09:57:54] WARNING[15579]: channel.c:1044 __ast_queue_frame:
Exceptionally long voice queue length queuing to IAX2/x38-9660
[Jun 17 09:57:54] WARNING[15579]: channel.c:1044 __ast_queue_frame:
Exceptionally long voice queue length queuing to IAX2/x38-9660
[Jun 17 09:58:07] NOTICE[15579]: chan_iax2.c:11447 __iax2_poke_noanswer:
Peer 'x29' is now UNREACHABLE! Time: 2
[Jun 17 09:58:07] NOTICE[15579]: chan_iax2.c:11447 __iax2_poke_noanswer:
Peer 'jrclaptop' is now UNREACHABLE! Time: 4
[Jun 17 09:58:07] NOTICE[15579]: chan_iax2.c:11447 __iax2_poke_noanswer:
Peer 'x38' is now UNREACHABLE! Time: 136
[Jun 17 09:58:10] WARNING[15579]: channel.c:1044 __ast_queue_frame:
Exceptionally long voice queue length queuing to IAX2/x38-9660
[Jun 17 09:58:10] WARNING[15579]: channel.c:1044 __ast_queue_frame:
Exceptionally long voice queue length queuing to IAX2/x38-9660
[Jun 17 09:58:10] WARNING[15579]: channel.c:1044 __ast_queue_frame:
Exceptionally long voice queue length queuing to IAX2/x38-9660
    -- Hungup 'IAX2/x38-9660'
  == Spawn extension (dialstation, 38, 1) exited non-zero on
'SIP/x28-0000048b'
[Jun 17 09:58:12] NOTICE[15579]: chan_iax2.c:10418 socket_process: Peer
'x29' is now REACHABLE! Time: 2
[Jun 17 09:58:12] NOTICE[15579]: chan_iax2.c:10418 socket_process: Peer
'jrclaptop' is now REACHABLE! Time: 4
[Jun 17 09:58:12] NOTICE[15579]: chan_iax2.c:10418 socket_process: Peer
'x38' is now REACHABLE! Time: 137

This tends to reproduce for me only on transatlantic calls.

/john

======================================================================
Relationships       ID      Summary
----------------------------------------------------------------------
related to          0015609 [patch] WARNING[23025]: channel.c:952 _...
related to          0015900 Console flood & CPU load 100% when ...
====================================================================== 

---------------------------------------------------------------------- 
 (0124234) jcovert (reporter) - 2010-07-05 14:53
 https://issues.asterisk.org/view.php?id=17521#c124234 
---------------------------------------------------------------------- 
I am beginning to think this is a performance problem in queue handling
which is more likely to affect a machine with a slower processor.

I did not have qite the same the problem when I was running
asterisk-1.6.0.3.

I have two PowerPC laptops with Asterisk.  My main PBX runs on a 550 MHz
original Titanium.  I also run asterisk on another Alumninum Powerbook
(1.33 GHz).  Both are running identical kernels, and both are now running
1.6.2.9.

The faster machine does not have this problem at all.

I downgraded the slower machine to 1.6.0.3 and no longer see the queue
length messages.  Instead, what I see on 1.6.0.3 is:

[Jul  5 15:46:25] WARNING[11634]: chan_iax2.c:2365 __attempt_transmit: Max
retries exceeded to host 64.25.152.29 on IAX2/64.25.152.29:4569-1092 (type
= 6, subclass = 11, ts=20012, seqno=6)
[Jul  5 15:46:25] WARNING[11634]: chan_iax2.c:2365 __attempt_transmit: Max
retries exceeded to host 64.25.152.29 on IAX2/64.25.152.29:4569-1092 (type
= 6, subclass = 2, ts=21008, seqno=7)
[Jul  5 15:46:25] WARNING[11634]: chan_iax2.c:2365 __attempt_transmit: Max
retries exceeded to host 64.25.152.29 on IAX2/64.25.152.29:4569-1092 (type
= 6, subclass = 11, ts=30017, seqno=8)
[Jul  5 15:46:25] WARNING[11634]: chan_iax2.c:2365 __attempt_transmit: Max
retries exceeded to host 64.25.152.29 on IAX2/64.25.152.29:4569-1092 (type
= 6, subclass = 11, ts=40022, seqno=9)
[Jul  5 15:46:25] WARNING[11634]: chan_iax2.c:2365 __attempt_transmit: Max
retries exceeded to host 64.25.152.29 on IAX2/64.25.152.29:4569-1092 (type
= 6, subclass = 2, ts=42012, seqno=10)
[Jul  5 15:46:25] WARNING[11634]: chan_iax2.c:2365 __attempt_transmit: Max
retries exceeded to host 64.25.152.29 on IAX2/64.25.152.29:4569-1092 (type
= 6, subclass = 12, ts=10005, seqno=11)
[Jul  5 15:46:25] WARNING[11634]: chan_iax2.c:2365 __attempt_transmit: Max
retries exceeded to host 64.25.152.29 on IAX2/64.25.152.29:4569-1092 (type
= 6, subclass = 12, ts=20004, seqno=12)

The following may or may not be related.  I see it on the slower machine
but not on the faster one.

asterisk*CLI> iax2 reload
[Jul  5 15:22:13] WARNING[9559]: utils.c:1536 __ast_string_field_init:
trying to reset empty pool
[Jul  5 15:22:13] WARNING[9559]: utils.c:1536 __ast_string_field_init:
trying to reset empty pool
[Jul  5 15:22:13] WARNING[9559]: utils.c:1536 __ast_string_field_init:
trying to reset empty pool
[Jul  5 15:22:13] WARNING[9559]: chan_iax2.c:12087 build_peer: Set
peer->pokefreqnotok to 200
[Jul  5 15:22:13] WARNING[9559]: utils.c:1536 __ast_string_field_init:
trying to reset empty pool
[Jul  5 15:22:13] WARNING[9559]: chan_iax2.c:12087 build_peer: Set
peer->pokefreqnotok to 5000
[Jul  5 15:22:13] WARNING[9559]: utils.c:1536 __ast_string_field_init:
trying to reset empty pool
[Jul  5 15:22:13] WARNING[9559]: chan_iax2.c:12087 build_peer: Set
peer->pokefreqnotok to 5000
[Jul  5 15:22:13] WARNING[9559]: utils.c:1536 __ast_string_field_init:
trying to reset empty pool
[Jul  5 15:22:13] WARNING[9559]: chan_iax2.c:12087 build_peer: Set
peer->pokefreqnotok to 5000
[Jul  5 15:22:13] WARNING[9559]: utils.c:1536 __ast_string_field_init:
trying to reset empty pool
[Jul  5 15:22:13] WARNING[9559]: utils.c:1536 __ast_string_field_init:
trying to reset empty pool 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2010-07-05 14:53 jcovert        Note Added: 0124234                          
======================================================================

More information about the asterisk-bugs mailing list