Q: How can I have multiple fmt writers with different level?

[oblique]

I'm trying to migrate from simplelog to tracing, however I have a very special case:
I have three writers, different level each (In the real case actually they are three different files).

In my first attempt, I tried to combine multiple fmt::Layer with Registry:

use tracing::{debug, info, info_span, trace, trace_span, warn};
use tracing_subscriber::fmt;
use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::Registry;

fn main() {
    let logger = Registry::default()
        .with(fmt::Layer::default())
        .with(fmt::Layer::default())
        .with(fmt::Layer::default());

    tracing::subscriber::set_global_default(logger).unwrap();

    let x = 1;
    let span = info_span!("info", x);
    let _guard = span.enter();

    let y = 2;
    let span = trace_span!("trace", y);
    let _guard = span.enter();

    info!("ABC");
    warn!("DEF");
    debug!("1234");
    trace!("5678");
}

And the output is:

Feb 22 23:29:02.783  INFO info{x=1x=1x=1}:trace{y=2y=2y=2}: tt: ABC
Feb 22 23:29:02.783  INFO info{x=1x=1x=1}:trace{y=2y=2y=2}: tt: ABC
Feb 22 23:29:02.783  INFO info{x=1x=1x=1}:trace{y=2y=2y=2}: tt: ABC
Feb 22 23:29:02.783  WARN info{x=1x=1x=1}:trace{y=2y=2y=2}: tt: DEF
Feb 22 23:29:02.783  WARN info{x=1x=1x=1}:trace{y=2y=2y=2}: tt: DEF
Feb 22 23:29:02.783  WARN info{x=1x=1x=1}:trace{y=2y=2y=2}: tt: DEF
Feb 22 23:29:02.783 DEBUG info{x=1x=1x=1}:trace{y=2y=2y=2}: tt: 1234
Feb 22 23:29:02.783 DEBUG info{x=1x=1x=1}:trace{y=2y=2y=2}: tt: 1234
Feb 22 23:29:02.783 DEBUG info{x=1x=1x=1}:trace{y=2y=2y=2}: tt: 1234
Feb 22 23:29:02.783 TRACE info{x=1x=1x=1}:trace{y=2y=2y=2}: tt: 5678
Feb 22 23:29:02.784 TRACE info{x=1x=1x=1}:trace{y=2y=2y=2}: tt: 5678
Feb 22 23:29:02.784 TRACE info{x=1x=1x=1}:trace{y=2y=2y=2}: tt: 5678

With this approach the I found two issues:

1. I couldn't apply level filter in the layers
2. Notice the duplication: x=1x=1x=1 and y=2y=2y=2.

My final approach is:

use tracing::{
    debug, info, info_span, metadata::Level, span, trace, trace_span, warn, Event, Subscriber,
};
use tracing_subscriber::fmt;
use tracing_subscriber::layer::{Context, Layer, SubscriberExt};
use tracing_subscriber::registry::LookupSpan;
use tracing_subscriber::Registry;

fn main() {
    let logger = Registry::default()
        .with(fmt::Layer::default())
        .with(FmtWriterLayer::new(Level::DEBUG))
        .with(FmtWriterLayer::new(Level::INFO));

    tracing::subscriber::set_global_default(logger).unwrap();

    let x = 1;
    let span = info_span!("info", x);
    let _guard = span.enter();

    let y = 2;
    let span = trace_span!("trace", y);
    let _guard = span.enter();

    info!("ABC");
    warn!("DEF");
    debug!("1234");
    trace!("5678");
}

struct FmtWriterLayer<S>
where
    S: Subscriber + for<'a> LookupSpan<'a>,
{
    layer: fmt::Layer<S>,
    level: Level,
}

impl<S> FmtWriterLayer<S>
where
    S: Subscriber + for<'a> LookupSpan<'a>,
{
    fn new(level: Level) -> FmtWriterLayer<S> {
        let layer = fmt::Layer::default();

        FmtWriterLayer {
            layer,
            level,
        }
    }
}

impl<S> Layer<S> for FmtWriterLayer<S>
where
    S: Subscriber + for<'a> LookupSpan<'a>,
{
    fn new_span(&self, _attrs: &span::Attributes, _id: &span::Id, _ctx: Context<S>) {
        // intentionally not implemented
    }

    fn on_record(&self, id: &span::Id, values: &span::Record<'_>, ctx: Context<'_, S>) {
        self.layer.on_record(id, values, ctx);
    }

    fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
        if *event.metadata().level() <= self.level {
            self.layer.on_event(event, ctx);
        }
    }
}

And the output is:

Feb 22 23:34:34.345  INFO info{x=1}:trace{y=2}: tracing_multifmt: ABC
Feb 22 23:34:34.345  INFO info{x=1}:trace{y=2}: tracing_multifmt: ABC
Feb 22 23:34:34.345  INFO info{x=1}:trace{y=2}: tracing_multifmt: ABC
Feb 22 23:34:34.345  WARN info{x=1}:trace{y=2}: tracing_multifmt: DEF
Feb 22 23:34:34.346  WARN info{x=1}:trace{y=2}: tracing_multifmt: DEF
Feb 22 23:34:34.346  WARN info{x=1}:trace{y=2}: tracing_multifmt: DEF
Feb 22 23:34:34.346 DEBUG info{x=1}:trace{y=2}: tracing_multifmt: 1234
Feb 22 23:34:34.346 DEBUG info{x=1}:trace{y=2}: tracing_multifmt: 1234
Feb 22 23:34:34.346 TRACE info{x=1}:trace{y=2}: tracing_multifmt: 5678

This is almost what I expect, however one small issue is that trace span is printed in all levels.

So, some questions:

1. Is this a missing feature? Or is there another way?
2. In case of missing feature, how would you like to be added? I was thinking that add_writer_with_level could be implemented in fmt::Subscriber. What are your thoughts? Do you have any suggestion?

[davidbarsky]

Sorry for the delay in responding! Short answer: this is a missing feature and it's not supported in tracing yet. We've started work on supporting this in tracing in #508, but filtering has some subtle behavioral and performance properties.

As for something that works right now, I think your approach is reasonable. As for:

one small issue is that trace span is printed in all levels.

Levels implement Ord and PartialOrd (as they are a usize under the hood), so you'd need to filter for a specific level (while also filtering out other levels).

In case of missing feature, how would you like to be added? I was thinking that add_writer_with_level could be implemented in fmt::Subscriber. What are your thoughts? Do you have any suggestion?

I think #508 is the correct long-term solution for this problem. I'd rather not any additional methods/complex behavior to tracing_subscriber::fmt::Layer, but I'm not sure if @hawkw agrees with me.

[oblique]

Levels implement Ord and PartialOrd (as they are a usize under the hood), so you'd need to filter for a specific level (while also filtering out other levels).

Do you mean that I need to modify ctx of on_event? If yes, I couldn't find how I can remove spans.

[jacekchmiel]

Hi, I have somewhat similar case. I'd like to use tracing-subscriber fmt feature with EnvFilter logic as it's very handy. On top of that, I'd like to measure some span durations for performance analysis. One approach would be to create spans in form of trace_span!("some_span", perf=true) and only measure spans with perf value attached and set to true.

Layered structure provided by tracing-subscriber crate only allows global filtering and no matter what, I'd end with events from my perf spans being logged as their spans must be enabled to allow time measurement.

To allow decoupling of logging and performance measurement I've introduced a simple Dispatch layer. It consists of Vec<Box<dyn Layer<S>>> and essentially all Layer methods are implemented as self.layers.iter().for_each(...). Filtering methods uses simple logic:

• Layer::enabled() is implemented to return true if any of the inner Layers return true
• Layer::register_callsite() returns always if any inner Layer returns always, otherwise it returns sometimes if any inner Layer returns sometimes and it returns never if all inner Layers return never.

This simple approach allows separate filtering for multiple independent use cases, it could also help with multiple log destinations/levels case OP was trying to solve.

I could share the code if anyone would be interested. Also if anyone reads this and sees some obvious flaws in my approach I'd appreciate the feedback.

[hawkw]

@jacekchmiel I'd love to see your solution. I started investigating an implementation of per-layer filtering for tracing-subscriber that's somewhat different, but haven't had the time to finish it, so I'd love to compare notes. Also, if you've done any benchmarking of your solution, that would be very interesting --- ideally, we would want to minimize the overhead of per-layer filtering as much as possible.

[jacekchmiel]

I've created small repo with my solution. You can check it here: https://github.com/jacekchmiel/tracing-layer-dispatch. There is a criterion benchmark that does not show significant performance overhead. It may be possible that the benches are not constructed well. Feel free to open an issue/pull request there if there is something obvious to fix.

[hawkw]

@jacekchmiel ah, as far as I can tell, it looks like your implementation doesn't have a mechanism for an individual layer to disable a span or event and not be notified further about that span or event, even if another layer does enable it? I think that's where most of the potential overhead we're trying to avoid would be.

[jacekchmiel]

@hawkw big thanks for the feedback! You are completely right, this is not only a potential performance problem but actually it makes my solution not work as I intended.

I'll try to think about it a little more. Hopefully I'll find some fairly simple solution with acceptable performance that will work as a workaround until you land proper layer filtering feature.

[hawkw]

I can try to get the work I've been doing into a state where we can look at merging and iterating on it, since it seems like there's a lot of demand.

[jacekchmiel]

That would be great! I'd be happy to help if there is such need. For example, I could look at the feature to test it and check if it fits my use-case.

[kehlert]

If anyone else comes across this issue, here's an outline of code that works for the most recent version of the code on Github. I copied it out of a larger codebase, but I think the basic idea is clear (just don't expect it to work if you copy-paste). I'm far from a tracing expert, but it appears to get the job done (although I'm sure with some runtime cost). If somebody who knows more has any suggestions, they'd be appreciated.

