I enabled org.jboss.as.jpa TRACE logging as well as org.infinispan TRACE (I know overly verbose) logging. Output is here http://dl.dropbox.com/u/35343318/jboss/serverlogs.zip In the node1 log, I see that we delete the entity and then try to perform the remove command. I don't seem to see this command executed on node0: 09:10:22,416 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: delete from Employee where id=? ... 09:10:22,419 TRACE [org.infinispan.interceptors.CallInterceptor] (http-/127.0.0.1:8180-1) Executing command: RemoveCommand{key=org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1, value=null, flags=[CACHE_MODE_LOCAL, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP]}. ... I don't see anything in the node0 log about "RemoveCommand{key=org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1" being received or executed. Are there any other TRACE logging settings that I should enable? I'm going to make a small test change to show the 2lc cache statistics for node1 after the entity is deleted from the database. The elementCountInMemory went from one to zero (as expected).

Scott On 12/14/2012 12:03 AM, Scott Marlow wrote: > http://hudson.jboss.org/hudson/job/as7-param-pull/5123/ shows a failure > with the second level cache not being invalidated as expected across a > two node cluster. > > I'm able to reproduce locally, which is good. We will continue to use > Hibernate 4.1.6 until we get past this regression (hopefully we can > understand the test failure cause soon). > > https://github.com/jbossas/jboss-as/blob/master/testsuite/integration/clu... > is the line that is failing (yeah, the arguments to assertEquals are > backwards but that isn't the root issue ;) > > It is possible that its a bug in the test also. > > The cluster has two nodes, each with their own in-memory database. The > test assumes that it can create the same entity on both nodes (same > primary key) and that for the purpose of testing the second level cache, > we can expect cache invalidation to occur on both nodes when deleting > the entity on one of the nodes. > > I believe that the cache invalidation should be synchronous but I'll > probably try adding a sleep to see if it could be an async/timing issue. > > I hope to have more information soon (probably in the morning on Friday). > > Scott > _______________________________________________ > hibernate-dev mailing list > hibernate-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/hibernate-dev > _______________________________________________ hibernate-dev mailing list hibernate-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/hibernate-dev

I'll add TRACE logging to org.hibernate.cache.infinispan.access.TransactionalAccessDelegate to show more information about what is going on in there when we fail to invalidate the 2lc on the other node. Any other ideas? On 12/14/2012 10:13 AM, Scott Marlow wrote: > On 12/14/2012 09:46 AM, Scott Marlow wrote: >> I enabled org.jboss.as.jpa TRACE logging as well as org.infinispan TRACE >> (I know overly verbose) logging. Output is here >> http://dl.dropbox.com/u/35343318/jboss/serverlogs.zip >> >> In the node1 log, I see that we delete the entity and then try to >> perform the remove command. I don't seem to see this command executed >> on node0: >> >> 09:10:22,416 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: delete >> from Employee where id=? >> ... >> 09:10:22,419 TRACE [org.infinispan.interceptors.CallInterceptor] >> (http-/127.0.0.1:8180-1) Executing command: >> RemoveCommand{key=org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1, >> value=null, flags=[CACHE_MODE_LOCAL, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP]}. >> ... >> >> I don't see anything in the node0 log about >> "RemoveCommand{key=org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1" >> being received or executed. >> >> Are there any other TRACE logging settings that I should enable? >> >> I'm going to make a small test change to show the 2lc cache statistics >> for node1 after the entity is deleted from the database. The elementCountInMemory went from one to zero (as expected). > > The 2lc statistics on node1, show that the node1 2lc has been > invalidated to remove the deleted entity. > > 09:56:30,071 INFO [stdout] (http-/127.0.0.1:8180-1) 2lc for > stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: > SecondLevelCacheStatistics[hitCount=1,missCount=0,putCount=1,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1] > > Its node0, that didn't receive the "RemoveCommand" that also still has > the elementCountInMemory as one: > > 09:56:30,172 INFO [stdout] (http-/127.0.0.1:8080-1) 2lc for > stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: > SecondLevelCacheStatistics[hitCount=0,missCount=0,putCount=1,elementCountInMemory=1,elementCountOnDisk=-1,sizeInMemory=-1] > > >> >> Scott >> >> On 12/14/2012 12:03 AM, Scott Marlow wrote: >>> http://hudson.jboss.org/hudson/job/as7-param-pull/5123/ shows a failure >>> with the second level cache not being invalidated as expected across a >>> two node cluster. >>> >>> I'm able to reproduce locally, which is good. We will continue to use >>> Hibernate 4.1.6 until we get past this regression (hopefully we can >>> understand the test failure cause soon). >>> >>> https://github.com/jbossas/jboss-as/blob/master/testsuite/integration/clu... >>> is the line that is failing (yeah, the arguments to assertEquals are >>> backwards but that isn't the root issue ;) >>> >>> It is possible that its a bug in the test also. >>> >>> The cluster has two nodes, each with their own in-memory database. The >>> test assumes that it can create the same entity on both nodes (same >>> primary key) and that for the purpose of testing the second level cache, >>> we can expect cache invalidation to occur on both nodes when deleting >>> the entity on one of the nodes. >>> >>> I believe that the cache invalidation should be synchronous but I'll >>> probably try adding a sleep to see if it could be an async/timing issue. >>> >>> I hope to have more information soon (probably in the morning on Friday). >>> >>> Scott >>> _______________________________________________ >>> hibernate-dev mailing list >>> hibernate-dev(a)lists.jboss.org >>> https://lists.jboss.org/mailman/listinfo/hibernate-dev >>> >> >> _______________________________________________ >> hibernate-dev mailing list >> hibernate-dev(a)lists.jboss.org >> https://lists.jboss.org/mailman/listinfo/hibernate-dev >> > > _______________________________________________ > hibernate-dev mailing list > hibernate-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/hibernate-dev > _______________________________________________ hibernate-dev mailing list hibernate-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/hibernate-dev

