rustrust-macrosrust-no-std

rust logger macro (no-std) alloc fails to format


I've got the following Log and Verbosity structs.

use alloc::string::String;

#[derive(Copy, Clone, PartialOrd, Ord, PartialEq, Eq)]
pub enum Verbosity {
    Debug,
    Info,
    Warning,
    Error,
}

pub struct Log {
    pub file: &'static str,
    pub line: u32,
    pub verbosity: Verbosity,
    pub message: String,
}

And the following macro:

macro_rules! log {
    ($verbosity: expr, $s: expr $(, $args: expr)*) => {
        if $crate::logger::LOGGER.get_verbosity(module_path!()) <= $verbosity {
                println_serial!("[{}] {}:{} {}", $verbosity, file!(), line!(), $s);
                println_serial!($s $(, $args)*);

                let log = $crate::logger::Log {
                    file: file!(),
                    line: line!(),
                    verbosity: $verbosity,
                    message: alloc::format!($s $(, $args)*)
                };
                $crate::logger::LOGGER.push_log(log); // this triggers a println_serial! call 
            }
        }
}

I've left in a working println_serial! macro there for debugging! When I run the macro as follows:

log!(logger::Verbosity::Info, "Simple static string test");

I get the following output:

[INFO] src/main.rs:83 Simple static string test
Simple static string test

Full Scripts

logger.rs

use alloc::string::String;

use hashbrown::HashMap;

use crate::{
    interrupts::guard::InterruptLock, util::circular_buffer::CircularBuffer,
};

macro_rules! log {
    ($verbosity: expr, $s: expr $(, $args: expr)*) => {
        if $crate::logger::LOGGER.get_verbosity(module_path!()) <= $verbosity {
                let log = $crate::logger::Log {
                    file: file!(),
                    line: line!(),
                    verbosity: $verbosity,
                    message: alloc::format!($s $(, $args)*)
                };
                $crate::logger::LOGGER.push_log(log);
            }
        }
}

pub static LOGGER: Logger = Logger::new();

pub struct Log {
    pub file: &'static str,
    pub line: u32,
    pub verbosity: Verbosity,
    pub message: String,
}

impl core::fmt::Display for Log {
    fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result {
        f.write_fmt(format_args!(
            "[{}] {}:{} {}",
            self.verbosity, self.file, self.line, self.message
        ))?;

        Ok(())
    }
}

#[derive(Copy, Clone, PartialOrd, Ord, PartialEq, Eq)]
pub enum Verbosity {
    Debug,
    Info,
    Warning,
    Error,
}

impl core::fmt::Display for Verbosity {
    fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result {
        match self {
            Self::Debug => f.write_str("DEBUG"),
            Self::Info => f.write_str("INFO"),
            Self::Warning => f.write_str("WARNING"),
            Self::Error => f.write_str("ERROR"),
        }?;
        Ok(())
    }
}

pub struct Logger {
    verbose: InterruptLock<Option<HashMap<String, Verbosity>>>,
    logs: InterruptLock<CircularBuffer<Log, 1024>>,
}

impl Logger {
    const fn new() -> Self {
        Logger {
            verbose: InterruptLock::new(None),
            logs: InterruptLock::new(CircularBuffer::new()),
        }
    }

    pub fn get_verbosity(&self, module: &str) -> Verbosity {
        *self
            .verbose
            .lock()
            .as_ref()
            .expect("Logger not initialized")
            .get(module)
            .unwrap_or(&Verbosity::Info)
    }

    pub fn push_log(&self, log: Log) {
        if self.logs.lock().push_back(log).is_err() {
            panic!("Dropped log");
        }
    }

    pub fn trigger(&self) {
        while let Some(log) = self.logs.lock().pop_front() {
            println_serial!("{}", log);
        }
    }
}

pub fn init(verbose: HashMap<String, Verbosity>) {
    *LOGGER.verbose.lock() = Some(verbose);
}

pub fn trigger() {
    LOGGER.trigger()
}

circular_buffer.rs

use core::mem::MaybeUninit;

use thiserror_no_std::Error;

#[derive(Error, Debug)]
#[error("Failed to push item into buffer")]
pub struct PushError;

pub struct CircularBuffer<T, const N: usize> {
    array: [MaybeUninit<T>; N],
    head: usize,
    tail: usize,
}

impl<T, const N: usize> CircularBuffer<T, N> {
    pub const fn new() -> Self {
        Self {
            array: MaybeUninit::uninit_array(),
            head: 0,
            tail: 0,
        }
    }

    pub fn push_back(&mut self, item: T) -> Result<(), PushError> {
        let insertion_index = self.tail;

        match self.increment_tail() {
            Some(tail) => self.tail = tail,
            None => return Err(PushError),
        }

        self.array[insertion_index] = MaybeUninit::new(item);
        Ok(())
    }

    pub fn pop_front(&mut self) -> Option<T> {
        let index = self.head;

        if self.head == self.tail {
            return None;
        }

        wrapping_increment(&mut self.head, N);

        if self.tail == N + 1 {
            self.tail = index;
        }

        let mut ret = MaybeUninit::uninit();
        core::mem::swap(&mut ret, &mut self.array[index]);
        unsafe { Some(ret.assume_init()) }
    }

    fn increment_tail(&mut self) -> Option<usize> {
        if self.tail == N + 1 {
            return None;
        }

        wrapping_increment(&mut self.tail, N);

        if self.tail == self.head {
            self.tail = N + 1;
        }

        Some(self.tail)
    }
}

fn wrapping_increment(i: &mut usize, container_size: usize) {
    *i = (*i + 1) % container_size
}

guard.rs

use core::{
    arch::asm,
    cell::UnsafeCell,
    ops::{Deref, DerefMut},
    sync::atomic::{AtomicUsize, Ordering},
};

static NUM_GUARDS: AtomicUsize = AtomicUsize::new(0);

pub struct InterruptGuard<'a, T> {
    data: &'a mut T,
}

impl<'a, T> Drop for InterruptGuard<'a, T> {
    fn drop(&mut self) {
        if NUM_GUARDS.fetch_sub(1, Ordering::SeqCst) == 1 {
            unsafe {
                asm!("sti");
            }
        }
    }
}

impl<'a, T> Deref for InterruptGuard<'a, T> {
    type Target = T;

    fn deref(&self) -> &T {
        self.data
    }
}

impl<'a, T> DerefMut for InterruptGuard<'a, T> {
    fn deref_mut(&mut self) -> &mut T {
        self.data
    }
}

pub struct InterruptLock<T> {
    data: UnsafeCell<T>,
}

impl<T> InterruptLock<T> {
    pub const fn new(data: T) -> InterruptLock<T> {
        InterruptLock {
            data: UnsafeCell::new(data),
        }
    }

    pub fn lock(&self) -> InterruptGuard<'_, T> {
        NUM_GUARDS.fetch_add(1, Ordering::SeqCst);

        unsafe {
            asm!("cli");
        }

        unsafe {
            InterruptGuard {
                data: &mut *self.data.get(),
            }
        }
    }
}

// NOTE: Sync implementation assumes single threaded os
unsafe impl<T> Sync for InterruptLock<T> {}

Ideally the macros works with other expressions as well (ex: {:?})

PS: This is part of a custom kernel project so there's a lot of code. Happy to share that as well, I just thought I'll share the core bits.


Solution

  • So after a lot of digging turns out the problem had nothing to do with the way the logger was implemented. The error was infact with the way my custom memory allocator was implemented which is why alloc::format!(...) failed.

    Thanks for everyone in the comments who helped me further refine the question.