Change subscriber settings on the fly

[avifenesh]

Hi guys, i'll love to get some help on this issue

I have a multi-language library, with the core written in rust and the the different wrappers wrote in JS, python, Java and C#.
Iv'e created logger with the tracing crate and all of the wrappers sending their logs to "logger-core" wrote withe tracing crate.
The users of my library using the logger i'm providing "out of the box", meaning the are not rust programer and Im trying to wrap the logger and share just the API of the logger.
The challenge began when for example user want to change the level of the logger or change the logging from console to file.
Currently what i see is after "resetting the logger" the subscriber doesn't find the logs and they just not appearing anymore.
Is there any solution that Im not aware of? any idea's?
My code:

use std::sync::RwLock;
use tracing::{self, event};
use tracing_appender::{
    non_blocking,
    non_blocking::WorkerGuard,
    rolling::{RollingFileAppender, Rotation},
};
use tracing_subscriber::{self, filter::LevelFilter};
#[derive(Debug)]
pub enum LoggerInitiate {
    False = 0,
    File = 1,
    Console = 2,
}
// Guard is in charge of making sure that the logs been collected when program stop
pub static GUARD: RwLock<Option<WorkerGuard>> = RwLock::new(None);
pub static GUARD_READ: RwLock<LoggerInitiate> = RwLock::new(LoggerInitiate::False);

#[derive(Debug)]
pub enum Level {
    Error = 0,
    Warn = 1,
    Info = 2,
    Debug = 3,
    Trace = 4,
}

// Initialize a logger that writes the received logs to a file under the babushka-logs folder.
// The file name will be prefixed with the current timestamp, and will be replaced every hour.
// This logger doesn't block the calling thread, and will save only logs of the given level or above.
pub fn init_file(minimal_level: Level, file_name: &str) -> Level {
    let level_filter = minimal_level.to_filter();
    let file_appender = RollingFileAppender::new(Rotation::HOURLY, "babushka-logs", file_name);
    let (non_blocking, _guard) = non_blocking(file_appender);
    match *GUARD_READ.read().unwrap()
    {
        LoggerInitiate::File => (),
        _ => {
            let mut guard = GUARD.write().unwrap();
            *guard = Some(_guard);
            drop(guard);
        },

    }
    let _ = tracing::subscriber::set_global_default(
                tracing_subscriber::fmt()
                    .event_format(tracing_format())
                    .with_max_level(level_filter)
                    .with_writer(non_blocking)
                    .finish(),
            );
    let mut guard_read = GUARD_READ.write().unwrap();
    *guard_read = LoggerInitiate::File;
    minimal_level
}

// Initialize the global logger so that it will write the received logs to a file under the babushka-logs folder.
// The file name will be prefixed with the current timestamp, and will be replaced every hour.
// The logger doesn't block the calling thread, and will save only logs of the given level or above.
pub fn init_console(minimal_level: Level) -> Level {
    let level_filter = minimal_level.to_filter();
    let (non_blocking, _guard) = tracing_appender::non_blocking(std::io::stdout());
    match *GUARD_READ.read().unwrap()
    {
        LoggerInitiate::Console => (),
        _ => {
        let mut guard = GUARD.write().unwrap();
        *guard = Some(_guard);
        drop(guard);}
    }
    let _ = tracing::subscriber::set_global_default(
        tracing_subscriber::fmt()
            .event_format(tracing_format())
            .with_writer(non_blocking)
            .with_max_level(level_filter)
            .finish(),
    );
    let mut guard_read = GUARD_READ.write().unwrap();
    *guard_read = LoggerInitiate::Console;

    minimal_level
}

// Initialize the global logger so that it will write the received logs to the console.
// The logger will save only logs of the given level or above.
pub fn init(minimal_level: Option<Level>, file_name: Option<&str>) -> Level {
    let level = minimal_level.unwrap_or(Level::Warn);
    match file_name {
        None => init_console(level),
        Some(file) => init_file(level, file),
    }
}

macro_rules! create_log {
    ($name:ident, $uppercase_level:tt) => {
        pub fn $name<Message: AsRef<str>, Identifier: AsRef<str>>(
            log_identifier: Identifier,
            message: Message,
        ) {
            if GUARD.read().unwrap().is_none() {
                init(None, None);
            };

            let message_ref = message.as_ref();
            let identifier_ref = log_identifier.as_ref();
            event!(
                tracing::Level::$uppercase_level,
                "{identifier_ref} - {message_ref}"
            )
        }
    };
}

