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

Tue Jan 18 22:25:09 CST 2011

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:              2011-01-18 22:25 CST
====================================================================== 
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 &amp; CPU load 100% when ...
related to          0017625 &quot;I should never be called!&quot; m...
related to          0018511 [patch] Asterisk hangs with no calls be...
====================================================================== 

---------------------------------------------------------------------- 
 (0130654) jcovert (reporter) - 2011-01-18 22:25
 https://issues.asterisk.org/view.php?id=17521#c130654 
---------------------------------------------------------------------- 
The problem persists in 1.8.2.1:

    -- Executing [c-14849601 at dialcnet:4] Dial("SIP/x37-00000010",
"IAX2/cnet-guest at franksmicro.dyndns.org/14849601,120") in new stack
    -- Called cnet-guest at franksmicro.dyndns.org/14849601
    -- Call accepted by 98.118.147.150 (format ulaw)
    -- Format for call is ulaw
    -- IAX2/98.118.147.150:4569-964 answered SIP/x37-00000010
[Jan 18 23:18:42] NOTICE[939]: chan_iax2.c:11870 __iax2_poke_noanswer:
Peer 'jsolathome' is now UNREACHABLE! Time: 36
[Jan 18 23:18:52] NOTICE[939]: chan_iax2.c:11870 __iax2_poke_noanswer:
Peer 'x38' is now UNREACHABLE! Time: 133
[Jan 18 23:19:02] NOTICE[939]: chan_iax2.c:11870 __iax2_poke_noanswer:
Peer 'jrclaptop' is now UNREACHABLE! Time: 69
[Jan 18 23:19:04] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:19:04] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:19:04] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
    -- Registered IAX2 'jsolathome' (AUTHENTICATED) at 75.9.135.199:4569
[Jan 18 23:19:12] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:19:21] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:19:21] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
    -- Registered IAX2 'x29' (AUTHENTICATED) at 192.168.0.17:4569
[Jan 18 23:19:23] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:19:23] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:19:23] WARNING[939]: chan_iax2.c:1123 iax_error_output:
Information element length exceeds message size
[Jan 18 23:19:23] WARNING[939]: chan_iax2.c:9904 socket_process:
Undecodable frame received from '79.240.198.57'
    -- Registered IAX2 'jrclaptop' (AUTHENTICATED) at 192.168.0.4:4569
[Jan 18 23:19:46] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:19:46] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:19:46] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:19:46] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:19:47] NOTICE[939]: chan_iax2.c:10805 socket_process: Peer
'x38' is now REACHABLE! Time: 496
[Jan 18 23:19:47] NOTICE[939]: chan_iax2.c:11870 __iax2_poke_noanswer:
Peer 'jrclaptop' is now UNREACHABLE! Time: 10
[Jan 18 23:19:58] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:19:58] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:19:58] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:19:58] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:20:10] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:20:10] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:20:10] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:20:10] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:20:10] NOTICE[939]: chan_iax2.c:10811 socket_process: Peer
'x29' is now TOO LAGGED (3910 ms)!
[Jan 18 23:20:10] NOTICE[939]: chan_iax2.c:10811 socket_process: Peer
'jsolathome' is now TOO LAGGED (2268 ms)!
[Jan 18 23:20:11] NOTICE[939]: chan_iax2.c:10805 socket_process: Peer
'x29' is now REACHABLE! Time: 526
[Jan 18 23:20:11] NOTICE[939]: chan_iax2.c:11870 __iax2_poke_noanswer:
Peer 'x38' is now UNREACHABLE! Time: 496
[Jan 18 23:20:12] NOTICE[939]: chan_iax2.c:10805 socket_process: Peer
'jrclaptop' is now REACHABLE! Time: 114
[Jan 18 23:20:12] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:20:15] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:20:15] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:20:16] NOTICE[939]: chan_iax2.c:10805 socket_process: Peer
'x38' is now REACHABLE! Time: 225
    -- Registered IAX2 'jsolathome' (AUTHENTICATED) at 75.9.135.199:4569
[Jan 18 23:20:22] NOTICE[939]: chan_iax2.c:11870 __iax2_poke_noanswer:
Peer 'jsolathome' is now UNREACHABLE! Time: 2268
[Jan 18 23:20:36] NOTICE[939]: chan_iax2.c:11870 __iax2_poke_noanswer:
Peer 'jrclaptop' is now UNREACHABLE! Time: 114
[Jan 18 23:20:39] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:20:39] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:20:39] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:20:39] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:20:40] NOTICE[939]: chan_iax2.c:11870 __iax2_poke_noanswer:
Peer 'x38' is now UNREACHABLE! Time: 225
[Jan 18 23:20:41] NOTICE[939]: chan_iax2.c:10805 socket_process: Peer
'jrclaptop' is now REACHABLE! Time: 6
[Jan 18 23:20:55] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:20:55] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:20:55] WARNING[939]: channel.c:1426 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/98.118.147.150:4569-964
[Jan 18 23:20:56] NOTICE[939]: chan_iax2.c:10805 socket_process: Peer
'x38' is now REACHABLE! Time: 742
    -- Hungup 'IAX2/98.118.147.150:4569-964'
  == Spawn extension (dialcnet, c-14849601, 4) exited non-zero on
'SIP/x37-00000010' 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2011-01-18 22:25 jcovert        Note Added: 0130654                          
======================================================================