Convert GPX/KML to geojson

[GretaCB]

Per https://github.com/mapbox/preprocessorcerer/issues/19

• [x] Convert each layer of KML/GPX into geojson file (max 15 layers)
• [x] Add index file for each new file/layer > 10MB
• [x] Validate layer names
• [x] Include metadata file for original KML/GPX (run through mapnik-omnivore)
• [x] Drop GPX track_points. Found that these are automatically inserted by gdal (most of the time). @BergWerkGIS did we decide on if possible to allow track_points produced by an actual GPS device?
• [x] Tests (anything we're not testing that we should?)

@BergWerkGIS

[GretaCB]

Per https://github.com/mapbox/unpacker/issues/907, this PR just needs to run mapnik-omnivore and add the output as a JSON file to the bundle (for both KML/GPX preprocessor and geojson-index preprocessor). Happy to jump on this tomorrow.

[GretaCB]

The togeojson KML tests fail 50% of the time locally with the following error:

not ok 9 .end() called twice
  ---
    operator: fail
  ...

/Users/mapbox/dev/preprocessorcerer/node_modules/queue-async/build/queue.js:41
        if (!tasks[i]) throw new Error; // detect multiple callbacks

Going to split each fixture into its own tape test as a first step. Wonder if a previous test in the for loop is erroring and an assert.end() is lingering.

[GretaCB]

Looks like the original error that was causing the .end() callback error is:

max tree depth:8
split ratio:0.55
processing '/var/folders/2p/m7jcvfp90wngshgr9j0cd9tc0000gn/T/f32881494358414c/empty-features-only.geojson' as GeoJSON
Mapnik LOG> 2016-03-18 14:39:26: Error loading mapped memory file: '/var/folders/2p/m7jcvfp90wngshgr9j0cd9tc0000gn/T/f32881494358414c/empty-features-only.geojson' (Invalid argument)
Error : cannot memory map /var/folders/2p/m7jcvfp90wngshgr9j0cd9tc0000gn/T/f32881494358414c/empty-features-only.geojson
Error: failed to process /var/folders/2p/m7jcvfp90wngshgr9j0cd9tc0000gn/T/f32881494358414c/empty-features-only.geojson
done!

I console logged the above error from within the indexing logic.

I suspect mapnik doesnt like some of the geojson files we are feeding it for indexing or some kind of race condition when indexing each layer?

cc @artemp @springmeyer

[GretaCB]

Per chat with @springmeyer , looks like the indexing error is pointing to something else going on in the converted geojson layers.

I took a look at the resulting converted geojson layers for the tests that are failing, and looks as if they are producing incomplete objects (invalid json).

Note: not all resulting geojson layers are invalid.

Going to keep :eyes:

[wilhelmberg]

One step further with debugging the failing test.

I have proof now, that something is still holding on to tmpfile when it should be deleted:

Unfortunately it's a pain to find out: running the test from the console the exception occurs every time. Slowly stepping thru the test in a debug session works. Jumping between different break points in a debug session fails. I've already tried different things (without success):

• delay before delete
• nulling src in wmtiff
• ...

[GretaCB]

I think we have here a good ole fashioned control flow problem (when I remove createIndex locally, tests no longer fail). Looks like createIndex can potentially trigger before the forEach loops are finished. This is because createIndex is being called outside of the forEach loops, and is not relying on any sort of callback or way to determine when layers are in fact ready to be indexed.

I like your idea from yesterday, that we should index after all layers are converted. We can also refactor the main function a bit to better manage flow and modularize a bit.

Found a great example of how we can try untangling some of this:

var fs = require('fs');

function read_directory(path, next) {
  fs.readdir(".", function (err, files) {
    var count = files.length,
        results = {};
    files.forEach(function (filename) {
      fs.readFile(filename, function (data) {
        results[filename] = data;
        count--;
        if (count <= 0) {
          next(results);
        }
      });
    });
  });
}

function read_directories(paths, next) {
  var count = paths.length,
      data = {};
  paths.forEach(function (path) {
    read_directory(path, function (results) {
      data[path] = results;
      count--;
      if (count <= 0) {
        next(data);
      }
    });
  });
}

read_directories(['articles', 'authors', 'skin'], function (data) {
  // Do something
});

[wilhelmberg]

Nothing wrong with the control flow, just gdal has to be manually disposed to get rid of the file reference faster:

• preprocessorcerer: https://github.com/mapbox/preprocessorcerer/commit/8dc42912a9deff3d17ac64bdfba3f4ecb6cac4df
• wmtiff: https://github.com/mapbox/node-wmtiff/commit/6c809733b31627e3afdb4e4921c5238a0a2ff6ba

The 4 references to the dataset in the screenshot above came from

• wmtiff
• tif-reproject.preprocessor.js
• tif-toBytes.preprocessor.js
• preprocessor.criteria

as each of them opens the dataset (maybe room for improvement?) and ds is still holding on to the file (despite of ds.close()). Maybe because everything is done in callbacks and node hasn't yet let go of the objects.

---

Working on the next failing test now:

# [parts mbtiles] correct number of parts for mbtiles without grids table
ok 40 no error
ok 41 four parts

fs.js:772
  return binding.unlink(pathModule._makeLong(path));
                 ^
Error: EBUSY, resource busy or locked 'C:\Users\ADMINI~1\AppData\Local\Temp\2\79c7b0a1613d996b'
    at Object.fs.unlinkSync (fs.js:772:18)
    at c:\mb\preprocessorcerer\test\mbtiles-byTiles.test.js:17:10
    at Statement.<anonymous> (c:\mb\preprocessorcerer\parts\mbtiles-byTiles.js:25:9)
npm ERR! Test failed.  See above for more details.

[wilhelmberg]

Same with failing mbtiles test: resources are not properly disposed. In this case connection to the database is not closed. Fixed: https://github.com/mapbox/preprocessorcerer/commit/abf63bcb9b80b9580a9c4a07eee566f6c8ce33f5

---

Now all tests run through again, but 8 are failing. Continuing the test quest ... :smirk:

[wilhelmberg]

I think we have here a good ole fashioned control flow problem

Yes, you are right. This is a control flow problem.

I didn't realize that you were talking about GPX test and I was talking about tiff test

Here createIndex is called async, but at the same time control flow continues to here

[wilhelmberg]

That's also why .end() is called twiced: 1x from createIndex() and 1x from the exported function itself.

not ok 4 expected error message
  ---
    operator: equal
    expected: 'GPX does not contain any valid features.'
    actual:   undefined
  ...
not ok 5 .end() called twice
  ---
    operator: fail
  ...

[coveralls]

Coverage decreased (-1.5%) to 95.238% when pulling c9ca0303d0ea569087d28ceec2f4d6107ce7ba3f on togeojson into 455fc99efedb4ad68a63d94ba30b7e78712ac7af on master.

[wilhelmberg]

npm test works for me now - no failed tests. But I have to use https://github.com/mapbox/node-wmtiff/commit/6c809733b31627e3afdb4e4921c5238a0a2ff6ba.

[GretaCB]

Node v0.10.40 worked fine on OSX as well. I took a look around preprocessorcer and did a little research, but didnt find much that explains the immortal tmpfile. I did find this

Datasets get closed automatically when node garbage collects them, but there is no guarantee that node will garbage collect before exiting.

This lead me down a google search of node GC, but not sure that's the proper route at this point. Will keep pondering.

[wilhelmberg]

I did find this

Great find. Thanks. This was exactly my hunch: "Making sure the dataset is closed and flushed before the process exits fixes the problem for me. Datasets get closed automatically when node garbage collects them, but there is no guarantee that node will garbage collect before exiting."

but there is no guarantee that node will garbage collect before exiting or in our case before we try to delete the dataset.

but didnt find much that explains the immortal tmpfile

The explanation above was the reason for not being able to delete the tmpfile, as node hat not yet done its garbage collection.

Sorry if I caused any confusion, but this should be fixed now and the file should not be immortal anymore.

ds.close() and ds = null I've put into the code at various places should take care of disposing the objects (references to the file).

This lead me down a google search of node GC, but not sure that's the proper route at this point. Will keep pondering.

Not necessary to spend more time on this. I've literally spent weeks on node GC when investigating strange node-mapnik crashes some time ago.

There are GC parameters you can pass to the node executable to fiddle with the internals of its GC e.g.: --expose-gc, or others to change memory usage before GC kicks in, or to prevent GC at all. But none of them really helped and we decided to stick with the defaults.

---

The take away here is: always dispose of resources properly as soon as you are done with them.

Be it a file (fs.close()), a database connection (db.close()) or another native wrapper (like gdal).

[springmeyer]

The take away here is: always dispose of resources properly as soon as you are done with them.

Awesome work. Also agree @BergWerkGIS. This is a pretty classic case of windows behavior being more strict and that helping highlight core issues of the code that should be written more robustly. :100:

ds.close() and ds = null I've put into the code at various places should take care of disposing the objects (references to the file).

That is neat/great that setting to null triggers the actual close (I presume because it triggers the garbage collection sooner). I'm left however thinking that it is probably worth bringing this up again with Brian and Brandon. I'm sure the current close() behavior of not releasing until garbage collection makes sense given the design and object inheritance in node-gdal. But nevertheless it seems like odd behavior. Perhaps they would reconsider having ds.close() actually close the underlying gdal file handle directly or perhaps adding a ds.closeNow() method to force it. I've not looked at the code enough to know if this is feasible, but I think it would be great @BergWerkGIS if you would raise this for them in a ticket to flesh this out further.

[wilhelmberg]

@springmeyer Already looked at the code and I think this is purely on node's side (and our implementation) and there is nothing else gdal can do about it (although not familiar with node's GC internals).

