[asterisk-bugs] [Asterisk 0017625]: "I should never be called!" message printed from channels/chan_iax2.c

Tue Jul 13 03:41:24 CDT 2010

A NOTE has been added to this issue. 
====================================================================== 
https://issues.asterisk.org/view.php?id=17625 
====================================================================== 
Reported By:                vieri
Assigned To:                
====================================================================== 
Project:                    Asterisk
Issue ID:                   17625
Category:                   Channels/chan_iax2
Reproducibility:            sometimes
Severity:                   major
Priority:                   normal
Status:                     feedback
Asterisk Version:           1.4.31 
JIRA:                        
Regression:                 No 
Reviewboard Link:            
SVN Branch (only for SVN checkouts, not tarball releases): N/A 
SVN Revision (number only!):  
Request Review:              
====================================================================== 
Date Submitted:             2010-07-12 04:21 CDT
Last Modified:              2010-07-13 03:41 CDT
====================================================================== 
Summary:                    "I should never be called!" message printed from
channels/chan_iax2.c
Description: 
Hi,

Recently, one of my Asterisk servers stopped connecting calls and required
a reboot to "fix it" (did not try to restart or reload).

The log showed loads of this message:

NOTICE[302] chan_iax2.c: I should never be called!

This highly repeated message seems to be preceded by something like:

WARNING[10767] channel.c: Exceptionally long voice queue length queuing to
IAX2/coinbound-15879

When this happens it also seems that SIP peers on a gigabit LAN start
going on/offline frequently. So that seems to explain why calls start to
fail. There is absolutely nothing wrong with the network (and switches). I
don't know if it can be a NIC problem on the server but it's strange
because I have SIP peers on different local subnets connected to different
NICs and switches. It would be a terrific coincidence that all 3 NICs I
have on the server failed as well as the 3 switches... The fact that all
went back to normal after rebooting the Asterisk server led me to file a
bug report.

I'd like to know in what circumstances chan_iax2 can log the "I should
never be called!" message in 1.4.31.

When that happens I usually have a lot of messages such as:

NOTICE[10756] chan_sip.c: Peer '7054' is now Lagged. (2819ms / 2000ms)
NOTICE[10756] chan_sip.c: Peer '7054' is now Reachable. (860ms / 2000ms)
NOTICE[10756] chan_sip.c: Peer '7054' is now Lagged. (2003ms / 2000ms)
NOTICE[10756] chan_sip.c: Peer '7054' is now UNREACHABLE!  Last qualify:
3096
NOTICE[10756] chan_sip.c: Peer '7054' is now Lagged. (2131ms / 2000ms)

Any ideas as to what may be happening and what I should do the next time
it does?

Thanks,

Vieri
======================================================================
Relationships       ID      Summary
----------------------------------------------------------------------
related to          0017521 Brief lagginess on IAX2 channels is fatal
====================================================================== 

---------------------------------------------------------------------- 
 (0124527) vieri (reporter) - 2010-07-13 03:41
 https://issues.asterisk.org/view.php?id=17625#c124527 
---------------------------------------------------------------------- 
For now, I can only post console output leading to this message. If it
happens again, I hope I can post more info.

This is what happened on July 9th at 07:09 am: 

a call came in through an ISDN line (via Digium, Inc. Wildcard B410
quad-BRI card (rev 01)) to an Asterisk 1.4.31 server.
The call was automatically sent to another Asterisk 1.4.31 box (the
"failing" server reported here) over a IAX2 trunk (IAX2/coinbound) on a
gigabit LAN.
This box then dialed an external extension via a PRI link (g1/7060 below).
This was the first time the "I should never be called!" message came up (it
then happened over and over for more than 1 hour, accompanied by the
"lagged" messages until someone eventually rebooted the server because
people were noticing long delays in their conversations and some peers
started to be unreachable).

In this case, Zap/1-1 actually managed to answer IAX2/coinbound so the
call was established.

[Jul  9 07:09:44] VERBOSE[19371] logger.c:     -- Called g1/7060
[Jul  9 07:09:44] VERBOSE[19371] logger.c:     -- Zap/1-1 is proceeding
passing it to IAX2/coinbound-16087
[Jul  9 07:09:44] WARNING[10761] channel.c: Exceptionally long voice queue
length queuing to IAX2/coinbound-16087
[Jul  9 07:09:44] VERBOSE[19371] logger.c:     -- Zap/1-1 is ringing
[Jul  9 07:09:44] VERBOSE[19371] logger.c:     -- IAX2/coinbound-16087
requested special control 20, passing it to Zap/1-1
[Jul  9 07:09:44] VERBOSE[19371] logger.c:     -- IAX2/coinbound-16087
requested special control 20, passing it to Zap/1-1
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] NOTICE[19371] chan_iax2.c: I should never be called!
[Jul  9 07:09:44] VERBOSE[19371] logger.c:     -- IAX2/coinbound-16087
requested special control 20, passing it to Zap/1-1
[Jul  9 07:09:44] VERBOSE[19371] logger.c:     -- IAX2/coinbound-16087
requested special control 20, passing it to Zap/1-1
[Jul  9 07:09:50] DEBUG[10775] chan_dahdi.c: Echo cancellation already on
[Jul  9 07:09:50] VERBOSE[19371] logger.c:     -- Zap/1-1 answered
IAX2/coinbound-16087

By the way, Asterisk 1.4.31 was compiled with "DONT_OPTIMIZE
DEBUG_CHANNEL_LOCKS DEBUG_THREADS MALLOC_DEBUG DEBUG_FD_LEAKS". 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2010-07-13 03:41 vieri          Note Added: 0124527                          
======================================================================