Enrique Cordero created DIRMINA-968:
---------------------------------------
Summary: Memory leak in SSL Handshake errors
Key: DIRMINA-968
URL: https://issues.apache.org/jira/browse/DIRMINA-968
Project: MINA
Issue Type: Bug
Components: Handler
Affects Versions: 2.0.7
Environment: Centos
Reporter: Enrique Cordero
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.1#6144)
