Menu
▾
▴
RE: [Iaxclient-devel] IAX2 Client Library Bug Update - Sequence Number Confusion?
|
From: Steven S. <ss...@so...> - 2004-01-17 15:48:22
|
Here's the section of the trace that seems to best illustrate the issue:
17:49:52 (76041281) LOG_MESSAGE-> Tx Type: 6, Subtype:
IAX_COMMAND_ACK
Session Call Number: 26737
Peer Call Number: 3
Session In Seq Num: 2
Session Out Seq Num: 2
Sending Seq Num: 2
17:50:07 (76056281) LOG_MESSAGE-> Rx Type: 6, Subtype:
IAX_COMMAND_NEW
Session Call Number: 26733
Peer Call Number: 1
Frame Source Call: 384
Frame Dest Call: 0
Session In Seq Num: 2
Session Out Seq Num: 2
Frame In Seq Num: 0
Frame Out Seq Num: 0
17:50:07 (76056312) LOG_MESSAGE-> Packet arrived out of order (expecting
2, got 0) (frametype = 6, subclass = IAX_COMMAND_NEW)
17:50:07 (76056328) LOG_MESSAGE-> Sending Ack Anyway!
17:50:07 (76056343) LOG_MESSAGE-> Tx Type: 6, Subtype:
IAX_COMMAND_ACK
Session Call Number: 26733
Peer Call Number: 1
Session In Seq Num: 2
Session Out Seq Num: 2
Sending Seq Num: 0
Do I understand that you think the session is being recycled? That that
is the reason the InSeq and OutSeq are both set to 2 for the session? I
guess I have to dig further into iax.c to figure out how/where the
session is destroyed/created.
Do you have a copy of the whitepaper from Mark that is supposed to exist
and explain the inner workings of IAX2? I feel like I am flying a bit
blind here in that I don't have any definitive documentation as to how
it should work (except for the source which is rather silent in terms of
"here's how you do it" information).
Thanks,
Steve Sokol
-----Original Message-----
From: Steve Kann [mailto:st...@st...]
Sent: Friday, January 16, 2004 9:31 PM
To: Steven Sokol
Cc: iax...@li...; 'Dan'
Subject: Re: [Iaxclient-devel] IAX2 Client Library Bug Update - Sequence
Number Confusion?
Steve,
Sorry I haven't replied in a while. You've been doing so well, I didn't
want to get in the way :) [ and I was really busy with other things ].
So, from this, it sounds like there's some issue with the "session"
handling. Much of the session handling code the library wasn't written
by me, and even the stuff I did write I wasn't really sure about.
In this case, it seems like the iaxclient library is keeping a session
around when it should be destroying it. This problem could be libiax2
library code, and not in the iaxclient_lib handling because while in the
iaxclient_lib.c handling, we try to "shadow" the libiax2's session
handling, when the new call comes in, libiax2 is looking up the session
with iax_find_session.
If this was happening, then iax_find_session would be finding a session
that matched the new call. This should never happen.
It seems likely that somewhere, the libiax2 should be calling
destroy_session, but it isn't. There's lots of places this could happen.
You can probably find out if you look at the previous uses of session,
and how it was used last before it was re-used for this call.
It might be the registration stuff. I wasn't real sure how that all was
supposed to work in the library, so I might be doing it incorrectly. Or,
it might be that one end is hanging up or rejecting a call, and then not
destroying the associated session. Currently, I'm making a new session
for every "refresh" of the registrations, and I'm assuming it's no
longer valid when the reg reply comes in (see the big XXX in
iaxc_handle_regreply()). Maybe you need to do iax_destroy(session) at
the end of iaxc_handle_regreply()??? (This is likely to be the case;
chan_iax2.c does send_command_final when it sends the regack or regrej
back). Or, maybe libiax2 should be doing that for us. If it needs to be
done, it doesn't really matter where it's done, but maybe Mark has some
idea on whether he'd like it in his library or not. (In all other cases,
libiax2 handles destruction of sessions, even thought it does expose an
API for a caller to destroy them. We don't call that anywhere).
It looks like in your debug code that you should have enough debugging
output to see how the matching callno/dcallno was used for that
particular host right before the new call comes in. If you see that, it
should point us right to where the problem happens.
In my client, none of this is being triggered, because it is very
simple, and only makes a single, outgoing call during it's lifetime, so
I have never actually seen this problem. On the other hand, we're just
starting our alpha testing with my client, and already I've uncovered
some things I need to handle better, which will be in the library:
handling audio initialization errors in particular, handling a (reported
on the list) problem with changing devices, etc.
-SteveK
On Jan 16, 2004, at 6:20 PM, Steven Sokol wrote:
Dan,
Sorry for the HTML mail, but I wanted to be able to highlight some
things. No HTML-hater flames please.
I changed my iax.clogging again to provide additional information. I
can now see that the SESSION (i.e. the IAX line on the client) appears
to be the culprit. I originally thought that this was an Asterisk bug
(and it still could be) but I have more information now:
Good Call
Here's what we see from the Client's perspective when a "good" or
connecting call arrives:
We receive an incoming "new" message from Asterisk:
16:28:17(71109312) LOG_MESSAGE-> Rx Type: 6, Subtype:
IAX_COMMAND_NEW
Session Call Number: 11079
Peer Call Number: 1
Frame Source Call: 384
Frame DestCall: 0
Session In Seq Num: 0
SessionOut SeqNum: 0
Frame InSeqNum: 0
Frame OutSeqNum: 0
We respond with an acknowledgement, telling * that we received the
command.
16:28:17(71109328) LOG_MESSAGE->Tx Type: 6, Subtype:
IAX_COMMAND_ACK
Session Call Number: 11079
Peer Call Number: 1
Session In Seq Num: 1
SessionOut SeqNum: 0
SendingSeqNum: 0
We also send an accept message letting * know to initialize a valid
session on the server.
16:28:17(71109343) LOG_MESSAGE->Tx Type: 6, Subtype:
IAX_COMMAND_ACCEPT
Session Call Number: 11079
Peer Call Number: 1
Session In Seq Num: 1
SessionOut SeqNum: 0
SendingSeqNum: -1
Bad Call
Now here is what we see when a "bad" or non-connecting call arrives:
The same new message arrives on our system, but the sessionInSeq
andOutSeq are set to 2.
16:29:07(71159453) LOG_MESSAGE-> Rx Type: 6, Subtype:
IAX_COMMAND_NEW
Session Call Number: 11078
Peer Call Number: 3
Frame Source Call: 896
Frame DestCall: 0
Session In Seq Num: 2
SessionOut SeqNum: 2
Frame InSeqNum: 0
Frame OutSeqNum: 0
The code iniax_header_to_eventthat handles validating the ordination of
received messages chokes because the session was expecting Sequence
Number 2 and received a zero from Asterisk. This seems to point to the
session not being properly cleaned up when the previous call (or other
activity) terminated.
16:29:07(71159453) LOG_MESSAGE-> Packet arrived out of order (expecting
2, got 0) (frametype= 6, subclass = IAX_COMMAND_NEW)
The logic iniax_header_to_eventdefaults to sending the ACK message to
the server. Asterisk then expects to receive an ACCEPT message within a
few milliseconds. This never shows up because we bail out of the code as
you see below.
16:29:07(71159468) LOG_MESSAGE-> SendingAckAnyway!
16:29:07(71159484) LOG_MESSAGE->Tx Type: 6, Subtype:
IAX_COMMAND_ACK
Session Call Number: 11078
Peer Call Number: 3
Session In Seq Num: 2
SessionOut SeqNum: 2
SendingSeqNum: 0
The logic is to then bail out without returning an event. The library
assumes that the event is invalid (because of the invalid sequence
number) and simply disregards it.
16:29:07(71159484) LOG_MESSAGE-> Returning Null! Exiting In
ReSendSection!
After waiting for the ACCPET message for whatever tolerance is set in
thechan_iaxcode, the Asterisk server again tries to start a new call by
sending another NEW command. Since nothing has cleared up the InSeqand
OutSeqvalues in the session, this fails as well.
16:29:09(71161453) LOG_MESSAGE-> Rx Type: 6, Subtype:
IAX_COMMAND_NEW
Session Call Number: 11078
Peer Call Number: 3
Frame Source Call: 896
Frame DestCall: 128
Session In Seq Num: 2
SessionOut SeqNum: 2
Frame InSeqNum: 0
Frame OutSeqNum: 0
16:29:09(71161468) LOG_MESSAGE-> Packet arrived out of order (expecting
2, got 0) (frametype= 6, subclass = IAX_COMMAND_NEW)
16:29:09(71161468) LOG_MESSAGE-> SendingAckAnyway!
16:29:09(71161484) LOG_MESSAGE->Tx Type: 6, Subtype:
IAX_COMMAND_ACK
Session Call Number: 11078
Peer Call Number: 3
Session In Seq Num: 2
SessionOut SeqNum: 2
SendingSeqNum: 0
16:29:09(71161500) LOG_MESSAGE-> Returning Null! Exiting In
ReSendSection!
Summary
From what I can tell, the Sessions are held within the 'calls' variables
iniaxclient_lib.c. The 'calls' represents the virtual "lines" or
"channels" that your client allocates when you call
theiaxc_initialize(int audType,int inCalls). The session values for
each "call" must not be properly cleared when that session released by
either the remote end hanging up, or by the client dumping the call by
callingiaxc_clear_call(int toDump). I suspect that the
session'sInSeqandOutSeqshould be cleared but they are not.
I hope Steve Kann or Steve Underwood (who have much more experience
under the hood of iax2 than I) will be able to see where the issue is
taking place.
Regards,
Steven
|
