Allow configure `fmt::Layer` better (#353)

[tyranron]

Resolves #353

Synopsis

See https://github.com/cucumber-rs/cucumber/issues/353#issue-2770975250 and https://github.com/cucumber-rs/cucumber/issues/353#issuecomment-2602575639 for details:

I'd like to set .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE) on the tracing Layer when running Cucumber, but there is no API for it. I have tried plenty of workarounds, but I always get duplicated, unordered or missing logs. Could you please provide an API for customizing your tracing Layer?

actually, the struct Layered implements the Layer trait. However, you're referring to the fmt::Layer struct and its method, not the Layer trait. I see... and you want to access the initialized fmt::layer() directly to tweak it. Layered::downcast_ref() won't be much help here too, because the required methods have the self receiver, and we don't have Layered::downcast_mut() to mem::swap() it in any way too.

So, the current Cucumber::configure_and_init_tracing() API is quite limiting regarding the initialized fmt::Layer in the way that allows only specifying its .fmt_fields() and .event_format() directly.

Solution

Instead of accepting only .fmt_fields() and .event_format() in Cucumber::configure_and_init_tracing(), let's accept the whole fmt::Layer struct and reconfigure it before passing to the closure.

This doesn't make the API surface harder, since the following code

        World::cucumber()
            .configure_and_init_tracing(
                DefaultFields::new(),
                Format::default().with_ansi(false).without_time(),
                |layer| {
                    tracing_subscriber::registry()
                        .with(LevelFilter::INFO.and_then(layer))
                },
            )

becomes

        World::cucumber()
            .configure_and_init_tracing(
                fmt::layer().fmt_fields(DefaultFields::new()).event_format(
                    Format::default().with_ansi(false).without_time(),
                ),
                |layer| {
                    tracing_subscriber::registry()
                        .with(LevelFilter::INFO.and_then(layer))
                },
            )

but allows tweaking the fmt::layer() much more.

Checklist

• [x] Tests are updated
• [ ] Documentation is updated
• [ ] CHANGELOG entry is added

[tyranron]

@RemiBardon could you try out this new API and report back?

cucumber = { branch = "353-fmt-layer-tweaking", git = "https://github.com/cucumber-rs/cucumber", features = ["tracing"] }

And the API change in the following manner:

This doesn't make the API surface harder, since the following code

        World::cucumber()
            .configure_and_init_tracing(
                DefaultFields::new(),
                Format::default().with_ansi(false).without_time(),
                |layer| {
                    tracing_subscriber::registry()
                        .with(LevelFilter::INFO.and_then(layer))
                },
            )

becomes

        World::cucumber()
            .configure_and_init_tracing(
                fmt::layer().fmt_fields(DefaultFields::new()).event_format(
                    Format::default().with_ansi(false).without_time(),
                ),
                |layer| {
                    tracing_subscriber::registry()
                        .with(LevelFilter::INFO.and_then(layer))
                },
            )

but allows tweaking the fmt::layer() much more.

Thanks!

[RemiBardon]

@tyranron I will have a look later today or tomorrow at the latest. Thank you for the proposal!

[RemiBardon]

Ok so I had a try and it turns out one of the issues I had encountered is that cucumber::tracing uses tracing::instrument with level ERROR. This means logs are full of

ERROR scenario:step: cucumber::tracing: new
ERROR scenario:step: cucumber::tracing: close time.busy=800µs time.idle=754µs

between each step.

I'm pretty sure you use these events internally and used ERROR to avoid filtering, which is why I thought you didn't expose the full Layer in the first place.

I had managed to filter the ERROR events last time I tried, I'll try again in a sec. You should probably hide it though since no one will ever want to see cucumber::tracing error events.

[RemiBardon]

I suppose I need to add

.with_filter(
  tracing_subscriber::filter::Targets::new()
    .with_target("cucumber::tracing", tracing_subscriber::filter::LevelFilter::OFF),
)

to fmt::layer(), but I can't because you expect a Layer and with_filter returns a Layered.

When I return

let targets = vec![
    /* whatever */
    ("cucumber::tracing", LevelFilter::OFF),
];

let default_level: LevelFilter = /* whatever */;

tracing_subscriber::registry().with(
    filter::Targets::new()
        .with_default(default_level)
        .with_targets(targets)
        .and_then(fmt_layer),
)

in the closure, logs become unordered. Well, not completely unordered, but cucumber events don't appear at the right moment. I believe this is because of your internal handling of events that I turned off.

[RemiBardon]

Here are some logs to make my explanation clearer (as a screenshot because colors are very useful in this case):

Without filtering:

With filtering:

---

In both cases, some cucumber events are missing (Whens, Thens…) and some cucumber::tracing events seem to be emitted twice.

I will try to create a MRE so you can add check yourself and investigate.

[RemiBardon]

Here are the full logs, with color:

• cucumber::tracing not filtered:
• cucumber::tracing filtered out:

[!TIP] You can re-run it in your terminal to scroll back to lines which passed very quickly or download a text version.

[RemiBardon]

Here is a MRE:

Cargo.toml

[package]
name = "cucumber-rs-span-logging"
version = "0.1.0"
edition = "2021"
publish = false
authors = ["Rémi Bardon <[email protected]>"]

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

[dependencies]
tracing = { version = "0.1", default-features = false, features = [
    "attributes",
] }

[dev-dependencies]
cucumber = { branch = "353-fmt-layer-tweaking", git = "https://github.com/cucumber-rs/cucumber", default-features = false, features = [
    "macros",
    "tracing",
] }
tokio = { version = "1", default-features = false, features = [
    "rt-multi-thread",
    "macros",
] }
tracing-subscriber = { version = "0.3", default-features = false, features = [
] }

[[test]]
name = "behavior"
harness = false

tests/behavior.rs

use cucumber::World as _;
use tracing::level_filters::LevelFilter;
use tracing_subscriber::{
    filter,
    fmt::{
        self,
        format::{DefaultFields, FmtSpan},
    },
    layer::SubscriberExt as _,
    Layer as _,
};

#[tokio::main]
async fn main() {
    TestWorld::cucumber()
        .configure_and_init_tracing(
            fmt::layer()
                .fmt_fields(DefaultFields::new())
                .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE),
            |fmt_layer| {
                let args = std::env::args().collect::<Vec<_>>();
                let no_cucumber_spans = args.contains(&"@no-cucumber-spans".to_string());

                let targets = if no_cucumber_spans {
                    vec![("cucumber::tracing", LevelFilter::OFF)]
                } else {
                    vec![]
                };

                tracing_subscriber::registry().with(
                    filter::Targets::new()
                        .with_default(LevelFilter::TRACE)
                        .with_targets(targets)
                        .and_then(fmt_layer),
                )
            },
        )
        .run("tests/example.feature")
        .await;
}

// LIB CODE

#[tracing::instrument]
pub fn shave_yaks(n: u8) -> u8 {
    let mut shaved_yaks = 0;
    for n in 0..n {
        shave_yak(n);
        shaved_yaks += 1;
    }
    shaved_yaks
}

#[tracing::instrument]
fn shave_yak(n: u8) {
    tracing::trace!("Shaving yak {n}…");
}

// WORLD

#[derive(Debug, Default, cucumber::World)]
struct TestWorld {
    yak_count: Option<u8>,
    shaved_yaks_count: Option<u8>,
}

// STEPS

use cucumber::{given, then, when};

#[given(expr = "there are {int} yaks")]
fn given_n_yaks(world: &mut TestWorld, n: u8) {
    world.yak_count = Some(n);
}

#[when("I shave yaks")]
fn when_shave_yaks(world: &mut TestWorld) {
    let yak_count = world.yak_count.unwrap();
    world.shaved_yaks_count = Some(shave_yaks(yak_count));
}

#[then(expr = "{int} yaks are shaved")]
fn then_n_yaks_shaved(world: &mut TestWorld, n: u8) {
    assert_eq!(world.shaved_yaks_count, Some(n));
}

tests/example.feature

@no-cucumber-spans
Feature: Example

  Scenario: Shaving yaks
    Given there are 2 yaks
     When I shave yaks
     Then 2 yaks are shaved

And here is what it looks like when ran:

As you can see, Feature and Given are missing when span events are ON, and Given is missing when span events are OFF.

I won't try to reproduce the wrong ordering, it might just be fixed once you figure out what's going on here.

Also, Given is missing here because When is producing span events, but it'd probably be the same with When if Then emitted such events.

[RemiBardon]

@tyranron I forgot to ping you. I don't know if you have notifications on for non-mentionned comments so I just make sure. Sorry for the double notification if it's the case.

[tyranron]

@RemiBardon yes, I'm notified on any changes in this repo. I just haven't had time yet to look into this again. Will try to do it till the next week.

[RemiBardon]

Hey @tyranron! Have you had the chance to look into this again or have planned to?

[RemiBardon]

Hello @tyranron, hope you are doing well!

Do you think you’ll have some time to look into this at some point? It doesn’t impact me as much as when I had reported the issue since I managed to debug the big concurrency thing I had to debug but I’d still love if cucumber-rs could get this improvement 🙂

Best regards, Rémi

[tyranron]

@RemiBardon hi! Thank you for a kind reminder!

I do remember about this PR, and somewhat touched it previous months multiple times. However, it proved to be a little bit deeper rabbit hole than I had time to spend my hands on it. For the next 2 months, I'm unsure to have enough time for investing into cucumber to resolve this. After that, I hope to have this gestalt closed 😅

I'm glad to hear that this doesn't block or impact you, and sorry for not being able to resolve this quicker.

[RemiBardon]

No problem I understand. This already took too much of your time, I should be the one investigating it if I want it to move forward 😌 However I'm not familiar with the internals of tracing and if for you it is a deep rabbit hole then I guess it would be even worse for me 😕

We can close this now if you want to take that virtual weight off your shoulders, and we'll see if I make a comeback one day 😄

[fleetingbytes]

If I may chime it, I have followed this issue since shortly after its creation because I also ran into the tracing configuration limits. Similarly to Remi, it's not blocking me, but I hope that one day @tyranron will achieve the goal of this PR.