GeoTools

Intermittent build failure in gt-feature-pregeneralized ShapeFilePreGeneralizedFeatureSourceTest

Details

  • Type: Bug Bug
  • Status: Closed Closed
  • Priority: Blocker Blocker
  • Resolution: Fixed
  • Affects Version/s: 2.7-M4
  • Fix Version/s: None
  • Component/s: shapefile plugin
  • Labels:
    None
  • Environment:

Description

I am seeing intermittent build failures in gt-feature-pregeneralized (where by intermittent I mean it fails most of the time, but sometimes succeeds). I strongly suspect a shapefile handling race condition. At the other tests with the same abstract base class succeed.

This does not affect stable, does not affect Hudson, not my buildbot. Just my desktop. This looks like another Affects-Only-Ben bug. (Did we ever set that as a priority option?)

Failed tests: 
  testFeatureReader(org.geotools.data.gen.ShapeFilePreGeneralizedFeatureSourceTest)
  testFeatureReaderWithoutGeom(org.geotools.data.gen.ShapeFilePreGeneralizedFeatureSourceTest)
  testGetFeatures(org.geotools.data.gen.ShapeFilePreGeneralizedFeatureSourceTest)
  testGetFeatures3(org.geotools.data.gen.ShapeFilePreGeneralizedFeatureSourceTest)
  testGetSchema(org.geotools.data.gen.ShapeFilePreGeneralizedFeatureSourceTest)

Tests run: 52, Failures: 5, Errors: 0, Skipped: 0

[INFO] ------------------------------------------------------------------------
[ERROR] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] There are test failures.

The common symptom is an NPE thrown at ComplexTypeImpl:73:

throw new NullPointerException("PropertyDescriptor is null - did you request a property that does not exist?");

At this point the local variable properties is:

[GeometryDescriptorImpl the_geom <MultiLineString:MultiLineString> nillable 0:1, null]

So the type is being constructed with a null property.

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Andrea Aime added a comment -
Ben, how can I fix something I cannot reproduce?
Since when do you have this issue?
Show
Andrea Aime added a comment - Ben, how can I fix something I cannot reproduce? Since when do you have this issue?
Hide
Permalink
Ben Caradoc-Davies added a comment -
I have only seen the bug this week, but it has been a while since I ran a full build.

Can you run ShapeFilePreGeneralizedFeatureSourceTest in Eclipse? This seems to be the most reliable way of reproducing it.

You only got this because you are the default assignee. That does not mean you are obliged to fix it. :-)
Show
Ben Caradoc-Davies added a comment - I have only seen the bug this week, but it has been a while since I ran a full build. Can you run ShapeFilePreGeneralizedFeatureSourceTest in Eclipse? This seems to be the most reliable way of reproducing it. You only got this because you are the default assignee. That does not mean you are obliged to fix it. :-)
Hide
Permalink
Ben Caradoc-Davies added a comment -
Reverting your commit r36171 "Experimental shapefile index caching" does *not* fix the problem.
Show
Ben Caradoc-Davies added a comment - Reverting your commit r36171 "Experimental shapefile index caching" does *not* fix the problem.
Hide
Permalink
Andrea Aime added a comment -
Ok, never mind, I can reproduce the issue in Eclipse.
What I see running testFeatureReader(org.geotools.data.gen.ShapeFilePreGeneralizedFeatureSourceTest)
is that the pregeneralized store makes various access to an underlying shapefile, like 7 times in a row, at the 7-th
time it asks for a property that is apparently missing from the shapefile: CAT_ID

From what I can see the original shapefile has the CAT_ID property, but the pregeneralized versions do not. I looked around and it seems the test setup is involved in this, sometimes ShapefilesDataStore.createSchema() is called with a full feature type with all the attributes, other times with just the geometry. Not sure if it's the memory data store that's at fault (since the schema comes from there) or something else... Maybe Christian knows more.
One thing I've noticed is that apparently the test is not clearing up after itself, the pregeneralized shapefiles are not rebuilt at each run. If I wipe out target/0, target/5, .., target/50.0 and then I run "testFeatureReader" alone the test passes without issues, and then I can run all the tests without failures. Actually after doing that I haven't been able to reproduce the failure at all, now no matter what I do, using maven or using eclipse, all the tests are passing...
Show
Andrea Aime added a comment - Ok, never mind, I can reproduce the issue in Eclipse. What I see running testFeatureReader(org.geotools.data.gen.ShapeFilePreGeneralizedFeatureSourceTest) is that the pregeneralized store makes various access to an underlying shapefile, like 7 times in a row, at the 7-th time it asks for a property that is apparently missing from the shapefile: CAT_ID From what I can see the original shapefile has the CAT_ID property, but the pregeneralized versions do not. I looked around and it seems the test setup is involved in this, sometimes ShapefilesDataStore.createSchema() is called with a full feature type with all the attributes, other times with just the geometry. Not sure if it's the memory data store that's at fault (since the schema comes from there) or something else... Maybe Christian knows more. One thing I've noticed is that apparently the test is not clearing up after itself, the pregeneralized shapefiles are not rebuilt at each run. If I wipe out target/0, target/5, .., target/50.0 and then I run "testFeatureReader" alone the test passes without issues, and then I can run all the tests without failures. Actually after doing that I haven't been able to reproduce the failure at all, now no matter what I do, using maven or using eclipse, all the tests are passing...
Hide
Permalink
Christian Mueller added a comment -
No, this is not a Affects-Only-Ben bug. Look here

