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 <[email protected]> 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
