5 Replies Latest reply on Jan 20, 2011 2:46 PM by adamw

    Envers + Hib Search + Seam

    lovelyliatroim

      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
          nickarls

          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
            lovelyliatroim

            Explicitly calling flush before commiting.

             

            So dont think it is that.

            • 3. Envers + Hib Search + Seam
              lovelyliatroim

              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
                lovelyliatroim

                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
                  adamw

                  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