Skip to content

Instantly share code, notes, and snippets.

@galderz

galderz/ispn9194.org

Last active May 31, 2018 09:02
Show Gist options
  • Save galderz/cab649c0c368d437b1985be850876d03 to your computer and use it in GitHub Desktop.
Save galderz/cab649c0c368d437b1985be850876d03 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
ispn9194.org

ISPN-9194 EntityRegionAccessStrategyTest.testRemoveAll (25.05_2)

Try locate the size() calls at the end of testRemove

grep  -nH -e "org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest" infinispan.log
...
infinispan.log:170081:2018-05-25 19:14:08,648 INFO  [org.hibernate.testing.junit4.CustomRunner] (main:[]) Test: testRemove
...
infinispan.log:170369:2018-05-25 19:14:08,654 DEBUG [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (Time-limited test:[]) Create end invalidation latch: java.util.concurrent.CountDownLatch@6b412650[Count = 0]
...
2018-05-25 19:14:08,654 DEBUG [org.hibernate.engine.transaction.internal.TransactionImpl] (Time-limited test:[]) begin
...
2018-05-25 19:14:08,654 TRACE [org.infinispan.interceptors.impl.InvocationContextInterceptor] (Time-limited test:[]) Invoked with command PutKeyValueCommand{key=KEY112, value=Tombstone{78660470-d4b1-4b1a-867e-456c18a2c3a2=1527275681660}, flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, IGNORE_RETURN_VALUES], commandInvocationId=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:389, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, successful=true, topologyId=-1} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:389}]
...
2018-05-25 19:14:08,657 DEBUG [org.hibernate.engine.transaction.internal.TransactionImpl] (Time-limited test:[]) committing
...
2018-05-25 19:14:08,657 TRACE [org.infinispan.interceptors.impl.InvocationContextInterceptor] (Time-limited test:[]) Invoked with command PutKeyValueCommand{key=KEY112, value=FutureUpdate{uuid=78660470-d4b1-4b1a-867e-456c18a2c3a2, timestamp=1527275621660, value=null}, flags=[FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, IGNORE_RETURN_VALUES], commandInvocationId=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:390, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, successful=true, topologyId=-1} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:390}]
... ^ this is the put that's left hanging around
infinispan.log:170608:2018-05-25 19:14:08,661 INFO  [org.hibernate.testing.junit4.CustomRunner] (main:[]) Test: testRemoveAll
infinispan.log:170609:2018-05-25 19:14:08,661 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (Time-limited test:[]) testRemoveAll[non-JTA, REPL_SYNC, AccessType[read-write]]

Why is there a put after end invalidation latch creation?

2018-05-25 19:14:08,654 TRACE [org.infinispan.test.hibernate.cache.commons.util.ExpectingInterceptor] (Time-limited test:[]) After command(successful=true) GetKeyValueCommand {key=KEY112, flags=[]}
2018-05-25 19:14:08,654 DEBUG [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (Time-limited test:[]) Create end invalidation latch: java.util.concurrent.CountDownLatch@6b412650[Count = 0]
...
2018-05-25 19:14:08,654 DEBUG [org.hibernate.engine.transaction.internal.TransactionImpl] (Time-limited test:[]) On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == true
2018-05-25 19:14:08,654 DEBUG [org.hibernate.engine.transaction.internal.TransactionImpl] (Time-limited test:[]) begin
2018-05-25 19:14:08,654 TRACE [org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl] (Time-limited test:[]) ResourceLocalTransactionCoordinatorImpl#afterBeginCallback
2018-05-25 19:14:08,654 TRACE [org.infinispan.interceptors.impl.InvocationContextInterceptor] (Time-limited test:[]) Invoked with command PutKeyValueCommand{key=KEY112, value=Tombstone{78660470-d4b1-4b1a-867e-456c18a2c3a2=1527275681660}, flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, IGNORE_RETURN_VALUES], commandInvocationId=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:389, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, successful=true, topologyId=-1} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:389}]
... ^ what is this about?
... ^ calling remove() can result in putting a tombstone
... ^ but what is future update coming from?

