Hi there,
I developed an RPC library called "SIMON", based on Apache MINA 2.0.13,
using ProtocolCodecFactory. This is working fine since many years now.
Today I faced an issue, which I - at the moment - would say is caused by
MINA. I'll try to explain:
After running the problematic example code that makes use of my lib, it
takes some time until client AND server prints the following message:
-----
M�r 17, 2016 3:52:31 PM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
-----
The longer the application runs, the more often (maybe just a feeling)
this messages is logged. And the more ofthen this message is logged, the
closer we're getting to this exception:
SCHWERWIEGEND: exception Caught. thread=NioProcessor-2
session=0x00000001. Exception:
org.apache.mina.filter.codec.ProtocolDecoderException: No appropriate
message decoder: 00 00 00 02 00 00 00 36 AC ED 00 <a lot more bytes>)
at
org.apache.mina.filter.codec.demux.DemuxingProtocolDecoder.doDecode(DemuxingProtocolDecoder.java:176)
at
org.apache.mina.filter.codec.CumulativeProtocolDecoder.decode(CumulativeProtocolDecoder.java:176)
at
org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:230)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943)
at
org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:535)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:697)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:651)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:640)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:68)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1097)
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
This is what the example application does:
// send a "LOOKUP" Message to the server, which responds with a
"LOOPUK_RETURN" message
remoteHandler = (Handler)
nameLookup.lookup(Handler.class.getCanonicalName());
-----------------
for (;;) {
// This sends a single message to the server ("INVOKE").
// The server executes the requested method (trigger())
// The trigger() method will send a single message (which
get's answered by client), 100 messages with an delay of 1..100ms
between each (also answered by client) and another single message to the
client (also answered by client). In sum 102 messages server->client and
102 answers client->server.
// After that, the remotly invoked method returns and server
sends an messages back to the client, before the method returns an
"INVOKE_RETURN" message to the client
remoteHandler.trigger(monitor, System.currentTimeMillis());
Thread.sleep(100);
}
-------------------
The longer the sleep times on client and in trigger() method on server
is, the longer it takes to get this MINA messages and the longer it
takes until the exception occurs.
Of course it would be great to have an simple reproducer-example without
the code-overhead with my lib and this error producing sample
application. But I was not yet abe to track down the problem to create
such a simple, minimalistic reproducer.
My current thoughts:
1) I figured out, that the message logged by MINA is related to an
selector() issue. In that case, the selector is dropped and replaced
with a new one. For me it looks like there is an sync-issue with
creating this new instance. That could confuse the stream, so that a few
bytes are missing and the codec cannot continue it's work. But I did not
find this kind of sync-gap...
2) The reported message is ALWAYS the same. At least the first 15 bytes
are always the same.
3) The issue does not always happen at the same time. It really differs.
4) If I skip the 100 messages from server back to client while invoking
the remote method, the issue is gone.
5) But in general, this is not a problem. I have tons of code using this
mechanism without any issue. But the timing is different...
6) Tested with MINA 2.0.9, 2.0.13 as well as with Win7/64bit/Java8 and
Ubuntu Linux, also with Java8.
I would be very glad if someone can give me a hint...
If someone wants to debug this: I can give you an example project that
uses my library (which uses MINA2.0.13).
br,
Alex
