debug.log
[OF-496] javax.net.ssl.SSLException: Received fatal alert: bad_record_mac Created: 08/Dec/11 Updated: 15/Nov/13 Resolved: 15/Nov/13 |
|
| Status: | Resolved |
| Project: | Openfire |
| Components: | Core |
| Affects versions: | 3.7.0, 3.8.1, 3.8.2 |
| Fix versions: | 3.9.0 |
| Type: | Bug | Priority: | Major |
| Reporter: | Daryl Herzmann | Assignee: | Guus der Kinderen |
| Resolution: | Fixed | Votes: | 4 |
| Labels: | ssl | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original estimate: | Not Specified | ||
| Environment: |
Linux 64bit RHEL6 Sun java 1.6.0 |
||
| Attachments: |
debug.log
|
| Description |
|
Had an issue with a user unable to log in, put the server into debug mode and captured this 2011.12.08 00:19:26 [/XXX.XXX.XXX.XXX:49736] Data Read: org.apache.mina.filter.support.SSLHandler@21239bca (HeapBuffer[pos=0 lim=37 cap=1024: 15 03 01 00 20 4B 3C 99 DF B4 E7 5B B4 B8 A7 BD CF BE 54 B5 5E BB B7 59 63 82 A1 8B AC 06 FD ED 1B BD 8F AD 17]) 2011.12.08 00:19:26 [/XXX.XXX.XXX.XXX:49736] unwrap() 2011.12.08 00:19:26 [/XXX.XXX.XXX.XXX:49736] inNetBuffer: java.nio.DirectByteBuffer[pos=0 lim=37 cap=16665] 2011.12.08 00:19:26 [/XXX.XXX.XXX.XXX:49736] appBuffer: java.nio.DirectByteBuffer[pos=0 lim=33330 cap=33330] 2011.12.08 00:19:26 Launching thread for /XXX.XXX.XXX.XXX:49736 2011.12.08 00:19:26 ConnectionHandler: javax.net.ssl.SSLException: Received fatal alert: bad_record_mac at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190) at com.sun.net.ssl.internal.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1467) at com.sun.net.ssl.internal.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1435) at com.sun.net.ssl.internal.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1601) at com.sun.net.ssl.internal.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1031) at com.sun.net.ssl.internal.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:845) at com.sun.net.ssl.internal.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:721) at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:607) at org.apache.mina.filter.support.SSLHandler.unwrap0(SSLHandler.java:658) at org.apache.mina.filter.support.SSLHandler.unwrap(SSLHandler.java:596) at org.apache.mina.filter.support.SSLHandler.decrypt(SSLHandler.java:423) at org.apache.mina.filter.support.SSLHandler.messageReceived(SSLHandler.java:308) at org.apache.mina.filter.SSLFilter.messageReceived(SSLFilter.java:392) at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:299) at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilterChain.java:53) at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:648) at org.apache.mina.common.support.AbstractIoFilterChain$HeadFilter.messageReceived(AbstractIoFilterChain.java:499) at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:299) at org.apache.mina.common.support.AbstractIoFilterChain.fireMessageReceived(AbstractIoFilterChain.java:293) at org.apache.mina.transport.socket.nio.SocketIoProcessor.read(SocketIoProcessor.java:228) at org.apache.mina.transport.socket.nio.SocketIoProcessor.process(SocketIoProcessor.java:198) at org.apache.mina.transport.socket.nio.SocketIoProcessor.access$400(SocketIoProcessor.java:45) at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(SocketIoProcessor.java:485) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) 2011.12.08 00:19:26 Exiting since queue is empty for /XXX.XXX.XXX.XXX:49736 2011.12.08 00:19:26 Launching thread for /XXX.XXX.XXX.XXX:49736 2011.12.08 00:19:26 [/XXX.XXX.XXX.XXX:49736] Closed: org.apache.mina.filter.support.SSLHandler@21239bca 2011.12.08 00:19:26 [/XXX.XXX.XXX.XXX:49736] Unexpected exception from SSLEngine.closeInbound(). javax.net.ssl.SSLException: Inbound closed before receiving peer's close_notify: possible truncation attack? at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190) at com.sun.net.ssl.internal.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1467) at com.sun.net.ssl.internal.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1435) at com.sun.net.ssl.internal.ssl.SSLEngineImpl.closeInbound(SSLEngineImpl.java:1374) at org.apache.mina.filter.support.SSLHandler.destroy(SSLHandler.java:167) at org.apache.mina.filter.SSLFilter.sessionClosed(SSLFilter.java:367) at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:269) at org.apache.mina.common.support.AbstractIoFilterChain.access$800(AbstractIoFilterChain.java:53) at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionClosed(AbstractIoFilterChain.java:633) at org.apache.mina.common.support.AbstractIoFilterChain$HeadFilter.sessionClosed(AbstractIoFilterChain.java:484) at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:269) at org.apache.mina.common.support.AbstractIoFilterChain.fireSessionClosed(AbstractIoFilterChain.java:264) at org.apache.mina.common.support.IoServiceListenerSupport.fireSessionDestroyed(IoServiceListenerSupport.java:224) at org.apache.mina.transport.socket.nio.SocketIoProcessor.doRemove(SocketIoProcessor.java:188) at org.apache.mina.transport.socket.nio.SocketIoProcessor.access$600(SocketIoProcessor.java:45) at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(SocketIoProcessor.java:489) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) 2011.12.08 00:19:26 ConnectionHandler: java.io.IOException: Connection reset by peer at sun.nio.ch.FileDispatcher.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:198) at sun.nio.ch.IOUtil.read(IOUtil.java:171) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:243) at org.apache.mina.transport.socket.nio.SocketIoProcessor.read(SocketIoProcessor.java:218) at org.apache.mina.transport.socket.nio.SocketIoProcessor.process(SocketIoProcessor.java:198) at org.apache.mina.transport.socket.nio.SocketIoProcessor.access$400(SocketIoProcessor.java:45) at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(SocketIoProcessor.java:485) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) The client in debug just notes this: (18:33:06) jabber: Recv (ssl)(1): < (18:33:06) jabber: Recv (ssl)(116): iq type="result" id="purple3141490b" to="xxx@chat/Laptop"><vCard xmlns="vcard-temp"/></iq> (18:33:06) connection: Connection error on 0x3071af0 (reason: 0 description: Lost connection with server: Input/output error) (18:33:06) account: Disconnecting account xxx@chat/Laptop (0x25038b0) (18:33:06) connection: Disconnecting connection 0x3071af0 (18:33:06) jabber: Sending (ssl) (xxx@chat/Laptop): </stream:stream> (18:33:06) connection: Destroying connection 0x3071af0 I removed the user from a shared roster and the login now works. Wonder if openfire is generating some bad xml or something, hmmm |
| Comments |
| Comment by Marcin Cieślak [ 10/Dec/11 ] |
|
I've seen similar problem with JAXL-based client written in PHP (see JAXL bug report). Client was receiving the following SSL packets: 1 byte '<' which looks similar to your problem. JAXL was trying to parse every received I think it is a bug although it might be worth checking whether OF couldn't be I can't tell from timestamps what happened first - did client break the session |
| Comment by Daryl Herzmann [ 10/Dec/11 ] |
|
Thanks for your thoughts. I am not sure which happened first, it felt like the server did the disconnect. PS. I've contacted Guus to see about getting you svn rights. |
| Comment by Daryl Herzmann [ 18/Feb/12 ] |
|
Hey Guus, I updated to trunk and still am seeing this issue. Disabling the user from the shared roster fixes it. Hmmmmmm |
| Comment by Daryl Herzmann [ 19/Feb/12 ] |
|
Guus and I worked on this for most of Sunday |
| Comment by Daryl Herzmann [ 20/Feb/12 ] |
|
Full debug log for the connection on my test environment. |
| Comment by Hunter Smith [ 14/Jun/12 ] |
|
We've been running into exact same issues ever since we updated OpenFire last week (albeit we hadn't updated it in quite a while). Has there been a solution for this issue? |
| Comment by Daryl Herzmann [ 14/Jun/12 ] |
|
There is currently no solution. A hacky workaround is to adjust the group names of the shared rosters to increase or decrease the character count to get away from the 16,000 byte problem. For example, I have a shared group called 'Users', I'll simply adjust it to 'Users ' and that works, but is like playing whack-a-mole sometimes. |
| Comment by Hunter Smith [ 14/Jun/12 ] |
|
Is it different that it only works for specific users and not for everyone in the system? |
| Comment by Daryl Herzmann [ 14/Jun/12 ] |
|
I am not following your question. Certain users of your system may be hitting this bug, while others are not. |
| Comment by Hunter Smith [ 14/Jun/12 ] |
|
Yeah, that's exactly what we are experiencing. Yesterday we only had one user having problems, which somehow fixed itself after we turned debugging on in the logs in the admin console. I spent most of yesterday trying various usual fixes with no success until we turned on the debugging in the admin console. Then that one user worked. Thought we had it fixed until it happened this morning to myself and another user in my department. We did discover that if we removed our usernames from a shared roster it would work for us. I'm checking to see if we can change the shared roster names without affecting access to other systems since we are using openLDAP to authenticate and generate our rosters/groups. |
| Comment by Hunter Smith [ 14/Jun/12 ] |
|
Changing the names would cause too many conflicts with our systems. We ended up rolling it back to an earlier version that works with our current setup. |
| Comment by Daryl Herzmann [ 28/Mar/13 ] |
|
Sadly, OF 3.8.1 still has this issue. |
| Comment by Didier Roisse [ 10/Jul/13 ] |
|
Hello, javax.net.ssl.SSLException: SSLEngine error during encrypt: BUFFER_OVERFLOW src: java.nio.HeapByteBuffer[pos=16103 lim=16109 cap=32768]outNetBuffer: java.nio.DirectByteBuffer[pos=16170 lim=32768 cap=32768] Are these two exceptions linked ? I do not know if it can help you, but I saw that in this site https://issues.apache.org/jira/browse/DIRMINA-914 they solved the problem with BUFFER_OVERFLOW by expanding the buffer. Didier |
| Comment by Brian Menges [ 02/Aug/13 ] |
|
Looks like 3.8.2 is also affected by this similar bug; here's the excerpt that I get: 2013.08.01 15:53:00 org.jivesoftware.openfire.nio.ConnectionHandler - ConnectionHandler reports IOException for session: (SOCKET, R: /192.168.3.2:39004, L: /192.168.1.210:5222, S: 0.0.0.0/0.0.0.0:5222) javax.net.ssl.SSLException: Received fatal alert: bad_record_mac at sun.security.ssl.Alerts.getSSLException(Unknown Source) at sun.security.ssl.SSLEngineImpl.fatal(Unknown Source) at sun.security.ssl.SSLEngineImpl.fatal(Unknown Source) at sun.security.ssl.SSLEngineImpl.recvAlert(Unknown Source) at sun.security.ssl.SSLEngineImpl.readRecord(Unknown Source) at sun.security.ssl.SSLEngineImpl.readNetRecord(Unknown Source) at sun.security.ssl.SSLEngineImpl.unwrap(Unknown Source) at javax.net.ssl.SSLEngine.unwrap(Unknown Source) at org.apache.mina.filter.support.SSLHandler.unwrap0(SSLHandler.java:658) at org.apache.mina.filter.support.SSLHandler.unwrap(SSLHandler.java:596) at org.apache.mina.filter.support.SSLHandler.decrypt(SSLHandler.java:423) at org.apache.mina.filter.support.SSLHandler.messageReceived(SSLHandler.java:308) at org.apache.mina.filter.SSLFilter.messageReceived(SSLFilter.java:392) at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:299) at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilterChain.java:53) at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:648) at org.apache.mina.common.support.AbstractIoFilterChain$HeadFilter.messageReceived(AbstractIoFilterChain.java:499) at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:299) at org.apache.mina.common.support.AbstractIoFilterChain.fireMessageReceived(AbstractIoFilterChain.java:293) at org.apache.mina.transport.socket.nio.SocketIoProcessor.read(SocketIoProcessor.java:228) at org.apache.mina.transport.socket.nio.SocketIoProcessor.process(SocketIoProcessor.java:198) at org.apache.mina.transport.socket.nio.SocketIoProcessor.access$400(SocketIoProcessor.java:45) at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(SocketIoProcessor.java:485) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) 2013.08.01 15:53:00 org.jivesoftware.openfire.nio.ConnectionHandler - ConnectionHandler reports IOException for session: (SOCKET, R: /192.168.3.2:39004, L: /192.168.1.210:5222, S: 0.0.0.0/0.0.0.0:5222) java.io.IOException: Connection reset by peer at sun.nio.ch.FileDispatcherImpl.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(Unknown Source) at sun.nio.ch.IOUtil.readIntoNativeBuffer(Unknown Source) at sun.nio.ch.IOUtil.read(Unknown Source) at sun.nio.ch.SocketChannelImpl.read(Unknown Source) at org.apache.mina.transport.socket.nio.SocketIoProcessor.read(SocketIoProcessor.java:218) at org.apache.mina.transport.socket.nio.SocketIoProcessor.process(SocketIoProcessor.java:198) at org.apache.mina.transport.socket.nio.SocketIoProcessor.access$400(SocketIoProcessor.java:45) at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(SocketIoProcessor.java:485) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) The INFO log shows the above. I have a debug trace as well. Not sure if this is roster based for me; the forums speculate some avatar image causing this or manifesting this problem. |
| Comment by Brian Menges [ 02/Aug/13 ] |
|
Indeed, it does appear that the roster size was our issue. So since we use LDAP, I just added a new group that includes everyone (the same one we use for our filters), and that made the roster twice the size it needs to be, but now my users can log in without issue anymore. This affects 3.8.2 |
| Comment by Daryl Herzmann [ 02/Aug/13 ] |
|
Indeed, that workaround works for me as well. I updated the version field to show it occurs with 3.8.2. Out of curiosity, what JRE version and vendor are you using? |
| Comment by Brian Menges [ 02/Aug/13 ] |
|
We experienced the problem with both openjdk (version 6 compatibility I believe) and current oracle java. Currently we're running JRE 1.7 U27. I'm suspect that it is the JVM's problem, however that is a distinct possibility. |
| Comment by Brian Menges [ 05/Aug/13 ] |
|
Not sure if this is related as well (possibly not, however I cannot create issues it would seem, or I'm ignorant as to how), but http://community.igniterealtime.org/thread/49400?objectID==227805#227805 , this describes another error I see now; freaked me out because I use to only see the IOException reports with bad_record_mac, now I see this with 'Invalid Padding length'... wondering if there are more ssl issues, or if this is related but separate. 2013.08.05 08:50:16 org.jivesoftware.openfire.nio.ConnectionHandler - ConnectionHandler reports IOException for session: (SOCKET, R: /192.168.7.214:63553, L: /192.168.1.210:5222, S: 0.0.0.0/0.0.0.0:5222) javax.net.ssl.SSLHandshakeException: SSL handshake failed. at org.apache.mina.filter.SSLFilter.messageReceived(SSLFilter.java:416) at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:299) at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilterChain.java:53) at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:648) at org.apache.mina.common.support.AbstractIoFilterChain$HeadFilter.messageReceived(AbstractIoFilterChain.java:499) at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:299) at org.apache.mina.common.support.AbstractIoFilterChain.fireMessageReceived(AbstractIoFilterChain.java:293) at org.apache.mina.transport.socket.nio.SocketIoProcessor.read(SocketIoProcessor.java:228) at org.apache.mina.transport.socket.nio.SocketIoProcessor.process(SocketIoProcessor.java:198) at org.apache.mina.transport.socket.nio.SocketIoProcessor.access$400(SocketIoProcessor.java:45) at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(SocketIoProcessor.java:485) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) Caused by: javax.net.ssl.SSLHandshakeException: Invalid Padding length: 182 at sun.security.ssl.Alerts.getSSLException(Unknown Source) at sun.security.ssl.SSLEngineImpl.fatal(Unknown Source) at sun.security.ssl.SSLEngineImpl.readRecord(Unknown Source) at sun.security.ssl.SSLEngineImpl.readNetRecord(Unknown Source) at sun.security.ssl.SSLEngineImpl.unwrap(Unknown Source) at javax.net.ssl.SSLEngine.unwrap(Unknown Source) at org.apache.mina.filter.support.SSLHandler.unwrap0(SSLHandler.java:658) at org.apache.mina.filter.support.SSLHandler.unwrapHandshake(SSLHandler.java:614) at org.apache.mina.filter.support.SSLHandler.handshake(SSLHandler.java:493) at org.apache.mina.filter.support.SSLHandler.messageReceived(SSLHandler.java:306) at org.apache.mina.filter.SSLFilter.messageReceived(SSLFilter.java:392) ... 14 more Caused by: javax.crypto.BadPaddingException: Invalid Padding length: 182 at sun.security.ssl.CipherBox.removePadding(Unknown Source) at sun.security.ssl.CipherBox.decrypt(Unknown Source) at sun.security.ssl.InputRecord.decrypt(Unknown Source) at sun.security.ssl.EngineInputRecord.decrypt(Unknown Source) ... 23 more |
| Comment by Brian Menges [ 05/Aug/13 ] |
|
By the by, my environment is Debian 7.1 Wheezy using the openfire_3.8.2_all.deb installer. The javax.net.ssl.SSLException was reported for me in versions 3.8.0, 3.8.1, and 3.8.2. When I loaded 3.7.1 and finally got logged in, no one could see a roster, despite being connected. Unsure if the error was present during that version in my environment, however I do know for a fact that it was present in all the 3.8.x versions. I've used the following jvms: Currently I am running openfire under jre1.7.0_25 |
| Comment by Daryl Herzmann [ 12/Sep/13 ] |
|
http://community.igniterealtime.org/message/232710 offers an interesting assessment: SSLHandler if (src.remaining() > ((outNetBuffer.capacity() - outNetBuffer.position()) / 2)) { // We have to expand outNetBuffer // Note: there is no way to know the exact size required, but enrypted data // shouln't need to be larger than twice the source data size? outNetBuffer = SSLByteBufferPool.expandBuffer(outNetBuffer, src.capacity() * 2); Guus is going to check more into this soon! |
| Comment by Daryl Herzmann [ 12/Sep/13 ] |
|
My first pass of testing trunk for this bug looks promising. I was able to construct a roster stanza of 16113 bytes and the client was not disconnected. With 3.8.2, this bug would occur. |
| Comment by Guus der Kinderen [ 12/Sep/13 ] |
|
I replaced the MINA SSL filter with a version that is based on the source of the latest 1.1 branch of MINA (which we already used), but patched with a fix similar to the one described above and in DIRMINA-914. Daryl tested the new Openfire build, and confirmed that the issue appears to be solved. I invite you all to try out the fix. It can be obtained through this Bamboo build: http://bamboo.igniterealtime.org/browse/OPENFIRE-TRUNK/latest (use build number 393 or later). The nightlies that are available on igniterealtime.org will be updated tonight. |
| Comment by Daryl Herzmann [ 15/Nov/13 ] |
|
I'm gonna mark this as resolved. I was finally able to get this pushed to production yesterday and it resolved the issue. |
The issue is when the shared roster stanza approaches 16,000 bytes. Openfire is having difficulties sending this stanza. Once the stanza grows (much) larger than 16,000 , it is able to split it properly. The great news is that I am reproducing this on my laptop now!