[hds]

There are a couple of options which might help here: setting the default subscriber or using reload layers.

Set the default subscriber

One is that you can set a temporary subscriber for the current thread using tracing::subscriber::set_default: https://docs.rs/tracing/latest/tracing/subscriber/fn.set_default.html

This will overwrite the global default subscriber only in the current thread and only until you drop the returned guard.

Reload layers

If you want something that affects all threads in your program, then you can have a look at making layers reloadable with tracing_subscriber::reload: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/reload/index.html

I would suggest that you create both layers that you need (console and file) and make each of them reloadable. You can then use the returned reload handle to modify the filters on each of the layers as you need. This could be used - for example - to turn the conosle layer off and set the file layer to INFO level at runtime.

Important things to consider:

• Reload layers suffer a small performance penalty. You may want to benchmark your use case to ensure that it is acceptable for you.
• You cannot use reload layers to switch between None and Some(layer) or switch between different layers (you will end up with a runtime panic). Instead use the reload handle to modify the filters as I described above.

[avifenesh]

Hi,
thanks a lot for the help!
Im having hard time making the layers of console and file reloadable, there's maybe some example or something similar?

[hds]

I came up with a somewhat contrived example. This code will set up 2 fmt layers, one which writes to stdout and the other to a file called output.log.

(update 2023-06-23): Important Caveat: This solution will work fine for tracing events, but modifying filter levels can cause undesired effects when used with span traces. Any span whose creation and entering isn't captured because of the filter level is "lost", so that events which are recorded within the scope of the span won't appear within the span. This is true for the fmt Layer from the tracing-subscriber crate, other subscribers/layers may behave differently. Use with caution.

Initially the stdout layer will log at INFO level and the file layer will log at ERROR level. When you hit ctrl-c, the levels get switched so that the layer that was logging at INFO now only logs at ERROR and the layer that was logging at ERROR will now log at INFO.

For completness, here's are contents of Cargo.toml:

[package]
name = "tracing-reload"
version = "0.1.0"
edition = "2021"

[dependencies]
ctrlc = "3.4"
tracing = "0.1"
tracing-subscriber = "0.3"

And here is the code itself (in main.rs in the test project):

use std::fs::File;
use std::thread::sleep;
use std::time::Duration;

use tracing::{error, info};
use tracing_subscriber::prelude::*;
use tracing_subscriber::{filter::LevelFilter, reload};

fn toggle_filter(filter: &mut LevelFilter) {
    if filter == &LevelFilter::ERROR {
        *filter = LevelFilter::INFO;
    } else {
        *filter = LevelFilter::ERROR;
    }
}

fn main() {
    let stdout_fmt = tracing_subscriber::fmt::layer()
        .with_ansi(true)
        .with_filter(LevelFilter::INFO); // Stdout logging INFO by default
    let (stdout_layer, stdout_reload) = reload::Layer::new(stdout_fmt);

    let log_file = File::create("output.log").expect("Couldn't open file to write traces to.");
    let file_fmt = tracing_subscriber::fmt::layer()
        .with_ansi(true)
        .with_writer(log_file)
        .with_filter(LevelFilter::ERROR); // File logging ERROR by default
    let (file_layer, file_reload) = reload::Layer::new(file_fmt);

    tracing_subscriber::registry()
        .with(stdout_layer)
        .with(file_layer)
        .init();

    info!("Set up tracing register!");

    ctrlc::set_handler(move || {
        let stdout_modified = stdout_reload.modify(|layer| toggle_filter(layer.filter_mut()));
        let file_modified = file_reload.modify(|layer| toggle_filter(layer.filter_mut()));

        match (stdout_modified, file_modified) {
            (Ok(_), Ok(_)) => info!("Successfully modified filters!"),
            (stdout_result, file_result) => error!(
                "Failed to modify at least one filer: stdout_filter={:?} file_filter:{:?}",
                stdout_result, file_result
            ),
        }
    })
    .expect("Error setting Ctrl-C handler");

    let mut count = 0_usize;
    loop {
        info!("Tick {count}");
        count += 1;

        sleep(Duration::from_secs(1));
    }
}

Note that I left the colors enabled for the file as well as for stdout, this is probably not what you want.

I also made a demo video, because why not?

tracing-reload-demo.mov

