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>

10 files changed, 245 insertions, 34 deletions

diff --git a/cli/Cargo.toml b/cli/Cargo.toml
index 19a6e7bbe..c044d6c72 100644
--- a/cli/Cargo.toml
+++ b/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"] }
diff --git a/cli/lsp/testing/execution.rs b/cli/lsp/testing/execution.rs
index dcf980fd6..bc780a475 100644
--- a/cli/lsp/testing/execution.rs
+++ b/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(
diff --git a/cli/ops/testing.rs b/cli/ops/testing.rs
index eb2deb90c..16544dd98 100644
--- a/cli/ops/testing.rs
+++ b/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(())
 }
diff --git a/cli/tests/integration/mod.rs b/cli/tests/integration/mod.rs
index 2578989c7..ffd7e3596 100644
--- a/cli/tests/integration/mod.rs
+++ b/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");
diff --git a/cli/tests/integration/test_tests.rs b/cli/tests/integration/test_tests.rs
index 307f0f1fe..bf0ceb038 100644
--- a/cli/tests/integration/test_tests.rs
+++ b/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,
diff --git a/cli/tests/testdata/test/steps/output_within.out b/cli/tests/testdata/test/steps/output_within.out
new file mode 100644
index 000000000..b8610d903
--- /dev/null
+++ b/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]
diff --git a/cli/tests/testdata/test/steps/output_within.ts b/cli/tests/testdata/test/steps/output_within.ts
new file mode 100644
index 000000000..d3438a8ad
--- /dev/null
+++ b/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);
+});
diff --git a/cli/tools/test.rs b/cli/tools/test.rs
index 00317794f..8cfad29ee 100644
--- a/cli/tools/test.rs
+++ b/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) =
diff --git a/core/resources.rs b/core/resources.rs
index 07d4e7041..9a1447392 100644
--- a/core/resources.rs
+++ b/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
diff --git a/runtime/js/40_testing.js b/runtime/js/40_testing.js
index c4321c748..fdd044503 100644
--- a/runtime/js/40_testing.js
+++ b/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({