[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 09:50:53 CDT 2007
The following issue has been RESOLVED.
======================================================================
http://bugs.digium.com/view.php?id=10239
======================================================================
Reported By: stevedavies
Assigned To: russell
======================================================================
Project: Asterisk
Issue ID: 10239
Category: Channels/chan_iax2
Reproducibility: sometimes
Severity: minor
Priority: normal
Status: resolved
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:
Resolution: fixed
Fixed in Version:
======================================================================
Date Submitted: 07-19-2007 11:38 CDT
Last Modified: 08-02-2007 09:50 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
======================================================================
Relationships ID Summary
----------------------------------------------------------------------
related to 0010289 Old LAGRQ frames showing up in new IAX2...
======================================================================
----------------------------------------------------------------------
russell - 08-02-07 09:50
----------------------------------------------------------------------
I'm closing this as fixed as the patch from 10289 probably fixed this
problem. If you still have a problem after upgrading, please let me know.
Thanks!
Issue History
Date Modified Username Field Change
======================================================================
08-02-07 09:50 russell Status new => resolved
08-02-07 09:50 russell Resolution open => fixed
08-02-07 09:50 russell Assigned To => russell
08-02-07 09:50 russell Note Added: 0068311
======================================================================
More information about the asterisk-bugs
mailing list