Can't close session

Question

I have the following class:

public class TCPHandler extends IoHandlerAdapter{
    static AtomicInteger sessions = new AtomicInteger();

    @Override
    public void exceptionCaught(final IoSession session, final Throwable cause) throws Exception {
        cause.printStackTrace();
        //System.out.println(session.isConnected());    //true
        //System.out.println(session.isClosing());  //false
        session.close(true).addListener(new IoFutureListener<CloseFuture>() {   //immediately!
            @Override
            public void operationComplete(final CloseFuture future) {
                System.out.println("TCP! " + sessions.decrementAndGet());   //Never happens! :(
            }
        });
        //System.out.println(session.isConnected());    //true
        //System.out.println(session.isClosing());  //true
    }

    @Override
    public void sessionIdle(final IoSession session, final IdleStatus status) throws Exception {
        System.out.println("TCP " + session + " " + status + " " + session.getIdleCount(status));

    @Override
    public void sessionOpened(final IoSession session) throws Exception {
        System.out.println("TCP " + sessions.incrementAndGet());
    }

    @Override
    public void sessionClosed(final IoSession session) throws Exception {
        System.out.println("TCP " + sessions.decrementAndGet());
    }
}

And when I'm benchmarking my app using jMeter using 100 threads and stops the benchmark, I've got the following output:

TCP 1
TCP 2
TCP 3
...
...
TCP 75
TCP 74
TCP 73
TCP 72
TCP 71
TCP 70
TCP 69
TCP 68
TCP 67
TCP 66
Caused by: javax.net.ssl.SSLException: Received close_notify during handshake
    at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
    at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1646)
    at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1614)
    at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1756)
    at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1075)
    at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:901)
    at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:775)
    at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
    at org.apache.mina.filter.ssl.SslHandler.unwrap(SslHandler.java:748)
    at org.apache.mina.filter.ssl.SslHandler.unwrapHandshake(SslHandler.java:683)
    at org.apache.mina.filter.ssl.SslHandler.handshake(SslHandler.java:569)
    at org.apache.mina.filter.ssl.SslHandler.messageReceived(SslHandler.java:355)
    at org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:488)
    ... 15 more
javax.net.ssl.SSLHandshakeException: SSL handshake failed.
    at org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:507)
    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:714)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:668)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:657)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:67)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1121)
    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)
Caused by: javax.net.ssl.SSLException: Received close_notify during handshake
    at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
    at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1646)
    at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1614)
    at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1756)
    at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1075)
    at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:901)
    at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:775)
    at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
    at org.apache.mina.filter.ssl.SslHandler.unwrap(SslHandler.java:748)
    at org.apache.mina.filter.ssl.SslHandler.unwrapHandshake(SslHandler.java:683)
    at org.apache.mina.filter.ssl.SslHandler.handshake(SslHandler.java:569)
    at org.apache.mina.filter.ssl.SslHandler.messageReceived(SslHandler.java:355)
    at org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:488)
    ... 15 more
(0x0000006A: nio socket, server, /127.0.0.1:37867 => /127.0.0.1:10001) SSL handshake failed.
(0x00000066: nio socket, server, /127.0.0.1:37863 => /127.0.0.1:10001) SSL handshake failed.
javax.net.ssl.SSLHandshakeException: SSL handshake failed.
    at org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:507)
    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:714)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:668)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:657)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:67)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1121)
    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)
Caused by: javax.net.ssl.SSLException: Received close_notify during handshake
    at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
    at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1646)
    at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1614)
    at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1756)
    at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1075)
    at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:901)
    at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:775)
    at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
    at org.apache.mina.filter.ssl.SslHandler.unwrap(SslHandler.java:748)
    at org.apache.mina.filter.ssl.SslHandler.unwrapHandshake(SslHandler.java:683)
    at org.apache.mina.filter.ssl.SslHandler.handshake(SslHandler.java:569)
    at org.apache.mina.filter.ssl.SslHandler.messageReceived(SslHandler.java:355)
    at org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:488)
    ... 15 more
(0x0000004F: nio socket, server, /127.0.0.1:37842 => /127.0.0.1:10001) SSL handshake failed.
TCP 65
TCP 64
TCP 63
TCP 62
TCP 61
TCP 60
TCP 59
TCP 58
TCP 57
TCP 56
TCP 55

This means (if my code is correct) there are still 55 unclosed sessions! And after couple of those stopped benchmarks, app stops responding because there are too many opened file descriptors (sockets).

So my question is, why is the operationComplete method in close() listener never called, and so, why is close() never finished and socket is never closed?

is it possible that 'sessions.decrementAndGet()' inside 'operationComplete(final CloseFuture future)' throws an Exception? — jamp, Feb 06 '15 at 13:20
No, there is no exception. I just added try/catch and it's fine. — Pitel, Feb 06 '15 at 13:24
How come in your output there is no trace of your 'System.out.println(session.isConnected());' and 'System.out.println(session.isClosing());' ? — jamp, Feb 06 '15 at 13:43
I edited the log/code a bit. Those lines were commented out whe I generated the log. But the values were always as those in comments after those lines in code. — Pitel, Feb 06 '15 at 13:46
I think it would be better if you added some more code and include the actual output, maybe trying with less threads just for simplicity... — jamp, Feb 06 '15 at 13:53
I just commented the lines in code, as it was when I created the log. When I try the benchmark with less connections (10), I don't get the SSL handshake exception, but just the "connection reset by peer" `IOException`, and then the `operationComplete` finishes as expected. So meybe it's something with MINA's SSL filter. — Pitel, Feb 06 '15 at 14:07

Can't close session

0 Answers0