Improve keylist FS log output

[runesl]

After keylist comparision, a log line is made logging the number of missing objects among other things: https://github.com/basho/riak_repl/blob/develop/src/riak_repl_fullsync_helper.erl#L186

DiffState#diff_state.missing is incremented in the missing_key function:
https://github.com/basho/riak_repl/blob/develop/src/riak_repl_fullsync_helper.erl#L382

The problem is, that DiffState#diff_state.missing includes semantically different missing objects:

1. Missing object with data.
2. Missing object is a tombstone that should be kept.
3. Missing object is a tombstone that should have been purged, because it is older than delete_mode millis, but wasn't.

It would be extremely useful if these 3 were logged independently, because then FS log output could be used to verify that RT was working as it should. Currently, we're seeing some 100k missing on every FS, which are (hopefully!) tombstones - but we can't actually know if our two clusters are in sync data-wise, because we can't see if the missing objects are data-carrying or just tombstones purged on one side but not on the other.

[bsparrow435]

Rune,

Fullsync is a point in time sync which makes it an unreliable way to check if realtime is functioning correctly. I agree that breaking out the differences into more specific stats would be useful but not for the reason of validating realtime. The fullsync has no way of checking if writes are currently in the realtime queue or if we're fixing only one replica on the sink, etc. We have stats such as dropped, overload_dropped and rt_dirty that indicate whether objects have been dropped by the realtime queue. Further, if the riak_repl postcommit hook fails we increment a postcommit_failed stat. These cover all cases where a successful write will not be propagated and these are the stats that should be used to determine correct realtime operation.

Again, I agree that breaking the fullsync stats out can be helpful though I disagree with using these stats to determine correct operation of realtime. I've marked this request as a feature request and we'll discuss where it fits into out development timetable and set an appropriate milestone.

[runesl]

Thanks for taking action Brian. Yes, it's a feature request.

I'm not convinced that your list of potential RT failure causes is definitive. I think there are other ways for RT to not propagate correctly, which are not detectable, such as vnode_overload, which induces almost arbitrary message loss (also to stats) or simple restarts - as well as bugs or hardware failures, which we don't know of yet.

In my experience, having a different code base re-check the correctness of data is a very valuable assurance that the entire live transactional system works as expected - including but not limited to the FS code.

I'm aware of the timing issues when running a bulk job (FS) in a live system (RT). I usually estimate the number of in-transit objects, so I know roughly what to expect FS to report from "missing" and "differences" pr. partition. But FMK's "missing" is consistently 3-4 orders higher than the expected number. Only if this feature request makes it, will we know, whether this oddity is due to old tombstones or if the consistency of our customer's critical data is actually reduced for some reason that we should research into.

[bsparrow435]

vnode_overload will not cause a write to not propagate on realtime. That could cause a single replica to be dropped but if more than 1 vnode in a preflist are overloaded the write will fail(assuming default quorem). The postcommit hook is run on the coordinating vnode, which would immediately fail the write if it was in overload state. So, if a write succeeded, the post commit is succesful, and the object is not dropped from the queue it should be making it over.

Thanks for all the shared information thus far, we'll update this issue as our product management team discusses release timelines.