[infinispan-issues] [JBoss JIRA] (ISPN-4231) DistSyncL1FuncTest.testRemoteGetArrivesButWriteOccursBeforeRegistration random failures

[William Burns (JIRA)]

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

William Burns commented on ISPN-4231:
-------------------------------------

It looks like somehow NodeD processed the request twice from the same request...  Note how NodeD runs on both OOB-1 and OOB-2.

{code}
14:39:03,996 TRACE (transport-thread-NodeA-p13968-t3:dist) [JGroupsTransport] dests=[NodeD-61213, NodeC-23789], command=ClusteredGetCommand{key=key-to-the-cache, flags=null}, mode=WAIT_FOR_VALID_RESPONSE, timeout=60000
14:39:03,996 TRACE (OOB-2,NodeD-61213:) [StateTransferLockImpl] Waiting for transaction data for topology 0, current topology is 6
14:39:03,996 TRACE (OOB-2,NodeD-61213:) [InboundInvocationHandlerImpl] Calling perform() on ClusteredGetCommand{key=key-to-the-cache, flags=null}
14:39:03,996 TRACE (OOB-2,NodeD-61213:dist) [InvocationContextInterceptor] Invoked with command GetKeyValueCommand {key=key-to-the-cache, flags=[CACHE_MODE_LOCAL, SKIP_REMOTE_LOOKUP]} and InvocationContext [org.infinispan.context.impl.NonTxInvocationContext at 36ef0944]
14:39:03,996 TRACE (OOB-2,NodeD-61213:dist) [StateTransferInterceptor] handleTopologyAffectedCommand for command GetKeyValueCommand {key=key-to-the-cache, flags=[CACHE_MODE_LOCAL, SKIP_REMOTE_LOOKUP]}
14:39:03,996 TRACE (OOB-2,NodeD-61213:dist) [EntryFactoryImpl] Exists in context? null 
14:39:03,996 TRACE (OOB-2,NodeD-61213:dist) [EntryFactoryImpl] Retrieved from container ImmortalCacheEntry{key=key-to-the-cache, value=first-put} (isL1Enabled=true, isLocal=true)
14:39:03,996 TRACE (OOB-2,NodeD-61213:dist) [EntryFactoryImpl] Wrap key-to-the-cache for read. Entry=ImmortalCacheEntry{key=key-to-the-cache, value=first-put}
14:39:03,996 TRACE (OOB-2,NodeD-61213:dist) [L1ManagerImpl] Registering requestor NodeA-6018 for key 'key-to-the-cache'
14:39:03,996 TRACE (OOB-2,NodeD-61213:dist) [CallInterceptor] Executing command: GetKeyValueCommand {key=key-to-the-cache, flags=[CACHE_MODE_LOCAL, SKIP_REMOTE_LOOKUP]}.
14:39:03,996 TRACE (OOB-1,NodeD-61213:) [StateTransferLockImpl] Waiting for transaction data for topology 0, current topology is 6
14:39:03,997 TRACE (OOB-2,NodeD-61213:dist) [GetKeyValueCommand] Found entry ImmortalCacheEntry{key=key-to-the-cache, value=first-put}
14:39:03,997 TRACE (OOB-1,NodeD-61213:) [InboundInvocationHandlerImpl] Calling perform() on ClusteredGetCommand{key=key-to-the-cache, flags=null}
14:39:03,997 TRACE (OOB-2,NodeD-61213:dist) [BlockingInterceptor] Command blocking after completion of GetKeyValueCommand {key=key-to-the-cache, flags=[CACHE_MODE_LOCAL, SKIP_REMOTE_LOOKUP]}
14:39:03,997 TRACE (OOB-1,NodeD-61213:dist) [InvocationContextInterceptor] Invoked with command GetKeyValueCommand {key=key-to-the-cache, flags=[CACHE_MODE_LOCAL, SKIP_REMOTE_LOOKUP]} and InvocationContext [org.infinispan.context.impl.NonTxInvocationContext at 55edef53]
14:39:03,997 TRACE (OOB-1,NodeD-61213:dist) [StateTransferInterceptor] handleTopologyAffectedCommand for command GetKeyValueCommand {key=key-to-the-cache, flags=[CACHE_MODE_LOCAL, SKIP_REMOTE_LOOKUP]}
14:39:03,997 TRACE (OOB-1,NodeD-61213:dist) [EntryFactoryImpl] Exists in context? null 
14:39:03,997 TRACE (OOB-1,NodeD-61213:dist) [EntryFactoryImpl] Retrieved from container ImmortalCacheEntry{key=key-to-the-cache, value=first-put} (isL1Enabled=true, isLocal=true)
14:39:03,997 TRACE (OOB-1,NodeD-61213:dist) [EntryFactoryImpl] Wrap key-to-the-cache for read. Entry=ImmortalCacheEntry{key=key-to-the-cache, value=first-put}
14:39:03,997 TRACE (OOB-1,NodeD-61213:dist) [L1ManagerImpl] Registering requestor NodeA-6018 for key 'key-to-the-cache'
14:39:03,997 TRACE (OOB-1,NodeD-61213:dist) [CallInterceptor] Executing command: GetKeyValueCommand {key=key-to-the-cache, flags=[CACHE_MODE_LOCAL, SKIP_REMOTE_LOOKUP]}.
14:39:03,997 TRACE (OOB-1,NodeD-61213:dist) [GetKeyValueCommand] Found entry ImmortalCacheEntry{key=key-to-the-cache, value=first-put}
14:39:03,997 TRACE (OOB-1,NodeD-61213:dist) [BlockingInterceptor] Command arrived but already found a blocker
14:39:03,997 TRACE (OOB-1,NodeD-61213:dist) [EntryWrappingInterceptor] Entry for key key-to-the-cache is not changed(ImmortalCacheEntry{key=key-to-the-cache, value=first-put}): not calling commitUpdate
14:39:03,997 TRACE (OOB-1,NodeD-61213:) [InboundInvocationHandlerImpl] About to send back response SuccessfulResponse{responseValue=ImmortalCacheValue {value=first-put}}  for command ClusteredGetCommand{key=key-to-the-cache, flags=null}
{code}
                
> DistSyncL1FuncTest.testRemoteGetArrivesButWriteOccursBeforeRegistration random failures
> ---------------------------------------------------------------------------------------
>
>                 Key: ISPN-4231
>                 URL: https://issues.jboss.org/browse/ISPN-4231
>             Project: Infinispan
>          Issue Type: Bug
>          Components: Test Suite - Core
>    Affects Versions: 7.0.0.Alpha3
>            Reporter: Dan Berindei
>            Assignee: William Burns
>              Labels: testsuite_stability
>             Fix For: 7.0.0.Alpha4
>
>         Attachments: DistSyncL1FuncTest_t_4190_dont_loopback_m_20140424.log.gz
>
>
> {noformat}
> 14:39:04,037 ERROR (testng-DistSyncL1FuncTest:) [UnitTestTestNGListener] Test testRemoteGetArrivesButWriteOccursBeforeRegistration(org.infinispan.distribution.DistSyncL1FuncTest) failed.
> org.junit.ComparisonFailure: expected:<[second]-put> but was:<[first]-put>
> 	at org.junit.Assert.assertEquals(Assert.java:115)
> 	at org.junit.Assert.assertEquals(Assert.java:144)
> 	at org.infinispan.distribution.BaseDistSyncL1Test.testRemoteGetArrivesButWriteOccursBeforeRegistration(BaseDistSyncL1Test.java:342)
> {noformat}

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira