File appender writes gibberish

[bubelov]

I just discovered tracing crate and everything worked like a charm with stdout as an output (I'm aware that there are shortcuts and it could have been an one-liner):

let subscriber = Subscriber::builder()
    .with_env_filter(EnvFilter::from_default_env())
    .finish();

tracing::subscriber::set_global_default(subscriber)?;

tracing_log::LogTracer::builder()
    .with_max_level(tracing_core::LevelFilter::current().as_log())
    .init()?;

Here is an example of stdout output:

Aug 08 17:44:52.451  WARN pfd: Starting up
Aug 08 17:44:52.451  WARN pfd: data_dir=/home/igor/.pfd
Aug 08 17:44:52.451  WARN pfd: args=["target/debug/pfd", "serve"]
Aug 08 17:44:52.458  INFO pfd::db: Migrating db schema current_version=3 target_version=Latest
Aug 08 17:44:52.459  INFO pfd::db: Loaded migrations count=3
Aug 08 17:44:52.459  INFO pfd::db: Schema is up to date

I'm happy with default log format and the only extra thing I need is being able to save the same output to a file. After reading the docs and examples, I came up with a following solution:

let log_file_appender = tracing_appender::rolling::never(data_dir, "pfd.log");
let (log_file_appender, _log_file_guard) = tracing_appender::non_blocking(log_file_appender);

let subscriber = Registry::default()
    .with(EnvFilter::from_default_env())
    .with(Layer::new().with_writer(std::io::stdout))
    .with(Layer::new().with_writer(log_file_appender));

tracing::subscriber::set_global_default(subscriber)?;

tracing_log::LogTracer::builder()
    .with_max_level(tracing_core::LevelFilter::current().as_log())
    .init()?;

Full source: https://github.com/bubelov/pfd/blob/master/src/main.rs

It didn't affect stdout output, and it did create a log file, but the log file contents differ from stdout:

^[[2mAug 08 17:50:29.628^[[0m ^[[33m WARN^[[0m pfd: Starting up
^[[2mAug 08 17:50:29.628^[[0m ^[[33m WARN^[[0m pfd: data_dir=/home/igor/.pfd
^[[2mAug 08 17:50:29.628^[[0m ^[[33m WARN^[[0m pfd: args=["target/debug/pfd", "serve"]
^[[2mAug 08 17:50:29.635^[[0m ^[[32m INFO^[[0m pfd::db: Migrating db schema current_version=3 target_version=Latest
^[[2mAug 08 17:50:29.635^[[0m ^[[32m INFO^[[0m pfd::db: Loaded migrations count=3
^[[2mAug 08 17:50:29.635^[[0m ^[[32m INFO^[[0m pfd::db: Schema is up to date

Any ideas on what might be wrong here?

[davidbarsky]

Ah, the gibberish are ANSI color codes. You'll want to disable colors to Layer writing to a file by passing false to tracing_subscriber::fmt::Layer::with_ansi. Here's an example that should work:

let log_file_appender = tracing_appender::rolling::never(data_dir, "pfd.log");
let (log_file_appender, _log_file_guard) = tracing_appender::non_blocking(log_file_appender);

let subscriber = Registry::default()
    .with(EnvFilter::from_default_env())
    .with(Layer::new().with_writer(std::io::stdout))
    .with(Layer::new().with_ansi(false).with_writer(log_file_appender));

tracing::subscriber::set_global_default(subscriber)?;

tracing_log::LogTracer::builder()
    .with_max_level(tracing_core::LevelFilter::current().as_log())
    .init()?;

[hawkw]

Yup, @davidbarsky is correct.

It would be nice if we had a way to reliably detect if we are writing to stdout or to a file, and enable/disable ANSI color codes automatically...but that might take a bit of work. There's an issue for it, though: #1160

[bubelov]

@davidbarsky @hawkw that worked, thanks for your help! Is there a way to force-strip those ANSI color codes in LogTracer? I'm using rocket crate and it doesn't support turning the colors off (rwf2/Rocket#1712). This particular issue will be resolved soon so it's not a big deal, but it looks like a nice feature to have if some other crate tries to push colors to a file

[davidbarsky]

I'm somewhat unfamiliar with Rocket, but—does Rocket setup a logger for you, out of the box? If there's no way to disable that, then I think you'll need for that issue to ship, but other than that, wait for rwf2/Rocket#1579 to land—in, I assume—Rocket 0.6.