Connection disruption problem

zohar_etzioni · March 25, 2011, 6:12pm

Hi,

I’m having hard time to even characterise this problem, but I’ll try: I have 4 clients (using Smack) connecting to an openfire server, all local. They exchange messages and for an hour everything works fine. After one hour (I’m not sure the time is important, but maybe it is) strange things happen:

For 2 processes I get an EOFException in PacketReader, followed by an IllegalThreadStateException in the ReconnectionManager

java.io.EOFException: no more data available - expected end tag </stream:stream> to close start tag stream:stream from line 1, parser stopped on END_TAG seen …null… @13139:44

at org.xmlpull.mxp1.MXParser.fillBuf(MXParser.java:3035)

at org.xmlpull.mxp1.MXParser.more(MXParser.java:3046)

at org.xmlpull.mxp1.MXParser.nextImpl(MXParser.java:1144)

at org.xmlpull.mxp1.MXParser.next(MXParser.java:1093)

at org.jivesoftware.smack.PacketReader.parsePackets(PacketReader.java:368)

at org.jivesoftware.smack.PacketReader.access$000(PacketReader.java:44)

at org.jivesoftware.smack.PacketReader$1.run(PacketReader.java:76)

java.net.SocketException: Connection closed by remote host

at sun.security.ssl.SSLSocketImpl.checkWrite(SSLSocketImpl.java:1301)

at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:62)

at com.jcraft.jzlib.ZOutputStream.write(ZOutputStream.java:88)

at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:220)

at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:290)

at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:294)

at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:140)

at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)

at java.io.BufferedWriter.flush(BufferedWriter.java:253)

at org.jivesoftware.smack.PacketWriter.writePackets(PacketWriter.java:259)

at org.jivesoftware.smack.PacketWriter.access$000(PacketWriter.java:40)

at org.jivesoftware.smack.PacketWriter$1.run(PacketWriter.java:87)

Exception in thread “Smack Reconnection Manager” java.lang.IllegalThreadStateException

at java.lang.Thread.start(Thread.java:612)

at org.jivesoftware.smack.PacketWriter.startup(PacketWriter.java:183)

at org.jivesoftware.smack.XMPPConnection.initConnection(XMPPConnection.java:942)

at org.jivesoftware.smack.XMPPConnection.connectUsingConfiguration(XMPPConnection. java:904)

at org.jivesoftware.smack.XMPPConnection.connect(XMPPConnection.java:1415)

For 1 process I get a Socket Exception saying the connection was closed by remote host (during writePackets in PacketWriter)

java.net.SocketException: Connection closed by remote host

at sun.security.ssl.SSLSocketImpl.checkWrite(SSLSocketImpl.java:1327)

at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:62)

at com.jcraft.jzlib.ZOutputStream.write(ZOutputStream.java:88)

at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:220)

at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:290)

at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:294)

at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:140)

at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)

at java.io.BufferedWriter.flush(BufferedWriter.java:253)

at org.jivesoftware.smack.PacketWriter.writePackets(PacketWriter.java:259)

at org.jivesoftware.smack.PacketWriter.access$000(PacketWriter.java:40)

at org.jivesoftware.smack.PacketWriter$1.run(PacketWriter.java:87)

java.io.EOFException: no more data available - expected end tag </stream:stream> to close start tag stream:stream from line 1, parser stopped on END_TAG seen …ble" from=“sim-user-4@zohar-uni/Smack” to=“sim-user-5@zohar-uni”/>… @14817:134

at org.xmlpull.mxp1.MXParser.fillBuf(MXParser.java:3035)

at org.xmlpull.mxp1.MXParser.more(MXParser.java:3046)

at org.xmlpull.mxp1.MXParser.nextImpl(MXParser.java:1144)

at org.xmlpull.mxp1.MXParser.next(MXParser.java:1093)

at org.jivesoftware.smack.PacketReader.parsePackets(PacketReader.java:368)

at org.jivesoftware.smack.PacketReader.access$000(PacketReader.java:44)