[avifenesh]

First, @hds, thank you a lot! you are amazing and your'e solution work perfectly without a big cost in performance.
Second - I'll share my full implementation for logger using in production, providing the ability to rest the logger when ever the init function called, for the next confused SE that will be looking for something like this -

use once_cell::sync::OnceCell;
use std::sync::Once;
use std::sync::RwLock;
use tracing::{self, event};
use tracing_appender::rolling::{RollingFileAppender, Rotation};
use tracing_subscriber::{
    filter::Filtered,
    fmt::{
        format::{DefaultFields, Format},
        Layer,
    },
    layer::Layered,
    Registry,
};

use tracing_subscriber::{
    self,
    filter::{self, LevelFilter},
    prelude::*,
    reload::{self, Handle},
};

// INIT_ONCE is responsible for making sure that we initiating the logger just once, and every other call to the
// init function will just reload the existing logger
static INIT_ONCE: Once = Once::new();

// reloadable handles for resetting the logger
pub static STDOUT_RELOAD: OnceCell<
    RwLock<reload::Handle<Filtered<Layer<Registry>, LevelFilter, Registry>, Registry>>,
> = OnceCell::new();

pub static FILE_RELOAD: OnceCell<
    RwLock<
        Handle<
            Filtered<
                Layer<
                    Layered<
                        reload::Layer<Filtered<Layer<Registry>, LevelFilter, Registry>, Registry>,
                        Registry,
                    >,
                    DefaultFields,
                    Format,
                    RollingFileAppender,
                >,
                LevelFilter,
                Layered<
                    reload::Layer<Filtered<Layer<Registry>, LevelFilter, Registry>, Registry>,
                    Registry,
                >,
            >,
            Layered<
                reload::Layer<Filtered<Layer<Registry>, LevelFilter, Registry>, Registry>,
                Registry,
            >,
        >,
    >,
> = OnceCell::new();

#[derive(Debug)]
pub enum Level {
    Error = 0,
    Warn = 1,
    Info = 2,
    Debug = 3,
    Trace = 4,
}
impl Level {
    fn to_filter(&self) -> filter::LevelFilter {
        match self {
            Level::Trace => LevelFilter::TRACE,
            Level::Debug => LevelFilter::DEBUG,
            Level::Info => LevelFilter::INFO,
            Level::Warn => LevelFilter::WARN,
            Level::Error => LevelFilter::ERROR,
        }
    }
}

// Initialize the global logger to error level on the first call only
// In any of the calls to the function, including the first - resetting the existence loggers to the new setting provided
// by using the global reloadable handle
// The logger will save only logs of the given level or above.
pub fn init(minimal_level: Option<Level>, file_name: Option<&str>) -> Level {
    let level = minimal_level.unwrap_or(Level::Warn);
    let level_filter = level.to_filter();
    INIT_ONCE.call_once(|| {
        let stdout_fmt = tracing_subscriber::fmt::layer()
            .with_ansi(true)
            .with_filter(LevelFilter::ERROR); // Console logging ERROR by default

        let (stdout_layer, stdout_reload) = reload::Layer::new(stdout_fmt);

        let file_appender = RollingFileAppender::new(
            Rotation::HOURLY,
            "babushka-logs",
            file_name.unwrap_or("output.log"),
        );
        let file_fmt = tracing_subscriber::fmt::layer()
            .with_ansi(true)
            .with_writer(file_appender)
            .with_filter(LevelFilter::ERROR); // File logging ERROR by default
        let (file_layer, file_reload) = reload::Layer::new(file_fmt);
        tracing_subscriber::registry()
            .with(stdout_layer)
            .with(file_layer)
            .init();
        let _ = STDOUT_RELOAD.set(RwLock::new(stdout_reload));
        let _ = FILE_RELOAD.set(RwLock::new(file_reload));
    });

    match file_name {
        None => {
            let _ = STDOUT_RELOAD
                .get()
                .expect("error reloading stdout")
                .write()
                .expect("error reloading stdout")
                .modify(|layer| (*layer.filter_mut() = level_filter));
        }
        Some(file) => {
            let file_appender = RollingFileAppender::new(Rotation::HOURLY, "babushka-logs", file);
            let _ = FILE_RELOAD
                .get()
                .expect("error reloading stdout")
                .write()
                .expect("error reloading stdout")
                .modify(|layer| {
                    *layer.filter_mut() = level_filter;
                    *layer.inner_mut().writer_mut() = file_appender;
                });
        }
    };
    level
}

