[Asterisk-bugs] [Asterisk 0010239]: chan_iax2 sometimes incorrectly destroys channel immediately after sending NEW and getting AUTHREQ
noreply at bugs.digium.com
noreply at bugs.digium.com
Sat Jul 21 10:41:50 CDT 2007
A NOTE has been added to this issue.
======================================================================
http://bugs.digium.com/view.php?id=10239
======================================================================
Reported By: stevedavies
Assigned To:
======================================================================
Project: Asterisk
Issue ID: 10239
Category: Channels/chan_iax2
Reproducibility: sometimes
Severity: minor
Priority: normal
Status: new
Asterisk Version: SVN
SVN Branch (only for SVN checkouts, not tarball releases): N/A
SVN Revision (number only!): 74812
Disclaimer on File?: N/A
Request Review:
======================================================================
Date Submitted: 07-19-2007 11:38 CDT
Last Modified: 07-21-2007 10:41 CDT
======================================================================
Summary: chan_iax2 sometimes incorrectly destroys channel
immediately after sending NEW and getting AUTHREQ
Description:
See this debug log.
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] Tx-Frame
Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] Timestamp:
00009ms SCall: 00093 DCall: 00000 [196.40.106.60:4569]
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] VERSION
: 2
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] CALLED
NUMBER : 0216736730
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] CODEC_PREFS
: (g729|ilbc|gsm|speex|alaw|ulaw)
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] -- Called
phonehome-1/0216736730
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] CALLING
NUMBER : 0741003202
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] CALLING
PRESNTN : 3
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] CALLING
TYPEOFN : 1
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] CALLING
TRANSIT : 0
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] CALLING
NAME :
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] LANGUAGE
: en
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] USERNAME
: voipconnect
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] FORMAT
: 8
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] CAPABILITY
: 1632014
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] ADSICPE
: 2
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] DATE TIME
: 2007-07-19 16:40:06
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06]
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] Rx-Frame
Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: AUTHREQ
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] Timestamp:
00010ms SCall: 00008 DCall: 00093 [196.40.106.60:4569]
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] AUTHMETHODS
: 2
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] CHALLENGE
: 227338768
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] USERNAME
: voipconnect
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06]
[Jul 19 16:40:06] DEBUG[4509] chan_iax2.c: Received packet 0, (6, 8)
[Jul 19 16:40:06] DEBUG[4509] chan_iax2.c: Cancelling transmission of
packet 0
[Jul 19 16:40:06] DEBUG[4509] chan_iax2.c: Really destroying 93, having
been acked on final message
[Jul 19 16:40:06] DEBUG[4509] chan_iax2.c: IAX subclass 8 received
[Jul 19 16:40:06] DEBUG[4509] devicestate.c: Changing state for
IAX2/phonehome-1 - state 6 (Ringing)
[Jul 19 16:40:06] DEBUG[4509] chan_iax2.c: For call=93, set last=10
[Jul 19 16:40:06] DEBUG[4509] channel.c: Hanging up channel
'IAX2/phonehome-1-93'
[Jul 19 16:40:06] DEBUG[4509] chan_iax2.c: We're hanging up
IAX2/phonehome-1-93 now...
[Jul 19 16:40:06] DEBUG[4509] chan_iax2.c: Really destroying
IAX2/phonehome-1-93 now...
[Jul 19 16:40:06] VERBOSE[4509] logger.c: [Jul 19 16:40:06] -- Hungup
'IAX2/phonehome-1-93'
In it you see a NEW being sent.
Then, when the AUTHREQ arrives, the code is busy marking packets in the
send queue as ACKED.
It finds the NEW, and for some reason that NEW is marked as "final", so
the code hangs up the channel.
Here's the code loop:
/* The acknowledgement is within our window.
Time to acknowledge everything
that it says to */
for (x=iaxs[fr->callno]->rseqno; x !=
fr->iseqno; x++) {
/* Ack the packet with the given
timestamp */
if (iaxdebug)
ast_debug(1, "Cancelling
transmission of packet %d\n", x);
call_to_destroy = 0;
AST_LIST_LOCK(&frame_queue);
AST_LIST_TRAVERSE(&frame_queue, cur,
list) {
/* If it's our call, and our
timestamp, mark -1 retries */
if ((fr->callno ==
cur->callno) && (x == cur->oseqno)) {
cur->retries = -1;
/* Destroy call if
this is the end (final message has been acked) */
if (cur->final)
call_to_destroy = fr->callno;
}
}
AST_LIST_UNLOCK(&frame_queue);
if (call_to_destroy) {
if (iaxdebug)
ast_debug(1, "Really
destroying %d, having been acked on final message\n", call_to_destroy);
iax2_destroy(call_to_destroy);
}
}
I cannot figure out how the NEW got marked as final, so I suppose we must
be looking at some race meaning we are looking at the wrong frame, or else
some memory overwrite.
We do have lots of registering hosts, so lots of short REGREQ "calls", so
quite a few "final" packets in the queue.
Steve
======================================================================
----------------------------------------------------------------------
stevedavies - 07-21-07 10:41
----------------------------------------------------------------------
Hi Russell,
I added a little more logging, and also added an extra check in this code
loop - if the frame in the frame queue is already dead (retries < 0) then I
don't kill the call.
This is on a tentative theory that there was a "stale" frame stuck in the
queue from a previous use of that call number. We have about 100 systems
registering and qualifying to us, so lots of short "calls". We've had a
few days with lots of problems on the South African Internet, leading to
lost packets etc etc - so perhaps there is an issue somewhere with cleaning
up those calls which lead to an old packet sticking around long enough to
still be there when the call number gets reused.
Since then I tried to recreate the problem and couldn't.
By the way, I have one guy here who says this bug has always been around -
even in 1.2.
I might try to "instrument" the frame queue a bit more so I can see
exactly what's in it and how old they are.
This suprises me a bit. I have no active calls on the box at the moment,
but still:
voipconnect*CLI> core show channels
Channel Location State Application(Data)
0 active channels0 of 200 max active calls ( 0.00% of capacity)
voipconnect*CLI> iax2 show stats
IAX Statistics
---------------------
Outstanding frames: 17 (0 ingress, 17 egress)
0 timed and 0 untimed transmits; MTU 178/178/1240
Packets in transmit queue: 14 dead, 14 final, 17 total
Suprises me there are 17 packets in the transmit queue, many of which must
be both dead and final.
Maybe there is a logic error in the new multi-threaded stuff that results
in packets occasionally being left in the transmit queue.
Steve
Issue History
Date Modified Username Field Change
======================================================================
07-21-07 10:41 stevedavies Note Added: 0067697
======================================================================
More information about the asterisk-bugs
mailing list