[Iaxclient-devel] Bug info... (really weird bug info)

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

Greetings,

I put my trace code back into the library to see what is being sent and
received.  The result is bizarre.  In IAX to (SIP, ZAP) everything looks
normal.  Pings, registrations, all the normal stuff are sent and received.

In IAX-IAX conversations, however, the client seems to become confused and
send several spurious IAX_COMMAND_TXREJ messages.  I am guessing that this
confuses Asterisk which at some point stops relaying the voice frames.

The timing follows the 1000 ms timeout you see in the iax.c for
retransmission of reliably transmitted frames.

Another oddity.  During the negotiation and answer phase of calls from an
IAX source, the client seems to receive an IAX_COMMAND_TXREQ, to which we
reply with IAX_COMMAND_TXCNT.

Does ANYBODY know why we are seeing the transfer stuff being activated?  Is
this part of the native (IAX-IAX) protocol?  What gives?  I had a 40 minute
call today with somebody in the Ukraine using my softphone while I was using
my SIP phone.  This _HAS_ to be an IAX specific issue.

Below is an entire log of a client for a single call that lost audio.  Audio
dropped at approximately 14:02:35.

14:01:23 (2109140) -> Tx		Type: 6, Subtype: IAX_COMMAND_REGREQ
	Session Call Number:		9184
	Peer Call Number:   		0
	Session In Seq Num:  	0
	Session Out Seq Num: 	0
	Sending Seq Num:    		-1

14:01:23 (2109156) -> Rx		Type: 6, Subtype:
IAX_COMMAND_REGAUTH
	Session Call Number:		9184
	Peer Call Number:   		4
	Frame Source Call:   	1152
	Frame Dest Call:     	57379
	Session In Seq Num:  	0
	Session Out Seq Num: 	1
	Frame In Seq Num:    	1
	Frame Out Seq Num:   	0

14:01:23 (2109156) -> Tx		Type: 6, Subtype: IAX_COMMAND_REGREQ
	Session Call Number:		9185
	Peer Call Number:   		0
	Session In Seq Num:  	0
	Session Out Seq Num: 	0
	Sending Seq Num:    		-1

14:01:23 (2109156) -> Tx		Type: 6, Subtype: IAX_COMMAND_REGREQ
	Session Call Number:		9184
	Peer Call Number:   		4
	Session In Seq Num:  	1
	Session Out Seq Num: 	1
	Sending Seq Num:    		-1

14:01:24 (2109171) -> Rx		Type: 6, Subtype: IAX_COMMAND_REGACK
	Session Call Number:		9184
	Peer Call Number:   		4
	Frame Source Call:   	1152
	Frame Dest Call:     	57379
	Session In Seq Num:  	1
	Session Out Seq Num: 	2
	Frame In Seq Num:    	2
	Frame Out Seq Num:   	1

14:01:24 (2109187) -> Tx		Type: 6, Subtype: IAX_COMMAND_ACK
	Session Call Number:		9184
	Peer Call Number:   		4
	Session In Seq Num:  	2
	Session Out Seq Num: 	2
	Sending Seq Num:    		2

14:01:24 (2109218) -> Rx		Type: 6, Subtype:
IAX_COMMAND_REGAUTH
	Session Call Number:		9185
	Peer Call Number:   		337
	Frame Source Call:   	20865
	Frame Dest Call:     	57635
	Session In Seq Num:  	0
	Session Out Seq Num: 	1
	Frame In Seq Num:    	1
	Frame Out Seq Num:   	0

14:01:24 (2109234) -> Tx		Type: 6, Subtype: IAX_COMMAND_REGREQ
	Session Call Number:		9185
	Peer Call Number:   		337
	Session In Seq Num:  	1
	Session Out Seq Num: 	1
	Sending Seq Num:    		-1

14:01:24 (2109328) -> Rx		Type: 6, Subtype: IAX_COMMAND_REGACK
	Session Call Number:		9185
	Peer Call Number:   		337
	Frame Source Call:   	20865
	Frame Dest Call:     	57635
	Session In Seq Num:  	1
	Session Out Seq Num: 	2
	Frame In Seq Num:    	2
	Frame Out Seq Num:   	1

14:01:24 (2109328) -> Tx		Type: 6, Subtype: IAX_COMMAND_ACK
	Session Call Number:		9185
	Peer Call Number:   		337
	Session In Seq Num:  	2
	Session Out Seq Num: 	2
	Sending Seq Num:    		2

14:01:24 (2109359) -> Rx		Type: 6, Subtype: IAX_COMMAND_ACK
	Session Call Number:		9185
	Peer Call Number:   		337
	Frame Source Call:   	20865
	Frame Dest Call:     	57635
	Session In Seq Num:  	2
	Session Out Seq Num: 	2
	Frame In Seq Num:    	2
	Frame Out Seq Num:   	1

14:01:30 (2115453) -> Rx		Type: 6, Subtype: IAX_COMMAND_NEW
	Session Call Number:		9186
	Peer Call Number:   		5
	Frame Source Call:   	1408
	Frame Dest Call:     	0
	Session In Seq Num:  	0
	Session Out Seq Num: 	0
	Frame In Seq Num:    	0
	Frame Out Seq Num:   	0

