Hi Emmanuel,
Am 24.06.2016 um 21:46 schrieb Emmanuel Lécharny:
First, what has changed recently ? Java version ? Faster computer ?
Nothing changed. Issue is reproducible on different machines,
different OS and different Java versions.
It's more or less a scenario in the code, which has not been used in
the last 8 years.
One user has suggested that it *may* happen when you have reached the
maximum open files. Can you check that ?
I tried to observe the open handles (via process explorer) of the
affected process... Handles are about ~500 at peak.
2) The reported message is ALWAYS the same. At least the first 15
bytes are always the same.
At this point, I would question the decoder.
The decoder is working for years now. I tried to debug. But I did not
find any issued with it.
4) If I skip the 100 messages from server back to client while
invoking the remote method, the issue is gone.
Again, check teh decoder, or the encoder.
I checked it. If I add an delay to the RPC mechanism (to reduce the
stress on the selector), I can delay the error. If delay is big
enough, I can't reproduce it any longer.
For now, it seems the more the selector is on stress, the sooner it
happens.
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 need teh code, or at least a complete description of the
protocol.
Attached you will find the complete reproducer project (maven based).
The dependency "de.root1.simon" is the RPC library I was talking about.
Code &Source can be downloaded via maven, or you can have a look at
it here: http://dev.root1.de/projects/simon/repository/show/tags/1.3.0
Execute first the "Server" class, then the "Client" class.
Output for client will look like this (check for the first
exception...):
-----
[1467011505094] task started: size(100)
.[1467011505190] task started: size(100)
..[1467011505243] task started: size(100)
.........[1467011505295] task started: size(100)
.....[1467011505347] task started: size(100)
.......[1467011505399] task started: size(100)
.............[1467011505451] task started: size(100)
.............[1467011505503] task started: size(100)
...........[1467011505555] task started: size(100)
..................[1467011505607] task started: size(100)
....................[1467011505659] task started: size(100)
..................[1467011505711] task started: size(100)
.........................[1467011505763] task started: size(100)
.......................[1467011505815] task started: size(100)
..........................[1467011505867] task started: size(100)
..........................[1467011505919] task started: size(100)
....................................[1467011505973] task started:
size(100)
...............................[1467011506024] task started: size(100)
..............................[1467011506080] task started: size(100)
.............................................[1467011506135] task
started: size(100)
..............................................[1467011506187] task
started: size(100)
.........................................[1467011506239] task
started: size(100)
........................................[1467011506290] task started:
size(100)
...........................................[1467011506342] task
started: size(100)
..............................................[1467011506394] task
started: size(100)
..............................................[1467011506446] task
started: size(100)
................................................[1467011506497] task
started: size(100)
............................................[1467011506549] task
started: size(100)
...................................................[1467011506600]
task started: size(100)
...................................................Jun 27, 2016
9:11:48 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
.....[1467011506652] task started: size(100)
...............................................[1467011506703] task
started: size(100)
..............................................................[1467011506755]
task started: size(100)
...............................................................[1467011506806]
task started: size(100)
....Jun 27, 2016 9:11:48 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
............................................................[1467011506857]
task started: size(100)
......................................................................[1467011506908]
task started: size(100)
..............................................................[1467011506959]
task started: size(100)
........................................................................[1467011507015]
task started: size(100)
............................................................................[1467011507066]
task started: size(100)
........................................[1467011507117] task started:
size(100)
.....................................................................[1467011507168]
task started: size(100)
..............................................................................[1467011507219]
task started: size(100)
...........................................Jun 27, 2016 9:11:49 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
..............................................[1467011507270] task
started: size(100)
...................................................................................[1467011507321]
task started: size(100)
..............................................................Jun 27,
2016 9:11:49 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
.................................[1467011507372] task started: size(100)
...........Jun 27, 2016 9:11:49 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
.......................................................................[1467011507424]
task started: size(100)
...........................................................................................................[1467011507475]
task started: size(100)
.........................................................................................[1467011507530]
task started: size(100)
...Jun 27, 2016 9:11:49 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
..................................................Jun 27, 2016
9:11:49 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
.......Jun 27, 2016 9:11:49 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
...............................Jun 27, 2016 9:11:49 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
.......[1467011507587] task started: size(100)
....................................Jun 27, 2016 9:11:49 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
.....Jun 27, 2016 9:11:49 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
.....................................................[1467011507638]
task started: size(100)
...Jun 27, 2016 9:11:49 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
.......Jun 27, 2016 9:11:49 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
.......................................Jun 27, 2016 9:11:49 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
..............................................[1467011507689] task
started: size(100)
.............................................................................................[1467011507741]
task started: size(100)
............................................................................................................................[1467011507810]
task started: size(100)
..........................................................................[1467011507861]
task started: size(100)
...................................................................................Jun
27, 2016 9:11:50 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
....................[1467011507913] task started: size(100)
..........................................................
[1467011505295] task finished: success(true)
................................................[1467011507964] task
started: size(100)
...................Jun 27, 2016 9:11:50 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
...................................................................................................[1467011508015]
task started: size(100)
.....
[1467011505243] task finished: success(true)
............................................................
[1467011505190] task finished: success(true)
......................[1467011508066] task started: size(100)
...........
[1467011505555] task finished: success(true)
.........................................................................
[1467011505451] task finished: success(true)
...................[1467011508117] task started: size(100)
.........................................
[1467011505503] task finished: success(true)
..................................................
[1467011505607] task finished: success(true)
..................[1467011508168] task started: size(100)
..........................................................................
[1467011505867] task finished: success(true)
..........
[1467011505094] task finished: success(true)
.........................[1467011508220] task started: size(100)
....................................................
[1467011505347] task finished: success(true)
.................................................[1467011508271] task
started: size(100)
...........................................................................
[1467011505399] task finished: success(true)
............................[1467011508323] task started: size(100)
.......................................................
[1467011505659] task finished: success(true)
...................
[1467011505711] task finished: success(true)
...............................[1467011508374] task started: size(100)
.....................................................
[1467011505763] task finished: success(true)
...............................................[1467011508425] task
started: size(100)
...........................
[1467011505815] task finished: success(true)
.......................................................
[1467011506080] task finished: success(true)
.....................[1467011508477] task started: size(100)
..............................................................Jun 27,
2016 9:11:51 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
.............Jun 27, 2016 9:11:51 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
...Jun 27, 2016 9:11:51 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
.........
[1467011505919] task finished: success(true)
............[1467011508528] task started: size(100)
.............................................................................................[1467011508580]
task started: size(100)
.......................................
[1467011506024] task finished: success(true)
...........................................................[1467011508631]
task started: size(100)
....................................................................................................[1467011508682]
task started: size(100)
.......................................................................................[1467011508733]
task started: size(100)
..............................................................................................
[1467011505973] task finished: success(true)
.[1467011508791] task started: size(100)
.........................................
[1467011506239] task finished: success(true)
.......
[1467011506135] task finished: success(true)
...........................................................[1467011508870]
task started: size(100)
...................................................................................Jun
27, 2016 9:11:52 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
.....
[1467011506290] task finished: success(true)
............[1467011508968] task started: size(100)
...............................................
[1467011506187] task finished: success(true)
.............Jun 27, 2016 9:11:52 AM
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor run
WARNUNG: Create a new selector. Selected is 0, delta = 0
................................................[1467011509020] task
started: size(100)
............................
[1467011506394] task finished: success(true)
.................................
[1467011506446] task finished: success(true)
........................Jun 27, 2016 9:11:52 AM
de.root1.simon.Dispatcher exceptionCaught
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 05 73
72 01 00 0E 6A 61 76 61 2E 6C 61 6E 67 2E 4C 6F 6E 67 78 72 01 00 10
6A 61 76 61 2E 6C 61 6E 67 2E 4E 75 6D 62 65 72 78 70 00 00 01 55 90
B3 24 E0 00 00 00 36 AC ED 00 05 73 72 01 00 0E 6A 61 76 61 2E 6C 61
6E 67 2E 4C 6F 6E 67 78 72 01 00 10 6A 61 76 61 2E 6C 61 6E 67 2E 4E
75 6D 62 65 72 78 70 00 00 00 00 00 00 00 3C 02 00 00 13 85 00 00 00
FE 00 7C 53 69 6D 6F 6E 52 65 6D 6F 74 65 49 6E 73 74 61 6E 63 65 5B
64 65 2E 72 6F 6F 74 31 2E 73 69 6D 6F 6E 2E 74 65 73 74 2E 43 6C 69
65 6E 74 24 4D 6F 6E 69 74 6F 72 7C 69 70 3D 6C 6F 63 61 6C 68 6F 73
74 2F 31 32 37 2E 30 2E 30 2E 31 3A 35 35 35 35 35 3B 73 65 73 73 69
6F 6E 49 44 3D 31 3B 72 65 6D 6F 74 65 4F 62 6A 65 63 74 48 61 73 68
3D 31 30 39 32 39 33 36 39 35 33 5D 59 5E 09 5A 75 0E 67 BC 00 00 00
02 00 00 00 36 AC ED 00 05 73 72 01 00 0E 6A 61 76 61 2E (Hexdump: 00
00 00 02 00 00 00 36 AC ED 00 05 73 72 01 00 0E 6A 61 76 61 2E 6C 61
6E 67 2E 4C 6F 6E 67 78 72 01 00 10 6A 61 76 61 2E 6C 61 6E 67 2E 4E
75 6D 62 65 72 78 70 00 00 01 55 90 B3 24 E0 00 00 00 36 AC ED 00 05
73 72 01 00 0E 6A 61 76 61 2E 6C 61 6E 67 2E 4C 6F 6E 67 78 72 01 00
10 6A 61 76 61 2E 6C 61 6E 67 2E 4E 75 6D 62 65 72 78 70 00 00 00 00
00 00 00 3C 02 00 00 13 85 00 00 00 FE 00 7C 53 69 6D 6F 6E 52 65 6D
6F 74 65 49 6E 73 74 61 6E 63 65 5B 64 65 2E 72 6F 6F 74 31 2E 73 69
6D 6F 6E 2E 74 65 73 74 2E 43 6C 69 65 6E 74 24 4D 6F 6E 69 74 6F 72
7C 69 70 3D 6C 6F 63 61 6C 68 6F 73 74 2F 31 32 37 2E 30 2E 30 2E 31
3A 35 35 35 35 35 3B 73 65 73 73 69 6F 6E 49 44 3D 31 3B 72 65 6D 6F
74 65 4F 62 6A 65 63 74 48 61 73 68 3D 31 30 39 32 39 33 36 39 35 33
5D 59 5E 09 5A 75 0E 67 BC 00 00 00 02 00 00 00 36 AC ED 00 05 73 72
01 00 0E 6A 61 76 61 2E)
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)
Exception in thread "Simon.Dispatcher.WorkerPool.#13"
de.root1.simon.exceptions.SimonException: An error occured while
reading a message for remote object
'SimonRemoteInstance[de.root1.simon.test.Client$Monitor|ip=localhost/127.0.0.1:55555;sessionID=1;remoteObjectHash=1092936953]'.
Error message: Error while decoding invoke request
at
de.root1.simon.ProcessMessageRunnable.processError(ProcessMessageRunnable.java:741)
at
de.root1.simon.ProcessMessageRunnable.run(ProcessMessageRunnable.java:161)
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)
Caused by: java.lang.NullPointerException
at de.root1.simon.LookupTable.getMethod(LookupTable.java:383)
at
de.root1.simon.codec.base.MsgInvokeDecoder.decodeBody(MsgInvokeDecoder.java:67)
at
de.root1.simon.codec.base.AbstractMessageDecoder.decode(AbstractMessageDecoder.java:97)
at
org.apache.mina.filter.codec.demux.DemuxingProtocolDecoder.doDecode(DemuxingProtocolDecoder.java:188)
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)
... 3 more
Exception in thread "main"
de.root1.simon.exceptions.SessionException: Cannot handle method call
"public abstract void
de.root1.simon.tests.interfaces.Handler.trigger(de.root1.simon.tests.interfaces.ProgressInterface,long)"
on already closed Dispatcher for Session 0x00000001.
at
de.root1.simon.Dispatcher.checkForInvalidState(Dispatcher.java:691)
at de.root1.simon.Dispatcher.invokeMethod(Dispatcher.java:309)
at de.root1.simon.SimonProxy.invoke(SimonProxy.java:159)
at com.sun.proxy.$Proxy2.trigger(Unknown Source)
at de.root1.simon.test.Client.main(Client.java:43)
-----
The related encoder/decoder classes for the RPC call:
For the invoke call (client sends invoke request to server):
related message: de.root1.simon.codec.messages.MsgInvoke
de.root1.simon.codec.base.MsgInvokeEncoder --> used on client
de.root1.simon.codec.base.MsgInvokeDecoder --> used on server
For the invocation result (servers answers invoke request with
invocation result)
related message: de.root1.simon.codec.messages.MsgInvokeReturn
de.root1.simon.codec.base.MsgInvokeReturnEncoder --> used on server
de.root1.simon.codec.base.MsgInvokeReturnDecoder --> used on client
I'm very sorry that the environment on this issue is that complex. If
you need more information, please let me know.
Best regards and thanks for help,
Alex
