Uploaded image for project: 'Infinispan'
  1. Infinispan
  2. ISPN-12971

RemoveExpiredCommand should never have a dummy CommandInvocationId

    XMLWordPrintable

    Details

      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/:?]
      

        Attachments

          Activity

            People

            Assignee:
            dan.berindei Dan Berindei
            Reporter:
            dan.berindei Dan Berindei
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: