Exception from DbCleaner

[Nicklas Nordborg]

The DbCleaner is a scheduled task that runs about once every day and performs database cleanup. Recently we have found that it always generate an long stack trace:

22:16:27,974  WARN NewPooledConnection:559 - [c3p0] A PooledConnection that has already signalled a Connection error is still in use!
22:16:27,974  WARN NewPooledConnection:560 - [c3p0] Another error has occurred [ org.postgresql.util.PSQLException: This connection has been closed. ] which will not be reported to listeners!
org.postgresql.util.PSQLException: This connection has been closed.
        at org.postgresql.jdbc2.AbstractJdbc2Connection.checkClosed(AbstractJdbc2Connection.java:837)
        at org.postgresql.jdbc2.AbstractJdbc2Connection.clearWarnings(AbstractJdbc2Connection.java:715)
        at com.mchange.v2.c3p0.impl.NewProxyConnection.clearWarnings(NewProxyConnection.java:959)
        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.handleAndClearWarnings(SqlExceptionHelper.java:297)
        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.logAndClearWarnings(SqlExceptionHelper.java:269)
        at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.releaseConnection(LogicalConnectionImpl.java:252)
        at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.aggressiveRelease(LogicalConnectionImpl.java:214)
        at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.afterTransaction(JdbcCoordinatorImpl.java:301)
        at org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl.afterTransaction(TransactionCoordinatorImpl.java:148)
        at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.afterTransactionCompletion(JdbcTransaction.java:138)
        at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.rollback(AbstractTransactionImpl.java:216)
        at net.sf.basedb.core.HibernateUtil.rollback(HibernateUtil.java:1245)
        at net.sf.basedb.core.ChangeHistory.deleteStrayEntries(ChangeHistory.java:232)
        at net.sf.basedb.core.Application$DbCleaner.run(Application.java:1158)
        at net.sf.basedb.util.timer.ThreadTimerTask$1.run(ThreadTimerTask.java:89)
        at java.lang.Thread.run(Thread.java:745)
Exception in thread "Thread-126552" net.sf.basedb.core.BaseException: rollback failed
        at net.sf.basedb.core.HibernateUtil.rollback(HibernateUtil.java:1249)
        at net.sf.basedb.core.ChangeHistory.deleteStrayEntries(ChangeHistory.java:232)
        at net.sf.basedb.core.Application$DbCleaner.run(Application.java:1158)
        at net.sf.basedb.util.timer.ThreadTimerTask$1.run(ThreadTimerTask.java:89)
        at java.lang.Thread.run(Thread.java:745)
Caused by: org.hibernate.TransactionException: rollback failed
        at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.rollback(AbstractTransactionImpl.java:217)
        at net.sf.basedb.core.HibernateUtil.rollback(HibernateUtil.java:1245)
        ... 4 more
Caused by: org.hibernate.TransactionException: unable to rollback against JDBC connection
        at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doRollback(JdbcTransaction.java:167)
        at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.rollback(AbstractTransactionImpl.java:211)
        ... 5 more
Caused by: org.postgresql.util.PSQLException: This connection has been closed.
        at org.postgresql.jdbc2.AbstractJdbc2Connection.checkClosed(AbstractJdbc2Connection.java:837)
        at org.postgresql.jdbc2.AbstractJdbc2Connection.rollback(AbstractJdbc2Connection.java:854)
        at com.mchange.v2.c3p0.impl.NewProxyConnection.rollback(NewProxyConnection.java:1033)
        at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doRollback(JdbcTransaction.java:163)
        ... 6 more 

Initial investigation finds that this error is happening inside a catch clause and is masking the original exception.

The catch clause needs to be fixed so that it doesn't generate additional exceptions, then we need to fix whatever is to root cause of all this.

[Nicklas Nordborg]

The root exception is (with uninteresting parts cut out)

net.sf.basedb.core.BaseException: could not execute statement
	at net.sf.basedb.core.HibernateUtil.executeUpdate(HibernateUtil.java:1607)
	at net.sf.basedb.core.ChangeHistory.deleteStrayEntries(ChangeHistory.java:225)
	at net.sf.basedb.core.Application$DbCleaner.run(Application.java:1158)
	at net.sf.basedb.util.timer.ThreadTimerTask$1.run(ThreadTimerTask.java:89)
	at java.lang.Thread.run(Unknown Source)
...
Caused by: java.io.IOException: Tried to send an out-of-range integer as a 2-byte value: 49342
	at org.postgresql.core.PGStream.SendInteger2(PGStream.java:196)
...

Further investigation reveals that 49342 is the number of items to delete from the change history and each id is sent as a parameter. This is more than the limit imposed by PostgreSQL (the limit is around 32K). The solution would be to split the deletion into multiple queries.

In theory the same problem could pop up in other places since we don't have any check for this somewhere. There is no obvious way to know about those places until the problem pops up, and depending on the query the solution may be different as well.

[Nicklas Nordborg]

(In [6712]) References #1914: Exception from DbCleaner

Do not throw exceptions from close() or rollback() methods.

[Nicklas Nordborg]

(In [6713]) References #1914: Exception from DbCleaner

Catch and log errors in DbCleaner to ensure that it continues to work after an error and there is a place to see the information.

[Nicklas Nordborg]

(In [6714]) References #1914: Exception from DbCleaner

Divide the delete query into chunks of 10000 at a time. This is well below the limit in PostgreSQL and hopefully works in MySQL as well, though I have not been able to find any information about any limit for MySQL.

[Nicklas Nordborg]

(In [6717]) References #1914: Exception from DbCleaner

Same fix in for the query in AnyToAny.deleteStrayLinks().

Moved the max number of parameters to DbEngine interface. The default implementation set this to 10000 and there is no need for subclasses to override this unless they need a lower value.

[Nicklas Nordborg]

The ItemKey.deleteUnusedItemKeys() and ProjectKey.deleteUnusedItemKeys() also work with lists of id:s. In this case there is no natural way of splitting the list into a sublist and repeating the query since it is a 'not in list' restriction. On the other hand, the BASE permission system has been designed to keep the number of keys low, and I doubt that someone is able to generate >32K different keys (we have less than 100 on the production server) so this should not be an issue in reality.