ds.close() calls dispose() to null the internal resources:

    if (this_dataset) {
        LOG("Disposing Dataset [%p]", this_dataset);
        ptr_manager.dispose(uid);
        LOG("Disposed Dataset [%p]", this_dataset);
        this_dataset = NULL;
    }

---

Pseudo code of our implementation looks like this:

function one(){var ds = new gdal.ds; return two(ds);}
function two(ds){return three(ds);}
function three(ds){return four(ds);}
function four(ds){fs.unlink(ds);}

And with this implementation it absolutely makes sense for me that node hasn't fully released ds yet, as in method four() we are essentially still in method one(). Or am I missing something about node/js callbacks?

[GretaCB]

It happened to me after adding a few more fs.unlinks to clean up a bit in other tests:

# [spatial-index] indexes (input folder output file)
ok 108 should be equal
ok 109 no error
ok 110 (unnamed assert)

fs.js:772
  return binding.unlink(pathModule._makeLong(path));
                 ^
Error: EPERM, operation not permitted '/var/folders/2p/m7jcvfp90wngshgr9j0cd9tc0000gn/T/0fa9a8e51db16a2e'
    at Object.fs.unlinkSync (fs.js:772:18)
    at /Users/mapbox/dev/preprocessorcerer/test/spatial-index.test.js:64:12
    at ReadStream.<anonymous> (/Users/mapbox/dev/preprocessorcerer/node_modules/checksum/checksum.js:84:9)
    at ReadStream.emit (events.js:117:20)
    at _stream_readable.js:944:16
    at process._tickCallback (node.js:448:13)

