Improve env_logger output

[winksaville]

A simple improvement is to change the timestamp to higher precision, see env_logger search for format_timestamp for more info.

let env = env_logger::Env::default();
env_logger::Builder::from_env(env).format_timestamp_micros().init();

A bigger step is to create a Custom log formatter to provide other desired information. The env_log format below has a closure that prints the time, log level, module path, line number and thread_id. You need log, env_logger and humantime crates and this code:

#![feature(thread_id_value)] // Add above all `use` statements


fn main() -> Result<(), Box<dyn Error>> {
    let env = env_logger::Env::default();
    env_logger::Builder::from_env(env).format(|buf, record| {
        let time = std::time::SystemTime::now();
        writeln!(buf, "[{} {:5} {} {} {:2}] {}",
            format_rfc3339_micros(time),
            record.level(),
            if let Some(s) = record.module_path_static() { s } else { "" },
            if let Some(v) = record.line() { v } else { 0 },
            std::thread::current().id().as_u64(),
            record.args())
    }).init();


    // The rest of your `fn main()`
    …
}

Because as_u64() requires the feature thread_id_value an “unstable” rustc is needed. I use nightly and build cargo +nightly build or add rust-toolchain.toml:

$ cat rust-toolchain.toml 
[toolchain]
channel = "nightly"

[elenaf9]

Hi @winksaville, thank you for starting this discussion!
Is this a general discussion about logging in Rust, or are you proposing to change to the existing logging in the rust-libp2p examples?

I personally would think that timestamps are mostly relevant for debugging delays and that in most cases a granularity of seconds would be sufficient. Do you have a specific case in mind where a higher precision is needed?

[winksaville]

This was just FYI, that I thought it might be helpful to others. As for high precision timestamp, I've been using log statements to learn how libp2p works and thus the abundance of logs meant many had the same timestamp. So by adding more precision. I can reference a particular log line as each will have a unique timestamp.

I added record.line because it makes it faster to identify which log statement emitted the the line and the current thread id because it makes it easier to see context switches.

One thing I'd actually like to have is a "task id", by which I mean rust Task as defined by the rust runtime.