macro_rules! create_log {
    ($name:ident, $uppercase_level:tt) => {
        pub fn $name<Message: AsRef<str>, Identifier: AsRef<str>>(
            log_identifier: Identifier,
            message: Message,
        ) {
            if STDOUT_RELOAD.get().is_none() {
                init(Some(Level::Warn), None);
            };
            let message_ref = message.as_ref();
            let identifier_ref = log_identifier.as_ref();
            event!(
                tracing::Level::$uppercase_level,
                "{identifier_ref} - {message_ref}"
            )
        }
    };
}

create_log!(log_trace, TRACE);
create_log!(log_debug, DEBUG);
create_log!(log_info, INFO);
create_log!(log_warn, WARN);
create_log!(log_error, ERROR);

// Logs the given log, with log_identifier and log level prefixed. If the given log level is below the threshold of given when the logger was initialized, the log will be ignored.
// log_identifier should be used to add context to a log, and make it easier to connect it to other relevant logs. For example, it can be used to pass a task identifier.
// If this is called before a logger was initialized the log will not be registered.
// If logger doesn't exist, create the default
pub fn log<Message: AsRef<str>, Identifier: AsRef<str>>(
    log_level: Level,
    log_identifier: Identifier,
    message: Message,
) {
    match log_level {
        Level::Debug => log_debug(log_identifier, message),
        Level::Trace => log_trace(log_identifier, message),
        Level::Info => log_info(log_identifier, message),
        Level::Warn => log_warn(log_identifier, message),
        Level::Error => log_error(log_identifier, message),
    }
}

My tests for the logger:

#[cfg(test)]
mod tests {

    use std::fs::{read_dir, read_to_string};

    use logger_core::{init, log_trace};
    use rand::{distributions::Alphanumeric, Rng};

    const FILE_DIRECTORY: &str = "babushka-logs";

    fn generate_random_string(length: usize) -> String {
        rand::thread_rng()
            .sample_iter(&Alphanumeric)
            .take(length)
            .map(char::from)
            .collect()
    }

    fn get_file_contents(file_name: &str) -> String {
        let files = read_dir(FILE_DIRECTORY).unwrap();
        let file = files
            .into_iter()
            .find(|path| {
                path.as_ref()
                    .unwrap()
                    .path()
                    .file_name()
                    .unwrap()
                    .to_str()
                    .unwrap()
                    .starts_with(file_name)
            })
            .unwrap();
        read_to_string(file.unwrap().path()).unwrap()
    }
    #[test]
    fn log_to_console_works_after_multiple_inits_diff_log_level() {
        let identifier = generate_random_string(10);
        init(Some(logger_core::Level::Debug), None);
        init(Some(logger_core::Level::Trace), None);
        log_trace(identifier.clone(), "foo");
    }
    #[test]
    fn log_to_console_works_after_multiple_inits() {
        let identifier = generate_random_string(10);
        init(Some(logger_core::Level::Trace), None);
        init(Some(logger_core::Level::Trace), None);
        log_trace(identifier.clone(), "foo");
    }
    #[test]
    fn log_to_file_works_after_multiple_inits() {
        let identifier = generate_random_string(10);
        init(Some(logger_core::Level::Trace), Some(identifier.as_str()));
        log_trace(identifier.clone(), "foo");

        init(Some(logger_core::Level::Trace), Some(identifier.as_str()));
        log_trace(identifier.clone(), "foo");
        let contents = get_file_contents(identifier.as_str());
        assert!(
            contents.contains(identifier.as_str()),
            "Contens: {}",
            contents
        );
        assert!(contents.contains("foo"), "Contens: {}", contents);
    }

    #[test]
    fn log_to_console_works_after_file_init() {}

    #[test]
    fn log_to_file_works_after_console_init() {
        let identifier = generate_random_string(10);
        init(Some(logger_core::Level::Trace), None);
        init(Some(logger_core::Level::Trace), Some(identifier.as_str()));
        log_trace(identifier.clone(), "foo");
        let contents = get_file_contents(identifier.as_str());
        assert!(
            contents.contains(identifier.as_str()),
            "Contens: {}",
            contents
        );
        assert!(contents.contains("foo"), "Contens: {}", contents);
    }
}

Hopefully someone might find it helpful in the future.