Going to remove the new fs.unlinks for now. At least I know now that I can replicate on OSX.

Also seeing funky travis test failure, for node v0.12.0

> node-pre-gyp install --fallback-to-build
/bin/sh: 1: mapnik-config: not found
gyp: Call to 'mapnik-config --cflags' returned exit status 127. while trying to load binding.gyp
gyp ERR! configure error 
gyp ERR! stack Error: `gyp` failed with exit code: 1
gyp ERR! stack     at ChildProcess.onCpExit (/home/travis/.nvm/versions/node/v0.12.12/lib/node_modules/npm/node_modules/node-gyp/lib/configure.js:355:16)
gyp ERR! stack     at ChildProcess.emit (events.js:110:17)
gyp ERR! stack     at Process.ChildProcess._handle.onexit (child_process.js:1078:12)
gyp ERR! System Linux 3.13.0-40-generic
gyp ERR! command "/home/travis/.nvm/versions/node/v0.12.12/bin/node" "/home/travis/.nvm/versions/node/v0.12.12/lib/node_modules/npm/node_modules/node-gyp/bin/node-gyp.js" "configure" "--fallback-to-build" "--module=/home/travis/build/mapbox/preprocessorcerer/node_modules/mapnik/lib/binding/node-v14-linux-x64/mapnik.node" "--module_name=mapnik" "--module_path=/home/travis/build/mapbox/preprocessorcerer/node_modules/mapnik/lib/binding/node-v14-linux-x64"

