From 7e048de0ec118a8aa712ff189fe901361e76a47a Mon Sep 17 00:00:00 2001 From: Ilya Salauyeu <47687266+ilslv@users.noreply.github.com> Date: Mon, 13 Mar 2023 15:02:13 +0100 Subject: [PATCH] Support `--report-time` CLI option for `writer::Libtest` (#265, #264) --- CHANGELOG.md | 4 + book/src/SUMMARY.md | 2 +- book/src/output/index.md | 2 +- book/src/output/intellij.md | 18 ++- src/writer/libtest.rs | 174 +++++++++++++++++------ tests/libtest.rs | 43 +++++- tests/libtest/correct-report-time.stdout | 100 +++++++++++++ 7 files changed, 293 insertions(+), 50 deletions(-) create mode 100644 tests/libtest/correct-report-time.stdout diff --git a/CHANGELOG.md b/CHANGELOG.md index db43ae2c..1935f62b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,14 +15,18 @@ All user visible changes to `cucumber` crate will be documented in this file. Th - Added `Log` variant to `event::Scenario`. ([#258]) - Added `embeddings` field to `writer::json::Step` and `writer::json::HookResult`. ([#261]) +- Added `report_time` field to `writer::libtest::Cli`. ([#264], [#265]) ### Added - [`tracing`] crate integration behind the `tracing` feature flag. ([#213], [#258], [#261]) +- Support of `--report-time` CLI option for `writer::Libtest`. ([#264], [#265]) [#213]: /../../issues/213 [#258]: /../../pull/258 [#261]: /../../pull/261 +[#264]: /../../issues/264 +[#265]: /../../pull/265 diff --git a/book/src/SUMMARY.md b/book/src/SUMMARY.md index 2256670b..217158d4 100644 --- a/book/src/SUMMARY.md +++ b/book/src/SUMMARY.md @@ -22,7 +22,7 @@ - [Cucumber JSON format](output/json.md) - [Multiple outputs](output/multiple.md) - [`tracing` integration](output/tracing.md) - - [IntelliJ Rust integration](output/intellij.md) + - [IntelliJ Rust (`libtest`) integration](output/intellij.md) - [Architecture](architecture/index.md) - [Custom `Parser`](architecture/parser.md) - [Custom `Runner`](architecture/runner.md) diff --git a/book/src/output/index.md b/book/src/output/index.md index 8f3cc6a1..a028d926 100644 --- a/book/src/output/index.md +++ b/book/src/output/index.md @@ -8,4 +8,4 @@ This chapter describes possible way and tweaks of outputting test suite results. 3. [Cucumber JSON format](json.md) 4. [Multiple outputs](multiple.md) 5. [`tracing` integration](tracing.md) -6. [IntelliJ Rust integration](intellij.md) +6. [IntelliJ Rust (`libtest`) integration](intellij.md) diff --git a/book/src/output/intellij.md b/book/src/output/intellij.md index 5a0e1c8f..df1abfaf 100644 --- a/book/src/output/intellij.md +++ b/book/src/output/intellij.md @@ -1,5 +1,5 @@ -IntelliJ Rust integration -========================= +IntelliJ Rust (`libtest`) integration +===================================== [`writer::Libtest`] (enabled by `libtest` feature in `Cargo.toml`) allows [IntelliJ Rust] plugin to interpret output of [`cucumber`] tests similar to unit tests. To use it, just add [Cargo configuration][1] (current example uses `cargo test --test wait --features libtest` command) or run it via [Cargo command][2]. This automatically adds `--format=json` CLI option, which makes the [`cucumber`]'s output IDE-compatible. @@ -40,7 +40,18 @@ World::cucumber() +## `libtest` support + +Only a small subset of [`libtest`] harness is supported to integrate with other tools: +- Only [`--format=json`][5] output ([`JUnit` support is done separately](junit.md)); +- [`--report-time`][6] option; +- [`--show-output`][7] option. + + + + [`cucumber`]: https://docs.rs/cucumber +[`libtest`]: https://doc.rust-lang.org/rustc/tests/index.html [`writer::Basic`]: https://docs.rs/cucumber/*/cucumber/writer/struct.Basic.html [`writer::Libtest`]: https://docs.rs/cucumber/*/cucumber/writer/struct.Libtest.html [Cargo workspace]: https://doc.rust-lang.org/cargo/reference/workspaces.html @@ -51,3 +62,6 @@ World::cucumber() [2]: https://plugins.jetbrains.com/plugin/8182-rust/docs/cargo-command-configuration.html [3]: https://github.com/intellij-rust/intellij-rust/issues/9041 [4]: https://github.com/rust-lang/cargo/issues/3946#issuecomment-973132993 +[5]: https://doc.rust-lang.org/rustc/tests/index.html#--format-format +[6]: https://doc.rust-lang.org/rustc/tests/index.html#--report-time +[7]: https://doc.rust-lang.org/rustc/tests/index.html#--show-output diff --git a/src/writer/libtest.rs b/src/writer/libtest.rs index 204851e4..4762d42c 100644 --- a/src/writer/libtest.rs +++ b/src/writer/libtest.rs @@ -51,6 +51,10 @@ pub struct Cli { #[arg(long)] pub show_output: bool, + /// Show execution time of each test. + #[arg(long, value_name = "plain|colored", default_missing_value = "plain")] + pub report_time: Option, + /// Enable nightly-only flags. #[arg(short = 'Z')] pub nightly: Option, @@ -83,6 +87,30 @@ impl FromStr for Format { } } +/// Format of reporting time. +#[derive(Clone, Copy, Debug)] +pub enum ReportTime { + /// Plain time reporting. + Plain, + + /// Colored time reporting. + Colored, +} + +impl FromStr for ReportTime { + type Err = String; + + fn from_str(s: &str) -> Result { + match s.to_lowercase().as_str() { + "plain" => Ok(Self::Plain), + "colored" => Ok(Self::Colored), + s => Err(format!( + "Unknown option `{s}`, expected `plain` or `colored`", + )), + } + } +} + /// [`libtest`][1] compatible [`Writer`]. /// /// Currently used only to support `--format=json` option. @@ -165,6 +193,13 @@ pub struct Libtest { /// /// [`Started`]: event::Cucumber::Started started_at: Option, + + /// [`SystemTime`] when the [`Step::Started`]/[`Hook::Started`] event was + /// received. + /// + /// [`Hook::Started`]: event::Hook::Started + /// [`Step::Started`]: event::Step::Started + step_started_at: Option, } // Implemented manually to omit redundant `World: Clone` trait bound, imposed by @@ -183,6 +218,7 @@ impl Clone for Libtest { hook_errors: self.hook_errors, features_without_path: self.features_without_path, started_at: self.started_at, + step_started_at: self.step_started_at, } } } @@ -291,8 +327,9 @@ impl Libtest { parsing_errors: 0, hook_errors: 0, ignored: 0, - started_at: None, features_without_path: 0, + started_at: None, + step_started_at: None, } } @@ -372,12 +409,10 @@ impl Libtest { } .into()] } - Ok((Cucumber::Finished, _)) => { + Ok((Cucumber::Finished, meta)) => { let exec_time = self .started_at - .and_then(|started| { - SystemTime::now().duration_since(started).ok() - }) + .and_then(|started| meta.at.duration_since(started).ok()) .as_ref() .map(Duration::as_secs_f64); @@ -400,8 +435,8 @@ impl Libtest { vec![ev] } - Ok((Cucumber::Feature(feature, ev), _)) => { - self.expand_feature_event(&feature, ev, cli) + Ok((Cucumber::Feature(feature, ev), meta)) => { + self.expand_feature_event(&feature, ev, meta, cli) } Err(e) => { self.parsing_errors += 1; @@ -423,7 +458,9 @@ impl Libtest { vec![ TestEvent::started(name.clone()).into(), - TestEvent::failed(name).with_stdout(e.to_string()).into(), + TestEvent::failed(name, None) + .with_stdout(e.to_string()) + .into(), ] } } @@ -434,6 +471,7 @@ impl Libtest { &mut self, feature: &gherkin::Feature, ev: event::Feature, + meta: event::Metadata, cli: &Cli, ) -> Vec { use event::{Feature, Rule}; @@ -448,11 +486,11 @@ impl Libtest { Some(&rule), &scenario, ev, + meta, cli, ), - Feature::Scenario(scenario, ev) => { - self.expand_scenario_event(feature, None, &scenario, ev, cli) - } + Feature::Scenario(scenario, ev) => self + .expand_scenario_event(feature, None, &scenario, ev, meta, cli), } } @@ -463,6 +501,7 @@ impl Libtest { rule: Option<&gherkin::Rule>, scenario: &gherkin::Scenario, ev: event::RetryableScenario, + meta: event::Metadata, cli: &Cli, ) -> Vec { use event::Scenario; @@ -470,14 +509,14 @@ impl Libtest { let retries = ev.retries; match ev.event { Scenario::Started | Scenario::Finished => Vec::new(), - Scenario::Hook(ty, ev) => { - self.expand_hook_event(feature, rule, scenario, ty, ev, retries) - } + Scenario::Hook(ty, ev) => self.expand_hook_event( + feature, rule, scenario, ty, ev, retries, meta, cli, + ), Scenario::Background(step, ev) => self.expand_step_event( - feature, rule, scenario, &step, ev, retries, true, cli, + feature, rule, scenario, &step, ev, retries, true, meta, cli, ), Scenario::Step(step, ev) => self.expand_step_event( - feature, rule, scenario, &step, ev, retries, false, cli, + feature, rule, scenario, &step, ev, retries, false, meta, cli, ), // We do use `print!()` intentionally here to support `libtest` // output capturing properly, which can only capture output from @@ -493,6 +532,7 @@ impl Libtest { } /// Converts the provided [`event::Hook`] into [`LibTestJsonEvent`]s. + #[allow(clippy::too_many_arguments)] fn expand_hook_event( &mut self, feature: &gherkin::Feature, @@ -501,9 +541,15 @@ impl Libtest { hook: event::HookType, ev: event::Hook, retries: Option, + meta: event::Metadata, + cli: &Cli, ) -> Vec { match ev { - event::Hook::Started | event::Hook::Passed => Vec::new(), + event::Hook::Started => { + self.step_started_at(meta, cli); + Vec::new() + } + event::Hook::Passed => Vec::new(), event::Hook::Failed(world, info) => { self.hook_errors += 1; @@ -517,7 +563,7 @@ impl Libtest { vec![ TestEvent::started(name.clone()).into(), - TestEvent::failed(name) + TestEvent::failed(name, self.step_exec_time(meta, cli)) .with_stdout(format!( "{}{}", coerce_error(&info), @@ -542,6 +588,7 @@ impl Libtest { ev: event::Step, retries: Option, is_background: bool, + meta: event::Metadata, cli: &Cli, ) -> Vec { use event::Step; @@ -555,11 +602,14 @@ impl Libtest { ); let ev = match ev { - Step::Started => TestEvent::started(name), + Step::Started => { + self.step_started_at(meta, cli); + TestEvent::started(name) + } Step::Passed(_, loc) => { self.passed += 1; - let event = TestEvent::ok(name); + let event = TestEvent::ok(name, self.step_exec_time(meta, cli)); if cli.show_output { event.with_stdout(format!( "{}:{}:{} (defined){}", @@ -583,7 +633,8 @@ impl Libtest { Step::Skipped => { self.ignored += 1; - let event = TestEvent::ignored(name); + let event = + TestEvent::ignored(name, self.step_exec_time(meta, cli)); if cli.show_output { event.with_stdout(format!( "{}:{}:{} (defined)", @@ -611,22 +662,23 @@ impl Libtest { self.failed += 1; } - TestEvent::failed(name).with_stdout(format!( - "{}:{}:{} (defined){}\n{err}{}", - feature - .path - .as_ref() - .and_then(|p| p.to_str().map(trim_path)) - .unwrap_or(&feature.name), - step.position.line, - step.position.col, - loc.map(|l| format!( - "\n{}:{}:{} (matched)", - l.path, l.line, l.column, + TestEvent::failed(name, self.step_exec_time(meta, cli)) + .with_stdout(format!( + "{}:{}:{} (defined){}\n{err}{}", + feature + .path + .as_ref() + .and_then(|p| p.to_str().map(trim_path)) + .unwrap_or(&feature.name), + step.position.line, + step.position.col, + loc.map(|l| format!( + "\n{}:{}:{} (matched)", + l.path, l.line, l.column, + )) + .unwrap_or_default(), + world.map(|w| format!("\n{w:#?}")).unwrap_or_default(), )) - .unwrap_or_default(), - world.map(|w| format!("\n{w:#?}")).unwrap_or_default(), - )) } }; @@ -701,6 +753,29 @@ impl Libtest { .flatten() .join("::") } + + /// Saves [`Step`] starting [`SystemTime`]. + /// + /// [`Step`]: gherkin::Step + fn step_started_at(&mut self, meta: event::Metadata, cli: &Cli) { + self.step_started_at = + Some(meta.at).filter(|_| cli.report_time.is_some()); + } + + /// Retrieves [`Duration`] since the last [`Libtest::step_started_at()`] + /// call. + fn step_exec_time( + &mut self, + meta: event::Metadata, + cli: &Cli, + ) -> Option { + self.step_started_at.take().and_then(|started| { + meta.at + .duration_since(started) + .ok() + .filter(|_| cli.report_time.is_some()) + }) + } } /// Indicator, whether a [`Step`] is [`Background`] or not. @@ -862,24 +937,24 @@ impl TestEvent { } /// Creates a new [`TestEvent::Ok`]. - const fn ok(name: String) -> Self { - Self::Ok(TestEventInner::new(name)) + fn ok(name: String, exec_time: Option) -> Self { + Self::Ok(TestEventInner::new(name).with_exec_time(exec_time)) } /// Creates a new [`TestEvent::Failed`]. - const fn failed(name: String) -> Self { - Self::Failed(TestEventInner::new(name)) + fn failed(name: String, exec_time: Option) -> Self { + Self::Failed(TestEventInner::new(name).with_exec_time(exec_time)) } /// Creates a new [`TestEvent::Ignored`]. - const fn ignored(name: String) -> Self { - Self::Ignored(TestEventInner::new(name)) + fn ignored(name: String, exec_time: Option) -> Self { + Self::Ignored(TestEventInner::new(name).with_exec_time(exec_time)) } /// Creates a new [`TestEvent::Timeout`]. #[allow(dead_code)] - const fn timeout(name: String) -> Self { - Self::Timeout(TestEventInner::new(name)) + fn timeout(name: String, exec_time: Option) -> Self { + Self::Timeout(TestEventInner::new(name).with_exec_time(exec_time)) } /// Adds a [`TestEventInner::stdout`]. @@ -918,6 +993,10 @@ struct TestEventInner { /// [`Stderr`]: io::Stderr #[serde(skip_serializing_if = "Option::is_none")] stderr: Option, + + /// Test case execution time. + #[serde(skip_serializing_if = "Option::is_none")] + exec_time: Option, } impl TestEventInner { @@ -927,9 +1006,16 @@ impl TestEventInner { name, stdout: None, stderr: None, + exec_time: None, } } + /// Adds a [`TestEventInner::exec_time`]. + fn with_exec_time(mut self, exec_time: Option) -> Self { + self.exec_time = exec_time.as_ref().map(Duration::as_secs_f64); + self + } + /// Adds a [`TestEventInner::stdout`]. #[allow(clippy::missing_const_for_fn)] // false positive: drop in const fn with_stdout(mut self, stdout: String) -> Self { diff --git a/tests/libtest.rs b/tests/libtest.rs index 3dd1dc9e..0ce08b7e 100644 --- a/tests/libtest.rs +++ b/tests/libtest.rs @@ -1,6 +1,6 @@ use std::{fs, io::Read as _}; -use cucumber::{given, then, when, writer, World as _, WriterExt as _}; +use cucumber::{cli, given, then, when, writer, World as _, WriterExt as _}; use regex::Regex; use tempfile::NamedTempFile; @@ -32,7 +32,7 @@ async fn output() { // Required to strip out non-deterministic parts of output, so we could // compare them well. let non_deterministic = Regex::new( - "\"exec_time\":\\d*\\.?\\d*\ + "\":\\d+\\.\\d+\ |([^\"\\n\\s]*)[/\\\\]([A-z1-9-_]*)\\.(feature|rs)(:\\d+:\\d+)?\ |\\s?\n", ) @@ -47,5 +47,44 @@ async fn output() { ); } +#[tokio::test] +async fn output_report_time() { + let mut cli = cli::Opts::<_, _, writer::libtest::Cli>::default(); + cli.writer.report_time = Some(writer::libtest::ReportTime::Plain); + let mut file = NamedTempFile::new().unwrap(); + drop( + World::cucumber() + .with_writer( + writer::Libtest::new(file.reopen().unwrap()).normalized(), + ) + .fail_on_skipped() + .with_cli(cli) + .run("tests/features/wait") + .await, + ); + + let mut buffer = String::new(); + file.read_to_string(&mut buffer).unwrap(); + + // Required to strip out non-deterministic parts of output, so we could + // compare them well. + // let non_deterministic = Regex::new( + let non_deterministic = Regex::new( + "\":\\d+\\.\\d+\ + |([^\"\\n\\s]*)[/\\\\]([A-z1-9-_]*)\\.(feature|rs)(:\\d+:\\d+)?\ + |\\s?\n", + ) + .unwrap(); + + assert_eq!( + non_deterministic.replace_all(&buffer, ""), + non_deterministic.replace_all( + &fs::read_to_string("tests/libtest/correct-report-time.stdout") + .unwrap(), + "", + ), + ); +} + #[derive(Clone, Copy, cucumber::World, Debug, Default)] struct World(usize); diff --git a/tests/libtest/correct-report-time.stdout b/tests/libtest/correct-report-time.stdout new file mode 100644 index 00000000..92dc5f2c --- /dev/null +++ b/tests/libtest/correct-report-time.stdout @@ -0,0 +1,100 @@ +{"type":"suite","event":"started","test_count":49} +{"type":"test","event":"started","name":"Feature: Parsing /Users/work/Work/cucumber/tests/features/wait/invalid.feature"} +{"type":"test","event":"failed","name":"Feature: Parsing /Users/work/Work/cucumber/tests/features/wait/invalid.feature","stdout":"Failed to parse feature: Could not parse feature file: /Users/work/Work/cucumber/tests/features/wait/invalid.feature\n"} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/rule.feature::6: Scenario: 1 sec::3: Background Given 1 sec"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/rule.feature::6: Scenario: 1 sec::3: Background Given 1 sec","exec_time":0.000594} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/rule.feature::6: Scenario: 1 sec::7: Given 1 sec"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/rule.feature::6: Scenario: 1 sec::7: Given 1 sec","exec_time":0.000069} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/rule.feature::6: Scenario: 1 sec::8: When 1 sec"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/rule.feature::6: Scenario: 1 sec::8: When 1 sec","exec_time":0.000453} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/rule.feature::6: Scenario: 1 sec::9: Then unknown"} +{"type":"test","event":"failed","name":"Feature: Basic tests/features/wait/rule.feature::6: Scenario: 1 sec::9: Then unknown","stdout":"tests/features/wait/rule.feature:9:5 (defined)\nStep doesn't match any function\n","exec_time":0.000308} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/rule.feature::19: Rule: rule::21: Scenario: 2 secs::3: Background Given 1 sec"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/rule.feature::19: Rule: rule::21: Scenario: 2 secs::3: Background Given 1 sec","exec_time":0.000414} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/rule.feature::19: Rule: rule::21: Scenario: 2 secs::22: Given 2 secs"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/rule.feature::19: Rule: rule::21: Scenario: 2 secs::22: Given 2 secs","exec_time":0.000291} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/rule.feature::19: Rule: rule::21: Scenario: 2 secs::23: When 2 secs"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/rule.feature::19: Rule: rule::21: Scenario: 2 secs::23: When 2 secs","exec_time":0.000502} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/rule.feature::19: Rule: rule::21: Scenario: 2 secs::24: Then 2 secs"} +{"type":"test","event":"failed","name":"Feature: Basic tests/features/wait/rule.feature::19: Rule: rule::21: Scenario: 2 secs::24: Then 2 secs","stdout":"tests/features/wait/rule.feature:24:7 (defined)\ntests/libtest.rs:9:1 (matched)\nStep panicked. Captured output: Too much!\nWorld(\n 4,\n)\n","exec_time":0.000221} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/rule.feature::13: Scenario: 1 sec::3: Background Given 1 sec"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/rule.feature::13: Scenario: 1 sec::3: Background Given 1 sec","exec_time":0.000425} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/rule.feature::13: Scenario: 1 sec::14: Given 1 sec"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/rule.feature::13: Scenario: 1 sec::14: Given 1 sec","exec_time":0.000292} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/rule.feature::13: Scenario: 1 sec::15: When 1 sec"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/rule.feature::13: Scenario: 1 sec::15: When 1 sec","exec_time":0.00051} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/rule.feature::13: Scenario: 1 sec::16: Then unknown"} +{"type":"test","event":"ignored","name":"Feature: Basic tests/features/wait/rule.feature::13: Scenario: 1 sec::16: Then unknown","exec_time":0.000225} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/nested/rule.feature::6: Scenario: 1 sec::3: Background Given 1 sec"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/nested/rule.feature::6: Scenario: 1 sec::3: Background Given 1 sec","exec_time":0.000239} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/nested/rule.feature::6: Scenario: 1 sec::7: Given 1 sec"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/nested/rule.feature::6: Scenario: 1 sec::7: Given 1 sec","exec_time":0.000068} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/nested/rule.feature::6: Scenario: 1 sec::8: When 1 sec"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/nested/rule.feature::6: Scenario: 1 sec::8: When 1 sec","exec_time":0.000067} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/nested/rule.feature::6: Scenario: 1 sec::9: Then unknown"} +{"type":"test","event":"failed","name":"Feature: Basic tests/features/wait/nested/rule.feature::6: Scenario: 1 sec::9: Then unknown","stdout":"tests/features/wait/nested/rule.feature:9:5 (defined)\nStep doesn't match any function\n","exec_time":0.000056} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/nested/rule.feature::19: Rule: rule::21: Scenario: 2 secs::3: Background Given 1 sec"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/nested/rule.feature::19: Rule: rule::21: Scenario: 2 secs::3: Background Given 1 sec","exec_time":0.000417} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/nested/rule.feature::19: Rule: rule::21: Scenario: 2 secs::22: Given 2 secs"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/nested/rule.feature::19: Rule: rule::21: Scenario: 2 secs::22: Given 2 secs","exec_time":0.000285} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/nested/rule.feature::19: Rule: rule::21: Scenario: 2 secs::23: When 2 secs"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/nested/rule.feature::19: Rule: rule::21: Scenario: 2 secs::23: When 2 secs","exec_time":0.000546} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/nested/rule.feature::19: Rule: rule::21: Scenario: 2 secs::24: Then 2 secs"} +{"type":"test","event":"failed","name":"Feature: Basic tests/features/wait/nested/rule.feature::19: Rule: rule::21: Scenario: 2 secs::24: Then 2 secs","stdout":"tests/features/wait/nested/rule.feature:24:7 (defined)\ntests/libtest.rs:9:1 (matched)\nStep panicked. Captured output: Too much!\nWorld(\n 4,\n)\n","exec_time":0.000157} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/nested/rule.feature::13: Scenario: 1 sec::3: Background Given 1 sec"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/nested/rule.feature::13: Scenario: 1 sec::3: Background Given 1 sec","exec_time":0.000415} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/nested/rule.feature::13: Scenario: 1 sec::14: Given 1 sec"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/nested/rule.feature::13: Scenario: 1 sec::14: Given 1 sec","exec_time":0.000288} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/nested/rule.feature::13: Scenario: 1 sec::15: When 1 sec"} +{"type":"test","event":"ok","name":"Feature: Basic tests/features/wait/nested/rule.feature::13: Scenario: 1 sec::15: When 1 sec","exec_time":0.00055} +{"type":"test","event":"started","name":"Feature: Basic tests/features/wait/nested/rule.feature::13: Scenario: 1 sec::16: Then unknown"} +{"type":"test","event":"ignored","name":"Feature: Basic tests/features/wait/nested/rule.feature::13: Scenario: 1 sec::16: Then unknown","exec_time":0.000161} +{"type":"test","event":"started","name":"Feature: Outline tests/features/wait/outline.feature::14: Scenario Outline: wait::5: Given 2 secs"} +{"type":"test","event":"ok","name":"Feature: Outline tests/features/wait/outline.feature::14: Scenario Outline: wait::5: Given 2 secs","exec_time":0.000414} +{"type":"test","event":"started","name":"Feature: Outline tests/features/wait/outline.feature::14: Scenario Outline: wait::6: When 2 secs"} +{"type":"test","event":"ok","name":"Feature: Outline tests/features/wait/outline.feature::14: Scenario Outline: wait::6: When 2 secs","exec_time":0.000288} +{"type":"test","event":"started","name":"Feature: Outline tests/features/wait/outline.feature::14: Scenario Outline: wait::7: Then 2 secs"} +{"type":"test","event":"ok","name":"Feature: Outline tests/features/wait/outline.feature::14: Scenario Outline: wait::7: Then 2 secs","exec_time":0.000558} +{"type":"test","event":"started","name":"Feature: Outline tests/features/wait/outline.feature::15: Scenario Outline: wait::5: Given 1 secs"} +{"type":"test","event":"ok","name":"Feature: Outline tests/features/wait/outline.feature::15: Scenario Outline: wait::5: Given 1 secs","exec_time":0.000407} +{"type":"test","event":"started","name":"Feature: Outline tests/features/wait/outline.feature::15: Scenario Outline: wait::6: When 1 secs"} +{"type":"test","event":"ok","name":"Feature: Outline tests/features/wait/outline.feature::15: Scenario Outline: wait::6: When 1 secs","exec_time":0.000517} +{"type":"test","event":"started","name":"Feature: Outline tests/features/wait/outline.feature::15: Scenario Outline: wait::7: Then 1 secs"} +{"type":"test","event":"ok","name":"Feature: Outline tests/features/wait/outline.feature::15: Scenario Outline: wait::7: Then 1 secs","exec_time":0.000297} +{"type":"test","event":"started","name":"Feature: Outline tests/features/wait/outline.feature::16: Scenario Outline: wait::5: Given 1 secs"} +{"type":"test","event":"ok","name":"Feature: Outline tests/features/wait/outline.feature::16: Scenario Outline: wait::5: Given 1 secs","exec_time":0.000405} +{"type":"test","event":"started","name":"Feature: Outline tests/features/wait/outline.feature::16: Scenario Outline: wait::6: When 1 secs"} +{"type":"test","event":"ok","name":"Feature: Outline tests/features/wait/outline.feature::16: Scenario Outline: wait::6: When 1 secs","exec_time":0.000518} +{"type":"test","event":"started","name":"Feature: Outline tests/features/wait/outline.feature::16: Scenario Outline: wait::7: Then 1 secs"} +{"type":"test","event":"ok","name":"Feature: Outline tests/features/wait/outline.feature::16: Scenario Outline: wait::7: Then 1 secs","exec_time":0.000284} +{"type":"test","event":"started","name":"Feature: Outline tests/features/wait/outline.feature::21: Scenario Outline: wait::5: Given 5 secs"} +{"type":"test","event":"ok","name":"Feature: Outline tests/features/wait/outline.feature::21: Scenario Outline: wait::5: Given 5 secs","exec_time":0.000403} +{"type":"test","event":"started","name":"Feature: Outline tests/features/wait/outline.feature::21: Scenario Outline: wait::6: When 5 secs"} +{"type":"test","event":"ok","name":"Feature: Outline tests/features/wait/outline.feature::21: Scenario Outline: wait::6: When 5 secs","exec_time":0.000519} +{"type":"test","event":"started","name":"Feature: Outline tests/features/wait/outline.feature::21: Scenario Outline: wait::7: Then 5 secs"} +{"type":"test","event":"ok","name":"Feature: Outline tests/features/wait/outline.feature::21: Scenario Outline: wait::7: Then 5 secs","exec_time":0.000273} +{"type":"test","event":"started","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::11: Scenario Outline: wait::5: Given 2 secs"} +{"type":"test","event":"ok","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::11: Scenario Outline: wait::5: Given 2 secs","exec_time":0.000403} +{"type":"test","event":"started","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::11: Scenario Outline: wait::6: When 2 secs"} +{"type":"test","event":"ok","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::11: Scenario Outline: wait::6: When 2 secs","exec_time":0.000515} +{"type":"test","event":"started","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::11: Scenario Outline: wait::7: Then 2 secs"} +{"type":"test","event":"ok","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::11: Scenario Outline: wait::7: Then 2 secs","exec_time":0.000263} +{"type":"test","event":"started","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::12: Scenario Outline: wait::5: Given 1 secs"} +{"type":"test","event":"ok","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::12: Scenario Outline: wait::5: Given 1 secs","exec_time":0.0004} +{"type":"test","event":"started","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::12: Scenario Outline: wait::6: When 1 secs"} +{"type":"test","event":"ok","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::12: Scenario Outline: wait::6: When 1 secs","exec_time":0.000514} +{"type":"test","event":"started","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::12: Scenario Outline: wait::7: Then 1 secs"} +{"type":"test","event":"ok","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::12: Scenario Outline: wait::7: Then 1 secs","exec_time":0.000252} +{"type":"test","event":"started","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::13: Scenario Outline: wait::5: Given 1 secs"} +{"type":"test","event":"ok","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::13: Scenario Outline: wait::5: Given 1 secs","exec_time":0.000396} +{"type":"test","event":"started","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::13: Scenario Outline: wait::6: When 1 secs"} +{"type":"test","event":"ok","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::13: Scenario Outline: wait::6: When 1 secs","exec_time":0.000514} +{"type":"test","event":"started","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::13: Scenario Outline: wait::7: Then 1 secs"} +{"type":"test","event":"ok","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::13: Scenario Outline: wait::7: Then 1 secs","exec_time":0.000245} +{"type":"test","event":"started","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::14: Scenario Outline: wait::5: Given 5 secs"} +{"type":"test","event":"ok","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::14: Scenario Outline: wait::5: Given 5 secs","exec_time":0.000394} +{"type":"test","event":"started","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::14: Scenario Outline: wait::6: When 5 secs"} +{"type":"test","event":"ok","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::14: Scenario Outline: wait::6: When 5 secs","exec_time":0.000518} +{"type":"test","event":"started","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::14: Scenario Outline: wait::7: Then 5 secs"} +{"type":"test","event":"ok","name":"Feature: Rule Outline tests/features/wait/rule_outline.feature::3: Rule: To them all::14: Scenario Outline: wait::7: Then 5 secs","exec_time":0.000231} +{"type":"suite","event":"failed","passed":42,"failed":5,"ignored":2,"measured":0,"filtered_out":0,"exec_time":0.00549}