mina-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Enrique Cordero (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (DIRMINA-968) Memory leak in SSL Handshake errors
Date Wed, 16 Oct 2013 16:17:43 GMT

    [ https://issues.apache.org/jira/browse/DIRMINA-968?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13796934#comment-13796934
] 

Enrique Cordero commented on DIRMINA-968:
-----------------------------------------

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 is happening
is 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 

> 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
>            Priority: Critical
>              Labels: memory-leak
>   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.1#6144)

Mime
View raw message