[
https://issues.apache.org/jira/browse/DIRMINA-1083?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16417054#comment-16417054
]
Emmanuel Lecharny commented on DIRMINA-1083:
--------------------------------------------
It's a bit tricky, but as the failure is (almost) always reproductible, I can
already tell that the problem is when the client (\{{LDAP API}}) is initiating
the {{SSL}} handshake.
Technically speaking, the test starts a {{LDAP}} server (ApacheDS), no
{{SSL/TLS}} is involved at this point, the {{LDAPS}} port is not enabled. The
client (\{{LDAP API}}) is now sending a {{StartTLS}} extended operation (it's a
{{LDAP}} request asking the server to establish a secure communication over an
established {{TCP}} connection: we don't open a new connection).
There is a double {{SSL}} initialization occuring :
* one on the server, as we inject the {{SSLFilter}} in the {{MINA}} chain,
* one on the client, for the exact same reason.
The failure occurs on the second initialization, here are the {{MINA}} traces :
{noformat}
10:39:08] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] - Processing
a MESSAGE_RECEIVED for session 1
[10:39:08] DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Firing a
MESSAGE_RECEIVED event for session 1
[10:39:08] DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Event
MESSAGE_RECEIVED has been fired for session 1
[10:39:08] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 2
[10:39:08] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 1
[10:39:08] DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Firing a
MESSAGE_RECEIVED event for session 1
[10:39:08] DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Event
MESSAGE_RECEIVED has been fired for session 1
[10:39:08] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 2
[10:39:08] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 2
[10:39:08] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 1
[10:39:08] DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Firing a
MESSAGE_RECEIVED event for session 1
[10:39:08] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Adding the SSL Filter
sslFilter to the chain
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session Server[1](no
sslEngine) Initializing the SSL Handler
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session Server[1](no
sslEngine) SSL Handler Initialization done.
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...) : Starting the first handshake
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) processing the NEED_UNWRAP state
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=40
cap=40: 30 26 02 01 03 78 21 0A 01 00 04 00 04 00 8A 16...]
[10:39:09] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 2
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Writing Message : MessageWriteRequest, parent : WR
WrapperWriteRequest: StartTlsResponse : Ldap Result
Result code : (SUCCESS) success
Matched Dn : 'null'
Diagnostic message : 'null'
[10:39:09] DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Event
MESSAGE_RECEIVED has been fired for session 1
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Adding the SSL Filter
sslFilter to the chain
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session Client[2](no
sslEngine) Initializing the SSL Handler
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session Client[2](no
sslEngine) SSL Handler Initialization done.
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](ssl...) : Starting the first handshake
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](ssl...) processing the NEED_WRAP state
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](ssl...): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=302
cap=528: 16 03 03 01 29 01 00 01 25 03 03 5A BB 54 AD 04...]
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](ssl...) processing the NEED_UNWRAP state
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Message received : HeapBuffer[pos=0 lim=302 cap=32768: 16 03
03 01 29 01 00 01 25 03 03 5A BB 54 AD 04...]
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session Client[2]:
Writing Message : WriteRequest: HeapBuffer[pos=0 lim=7 cap=8: 15 03 01 00 02 01
00]
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) Processing the received message
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) processing the NEED_UNWRAP state
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) processing the NEED_TASK state
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslHandler] - 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:212)
at org.apache.mina.filter.ssl.SslFilter.sessionClosed(SslFilter.java:493)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:597)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$2(DefaultIoFilterChain.java:593)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.sessionClosed(DefaultIoFilterChain.java:1078)
at
org.apache.mina.core.filterchain.IoFilterAdapter.sessionClosed(IoFilterAdapter.java:97)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:597)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireSessionClosed(DefaultIoFilterChain.java:590)
at
org.apache.mina.core.service.IoServiceListenerSupport.fireSessionDestroyed(IoServiceListenerSupport.java:251)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.removeNow(AbstractPollingIoProcessor.java:1163)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.removeSessions(AbstractPollingIoProcessor.java:864)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:694)
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:745)
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) processing the NEED_WRAP state
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=813
cap=1057: 16 03 03 03 28 02 00 00 4D 03 03 5A BB 54 AD DE...]
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) processing the NEED_UNWRAP state
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Processing the SSL Data
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=78
cap=78: 30 4C 02 01 00 78 47 0A 01 34 04 00 04 28 55 4E...]
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Writing Message : MessageWriteRequest, parent : WR
WrapperWriteRequest: MessageType : EXTENDED_RESPONSE
Message ID : 0
Extended Response
ResponseName :'1.3.6.1.4.1.1466.20036'
Ldap Result
Result code : (UNAVAILABLE) unavailable
Matched Dn : 'null'
Diagnostic message : 'UNAVAILABLE: The server will disconnect!'
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=81
cap=81: 30 4F 02 01 00 78 4A 0A 01 02 04 00 04 2B 50 52...]
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Writing Message : MessageWriteRequest, parent : WR
WrapperWriteRequest: MessageType : EXTENDED_RESPONSE
Message ID : 0
Extended Response
ResponseName :'1.3.6.1.4.1.1466.20036'
Ldap Result
Result code : (PROTOCOL_ERROR) protocolError
Matched Dn : 'null'
Diagnostic message : 'PROTOCOL_ERROR: The server will disconnect!'
[10:39:09] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session Server[1]:
Writing Message : WriteRequest: HeapBuffer[pos=0 lim=7 cap=8: 15 03 03 00 02 01
00]
java.io.IOException: Broken pipe[10:39:09] DEBUG
[org.apache.mina.filter.ssl.SslHandler] - 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:212)
at org.apache.mina.filter.ssl.SslFilter.sessionClosed(SslFilter.java:493)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:597)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$2(DefaultIoFilterChain.java:593)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.sessionClosed(DefaultIoFilterChain.java:1078)
at
org.apache.mina.core.filterchain.IoFilterAdapter.sessionClosed(IoFilterAdapter.java:97)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:597)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireSessionClosed(DefaultIoFilterChain.java:590)
at
org.apache.mina.core.service.IoServiceListenerSupport.fireSessionDestroyed(IoServiceListenerSupport.java:251)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.removeNow(AbstractPollingIoProcessor.java:1163)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.writeBuffer(AbstractPollingIoProcessor.java:1115)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.flushNow(AbstractPollingIoProcessor.java:994)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.flush(AbstractPollingIoProcessor.java:921)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:688)
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:745)
at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
at sun.nio.ch.IOUtil.write(IOUtil.java:65)
at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:487)
at
org.apache.mina.transport.socket.nio.NioProcessor.write(NioProcessor.java:384)
at
org.apache.mina.transport.socket.nio.NioProcessor.write(NioProcessor.java:1)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.writeBuffer(AbstractPollingIoProcessor.java:1107)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.flushNow(AbstractPollingIoProcessor.java:994)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.flush(AbstractPollingIoProcessor.java:921)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:688)
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:745)
{noformat}
This *might* be a timing issue, as the test is sometime running green when I'm
debugging. Typically, here, what is interesting is that the
{{ExtendedResponse}} is sent after the handsake failure, leading to an error
(and it's expected, the socket has been closed, there is no way the server can
send something to the client anymore.
Now, while debugging, I may get some different failure, like this one :
{noformat}
[10:49:58] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 1
[10:49:58] DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Firing a
MESSAGE_RECEIVED event for session 1
[10:49:58] DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Event
MESSAGE_RECEIVED has been fired for session 1
[10:49:58] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 2
[10:49:58] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 1
[10:49:58] DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Firing a
MESSAGE_RECEIVED event for session 1
[10:49:58] DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Event
MESSAGE_RECEIVED has been fired for session 1
[10:49:58] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 2
[10:49:58] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 2
[10:49:58] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 1
[10:49:58] DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Firing a
MESSAGE_RECEIVED event for session 1
[10:49:58] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Adding the SSL Filter
sslFilter to the chain
[10:49:58] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session Server[1](no
sslEngine) Initializing the SSL Handler
[10:49:58] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session Server[1](no
sslEngine) SSL Handler Initialization done.
[10:50:01] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...) : Starting the first handshake
[10:50:01] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) processing the NEED_UNWRAP state
[10:50:01] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=40
cap=40: 30 26 02 01 03 78 21 0A 01 00 04 00 04 00 8A 16...]
[10:50:01] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 2
[10:50:01] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Writing Message : MessageWriteRequest, parent : WR
WrapperWriteRequest: StartTlsResponse : Ldap Result
Result code : (SUCCESS) success
Matched Dn : 'null'
Diagnostic message : 'null'
[10:50:01] DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Event
MESSAGE_RECEIVED has been fired for session 1
[10:50:09] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Adding the SSL Filter
sslFilter to the chain
[10:50:09] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session Client[2](no
sslEngine) Initializing the SSL Handler
[10:50:10] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session Client[2](no
sslEngine) SSL Handler Initialization done.
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](ssl...) : Starting the first handshake
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](ssl...) processing the NEED_WRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](ssl...): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=302
cap=528: 16 03 03 01 29 01 00 01 25 03 03 5A BB 57 42 0E...]
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Message received : HeapBuffer[pos=0 lim=302 cap=32768: 16 03
03 01 29 01 00 01 25 03 03 5A BB 57 42 0E...]
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) Processing the received message
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) processing the NEED_UNWRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) processing the NEED_TASK state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](ssl...) processing the NEED_UNWRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) processing the NEED_WRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=813
cap=1057: 16 03 03 03 28 02 00 00 4D 03 03 5A BB 57 43 CC...]
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) processing the NEED_UNWRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Processing the SSL Data
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](ssl...): Message received : HeapBuffer[pos=0 lim=813 cap=1024: 16 03
03 03 28 02 00 00 4D 03 03 5A BB 57 43 CC...]
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](ssl...) Processing the received message
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](ssl...) processing the NEED_UNWRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](ssl...) processing the NEED_TASK state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](ssl...) processing the NEED_WRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](ssl...): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=75
cap=132: 16 03 03 00 46 10 00 00 42 41 04 99 35 BB 5F 31...]
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](ssl...) processing the NEED_WRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](ssl...): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=6
cap=8: 14 03 03 00 01 01]
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](ssl...) processing the NEED_WRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](ssl...): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=101
cap=132: 16 03 03 00 60 E1 61 07 0A 9C 58 C8 0E BD 07 72...]
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](ssl...) processing the NEED_UNWRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](ssl...) processing the NEED_UNWRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](ssl...) processing the NEED_UNWRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](ssl...): Processing the SSL Data
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Message received : HeapBuffer[pos=0 lim=182 cap=16384: 16 03
03 00 46 10 00 00 42 41 04 99 35 BB 5F 31...]
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) Processing the received message
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) processing the NEED_UNWRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) processing the NEED_TASK state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) processing the NEED_UNWRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) processing the NEED_WRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=6
cap=8: 14 03 03 00 01 01]
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) processing the NEED_WRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](ssl...): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=101
cap=132: 16 03 03 00 60 99 31 3B FC A6 9D E5 7B 8B AB CF...]
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](ssl...) processing the FINISHED state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](SSL) is now secured
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](SSL) processing the FINISHED state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](SSL) is now secured
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](SSL): Processing the SSL Data
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](SSL): Writing Message : MessageWriteRequest, parent : WR
WrapperWriteRequest: StartTlsResponse : Ldap Result
Result code : (SUCCESS) success
Matched Dn : 'null'
Diagnostic message : 'null'
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](ssl...): Message received : HeapBuffer[pos=0 lim=107 cap=1024: 14 03
03 00 01 01 16 03 03 00 60 99 31 3B FC A6...]
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](ssl...) Processing the received message
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](ssl...) processing the NEED_UNWRAP state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](ssl...) processing the FINISHED state
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](SSL) is now secured
[10:50:11] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](SSL): Processing the SSL Data
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](SSL): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=61 cap=61:
30 3B 02 01 04 63 36 04 13 75 69 64 3D 61 64 6D...]
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](SSL): Message received : HeapBuffer[pos=0 lim=133 cap=16384: 17 03 03
00 80 CA 0F 40 89 1A 3E 70 F6 6D 00 9C...]
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](SSL) Processing the received message
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](SSL): Processing the SSL Data
[10:50:14] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 1
[10:50:14] DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Firing a
MESSAGE_RECEIVED event for session 1
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](SSL): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=1706
cap=1706: 30 82 06 A6 02 01 04 64 82 06 9F 04 13 75 69 64...]
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](SSL): Message received : HeapBuffer[pos=0 lim=512 cap=512: 17 03 03
06 F0 19 77 B0 A3 6F 3B B0 14 CC 5E C5...]
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](SSL): Writing Message : MessageWriteRequest, parent : WR
WrapperWriteRequest: MessageType : SEARCH_RESULT_ENTRY
Message ID : 4
Search Result Entry
Entry
dn[n]: uid=admin,ou=system
objectClass: top
objectClass: person
objectClass: organizationalPerson
objectClass: inetOrgPerson
objectClass: tlsKeyInfo
uid: admin
userPassword: 0x73 0x65 0x63 0x72 0x65 0x74
publicKey: 0x30 0x81 0x9F 0x30 0x0D 0x06 0x09 0x2A 0x86 0x48 0x86 0xF7 0x0D
0x01 0x01 0x01 ...
publicKeyFormat: X.509
userCertificate: 0x30 0x82 0x01 0xF8 0x30 0x82 0x01 0x61 0x02 0x06 0x01
0x62 0x6B 0xCC 0xAC 0x66 ...
privateKey: 0x30 0x82 0x02 0x76 0x02 0x01 0x00 0x30 0x0D 0x06 0x09 0x2A
0x86 0x48 0x86 0xF7 ...
keyAlgorithm: RSA
privateKeyFormat: PKCS#8
cn: system administrator
sn: administrator
displayName: Directory Superuser
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](SSL) Processing the received message
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](SSL): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=14 cap=14:
30 0C 02 01 04 65 07 0A 01 00 04 00 04 00]
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](SSL): Processing the SSL Data
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](SSL): Message received : HeapBuffer[pos=0 lim=1024 cap=1024: BA 78 7C
1E 15 D5 A7 31 2B BA 07 F7 8A A2 CE 78...]
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](SSL) Processing the received message
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](SSL): Processing the SSL Data
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](SSL): Writing Message : MessageWriteRequest, parent : WR
WrapperWriteRequest: MessageType : SEARCH_RESULT_DONE
Message ID : 4
Search Result Done
Ldap Result
Result code : (SUCCESS) success
Matched Dn : 'null'
Diagnostic message : 'null'
[10:50:14] DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Event
MESSAGE_RECEIVED has been fired for session 1
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](SSL): Message received : HeapBuffer[pos=0 lim=330 cap=2048: 52 10 7C
4A CA 65 9E 03 48 82 D7 9D 01 C9 5A 97...]
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Client[2](SSL) Processing the received message
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](SSL): Processing the SSL Data
[10:50:14] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 2
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](SSL): Writing Message : MessageWriteRequest, parent : WR
WrapperWriteRequest: MessageType : SEARCH_REQUEST
Message ID : 4
SearchRequest
baseDn : 'uid=admin,ou=system'
filter : '(objectClass=*)'
scope : base object
typesOnly : false
Size Limit : no limit
Time Limit : no limit
Deref Aliases : deref Always
attributes : '*'
org.apache.directory.api.ldap.model.message.SearchRequestImpl@6f1f8e8e
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](SSL): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=7 cap=7:
30 05 02 01 05 42 00]
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Client[2](SSL): Writing Message : MessageWriteRequest, parent : WR
WrapperWriteRequest: MessageType : UNBIND_REQUEST
Message ID : 5
UnBind
Requestorg.apache.directory.api.ldap.model.message.UnbindRequestImpl@b33423f3
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](SSL): Message received : HeapBuffer[pos=0 lim=85 cap=8192: 17 03 03
00 50 BD D4 DD 89 66 CB 19 3C 86 5C CA...]
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](SSL) Processing the received message
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session Client[2]:
Writing Message : WriteRequest: HeapBuffer[pos=0 lim=85 cap=132: 15 03 03 00 50
18 3D 5E 50 F7 D6 DB 74 E6 B1 83...]
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](SSL): Processing the SSL Data
[10:50:14] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
Processing a MESSAGE_RECEIVED for session 1
[10:50:14] DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Firing a
MESSAGE_RECEIVED event for session 1
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](SSL): Message received : HeapBuffer[pos=0 lim=85 cap=8192: 15 03 03
00 50 18 3D 5E 50 F7 D6 DB 74 E6 B1 83...]
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslHandler] - Session
Server[1](SSL) Processing the received message
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session
Server[1](SSL): Processing the SSL Data
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session Server[1]:
Writing Message : WriteRequest: HeapBuffer[pos=0 lim=85 cap=132: 15 03 03 00 50
05 1C E6 FC 3B 8C CD 57 44 77 D8...]
[10:50:14] DEBUG [org.apache.mina.core.filterchain.IoFilterEvent] - Event
MESSAGE_RECEIVED has been fired for session 1
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslFilter] - Session Client[2]:
Message received : HeapBuffer[pos=0 lim=85 cap=2048: 15 03 03 00 50 05 1C E6 FC
3B 8C CD 57 44 77 D8...]
[10:50:14] DEBUG [org.apache.mina.filter.ssl.SslHandler] - 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:212)
at org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:520)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:641)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$6(DefaultIoFilterChain.java:637)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:1114)
at
org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:121)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:641)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:634)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:539)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$17(AbstractPollingIoProcessor.java:505)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.process(AbstractPollingIoProcessor.java:1242)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.process(AbstractPollingIoProcessor.java:1231)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:683)
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:745)
{noformat}
Here, the handshake was fine on both side, then we can see in this trace that
the client is sending a {{SearchRequest}} and get the result properly - so far,
so good -, the failure happens at the very end, when the client has sent an
{{UnbindRequest}}. Now, this is a bit weird, because such a request does not
expect to receive any response. I would assume it's the moment the {{SSL}}
binding is being shut down.
I'm still diging... What makes things more complex is that I'm using {{MINA}}
at both sides, so the problem may be on the client or server side. I may switch
to {{MINA 2.0.16}} on the server side and keep {{MINA 2.0.17}} on the client
side, to see if it still fails, that would make things easier to debug...
> Regression on SSL connection
> ----------------------------
>
> Key: DIRMINA-1083
> URL: https://issues.apache.org/jira/browse/DIRMINA-1083
> Project: MINA
> Issue Type: Bug
> Affects Versions: 2.0.17
> Reporter: Emmanuel Lecharny
> Priority: Major
> Fix For: 2.0.18
>
>
> We are using MINA in Apache Directory. After having moved to MINA 2.0.17, we
> now have failures like :
> {noformat}
> Running org.apache.directory.shared.client.api.LdapSSLConnectionTest
> java.io.IOException: Broken pipe
> at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
> at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
> at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
> at sun.nio.ch.IOUtil.write(IOUtil.java:65)
> at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)
> at
> org.apache.mina.transport.socket.nio.NioProcessor.write(NioProcessor.java:384)
> at
> org.apache.mina.transport.socket.nio.NioProcessor.write(NioProcessor.java:47)
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.writeBuffer(AbstractPollingIoProcessor.java:1107)
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.flushNow(AbstractPollingIoProcessor.java:994)
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.flush(AbstractPollingIoProcessor.java:921)
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:688)
> at
> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
> {noformat}
>
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
