[jitsi-dev] Race condition


#1

Hi,
I think I've run into a race condition when trying create a PseudoTCP-stream. I've created XMPP-signalling and both the local and the remote Agent successfully enters both COMPLETED and TERMINATED state. The problem occurs when I try to create the PseudoTCP-streams after entering TERMINATED state. I've tried to create it the same way as it is done in IcePseudoTcp. I.e. by calling agent.free() and then creating new DatagramSocket-instances using the transport addresses in the candidate pair.

When I try to do this it works sometimes and sometimes not, which leads me to believe that there's some concurrency issue.
I haven't found the exact problem but my theory is that there's a race condition in the call of free() and the creation of the new DatagramSocket. Something like this:

1. The remote peer enters TERMINATED state and calls free(), creates a new DatagramSocket and then calls Connect on the new PseudoTcpSocket.

2. The local peer hasn't called free() yet and therefore receives the TCP_SYN_SENT from the local peer on the DatagramSocket instance used by the connectivity checker.

3. The local peer enters TERMINATED state, closes the old DatagramSocket (through free), creates a new one and calls Accept on the new PseudoTcpSocket.

4. Both peers timeout because the TCP_SYN_SENT has been lost.

I've attached a log-file for one of the execution attempts that failed.

When I sleep for 1s between the call to free() and the creation of the PseudoTcpSocket it works almost all the time, which strengthens the theory that there's a race condition. However, this feels like a very hackish way of solving it

I've also tried not calling free() and just trying to re-use selectedPair.getLocalCandidate().getDatagramSocket() but doesn't work either. My theory is that PseudoTCPSocket then mixes the stun messages with the TCP_SYN_SENT somehow (I guess there must be a reason why IcePseudoTcp calls free() and then creates a new DatagramSocket).

This is just a guess from my side and I might very well be wrong. My questions are:

1. Could my theory be correct or have I missed something fundamentally on how ICE works?

2. How would you recommend me solving this? I need to somehow synchronize the creation of the PseudoTcpSocket.

Thanks in advance!

Kind Regards
Carl Hasselskog
Degoo Backup AB
carl@degoo.com<mailto:carl@degoo.com>
Phone: +46 73 070 1821
http://degoo.com<http://degoo.com/>
http://twitter.com/#!/CarlHasselskog

ice.log (142 KB)


#2

I should also add that it looks like this can occur the other way around as well. Like this:

1. The local peer calls Accept on PseudoTCPSocket before the remote peer enters TERMINATED state.

2. The remote peer sends some Stun-packet on that DatagramSocket that the PseudoTCPSocket can't parse, causing it to throw this exception:
java.io.IOException: wrong conversation number, this: 0 remote: 1114136
               at org.ice4j.pseudotcp.PseudoTCPBase.process(PseudoTCPBase.java:959)
               at org.ice4j.pseudotcp.PseudoTCPBase.parse(PseudoTCPBase.java:887)
               at org.ice4j.pseudotcp.PseudoTCPBase.NotifyPacket(PseudoTCPBase.java:493)
               at org.ice4j.pseudotcp.PseudoTcpSocket.ReceivePackets(PseudoTcpSocket.java:476)
               at org.ice4j.pseudotcp.PseudoTcpSocket.access$000(PseudoTcpSocket.java:14)
               at org.ice4j.pseudotcp.PseudoTcpSocket$1.run(PseudoTcpSocket.java:245)
               at java.lang.Thread.run(Thread.java:722)

I have attached the log for that execution as well.

Regards
Carl

ice2.log (121 KB)

···

From: Carl Hasselskog [mailto:carl@degoo.com]

Sent: den 9 augusti 2012 12:58
To: dev@jitsi.java.net
Subject: [jitsi-dev] Race condition

Hi,
I think I've run into a race condition when trying create a PseudoTCP-stream. I've created XMPP-signalling and both the local and the remote Agent successfully enters both COMPLETED and TERMINATED state. The problem occurs when I try to create the PseudoTCP-streams after entering TERMINATED state. I've tried to create it the same way as it is done in IcePseudoTcp. I.e. by calling agent.free() and then creating new DatagramSocket-instances using the transport addresses in the candidate pair.

When I try to do this it works sometimes and sometimes not, which leads me to believe that there's some concurrency issue.
I haven't found the exact problem but my theory is that there's a race condition in the call of free() and the creation of the new DatagramSocket. Something like this:

1. The remote peer enters TERMINATED state and calls free(), creates a new DatagramSocket and then calls Connect on the new PseudoTcpSocket.

2. The local peer hasn't called free() yet and therefore receives the TCP_SYN_SENT from the local peer on the DatagramSocket instance used by the connectivity checker.

3. The local peer enters TERMINATED state, closes the old DatagramSocket (through free), creates a new one and calls Accept on the new PseudoTcpSocket.

4. Both peers timeout because the TCP_SYN_SENT has been lost.

I've attached a log-file for one of the execution attempts that failed.

When I sleep for 1s between the call to free() and the creation of the PseudoTcpSocket it works almost all the time, which strengthens the theory that there's a race condition. However, this feels like a very hackish way of solving it

I've also tried not calling free() and just trying to re-use selectedPair.getLocalCandidate().getDatagramSocket() but doesn't work either. My theory is that PseudoTCPSocket then mixes the stun messages with the TCP_SYN_SENT somehow (I guess there must be a reason why IcePseudoTcp calls free() and then creates a new DatagramSocket).

This is just a guess from my side and I might very well be wrong. My questions are:

1. Could my theory be correct or have I missed something fundamentally on how ICE works?

2. How would you recommend me solving this? I need to somehow synchronize the creation of the PseudoTcpSocket.

Thanks in advance!

Kind Regards
Carl Hasselskog
Degoo Backup AB
carl@degoo.com<mailto:carl@degoo.com>
Phone: +46 73 070 1821
http://degoo.com<http://degoo.com/>
http://twitter.com/#!/CarlHasselskog


#3

Hey Carl,
Hey Carl,

Hi,

I think I’ve run into a race condition when trying create a
PseudoTCP-stream. I’ve created XMPP-signalling and both the local and the
remote Agent successfully enters both COMPLETED and TERMINATED state. The
problem occurs when I try to create the PseudoTCP-streams after entering
TERMINATED state. I’ve tried to create it the same way as it is done in
IcePseudoTcp.

Unfortunately that example does not do it properly. Sorry about that.
Pawel is currently working on correcting it (and all the bugs he's
stumbling upon while doing so :wink: ). The thing is that, in order to use
ice4j, one has to use the sockets that it creates. ice4j also creates
a master socket and a stun filtering socket. It then uses the stun
socket so that it can continue ICE processing while the application
continues exchanging data.

I.e. by calling agent.free() and then creating new
DatagramSocket-instances using the transport addresses in the candidate
pair.

You should only call free() once you are done with your session and
you are not going to use the sockets any more.

I believe the above are addressing all your comments below and your next mail..

Could you please let me know if I missed something?

Thanks,
Emil

···

On Thu, Aug 9, 2012 at 12:58 PM, Carl Hasselskog <carl@degoo.com> wrote:

When I try to do this it works sometimes and sometimes not, which leads me
to believe that there’s some concurrency issue.

I haven’t found the exact problem but my theory is that there’s a race
condition in the call of free() and the creation of the new DatagramSocket.
Something like this:

1. The remote peer enters TERMINATED state and calls free(), creates a
new DatagramSocket and then calls Connect on the new PseudoTcpSocket.

2. The local peer hasn’t called free() yet and therefore receives the
TCP_SYN_SENT from the local peer on the DatagramSocket instance used by the
connectivity checker.

3. The local peer enters TERMINATED state, closes the old
DatagramSocket (through free), creates a new one and calls Accept on the new
PseudoTcpSocket.

4. Both peers timeout because the TCP_SYN_SENT has been lost.

I’ve attached a log-file for one of the execution attempts that failed.

When I sleep for 1s between the call to free() and the creation of the
PseudoTcpSocket it works almost all the time, which strengthens the theory
that there’s a race condition. However, this feels like a very hackish way
of solving it

I’ve also tried not calling free() and just trying to re-use
selectedPair.getLocalCandidate().getDatagramSocket() but doesn’t work
either. My theory is that PseudoTCPSocket then mixes the stun messages with
the TCP_SYN_SENT somehow (I guess there must be a reason why IcePseudoTcp
calls free() and then creates a new DatagramSocket).

This is just a guess from my side and I might very well be wrong. My
questions are:

1. Could my theory be correct or have I missed something fundamentally
on how ICE works?

2. How would you recommend me solving this? I need to somehow
synchronize the creation of the PseudoTcpSocket.

Thanks in advance!

Kind Regards

Carl Hasselskog

Degoo Backup AB

carl@degoo.com

Phone: +46 73 070 1821

http://degoo.com

http://twitter.com/#!/CarlHasselskog

--
Emil Ivov, Ph.D. 67000 Strasbourg,
Project Lead France
Jitsi
emcho@jitsi.org PHONE: +33.1.77.62.43.30
http://jitsi.org FAX: +33.1.77.62.47.31


#4

Thanks, I will try that! So I should just get the DatagramSocket from selectedPair.getLocalCandidate().getDatagramSocket() and let PseudoTcpSocket use that (and not call free())? Let me know if I can be of any assistance to Pawel.

Regards
Carl

···

-----Original Message-----

From: Emil Ivov [mailto:emcho@jitsi.org]

Sent: den 9 augusti 2012 18:01
To: dev@jitsi.java.net
Subject: [jitsi-dev] Re: Race condition

Hey Carl,
Hey Carl,

On Thu, Aug 9, 2012 at 12:58 PM, Carl Hasselskog <carl@degoo.com> wrote:

Hi,

I think I've run into a race condition when trying create a
PseudoTCP-stream. I've created XMPP-signalling and both the local and
the remote Agent successfully enters both COMPLETED and TERMINATED
state. The problem occurs when I try to create the PseudoTCP-streams
after entering TERMINATED state. I've tried to create it the same way
as it is done in IcePseudoTcp.

