Subject: Problem connecting client
Hi all,
I'm experiencing a strange behavior with OpenFire 3.9.3 that I'm not able to reproduce systematically: I wrote a Window service that connects multiple MatriX .NET clients, let's say 1 every 5 seconds. It occasionally happens that I get no OnLogin/OnBind events fired and so I quit for timeout after some time.
If I look at the client logs, nothing happens until my timer expires; if I look at the server, nothing is reported in Error/Warn/Info logs, but I found two different patterns in Debug:
when everything goes fine I see:
and when it doesn't I see:
I'm not sure about that, but it seems to me that while in the first case everything happens within the same second, in the other case the thread exits without doing the doHandshake() stuff between the 40 and 50 seconds.
Can someone give me a hint?
Thank you for your replies
I'm experiencing a strange behavior with OpenFire 3.9.3 that I'm not able to reproduce systematically: I wrote a Window service that connects multiple MatriX .NET clients, let's say 1 every 5 seconds. It occasionally happens that I get no OnLogin/OnBind events fired and so I quit for timeout after some time.
If I look at the client logs, nothing happens until my timer expires; if I look at the server, nothing is reported in Error/Warn/Info logs, but I found two different patterns in Debug:
when everything goes fine I see:
2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Launching thread for /0:0:0:0:0:0:0:1:64881
2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64881
2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Launching thread for /0:0:0:0:0:0:0:1:64881
2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64881
2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Launching thread for /0:0:0:0:0:0:0:1:64881
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.NIOConnection - NIOConnection: startTLS: using c2s
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881] doHandshake()
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881] handshakeStatus=NEED_UNWRAP
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881] unwrapHandshake()
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881] inNetBuffer: java.nio.DirectByteBuffer[pos=0 lim=0 cap=16921]
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881] appBuffer: java.nio.DirectByteBuffer[pos=0 lim=33842 cap=33842]
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881] Unwrap res:Status = BUFFER_UNDERFLOW HandshakeStatus = NEED_UNWRAP
bytesConsumed = 0 bytesProduced = 0
2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64881
2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64881
2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Launching thread for /0:0:0:0:0:0:0:1:64881
2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64881
2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Launching thread for /0:0:0:0:0:0:0:1:64881
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.NIOConnection - NIOConnection: startTLS: using c2s
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881] doHandshake()
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881] handshakeStatus=NEED_UNWRAP
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881] unwrapHandshake()
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881] inNetBuffer: java.nio.DirectByteBuffer[pos=0 lim=0 cap=16921]
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881] appBuffer: java.nio.DirectByteBuffer[pos=0 lim=33842 cap=33842]
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881] Unwrap res:Status = BUFFER_UNDERFLOW HandshakeStatus = NEED_UNWRAP
bytesConsumed = 0 bytesProduced = 0
2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64881
and when it doesn't I see:
2015.10.14 17:33:40 org.apache.mina.filter.executor.ExecutorFilter - Launching thread for /0:0:0:0:0:0:0:1:64890
2015.10.14 17:33:40 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64890
2015.10.14 17:33:40 org.apache.mina.filter.executor.ExecutorFilter - Launching thread for /0:0:0:0:0:0:0:1:64890
2015.10.14 17:33:40 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64890
2015.10.14 17:33:50 org.apache.mina.filter.executor.ExecutorFilter - Launching thread for /0:0:0:0:0:0:0:1:64890
2015.10.14 17:33:50 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64890
2015.10.14 17:33:40 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64890
2015.10.14 17:33:40 org.apache.mina.filter.executor.ExecutorFilter - Launching thread for /0:0:0:0:0:0:0:1:64890
2015.10.14 17:33:40 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64890
2015.10.14 17:33:50 org.apache.mina.filter.executor.ExecutorFilter - Launching thread for /0:0:0:0:0:0:0:1:64890
2015.10.14 17:33:50 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64890
I'm not sure about that, but it seems to me that while in the first case everything happens within the same second, in the other case the thread exits without doing the doHandshake() stuff between the 40 and 50 seconds.
Can someone give me a hint?
Thank you for your replies