Who does KEY112 belong to?

grep  -nH -e KEY112 infinispan.log
...
infinispan.log:170082:2018-05-25 19:14:08,648 INFO  [org.hibernate.testing.junit4.CustomRunner] (main:[]) Test: testRemove
...
infinispan.log:170088:2018-05-25 19:14:08,649 TRACE [org.infinispan.interceptors.impl.InvocationContextInterceptor] (Time-limited test:[]) Invoked with command GetKeyValueCommand {key=KEY112, flags=[]} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=null}]
... ^ belongs to testRemove (unclear which combination of params, but probably the same as below)
infinispan.log:170457:2018-05-25 19:14:08,657 TRACE [org.infinispan.interceptors.impl.InvocationContextInterceptor] (Time-limited test:[]) Invoked with command PutKeyValueCommand{key=KEY112, value=FutureUpdate{uuid=78660470-d4b1-4b1a-867e-456c18a2c3a2, timestamp=1527275621660, value=null}, flags=[FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, IGNORE_RETURN_VALUES], commandInvocationId=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:390, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, successful=true, topologyId=-1} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:390}]
...
2018-05-25 19:14:08,663 TRACE [org.infinispan.test.hibernate.cache.commons.util.ExpectingInterceptor] (remote-thread-EntityRegionAccessStrategyTest-NodeAD-p234-t2:[]) After command(successful=true) PutKeyValueCommand{key=KEY112, value=FutureUpdate{uuid=78660470-d4b1-4b1a-867e-456c18a2c3a2, timestamp=1527275621660, value=null}, flags=[FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, IGNORE_RETURN_VALUES], commandInvocationId=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:390, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedLifespanExpirableMetadata{lifespan=60000, version=null}, successful=false, topologyId=5}
...

What is command :390?

grep  -nH -e "EntityRegionAccessStrategyTest-NodeAC-29955:390" infinispan.lo
...
infinispan.log:170369:2018-05-25 19:14:08,654 DEBUG [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (Time-limited test:[]) Create end invalidation latch: java.util.concurrent.CountDownLatch@6b412650[Count = 0]
...
infinispan.log:170457:2018-05-25 19:14:08,657 TRACE [org.infinispan.interceptors.impl.InvocationContextInterceptor] (Time-limited test:[]) Invoked with command PutKeyValueCommand{key=KEY112, value=FutureUpdate{uuid=78660470-d4b1-4b1a-867e-456c18a2c3a2, timestamp=1527275621660, value=null}, flags=[FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, IGNORE_RETURN_VALUES], commandInvocationId=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:390, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, successful=true, topologyId=-1} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:390}]
... ^ where does this put come from? Who does KEY112 belong to?
infinispan.log:170609:2018-05-25 19:14:08,661 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (Time-limited test:[]) testRemoveAll[non-JTA, REPL_SYNC, AccessType[read-write]]

What command makes the condition succeed?

