Review utility of logging output

[chelseakomlo]

This is a task to review the current logging output and come up with a plan for better logging output if required.

We should review, for example:

• Whether different log levels are currently used/supported
• Whether logging output clearly indicates where in the code certain log lines are from
• Whether different log lines output identical messages (this is bad because then it is hard to determine which caused their output)

[gtank]

During initial sync, the default log output is not very useful:

2019-08-21 13:46:13 UTC INFO sync Processed 31 blocks in 60.00 seconds (0.52 blk/s).    Peers: 10 (act: 0, idl: 10, bad: 0).    Chain: [sch:4160 > req:0 > vfy:1780 > db:29980]
2019-08-21 13:47:13 UTC INFO sync Processed 32 blocks in 60.00 seconds (0.53 blk/s).    Peers: 10 (act: 0, idl: 10, bad: 0).    Chain: [sch:4160 > req:0 > vfy:1748 > db:30012]
2019-08-21 13:48:13 UTC INFO sync Processed 26 blocks in 60.00 seconds (0.43 blk/s).    Peers: 10 (act: 0, idl: 10, bad: 0).    Chain: [sch:4160 > req:0 > vfy:1722 > db:30038]
2019-08-21 13:49:13 UTC INFO sync Processed 35 blocks in 60.00 seconds (0.58 blk/s).    Peers: 10 (act: 0, idl: 10, bad: 0).    Chain: [sch:4160 > req:0 > vfy:1687 > db:30073]
2019-08-21 13:50:13 UTC INFO sync Processed 36 blocks in 60.00 seconds (0.60 blk/s).    Peers: 10 (act: 0, idl: 10, bad: 0).    Chain: [sch:4160 > req:0 > vfy:1651 > db:30109]
2019-08-21 13:51:13 UTC INFO sync Processed 26 blocks in 60.00 seconds (0.43 blk/s).    Peers: 10 (act: 0, idl: 10, bad: 0).    Chain: [sch:4160 > req:0 > vfy:1625 > db:30135]
2019-08-21 13:52:13 UTC INFO sync Processed 18 blocks in 60.00 seconds (0.30 blk/s).    Peers: 10 (act: 0, idl: 10, bad: 0).    Chain: [sch:4160 > req:0 > vfy:1607 > db:30153]
2019-08-21 13:53:13 UTC INFO sync Processed 16 blocks in 60.00 seconds (0.27 blk/s).    Peers: 10 (act: 0, idl: 10, bad: 0).    Chain: [sch:4160 > req:0 > vfy:1591 > db:30169]
2019-08-21 13:54:13 UTC INFO sync Processed 22 blocks in 60.00 seconds (0.37 blk/s).    Peers: 10 (act: 0, idl: 10, bad: 0).    Chain: [sch:4160 > req:0 > vfy:1569 > db:30191]
2019-08-21 13:55:13 UTC INFO sync Processed 28 blocks in 60.01 seconds (0.47 blk/s).    Peers: 10 (act: 0, idl: 10, bad: 0).    Chain: [sch:4160 > req:0 > vfy:1541 > db:30219]
2019-08-21 13:56:13 UTC INFO sync Processed 12 blocks in 60.00 seconds (0.20 blk/s).    Peers: 10 (act: 0, idl: 10, bad: 0).    Chain: [sch:4160 > req:0 > vfy:1529 > db:30231]
2019-08-21 13:57:13 UTC INFO sync Processed 38 blocks in 60.00 seconds (0.63 blk/s).    Peers: 10 (act: 0, idl: 10, bad: 0).    Chain: [sch:4160 > req:0 > vfy:1491 > db:30269]

The log level seems to be set at INFO, but it isn't obviously configurable. By contrast, zcashd has a curses-style interface that tells you how far through the process you are and what's going on, while streaming output like this to a secondary debug.log file.

[hdevalence]

Dropping the logging module we have now and replacing it with tracing solves the configurable-log-level problem for free.

[gtank]

Logging is configurable via environment variable, like so. Full details in the README.

RUST_LOG=sync=trace,p2p=trace,verification=trace,db=trace ./target/release/zebra

Trace-level logs are chatty but actually look pretty useful. That said there are clearly gaps. For instance, failure to bind to a default port (because it's already occupied by a zcashd) shows up as

$ RUST_LOG=sync=trace,p2p=trace,verification=trace,db=trace ./target/release/zebrad --testnet --jsonrpc-port 8080 -d ~/.zebra-testnet 2>&1 | tee -a testnet-trace.log                                                          
2019-08-29 14:50:45 UTC TRACE db canonize BestBlock { number: 0, hash: 05a60a92d99d85997cce3b87616c089f6124d7342af37106edc76126334a2c38 }                                                                                                              
Failed to start p2p module

Which really could be more helpful. The logging still does not indicate where it comes from even at the trace level.