feat(cli): Add slow test warning (#23874)

By default, uses a 60 second timeout, backing off 2x each time (can be
overridden using the hidden `DENO_SLOW_TEST_TIMEOUT` which we implement
only really for spec testing.

```
Deno.test(async function test() {
  await new Promise(r => setTimeout(r, 130_000));
});
```

```
$ target/debug/deno test /tmp/test_slow.ts 
Check file:///tmp/test_slow.ts
running 1 test from ../../../../../../tmp/test_slow.ts
test ...'test' is running very slowly (1m0s)
'test' is running very slowly (2m0s)
 ok (2m10s)

ok | 1 passed | 0 failed (2m10s)
```

---------

Signed-off-by: Matt Mastracci <matthew@mastracci.com>
Co-authored-by: Bartek Iwańczuk <biwanczuk@gmail.com>

cli/lsp/testing/execution.rs

@@ -353,6 +353,9 @@ impl TestRun {
             test::TestEvent::Output(_, output) => {
               reporter.report_output(&output);
             }
+            test::TestEvent::Slow(id, elapsed) => {
+              reporter.report_slow(tests.read().get(&id).unwrap(), elapsed);
+            }
             test::TestEvent::Result(id, result, elapsed) => {
               if tests_with_result.insert(id) {
                 let description = tests.read().get(&id).unwrap().clone();
@@ -610,6 +613,8 @@ impl LspTestReporter {
     self.progress(lsp_custom::TestRunProgressMessage::Started { test });
   }
 
+  fn report_slow(&mut self, _desc: &test::TestDescription, _elapsed: u64) {}
+
   fn report_output(&mut self, output: &[u8]) {
     let test = self
       .current_test

cli/tools/test/mod.rs

@@ -74,6 +74,7 @@ use std::collections::BTreeMap;
 use std::collections::BTreeSet;
 use std::collections::HashMap;
 use std::collections::HashSet;
+use std::env;
 use std::fmt::Write as _;
 use std::future::poll_fn;
 use std::io::Write;
@@ -454,6 +455,7 @@ pub enum TestEvent {
   Plan(TestPlan),
   Wait(usize),
   Output(TestStdioStream, Vec<u8>),
+  Slow(usize, u64),
   Result(usize, TestResult, u64),
   UncaughtError(String, Box<JsError>),
   StepRegister(TestStepDescription),
@@ -912,11 +914,44 @@ async fn run_tests_for_worker_inner(
 
     let earlier = Instant::now();
     let call = worker.js_runtime.call(&function);
-    let result = match worker
+
+    let slow_state_rc = state_rc.clone();
+    let slow_test_id = desc.id;
+    let slow_test_warning = spawn(async move {
+      // The slow test warning should pop up every DENO_SLOW_TEST_TIMEOUT*(2**n) seconds,
+      // with a duration that is doubling each time. So for a warning time of 60s,
+      // we should get a warning at 60s, 120s, 240s, etc.
+      let base_timeout = env::var("DENO_SLOW_TEST_TIMEOUT").unwrap_or_default();
+      let base_timeout = base_timeout.parse().unwrap_or(60).max(1);
+      let mut multiplier = 1;
+      let mut elapsed = 0;
+      loop {
+        tokio::time::sleep(Duration::from_secs(
+          base_timeout * (multiplier - elapsed),
+        ))
+        .await;
+        if send_test_event(
+          &slow_state_rc,
+          TestEvent::Slow(
+            slow_test_id,
+            Duration::from_secs(base_timeout * multiplier).as_millis() as _,
+          ),
+        )
+        .is_err()
+        {
+          break;
+        }
+        multiplier *= 2;
+        elapsed += 1;
+      }
+    });
+
+    let result = worker
       .js_runtime
       .with_event_loop_promise(call, PollEventLoopOptions::default())
-      .await
+      .await;
-    {
+    slow_test_warning.abort();
+    let result = match result {
       Ok(r) => r,
       Err(error) => {
         if error.is::<JsError>() {
@@ -1458,6 +1493,9 @@ pub async fn report_tests(
       TestEvent::Output(_, output) => {
         reporter.report_output(&output);
       }
+      TestEvent::Slow(id, elapsed) => {
+        reporter.report_slow(tests.get(&id).unwrap(), elapsed);
+      }
       TestEvent::Result(id, result, elapsed) => {
         if tests_with_result.insert(id) {
           match result {

cli/tools/test/reporters/compound.rs

@@ -31,6 +31,12 @@ impl TestReporter for CompoundTestReporter {
     }
   }
 
+  fn report_slow(&mut self, description: &TestDescription, elapsed: u64) {
+    for reporter in &mut self.test_reporters {
+      reporter.report_slow(description, elapsed);
+    }
+  }
+
   fn report_output(&mut self, output: &[u8]) {
     for reporter in &mut self.test_reporters {
       reporter.report_output(output);

cli/tools/test/reporters/dot.rs

@@ -95,6 +95,7 @@ impl TestReporter for DotTestReporter {
     std::io::stdout().flush().unwrap();
   }
 
+  fn report_slow(&mut self, _description: &TestDescription, _elapsed: u64) {}
   fn report_output(&mut self, _output: &[u8]) {}
 
   fn report_result(

cli/tools/test/reporters/junit.rs

@@ -92,6 +92,7 @@ impl TestReporter for JunitTestReporter {
 
   fn report_plan(&mut self, _plan: &TestPlan) {}
 
+  fn report_slow(&mut self, _description: &TestDescription, _elapsed: u64) {}
   fn report_wait(&mut self, _description: &TestDescription) {}
 
   fn report_output(&mut self, _output: &[u8]) {

cli/tools/test/reporters/mod.rs

@@ -19,6 +19,7 @@ pub trait TestReporter {
   fn report_register(&mut self, description: &TestDescription);
   fn report_plan(&mut self, plan: &TestPlan);
   fn report_wait(&mut self, description: &TestDescription);
+  fn report_slow(&mut self, description: &TestDescription, elapsed: u64);
   fn report_output(&mut self, output: &[u8]);
   fn report_result(
     &mut self,

cli/tools/test/reporters/pretty.rs

@@ -197,6 +197,18 @@ impl TestReporter for PrettyTestReporter {
     self.started_tests = true;
   }
 
+  fn report_slow(&mut self, description: &TestDescription, elapsed: u64) {
+    writeln!(
+      &mut self.writer,
+      "{}",
+      colors::yellow_bold(format!(
+        "'{}' has been running for over {}",
+        description.name,
+        colors::gray(format!("({})", display::human_elapsed(elapsed.into()))),
+      ))
+    )
+    .unwrap();
+  }
   fn report_output(&mut self, output: &[u8]) {
     if !self.echo_output {
       return;

cli/tools/test/reporters/tap.rs

@@ -140,6 +140,7 @@ impl TestReporter for TapTestReporter {
     std::io::stdout().flush().unwrap();
   }
 
+  fn report_slow(&mut self, _description: &TestDescription, _elapsed: u64) {}
   fn report_output(&mut self, _output: &[u8]) {}
 
   fn report_result(

tests/specs/test/slow_test/__test__.jsonc

@@ -0,0 +1,8 @@
+{
+  "args": "test main.js",
+  "envs": {
+    "DENO_SLOW_TEST_TIMEOUT": "1"
+  },
+  "output": "main.out",
+  "exitCode": 0
+}

tests/specs/test/slow_test/main.js

@@ -0,0 +1,4 @@
+Deno.test(async function test() {
+  // We want to get at least one slow test warning
+  await new Promise((r) => setTimeout(r, 3_000));
+});

tests/specs/test/slow_test/main.out

@@ -0,0 +1,3 @@
+running 1 test from [WILDCARD]
+test ...'test' has been running for over (1s)
+[WILDCARD]