mina-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Eduard Tudenhoefner (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (DIRMINA-1046) Occasionally seeing "Invalid TLS padding data" due to "bad_record_mac"
Date Thu, 27 Oct 2016 10:23:58 GMT

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

Eduard Tudenhoefner commented on DIRMINA-1046:
----------------------------------------------

[~elecharny] I enabled SSL debugging and compared between a successful & a failed run
and the only difference I found in the SSL debug output was the below stuff
{code}
Node 1 stdout: NioProcessor-1, fatal error: 80: problem unwrapping net record
Node 1 stdout: javax.net.ssl.SSLProtocolException: Input SSL/TLS record too big: max = 33305
len = 50586
Node 1 stdout: %% Invalidated:  [Session-1, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384]
Node 1 stdout: NioProcessor-1, SEND TLSv1.2 ALERT:  fatal, description = internal_error
Node 1 stdout: NioProcessor-1, WRITE: TLSv1.2 Alert, length = 80
Node 1 stdout: NioProcessor-1, called closeOutbound()
Node 1 stdout: NioProcessor-1, closeOutboundInternal()
Node 1 stdout: NioProcessor-1, called closeInbound()
Node 1 stdout: NioProcessor-1, fatal: engine already closed.  Rethrowing javax.net.ssl.SSLException:
Inbound closed before receiving peer's close_notify: possible truncation attack?
Node 1 stdout: NioProcessor-1, called closeOutbound()
Node 1 stdout: NioProcessor-1, closeOutboundInternal()
[Raw read]: length = 5
0000: 15 03 03 00 50                                     ....P
[Raw read]: length = 80
0000: B8 08 BB DE 88 16 7C FC   E5 92 95 EB 1F BB B3 19  ................
0010: E5 41 C8 4D DD 73 5D 80   DA B5 3D 19 C8 8A 1D ED  .A.M.s]...=.....
0020: 17 4F E8 ED 44 E0 22 6B   BC 6F 36 DF 9F 6E 79 05  .O..D."k.o6..ny.
0030: 19 51 0A 60 5C 8D 9A 89   9B 76 1C 4E 0B 3B B0 53  .Q.`\....v.N.;.S
0040: 96 EA E7 BC 70 07 D7 E0   5F AA 12 2E 00 57 85 0A  ....p..._....W..
NioProcessor-6, READ: TLSv1.2 Alert, length = 80
Padded plaintext after DECRYPTION:  len = 80
0000: 9E 53 24 92 22 EE 90 95   E9 E6 F7 9D 9A F9 3B 60  .S$.".........;`
0010: 02 50 FA A8 B0 08 7F A3   3C 90 80 1F AE BD 31 DE  .P......<.....1.
0020: 6F DA 8F 87 4A 5E 7E 34   70 4D 6C 77 74 1B B1 56  o...J^.4pMlwt..V
0030: 2E C2 EE 6C D5 D0 53 7E   74 EE CA 40 82 06 22 E6  ...l..S.t..@..".
0040: 6F 78 0D 0D 0D 0D 0D 0D   0D 0D 0D 0D 0D 0D 0D 0D  ox..............
NioProcessor-6, RECV TLSv1.2 ALERT:  fatal, internal_error
NioProcessor-6, fatal: engine already closed.  Rethrowing javax.net.ssl.SSLException: Received
fatal alert: internal_error
NioProcessor-6, fatal: engine already closed.  Rethrowing javax.net.ssl.SSLException: Received
fatal alert: internal_error
{code}

This is very interesting: {{Input SSL/TLS record too big: max = 33305 len = 50586}} 

The stack trace in the log just shows
{code}
1  WARN [NioProcessor-1] 2016-10-27 08:39:45,676 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
{code}

> 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)

Mime
View raw message