Re: [Iaxclient-devel] IAX2 Client Library Bug Update - Sequence Number Confusion?

SourceForge Headquarters 225 Broadway Suite 1600 San Diego, CA 92101 +1 (858) 422-6466

Steve,

	Sorry I haven't replied in a while.  You've been doing so well, =
I=20
didn't want to get in the way :) [ and I was really busy with other=20
things ].

	So, from this, it sounds like there's some issue with the =
"session"=20
handling.   Much of the session handling code the library wasn't=20
written by me, and even the stuff I did write I wasn't really sure=20
about.

	In this case, it seems like the iaxclient library is keeping a =
session=20
around when it should be destroying it.  This problem could be  libiax2=20=

library code, and not in the iaxclient_lib handling because while in=20
the iaxclient_lib.c handling, we try to "shadow" the libiax2's session=20=

handling, when the new call comes in, libiax2 is looking up the session=20=

with iax_find_session.

	If this was happening, then iax_find_session would be finding a=20=

session that matched the new call.  This should never happen.

	It seems likely that somewhere, the libiax2 should be calling=20
destroy_session, but it isn't.  There's lots of places this could=20
happen.  You can probably find out if you look at the previous uses of=20=

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=20
was supposed to work in the library, so I might be doing it=20
incorrectly.   Or, it might be that one end is hanging up or rejecting=20=

a call, and then not destroying the associated session.  Currently, I'm=20=

making a new session for every "refresh" of the registrations, and I'm=20=

assuming it's no longer valid when the reg reply comes in (see the big=20=

XXX in iaxc_handle_regreply()).  Maybe you need to do=20
iax_destroy(session) at the end of iaxc_handle_regreply()???  (This is=20=

likely to be the case; chan_iax2.c does send_command_final when it=20
sends the regack or regrej back).  Or, maybe libiax2 should be doing=20
that for us.  If it needs to be done, it doesn't really matter where=20
it's done, but maybe Mark has some idea on whether he'd like it in his=20=