http://gis.linux4all.at/hudson64/view/Geotools-Trunk-64-Bit/job/geotools-trunk-SUN-SDK-6-64-Bit/lastFailedBuild/#showFailuresLink

Looks like a race condition.
Show
Christian Mueller added a comment - No, this is not a Affects-Only-Ben bug. Look here http://gis.linux4all.at/hudson64/view/Geotools-Trunk-64-Bit/job/geotools-trunk-SUN-SDK-6-64-Bit/lastFailedBuild/#showFailuresLink Looks like a race condition.
Hide
Permalink
Andrea Aime added a comment -
Yep... now no matter what I do I end up with all pass. Can't seem to find a way to reproduce the bug anymore...
Show
Andrea Aime added a comment - Yep... now no matter what I do I end up with all pass. Can't seem to find a way to reproduce the bug anymore...
Hide
Permalink
Andrea Aime added a comment -
Aaah, Java 6! That's the reliable way to make it fail.
If the pregeneralized shapefiles are created while running java 6 the bug shows up, whilst if they are created while running java 5 the problem does not occur.
Show
Andrea Aime added a comment - Aaah, Java 6! That's the reliable way to make it fail. If the pregeneralized shapefiles are created while running java 6 the bug shows up, whilst if they are created while running java 5 the problem does not occur.
Hide
Permalink
Andrea Aime added a comment -
And once created with Java 5 you can run the tests with java 6 as much as you like, the problem does not show up. So there's something going on in the test setup when running Java 6.
I have to upgrade my machine to Ubuntu 10.04 now and in the process I'll have to reformat the disk to get the best performance out of it (to support the WD adanced format setup), meaning I won't be around for a few hours, maybe the whole day.
Show
Andrea Aime added a comment - And once created with Java 5 you can run the tests with java 6 as much as you like, the problem does not show up. So there's something going on in the test setup when running Java 6. I have to upgrade my machine to Ubuntu 10.04 now and in the process I'll have to reformat the disk to get the best performance out of it (to support the WD adanced format setup), meaning I won't be around for a few hours, maybe the whole day.
Hide
Permalink
Ben Caradoc-Davies added a comment -
Thanks Andrea and Christian for confirming this one. I thought i was losing my mind.

Andrea, I can reproduce this with Java 5 32-bit (see the environment above.) Even in Eclipse I am using 1.5 (22) as my JRE. With 6 (21) 32-bit and 64-bit it looks the same. I am trying to figure out why I have not been this before. If I use git to wander around with a detached HEAD (even back to r36070) I still see this.

I recently upgraded to Maven 2.2.1, but this cannot explain Eclipse failures. I also upgraded to Eclipse Helios, but this cannot explain failures in Maven.

