Tracing spans for scenarios and steps

[stepantubanov]

This is a feature request. It would be great if cucumber had an optional tracing feature (with tracing dependency) and add a span for every scenario / step run.

Mainly I think it'd be helpful to add spans for Scenario (with name field) and Step (with value field).

With tracing enabled, it could look something like this in logs (example):

  2023-03-07T16:33:02.947730Z  INFO my_app::some_module::abc: hello, world!
    at /Users/.../main.rs:123 on tokio-runtime-worker
    in some_lib::request with request_id="f6718872-9684-4f58-ae78-3ba5fec4c06e" method=POST path=https://localhost:51358/users/5/tables
    in cucumber::some_module::step value="When I create a table"
    in cucumber::some_module::scenario name="User creates a table"

[tyranron]

@stepantubanov please, see #213, #258, #261 and this Book chapter.

[stepantubanov]

@tyranron
Thanks.

From the book example, tracing output is like this:

2023-03-07T20:47:46.224716Z  INFO scenario:step: cucu_test: before 2s sleep: 36
2023-03-07T20:47:48.226978Z  INFO scenario:step: cucu_test: after 2s sleep: 36
2023-03-07T20:47:52.224619Z  INFO scenario:step: cucu_test: before 5s sleep: 44
2023-03-07T20:47:57.225896Z  INFO scenario:step: cucu_test: after 5s sleep: 44

There isn't any information as to which step/scenario this trace came from. Imagine we have 1000s of lines like this from a CI test run with some amount of concurrency, if we had scenario name / step value attributes right on the spans, then it would show up attached to each trace and make it a lot easier to track that execution through the log. But without these arguments it doesn't really add much value (just adds same words "scenario:step" to each line).

And one more suggestion: It seems like enabling tracing in cucumber enables both instrumentation & sets a global tracing subscriber. Settings a subscriber is typically done by the app. It would be great if it was optional in cucumber (we could enable tracing instrumentation, but do not set global tracing subscriber).
See https://docs.rs/tracing-core/0.1.30/tracing_core/dispatcher/fn.set_global_default.html

Warning: In general, libraries should not call set_global_default()! Doing so will cause conflicts when executables that depend on the library try to set the default later.

[tyranron]

@stepantubanov

There isn't any information as to which step/scenario this trace came from.

There is no way traces of scenario A will be output in the middle of scenario B. They're always output before the scenario/step to which Span they belong, despite any concurrency execution and et cetera. This is handled by design. Repeating step/scenario name in such traces will only make output less readable.

In other Writers, like Cucumber JSON, for example, they may be output in the way natural for the format.

Also, nothing prevents you from instrumenting the concrete step matching functions with additional fields, if you will so.

It seems like enabling tracing in cucumber enables both instrumentation & sets a global tracing subscriber.

AFAIRc, enabling tracing Cargo feature enables the instrumentation, while setting a subscriber is made by Cucumber::init_tracing()/Cucumber::configure_and_init_tracing() methods on the library user's will.

@ilslv please, correct me if I'm wrong.

It would be great if it was optional in cucumber (we could enable tracing instrumentation, but do not set global tracing subscriber).

It's hard to imagine the use-case for that. Could you specify some meaningful ones?

A typical cucumber usage is just a test app, configuring Cucumber object and running it. You want some tracing subscriber customization? You could do that easily with layering via Cucumber::configure_and_init_tracing(). Why would one want to register a tracing subscriber totally separately?
I don't see technical problems with extending APIs and exposing integration stuff for implementing that, but I barely see a need for that. If there will be enough demand/request for that from users, we could do that.

[ilslv]

@stepantubanov

There isn't any information as to which step/scenario this trace came from. Imagine we have 1000s of lines like this from a CI test run with some amount of concurrency

Our tracing implementation intercepts all tracing events, understands what Scenario this event is coming from and passes decision when to output them to Writer. This allows us to output those events near Scenarios, as shown in the book chapter. So you don't need to deduce where those logs were emitted, as we are doing that job for you.

And one more suggestion: It seems like enabling tracing in cucumber enables both instrumentation & sets a global tracing subscriber. Settings a subscriber is typically done by the app.

Typically yes, but we are in a special position. First, we have to embed some special tracing Layers/Formats to deduce where traces are coming from and intercept them. Second, this crate is intended to be the only thing doing stuff in the binary, as it's literally the testing framework. And if you want to add additional configuration, like jaeger collector, there is Cucumber::configure_and_init_tracing().

I believe that above should cover all tracing needs. If this isn't the case feel free to reopen this issue/file a new one.

[stepantubanov]

Thanks for the explanation. That's really nice that scenarios are printed in a linear way without being intermixed.

It's hard to imagine the use-case for that. Could you specify some meaningful ones?

and

Second, this crate is intended to be the only thing doing stuff in the binary, as it's literally the testing framework.

We're using it for end-to-end testing, with the webserver & background workers running in the background. And it sets it's own tracing subscriber, with various configuration parameters. I don't know if we can easily extract it into a Layer to pass to cucumber. We also write logs to a file and archive it in CI.

[stepantubanov]

Also, nothing prevents you from instrumenting the concrete step matching functions with additional fields, if you will so.

This is what I was trying to do originally when I created the issue. I actually have a question about that - how can I get the current Scenario (we can add Step as an argument, but it doesn't have any references to Scenario)?

[ilslv]

@stepantubanov

And it sets it's own tracing subscriber, with various configuration parameters. I don't know if we can easily extract it into a Layer to pass to cucumber.

I can't imagine a use-case when this is not possible or even challenging. Layer abstraction with Registry should be great for this.

We also write logs to a file and archive it in CI.

This for example could be done either as a separate Layer or with fmt::Layer::map_writer()

This is what I was trying to do originally when I created the issue. I actually have a question about that - how can I get the current Scenario (we can add Step as an argument, but it doesn't have any references to Scenario)?

There is currently no way to get Rule or Scenario inside Step function.