Dynamically add more log layers at run-time

[emilk]

Feature Request

Crates

tracing-subscriber

Motivation

There are many places I want to pipe my log events:

• stderr
• a log file
• The GUI
• the network
• …

These can all be implemented as Layers.

The first thing I want to add is the stderr and file layers. The GUI and the network layers I want to add later once the GUI and network connections are up and running. That way any problems with the GUI/network setup is properly logged to stdout and to file.

In other words: I want to dynamically add layers as the program runs.

Proposal

I propose some sort of simple API along the lines of tracing_subscriber::registry().add(layer);

Prior art

My own C++ logging Loguru has a simple method for adding new log sinks (https://emilk.github.io/loguru/index.html#callbacks):

loguru::add_callback("network_logger", user_data, logging_function, loguru::Verbosity_INFO);

This lets different sub-modules of an application can easily add new log sinks at will.

Alternatives

As I was trying to get this work, several helpful people on Discord pointed me towards tracing_subscriber::reload.

I've tried to get it to work, but so far I've failed. My code thus far:

use tracing_subscriber::prelude::*;

let stdout_layer = tracing_subscriber::fmt::layer().with_filter(tracing_subscriber::EnvFilter::from_default_env());
    
let tracing_layers: Vec<Box<dyn tracing_subscriber::layer::Layer<_> + 'static> = vec![Box::new(stdout_layer)];
let (tracing_layers, reload_handle) = tracing_subscriber::reload::Layer::new(tracing_layers);
tracing_subscriber::registry().with(tracing_layers).init();

// set up GUI or network connect or similar, then:

reload_handle.modify(|layers| {
    let gui_layer = GuiLayer::new(gui_handle);
    layers.push(Box::new(gui_layer));
});

There are several issues with this approach:

• It is using a lot of different features that are hard to find ("Vec implements Layer!")
• It is too difficult to use (I can't get it to compile)
• It requires one to keep track of the reload_handle
• It is VERY verbose

Perhaps all the above issues could be solved by an tracing_subscriber expert plus a little bit of documentation. I don't know - I'm not an expert :)

The error message for the above code:

 1  error[E0277]: the size for values of type `dyn tracing_subscriber::Layer<tracing_subscriber::Registry>` cannot be known at compilation time                                                                                              ▐
     --> examples/rust/api_demo/src/main.rs:652:41                                                                                                                                                                                           ▐
      |                                                                                                                                                                                                                                      ▐
 652  |     tracing_subscriber::registry().with(tracing_layers).init();
      |                                    ---- ^^^^^^^^^^^^^^ doesn't have a size known at compile-time
      |                                    |
      |                                    required by a bound introduced by this call
      |
      = help: the trait `std::marker::Sized` is not implemented for `dyn tracing_subscriber::Layer<tracing_subscriber::Registry>`
      = help: the trait `tracing_subscriber::Layer<S>` is implemented for `tracing_subscriber::reload::Layer<L, S>`
      = note: required for `std::boxed::Box<dyn tracing_subscriber::Layer<tracing_subscriber::Registry>>` to implement `tracing_subscriber::Layer<tracing_subscriber::Registry>`
      = note: 2 redundant requirements hidden
      = note: required for `tracing_subscriber::reload::Layer<std::vec::Vec<std::boxed::Box<dyn tracing_subscriber::Layer<...>>>, ...>` to implement `tracing_subscriber::Layer<tracing_subscriber::Registry>`
      = note: the full type name has been written to '/Users/emilk/code/rerun/rerun/target/debug/deps/api_demo-118a8d78b3eddbda.long-type-14231036155949571826.txt'
 note: required by a bound in `tracing_subscriber::prelude::__tracing_subscriber_SubscriberExt::with`
     --> /Users/emilk/.cargo/registry/src/github.heygears.com-1ecc6299db9ec823/tracing-subscriber-0.3.16/src/layer/mod.rs:1485:12
      |
 1485 |         L: Layer<Self>,
      |            ^^^^^^^^^^^ required by this bound in `tracing_subscriber::prelude::__tracing_subscriber_SubscriberExt::with`

[emilk]

Hayden helped me on Discord to get it to compile:

fn tracing_init() {
    use tracing_subscriber::prelude::*;
    use tracing_subscriber::{filter, fmt, registry, reload};

    let stdout_layer = fmt::Layer::default()
        .with_filter(filter::LevelFilter::INFO)
        .boxed();

    let tracing_layers = vec![stdout_layer];
    let (tracing_layers, reload_handle) = reload::Layer::new(tracing_layers);

    registry().with(tracing_layers).init();

    tracing::info!("before reload");

    let reload_result = reload_handle.modify(|layers| {
        let json_layer = fmt::Layer::default()
            .json()
            .with_filter(filter::LevelFilter::INFO)
            .boxed();
        (*layers).push(json_layer);
    });
    match reload_result {
        Ok(_) => {} // Great!
        Err(err) => tracing::warn!("Unable to add new layer: {}", err),
    }

    tracing::info!("after reload");
}

But according to Hayden, it panics at runtime, so this is still an issue.

[pl4nty]

+1, I've run into this when adding https://github.com/tokio-rs/tracing-opentelemetry to an existing app. It has an early stdout to ensure network init issues are captured - this might be a common scenario

[Yongle-Fu]

type SimplifiedHandle = reload::Handle<
    LevelFilter,
    fmt::Layer<Registry, DefaultFields, Format<Full, SystemTime>, Stdout>,
>;

lazy_static! {
    static ref RELOAD_HANDLE: Option<SimplifiedHandle> = None;
}

pub fn initialize_logging(level: i32) {
    // Create a LevelFilter and a reload::Layer
    // let (level_filter, reload_handle) = reload::Layer::new(level_to_filter(level));

    // Update the static handle.
    // *RELOAD_HANDLE = Some(reload_handle);

    let file_fmt_layer = fmt::Layer::default()
        .with_level(false)
        .with_writer(CallbackWriter)
        .with_timer(WithoutTimeFormat)
        .with_filter(level_to_filter(level)); // Use the same level filter

    let console_fmt_layer = fmt::Layer::default()
        .with_file(true)
        .with_line_number(true)
        .with_writer(std::io::stdout)
        .with_timer(CustomTimeFormat)
        .with_filter(level_to_filter(level)); // Use the same level filter

    // let subscriber = Registry::default().with(level_filter);
    let subscriber = Registry::default()
        .with(file_fmt_layer)
        .with(console_fmt_layer);

    tracing::subscriber::set_global_default(subscriber).expect("Failed to set subscriber");
}

pub fn update_logging_level(level: i32) {
    let level_filter = level_to_filter(level);

    if let Some(reload_handle) = &*RELOAD_HANDLE {
        reload_handle
            .modify(|filter| *filter = level_filter)
            .expect("Failed to update logging level");
    }
}

fn level_to_filter(level: i32) -> LevelFilter {
    match level {
        0 => LevelFilter::ERROR,
        1 => LevelFilter::WARN,
        2 => LevelFilter::INFO,
        3 => LevelFilter::DEBUG,
        4 => LevelFilter::TRACE,
        _ => LevelFilter::INFO,
    }
}

how to save a reload_handle, need help

[Yongle-Fu]

found correct usage 😸

lazy_static! {
    static ref IS_INITIALIZED: AtomicBool = AtomicBool::new(false);
    static ref RELOAD_HANDLE: Mutex<Option<reload::Handle<filter::LevelFilter, Registry>>> =
        Mutex::new(None);
}

pub fn setup_logging(level: i32) {
    if IS_INITIALIZED.load(Ordering::Acquire) {
        update_logging_level(level);
        return;
    }

    let result = IS_INITIALIZED.compare_exchange(false, true, Ordering::Acquire, Ordering::Relaxed);
    match result {
        Ok(_) => {
            let (level_filter, reload_handle) = reload::Layer::new(level_to_filter(level));
            set_reload_handle(reload_handle);

            tracing_subscriber::registry()
                .with(level_filter)
                .with(
                    fmt::Layer::default()
                        .with_level(false)
                        .with_writer(CStringWriter)
                        .with_timer(WithoutTimeFormat),
                )
                .with(
                    fmt::Layer::default()
                        .with_file(true)
                        .with_line_number(true)
                        .with_timer(CustomTimeFormat),
                )
                .init();
        }
        Err(_) => {
            // if the logging has already been initialized, just update the logging level
            update_logging_level(level);
        }
    }
}

pub fn update_logging_level(level: i32) {
    if let Some(reload_handle) = &*RELOAD_HANDLE.lock().unwrap() {
        reload_handle
            .modify(|filter| *filter = level_to_filter(level))
            .expect("Failed to update logging level");
    }
}

fn set_reload_handle(reload_handle: reload::Handle<filter::LevelFilter, Registry>) {
    let mut handle = RELOAD_HANDLE.lock().unwrap();
    *handle = Some(reload_handle);
}

[3lpsy]

Overall, I think I have a solution and figured i'd share in case anyone else is googling how to dynamically add layers. My use case was just initializing the console layer first and then adding a file system layer based off a tauri's app config and CLI options.

Here's my main function:

#[cfg_attr(mobile, tauri::mobile_entry_point)]
pub fn run() {
    // this is where I init console layer and return handle
    let log_handle = match logging::setup() {
        Ok(handle) => {
            info!("Console tracing initialized");
            handle
        }
        Err(e) => {
            panic!("Error setting up logging: {:?}", e);
        }
    };
    let mut builder = tauri::Builder::default();
   // other stuff unreleated
   // fs layer added in setup callback
    builder = builder.setup(|app| Ok(setup(app, log_handle)?));
   // build invokers and run tauri
    });
}
// parent is None to just get rid of large tauri messages
#[tracing::instrument(skip_all, parent = None)]
fn setup(app: &mut App, log_handle: logging::LogHandle) -> Result<()> {
    let rt = tauri::async_runtime::handle();
    rt.block_on(async {
        // other stuff, get config
        logging::setup_fs(&config.logs_dir, log_handle)?;
        info!("File tracing initialized");
        // other stuff
    })?;
    info!("App setup complete");
    Ok(())
}

