h1 async log
- 2019-06-29

Today we’d like to introduce async-log, a general-purpose crate that extends the standard log crate with asynchronous metadata. This is a first step in introducing full-fledged asynchronous tracing capabilities to Rust.

What is asynchronous 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 utilizing 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 does this work?

async-log provides two extensions to the standard log crate: a span! macro, and a log::Log wrapper.

The span! macro creates a pair of log points. One at the start of the scope, and one at the end of the scope. The macro works with sync and async alike:

use runtime::time::Delay;
use async_log::span;

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

    span!("level II", {
        let y = "boop";
        Delay::new(Duration::from_secs(3)).await; // wait for 3 secs
        info!("another nice value, y={}", y);
    })
})

The Log implementation extends all existing log macros with asynchronous information. This means that no existing call to log need to be changed, all that’s needed is to wrap an existing logger (such as env-logger) you’re using in async-log to add async logging capabilities.

Wrapping an existing logger is relatively straightforward:

// Setup env_logger
let logger = env_logger::Builder::new()
    .filter(None, log::LevelFilter::Trace)
    .build();

// Add async logging capabilities
async_log::Logger::wrap(logger, || /*get the task id here*/ 0)
    .start(log::LevelFilter::Trace)?;

Currently we insert key=value string literals into the log string. But once key-value logging stabilizes, we’ll switch to support that natively. This is similar to how slog intends to switch.

How are spans built?

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

async-log itself does not specify a logging format, it only provides the ascriptions required to build asynchronous loggers. However when async-log is instantiated, and none of metadata is consumed, a typical log will look like this:

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

Annotating functions

One of the most common actions performed with async logging is to annotate specific functions. For example there might be a method that calls to a database, and you’d like to instrument. Or a method that locks a file for exclusive access.

For this reason we provide a convenient #[instrument] macro that allows instrumenting calls to functions. All that’s required is adding the attribute to the top of the method, and its internals will be wrapped in a span!, the file name, method name, and arguments will be logged:

#[async_log::instrument]
fn inner(y: &str) {
    info!("another nice value, y={}", y);
}

inner("boop");

examples/trace.rs#inner, arg_0=boop, span_mark=start, task_id=0, thread_id=1
examples/trace.rs#inner, span_mark=end, task_id=0, thread_id=1

What about distributed tracing?

We’ve been thinking hard about distributed tracing. The reality is that there are no silver bullets, and while specifications are being worked on, implementations are unfortunately still mostly vendor specific.

However, async-log is designed as a foundational building piece for distributed tracing. All information needed to trace individual functions can be extracted from the log::Log provider.

If you’re an APM vendor that would like to provide a transport for Rust and is interested the work we’re doing, we’d love to hear how we can help you succeed!

What’s next?

The rustasync organization is mostly interested in providing standards based approaches. But also likes to experiment with novel approaches to make Rust, and in turn technology in general, more accessible for a wider range of people.

Some of the areas we’re looking to explore include creating flame graphs from log data (we’re almost there!) and hooking into tracing protocols. In particular Google’s Perfetto and chrome://tracing seem of interest. We also have some other ideas we for visualization experiments, so stay tuned for more in the future!

Like we said ealier, async-trace is but a building block of a wider tracing story. There is much work to be done to provide varying transports, standards, and integrations. If this sounds interesting to you, come join us during our weekly, open meetings.

Conclusion

In this post we introduce the async-log crate which extends the standard log crate with asynchronous tracing functionality. The crate introduces a new span! macro to create pairs of log points, and annotates each log call with a task id to provide asynchronous tracing.

We’re particularly excited for this crate because it’s a working example of a possible extension to log that would make it work in asynchronous contexts, without a need to update any of the existing calls to the log macros. In addition we think the instrument! attribute will make it very convenient for people to trace their functions using spans.

We hope you enjoy async-log. You can check out the project on crates.io, docs.rs and github. Thanks for reading, and have a great weekend!

Thanks to Stjepan Glavina, Alex Crichton, and Ferrous Systems for the input and refinement of async-log.

h1 async log - 2019-06-29