Infinispan, Hibernate, and TimeoutException in 0ms

[jnadler]

Just got our Hibernate app (Spring, Hibernate, Atomikos TM) converted from EHCache to Infinispan.  Yay!  Er, mostly - we see repeated exceptions with Unable to acquire lock after 0ms.   The lock timeout is set to 30000 (30 seconds) in our XML config file and we have verified that for most cases this lock timeout is taking effect as expected.

Can anyone suggest what I'm doing wrong that might cause this exception?  We are using 4.1.0.CR2:

[2010-07-27 02:20:48.551,435701]ERROR[schedulerFactoryBean_Worker-1](InvocationContextInterceptor.java:79) - Execution error: 
org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [0 milliseconds] on key [sql: select this_.articleId as articleId5_0_, this_.articleContentId as article17_5_0_, this_.author as author5_0_, this_.averageRating as averageR4_5_0_, this_.bookmarks as bookmarks5_0_, this_.commentCategory_ontologyId as comment18_5_0_, this_.commentFeed_ontologyId as comment19_5_0_, this_.comments as comments5_0_, this_.creationDate as creation7_5_0_, this_.dateForDisplay as dateForD8_5_0_, this_.draft as draft5_0_, this_.guidDigest as guidDigest5_0_, this_.originalSource_ontologyId as origina20_5_0_, this_.ratings as ratings5_0_, this_.readCount as readCount5_0_, this_.shares as shares5_0_, this_.sortTitle as sortTitle5_0_, this_.tags as tags5_0_, this_.userPublished as userPub16_5_0_, this_.authorParty_partyId as authorP21_5_0_, this_.relatedArticle_articleId as related22_5_0_, this_.articleType as articleT1_5_0_ from article this_ where this_.guidDigest=?; parameters: DABYiKmgcamwHXWfhvFBeRxJOME=, ; transformer: org.hibernate.transform.RootEntityResultTransformer@34c6ca0b] for requestor [GlobalTransaction:<null>:359]! Lock held by [GlobalTransaction:<null>:357]
    at org.infinispan.container.EntryFactoryImpl.acquireLock(EntryFactoryImpl.java:213)
    at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:148)
    at org.infinispan.container.EntryFactoryImpl.wrapEntryForWriting(EntryFactoryImpl.java:106)
    at org.infinispan.interceptors.LockingInterceptor.visitPutKeyValueCommand(LockingInterceptor.java:197)
    at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
    at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
    at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
    at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:57)
    at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
    at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
    at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:183)
    at org.infinispan.interceptors.TxInterceptor.visitPutKeyValueCommand(TxInterceptor.java:132)
    at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
    at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
    at org.infinispan.interceptors.CacheMgmtInterceptor.visitPutKeyValueCommand(CacheMgmtInterceptor.java:113)
    at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
    at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
    at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:58)
    at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:39)
    at org.infinispan.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:57)
    at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:76)
    at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:271)
    at org.infinispan.CacheDelegate.put(CacheDelegate.java:426)
    at org.infinispan.CacheSupport.put(CacheSupport.java:28)
    at org.hibernate.cache.infinispan.util.CacheAdapterImpl.putAllowingTimeout(CacheAdapterImpl.java:104)
    at org.hibernate.cache.infinispan.query.QueryResultsRegionImpl.put(QueryResultsRegionImpl.java:82)
    at org.hibernate.cache.StandardQueryCache.put(StandardQueryCache.java:112)
    at org.hibernate.loader.Loader.putResultInQueryCache(Loader.java:2274)
    at org.hibernate.loader.Loader.listUsingQueryCache(Loader.java:2206)
    at org.hibernate.loader.Loader.list(Loader.java:2164)
    at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:119)
    at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1706)
    at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:347)
    at com.attensa.core.persistence.dao.GenericDAOHibernateImpl.findByNaturalId(GenericDAOHibernateImpl.java:276)
    at com.attensa.core.persistence.dao.GenericDAOHibernateImpl.findByNaturalId(GenericDAOHibernateImpl.java:247)
    at com.attensa.core.services.postaggregation.DetermineArticleChanged.articleExists(DetermineArticleChanged.java:83)
    at com.attensa.core.services.postaggregation.DetermineArticleChanged.execute(DetermineArticleChanged.java:47)
    at com.attensa.core.services.postaggregation.AbstractPostAggregationCommand.execute(AbstractPostAggregationCommand.java:15)
    at sun.reflect.GeneratedMethodAccessor67.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
    at $Proxy120.execute(Unknown Source)
<snip...>

[jnadler]

Here's what I've found:  In that stack trace is CacheAdapterImpl.putAllowingTimeout, the point of this method appears to be that TimeoutException is expected and can be ignored.

However I'm getting ugly apparent failures in the log - these are probably "false positives" and there isnt really a problem.  So why is it logged as an error?

Here's the block in InvocationContextInterceptor where the exception gets logged:

        if (suppressExceptions) {   

            log.trace("Exception while executing code, failing silently...", th);

            return null;

         } else {

            log.error("Execution error: ", th);

            throw th;

         }

[jnadler]

I filed a bug here if anyone else wants to follow this; the issue is probably only relevant to those who use Infinispan as a Hibernate L2 cache: https://jira.jboss.org/browse/ISPN-553

[manik]

Thanks for filing the bug, it will get looked at before 4.1.0.Final.