chore: improve spec tests output (#22908)

tests/specs/mod.rs

@@ -1,8 +1,13 @@
 // Copyright 2018-2024 the Deno authors. All rights reserved. MIT license.
 
+use std::cell::RefCell;
 use std::collections::HashSet;
+use std::panic::AssertUnwindSafe;
+use std::rc::Rc;
+use std::sync::Arc;
 
 use deno_core::anyhow::Context;
+use deno_core::parking_lot::Mutex;
 use deno_core::serde_json;
 use deno_terminal::colors;
 use serde::Deserialize;
@@ -21,22 +26,36 @@ pub fn main() {
   for category in &categories {
     eprintln!();
     eprintln!("     {} {}", colors::green_bold("Running"), category.name);
+    eprintln!();
     for test in &category.tests {
-      eprintln!();
-      eprintln!("==== Starting {} ====", test.name);
-      let result = std::panic::catch_unwind(|| run_test(test));
+      eprint!("test {} ... ", test.name);
+      let diagnostic_logger = Rc::new(RefCell::new(Vec::<u8>::new()));
+      let panic_message = Arc::new(Mutex::new(Vec::<u8>::new()));
+      std::panic::set_hook({
+        let panic_message = panic_message.clone();
+        Box::new(move |info| {
+          panic_message
+            .lock()
+            .extend(format!("{}", info).into_bytes());
+        })
+      });
+      let result = std::panic::catch_unwind(AssertUnwindSafe(|| {
+        run_test(test, diagnostic_logger.clone())
+      }));
       let success = result.is_ok();
       if !success {
-        failures.push(&test.name);
+        let mut output = diagnostic_logger.borrow().clone();
+        output.push(b'\n');
+        output.extend(panic_message.lock().iter());
+        failures.push((test, output));
       }
       eprintln!(
-        "==== {} {} ====",
+        "{}",
         if success {
-          "Finished".to_string()
+          colors::green("ok")
         } else {
-          colors::red("^^FAILED^^").to_string()
+          colors::red("fail")
         },
-        test.name
       );
     }
   }
@@ -44,13 +63,18 @@ pub fn main() {
   eprintln!();
   if !failures.is_empty() {
     eprintln!("spec failures:");
-    for failure in &failures {
-      eprintln!("  {}", failure);
-    }
     eprintln!();
+    for (failure, output) in &failures {
+      eprintln!("---- {} ----", failure.name);
+      eprintln!("{}", String::from_utf8_lossy(output));
+      eprintln!("Test file: {}", failure.manifest_file());
+      eprintln!();
+    }
     panic!("{} failed of {}", failures.len(), total_tests);
+  } else {
+    eprintln!("{} tests passed", total_tests);
   }
-  eprintln!("{} tests passed", total_tests);
+  eprintln!();
 }
 
 fn parse_cli_arg_filter() -> Option<String> {
@@ -60,9 +84,10 @@ fn parse_cli_arg_filter() -> Option<String> {
   maybe_filter.cloned()
 }
 
-fn run_test(test: &Test) {
+fn run_test(test: &Test, diagnostic_logger: Rc<RefCell<Vec<u8>>>) {
   let metadata = &test.metadata;
   let mut builder = TestContextBuilder::new();
+  builder = builder.logging_capture(diagnostic_logger);
   let cwd = &test.cwd;
 
   if test.metadata.temp_dir {
@@ -77,7 +102,7 @@ fn run_test(test: &Test) {
         builder = builder.add_npm_env_vars();
       }
       "jsr" => {
-        builder = builder.add_jsr_env_vars();
+        builder = builder.add_jsr_env_vars().add_npm_env_vars();
       }
       _ => panic!("Unknown test base: {}", base),
     }
@@ -178,10 +203,16 @@ struct Test {
   pub metadata: MultiTestMetaData,
 }
 
+impl Test {
+  pub fn manifest_file(&self) -> PathRef {
+    self.cwd.join("__test__.json")
+  }
+}
+
 impl Test {
   pub fn resolve_test_and_assertion_files(&self) -> HashSet<PathRef> {
     let mut result = HashSet::with_capacity(self.metadata.steps.len() + 1);
-    result.insert(self.cwd.join("__test__.json"));
+    result.insert(self.manifest_file());
     result.extend(
       self
         .metadata

tests/util/server/src/assertions.rs

@@ -1,5 +1,7 @@
 // Copyright 2018-2024 the Deno authors. All rights reserved. MIT license.
 
+use std::io::Write;
+
 use crate::colors;
 
 #[macro_export]
@@ -54,6 +56,15 @@ macro_rules! assert_not_contains {
 
 #[track_caller]
 pub fn assert_wildcard_match(actual: &str, expected: &str) {
+  assert_wildcard_match_with_logger(actual, expected, &mut std::io::stderr())
+}
+
+#[track_caller]
+pub fn assert_wildcard_match_with_logger(
+  actual: &str,
+  expected: &str,
+  logger: &mut dyn Write,
+) {
   if !expected.contains("[WILD") && !expected.contains("[UNORDERED_START]") {
     pretty_assertions::assert_eq!(actual, expected);
   } else {
@@ -62,30 +73,36 @@ pub fn assert_wildcard_match(actual: &str, expected: &str) {
         // ignore
       }
       crate::WildcardMatchResult::Fail(debug_output) => {
-        println!(
+        writeln!(
+          logger,
           "{}{}{}",
           colors::bold("-- "),
           colors::bold_red("OUTPUT"),
           colors::bold(" START --"),
-        );
-        println!("{}", actual);
-        println!("{}", colors::bold("-- OUTPUT END --"));
-        println!(
+        )
+        .unwrap();
+        writeln!(logger, "{}", actual).unwrap();
+        writeln!(logger, "{}", colors::bold("-- OUTPUT END --")).unwrap();
+        writeln!(
+          logger,
           "{}{}{}",
           colors::bold("-- "),
           colors::bold_green("EXPECTED"),
           colors::bold(" START --"),
-        );
-        println!("{}", expected);
-        println!("{}", colors::bold("-- EXPECTED END --"));
-        println!(
+        )
+        .unwrap();
+        writeln!(logger, "{}", expected).unwrap();
+        writeln!(logger, "{}", colors::bold("-- EXPECTED END --")).unwrap();
+        writeln!(
+          logger,
           "{}{}{}",
           colors::bold("-- "),
           colors::bold_blue("DEBUG"),
           colors::bold(" START --"),
-        );
-        println!("{debug_output}");
-        println!("{}", colors::bold("-- DEBUG END --"));
+        )
+        .unwrap();
+        writeln!(logger, "{debug_output}").unwrap();
+        writeln!(logger, "{}", colors::bold("-- DEBUG END --")).unwrap();
         panic!("pattern match failed");
       }
     }

tests/util/server/src/builders.rs

@@ -19,6 +19,7 @@ use std::rc::Rc;
 use os_pipe::pipe;
 
 use crate::assertions::assert_wildcard_match;
+use crate::assertions::assert_wildcard_match_with_logger;
 use crate::deno_exe_path;
 use crate::denort_exe_path;
 use crate::env_vars_for_jsr_tests;
@@ -65,8 +66,25 @@ static HAS_DENO_JSON_IN_WORKING_DIR_ERR: once_cell::sync::Lazy<Option<String>> =
     None
   });
 
+#[derive(Default, Clone)]
+struct DiagnosticLogger(Option<Rc<RefCell<Vec<u8>>>>);
+
+impl DiagnosticLogger {
+  pub fn writeln(&self, text: impl AsRef<str>) {
+    match &self.0 {
+      Some(logger) => {
+        let mut logger = logger.borrow_mut();
+        logger.write_all(text.as_ref().as_bytes()).unwrap();
+        logger.write_all(b"\n").unwrap();
+      }
+      None => eprintln!("{}", text.as_ref()),
+    }
+  }
+}
+
 #[derive(Default)]
 pub struct TestContextBuilder {
+  diagnostic_logger: DiagnosticLogger,
   use_http_server: bool,
   use_temp_cwd: bool,
   use_symlinked_temp_dir: bool,
@@ -92,6 +110,11 @@ impl TestContextBuilder {
     Self::new().use_http_server().add_jsr_env_vars()
   }
 
+  pub fn logging_capture(mut self, logger: Rc<RefCell<Vec<u8>>>) -> Self {
+    self.diagnostic_logger = DiagnosticLogger(Some(logger));
+    self
+  }
+
   pub fn temp_dir_path(mut self, path: impl AsRef<Path>) -> Self {
     self.temp_dir_path = Some(path.as_ref().to_path_buf());
     self
@@ -202,7 +225,9 @@ impl TestContextBuilder {
     }
 
     let deno_exe = deno_exe_path();
-    println!("deno_exe path {}", deno_exe);
+    self
+      .diagnostic_logger
+      .writeln(format!("deno_exe path {}", deno_exe));
 
     let http_server_guard = if self.use_http_server {
       Some(Rc::new(http_server()))
@@ -224,6 +249,7 @@ impl TestContextBuilder {
       cwd,
       deno_exe,
       envs: self.envs.clone(),
+      diagnostic_logger: self.diagnostic_logger.clone(),
       _http_server_guard: http_server_guard,
       deno_dir,
       temp_dir,
@@ -234,6 +260,7 @@ impl TestContextBuilder {
 #[derive(Clone)]
 pub struct TestContext {
   deno_exe: PathRef,
+  diagnostic_logger: DiagnosticLogger,
   envs: HashMap<String, String>,
   cwd: PathRef,
   _http_server_guard: Option<Rc<HttpServerGuard>>,
@@ -262,6 +289,7 @@ impl TestContext {
 
   pub fn new_command(&self) -> TestCommandBuilder {
     TestCommandBuilder::new(self.deno_dir.clone())
+      .set_diagnostic_logger(self.diagnostic_logger.clone())
       .envs(self.envs.clone())
       .current_dir(&self.cwd)
   }
@@ -345,6 +373,7 @@ impl StdioContainer {
 #[derive(Clone)]
 pub struct TestCommandBuilder {
   deno_dir: TempDir,
+  diagnostic_logger: DiagnosticLogger,
   stdin: Option<StdioContainer>,
   stdout: Option<StdioContainer>,
   stderr: Option<StdioContainer>,
@@ -363,6 +392,7 @@ impl TestCommandBuilder {
   pub fn new(deno_dir: TempDir) -> Self {
     Self {
       deno_dir,
+      diagnostic_logger: Default::default(),
       stdin: None,
       stdout: None,
       stderr: None,
@@ -505,6 +535,11 @@ impl TestCommandBuilder {
     self
   }
 
+  fn set_diagnostic_logger(mut self, logger: DiagnosticLogger) -> Self {
+    self.diagnostic_logger = logger;
+    self
+  }
+
   pub fn with_pty(&self, mut action: impl FnMut(Pty)) {
     if !Pty::is_supported() {
       return;
@@ -533,8 +568,14 @@ impl TestCommandBuilder {
       .unwrap_or_else(|| std::env::current_dir().unwrap());
     let command_path = self.build_command_path();
 
-    println!("command {} {}", command_path, args.join(" "));
-    println!("command cwd {}", cwd.display());
+    self.diagnostic_logger.writeln(format!(
+      "command {} {}",
+      command_path,
+      args.join(" ")
+    ));
+    self
+      .diagnostic_logger
+      .writeln(format!("command cwd {}", cwd.display()));
     action(Pty::new(command_path.as_path(), &args, &cwd, Some(envs)))
   }
 
@@ -650,6 +691,7 @@ impl TestCommandBuilder {
       asserted_stdout: RefCell::new(false),
       asserted_stderr: RefCell::new(false),
       asserted_combined: RefCell::new(false),
+      diagnostic_logger: self.diagnostic_logger.clone(),
       _deno_dir: self.deno_dir.clone(),
     }
   }
@@ -657,10 +699,16 @@ impl TestCommandBuilder {
   fn build_command(&self) -> Command {
     let command_path = self.build_command_path();
     let args = self.build_args();
-    println!("command {} {}", command_path, args.join(" "));
+    self.diagnostic_logger.writeln(format!(
+      "command {} {}",
+      command_path,
+      args.join(" ")
+    ));
     let mut command = Command::new(command_path);
     if let Some(cwd) = &self.cwd {
-      println!("command cwd {}", cwd);
+      self
+        .diagnostic_logger
+        .writeln(format!("command cwd {}", cwd));
       command.current_dir(cwd);
     }
     if let Some(stdin) = &self.stdin {
@@ -774,6 +822,7 @@ pub struct TestCommandOutput {
   asserted_stderr: RefCell<bool>,
   asserted_combined: RefCell<bool>,
   asserted_exit_code: RefCell<bool>,
+  diagnostic_logger: DiagnosticLogger,
   // keep alive for the duration of the output reference
   _deno_dir: TempDir,
 }
@@ -781,12 +830,14 @@ pub struct TestCommandOutput {
 impl Drop for TestCommandOutput {
   // assert the output and exit code was asserted
   fn drop(&mut self) {
-    fn panic_unasserted_output(text: &str) {
-      println!("OUTPUT\n{text}\nOUTPUT");
+    fn panic_unasserted_output(output: &TestCommandOutput, text: &str) {
+      output
+        .diagnostic_logger
+        .writeln(format!("OUTPUT\n{}\nOUTPUT", text));
       panic!(concat!(
         "The non-empty text of the command was not asserted. ",
         "Call `output.skip_output_check()` to skip if necessary.",
-      ),);
+      ));
     }
 
     if std::thread::panicking() {
@@ -796,15 +847,15 @@ impl Drop for TestCommandOutput {
     // either the combined output needs to be asserted or both stdout and stderr
     if let Some(combined) = &self.combined {
       if !*self.asserted_combined.borrow() && !combined.is_empty() {
-        panic_unasserted_output(combined);
+        panic_unasserted_output(self, combined);
       }
     }
     if let Some((stdout, stderr)) = &self.std_out_err {
       if !*self.asserted_stdout.borrow() && !stdout.is_empty() {
-        panic_unasserted_output(stdout);
+        panic_unasserted_output(self, stdout);
       }
       if !*self.asserted_stderr.borrow() && !stderr.is_empty() {
-        panic_unasserted_output(stderr);
+        panic_unasserted_output(self, stderr);
       }
     }
 
@@ -910,10 +961,16 @@ impl TestCommandOutput {
 
   pub fn print_output(&self) {
     if let Some(combined) = &self.combined {
-      println!("OUTPUT\n{combined}\nOUTPUT");
+      self
+        .diagnostic_logger
+        .writeln(format!("OUTPUT\n{combined}\nOUTPUT"));
     } else if let Some((stdout, stderr)) = &self.std_out_err {
-      println!("STDOUT OUTPUT\n{stdout}\nSTDOUT OUTPUT");
-      println!("STDERR OUTPUT\n{stderr}\nSTDERR OUTPUT");
+      self
+        .diagnostic_logger
+        .writeln(format!("STDOUT OUTPUT\n{stdout}\nSTDOUT OUTPUT"));
+      self
+        .diagnostic_logger
+        .writeln(format!("STDERR OUTPUT\n{stderr}\nSTDERR OUTPUT"));
     }
   }
 
@@ -965,7 +1022,14 @@ impl TestCommandOutput {
     actual: &str,
     expected: impl AsRef<str>,
   ) -> &Self {
-    assert_wildcard_match(actual, expected.as_ref());
+    match &self.diagnostic_logger.0 {
+      Some(logger) => assert_wildcard_match_with_logger(
+        actual,
+        expected.as_ref(),
+        &mut *logger.borrow_mut(),
+      ),
+      None => assert_wildcard_match(actual, expected.as_ref()),
+    };
     self
   }
 
@@ -976,7 +1040,9 @@ impl TestCommandOutput {
     file_path: impl AsRef<Path>,
   ) -> &Self {
     let output_path = testdata_path().join(file_path);
-    println!("output path {}", output_path);
+    self
+      .diagnostic_logger
+      .writeln(format!("output path {}", output_path));
     let expected_text = output_path.read_to_string();
     self.inner_assert_matches_text(actual, expected_text)
   }

tests/util/server/src/fs.rs

@@ -147,7 +147,7 @@ impl PathRef {
     )
     .with_context(|| format!("Failed to parse {}", self))
     .unwrap()
-    .expect("Found no value.")
+    .unwrap_or_else(|| panic!("JSON file was empty for {}", self))
   }
 
   pub fn rename(&self, to: impl AsRef<Path>) {