[
https://issues.apache.org/jira/browse/DIRMINA-1046?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Eduard Tudenhoefner updated DIRMINA-1046:
-----------------------------------------
Description:
We're occasionally (especially under higher load) seeing the below stack trace
{code}
1 DEBUG [SharedPool-Worker-1] 2016-09-21 17:55:11,077 SslFilter.java (line 608)
Session Client[1](SSL): Writing Message : MessageWriteRequest, parent : WR
WrapperWriteRequest: MessageType : SEARCH_REQUEST
Message ID : 4
SearchRequest
baseDn : 'ou=users,dc=ds,dc=com'
filter : '(uid=cass)'
scope : whole subtree
typesOnly : false
Size Limit : no limit
Time Limit : no limit
Deref Aliases : deref Always
attributes :
org.apache.directory.api.ldap.model.message.SearchRequestImpl@d2256c99
DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,080 IoFilterEvent.java (line 68)
Firing a MESSAGE_RECEIVED event for session 2
DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,085 SslFilter.java (line 608)
Session Server[2](SSL): Writing Message : WriteRequest: HeapBuffer[pos=0
lim=521 cap=521: 30 82 02 05 02 01 04 64 82 01 FE 04 29 75 69 64...]
DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,086 SslFilter.java (line 608)
Session Server[2](SSL): Writing Message : MessageWriteRequest, parent : WR
WrapperWriteRequest: MessageType : SEARCH_RESULT_ENTRY
Message ID : 4
Search Result Entry
Entry
dn[n]: uid=cass,ou=users,dc=ds,dc=com
objectclass: organizationalPerson
objectclass: person
objectclass: krb5principal
objectclass: inetOrgPerson
objectclass: krb5kdcentry
objectclass: top
uid: cass
userPassword: 0x7B 0x53 0x53 0x48 0x41 0x7D 0x45 0x45 0x6A 0x30 0x77 0x31
0x73 0x48 0x4B 0x52 ...
cn: Cass User
sn: User
krb5KeyVersionNumber: 0
krb5Key: 0x30 0x19 0xA0 0x03 0x02 0x01 0x11 0xA1 0x12 0x04 0x10 0x47 0xCA
0x25 0xE8 0xD2 ...
krb5Key: 0x30 0x19 0xA0 0x03 0x02 0x01 0x17 0xA1 0x12 0x04 0x10 0x87 0x8D
0x80 0x14 0x60 ...
krb5Key: 0x30 0x11 0xA0 0x03 0x02 0x01 0x03 0xA1 0x0A 0x04 0x08 0xA4 0x7F
0xB0 0x9D 0xAE ...
krb5Key: 0x30 0x21 0xA0 0x03 0x02 0x01 0x10 0xA1 0x1A 0x04 0x18 0xC8 0x76
0x52 0xA1 0x16 ...
krb5Key: 0x30 0x29 0xA0 0x03 0x02 0x01 0x12 0xA1 0x22 0x04 0x20 0x4A 0xAF
0xE1 0x47 0x70 ...
krb5principalname: cass@DSX
DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,087 SslFilter.java (line 608)
Session Server[2](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]
DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,087 SslFilter.java (line 608)
Session Server[2](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'
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,086 SslFilter.java (line 484)
Session Client[1](SSL): Message received : HeapBuffer[pos=512 lim=512 cap=512:
empty]
DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,087 IoFilterEvent.java (line 117)
Event MESSAGE_RECEIVED has been fired for session 2
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,087 SslHandler.java (line 345)
Session Client[1](SSL) Processing the received message
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,087 SslFilter.java (line 770)
Session Client[1](SSL): Processing the SSL Data
INFO [pool-1-thread-3] 2016-09-21 17:55:11,089
RemoteAppenderStreamClient.java (line 123) client 127.0.0.1:34082: connection
closed
INFO [pool-1-thread-4] 2016-09-21 17:55:11,090
RemoteAppenderStreamClient.java (line 88) client 127.0.0.1:34918: connected
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,087 SslHandler.java (line 345)
Session Client[1](SSL) Processing the received message
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,087 SslFilter.java (line 770)
Session Client[1](SSL): Processing the SSL Data
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,088 SslFilter.java (line 484)
Session Client[1](SSL): Message received : HeapBuffer[pos=85 lim=85 cap=1024:
empty]
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,088 SslHandler.java (line 345)
Session Client[1](SSL) Processing the received message
DEBUG [NioProcessor-21] 2016-09-21 17:55:11,093 SslFilter.java (line 484)
Session Server[2](SSL): Message received : HeapBuffer[pos=0 lim=85 cap=8192: 15
03 03 00 50 4C 5A 2A AA 6C 06 5E FD 83 F3 5F...]
DEBUG [NioProcessor-21] 2016-09-21 17:55:11,093 SslHandler.java (line 345)
Session Server[2](SSL) Processing the received message
1 WARN [NioProcessor-1] 2016-09-21 17:55:11,091 LdapNetworkConnection.java
(line 1898) Invalid TLS padding data
javax.net.ssl.SSLException: Invalid TLS padding data
at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1703)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:965)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:890)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:764)
~[na:1.7.0_80]
at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624) ~[na:1.7.0_80]
at org.apache.mina.filter.ssl.SslHandler.unwrap(SslHandler.java:753)
~[mina-core-2.0.13.jar:na]
at
org.apache.mina.filter.ssl.SslHandler.messageReceived(SslHandler.java:368)
~[mina-core-2.0.13.jar:na]
at
org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:500)
~[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:535)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:697)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:651)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:640)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:68)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1097)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
[mina-core-2.0.13.jar:na]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[na:1.7.0_80]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[na:1.7.0_80]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_80]
Caused by: javax.crypto.BadPaddingException: Invalid TLS padding data
at sun.security.ssl.CipherBox.removePadding(CipherBox.java:738)
~[na:1.7.0_80]
at sun.security.ssl.CipherBox.decrypt(CipherBox.java:494) ~[na:1.7.0_80]
at
sun.security.ssl.EngineInputRecord.decrypt(EngineInputRecord.java:210)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:959)
~[na:1.7.0_80]
... 21 common frames omitted
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,091 SslFilter.java (line 608)
Session Client[1]: Writing Message : WriteRequest: HeapBuffer[pos=0 lim=85
cap=132: 15 03 03 00 50 4C 5A 2A AA 6C 06 5E FD 83 F3 5F...]
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,092 SslHandler.java (line 214)
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)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1639)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1607)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.closeInbound(SSLEngineImpl.java:1537)
~[na:1.7.0_80]
at org.apache.mina.filter.ssl.SslHandler.destroy(SslHandler.java:212)
~[mina-core-2.0.13.jar:na]
at
org.apache.mina.filter.ssl.SslFilter.initiateClosure(SslFilter.java:753)
[mina-core-2.0.13.jar:na]
at org.apache.mina.filter.ssl.SslFilter.filterClose(SslFilter.java:675)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callPreviousFilterClose(DefaultIoFilterChain.java:644)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1600(DefaultIoFilterChain.java:48)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.filterClose(DefaultIoFilterChain.java:958)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.IoFilterAdapter.filterClose(IoFilterAdapter.java:130)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callPreviousFilterClose(DefaultIoFilterChain.java:644)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1600(DefaultIoFilterChain.java:48)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.filterClose(DefaultIoFilterChain.java:958)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.filterClose(DefaultIoFilterChain.java:882)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callPreviousFilterClose(DefaultIoFilterChain.java:644)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireFilterClose(DefaultIoFilterChain.java:637)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.session.AbstractIoSession.closeNow(AbstractIoSession.java:348)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.session.AbstractIoSession.close(AbstractIoSession.java:306)
[mina-core-2.0.13.jar:na]
at
org.apache.directory.ldap.client.api.LdapNetworkConnection.exceptionCaught(LdapNetworkConnection.java:1915)
[api-ldap-client-api-1.0.0-RC1.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.exceptionCaught(DefaultIoFilterChain.java:824)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextExceptionCaught(DefaultIoFilterChain.java:590)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1100(DefaultIoFilterChain.java:48)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.exceptionCaught(DefaultIoFilterChain.java:933)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.IoFilterAdapter.exceptionCaught(IoFilterAdapter.java:102)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextExceptionCaught(DefaultIoFilterChain.java:590)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1100(DefaultIoFilterChain.java:48)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.exceptionCaught(DefaultIoFilterChain.java:933)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.filter.ssl.SslFilter.exceptionCaught(SslFilter.java:585)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextExceptionCaught(DefaultIoFilterChain.java:590)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1100(DefaultIoFilterChain.java:48)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.exceptionCaught(DefaultIoFilterChain.java:933)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.IoFilterAdapter.exceptionCaught(IoFilterAdapter.java:102)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextExceptionCaught(DefaultIoFilterChain.java:590)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireExceptionCaught(DefaultIoFilterChain.java:580)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:544)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:535)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:697)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:651)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:640)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:68)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1097)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
[mina-core-2.0.13.jar:na]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[na:1.7.0_80]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[na:1.7.0_80]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_80]
WARN [NioProcessor-21] 2016-09-21 17:55:11,099 LdapProtocolHandler.java (line
236) Unexpected exception forcing session to close: sending disconnect notice
to client.
javax.net.ssl.SSLException: Received fatal alert: bad_record_mac
at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1639)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1607)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1776)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1068)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:890)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:764)
~[na:1.7.0_80]
at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624) ~[na:1.7.0_80]
at org.apache.mina.filter.ssl.SslHandler.unwrap(SslHandler.java:753)
~[mina-core-2.0.13.jar:na]
at
org.apache.mina.filter.ssl.SslHandler.messageReceived(SslHandler.java:368)
~[mina-core-2.0.13.jar:na]
at
org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:500)
~[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:535)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:697)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:651)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:640)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:68)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1097)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
[mina-core-2.0.13.jar:na]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[na:1.7.0_80]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[na:1.7.0_80]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_80]
1 DEBUG [SharedPool-Worker-1] 2016-09-21 17:55:11,100 Message.java (line 452)
Responding: ERROR BAD_CREDENTIALS: Username and/or password are incorrect, v=3
DEBUG [NioProcessor-21] 2016-09-21 17:55:11,102 SslFilter.java (line 608)
Session Server[2](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...]
DEBUG [NioProcessor-21] 2016-09-21 17:55:11,103 SslFilter.java (line 608)
Session Server[2](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!'
DEBUG [NioProcessor-21] 2016-09-21 17:55:11,104 SslFilter.java (line 608)
Session Server[2]: Writing Message : WriteRequest: HeapBuffer[pos=0 lim=85
cap=132: 15 03 03 00 50 30 13 70 D3 3E 79 F2 81 9D 1B CF...]
INFO [NioProcessor-21] 2016-09-21 17:55:11,105 LdapResponseHandler.java (line
75) ignoring the message 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!'
received from null session
{code}
We've been seeing that issue with *2.0.10* and *2.0.13* and so far we failed to
reliably reproduce the issue. Could this be some kind of race condition in the
SslFilter/SslHandler/X code?
Any help is appreciated.
was:
We're occasionally (especially under higher load) seeing the below stack trace
{code}
1 DEBUG [SharedPool-Worker-1] 2016-09-21 17:55:11,077 SslFilter.java (line 608)
Session Client[1](SSL): Writing Message : MessageWriteRequest, parent : WR
WrapperWriteRequest: MessageType : SEARCH_REQUEST
Message ID : 4
SearchRequest
baseDn : 'ou=users,dc=ds,dc=com'
filter : '(uid=cass)'
scope : whole subtree
typesOnly : false
Size Limit : no limit
Time Limit : no limit
Deref Aliases : deref Always
attributes :
org.apache.directory.api.ldap.model.message.SearchRequestImpl@d2256c99
DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,080 IoFilterEvent.java (line 68)
Firing a MESSAGE_RECEIVED event for session 2
DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,085 SslFilter.java (line 608)
Session Server[2](SSL): Writing Message : WriteRequest: HeapBuffer[pos=0
lim=521 cap=521: 30 82 02 05 02 01 04 64 82 01 FE 04 29 75 69 64...]
DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,086 SslFilter.java (line 608)
Session Server[2](SSL): Writing Message : MessageWriteRequest, parent : WR
WrapperWriteRequest: MessageType : SEARCH_RESULT_ENTRY
Message ID : 4
Search Result Entry
Entry
dn[n]: uid=cass,ou=users,dc=ds,dc=com
objectclass: organizationalPerson
objectclass: person
objectclass: krb5principal
objectclass: inetOrgPerson
objectclass: krb5kdcentry
objectclass: top
uid: cass
userPassword: 0x7B 0x53 0x53 0x48 0x41 0x7D 0x45 0x45 0x6A 0x30 0x77 0x31
0x73 0x48 0x4B 0x52 ...
cn: Cass User
sn: User
krb5KeyVersionNumber: 0
krb5Key: 0x30 0x19 0xA0 0x03 0x02 0x01 0x11 0xA1 0x12 0x04 0x10 0x47 0xCA
0x25 0xE8 0xD2 ...
krb5Key: 0x30 0x19 0xA0 0x03 0x02 0x01 0x17 0xA1 0x12 0x04 0x10 0x87 0x8D
0x80 0x14 0x60 ...
krb5Key: 0x30 0x11 0xA0 0x03 0x02 0x01 0x03 0xA1 0x0A 0x04 0x08 0xA4 0x7F
0xB0 0x9D 0xAE ...
krb5Key: 0x30 0x21 0xA0 0x03 0x02 0x01 0x10 0xA1 0x1A 0x04 0x18 0xC8 0x76
0x52 0xA1 0x16 ...
krb5Key: 0x30 0x29 0xA0 0x03 0x02 0x01 0x12 0xA1 0x22 0x04 0x20 0x4A 0xAF
0xE1 0x47 0x70 ...
krb5principalname: cass@DSX
DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,087 SslFilter.java (line 608)
Session Server[2](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]
DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,087 SslFilter.java (line 608)
Session Server[2](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'
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,086 SslFilter.java (line 484)
Session Client[1](SSL): Message received : HeapBuffer[pos=512 lim=512 cap=512:
empty]
DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,087 IoFilterEvent.java (line 117)
Event MESSAGE_RECEIVED has been fired for session 2
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,087 SslHandler.java (line 345)
Session Client[1](SSL) Processing the received message
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,087 SslFilter.java (line 770)
Session Client[1](SSL): Processing the SSL Data
INFO [pool-1-thread-3] 2016-09-21 17:55:11,089
RemoteAppenderStreamClient.java (line 123) client 127.0.0.1:34082: connection
closed
INFO [pool-1-thread-4] 2016-09-21 17:55:11,090
RemoteAppenderStreamClient.java (line 88) client 127.0.0.1:34918: connected
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,087 SslHandler.java (line 345)
Session Client[1](SSL) Processing the received message
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,087 SslFilter.java (line 770)
Session Client[1](SSL): Processing the SSL Data
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,088 SslFilter.java (line 484)
Session Client[1](SSL): Message received : HeapBuffer[pos=85 lim=85 cap=1024:
empty]
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,088 SslHandler.java (line 345)
Session Client[1](SSL) Processing the received message
DEBUG [NioProcessor-21] 2016-09-21 17:55:11,093 SslFilter.java (line 484)
Session Server[2](SSL): Message received : HeapBuffer[pos=0 lim=85 cap=8192: 15
03 03 00 50 4C 5A 2A AA 6C 06 5E FD 83 F3 5F...]
DEBUG [NioProcessor-21] 2016-09-21 17:55:11,093 SslHandler.java (line 345)
Session Server[2](SSL) Processing the received message
1 WARN [NioProcessor-1] 2016-09-21 17:55:11,091 LdapNetworkConnection.java
(line 1898) Invalid TLS padding data
javax.net.ssl.SSLException: Invalid TLS padding data
at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1703)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:965)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:890)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:764)
~[na:1.7.0_80]
at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624) ~[na:1.7.0_80]
at org.apache.mina.filter.ssl.SslHandler.unwrap(SslHandler.java:753)
~[mina-core-2.0.13.jar:na]
at
org.apache.mina.filter.ssl.SslHandler.messageReceived(SslHandler.java:368)
~[mina-core-2.0.13.jar:na]
at
org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:500)
~[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:535)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:697)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:651)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:640)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:68)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1097)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
[mina-core-2.0.13.jar:na]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[na:1.7.0_80]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[na:1.7.0_80]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_80]
Caused by: javax.crypto.BadPaddingException: Invalid TLS padding data
at sun.security.ssl.CipherBox.removePadding(CipherBox.java:738)
~[na:1.7.0_80]
at sun.security.ssl.CipherBox.decrypt(CipherBox.java:494) ~[na:1.7.0_80]
at
sun.security.ssl.EngineInputRecord.decrypt(EngineInputRecord.java:210)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:959)
~[na:1.7.0_80]
... 21 common frames omitted
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,091 SslFilter.java (line 608)
Session Client[1]: Writing Message : WriteRequest: HeapBuffer[pos=0 lim=85
cap=132: 15 03 03 00 50 4C 5A 2A AA 6C 06 5E FD 83 F3 5F...]
1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,092 SslHandler.java (line 214)
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)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1639)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1607)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.closeInbound(SSLEngineImpl.java:1537)
~[na:1.7.0_80]
at org.apache.mina.filter.ssl.SslHandler.destroy(SslHandler.java:212)
~[mina-core-2.0.13.jar:na]
at
org.apache.mina.filter.ssl.SslFilter.initiateClosure(SslFilter.java:753)
[mina-core-2.0.13.jar:na]
at org.apache.mina.filter.ssl.SslFilter.filterClose(SslFilter.java:675)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callPreviousFilterClose(DefaultIoFilterChain.java:644)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1600(DefaultIoFilterChain.java:48)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.filterClose(DefaultIoFilterChain.java:958)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.IoFilterAdapter.filterClose(IoFilterAdapter.java:130)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callPreviousFilterClose(DefaultIoFilterChain.java:644)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1600(DefaultIoFilterChain.java:48)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.filterClose(DefaultIoFilterChain.java:958)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.filterClose(DefaultIoFilterChain.java:882)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callPreviousFilterClose(DefaultIoFilterChain.java:644)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireFilterClose(DefaultIoFilterChain.java:637)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.session.AbstractIoSession.closeNow(AbstractIoSession.java:348)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.session.AbstractIoSession.close(AbstractIoSession.java:306)
[mina-core-2.0.13.jar:na]
at
org.apache.directory.ldap.client.api.LdapNetworkConnection.exceptionCaught(LdapNetworkConnection.java:1915)
[api-ldap-client-api-1.0.0-RC1.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.exceptionCaught(DefaultIoFilterChain.java:824)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextExceptionCaught(DefaultIoFilterChain.java:590)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1100(DefaultIoFilterChain.java:48)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.exceptionCaught(DefaultIoFilterChain.java:933)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.IoFilterAdapter.exceptionCaught(IoFilterAdapter.java:102)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextExceptionCaught(DefaultIoFilterChain.java:590)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1100(DefaultIoFilterChain.java:48)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.exceptionCaught(DefaultIoFilterChain.java:933)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.filter.ssl.SslFilter.exceptionCaught(SslFilter.java:585)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextExceptionCaught(DefaultIoFilterChain.java:590)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1100(DefaultIoFilterChain.java:48)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.exceptionCaught(DefaultIoFilterChain.java:933)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.IoFilterAdapter.exceptionCaught(IoFilterAdapter.java:102)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextExceptionCaught(DefaultIoFilterChain.java:590)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireExceptionCaught(DefaultIoFilterChain.java:580)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:544)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:535)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:697)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:651)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:640)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:68)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1097)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
[mina-core-2.0.13.jar:na]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[na:1.7.0_80]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[na:1.7.0_80]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_80]
WARN [NioProcessor-21] 2016-09-21 17:55:11,099 LdapProtocolHandler.java (line
236) Unexpected exception forcing session to close: sending disconnect notice
to client.
javax.net.ssl.SSLException: Received fatal alert: bad_record_mac
at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1639)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1607)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1776)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1068)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:890)
~[na:1.7.0_80]
at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:764)
~[na:1.7.0_80]
at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624) ~[na:1.7.0_80]
at org.apache.mina.filter.ssl.SslHandler.unwrap(SslHandler.java:753)
~[mina-core-2.0.13.jar:na]
at
org.apache.mina.filter.ssl.SslHandler.messageReceived(SslHandler.java:368)
~[mina-core-2.0.13.jar:na]
at
org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:500)
~[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:535)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:697)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:651)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:640)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:68)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1097)
[mina-core-2.0.13.jar:na]
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
[mina-core-2.0.13.jar:na]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[na:1.7.0_80]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[na:1.7.0_80]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_80]
1 DEBUG [SharedPool-Worker-1] 2016-09-21 17:55:11,100 Message.java (line 452)
Responding: ERROR BAD_CREDENTIALS: Username and/or password are incorrect, v=3
DEBUG [NioProcessor-21] 2016-09-21 17:55:11,102 SslFilter.java (line 608)
Session Server[2](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...]
DEBUG [NioProcessor-21] 2016-09-21 17:55:11,103 SslFilter.java (line 608)
Session Server[2](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!'
DEBUG [NioProcessor-21] 2016-09-21 17:55:11,104 SslFilter.java (line 608)
Session Server[2]: Writing Message : WriteRequest: HeapBuffer[pos=0 lim=85
cap=132: 15 03 03 00 50 30 13 70 D3 3E 79 F2 81 9D 1B CF...]
INFO [NioProcessor-21] 2016-09-21 17:55:11,105 LdapResponseHandler.java (line
75) ignoring the message 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!'
received from null session
{code}
We've been seeing that issue with *2.0.10* and *2.0.13* and so far we failed to
reliably reproduce the issue.
Any help is appreciated.
> Occasionally seeing "Invalid TLS padding data" due to "bad_record_mac"
> ----------------------------------------------------------------------
>
> Key: DIRMINA-1046
> URL: https://issues.apache.org/jira/browse/DIRMINA-1046
> Project: MINA
> Issue Type: Bug
> Components: SSL
> Affects Versions: 2.0.10, 2.0.13
> Reporter: Eduard Tudenhoefner
> Priority: Critical
>
> We're occasionally (especially under higher load) seeing the below stack trace
> {code}
> 1 DEBUG [SharedPool-Worker-1] 2016-09-21 17:55:11,077 SslFilter.java (line
> 608) Session Client[1](SSL): Writing Message : MessageWriteRequest, parent :
> WR WrapperWriteRequest: MessageType : SEARCH_REQUEST
> Message ID : 4
> SearchRequest
> baseDn : 'ou=users,dc=ds,dc=com'
> filter : '(uid=cass)'
> scope : whole subtree
> typesOnly : false
> Size Limit : no limit
> Time Limit : no limit
> Deref Aliases : deref Always
> attributes :
> org.apache.directory.api.ldap.model.message.SearchRequestImpl@d2256c99
> DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,080 IoFilterEvent.java (line
> 68) Firing a MESSAGE_RECEIVED event for session 2
> DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,085 SslFilter.java (line 608)
> Session Server[2](SSL): Writing Message : WriteRequest: HeapBuffer[pos=0
> lim=521 cap=521: 30 82 02 05 02 01 04 64 82 01 FE 04 29 75 69 64...]
> DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,086 SslFilter.java (line 608)
> Session Server[2](SSL): Writing Message : MessageWriteRequest, parent : WR
> WrapperWriteRequest: MessageType : SEARCH_RESULT_ENTRY
> Message ID : 4
> Search Result Entry
> Entry
> dn[n]: uid=cass,ou=users,dc=ds,dc=com
> objectclass: organizationalPerson
> objectclass: person
> objectclass: krb5principal
> objectclass: inetOrgPerson
> objectclass: krb5kdcentry
> objectclass: top
> uid: cass
> userPassword: 0x7B 0x53 0x53 0x48 0x41 0x7D 0x45 0x45 0x6A 0x30 0x77 0x31
> 0x73 0x48 0x4B 0x52 ...
> cn: Cass User
> sn: User
> krb5KeyVersionNumber: 0
> krb5Key: 0x30 0x19 0xA0 0x03 0x02 0x01 0x11 0xA1 0x12 0x04 0x10 0x47 0xCA
> 0x25 0xE8 0xD2 ...
> krb5Key: 0x30 0x19 0xA0 0x03 0x02 0x01 0x17 0xA1 0x12 0x04 0x10 0x87 0x8D
> 0x80 0x14 0x60 ...
> krb5Key: 0x30 0x11 0xA0 0x03 0x02 0x01 0x03 0xA1 0x0A 0x04 0x08 0xA4 0x7F
> 0xB0 0x9D 0xAE ...
> krb5Key: 0x30 0x21 0xA0 0x03 0x02 0x01 0x10 0xA1 0x1A 0x04 0x18 0xC8 0x76
> 0x52 0xA1 0x16 ...
> krb5Key: 0x30 0x29 0xA0 0x03 0x02 0x01 0x12 0xA1 0x22 0x04 0x20 0x4A 0xAF
> 0xE1 0x47 0x70 ...
> krb5principalname: cass@DSX
> DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,087 SslFilter.java (line 608)
> Session Server[2](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]
> DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,087 SslFilter.java (line 608)
> Session Server[2](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'
> 1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,086 SslFilter.java (line 484)
> Session Client[1](SSL): Message received : HeapBuffer[pos=512 lim=512
> cap=512: empty]
> DEBUG [pool-26-thread-1] 2016-09-21 17:55:11,087 IoFilterEvent.java (line
> 117) Event MESSAGE_RECEIVED has been fired for session 2
> 1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,087 SslHandler.java (line 345)
> Session Client[1](SSL) Processing the received message
> 1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,087 SslFilter.java (line 770)
> Session Client[1](SSL): Processing the SSL Data
> INFO [pool-1-thread-3] 2016-09-21 17:55:11,089
> RemoteAppenderStreamClient.java (line 123) client 127.0.0.1:34082: connection
> closed
> INFO [pool-1-thread-4] 2016-09-21 17:55:11,090
> RemoteAppenderStreamClient.java (line 88) client 127.0.0.1:34918: connected
> 1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,087 SslHandler.java (line 345)
> Session Client[1](SSL) Processing the received message
> 1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,087 SslFilter.java (line 770)
> Session Client[1](SSL): Processing the SSL Data
> 1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,088 SslFilter.java (line 484)
> Session Client[1](SSL): Message received : HeapBuffer[pos=85 lim=85 cap=1024:
> empty]
> 1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,088 SslHandler.java (line 345)
> Session Client[1](SSL) Processing the received message
> DEBUG [NioProcessor-21] 2016-09-21 17:55:11,093 SslFilter.java (line 484)
> Session Server[2](SSL): Message received : HeapBuffer[pos=0 lim=85 cap=8192:
> 15 03 03 00 50 4C 5A 2A AA 6C 06 5E FD 83 F3 5F...]
> DEBUG [NioProcessor-21] 2016-09-21 17:55:11,093 SslHandler.java (line 345)
> Session Server[2](SSL) Processing the received message
> 1 WARN [NioProcessor-1] 2016-09-21 17:55:11,091 LdapNetworkConnection.java
> (line 1898) Invalid TLS padding data
> javax.net.ssl.SSLException: Invalid TLS padding data
> at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
> ~[na:1.7.0_80]
> at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1703)
> ~[na:1.7.0_80]
> at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:965)
> ~[na:1.7.0_80]
> at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:890)
> ~[na:1.7.0_80]
> at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:764)
> ~[na:1.7.0_80]
> at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624) ~[na:1.7.0_80]
> at org.apache.mina.filter.ssl.SslHandler.unwrap(SslHandler.java:753)
> ~[mina-core-2.0.13.jar:na]
> at
> org.apache.mina.filter.ssl.SslHandler.messageReceived(SslHandler.java:368)
> ~[mina-core-2.0.13.jar:na]
> at
> org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:500)
> ~[mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:535)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:697)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:651)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:640)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:68)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1097)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
> [mina-core-2.0.13.jar:na]
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> [na:1.7.0_80]
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> [na:1.7.0_80]
> at java.lang.Thread.run(Thread.java:745) [na:1.7.0_80]
> Caused by: javax.crypto.BadPaddingException: Invalid TLS padding data
> at sun.security.ssl.CipherBox.removePadding(CipherBox.java:738)
> ~[na:1.7.0_80]
> at sun.security.ssl.CipherBox.decrypt(CipherBox.java:494) ~[na:1.7.0_80]
> at
> sun.security.ssl.EngineInputRecord.decrypt(EngineInputRecord.java:210)
> ~[na:1.7.0_80]
> at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:959)
> ~[na:1.7.0_80]
> ... 21 common frames omitted
> 1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,091 SslFilter.java (line 608)
> Session Client[1]: Writing Message : WriteRequest: HeapBuffer[pos=0 lim=85
> cap=132: 15 03 03 00 50 4C 5A 2A AA 6C 06 5E FD 83 F3 5F...]
> 1 DEBUG [NioProcessor-1] 2016-09-21 17:55:11,092 SslHandler.java (line 214)
> 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)
> ~[na:1.7.0_80]
> at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1639)
> ~[na:1.7.0_80]
> at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1607)
> ~[na:1.7.0_80]
> at sun.security.ssl.SSLEngineImpl.closeInbound(SSLEngineImpl.java:1537)
> ~[na:1.7.0_80]
> at org.apache.mina.filter.ssl.SslHandler.destroy(SslHandler.java:212)
> ~[mina-core-2.0.13.jar:na]
> at
> org.apache.mina.filter.ssl.SslFilter.initiateClosure(SslFilter.java:753)
> [mina-core-2.0.13.jar:na]
> at org.apache.mina.filter.ssl.SslFilter.filterClose(SslFilter.java:675)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.callPreviousFilterClose(DefaultIoFilterChain.java:644)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1600(DefaultIoFilterChain.java:48)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.filterClose(DefaultIoFilterChain.java:958)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.IoFilterAdapter.filterClose(IoFilterAdapter.java:130)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.callPreviousFilterClose(DefaultIoFilterChain.java:644)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1600(DefaultIoFilterChain.java:48)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.filterClose(DefaultIoFilterChain.java:958)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.filterClose(DefaultIoFilterChain.java:882)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.callPreviousFilterClose(DefaultIoFilterChain.java:644)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.fireFilterClose(DefaultIoFilterChain.java:637)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.session.AbstractIoSession.closeNow(AbstractIoSession.java:348)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.session.AbstractIoSession.close(AbstractIoSession.java:306)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.directory.ldap.client.api.LdapNetworkConnection.exceptionCaught(LdapNetworkConnection.java:1915)
> [api-ldap-client-api-1.0.0-RC1.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.exceptionCaught(DefaultIoFilterChain.java:824)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextExceptionCaught(DefaultIoFilterChain.java:590)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1100(DefaultIoFilterChain.java:48)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.exceptionCaught(DefaultIoFilterChain.java:933)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.IoFilterAdapter.exceptionCaught(IoFilterAdapter.java:102)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextExceptionCaught(DefaultIoFilterChain.java:590)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1100(DefaultIoFilterChain.java:48)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.exceptionCaught(DefaultIoFilterChain.java:933)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.filter.ssl.SslFilter.exceptionCaught(SslFilter.java:585)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextExceptionCaught(DefaultIoFilterChain.java:590)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1100(DefaultIoFilterChain.java:48)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.exceptionCaught(DefaultIoFilterChain.java:933)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.IoFilterAdapter.exceptionCaught(IoFilterAdapter.java:102)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextExceptionCaught(DefaultIoFilterChain.java:590)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.fireExceptionCaught(DefaultIoFilterChain.java:580)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:544)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:535)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:697)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:651)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:640)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:68)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1097)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
> [mina-core-2.0.13.jar:na]
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> [na:1.7.0_80]
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> [na:1.7.0_80]
> at java.lang.Thread.run(Thread.java:745) [na:1.7.0_80]
> WARN [NioProcessor-21] 2016-09-21 17:55:11,099 LdapProtocolHandler.java
> (line 236) Unexpected exception forcing session to close: sending disconnect
> notice to client.
> javax.net.ssl.SSLException: Received fatal alert: bad_record_mac
> at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
> ~[na:1.7.0_80]
> at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1639)
> ~[na:1.7.0_80]
> at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1607)
> ~[na:1.7.0_80]
> at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1776)
> ~[na:1.7.0_80]
> at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1068)
> ~[na:1.7.0_80]
> at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:890)
> ~[na:1.7.0_80]
> at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:764)
> ~[na:1.7.0_80]
> at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624) ~[na:1.7.0_80]
> at org.apache.mina.filter.ssl.SslHandler.unwrap(SslHandler.java:753)
> ~[mina-core-2.0.13.jar:na]
> at
> org.apache.mina.filter.ssl.SslHandler.messageReceived(SslHandler.java:368)
> ~[mina-core-2.0.13.jar:na]
> at
> org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:500)
> ~[mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:109)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:535)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:697)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:651)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:640)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:68)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1097)
> [mina-core-2.0.13.jar:na]
> at
> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
> [mina-core-2.0.13.jar:na]
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> [na:1.7.0_80]
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> [na:1.7.0_80]
> at java.lang.Thread.run(Thread.java:745) [na:1.7.0_80]
> 1 DEBUG [SharedPool-Worker-1] 2016-09-21 17:55:11,100 Message.java (line 452)
> Responding: ERROR BAD_CREDENTIALS: Username and/or password are incorrect, v=3
> DEBUG [NioProcessor-21] 2016-09-21 17:55:11,102 SslFilter.java (line 608)
> Session Server[2](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...]
> DEBUG [NioProcessor-21] 2016-09-21 17:55:11,103 SslFilter.java (line 608)
> Session Server[2](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!'
> DEBUG [NioProcessor-21] 2016-09-21 17:55:11,104 SslFilter.java (line 608)
> Session Server[2]: Writing Message : WriteRequest: HeapBuffer[pos=0 lim=85
> cap=132: 15 03 03 00 50 30 13 70 D3 3E 79 F2 81 9D 1B CF...]
> INFO [NioProcessor-21] 2016-09-21 17:55:11,105 LdapResponseHandler.java
> (line 75) ignoring the message 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!'
> received from null session
> {code}
> We've been seeing that issue with *2.0.10* and *2.0.13* and so far we failed
> to reliably reproduce the issue. Could this be some kind of race condition in
> the SslFilter/SslHandler/X code?
> Any help is appreciated.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