Unfortunately that example does not do it properly. Sorry about that.
Pawel is currently working on correcting it (and all the bugs he's stumbling upon while doing so :wink: ). The thing is that, in order to use ice4j, one has to use the sockets that it creates. ice4j also creates a master socket and a stun filtering socket. It then uses the stun socket so that it can continue ICE processing while the application continues exchanging data.

I.e. by calling agent.free() and then creating new
DatagramSocket-instances using the transport addresses in the
candidate pair.

You should only call free() once you are done with your session and you are not going to use the sockets any more.

I believe the above are addressing all your comments below and your next mail..

Could you please let me know if I missed something?

Thanks,
Emil

When I try to do this it works sometimes and sometimes not, which
leads me to believe that there's some concurrency issue.

I haven't found the exact problem but my theory is that there's a race
condition in the call of free() and the creation of the new DatagramSocket.
Something like this:

1. The remote peer enters TERMINATED state and calls free(), creates a
new DatagramSocket and then calls Connect on the new PseudoTcpSocket.

2. The local peer hasn't called free() yet and therefore receives the
TCP_SYN_SENT from the local peer on the DatagramSocket instance used
by the connectivity checker.

3. The local peer enters TERMINATED state, closes the old
DatagramSocket (through free), creates a new one and calls Accept on
the new PseudoTcpSocket.

4. Both peers timeout because the TCP_SYN_SENT has been lost.

I've attached a log-file for one of the execution attempts that failed.

When I sleep for 1s between the call to free() and the creation of the
PseudoTcpSocket it works almost all the time, which strengthens the
theory that there's a race condition. However, this feels like a very
hackish way of solving it

I've also tried not calling free() and just trying to re-use
selectedPair.getLocalCandidate().getDatagramSocket() but doesn't work
either. My theory is that PseudoTCPSocket then mixes the stun messages
with the TCP_SYN_SENT somehow (I guess there must be a reason why
IcePseudoTcp calls free() and then creates a new DatagramSocket).

This is just a guess from my side and I might very well be wrong. My
questions are:

1. Could my theory be correct or have I missed something fundamentally
on how ICE works?

2. How would you recommend me solving this? I need to somehow
synchronize the creation of the PseudoTcpSocket.

Thanks in advance!

Kind Regards

Carl Hasselskog

Degoo Backup AB

carl@degoo.com

Phone: +46 73 070 1821

http://degoo.com

http://twitter.com/#!/CarlHasselskog

--
Emil Ivov, Ph.D. 67000 Strasbourg,
Project Lead France
Jitsi
emcho@jitsi.org PHONE: +33.1.77.62.43.30
http://jitsi.org FAX: +33.1.77.62.47.31


#5

Hi,
I've now tried using selectedPair.getLocalCandidate().getDatagramSocket() to get the DatagramSocket and not calling iceAgent.free(). Unfortunately I get timeouts in Accept and Connect in PseudoTCPSocket (see attached log). To me it looks like the TCP_SYN_SENT is being directed to StunStack instead of the PseudoTCPSocket. I base that on this part of the log:

10:02:57.697 Fin: org.ice4j.pseudotcp.PseudoTCPBase.Connect() State: TCP_SYN_SENT
10:02:57.698 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.queue() enqueued send segment seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() [cwnd: 360 nWindow: 4 nInFlight: 0 nAvailable: 4 nQueued: 4 nEmpty: 92156 ssthresh: 61440]
10:02:57.700 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() TRANSMIT SEGMENT seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.packet() <-- <CONV=0><FLG=2><SEQ=0:4><ACK=0><WND=61440><SCALE=0><TS=261014052><TSR=0><LEN=4>
10:02:57.701 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.TcpWritePacket() write packet to network 28
10:02:57.701 Finaste: org.ice4j.stack.Connector.run() received datagram
10:02:57.705 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() nAvailable == 0: quit
10:02:57.705 Finaste: org.ice4j.stack.MessageQueue.add() Adding raw message to queue.
10:02:57.706 Finaste: org.ice4j.stack.MessageProcessor.run() Dispatching a StunMessageEvent.
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent() Received a message on /2001:6b0:1:1041:d843:8fd0:ab52:d8f4:3031/udp of type:0
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent() parsing request
10:02:57.707 Finaste: org.ice4j.stack.StunStack.handleMessageEvent() existing transaction not found

Any idea on what might be causing this?

Regards
Carl

ice3.log (176 KB)

···

-----Original Message-----

From: Emil Ivov [mailto:emcho@jitsi.org]

Sent: den 9 augusti 2012 18:01
To: dev@jitsi.java.net
Subject: [jitsi-dev] Re: Race condition

Hey Carl,
Hey Carl,

On Thu, Aug 9, 2012 at 12:58 PM, Carl Hasselskog <carl@degoo.com> wrote:

Hi,

I think I've run into a race condition when trying create a
PseudoTCP-stream. I've created XMPP-signalling and both the local and
the remote Agent successfully enters both COMPLETED and TERMINATED
state. The problem occurs when I try to create the PseudoTCP-streams
after entering TERMINATED state. I've tried to create it the same way
as it is done in IcePseudoTcp.

Unfortunately that example does not do it properly. Sorry about that.
Pawel is currently working on correcting it (and all the bugs he's stumbling upon while doing so :wink: ). The thing is that, in order to use ice4j, one has to use the sockets that it creates. ice4j also creates a master socket and a stun filtering socket. It then uses the stun socket so that it can continue ICE processing while the application continues exchanging data.

I.e. by calling agent.free() and then creating new
DatagramSocket-instances using the transport addresses in the
candidate pair.

You should only call free() once you are done with your session and you are not going to use the sockets any more.

I believe the above are addressing all your comments below and your next mail..

Could you please let me know if I missed something?

Thanks,
Emil

When I try to do this it works sometimes and sometimes not, which
leads me to believe that there's some concurrency issue.

I haven't found the exact problem but my theory is that there's a race
condition in the call of free() and the creation of the new DatagramSocket.
Something like this:

1. The remote peer enters TERMINATED state and calls free(), creates a
new DatagramSocket and then calls Connect on the new PseudoTcpSocket.

2. The local peer hasn't called free() yet and therefore receives the
TCP_SYN_SENT from the local peer on the DatagramSocket instance used
by the connectivity checker.

3. The local peer enters TERMINATED state, closes the old
DatagramSocket (through free), creates a new one and calls Accept on
the new PseudoTcpSocket.

4. Both peers timeout because the TCP_SYN_SENT has been lost.

I've attached a log-file for one of the execution attempts that failed.

When I sleep for 1s between the call to free() and the creation of the
PseudoTcpSocket it works almost all the time, which strengthens the
theory that there's a race condition. However, this feels like a very
hackish way of solving it

I've also tried not calling free() and just trying to re-use
selectedPair.getLocalCandidate().getDatagramSocket() but doesn't work
either. My theory is that PseudoTCPSocket then mixes the stun messages
with the TCP_SYN_SENT somehow (I guess there must be a reason why
IcePseudoTcp calls free() and then creates a new DatagramSocket).

This is just a guess from my side and I might very well be wrong. My
questions are:

1. Could my theory be correct or have I missed something fundamentally
on how ICE works?

2. How would you recommend me solving this? I need to somehow
synchronize the creation of the PseudoTcpSocket.

Thanks in advance!

Kind Regards

Carl Hasselskog

Degoo Backup AB

carl@degoo.com

Phone: +46 73 070 1821

http://degoo.com

http://twitter.com/#!/CarlHasselskog

--
Emil Ivov, Ph.D. 67000 Strasbourg,
Project Lead France
Jitsi
emcho@jitsi.org PHONE: +33.1.77.62.43.30
http://jitsi.org FAX: +33.1.77.62.47.31


#6

Hi,

Hi,
I've now tried using selectedPair.getLocalCandidate().getDatagramSocket()
to get the DatagramSocket and not calling iceAgent.free(). Unfortunately I
get timeouts in Accept and Connect in PseudoTCPSocket (see attached log).
To me it looks like the TCP_SYN_SENT is being directed to StunStack instead
of the PseudoTCPSocket. I base that on this part of the log:

10:02:57.697 Fin: org.ice4j.pseudotcp.PseudoTCPBase.Connect() State:
TCP_SYN_SENT
10:02:57.698 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.queue() enqueued
send segment seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() [cwnd:
360 nWindow: 4 nInFlight: 0 nAvailable: 4 nQueued: 4 nEmpty: 92156
ssthresh: 61440]
10:02:57.700 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend()
TRANSMIT SEGMENT seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.packet() <--
<CONV=0><FLG=2><SEQ=0:4><ACK=0><WND=61440><SCALE=0><TS=261014052><TSR=0><LEN=4>
10:02:57.701 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.TcpWritePacket()
write packet to network 28
10:02:57.701 Finaste: org.ice4j.stack.Connector.run() received datagram
10:02:57.705 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend()
nAvailable == 0: quit
10:02:57.705 Finaste: org.ice4j.stack.MessageQueue.add() Adding raw
message to queue.
10:02:57.706 Finaste: org.ice4j.stack.MessageProcessor.run() Dispatching a
StunMessageEvent.
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent()
Received a message on /2001:6b0:1:1041:d843:8fd0:ab52:d8f4:3031/udp of
type:0
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent()
parsing request
10:02:57.707 Finaste: org.ice4j.stack.StunStack.handleMessageEvent()
existing transaction not found

Any idea on what might be causing this?

Yes that's because of STUN packet filter. Please try to use
PseudoTcpSockets with conversation number that will have it's two most
significant bit not equal to zero. Conversation number is passed to the
constructor as first argument. We are still working on fixing properly that
issue.

Also please set MTU as I don't know how to figure out that the packets are
too long to transmit and they do get truncated at some point when are used
with sockets provided by ICE Agent.

There is at least one more bug I do know about and I'm tracking it down.
Also I've commited some changes which introduce PseudoTcpSocketImpl that
extends java.net.SocketImpl as I'm trying to use it with Apache HttpClient.
Please use PseudoTcpSocketImpl class now.

The example IcePseudoTcp is changed to use ICE datagram sockets.

···

2012/8/10 Carl Hasselskog <carl@degoo.com>

--
Regards, Paweł Domas


#7

Thanks, that solved it! At first I had some problems because I was setting the leftmost bit, not the most significant bit (i.e. the sign-bit). Now I use 0b0100_0000_0000_0000_0000_0000_0000_0000 and have the MTU set to 1500 (that should work for most cases, right?) and it works well in my tests. The message arrives at the other peer but I still get some errors in the log. This is repeatedly written to the log after the peers reach TCP_ESTABLISHED state:

11:30:58.220 Fin: org.ice4j.stack.NetAccessManager.handleError() The following error occurred with an incoming message:
org.ice4j.StunException: The given binary array does not seem to contain a whole StunMessage: given 28 bytes of UNKNOWN-MESSAGE but expecting 44
               at org.ice4j.message.Message.decode(Message.java:1041)
               at org.ice4j.stack.MessageProcessor.run(MessageProcessor.java:139)
               at java.lang.Thread.run(Thread.java:722)

Regards
Carl

···

From: Paweł Domas [mailto:paweldomas@gmail.com]

Sent: den 10 augusti 2012 11:04
To: dev@jitsi.java.net
Subject: [jitsi-dev] Re: Race condition

Hi,
2012/8/10 Carl Hasselskog <carl@degoo.com<mailto:carl@degoo.com>>
Hi,
I've now tried using selectedPair.getLocalCandidate().getDatagramSocket() to get the DatagramSocket and not calling iceAgent.free(). Unfortunately I get timeouts in Accept and Connect in PseudoTCPSocket (see attached log). To me it looks like the TCP_SYN_SENT is being directed to StunStack instead of the PseudoTCPSocket. I base that on this part of the log:

10:02:57.697 Fin: org.ice4j.pseudotcp.PseudoTCPBase.Connect() State: TCP_SYN_SENT
10:02:57.698 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.queue() enqueued send segment seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() [cwnd: 360 nWindow: 4 nInFlight: 0 nAvailable: 4 nQueued: 4 nEmpty: 92156 ssthresh: 61440]
10:02:57.700 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() TRANSMIT SEGMENT seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.packet() <-- <CONV=0><FLG=2><SEQ=0:4><ACK=0><WND=61440><SCALE=0><TS=261014052><TSR=0><LEN=4>
10:02:57.701 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.TcpWritePacket() write packet to network 28
10:02:57.701 Finaste: org.ice4j.stack.Connector.run() received datagram
10:02:57.705 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() nAvailable == 0: quit
10:02:57.705 Finaste: org.ice4j.stack.MessageQueue.add() Adding raw message to queue.
10:02:57.706 Finaste: org.ice4j.stack.MessageProcessor.run() Dispatching a StunMessageEvent.
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent() Received a message on /2001:6b0:1:1041:d843:8fd0:ab52:d8f4:3031/udp of type:0
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent() parsing request
10:02:57.707 Finaste: org.ice4j.stack.StunStack.handleMessageEvent() existing transaction not found

Any idea on what might be causing this?

Yes that's because of STUN packet filter. Please try to use PseudoTcpSockets with conversation number that will have it's two most significant bit not equal to zero. Conversation number is passed to the constructor as first argument. We are still working on fixing properly that issue.

Also please set MTU as I don't know how to figure out that the packets are too long to transmit and they do get truncated at some point when are used with sockets provided by ICE Agent.

There is at least one more bug I do know about and I'm tracking it down. Also I've commited some changes which introduce PseudoTcpSocketImpl that extends java.net.SocketImpl as I'm trying to use it with Apache HttpClient. Please use PseudoTcpSocketImpl class now.

The example IcePseudoTcp is changed to use ICE datagram sockets.

--
Regards, Paweł Domas


#8

Hi,
I'm now running into a bit strange issue when testing the pseudo tcp code. I've written a test that has two threads. One that repeatedly writes messages of size x bytes on the output stream of the PseudoTcpSocketImpl instance and one that repeatedly reads them. It works well as long as the message size is <4096 bytes. If the message is >=4096 bytes then some of the read messages don't match the written one. I've tried to find some patterns in how the messages differ with regards to message size. I've found the following:
Message size: 4100 - 29th message is different (difference starts at 1348th byte)
Message size: 4150 - 1st message is different (difference starts at 4093rd byte)
Message size: 4200 - 1st message is different (difference starts at 2747th byte)
Message size: 5000 - 1st message is different (difference starts at 2747th byte)

I am not able to find any pattern out of this. Do you guys have any ideas?

Regards
Carl

···

From: Paweł Domas [mailto:paweldomas@gmail.com]

Sent: den 10 augusti 2012 11:04
To: dev@jitsi.java.net
Subject: [jitsi-dev] Re: Race condition

Hi,
2012/8/10 Carl Hasselskog <carl@degoo.com<mailto:carl@degoo.com>>
Hi,
I've now tried using selectedPair.getLocalCandidate().getDatagramSocket() to get the DatagramSocket and not calling iceAgent.free(). Unfortunately I get timeouts in Accept and Connect in PseudoTCPSocket (see attached log). To me it looks like the TCP_SYN_SENT is being directed to StunStack instead of the PseudoTCPSocket. I base that on this part of the log:

10:02:57.697 Fin: org.ice4j.pseudotcp.PseudoTCPBase.Connect() State: TCP_SYN_SENT
10:02:57.698 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.queue() enqueued send segment seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() [cwnd: 360 nWindow: 4 nInFlight: 0 nAvailable: 4 nQueued: 4 nEmpty: 92156 ssthresh: 61440]
10:02:57.700 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() TRANSMIT SEGMENT seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.packet() <-- <CONV=0><FLG=2><SEQ=0:4><ACK=0><WND=61440><SCALE=0><TS=261014052><TSR=0><LEN=4>
10:02:57.701 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.TcpWritePacket() write packet to network 28
10:02:57.701 Finaste: org.ice4j.stack.Connector.run() received datagram
10:02:57.705 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() nAvailable == 0: quit
10:02:57.705 Finaste: org.ice4j.stack.MessageQueue.add() Adding raw message to queue.
10:02:57.706 Finaste: org.ice4j.stack.MessageProcessor.run() Dispatching a StunMessageEvent.
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent() Received a message on /2001:6b0:1:1041:d843:8fd0:ab52:d8f4:3031/udp of type:0
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent() parsing request
10:02:57.707 Finaste: org.ice4j.stack.StunStack.handleMessageEvent() existing transaction not found

Any idea on what might be causing this?

Yes that's because of STUN packet filter. Please try to use PseudoTcpSockets with conversation number that will have it's two most significant bit not equal to zero. Conversation number is passed to the constructor as first argument. We are still working on fixing properly that issue.

Also please set MTU as I don't know how to figure out that the packets are too long to transmit and they do get truncated at some point when are used with sockets provided by ICE Agent.

There is at least one more bug I do know about and I'm tracking it down. Also I've commited some changes which introduce PseudoTcpSocketImpl that extends java.net.SocketImpl as I'm trying to use it with Apache HttpClient. Please use PseudoTcpSocketImpl class now.

The example IcePseudoTcp is changed to use ICE datagram sockets.

--
Regards, Paweł Domas


#9

Hi Pawel, all,

I have just updated (svn revision #330 (Ice4j) / #9803 (Jitsi)) the filter to detect if a received packet is a STUN packet (detection of MAGIC_COOKIE and packet header length field).

Can you check if it solves the problem with the conversation number equal to 0?

Regards,
Vincent

···

On 8/10/12 11:03 AM, Pawe� Domas wrote:

Hi,

2012/8/10 Carl Hasselskog <carl@degoo.com>

Hi,
I've now tried using selectedPair.getLocalCandidate().getDatagramSocket()
to get the DatagramSocket and not calling iceAgent.free(). Unfortunately I
get timeouts in Accept and Connect in PseudoTCPSocket (see attached log).
To me it looks like the TCP_SYN_SENT is being directed to StunStack instead
of the PseudoTCPSocket. I base that on this part of the log:

10:02:57.697 Fin: org.ice4j.pseudotcp.PseudoTCPBase.Connect() State:
TCP_SYN_SENT
10:02:57.698 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.queue() enqueued
send segment seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() [cwnd:
360 nWindow: 4 nInFlight: 0 nAvailable: 4 nQueued: 4 nEmpty: 92156
ssthresh: 61440]
10:02:57.700 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend()
TRANSMIT SEGMENT seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.packet() <--
  <CONV=0><FLG=2><SEQ=0:4><ACK=0><WND=61440><SCALE=0><TS=261014052><TSR=0><LEN=4>
10:02:57.701 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.TcpWritePacket()
write packet to network 28
10:02:57.701 Finaste: org.ice4j.stack.Connector.run() received datagram
10:02:57.705 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend()
nAvailable == 0: quit
10:02:57.705 Finaste: org.ice4j.stack.MessageQueue.add() Adding raw
message to queue.
10:02:57.706 Finaste: org.ice4j.stack.MessageProcessor.run() Dispatching a
StunMessageEvent.
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent()
Received a message on /2001:6b0:1:1041:d843:8fd0:ab52:d8f4:3031/udp of
type:0
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent()
parsing request
10:02:57.707 Finaste: org.ice4j.stack.StunStack.handleMessageEvent()
existing transaction not found

Any idea on what might be causing this?

Yes that's because of STUN packet filter. Please try to use
PseudoTcpSockets with conversation number that will have it's two most
significant bit not equal to zero. Conversation number is passed to the
constructor as first argument. We are still working on fixing properly that
issue.

Also please set MTU as I don't know how to figure out that the packets are
too long to transmit and they do get truncated at some point when are used
with sockets provided by ICE Agent.

There is at least one more bug I do know about and I'm tracking it down.
Also I've commited some changes which introduce PseudoTcpSocketImpl that
extends java.net.SocketImpl as I'm trying to use it with Apache HttpClient.
Please use PseudoTcpSocketImpl class now.

The example IcePseudoTcp is changed to use ICE datagram sockets.

--
Vincent Lucas, Ph.D. Jitsi developer
chenzo@jitsi.org http://jitsi.org


#10

I just realized that the message size I provided is not correct. I serialize messages using Protocol Buffers so the actual data being sent is 5 bytes more per message (due to some overhead from PB)

/Carl

···

From: Carl Hasselskog [mailto:carl@degoo.com]

Sent: den 12 augusti 2012 17:01
To: dev@jitsi.java.net
Subject: [jitsi-dev] Re: Race condition

Hi,
I'm now running into a bit strange issue when testing the pseudo tcp code. I've written a test that has two threads. One that repeatedly writes messages of size x bytes on the output stream of the PseudoTcpSocketImpl instance and one that repeatedly reads them. It works well as long as the message size is <4096 bytes. If the message is >=4096 bytes then some of the read messages don't match the written one. I've tried to find some patterns in how the messages differ with regards to message size. I've found the following:
Message size: 4100 - 29th message is different (difference starts at 1348th byte)
Message size: 4150 - 1st message is different (difference starts at 4093rd byte)
Message size: 4200 - 1st message is different (difference starts at 2747th byte)
Message size: 5000 - 1st message is different (difference starts at 2747th byte)

I am not able to find any pattern out of this. Do you guys have any ideas?

Regards
Carl

From: Paweł Domas [mailto:paweldomas@gmail.com]<mailto:[mailto:paweldomas@gmail.com]>

Sent: den 10 augusti 2012 11:04
To: dev@jitsi.java.net<mailto:dev@jitsi.java.net>
Subject: [jitsi-dev] Re: Race condition

Hi,
2012/8/10 Carl Hasselskog <carl@degoo.com<mailto:carl@degoo.com>>
Hi,
I've now tried using selectedPair.getLocalCandidate().getDatagramSocket() to get the DatagramSocket and not calling iceAgent.free(). Unfortunately I get timeouts in Accept and Connect in PseudoTCPSocket (see attached log). To me it looks like the TCP_SYN_SENT is being directed to StunStack instead of the PseudoTCPSocket. I base that on this part of the log:

10:02:57.697 Fin: org.ice4j.pseudotcp.PseudoTCPBase.Connect() State: TCP_SYN_SENT
10:02:57.698 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.queue() enqueued send segment seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() [cwnd: 360 nWindow: 4 nInFlight: 0 nAvailable: 4 nQueued: 4 nEmpty: 92156 ssthresh: 61440]
10:02:57.700 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() TRANSMIT SEGMENT seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.packet() <-- <CONV=0><FLG=2><SEQ=0:4><ACK=0><WND=61440><SCALE=0><TS=261014052><TSR=0><LEN=4>
10:02:57.701 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.TcpWritePacket() write packet to network 28
10:02:57.701 Finaste: org.ice4j.stack.Connector.run() received datagram
10:02:57.705 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() nAvailable == 0: quit
10:02:57.705 Finaste: org.ice4j.stack.MessageQueue.add() Adding raw message to queue.
10:02:57.706 Finaste: org.ice4j.stack.MessageProcessor.run() Dispatching a StunMessageEvent.
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent() Received a message on /2001:6b0:1:1041:d843:8fd0:ab52:d8f4:3031/udp of type:0
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent() parsing request
10:02:57.707 Finaste: org.ice4j.stack.StunStack.handleMessageEvent() existing transaction not found

Any idea on what might be causing this?

Yes that's because of STUN packet filter. Please try to use PseudoTcpSockets with conversation number that will have it's two most significant bit not equal to zero. Conversation number is passed to the constructor as first argument. We are still working on fixing properly that issue.

Also please set MTU as I don't know how to figure out that the packets are too long to transmit and they do get truncated at some point when are used with sockets provided by ICE Agent.

There is at least one more bug I do know about and I'm tracking it down. Also I've commited some changes which introduce PseudoTcpSocketImpl that extends java.net.SocketImpl as I'm trying to use it with Apache HttpClient. Please use PseudoTcpSocketImpl class now.

The example IcePseudoTcp is changed to use ICE datagram sockets.

--
Regards, Paweł Domas


#11

Hi,

···

2012/8/21 Vincent Lucas <chenzo@jitsi.org>:

Hi Pawel, all,

I have just updated (svn revision #330 (Ice4j) / #9803 (Jitsi)) the filter
to detect if a received packet is a STUN packet (detection of MAGIC_COOKIE
and packet header length field).

Can you check if it solves the problem with the conversation number equal to
0?

Regards,
Vincent

On 8/10/12 11:03 AM, Paweł Domas wrote:

Hi,

2012/8/10 Carl Hasselskog <carl@degoo.com>

Hi,
I've now tried using selectedPair.getLocalCandidate().getDatagramSocket()
to get the DatagramSocket and not calling iceAgent.free(). Unfortunately
I
get timeouts in Accept and Connect in PseudoTCPSocket (see attached log).
To me it looks like the TCP_SYN_SENT is being directed to StunStack
instead
of the PseudoTCPSocket. I base that on this part of the log:

10:02:57.697 Fin: org.ice4j.pseudotcp.PseudoTCPBase.Connect() State:
TCP_SYN_SENT
10:02:57.698 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.queue() enqueued
send segment seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() [cwnd:
360 nWindow: 4 nInFlight: 0 nAvailable: 4 nQueued: 4 nEmpty: 92156
ssthresh: 61440]
10:02:57.700 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend()
TRANSMIT SEGMENT seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.packet() <--

<CONV=0><FLG=2><SEQ=0:4><ACK=0><WND=61440><SCALE=0><TS=261014052><TSR=0><LEN=4>
10:02:57.701 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.TcpWritePacket()
write packet to network 28
10:02:57.701 Finaste: org.ice4j.stack.Connector.run() received datagram
10:02:57.705 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend()
nAvailable == 0: quit
10:02:57.705 Finaste: org.ice4j.stack.MessageQueue.add() Adding raw
message to queue.
10:02:57.706 Finaste: org.ice4j.stack.MessageProcessor.run() Dispatching
a
StunMessageEvent.
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent()
Received a message on /2001:6b0:1:1041:d843:8fd0:ab52:d8f4:3031/udp of
type:0
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent()
parsing request
10:02:57.707 Finaste: org.ice4j.stack.StunStack.handleMessageEvent()
existing transaction not found

Any idea on what might be causing this?

Yes that's because of STUN packet filter. Please try to use
PseudoTcpSockets with conversation number that will have it's two most
significant bit not equal to zero. Conversation number is passed to the
constructor as first argument. We are still working on fixing properly
that
issue.

Also please set MTU as I don't know how to figure out that the packets are
too long to transmit and they do get truncated at some point when are used
with sockets provided by ICE Agent.

There is at least one more bug I do know about and I'm tracking it down.
Also I've commited some changes which introduce PseudoTcpSocketImpl that
extends java.net.SocketImpl as I'm trying to use it with Apache
HttpClient.
Please use PseudoTcpSocketImpl class now.

The example IcePseudoTcp is changed to use ICE datagram sockets.

--
Vincent Lucas, Ph.D. Jitsi developer
chenzo@jitsi.org http://jitsi.org

Sure, thanks !

--
Regards, Paweł Domas


#12

I think I've found the bug. In PseudoTCPBase.Recv(byte[] buffer, int offset, int len) the offset parameter is ignored. So if you read from the socket like this:
public static int read(InputStream in, byte[] b, int off, int len)
      throws IOException {

    int total = 0;
    while (total < len) {
      int result = in.read(b, off + total, len - total);
      if (result == -1) {
        break;
      }
      total += result;
    }
    return total;
  }

Then the data in b gets overwritten if in.read(b,off+total,len-total)gets called more than once, because it doesn't take offset into account when reading from PseudoTcpSocketImpl's InputStream.

I also found a bug in PseudoTcpOutputStream. More specifically in this method:

public void write(int b) throws IOException
        {
            byte[] bytes = new byte[1];
            bytes[0] = (byte) b;
            write(b);
        }

The last line goes into infinite recursion and should be changed to write(bytes);

Regards
Carl

···

From: Carl Hasselskog [mailto:carl@degoo.com]

Sent: den 12 augusti 2012 17:18
To: dev@jitsi.java.net
Subject: [jitsi-dev] Re: Race condition

I just realized that the message size I provided is not correct. I serialize messages using Protocol Buffers so the actual data being sent is 5 bytes more per message (due to some overhead from PB)

/Carl

From: Carl Hasselskog [mailto:carl@degoo.com]<mailto:[mailto:carl@degoo.com]>

Sent: den 12 augusti 2012 17:01
To: dev@jitsi.java.net<mailto:dev@jitsi.java.net>
Subject: [jitsi-dev] Re: Race condition

Hi,
I'm now running into a bit strange issue when testing the pseudo tcp code. I've written a test that has two threads. One that repeatedly writes messages of size x bytes on the output stream of the PseudoTcpSocketImpl instance and one that repeatedly reads them. It works well as long as the message size is <4096 bytes. If the message is >=4096 bytes then some of the read messages don't match the written one. I've tried to find some patterns in how the messages differ with regards to message size. I've found the following:
Message size: 4100 - 29th message is different (difference starts at 1348th byte)
Message size: 4150 - 1st message is different (difference starts at 4093rd byte)
Message size: 4200 - 1st message is different (difference starts at 2747th byte)
Message size: 5000 - 1st message is different (difference starts at 2747th byte)

I am not able to find any pattern out of this. Do you guys have any ideas?

Regards
Carl

From: Paweł Domas [mailto:paweldomas@gmail.com]<mailto:[mailto:paweldomas@gmail.com]>

Sent: den 10 augusti 2012 11:04
To: dev@jitsi.java.net<mailto:dev@jitsi.java.net>
Subject: [jitsi-dev] Re: Race condition

Hi,
2012/8/10 Carl Hasselskog <carl@degoo.com<mailto:carl@degoo.com>>
Hi,
I've now tried using selectedPair.getLocalCandidate().getDatagramSocket() to get the DatagramSocket and not calling iceAgent.free(). Unfortunately I get timeouts in Accept and Connect in PseudoTCPSocket (see attached log). To me it looks like the TCP_SYN_SENT is being directed to StunStack instead of the PseudoTCPSocket. I base that on this part of the log:

10:02:57.697 Fin: org.ice4j.pseudotcp.PseudoTCPBase.Connect() State: TCP_SYN_SENT
10:02:57.698 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.queue() enqueued send segment seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() [cwnd: 360 nWindow: 4 nInFlight: 0 nAvailable: 4 nQueued: 4 nEmpty: 92156 ssthresh: 61440]
10:02:57.700 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() TRANSMIT SEGMENT seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.packet() <-- <CONV=0><FLG=2><SEQ=0:4><ACK=0><WND=61440><SCALE=0><TS=261014052><TSR=0><LEN=4>
10:02:57.701 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.TcpWritePacket() write packet to network 28
10:02:57.701 Finaste: org.ice4j.stack.Connector.run() received datagram
10:02:57.705 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() nAvailable == 0: quit
10:02:57.705 Finaste: org.ice4j.stack.MessageQueue.add() Adding raw message to queue.
10:02:57.706 Finaste: org.ice4j.stack.MessageProcessor.run() Dispatching a StunMessageEvent.
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent() Received a message on /2001:6b0:1:1041:d843:8fd0:ab52:d8f4:3031/udp of type:0
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent() parsing request
10:02:57.707 Finaste: org.ice4j.stack.StunStack.handleMessageEvent() existing transaction not found

Any idea on what might be causing this?

Yes that's because of STUN packet filter. Please try to use PseudoTcpSockets with conversation number that will have it's two most significant bit not equal to zero. Conversation number is passed to the constructor as first argument. We are still working on fixing properly that issue.

Also please set MTU as I don't know how to figure out that the packets are too long to transmit and they do get truncated at some point when are used with sockets provided by ICE Agent.

There is at least one more bug I do know about and I'm tracking it down. Also I've commited some changes which introduce PseudoTcpSocketImpl that extends java.net.SocketImpl as I'm trying to use it with Apache HttpClient. Please use PseudoTcpSocketImpl class now.

The example IcePseudoTcp is changed to use ICE datagram sockets.

--
Regards, Paweł Domas


#13

Hi,

Hi,

Hi Pawel, all,

I have just updated (svn revision #330 (Ice4j) / #9803 (Jitsi)) the filter
to detect if a received packet is a STUN packet (detection of MAGIC_COOKIE
and packet header length field).

Can you check if it solves the problem with the conversation number equal to
0?

Regards,
Vincent

Hi,

Hi,
I've now tried using selectedPair.getLocalCandidate().getDatagramSocket()
to get the DatagramSocket and not calling iceAgent.free(). Unfortunately
I
get timeouts in Accept and Connect in PseudoTCPSocket (see attached log).
To me it looks like the TCP_SYN_SENT is being directed to StunStack
instead
of the PseudoTCPSocket. I base that on this part of the log:

10:02:57.697 Fin: org.ice4j.pseudotcp.PseudoTCPBase.Connect() State:
TCP_SYN_SENT
10:02:57.698 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.queue() enqueued
send segment seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() [cwnd:
360 nWindow: 4 nInFlight: 0 nAvailable: 4 nQueued: 4 nEmpty: 92156
ssthresh: 61440]
10:02:57.700 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend()
TRANSMIT SEGMENT seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.packet() <--

<CONV=0><FLG=2><SEQ=0:4><ACK=0><WND=61440><SCALE=0><TS=261014052><TSR=0><LEN=4>
10:02:57.701 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.TcpWritePacket()
write packet to network 28
10:02:57.701 Finaste: org.ice4j.stack.Connector.run() received datagram
10:02:57.705 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend()
nAvailable == 0: quit
10:02:57.705 Finaste: org.ice4j.stack.MessageQueue.add() Adding raw
message to queue.
10:02:57.706 Finaste: org.ice4j.stack.MessageProcessor.run() Dispatching
a
StunMessageEvent.
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent()
Received a message on /2001:6b0:1:1041:d843:8fd0:ab52:d8f4:3031/udp of
type:0
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent()
parsing request
10:02:57.707 Finaste: org.ice4j.stack.StunStack.handleMessageEvent()
existing transaction not found

Any idea on what might be causing this?

Yes that's because of STUN packet filter. Please try to use
PseudoTcpSockets with conversation number that will have it's two most
significant bit not equal to zero. Conversation number is passed to the
constructor as first argument. We are still working on fixing properly
that
issue.

Also please set MTU as I don't know how to figure out that the packets are
too long to transmit and they do get truncated at some point when are used
with sockets provided by ICE Agent.

There is at least one more bug I do know about and I'm tracking it down.
Also I've commited some changes which introduce PseudoTcpSocketImpl that
extends java.net.SocketImpl as I'm trying to use it with Apache
HttpClient.
Please use PseudoTcpSocketImpl class now.

The example IcePseudoTcp is changed to use ICE datagram sockets.

--
Vincent Lucas, Ph.D. Jitsi developer
chenzo@jitsi.org http://jitsi.org

Sure, thanks !

--
Regards, Paweł Domas

So it would work, but a small change is required:

// Checks if the length of the data correspond to the length
// field of the STUN header. The message length field of the
// STUN header does not include the 20-byte of the STUN header.
int total_header_length
    = ((((int)data[2]) & 0xff) << 8) + (((int) data[3]) & 0xff);
boolean isHeaderLengthValid = (length == total_header_length);

As you wrote in comment message length field does not include 20 bytes
of the header itself. So there was missing +20 to total_header_length
and then it's working.

However I found some other misterious behaviour and I don't know what
is causing it.
It is about packet marked by Wireshark as STUN CLASSIC and only some of them.
In Wireshark I get data like this(HEX):
00 01 00 24 6c 46 4a 44 32 71 54 38 49 2f 36 56
4f 32 34 7a 00 06 00 20 62 66 64 67 6f 73 33 30
61 65 63 36 61 63 65 72 68 4f 37 44 74 59 50 33
49 6f 39 54 38 75 46 73

And the message length is 0x24 that is 36 + 20 = 56 and it is correct.

But in StunDatagramPacketFilter.accept() method this packet is
truncated to length of 24(p.getLength() = 24), but header field still
says it's 36 and it passes that packet to PseudoTCP in my case. So I
print whole packet data at that point and it looks like this:

00 01 00 24 6c 46 4a 44 32 71 54 38 49 2f 36 56
4F 32 34 7A 00 06 00 20 [here ends 24] and the rest of it is some
random buffer data, as it should probably:
47:45:54:20:2f:73:72:63:2f:31:33:34:35:36:32:32:36:36:35:33...

So the problem is that some packets are truncated to that size and I
don't know what may be causing this. Is the DatagramPacket overloaded
somewhere or recreated after reading from the network ?

···

2012/8/21 Paweł Domas <paweldomas@gmail.com>:

2012/8/21 Vincent Lucas <chenzo@jitsi.org>:

On 8/10/12 11:03 AM, Paweł Domas wrote:

2012/8/10 Carl Hasselskog <carl@degoo.com>

--
Regards, Paweł Domas


#14

Hi,

···

2012/8/12 Carl Hasselskog <carl@degoo.com>

I think I've found the bug. In PseudoTCPBase.Recv(byte[] buffer, int
offset, int len) the offset parameter is ignored. So if you read from the
socket like this:****

public static int read(InputStream in, byte[] b, int off, int len)****

      throws IOException {****

** **

    int total = 0;****

    while (total < len) {****

      int result = in.read(b, off + total, len - total);****

      if (result == -1) {****

        break;****

      }****

      total += result;****

    }****

    return total;****

  }****

** **

Then the data in b gets overwritten if in.read(b,off+total,len-total)gets
called more than once, because it doesn't take offset into account when
reading from PseudoTcpSocketImpl's InputStream.****

** **

I also found a bug in PseudoTcpOutputStream. More specifically in this
method:****

** **

public void write(int b) throws IOException****

        {****

            byte[] bytes = new byte[1];****

            bytes[0] = (byte) b;****

            write(b);****

        }****

** **

The last line goes into infinite recursion and should be changed to
write(bytes);****

** **

Regards****

Carl****

** **

*From:* Carl Hasselskog [mailto:carl@degoo.com]
*Sent:* den 12 augusti 2012 17:18

*To:* dev@jitsi.java.net
*Subject:* [jitsi-dev] Re: Race condition****

** **

I just realized that the message size I provided is not correct. I
serialize messages using Protocol Buffers so the actual data being sent is
5 bytes more per message (due to some overhead from PB)****

** **

/Carl****

** **

*From:* Carl Hasselskog [mailto:carl@degoo.com]
*Sent:* den 12 augusti 2012 17:01
*To:* dev@jitsi.java.net
*Subject:* [jitsi-dev] Re: Race condition****

** **

Hi,****

I'm now running into a bit strange issue when testing the pseudo tcp code.
I've written a test that has two threads. One that repeatedly writes
messages of size x bytes on the output stream of the PseudoTcpSocketImpl
instance and one that repeatedly reads them. It works well as long as the
message size is <4096 bytes. If the message is >=4096 bytes then some of
the read messages don't match the written one. I've tried to find some
patterns in how the messages differ with regards to message size. I've
found the following:****

Message size: 4100 - 29th message is different (difference starts at
1348th byte)****

Message size: 4150 - 1st message is different (difference starts at 4093rd
byte)****

Message size: 4200 - 1st message is different (difference starts at 2747th
byte)****

Message size: 5000 - 1st message is different (difference starts at 2747th
byte)****

** **

I am not able to find any pattern out of this. Do you guys have any ideas?
****

** **

Regards****

Carl****

** **

*From:* Paweł Domas [mailto:paweldomas@gmail.com]
*Sent:* den 10 augusti 2012 11:04
*To:* dev@jitsi.java.net
*Subject:* [jitsi-dev] Re: Race condition****

** **

Hi,****

2012/8/10 Carl Hasselskog <carl@degoo.com>****

Hi,
I've now tried using selectedPair.getLocalCandidate().getDatagramSocket()
to get the DatagramSocket and not calling iceAgent.free(). Unfortunately I
get timeouts in Accept and Connect in PseudoTCPSocket (see attached log).
To me it looks like the TCP_SYN_SENT is being directed to StunStack instead
of the PseudoTCPSocket. I base that on this part of the log:

10:02:57.697 Fin: org.ice4j.pseudotcp.PseudoTCPBase.Connect() State:
TCP_SYN_SENT
10:02:57.698 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.queue() enqueued
send segment seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend() [cwnd:
360 nWindow: 4 nInFlight: 0 nAvailable: 4 nQueued: 4 nEmpty: 92156
ssthresh: 61440]
10:02:57.700 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend()
TRANSMIT SEGMENT seq: 0 len: 4
10:02:57.700 Fin: org.ice4j.pseudotcp.PseudoTCPBase.packet() <--
<CONV=0><FLG=2><SEQ=0:4><ACK=0><WND=61440><SCALE=0><TS=261014052><TSR=0><LEN=4>
10:02:57.701 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.TcpWritePacket()
write packet to network 28
10:02:57.701 Finaste: org.ice4j.stack.Connector.run() received datagram
10:02:57.705 Finaste: org.ice4j.pseudotcp.PseudoTCPBase.attemptSend()
nAvailable == 0: quit
10:02:57.705 Finaste: org.ice4j.stack.MessageQueue.add() Adding raw
message to queue.
10:02:57.706 Finaste: org.ice4j.stack.MessageProcessor.run() Dispatching a
StunMessageEvent.
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent()
Received a message on /2001:6b0:1:1041:d843:8fd0:ab52:d8f4:3031/udp of
type:0
10:02:57.706 Finaste: org.ice4j.stack.StunStack.handleMessageEvent()
parsing request
10:02:57.707 Finaste: org.ice4j.stack.StunStack.handleMessageEvent()
existing transaction not found

Any idea on what might be causing this?****

** **

** **

Yes that's because of STUN packet filter. Please try to use
PseudoTcpSockets with conversation number that will have it's two most
significant bit not equal to zero. Conversation number is passed to the
constructor as first argument. We are still working on fixing properly that
issue.****

** **

Also please set MTU as I don't know how to figure out that the packets are
too long to transmit and they do get truncated at some point when are used
with sockets provided by ICE Agent.****

** **

There is at least one more bug I do know about and I'm tracking it down.
Also I've commited some changes which introduce PseudoTcpSocketImpl that
extends java.net.SocketImpl as I'm trying to use it with Apache HttpClient.
Please use PseudoTcpSocketImpl class now. ****

** **

The example IcePseudoTcp is changed to use ICE datagram sockets.****

** **

--
Regards, Paweł Domas****

Thanks a lot ! I'll take a look on that and try to add some unit tests for
the stream, so that won't happen again.

--
Regards, Paweł Domas


#15

Hi Pawel,

[snip]

So it would work, but a small change is required:

// Checks if the length of the data correspond to the length
// field of the STUN header. The message length field of the
// STUN header does not include the 20-byte of the STUN header.
int total_header_length
     = ((((int)data[2])& 0xff)<< 8) + (((int) data[3])& 0xff);
boolean isHeaderLengthValid = (length == total_header_length);

As you wrote in comment message length field does not include 20 bytes
of the header itself. So there was missing +20 to total_header_length
and then it's working.

Thank you for pointing this out (corrected with Ice4j revision #331).

However I found some other misterious behaviour and I don't know what
is causing it.
It is about packet marked by Wireshark as STUN CLASSIC and only some of them.
In Wireshark I get data like this(HEX):
00 01 00 24 6c 46 4a 44 32 71 54 38 49 2f 36 56
4f 32 34 7a 00 06 00 20 62 66 64 67 6f 73 33 30
61 65 63 36 61 63 65 72 68 4f 37 44 74 59 50 33
49 6f 39 54 38 75 46 73

And the message length is 0x24 that is 36 + 20 = 56 and it is correct.

But in StunDatagramPacketFilter.accept() method this packet is
truncated to length of 24(p.getLength() = 24), but header field still
says it's 36 and it passes that packet to PseudoTCP in my case. So I
print whole packet data at that point and it looks like this:

00 01 00 24 6c 46 4a 44 32 71 54 38 49 2f 36 56
4F 32 34 7A 00 06 00 20 [here ends 24] and the rest of it is some
random buffer data, as it should probably:
47:45:54:20:2f:73:72:63:2f:31:33:34:35:36:32:32:36:36:35:33...

So the problem is that some packets are truncated to that size and I
don't know what may be causing this. Is the DatagramPacket overloaded
somewhere or recreated after reading from the network ?

Hey, for this one remind me to buy you a beer the next we meet again :slight_smile:

You help me to track down an old bug of truncated packets (as well for RTP as for STUN). Ice4j revision #332 normally handles this problem. Please give it a try and give us some feedback.

Thank you very much Pawel for your help.

Regards,
Vincent

···

On 08/22/2012 10:25 AM, Pawe� Domas wrote:

--
Vincent Lucas, Ph.D. Jitsi developer
chenzo@jitsi.org http://jitsi.org


#16

Hi,

···

2012/8/23 Vincent Lucas <chenzo@jitsi.org>:

Hi Pawel,

On 08/22/2012 10:25 AM, Paweł Domas wrote:

[snip]

So it would work, but a small change is required:

// Checks if the length of the data correspond to the length
// field of the STUN header. The message length field of the
// STUN header does not include the 20-byte of the STUN header.
int total_header_length
     = ((((int)data[2])& 0xff)<< 8) + (((int) data[3])& 0xff);

boolean isHeaderLengthValid = (length == total_header_length);

As you wrote in comment message length field does not include 20 bytes
of the header itself. So there was missing +20 to total_header_length
and then it's working.

Thank you for pointing this out (corrected with Ice4j revision #331).

However I found some other misterious behaviour and I don't know what
is causing it.
It is about packet marked by Wireshark as STUN CLASSIC and only some of
them.
In Wireshark I get data like this(HEX):
00 01 00 24 6c 46 4a 44 32 71 54 38 49 2f 36 56
4f 32 34 7a 00 06 00 20 62 66 64 67 6f 73 33 30
61 65 63 36 61 63 65 72 68 4f 37 44 74 59 50 33
49 6f 39 54 38 75 46 73

And the message length is 0x24 that is 36 + 20 = 56 and it is correct.

But in StunDatagramPacketFilter.accept() method this packet is
truncated to length of 24(p.getLength() = 24), but header field still
says it's 36 and it passes that packet to PseudoTCP in my case. So I
print whole packet data at that point and it looks like this:

00 01 00 24 6c 46 4a 44 32 71 54 38 49 2f 36 56
4F 32 34 7A 00 06 00 20 [here ends 24] and the rest of it is some
random buffer data, as it should probably:
47:45:54:20:2f:73:72:63:2f:31:33:34:35:36:32:32:36:36:35:33...

So the problem is that some packets are truncated to that size and I
don't know what may be causing this. Is the DatagramPacket overloaded
somewhere or recreated after reading from the network ?

Hey, for this one remind me to buy you a beer the next we meet again :slight_smile:

You help me to track down an old bug of truncated packets (as well for RTP
as for STUN). Ice4j revision #332 normally handles this problem. Please give
it a try and give us some feedback.

Thank you very much Pawel for your help.

Regards,
Vincent

--
Vincent Lucas, Ph.D. Jitsi developer
chenzo@jitsi.org http://jitsi.org

Thanks, I'm glad that I could help :slight_smile: Now it works like a charm.

--
Regards, Paweł Domas