[JBoss JIRA] Created: (ISPN-553) TimeoutException Logged As Error When Infinispan Used With Hibernate
10:10 a.m.
TimeoutException Logged As Error When Infinispan Used With Hibernate
--------------------------------------------------------------------
Key: ISPN-553
URL: https://jira.jboss.org/browse/ISPN-553
Project: Infinispan
Issue Type: Bug
Affects Versions: 4.1.0.CR2
Reporter: Jeff Nadler
Assignee: Manik Surtani
Fix For: 4.1.0.Final
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
12:50 p.m.
New subject: [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...)
TimeoutException Logged As Error When Infinispan Used With Hibernate
--------------------------------------------------------------------
Key: ISPN-553
URL: https://jira.jboss.org/browse/ISPN-553
Project: Infinispan
Issue Type: Bug
Affects Versions: 4.1.0.CR2
Reporter: Jeff Nadler
Assignee: Manik Surtani
Fix For: 4.1.0.Final
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...)
--
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
4:04 a.m.
New subject: [JBoss JIRA] Assigned: (ISPN-553) TimeoutException Logged As Error When Infinispan Used With Hibernate
[
https://jira.jboss.org/browse/ISPN-553?page=com.atlassian.jira.plugin.sys...
]
Manik Surtani reassigned ISPN-553:
----------------------------------
Assignee: Galder Zamarreno (was: Manik Surtani)
TimeoutException Logged As Error When Infinispan Used With Hibernate
--------------------------------------------------------------------
Key: ISPN-553
URL: https://jira.jboss.org/browse/ISPN-553
Project: Infinispan
Issue Type: Bug
Affects Versions: 4.1.0.CR2
Reporter: Jeff Nadler
Assignee: Galder Zamarreno
Fix For: 4.1.0.Final
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...)
--
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
4:04 a.m.
New subject: [JBoss JIRA] Commented: (ISPN-553) TimeoutException Logged As Error When Infinispan Used With Hibernate
[
https://jira.jboss.org/browse/ISPN-553?page=com.atlassian.jira.plugin.sys...
]
Manik Surtani commented on ISPN-553:
------------------------------------
I suppose putAllowingTimeout() should use the fail silently flag?
TimeoutException Logged As Error When Infinispan Used With Hibernate
--------------------------------------------------------------------
Key: ISPN-553
URL: https://jira.jboss.org/browse/ISPN-553
Project: Infinispan
Issue Type: Bug
Affects Versions: 4.1.0.CR2
Reporter: Jeff Nadler
Assignee: Galder Zamarreno
Priority: Critical
Fix For: 4.1.0.Final
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...)
--
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
4:04 a.m.
New subject: [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...
]
Manik Surtani updated ISPN-553:
-------------------------------
Priority: Critical (was: Major)
Complexity: Low
TimeoutException Logged As Error When Infinispan Used With Hibernate
--------------------------------------------------------------------
Key: ISPN-553
URL: https://jira.jboss.org/browse/ISPN-553
Project: Infinispan
Issue Type: Bug
Affects Versions: 4.1.0.CR2
Reporter: Jeff Nadler
Assignee: Galder Zamarreno
Priority: Critical
Fix For: 4.1.0.Final
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...)
--
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
7:27 p.m.
New subject: [JBoss JIRA] Resolved: (ISPN-553) TimeoutException Logged As Error When Infinispan Used With Hibernate
[
https://jira.jboss.org/browse/ISPN-553?page=com.atlassian.jira.plugin.sys...
]
Galder Zamarreno resolved ISPN-553.
-----------------------------------
Resolution: Rejected
This is an issue in the 2LC code, see
http://opensource.atlassian.com/projects/hibernate/browse/HHH-5431
TimeoutException Logged As Error When Infinispan Used With Hibernate
--------------------------------------------------------------------
Key: ISPN-553
URL: https://jira.jboss.org/browse/ISPN-553
Project: Infinispan
Issue Type: Bug
Affects Versions: 4.1.0.CR2
Reporter: Jeff Nadler
Assignee: Galder Zamarreno
Priority: Critical
Fix For: 4.1.0.Final
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...)
--
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
7:27 p.m.
New subject: [JBoss JIRA] Commented: (ISPN-553) TimeoutException Logged As Error When Infinispan Used With Hibernate
[
https://jira.jboss.org/browse/ISPN-553?page=com.atlassian.jira.plugin.sys...
]
Galder Zamarreno commented on ISPN-553:
---------------------------------------
Yup, but this is not the place to report this. The issue lies in the 2LC code which lives
in Hibernate. Hence, I've opened
http://opensource.atlassian.com/projects/hibernate/browse/HHH-5431 and will be closing
this Infinispan JIRA.
Jeff, make sure you watch
http://opensource.atlassian.com/projects/hibernate/browse/HHH-5431 to find out about its
resolution.
TimeoutException Logged As Error When Infinispan Used With Hibernate
--------------------------------------------------------------------
Key: ISPN-553
URL: https://jira.jboss.org/browse/ISPN-553
Project: Infinispan
Issue Type: Bug
Affects Versions: 4.1.0.CR2
Reporter: Jeff Nadler
Assignee: Galder Zamarreno
Priority: Critical
Fix For: 4.1.0.Final
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...)
--
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
7:37 p.m.
New subject: [JBoss JIRA] Commented: (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 commented on ISPN-553:
----------------------------------
Thank you Galder. I'm now watching HHH-5431.
TimeoutException Logged As Error When Infinispan Used With Hibernate
--------------------------------------------------------------------
Key: ISPN-553
URL: https://jira.jboss.org/browse/ISPN-553
Project: Infinispan
Issue Type: Bug
Affects Versions: 4.1.0.CR2
Reporter: Jeff Nadler
Assignee: Galder Zamarreno
Priority: Critical
Fix For: 4.1.0.Final
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...)
--
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
6:37 a.m.
New subject: [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...
]
Galder Zamarreno updated ISPN-553:
----------------------------------
Fix Version/s: (was: 4.1.0.Final)
Affects Version/s: (was: 4.1.0.CR2)
TimeoutException Logged As Error When Infinispan Used With Hibernate
--------------------------------------------------------------------
Key: ISPN-553
URL: https://jira.jboss.org/browse/ISPN-553
Project: Infinispan
Issue Type: Bug
Reporter: Jeff Nadler
Assignee: Galder Zamarreno
Priority: Critical
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...)
--
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
5267
days inactive
5276
days old
infinispan-issues@lists.jboss.org
8 comments
3 participants
participants (3)
-
Galder Zamarreno (JIRA) -
Jeff Nadler (JIRA)
-
Manik Surtani (JIRA)