Implement tracing crate integration (#258, #213)

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

Co-authored-by: Kai Ren <[email protected]>

.github/workflows/ci.yml

@@ -81,6 +81,7 @@ jobs:
           - output-json
           - output-junit
           - libtest
+          - tracing
     runs-on: ubuntu-latest
     steps:
       - uses: actions/checkout@v3

CHANGELOG.md

@@ -6,6 +6,25 @@ All user visible changes to `cucumber` crate will be documented in this file. Th
 
 
 
+## [0.20.0] · 2023-??-??
+[0.20.0]: /../../tree/v0.20.0
+
+[Diff](/../../compare/v0.19.1...v0.20.0) | [Milestone](/../../milestone/24)
+
+### BC Breaks
+
+- Added `Log` variant to `event::Scenario`. ([#258])
+
+### Added
+
+- [`tracing`] crate integration behind the `tracing` feature flag. ([#213], [#258])
+
+[#213]: /../../issues/213
+[#258]: /../../pull/258
+
+
+
+
 ## [0.19.1] · 2022-12-29
 [0.19.1]: /../../tree/v0.19.1
 
@@ -680,6 +699,7 @@ All user visible changes to `cucumber` crate will be documented in this file. Th
 [`clap`]: https://docs.rs/clap
 [`gherkin`]: https://docs.rs/gherkin
 [`gherkin_rust`]: https://docs.rs/gherkin_rust
+[`tracing`]: https://docs.rs/tracing
 
 [Cargo feature]: https://doc.rust-lang.org/cargo/reference/features.html
 [Cucumber Expressions]: https://cucumber.github.io/cucumber-expressions

Cargo.toml

@@ -19,7 +19,7 @@ repository = "https://github.com/cucumber-rs/cucumber"
 readme = "README.md"
 categories = ["asynchronous", "development-tools::testing"]
 keywords = ["cucumber", "testing", "bdd", "atdd", "async"]
-include = ["/src/", "/tests/json.rs", "/tests/junit.rs", "/tests/libtest.rs", "/tests/wait.rs", "/LICENSE-*", "/README.md", "/CHANGELOG.md"]
+include = ["/src/", "/tests/json.rs", "/tests/junit.rs", "/tests/libtest.rs", "/tests/tracing.rs", "/tests/wait.rs", "/LICENSE-*", "/README.md", "/CHANGELOG.md"]
 
 [package.metadata.docs.rs]
 all-features = true
@@ -37,12 +37,14 @@ output-json = ["dep:Inflector", "dep:serde", "dep:serde_json", "timestamps"]
 output-junit = ["dep:junit-report", "timestamps"]
 # Enables timestamps collecting for all events.
 timestamps = []
+# Enables integraion with `tracing` crate.
+tracing = ["dep:crossbeam-utils", "dep:tracing", "dep:tracing-subscriber"]
 
 [dependencies]
 async-trait = "0.1.43"
 clap = { version = "4.0.27", features = ["derive", "wrap_help"] }
 console = "0.15"
-derive_more = { version = "0.99.17", features = ["as_ref", "deref", "deref_mut", "display", "error", "from", "into"], default_features = false }
+derive_more = { version = "0.99.17", features = ["as_ref", "deref", "deref_mut", "display", "error", "from", "from_str", "into"], default_features = false }
 drain_filter_polyfill = "0.1.2"
 either = "1.6"
 futures = "0.3.17"
@@ -53,6 +55,7 @@ is-terminal = "0.4.4"
 itertools = "0.10"
 linked-hash-map = "0.5.3"
 once_cell = "1.13"
+pin-project = "1.0"
 regex = "1.5.5"
 sealed = "0.4"
 smart-default = "0.6"
@@ -71,6 +74,11 @@ Inflector = { version = "0.11", default-features = false, optional = true }
 # "output-junit" feature dependencies.
 junit-report = { version = "0.8", optional = true }
 
+# "tracing" feature dependencies.
+crossbeam-utils = { version = "0.8.14", optional = true }
+tracing = { version = "0.1", optional = true }
+tracing-subscriber = { version = "0.3.16", optional = true }
+
 [dev-dependencies]
 derive_more = "0.99.17"
 rand = "0.8"
@@ -89,6 +97,11 @@ required-features = ["output-junit"]
 name = "libtest"
 required-features = ["libtest"]
 
+[[test]]
+name = "tracing"
+required-features = ["tracing"]
+harness = false
+
 [[test]]
 name = "wait"
 required-features = ["libtest"]

book/src/SUMMARY.md

@@ -21,6 +21,7 @@
     - [JUnit XML report](output/junit.md)
     - [Cucumber JSON format](output/json.md)
     - [Multiple outputs](output/multiple.md)
+    - [`tracing` integration](output/tracing.md)
     - [IntelliJ Rust integration](output/intellij.md)
 - [Architecture](architecture/index.md)
     - [Custom `Parser`](architecture/parser.md) 

book/src/output/index.md

@@ -7,4 +7,5 @@ This chapter describes possible way and tweaks of outputting test suite results.
 2. [JUnit XML report](junit.md)
 3. [Cucumber JSON format](json.md)
 4. [Multiple outputs](multiple.md)
-5. [IntelliJ Rust integration](intellij.md)
+5. [`tracing` integration](tracing.md)
+6. [IntelliJ Rust integration](intellij.md)

book/src/output/terminal.md

@@ -213,9 +213,9 @@ async fn main() {
 
 
 
-## Manual printing
+## Debug printing and/or logging
 
-Though [`cucumber`] crate doesn't capture any manual printing produced in a [step] matching function (such as [`dbg!`] or [`println!`] macros), it may be [quite misleading][#177] to produce and use it for debugging purposes. The reason is simply because [`cucumber`] crate executes [scenario]s concurrently and [normalizes][3] their results before outputting, while any manual print is produced instantly at the moment of its [step] execution.
+Though [`cucumber`] crate doesn't capture any manual debug printing produced in a [step] matching function (such as [`dbg!`] or [`println!`] macros), it may be [quite misleading][#177] to produce and use it for debugging purposes. The reason is simply because [`cucumber`] crate executes [scenario]s concurrently and [normalizes][3] their results before outputting, while any manual print is produced instantly at the moment of its [step] execution.
 
 > __WARNING:__ Moreover, manual printing will very likely interfere with [default][1] interactive pretty-printing.
 
@@ -348,7 +348,48 @@ async fn main() {
 ```
 ![record](../rec/output_terminal_custom.gif)
 
-> __NOTE__: The custom print is still output before its [step], because is printed during the [step] execution. 
+> __NOTE__: The custom print is still output before its [step], because is printed during the [step] execution.
+
+Much better option for debugging would be using [`tracing` crate integration](tracing.md) instead of [`dbg!`]/[`println!`] for doing logs.
+
+```rust
+# extern crate cucumber;
+# extern crate tokio;
+# extern crate tracing;
+#
+use std::{
+    sync::atomic::{AtomicUsize, Ordering},
+    time::Duration,
+};
+
+use cucumber::{given, then, when, World as _};
+use tokio::time;
+
+#[derive(cucumber::World, Debug, Default)]
+struct World;
+
+#[given(regex = r"(\d+) secs?")]
+#[when(regex = r"(\d+) secs?")]
+#[then(regex = r"(\d+) secs?")]
+async fn sleep(_: &mut World, secs: u64) {
+    static ID: AtomicUsize = AtomicUsize::new(0);
+
+    let id = ID.fetch_add(1, Ordering::Relaxed);
+
+    tracing::info!("before {secs}s sleep: {id}");
+    time::sleep(Duration::from_secs(secs)).await;
+    tracing::info!("after {secs}s sleep: {id}");
+}
+
+#[tokio::main]
+async fn main() {
+    World::cucumber()
+        .init_tracing()
+        .run("tests/features/wait")
+        .await;
+}
+```
+![record](../rec/tracing_basic_writer.gif)
 
 
 

book/src/output/tracing.md

@@ -0,0 +1,119 @@
+`tracing` integration
+=====================
+
+[`Cucumber::init_tracing()`] (enabled by `tracing` feature in `Cargo.toml`) initializes global [`tracing::Subscriber`] that intercepts all the [`tracing` events][1] and transforms them into [`event::Scenario::Log`]s. Each [`Writer`] can handle those [`event::Scenario::Log`]s in its own way. [`writer::Basic`], for example, emits all the [`event::Scenario::Log`]s only whenever [scenario] itself is outputted.
+
+```rust
+# extern crate cucumber;
+# extern crate tokio;
+# extern crate tracing;
+#
+use std::{
+    sync::atomic::{AtomicUsize, Ordering},
+    time::Duration,
+};
+
+use cucumber::{given, then, when, World as _};
+use tokio::time;
+
+#[derive(cucumber::World, Debug, Default)]
+struct World;
+
+#[given(regex = r"(\d+) secs?")]
+#[when(regex = r"(\d+) secs?")]
+#[then(regex = r"(\d+) secs?")]
+async fn sleep(_: &mut World, secs: u64) {
+    static ID: AtomicUsize = AtomicUsize::new(0);
+
+    let id = ID.fetch_add(1, Ordering::Relaxed);
+
+    tracing::info!("before {secs}s sleep: {id}");
+    time::sleep(Duration::from_secs(secs)).await;
+    tracing::info!("after {secs}s sleep: {id}");
+}
+
+#[tokio::main]
+async fn main() {
+    World::cucumber()
+        .init_tracing()
+        .run("tests/features/wait")
+        .await;
+}
+```
+![record](../rec/tracing_basic_writer.gif)
+
+
+
+
+## Loosing [`tracing::Span`]
+
+[`tracing::Span`] is used to wire emitted [`tracing` events][1] (logs) to concrete [scenario]s: each [scenario] is executed in its own [`tracing::Span`]. In case a [`tracing` event][1] is emitted outside the [`tracing::Span`] of a [scenario], it will be propagated to every running [scenario] at the moment.
+
+```rust
+# extern crate cucumber;
+# extern crate tokio;
+# extern crate tracing;
+#
+# use std::{
+#     sync::atomic::{AtomicUsize, Ordering},
+#     time::Duration,
+# };
+# 
+# use cucumber::{given, then, when, World as _};
+# use tokio::time;
+# 
+# #[derive(cucumber::World, Debug, Default)]
+# struct World;
+# 
+# #[given(regex = r"(\d+) secs?")]
+# #[when(regex = r"(\d+) secs?")]
+# #[then(regex = r"(\d+) secs?")]
+# async fn sleep(_: &mut World, secs: u64) {
+#     static ID: AtomicUsize = AtomicUsize::new(0);
+# 
+#     let id = ID.fetch_add(1, Ordering::Relaxed);
+# 
+#     tracing::info!("before {secs}s sleep: {id}");
+#     time::sleep(Duration::from_secs(secs)).await;
+#     tracing::info!("after {secs}s sleep: {id}");
+# }
+# 
+#[tokio::main]
+async fn main() {
+    // Background task outside of any scenario.
+    tokio::spawn(async {
+        let mut id = 0;
+        loop {
+            time::sleep(Duration::from_secs(3)).await;
+            tracing::info!("Background: {id}");
+            id += 1;
+        }
+    });
+
+    World::cucumber()
+        .init_tracing()
+        .run("tests/features/wait")
+        .await;
+}
+```
+![record](../rec/tracing_outside_span.gif)
+
+As we see, `Background: 2`/`3`/`4` is shown in multiple [scenario]s, while being emitted only once each.
+
+> __TIP__: If you're [`spawn`]ing a [`Future`] inside your [step] matching function, consider to [propagate][2] its [`tracing::Span`] into the [`spawn`]ed [`Future`] for outputting its logs properly.
+
+
+
+
+[`Cucumber::init_tracing()`]: https://docs.rs/cucumber/*/cucumber/struct.Cucumber.html#method.init_tracing
+[`event::Scenario::Log`]: https://docs.rs/cucumber/*/cucumber/event/enum.Scenario.html#variant.Log
+[`Future`]: https://doc.rust-lang.org/stable/std/future/trait.Future.html
+[`spawn`]: https://docs.rs/tokio/*/tokio/fn.spawn.html
+[`tracing::Span`]: https://docs.rs/tracing/*/tracing/struct.Span.html
+[`tracing::Subscriber`]: https://docs.rs/tracing/*/tracing/trait.Subscriber.html
+[`Writer`]: https://docs.rs/cucumber/*/cucumber/writer/trait.Writer.html
+[`writer::Basic`]: https://docs.rs/cucumber/*/cucumber/writer/struct.Basic.html
+[scenario]: https://cucumber.io/docs/gherkin/reference#example
+[step]: https://cucumber.io/docs/gherkin/reference#steps
+[1]: https://docs.rs/tracing/*/tracing/index.html#events
+[2]: https://docs.rs/tracing/*/tracing/struct.Span.html#method.enter

src/cucumber.rs

@@ -66,7 +66,7 @@ where
     /// [`Runner`] executing [`Scenario`]s and producing [`event`]s.
     ///
     /// [`Scenario`]: gherkin::Scenario
-    runner: R,
+    pub(crate) runner: R,
 
     /// [`Writer`] outputting [`event`]s to some output.
     writer: Wr,

src/event.rs

@@ -495,6 +495,9 @@ pub enum Scenario<World> {
     /// [`Step`] event.
     Step(Arc<gherkin::Step>, Step<World>),
 
+    /// [`Scenario`]'s log entry is emitted.
+    Log(String),
+
     /// [`Scenario`] execution being finished.
     ///
     /// [`Scenario`]: gherkin::Scenario
@@ -512,6 +515,7 @@ impl<World> Clone for Scenario<World> {
                 Self::Background(Arc::clone(bg), ev.clone())
             }
             Self::Step(st, ev) => Self::Step(Arc::clone(st), ev.clone()),
+            Self::Log(msg) => Self::Log(msg.clone()),
             Self::Finished => Self::Finished,
         }
     }