From the TRACE logs, I can see that org.hibernate.cache.infinispan.access.TransactionalAccessDelegate.remove(Object) invoked the writeCache.remove(key) with key=org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1 but the other node isn't notified of this change (as far as I can tell from the Infinispan trace output). I looked closer at TransactionalAccessDelegate.remove and looks like we are removing the entry via the writeCache. If the AS 2lc entity cache definition is using invalidation (which I think it is), TransactionalAccessDelegate will also use CACHE_MODE_LOCAL. I tried changing TransactionalAccessDelegate.writeCache from: this.writeCache = Caches.isInvalidationCache(cache) ? Caches.ignoreReturnValuesCache(cache, Flag.CACHE_MODE_LOCAL) : Caches.ignoreReturnValuesCache(cache); To: this.writeCache = Caches.ignoreReturnValuesCache(cache); And my simplified version of the AS7 clustered 2lc test passed. Why would we want to use Flag.CACHE_MODE_LOCAL when the cache is configured to be an invalidation cache? Scott On 12/14/2012 11:52 AM, Scott Marlow wrote: > I'll add TRACE logging to > org.hibernate.cache.infinispan.access.TransactionalAccessDelegate to > show more information about what is going on in there when we fail to > invalidate the 2lc on the other node. > > Any other ideas? > > > On 12/14/2012 10:13 AM, Scott Marlow wrote: >> On 12/14/2012 09:46 AM, Scott Marlow wrote: >>> I enabled org.jboss.as.jpa TRACE logging as well as org.infinispan TRACE >>> (I know overly verbose) logging. Output is here >>> http://dl.dropbox.com/u/35343318/jboss/serverlogs.zip >>> >>> In the node1 log, I see that we delete the entity and then try to >>> perform the remove command. I don't seem to see this command executed >>> on node0: >>> >>> 09:10:22,416 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: delete >>> from Employee where id=? >>> ... >>> 09:10:22,419 TRACE [org.infinispan.interceptors.CallInterceptor] >>> (http-/127.0.0.1:8180-1) Executing command: >>> RemoveCommand{key=org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1, >>> value=null, flags=[CACHE_MODE_LOCAL, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP]}. >>> ... >>> >>> I don't see anything in the node0 log about >>> "RemoveCommand{key=org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1" >>> being received or executed. >>> >>> Are there any other TRACE logging settings that I should enable? >>> >>> I'm going to make a small test change to show the 2lc cache statistics >>> for node1 after the entity is deleted from the database. The elementCountInMemory went from one to zero (as expected). >> >> The 2lc statistics on node1, show that the node1 2lc has been >> invalidated to remove the deleted entity. >> >> 09:56:30,071 INFO [stdout] (http-/127.0.0.1:8180-1) 2lc for >> stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: >> SecondLevelCacheStatistics[hitCount=1,missCount=0,putCount=1,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1] >> >> Its node0, that didn't receive the "RemoveCommand" that also still has >> the elementCountInMemory as one: >> >> 09:56:30,172 INFO [stdout] (http-/127.0.0.1:8080-1) 2lc for >> stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: >> SecondLevelCacheStatistics[hitCount=0,missCount=0,putCount=1,elementCountInMemory=1,elementCountOnDisk=-1,sizeInMemory=-1] >> >> >>> >>> Scott >>> >>> On 12/14/2012 12:03 AM, Scott Marlow wrote: >>>> http://hudson.jboss.org/hudson/job/as7-param-pull/5123/ shows a failure >>>> with the second level cache not being invalidated as expected across a >>>> two node cluster. >>>> >>>> I'm able to reproduce locally, which is good. We will continue to use >>>> Hibernate 4.1.6 until we get past this regression (hopefully we can >>>> understand the test failure cause soon). >>>> >>>> https://github.com/jbossas/jboss-as/blob/master/testsuite/integration/clu... >>>> is the line that is failing (yeah, the arguments to assertEquals are >>>> backwards but that isn't the root issue ;) >>>> >>>> It is possible that its a bug in the test also. >>>> >>>> The cluster has two nodes, each with their own in-memory database. The >>>> test assumes that it can create the same entity on both nodes (same >>>> primary key) and that for the purpose of testing the second level cache, >>>> we can expect cache invalidation to occur on both nodes when deleting >>>> the entity on one of the nodes. >>>> >>>> I believe that the cache invalidation should be synchronous but I'll >>>> probably try adding a sleep to see if it could be an async/timing issue. >>>> >>>> I hope to have more information soon (probably in the morning on Friday). >>>> >>>> Scott >>>> _______________________________________________ >>>> hibernate-dev mailing list >>>> hibernate-dev(a)lists.jboss.org >>>> https://lists.jboss.org/mailman/listinfo/hibernate-dev >>>> >>> >>> _______________________________________________ >>> hibernate-dev mailing list >>> hibernate-dev(a)lists.jboss.org >>> https://lists.jboss.org/mailman/listinfo/hibernate-dev >>> >> >> _______________________________________________ >> hibernate-dev mailing list >> hibernate-dev(a)lists.jboss.org >> https://lists.jboss.org/mailman/listinfo/hibernate-dev >> > > _______________________________________________ > hibernate-dev mailing list > hibernate-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/hibernate-dev > _______________________________________________ hibernate-dev mailing list hibernate-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/hibernate-dev