at org.jivesoftware.smack.PacketReader$1.run(PacketReader.java:76)

java.io.IOException: Stream closed

at java.io.BufferedWriter.ensureOpen(BufferedWriter.java:115)

at java.io.BufferedWriter.flushBuffer(BufferedWriter.java:125)

at java.io.BufferedWriter.flush(BufferedWriter.java:252)

at org.jivesoftware.smack.PacketWriter.writePackets(PacketWriter.java:274)

at org.jivesoftware.smack.PacketWriter.access$000(PacketWriter.java:40)

at org.jivesoftware.smack.PacketWriter$1.run(PacketWriter.java:87)

For one process I get parsing exceptions, and SSL exceptions:

java.net.SocketException: Connection closed by remote host

at sun.security.ssl.SSLSocketImpl.checkWrite(SSLSocketImpl.java:1327)

at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:62)

at com.jcraft.jzlib.ZOutputStream.write(ZOutputStream.java:88)

at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:220)

at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:290)

at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:294)

at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:140)

at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)

at java.io.BufferedWriter.flush(BufferedWriter.java:253)

at org.jivesoftware.smack.PacketWriter.writePackets(PacketWriter.java:259)

at org.jivesoftware.smack.PacketWriter.access$000(PacketWriter.java:40)

at org.jivesoftware.smack.PacketWriter$1.run(PacketWriter.java:87)

java.io.EOFException: no more data available - expected end tag </stream:stream> to close start tag stream:stream from line 1, parser stopped on END_TAG seen …XKkz41299… @16497:44

at org.xmlpull.mxp1.MXParser.fillBuf(MXParser.java:3035)

at org.xmlpull.mxp1.MXParser.more(MXParser.java:3046)

at org.xmlpull.mxp1.MXParser.nextImpl(MXParser.java:1144)

at org.xmlpull.mxp1.MXParser.next(MXParser.java:1093)

at org.jivesoftware.smack.PacketReader.parsePackets(PacketReader.java:368)

at org.jivesoftware.smack.PacketReader.access$000(PacketReader.java:44)

at org.jivesoftware.smack.PacketReader$1.run(PacketReader.java:76)

javax.net.ssl.SSLException: Connection has been shutdown: javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake

at sun.security.ssl.SSLSocketImpl.checkEOF(SSLSocketImpl.java:1313)

at sun.security.ssl.SSLSocketImpl.checkWrite(SSLSocketImpl.java:1325)

at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:62)

at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:220)

at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:290)

at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:294)

at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:140)

at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)

at java.io.BufferedWriter.flush(BufferedWriter.java:253)

at org.jivesoftware.smack.PacketWriter.writePackets(PacketWriter.java:259)

at org.jivesoftware.smack.PacketWriter.access$000(PacketWriter.java:40)

at org.jivesoftware.smack.PacketWriter$1.run(PacketWriter.java:87)

Caused by: javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake

at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:837)

at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1158)

at sun.security.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:652)

at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:78)

at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:220)

at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:290)

at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:294)

at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:140)

at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)

at java.io.BufferedWriter.flush(BufferedWriter.java:253)

at org.jivesoftware.smack.PacketWriter.openStream(PacketWriter.java:352)

at org.jivesoftware.smack.XMPPConnection.proceedTLSReceived(XMPPConnection.java:12 74)

at org.jivesoftware.smack.PacketReader.parsePackets(PacketReader.java:313)

at org.jivesoftware.smack.PacketReader.access$000(PacketReader.java:44)

at org.jivesoftware.smack.PacketReader$1.run(PacketReader.java:76)

Caused by: java.io.EOFException: SSL peer shut down incorrectly

at sun.security.ssl.InputRecord.read(InputRecord.java:352)

at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:818)

… 14 more

javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake

at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:837)

at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1158)

at sun.security.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:652)

at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:78)

at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:220)

at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:290)

at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:294)

at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:140)

at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)

at java.io.BufferedWriter.flush(BufferedWriter.java:253)

