Traceon - trace on json

A simple log and trace formatter with a structured json output, it flattens events from nested spans and simply overwrites the parent if required.

The tracing library is difficult to understand initially, this crate is designed to be as easy to use as possible with sensible defaults and configuration options. It should only be used from a binary, don't use in libray code as it sets the default subscriber which could cause conflicts for users.

The only two crates you'll need in your Cargo.toml are:

[dependencies]
tracing = "0.1"
traceon = "0.1"

For pretty printing the output like the examples below, install jq and run commands like:

cargo run | jq -R 'fromjson?'

By default env-filter is used at the info level, there is a large amount of filter options available detailed here via an environment variable for example RUST_LOG=warn

This library uses code originated from: LukeMathWalker/tracing-bunyan-formatter which is great for bunyan formatting

Examples

Simple

There are some useful fields included by default that can be turned off:

fn main() {
    traceon::on();
    tracing::info!("a simple message");
}

{
  "message": "a simple message",
  "level": 30,
  "time": "2022-12-27T10:16:24.570889Z",
  "file": "src/main.rs:14"
}

Log levels are converted to numbers by default:

trace: 10
debug: 20
info:  30
warn:  40
error: 50

#[instrument] macro

If you're using normal functions or async, you can use the tracing::instrument macro to capture the paremeters for each function call:

#[tracing::instrument]
async fn add(a: i32, b: i32) {
    tracing::info!("result: {}", a + b);
}

#[tokio::main]
async fn main() {
    traceon::on();
    add(5, 10).await;
}

{
  "message": "result: 15",
  "level": 30,
  "time": "2022-12-27T10:48:56.957671Z",
  "span": "add",
  "file": "src/main.rs:3",
  "a": 5,
  "b": 10
}

Instrument trait

If you need to add some additional context to an async function, e.g. compile time captured env vars, you can create a span and instrument the async function:

use tracing::Instrument;

async fn add(a: i32, b: i32) {
    tracing::info!("result: {}", a + b);
}

#[tokio::main]
async fn main() {
    traceon::on();
    let span = tracing::info_span!("math functions", package_name = env!("CARGO_PKG_NAME"));
    add(5, 10).instrument(span).await;
}

{
  "message": "result: 15",
  "level": 30,
  "time": "2022-12-27T11:11:25.540256Z",
  "span": "math functions",
  "file": "src/main.rs:4",
  "package_name": "testing_traceon"
}

The above package_name comes from the Cargo.toml:

[package]
name = "testing_traceon"

It's captured at compile time, and baked into the binary, which is useful as cargo environment variables are lost at runtime.

IMPORTANT! for async functions only ever use the above two methods, which are the #[instrument] macro, and Instrument trait. The guard detailed below should not be used across async boundaries.

Instrument trait and entered span

To combine the output from the two examples above we can enter a span with the arguments added to the trace:

use tracing::Instrument;

async fn add(a: i32, b: i32) {
    // Important! Don't put any `.await` calls in between `entered()` and `exit()`
    let span = tracing::info_span!("add", a, b).entered();
    tracing::info!("result: {}", a + b);
    span.exit();
}

#[tokio::main]
async fn main() {
    traceon::on();
    let span = tracing::info_span!("math functions", package_name = env!("CARGO_PKG_NAME"));
    add(5, 10).instrument(span).await;
}

{
  "message": "result: 15",
  "level": 30,
  "time": "2022-12-27T11:18:46.805758Z",
  "span": "add",
  "file": "src/main.rs:5",
  "b": 10,
  "package_name": "testing_traceon",
  "a": 5
}

You can see above that the span field was also overwritten with add

The add function from above could be rewritten like this:

async fn add(a: i32, b: i32) {
    let _span = tracing::info_span!("add", a, b).entered();
    tracing::info!("result: {}", a + b);
}

This will cause the span to exit at the end of the function when _span is dropped, just remember to be very careful not to put any .await points when an EnteredSpan like _span above is being held

Turn off fields

This is an example of changing all the defaults fields to their opposites:

use traceon::{Level, Traceon};

mod helpers {
    pub fn trace() {
        tracing::info!("in helpers module");
    }
}

#[tokio::main]
async fn main() {
    Traceon::new(std::io::stdout)
        .module(true)
        .span(false)
        .file(false)
        .time(false)
        .level(Level::Off)
        .on();

    tracing::info!("only the module and message");
    helpers::trace();
}

{
  "message": "only the module and message",
  "module": "bootstrap"
}
{
  "message": "in helpers module",
  "module": "bootstrap::helpers"
}

This was using a Cargo.toml with the binary renamed to bootstrap for demonstration purposes:

[[bin]]
name = "bootstrap"
path = "src/main.rs"