.with_ansi(false) doesnt work

[TheGP]

I have a weird symbols added to a log file, I guess its some prettification for terminal output

2024-10-23T00:00:19.268093Z TRACE process_token{^[[3mmint^[[0m^[[2m=^[[0m"FxcVT3p9Mfrw84DPYrNc4o2MHryuL8Wvcmgqrjtbpump"}

But I expected it should be this

2024-10-23T00:00:19.268093Z TRACE process_token{mint="FxcVT3p9Mfrw84DPYrNc4o2MHryuL8Wvcmgqrjtbpump"}

Thats my log writing setup

use tracing::{Level, info, error, trace, warn, debug, instrument};
use tracing_subscriber::{Layer, Registry, prelude::*, filter};
use tracing_appender::rolling::daily;
use tracing_appender::non_blocking::WorkerGuard;
use tracing_subscriber::fmt::format::FmtSpan;

fn main() {
    let file_appender = daily("logs", "app.log");
    let (non_blocking_appender, guard) = tracing_appender::non_blocking(file_appender);

    let error_file_appender = daily("logs", "error.log");
    let (non_blocking_error_appender, error_guard) = tracing_appender::non_blocking(error_file_appender);

    let debug_file_layer = tracing_subscriber::fmt::layer()
        .with_writer(non_blocking_appender)
        .with_ansi(false)
        .with_target(false)
        .with_span_events(FmtSpan::CLOSE)
        .with_filter(filter::LevelFilter::TRACE);

    let console_layer = tracing_subscriber::fmt::layer::<tracing_subscriber::Registry>()
        .with_ansi(true)
        .with_target(false)
        .with_span_events(FmtSpan::CLOSE)
        .with_filter(filter::LevelFilter::INFO);

    let subscriber = Registry::default()
        .with(console_layer)
        .with(debug_file_layer);
        //.with(error_file_layer);

    // Set the subscriber as the default
    tracing::subscriber::set_global_default(subscriber)
        .expect("Failed to set subscriber");

    process_token("test data");
}

#[instrument]
fn process_token(mint: &str) -> Result<(), String> {
    Ok(())
}

Cargo.toml

[package]
name = "tracing-bug"
version = "0.1.0"
edition = "2021"

[dependencies]
tracing = "0.1.40"
tracing-appender = "0.2.3"
tracing-subscriber = "0.3.18"

How I can remove those characters?

And in how many years till a simple problem like this will be fixed? Its not the first time it mentioned

[mladedav]

And in how many years till a simple problem like this will be fixed? Its not the first time it mentioned

People working on this do so in their spare time. I don't think this attitude is constructive.

Can you try using the deubg_file_layer without the console_layer? I think the subscribers interfere with each other when you try the same one multiple times.

[TheGP]

I think it worked like that as I remember, but this is not a solution.

People working on this do so in their spare time. I don't think this attitude is constructive.

I know, that's why I didn't add that the documentation is awful as well as the testing.

The problem is behind sorting, when console layer with ANSI is the last it works correctly:

    let subscriber = Registry::default()
        .with(debug_file_layer)
        .with(error_file_layer)
    .with(console_layer);

I guess it should be marked as a bug.

[kzhui125]

I have this issue too, this is a small code to reproduce:

use anyhow::{anyhow, Result};
use tracing::{error, info, instrument};
use tracing_appender::rolling::{RollingFileAppender, Rotation};
use tracing_subscriber::fmt::format::FmtSpan;
use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::Registry;

#[derive(Debug)]
struct TaskContext {
    task_id: String,
    task_type: String,
}

#[instrument(err)]
async fn risky_operation2(value: i32) -> Result<i32> {
    info!("1");
    if value < 0 {
        info!("2");
        Err(anyhow!("Value must be positive"))
    } else {
        Ok(value * 2)
    }
}

#[instrument(err, skip(context), fields(task_id = %context.task_id, task_type = %context.task_type))]
async fn process_task(context: TaskContext) -> Result<()> {
    info!("Starting task processing");

    if let Err(e) = do_work(&context).await {
        error!(
            task_id = %context.task_id,
            error = %e,
            "Task processing failed"
        );
        return Ok(());
    }

    info!("Task processing completed");

    Ok(())
}

#[tokio::main]
async fn main() {
    // Set up rolling file appender
    let file_appender = RollingFileAppender::new(
        Rotation::DAILY, // or HOURLY, MINUTELY, etc.
        "logs",          // directory to store log files
        "prefix.log",    // prefix for log files
    );

    // Create a file writing layer
    let (non_blocking_appender, _guard) = tracing_appender::non_blocking(file_appender);
    let file_layer = tracing_subscriber::fmt::layer()
        .with_line_number(true)
        .with_thread_ids(true)
        .with_target(true)
        .with_ansi(false) // disable ANSI escape codes in file output
        .with_writer(non_blocking_appender)
        .with_span_events(FmtSpan::FULL);

    // Create a console layer
    let console_layer = tracing_subscriber::fmt::layer()
        .with_line_number(true)
        .with_thread_ids(true)
        .with_target(true)
        .with_ansi(true)
        .with_span_events(FmtSpan::FULL);

    // Combine layers
    let subscriber = Registry::default().with(console_layer).with(file_layer);

    // Set the subscriber as the default
    tracing::subscriber::set_global_default(subscriber).expect("Failed to set tracing subscriber");

    for i in 0..3 {
        let context = TaskContext {
            task_id: format!("task-{}", i),
            task_type: "processing".to_string(),
        };

        tokio::spawn(process_task(context));
    }

    // Wait for some time to let tasks complete
    tokio::time::sleep(tokio::time::Duration::from_secs(2)).await;
}

#[instrument(err, skip(context), fields(task_id = %context.task_id, task_type = %context.task_type))]
async fn do_work(context: &TaskContext) -> Result<(), Box<dyn std::error::Error>> {
    // Simulate some work
    tokio::time::sleep(tokio::time::Duration::from_millis(100)).await;
    Ok(())
}

[package]
name = "t1"
version = "0.1.0"
edition = "2021"

[dependencies]
anyhow = "1"
tokio = { version = "1.0", features = ["full"] }
tracing = "0.1"
tracing-appender = "0.2"
tracing-subscriber = { version = "0.3", features = ["env-filter"] }

[kzhui125]

In this example, I have a file writing layer and a console layer. But the .with_ansi(false) for file writing layer doesn't work.

This should be a bug.

[TheGP]

@kzhui125 many people reported it before but the maintainers are ignoring the issue.

[kadenlnelson]

The documentation and testing could use some work, that's another discussion in itself. There are tons of opportunities for contributing here within that space. FWIW the multi-writer example exhibits the same observed behavior.

After trying to understand how things are layered in the code examples above, I'm conflicted. On one hand, @mladedav's suggestion should work. On the other hand, I don't think it should be expected to work because of how layering is designed today.

Objectively, if I'm layering something then I would expect some of that span data to be inherent to other layered subscribers. Since the formatted fields are rendered and stored in the span's extensions, it sort of makes sense why we see the behavior described above. If I remember the purpose of a Registry correctly, I'm more suspicious that this is where the problem lies. The purpose of a Registry is to store span data that other subscribers can consume (extensions)...

---

Could the layers be hacked together to make it work? Sure, but it feels unwieldy and makes the layering even hard to reason with. Layering should be used for filtering and massaging the data to a sink of subscribers that expect the same written format. Layering doesn't seem appropriate to build a sink of subscribers that expect the data to be written in their own respective format.

Vector's approach to collecting, transforming, and dispatching telemetry is sort of what I'm expecting here. One could say that a program should only log to stdout and have a downstream aggregator do the dirty work of transforming and shipping your data. Then this isn't even a problem anymore. To each their own though.

I say all of this as an outside user of this crate, I would like a maintainer to chime in here, and please correct me if I'm wrong.

[kadenlnelson]

Possibly related (maybe even duplicate) https://github.com/tokio-rs/tracing/issues/3065#issuecomment-2318179647.

[kadenlnelson]

FWIW the multi-writer example exhibits the same observed behavior.

I was wrong here. The example works as expected, but you must use tracing v0.2 which is unreleased at this point in time. I used the commit 91fedc1f45d0d4eaafb46917d57fe0e8b8b467cb to test it with the modified example below.

//! NOTE: This is pre-release documentation for the upcoming tracing 0.2.0 ecosystem. For the
//! release examples, please see the `v0.1.x` branch instead.
//!
//! An example demonstrating how `fmt::Subcriber` can write to multiple
//! destinations (in this instance, `stdout` and a file) simultaneously.

#[path = "fmt/yak_shave.rs"]
mod yak_shave;

use std::io;
use tracing_subscriber::{fmt, subscribe::CollectExt, EnvFilter};

fn main() {
    let dir = tempfile::tempdir().expect("Failed to create tempdir");

    let file_appender = tracing_appender::rolling::hourly(dir.path(), "example.log");
    let (non_blocking, _guard) = tracing_appender::non_blocking(file_appender);

    let collector = tracing_subscriber::registry()
        .with(EnvFilter::from_default_env().add_directive(tracing::Level::TRACE.into()))
        .with(
            fmt::Subscriber::new()
                .with_ansi(true)
                .with_writer(io::stdout),
        )
        .with(
            fmt::Subscriber::new()
                .with_ansi(false)
                .with_writer(non_blocking),
        );
    tracing::collect::set_global_default(collector).expect("Unable to set a global collector");

    let number_of_yaks = 3;
    // this creates a new event, outside of any spans.
    tracing::info!(number_of_yaks, "preparing to shave yaks");

    let number_shaved = yak_shave::shave_all(number_of_yaks);
    tracing::info!(
        all_yaks_shaved = number_shaved == number_of_yaks,
        "yak shaving completed."
    );

    // prints the contents of the log file to stdout
    for entry in std::fs::read_dir(dir.path()).expect("failed to read log dir") {
        let entry = entry.unwrap();
        let path = entry.path();
        println!("contents of {:?}:", path);
        println!("{}", std::fs::read_to_string(path).unwrap());
    }
}

[kaffarell]

You can also just put the debug_file_layer above the console_layer in the registry definition.