And then here is my logging functions. The LogHandle type will change depending on what's being setup. If you want to dynamically change the filter, you'll need two reload handlers probably. Or loop over the vec and change the EnvFilter. Doing this made my Types annoying so I didn't put too much effort into trying to get it to work.

// imports

// type for return value
pub type LogHandle = Handle<
    Vec<Box<dyn Layer<Layered<EnvFilter, Registry>> + Send + Sync>>,
    Layered<EnvFilter, Registry>,
>;

// initialize console layer
pub fn setup() -> Result<LogHandle> {
    let layers = default_layers()?;
    // wrap the vec in a reload layer
    let (layers, reload_handle) = reload::Layer::new(layers);
    let env_filter_ = env_filter();
    let subscriber = tracing_subscriber::registry()
        .with(env_filter_)
        .with(layers);
    match tracing::subscriber::set_global_default(subscriber) {
        Ok(_) => Ok(reload_handle),
        Err(_e) => Err(Error::msg("Tracing subscriber already registered.")),
    }
}
// later add dir layer via handle
pub fn setup_fs(log_dir: &PathBuf, handle: LogHandle) -> Result<()> {
    handle.modify(|filter| {
        (*filter).push(fs_layer(log_dir).unwrap());
    })?;
    Ok(())
}

// probably doesn't need to be it's own func, just an artifact of previous attempts
// Vec impls Layer so it's important to be a vec
fn default_layers<S>() -> Result<Vec<Box<dyn Layer<S> + Send + Sync + 'static>>>
where
    S: Subscriber,
    for<'a> S: LookupSpan<'a>,
{
    let console_error_ = console_layer()?;
    Ok(vec![console_error_])
}