2018-05-25 19:14:08,663 TRACE [org.infinispan.test.hibernate.cache.commons.util.ExpectingInterceptor] (remote-thread-EntityRegionAccessStrategyTest-NodeAD-p234-t2:[]) After command(successful=true) PutKeyValueCommand{key=KEY112, value=FutureUpdate{uuid=78660470-d4b1-4b1a-867e-456c18a2c3a2, timestamp=1527275621660, value=null}, flags=[FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, IGNORE_RETURN_VALUES], commandInvocationId=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:390, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedLifespanExpirableMetadata{lifespan=60000, version=null}, successful=false, topologyId=5}
2018-05-25 19:14:08,663 TRACE [org.infinispan.test.hibernate.cache.commons.util.ExpectingInterceptor] (remote-thread-EntityRegionAccessStrategyTest-NodeAD-p234-t2:[]) Testing condition Condition{source=AbstractRegionAccessStrategyTest.java:604, predicate=org.infinispan.test.hibernate.cache.commons.AbstractRegionAccessStrategyTest$$Lambda$471/1137799377@319b19e2, success=false, action=org.infinispan.test.hibernate.cache.commons.AbstractRegionAccessStrategyTest$$Lambda$473/409450588@39e4f0aa}
2018-05-25 19:14:08,663 TRACE [org.infinispan.test.hibernate.cache.commons.util.ExpectingInterceptor] (remote-thread-EntityRegionAccessStrategyTest-NodeAD-p234-t2:[]) Condition test failed
2018-05-25 19:14:08,663 TRACE [org.infinispan.test.hibernate.cache.commons.util.ExpectingInterceptor] (remote-thread-EntityRegionAccessStrategyTest-NodeAD-p234-t2:[]) Testing condition Condition{source=AbstractRegionAccessStrategyTest.java:596, predicate=org.infinispan.test.hibernate.cache.commons.AbstractRegionAccessStrategyTest$$Lambda$470/20412370@1f5d613b, success=null, action=org.infinispan.test.hibernate.cache.commons.AbstractRegionAccessStrategyTest$$Lambda$472/1485997290@2f565f30}
2018-05-25 19:14:08,663 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (remote-thread-EntityRegionAccessStrategyTest-NodeAD-p234-t2:[]) Remote condition [test: isRemote=true, isPut=true;, should be true: true]
2018-05-25 19:14:08,663 TRACE [org.infinispan.test.hibernate.cache.commons.util.ExpectingInterceptor] (remote-thread-EntityRegionAccessStrategyTest-NodeAD-p234-t2:[]) Condition succeeded
2018-05-25 19:14:08,663 TRACE [org.infinispan.test.hibernate.cache.commons.util.ExpectingInterceptor] (remote-thread-EntityRegionAccessStrategyTest-NodeAD-p234-t2:[]) Executing org.infinispan.test.hibernate.cache.commons.AbstractRegionAccessStrategyTest$$Lambda$472/1485997290@2f565f30
2018-05-25 19:14:08,663 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (remote-thread-EntityRegionAccessStrategyTest-NodeAD-p234-t2:[]) Counting down latch because remote condition succeed
... ^ 2 conditions associated with a single command for an earlier put?
...

Why does latch for :391 not work?

infinispan.log:170628:2018-05-25 19:14:08,662 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (Time-limited test:[]) Call local putFromLoad strategy get for key=KEY113
2018-05-25 19:14:08,662 TRACE [org.infinispan.interceptors.impl.InvocationContextInterceptor] (Time-limited test:[]) Invoked with command PutKeyValueCommand{key=KEY113, value=TombstoneUpdate{timestamp=1527275621661, value=VALUE1/1}, flags=[ZERO_LOCK_ACQUISITION_TIMEOUT, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, FAIL_SILENTLY, SKIP_REMOTE_LOOKUP, IGNORE_RETURN_VALUES], commandInvocationId=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:391, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, successful=true, topologyId=-1} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:391}]
...
infinispan.log:170676:2018-05-25 19:14:08,663 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (remote-thread-EntityRegionAccessStrategyTest-NodeAD-p234-t2:[]) Remote condition [test: isRemote=true, isPut=true;, should be true: true]
...
infinispan.log:170679:2018-05-25 19:14:08,663 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (remote-thread-EntityRegionAccessStrategyTest-NodeAD-p234-t2:[]) Counting down latch because remote condition succeed
... ^ remote condition succeeded even though container had not been updated?
infinispan.log:170707:2018-05-25 19:14:08,663 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (Time-limited test:[]) Remote condition [test: isRemote=false, isPut=true;, should be true: false]

What happens to remote initiated :392 put from load?

