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

[Scott Marlow]

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
>