at org.jivesoftware.smack.PacketWriter.openStream(PacketWriter.java:352)

at org.jivesoftware.smack.XMPPConnection.proceedTLSReceived(XMPPConnection.java:12 74)

at org.jivesoftware.smack.PacketReader.parsePackets(PacketReader.java:313)

at org.jivesoftware.smack.PacketReader.access$000(PacketReader.java:44)

at org.jivesoftware.smack.PacketReader$1.run(PacketReader.java:76)

Caused by: java.io.EOFException: SSL peer shut down incorrectly

at sun.security.ssl.InputRecord.read(InputRecord.java:352)

at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:818)

… 14 more

java.io.IOException: Stream closed

at java.io.BufferedWriter.ensureOpen(BufferedWriter.java:115)

at java.io.BufferedWriter.flushBuffer(BufferedWriter.java:125)

at java.io.BufferedWriter.flush(BufferedWriter.java:252)

at org.jivesoftware.smack.PacketWriter.writePackets(PacketWriter.java:274)

at org.jivesoftware.smack.PacketWriter.access$000(PacketWriter.java:40)

at org.jivesoftware.smack.PacketWriter$1.run(PacketWriter.java:87)

org.xmlpull.v1.XmlPullParserException: only whitespace content allowed before start tag and not i (position: START_TAG seen …<mechani… @1:183)

at org.xmlpull.mxp1.MXParser.parseProlog(MXParser.java:1519)

at org.xmlpull.mxp1.MXParser.nextImpl(MXParser.java:1395)

at org.xmlpull.mxp1.MXParser.next(MXParser.java:1093)

at org.jivesoftware.smack.PacketReader.parsePackets(PacketReader.java:368)

at org.jivesoftware.smack.PacketReader.access$000(PacketReader.java:44)

at org.jivesoftware.smack.PacketReader$1.run(PacketReader.java:76)

There is nothing different that happens (from the application point of view) at the time of failure, no special or different messages that are not sent earlier. The two clients that have the IllegalThreadStateException seem to be still connected to the server, the others seem unavailable (in the server). I’m using openfire 3.7.0 and smack 3.1.0.

Any ideas?

Walter_Ebeling · March 25, 2011, 7:36pm

Assuming a custom build client… It would be interesting, if this happens also with Smack 3.2. b2 or a nightly build of Smack. There are a couple of fixes (more than 50) in Smack 3.2 and your issue might be fixed already.

zohar_etzioni · March 25, 2011, 9:18pm

I’ll try tomorrow with the nightly build, but any idea what could lead to that behaviour?

zohar_etzioni · March 26, 2011, 4:24pm

well, tried with the last nightly build. The behaviour is slightly modified, but effectively the same, the illegal thread state exception was replaced with a null pointer exception, but besides they still all disconnect abruptly after an hour. I attached the exceptions for each of the clients.
errors.rtf (12299 Bytes)

Walter_Ebeling · March 26, 2011, 5:59pm

The Spark dev team will take a look into it…

zohar_etzioni · March 26, 2011, 6:00pm

cool, let me know if I can help in any way!

Robin_Collier · March 26, 2011, 9:40pm

Can you give some information as to what the clients are doing? I assume this is a custom client, is it also using any custom IQProviders or extension providers?

Also, can you turn on debug to see what is happening when this exception occurs.

zohar_etzioni · March 27, 2011, 7:18am

I’m using smack (and XMPP) for messaging in a distributed system. At the moment it is just a prototype so I’m not usint IQ (although I probably should), only IM, such that each client sends about 1000 messages overall. Messages are short and well formed. Each one of the 4 clients is connected to all others. The problem occurs during an automatic run that results in some message exchange. As I mentioned above, there is nothing (that I can see) that is different from application point of view when the error occurs.

I turned all logs on when I noticed the errors. I also turned on the message audit. In the error file there was nothing suspicious. I didn’t notice anything in the debug log but maybe I didn’t know what to look for. The warn file had the following errors that seem related:

