fix(test): output parallel test results independently (#15399)

.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)

cli/lsp/testing/execution.rs

@@ -374,8 +374,7 @@ impl TestRun {
       .buffer_unordered(concurrent_jobs)
       .collect::<Vec<Result<Result<(), AnyError>, tokio::task::JoinError>>>();
 
-    let mut reporter: Box<dyn test::TestReporter + Send> =
-      Box::new(LspTestReporter::new(
+    let mut reporter = Box::new(LspTestReporter::new(
       self,
       client.clone(),
       maybe_root_uri,
@@ -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) {

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,
+});

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

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.");
+    });
+  });
+});

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])
 

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])
 

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 -----

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<usize, Vec<DeferredStepOutput>>,
   in_new_line: bool,
   last_wait_id: Option<usize>,
   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;
+      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,21 +489,41 @@ impl TestReporter for PrettyTestReporter {
     description: &TestStepDescription,
     result: &TestStepResult,
     elapsed: u64,
+    tests: &IndexMap<usize, TestDescription>,
+    test_steps: &IndexMap<usize, TestStepDescription>,
   ) {
-    if self.concurrent {
-      self
-        .deferred_step_output
-        .entry(description.root_id)
-        .or_insert_with(Vec::new)
-        .push(DeferredStepOutput::StepResult(
-          description.clone(),
-          result.clone(),
-          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(&current_desc.parent_id) {
+          ancestor_names.push(&step_desc.name);
+          current_desc = step_desc;
         } else {
-      self.force_report_step_result(description, result, elapsed);
+          root = tests.get(&current_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) {
     if !summary.failures.is_empty() || !summary.uncaught_errors.is_empty() {
@@ -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<dyn TestReporter + Send> {
-  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::<Vec<Result<Result<(), AnyError>, 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,
             );
           }
         }