Unable to output ANSI logs correctly in Windows powershell

[34205037]

log/src/main.rs

use log::{debug, error, info, trace, warn};

fn main() {
    std::env::set_var("RUST_LOG", "trace");
    env_logger::init();

    trace!("trace");
    debug!("debug");
    info!("info");
    warn!("warn");
    error!("error");
}

tracing/src/main.rs

use tracing::{trace, debug, info, warn, error, Level};
use tracing_subscriber::FmtSubscriber;
use tracing_subscriber::fmt::time::LocalTime;
use time::macros::format_description;

fn main() {
    let timer = LocalTime::new(format_description!("[year]-[month]-[day] [hour]:[minute]:[second].[subsecond digits:3]"));
    let subscriber = FmtSubscriber::builder()
        .with_max_level(Level::TRACE)
        .with_ansi(true)
        .with_timer(timer)
        .finish();
    tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed");

    trace!("trace");
    debug!("debug");
    info!("info");
    let number_of_teams: i32 = 3;
    info!(number_of_teams = "a", "We've got {} teams!", number_of_teams);
    info!(a_bool = true, answer = 42, message = "first example");
    warn!("warn");
    error!("error");
}

Did I miss anything?

[spitfire05]

Running into the same issue, env_logger is properly rendered in poor old cmd.exe, but tracing_subscriber prints out the ansi literals..

[spitfire05]

Interesting thing is that running the same app with cargo run gives proper behavior in windows console host, but running the built executable from target folder gives this buggy behavior.

Anyway, after some digging, I found out that updating the nu-ansi-term dependency to 0.47 seems to fix this bug.

[spitfire05]

So.. this seems more complicated. I definitely can reproduce the issue using nu-ansi-term v0.46, using their examples, but can not replicate using v0.47. That's why I assumed bumping the dependency version should fix it. However, I bumped it in my fork, and the issue is till there 😢 -- so it has to be not the sole reason.

The mentioned fork for reference: https://github.com/spitfire05/tracing/tree/v0.1.x

[spitfire05]

Turns out, the real culprit is that ENABLE_VIRTUAL_TERMINAL_PROCESSING console mode is not set by default for windows legacy console host. See more details in this SO answer: https://superuser.com/a/1300251

It seems like cargo, log-sinks and other libs do set this mode on startup, while tracing_subscriber does not (pure guess here, I was not checking the code of any of those).

I was able to fix this issue by calling mentioned windows API:

#[cfg(windows)]
fn fix_legacy_windows_console() -> Result<()> {
    unsafe {
        use windows::Win32::System::Console::{
            GetConsoleMode, GetStdHandle, SetConsoleMode, CONSOLE_MODE, ENABLE_PROCESSED_OUTPUT,
            ENABLE_VIRTUAL_TERMINAL_PROCESSING, STD_OUTPUT_HANDLE,
        };

        let handle = GetStdHandle(STD_OUTPUT_HANDLE).into_diagnostic()?;
        let mut mode = CONSOLE_MODE::default();
        let mode_ptr = std::ptr::addr_of_mut!(mode);
        GetConsoleMode(handle, mode_ptr).into_diagnostic()?;
        mode |= ENABLE_PROCESSED_OUTPUT;
        mode |= ENABLE_VIRTUAL_TERMINAL_PROCESSING;
        SetConsoleMode(handle, mode).into_diagnostic()?;
    }

    Ok(())
}

I will probably be working on a PR to bring this functionalisty to tracing_subscriber.