Changeset metadata intermittently fails to save to redis

[kriscarle]

I'm seeing a large number of "not found" messages for metadata that is missing from redis so it never gets joined and sent out. I've confirmed that planet stream is loading the changeset metadata file from OSM, but occasionally it fails to store an entire file's worth of changesets in redis.

I'm going to turn on DEBUG=* and see if I can get and details from the redis client logs.

I'm thinking it might happen if overpass also comes back at the same time. Here are the logs around a file that didn't save:

Fri Jun 10 2016 21:39:16 GMT+0000 (UTC)] INFO Polling OSM planet
[Fri Jun 10 2016 21:39:19 GMT+0000 (UTC)] INFO Retrieving http://planet.osm.org/replication/changesets/001/880/581.osm.gz from planet
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] INFO Polling Overpass
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] INFO Matching 24 members
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]7085924
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]7166210
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]13897298
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]21938396
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]22146408
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39591061
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39938357
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39941586
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39941739
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39942584
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39942654
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39942703
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39942704
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39942705
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39942706
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39942707
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39942708
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39942709
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39942710
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39942711
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39942712
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39942713
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39942714
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG [to match]39942715
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] INFO Polling OSM planet
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG 7085924 not found
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG 7166210 not found
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG 13897298 not found
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG 21938396 not found
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG 22146408 not found
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG 39591061 not found
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG 39938357 not found
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG 39941586 not found
[Fri Jun 10 2016 21:39:46 GMT+0000 (UTC)] DEBUG 39941739 not found

Here is an example of all the not found errors I'm seeing in AWS.

[kamicut]

Did you look into this further @kriscarle? I was thinking of moving the code in index.js to use some sort of redis based queue (like celery in python) rather than having us figure out all the edge cases. Any recommendations on that front?

[kriscarle]

@kamicut Haven't made any progress, been working on other stuff. My thought was the two calls to redis.pipline() at https://github.com/developmentseed/planet-stream/blob/master/lib/planetstream.js#L34 and https://github.com/developmentseed/planet-stream/blob/master/lib/planetstream.js#L47 could happen while the other one was still transmitting data to redis and that the pipeline() call cancels any ongoing transmissions. I haven't confirmed that though, just a theory.

When I saw this issue, I saw the metadata file arrive and then immediately after a diff file. The metadata was never processed, so it seems like the diff cancelled the metadata processing.

I tried creating different redis clients, but I haven't had time to confirm whether it fixed it https://github.com/loggingroads/planet-stream/blob/metadata_not_recorded/lib/planetstream.js#L18

We might need a test that simulates response times for a metadata and diff so we can schedule them to arrive at the same time.

My instinct would be to just use Postgres for this, mainly because I'm less familiar with Redis edge cases, but also because a more persistent data store might help with things like collecting historical data, and tracking down lost data? Each changeset gets a row in the table with changeset_id, metadata, elements, payload, etc. Then for things like OSM Stats that gives us the option of connecting to the database directly, instead of streaming. We can just do a transaction with "select changeset_id, payload from table where payload is not null and processed=false limit 1" then "update table set processed=true where changset_id=123". Not sure if this would have problems scaling? I think Postgres could handle it?

I would like to get OSM Stats running entirely on docker so I can run it on something like a $35/month Packet server instead of Amazon...

[kamicut]

@kriscarle I definitely echo your sentiment for looking at a dockerized version of osm-stats, we would need to find alternatives to kinesis and lambda workers. As for planet-stream, I started work on a branch using kue, a node.js task manager backed by redis. It has support for task retry, and delaying tasks. That could structure planet-stream's logging of missed syncs between the data and metadata.

Once it's at a good point, it would be great if you could take a look at it. I think it could solve this issue, or at the very least have better logs.

[kamicut]

The postgres DB is an interesting idea, and could definitely benefit if we're looking at historical processing. The original intention for planet-stream is to be a "live stream of OSM" and to get as close as possible to deliver stats to the leaderboards. I think a cron-job approach for backfilling and historical processing would then live outside of this repo, and be complementary for osm-stats.