2011.03.25 14:27:48 Closing session due to exception: (SOCKET, R: /134.226.56.7:41940, L: /134.226.62.17:5222, S: 0.0.0.0/0.0.0.0:5222)

org.apache.mina.filter.codec.ProtocolDecoderException: java.lang.Exception: Disallowed character (Hexdump: 80 AD 01 03 01 00 84 00 00 00 20 00 00 04 01 00 80 00 00 05 00 00 2F 00 00 35 00 C0 02 00 C0 04 01 00 80 00 C0 05 00 C0 0C 00 C0 0E 00 C0 0F 00 C0 07 05 00 80 00 C0 09 06 00 40 00 C0 0A 07 00 C0 00 C0 11 00 C0 13 00 C0 14 00 00 33 00 00 39 00 00 32 00 00 38 00 00 0A 07 00 C0 00 C0 03 02 00 80 00 C0 0D 00 C0 08 00 C0 12 00 00 16 00 00 13 00 00 09 06 00 40 00 00 15 00 00 12 00 00 03 02 00 80 00 00 08 00 00 14 00 00 11 00 00 FF 4D 8C A5 E8 59 03 0B F1 54 E8 5A D3 7D 3D 9C 96 4B 7C E5 83 06 E1 9B 8C 93 F6 BF 19 B0 44 BC 64)

at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecF ilter.java:170)

at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)

at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)

at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)

at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java :239)

at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(Execut orFilter.java:283)

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java: 886)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51)

at java.lang.Thread.run(Thread.java:680)

Caused by: java.lang.Exception: Disallowed character

at org.jivesoftware.openfire.nio.XMLLightweightParser.read(XMLLightweightParser.ja va:211)

at org.jivesoftware.openfire.nio.XMPPDecoder.doDecode(XMPPDecoder.java:32)

at org.apache.mina.filter.codec.CumulativeProtocolDecoder.decode(CumulativeProtoco lDecoder.java:133)

at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecF ilter.java:163)

… 9 more

2011.03.25 14:28:23 TLS was required by the server and connection was never secured. Closing connection : org.jivesoftware.openfire.nio.NIOConnection@7d0b4eb3 MINA Session: (SOCKET, R: /134.226.56.7:42816, L: /134.226.62.17:5222, S: 0.0.0.0/0.0.0.0:5222)

2011.03.25 14:28:51 TLS was required by the server and connection was never secured. Closing connection : org.jivesoftware.openfire.nio.NIOConnection@10bf5f33 MINA Session: (SOCKET, R: /134.226.56.7:40480, L: /134.226.62.17:5222, S: 0.0.0.0/0.0.0.0:5222)

2011.03.25 15:55:50 Closing session due to exception: (SOCKET, R: /134.226.56.7:46982, L: /134.226.62.17:5222, S: 0.0.0.0/0.0.0.0:5222)

org.apache.mina.filter.codec.ProtocolDecoderException: java.lang.Exception: Disallowed character (Hexdump: 80 AD 01 03 01 00 84 00 00 00 20 00 00 04 01 00 80 00 00 05 00 00 2F 00 00 35 00 C0 02 00 C0 04 01 00 80 00 C0 05 00 C0 0C 00 C0 0E 00 C0 0F 00 C0 07 05 00 80 00 C0 09 06 00 40 00 C0 0A 07 00 C0 00 C0 11 00 C0 13 00 C0 14 00 00 33 00 00 39 00 00 32 00 00 38 00 00 0A 07 00 C0 00 C0 03 02 00 80 00 C0 0D 00 C0 08 00 C0 12 00 00 16 00 00 13 00 00 09 06 00 40 00 00 15 00 00 12 00 00 03 02 00 80 00 00 08 00 00 14 00 00 11 00 00 FF 4D 8C BA 86 86 0D 54 0C 84 8A F7 CD E3 FE 51 FC 7E AD 2D 9E FD 6D DD 71 B7 EE 13 3B 03 44 AE 07)