On the road today Le jeudi 30 juin 2016, Alexander Christian <a...@root1.de> a écrit :
> Any update on this? > > @Emmanuel > Did you find some time to have a look into? > > > regards > Alex > > > Am 27.06.2016 um 09:34 schrieb Alexander Christian: > >> Sorry, forgot to add the attachement.... >> >> >> Am 27.06.2016 um 09:33 schrieb Alexander Christian: >> >>> 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 >>> >> > -- Regards, Cordialement, Emmanuel Lécharny www.iktek.com
