Prev post Next post Archive

Logging in Servoiardi

Introduction

Proper logging is something that I always leave far too late when writing a project. Having a solid solution for logging is invaluable in early development, and can save hours of debugging, and yet it's almost always one of the final finishing touches I make to a project. I've therefore decided that it's time to add it to Servoiardi, before I start adding the fun features.

Good quality logging is important for a web-server like Servoiardi, not just for development, but also for the end-users, who may want to log activity on their websites for debugging, security, or performance reasons. It is therefore important that Servoiardi has an extensible and flexible logging system.

Logging interface

For a logging interface, I decided to leverage the Log crate. This crate defines a simple log::Log trait, and other crates can implement this trait to provide various logging implementations. There are libraries for the console, systemd, logfiles, and so on.

Another advantage of using the Log crate is that other libraries can use the same logging macros to produce log messages that can be consumed by my logging system.

Logging to multiple loggers

Since I wanted to support logging to multiple dynamically installable loggers, I wrote a simple Demultiplexer struct to distribute log records to multiple loggers. While very simple, it should give you an idea what the log::Log trait looks like, and how it works.

#[derive(Default)]
pub struct Demultiplexer
{
    loggers: RwLock<Vec<Box<dyn log::Log>>>
}

impl log::Log for Demultiplexer
{
    fn enabled(&self, metadata: &log::Metadata<'_>) -> bool
    {
        self.loggers.read().unwrap().iter()
            .any(|logger| logger.enabled(metadata))
    }

    fn log(&self, record: &log::Record<'_>)
    {
        for logger in self.loggers.read().unwrap().iter()
        {
            logger.log(record);
        }
    }

    fn flush(&self)
    {
        for logger in self.loggers.read().unwrap().iter()
        {
            logger.flush();
        }
    }
}

impl Demultiplexer
{
    pub fn add_logger(&self, logger: Box<dyn log::Log>)
    {
        self.loggers.write().unwrap()
            .push(logger)
    }
}

For an application like Servoiardi, something of note is that the log::Log has no support for async loggers, and the log::Record<'_> structure does not outlive the call to the logger. This means that the logging records cannot be queued up for later, or sent to another thread for processing. Logging generally involves some kind of IO operation, and so in an async application like Servoiardi, potentially blocking logging IO operations have the potential to starve the async runtime.

The reasons why log::Log is designed like this are clear - to remove the lifetime on log records, one would either have to:

  1. Clone any data structures that might need to be formatted in the log message. This is a potentially expensive operation that may uselessly clone pieces of data that aren't even used in the log message. Or...
  2. Immediately format the log message text into a String or similar owned data structure. This means that the log message will always need to be memcpy'd to its final destination, rather than the current approach, where logged messages can be written in-place to types implementing the fmt::Write trait.

Both of these approaches might have performance impacts, and rely on unnecessary heap allocations, a potential problem on embedded hardware.

Moveover, it would be entirely possible to implement the second approach in a dedicated async logger that exports its records to another thread implementing the IO. This is something I might investigate doing in the future, especially as I plan on adding some custom loggers accessible through a special "debug" HTTP service type.

This might all be overthinking though. If a logger were to significantly block, on a modern non-embedded system, then it sounds like the logger is badly designed. So for now, I'm simply ignoring the ugly synchronous IO.

Annotating records with task-specific context

In a multi-threaded webserver like Servoiardi, multiple HTTP requests are serviced in parallel, and it can be impossible to make sense of log messages without a way to associate each message with a particular request.

Since we are using async Rust with Tokio, we need to deal with the fact that in addition to different threads handling different HTTP requests, a single thread may be servicing multiple HTTP requests in different tasks.

Luckily, Tokio provides the tokio::task::LocalKey struct and the tokio::task_local macro to help create them. These structs are analogous to std::thread::LocalKey, but provide access to tokio-task-local storage.

The API for the LocalKey type is a little odd. The .scope() method will run a future with the LocalKey set to a particular value. The .try_with() method meanwhile will pass reference to the value of the LocalKey to a callback, and return the result of the callback. The more intuitive .set() and .get() methods of std::thread::LocalKey are not mirrored for tokio::task::LocalKey.

I used this to write a simple module to store and retreive per-task logging context. The HTTP request future is simply passed to run(), along with an arbitrary ID:

pub struct Context
{
    request_id: usize,
    log_level:  RefCell<log::LevelFilter>
}

tokio::task_local! { static CURRENT_CONTEXT: Context }

impl Context
{
    fn new(request_id: usize) -> Self
    {
        Self { request_id, log_level: RefCell::new(log::max_level()) }
    }
}

pub fn run<F>(f: F, request_id: usize)
    -> tokio::task::futures::TaskLocalFuture<Context, F>
    where F: std::future::Future
{
    CURRENT_CONTEXT.scope(Context::new(request_id), f)
}

pub fn set_log_level(filter: log::LevelFilter)
{
    if CURRENT_CONTEXT.try_with(|ctx| ctx.log_level.replace(filter)).is_err()
    {
        error!("Called set_log_level with no context.");
    }
}

pub fn get_log_level() -> log::LevelFilter
{
    CURRENT_CONTEXT.try_with(|ctx| *ctx.log_level.borrow())
        .unwrap_or_else(|_| log::max_level())
}

pub fn get_request_id() -> Option<usize>
{
    CURRENT_CONTEXT.try_with(|ctx| ctx.request_id).ok()
}

I then implemented a simple Annotator<L> shim that can extend any existing logger with the following function:

pub fn log_annotated_record<'a>(
    log:    &impl log::Log,
    record: &log::Record<'_>,
    req_id: usize
)
{
    // Extract the key-value pairs of the record
    let mut kvs = KeyValueVisitor::default();
    record.key_values().visit(&mut kvs).unwrap();

    // Insert our new key-value pair
    kvs.0.insert(
        log::kv::Key::from("request_id"),
        log::kv::Value::from(req_id));

    log.log(
        &record.to_builder()
            .args(format_args!("[{}] {}", req_id, record.args()))
            .key_values(&kvs.0)
            .build()
    );
}

The log record is re-built with a "request_id" structural key, and the same ID included in the message itself. This annotated record can then be passed to any other logger.

Setting up the logging system

Once I had my logger compatible with log::Log, I needed to install it by calling log::set_logger(), which takes a &'static dyn log::Log. It may be more convenient to use log::set_boxed_logger() in many cases, but I needed to share a reference to my logger to allow me to implement add_logger().

I used a std::sync::Once struct to implement this. I could not use the finally stabilized OnceCell, as I needed to be able to create a 'static reference to the logger from inside the .call_once(|| {...}) callback, to pass to log::set_logger() which would not have been possible using OnceCell's .get_or_init(|| {...}) method, which would have to return the logger.

type Logger = Annotator<Demultiplexer>;

static LOGGER_ONCE: std::sync::Once = std::sync::Once::new();
static mut LOGGER:  Option<Logger> = None;

fn get_logger() -> &'static Logger
{
    LOGGER_ONCE.call_once(|| {
        let logger = unsafe { LOGGER.insert(Logger::default()) };
        log::set_logger(logger)
            .expect("Logger was already set!");
        log::set_max_level(log::LevelFilter::Trace);
    });
    unsafe { LOGGER.as_ref().unwrap() }
}

pub fn add_logger(log: impl log::Log + 'static + Sized + Send)
{
    get_logger().inner.add_logger(Box::new(log))
}

Once add_logger() is called, the logging system will be initialized, and the macros info!(), error!(), etc. will produce log messages.

Using the env_logger crate as a simple logging client

As a first logger, I chose to use the env_logger crate, not for any particularly strong reasons. I added some custom formatting to it, since I found the default style pretty unreadable.

fn format_console_log(
    buf:    &mut env_logger::fmt::Formatter,
    record: &log::Record<'_>
)
    -> Result<(), std::io::Error>
{
    let level_style  = buf.default_level_style(record.level());
    let level_letter = record.level().as_str().split_at(1).0;
    let filename     = record.file().unwrap_or("UNKNOWN");
    let lineno       = record.line().unwrap_or(0);

    use std::io::Write;
    writeln!(
        buf,
        "[{}] {} ({}:{})",
        level_style.value(level_letter),
        record.args(),
        buf.style().set_dimmed(true).value(filename),
        buf.style().set_dimmed(true).value(lineno)
    )?;

    Ok(())
}

pub fn setup(test: bool)
{
    let env = env_logger::Env::new()
        .default_filter_or("INFO");

    let logger = env_logger::Builder::from_env(env)
        .format(format_console_log)
        .is_test(test)
        .build();

    add_logger(logger);
}

And after running the setup() function, I finally get useful log messages that look like this:

[I] Accepted request 157 from 127.0.0.1:41440 (63 permits left) (src/server/handler.rs:27)
[I] Accepted request 158 from 127.0.0.1:41456 (62 permits left) (src/server/handler.rs:27)
[I] Accepted request 159 from 127.0.0.1:41472 (61 permits left) (src/server/handler.rs:27)
[I] [157] <- GET static/css/style/lined-paper-effect.css (src/http/request/mod.rs:65)
[I] [158] <- GET static/css/style/folded-corner-effect.css (src/http/request/mod.rs:65)
[I] [159] <- GET static/css/style/figure.css (src/http/request/mod.rs:65)
[I] Accepted request 160 from 127.0.0.1:41488 (60 permits left) (src/server/handler.rs:27)
[I] [160] <- GET static/css/style/code.css (src/http/request/mod.rs:65)
[I] [158] -> 304 Not Modified (src/http/response/mod.rs:107)
[I] [159] -> 304 Not Modified (src/http/response/mod.rs:107)
[I] [157] -> 304 Not Modified (src/http/response/mod.rs:107)

Pitfalls and Tips

Along the way, I picked up a couple of tips that might be useful for someone:

Written by Francis Wharf
Prev post Next post Archive