tracing integration (#213)

.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
+
+- Added integration with `tracing` crate under `tracing` feature gate. ([#258], [#213])
+
+[#213]: /../../issues/213
+[#258]: /../../pull/258
+
+
+
+
 ## [0.19.1] · 2022-12-29
 [0.19.1]: /../../tree/v0.19.1
 

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,13 @@ output-json = ["dep:Inflector", "dep:serde", "dep:serde_json", "timestamps"]
 output-junit = ["dep:junit-report", "timestamps"]
 # Enables timestamps collecting for all events.
 timestamps = []
+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 +54,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 +73,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 +96,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/tracing.md

@@ -0,0 +1,113 @@
+`tracing` integration
+=====================
+
+[`Cucumber::init_tracing()`] (enabled by `tracing` feature in `Cargo.toml`) initializes global [`tracing::Subscriber`] that intercepts all [`tracing` events][1] and transforms them into [`event::Scenario::Log`]s. Each [`Writer`] can handle those events in its own way. [`writer::Basic`] for example, emits all `Scenario` logs, only when `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)
+
+---
+
+Tracking which `Scenario` log is emitted in is done with [`tracing::Span`]s: each `Scenario` is executed in its own [`tracing::Span`]. In case [`tracing` event][1] is emitted outside the [`tracing::Span`] of a `Scenario`, it will be propagated to every running `Scenario`:
+
+```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)
+
+`Background: 2`/`3`/`4` is shown in multiple `Scenario`s. 
+
+
+
+
+[`Cucumber::init_tracing()`]: https://docs.rs/cucumber/latest/cucumber/struct.Cucumber.html#method.init_tracing
+[`event::Scenario::Log`]: https://docs.rs/cucumber/latest/cucumber/event/enum.Scenario.html#variant.Log
+[`tracing::Span`]: https://docs.rs/tracing/latest/tracing/struct.Span.html
+[`tracing::Subscriber`]: https://docs.rs/tracing/latest/tracing/trait.Subscriber.html
+[`Writer`]: https://docs.rs/cucumber/latest/cucumber/writer/trait.Writer.html
+[`writer::Basic`]: https://docs.rs/cucumber/latest/cucumber/writer/struct.Basic.html
+
+[1]: https://docs.rs/tracing/latest/tracing/index.html#events

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`] log 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,
         }
     }

src/future.rs

@@ -2,6 +2,12 @@
 
 use std::{future::Future, pin::Pin, task};
 
+use futures::{
+    future::{Either, FusedFuture, Then},
+    FutureExt as _,
+};
+use pin_project::pin_project;
+
 /// Wakes the current task and returns [`task::Poll::Pending`] once.
 ///
 /// This function is useful when we want to cooperatively give time to a task
@@ -31,3 +37,121 @@ impl Future for YieldNow {
         }
     }
 }
+
+/// Return type of [`FutureExt::then_yield()`].
+type ThenYield<F, O> = Then<F, YieldThenReturn<O>, fn(O) -> YieldThenReturn<O>>;
+
+/// [`Future`] extensions.
+pub(crate) trait FutureExt: Future + Sized {
+    /// Yields after [`Future`] is resolved to allow other [`Future`]s to make
+    /// progress.
+    fn then_yield(self) -> ThenYield<Self, Self::Output> {
+        self.then(YieldThenReturn::new)
+    }
+}
+
+impl<T: Future> FutureExt for T {}
+
+/// [`Future`] that returns [`task::Poll::Pending`] once and then returns the
+/// value.
+#[derive(Debug)]
+#[pin_project]
+pub(crate) struct YieldThenReturn<V> {
+    /// Returned value.
+    value: Option<V>,
+
+    /// [`YieldNow`] [`Future`].
+    #[pin]
+    r#yield: YieldNow,
+}
+
+impl<V> YieldThenReturn<V> {
+    /// Creates new [`YieldThenReturn`].
+    const fn new(v: V) -> Self {
+        Self {
+            value: Some(v),
+            r#yield: yield_now(),
+        }
+    }
+}
+
+impl<V> Future for YieldThenReturn<V> {
+    type Output = V;
+
+    fn poll(
+        self: Pin<&mut Self>,
+        cx: &mut task::Context<'_>,
+    ) -> task::Poll<Self::Output> {
+        let this = self.project();
+        task::ready!(this.r#yield.poll(cx));
+        this.value
+            .take()
+            .map_or(task::Poll::Pending, task::Poll::Ready)
+    }
+}
+
+/// [`select`] that always [`task::Poll`]s `biased` [`Future`] first and only
+/// if it returns [`task::Poll::Pending`] tries to [`task::Poll`] `regular`.
+///
+/// Implementation is exactly the same, as [`select`] at the moment, but
+/// documentation has no guarantee about this behaviour, so can be changed.
+///
+/// [`select`]: futures::future::select
+pub(crate) const fn select_with_biased_first<A, B>(
+    biased: A,
+    regular: B,
+) -> SelectWithBiasedFirst<A, B>
+where
+    A: Future + Unpin,
+    B: Future + Unpin,
+{
+    SelectWithBiasedFirst {
+        inner: Some((biased, regular)),
+    }
+}
+
+/// [`Future`] of [`select_with_biased_first`].
+pub(crate) struct SelectWithBiasedFirst<A, B> {
+    /// Inner [`Future`]s.
+    inner: Option<(A, B)>,
+}
+
+impl<A, B> Future for SelectWithBiasedFirst<A, B>
+where
+    A: Future + Unpin,
+    B: Future + Unpin,
+{
+    type Output = Either<(A::Output, B), (B::Output, A)>;
+
+    #[allow(clippy::expect_used)]
+    fn poll(
+        mut self: Pin<&mut Self>,
+        cx: &mut task::Context<'_>,
+    ) -> task::Poll<Self::Output> {
+        let (mut a, mut b) = self
+            .inner
+            .take()
+            .expect("cannot poll `SelectWithBiasedFirst` twice");
+
+        if let task::Poll::Ready(val) = a.poll_unpin(cx) {
+            return task::Poll::Ready(Either::Left((val, b)));
+        }
+
+        if let task::Poll::Ready(val) = b.poll_unpin(cx) {
+            return task::Poll::Ready(Either::Right((val, a)));
+        }
+
+        self.inner = Some((a, b));
+        task::Poll::Pending
+    }
+}
+
+impl<A, B> FusedFuture for SelectWithBiasedFirst<A, B>
+where
+    A: Future + Unpin,
+    B: Future + Unpin,
+{
+    fn is_terminated(&self) -> bool {
+        self.inner.is_none()
+    }
+}

src/lib.rs

@@ -143,6 +143,8 @@ pub mod writer;
 
 #[cfg(feature = "macros")]
 pub mod codegen;
+#[cfg(feature = "tracing")]
+pub mod tracing;
 
 // TODO: Remove once tests run without complains about it.
 #[cfg(test)]