2:58 a.m.
Dan Berindei created ISPN-11598:
-----------------------------------
Summary:
EvictionWithPassivationAndConcurrentOperationsTest.testEvictionDuringWriteWithConcurrentRead
random failures
Key: ISPN-11598
URL: https://issues.redhat.com/browse/ISPN-11598
Project: Infinispan
Issue Type: Bug
Components: Core, Test Suite
Affects Versions: 11.0.0.Dev03
Reporter: Dan Berindei
Assignee: Dan Berindei
Fix For: 11.0.0.Dev04
According to the code comments, the test is supposed to block the {{put(evicted-key)}}
operation before releasing the orderer, but because of
{{operationCheckPoint.trigger(Mocks.BEFORE_RELEASE)}} it only blocks *after* releasing the
orderer. This means the eviction triggered by {{put(other-key)}} and the activation
triggered later by {{get(evicted-key)}} are not blocked.
All three operations eventually call
{{operationCheckPoint.awaitStrict(Mocks.BEFORE_RELEASE)}}. The test triggers that event
twice, so it unblocks {{put(evicted-key)}} *and* one of
{{put(other-key)}}/{{get(evicted-key)}}. The two unblocked operations then compete for a
single {{Mocks.AFTER_RELEASE}} event.
If {{put(evicted-key)}} receives the {{Mocks.AFTER_RELEASE}} event, the test passes,
because the other operations can finish without waiting for the activation/passivation to
finish. (It just needs to be queued in )
Because {{CheckPoint}} doesn't guarantee waiters receive events in the queueing order,
either {{put(other-key, "value"}}, or {{get(evicted-key)}} could receive the
{{AFTER_RELEASE}} event from {{put(evicted-key, "value")}}, making it time out.
{noformat}
19:53:59,795 TRACE (ForkThread-1,Test:[]) [InvocationContextInterceptor] Invoked with
command PutKeyValueCommand{key=evicted-key, value=value, flags=[SKIP_CACHE_LOAD],
commandInvocationId=CommandInvocation:<local>:37070, putIfAbsent=false,
valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{version=null, lifespan=-1,
maxIdle=-1}, successful=true, topologyId=-1} and InvocationContext
[SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null,
lockOwner=CommandInvocation:<local>:37070}]
19:53:59,807 TRACE (non-blocking-thread-Test-NodeK-p23146-t1:[]) [DataOperationOrderer]
Ordered future java.util.concurrent.CompletableFuture@76d1e6bc[Not completed] is completed
for key evicted-key from op WRITE
19:53:59,811 TRACE (non-blocking-thread-Test-NodeK-p23146-t1:[]) [CheckPoint] Waiting for
event post_released * 1
{noformat}
^ put(evicted-key) is blocked
{noformat}
19:53:59,807 TRACE (testng-Test:[]) [InvocationContextInterceptor] Invoked with command
PutKeyValueCommand{key=other-key, value=other-value, flags=[],
commandInvocationId=CommandInvocation:<local>:37073, putIfAbsent=false,
valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{version=null, lifespan=-1,
maxIdle=-1}, successful=true, topologyId=-1} and InvocationContext
[SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null,
lockOwner=CommandInvocation:<local>:37073}]
19:53:59,816 TRACE (non-blocking-thread-Test-NodeK-p23146-t2:[])
[AbstractInternalDataContainer] Store other-key=ImmortalCacheEntry{key=other-key,
value=other-value, internalMetadata=null} in container
19:53:59,817 TRACE (non-blocking-thread-Test-NodeK-p23146-t2:[]) [DataOperationOrderer]
Ordering upcoming future java.util.concurrent.CompletableFuture@32541e18[Not completed]
for key evicted-key to run after null
{noformat}
^ put(other-key) is not blocked here
{noformat}
19:53:59,818 TRACE (non-blocking-thread-Test-NodeK-p23146-t2:[]) [PassivationManagerImpl]
Passivating entry evicted-key
19:53:59,818 TRACE (non-blocking-thread-Test-NodeK-p23146-t2:[]) [PersistenceManagerImpl]
Writing to all stores for id 67588
19:53:59,841 TRACE (non-blocking-thread-Test-NodeK-p23146-t3:[]) [CompletionStages]
Continuing execution of id 67588
19:53:59,844 TRACE (non-blocking-thread-Test-NodeK-p23146-t3:[]) [CheckPoint] Waiting for
event pre_released * 1
{noformat}
^ put(other-key) blocks in the checkpoint
{noformat}
19:53:59,956 TRACE (testng-Test:[]) [CheckPoint] Triggering event pre_released * 1
(available = 1, total = 2)
19:53:59,956 TRACE (testng-Test:[]) [CheckPoint] Triggering event post_released * 1
(available = 1, total = 1)
19:53:59,956 TRACE (non-blocking-thread-Test-NodeK-p23146-t3:[]) [CheckPoint] Received
event pre_released * 1 (available = 0, total = 2)
{noformat}
^ put(other-key) is unblocked, put(evicted-key) stays blocked
{noformat}
19:54:09,998 ERROR (testng-Test:[]) [TestSuiteProgress] Test failed:
org.infinispan.eviction.impl.EvictionWithPassivationAndConcurrentOperationsTest.testEvictionDuringWriteWithConcurrentRead
java.util.concurrent.TimeoutException: null
at java.util.concurrent.FutureTask.get(FutureTask.java:204) ~[?:?]
at
org.infinispan.eviction.impl.EvictionWithPassivationAndConcurrentOperationsTest.testEvictionDuringWriteWithConcurrentRead(EvictionWithPassivationAndConcurrentOperationsTest.java:99)
~[test-classes/:?]
{noformat}
--
This message was sent by Atlassian Jira
(v7.13.8#713008)