IoAcceptor not responding for new connections_问答_开发者

In our code we are using Apache Mina on both the sides(server and client). Client is a java applet. Server is hosted on a separate machine and multiple applets connect to it and data is exchanged between them. We today experienced a strange issue that server was not accepting (or responding) to new connections coming from client whereas old sessions were working fine (data is being exchanged correctly). This is very strange because the server was up and running (and working properly) since months. This bug is difficult to track because nothing is logged on the server side when applet try to create session (not even START of sessionOpened()) and there is no exception. It seems like server is in partially non-responding state. We also tried to reproduce it but no success.

On server side this is how we have initialized mina:

acceptor.setHandler(handler);
acceptor.getSessionConfig().setReadBufferSize(2048);
acceptor.getSessionConfig().setIdleTime(IdleStatus.BOTH_IDLE, tcpServerIdleTime);
acceptor.bind(new InetSocketAddress(m_tcpPort));

This is how data written to the client:

cardReadersession.getConfig().setUseReadOperation(true);
final WriteFuture writeFuture = cardReadersession.write(message);
writeFuture.awaitUninterruptibly();
    if (writeFuture.getException() != null)
    {
        cardReadersession.getConfig().setUseReadOperation(false);
        return null;
    }

final ReadFuture readFuture = cardReadersession.read();
readFuture.awaitUninterruptibly();

if (readFuture.getException() != null) 
    {
        cardReadersession.getConfig().setUseReadOperation(false);
        return null;
}

  messageResponse = (MessageResponse ) readFuture.getMessage();
  // stop blocking inbound messages
  cardReadersession.getConfig().setUseReadOperation(false);

This is how Client connects to the server:

ConnectFuture future = connector.connect(new InetSocketAddress(hostName, portNumber));
future开发者_StackOverflow中文版.awaitUninterruptibly();
session = future.getSession();
session.getCloseFuture().awaitUninterruptibly();

Thread dump at that point

Full thread dump Java HotSpot(TM) 64-Bit Server VM (1.5.0_18-b02 mixed mode):

"NioProcessor-8" prio=1 tid=0x0000000050ed2250 nid=0x7a88 runnable [0x0000000042e04000..0x0000000042e04a90]
    at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
    at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
    at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
    - locked <0x00002aac600f4b28> (a sun.nio.ch.Util$1)
    - locked <0x00002aac600f4b10> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00002aac600f49f0> (a sun.nio.ch.PollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:70)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1067)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioProcessor-10" prio=1 tid=0x0000000050ed3e40 nid=0x538a runnable [0x0000000041447000..0x0000000041447b10]
    at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
    at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
    at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
    - locked <0x00002aac600e0b30> (a sun.nio.ch.Util$1)
    - locked <0x00002aac600e0b18> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00002aac600e02a8> (a sun.nio.ch.PollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:70)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1067)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioProcessor-15" prio=1 tid=0x00000000503f18a0 nid=0x30ab runnable [0x0000000042a00000..0x0000000042a00c10]
    at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
    at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
    at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
    - locked <0x00002aac600abf88> (a sun.nio.ch.Util$1)
    - locked <0x00002aac600abf70> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00002aac600abe68> (a sun.nio.ch.PollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:70)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1067)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioProcessor-14" prio=1 tid=0x0000000050654d60 nid=0x307e runnable [0x0000000042b01000..0x0000000042b01c90]
    at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
    at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
    at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
    - locked <0x00002aac600acc78> (a sun.nio.ch.Util$1)
    - locked <0x00002aac600acc60> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00002aac600acb40> (a sun.nio.ch.PollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:70)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1067)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioProcessor-13" prio=1 tid=0x0000000050724420 nid=0x2f9c runnable [0x00000000428ff000..0x00000000428ffe10]
    at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
    at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
    at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
    - locked <0x00002aac60086310> (a sun.nio.ch.Util$1)
    - locked <0x00002aac600862f8> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00002aac600860e0> (a sun.nio.ch.PollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:70)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1067)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioProcessor-12" prio=1 tid=0x00000000505e0b30 nid=0x2f80 runnable [0x0000000041346000..0x0000000041346a90]
    at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
    at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
    at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
    - locked <0x00002aac600a9758> (a sun.nio.ch.Util$1)
    - locked <0x00002aac600a9740> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00002aac60085e60> (a sun.nio.ch.PollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:70)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1067)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioProcessor-11" prio=1 tid=0x0000000050b67b00 nid=0x2f47 runnable [0x00000000427fe000..0x00000000427feb10]
    at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
    at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
    at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
    - locked <0x00002aac600abbf0> (a sun.nio.ch.Util$1)
    - locked <0x00002aac600abbd8> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00002aac600ab8a0> (a sun.nio.ch.PollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:70)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1067)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioSocketAcceptor-3" prio=1 tid=0x00002aaab4271a20 nid=0x2f3c waiting on condition [0x00000000425fc000..0x00000000425fcd90]
    at java.lang.Thread.sleep(Native Method)
    at org.apache.mina.core.polling.AbstractPollingIoAcceptor$Acceptor.run(AbstractPollingIoAcceptor.java:432)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioSocketAcceptor-2" prio=1 tid=0x00002aaab44074c0 nid=0x2f3b waiting on condition [0x00000000424fb000..0x00000000424fbe10]
    at java.lang.Thread.sleep(Native Method)
    at org.apache.mina.core.polling.AbstractPollingIoAcceptor$Acceptor.run(AbstractPollingIoAcceptor.java:432)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioSocketAcceptor-1" prio=1 tid=0x00002aaab4273210 nid=0x2f3a runnable [0x00000000423fa000..0x00000000423faa90]
    at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
    at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
    at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
    - locked <0x00002aac600586e0> (a sun.nio.ch.Util$1)
    - locked <0x00002aac600586c8> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00002aac600581f8> (a sun.nio.ch.PollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84)
    at org.apache.mina.transport.socket.nio.NioSocketAcceptor.select(NioSocketAcceptor.java:285)
    at org.apache.mina.core.polling.AbstractPollingIoAcceptor$Acceptor.run(AbstractPollingIoAcceptor.java:400)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"Thread-5" prio=1 tid=0x00002aaab40fec50 nid=0x2f39 waiting on condition [0x000000004188c000..0x000000004188cb10]
    at java.lang.Thread.sleep(Native Method)
    at com.novosys.fts.business.backend.process.downloadauthentication.DownloadAuthenticationServer.run(DownloadAuthenticationServer.java:372)

