Transactional, optimistic-locked caches do not honour Flag.FAIL_SILENTLY ------------------------------------------------------------------------ Key: ISPN-5356 URL: https://issues.jboss.org/browse/ISPN-5356 Project: Infinispan Issue Type: Bug Components: Core Affects Versions: 6.0.2.Final Environment: Infinispan 6.0.2 Hibernate ORM 4.3.6 Apache Tomcat 8 JDK 1.8.0_25 Reporter: Mitchell Archibald Assignee: Galder Zamarreño Fix For: 7.2.0.Final There is a related issue in the Hibernate JIRA, which can be found at: https://hibernate.atlassian.net/browse/HHH-7898 However, I believe this to be an Infinispan issue, as per my analysis below. The following Exception is thrown when two threads are simultaneously committing a JTA transaction in which an entry has been written to Hibernate's "replicated-query" cache using the same key. {code} 10:55:02.238 ERROR saction.TransactionCoordinator - ISPN000255: Error while processing prepare org.infinispan.util.concurrent.TimeoutException: Unable to acquire lock after [0 milliseconds] on key [sql: select ...; parameters: ...; named parameters: {...}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2] for requestor [GlobalTransaction:<null>:197882:local]! Lock held by [null] at org.infinispan.util.concurrent.locks.LockManagerImpl.lock(LockManagerImpl.java:198) at org.infinispan.util.concurrent.locks.LockManagerImpl.acquireLock(LockManagerImpl.java:171) at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockKeyAndCheckOwnership(AbstractTxLockingInterceptor.java:169) at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockAndRegisterBackupLock(AbstractTxLockingInterceptor.java:98) at org.infinispan.interceptors.locking.OptimisticLockingInterceptor$LockAcquisitionVisitor.lockAndRecord(OptimisticLockingInterceptor.java:211) at org.infinispan.interceptors.locking.OptimisticLockingInterceptor$LockAcquisitionVisitor.visitSingleKeyCommand(OptimisticLockingInterceptor.java:206) at org.infinispan.interceptors.locking.OptimisticLockingInterceptor$LockAcquisitionVisitor.visitPutKeyValueCommand(OptimisticLockingInterceptor.java:199) at org.infinispan.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:70) at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.acquireLocksVisitingCommands(OptimisticLockingInterceptor.java:270) at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:75) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.NotificationInterceptor.visitPrepareCommand(NotificationInterceptor.java:36) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:114) at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:101) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:112) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:96) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124) at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98) at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:110) at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:73) at org.infinispan.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:96) at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124) at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:333) at org.infinispan.transaction.TransactionCoordinator.prepare(TransactionCoordinator.java:119) at org.infinispan.transaction.TransactionCoordinator.prepare(TransactionCoordinator.java:101) at org.infinispan.transaction.synchronization.SynchronizationAdapter.beforeCompletion(SynchronizationAdapter.java:44) at com.metiom.core.transaction.TransactionImpl.lambda$commit$0(TransactionImpl.java:115) at com.metiom.core.transaction.TransactionImpl$$Lambda$2/330107372.accept(Unknown Source) at com.metiom.core.transaction.TransactionImpl.forEachSynchronisation(TransactionImpl.java:264) at com.metiom.core.transaction.TransactionImpl.commit(TransactionImpl.java:114) at com.metiom.core.transaction.TransactionManagerImpl.commit(TransactionManagerImpl.java:142) at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1021) at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:757) at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:726) at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:497) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:277) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ... {code} The configuration for Hibernate's "replicated-query" cache is as follows (from Hibernate's infinispan-configs.xml) {code} <!-- An alternative configuration for entity/collection caching that uses replication instead of invalidation --> <namedCache name="replicated-entity"> <clustering mode="replication"> <stateTransfer fetchInMemoryState="false" timeout="20000"/> <sync replTimeout="20000"/> </clustering> <locking isolationLevel="READ_COMMITTED" concurrencyLevel="1000" lockAcquisitionTimeout="15000" useLockStriping="false"/> <!-- Eviction configuration. WakeupInterval defines how often the eviction thread runs, in milliseconds. 0 means the eviction thread will never run. A separate executor is used for eviction in each cache. --> <eviction maxEntries="10000" strategy="LRU"/> <expiration maxIdle="100000" wakeUpInterval="5000"/> <lazyDeserialization enabled="true"/> <transaction transactionMode="TRANSACTIONAL" autoCommit="false" lockingMode="OPTIMISTIC"/> </namedCache> {code} Additionally, the cache is configured programmatically with: * {{Flag.ZERO_LOCK_ACQUISITION_TIMEOUT}}; and * {{Flag.FAIL_SILENTLY}} The situation is that two threads are concurrently attempting to lock the same key on commit. * During a JTA transaction, a Hibernate query is executed, and Hibernate places a result in the query cache. * On commit, the {{SynchronizationAdaptor}} creates a {{PrepareCommand}}, which contains one or more "modifications", one of which is a {{PutKeyValueCommand}}. The {{SynchronizationAdapter}} invokes the {{PrepareCommand}}. * When visited, the {{OptimisticLockingInterceptor}} loops through the modifications held by the {{PrepareCommand}} and visits each one. * When the {{PutKeyValueCommand}} is visited, {{LockManagerImpl}} discovers that the key is locked, and throws {{TimeoutException}}. * The Exception is caught by {{InvocationContextInterceptor}}, and attempts to find out whether the command it was invoking is affected by {{Flag.FAIL_SILENTLY}}. {{PrepareCommand}} does not implement {{FlagAffectedCommand}}, so this test fails and the Exception is propagated. It is important to note here that the {{PutKeyValueCommand}} _does_ implement {{FlagAffectedCommand}}, and _does_ have the {{Flag.FAIL_SILENTLY}} flag set. So the problem seems to be that {{OptimisticLockingInterceptor}} is unaware that the modifications to the {{PrepareCommand}} could throw Exceptions which can be suppressed.