powered by Jive Software

Connection disruption problem

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:

  1. 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)

  1. 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)

  1. 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?

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.

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

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)

The Spark dev team will take a look into it…

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

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.

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)

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

Hope it helps, let me know if you need anything else.

Thanks,

Zohar

OK, this appears to be a problem with the message content being sent to the server. With that last stack trace you provided it looks like there is a message with unparseable content being sent to the server. This is causing the disconnect from the server end.

This seems to indicate that it may not actually be a Smack issue but either an application one (bad content) or an OpenFire one.

assuming there is a problem with the message, why does it result in a NPE (in XMPPConnection shutdown) ? shouldn’t the app be able to receive a parsing exception from smack and handle it instead? why does it terminally disconnect the client?

In the meantime I will write to a file all the messages before they are sent and see if there is an illegal character or anything like that.

I didn’t see any NPE, but in any case the connection to the server has been terminated by the server. It would seem appropriate that a SocketException would be appropriate. It does have the message that the connection was close by the remote host, which appears to be accurate.

That’s the NPE (was attached above):

Exception in thread “Smack Packet Reader (0)” java.lang.NullPointerException

at org.jivesoftware.smack.XMPPConnection.shutdown(XMPPConnection.java:416)

at org.jivesoftware.smack.PacketReader.notifyConnectionError(PacketReader.java:166 )

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

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

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

It might be the right behaviour with regard to SocketException, but I may be missing the point where in the application code I could do something useful with it.

I having a similar problem, the error message is as follows:

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 …… @1:420

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:325)

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

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

I’m also getting the same exception.

java.net.SocketException: Connection closed by remote host

2012-08-08 00:00:02,346 ERROR [STDERR] (Smack Packet Writer (66)) at sun.security.ssl.SSLSocketImpl.checkWrite(SSLSocketImpl.java:1301)

2012-08-08 00:00:02,346 ERROR [STDERR] (Smack Packet Writer (66)) at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:62)

2012-08-08 00:00:02,346 ERROR [STDERR] (Smack Packet Writer (66)) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:220)