fn setup() {
    let my_subscriber = Subscriber::new()
        .with_writer(MakeMyWriter {})
        .with_target(false)
        .with_ansi(false);

    let collector = tracing_subscriber::registry()
        .with(LevelFilter::from_level(Level::INFO))
        .with(
            Subscriber::new()
                .with_writer(std_out_writer)
                .with_target(false),
        )
        .with(
            Subscriber::new()
                .with_writer(file_writer)
                .with_target(false),
        )
        .with(MySubscriberWrapper {
            inner: my_subscriber,
        });

    tracing::collect::set_global_default(collector).expect("unable to set tracing collector");
}

struct MySubscriberWrapper<S> {
    inner: S,
}

impl<S: Subscribe<C>, C: tracing::Collect> Subscribe<C> for MySubscriberWrapper<S> {
    fn on_event(&self, event: &Event<'_>, context: Context<'_, C>) {
        if *event.metadata().level() == Level::ERROR {
            self.inner.on_event(event, context);
        }
    }
}

[a1ph]

It does not work for me (using tracing-subscriber = "0.2.17").

    tracing_subscriber::registry()
        .with(console_subscriber)
        .init();

fails with

296 |         .with(console_subscriber)
    |               ^^^^^^^^^^^^^^^^^^ the trait `__tracing_subscriber_Layer<Registry>` is not implemented for `FmtSubscriber`

@kehlert Any hints?

[kehlert]

It does not work for me (using tracing-subscriber = "0.2.17").

    tracing_subscriber::registry()
        .with(console_subscriber)
        .init();

fails with

296 |         .with(console_subscriber)
    |               ^^^^^^^^^^^^^^^^^^ the trait `__tracing_subscriber_Layer<Registry>` is not implemented for `FmtSubscriber`

@kehlert Any hints?

I'm using code directly from Github, and not via crates.io. That might be the difference.

Edit: Also noticed that the trait you're referring to is here: https://docs.rs/tracing-subscriber/0.2.17/tracing_subscriber/prelude/index.html

Looks like tracing_subscriber_layer::Layer<Registry> is not implemented for the console_subscriber.

[kehlert]

It does not work for me (using tracing-subscriber = "0.2.17").

    tracing_subscriber::registry()
        .with(console_subscriber)
        .init();

fails with

296 |         .with(console_subscriber)
    |               ^^^^^^^^^^^^^^^^^^ the trait `__tracing_subscriber_Layer<Registry>` is not implemented for `FmtSubscriber`

@kehlert Any hints?

@alamb, here's a fully working example. You should be able to copy-paste it into a fresh crate and it'll work.

Cargo.toml

[package]
name = "tracing_test"
version = "0.1.0"
authors = ["MyName"]
edition = "2018"

# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html

[dependencies]
tracing = {git="https://github.com/tokio-rs/tracing"}
tracing-appender = {git="https://github.com/tokio-rs/tracing"}
tracing-subscriber = {git="https://github.com/tokio-rs/tracing"} #need CollectExt

main.rs

use tracing::Level;
use tracing::{error, info, info_span, Event};
use tracing_subscriber::filter::LevelFilter;
use tracing_subscriber::fmt::Subscriber;
use tracing_subscriber::subscribe::CollectExt;
use tracing_subscriber::subscribe::Context;
use tracing_subscriber::subscribe::Subscribe;

fn main() {
    let _guard = setup_logger();
    let span = info_span!("my span");
    let _enter = span.enter();
    info!("this is processed only by stdout");
    error!("this is processed by all subscribers");
}

fn setup_logger() -> tracing_appender::non_blocking::WorkerGuard {
    //these non-blocking writers can drop messages if queue > 128,000
    let (std_out_writer, guard) = tracing_appender::non_blocking(std::io::stdout());

    let collector = tracing_subscriber::registry()
        .with(LevelFilter::from_level(Level::INFO))
        .with(
            Subscriber::new()
                .with_writer(std_out_writer)
                .with_target(false),
        );

    let my_subscriber = Subscriber::new()
        .with_writer(MakeMyWriter {})
        .with_target(false);

    let collector = collector.with(MyFilter(my_subscriber));

    tracing::collect::set_global_default(collector).expect("unable to set tracing collector");
    guard
}

struct MyFilter<S>(S);

impl<S: Subscribe<C>, C: tracing::Collect> Subscribe<C> for MyFilter<S> {
    fn on_event(&self, event: &Event, context: Context<C>) {
        if *event.metadata().level() == Level::ERROR {
            self.0.on_event(event, context);
        }
    }
}

struct MakeMyWriter {}

struct MyWriter {}

impl<'a> tracing_subscriber::fmt::MakeWriter<'a> for MakeMyWriter {
    type Writer = MyWriter;

    fn make_writer(&'a self) -> Self::Writer {
        MyWriter {}
    }
}

impl std::io::Write for MyWriter {
    fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
        println!("MyWriter is writing: {}", std::str::from_utf8(buf).unwrap());
        Ok(buf.len())
    }

    fn flush(&mut self) -> std::io::Result<()> {
        Ok(())
    }
}

Here is the output:

[alamb]

@tustvold and @jacobmarble -- FYI (check out the example from @kehlert in #597 (comment))