Skip to content
Async tracing capabilities for the log crate
Branch: master
Clone or download
yoshuawuyts Update changelog
Signed-off-by: Yoshua Wuyts <yoshuawuyts@gmail.com>
Latest commit 6552030 Jul 9, 2019
Permalink
Type Name Latest commit message Commit time
Failed to load latest commit information.
.github . Jun 8, 2019
async-log-attributes Named arguments (#1) Jul 9, 2019
examples Named arguments (#1) Jul 9, 2019
src fix clippy warnings (#2) Jul 9, 2019
tests . Jun 8, 2019
.gitignore . Jun 8, 2019
.travis.yml . Jun 8, 2019
CHANGELOG.md Update changelog Jul 9, 2019
Cargo.toml (cargo-release) version 1.1.0 Jul 9, 2019
LICENSE-APACHE . Jun 8, 2019
LICENSE-MIT . Jun 8, 2019
README.md cleanup base use Jun 28, 2019

README.md

async-log

crates.io version build status downloads docs.rs docs

Async tracing capabilities for the standard log crate.

This crate provides extension types and hooks to log to enable asynchronous logging.

What is Async Logging?

When building a synchronous application, log messages can be relied on to always happen in sequence. But unfortunately synchronous applications are rarely capable of utilizating system resources to their full potential.

In contrast, concurrent applications make a lot better use of system resources. But it also means we can no longer rely on log messages to strictly happen in sequence. In order to make sense of logs in asynchronous applications, we need to be able to correlate sequences of events with each other:

a1 -> b1 -> b2 -> a2 -> b3     # raw log stream

a1 -------------> a2           # parsed log stream a
      b1 -> b2 -------> b3     # parsed log stream b

The raw log stream contains items for both "a" and "b". With async logging you want to be able to distinguish between the items for "a", and the items from "b".

How do we correlate messages?

The goal of async logging is to determine which events happened in sequence inside your code. In practice this means being able to correlate events with each other past yield points (e.g. .await), and thread bounds.

The way we do this is by adding the current task ID, and thread ID from where the log is occurring. An whenever a new task is spawned we log the following values:

  • The ID of the task from which the new task is spawned (task_parent_id)
  • The ID of the new task that's spawned (task_id)
  • The current thread ID (thread_id)
  • The line from where the task was spawned (spawn_line, when RUST_BACKTRACE=1 enabled)

With all this information we have all the information to correlate tasks with each other. We know what the parent task was, what the new task is, and log that information together. On the receiving side we can then reconstruct that to create correlations.

What is a span?

A span is a pair of messages. One is emitted at the start of an operation, and the other is emitted at the end of the operation. If we add timestamps to when each message was sent, we're able to determine how long operations take. Or determine which operations never finished.

In async-log each span is annotated with a span_mark message:

  • span_mark=start marks the start of a span
  • span_mark=end marks the end of a span

example

runtime::fs::read_to_string, span_mark=start, path=/tmp/foob, task_id=7, thread_id=8
runtime::fs::read_to_string, span_mark=end, path=/tmp/foob, task_id=7, thread_id=8

Why build on the log crate?

log is Rust's standard log crate. It's incredibly flexible, and was built with extensibility in mind. Because it's so widely used, being able to extend it allows us to add tracing data to crates without needing to make any changes to their log! calls.

Formatting

Structured logging (key-value logging) is currently in the process of being added to log.

At the time of writing there are no published versions available with even the experimental features available. So until then we have to add key-value pairs using strings. Once key-value logging is added to log we'll publish a breaking change, and move over.

The syntax we've chosen to use is foo=bar pairs. Multiple pairs should be delimited using commas (,). Every pair should come after the first message. An example log looks like this:

a new cat has logged on, name=nori, snacks=always

Examples

use async_log::span;
use log::info;

fn setup_logger() {
    let logger = env_logger::Builder::new()
        .filter(None, log::LevelFilter::Trace)
        .build();

    async_log::Logger::wrap(logger, || 12)
        .start(log::LevelFilter::Trace)
        .unwrap();
}

fn main() {
    setup_logger();

    span!("level I", {
        let x = "beep";
        info!("look at this value, x={}", x);

        span!("level II", {
            let y = "boop";
            info!("another nice value, y={}", y);
        })
    })
}

Installation

$ cargo add async-log

Safety

This crate uses #![deny(unsafe_code)] to ensure everything is implemented in 100% Safe Rust.

Contributing

Want to join us? Check out our "Contributing" guide and take a look at some of these issues:

References

License

MIT OR Apache-2.0

You can’t perform that action at this time.