[
https://issues.apache.org/jira/browse/DIRMINA-968?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Emmanuel Lecharny updated DIRMINA-968:
--------------------------------------
Component/s: (was: Handler)
SSL
> Memory leak in SSL Handshake errors
> -----------------------------------
>
> Key: DIRMINA-968
> URL: https://issues.apache.org/jira/browse/DIRMINA-968
> Project: MINA
> Issue Type: Bug
> Components: SSL
> Affects Versions: 2.0.7
> Environment: Centos
> Reporter: Enrique Cordero
> Priority: Critical
> Labels: memory-leak
> Fix For: 2.0.8
>
> Original Estimate: 96h
> Remaining Estimate: 96h
>
> 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
> ----------------------
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
