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>

8 files changed, 235 insertions, 23 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) =