[infinispan-issues] [JBoss JIRA] Updated: (ISPN-553) TimeoutException Logged As Error When Infinispan Used With Hibernate

[ https://jira.jboss.org/browse/ISPN-553?page=com.atlassian.jira.plugin.sys... ] Jeff Nadler updated ISPN-553: ----------------------------- Description: Testing 4.1.0.CR2 with a Hibernate app. We aren't seeing problems in the app but some ERRORs are logged that probably should not be. In org.hibernate.cache.infinispan.util.CacheAdapterImpl is a method putAllowingTimeout - the intention is clearly that a TimeoutException is expected here and not to be considered a problem. So presumably nothing should be logged (or maybe something at the TRACE level). However the InvocationContextInterceptor (see line 79) logs an error and rethrows the exception. Log and rethrow usually leads to double-logging anyway so this might not be the greatest practice. Not all callers consider this TimeoutException to be an error. Here's a sample of the stack traces we get in the logs: [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) (etc...) was: Testing 4.1.0.CR2 with a Hibernate app. We aren't seeing problems in the app but some ERRORs are logged that probably should not be. In org.hibernate.cache.infinispan.util.CacheAdapterImpl is a method putAllowingTimeout - the intention is clearly that a TimeoutException is expected here and not to be considered a problem. So presumably nothing should be logged (or maybe something at the TRACE level). However the InvocationContextInterceptor (see line 79) logs an error and rethrowing the exception. Log and rethrow usually leads to double-logging anyway so this might not be the greatest practice. Not all callers consider this TimeoutException to be an error. Here's a sample of the stack traces we get in the logs: [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) (etc...) -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: https://jira.jboss.org/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira