views:

476

answers:

1

Hello there !

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  A: 

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)

Magnus Hagander
Thank you Magnus. Will the patched version of PostgreSQL 8.3 reach the Lenny security updates ?
Stéphane Bagnier
more investigation, I doubt of this explanation. I had got a process with verbose SSL enabled which crashed after ~150kB of data read. Seems far from the 512Mb limitation.
Stéphane Bagnier
It's not actually a security update, so I'm not sure if it will. I think they will push it anyway - they usually do - but the wait may be a bit longer.
Magnus Hagander