Tracing support

[joshka]

I'd like to re-suggest adding tracing support. My current workaround whenever I write a cli is to add clap-verbosity-flag, tracing-log, and add a method which calls level_filter().as_trace() to the parser. This seems like code which should just be part of the verbosity flag and feature flagged in.

Previously:

• make tracing supported as first-class citizen #87 was closed suggested opening an issue.
• Add tracing support parity with log #44 was closed suggesting opening an issue.
  • suggests feature flags
• Add optional support for tracing besides log #37 was closed as another PR had a demo of manually working around the problem

Questions previously raised (paraphrased):

1. How mature is tracing?
   Tracing 0.1 has the same order of magnitude daily / all time downloads as log / clap (200M vs 340M / 300M). While this is not a perfect indication of stability / maturity, it implies that making a breaking change would have large impact on a large portion of the rust ecosystem. Development of tracing happens on its master branch which tracks a long running yet to be released 0.2.x, with changes that are backwards compatible are backported to 0.1.x. The core LevelFilter and Level types are unchanged between the versions. Also, the tracing-core crate (where level and levelfilter ultimately live) contains the following in its readme:

   Application authors will typically not use this crate directly. Instead, they will use the tracing crate, which provides a much more fully-featured API. However, this crate’s API will change very infrequently, so it may be used when dependencies must be very stable.

2. How should this support tracing 0.1, 0.2, .... Does doing so require this library to go to 2.0 to support the next version etc.
   It's fairly common for libs that want to support multiple versions of libs to have versioned feature flags. E.g. here that would be tracing / tracing-0.1 / tracing-0.2 etc. The same question applies to log though. What happens when log 0.5 comes out? I'd recommend adding a tracing feature, and having that be mean the latest version of tracing, while adding a tracing-0.1 feature when tracing-0.2 comes out. You could pre-create a -01 feature and only use that. @epage you likely have much more insight into the right choice here than most people. Perhaps pick an approach that makes sense, or accept one that is good enough?
3. How do tracing users generally feel about still requiring log? If a breaking change is involved in the future, should we allow disabling it?
   IMO, it should be in a feature flag enabled by default for backwards compatibility
4. For tracing, is it more appropriate to return Level or LevelFilter?
   LevelFilter is struct LevelFilter(Option<Level>), and LevelFilter::OFF is LevelFilter(None). It makes some sense to have both as there are two possible use cases for these settings - directly using the value to filter logs, or using the Level to perform further config from other sources (e.g. environment vars, config files, etc). The former is simplest with LevelFilter, the latter is simplest with Option. Having just one loses symmetry with the existing log crate Level/LevelFilter values. I'd recommend keeping both.

So:

• add a tracing feature flag
• add a log feature flag
• make log default
• add fn tracing_level() -> Option<tracing_core::metadata::Level>
• add fn tracing_level_filter() -> tracing_core::metadata::LevelFilter()
• update CI to test these and examples to test both.

I'm going to open another PR that aligns with the recommendations above as the code to do this is much more concise / less ambiguous than the narrative above.

[epage]

IMO, it should be in a feature flag enabled by default for backwards compatibility

Moving built-in functionality into a default feature is not backwards compatible.

[epage]

Thank you for taking the time for stepping through and evaluating the different sides to this that need to be addressed for being able to move this forward as well as including a recommendation.

How mature / stable is tracing for being a 0.1 crate? We just went 1.0 and I don't want to repeatedly bump by taking on a potentially volatile dependency

When I said that, I hadn't accounted for clap's API stability which seems to be less than log and tracing. I was also a lot less familiar with tracing as I don't use it myself (and I still barely use it).

