[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