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

[Steven S. <ss...@so...>]

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.c logging 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 Dest Call:           0
       Session In Seq Num:        0
Session Out Seq Num:       0
       Frame In Seq Num:          0
       Frame Out Seq Num:         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
       Session Out Seq Num:       0
       Sending Seq Num:    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
       Session Out Seq Num:       0
       Sending Seq Num:    -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 session InSeq and
OutSeq 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 Dest Call:           0
       Session In Seq Num:        2
Session Out Seq Num:       2
       Frame In Seq Num:          0
       Frame Out Seq Num:         0
 
The code in iax_header_to_event that 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 in iax_header_to_event defaults 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-> Sending Ack Anyway!
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
       Session Out Seq Num:       2
       Sending Seq Num:           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 ReSend
Section!
 
After waiting for the ACCPET message for whatever tolerance is set in
the chan_iax code, the Asterisk server again tries to start a new call
by sending another NEW command.  Since nothing has cleared up the InSeq
and OutSeq values 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 Dest Call:           128
       Session In Seq Num:        2
       Session Out Seq Num:       2
       Frame In Seq Num:          0
       Frame Out Seq Num:         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-> Sending Ack Anyway!
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
       Session Out Seq Num:       2
       Sending Seq Num:           0
 
16:29:09 (71161500) LOG_MESSAGE-> Returning Null! Exiting In ReSend
Section!
 
Summary
From what I can tell, the Sessions are held within the 'calls' variables
in iaxclient_lib.c.  The 'calls' represents the virtual "lines" or
"channels" that your client allocates when you call the
iaxc_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 calling
iaxc_clear_call(int toDump).  I suspect that the session's InSeq and
OutSeq should 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