From 34328690dc2090fd9282337aca1df74cbf837cab Mon Sep 17 00:00:00 2001 From: Nayeem Rahman Date: Thu, 4 Aug 2022 17:38:40 +0100 Subject: [PATCH] fix(test): output parallel test results independently (#15399) --- .github/workflows/ci.yml | 6 +- cli/lsp/testing/execution.rs | 15 +- cli/tests/integration/test_tests.rs | 12 +- cli/tests/testdata/test/parallel_output.out | 57 +++++++ cli/tests/testdata/test/parallel_output.ts | 27 ++++ .../test/short-pass-jobs-flag-warning.out | 3 +- cli/tests/testdata/test/short-pass.out | 3 +- .../testdata/test/steps/output_within.out | 2 - cli/tools/test.rs | 146 +++++++----------- 9 files changed, 160 insertions(+), 111 deletions(-) create mode 100644 cli/tests/testdata/test/parallel_output.out create mode 100644 cli/tests/testdata/test/parallel_output.ts diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index d74e21b0c8d95..36656d7c62010 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -235,7 +235,7 @@ jobs: ~/.cargo/registry/index ~/.cargo/registry/cache ~/.cargo/git/db - key: 17-cargo-home-${{ matrix.os }}-${{ hashFiles('Cargo.lock') }} + key: 18-cargo-home-${{ matrix.os }}-${{ hashFiles('Cargo.lock') }} # In main branch, always creates fresh cache - name: Cache build output (main) @@ -251,7 +251,7 @@ jobs: !./target/*/*.zip !./target/*/*.tar.gz key: | - 17-cargo-target-${{ matrix.os }}-${{ matrix.profile }}-${{ github.sha }} + 18-cargo-target-${{ matrix.os }}-${{ matrix.profile }}-${{ github.sha }} # Restore cache from the latest 'main' branch build. - name: Cache build output (PR) @@ -267,7 +267,7 @@ jobs: !./target/*/*.tar.gz key: never_saved restore-keys: | - 17-cargo-target-${{ matrix.os }}-${{ matrix.profile }}- + 18-cargo-target-${{ matrix.os }}-${{ matrix.profile }}- # Don't save cache after building PRs or branches other than 'main'. - name: Skip save cache (PR) diff --git a/cli/lsp/testing/execution.rs b/cli/lsp/testing/execution.rs index 7c0552a0ae8b3..8d789b20e3eb5 100644 --- a/cli/lsp/testing/execution.rs +++ b/cli/lsp/testing/execution.rs @@ -374,13 +374,12 @@ impl TestRun { .buffer_unordered(concurrent_jobs) .collect::, tokio::task::JoinError>>>(); - let mut reporter: Box = - Box::new(LspTestReporter::new( - self, - client.clone(), - maybe_root_uri, - self.tests.clone(), - )); + let mut reporter = Box::new(LspTestReporter::new( + self, + client.clone(), + maybe_root_uri, + self.tests.clone(), + )); let handler = { tokio::task::spawn(async move { @@ -653,9 +652,7 @@ impl LspTestReporter { }, )); } -} -impl test::TestReporter for LspTestReporter { fn report_plan(&mut self, _plan: &test::TestPlan) {} fn report_register(&mut self, desc: &test::TestDescription) { diff --git a/cli/tests/integration/test_tests.rs b/cli/tests/integration/test_tests.rs index f4caacd6f01ac..02c4256b12b52 100644 --- a/cli/tests/integration/test_tests.rs +++ b/cli/tests/integration/test_tests.rs @@ -304,12 +304,6 @@ itest!(steps_passing_steps { output: "test/steps/passing_steps.out", }); -itest!(steps_passing_steps_concurrent { - args: "test --jobs=2 test/steps/passing_steps.ts", - exit_code: 0, - output: "test/steps/passing_steps.out", -}); - itest!(steps_failing_steps { args: "test test/steps/failing_steps.ts", exit_code: 1, @@ -447,3 +441,9 @@ itest!(non_error_thrown { output: "test/non_error_thrown.out", exit_code: 1, }); + +itest!(parallel_output { + args: "test --parallel --reload test/parallel_output.ts", + output: "test/parallel_output.out", + exit_code: 1, +}); diff --git a/cli/tests/testdata/test/parallel_output.out b/cli/tests/testdata/test/parallel_output.out new file mode 100644 index 0000000000000..3ec9c5221052c --- /dev/null +++ b/cli/tests/testdata/test/parallel_output.out @@ -0,0 +1,57 @@ +Check [WILDCARD]/test/parallel_output.ts +./test/parallel_output.ts => step output ... step 1 ... ok ([WILDCARD]ms) +./test/parallel_output.ts => step output ... step 2 ... ok ([WILDCARD]ms) +------- output ------- +Hello, world! (from step 3) +----- output end ----- +./test/parallel_output.ts => step output ... step 3 ... ok ([WILDCARD]ms) +------- output ------- +Hello, world! (from step 4) +----- output end ----- +./test/parallel_output.ts => step output ... step 4 ... ok ([WILDCARD]ms) +./test/parallel_output.ts => step output ... ok ([WILDCARD]ms) +./test/parallel_output.ts => step failures ... step 1 ... ok ([WILDCARD]ms) +./test/parallel_output.ts => step failures ... step 2 ... FAILED ([WILDCARD]ms) + error: Error: Fail. + throw new Error("Fail."); + ^ + at file:///[WILDCARD]/test/parallel_output.ts:15:11 + at [WILDCARD] + at file:///[WILDCARD]/test/parallel_output.ts:14:11 +./test/parallel_output.ts => step failures ... step 3 ... FAILED ([WILDCARD]ms) + error: Error: Fail. + await t.step("step 3", () => Promise.reject(new Error("Fail."))); + ^ + at file:///[WILDCARD]/test/parallel_output.ts:17:47 + at [WILDCARD] + at file:///[WILDCARD]/test/parallel_output.ts:17:11 +./test/parallel_output.ts => step failures ... FAILED ([WILDCARD]ms) +./test/parallel_output.ts => step nested failure ... step 1 ... inner 1 ... ok ([WILDCARD]ms) +./test/parallel_output.ts => step nested failure ... step 1 ... inner 2 ... FAILED ([WILDCARD]ms) + error: Error: Failed. + throw new Error("Failed."); + ^ + at file:///[WILDCARD]/test/parallel_output.ts:24:13 + at [WILDCARD] + at file:///[WILDCARD]/test/parallel_output.ts:23:13 +./test/parallel_output.ts => step nested failure ... step 1 ... FAILED ([WILDCARD]ms) +./test/parallel_output.ts => step nested failure ... FAILED ([WILDCARD]ms) + + ERRORS + +step failures => ./test/parallel_output.ts:12:6 +error: Error: 2 test steps failed. + at [WILDCARD] + +step nested failure => ./test/parallel_output.ts:20:6 +error: Error: 1 test step failed. + at [WILDCARD] + + FAILURES + +step failures => ./test/parallel_output.ts:12:6 +step nested failure => ./test/parallel_output.ts:20:6 + +FAILED | 1 passed (6 steps) | 2 failed (4 steps) ([WILDCARD]ms) + +error: Test failed diff --git a/cli/tests/testdata/test/parallel_output.ts b/cli/tests/testdata/test/parallel_output.ts new file mode 100644 index 0000000000000..5de733aad0837 --- /dev/null +++ b/cli/tests/testdata/test/parallel_output.ts @@ -0,0 +1,27 @@ +Deno.test("step output", async (t) => { + await t.step("step 1", () => {}); + await t.step("step 2", () => {}); + await t.step("step 3", () => { + console.log("Hello, world! (from step 3)"); + }); + await t.step("step 4", () => { + console.log("Hello, world! (from step 4)"); + }); +}); + +Deno.test("step failures", async (t) => { + await t.step("step 1", () => {}); + await t.step("step 2", () => { + throw new Error("Fail."); + }); + await t.step("step 3", () => Promise.reject(new Error("Fail."))); +}); + +Deno.test("step nested failure", async (t) => { + await t.step("step 1", async (t) => { + await t.step("inner 1", () => {}); + await t.step("inner 2", () => { + throw new Error("Failed."); + }); + }); +}); diff --git a/cli/tests/testdata/test/short-pass-jobs-flag-warning.out b/cli/tests/testdata/test/short-pass-jobs-flag-warning.out index b70ec5ee1b366..8a2f7fe5d7830 100644 --- a/cli/tests/testdata/test/short-pass-jobs-flag-warning.out +++ b/cli/tests/testdata/test/short-pass-jobs-flag-warning.out @@ -1,7 +1,6 @@ Warning: --jobs flag is deprecated. Use the --parallel flag with possibly the 'DENO_JOBS' environment variable. Check [WILDCARD]/test/short-pass.ts -running 1 test from ./test/short-pass.ts -test ... ok ([WILDCARD]) +./test/short-pass.ts => test ... ok ([WILDCARD]) ok | 1 passed | 0 failed ([WILDCARD]) diff --git a/cli/tests/testdata/test/short-pass.out b/cli/tests/testdata/test/short-pass.out index 09b72d5fd9017..3f239de414705 100644 --- a/cli/tests/testdata/test/short-pass.out +++ b/cli/tests/testdata/test/short-pass.out @@ -1,6 +1,5 @@ Check [WILDCARD]/test/short-pass.ts -running 1 test from ./test/short-pass.ts -test ... ok ([WILDCARD]) +./test/short-pass.ts => test ... ok ([WILDCARD]) ok | 1 passed | 0 failed ([WILDCARD]) diff --git a/cli/tests/testdata/test/steps/output_within.out b/cli/tests/testdata/test/steps/output_within.out index 0f5c95ce36bb5..34d94b6f8bec5 100644 --- a/cli/tests/testdata/test/steps/output_within.out +++ b/cli/tests/testdata/test/steps/output_within.out @@ -18,12 +18,10 @@ description ... 4 ----- output end ----- inner 2 ... ok ([WILDCARD]ms) - ------- output ------- 5 ----- output end ----- step 1 ... ok ([WILDCARD]ms) - ------- output ------- 6 ----- output end ----- diff --git a/cli/tools/test.rs b/cli/tools/test.rs index e42ea673b224b..e4b9ad398015a 100644 --- a/cli/tools/test.rs +++ b/cli/tools/test.rs @@ -278,38 +278,9 @@ impl TestSummary { } } -pub trait TestReporter { - fn report_register(&mut self, plan: &TestDescription); - fn report_plan(&mut self, plan: &TestPlan); - fn report_wait(&mut self, description: &TestDescription); - fn report_output(&mut self, output: &[u8]); - fn report_result( - &mut self, - description: &TestDescription, - result: &TestResult, - elapsed: u64, - ); - fn report_uncaught_error(&mut self, origin: &str, error: &JsError); - fn report_step_register(&mut self, description: &TestStepDescription); - fn report_step_wait(&mut self, description: &TestStepDescription); - fn report_step_result( - &mut self, - description: &TestStepDescription, - result: &TestStepResult, - elapsed: u64, - ); - fn report_summary(&mut self, summary: &TestSummary, elapsed: &Duration); -} - -enum DeferredStepOutput { - StepWait(TestStepDescription), - StepResult(TestStepDescription, TestStepResult, u64), -} - struct PrettyTestReporter { - concurrent: bool, + parallel: bool, echo_output: bool, - deferred_step_output: IndexMap>, in_new_line: bool, last_wait_id: Option, cwd: Url, @@ -318,12 +289,11 @@ struct PrettyTestReporter { } impl PrettyTestReporter { - fn new(concurrent: bool, echo_output: bool) -> PrettyTestReporter { + fn new(parallel: bool, echo_output: bool) -> PrettyTestReporter { PrettyTestReporter { - concurrent, + parallel, echo_output, in_new_line: true, - deferred_step_output: IndexMap::new(), last_wait_id: None, cwd: Url::from_directory_path(std::env::current_dir().unwrap()).unwrap(), did_have_user_output: false, @@ -335,6 +305,15 @@ impl PrettyTestReporter { if !self.in_new_line { println!(); } + if self.parallel { + print!( + "{}", + colors::gray(format!( + "{} => ", + self.to_relative_path_or_remote_url(&description.origin) + )) + ); + } print!("{} ...", description.name); self.in_new_line = false; // flush for faster feedback when line buffered @@ -408,12 +387,13 @@ impl PrettyTestReporter { self.did_have_user_output = false; } } -} -impl TestReporter for PrettyTestReporter { fn report_register(&mut self, _description: &TestDescription) {} fn report_plan(&mut self, plan: &TestPlan) { + if self.parallel { + return; + } let inflection = if plan.total == 1 { "test" } else { "tests" }; println!( "{}", @@ -428,7 +408,7 @@ impl TestReporter for PrettyTestReporter { } fn report_wait(&mut self, description: &TestDescription) { - if !self.concurrent { + if !self.parallel { self.force_report_wait(description); } self.started_tests = true; @@ -441,7 +421,9 @@ impl TestReporter for PrettyTestReporter { if !self.did_have_user_output && self.started_tests { self.did_have_user_output = true; - println!(); + if !self.in_new_line { + println!(); + } println!("{}", colors::gray("------- output -------")); self.in_new_line = true; } @@ -457,29 +439,8 @@ impl TestReporter for PrettyTestReporter { result: &TestResult, elapsed: u64, ) { - if self.concurrent { + if self.parallel { self.force_report_wait(description); - - if let Some(step_outputs) = - self.deferred_step_output.remove(&description.id) - { - for step_output in step_outputs { - match step_output { - DeferredStepOutput::StepWait(description) => { - self.force_report_step_wait(&description) - } - DeferredStepOutput::StepResult( - step_description, - step_result, - elapsed, - ) => self.force_report_step_result( - &step_description, - &step_result, - elapsed, - ), - } - } - } } self.write_output_end(); @@ -518,13 +479,7 @@ impl TestReporter for PrettyTestReporter { fn report_step_register(&mut self, _description: &TestStepDescription) {} fn report_step_wait(&mut self, description: &TestStepDescription) { - if self.concurrent { - self - .deferred_step_output - .entry(description.root_id) - .or_insert_with(Vec::new) - .push(DeferredStepOutput::StepWait(description.clone())); - } else { + if !self.parallel { self.force_report_step_wait(description); } } @@ -534,20 +489,40 @@ impl TestReporter for PrettyTestReporter { description: &TestStepDescription, result: &TestStepResult, elapsed: u64, + tests: &IndexMap, + test_steps: &IndexMap, ) { - if self.concurrent { - self - .deferred_step_output - .entry(description.root_id) - .or_insert_with(Vec::new) - .push(DeferredStepOutput::StepResult( - description.clone(), - result.clone(), - elapsed, - )); - } else { - self.force_report_step_result(description, result, elapsed); + if self.parallel { + self.write_output_end(); + let root; + let mut ancestor_names = vec![]; + let mut current_desc = description; + loop { + if let Some(step_desc) = test_steps.get(¤t_desc.parent_id) { + ancestor_names.push(&step_desc.name); + current_desc = step_desc; + } else { + root = tests.get(¤t_desc.parent_id).unwrap(); + break; + } + } + ancestor_names.reverse(); + print!( + "{}", + colors::gray(format!( + "{} =>", + self.to_relative_path_or_remote_url(&description.origin) + )) + ); + print!(" {} ...", root.name); + for name in ancestor_names { + print!(" {} ...", name); + } + print!(" {} ...", description.name); + self.in_new_line = false; + self.last_wait_id = Some(description.id); } + self.force_report_step_result(description, result, elapsed); } fn report_summary(&mut self, summary: &TestSummary, elapsed: &Duration) { @@ -735,13 +710,6 @@ pub fn format_test_error(js_error: &JsError) -> String { format_js_error(&js_error) } -fn create_reporter( - concurrent: bool, - echo_output: bool, -) -> Box { - Box::new(PrettyTestReporter::new(concurrent, echo_output)) -} - /// Test a single specifier as documentation containing test programs, an executable test module or /// both. async fn test_specifier( @@ -1160,8 +1128,10 @@ async fn test_specifiers( .buffer_unordered(concurrent_jobs.get()) .collect::, tokio::task::JoinError>>>(); - let mut reporter = - create_reporter(concurrent_jobs.get() > 1, log_level != Some(Level::Error)); + let mut reporter = Box::new(PrettyTestReporter::new( + concurrent_jobs.get() > 1, + log_level != Some(Level::Error), + )); let handler = { tokio::task::spawn(async move { @@ -1261,6 +1231,8 @@ async fn test_specifiers( test_steps.get(&id).unwrap(), &result, duration, + &tests, + &test_steps, ); } }