So I can't explain exactly why, but the problem comes from the removal of the following variable:
https://github.com/apache/mina/commit/60cb619b6f0a940e7a6b18c060158270c227255b#diff-e3418ff2f83464c155b780cdbfb9e4aaL754 Le jeu. 21 juin 2018 à 10:47, Guillaume Nodet <gno...@apache.org> a écrit : > It looks like visper is receiving a duplicate message from mina or > something like that and thus is closing the session because it assumes a > protocol error. > The actual location is the following: > java.lang.Throwable > at > org.apache.vysper.xmpp.protocol.ProtocolWorker.processTLSEstablishedInternal(ProtocolWorker.java:206) > at > org.apache.vysper.xmpp.protocol.QueuedStanzaProcessor.processTLSEstablished(QueuedStanzaProcessor.java:61) > at > org.apache.vysper.mina.XmppIoHandlerAdapter.messageReceivedNoStanza(XmppIoHandlerAdapter.java:82) > at > org.apache.vysper.mina.XmppIoHandlerAdapter.messageReceived(XmppIoHandlerAdapter.java:65) > at > org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:997) > at > org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:641) > at > org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48) > at > org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:1114) > at > org.apache.vysper.mina.StanzaLoggingFilter.messageReceived(StanzaLoggingFilter.java:67) > at > org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:641) > at > org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48) > at > org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:1114) > at > org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:236) > at > org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:641) > at > org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48) > at > org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:1114) > at > org.apache.mina.filter.ssl.SslHandler.flushScheduledEvents(SslHandler.java:323) > at org.apache.mina.filter.ssl.SslFilter.filterWrite(SslFilter.java:683) > at > org.apache.mina.filter.ssl.SslHandler.flushPreHandshakeEvents(SslHandler.java:286) > at org.apache.mina.filter.ssl.SslFilter.handleSslData(SslFilter.java:811) > at org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:533) > at > org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:641) > at > org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48) > at > org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:1114) > at > org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:121) > at > org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:641) > at > org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:634) > at > org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:539) > at > org.apache.mina.core.polling.AbstractPollingIoProcessor.access$1200(AbstractPollingIoProcessor.java:68) > at > org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.process(AbstractPollingIoProcessor.java:1242) > at > org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.process(AbstractPollingIoProcessor.java:1231) > at > org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:683) > at > org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) > at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) > at java.lang.Thread.run(Thread.java:748) > > I'm going to git bisect between 2.0.17 and 2.0.19 to see which commit is > the culprit. > > Le mer. 20 juin 2018 à 20:39, Emmanuel Lécharny <elecha...@gmail.com> a > écrit : > >> >> >> Le 20/06/2018 à 19:00, Guillaume Nodet a écrit : >> > So I've enabled debug logging which helps a bit. >> > https://gist.github.com/gnodet/04b08b1d19caa67359f352522774a70d >> > >> > I suspect a concurrent access to the byte buffer because the exception >> > should be thrown from the HeapByteBuffer#checkIndex instead of from >> > HeapByteBuffer#get. So I think there is a concurrent access which is >> > called between the call to checkIndex and the array access. >> > But this exception may be irrelevant as it's happening while handling >> > another exception which is >> > org.apache.mina.core.write.WriteToClosedSessionException >> > >> > While debugging, I noticed that during the call to isCloseNotify, the >> > IoBuffer is at the end, so not sure that this is expected by the code. >> >> Looking at the logs, what I see is that the apps is sending a message : >> >> 2018-06-20 18:51:59,863 [NioProcessor-2 ] DEBUG SslFilter >> - Session Server[1](SSL): Writing Message : WriteRequest: >> HeapBuffer[pos=0 lim=177 cap=256: 3C 3F 78 6D 6C 20 76 65 72 73 69 6F 6E >> 3D 22 31 2E 30 22 20 65 6E 63 6F 64 69 6E 67 3D 22 55 54 46 2D 38 22 3F >> 3E 3C 65 72 72 6F 72 20 78 6D 6C 6E 73 3D 22 75 72 6E 3A 69 65 74 66 3A >> 70 61 72 61 6D 73 3A 78 6D 6C 3A 6E 73 3A 78 6D 70 70 2D 73 74 72 65 61 >> 6D 73 22 3E 3C 62 61 64 2D 66 6F 72 6D 61 74 3E 3C 2F 62 61 64 2D 66 6F >> 72 6D 61 74 3E 3C 74 65 78 74 20 78 6D 6C 3A 6C 61 6E 67 3D 22 65 6E 5F >> 55 53 22 3E 63 6F 75 6C 64 20 6E 6F 74 20 70 72 6F 63 65 73 73 20 69 6E >> 63 6F 6D 69 6E 67 20 73 74 61 6E 7A 61 3C 2F 74 65 78 74 3E...] >> >> ie "<?xml version="1.0" encoding="UTF-8"?><error >> xmlns="urn:ietf:params:xml:ns:xmpp-streams"><bad-format></bad-format><text >> xml:lang="en_US">could not process incoming stanza</text>" >> >> then it closes the session: >> >> 2018-06-20 18:51:59,864 [NioProcessor-2 ] INFO MinaBackedSessionContext >> - session will be closed now >> >> Now, what happens is that MINA will try to flush the pending messages, >> which leads to errors. >> >> What need to be analyzed is why we get a IndexOutOfBoundsException, but >> regardless, it's teh app that has closed the connection, MINA is not >> responsible for that. Unless the error message is a direct consequence >> of a MINA failure... >> >> -- >> Emmanuel Lecharny >> >> Symas.com >> directory.apache.org >> >> > > -- > ------------------------ > Guillaume Nodet > > -- ------------------------ Guillaume Nodet