14:01:30 (2115453) -> Tx		Type: 6, Subtype: IAX_COMMAND_ACK
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	1
	Session Out Seq Num: 	0
	Sending Seq Num:    		0

14:01:30 (2115468) -> Tx		Type: 6, Subtype: IAX_COMMAND_ACCEPT
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	1
	Session Out Seq Num: 	0
	Sending Seq Num:    		-1

14:01:30 (2115484) -> Tx		Type: 4, Subtype: IAX_COMMAND_PONG
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	1
	Session Out Seq Num: 	1
	Sending Seq Num:    		-1

14:01:30 (2115484) -> Rx		Type: 6, Subtype: IAX_COMMAND_ACK
	Session Call Number:		9186
	Peer Call Number:   		5
	Frame Source Call:   	1408
	Frame Dest Call:     	57891
	Session In Seq Num:  	1
	Session Out Seq Num: 	2
	Frame In Seq Num:    	1
	Frame Out Seq Num:   	1

14:01:30 (2115500) -> Rx		Type: 6, Subtype: IAX_COMMAND_ACK
	Session Call Number:		9186
	Peer Call Number:   		5
	Frame Source Call:   	1408
	Frame Dest Call:     	57891
	Session In Seq Num:  	1
	Session Out Seq Num: 	2
	Frame In Seq Num:    	2
	Frame Out Seq Num:   	1

14:01:32 (2117609) -> Tx		Type: 4, Subtype: IAX_COMMAND_ACK
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	2
	Session Out Seq Num: 	2
	Sending Seq Num:    		-1

14:01:32 (2117625) -> Tx		Type: 6, Subtype: IAX_COMMAND_ACK
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	2
	Session Out Seq Num: 	2
	Sending Seq Num:    		2

14:01:32 (2117640) -> Rx		Type: 6, Subtype: IAX_COMMAND_ACK
	Session Call Number:		9186
	Peer Call Number:   		5
	Frame Source Call:   	1408
	Frame Dest Call:     	57891
	Session In Seq Num:  	2
	Session Out Seq Num: 	3
	Frame In Seq Num:    	3
	Frame Out Seq Num:   	2

14:01:32 (2117640) -> Rx		Type: 6, Subtype: IAX_COMMAND_TXREQ
	Session Call Number:		9186
	Peer Call Number:   		5
	Frame Source Call:   	1408
	Frame Dest Call:     	57891
	Session In Seq Num:  	2
	Session Out Seq Num: 	3
	Frame In Seq Num:    	3
	Frame Out Seq Num:   	2

14:01:32 (2117656) -> Tx		Type: 6, Subtype: IAX_COMMAND_TXCNT
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	3
	Session Out Seq Num: 	3
	Sending Seq Num:    		0

14:01:32 (2117718) -> Rx		Type: 6, Subtype: IAX_COMMAND_ACK
	Session Call Number:		9186
	Peer Call Number:   		5
	Frame Source Call:   	1408
	Frame Dest Call:     	57891
	Session In Seq Num:  	3
	Session Out Seq Num: 	4
	Frame In Seq Num:    	4
	Frame Out Seq Num:   	3

14:01:41 (2126953) -> Tx		Type: 6, Subtype: IAX_COMMAND_TXREJ
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	3
	Session Out Seq Num: 	4
	Sending Seq Num:    		0

14:01:51 (2136375) -> Tx		Type: 6, Subtype: IAX_COMMAND_TXREJ
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	3
	Session Out Seq Num: 	4
	Sending Seq Num:    		0

14:02:00 (2145656) -> Tx		Type: 6, Subtype: IAX_COMMAND_TXREJ
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	3
	Session Out Seq Num: 	4
	Sending Seq Num:    		0

14:02:09 (2154953) -> Tx		Type: 6, Subtype: IAX_COMMAND_TXREJ
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	3
	Session Out Seq Num: 	4
	Sending Seq Num:    		0

14:02:19 (2164265) -> Tx		Type: 6, Subtype: IAX_COMMAND_TXREJ
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	3
	Session Out Seq Num: 	4
	Sending Seq Num:    		0

14:02:24 (2169140) -> Tx		Type: 6, Subtype: IAX_COMMAND_REGREQ
	Session Call Number:		9187
	Peer Call Number:   		0
	Session In Seq Num:  	0
	Session Out Seq Num: 	0
	Sending Seq Num:    		-1

14:02:24 (2169156) -> Rx		Type: 6, Subtype:
IAX_COMMAND_REGAUTH
	Session Call Number:		9187
	Peer Call Number:   		2
	Frame Source Call:   	640
	Frame Dest Call:     	58147
	Session In Seq Num:  	0
	Session Out Seq Num: 	1
	Frame In Seq Num:    	1
	Frame Out Seq Num:   	0

14:02:24 (2169171) -> Tx		Type: 6, Subtype: IAX_COMMAND_REGREQ
	Session Call Number:		9187
	Peer Call Number:   		2
	Session In Seq Num:  	1
	Session Out Seq Num: 	1
	Sending Seq Num:    		-1