grep  -nH -e :392 infinispan.log
infinispan.log:170714:2018-05-25 19:14:08,664 TRACE [org.infinispan.interceptors.impl.InvocationContextInterceptor] (Time-limited test:[]) Invoked with command PutKeyValueCommand{key=KEY113, value=TombstoneUpdate{timestamp=1527275621661, value=VALUE1/1}, flags=[ZERO_LOCK_ACQUISITION_TIMEOUT, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, FAIL_SILENTLY, SKIP_REMOTE_LOOKUP, IGNORE_RETURN_VALUES], commandInvocationId=CommandInvocation:EntityRegionAccessStrategyTest-NodeAD-12149:392, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, successful=true, topologyId=-1} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:EntityRegionAccessStrategyTest-NodeAD-12149:392}]
...
infinispan.log:170736:org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 0 milliseconds for key KEY113 and requestor CommandInvocation:EntityRegionAccessStrategyTest-NodeAD-12149:392. Lock is held by CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:391
... ^ cannot acquire lock

What happens to local initiated :391 put from load?

Why doesn’t it update the remote store?

grep  -nH -e ":391" infinispan.log
infinispan.log:170628:2018-05-25 19:14:08,662 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (Time-limited test:[]) Call local putFromLoad strategy get for key=KEY113
infinispan.log:170629:2018-05-25 19:14:08,662 TRACE [org.infinispan.interceptors.impl.InvocationContextInterceptor] (Time-limited test:[]) Invoked with command PutKeyValueCommand{key=KEY113, value=TombstoneUpdate{timestamp=1527275621661, value=VALUE1/1}, flags=[ZERO_LOCK_ACQUISITION_TIMEOUT, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, FAIL_SILENTLY, SKIP_REMOTE_LOOKUP, IGNORE_RETURN_VALUES], commandInvocationId=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:391, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, successful=true, topologyId=-1} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:391}]
...
infinispan.log:170806:2018-05-25 19:14:08,665 TRACE [org.infinispan.container.EntryFactoryImpl] (Time-limited test:[]) Wrap KEY113 for read. Entry=NullCacheEntry{}
... ^ the get comes before the put has completed in remote
infinispan.log:170830:2018-05-25 19:14:08,665 TRACE [org.infinispan.container.EntryFactoryImpl] (remote-thread-EntityRegionAccessStrategyTest-NodeAD-p234-t2:[]) Updated context entry null -> ReadCommittedEntry(46eb0731){key=KEY113, value=null, isCreated=true, isChanged=false, isRemoved=false, isExpired=false, skipLookup=false, metadata=null}
...

Locate boundaries of test log messages

