"bad record MAC" SSL error between Java and PortgreSQL

2
votes

We've got here a problem of random disconnections between our Java apps and our PostgreSQL 8.3 server with a "bad record MAC" SSL error.

We run Debian / Lenny on both side. On the client side, we see :

main, WRITE: TLSv1 Application Data, length = 104
main, READ: TLSv1 Application Data, length = 24
main, READ: TLSv1 Application Data, length = 104
main, WRITE: TLSv1 Application Data, length = 384
main, READ: TLSv1 Application Data, length = 24
main, READ: TLSv1 Application Data, length = 8216
%% Invalidated:  [Session-1, SSL_RSA_WITH_3DES_EDE_CBC_SHA]
main, SEND TLSv1 ALERT:  fatal, description = bad_record_mac
main, WRITE: TLSv1 Alert, length = 24
main, called closeSocket()
main, handling exception: javax.net.ssl.SSLException: bad record MAC
    2010-03-09 02:36:27,980 WARN org.hibernate.util.JDBCExceptionReporter.logExceptions(JDBCExceptionReporter.java:100) - SQL Error: 0, SQLState: 08006
    2010-03-09 02:36:27,980 ERROR org.hibernate.util.JDBCExceptionReporter.logExceptions(JDBCExceptionReporter.java:101) - An I/O error occured while sending to the backend.
    2010-03-09 02:36:27,981 ERROR org.hibernate.transaction.JDBCTransaction.toggleAutoCommit(JDBCTransaction.java:232) - Could not toggle autocommit
    org.postgresql.util.PSQLException: An I/O error occured while sending to the backend.
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:220)
        at org.postgresql.jdbc2.AbstractJdbc2Connection.executeTransactionCommand(AbstractJdbc2Connection.java:650)
        at org.postgresql.jdbc2.AbstractJdbc2Connection.commit(AbstractJdbc2Connection.java:670)
        at org.postgresql.jdbc2.AbstractJdbc2Connection.setAutoCommit(AbstractJdbc2Connection.java:633)
        at sun.reflect.GeneratedMethodAccessor5.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.springframework.jdbc.datasource.SingleConnectionDataSource$CloseSuppressingInvocationHandler.invoke(SingleConnectionDataSource.java:336)
        at $Proxy17.setAutoCommit(Unknown Source)
        at org.hibernate.transaction.JDBCTransaction.toggleAutoCommit(JDBCTransaction.java:228)
        at org.hibernate.transaction.JDBCTransaction.rollbackAndResetAutoCommit(JDBCTransaction.java:220)
        at org.hibernate.transaction.JDBCTransaction.rollback(JDBCTransaction.java:196)
        at org.hibernate.ejb.TransactionImpl.rollback(TransactionImpl.java:85)
        at org.springframework.orm.jpa.JpaTransactionManager.doRollback(JpaTransactionManager.java:482)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.processRollback(AbstractPlatformTransactionManager.java:823)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.rollback(AbstractPlatformTransactionManager.java:800)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.completeTransactionAfterThrowing(TransactionAspectSupport.java:339)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
        at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:635)
        ...
    Caused by: javax.net.ssl.SSLException: Connection has been shutdown: javax.net.ssl.SSLException: bad record MAC
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.checkEOF(SSLSocketImpl.java:1255)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.checkWrite(SSLSocketImpl.java:1267)
        at com.sun.net.ssl.internal.ssl.AppOutputStream.write(AppOutputStream.java:43)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
        at org.postgresql.core.PGStream.flush(PGStream.java:508)
        at org.postgresql.core.v3.QueryExecutorImpl.sendSync(QueryExecutorImpl.java:692)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:193)
        ... 22 more
    Caused by: javax.net.ssl.SSLException: bad record MAC
        at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1611)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1569)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:850)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:746)
        at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75)
        at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:135)
        at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:104)
        at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:186)
        at org.postgresql.core.PGStream.Receive(PGStream.java:445)
        at org.postgresql.core.PGStream.ReceiveTupleV3(PGStream.java:350)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1322)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:194)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:451)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:350)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:254)
        at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)
        at org.hibernate.loader.Loader.getResultSet(Loader.java:1808)
        at org.hibernate.loader.Loader.doQuery(Loader.java:697)
        at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:259)
        at org.hibernate.loader.Loader.loadCollection(Loader.java:2015)
        at org.hibernate.loader.collection.CollectionLoader.initialize(CollectionLoader.java:59)
        at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:587)
        at org.hibernate.event.def.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:83)
        at org.hibernate.impl.SessionImpl.initializeCollection(SessionImpl.java:1743)
        at org.hibernate.collection.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:366)
        at org.hibernate.collection.PersistentSet.add(PersistentSet.java:212)
    ...

the cypher suites SSL_RSA_WITH_3DES_EDE_CBC_SHA or SSL_RSA_WITH_RC4_128_SHA were used.

We tried on the client side :

  • the OpenJDK package
  • the sun JDK package
  • the sun tar package
  • the libbcprov-java package
  • the PostgreSQL driver 8.3 instead of 8.4

On the server side we see : 

2010-03-01 08:26:05 CET [18513]: [161833-1] LOG:  SSL error: sslv3 alert bad record mac
2010-03-01 08:26:05 CET [18513]: [161834-1] LOG:  could not receive data from client: Connection reset by peer
2010-03-01 08:26:05 CET [18513]: [161835-1] LOG:  unexpected EOF on client connection

the error type seams to be SSL_R_SSLV3_ALERT_BAD_RECORD_MAC.

the SSL layer is configured with : ssl_ciphers = 'ALL:!ADH:!LOW:!EXP:!MD5:@STRENGTH'

and on the server side we changed the cipher suites to : 'ALL:!SSLv2:!MEDIUM:!AES:!ADH:!LOW:!EXP:!MD5:@STRENGTH'

but none of these changes fixed the problem. Suggestions appreciated !

1
javapostgresqlsslopenssldebian
Which piece of code is responsible for reading bytes from the tcp socket and writing them into OpenSSL? This issue normally results when someon'es rolled-at-home tcp implementation doesnt understand tcp's buffering well enough, and writes a different number of bytes into OpenSSL that were read from the wire. – Chris Becke
Is this a recent event? Might have something in common with the case discussed here - archives.postgresql.org/pgsql-admin/2010-03/msg00082.php. – Milen A. Radev
Chris, the piece of code between the socket and libssl is PostgreSQL... Milen, your hypothesis seems quite possible. The problem occured a few days after this upgrade, at a time we did a major hardware migration and relaunched big processes. what should be the solution or the workaround ? thank you both for your support ! – user289542

1 Answers

1
votes

I don't know how Java deals with it, but a number of vendors recently released security updates that disabled SSL renegotiation support, sometimes in broken ways. Some have been fixed since, some not. This could be your problem, in case this is something that happens after a fairly large amount of data (512Mb by default) has passed over a connection. Since you're likely using a connection pool, that seems quite possible.

In PostgreSQL 8.4.3 (due out this week), we have added a configuration parameter that lets you disable SSL renegotiation completely - that might be worth a try. (there are also new versions in the previous trees (like 8.3) that contain this feature)