14:02:24 (2169171) -> Tx		Type: 6, Subtype: IAX_COMMAND_REGREQ
	Session Call Number:		9188
	Peer Call Number:   		0
	Session In Seq Num:  	0
	Session Out Seq Num: 	0
	Sending Seq Num:    		-1

14:02:24 (2169187) -> Rx		Type: 6, Subtype: IAX_COMMAND_REGACK
	Session Call Number:		9187
	Peer Call Number:   		2
	Frame Source Call:   	640
	Frame Dest Call:     	58147
	Session In Seq Num:  	1
	Session Out Seq Num: 	2
	Frame In Seq Num:    	2
	Frame Out Seq Num:   	1

14:02:24 (2169203) -> Tx		Type: 6, Subtype: IAX_COMMAND_ACK
	Session Call Number:		9187
	Peer Call Number:   		2
	Session In Seq Num:  	2
	Session Out Seq Num: 	2
	Sending Seq Num:    		2

14:02:24 (2169250) -> Rx		Type: 6, Subtype:
IAX_COMMAND_REGAUTH
	Session Call Number:		9188
	Peer Call Number:   		192
	Frame Source Call:   	49280
	Frame Dest Call:     	58403
	Session In Seq Num:  	0
	Session Out Seq Num: 	1
	Frame In Seq Num:    	1
	Frame Out Seq Num:   	0

14:02:24 (2169265) -> Tx		Type: 6, Subtype: IAX_COMMAND_REGREQ
	Session Call Number:		9188
	Peer Call Number:   		192
	Session In Seq Num:  	1
	Session Out Seq Num: 	1
	Sending Seq Num:    		-1

14:02:24 (2169296) -> Rx		Type: 6, Subtype: IAX_COMMAND_ACK
	Session Call Number:		9188
	Peer Call Number:   		192
	Frame Source Call:   	49280
	Frame Dest Call:     	58403
	Session In Seq Num:  	1
	Session Out Seq Num: 	2
	Frame In Seq Num:    	1
	Frame Out Seq Num:   	0

14:02:24 (2169328) -> Rx		Type: 6, Subtype: IAX_COMMAND_REGACK
	Session Call Number:		9188
	Peer Call Number:   		192
	Frame Source Call:   	49280
	Frame Dest Call:     	58403
	Session In Seq Num:  	1
	Session Out Seq Num: 	2
	Frame In Seq Num:    	2
	Frame Out Seq Num:   	1

14:02:24 (2169343) -> Tx		Type: 6, Subtype: IAX_COMMAND_ACK
	Session Call Number:		9188
	Peer Call Number:   		192
	Session In Seq Num:  	2
	Session Out Seq Num: 	2
	Sending Seq Num:    		2

14:02:28 (2173562) -> Tx		Type: 6, Subtype: IAX_COMMAND_TXREJ
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	3
	Session Out Seq Num: 	4
	Sending Seq Num:    		0

14:02:37 (2182859) -> Tx		Type: 6, Subtype: IAX_COMMAND_TXREJ
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	4
	Session Out Seq Num: 	4
	Sending Seq Num:    		0

14:02:38 (2183062) -> Tx		Type: 6, Subtype: IAX_COMMAND_ACK
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	4
	Session Out Seq Num: 	4
	Sending Seq Num:    		4

14:02:46 (2191031) -> Rx		Type: 6, Subtype: IAX_COMMAND_PING
	Session Call Number:		9186
	Peer Call Number:   		5
	Frame Source Call:   	1408
	Frame Dest Call:     	57891
	Session In Seq Num:  	4
	Session Out Seq Num: 	4
	Frame In Seq Num:    	4
	Frame Out Seq Num:   	4

14:02:46 (2191046) -> Tx		Type: 6, Subtype: IAX_COMMAND_ACK
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	5
	Session Out Seq Num: 	4
	Sending Seq Num:    		4

14:02:47 (2192156) -> Tx		Type: 6, Subtype: IAX_COMMAND_TXREJ
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	5
	Session Out Seq Num: 	4
	Sending Seq Num:    		0

14:02:47 (2192875) -> Tx		Type: 6, Subtype: IAX_COMMAND_HANGUP
	Session Call Number:		9186
	Peer Call Number:   		5
	Session In Seq Num:  	5
	Session Out Seq Num: 	4
	Sending Seq Num:    		-1

14:02:48 (2193031) -> Rx		Type: 6, Subtype: IAX_COMMAND_ACK
	Session Call Number:		9186
	Peer Call Number:   		5
	Frame Source Call:   	1408
	Frame Dest Call:     	57891
	Session In Seq Num:  	5
	Session Out Seq Num: 	5
	Frame In Seq Num:    	5
	Frame Out Seq Num:   	5

14:02:48 (2193046) -> Rx		Type: 6, Subtype: IAX_COMMAND_INVAL
	Session Call Number:		9186
	Peer Call Number:   		5
	Frame Source Call:   	1408
	Frame Dest Call:     	57891
	Session In Seq Num:  	5
	Session Out Seq Num: 	5
	Frame In Seq Num:    	0
	Frame Out Seq Num:   	0