[hibernate-dev] Regression in AS7 (master) cluster cache invalidation test after moving from Hibernate ORM 4.1.6 to 4.1.9

[Scott Marlow]

I'll build 4.1.x and use it with the AS7 testsuite to verify the fix for 
HHH-7871.

On 12/17/2012 10:43 AM, Scott Marlow wrote:
> 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/clust/src/test/java/org/jboss/as/test/clustering/cluster/ejb3/xpc/StatefulWithXPCFailoverTestCase.java#L276
>>>>>>> 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 at lists.jboss.org
>>>>>>> https://lists.jboss.org/mailman/listinfo/hibernate-dev
>>>>>>>
>>>>>>
>>>>>> _______________________________________________
>>>>>> hibernate-dev mailing list
>>>>>> hibernate-dev at lists.jboss.org
>>>>>> https://lists.jboss.org/mailman/listinfo/hibernate-dev
>>>>>>
>>>>>
>>>>> _______________________________________________
>>>>> hibernate-dev mailing list
>>>>> hibernate-dev at lists.jboss.org
>>>>> https://lists.jboss.org/mailman/listinfo/hibernate-dev
>>>>>
>>>>
>>>> _______________________________________________
>>>> hibernate-dev mailing list
>>>> hibernate-dev at lists.jboss.org
>>>> https://lists.jboss.org/mailman/listinfo/hibernate-dev
>>>>
>>>
>>> _______________________________________________
>>> hibernate-dev mailing list
>>> hibernate-dev at lists.jboss.org
>>> https://lists.jboss.org/mailman/listinfo/hibernate-dev
>>>
>>
>> _______________________________________________
>> hibernate-dev mailing list
>> hibernate-dev at lists.jboss.org
>> https://lists.jboss.org/mailman/listinfo/hibernate-dev
>>
>
> _______________________________________________
> hibernate-dev mailing list
> hibernate-dev at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/hibernate-dev
>