Tracing

[pwojcikdev]

The goal of this PR is to introduce a framework for tracing events in the node. This is meant to be used for debugging and profiling purposes, eg. by visualizing the flow of votes through the network or analyzing the delay between receiving a block and confirming it.

This is accomplished by introducing a nano::object_stream class that can be used to serialize objects. It is meant to be a relatively thin wrapper around the underlying stream, that ensures the output format is structured and consistent. It avoids allocations and unnecessary run-time dispatching by using a compile-time visitor pattern.

This interface also allows to switch between different output formats and automatically handles some common functionality, like providing operator<<, to_string() and to_json(). If in the future a better serialization library is found, it should be possible to easily replace the underlying implementation without changing the interface.

Usage

To use tracing, it must be enabled at compile time by passing -DNANO_TRACING=ON flag to CMake. By default, it is disabled for release builds and enabled for debug builds.

After that, tracing can be enabled by setting the logging verbosity level to trace. (NANO_LOG=trace)

Since the amount of logs when setting logging level to trace is very large, it is recommended to use trace level only for specific components. This can be done by setting NANO_LOG_LEVELS environment variable to a comma-separated list of components to trace. For example, to trace only active_transactions and vote_processor, set NANO_LOG_LEVELS="active_transactions=trace,vote_processor=trace". Alternatively this can also be done by modifying the config-log.toml file.

Tracing Formats

It is possible to specify format of tracing output at runtime. This is done by setting NANO_TRACE_FORMAT environment variable to one of the following: standard or json.

Standard

Standard tracing format is enabled by default. It is a simple key: { value } format with indentation that should be easy to read.
Sample output:

[2024-01-30 17:04:19.001] [active_transactions::active_stopped] [trace] event: "active_transactions::active_stopped",
time: 1706630658999596,
election: {
   id: "0x10b0171e68aac183",
   qualified_root: "AA97A292E1F8B84B2F95F03CE54DE97F8E7ACF9B3CFE6408A58CD859E89BAFBBAA97A292E1F8B84B2F95F03CE54DE97F8E7ACF9B3CFE6408A58CD859E89BAFBB",
   behaviour: "normal",
   height: 1027,
   status: {
      winner: "2F5FE06EA686B46AEDF807FE1BB87AA87650EC2B9FBD6EE45BE0E248CF6DFC01",
      tally_amount: "63604200648126004984521699083584821166",
      final_tally_amount: "63604200648126004984521699083584821166",
      confirmation_request_count: 1,
      block_count: 1,
      voter_count: 46,
      type: "active_confirmed_quorum",
      votes: [
         {
            account: "nano_37imps4zk1dfahkqweqa91xpysacb7scqxf3jqhktepeofcxqnpx531b3mnt",
            hash: "2F5FE06EA686B46AEDF807FE1BB87AA87650EC2B9FBD6EE45BE0E248CF6DFC01",
            final: true,
            timestamp: 18446744073709551615,
            time: 9747922583882
         }
      ],
      blocks: [
         {
            type: "state",
            hash: "2F5FE06EA686B46AEDF807FE1BB87AA87650EC2B9FBD6EE45BE0E248CF6DFC01",
            sideband: {
               successor: "F397C6B0B4DA7F78A371A7C1104FC09CF9026DBDC1F1362DCC8FF79A34397074",
               account: "0000000000000000000000000000000000000000000000000000000000000000",
               balance: "00000000000000000000000000000000",
               height: 1027,
               timestamp: 1706630658,
               source_epoch: "epoch_begin",
               details: {
                  epoch: "epoch_2",
                  is_send: true,
                  is_receive: false,
                  is_epoch: false
               }
            },
            account: "000F4E4E400F69BE1CE68B685380CF8D07C46CE2E75A1C1DB36CBC06A129EA49",
            previous: "AA97A292E1F8B84B2F95F03CE54DE97F8E7ACF9B3CFE6408A58CD859E89BAFBB",
            representative: "897F7EE0A29F631912ABB513FAC371FC82B319DA76D665149E70C8263FEF802E",
            balance: "0000000000000000000000000001869E",
            link: "000F4E4E400F69BE1CE68B685380CF8D07C46CE2E75A1C1DB36CBC06A129EA49",
            signature: "6017882E2970085AC44BE3CA3B9424D6093A8266CC04012114B718ACE6D688E183EDEE89D10F8D2072E9DB27111E5D3FFCA7DC786A45C1CB25470BCEBE75790A",
            work: 13187085369013726348
         }
      ],
      tally: [
         {
            hash: "2F5FE06EA686B46AEDF807FE1BB87AA87650EC2B9FBD6EE45BE0E248CF6DFC01",
            amount: "63604200648126004984521699083584821166"
         }
      ]
   }
}

JSON

JSON tracing format is meant to be parsed by external tools. There is no indentation or newlines, so each log output line can be treated as a separate event, which simplifies parsing.
Sample output:

[2024-01-30 17:56:53.312] [vote_processor::vote_processed] [trace] "event":"vote_processor::vote_processed","time":1706633813312751,"vote":{"account":"FD16B0FE0102F68C2D9482348AE7211E3CBF86681364E53D8793A5E551167A6C","final":true,"timestamp":18446744073709551615,"hashes":["7DEF4D1F5EB222BC5DE2123293EE5A8CE58E283176AB65DF3373DA009FD99E86"]},"result":"indeterminate"

[dsiganos]

To achieve more compression of data, we could remove the dropped field when it is set to false.
So, a missing dropped would mean that the message was not dropped.

[pwojcikdev]

Some tools that automatically detect data format (eg. Apache Drill, but likely others too) might have problems with format that is inconsistent. I believe in case of Drill it infers schema from first ~60k entries. Looking at this now, this function flow should be refactored, so that it has a single point at which data is logged.