tracing integration (#213)

[ilslv]

Synopsis

#213

Solution

Implement tracing integration under tracing feature. Writers integrations will be done in separate PRs.

Checklist

• Created PR:
  • In draft mode
  • Name contains Draft: prefix
  • Name contains issue reference
  • Has assignee
• Documentation is updated (if required)
• Tests are updated (if required)
• Changes conform code style
• CHANGELOG entry is added (if required)
• FCM (final commit message) is posted
  • and approved
• Review is completed and changes are approved
• Before merge:
  • Milestone is set
  • PR's name and description are correct and up-to-date
  • Draft: prefix is removed
  • All temporary labels are removed

[ilslv]

@tyranron

Current integration looks like this:

Basically we now run each scenario in tracing::Span, intercept traces, lookup in which Scenario it was done, emit event::Scenario::Log and each Writer does it's job. writer::Basic outputs Scenario's logs only when Scenario is outputted to simplify debugging.

The only question remains: what to do with traces that aren't attached to special tracing::Span? This can happen when spawn(async { ... }) is done or logging from background task.
We can:

1. Ignore them entirely
2. Emit them all at the end
3. Duplicate for each running Scenario with event::Scenario::Log and special flag.
4. Emit event::Cucumber::Log (not event::Scenario::Log) and let the Writer decide.

Strangely enough, but I would go with option number 3, as it gives the most flexibility. And each Writer can decide on their own, whether to write or skip those traces.

[ilslv]

@tyranron

Strangely enough, but I would go with option number 3, as it gives the most flexibility. And each Writer can decide on their own, whether to write or skip those traces.

To illustrate my proposal more, if we change function from

#[given(regex = r"(\d+) secs?")]
#[when(regex = r"(\d+) secs?")]
#[then(expr = "{u64} sec(s)")]
async fn step(world: &mut World, secs: CustomU64) {
    tracing::info!("before waiting {secs}s");
    time::sleep(Duration::from_secs(*secs) / 2).await;
    tracing::info!("in between waiting {secs}s");
    time::sleep(Duration::from_secs(*secs) / 2).await;
    tracing::info!("after waiting {secs}s");

    world.0 += 1;
    assert!(world.0 < 4, "Too much!");
}

to

#[given(regex = r"(\d+) secs?")]
#[when(regex = r"(\d+) secs?")]
#[then(expr = "{u64} sec(s)")]
async fn step(world: &mut World, secs: CustomU64) {
    tracing::info!("before waiting {secs}s");
    time::sleep(Duration::from_secs(*secs) / 2).await;
    // Not attached to current `Span`.
    tokio::spawn(async move {
        tracing::info!("in between waiting {secs}s");
    });
    time::sleep(Duration::from_secs(*secs) / 2).await;
    tracing::info!("after waiting {secs}s");

    world.0 += 1;
    assert!(world.0 < 4, "Too much!");
}

We'll get following output:

For @serial Scenarios everything is the same except for missing scenario Span in output, but for concurrently run Scenarios we see all in between waiting ... messages.

[tyranron]

@ilslv yes, I agree that the option 3 seems to be the most reasonable in this case.

[tyranron]

@ilslv also, is it possible to reasonable feature-gate this tracing integration? I believe most of the time people won't need it, so we can avoid increasing compilations times redundantly.

[ilslv]

FCM

Implement `tracing` crate integration (#258, #213)

- add `tracing` Cargo feature
- add `Log` variant to `event::Scenario`
- describe "`tracing` integration" Book chapter

[tyranron]

@ilslv mostly OK, but some minor stuff still to be polished.

[tyranron]

I also dislike the monstrocity happening in runner/basic.rs. It has grown too much. But that's the topic for a different PR in different times.