[TEST-FAILURE] LocalRegionFactoryDefaultTest.testQuery

mesutcelik commented 10 years ago

Maintenance-3x issue

https://hazelcast-l337.ci.cloudbees.com/job/Hazelcast-3.maintenance-problematicTest/com.hazelcast$hazelcast-hibernate4/96/testReport/junit/com.hazelcast.hibernate/LocalRegionFactoryDefaultTest/testQuery/

java.lang.AssertionError: expected:<1> but was:<3>
    at org.junit.Assert.fail(Assert.java:88)
    at org.junit.Assert.failNotEquals(Assert.java:743)
    at org.junit.Assert.assertEquals(Assert.java:118)
    at org.junit.Assert.assertEquals(Assert.java:555)
    at org.junit.Assert.assertEquals(Assert.java:542)
    at com.hazelcast.hibernate.HibernateStatisticsTestSupport.testQuery(HibernateStatisticsTestSupport.java:181)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    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.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.runners.ParentRunner.runLeaf(ParentRunner.java:271)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
    at com.hazelcast.test.HazelcastSerialClassRunner.runChild(HazelcastSerialClassRunner.java:37)
    at com.hazelcast.test.HazelcastSerialClassRunner.runChild(HazelcastSerialClassRunner.java:26)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
    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.runners.ParentRunner.run(ParentRunner.java:309)
    at org.junit.runners.Suite.runChild(Suite.java:127)
    at org.junit.runners.Suite.runChild(Suite.java:26)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
    at org.junit.runner.JUnitCore.run(JUnitCore.java:160)
    at org.junit.runner.JUnitCore.run(JUnitCore.java:138)
    at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:113)
    at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:85)
    at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:54)
    at org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:134)
    at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200)
    at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153)
    at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)

serkan-ozal commented 10 years ago

Hi,

The issue is caused by isUpToDate method of org.hibernate.cache.spi.UpdateTimestampsCache class. Sometimes, current timestamp may be equal to last update timestamp of entry.

Timestamps are taken from cache regions by nextTimestamp() method and for Hazelcast Hibernate Integration, this method is implemented in com.hazelcast.hibernate.region.AbstractHazelcastRegion. This implementation uses nextTimestamp method of com.hazelcast.hibernate.HazelcastTimestamper and returns timestamp as milliseconds resolution.

Milliseconds resolution based timestamps can be insufficient for fast running operations since they can be executed in the same milliseconds interval. So to solve the issue timestamps can be nanoseconds based. For nanosecond based timestamps, I run unit test 100 times and got no error. But in current code state nextTimestamp() method cannot be overriden in com.hazelcast.hibernate.region.HazelcastQueryResultsRegion since it is defined as final in com.hazelcast.hibernate.region.AbstractHazelcastRegion. There are two ways:

Make unfinal nextTimestamp() method in com.hazelcast.hibernate.region.AbstractHazelcastRegion and override in com.hazelcast.hibernate.region.HazelcastQueryResultsRegion as using nanosecond based timestamp like "System.nanoTime()"
Update implementation of nextTimestamp() method in com.hazelcast.hibernate.region.AbstractHazelcastRegion as using nanosecond based timestamp like System.nanoTime() for all regions ?

What do you think @mesutcelik ?

jerrinot commented 10 years ago

@serkan-ozal: see this for issue with nanoTime(): https://github.com/hazelcast/hazelcast/issues/2666

serkan-ozal commented 10 years ago

@jerrinot @mesutcelik

Hmm, you are right @jerrinot thanks for your point

In that case maybe we should override some classes and methods only for ignoring timestamp equal conditions.

Or maybe we can use nano time as order for operations in same milliseconds interval such as (HazelcastTimestamper.nextTimestamp(instance) * 1000000L) + (System.nanoTime() % 1000000L); This is not going to cause an overflow of long type many years :) But this doesn't guarantee right order of operations in the same milliseconds interval on distributed environment.

mdogan commented 10 years ago

Upgraded Hibernate version to 4.2.13.Final from 4.1.0. We inspected Hibernate code with Mesut and it seems issue is related to Hibernate itself since it doesn't make sense query execution count is different than query miss and query put count.

Master branch is using Hibernate 4.2.13 and this test never failed there.

MrEasy commented 10 years ago

Be aware, that this change now creates Import-Package statements for org.hibernate.* with the version added. This was not the case before and thus now the package is only deployable if target system fulfills exactly the hibernate version. Was this intended?

Before: Import-Package: org.hibernate,org.hibernate.cache,org.hibernate.cache.spi,org.hibernate.cache.spi.access,org.hibernate.cache.spi.entry,org.hibernate.cfg,org.hibernate.engine.spi,org.hibernate.internal.util,org.hibernate.internal.util.config

After: Import-Package: org.hibernate;version="[4.2,5)",org.hibernate.cache;version="[4.2,5)",org.hibernate.cache.spi;version="[4.2,5)",org.hibernate.cache.spi.access;version="[4.2,5)",org.hibernate.cache.spi.entry;version="[4.2,5)",org.hibernate.cfg;version="[4.2,5)",org.hibernate.engine.spi;version="[4.2,5)",org.hibernate.internal.util;version="[4.2,5)",org.hibernate.internal.util.config

mdogan commented 10 years ago

I guess this is related to Hibernate packaging change. Hibernate 4.1 doesn't have OSGI metadata in manifest, but 4.2 has.

MrEasy commented 10 years ago

Without this change, hazelcast still works perfectly in an environment with Hibernate 4.0.1 (e.g. Jboss 7.1)

mesutcelik commented 10 years ago

this has failed again.

https://hazelcast-l337.ci.cloudbees.com/job/Hazelcast-3.maintenance-problematicTest/com.hazelcast$hazelcast-hibernate4/110/testReport/com.hazelcast.hibernate/LocalRegionFactoryDefaultTest/testQuery/

serkan-ozal commented 10 years ago

@mesutcelik WDYT about these from my previous comments ?

The issue is caused by "isUpToDate" method of "org.hibernate.cache.spi.UpdateTimestampsCache" class. 
Sometimes, current timestamp may be equal to last update timestamp of entry. 
Milliseconds resolution based timestamps can be insufficient for fast running operations since they can be executed in the same milliseconds interval.

...

Or maybe we can use nano time as order for operations in same milliseconds interval such as 
"(HazelcastTimestamper.nextTimestamp(instance) * 1000000L) + (System.nanoTime() % 1000000L);"
This is not going to cause an overflow of long type many years :)

mesutcelik commented 10 years ago

@serkan-ozal the problem here is that it is only failing in maintenance 3.x with hibernate4 module. All other 3 options (master+hibernate3, master+hibernate4,maintenance-3.x+hibernate3) are ok.

I will check what has been changed between master and maintenance to see if some weird change is causing the problem.

mesutcelik commented 10 years ago

I just removed the Problematic Marker. Lets wait for a while to see if it is gonna fail in normal maintenance builds.

mesutcelik commented 10 years ago

@bilalyasar This does not fail in the normal build last 3 weeks. please keep an eye on that and please reopen it if you see it failed again.

pivovarit commented 4 years ago

After all these years... it still fails :)

pivovarit commented 4 years ago

This should be fixed by https://github.com/hazelcast/hazelcast-hibernate5/pull/147

hazelcast / hazelcast-hibernate

[TEST-FAILURE] LocalRegionFactoryDefaultTest.testQuery #126