[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
Thu Aug 2 00:49:00 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: 08-02-2007 00:49 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 - 08-02-07 00:49
----------------------------------------------------------------------
Steve thinks this issue will probably be solved by the patch on bug 10289.
Issue History
Date Modified Username Field Change
======================================================================
08-02-07 00:49 stevedavies Note Added: 0068293
======================================================================
More information about the asterisk-bugs
mailing list