basho/riak_core — pull request #501 by buddhisthead (2014-01-06 18:37:37+00:00)
Title: Add logging and pretty printing of log file to background manager.

The background manager already contains functions to view the current set of locks and tokens, but lacks any historical view of how subsystems have interacted. It would be highly useful to examine past get_lock/get_token patterns in the event of performance problems around the participating subsystems that use the background manager, especially on nodes with extreme overload or crashed nodes.

This PR adds logging to disk, which will persist after a crashed node. All writes are done using Erlang's disk_log module and are asynchronous so that normal operations are not blocked by slow disk writes. Losing a little data from the disk_log cash is preferable to blocking a caller of the background manager.

Three logging levels are provided, with ```on``` being the default of the config variable ```background_manager_loglevel```:
* ```off``` - no logging is done
* ```on``` - logs only the get_lock, get_token, enable/disable, and bypass calls as events.
* ```debug``` - logs all operations

Logfile entries are in disk_log's "internal" format under ```riak_core_bg_manager/events.xxx``` in the data directory of each node. Writing is fast and the log files are repairable when read. The logs are ```wrap``` logs and thus will occupy a fixed maximum space on disk (and memory for the disk_log write buffer). The total size of the logs are controlled by ```background_manager_log_size``` application configuration variable, and default to 5 files of 1MB each, so the maximum disk space used is 5 MB, which should give days of logged events for postmortem analysis.

Testing was done using both the ```bg_manager_eqc.erl``` EQC test as a driver (find log files in /tmp/riak_core_bg_manager/events.xxx) , and with ```riak_test -t rtee replication2``` (find log files in devN/data/riak_core_bg_manager/events.xxx). After running the replication2 test, we see entries like the following:

```
6/Jan/2014:18:29:0 get_lock {vnode_lock, 685078892498860742907977265335757665463718379520} [{task, handoff}] ok
6/Jan/2014:18:29:0 get_lock {vnode_lock, 685078892498860742907977265335757665463718379520} [{task, repl_fullsync}] max_concurrency
6/Jan/2014:18:29:0 get_lock {vnode_lock, 68507889249886074290797726533575766546371837952} [{task, repl_fullsync}] ok
```