fn env_filter() -> EnvFilter {
    // build EnvFilter from RUST_LOG and add custom directives if you want, this is unrelated to adding a new layer
    // if you want to dynamically change filter, you'll probably need to get a reload handle to this though
}

fn console_layer<S>() -> Result<Box<dyn Layer<S> + Send + Sync + 'static>>
where
    S: Subscriber,
    for<'a> S: LookupSpan<'a>,
{
    let timer = UtcTime::rfc_3339();
    Ok(fmt::layer()
        .with_timer(timer)
        .with_thread_ids(true)
        .with_target(true)
        .compact()
        .boxed())
}
pub fn fs_layer<S>(log_dir: &PathBuf) -> Result<Box<dyn Layer<S> + Send + Sync + 'static>>
where
    S: Subscriber,
    for<'a> S: LookupSpan<'a>,
{
    // create dir, build appender and timer, etc
    Ok(fmt::layer()
        .with_writer(file_appender)
        .with_timer(timer.clone())
        .with_thread_ids(true)
        .with_thread_names(true)
        .with_target(true)
        .with_file(true)
        .with_line_number(true)
        .with_ansi(false)
        .boxed())
}

[st4s1k]

It's been 2 years, and this is the only place I found discussing this issue... and I'm not even using tokio, I'm just using the tracing library.
I work with Tauri and here's my main function:

fn main() {
    let format_layer = fmt::layer().with_target(false);
    let filter_layer = EnvFilter::from_default_env()
        .add_directive(Level::INFO.into())
        .add_directive("scenario_rs=debug".parse().unwrap());
    
    let ui_event_channel = UiEventChannel::new(/* > app_handle < */); // <--- I need the app handle to AppHandle#emit events to UI, to display the logs
    let ui_log_layer = UiLogLayer::new(ui_event_channel);

    tracing_subscriber::registry()
        .with(format_layer) // I need this here to log all the application events
        .with(filter_layer)
        .with(ui_log_layer) // I don't need this here
        .init();

    tauri::Builder::default()
        .plugin(tauri_plugin_shell::init())
        .plugin(tauri_plugin_dialog::init())
        .setup(|app| {  // <--- get app handler here
            let app_state = ScenarioAppState::new(app.handle());
            app.manage(Mutex::new(app_state));
            let state = app.handle().state::<Mutex<ScenarioAppState>>();
            let mut app_state = state.safe_lock();
            app_state.init(); // <--- I would like to be able to add a layer here after the subscriber was initialized
            Ok(())
        })
        // ...
        .run(tauri::generate_context!())
        .expect("error while running tauri application");
}

[st4s1k]

Decided on this solution:

fn main() {
    let (frontend_tx, frontend_rx) = std::sync::mpsc::channel::<String>();

    tracing_subscriber::registry()
        .with(fmt::layer().with_target(false))
        .with(EnvFilter::from_default_env().add_directive(Level::INFO.into()))
        .with(FrontendLogLayer::from(frontend_tx))
        .init();

    tauri::Builder::default()
        .plugin(tauri_plugin_shell::init())
        .plugin(tauri_plugin_dialog::init())
        .setup(|app| {
            let app_state = ScenarioAppState::new(app.handle());
            app.manage(Mutex::new(app_state));
            let state = app.handle().state::<Mutex<ScenarioAppState>>();
            let mut app_state = state.safe_lock();
            app_state.init(frontend_rx);
            Ok(())
        })
        // ...
        .run(tauri::generate_context!())
        .expect("error while running tauri application");
}

layer:

pub(crate) struct FrontendLogLayer(Sender<String>);

impl Deref for FrontendLogLayer {
    type Target = Sender<String>;

    fn deref(&self) -> &Self::Target {
        &self.0
    }
}

impl From<Sender<String>> for FrontendLogLayer {
    fn from(sender: Sender<String>) -> Self {
        FrontendLogLayer(sender)
    }
}

impl<S> Layer<S> for FrontendLogLayer
where
    S: Subscriber,
    S: for<'a> LookupSpan<'a>,
{
    fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) {
        let mut message = String::new();
        let mut visitor = MessageVisitor(&mut message);
        event.record(&mut visitor);
        self.send_event(message);
    }
}

struct MessageVisitor<'a>(&'a mut String);

impl<'a> tracing::field::Visit for MessageVisitor<'a> { /* ... */ }

now I can take the receiver (frontend_rx) and listen to events from anywhere, anytime I want:

tauri::async_runtime::spawn(async move {
    for message in frontend_rx {
        let state = app_handle.state::<Mutex<ScenarioAppState>>();
        let mut state = state.safe_lock();
        let timestamp = Local::now().format("%H:%M:%S.%3f").to_string();
        state.output_log.push_str(&format!("[{timestamp}] {message}\n"));
        let _ = app_handle.emit("log-update", ());
    }
});