Details
-
Bug
-
Resolution: Done
-
Major
-
12.1.1.Final
Description
In a transactional cache, RemoveExpiredCommand still behaves like a non-transactional command, acquiring and releasing locks with its CommandInvocationId as the owner. But the CommandInvocationId is always DUMMY_INVOCATION_ID in such caches, meaning a second RemovingExpiredCommand could expire the same key in parallel.
At the very least allowing two parallel expirations of the same key breaks the accounting of used memory in TransactionalExceptionEvictionInterceptor.
E.g. it causes a random failure in ExceptionEvictionTest.testExpiration() as the test starts one expiration via cache.get() and one via cache.getAdvancedCache().getExpirationManager().processExpiration().
23:18:35,093 TRACE (testng-Test:[]) [InvocationContextInterceptor] Invoked with command GetKeyValueCommand {key=WrappedByteArray{bytes=\(00... (2 bytes), hashCode=0}, flags=[]} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=null}]
23:18:35,094 TRACE (testng-Test:[]) [ClusterExpirationManager] Submitting expiration removal for key: WrappedByteArray{bytes=\(00... (2 bytes), hashCode=2201} which is maxIdle: false of: 10000
23:18:35,094 TRACE (testng-Test:[]) [InvocationContextInterceptor] Invoked with command RemoveExpiredCommand{key=WrappedByteArray{bytes=\(00... (2 bytes), hashCode=2201}, value=WrappedByteArray{bytes=\(00... (2 bytes), hashCode=0}, lifespan=10000, maxIde=false, internalMetadata=null} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:local:0}]
23:18:35,094 TRACE (testng-Test:[]) [JGroupsTransport] Test-NodeA sending single request 137 to Test-NodeC: SingleRpcCommand{cacheName='defaultcache', command=RemoveExpiredCommand{key=WrappedByteArray{bytes=\(00... (2 bytes), hashCode=2201}, value=WrappedByteArray{bytes=\(00... (2 bytes), hashCode=0}, lifespan=10000, maxIde=false, internalMetadata=null}}
23:18:35,095 TRACE (jgroups-8,Test-NodeC:[]) [InvocationContextInterceptor] Invoked with command RemoveExpiredCommand{key=WrappedByteArray{bytes=\(00... (2 bytes), hashCode=2201}, value=WrappedByteArray{bytes=\(00... (2 bytes), hashCode=0}, lifespan=10000, maxIde=false, internalMetadata=null} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=Test-NodeA, lockOwner=CommandInvocation:local:0}]
### get-triggered RemoveExpiredCommand acquires lock
23:18:35,095 TRACE (jgroups-8,Test-NodeC:[]) [DefaultLockManager] Lock key=WrappedByteArray{bytes=\(00... (2 bytes), hashCode=2201} for owner=CommandInvocation:local:0. timeout=0 (MILLISECONDS)
23:18:35,096 TRACE (jgroups-8,Test-NodeC:[]) [JGroupsTransport] Test-NodeC sending broadcast request 21 to [Test-NodeA, Test-NodeB, Test-NodeC]: SingleRpcCommand{cacheName='defaultcache', command=RemoveExpiredCommand{key=WrappedByteArray{bytes=\(00... (2 bytes), hashCode=2201}, value=WrappedByteArray{bytes=\(00... (2 bytes), hashCode=0}, lifespan=10000, maxIde=false, internalMetadata=null}}
23:18:35,097 TRACE (testng-Test:[]) [ClusterExpirationManager] Submitting expiration removal for key: WrappedByteArray{bytes=\(00... (2 bytes), hashCode=2201} which is maxIdle: false of: 10000
23:18:35,097 TRACE (testng-Test:[]) [InvocationContextInterceptor] Invoked with command RemoveExpiredCommand{key=WrappedByteArray{bytes=\(00... (2 bytes), hashCode=2201}, value=WrappedByteArray{bytes=\(00... (2 bytes), hashCode=0}, lifespan=10000, maxIde=false, internalMetadata=null} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:local:0}]
### processExpired-triggered RemoveExpiredCommand acquires the same lock
23:18:35,097 TRACE (testng-Test:[]) [DefaultLockManager] Lock key=WrappedByteArray{bytes=\(00... (2 bytes), hashCode=2201} for owner=CommandInvocation:local:0. timeout=0 (MILLISECONDS)
23:18:35,097 TRACE (testng-Test:[]) [JGroupsTransport] Test-NodeC sending broadcast request 22 to [Test-NodeA, Test-NodeB, Test-NodeC]: SingleRpcCommand{cacheName='defaultcache', command=RemoveExpiredCommand{key=WrappedByteArray{bytes=\(00... (2 bytes), hashCode=2201}, value=WrappedByteArray{bytes=\(00... (2 bytes), hashCode=0}, lifespan=10000, maxIde=false, internalMetadata=null}}
### TransactionalExceptionEvictionInterceptor size is adjusted twice
23:18:35,098 TRACE (jgroups-7,Test-NodeB:[]) [TransactionalExceptionEvictionInterceptor] Key WrappedByteArray{bytes=\(00... (2 bytes), hashCode=2201} was removed via expiration
23:18:35,098 TRACE (jgroups-7,Test-NodeB:[]) [TransactionalExceptionEvictionInterceptor] Increased exception based size by -64 to 2496
23:18:35,099 TRACE (jgroups-6,Test-NodeB:[]) [TransactionalExceptionEvictionInterceptor] Key WrappedByteArray{bytes=\(00... (2 bytes), hashCode=2201} was removed via expiration
23:18:35,102 TRACE (jgroups-7,Test-NodeC:[]) [TransactionalExceptionEvictionInterceptor] Increased exception based size by -64 to 2496
### Insert now succeeds instead of failing
23:18:35,119 ERROR (testng-Test:[]) [TestSuiteProgress] Test failed: org.infinispan.eviction.impl.ExceptionEvictionTest.testEntryExpiration[REPL_SYNC, locking=PESSIMISTIC, OFF_HEAP, nodeCount=3]([false, false])
java.lang.AssertionError: Wrong exception thrown: expected:<org.infinispan.interceptors.impl.ContainerFullException>, actual:<java.lang.AssertionError>
at org.infinispan.commons.test.Exceptions.assertException(Exceptions.java:24) ~[infinispan-commons-test-13.0.0-SNAPSHOT.jar:13.0.0-SNAPSHOT]
at org.infinispan.eviction.impl.ExceptionEvictionTest.testEntryExpiration(ExceptionEvictionTest.java:508) ~[test-classes/:?]