Implementation of TraceKVStore

[alexanderbez]

Changes

• Implemented TraceKVStore
• Cleaned up some godocs (mostly server, stores and baseapp)
• Cleaned up structure in server constructors
• Added a CLI flag for KVStore tracing output (such a flag dictates tracing is desired opposed to needing two separate flags)
• Updated <root/cache>MultStore to support store tracing

TODO

• How to write the actual keys/values? Right now they're stringified (@cwgoes)
• Use TraceKVStore "under" a CacheKVStore, otherwise, all operations are traced regardless if they're in the cache or not (this will severely bloat up the trace log).
• Rebase onto latest develop

---

• Updated all relevant documentation in docs
• Updated all code comments where relevant
• Wrote tests
• Updated CHANGELOG.md
• Updated Gaia/Examples
• Squashed all commits, uses message "Merge pull request #XYZ: [title]" (coding standards)
• Added appropriate labels to PR (ex. wip, ready-for-review, docs)

closes: #1523

[cwgoes]

I think we want to log block height, not timestamp.

[alexanderbez]

@cwgoes suggestions about how to go about doing this? Do we need to pass/use the context?

[cwgoes]

See PR review below.

[cwgoes]

We want to log operations conducted through iterators too; probably need a TraceKVStoreIterator wrapper, see gasIterator in store/gaskvstore.go which is comparable.

[cwgoes]

Does this fail sometimes? Might be better to panic.

[alexanderbez]

Mhmmm, I thought about that. It should never panic really. Do we really wanna panic on a failure to trace some operation? It would make debugging tricky maybe, but idk if it warrants a panic.

[cwgoes]

I think we should; better than to fail silently (maybe the machine ran out of RAM? Hard to imagine a case when this would panic). This is an opt-in setting anyways; most users won't use a TraceKVStore.

[alexanderbez]

Fair point 👍

[cwgoes]

Deleting and writing nil are not the same operation; I think we should track a deleteOp here.

[cwgoes]

Thanks - see comments; most importantly, I think we want trace store logs which are:

• Identical across machines (no timestamps)
• Useful for finding transactions (so the block height and if possible the transaction hash and Msg index should be included in the logs, or BeginBlock / EndBlock for store operations within one of those functions)

Including all this metadata probably requires hooking the TraceKVStore into sdk.Context in a way such that ctx.KVStore can set the appropriate fields on the TraceKVStore when called - does that seem reasonable?

[cwgoes]

Re: how to write keys/values: probably base64 (should be default in JSON if you encode bytes), I'd expect just converting to string would produce a bunch of unusual characters. Means we have to convert to base64 before searching but that's probably unavoidable.

[codecov]

Codecov Report

Merging #1599 into master will decrease coverage by 0.41%.
The diff coverage is 34.75%.

@@            Coverage Diff             @@
##           master    #1599      +/-   ##
==========================================
- Coverage   63.62%   63.21%   -0.42%     
==========================================
  Files         122      123       +1     
  Lines        6804     6918     +114     
==========================================
+ Hits         4329     4373      +44     
- Misses       2229     2295      +66     
- Partials      246      250       +4

[alexanderbez]

Updated @cwgoes, please let me know your thoughts.

• Add table-driven unit tests
• Wrapped TraceKVStore behind a cache wrapper
• Added block height to trace context via BeginBlock. I tried other means, but ran into troubles, although I'm sure it's possible.
• Added native support for iteration in TraceKVStore -- operations are traced on each Next call.

If you also have an inclination into how to introduce TX hashes and message indexes, please let me know.

[cwgoes]

Mostly LGTM; commented about TX hash inclusion.

[cwgoes]

Hmm, I don't think this implementation is quite what we want - if I create an iterator, read one key, and never call .Next(), we won't log any operations - perhaps instead log key and value the first time .Key() is called, and reset a boolean on .Next()?

[cwgoes]

To add transaction hashes, add TxHash to sdk.TraceContext and set it in runTx.

[alexanderbez]

@cwgoes Updated to include TX hashes. I changed to the context stuff to be a map so it can be more flexible. I also updated the tracing to trace individual key/value calls.

re: TX hashes. Probably warrants creating a separate issue for this, but can we update the sdk.Tx interface to also include?:

type Tx struct {
    // ...
    Hash sdk.Hash // sdk.Hash should implement marshaling, Stringer, etc...
}

[cwgoes]

re: TX hashes. Probably warrants creating a separate issue for this, but can we update the sdk.Tx interface to also include?:

Maybe; if we aren't logging it I'm not sure we need/want to compute the hash, but worth discussing (as a separate issue from this PR).

[cwgoes]

Can this just be Metadata (type aliased) - any reason for a wrapper struct?

[alexanderbez]

Not anymore since I changed it to a map, so we can use a type alias.

[cwgoes]

Update comment to indicate that the metadata will be merged by-key.

[cwgoes]

One minor suggestion - also, can we add a usage example in docs/ somewhere (in the how-to-run-gaiad section)?

[alexanderbez]

@cwgoes Updated to use type alias and added examples (including a jq example) to docs/clients/node.md

[cwgoes]

Tested ACK

Here's a brief Python script to pretty-print logs:

#!/usr/bin/env python2.7

from __future__ import print_function
import sys, json, base64, termcolor

cprint = termcolor.cprint
alpha = 'abcdefghijlmnopqrstuvwxyz'
alpha += alpha.upper()

def is_alpha(string):
    return all(char in alpha for char in string)

while 1:
    line = json.loads(sys.stdin.readline()[:-1])
    op = line['operation']
    key = line['key']
    key_decode = base64.b64decode(line['key'])
    if is_alpha(key_decode):
        key = key_decode
    value = line['value']
    cprint(op, 'cyan', end = '')
    print(' ', end = '')
    cprint(key, 'red', end = '')
    print(' => ', end = '')
    cprint(value, 'green', end = '')
    print('')

Usage: gaiad start --trace-store trace.log, tail -f trace.log | ./pretty.py

[jbibla]

all looks well on the markdown front. not sure if we need to reference tendermint for running a full node but also know that that was not @alexanderbez 's contribution.

👍👍👍