All About Logs

Overview

This codebase uses the slog crate for structured logging. Use the info!, debug! etc macros. See existing usage for examples, and also the log macro documentation.

Structure of a log message

Here's what a typical log message might look like:

INFO [1685718425.067022] [testnet/stacks-node/src/main.rs:82] [main] stacks-node 0.1.0 (chore/logs:a93c2867d+, debug build, macos [aarch64])

Let's break down the components:

1. Log level: DEBG, INFO, WARN or ERRO (4 chars wide)
2. Timestamp: By default, this is the Unix time (basically, time since std::time::UNIX_EPOCH), in seconds and nanoseconds (6 degrees of precision). This can be changed using STACKS_LOG_FORMAT_TIME, see below for details.
3. Filename and line number: where the log message comes from in the source.
4. Thread identifier: A string that identifies the thread where the log message was generated. Most threads will have descriptive identifiers like main, chains-coordinator-0.0.0.0:20443, p2p-(0.0.0.0:20444,0.0.0.0:20443). Note that some of the thread identifiers include a host/port on which that thread might be listening on.
5. Log message: the actual contents of the log. This is where the "structured" part of slog comes in, among other things.

Tips and Tricks

Logging to stdout instead of stderr

The stacks-node binary output logs to stderr (vs. stdout). To easily capture / pipe / filter logs (e.g. using tools like tee), redirect stderr to stdout. In bash, this is accomplished with 2>&1, like so:

$ stacks-node start --config follower.toml 2>&1 | tee info-logs.txt`

Enabling debug logs

By default, the log level is set to INFO. To enable debug logging, set the environment variable STACKS_LOG_DEBUG=1.

$ STACKS_LOG_DEBUG=1 stacks-node start --config follower.toml 2>&1 | tee info-logs.txt`

To set the log-level to TRACE, set STACKS_LOG_TRACE=1 instead.

Output logs in JSON

First, you must compile stacks-node with the slog_json feature enabled, like so:

$ cargo build -F slog_json -p stacks-node --bin stacks-node

Once enabled, set the environment variable STACKS_LOG_JSON=1:

$ STACKS_LOG_JSON=1  stacks-node check-config --config follower.toml 2>&1 | jq .
{
  "msg": "stacks-node 0.1.0 (chore/logs:a93c2867d+, debug build, macos [aarch64])",
  "level": "INFO",
  "ts": "2023-06-02T16:54:04.377153Z",
  "thread": "main",
  "line": 82,
  "file": "testnet/stacks-node/src/main.rs"
}

Change timestamp format

Set the STACKS_LOG_FORMAT_TIME environment variable to change the default timestamp formatting. Any valid strftime is acceptable.

Here's an example:

$ STACKS_LOG_FORMAT_TIME="%F:%T" ./target/debug/stacks-node start --config follower.toml
# Note the timestamp format
INFO [2023-06-02:14:10:12] [testnet/stacks-node/src/main.rs:82] [main] stacks-node 0.1.0 (chore/logs:a93c2867d+, debug build, macos [aarch64])
INFO [2023-06-02:14:10:12] [testnet/stacks-node/src/main.rs:140] [main] Loading config at path follower.toml

Pretty-printed logs

Set the environment variable STACKS_LOG_PP=1 (PP for pretty-print) to enable pretty-printed logs. Note that this mode is not actively developed or tested, so YMMV. It uses a more human-readable timestamp format, colorized output etc. Here's a screenshot of what it looks like: