-
1. Envers + Hib Search + Seam
nickarls Jan 18, 2011 3:36 AM (in response to lovelyliatroim)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 Jan 18, 2011 4:33 AM (in response to nickarls)Explicitly calling flush before commiting.
So dont think it is that.
-
3. Envers + Hib Search + Seam
lovelyliatroim Jan 18, 2011 5:31 AM (in response to 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 Jan 19, 2011 5:27 AM (in response to 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 connectionsWorkaround ........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 Jan 20, 2011 2:46 PM (in response to lovelyliatroim)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