I have a problem with using Hibernate and have isolated it to the setting QueryCacheEnabled=true. With this set to false the bug is not present and the application works flawlessly. When QueryCacheEnabled is set to true the error occurs. Below is a description of how things work. The error, and my suspicions follow at the end.

I have spent some considerable time looking into this issue, and believe I have narrowed it down substantially

Hibernate version: 2.1.6
JBoss version: 4.0.0

In summary: Hibernate runs within JBoss application server as a registered MBean. It uses JBossTree cache as its cache provider, which is also registereas an MBean. See below.



The "MyJBossTreeCacheProvider" hibernate cache provider class is a copy of the Hibernate supplied "net.sf.hibernate.cacheTreeCacheProvider", but looks up the Cache in JNDI, rather than constructing the Cache on the fly. This allows the cache to be configured and managed as a regular MBean.

All hibernate access is done within Stateless session EJB's. This bean method has been declared with a Transaction Attribute of "Required", meaning a JTA transaction is created, and managed by the container. The above MBean configuration ensures that the Cache and Hibernate act within the semantics of JTA transactions.

I have ensured all hibernate mapping documents have set cache usage as either "transactional" or as "read-only"

The EJB's obtains a hibernate session by using the JBoss 4.0.0 (final release) org.jboss.hibernate.session.HibernateContext.getSession( String name ); method. And do not flush, commit, or otherwise close the session, leaving this up to JTA.

The EJB's are invoked via a Structs action class, which calls the bean, performs a hibernate update, stores the result in the Session. A JSP then presents the information. This architecture should be fairly standard, and works perfectly.

QueryCacheEnabled=true

After setting QueryCacheEnabled=true, The bug occurs on the second request to a URL, wheras worked perfectly before. The error produced is as follows.



However I believe the error was caused by a previous URL request creating a lock in the cache which was never released. Remember the error occurs on the second invocation to the URL.

To diagnose the problem enabled DEBUG level logging in JBoss for Hibernate, and JBossCache. When the application is working (QueryCacheEnabled=false) the following is a dump of the DEBUG log.



The last line of the log is where my JSP takes over, notice that the last thing the cache does is to do a commit. When the application is Not working (QueryCacheEnabled=true) the following appears in the log.



Note the bolded section of the document, which is not present in the original log, this appears to be the QueryCache invalidation in the cache. However notice that there does not appear to be any commit logic at the end of the process. There fore I surmise, that locks are remaining open in the cache, and the next invocation of the URL, cannot obtain the locks it requires.

I have looked at the source code of hibernate, and believe the issue is in the area of the public void afterTransactionCompletion(boolean success) method in SessionImpl class. This method appears to be where query cache invalidation occurs, my guess based on the name of the method, it occurs after the JTA transaction has been committed, and as a consequence the JBossCache, which also uses JTA, has already done its commit. Therefore the locks generated from this call are never committed. This is also evidenced in the debug log above.

Shouldn

Sorry about the bold not appearing in the log above.

Mark.

2004-10-18 14:49:01,000 DEBUG [net.sf.hibernate.impl.SessionImpl] post flush
2004-10-18 14:49:01,000 DEBUG [net.sf.hibernate.engine.CacheSynchronization] transaction before completion callback
2004-10-18 14:49:01,000 DEBUG [net.sf.hibernate.impl.SessionImpl] closing session
2004-10-18 14:49:01,000 DEBUG [net.sf.hibernate.impl.SessionImpl] disconnecting session
2004-10-18 14:49:01,000 DEBUG [org.jboss.cache.interceptors.ReplicationInterceptor] runPreparePhase(): run remote prepare with async mode: true commit: true and coordinator: primary:3342
2004-10-18 14:49:01,000 DEBUG [org.jboss.cache.TreeCache] callRemoteMethods(): valid members are [smtpserver:4076]
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.TreeCache] commit(): called to commit cache with gtx <primary:3342>:16
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.TreeCache] commit(): releasing lock
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.lock.IdentityLock] release(): lock map owner <primary:3342>:16 not found. Could have been released.
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.TreeCache] commit(): releasing lock read owners=[<primary:3342>:16]
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.TreeCache] commit(): releasing lock write owner=<primary:3342>:16
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.TreeCache] commit(): releasing lock write owner=<primary:3342>:16
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.TreeCache] commit(): releasing lock read owners=[<primary:3342>:16]
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.TreeCache] commit(): releasing lock write owner=<primary:3342>:16
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.TreeCache] commit(): releasing lock read owners=[<primary:3342>:16]
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.TreeCache] commit(): removing local transaction key TransactionImpl:XidImpl[FormatId=257, GlobalId=cw-scgymo62h4gl/26, BranchQual=, localId=26]
2004-10-18 14:49:01,015 DEBUG [net.sf.hibernate.engine.CacheSynchronization] transaction after completion callback, status: 3
2004-10-18 14:49:01,015 DEBUG [net.sf.hibernate.impl.SessionImpl] transaction completion
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.TreeCache] _put(<primary:3342>:17, "//net/sf/hibernate/cache/UpdateTimestampsCache/UserList", item, 10981073410)
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.Node] acquired RL: fqn=//net/sf/hibernate/cache/UpdateTimestampsCache, owner=<primary:3342>:17, lock=read owners=[<primary:3342>:17]
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.Node] acquired WL: fqn=//net/sf/hibernate/cache/UpdateTimestampsCache/UserList, owner=<primary:3342>:17, lock=write owner=<primary:3342>:17
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.TreeCache] _put(<primary:3342>:17, "//net/sf/hibernate/cache/UpdateTimestampsCache/GroupUser", item, 10981073410)
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.lock.IdentityLock] caller already owns lock.
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.Node] acquired RL: fqn=//net/sf/hibernate/cache/UpdateTimestampsCache, owner=<primary:3342>:17, lock=read owners=[<primary:3342>:17]
2004-10-18 14:49:01,015 DEBUG [org.jboss.cache.Node] acquired WL: fqn=//net/sf/hibernate/cache/UpdateTimestampsCache/GroupUser, owner=<primary:3342>:17, lock=write owner=<primary:3342>:17
2004-10-18 14:49:01,031 DEBUG [JSP] JSP Start

