Details

    • Type: Bug
    • Status: Resolved
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 2.0.7
    • Fix Version/s: 2.0.8
    • Component/s: SSL
    • Labels:
    • Environment:
      Centos

      Description

      I am having some application using Mina 2.0.7 which is getting huge amount of SSL Handshake errors (7 million per day) because old clients do not accept the server certificate, and is leaking quite much memory.

      I have checked that we are not leaking because of leaving open connections. We are properly closing those ether by timeout or exception. But still leaking quite much.

      The only reason that I really think about is that when the client send the "bad certificate" message and the SSL Handshake fails, there would be some memory which is not properly released.

      These are the logs which corresponds to one failed request:

      --------------------------
      2013-09-23 09:36:23,827 DEBUG [NioProcessor-2] (SslFilter.java:406) - Adding the SSL Filter sslFilter to the chain
      2013-09-23 09:36:23,831 DEBUG [NioProcessor-2] (SslHandler.java:139) - Session Server[1](no sslEngine) Initializing the SSL Handler
      2013-09-23 09:36:23,844 DEBUG [NioProcessor-2] (SslHandler.java:190) - Session Server[1](no sslEngine) SSL Handler Initialization done.
      2013-09-23 09:36:23,844 DEBUG [NioProcessor-2] (SslFilter.java:645) - Session Server[1](ssl...) : Starting the first handshake
      2013-09-23 09:36:23,845 DEBUG [NioProcessor-2] (SslHandler.java:549) - Session Server[1](ssl...) processing the NEED_UNWRAP state

      2013-09-23 09:36:23,847 INFO [NioProcessor-2] (LoggingFilter.java:186) - CREATED
      2013-09-23 09:36:23,847 INFO [NioProcessor-2] (LoggingFilter.java:186) - OPENED
      2013-09-23 09:36:23,850 DEBUG [NioProcessor-2] (ServerHandler.java:65) - /125.xxx.xxx.xxx id(1) - Session opened
      2013-09-23 09:36:25,151 INFO [NioProcessor-2] (LoggingFilter.java:157) - RECEIVED: HeapBuffer[pos=0 lim=60 cap=2048: 16 03 01 00 37 01 00 00 33 03 01 D0 48 18 E0 96...]
      2013-09-23 09:36:25,152 DEBUG [NioProcessor-2] (SslFilter.java:452) - Session Server[1](ssl...): Message received : HeapBuffer[pos=0 lim=60 cap=2048: 16 03 01 00 37 01 00 00 33 03 01 D0 48 18 E0 96...]
      2013-09-23 09:36:25,152 DEBUG [NioProcessor-2] (SslHandler.java:337) - Session Server[1](ssl...) Processing the received message
      2013-09-23 09:36:25,153 DEBUG [NioProcessor-2] (SslHandler.java:549) - Session Server[1](ssl...) processing the NEED_UNWRAP state
      2013-09-23 09:36:25,154 DEBUG [NioProcessor-2] (SslHandler.java:541) - Session Server[1](ssl...) processing the NEED_TASK state
      2013-09-23 09:36:25,156 DEBUG [NioProcessor-2] (SslHandler.java:564) - Session Server[1](ssl...) processing the NEED_WRAP state
      2013-09-23 09:36:25,156 DEBUG [NioProcessor-2] (SslFilter.java:570) - Session Server[1](ssl...): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=4194 cap=4230: 16 03 01 10 5D 02 00 00 4D 03 01 52 3F E1 69 34...]
      2013-09-23 09:36:25,156 DEBUG [NioProcessor-2] (SslHandler.java:549) - Session Server[1](ssl...) processing the NEED_UNWRAP state
      2013-09-23 09:36:25,157 DEBUG [NioProcessor-2] (SslFilter.java:685) - Session Server[1](ssl...): Processing the SSL Data
      2013-09-23 09:36:25,157 INFO [NioProcessor-2] (LoggingFilter.java:157) - SENT: HeapBuffer[pos=0 lim=4194 cap=4230: 16 03 01 10 5D 02 00 00 4D 03 01 52 3F E1 69 34...]
      2013-09-23 09:36:26,826 INFO [NioProcessor-2] (LoggingFilter.java:157) - RECEIVED: HeapBuffer[pos=0 lim=7 cap=2048: 15 03 01 00 02 02 2A]
      2013-09-23 09:36:26,826 DEBUG [NioProcessor-2] (SslFilter.java:452) - Session Server[1](ssl...): Message received : HeapBuffer[pos=0 lim=7 cap=2048: 15 03 01 00 02 02 2A]
      2013-09-23 09:36:26,826 DEBUG [NioProcessor-2] (SslHandler.java:337) - Session Server[1](ssl...) Processing the received message
      2013-09-23 09:36:26,827 DEBUG [NioProcessor-2] (SslHandler.java:549) - Session Server[1](ssl...) processing the NEED_UNWRAP state
      2013-09-23 09:36:26,827 WARN [NioProcessor-2] (LoggingFilter.java:130) - EXCEPTION :
      javax.net.ssl.SSLHandshakeException: SSL handshake failed.
      at org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:487)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
      at org.apache.mina.filter.logging.LoggingFilter.messageReceived(LoggingFilter.java:208)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
      at org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:410)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:710)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:664)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:653)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:67)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1124)
      at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
      at java.lang.Thread.run(Thread.java:724)
      Caused by: javax.net.ssl.SSLException: Received fatal alert: bad_certificate
      at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
      at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1619)
      at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1587)
      at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1756)
      at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1060)
      at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:884)
      at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:758)
      at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
      at org.apache.mina.filter.ssl.SslHandler.unwrap(SslHandler.java:728)
      at org.apache.mina.filter.ssl.SslHandler.unwrapHandshake(SslHandler.java:666)
      at org.apache.mina.filter.ssl.SslHandler.handshake(SslHandler.java:552)
      at org.apache.mina.filter.ssl.SslHandler.messageReceived(SslHandler.java:351)
      at org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:468)
      ... 19 more
      2013-09-23 09:36:26,828 ERROR [NioProcessor-2] (ServerHandler.java:55) - /125.xxx.xxx.xxx id(1) - EXCEPTION : SSL handshake failed.
      javax.net.ssl.SSLHandshakeException: SSL handshake failed.
      at org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:487)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
      at org.apache.mina.filter.logging.LoggingFilter.messageReceived(LoggingFilter.java:208)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
      at org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:410)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:710)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:664)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:653)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:67)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1124)
      at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
      at java.lang.Thread.run(Thread.java:724)
      Caused by: javax.net.ssl.SSLException: Received fatal alert: bad_certificate
      at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
      at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1619)
      at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1587)
      at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1756)
      at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1060)
      at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:884)
      at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:758)
      at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
      at org.apache.mina.filter.ssl.SslHandler.unwrap(SslHandler.java:728)
      at org.apache.mina.filter.ssl.SslHandler.unwrapHandshake(SslHandler.java:666)
      at org.apache.mina.filter.ssl.SslHandler.handshake(SslHandler.java:552)
      at org.apache.mina.filter.ssl.SslHandler.messageReceived(SslHandler.java:351)
      at org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:468)
      ... 19 more
      2013-09-23 09:36:26,830 DEBUG [NioProcessor-2] (SslFilter.java:570) - Session Server[1]: Writing Message : WriteRequest: HeapBuffer[pos=0 lim=7 cap=8: 15 03 01 00 02 01 00]
      2013-09-23 09:36:26,831 INFO [NioProcessor-2] (LoggingFilter.java:157) - SENT: HeapBuffer[pos=0 lim=7 cap=8: 15 03 01 00 02 01 00]
      2013-09-23 09:36:26,831 INFO [NioProcessor-2] (LoggingFilter.java:186) - CLOSED
      2013-09-23 09:36:26,831 DEBUG [NioProcessor-2] (SslHandler.java:206) - Unexpected exception from SSLEngine.closeInbound().
      javax.net.ssl.SSLException: Inbound closed before receiving peer's close_notify: possible truncation attack?
      at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
      at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1619)
      at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1587)
      at sun.security.ssl.SSLEngineImpl.closeInbound(SSLEngineImpl.java:1517)
      at org.apache.mina.filter.ssl.SslHandler.destroy(SslHandler.java:204)
      at org.apache.mina.filter.ssl.SslFilter.sessionClosed(SslFilter.java:439)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:382)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$900(DefaultIoFilterChain.java:47)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.sessionClosed(DefaultIoFilterChain.java:750)
      at org.apache.mina.filter.logging.LoggingFilter.sessionClosed(LoggingFilter.java:238)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:382)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$900(DefaultIoFilterChain.java:47)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.sessionClosed(DefaultIoFilterChain.java:750)
      at org.apache.mina.core.filterchain.IoFilterAdapter.sessionClosed(IoFilterAdapter.java:88)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:382)
      at org.apache.mina.core.filterchain.DefaultIoFilterChain.fireSessionClosed(DefaultIoFilterChain.java:375)
      at org.apache.mina.core.service.IoServiceListenerSupport.fireSessionDestroyed(IoServiceListenerSupport.java:244)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor.removeNow(AbstractPollingIoProcessor.java:600)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor.removeSessions(AbstractPollingIoProcessor.java:560)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$800(AbstractPollingIoProcessor.java:67)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1132)
      at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
      at java.lang.Thread.run(Thread.java:724)
      2013-09-23 09:36:26,832 DEBUG [NioProcessor-2] (ServerHandler.java:73) - /125.xxx.xxx.xxx id(1) - Session closed
      ----------------------

        Activity

        Hide
        elecharny Emmanuel Lecharny added a comment -

        fixed (hopefully) with commit 1223863fdcba6848db3ee9f2e381f45df75ef999

        Show
        elecharny Emmanuel Lecharny added a comment - fixed (hopefully) with commit 1223863fdcba6848db3ee9f2e381f45df75ef999
        Hide
        elecharny Emmanuel Lecharny added a comment -

        This is quite likely the same problem.

        Show
        elecharny Emmanuel Lecharny added a comment - This is quite likely the same problem.
        Hide
        ecorderob Enrique Cordero added a comment - - edited

        No, I don't have test case for this, it is happening in production.

        I have made a dump of the memory comparing different periods and what it seems that when the SSLHandshake exception is thrown, the SSLEngine does not free its resources. I guess it is the same problem than Netty was having in previous releases.

        https://issues.jboss.org/browse/NETTY-445

        Show
        ecorderob Enrique Cordero added a comment - - edited No, I don't have test case for this, it is happening in production. I have made a dump of the memory comparing different periods and what it seems that when the SSLHandshake exception is thrown, the SSLEngine does not free its resources. I guess it is the same problem than Netty was having in previous releases. https://issues.jboss.org/browse/NETTY-445
        Hide
        jeffmaury Jeff MAURY added a comment -

        Do you have a test case ?

        Show
        jeffmaury Jeff MAURY added a comment - Do you have a test case ?

          People

          • Assignee:
            Unassigned
            Reporter:
            ecorderob Enrique Cordero
          • Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Time Tracking

              Estimated:
              Original Estimate - 96h
              96h
              Remaining:
              Remaining Estimate - 96h
              96h
              Logged:
              Time Spent - Not Specified
              Not Specified

                Development