However, the compounding affect of more crates in a stable API is not ideal. If log becomes optional, its also annoying that we would need to dual-implement all of the logic (though it is relatively small though there is still care to be taken as shown in #115). Having versioned features is an option for addressing this.

It didn't help that it came months within a breaking release as I'm getting pressure from people on other projects to not issue breaking releases too often. Its likely been sufficient time since the last breaking release that we could consider one (for making log optional). I keep hoping to get to clap v5 "soon" though its likely not too soon.

So the main question is whether to make a breaking release with log or tracing breaking releases or to version the feature flags. Is there a reason you went with unversioned feature flags?

[joshka]

I'm fairly bullish on low impact breaking changes for things which fit generally into the developer tooling category. Mainly because the people impacted can fix things fairly quickly, especially when the churn is low.

So the main question is whether to make a breaking release with log or tracing breaking releases or to version the feature flags. Is there a reason you went with unversioned feature flags?

Mainly because so far there's just been a single version of both tracing (5 years) and log (7 years), so a versioned feature flag doesn't seem like it adds much value. This is the sort of general rust wide problem though, so perhaps there's a general feel for what is the right thing to do.

Moving built-in functionality into a default feature is not backwards compatible.

Yes but here that only breaks those that are actively using default-features = false, but this crate has no default features that that would affect, so crates doing that are in a weird state already. This seems like one of those places the letter and spirit of the law differ in their usefulness. It might be reasonable to run mini-crater or something and check if anything breaks, or search github for "clap-verbosity-flag = { version = " "default-features=false" - 3 packages total that are hosted on github.

In taking a look at this though, the main problem with making log optional is that the LogLevel trait's default function, which returns Option<log::Level>, that's then used to calculate the verbosity number. To me this suggests just dropping that, implementing the verbosity value as a number and adding levels for Debug/Trace/Off makes sense. That might be a breaking change though.

[epage]

Yes but here that only breaks those that are actively using default-features = false, but this crate has no default features that that would affect, so crates doing that are in a weird state already.

I know people who always set default-features = false and then opt-in to features on an individual basis, rather than accepting what features a crate author chooses for defaults.

In taking a look at this though, the main problem with making log optional is that the LogLevel trait's default function, which returns Optionlog::Level, that's then used to calculate the verbosity number. To me this suggests just dropping that, implementing the verbosity value as a number and adding levels for Debug/Trace/Off makes sense. That might be a breaking change though.

Something I regret is focusing on Level rather than LevelFilter. Looks like there is a log::LevelFilter::from_usize, so they have a stable mapping of number to log level.

This is not true for tracing but if we say that the number corresponds to the log API, then it would be ok to have Verbosity to handle the translation for tracing.

So my current thought

• This is a breaking change
• Change LogLevel::default to return a usize
• Move log behavior behind a log default feature gate (I'd prefer this to be explicit in Cargo.toml, rather than just making the dependency optional)
• Add a tracing feature and the corresponding functionality
• Add or update tests to ensure the two levels always come out the same

Nothing should need to be changed in our CI workflows because we use cargo hack to test all feature combinations. Yes, there are no features today but I maintain a consistent project template, regardless of the needs of a single project (https://github.com/epage/_rust).

[joshka]

That all sounds about right to me. The other thing I'd add is notifying the various repos that implement LogLevel of the replacements (and the related change for the added log levels. It's not a huge number (24, 32 if you include forks), and the users may appreciate the heads up.

[epage]

Hmm, wasn't thinking of that part of this LogLevel::default requires them to emit an arbitrary number.

sigh maybe we need a u8 newtype so people can set the default without knowing numbers and without tying to log?

[joshka]

That makes more sense

[joshka]

Thinking more on this. If a breaking change is an option, then we can do better than using a number to indicate the verbosity and make LogLevel generic over the type of level filter instead. This would be breaking for any implementations of LogLevel, but mostly code compatible with apps that don't implement this manually. Taking a look over the 24 repos that do implement the trait, most are just implementing Debug, Trace, Off etc. 2 or 3 implement feature flag / config -> default log level, and 4 or 5 implement custom help messages, so any transition effort should be fairly small (at least in public code).

This is working prototype code that demonstrates making the LogLevel trait into LogLevel { type = LevelFilter }, with the existing implementations of this being named as-is (could easily type alias these for consistency too), and the new Tracing types named e.g. TracingErrorLevel, TracingInfoLevel etc. (could easily move these into a tracing module too).

Note that this changes the default function to instead deal with the LevelFilter as the primary trait method, rather than Option<Level>, which is generally what interactions with log/tracing need to perform filtering.

The main benefit of this is that if you want log support, you just get log support, if you want tracing support, you just get tracing support.

#![allow(unused)]
use clap::{ArgAction, Args, Parser};
use log::LevelFilter as LogLevelFilter;
use tracing::{level_filters::LevelFilter as TracingLevelFilter, Level as TracingLevel};

fn main() {
    let args = DefaultCli::parse();
    dbg!(args.verbosity.log_level_filter());
    let args = LogCli::parse();
    dbg!(args.verbosity.log_level_filter());
    let args = TracingCli::parse();
    dbg!(args.verbosity.tracing_level_filter());
}

#[derive(Debug, Parser)]
struct DefaultCli {
    #[command(flatten)]
    verbosity: Verbosity,
}

#[derive(Debug, Parser)]
struct LogCli {
    #[command(flatten)]
    verbosity: Verbosity<ErrorLevel>,
}

#[derive(Debug, Parser)]
struct TracingCli {
    #[command(flatten)]
    verbosity: Verbosity<TracingErrorLevel>,
}

#[derive(Debug, Clone, Default, Args)]
#[command(about = None, long_about = None)]
struct Verbosity<L: LogLevel = ErrorLevel> {
    #[arg(
        long,
        short = 'v',
        action = ArgAction::Count,
        global = true,
    )]
    verbose: u8,

    #[arg(
        long,
        short = 'q',
        action = ArgAction::Count,
        global = true,
        conflicts_with = "verbose",
    )]
    quiet: u8,

    #[arg(skip)]
    phantom: std::marker::PhantomData<L>,
}

impl<L: LogLevel<LevelFilter = LogLevelFilter>> Verbosity<L> {
    pub fn log_level(&self) -> Option<log::Level> {
        self.log_level_filter().to_level()
    }

    pub fn log_level_filter(&self) -> LogLevelFilter {
        let verbosity = Self::verbosity() as i16 - self.quiet as i16 + self.verbose as i16;
        let verbosity = verbosity.clamp(0, 5);
        match verbosity {
            0 => LogLevelFilter::Off,
            1 => LogLevelFilter::Error,
            2 => LogLevelFilter::Warn,
            3 => LogLevelFilter::Info,
            4 => LogLevelFilter::Debug,
            5 => LogLevelFilter::Trace,
            _ => unreachable!(),
        }
    }

    fn verbosity() -> u8 {
        match L::default_level_filter() {
            LogLevelFilter::Off => 0,
            LogLevelFilter::Error => 1,
            LogLevelFilter::Warn => 2,
            LogLevelFilter::Info => 3,
            LogLevelFilter::Debug => 4,
            LogLevelFilter::Trace => 5,
        }
    }
}

impl<L: LogLevel<LevelFilter = TracingLevelFilter>> Verbosity<L> {
    pub fn tracing_level(&self) -> Option<TracingLevel> {
        self.tracing_level_filter().into_level()
    }

    pub fn tracing_level_filter(&self) -> TracingLevelFilter {
        let verbosity = Self::tracing_verbosity() as i16 - self.quiet as i16 + self.verbose as i16;
        let verbosity = verbosity.clamp(0, 5);
        match verbosity {
            0 => TracingLevelFilter::OFF,
            1 => TracingLevelFilter::ERROR,
            2 => TracingLevelFilter::WARN,
            3 => TracingLevelFilter::INFO,
            4 => TracingLevelFilter::DEBUG,
            5 => TracingLevelFilter::TRACE,
            _ => unreachable!(),
        }
    }

    fn tracing_verbosity() -> u8 {
        match L::default_level_filter() {
            TracingLevelFilter::OFF => 0,
            TracingLevelFilter::ERROR => 1,
            TracingLevelFilter::WARN => 2,
            TracingLevelFilter::INFO => 3,
            TracingLevelFilter::DEBUG => 4,
            TracingLevelFilter::TRACE => 5,
        }
    }
}

trait LogLevel {
    type LevelFilter;
    fn default_level_filter() -> Self::LevelFilter;
}

#[derive(Debug, Clone, Default)]
struct ErrorLevel;

impl LogLevel for ErrorLevel {
    type LevelFilter = LogLevelFilter;
    fn default_level_filter() -> Self::LevelFilter {
        Self::LevelFilter::Error
    }
}

#[derive(Debug, Clone, Default)]
struct TracingErrorLevel;

impl LogLevel for TracingErrorLevel {
    type LevelFilter = TracingLevelFilter;
    fn default_level_filter() -> Self::LevelFilter {
        Self::LevelFilter::ERROR
    }
}

Edit: PoC PR #124

Edit 2: actually having a new type does help move a bunch of code that is specific to tracing / log to a shared spot. There's one blocker to getting this to be pure conversion methods and generic values, and that's that the log crate doesn't have a From<LevelFilter> to Option<Level> implementation. I submitted a PR to address that in rust-lang/log#644

[epage]

Ah, looks like I looked at things out of order.

If we're including tracing, we should not be bifurcating the entire code base to do so. We should have one type for each level and one type for clap.

[joshka]

If we're including tracing, we should not be bifurcating the entire code base to do so. We should have one type for each level and one type for clap.

Yep, I think the dual types / associated Level/LevelFilter types definitely complicates things a bit too much. I changed this to instead be a few methods that are log specific and a few that are tracing specific.

If there was an open ended number of logging crates to support, this be the wrong decision, but this number should always be fairly small.

[lvanasse]

Hi all, thank you @joshka for the new feature, I've just started using clap-verbosity-flag and wondered if the tracing support was possible and then stumble upon your issue. I've followed the development a bit, and was happy that the new version came out with this feature.

But I still have an error trying to use it in my code, simply rustc doesn't seem to find the function in the lib:

no method named `tracing_level` found for struct `Verbosity` in the current scope

And here's what I did to try to use this feature:

1. I've added inside the Cargo.toml this line: clap-verbosity-flag = {version = "3.0.0", feature = ["tracing"]}
2. I've configure it like the tracing example https://github.com/clap-rs/clap-verbosity-flag/blob/master/examples/tracing.rs . More precisely:

use clap::{Parser, ValueEnum};
use clap_verbosity_flag::Verbosity;

#[derive(Parser, Debug)]
#[command(author, version, about, long_about = None)]
struct Args {
    //...
    #[command(flatten)]
    verbose: Verbosity,
}

fn main() -> anyhow::Result<()> {
    let args = Args::parse();

    let file_appender = tracing_appender::rolling::RollingFileAppender::builder()
        .rotation(Rotation::NEVER)
        .filename_prefix(Utc::now().format("%+").to_string())
        .filename_suffix("test.log")
        .build("logs/")
        .context("Initializing rolling file appender failed")?;

    let (non_blocking, _guard) = tracing_appender::non_blocking(file_appender);

    let stdout = std::io::stdout.with_max_level(&args.verbose.tracing_level()); <--- error here
    tracing_subscriber::fmt()
        .with_ansi(false)
        .with_writer(stdout.and(non_blocking))
        .init();
   
    //...
}

I've also done a cargo clean and made sure it downloaded the 3.0.0, version of the crate.

Any guidance would be appreciated!

Thanks again for the awesome feature :)

[epage]

I tried to reproduce the error you get but wasn't able to

#!/usr/bin/env nargo
---
[dependencies]
clap = { version = "4", features = ["derive"] }
clap-verbosity-flag = { version = "3", default-features = false, features = ["tracing"] }
tracing-subscriber = "*"
tracing = "*"
anyhow = "1"
---

use clap::Parser;
use clap_verbosity_flag::Verbosity;
use tracing_subscriber::fmt::writer::MakeWriterExt;

#[derive(Parser, Debug)]
#[command(author, version, about, long_about = None)]
struct Args {
    //...
    #[command(flatten)]
    verbose: Verbosity,
}

fn main() -> anyhow::Result<()> {
    let args = Args::parse();

    let stdout = std::io::stdout.with_max_level(args.verbose.tracing_level().unwrap_or(tracing::Level::ERROR));
    tracing_subscriber::fmt()
        .with_ansi(false)
        .init();
    Ok(())
}

[epage]

Note: with_max_level doesn't seem to support, through its parameter, being able to turn off logging

[joshka]

Any guidance would be appreciated!

To understand what features are enabled for your app and why, run:

cargo tree --edges features -i clap-verbosity-flag

Note: with_max_level doesn't seem to support, through its parameter, being able to turn off logging

Generally speaking, it makes sense to use the filter and not the Option<Level> (i.e. call tracing_level_filter instead of tracing_level, but None should be the same as turning off the logging. There's a bug in this code.

    let stdout = std::io::stdout.with_max_level(args.verbose.tracing_level().unwrap_or(tracing::Level::ERROR));
    tracing_subscriber::fmt()
        .with_ansi(false)
        .init();

The stdout var is unused. It's a function that creates a writer with a specific level, but it's never passed to the subscriber. The subscriber builder (fmt()) also has a with_max_level method, so you can skip setting things to stdout from the code altogether.

Given that the with_max_level function accepts Into, it could be worthwhile implementing From<Verbosity> for LevelFilter, which would simplify that example to something like:

fn main() -> anyhow::Result<()> {
    let args = Args::parse();

    tracing_subscriber::fmt()
		.with_max_level(args.verbose)
        .with_ansi(false)
        .init();
    Ok(())
}

(PR #128)