hibernate envers

[Deno Vichas]

Is there any know issues using Hibernate Envers for auditing?  It was working great for me before switching to HikariCP when I was using c3p0.  After upgrading the exception from Envers looks to be getting suppressed by Hikari.  And Hikari doesn't seem to be rolling back the transactions on a failed audit, like it should.  

thanks,

deno

[Brett Wooldridge]

What exception do you think HikariCP is suppressing? HikariCP only catches exceptions in one place, to check for SQL states that indicate disconnection, but always rethrows the original exception.

[Brett Wooldridge]

Didn’t you post about a similar issue a few months ago?

https://groups.google.com/forum/m/#!topic/hikari-cp/oUG5vQMEHOQ

[Brett Wooldridge]

This rather long blog post about Hibernate Envers goes through a full example, including using HikariCP as the connection pool, demonstrating that they work together just fine. Maybe try asking the author of the blog about the issue you are encountering.

https://bytefish.de/blog/hibernate_envers_versioning_and_auditing/

[Deno Vichas]

No, this is a completely different issue.  That other one was a startup issue.   The posted info about how things should be configured didn't work for me and I had to make a small change.   Don't remember the details...

[Deno Vichas]

The problem I'm seeing is that the transaction isn't getting rolled back when enver throws an exception due to not being able to write to the history table.  

[Brett Wooldridge]

I don't know what to say other than to check your auto-commit setting (run with DEBUG logging to see the startup configuration).  HikariCP will automatically rollback any transaction that has not been committed, see here: https://github.com/brettwooldridge/HikariCP/blob/dev/src/main/java/com/zaxxer/hikari/pool/ProxyConnection.java#L239

isCommitStateDirty is set to true whenever any SQL update is run.  The only case in which that would not happen is if autoCommit=true, or the connection is never closed -- which would constitute a leak.  If you enable the leakDetectionThreshold you can see whether this is happening.

-Brett

[Deno Vichas]

thanks for giving me a starting point of where to look

[Deno Vichas]

setting a break point at line https://github.com/brettwooldridge/HikariCP/blob/dev/src/main/java/com/zaxxer/hikari/pool/ProxyConnection.java#L239 i see 

isCommitStateDirty == false
isAutoCommit == true
leakTask.isLeaked = true
leakTask.exception = "java.lang.Exception: Apparent connection leak detected"

without the break point I don't see anything in my logs about a leak.  i just see

[2017-10-25 23:20:33.364] [] [BlackBox] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:389 - DB_POOL - Pool stats (total=2, active=1, idle=1, waiting=0)
23:20:33.366 [http-apr-8080-exec-8] ERROR org.hibernate.AssertionFailure - HHH000099: an assertion failure occurred (this may indicate a bug in Hibernate, but is more likely due to unsafe use of the session): java.lang.RuntimeException: Cannot update previous revision for entity org.magic.model.reference.Reference_history and id 250
[2017-10-25 23:21:03.365] [] [BlackBox] [DB_POOL housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool@logPoolState:389 - DB_POOL - Pool stats (total=2, active=0, idle=2, waiting=0)

the AssertionFailure is coming from org.hibernate.envers.strategy.ValidityAuditStrategy

my config looks like

        config.setDriverClassName(_env.getProperty("db.driver")); // com.mysql.cj.jdbc.Driver
        config.setJdbcUrl(_env.getProperty("db.url"));  // jdbc:mysql://localhost:3306/app?autoReconnect=true&useSSL=false&noAccessToProcedureBodies=true&serverTimezone=UTC
        config.setUsername(_env.getProperty("db.user"));
        config.setPassword(_env.getProperty("db.pass"));
        config.setMaximumPoolSize(_env.getProperty("hikari.pool.max.size", Integer.class)); // 2 for local
        config.setConnectionTestQuery("SELECT 1");
        config.addDataSourceProperty("cachePrepStmts", "true");
        config.addDataSourceProperty("prepStmtCacheSize", "250");
        config.addDataSourceProperty("prepStmtCacheSqlLimit", "2048");
        config.addDataSourceProperty("elideSetAutoCommits", "true");
        config.addDataSourceProperty("maintainTimeStats", "false");
        config.addDataSourceProperty("cacheServerConfiguration", "true");
        config.addDataSourceProperty("cacheResultSetMetadata", "true");
        config.setLeakDetectionThreshold(FIVE_SECONDS);

On Monday, October 23, 2017 at 6:26:01 AM UTC-7, Brett Wooldridge wrote:

[Deno Vichas]

after digging a little bit more I'm seeing commit() in ProxyConnection setting isCommitStateDirty = false; being called before ValidityAuditStrategy.perform() is called.  The method in this that does throw an exception in an anon inner class - https://github.com/hibernate/hibernate-orm/blob/master/hibernate-envers/src/main/java/org/hibernate/envers/strategy/ValidityAuditStrategy.java#L224

[Brett Wooldridge]

commit() is setting isComntStateDirty=false because something called commit(). :-P

The line of code in envar that you referenced is checking three conditions. I assume that the exception is thrown because rowCount != 1, have you verified that? It might provide a clue.

Also, it looks like ReturningWork.execute() receives a Connection object, can you verify if it is the same one that was committed? If you breakpoint there and inspect the Connection, what does its state look like?

[Deno Vichas]

ah shit... commit() was being called.  I had a method that had a  unneeded call to commit().  the method is using session.doWork and some sql where i need to write as fast as possible.  removing the commit() seem to fix the rollback issue.

you are right about the rowCount != 1.  i had corrupted some data to force this condition to be true for testing.  

THANKS for bunch for assist on this!!!