Zebra: Revise Zebra's logging and metrics based on a consistent design

[teor2345]

Is your feature request related to a problem? Please describe.

Zebra's log levels, spans, fields, and metrics have been added over time. They sometimes log duplicate data, or they're missing important data.

Goals

We should revise the content and levels of log messages so the default logs provide a good experience for users and occasional developers. These users should be able to see Zebra's progress, understand errors, and provide useful bug reports by copying and pasting recent log messages.

The default logs should be limited, so that they don't fill up disks, hide important messages, or confuse users.

We should also provide debug and trace logs, so that experienced developers can diagnose issues with Zebra.

Metrics should help developers monitor Zebra's progress, and diagnose issues. We could also document some important metrics in our metrics documentation.

Common metrics should be named and specified in an implementation-agnostic way, so that Zebra and zcashd logs can be analysed and viewed by the same tools.

Metrics should be named consistently. We could use:

• the Prometheus style guide
• these naming recommendations for Prometheus
• the zcashd metrics names: PR #1900 (ticket #1746) and https://github.com/zcash/zcash/pull/4947

Describe the solution you'd like

Create logging/metrics principles and designs for Zebra.
Revise the existing Zebra logs and metrics to fit this design.

Describe alternatives you've considered

Continue to add logs without an overall framework. This could work, but it leads to inconsistencies and gaps.

Related Tickets

Time-based log suppression in #1405, based on ticket #695

[str4d]

It would also be nice if the general metrics were named and specified in a consistent impl-agnostic way; this would enable the same GUI to easily render metrics from both zebrad and zcashd.

[teor2345]

It would also be nice if the general metrics were named and specified in a consistent impl-agnostic way; this would enable the same GUI to easily render metrics from both zebrad and zcashd.

I've added this to the goals

[daira]

Seems like the best way to keep metric names in sync would be to write a ZIP about it.

[hdevalence]

I don't think that common metrics between Zebra and zcashd is a desirable goal. Metrics are coupled to the design of the software, and those two nodes have radically different internal structures. I also don't think that it's a good idea to provide any kind of stability promise about Zebra's metrics, because that stability promise would ossify the internal structure that those metrics record. So, I think that writing a ZIP about this would be a bad idea.

Another point to note is that Zebra doesn't have logging, it has tracing. This might seem like just a difference of terminology, but it is more fundamental than that (see here for more details). Zebra does not emit logs, it emits a set of structured execution traces, and, as a side effect, renders a formatted version of those execution traces to the console. But, as execution traces, these spans are closely coupled to our implementation structure, and are unstable for the same reason as above.

[str4d]

I was not referring to the traces (though note that zcashd has these as well now). I was only referring to general metrics that are (for the most part) independent of implementation structure (such as block heights, time-to-validate histograms, current peer counts, etc).

[teor2345]

I think it's fine to have a naming standard that says something like:
"if you have this common metric, we recommend you give it this name"
... as long as there is no requirement to have any particular metric, and sufficient flexibility in the definition of each metric.

But I'm not sure how many common metrics we'd actually end up with.

For example, Zebra doesn't really have a concept of a per-block time-to-validate. We don't attach any times to blocks right now. We could measure the download time, parse time, context-free verification time, or contextual verification time. But I don't know how we would add them together into a single metric - or match them up to zcashd's concept of verification time.

Zebra currently has block height and peer count metrics. But unlike zcashd, Zebra doesn't download headers separately from blocks. And even if we start downloading headers separately, we don't have plans for downloading a chain of headers in advance of their blocks.

So if it's a matter of renaming an existing metric, we could probably make that change. But if it involves writing a lot of extra code, I'm not sure if we'd have time to do it any time soon. And if it affects the structure of Zebra, it probably won't happen.

[str4d]

I grepped the zebrad codebase a while back for the metrics it defines, and this is the subset that I could see how to apply to zcashd:

• block.verified.block.height gauge
• block.verified.block.count counter
• sync.downloaded.block.count counter
• sync.verified.block.count counter
  
  
  
  • In zcashd's case these two are almost always in lockstep, as we validate blocks and update the chain inline when we finish receiving a new block from a peer.
  
  
• peer.inbound_messages counter
• peer.outbound_messages counter
• pool.num_peers gauge
• bytes.read counter
• bytes.written counter

So e.g. a clear candidate for more consistent / useful naming would be bytes.* (to something like net.bytes.*, assuming it remains a global counter across all peers). It might also make more sense for block.verified.* to be renamed to chain.verified.*.

As for new metrics for which there should be relatively easy agreement between zebrad and zcashd, here are some ideas:

• mempool.size.transactions gauge (number of transactions currently in the node's mempool)
• mempool.size.bytes gauge (sum of encoded tx sizes)
  
  
  
  • Maybe also mempool.usage.bytes if you want to track in-memory usage like zcashd does.
  
  
• peer.ping.time and peer.ping.wait histograms (see zcash-cli getpeerinfo and here for details)
  
  
  
  • It looks like zcashd only generates pings to fill this data on-demand via zcash-cli ping.
  
  
• pool.sprout.value gauge (tracking the amount of ZEC in the Sprout pool)
• pool.sapling.value gauge (tracking the amount of ZEC in the Sapling pool)
• pool.transparent.value gauge (tracking the amount of ZEC in the transparent pool)
  
  
  
  • Maybe these are named .total_value instead?
  
  
• pool.transparent.utxos gauge (current size of the UTXO set)

[daira]

Also the total numbers of commitments and nullifiers for Sprout and Sapling.

[str4d]

Also relevant: the metrics crate transforms metrics labels into the Prometheus format by replacing . with _, so we may want to look at the Prometheus naming style-guide for suggestions on renaming. For example:

• net.read.bytes_total
• pool.sapling.value.zatoshis_total
  
  
  
  • The .total / _total suffix should only be used with accumulating counters (and has specific meaning in Prometheus); this would be a gauge.
  
  

[teor2345]

we may want to look at the Prometheus naming style-guide for suggestions on renaming

I've added "consistent names" to the goals.

[str4d]

We also need to be careful to not use .total (aside from accumulating counters), .sum, .count, or .bucket suffixes (or their _* variants), as these have special meaning in Prometheus.

[str4d]

Ethereum has an EIP collecting common Prometheus metric names, to help node operators monitor clusters of heterogeneous nodes: https://eips.ethereum.org/EIPS/eip-2159