Have you recieved any help with this issue? I appear to be experiencing a similar problem with hibernate attempting to place items in TreeCache after the transaction has been committed. I get the exception:

java.lang.IllegalStateException: Already committed.
at org.jboss.tm.TransactionImpl.registerSynchronization(TransactionImpl.java:702)
at org.jboss.cache.TreeCache.getCurrentTransaction(TreeCache.java:2592)
at org.jboss.cache.TreeCache.put(TreeCache.java:1329)
at net.sf.hibernate.cache.TreeCache.put(TreeCache.java:67)
at net.sf.hibernate.cache.UpdateTimestampsCache.invalidate(UpdateTimestampsCache.java:52)
at net.sf.hibernate.impl.SessionImpl.afterTransactionCompletion(SessionImpl.java:605)
at net.sf.hibernate.engine.CacheSynchronization.afterCompletion(CacheSynchronization.java:29)
at org.jboss.tm.TransactionImpl.doAfterCompletion(TransactionImpl.java:1398)
at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:421)
at org.jboss.tm.TxManager.commit(TxManager.java:142)
at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:126)

This appears to leave TreeCache in an unknown lock state because when I attempt to execute the operation again I get a lock exception.

Any ideas? This problem is killing me. :)

Mike

You stack trace looks very similar to what I remember while debugging, but I never got the error you are experiancing. The are two possible workarounds

Set the following Tree cache setting, this effectivly disables locking in TreeCache, biggest impact is on state of cache during a rollback, as cache may conatin the uncommited data, unsure of this though.

<attribute name="IsolationLevel">NONE</attribute>

Second option is to disable the Hiberate Query Cache, which has a detrimatal impact on performance, but wont lave the cache in un unknow state. This setting I think is the cause of the issue.

<attribute name="QueryCacheEnabled">false</attribute>

Not sure how to raise this to a higher level, any ideas?

What version of jboss-hibernate.jar you're using? Some time ago there was a bug where hibernate's flush() was called in TransactionSync.afterCompletion() instead of beforeCompletion() - which is definitely causes the exception you got. In current version (shipped with releases 4.0 and 3.2.6) it is fixed.

Mark, I have exactly the same problem at the moment (btw I'm also using my own version of TreeCacheProvider to lookup for separately deployed cache, although this is not the source of the problem). By now I see that this bug appears only when <cache usage="read-only"/> is set, when it is "transactional" - problem disappears (I run into it caching hibernate entities, not query results).
I'm now trying to sort it out. Can someone explain the diffenence between "read-only" and "transactional" on terms of how hibernate deals with them, besides now allowing to change read-only entities? Maybe someone from the hibernate team can say a couple of words?
For example, why net.sf.hibernate.cache.TransactionalCache has no differences with net.sf.hibernate.cache.ReadOnlyCache besides only one - in ReadOnlyCache put() and get() are synchronized?

I'm currently using JBoss 3.2.6 with Hibernate 2.1.6 and JbossCache 1.1.
I'm deploying Hibernate as a SAR.

I did some checking and realized I unknowingly had query cache enabled so I disabled that and it appears to work fine now.

Thanks,
Mike

I started out using the jboss-hibernate.jar shipping with JBoss 4.0.0, saw the post about the TransactionSync.afterCompletion() bug, fixed this by copying the repaired classes into my source (rather than rebuilding JBoss) but the issue still exists.



I also use a custom TreeCacheProvider that looks up the Cache in JNDI, deployed using MBean service.xml. I have mixed cache-usage="read-only" and "transactinal", will try replacing "read-only" with "transactional" and let you know.



IMHO the reason may be is that hibernate doesnt control transactions in the Cache, this control is taken away when JTA is used, so everthing in Cache happens as part of the transaction, "read-only" or not. What do you think?

Can anyone else shed some light

Mark.

This would have no effect. You need to patch the jboss install directly. Really it's just the JBoss "hibernate" module that needs to be rebuilt. Get the source, build the hibernate module and replace the jboss-hibernate.jar with the new one resulting from the build.

I encountered the same problem using JBoss-4.0.0, Hibernate and JBoss Cache with the UseQueryCache = true. The problem still persists after using the latest snapshots of Hibernate, JBoss Cache and jboss-hibernate.jar from CVS. The same problem appears when I use the Spring

This is a known issue in Hibernate (search the forums/JIRA) when using query caching and transactional caching. It has nothing to do with the integration code.

No, this is not a known issue. The last time this error message came up we couldn't find any problem. We also didn't have a proper bug report. Please, if you are absolutely sure that your setup is correct (you have JTATransactionFactory and the correct TransactionManagerLookup, right?) then post a simplified test case to JIRA.

Thanks