log_file not allow internal logging

[EPashkin]

This example stalling after writing second "Kek" but works fine if "log_file" commented.

// log = "0.4.14"
// fern = "0.6.0"

use std::fmt;

fn setup_logger() -> Result<(), fern::InitError> {
    fern::Dispatch::new()
        .format(|out, message, record| {
            out.finish(format_args!(
                "[{}][{}] {}",
                record.target(),
                record.level(),
                message
            ))
        })
        .level(log::LevelFilter::Debug)
        .chain(std::io::stdout())
        .chain(fern::log_file("output.log")?)
        .apply()?;
    Ok(())
}

fn main() {
    setup_logger().unwrap();
    println!("run");
    log::error!("Error: {}", get_str());

    println!("exiting");
}
struct Error;
impl fmt::Display for Error {
    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
        log::debug!("Kek");
        write!(f, "wow")
    }
}

fn get_str() -> &'static str {
    log::warn!("get_str: {}", Error);
    "test"
}

     Running `target/debug/test_i18_stall`
run
[test_i18_stall][WARN] get_str: [test_i18_stall][DEBUG] Kek
wow
[test_i18_stall][DEBUG] Kek

gdb backtrace after interrupting

(gdb) bt
#0  0x00007ffff7f93610 in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x00007ffff7f8bf53 in pthread_mutex_lock () from /lib64/libpthread.so.0
#2  0x0000555555578dbd in std::sys::unix::mutex::Mutex::lock (self=0x5555555f3ed0)
    at /home/evgen/.rustup/toolchains/1.47.0-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys/unix/mutex.rs:63
#3  0x0000555555563f8a in std::sys_common::mutex::Mutex::raw_lock (self=0x5555555f3ed0)
    at /home/evgen/.rustup/toolchains/1.47.0-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys_common/mutex.rs:42
#4  0x0000555555571d26 in std::sync::mutex::Mutex<T>::lock (self=0x5555555f3f90)
    at /home/evgen/.rustup/toolchains/1.47.0-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sync/mutex.rs:269
#5  0x0000555555578048 in <fern::log_impl::File as log::Log>::log::{{closure}} (record=0x7fffffffc3b8)
    at /home/evgen/.cargo/registry/src/github.com-1ecc6299db9ec823/fern-0.6.0/src/log_impl.rs:549
#6  0x0000555555577eb1 in fern::log_impl::fallback_on_error (record=0x7fffffffc3b8, log_func=...)
    at /home/evgen/.cargo/registry/src/github.com-1ecc6299db9ec823/fern-0.6.0/src/log_impl.rs:733
#7  <fern::log_impl::File as log::Log>::log (self=0x5555555f3f90, record=0x7fffffffc3b8)
    at /home/evgen/.cargo/registry/src/github.com-1ecc6299db9ec823/fern-0.6.0/src/log_impl.rs:535
#8  0x0000555555575e44 in <fern::log_impl::Output as log::Log>::log (self=0x5555555f3f88, record=0x7fffffffc3b8)
    at /home/evgen/.cargo/registry/src/github.com-1ecc6299db9ec823/fern-0.6.0/src/log_impl.rs:326
#9  0x00005555555763a4 in fern::log_impl::Dispatch::finish_logging (self=0x5555555f1e30, record=0x7fffffffc3b8)
    at /home/evgen/.cargo/registry/src/github.com-1ecc6299db9ec823/fern-0.6.0/src/log_impl.rs:427
#10 0x00005555555767f1 in fern::log_impl::FormatCallback::finish (self=..., formatted_message=...)
    at /home/evgen/.cargo/registry/src/github.com-1ecc6299db9ec823/fern-0.6.0/src/log_impl.rs:487

[daboross]

There's a workaround built in for this, the meta-logging-in-format feature. Enable it (like with fern = { version = "...", features = ["meta-logging-in-format"]), and fern will use an additional buffer to support this kids of logging. It's not enabled by default since it comes at a performance cost.

I'll leave this open since just hanging the thread really isn't ideal - we should probably detect this and error out. But I figure logging during format calls in a niche enough use case that not supporting it by default is usually ok?

[EPashkin]

Meta logging helps, thanks.

In full application second log happens when no localized string found, so it seems "rare" case.