[Asterisk-Dev] IAX2 Client Library Bug Update - Sequence Number Confusion?

Steven Sokol ssokol at sokol-associates.com
Fri Jan 16 11:54:21 MST 2004


Greetings.  Here's a puzzler for you.  I have been working with a number
of people, including Mark Spencer to try to track down this bug.  The
bizarre thing that seems to be happening is this: when a NEW call
message arrives from the Asterisk server, it should have an inbound
sequence number (iseqno) of 0.  However, it appears that, for the calls
that fail, the sequence number is incorrectly set to 2.  Is this done by
Asterisk when it sends?  By libiax2 when it receives?  Therein lies the
mystery.

This is seen in both the trace from Asterisk and from my tracing.  (Both
of which are included below for your reading pleasure.)  From what I can
fathom from the chan_iax2 code, each time a call is started using the
IAX_COMMAND_NEW subtype, the sequence number SHOULD be zero.  From the
perspective of the chan_iax2.c code in Asterisk, the IAX_COMMAND_NEW
message is always sent by calling the send_command function and passing
a sequence number of -1.  Follow:

1. send_command(...) function calls the __send_command function.
2. __send_command(...) in turn calls iax2_send(...) function passing
along the seqno = -1
3. iax2_send(...) sets the oseqno based on the seqno passed.  If seqno >
-1 (which it ain't) the frame's outgoing sequence number is set to the
seqno passed in.
4. In our case, the seqno IS -1, so the outgoing (oseqno) sequence
number is set to the value of the channel's oseqno + 1 (oseqno++).
5. In either case, the iseqno is set to the channel's iseqno value.
6. An IAX header frame (fh) is created.
7. The frame header's call number (callno) is set to the frame's call
number.
8. The frame header's oseqno is set to the frame's oseqno.
9. As long as the call is not a transfer, the frame header's iseqno is
set to the frame's seqno.
10.  The frame is packetized and sent.

This can all be seen in chan_iax2.c lines 2408 - 2421.

Here's what the iax2 debugging shows:


{{{{{{{{{{{{{{{{{{{{{ GOOD CALL HERE }}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}

    -- Executing Dial("SIP/1101-bf98", "IAX2/1105|30") in new stack
    -- Called 1105
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass:
NEW
   Timestamp: 00001ms  SCall: 00007  DCall: 00000 [64.151.42.28:4569]
   VERSION         : 2
   CALLED NUMBER   : s
   CALLING NUMBER  : 1101
   CALLING NAME    : Steven Sokol
   LANGUAGE        : en
   FORMAT          : 2
   CAPABILITY      : 2
   ADSICPE         : 2
   DATE TIME       : 137389161

Rx-Frame Retry[No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass:
ACK
   Timestamp: 00001ms  SCall: 30543  DCall: 00007 [64.151.42.28:4569]
Rx-Frame Retry[No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass:
ACCEPT
   Timestamp: 00016ms  SCall: 30543  DCall: 00007 [64.151.42.28:4569]
    -- Call accepted by 64.151.42.28 (format GSM)
    -- Format for call is GSM
Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass:
ACK
   Timestamp: 00016ms  SCall: 00007  DCall: 30543 [64.151.42.28:4569]
Rx-Frame Retry[No] -- OSeqno: 001 ISeqno: 001 Type: CONTROL Subclass:
RINGING
   Timestamp: 00031ms  SCall: 30543  DCall: 00007 [64.151.42.28:4569]
Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass:
ACK
   Timestamp: 00031ms  SCall: 00007  DCall: 30543 [64.151.42.28:4569]
    -- IAX2[1105]/7 is ringing
Rx-Frame Retry[No] -- OSeqno: 002 ISeqno: 001 Type: CONTROL Subclass:
ANSWER
   Timestamp: 02766ms  SCall: 30543  DCall: 00007 [64.151.42.28:4569]
Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 003 Type: IAX     Subclass:
ACK
   Timestamp: 02766ms  SCall: 00007  DCall: 30543 [64.151.42.28:4569]
    -- IAX2[1105]/7 answered SIP/1101-bf98
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 003 Type: VOICE   Subclass: 2
   Timestamp: 02815ms  SCall: 00007  DCall: 30543 [64.151.42.28:4569]
Rx-Frame Retry[No] -- OSeqno: 003 ISeqno: 001 Type: VOICE   Subclass: 2
   Timestamp: 02797ms  SCall: 30543  DCall: 00007 [64.151.42.28:4569]
Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 004 Type: IAX     Subclass:
ACK
   Timestamp: 02797ms  SCall: 00007  DCall: 30543 [64.151.42.28:4569]
Rx-Frame Retry[No] -- OSeqno: 004 ISeqno: 002 Type: IAX     Subclass:
ACK
   Timestamp: 02797ms  SCall: 30543  DCall: 00007 [64.151.42.28:4569]
Rx-Frame Retry[No] -- OSeqno: 004 ISeqno: 002 Type: IAX     Subclass:
HANGUP
   Timestamp: 06031ms  SCall: 30543  DCall: 00007 [64.151.42.28:4569]
   CAUSE           : Dumped Call
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 005 Type: IAX     Subclass:
ACK
   Timestamp: 06031ms  SCall: 00007  DCall: 30543 [64.151.42.28:4569]
    -- Hungup 'IAX2[1105]/7'
  == Spawn extension (default, 1109, 1) exited non-zero on
'SIP/1101-bf98'
Rx-Frame Retry[Yes] -- OSeqno: 004 ISeqno: 002 Type: IAX     Subclass:
HANGUP
   Timestamp: 06031ms  SCall: 30543  DCall: 00007 [64.151.42.28:4569]
   CAUSE           : Dumped Call


{{{{{{{{{{{{{{{{{{{{{{ REGISTRATION HERE
}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}

Rx-Frame Retry[No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass:
REGREQ
   Timestamp: 00001ms  SCall: 30544  DCall: 00000 [64.151.42.28:4569]
   USERNAME        : 1105
   REFRESH         : 60

Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass:
REGAUTH
   Timestamp: 00001ms  SCall: 00004  DCall: 30544 [64.151.42.28:4569]
   AUTHMETHODS     : 7
   CHALLENGE       : 179726065
   USERNAME        : 1105

Rx-Frame Retry[No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass:
REGREQ
   Timestamp: 00047ms  SCall: 30544  DCall: 00004 [64.151.42.28:4569]
   USERNAME        : 1105
   REFRESH         : 60
   MD5 RESULT      : 5f74d808d3b1216dd6fec0daf0dafd74

Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass:
REGACK
   Timestamp: 00036ms  SCall: 00004  DCall: 30544 [64.151.42.28:4569]
   USERNAME        : 1105
   REFRESH         : 60
   DATE TIME       : 137389167
   APPARENT ADDRES : IPV4 64.151.42.28:4569
   CALLING NAME    : "Steve 1105" <(816) 822-1807>

Rx-Frame Retry[No] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass:
ACK
   Timestamp: 00036ms  SCall: 30544  DCall: 00004 [64.151.42.28:4569]


{{{{{{{{{{{{{ GOOD CALL HERE - ABORTED BEFORE ANSWER
}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}


    -- Executing Dial("SIP/1101-c1ed", "IAX2/1105|30") in new stack
    -- Called 1105
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass:
NEW
   Timestamp: 00001ms  SCall: 00005  DCall: 00000 [64.151.42.28:4569]
   VERSION         : 2
   CALLED NUMBER   : s
   CALLING NUMBER  : 1101
   CALLING NAME    : Steven Sokol
   LANGUAGE        : en
   FORMAT          : 2
   CAPABILITY      : 2
   ADSICPE         : 2
   DATE TIME       : 137389171

Rx-Frame Retry[No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass:
ACK
   Timestamp: 00001ms  SCall: 30545  DCall: 00005 [64.151.42.28:4569]
Rx-Frame Retry[No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass:
ACCEPT
   Timestamp: 00015ms  SCall: 30545  DCall: 00005 [64.151.42.28:4569]
    -- Call accepted by 64.151.42.28 (format GSM)
    -- Format for call is GSM
Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass:
ACK
   Timestamp: 00015ms  SCall: 00005  DCall: 30545 [64.151.42.28:4569]
Rx-Frame Retry[No] -- OSeqno: 001 ISeqno: 001 Type: CONTROL Subclass:
RINGING
   Timestamp: 00031ms  SCall: 30545  DCall: 00005 [64.151.42.28:4569]
Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass:
ACK
   Timestamp: 00031ms  SCall: 00005  DCall: 30545 [64.151.42.28:4569]
    -- IAX2[1105]/5 is ringing
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass:
HANGUP
   Timestamp: 02018ms  SCall: 00005  DCall: 30545 [64.151.42.28:4569]
    -- Hungup 'IAX2[1105]/5'
  == Spawn extension (default, 1109, 1) exited non-zero on
'SIP/1101-c1ed'
Rx-Frame Retry[No] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass:
ACK
   Timestamp: 02018ms  SCall: 30545  DCall: 00005 [64.151.42.28:4569]


{{{{{{{{{{{{BAD CALL
HERE}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}


    -- Executing Dial("SIP/1101-6144", "IAX2/1105|30") in new stack
    -- Called 1105
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass:
NEW
   Timestamp: 00001ms  SCall: 00006  DCall: 00000 [64.151.42.28:4569]
   VERSION         : 2
   CALLED NUMBER   : s
   CALLING NUMBER  : 1101
   CALLING NAME    : Steven Sokol
   LANGUAGE        : en
   FORMAT          : 2
   CAPABILITY      : 2
   ADSICPE         : 2
   DATE TIME       : 137389176

Rx-Frame Retry[No] -- OSeqno: 000 ISeqno: 002 Type: IAX     Subclass:
ACK
   Timestamp: 00001ms  SCall: 30540  DCall: 00006 [64.151.42.28:4569]
Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass:
NEW
   Timestamp: 00001ms  SCall: 00006  DCall: 00000 [64.151.42.28:4569]
   VERSION         : 2
   CALLED NUMBER   : s
   CALLING NUMBER  : 1101
   CALLING NAME    : Steven Sokol
   LANGUAGE        : en
   FORMAT          : 2
   CAPABILITY      : 2
   ADSICPE         : 2
   DATE TIME       : 137389176

Rx-Frame Retry[No] -- OSeqno: 000 ISeqno: 002 Type: IAX     Subclass:
ACK
   Timestamp: 00001ms  SCall: 30540  DCall: 00006 [64.151.42.28:4569]
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 000 Type: IAX     Subclass:
LAGRQ
   Timestamp: 10002ms  SCall: 00006  DCall: 30540 [64.151.42.28:4569]
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass:
REGREQ
   Timestamp: 00001ms  SCall: 00001  DCall: 00000 [69.73.19.178:4569]
   USERNAME        : ssokol01
   REFRESH         : 60

Rx-Frame Retry[No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass:
REGAUTH
   Timestamp: 00001ms  SCall: 00190  DCall: 00001 [69.73.19.178:4569]
   AUTHMETHODS     : 3
   CHALLENGE       : 187891203
   USERNAME        : ssokol01

Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass:
REGREQ
   Timestamp: 00053ms  SCall: 00001  DCall: 00190 [69.73.19.178:4569]
   USERNAME        : ssokol01
   REFRESH         : 60
   MD5 RESULT      : 0b907bfdb681b46d9696baba55388b34

Rx-Frame Retry[No] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass:
REGACK
   Timestamp: 00049ms  SCall: 00190  DCall: 00001 [69.73.19.178:4569]
   USERNAME        : ssokol01
   REFRESH         : 60
   DATE TIME       : 137388674
   APPARENT ADDRES : IPV4 64.151.32.77:4569
   CALLING NAME    : "Steven Sokol" <(700) 613-9004>

Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass:
ACK
   Timestamp: 00049ms  SCall: 00001  DCall: 00190 [69.73.19.178:4569]
Tx-Frame Retry[001] -- OSeqno: 001 ISeqno: 000 Type: IAX     Subclass:
LAGRQ
   Timestamp: 10002ms  SCall: 00006  DCall: 30540 [64.151.42.28:4569]
Tx-Frame Retry[002] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass:
NEW
   Timestamp: 00001ms  SCall: 00006  DCall: 00000 [64.151.42.28:4569]
   VERSION         : 2
   CALLED NUMBER   : s
   CALLING NUMBER  : 1101
   CALLING NAME    : Steven Sokol
   LANGUAGE        : en
   FORMAT          : 2
   CAPABILITY      : 2
   ADSICPE         : 2
   DATE TIME       : 137389176

    -- Hungup 'IAX2[1105]/6'
  == Spawn extension (default, 1109, 1) exited non-zero on
'SIP/1101-6144'
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 000 Type: IAX     Subclass:
HANGUP
   Timestamp: 13617ms  SCall: 00006  DCall: 30540 [64.151.42.28:4569]
Tx-Frame Retry[001] -- OSeqno: 002 ISeqno: 000 Type: IAX     Subclass:
HANGUP
   Timestamp: 13617ms  SCall: 00006  DCall: 30540 [64.151.42.28:4569]

Here's what my client log shows:

{{{{{{{{{{{{{{{{{{{{ GOOD CALL }}}}}}}}}}}}}}}}}}}}}}}}}}}}}

12:34:36 (57093781) LOG_MESSAGE-> COMMAND RECEIVED: SourceCall: 1920
DestCall: 0	 InSequ: 0	 OutSequ: 0	 Type: 6
Subclass: IAX_COMMAND_NEW
12:34:36 (57093796) LOG_MESSAGE-> COMMAND SENT: Sequence: 0	 Type: 6
Subclass: IAX_COMMAND_ACK
12:34:36 (57093812) LOG_MESSAGE-> COMMAND SENT: Sequence: -1	 Type: 6
Subclass: IAX_COMMAND_ACCEPT
12:34:36 (57093828) LOG_MESSAGE-> COMMAND SENT: Sequence: -1	 Type: 4
Subclass: IAX_COMMAND_PONG
12:34:36 (57093843) LOG_MESSAGE-> COMMAND RECEIVED: SourceCall: 1920
DestCall: 20343	 InSequ: 1	 OutSequ: 1	 Type: 6
Subclass: IAX_COMMAND_ACK
12:34:36 (57093859) LOG_MESSAGE-> COMMAND RECEIVED: SourceCall: 1920
DestCall: 20343	 InSequ: 1	 OutSequ: 1	 Type: 6
Subclass: IAX_COMMAND_ACK
12:34:39 (57096562) LOG_MESSAGE-> COMMAND SENT: Sequence: -1	 Type: 4
Subclass: IAX_COMMAND_ACK
12:34:39 (57096609) LOG_MESSAGE-> COMMAND RECEIVED: SourceCall: 1920
DestCall: 20343	 InSequ: 1	 OutSequ: 1	 Type: 6
Subclass: IAX_COMMAND_ACK
12:34:39 (57096625) LOG_MESSAGE-> COMMAND RECEIVED: SourceCall: 1920
DestCall: 20343	 InSequ: 2	 OutSequ: 1	 Type: 6
Subclass: IAX_COMMAND_ACK
12:34:39 (57096640) LOG_MESSAGE-> COMMAND SENT: Sequence: 4	 Type: 6
Subclass: IAX_COMMAND_ACK
12:34:42 (57099828) LOG_MESSAGE-> COMMAND SENT: Sequence: -1	 Type: 6
Subclass: IAX_COMMAND_HANGUP
12:34:42 (57100062) LOG_MESSAGE-> COMMAND RECEIVED: SourceCall: 1920
DestCall: 20343	 InSequ: 2	 OutSequ: 2	 Type: 6
Subclass: IAX_COMMAND_ACK
12:34:42 (57100078) LOG_MESSAGE-> COMMAND RECEIVED: SourceCall: 1920
DestCall: 20343	 InSequ: 2	 OutSequ: 0	 Type: 6
Subclass: IAX_COMMAND_INVAL

{{{{{{{{{{{{{{{{{{{{{ REGISTRATION }}}}}}}}}}}}}}}}}}}}}}}}

12:34:48 (57105796) LOG_MESSAGE-> COMMAND SENT: Sequence: -1	 Type: 6
Subclass: IAX_COMMAND_REGREQ
12:34:48 (57105812) LOG_MESSAGE-> COMMAND RECEIVED: SourceCall: 1152
DestCall: 20599	 InSequ: 0	 OutSequ: 0	 Type: 6
Subclass: IAX_COMMAND_REGAUTH
12:34:48 (57105828) LOG_MESSAGE-> COMMAND SENT: Sequence: -1	 Type: 6
Subclass: IAX_COMMAND_REGREQ
12:34:48 (57105843) LOG_MESSAGE-> COMMAND RECEIVED: SourceCall: 1152
DestCall: 20599	 InSequ: 1	 OutSequ: 1	 Type: 6
Subclass: IAX_COMMAND_REGACK
12:34:48 (57105859) LOG_MESSAGE-> COMMAND SENT: Sequence: 2	 Type: 6
Subclass: IAX_COMMAND_ACK

{{{{{{{{{{{{{{{{{{{{ GOOD CALL - ABORTED BEFORE ANSWER
}}}}}}}}}}}}}}}}}}}}}}}}}}}}}

12:34:55 (57112250) LOG_MESSAGE-> COMMAND RECEIVED: SourceCall: 1408
DestCall: 0	 InSequ: 0	 OutSequ: 0	 Type: 6
Subclass: IAX_COMMAND_NEW
12:34:55 (57112265) LOG_MESSAGE-> COMMAND SENT: Sequence: 0	 Type: 6
Subclass: IAX_COMMAND_ACK
12:34:55 (57112281) LOG_MESSAGE-> COMMAND SENT: Sequence: -1	 Type: 6
Subclass: IAX_COMMAND_ACCEPT
12:34:55 (57112296) LOG_MESSAGE-> COMMAND SENT: Sequence: -1	 Type: 4
Subclass: IAX_COMMAND_PONG
12:34:55 (57112312) LOG_MESSAGE-> COMMAND RECEIVED: SourceCall: 1408
DestCall: 20855	 InSequ: 1	 OutSequ: 1	 Type: 6
Subclass: IAX_COMMAND_ACK
12:34:55 (57112312) LOG_MESSAGE-> COMMAND RECEIVED: SourceCall: 1408
DestCall: 20855	 InSequ: 1	 OutSequ: 1	 Type: 6
Subclass: IAX_COMMAND_ACK
12:34:57 (57114265) LOG_MESSAGE-> COMMAND RECEIVED: SourceCall: 1408
DestCall: 20855	 InSequ: 1	 OutSequ: 1	 Type: 6
Subclass: IAX_COMMAND_HANGUP
12:34:57 (57114281) LOG_MESSAGE-> COMMAND SENT: Sequence: 2	 Type: 6
Subclass: IAX_COMMAND_ACK

{{{{{{{{{{{{ BAD CALL }}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}}

12:35:06 (57123500) LOG_MESSAGE-> COMMAND RECEIVED: SourceCall: 1664
DestCall: 0	 InSequ: 2	 OutSequ: 0	 Type: 6
Subclass: IAX_COMMAND_NEW
12:35:06 (57123515) LOG_MESSAGE-> Packet arrived out of order (expecting
2, got 0) (frametype = 6, subclass = IAX_COMMAND_NEW)
12:35:06 (57123531) LOG_MESSAGE-> Sending Ack Anyway!
12:35:06 (57123546) LOG_MESSAGE-> COMMAND SENT: Sequence: 0	 Type: 6
Subclass: IAX_COMMAND_ACK
12:35:06 (57123562) LOG_MESSAGE-> Returning Null! Exiting In ReSend
Section!
12:35:08 (57125515) LOG_MESSAGE-> COMMAND RECEIVED: SourceCall: 1664
DestCall: 128	 InSequ: 2	 OutSequ: 0	 Type: 6
Subclass: IAX_COMMAND_NEW
12:35:08 (57125531) LOG_MESSAGE-> Packet arrived out of order (expecting
2, got 0) (frametype = 6, subclass = IAX_COMMAND_NEW)
12:35:08 (57125531) LOG_MESSAGE-> Sending Ack Anyway!
12:35:08 (57125546) LOG_MESSAGE-> COMMAND SENT: Sequence: 0	 Type: 6
Subclass: IAX_COMMAND_ACK
12:35:08 (57125562) LOG_MESSAGE-> Returning Null! Exiting In ReSend
Section!


Look at the last section (bad call) of both the asterisk trace and my
trace.  Does anybody have any idea what is going on here with the
sequence numbers?  Is sure looks like asterisk thinks it is sending us
sequence number zero for the new call, but we are seeing it as sequence
number 2.  I don't know where the tracing that asterisk generates is
done, but somewhere, on one side of the network or the other, the
sequence number is getting miss-set to 2.

When we get sequence number 2, we see it as out of order.  We simply
send and an ACK.  We never send the ACCEPT that needs to follow in order
to start the conversation.  As you can see, get a repeated NEW message
again with the buggered iseqno, and again we simply ACK it.  After a
while asterisk gives up and destroys the call.

Can SOMEBODY knowledgeable PLEASE take a look at both the client library
and chan_iax2 and fathom where this number is being miss set.  I am
working at the very upper range of my capabilities here.  (Remember, I
am primarily a windows weenie).

Thanks!

Steve Sokol 





More information about the asterisk-dev mailing list