library or not.  (In all other cases, libiax2 handles destruction of=20
sessions, even thought it does expose an API for a caller to destroy=20
them.  We don't call that anywhere).

	It looks like in your debug code that you should have enough =
debugging=20
  output to see how the matching callno/dcallno was used for that=20
particular host right before the new call comes in. If you see that, it=20=

should point us right to where the problem happens.

	In my client, none of this is being triggered, because it is =
very=20
simple, and only makes a single, outgoing call during it's lifetime, so=20=

I have never actually seen this problem.  On the other hand, we're just=20=

starting our alpha testing with my client, and already I've uncovered=20
some things I need to handle better, which will be in the library: =20
handling audio initialization errors in particular, handling a=20
(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=20
> things.=A0No HTML-hater flames please.
>
> =A0
>
> I changed my iax.clogging again to provide additional information.=A0 =
I=20
> can now see that the SESSION (i.e. the IAX line on the client) appears=20=

> to be the culprit.=A0 I originally thought that this was an Asterisk =
bug=20
> (and it still could be) but I have more information now:
>
> =A0
>
> Good Call
>
> Here's what we see from the Client's perspective when a "good" or=20
> connecting call arrives:
>
> =A0
>
> We receive an incoming =93new=94 message from Asterisk:
>
> 16:28:17(71109312) LOG_MESSAGE-> Rx=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0Type=
: 6, Subtype:=20
> IAX_COMMAND_NEW
>
> =A0=A0=A0=A0=A0=A0Session Call Number: 11079
>
> =A0=A0=A0=A0=A0=A0Peer Call Number:=A0=A0 1
>
> =A0=A0=A0=A0=A0=A0Frame Source Call:=A0=A0=A0=A0=A0=A0=A0 384
>
> =A0=A0=A0=A0=A0=A0Frame DestCall:=A0=A0=A0=A0=A0=A0=A0=A0=A0 0
>
> =A0=A0=A0=A0=A0=A0Session In Seq Num:=A0=A0=A0=A0=A0=A0 0
>
> SessionOut SeqNum:=A0=A0=A0=A0=A0 0
>
> =A0=A0=A0=A0=A0=A0Frame InSeqNum:=A0=A0=A0=A0=A0=A0=A0=A0 0
>
> =A0=A0=A0=A0=A0=A0Frame OutSeqNum:=A0=A0=A0=A0=A0=A0=A0 0
>
> =A0
>
> We respond with an acknowledgement, telling * that we received the=20
> command.
>
> 16:28:17(71109328) LOG_MESSAGE->Tx=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0Type:=
 6, Subtype:=20
> IAX_COMMAND_ACK
>
> =A0=A0=A0=A0=A0=A0Session Call Number: 11079
>
> =A0=A0=A0=A0=A0=A0Peer Call Number:=A0=A0 1
>
> =A0=A0=A0=A0=A0=A0Session In Seq Num:=A0=A0=A0=A0=A0=A0 1
>
> =A0=A0=A0=A0=A0=A0SessionOut SeqNum:=A0=A0=A0=A0=A0 0
>
> =A0=A0=A0=A0=A0=A0SendingSeqNum:=A0=A0=A0 0
>
> =A0
>
> We also send an accept message letting * know to initialize a valid=20
> session on the server.
>
> 16:28:17(71109343) LOG_MESSAGE->Tx=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0Type:=
 6, Subtype:=20
> IAX_COMMAND_ACCEPT
>
> =A0=A0=A0=A0=A0=A0Session Call Number: 11079
>
> =A0=A0=A0=A0=A0=A0Peer Call Number:=A0=A0 1
>
> =A0=A0=A0=A0=A0=A0Session In Seq Num:=A0=A0=A0=A0=A0=A0 1
>
> =A0=A0=A0=A0=A0=A0SessionOut SeqNum:=A0=A0=A0=A0=A0 0
>
> =A0=A0=A0=A0=A0=A0SendingSeqNum:=A0=A0=A0 -1
>
> =A0
>
> Bad Call
>
> Now here is what we see when a "bad" or non-connecting call arrives:
>
> =A0
>
> The same new message arrives on our system, but the sessionInSeq=20
> andOutSeq are set to 2.
>
> 16:29:07(71159453) LOG_MESSAGE-> Rx=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0Type=
: 6, Subtype:=20
> IAX_COMMAND_NEW
>
> =A0=A0=A0=A0=A0=A0Session Call Number: 11078
>
> =A0=A0=A0=A0=A0=A0Peer Call Number:=A0=A0 3
>
> =A0=A0=A0=A0=A0=A0Frame Source Call:=A0=A0=A0=A0=A0=A0=A0 896
>
> =A0=A0=A0=A0=A0=A0Frame DestCall:=A0=A0=A0=A0=A0=A0=A0=A0=A0 0
>
> =A0=A0=A0=A0=A0=A0Session In Seq Num:=A0=A0=A0=A0=A0=A0 2
>
> SessionOut SeqNum:=A0=A0=A0=A0=A0 2
>
> =A0=A0=A0=A0=A0=A0Frame InSeqNum:=A0=A0=A0=A0=A0=A0=A0=A0 0
>
> =A0=A0=A0=A0=A0=A0Frame OutSeqNum:=A0=A0=A0=A0=A0=A0=A0 0
>
> =A0
>
> The code iniax_header_to_eventthat handles validating the ordination=20=

> of received messages chokes because the session was expecting Sequence=20=

> Number 2 and received a zero from Asterisk.=A0This seems to point to =
the=20
> session not being properly cleaned up when the previous call (or other=20=

> activity) terminated.
>
> 16:29:07(71159453) LOG_MESSAGE-> Packet arrived out of order=20
> (expecting 2, got 0) (frametype=3D 6, subclass =3D IAX_COMMAND_NEW)
>
> =A0
>
> The logic iniax_header_to_eventdefaults to sending the ACK message to=20=

> the server.=A0Asterisk then expects to receive an ACCEPT message =
within=20
> a few milliseconds.=A0This never shows up because we bail out of the=20=

> code as you see below.
>
> 16:29:07(71159468) LOG_MESSAGE-> SendingAckAnyway!
>
> 16:29:07(71159484) LOG_MESSAGE->Tx=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0Type:=
 6, Subtype:=20
> IAX_COMMAND_ACK
>
> =A0=A0=A0=A0=A0=A0Session Call Number:=A0=A0=A0=A0=A0=A011078
>
> =A0=A0=A0=A0=A0=A0Peer Call Number:=A0=A0=A0=A0=A0=A0=A0=A0 3
>
> =A0=A0=A0=A0=A0=A0Session In Seq Num:=A0=A0=A0=A0=A0=A0 2
>
> =A0=A0=A0=A0=A0=A0SessionOut SeqNum:=A0=A0=A0=A0=A0 2
>
> =A0=A0=A0=A0=A0=A0SendingSeqNum:=A0=A0=A0=A0=A0=A0=A0=A0=A0 0
>
> =A0
>
> The logic is to then bail out without returning an event.=A0 The =
library=20
> assumes that the event is invalid (because of the invalid sequence=20
> number) and simply disregards it.
>
> 16:29:07(71159484) LOG_MESSAGE-> Returning Null! Exiting In=20
> ReSendSection!
>
> =A0
>
> After waiting for the ACCPET message for whatever tolerance is set in=20=

> thechan_iaxcode, the Asterisk server again tries to start a new call=20=

> by sending another NEW command.=A0Since nothing has cleared up the=20
> InSeqand OutSeqvalues in the session, this fails as well.
>
> 16:29:09(71161453) LOG_MESSAGE-> Rx=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0Type=
: 6, Subtype:=20
> IAX_COMMAND_NEW
>
> =A0=A0=A0=A0=A0=A0Session Call Number:=A0=A0=A0=A0=A0=A011078
>
> =A0=A0=A0=A0=A0=A0Peer Call Number:=A0=A0=A0=A0=A0=A0=A0=A0 3
>
> =A0=A0=A0=A0=A0=A0Frame Source Call:=A0=A0=A0=A0=A0=A0=A0 896
>
> =A0=A0=A0=A0=A0=A0Frame DestCall:=A0=A0=A0=A0=A0=A0=A0=A0=A0 128
>
> =A0=A0=A0=A0=A0=A0Session In Seq Num:=A0=A0=A0=A0=A0=A0 2
>
> =A0=A0=A0=A0=A0=A0SessionOut SeqNum:=A0=A0=A0=A0=A0 2
>
> =A0=A0=A0=A0=A0=A0Frame InSeqNum:=A0=A0=A0=A0=A0=A0=A0=A0 0
>
> =A0=A0=A0=A0=A0=A0Frame OutSeqNum:=A0=A0=A0=A0=A0=A0=A0 0
>
> =A0
>
> 16:29:09(71161468) LOG_MESSAGE-> Packet arrived out of order=20
> (expecting 2, got 0) (frametype=3D 6, subclass =3D IAX_COMMAND_NEW)
>
> 16:29:09(71161468) LOG_MESSAGE-> SendingAckAnyway!
>
> 16:29:09(71161484) LOG_MESSAGE->Tx=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0Type:=
 6, Subtype:=20
> IAX_COMMAND_ACK
>
> =A0=A0=A0=A0=A0=A0Session Call Number:=A0=A0=A0=A0=A0=A011078
>
> =A0=A0=A0=A0=A0=A0Peer Call Number:=A0=A0=A0=A0=A0=A0=A0=A0 3
>
> =A0=A0=A0=A0=A0=A0Session In Seq Num:=A0=A0=A0=A0=A0=A0 2
>
> =A0=A0=A0=A0=A0=A0SessionOut SeqNum:=A0=A0=A0=A0=A0 2
>
> =A0=A0=A0=A0=A0=A0SendingSeqNum:=A0=A0=A0=A0=A0=A0=A0=A0=A0 0
>
> =A0
>
> 16:29:09(71161500) LOG_MESSAGE-> Returning Null! Exiting In=20
> ReSendSection!
>
> =A0
>
> Summary
>
> =46rom what I can tell, the Sessions are held within the =91calls=92=20=

> variables iniaxclient_lib.c.=A0 The =91calls=92 represents the virtual=20=

> =93lines=94 or =93channels=94 that your client allocates when you call=20=

> theiaxc_initialize(int audType,int inCalls).=A0 The session values for=20=

> each =93call=94 must not be properly cleared when that session =
released by=20
> either the remote end hanging up, or by the client dumping the call by=20=

> callingiaxc_clear_call(int toDump).=A0 I suspect that the=20
> session=92sInSeqandOutSeqshould be cleared but they are not.
>
> =A0
>
> I hope Steve Kann or Steve Underwood (who have much more experience=20
> under the hood of iax2 than I) will be able to see where the issue is=20=

> taking place.
>
> =A0
>
> Regards,
>
> =A0
>
> Steven