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

Thu Dec 30 02:58:18 UTC 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-12-29 20:58 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...
====================================================================== 

---------------------------------------------------------------------- 
 (0130036) jcovert (reporter) - 2010-12-29 20:58
 https://issues.asterisk.org/view.php?id=17521#c130036 
---------------------------------------------------------------------- 
I have a solid reproducer on this now under 1.8.1.1

Everything is on the local LAN.

Device at x33 is a Cisco ATA186.

At the CLI, type:
asterisk*CLI> originate sip/x33 application dial
IAX2/guest at iax.covert.org/ringnoanswer

Answer the phone connected to the Cisco ATA186.

The Dial command executes, and terminates on the same machine at::

exten => ringnoanswer,1,Progress()
exten => ringnoanswer,n,Noop(${CALLERID(all)})
exten => ringnoanswer,n,Playtones(440+495/2000,0/4000)
exten => ringnoanswer,n,Wait(120) ; Implement a Ring-no-Answer
exten => ringnoanswer,n,Hangup

The following appears:

    -- Launching dial(IAX2/guest at iax.covert.org/ringnoanswer) on
SIP/x33-0000010e
    -- Called guest at iax.covert.org/ringnoanswer
    -- Accepting UNAUTHENTICATED call from 192.168.0.100:
       > requested format = ulaw,
       > requested prefs = (ulaw|alaw|g726|gsm),
       > actual format = ulaw,
       > host prefs = (ulaw|alaw|g726|gsm),
       > priority = caller
    -- Call accepted by 192.168.0.100 (format ulaw)
    -- Format for call is ulaw
    -- Executing [ringnoanswer at sip:1]
Progress("IAX2/192.168.0.100:4569-2400", "") in new stack
    -- Executing [ringnoanswer at sip:2] NoOp("IAX2/192.168.0.100:4569-2400",
""Cisco 33" <33>") in new stack
    -- Executing [ringnoanswer at sip:3]
PlayTones("IAX2/192.168.0.100:4569-2400", "440+495/2000,0/4000") in new
stack
    -- Executing [ringnoanswer at sip:4] Wait("IAX2/192.168.0.100:4569-2400",
"120") in new stack
    -- IAX2/192.168.0.100:4569-13524 is making progress passing it to
SIP/x33-0000010e
[Dec 29 21:43:35] WARNING[22843]: channel.c:1399 __ast_queue_frame:
Exceptionally long voice queue length queuing to
IAX2/192.168.0.100:4569-13524
    -- Hungup 'IAX2/192.168.0.100:4569-13524'
[Dec 29 21:43:51] WARNING[22843]: chan_iax2.c:1123 iax_error_output:
Information element length exceeds message size
[Dec 29 21:43:51] WARNING[22843]: chan_iax2.c:9901 socket_process:
Undecodable frame received from '192.168.0.4'
  == Spawn extension (sip, ringnoanswer, 4) exited non-zero on
'IAX2/192.168.0.100:4569-2400'
    -- Hungup 'IAX2/192.168.0.100:4569-2400'

Note that while all of this was going on, the rest of the IAX world was
getting screwed up.  Here's a remote IAX peer that was inactive, except for
ping/pokes:

[Dec 29 21:43:54] NOTICE[22843]: chan_iax2.c:11867 __iax2_poke_noanswer:
Peer 'x38' is now UNREACHABLE! Time: 234
[Dec 29 21:43:59] NOTICE[22843]: chan_iax2.c:10802 socket_process: Peer
'x38' is now REACHABLE! Time: 133

Now that I have this easy reproducer, how do we work on actually solving
this problem?  It would be great to restore credibility to the IAX
channel.

/john 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2010-12-29 20:58 jcovert        Note Added: 0130036                          
======================================================================