On 12/17/2012 10:35 AM, Scott Marlow wrote: > I will create a jira for this regression (2lc invalidation not being > sent in a cluster) targeting Hibernate ORM 4.1.10. > > Currently, I'm getting a jira error "Version with id '4.1.9' does not > exist" when attempting to create the jira. HHH-7871 is the new jira (the 4.1.9 jira error went away). Galder, can you take a look at helping to resolve this issue? Scott > > > On 12/14/2012 10:38 PM, Scott Marlow wrote: >> >> From the TRACE logs, I can see that >> org.hibernate.cache.infinispan.access.TransactionalAccessDelegate.remove(Object) >> invoked the writeCache.remove(key) with >> key=org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1 but >> the other node isn't notified of this change (as far as I can tell from >> the Infinispan trace output). >> >> I looked closer at TransactionalAccessDelegate.remove and looks like we >> are removing the entry via the writeCache. If the AS 2lc entity cache >> definition is using invalidation (which I think it is), >> TransactionalAccessDelegate will also use CACHE_MODE_LOCAL. >> >> I tried changing TransactionalAccessDelegate.writeCache from: >> >> this.writeCache = >> Caches.isInvalidationCache(cache) ? >> Caches.ignoreReturnValuesCache(cache, Flag.CACHE_MODE_LOCAL) : >> Caches.ignoreReturnValuesCache(cache); >> >> To: >> >> this.writeCache = Caches.ignoreReturnValuesCache(cache); >> >> And my simplified version of the AS7 clustered 2lc test passed. >> >> Why would we want to use Flag.CACHE_MODE_LOCAL when the cache is >> configured to be an invalidation cache? >> >> Scott >> >> On 12/14/2012 11:52 AM, Scott Marlow wrote: >>> I'll add TRACE logging to >>> org.hibernate.cache.infinispan.access.TransactionalAccessDelegate to >>> show more information about what is going on in there when we fail to >>> invalidate the 2lc on the other node. >>> >>> Any other ideas? >>> >>> >>> On 12/14/2012 10:13 AM, Scott Marlow wrote: >>>> On 12/14/2012 09:46 AM, Scott Marlow wrote: >>>>> I enabled org.jboss.as.jpa TRACE logging as well as org.infinispan TRACE >>>>> (I know overly verbose) logging. Output is here >>>>> http://dl.dropbox.com/u/35343318/jboss/serverlogs.zip >>>>> >>>>> In the node1 log, I see that we delete the entity and then try to >>>>> perform the remove command. I don't seem to see this command executed >>>>> on node0: >>>>> >>>>> 09:10:22,416 INFO [stdout] (http-/127.0.0.1:8180-1) Hibernate: delete >>>>> from Employee where id=? >>>>> ... >>>>> 09:10:22,419 TRACE [org.infinispan.interceptors.CallInterceptor] >>>>> (http-/127.0.0.1:8180-1) Executing command: >>>>> RemoveCommand{key=org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1, >>>>> value=null, flags=[CACHE_MODE_LOCAL, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP]}. >>>>> ... >>>>> >>>>> I don't see anything in the node0 log about >>>>> "RemoveCommand{key=org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1" >>>>> being received or executed. >>>>> >>>>> Are there any other TRACE logging settings that I should enable? >>>>> >>>>> I'm going to make a small test change to show the 2lc cache statistics >>>>> for node1 after the entity is deleted from the database. The elementCountInMemory went from one to zero (as expected). >>>> >>>> The 2lc statistics on node1, show that the node1 2lc has been >>>> invalidated to remove the deleted entity. >>>> >>>> 09:56:30,071 INFO [stdout] (http-/127.0.0.1:8180-1) 2lc for >>>> stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: >>>> SecondLevelCacheStatistics[hitCount=1,missCount=0,putCount=1,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1] >>>> >>>> Its node0, that didn't receive the "RemoveCommand" that also still has >>>> the elementCountInMemory as one: >>>> >>>> 09:56:30,172 INFO [stdout] (http-/127.0.0.1:8080-1) 2lc for >>>> stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee: >>>> SecondLevelCacheStatistics[hitCount=0,missCount=0,putCount=1,elementCountInMemory=1,elementCountOnDisk=-1,sizeInMemory=-1] >>>> >>>> >>>>> >>>>> Scott >>>>> >>>>> On 12/14/2012 12:03 AM, Scott Marlow wrote: >>>>>> http://hudson.jboss.org/hudson/job/as7-param-pull/5123/ shows a failure >>>>>> with the second level cache not being invalidated as expected across a >>>>>> two node cluster. >>>>>> >>>>>> I'm able to reproduce locally, which is good. We will continue to use >>>>>> Hibernate 4.1.6 until we get past this regression (hopefully we can >>>>>> understand the test failure cause soon). >>>>>> >>>>>> https://github.com/jbossas/jboss-as/blob/master/testsuite/integration/clu... >>>>>> is the line that is failing (yeah, the arguments to assertEquals are >>>>>> backwards but that isn't the root issue ;) >>>>>> >>>>>> It is possible that its a bug in the test also. >>>>>> >>>>>> The cluster has two nodes, each with their own in-memory database. The >>>>>> test assumes that it can create the same entity on both nodes (same >>>>>> primary key) and that for the purpose of testing the second level cache, >>>>>> we can expect cache invalidation to occur on both nodes when deleting >>>>>> the entity on one of the nodes. >>>>>> >>>>>> I believe that the cache invalidation should be synchronous but I'll >>>>>> probably try adding a sleep to see if it could be an async/timing issue. >>>>>> >>>>>> I hope to have more information soon (probably in the morning on Friday). >>>>>> >>>>>> Scott >>>>>> _______________________________________________ >>>>>> hibernate-dev mailing list >>>>>> hibernate-dev(a)lists.jboss.org >>>>>> https://lists.jboss.org/mailman/listinfo/hibernate-dev >>>>>> >>>>> >>>>> _______________________________________________ >>>>> hibernate-dev mailing list >>>>> hibernate-dev(a)lists.jboss.org >>>>> https://lists.jboss.org/mailman/listinfo/hibernate-dev >>>>> >>>> >>>> _______________________________________________ >>>> hibernate-dev mailing list >>>> hibernate-dev(a)lists.jboss.org >>>> https://lists.jboss.org/mailman/listinfo/hibernate-dev >>>> >>> >>> _______________________________________________ >>> hibernate-dev mailing list >>> hibernate-dev(a)lists.jboss.org >>> https://lists.jboss.org/mailman/listinfo/hibernate-dev >>> >> >> _______________________________________________ >> hibernate-dev mailing list >> hibernate-dev(a)lists.jboss.org >> https://lists.jboss.org/mailman/listinfo/hibernate-dev >> > > _______________________________________________ > hibernate-dev mailing list > hibernate-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/hibernate-dev > _______________________________________________ hibernate-dev mailing list hibernate-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/hibernate-dev