Maybe my SSD is getting just enough jitter as it ages to cause this race condition to be evident. :-)
Show
Ben Caradoc-Davies added a comment - Thanks Andrea and Christian for confirming this one. I thought i was losing my mind. Andrea, I can reproduce this with Java 5 32-bit (see the environment above.) Even in Eclipse I am using 1.5 (22) as my JRE. With 6 (21) 32-bit and 64-bit it looks the same. I am trying to figure out why I have not been this before. If I use git to wander around with a detached HEAD (even back to r36070) I still see this. I recently upgraded to Maven 2.2.1, but this cannot explain Eclipse failures. I also upgraded to Eclipse Helios, but this cannot explain failures in Maven. Maybe my SSD is getting just enough jitter as it ages to cause this race condition to be evident. :-)
Hide
Permalink
Ben Caradoc-Davies added a comment -
Andrea, I have found the cause of the race condition: stale DBF existence status in Shpfiles.lastChecked. If I replace ShpFiles:974
{code}
if(status == null || status.lastChecked > now - 1000) {
{code}
with
{code}
if(true) {
{code}
(disabling existence caching) then the intermittent failure is fixed (in Maven and Eclipse).

What is going on is that the test fixture is creating new shapefiles and setting the schema to that of the old, then forcing a reload of the schema. What I see is that null is being returned at ShapefileDataStore:551 because the new DBF is ignored if it is not already 1000 milliseconds old. I see this more than others because I have an SSD and /tmp on a tmpfs (i.e. a ramdisk).

The existence test looks like a performance optimisation. If you would like to retain this, we could add a Thread.sleep(1000) in gt-feature-pregeneralized TestSetup between the creation of the shapefiles and their use. Which would you prefer?
Show
Ben Caradoc-Davies added a comment - Andrea, I have found the cause of the race condition: stale DBF existence status in Shpfiles.lastChecked. If I replace ShpFiles:974 {code} if(status == null || status.lastChecked > now - 1000) { {code} with {code} if(true) { {code} (disabling existence caching) then the intermittent failure is fixed (in Maven and Eclipse). What is going on is that the test fixture is creating new shapefiles and setting the schema to that of the old, then forcing a reload of the schema. What I see is that null is being returned at ShapefileDataStore:551 because the new DBF is ignored if it is not already 1000 milliseconds old. I see this more than others because I have an SSD and /tmp on a tmpfs (i.e. a ramdisk). The existence test looks like a performance optimisation. If you would like to retain this, we could add a Thread.sleep(1000) in gt-feature-pregeneralized TestSetup between the creation of the shapefiles and their use. Which would you prefer?
Hide
Permalink
Ben Caradoc-Davies added a comment - - edited
Aha! Thread.sleep(1000) does not help, because there is also a logic error:

if(status == null || status.lastChecked > now - 1000) {

should be

if(status == null || status.lastChecked < now - 1000) {

meaning last checked more than 1000 milliseconds ago?
Show
Ben Caradoc-Davies added a comment - - edited Aha! Thread.sleep(1000) does not help, because there is also a logic error: if(status == null || status.lastChecked > now - 1000) { should be if(status == null || status.lastChecked < now - 1000) { meaning last checked more than 1000 milliseconds ago?
Hide
Permalink
Andrea Aime added a comment -
Ah yeah, under high load those existence checks are quite heavy so the usual trick is to force the code not to check the file every 10ms. The fix makes sense, as well as the workaround.
Show
Andrea Aime added a comment - Ah yeah, under high load those existence checks are quite heavy so the usual trick is to force the code not to check the file every 10ms. The fix makes sense, as well as the workaround.
Hide
Permalink
Ben Caradoc-Davies added a comment -
Andrea, fixing the logic error causes many gt-shapefile failures because any test that creates an index or other file in under a second can be hit by the existence caching.

You introduced existence caching in r36128 (25 August). I would like to revert this change because I think it has unintended consequences.
Show
Ben Caradoc-Davies added a comment - Andrea, fixing the logic error causes many gt-shapefile failures because any test that creates an index or other file in under a second can be hit by the existence caching. You introduced existence caching in r36128 (25 August). I would like to revert this change because I think it has unintended consequences.
Hide
Permalink
Ben Caradoc-Davies added a comment -
Attached proposed change to remove shapefile existence caching.
Show
Ben Caradoc-Davies added a comment - Attached proposed change to remove shapefile existence caching.
Hide
Permalink
Ben Caradoc-Davies added a comment -
Note that not all of r36128 is reverted by this patch. There were some other code simplifications unrelated to existence caching. I am only reverting two chunks.
Show
Ben Caradoc-Davies added a comment - Note that not all of r36128 is reverted by this patch. There were some other code simplifications unrelated to existence caching. I am only reverting two chunks.
Hide
Permalink
Andrea Aime added a comment -
Humm... ok go ahead, I don't have time to look into this further right now.
Show
Andrea Aime added a comment - Humm... ok go ahead, I don't have time to look into this further right now.
Hide
Permalink
Ben Caradoc-Davies added a comment -
Thanks Andrea. Committed on trunk in r36214.
Show
Ben Caradoc-Davies added a comment - Thanks Andrea. Committed on trunk in r36214.

People

  • Assignee:
    Ben Caradoc-Davies
    Reporter:
    Ben Caradoc-Davies
Vote (0)
Watch (1)

Dates

  • Created:
    Updated:
    Resolved: