feat(test): format user code output (#14271)

This commit changes "deno test" to better denote user output coming
from test cases.

This is done by printing "---- output ----" and "---- output end ----"
markers if an output is produced. The output from "console" and
"Deno.core.print" is captured, as well as direct writes to "Deno.stdout"
and "Deno.stderr".

To achieve that new APIs were added to "deno_core" crate, that allow
to replace an existing resource with a different one (while keeping resource
ids intact). Resources for stdout and stderr are replaced by pipes.

Co-authored-by: David Sherret <dsherret@gmail.com>

cli/Cargo.toml

@@ -78,6 +78,7 @@ node_resolver = "=0.1.1"
 notify = "=5.0.0-pre.14"
 num-format = "=0.4.0"
 once_cell = "=1.10.0"
+os_pipe = "=1.0.1"
 percent-encoding = "=2.1.0"
 pin-project = "=1.0.8"
 rand = { version = "=0.8.4", features = ["small_rng"] }

cli/lsp/testing/execution.rs

@@ -14,6 +14,7 @@ use crate::lsp::client::TestingNotification;
 use crate::lsp::config;
 use crate::lsp::logging::lsp_log;
 use crate::ops;
+use crate::ops::testing::create_stdout_stderr_pipes;
 use crate::proc_state;
 use crate::tools::test;
 
@@ -183,11 +184,17 @@ async fn test_specifier(
   options: Option<Value>,
 ) -> Result<(), AnyError> {
   if !token.is_cancelled() {
+    let (stdout_writer, stderr_writer) =
+      create_stdout_stderr_pipes(channel.clone());
     let mut worker = create_main_worker(
       &ps,
       specifier.clone(),
       permissions,
-      vec![ops::testing::init(channel.clone())],
+      vec![ops::testing::init(
+        channel.clone(),
+        stdout_writer,
+        stderr_writer,
+      )],
     );
 
     worker
@@ -752,16 +759,20 @@ impl test::TestReporter for LspTestReporter {
         .get(origin)
         .and_then(|v| v.last().map(|td| td.into()))
     });
-    match output {
-      test::TestOutput::Console(value) => {
-        self.progress(lsp_custom::TestRunProgressMessage::Output {
-          value: value.replace('\n', "\r\n"),
-          test,
-          // TODO(@kitsonk) test output should include a location
-          location: None,
-        })
+    let value = match output {
+      test::TestOutput::PrintStdout(value)
+      | test::TestOutput::PrintStderr(value) => value.replace('\n', "\r\n"),
+      test::TestOutput::Stdout(bytes) | test::TestOutput::Stderr(bytes) => {
+        String::from_utf8_lossy(bytes).replace('\n', "\r\n")
       }
-    }
+    };
+
+    self.progress(lsp_custom::TestRunProgressMessage::Output {
+      value,
+      test,
+      // TODO(@kitsonk) test output should include a location
+      location: None,
+    })
   }
 
   fn report_result(

cli/ops/testing.rs

@@ -1,17 +1,31 @@
+use std::cell::RefCell;
+use std::io::Read;
+use std::rc::Rc;
+
 use crate::tools::test::TestEvent;
+use crate::tools::test::TestOutput;
 use deno_core::error::generic_error;
 use deno_core::error::AnyError;
 use deno_core::op;
 use deno_core::Extension;
 use deno_core::ModuleSpecifier;
 use deno_core::OpState;
+use deno_runtime::ops::io::StdFileResource;
 use deno_runtime::permissions::create_child_permissions;
 use deno_runtime::permissions::ChildPermissionsArg;
 use deno_runtime::permissions::Permissions;
 use tokio::sync::mpsc::UnboundedSender;
 use uuid::Uuid;
 
-pub fn init(sender: UnboundedSender<TestEvent>) -> Extension {
+pub fn init(
+  sender: UnboundedSender<TestEvent>,
+  stdout_writer: os_pipe::PipeWriter,
+  stderr_writer: os_pipe::PipeWriter,
+) -> Extension {
+  // todo(dsheret): don't do this? Taking out the writers was necessary to prevent invalid handle panics
+  let stdout_writer = Rc::new(RefCell::new(Some(stdout_writer)));
+  let stderr_writer = Rc::new(RefCell::new(Some(stderr_writer)));
+
   Extension::builder()
     .ops(vec![
       op_pledge_test_permissions::decl(),
@@ -19,13 +33,82 @@ pub fn init(sender: UnboundedSender<TestEvent>) -> Extension {
       op_get_test_origin::decl(),
       op_dispatch_test_event::decl(),
     ])
+    .middleware(|op| match op.name {
+      "op_print" => op_print::decl(),
+      _ => op,
+    })
     .state(move |state| {
+      state.resource_table.replace(
+        1,
+        StdFileResource::stdio(
+          &pipe_writer_to_file(&stdout_writer.borrow_mut().take().unwrap()),
+          "stdout",
+        ),
+      );
+      state.resource_table.replace(
+        2,
+        StdFileResource::stdio(
+          &pipe_writer_to_file(&stderr_writer.borrow_mut().take().unwrap()),
+          "stderr",
+        ),
+      );
       state.put(sender.clone());
       Ok(())
     })
     .build()
 }
 
+#[cfg(windows)]
+fn pipe_writer_to_file(writer: &os_pipe::PipeWriter) -> std::fs::File {
+  use std::os::windows::prelude::AsRawHandle;
+  use std::os::windows::prelude::FromRawHandle;
+  unsafe { std::fs::File::from_raw_handle(writer.as_raw_handle()) }
+}
+
+#[cfg(unix)]
+fn pipe_writer_to_file(writer: &os_pipe::PipeWriter) -> std::fs::File {
+  use std::os::unix::io::AsRawFd;
+  use std::os::unix::io::FromRawFd;
+  unsafe { std::fs::File::from_raw_fd(writer.as_raw_fd()) }
+}
+
+/// Creates the stdout and stderr pipes and returns the writers for stdout and stderr.
+pub fn create_stdout_stderr_pipes(
+  sender: UnboundedSender<TestEvent>,
+) -> (os_pipe::PipeWriter, os_pipe::PipeWriter) {
+  let (stdout_reader, stdout_writer) = os_pipe::pipe().unwrap();
+  let (stderr_reader, stderr_writer) = os_pipe::pipe().unwrap();
+
+  start_output_redirect_thread(stdout_reader, sender.clone(), |bytes| {
+    TestOutput::Stdout(bytes)
+  });
+  start_output_redirect_thread(stderr_reader, sender, |bytes| {
+    TestOutput::Stderr(bytes)
+  });
+
+  (stdout_writer, stderr_writer)
+}
+
+fn start_output_redirect_thread(
+  mut pipe_reader: os_pipe::PipeReader,
+  sender: UnboundedSender<TestEvent>,
+  map_test_output: impl Fn(Vec<u8>) -> TestOutput + Send + 'static,
+) {
+  tokio::task::spawn_blocking(move || loop {
+    let mut buffer = [0; 512];
+    let size = match pipe_reader.read(&mut buffer) {
+      Ok(0) | Err(_) => break,
+      Ok(size) => size,
+    };
+    if sender
+      .send(TestEvent::Output(map_test_output(buffer[0..size].to_vec())))
+      .is_err()
+    {
+      break;
+    }
+  });
+}
+
 #[derive(Clone)]
 struct PermissionsHolder(Uuid, Permissions);
 
@@ -77,6 +160,21 @@ fn op_dispatch_test_event(
 ) -> Result<(), AnyError> {
   let sender = state.borrow::<UnboundedSender<TestEvent>>().clone();
   sender.send(event).ok();
-
+  Ok(())
+}
+
+#[op]
+pub fn op_print(
+  state: &mut OpState,
+  msg: String,
+  is_err: bool,
+) -> Result<(), AnyError> {
+  let sender = state.borrow::<UnboundedSender<TestEvent>>().clone();
+  let msg = if is_err {
+    TestOutput::PrintStderr(msg)
+  } else {
+    TestOutput::PrintStdout(msg)
+  };
+  sender.send(TestEvent::Output(msg)).ok();
   Ok(())
 }

cli/tests/integration/mod.rs

@@ -753,7 +753,10 @@ fn websocket_server_multi_field_connection_header() {
   assert!(child.wait().unwrap().success());
 }
 
+// TODO(bartlomieju): this should use `deno run`, not `deno test`; but the
+// test hangs then. https://github.com/denoland/deno/issues/14283
 #[test]
+#[ignore]
 fn websocket_server_idletimeout() {
   let script = util::testdata_path().join("websocket_server_idletimeout.ts");
   let root_ca = util::testdata_path().join("tls/RootCA.pem");

cli/tests/integration/test_tests.rs

@@ -281,6 +281,12 @@ itest!(steps_invalid_usage {
   output: "test/steps/invalid_usage.out",
 });
 
+itest!(steps_output_within {
+  args: "test test/steps/output_within.ts",
+  exit_code: 0,
+  output: "test/steps/output_within.out",
+});
+
 itest!(no_prompt_by_default {
   args: "test test/no_prompt_by_default.ts",
   exit_code: 1,

cli/tests/testdata/test/steps/output_within.out

@@ -0,0 +1,31 @@
+[WILDCARD]
+running 1 test from test/steps/output_within.ts
+description ...
+------- output -------
+1
+----- output end -----
+  step 1 ...
+------- output -------
+2
+----- output end -----
+    inner 1 ...
+------- output -------
+3
+----- output end -----
+    ok ([WILDCARD]ms)
+    inner 2 ...
+------- output -------
+4
+----- output end -----
+    ok ([WILDCARD]ms)
+
+------- output -------
+5
+----- output end -----
+  ok ([WILDCARD]ms)
+
+------- output -------
+6
+----- output end -----
+ok ([WILDCARD]ms)
+[WILDCARD]

cli/tests/testdata/test/steps/output_within.ts

@@ -0,0 +1,15 @@
+Deno.test("description", async (t) => {
+  // the output is not great, but this is an extreme scenario
+  console.log(1);
+  await t.step("step 1", async (t) => {
+    console.log(2);
+    await t.step("inner 1", () => {
+      console.log(3);
+    });
+    await t.step("inner 2", () => {
+      console.log(4);
+    });
+    console.log(5);
+  });
+  console.log(6);
+});

cli/tools/test.rs

@@ -21,6 +21,7 @@ use crate::graph_util::graph_valid;
 use crate::located_script_name;
 use crate::lockfile;
 use crate::ops;
+use crate::ops::testing::create_stdout_stderr_pipes;
 use crate::proc_state::ProcState;
 use crate::resolver::ImportMapResolver;
 use crate::resolver::JsxResolver;
@@ -80,8 +81,10 @@ pub struct TestDescription {
 #[derive(Debug, Clone, PartialEq, Deserialize)]
 #[serde(rename_all = "camelCase")]
 pub enum TestOutput {
-  // TODO(caspervonb): add stdout and stderr redirection.
-  Console(String),
+  PrintStdout(String),
+  PrintStderr(String),
+  Stdout(Vec<u8>),
+  Stderr(Vec<u8>),
 }
 
 #[derive(Debug, Clone, PartialEq, Deserialize)]
@@ -219,8 +222,10 @@ struct PrettyTestReporter {
   concurrent: bool,
   echo_output: bool,
   deferred_step_output: HashMap<TestDescription, Vec<DeferredStepOutput>>,
+  in_test_count: usize,
   last_wait_output_level: usize,
   cwd: Url,
+  did_have_user_output: bool,
 }
 
 impl PrettyTestReporter {
@@ -228,9 +233,11 @@ impl PrettyTestReporter {
     PrettyTestReporter {
       concurrent,
       echo_output,
+      in_test_count: 0,
       deferred_step_output: HashMap::new(),
       last_wait_output_level: 0,
       cwd: Url::from_directory_path(std::env::current_dir().unwrap()).unwrap(),
+      did_have_user_output: false,
     }
   }
 
@@ -251,7 +258,8 @@ impl PrettyTestReporter {
   }
 
   fn force_report_step_wait(&mut self, description: &TestStepDescription) {
-    if self.last_wait_output_level < description.level {
+    let wrote_user_output = self.write_output_end();
+    if !wrote_user_output && self.last_wait_output_level < description.level {
       println!();
     }
     print!("{}{} ...", "  ".repeat(description.level), description.name);
@@ -273,7 +281,8 @@ impl PrettyTestReporter {
       TestStepResult::Failed(_) => colors::red("FAILED").to_string(),
     };
 
-    if self.last_wait_output_level == description.level {
+    let wrote_user_output = self.write_output_end();
+    if !wrote_user_output && self.last_wait_output_level == description.level {
       print!(" ");
     } else {
       print!("{}", "  ".repeat(description.level));
@@ -291,6 +300,16 @@ impl PrettyTestReporter {
       }
     }
   }
+
+  fn write_output_end(&mut self) -> bool {
+    if self.did_have_user_output {
+      println!("{}", colors::gray("----- output end -----"));
+      self.did_have_user_output = false;
+      true
+    } else {
+      false
+    }
+  }
 }
 
 impl TestReporter for PrettyTestReporter {
@@ -311,12 +330,31 @@ impl TestReporter for PrettyTestReporter {
     if !self.concurrent {
       self.force_report_wait(description);
     }
+    self.in_test_count += 1;
   }
 
   fn report_output(&mut self, output: &TestOutput) {
-    if self.echo_output {
-      match output {
-        TestOutput::Console(line) => println!("{}", line),
+    if !self.echo_output {
+      return;
+    }
+
+    if !self.did_have_user_output && self.in_test_count > 0 {
+      self.did_have_user_output = true;
+      println!();
+      println!("{}", colors::gray("------- output -------"));
+    }
+    match output {
+      TestOutput::PrintStdout(line) => {
+        print!("{}", line)
+      }
+      TestOutput::PrintStderr(line) => {
+        eprint!("{}", line)
+      }
+      TestOutput::Stdout(bytes) => {
+        std::io::stdout().write_all(bytes).unwrap();
+      }
+      TestOutput::Stderr(bytes) => {
+        std::io::stderr().write_all(bytes).unwrap();
       }
     }
   }
@@ -327,6 +365,8 @@ impl TestReporter for PrettyTestReporter {
     result: &TestResult,
     elapsed: u64,
   ) {
+    self.in_test_count -= 1;
+
     if self.concurrent {
       self.force_report_wait(description);
 
@@ -351,16 +391,17 @@ impl TestReporter for PrettyTestReporter {
       }
     }
 
+    let wrote_user_output = self.write_output_end();
+    if !wrote_user_output && self.last_wait_output_level == 0 {
+      print!(" ");
+    }
+
     let status = match result {
       TestResult::Ok => colors::green("ok").to_string(),
       TestResult::Ignored => colors::yellow("ignored").to_string(),
       TestResult::Failed(_) => colors::red("FAILED").to_string(),
     };
 
-    if self.last_wait_output_level == 0 {
-      print!(" ");
-    }
-
     println!(
       "{} {}",
       status,
@@ -487,11 +528,17 @@ async fn test_specifier(
   channel: UnboundedSender<TestEvent>,
   options: TestSpecifierOptions,
 ) -> Result<(), AnyError> {
+  let (stdout_writer, stderr_writer) =
+    create_stdout_stderr_pipes(channel.clone());
   let mut worker = create_main_worker(
     &ps,
     specifier.clone(),
     permissions,
-    vec![ops::testing::init(channel.clone())],
+    vec![ops::testing::init(
+      channel.clone(),
+      stdout_writer,
+      stderr_writer,
+    )],
   );
 
   let mut maybe_coverage_collector = if let Some(ref coverage_dir) =

core/resources.rs

@@ -147,6 +147,16 @@ impl ResourceTable {
       .ok_or_else(bad_resource_id)
   }
 
+  /// Replaces a resource with a new resource.
+  ///
+  /// Panics if the resource does not exist.
+  pub fn replace<T: Resource>(&mut self, rid: ResourceId, resource: T) {
+    let result = self
+      .index
+      .insert(rid, Rc::new(resource) as Rc<dyn Resource>);
+    assert!(result.is_some());
+  }
+
   /// Removes a resource of type `T` from the resource table and returns it.
   /// If a resource with the given `rid` exists but its type does not match `T`,
   /// it is not removed from the resource table. Note that the resource's

runtime/js/40_testing.js

@@ -871,12 +871,6 @@
     });
   }
 
-  function reportTestConsoleOutput(console) {
-    core.opSync("op_dispatch_test_event", {
-      output: { console },
-    });
-  }
-
   function reportTestWait(test) {
     core.opSync("op_dispatch_test_event", {
       wait: test,
@@ -955,9 +949,6 @@
     core.setMacrotaskCallback(handleOpSanitizerDelayMacrotask);
 
     const origin = getTestOrigin();
-    const originalConsole = globalThis.console;
-
-    globalThis.console = new Console(reportTestConsoleOutput);
 
     const only = ArrayPrototypeFilter(tests, (test) => test.only);
     const filtered = ArrayPrototypeFilter(
@@ -1004,8 +995,6 @@
 
       reportTestResult(description, result, elapsed);
     }
-
-    globalThis.console = originalConsole;
   }
 
   async function runBenchmarks({