5 Replies Latest reply: Jan 20, 2011 2:46 PM by Adam Warski RSS

Envers + Hib Search + Seam

J B Novice

Hi Guys,

   Im currently trying to hook up envers into our system and i hit a stumbling block.

 

 

I have successfully managed to get it working standalone, that is, our data model annotated with what I want audited and a test unit case of just creating a object and editing it and saving. That works no problem.

 

Now when i try and integrate the new data model into our web app, it just doesnt seem to work. Everything looks fine, i even see the insert statements logged for the audit tables for the update but i dont see records in the tables in the database.

 

Now the only difference between standalone and the webapp is seam...the entity manager is hooked up differently than standalone but shouldnt make all that much of a difference.

 

What is baffling me is that i see the insert statements for the _AUD tables but no records in them. It is like the inserts are cached in memory.

 

 

Ever come across anything like that before??

 

 

Cheers,

LL

  • 1. Envers + Hib Search + Seam
    Nicklas Karlsson Master

    I recall seeing that with one particular version of Envers. It required an explicit flush() on the EntityManager for it to actually get inserted...

  • 2. Envers + Hib Search + Seam
    J B Novice

    Explicitly calling flush before commiting.

     

    So dont think it is that.

  • 3. Envers + Hib Search + Seam
    J B Novice

    I filtered out the log so you can see the chain of events, removed some parts for obvious reasons

     

    10:55:18,721 [http-8080-1] [userID] DEBUG [SecurityEditor] saveItem()

    10:55:22,836 [http-8080-1] [userID] INFO  [StaticData] updating begins

    10:55:24,871 [http-8080-1] [userID] DEBUG [hibernate.transaction.JDBCTransaction] begin

    10:55:24,871 [http-8080-1] [userID] DEBUG [hibernate.transaction.JDBCTransaction] current autocommit status: false

    10:55:29,878 [http-8080-1] [userID] DEBUG [org.hibernate.SQL] select *

    10:55:30,614 [http-8080-1] [userID] DEBUG [org.hibernate.SQL] select

    10:55:30,942 [http-8080-1] [userID] DEBUG [org.hibernate.SQL] select

    10:55:30,942 [http-8080-1] [userID] DEBUG [org.hibernate.SQL] select

    10:55:30,974 [http-8080-1] [userID] DEBUG [org.hibernate.SQL] select

    10:55:30,974 [http-8080-1] [userID] DEBUG [org.hibernate.SQL] select

    10:55:31,005 [http-8080-1] [userID] DEBUG [org.hibernate.SQL] select

    10:55:33,211 [http-8080-1] [userID] INFO  [StaticData] Before Flushing

    10:55:38,250 [http-8080-1] [userID] DEBUG [org.hibernate.SQL] update

    10:55:39,925 [http-8080-1] [userID] INFO  [StaticData] After Flushing

    10:55:43,602 [http-8080-1] [userID] INFO  [StaticData] Before Commit

    10:55:46,231 [http-8080-1] [userID] DEBUG [hibernate.transaction.JDBCTransaction] commit

    10:55:46,231 [http-8080-1] [userID] DEBUG [org.hibernate.SQL] select hibernate_sequence.nextval from dual

    10:55:46,247 [http-8080-1] [userID] DEBUG [org.hibernate.SQL] insert into REVINFO (REVTSTMP, REV) values (?, ?)

    10:55:46,247 [http-8080-1] [userID] DEBUG [org.hibernate.SQL] insert into instance_AUD (

    10:55:46,278 [http-8080-1] [userID] DEBUG [org.hibernate.SQL] insert into instance2_AUD (id, REV) values (?, ?)

    10:55:46,278 [http-8080-1] [userID] DEBUG [hibernate.transaction.JDBCTransaction] committed JDBC Connection

    10:55:51,254 [http-8080-1] [userID] INFO  [StaticData] after commit

  • 4. Re: Envers + Hib Search + Seam
    J B Novice

    Ok I have found the problem!!

     

    I added a custom listener to pick up the events in both the standalone and in the webapp cases. The only difference with my listener is i print what the session impl  hash code is. Example

     

    log.debug("CustomAuditEventListener:onPostInsert:" + event.getPersister().getEntityName() + " SessionHash="

                + event.getSession().hashCode() + " Impl=" + event.getSession().getClass());

     

     

    Sample test case, standalone version looks like so

     

    entityManager.getTransaction().begin();

    log.debug("EntityManagerHash=" + entityManager.getDelegate().hashCode() + " Impl="

                + entityManager.getDelegate().getClass());

    security.setComments("RevisionComment " + Calendar.getInstance().getTime().toString());

    entityManager.merge(security);

    log.debug("before merge");

    entityManager.flush();

    log.debug("after flush");

    entityManager.getTransaction().commit();

    log.debug("EntityManagerHash=" + entityManager.getDelegate().hashCode());

     

     

     

    The above generates the following log

     

    17376 [main] DEBUG org.hibernate.transaction.JDBCTransaction  - begin

    17376 [main] DEBUG org.hibernate.transaction.JDBCTransaction  - current autocommit status: false

    20016 [main] DEBUG SecurityAuditTest  - EntityManagerHash=7717178 Impl=class org.hibernate.impl.SessionImpl

    26157 [main] DEBUG SecurityAuditTest  - before merge

    27157 [main] DEBUG org.hibernate.SQL  - update

    27189 [main] DEBUG CustomAuditEventListener  - CustomAuditEventListener:onPostUpdate: SessionHash=7717178

    27220 [main] DEBUG CustomAuditEventListener  - CustomAuditEventListener:generateBidirectionalCollectionChangeWorkUnits

    27704 [main] DEBUG SecurityAuditTest  - after flush

    28220 [main] DEBUG org.hibernate.transaction.JDBCTransaction  - commit

    28267 [main] DEBUG org.hibernate.SQL  - select hibernate_sequence.nextval from dual

    28392 [main] DEBUG org.hibernate.SQL  - insert into REVINFO (REVTSTMP, REV) values (?, ?)

    28392 [main] DEBUG CustomAuditEventListener  - CustomAuditEventListener:onPostInsert:org.hibernate.envers.DefaultRevisionEntity SessionHash=7717178 Impl=class org.hibernate.impl.SessionImpl

    28392 [main] DEBUG org.hibernate.SQL  - insert into xxx_tbl_AUD (REVTYPE, etc etc

    28408 [main] DEBUG org.hibernate.SQL  - insert into xxx_tbl_AUD (id, REV) values (?, ?)

    28408 [main] DEBUG CustomAuditEventListener  - CustomAuditEventListener:onPostInsert: SessionHash=7717178 Impl=class org.hibernate.impl.SessionImpl

    28423 [main] DEBUG org.hibernate.transaction.JDBCTransaction  - committed JDBC Connection

    29814 [main] DEBUG SecurityAuditTest  - EntityManagerHash=7717178

     

    You will notice that the same sessionImpl object is the same for the whole transaction i.e the hash code doesnt change!!

     

     

    Now enter the world of seam

     

    Im using seams injection dependency manager to inject the entity manager. My code is very similar to above and here is what my log looks like

     

    10:43:25,845 [http-8080-1] [] INFO  [StaticData] StartTrans 812040 Impl class $Proxy161

    10:45:35,322 [http-8080-1] [] DEBUG [org.hibernate.SQL] select * from 

    10:45:35,354 [http-8080-1] [] DEBUG [org.hibernate.SQL] select

    10:45:35,666 [http-8080-1] [] DEBUG [org.hibernate.SQL] select

    10:45:35,666 [http-8080-1] [] DEBUG [org.hibernate.SQL] select

    10:45:35,697 [http-8080-1] [] DEBUG [org.hibernate.SQL] select

    10:45:35,697 [http-8080-1] [] DEBUG [org.hibernate.SQL] select

    10:45:35,713 [http-8080-1] [] DEBUG [org.hibernate.SQL] select

    10:45:35,729 [http-8080-1] [] INFO  [StaticData] Before Flushing 29170238

    10:45:36,041 [http-8080-1] [] DEBUG [org.hibernate.SQL] update xxxx_tbl

    10:45:42,026 [http-8080-1] [] DEBUG [CustomAuditEventListener] CustomAuditEventListener:onPostUpdate: SessionHash=18823587

    10:45:42,026 [http-8080-1] [] DEBUG [CustomAuditEventListener] CustomAuditEventListener:generateBidirectionalCollectionChangeWorkUnits

    10:45:42,026 [http-8080-1] [] DEBUG [CustomAuditEventListener] CustomAuditEventListener:onPreUpdateCollection:  SessionHash=18823587

    10:45:42,026 [http-8080-1] [] DEBUG [CustomAuditEventListener] CustomAuditEventListener:onCollectionAction

    10:45:42,042 [http-8080-1] [] DEBUG [CustomAuditEventListener] CustomAuditEventListener:onPreUpdateCollection:  SessionHash=18823587

    10:45:42,042 [http-8080-1] [] INFO  [StaticData] After Flushing12526746

    10:45:42,042 [http-8080-1] [] INFO  [StaticData] Before Commit 16525044

    10:45:42,042 [http-8080-1] [] DEBUG [hibernate.transaction.JDBCTransaction] commit

    10:45:42,042 [http-8080-1] [] DEBUG [org.hibernate.SQL] select hibernate_sequence.nextval from dual

    10:45:42,042 [http-8080-1] [] DEBUG [org.hibernate.SQL] insert into REVINFO (REVTSTMP, REV) values (?, ?)

    10:45:44,245 [http-8080-1] [] DEBUG [CustomAuditEventListener] CustomAuditEventListener:onPostInsert:org.hibernate.envers.DefaultRevisionEntity SessionHash=16769739 Impl=class org.hibernate.impl.SessionImpl

    10:45:44,245 [http-8080-1] [] DEBUG [org.hibernate.SQL] insert into XXX_tbl_AUD     

    10:45:44,260 [http-8080-1] [] DEBUG [org.hibernate.SQL] insert into XXX_tbl_AUD (id, REV) values (?, ?)

    10:45:46,214 [http-o080-1] [] DEBUG [CustomAuditEventListener] CustomAuditEventListener:onPostInsert: SessionHash=16769739 Impl=class org.hibernate.impl.SessionImpl

    10:45:46,214 [http-8080-1] [] DEBUG [hibernate.transaction.JDBCTransaction] committed JDBC Connection

    10:45:50,308 [http-8080-1] [] INFO  [StaticData] data update finished 24318759

     

     

    First difference to the standalone version is that it is no longer using org.hibernate.impl.SessionImpl as the implementation for the entity manager but is using a seam proxy.

    10:43:25,845 [http-8080-1] [] INFO  [StaticData] StartTrans 812040 Impl class $Proxy161

     

    As the transaction goes on you will see that the proxy never stays the same for the transaction e.g

     

    log.info("Before Flushing " + em.getDelegate().hashCode());

    em.flush();

    log.info("After Flushing" + em.getDelegate().hashCode());

     

    Produces

    10:45:35,729 [http-8080-1] [] INFO  [StaticData] Before Flushing 29170238

    10:45:42,042 [http-8080-1] [] INFO  [StaticData] After Flushing12526746

     


    You will also see that the custom audit listener is using the original org.hibernate.impl.SessionImpl as its "connection" but it doesnt stay the same for the duration of the transaction. What is clear to me is that they arent using the same connection, so the entity manager with its proxy implementation and how the AuditListener picks up its connection both are using two seperate connections

     

     

    Workaround ........instead of injecting the entity manager in, i inject the factory and from there create an entity manager. Log if your interested looks like so

     

    10:53:57,183 [http-8080-2] [ADMINbaumhauerk] INFO  [StaticData] StartTrans 11739041 Impl class org.hibernate.impl.SessionImpl

    10:54:07,433 [http-8080-2] [ADMINbaumhauerk] DEBUG [org.hibernate.SQL] select *

    10:54:08,558 [http-8080-2] [ADMINbaumhauerk] DEBUG [org.hibernate.SQL] select

    10:54:09,027 [http-8080-2] [ADMINbaumhauerk] DEBUG [org.hibernate.SQL] select

    10:54:09,027 [http-8080-2] [ADMINbaumhauerk] DEBUG [org.hibernate.SQL] select

    10:54:09,058 [http-8080-2] [ADMINbaumhauerk] DEBUG [org.hibernate.SQL] select

    10:54:09,058 [http-8080-2] [ADMINbaumhauerk] DEBUG [org.hibernate.SQL] select

    10:54:09,074 [http-8080-2] [ADMINbaumhauerk] DEBUG [org.hibernate.SQL] select

    10:54:11,590 [http-8080-2] [ADMINbaumhauerk] INFO  [StaticData] Before Flushing 11739041

    10:54:19,840 [http-8080-2] [ADMINbaumhauerk] DEBUG [org.hibernate.SQL] update                

    10:54:19,840 [http-8080-2] [ADMINbaumhauerk] DEBUG [CustomAuditEventListener] CustomAuditEventListener:onPostUpdate: SessionHash=11739041

    10:54:19,856 [http-8080-2] [ADMINbaumhauerk] DEBUG [CustomAuditEventListener] CustomAuditEventListener:generateBidirectionalCollectionChangeWorkUnits

    10:54:19,856 [http-8080-2] [ADMINbaumhauerk] DEBUG [CustomAuditEventListener] CustomAuditEventListener:onPreUpdateCollection:  SessionHash=11739041

    10:54:19,856 [http-8080-2] [ADMINbaumhauerk] DEBUG [CustomAuditEventListener] CustomAuditEventListener:onCollectionAction

    10:54:19,856 [http-8080-2] [ADMINbaumhauerk] DEBUG [CustomAuditEventListener] CustomAuditEventListener:onPreUpdateCollection:  SessionHash=11739041

    10:54:22,387 [http-8080-2] [ADMINbaumhauerk] INFO  [StaticData] After Flushing11739041

    10:54:24,794 [http-8080-2] [ADMINbaumhauerk] INFO  [StaticData] Before Commit 11739041

    10:54:25,575 [http-8080-2] [ADMINbaumhauerk] DEBUG [hibernate.transaction.JDBCTransaction] commit

    10:54:25,747 [http-8080-2] [ADMINbaumhauerk] DEBUG [org.hibernate.SQL] select hibernate_sequence.nextval from dual

    10:54:25,841 [http-8080-2] [ADMINbaumhauerk] DEBUG [org.hibernate.SQL] insert into REVINFO (REVTSTMP, REV) values (?, ?)

    10:54:31,560 [http-8080-2] [ADMINbaumhauerk] DEBUG [CustomAuditEventListener] CustomAuditEventListener:onPostInsert:org.hibernate.envers.DefaultRevisionEntity SessionHash=11739041 Impl=class org.hibernate.impl.SessionImpl

    10:54:31,575 [http-8080-2] [ADMINbaumhauerk] DEBUG [org.hibernate.SQL] insert into xxxx_tbl_AUD    

    10:54:31,575 [http-8080-2] [ADMINbaumhauerk] DEBUG [org.hibernate.SQL] insert into xxxxx_tbl_AUD (id, REV) values (?, ?)

    10:54:31,591 [http-8080-2] [ADMINbaumhauerk] DEBUG [CustomAuditEventListener] CustomAuditEventListener:onPostInsert: SessionHash=11739041 Impl=class org.hibernate.impl.SessionImpl

    10:54:31,591 [http-8080-2] [ADMINbaumhauerk] DEBUG [hibernate.transaction.JDBCTransaction] committed JDBC Connection

    10:54:33,779 [http-8080-2] [ADMINbaumhauerk] INFO  [StaticData] data update finished 11739041

     

     

     

    You will see that there is no proxy now for the EntityManager implementation and that the whole transaction uses the same session impl so when the commit happens, it happens off the same connection!!

     

    So i now have auditing working in my webapp..........finally

     

    Cheers,

    JB

  • 5. Re: Envers + Hib Search + Seam
    Adam Warski Master

    Heh, seems really weird that the session was different.

    But thanks for the solution, I'm sure people will find it useful in the future!

     

    Adam