[infinispan-issues] [JBoss JIRA] (ISPN-7063) FunctionalCachestoreTest and FunctionalInMemoryTest random failures

[Dan Berindei (JIRA)]

    [ https://issues.jboss.org/browse/ISPN-7063?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13300503#comment-13300503 ] 

Dan Berindei commented on ISPN-7063:
------------------------------------

I'm seeing one more random failure in {{FunctionalCachestoreTest.testLoad}} with TRACE logging enabled. The extra logging sometimes introduces delays big enough to trigger a remote get to a backup owner and allows a {{ClusteredGetCommand}} to run after {{cache.get(key)}} has finished, overlapping with the later {{cache.evict(key)}} calls:

{noformat}
14:22:59,177 TRACE (testng-Test:[]) [RpcManagerImpl] Test-NodeAJ-5500 invoking ClusteredGetCommand{key=key0, flags=[]} to recipient list [Test-NodeAH-1989, Test-NodeAI-5884] with options RpcOptions{timeout=15000, unit=MILLISECONDS, deliverOrder=NONE, responseFilter=org.infinispan.remoting.responses.ClusteredGetResponseValidityFilter at 470fd6fc, responseMode=WAIT_FOR_VALID_RESPONSE}
14:22:59,177 TRACE (testng-Test:[]) [RequestCorrelator] Test-NodeAJ-5500: invoking unicast RPC [req-id=128461] on Test-NodeAH-1989
14:22:59,184 TRACE (timeout-thread-Test-NodeAJ-p40801-t1:[]) [RequestCorrelator] Test-NodeAJ-5500: invoking unicast RPC [req-id=128462] on Test-NodeAI-5884
14:22:59,186 TRACE (testng-Test:[]) [InvocationContextInterceptor] Invoked with command EvictCommand{key=key0, value=null, flags=[]} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext at 2157c962]
14:22:59,186 TRACE (testng-Test:[]) [ReadCommittedEntry] Updating entry (key=key0 removed=true valid=true changed=true created=true value=null metadata=null, providedMetadata=null)
14:22:59,186 TRACE (testng-Test:[]) [InvocationContextInterceptor] Invoked with command EvictCommand{key=key0, value=null, flags=[]} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext at 7e9138e4]
14:22:59,187 TRACE (testng-Test:[]) [ReadCommittedEntry] Updating entry (key=key0 removed=true valid=false changed=true created=false value=value metadata=MetaParamsInternalMetadata{params=MetaParams{metas=[]}}, providedMetadata=null)
14:22:59,187 TRACE (testng-Test:[]) [InvocationContextInterceptor] Invoked with command EvictCommand{key=key0, value=null, flags=[]} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext at 1722a1b2]
14:22:59,187 TRACE (testng-Test:[]) [ReadCommittedEntry] Updating entry (key=key0 removed=true valid=false changed=true created=false value=value metadata=MetaParamsInternalMetadata{params=MetaParams{metas=[]}}, providedMetadata=null)
14:22:59,187 TRACE (testng-Test:[]) [InvocationContextInterceptor] Invoked with command EvictCommand{key=key0, value=null, flags=[]} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext at 22274f88]
14:22:59,187 TRACE (OOB-2,Test-NodeAH-1989:[]) [RequestCorrelator] calling (org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher) with request 128461
14:22:59,187 TRACE (OOB-2,Test-NodeAH-1989:[]) [GlobalInboundInvocationHandler] Attempting to execute CacheRpcCommand: ClusteredGetCommand{key=key0, flags=[]} [sender=Test-NodeAJ-5500]
14:22:59,188 TRACE (OOB-2,Test-NodeAH-1989:[]) [PersistenceUtil] Loaded MarshalledEntryImpl{keyBytes=null, valueBytes=null, metadataBytes=null, key=key0, value=value, metadata=InternalMetadataImpl{actual=MetaParamsInternalMetadata{params=MetaParams{metas=[]}}, created=-1, lastUsed=-1}, marshaller=org.infinispan.marshall.core.GlobalMarshaller at 7e35ced9} for key key0 from persistence.
14:22:59,188 TRACE (OOB-2,Test-NodeAH-1989:[]) [DefaultDataContainer] Store MetadataImmortalCacheEntry{key=key0, value=value, metadata=MetaParamsInternalMetadata{params=MetaParams{metas=[]}}} in container
14:22:59,202 TRACE (testng-Test:[]) [ReadCommittedEntry] Updating entry (key=key0 removed=true valid=true changed=true created=true value=null metadata=null, providedMetadata=null)
14:22:59,203 ERROR (testng-Test:[]) [TestSuiteProgress] Test failed: org.infinispan.functional.FunctionalCachestoreTest.testLoad
java.lang.AssertionError: Test-NodeAH-1989 expected [false] but found [true]
	at org.testng.Assert.fail(Assert.java:94) ~[testng-6.8.8.jar:?]
	at org.testng.Assert.failNotEquals(Assert.java:494) ~[testng-6.8.8.jar:?]
	at org.testng.Assert.assertFalse(Assert.java:63) ~[testng-6.8.8.jar:?]
	at org.infinispan.functional.FunctionalCachestoreTest.lambda$testLoad$3(FunctionalCachestoreTest.java:46) ~[test-classes/:?]
	at java.util.ArrayList.forEach(ArrayList.java:1249) ~[?:1.8.0_101]
	at org.infinispan.functional.FunctionalCachestoreTest.testLoad(FunctionalCachestoreTest.java:46) ~[test-classes/:?]
{noformat}

> FunctionalCachestoreTest and FunctionalInMemoryTest random failures
> -------------------------------------------------------------------
>
>                 Key: ISPN-7063
>                 URL: https://issues.jboss.org/browse/ISPN-7063
>             Project: Infinispan
>          Issue Type: Bug
>          Components: Test Suite - Core
>            Reporter: Dan Berindei
>            Assignee: Radim Vansa
>              Labels: testsuite_stability
>             Fix For: 9.0.0.Beta1
>
>
> ISPN-6586 introduced a static field in {{invocationCount}} that is shared by {{FunctionalInMemoryTest}} and {{FunctionalCachestoreTest}}. When they run in parallel, the counter is no longer deterministic and they both fail randomly.



--
This message was sent by Atlassian JIRA
(v6.4.11#64026)