[coveralls]

Coverage decreased (-1.7%) to 95.111% when pulling fa905010cbfeefe5a3e2c784f5c218ed99c85289 on togeojson into 455fc99efedb4ad68a63d94ba30b7e78712ac7af on master.

[wilhelmberg]

Interesting, doesn't happen for me, neither with

node node_modules\tape\bin\tape test\spatial-index.test.js

nor with

npm test

@GretaCB could you try with this commit? https://github.com/mapbox/preprocessorcerer/pull/61/commits/a08b2cac71947f60592f342a57a65114936a54c9

[coveralls]

Coverage decreased (-1.7%) to 95.111% when pulling a08b2cac71947f60592f342a57a65114936a54c9 on togeojson into 455fc99efedb4ad68a63d94ba30b7e78712ac7af on master.

[GretaCB]

Ok, looks like the funky travis test is due to multiple node-mapnik versions:

├── mapnik@3.5.2 
└─┬ mapnik-omnivore@7.1.1
  └── mapnik@3.4.17 

so going to update to mapnik-omnivore 7.3.0 (which contains the newest node-mapnik)

[coveralls]

Coverage decreased (-1.7%) to 95.111% when pulling d07f0076c9241d8ffe6fde67d5dc329d7c0c7cb7 on togeojson into 455fc99efedb4ad68a63d94ba30b7e78712ac7af on master.

[coveralls]

Coverage decreased (-1.7%) to 95.111% when pulling f781e3c9ff789a1f14c5b263b2a06be69863052f on togeojson into 455fc99efedb4ad68a63d94ba30b7e78712ac7af on master.

[GretaCB]

UPDATE on funky test failure

Per chat with Jake, node-mapnik no longer supports builds for node 0.12

[coveralls]

Coverage decreased (-1.7%) to 95.111% when pulling cd5474eef945926754af79b1b574bc4a477a1874 on togeojson into 455fc99efedb4ad68a63d94ba30b7e78712ac7af on master.

[coveralls]

Coverage decreased (-1.7%) to 95.111% when pulling a61209a0bd6680dcfad5b085cb3c76eb91ee3ff8 on togeojson into 455fc99efedb4ad68a63d94ba30b7e78712ac7af on master.

[coveralls]

Coverage decreased (-1.7%) to 95.111% when pulling d6af91f8cd43f5875863f8f058646f6f0fcfdf5c on togeojson into 455fc99efedb4ad68a63d94ba30b7e78712ac7af on master.

[wilhelmberg]

Cannot reproduce the unlink problem locally also Travis didn't have a problem on the last run: https://travis-ci.org/mapbox/preprocessorcerer/builds/118480437

---

The highlighted files are those left after npm test. Will take a look where there are coming from.

[coveralls]

Coverage decreased (-1.7%) to 95.111% when pulling 2a20b12a5176c0712a0b80a213b023d3f10a5dc8 on togeojson into 455fc99efedb4ad68a63d94ba30b7e78712ac7af on master.

[coveralls]

Coverage decreased (-1.7%) to 95.133% when pulling 338d5a29077dbde0c9f4aebb842727583544989e on togeojson into 455fc99efedb4ad68a63d94ba30b7e78712ac7af on master.

[GretaCB]

Hmmm, looking into why tests are still failing here, so we can get this ready to rock.

[coveralls]

Coverage decreased (-1.6%) to 95.143% when pulling 5aad818a4a7fdb53f9df5bf4be458e8dbadc98a8 on togeojson into 455fc99efedb4ad68a63d94ba30b7e78712ac7af on master.

[coveralls]

Coverage decreased (-1.6%) to 95.143% when pulling 4cc9d80316eb22bef42a25118318cb31e9832ca3 on togeojson into 059ebf909b6b14b0f1dd38fb3c75a81d4d4fef5b on master.

[coveralls]

Coverage decreased (-1.7%) to 95.133% when pulling 18c3a2669d4da65031d48a595c73f8de5353f047 on togeojson into 059ebf909b6b14b0f1dd38fb3c75a81d4d4fef5b on master.

[coveralls]

Coverage decreased (-1.7%) to 95.133% when pulling 18c3a2669d4da65031d48a595c73f8de5353f047 on togeojson into 059ebf909b6b14b0f1dd38fb3c75a81d4d4fef5b on master.