galderz/gist:676f689884969658b01a7695f08dd7a2 Secret

## gistfile1.txt
# Success - Hibernate 5.2.2 w/ Infinispan 8.2.3

:6836:2017-01-26 12:18:17,290 DEBUG [org.hibernate.cache.spi.UpdateTimestampsCache] (main:[]) Invalidating space [Event], timestamp: 1485429497290
:6837:2017-01-26 12:18:17,290 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (main:[org.hibernate.cache.spi.UpdateTimestampsCache]) Invoked with command PutKeyValueCommand{key=Event, value=1485429497290, flags=[SKIP_LOCKING, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext@61ff6a49]
...
:6846:2017-01-26 12:18:17,290 TRACE [org.infinispan.interceptors.distribution.BaseDistributionInterceptor] (main:[org.hibernate.cache.spi.UpdateTimestampsCache]) I'm the primary owner, sending the command to all the backups (null) in order to be applied.
...
:6857:2017-01-26 12:18:17,290 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (main:[org.hibernate.cache.spi.UpdateTimestampsCache]) About to commit entry ReadCommittedEntry(18dd5ed3){key=Event, value=1485429497290, oldValue=1485429557287, isCreated=false, isChanged=true, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}}
...
:6865:2017-01-26 12:18:17,290 INFO  [org.infinispan.tutorial.secondlc.util.HibernateUtils] (main:[]) Update entity(id=2) on node 2: [hits=5, misses=3, puts=6, queryHits=1, queryMisses=1, queryPuts=1]
...
2017-01-26 12:18:17,291 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (main:[]) Checking query spaces are up-to-date: [Event]
2017-01-26 12:18:17,291 DEBUG [org.hibernate.cache.spi.UpdateTimestampsCache] (main:[]) [Event] last update timestamp: 1485429497290, result set timestamp: 1485429497272
2017-01-26 12:18:17,291 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (main:[]) Cached query results were not up-to-date

# Fail - Hibernate 5.2.2 w/ Infinispan 8.2.3

2017-01-25 16:58:51,259 DEBUG [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-2,gs-MacBook-Pro-4-46107:[]) New view accepted: [gs-MacBook-Pro-4-46107|1] (2) [gs-MacBook-Pro-4-46107, gs-MacBook-Pro-4-36035]
...
2017-01-25 16:58:51,711 DEBUG [org.hibernate.cache.spi.UpdateTimestampsCache] (main:[]) Invalidating space [Event], timestamp: 1485359931711
2017-01-25 16:58:51,711 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (main:[org.hibernate.cache.spi.UpdateTimestampsCache]) Invoked with command PutKeyValueCommand{key=Event, value=1485359931711, flags=[SKIP_LOCKING, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext@715f45c6]
...
2017-01-25 16:58:51,711 TRACE [org.infinispan.interceptors.distribution.BaseDistributionInterceptor] (main:[org.hibernate.cache.spi.UpdateTimestampsCache]) I'm not the primary owner, so sending the command to the primary owner(gs-MacBook-Pro-4-46107) in order to be forwarded
...
2017-01-25 16:58:51,712 INFO  [org.infinispan.tutorial.secondlc.util.HibernateUtils] (main:[]) Update entity on node 2: [hits=2, misses=1, puts=2, queryHits=0, queryMisses=0, queryPuts=0]
...
2017-01-25 16:58:51,736 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (Incoming-2,gs-MacBook-Pro-4-46107:[org.hibernate.cache.spi.UpdateTimestampsCache]) About to commit entry ReadCommittedEntry(4ef34602){key=Event, value=1485359931711, oldValue=1485359991710, isCreated=false, isChanged=true, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}}
...
2017-01-25 16:58:51,753 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (Incoming-2,gs-MacBook-Pro-4-36035:[org.hibernate.cache.spi.UpdateTimestampsCache]) About to commit entry ReadCommittedEntry(419411cd){key=Event, value=1485359931711, oldValue=1485359991710, isCreated=false, isChanged=true, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}}
...
2017-01-25 16:58:51,846 TRACE [org.hibernate.internal.SessionImpl] (main:[]) Opened Session [e6759531-d9f6-4e03-87ee-0919c3613a46] at timestamp: 1485359931846
2017-01-25 16:58:51,852 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (main:[]) Caching query results in region: org.hibernate.cache.internal.StandardQueryCache; timestamp=1485359931846
...
2017-01-25 16:58:51,859 DEBUG [org.hibernate.cache.spi.UpdateTimestampsCache] (main:[]) Invalidating space [Event], timestamp: 1485359931859
...
2017-01-25 16:58:51,859 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (main:[org.hibernate.cache.spi.UpdateTimestampsCache]) Invoked with command PutKeyValueCommand{key=Event, value=1485359931859, flags=[SKIP_LOCKING, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext@54c60202]
...
2017-01-25 16:58:51,860 TRACE [org.infinispan.interceptors.distribution.BaseDistributionInterceptor] (main:[org.hibernate.cache.spi.UpdateTimestampsCache]) I'm not the primary owner, so sending the command to the primary owner(gs-MacBook-Pro-4-46107) in order to be forwarded
...
2017-01-25 16:58:51,860 INFO  [org.infinispan.tutorial.secondlc.util.HibernateUtils] (main:[]) Update entity on node 2: [hits=5, misses=3, puts=6, queryHits=1, queryMisses=1, queryPuts=1]
...
2017-01-25 16:58:51,860 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (main:[]) Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
...
2017-01-25 16:58:51,860 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (main:[]) Checking query spaces are up-to-date: [Event]
2017-01-25 16:58:51,860 DEBUG [org.hibernate.cache.spi.UpdateTimestampsCache] (main:[]) [Event] last update timestamp: 1485359931711, result set timestamp: 1485359931846

^ 1485359931711 probably coming from outdated ClusteredTimestampsRegionImpl.localCache
^ no "About to commit entry" message (events are sent after this message)

2017-01-25 16:58:51,861 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (main:[]) Returning cached query results
...
2017-01-25 16:58:51,861 INFO  [org.infinispan.tutorial.secondlc.util.HibernateUtils] (main:[]) Repeat query on node 2 after update: [hits=7, misses=3, puts=6, queryHits=2, queryMisses=1, queryPuts=1]

last update:  1485359931711
query result: 1485359931846
	# Success - Hibernate 5.2.2 w/ Infinispan 8.2.3

	:6836:2017-01-26 12:18:17,290 DEBUG [org.hibernate.cache.spi.UpdateTimestampsCache] (main:[]) Invalidating space [Event], timestamp: 1485429497290
	:6837:2017-01-26 12:18:17,290 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (main:[org.hibernate.cache.spi.UpdateTimestampsCache]) Invoked with command PutKeyValueCommand{key=Event, value=1485429497290, flags=[SKIP_LOCKING, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext@61ff6a49]
	...
	:6846:2017-01-26 12:18:17,290 TRACE [org.infinispan.interceptors.distribution.BaseDistributionInterceptor] (main:[org.hibernate.cache.spi.UpdateTimestampsCache]) I'm the primary owner, sending the command to all the backups (null) in order to be applied.
	...
	:6857:2017-01-26 12:18:17,290 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (main:[org.hibernate.cache.spi.UpdateTimestampsCache]) About to commit entry ReadCommittedEntry(18dd5ed3){key=Event, value=1485429497290, oldValue=1485429557287, isCreated=false, isChanged=true, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}}
	...
	:6865:2017-01-26 12:18:17,290 INFO [org.infinispan.tutorial.secondlc.util.HibernateUtils] (main:[]) Update entity(id=2) on node 2: [hits=5, misses=3, puts=6, queryHits=1, queryMisses=1, queryPuts=1]
	...
	2017-01-26 12:18:17,291 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (main:[]) Checking query spaces are up-to-date: [Event]
	2017-01-26 12:18:17,291 DEBUG [org.hibernate.cache.spi.UpdateTimestampsCache] (main:[]) [Event] last update timestamp: 1485429497290, result set timestamp: 1485429497272
	2017-01-26 12:18:17,291 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (main:[]) Cached query results were not up-to-date

	# Fail - Hibernate 5.2.2 w/ Infinispan 8.2.3

	2017-01-25 16:58:51,259 DEBUG [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-2,gs-MacBook-Pro-4-46107:[]) New view accepted: [gs-MacBook-Pro-4-46107\|1] (2) [gs-MacBook-Pro-4-46107, gs-MacBook-Pro-4-36035]
	...
	2017-01-25 16:58:51,711 DEBUG [org.hibernate.cache.spi.UpdateTimestampsCache] (main:[]) Invalidating space [Event], timestamp: 1485359931711
	2017-01-25 16:58:51,711 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (main:[org.hibernate.cache.spi.UpdateTimestampsCache]) Invoked with command PutKeyValueCommand{key=Event, value=1485359931711, flags=[SKIP_LOCKING, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext@715f45c6]
	...
	2017-01-25 16:58:51,711 TRACE [org.infinispan.interceptors.distribution.BaseDistributionInterceptor] (main:[org.hibernate.cache.spi.UpdateTimestampsCache]) I'm not the primary owner, so sending the command to the primary owner(gs-MacBook-Pro-4-46107) in order to be forwarded
	...
	2017-01-25 16:58:51,712 INFO [org.infinispan.tutorial.secondlc.util.HibernateUtils] (main:[]) Update entity on node 2: [hits=2, misses=1, puts=2, queryHits=0, queryMisses=0, queryPuts=0]
	...
	2017-01-25 16:58:51,736 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (Incoming-2,gs-MacBook-Pro-4-46107:[org.hibernate.cache.spi.UpdateTimestampsCache]) About to commit entry ReadCommittedEntry(4ef34602){key=Event, value=1485359931711, oldValue=1485359991710, isCreated=false, isChanged=true, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}}
	...
	2017-01-25 16:58:51,753 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (Incoming-2,gs-MacBook-Pro-4-36035:[org.hibernate.cache.spi.UpdateTimestampsCache]) About to commit entry ReadCommittedEntry(419411cd){key=Event, value=1485359931711, oldValue=1485359991710, isCreated=false, isChanged=true, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}}
	...
	2017-01-25 16:58:51,846 TRACE [org.hibernate.internal.SessionImpl] (main:[]) Opened Session [e6759531-d9f6-4e03-87ee-0919c3613a46] at timestamp: 1485359931846
	2017-01-25 16:58:51,852 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (main:[]) Caching query results in region: org.hibernate.cache.internal.StandardQueryCache; timestamp=1485359931846
	...
	2017-01-25 16:58:51,859 DEBUG [org.hibernate.cache.spi.UpdateTimestampsCache] (main:[]) Invalidating space [Event], timestamp: 1485359931859
	...
	2017-01-25 16:58:51,859 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (main:[org.hibernate.cache.spi.UpdateTimestampsCache]) Invoked with command PutKeyValueCommand{key=Event, value=1485359931859, flags=[SKIP_LOCKING, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext@54c60202]
	...
	2017-01-25 16:58:51,860 TRACE [org.infinispan.interceptors.distribution.BaseDistributionInterceptor] (main:[org.hibernate.cache.spi.UpdateTimestampsCache]) I'm not the primary owner, so sending the command to the primary owner(gs-MacBook-Pro-4-46107) in order to be forwarded
	...
	2017-01-25 16:58:51,860 INFO [org.infinispan.tutorial.secondlc.util.HibernateUtils] (main:[]) Update entity on node 2: [hits=5, misses=3, puts=6, queryHits=1, queryMisses=1, queryPuts=1]
	...
	2017-01-25 16:58:51,860 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (main:[]) Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache
	...
	2017-01-25 16:58:51,860 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (main:[]) Checking query spaces are up-to-date: [Event]
	2017-01-25 16:58:51,860 DEBUG [org.hibernate.cache.spi.UpdateTimestampsCache] (main:[]) [Event] last update timestamp: 1485359931711, result set timestamp: 1485359931846

	^ 1485359931711 probably coming from outdated ClusteredTimestampsRegionImpl.localCache
	^ no "About to commit entry" message (events are sent after this message)

	2017-01-25 16:58:51,861 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (main:[]) Returning cached query results
	...
	2017-01-25 16:58:51,861 INFO [org.infinispan.tutorial.secondlc.util.HibernateUtils] (main:[]) Repeat query on node 2 after update: [hits=7, misses=3, puts=6, queryHits=2, queryMisses=1, queryPuts=1]

	last update: 1485359931711
	query result: 1485359931846