1

I do not understand why this code doesn't print anything on my terminal:

use tracing::info;

fn main() {
    init();

    info!("test me");

    println!("i should have info! message before this")
}

pub fn init() {
    let (non_blocking, _guard) = tracing_appender::non_blocking(std::io::stdout());

    tracing_subscriber::fmt()
        // .with_writer(non_blocking) // with this info! is not printed
        .init();
}
kmdreko
  • 42,554
  • 6
  • 57
  • 106
Fred Hors
  • 3,258
  • 3
  • 25
  • 71

1 Answers1

4

tracing_appender doesn't write the logs to its output immediately, but buffers them for some time. Therefore, this info output is stored in the buffer, println executes, main returns, and program is terminated before the log gets printed.

To ensure that the logs will be flushed, you must use the returned guard value. According to documentation, you're expected to store it in variable which is dropped after all the logs were sent - for example, at the end of main; therefore, this will almost work:

use tracing::info;

fn main() {
    let guard = init();

    info!("test me");

    println!("i should have info! message before this")
}

pub fn init() -> tracing_appender::non_blocking::WorkerGuard {
    let (non_blocking, guard) = tracing_appender::non_blocking(std::io::stdout());

    tracing_subscriber::fmt()
        .with_writer(non_blocking)
        .init();

    guard
}

I say "almost", because it will still first execute println!:

i should have info! message before this
2022-08-03T18:08:51.728620Z  INFO playground: test me

It's not advised to mix tracing logs and prints in general, precisely because of the buffering. In this specific case, however, it's possible to get the result you want - just add drop(guard) before println.

kmdreko
  • 42,554
  • 6
  • 57
  • 106
Cerberus
  • 8,879
  • 1
  • 25
  • 40
  • Thank you very much. It works. Is there a way to not have in `main()` the code that drop the `guard` coming from `init()`? – Fred Hors Aug 03 '22 at 18:51
  • In the provided code, guard will be dropped automatically at the end of `main`, you don't have to do this explicitly. Explicit `drop` is used only to ensure ordering between `tracing` and non-`tracing` logs. – Cerberus Aug 03 '22 at 19:00
  • Yeah. I know. But I don't want to clippy warnings in console. Should I disable clippy warning about `unused variable` check? – Fred Hors Aug 03 '22 at 19:02
  • 1
    I can use `let _guard = init();` and it does not complain about. – Fred Hors Aug 03 '22 at 19:06
  • There is also a similar question in the tracing issues https://github.com/tokio-rs/tracing/issues/1493#issuecomment-894352695 – joseluisq Aug 02 '23 at 23:16