[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
Fri Jul 20 01:53:11 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-20-2007 01:53 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-20-07 01:53
----------------------------------------------------------------------
Further to this, I added some extra debugging to my source:
[Jul 20 08:43:47] DEBUG[11808] chan_iax2.c: Sending 1 on 84/0 to
196.40.106.60:4569
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] Tx-Frame
Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] Timestamp:
00001ms SCall: 00084 DCall: 00000 [196.40.106.60:4569]
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] VERSION
: 2
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] CALLED
NUMBER : 0216736730
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47]
CODEC_PREFS : (g729|ilbc|gsm|speex|alaw|ulaw)
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] CALLING
NUMBER : 0741003202
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] CALLING
PRESNTN : 3
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] CALLING
TYPEOFN : 1
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] CALLING
TRANSIT : 0
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] CALLING
NAME :
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] LANGUAGE
: en
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] USERNAME
: voipconnect
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] FORMAT
: 8
[Jul 20 08:43:47] DEBUG[11808] devicestate.c: Changing state for
IAX2/phonehome-1 - state 6 (Ringing)
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] CAPABILITY
: 1632014
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] ADSICPE
: 2
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] DATE TIME
: 2007-07-20 08:43:46
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47]
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] Rx-Frame
Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: AUTHREQ
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] Timestamp:
00004ms SCall: 00012 DCall: 00084 [196.40.106.60:4569]
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47]
AUTHMETHODS : 2
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] CHALLENGE
: 586202265
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47] USERNAME
: voipconnect
[Jul 20 08:43:47] VERBOSE[11808] logger.c: [Jul 20 08:43:47]
[Jul 20 08:43:47] DEBUG[11808] chan_iax2.c: Received packet 0, (6, 8)
[Jul 20 08:43:47] DEBUG[11808] chan_iax2.c: Cancelling transmission of
packet 0
[Jul 20 08:43:47] DEBUG[11808] chan_iax2.c: We think we got acked on 0
(6,3) frame on call 84 with final flag set(arriving frame is for call 84)
[Jul 20 08:43:47] DEBUG[11808] chan_iax2.c: Really destroying 84, having
been acked on final message
So frametype 6 is IAX, as expected. But subtype 3 is a PONG, which is NOT
expected because the only frame we sent on this call (call 84) was a NEW
(subtype=1)
Issue History
Date Modified Username Field Change
======================================================================
07-20-07 01:53 stevedavies Note Added: 0067615
======================================================================
More information about the asterisk-bugs
mailing list