grep  -nH -e org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest infinispan.log
...
infinispan.log:170609:2018-05-25 19:14:08,661 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (Time-limited test:[]) testRemoveAll[non-JTA, REPL_SYNC, AccessType[read-write]]
infinispan.log:170628:2018-05-25 19:14:08,662 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (Time-limited test:[]) Call local putFromLoad strategy get for key=KEY113
2018-05-25 19:14:08,662 TRACE [org.infinispan.interceptors.impl.InvocationContextInterceptor] (Time-limited test:[]) Invoked with command PutKeyValueCommand{key=KEY113, value=TombstoneUpdate{timestamp=1527275621661, value=VALUE1/1}, flags=[ZERO_LOCK_ACQUISITION_TIMEOUT, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, FAIL_SILENTLY, SKIP_REMOTE_LOOKUP, IGNORE_RETURN_VALUES], commandInvocationId=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:391, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, successful=true, topologyId=-1} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:EntityRegionAccessStrategyTest-NodeAC-29955:391}]
... ^ put EntityRegionAccessStrategyTest-NodeAC-29955:391
... why doesn't it succeed to store in remote?
infinispan.log:170676:2018-05-25 19:14:08,663 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (remote-thread-EntityRegionAccessStrategyTest-NodeAD-p234-t2:[]) Remote condition [test: isRemote=true, isPut=true;, should be true: true]
infinispan.log:170679:2018-05-25 19:14:08,663 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (remote-thread-EntityRegionAccessStrategyTest-NodeAD-p234-t2:[]) Counting down latch because remote condition succeed
infinispan.log:170707:2018-05-25 19:14:08,663 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (Time-limited test:[]) Remote condition [test: isRemote=false, isPut=true;, should be true: false]
infinispan.log:170713:2018-05-25 19:14:08,664 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (Time-limited test:[]) Call remote putFromLoad strategy get for key=KEY113
2018-05-25 19:14:08,664 TRACE [org.infinispan.interceptors.impl.InvocationContextInterceptor] (Time-limited test:[]) Invoked with command PutKeyValueCommand{key=KEY113, value=TombstoneUpdate{timestamp=1527275621661, value=VALUE1/1}, flags=[ZERO_LOCK_ACQUISITION_TIMEOUT, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, FAIL_SILENTLY, SKIP_REMOTE_LOOKUP, IGNORE_RETURN_VALUES], commandInvocationId=CommandInvocation:EntityRegionAccessStrategyTest-NodeAD-12149:392, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, successful=true, topologyId=-1} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:EntityRegionAccessStrategyTest-NodeAD-12149:392}]
... ^ put EntityRegionAccessStrategyTest-NodeAD-12149:392
... why doesn't it succeed to store in remote?
infinispan.log:170731:2018-05-25 19:14:08,664 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (Time-limited test:[]) Local condition [test: isLocal=true, isPut=true;, should be false: true]
infinispan.log:170734:2018-05-25 19:14:08,664 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (Time-limited test:[]) Counting down latch because local condition succeed
infinispan.log:170795:2018-05-25 19:14:08,665 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (Time-limited test:[]) Call local strategy get for key=KEY113
...
2018-05-25 19:14:08,665 TRACE [org.infinispan.interceptors.impl.InvocationContextInterceptor] (Time-limited test:[]) Invoked with command GetKeyValueCommand {key=KEY113, flags=[]} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=null}]
...
2018-05-25 19:14:08,665 TRACE [org.infinispan.container.EntryFactoryImpl] (Time-limited test:[]) Retrieved from container TransientCacheEntry{key=KEY113, value=VALUE1/1}
...
2018-05-25 19:14:08,665 TRACE [org.infinispan.interceptors.impl.InvocationContextInterceptor] (Time-limited test:[]) Invoked with command GetKeyValueCommand {key=KEY113, flags=[]} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=null}]
...
2018-05-25 19:14:08,665 TRACE [org.infinispan.container.EntryFactoryImpl] (Time-limited test:[]) Retrieved from container null
2018-05-25 19:14:08,665 TRACE [org.infinispan.container.EntryFactoryImpl] (Time-limited test:[]) Wrap KEY113 for read. Entry=NullCacheEntry{}

Locate start/end of failing test

grep  -nH -e testRemoveAll infinispan.log
...
infinispan.log:170609:2018-05-25 19:14:08,661 INFO  [org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest] (Time-limited test:[]) testRemoveAll[non-JTA, REPL_SYNC, AccessType[read-write]]
...

Failure

[ERROR] testRemoveAll[non-JTA, REPL_SYNC, AccessType[read-write]](org.infinispan.test.hibernate.cache.commons.entity.EntityRegionAccessStrategyTest)  Time elapsed: 0.024 s  <<< FAILURE!
java.lang.AssertionError: expected:<VALUE1/1> but was:<null>
        at org.junit.Assert.fail(Assert.java:88)
        at org.junit.Assert.failNotEquals(Assert.java:834)
        at org.junit.Assert.assertEquals(Assert.java:118)
        at org.junit.Assert.assertEquals(Assert.java:144)
        at org.infinispan.test.hibernate.cache.commons.AbstractRegionAccessStrategyTest.evictOrRemoveAllTest(AbstractRegionAccessStrategyTest.java:498)
        at org.infinispan.test.hibernate.cache.commons.AbstractRegionAccessStrategyTest.testRemoveAll(AbstractRegionAccessStrategyTest.java:440)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
        at org.hibernate.testing.junit4.ExtendedFrameworkMethod.invokeExplosively(ExtendedFrameworkMethod.java:45)
        at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
        at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
        at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
        at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
        at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.lang.Thread.run(Thread.java:748)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment