carboncopy 0.3.0

A user (programmer) interface for asynchronous logging in Rust
Documentation
use chrono::{DateTime, Utc};
use serde::Serialize;
use std::fmt::{Debug, Display};
use std::sync::Arc;

mod json;
mod valid;
pub use futures::future::BoxFuture;
pub use valid::*;

/// Takes entries and filter/submit them to the provided backend implementation.
pub struct Logger {
    max_level: Level,
    sink: Arc<dyn Sink + Send + Sync>,
}

impl Logger {
    /// Creates a new Logger connected to backend implementation sink. This Logger will ignore
    /// and discard entries at severity levels lower than max_level.
    pub fn new(max_level: Level, sink: Arc<dyn Sink + Send + Sync>) -> Self {
        Self {
            max_level: max_level,
            sink: sink,
        }
    }

    /// Logs entry at the specified severity level. This Logger will ignore and discard entries
    /// at severity levels lower than `self.max_level()`.
    pub fn log<T: Clone + Serialize>(
        &self,
        mode: SinkMode,
        level: Level,
        entry: Entry<T>,
    ) -> SinkAcknowledgment {
        self.log_expensive(mode, level, || entry)
    }

    /// Logs an Entry obtained through an expensive computation in function func. If level
    /// is lower than `self.max_level()`, logging won't be performed so there is no need to
    /// execute func.
    pub fn log_expensive<F, T: Clone + Serialize>(
        &self,
        mode: SinkMode,
        level: Level,
        func: F,
    ) -> SinkAcknowledgment
    where
        F: FnOnce() -> Entry<T>,
    {
        if level < self.max_level {
            SinkAcknowledgment::NotPerformed
        } else {
            let entry = func();
            match mode {
                SinkMode::Blocking => {
                    SinkAcknowledgment::Completed(self.sink.sink_blocking(entry.json(level)))
                }
                SinkMode::Awaitable => {
                    SinkAcknowledgment::Awaitable(self.sink.sink(entry.json(level)))
                }
            }
        }
    }

    /// Shortcut for `self.log(SinkMode::Blocking, level, entry)`.
    /// If level is ignored, None is returned.
    pub fn log_blocking<T: Clone + Serialize>(
        &self,
        level: Level,
        entry: Entry<T>,
    ) -> Option<std::io::Result<()>> {
        match self.log(SinkMode::Blocking, level, entry) {
            SinkAcknowledgment::Completed(result) => Some(result),
            SinkAcknowledgment::NotPerformed => None,
            SinkAcknowledgment::Awaitable(_) => Some(Err(new_mode_ack_mismatch_err())),
        }
    }

    /// Shortcut for `self.log(SinkMode::Awaitable, level, entry)`.
    /// If level is ignored, None is returned.
    pub fn log_async<T: Clone + Serialize>(
        &self,
        level: Level,
        entry: Entry<T>,
    ) -> Option<BoxFuture<std::io::Result<()>>> {
        match self.log(SinkMode::Awaitable, level, entry) {
            SinkAcknowledgment::NotPerformed => None,
            SinkAcknowledgment::Completed(_) => Some(Box::pin(futures::future::ready(Err(
                new_mode_ack_mismatch_err(),
            )))),
            SinkAcknowledgment::Awaitable(fut) => Some(fut),
        }
    }

    /// Shortcut for `self.log_expensive(SinkMode::Blocking, level, func)`.
    /// If level is ignored, None is returned.
    pub fn log_expensive_blocking<F, T: Clone + Serialize>(
        &self,
        level: Level,
        func: F,
    ) -> Option<std::io::Result<()>>
    where
        F: FnOnce() -> Entry<T>,
    {
        match self.log_expensive(SinkMode::Blocking, level, func) {
            SinkAcknowledgment::NotPerformed => None,
            SinkAcknowledgment::Completed(result) => Some(result),
            SinkAcknowledgment::Awaitable(_) => Some(Err(new_mode_ack_mismatch_err())),
        }
    }

    /// Shortcut for `self.log_expensive(SinkMode::Awaitable, level, func)`.
    /// If level is ignored, None is returned.
    pub fn log_expensive_async<F, T: Clone + Serialize>(
        &self,
        level: Level,
        func: F,
    ) -> Option<BoxFuture<std::io::Result<()>>>
    where
        F: FnOnce() -> Entry<T>,
    {
        match self.log_expensive(SinkMode::Awaitable, level, func) {
            SinkAcknowledgment::NotPerformed => None,
            SinkAcknowledgment::Completed(_) => Some(Box::pin(futures::future::ready(Err(
                new_mode_ack_mismatch_err(),
            )))),
            SinkAcknowledgment::Awaitable(fut) => Some(fut),
        }
    }

    /// Returns the lowest level entry which this Logger will sink into the backend.
    pub fn max_level(&self) -> Level {
        self.max_level
    }

    /// Sets the lowest level entry which this Logger will sink into the backend.
    pub fn set_max_level(&mut self, level: Level) {
        self.max_level = level;
    }
}

const MODE_ACK_MISMATCH_ERR_MESSAGE: &'static str =
    "sink acknowledgment does not match mode requested";

fn new_mode_ack_mismatch_err() -> std::io::Error {
    std::io::Error::new(std::io::ErrorKind::Other, MODE_ACK_MISMATCH_ERR_MESSAGE)
}

/// The mode with which an entry is to be submitted into the provided sink. Refer to the Sink
/// trait documentation for further details.
#[derive(Copy, Clone, Debug, Eq, PartialEq, Ord, PartialOrd, Hash)]
pub enum SinkMode {
    Blocking,
    Awaitable,
}

/// The acknowledgment returned from logging entries. Refer to the Sink trait documentation for
/// further details.
pub enum SinkAcknowledgment<'a> {
    /// The acknowledgment returned by Logger indicating an entry has been level filtered and
    /// therefore not submitted to the provided sink.
    NotPerformed,

    /// The acknowledgment returned after Logger has just submitted an entry to the backend sink
    /// in a blocking manner.
    Completed(std::io::Result<()>),

    /// The acknowledgment returned after Logger has just submitted an entry to the backend sink
    /// in an async manner.
    Awaitable(BoxFuture<'a, std::io::Result<()>>),
}

/// An enum used to specify the severity level of a log message. Several examples of
/// corresponding scenarios will be provided for each enum variant. The examples are only
/// to be used as a guide and not a hard rule.
#[derive(Copy, Clone, Debug, Eq, PartialEq, Ord, PartialOrd, Hash, Serialize)]
pub enum Level {
    /// Indicates an extremely verbose information which only rarely needs to be activated
    /// or perused for detective work (forensics, audits). Activating this level for a
    /// sustained period could degrade performance.
    ///
    /// Examples:
    ///
    /// * The request method, URL, full request body, and full response body of a REST API
    ///   call to a payment processor.
    /// * An entire form submission.
    /// * Complete step-by-step of a program flow (such as entering and exiting a loop or
    ///   function).
    TRACE,

    /// Indicates an information that helps with debugging, usually containing the value of
    /// variables after a significant event triggered by a user activity has just happened.
    ///
    /// Examples:
    ///
    /// * The updated shipping cost or total price in a shopping cart after an item has
    ///   been added to it.
    /// * The updated account balance after some money has been transferred into/out of it.
    /// * Error codes returned to users.
    DEBUG,

    /// Indicates a useful information that doesn't qualify as an error.
    ///
    /// Examples:
    ///
    /// * Notice that an application has just started.
    /// * The IP address and port number that a web service is bound to.
    /// * Notice that a connection with an external service has just been established
    ///   successfully.
    INFO,

    /// Indicates a non-desired situation that doesn't qualify as an error.
    ///
    /// Examples:
    ///
    /// * A deprecated function or REST API endpoint is invoked or consumed.
    /// * Recovery from a panic which could have been prevented by a simple conditional
    ///   logic.
    /// * Notice of malicious user activities such as SQL injection attempts or absurdly
    ///   high number of requests per second.
    WARN,

    /// Indicates a serious error that the application can still recover from. An example
    /// of such error is when an application which relies on a database failed to connect
    /// to it after a single try, but one or more retries will be attempted later.
    ERROR,

    /// Indicates that a severe error that causes a program to terminate has just happened.
    /// An example of such error is when an application which heavily relies on an external
    /// service (say, a database) can't connect to it after many retries. There is no point
    /// in continuing execution as the application won't be able to do much of anything.
    /// The process usually must exit after logging the message.
    FATAL,
}

impl Display for Level {
    fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result {
        Debug::fmt(self, f)
    }
}

/// Represents a single log entry.
#[derive(Clone, Serialize)]
pub struct Entry<T: Clone + Serialize> {
    #[serde(rename = "msg")]
    message: T,

    #[serde(rename = "ts")]
    #[serde(skip_serializing_if = "Option::is_none")]
    created: Option<DateTime<Utc>>,

    #[serde(skip_serializing_if = "Option::is_none")]
    #[serde(serialize_with = "json::as_base64")]
    #[serde(rename = "spid")]
    span_id: Option<Vec<u8>>,

    #[serde(skip_serializing_if = "Option::is_none")]
    tags: Option<Tags>,
}

impl<T: Clone + Serialize> Entry<T> {
    /// Creates a new log entry.
    ///
    /// If timestamp is true, entry is timestamped at `Utc::now()`. Otherwise, entry is not
    /// timestamped. Use this option to avoid double timestamping (e.g when using Docker).
    ///
    /// When processing the log using a third party log processor, `span_id` may be used to group
    /// entries related to the same event together, while `tags` may be used to add labels for
    /// categorization.
    pub fn new(message: T, timestamp: bool, span_id: Option<Vec<u8>>, tags: Option<Tags>) -> Self {
        Self {
            message: message,
            created: if timestamp { Some(Utc::now()) } else { None },
            span_id: span_id,
            tags: tags,
        }
    }

    pub fn json(self, level: Level) -> String {
        let mut log_line = json::serialize::<T>(self, level);
        log_line.push('\n');
        log_line
    }
}

/// A trait to be implemented by an external crate whose job is to take an entry (already
/// stringified) and append it to the storage that holds previous log entries.
pub trait Sink {
    /// Sinks a log entry and blocks the current thread while waiting for I/O completion for
    /// async blind callers that want to wait for acknowledgment.
    /// Example implementation is `block_on(/* I/O logic */)`. Refer to the `block_on`
    /// API offered by tokio, async-std, etc.
    fn sink_blocking(&self, entry: String) -> std::io::Result<()>;

    /// Sinks a log entry using async I/O and returns a future to be await-ed by the caller.
    /// Caller must likely use the same executor as Sink implementation.
    fn sink(&self, entry: String) -> BoxFuture<std::io::Result<()>>;
}

#[cfg(test)]
mod tests {
    use super::*;
    use futures::executor::block_on;

    #[test]
    fn stringify_enum() {
        assert_eq!("WARN", format!("{}", Level::WARN));
        assert_eq!("TRACE", format!("{}", Level::TRACE));
    }

    // create a dummy sink
    struct DummySink;
    impl Sink for DummySink {
        fn sink_blocking(&self, _entry: String) -> std::io::Result<()> {
            Ok(())
        }
        fn sink(&self, _entry: String) -> BoxFuture<std::io::Result<()>> {
            Box::pin(async { Ok(()) })
        }
    }

    #[test]
    fn log_expensive() {
        let dummy_sink = DummySink;

        let logger = Logger {
            max_level: Level::INFO,
            sink: Arc::new(dummy_sink),
        };

        let mut i = 400;
        let entry = Entry::new("asffdf", false, None, None);
        logger.log_expensive(SinkMode::Blocking, Level::TRACE, || {
            i += 1;
            entry.clone()
        });
        assert_eq!(i, 400);
        logger.log_expensive(SinkMode::Blocking, Level::FATAL, || {
            i += 1;
            entry.clone()
        });
        assert_eq!(i, 401);
        logger.log_expensive(SinkMode::Blocking, Level::INFO, || {
            i += 1;
            entry.clone()
        });
        assert_eq!(i, 402);
    }

    #[test]
    fn log_shortcuts() {
        let dummy_sink = DummySink;

        let logger = Logger {
            max_level: Level::INFO,
            sink: Arc::new(dummy_sink),
        };

        let entry = Entry::new("asffdf", false, None, None);

        assert!(logger
            .log_blocking(Level::ERROR, entry.clone())
            .unwrap()
            .is_ok());

        assert!(block_on(logger.log_async(Level::ERROR, entry.clone()).unwrap()).is_ok());

        let mut i = 400;
        assert!(logger
            .log_expensive_blocking(Level::TRACE, || {
                i += 1;
                entry.clone()
            })
            .is_none());
        assert_eq!(i, 400); // lambda not performed

        assert!(block_on(
            logger
                .log_expensive_async(Level::ERROR, || {
                    i += 1;
                    entry.clone()
                })
                .unwrap(),
        )
        .is_ok());
        assert_eq!(i, 401);
    }
}