gistfile1.txt

testAll[read-only, INVALIDATION_SYNC](org.infinispan.test.hibernate.cache.functional.cluster.NaturalIdInvalidationTest)  Time elapsed: 0.526 sec  <<< FAILURE!
java.lang.AssertionError: Citizen (1234) should have present in the cache
	at org.junit.Assert.fail(Assert.java:88)
	at org.infinispan.test.hibernate.cache.functional.cluster.NaturalIdInvalidationTest.assertLoadedFromCache(NaturalIdInvalidationTest.java:144)
	at org.infinispan.test.hibernate.cache.functional.cluster.NaturalIdInvalidationTest.testAll(NaturalIdInvalidationTest.java:114)
	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:47)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
	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.internal.runners.statements.FailOnTimeout$StatementThread.run(FailOnTimeout.java:74)


infinispan-fail.log:57667:
2017-07-28 12:27:16,529 TRACE [org.infinispan.interceptors.impl.InvocationContextInterceptor] (Thread-347:[]) 
Invoked with command PutKeyValueCommand{key=null##NaturalId[1234, 2], value=3, 
flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, IGNORE_RETURN_VALUES], 
commandInvocationId=CommandInvocation:NaturalIdInvalidationTest-NodeI-24674:166, 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:NaturalIdInvalidationTest-NodeI-24674:166}]

...

infinispan-fail.log:57682:
2017-07-28 12:27:16,529 TRACE [org.infinispan.hibernate.cache.access.PutFromLoadValidator] (Thread-347:[]) 
beginInvalidatingKey(org.infinispan.test.hibernate.cache.functional.entities.Citizen##NaturalId#null##NaturalId[1234, 2], 
CommandInvocation:NaturalIdInvalidationTest-NodeI-24674:166) ends with { 
PendingPuts=[R@CommandInvocation:NaturalIdInvalidationTest-NodeI-24674:166], 
Invalidators=[{Owner=CommandInvocation:NaturalIdInvalidationTest-NodeI-24674:166, Timestamp=1501244836529}], 
LastInvalidationEnd=<none>, Removed=false}

...

infinispan-fail.log:57707:
2017-07-28 12:27:16,530 TRACE [org.infinispan.hibernate.cache.access.PutFromLoadValidator] (jgroups-3,NaturalIdInvalidationTest-NodeJ-31931:[]) 
beginInvalidatingKey(org.infinispan.test.hibernate.cache.functional.entities.Citizen##NaturalId#null##NaturalId[1234, 2], 
CommandInvocation:NaturalIdInvalidationTest-NodeI-24674:166) ends with 
{ PendingPuts=[R@CommandInvocation:NaturalIdInvalidationTest-NodeI-24674:166], 
Invalidators=[{Owner=CommandInvocation:NaturalIdInvalidationTest-NodeI-24674:166, Timestamp=1501244836530}], 
LastInvalidationEnd=<none>, Removed=false}

...

infinispan-fail.log:58040:
2017-07-28 12:27:16,536 TRACE [org.infinispan.hibernate.cache.access.PutFromLoadValidator] (Thread-347:[]) 
endInvalidatingKey(org.infinispan.test.hibernate.cache.functional.entities.Citizen##NaturalId#null##NaturalId[1234, 2], 
CommandInvocation:NaturalIdInvalidationTest-NodeI-24674:166) ends with { PendingPuts=[], Invalidators=[], 
LastInvalidationEnd=1501244836536, Removed=false}
2017-07-28 12:27:16,536 TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] (Thread-347:[]) 
NaturalIdInvalidationTest-NodeI-24674 invoking EndInvalidationCommand{
cacheName=org.infinispan.test.hibernate.cache.functional.entities.Citizen##NaturalId, keys=[null##NaturalId[1234, 2]], 
sessionTransactionId=CommandInvocation:NaturalIdInvalidationTest-NodeI-24674:166} to recipient list 
[NaturalIdInvalidationTest-NodeI-24674, NaturalIdInvalidationTest-NodeJ-31931] with options 
RpcOptions{timeout=20000, unit=MILLISECONDS, deliverOrder=NONE, responseFilter=null, responseMode=ASYNCHRONOUS}

...

infinispan-fail.log:58349:
2017-07-28 12:27:16,545 TRACE [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (jgroups-7,NaturalIdInvalidationTest-NodeJ-31931:[]) 
NaturalIdInvalidationTest-NodeJ-31931 received command from NaturalIdInvalidationTest-NodeI-24674: 
EndInvalidationCommand{cacheName=org.infinispan.test.hibernate.cache.functional.entities.Citizen##NaturalId, 
keys=[null##NaturalId[1234, 2]], sessionTransactionId=CommandInvocation:NaturalIdInvalidationTest-NodeI-24674:166}

infinispan-fail.log:58350:
2017-07-28 12:27:16,545 TRACE [org.infinispan.remoting.inboundhandler.GlobalInboundInvocationHandler] (jgroups-7,NaturalIdInvalidationTest-NodeJ-31931:[]) 
Attempting to execute CacheRpcCommand: EndInvalidationCommand{
cacheName=org.infinispan.test.hibernate.cache.functional.entities.Citizen##NaturalId, 
keys=[null##NaturalId[1234, 2]], sessionTransactionId=CommandInvocation:NaturalIdInvalidationTest-NodeI-24674:166} 
[sender=NaturalIdInvalidationTest-NodeI-24674]

// no trace of remote-thread-... version of ^ execution...

...

infinispan-fail.log:58421:
2017-07-28 12:27:16,550 TRACE [org.infinispan.hibernate.cache.access.PutFromLoadValidator] (Thread-347:[]) 
acquirePutFromLoadLock(org.infinispan.test.hibernate.cache.functional.entities.Citizen##NaturalId#null##NaturalId[1234, 2], 
1501244836547) ended with { PendingPuts=[R@CommandInvocation:NaturalIdInvalidationTest-NodeI-24674:166], 
Invalidators=[{Owner=CommandInvocation:NaturalIdInvalidationTest-NodeI-24674:166, Timestamp=1501244836530}], 
LastInvalidationEnd=<none>, Removed=false}, valid: false

// 1501244836530 does not get removed, why?
// could it have been delayed? see below...

// delay in actually calling perform on command in spite of receiving it earlier, delay in dispatching between threads?

infinispan-fail.log:59578:
2017-07-28 12:27:16,589 TRACE [org.infinispan.remoting.inboundhandler.NonTotalOrderPerCacheInboundInvocationHandler] (remote-thread-NaturalIdInvalidationTest-NodeJ-p74-t1:[]) 
Calling perform() on EndInvalidationCommand{cacheName=org.infinispan.test.hibernate.cache.functional.entities.Citizen##NaturalId, 
keys=[null##NaturalId[1234, 2]], sessionTransactionId=CommandInvocation:NaturalIdInvalidationTest-NodeI-24674:166}

infinispan-fail.log:59580:
2017-07-28 12:27:16,589 TRACE [org.infinispan.hibernate.cache.access.PutFromLoadValidator] (remote-thread-NaturalIdInvalidationTest-NodeJ-p74-t1:[]) 
endInvalidatingKey(org.infinispan.test.hibernate.cache.functional.entities.Citizen##NaturalId#null##NaturalId[1234, 2], 
CommandInvocation:NaturalIdInvalidationTest-NodeI-24674:166) ends with 
{ PendingPuts=[R@CommandInvocation:NaturalIdInvalidationTest-NodeI-24674:166], Invalidators=[], 
LastInvalidationEnd=1501244836589, Removed=false}