tracing-appender does not write a single byte

[JakkuSakura]

Bug Report

Version

│   └── tracing v0.1.26
│       ├── tracing-attributes v0.1.15 (proc-macro)
│       └── tracing-core v0.1.18
│   │   │   │   │   └── tracing v0.1.26 (*)
│   │   │   │   ├── tracing v0.1.26 (*)
│   ├── tracing v0.1.26 (*)
│   ├── tracing-appender v0.1.2
│   │   └── tracing-subscriber v0.2.19
│   │       ├── tracing v0.1.26 (*)
│   │       ├── tracing-core v0.1.18 (*)
│   │       ├── tracing-log v0.1.2
│   │       │   └── tracing-core v0.1.18 (*)
│   │       └── tracing-serde v0.1.2
│   │           └── tracing-core v0.1.18 (*)
│   ├── tracing-log v0.1.2 (*)
│   └── tracing-subscriber v0.2.19 (*)
│   │   │   └── tracing v0.1.26 (*)
│   │   │   │   ├── tracing v0.1.26 (*)
│   │   │   └── tracing v0.1.26 (*)
│   │   │   └── tracing v0.1.26 (*)
│   │   ├── tracing v0.1.26 (*)
│   │   ├── tracing v0.1.26 (*)
│   │   │   ├── tracing v0.1.26 (*)
│   ├── tracing v0.1.26 (*)
│   ├── tracing v0.1.26 (*)
│   ├── tracing-log v0.1.2 (*)
│   ├── tracing v0.1.26 (*)
│   ├── tracing-log v0.1.2 (*)
│   ├── tracing-subscriber v0.2.19 (*)
├── tracing v0.1.26 (*)
├── tracing-log v0.1.2 (*)
└── tracing-subscriber v0.2.19 (*)

Platform

Linux jack-pc 5.10.53-1-MANJARO #1 SMP PREEMPT Mon Jul 26 07:18:28 UTC 2021 x86_64 GNU/Linux

Crates

tracing-appender v0.1.2

Description

One way to structure the description:

tracing-appender creates the specified log file, but does not write anything into it

I tried this code:

pub fn setup_logs(log_level: LevelFilter) -> anyhow::Result<()> {
    // log_panics::init();
    LogTracer::init().context("Cannot setup_logs")?;
    let default_level = format!("[]={}", log_level);
    let name = std::env::current_exe()?
        .file_name()
        .unwrap()
        .to_str()
        .unwrap()
        .to_owned();
    let appender = tracing_appender::rolling::hourly("logs", format!("{}.log", name));
    let (non_blocking_appender, _guard) = tracing_appender::non_blocking(appender);
    let subscriber = fmt()
        .with_thread_names(true)
        .with_writer(non_blocking_appender)
        .with_env_filter(
            &[
                &default_level
            ]
            .join(","),
        )
        .finish();
    tracing::subscriber::set_global_default(subscriber).context("Cannot setup_logs")?;
    Ok(())
}

I expected to see this happen: the log file contains log
Instead, this happened: the log file exists but is empty

[hawkw]

The tracing_appender::non_blocking function returns a non-blocking writer and a drop guard which flushes the writer and shuts it down when dropped. This is intended to be used to ensure the background thread terminates cleanly when the application exits, even in the event of a panic.

However, in order for this to work, the returned guard value has to be held in the program's main function, since dropping it earlier will shut down the writer. In this case, your setup_logs function drops the returned guard as soon as it exits, so the worker thread is shut down immediately.

Try changing your code to something like this, and ensuring that you hold onto the returned guard in your main function:

pub fn setup_logs(log_level: LevelFilter) -> anyhow::Result<tracing_appender::non_blocking::WorkerGuard> {
    // log_panics::init();
    LogTracer::init().context("Cannot setup_logs")?;
    let default_level = format!("[]={}", log_level);
    let name = std::env::current_exe()?
        .file_name()
        .unwrap()
        .to_str()
        .unwrap()
        .to_owned();
    let appender = tracing_appender::rolling::hourly("logs", format!("{}.log", name));
    let (non_blocking_appender, guard) = tracing_appender::non_blocking(appender);
    let subscriber = fmt()
        .with_thread_names(true)
        .with_writer(non_blocking_appender)
        .with_env_filter(
            &[
                &default_level
            ]
            .join(","),
        )
        .finish();
    tracing::subscriber::set_global_default(subscriber).context("Cannot setup_logs")?;
    Ok(guard)
}