"Timer-1" prio=1 tid=0x00002aaab4283400 nid=0x2f38 in Object.wait() [0x000000004178b000..0x000000004178bb90]
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00002aac6005c7f8> (a java.util.TaskQueue)
    at java.lang.Object.wait(Object.java:474)
    at java.util.TimerThread.mainLoop(Timer.java:483)
    - locked <0x00002aac6005c7f8> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:462)

"com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2" daemon prio=1 tid=0x00002aaab411aed0 nid=0x2f37 waiting on condition [0x0000000040f3e000..0x0000000040f3ec10]
    at java.lang.Thread.sleep(Native Method)
    at com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask.run(BasicResourcePool.java:1805)
    at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)

"com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1" daemon prio=1 tid=0x00002aaab41048d0 nid=0x2f36 in Object.wait() [0x0000000040e3d000..0x0000000040e3dc90]
    at java.lang.Object.wait(Native Method)
    at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:534)
    - locked <0x00002aac5f9a2c48> (a com.mchange.v2.async.ThreadPoolAsynchronousRunner)

"com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0" daemon prio=1 tid=0x00002aaab40cb2d0 nid=0x2f35 waiting on condition [0x0000000040d3c000..0x0000000040d3cd10]
    at java.lang.Thread.sleep(Native Method)
    at com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask.run(BasicResourcePool.java:1805)
    at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)

"Timer-0" daemon prio=1 tid=0x00002aaab411bd50 nid=0x2f34 in Object.wait() [0x0000000040c3b000..0x0000000040c3bd90]
    at java.lang.Object.wait(Native Method)
    at java.util.TimerThread.mainLoop(Timer.java:509)
    - locked <0x00002aac5f9a3020> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:462)

"Low Memory Detector" daemon prio=1 tid=0x00002aaab0003740 nid=0x2f32 runnable [0x0000000000000000..0x0000000000000000]

"CompilerThread1" daemon prio=1 tid=0x00002aaab0001ce0 nid=0x2f31 waiting on condition [0x0000000000000000..0x0000000040937430]

"CompilerThread0" daemon prio=1 tid=0x00002aaab0000940 nid=0x2f30 waiting on condition [0x0000000000000000..0x00000000408364e0]

"AdapterThread" daemon prio=1 tid=0x00000000503c6b90 nid=0x2f2f waiting on condition [0x0000000000000000..0x0000000000000000]

"Signal Dispatcher" daemon prio=1 tid=0x00000000503c58a0 nid=0x2f2e waiting on condition [0x0000000000000000..0x0000000000000000]

"Finalizer" daemon prio=1 tid=0x00000000503b1e20 nid=0x2f2d in Object.wait() [0x00000000422f9000..0x00000000422f9d10]
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00002aac5f8b4528> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:120)
    - locked <0x00002aac5f8b4528> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:136)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=1 tid=0x00000000503b1680 nid=0x2f2c in Object.wait() [0x00000000421f8000..0x00000000421f8d90]
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:474)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
    - locked <0x00002aac5f855928> (a java.lang.ref.Reference$Lock)

"main" prio=1 tid=0x00000000502c0b10 nid=0x2f24 runnable [0x00007fff576db000..0x00007fff576dc130]
    at java.net.PlainSocketImpl.socketAccept(Native Method)
    at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
    - locked <0x00002aac602100f8> (a java.net.SocksSocketImpl)
    at java.net.ServerSocket.implAccept(ServerSocket.java:450)
    at java.net.ServerSocket.accept(ServerSocket.java:421)
    at com.novosys.fts.business.backend.process.downloadauthentication.DownloadAuthenticationService.waitForStopSignal(DownloadAuthenticationService.java:356)
    at com.novosys.fts.business.backend.process.downloadauthentication.DownloadAuthenticationService.start(DownloadAuthenticationService.java:319)
    at com.novosys.fts.business.backend.process.downloadauthentication.DownloadAuthenticationService.serviceStart(DownloadAuthenticationService.java:196)
    at com.novosys.fts.business.backend.process.downloadauthentication.DownloadAuthenticationService.main(DownloadAuthenticationService.java:87)

"VM Thread" prio=1 tid=0x00000000503ad190 nid=0x2f2b runnable 

"GC task thread#0 (ParallelGC)" prio=1 tid=0x00000000502de4b0 nid=0x2f27 runnable 

"GC task thread#1 (ParallelGC)" prio=1 tid=0x00000000502df330 nid=0x2f28 runnable 

"GC task thread#2 (ParallelGC)" prio=1 tid=0x00000000502e01b0 nid=0x2f29 runnable 

"GC task thread#3 (ParallelGC)" prio=1 tid=0x00000000502e1030 nid=0x2f2a runnable 

"VM Periodic Task Thread" prio=1 tid=0x00002aaab0006120 nid=0x2f33 waiting on condition

I can see that there are some 'locked' thread in this thread dump but can't really comprehend what is the problem. I tried analyzing it in Lockeness (an Eclipse plugin) but found difficult to pin point a problem.

Any explanation or clue on why it happened ?