Debugging Hibernate AbstractFlushingEventListener Errors When Batching

Here is little trick for Hibernate users.

If you have Hibernate configured to use JDBC batching, then statements in the same transaction might be batched into one or few update trips to the server. In case of any errors when performing the batch operation, you wont be able to see which statement that failed. What you will see is something in the lines of this stacktrace:

org.hibernate.exception.ConstraintViolationException: Could not execute JDBC batch update
	at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:94)
	at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
	at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:275)
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:266)
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:167)
	at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
	at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
	...
Caused by: java.sql.BatchUpdateException: ORA-00001: unique constraint (XXX) violated
	at oracle.jdbc.driver.OraclePreparedStatement.executeBatch(OraclePreparedStatement.java:10055)
	at oracle.jdbc.driver.OracleStatementWrapper.executeBatch(OracleStatementWrapper.java:213)
	at org.apache.tomcat.dbcp.dbcp.DelegatingStatement.executeBatch(DelegatingStatement.java:297)
	at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
	at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268)
	... 112 more

You can see the offending SQL exception, in this case a Oracle unique constraint violation, but you cannot see the SQL from the batch.

Hibernate uses a class called org.hibernate.util.JDBCExceptionReporter when logging JDBC exceptions. It either WARN of ERROR logs, and most people have at least ERROR level activated for something like hibernate. But, this little piece of the class is interesting:

	public static void logExceptions(SQLException ex, String message) {
		if ( log.isErrorEnabled() ) {
			if ( log.isDebugEnabled() ) {
				message = StringHelper.isNotEmpty(message) ? message : DEFAULT_EXCEPTION_MSG;
				log.debug( message, ex );
			}
			while (ex != null) {
				StringBuffer buf = new StringBuffer(30)
						.append( "SQL Error: " )
				        .append( ex.getErrorCode() )
				        .append( ", SQLState: " )
				        .append( ex.getSQLState() );
				log.warn( buf.toString() );
				log.error( ex.getMessage() );
				ex = ex.getNextException();
			}
		}
	}

What is does is WARN and ERROR log a given exception and its causes. But it as has a part only executed, if DEBUG level has been turned on for this particular class/logger. It DEBUG logs the incoming parameter message and this message just so happens to be the offending SQL statement.

So, turn on DEBUG level for the org.hibernate.util.JDBCExceptionReporter logger and get more information on your failing SQL.

January 25, 2010   Posted in: Programming

Leave a Reply