feat(test): improved op sanitizer errors + traces (#13676)

This commit improves the error messages for the `deno test` async op
sanitizer. It does this in two ways:
- it uses handwritten error messages for each op that could be leaking
- it includes traces showing where each op was started

This "async op tracing" functionality is a new feature in deno_core.
It likely has a significant performance impact, which is why it is only
enabled in tests.

cli/tests/testdata/test/ops_sanitizer_multiple_timeout_tests.out

@@ -6,45 +6,35 @@ test test 2 ... FAILED ([WILDCARD])
 failures:
 
 test 1
-AssertionError: Test case is leaking async ops.
-Before:
-  - dispatched: 0
-  - completed: 0
-After:
-  - dispatched: [WILDCARD]
-  - completed: [WILDCARD]
-Ops:
-  op_sleep:
-    Before:
-      - dispatched: 0
-      - completed: 0
-    After:
-      - dispatched: [WILDCARD]
-      - completed: [WILDCARD]
-
-Make sure to await all promises returned from Deno APIs before
-finishing test case.
+Test case is leaking async ops.
+
+- 2 async operations to sleep for a duration were started in this test, but never completed. This is often caused by not cancelling a `setTimeout` or `setInterval` call. The operations were started here:
+    at [WILDCARD]
+    at setTimeout ([WILDCARD])
+    at test ([WILDCARD]/testdata/test/ops_sanitizer_multiple_timeout_tests.ts:4:3)
+    at [WILDCARD]/testdata/test/ops_sanitizer_multiple_timeout_tests.ts:8:27
+    at [WILDCARD]
+
+    at [WILDCARD]
+    at setTimeout ([WILDCARD])
+    at test ([WILDCARD]/testdata/test/ops_sanitizer_multiple_timeout_tests.ts:5:3)
+    at [WILDCARD]/testdata/test/ops_sanitizer_multiple_timeout_tests.ts:8:27
     at [WILDCARD]
 
 test 2
-AssertionError: Test case is leaking async ops.
-Before:
-  - dispatched: [WILDCARD]
-  - completed: [WILDCARD]
-After:
-  - dispatched: [WILDCARD]
-  - completed: [WILDCARD]
-Ops:
-  op_sleep:
-    Before:
-      - dispatched: [WILDCARD]
-      - completed: [WILDCARD]
-    After:
-      - dispatched: [WILDCARD]
-      - completed: [WILDCARD]
-
-Make sure to await all promises returned from Deno APIs before
-finishing test case.
+Test case is leaking async ops.
+
+- 2 async operations to sleep for a duration were started in this test, but never completed. This is often caused by not cancelling a `setTimeout` or `setInterval` call. The operations were started here:
+    at [WILDCARD]
+    at setTimeout ([WILDCARD])
+    at test ([WILDCARD]/testdata/test/ops_sanitizer_multiple_timeout_tests.ts:4:3)
+    at [WILDCARD]/testdata/test/ops_sanitizer_multiple_timeout_tests.ts:10:27
+    at [WILDCARD]
+
+    at [WILDCARD]
+    at setTimeout ([WILDCARD])
+    at test ([WILDCARD]/testdata/test/ops_sanitizer_multiple_timeout_tests.ts:5:3)
+    at [WILDCARD]/testdata/test/ops_sanitizer_multiple_timeout_tests.ts:10:27
     at [WILDCARD]
 
 failures:

cli/tests/testdata/test/ops_sanitizer_multiple_timeout_tests.ts

@@ -5,6 +5,6 @@ function test() {
   setTimeout(() => {}, 10001);
 }
 
-Deno.test("test 1", test);
+Deno.test("test 1", () => test());
 
-Deno.test("test 2", test);
+Deno.test("test 2", () => test());

cli/tests/testdata/test/ops_sanitizer_unstable.out

@@ -6,24 +6,12 @@ test leak interval ... FAILED ([WILDCARD])
 failures:
 
 leak interval
-AssertionError: Test case is leaking async ops.
-Before:
-  - dispatched: 1
-  - completed: 1
-After:
-  - dispatched: [WILDCARD]
-  - completed: [WILDCARD]
-Ops:
-  op_sleep:
-    Before:
-      - dispatched: 1
-      - completed: 1
-    After:
-      - dispatched: [WILDCARD]
-      - completed: [WILDCARD]
+Test case is leaking async ops.
 
-Make sure to await all promises returned from Deno APIs before
-finishing test case.
+- 1 async operation to sleep for a duration was started in this test, but never completed. This is often caused by not cancelling a `setTimeout` or `setInterval` call. The operation was started here:
+    at [WILDCARD]
+    at setInterval ([WILDCARD])
+    at [WILDCARD]/testdata/test/ops_sanitizer_unstable.ts:3:3
     at [WILDCARD]
 
 failures:

cli/tests/testdata/test/ops_sanitizer_unstable.ts

@@ -1,4 +1,4 @@
 Deno.test("no-op", function () {});
 Deno.test("leak interval", function () {
-  setInterval(function () {});
+  setInterval(function () {}, 100000);
 });

cli/tests/unit/http_test.ts

@@ -868,7 +868,7 @@ Deno.test(
     const readable = new ReadableStream({
       async pull(controller) {
         client.close();
-        await delay(100);
+        await delay(1000);
         controller.enqueue(new TextEncoder().encode(
           "written to the writable side of a TransformStream",
         ));

cli/tests/unit/timers_test.ts

@@ -397,10 +397,12 @@ Deno.test(async function timerMaxCpuBug() {
   clearTimeout(setTimeout(() => {}, 1000));
   // We can check this by counting how many ops have triggered in the interim.
   // Certainly less than 10 ops should have been dispatched in next 100 ms.
-  const { opsDispatched } = Deno.metrics();
+  const { ops: pre } = Deno.metrics();
   await delay(100);
-  const opsDispatched_ = Deno.metrics().opsDispatched;
-  assert(opsDispatched_ - opsDispatched < 10);
+  const { ops: post } = Deno.metrics();
+  const before = pre.op_sleep.opsDispatched;
+  const after = post.op_sleep.opsDispatched;
+  assert(after - before < 10);
 });
 
 Deno.test(async function timerOrdering() {

cli/tools/test.rs

@@ -475,6 +475,12 @@ async fn test_specifier(
     None
   };
 
+  // Enable op call tracing in core to enable better debugging of op sanitizer
+  // failures.
+  worker
+    .execute_script(&located_script_name!(), "Deno.core.enableOpCallTracing();")
+    .unwrap();
+
   // We only execute the specifier as a module if it is tagged with TestMode::Module or
   // TestMode::Both.
   if mode != TestMode::Documentation {

core/01_core.js

@@ -22,6 +22,8 @@
     MapPrototypeDelete,
     MapPrototypeSet,
     PromisePrototypeThen,
+    PromisePrototypeFinally,
+    StringPrototypeSlice,
     ObjectAssign,
     SymbolFor,
   } = window.__bootstrap.primordials;
@@ -48,6 +50,13 @@
   // to users. Currently missing bindings.
   const promiseIdSymbol = SymbolFor("Deno.core.internalPromiseId");
 
+  let opCallTracingEnabled = false;
+  const opCallTraces = new Map();
+
+  function enableOpCallTracing() {
+    opCallTracingEnabled = true;
+  }
+
   function setPromise(promiseId) {
     const idx = promiseId % RING_SIZE;
     // Move old promise from ring to map
@@ -139,7 +148,17 @@
     const maybeError = opcallAsync(opsCache[opName], promiseId, arg1, arg2);
     // Handle sync error (e.g: error parsing args)
     if (maybeError) return unwrapOpResult(maybeError);
-    const p = PromisePrototypeThen(setPromise(promiseId), unwrapOpResult);
+    let p = PromisePrototypeThen(setPromise(promiseId), unwrapOpResult);
+    if (opCallTracingEnabled) {
+      // Capture a stack trace by creating a new `Error` object. We remove the
+      // first 6 characters (the `Error\n` prefix) to get just the stack trace.
+      const stack = StringPrototypeSlice(new Error().stack, 6);
+      MapPrototypeSet(opCallTraces, promiseId, { opName, stack });
+      p = PromisePrototypeFinally(
+        p,
+        () => MapPrototypeDelete(opCallTraces, promiseId),
+      );
+    }
     // Save the id on the promise so it can later be ref'ed or unref'ed
     p[promiseIdSymbol] = promiseId;
     return p;
@@ -226,6 +245,8 @@
     BadResourcePrototype,
     Interrupted,
     InterruptedPrototype,
+    enableOpCallTracing,
+    opCallTraces,
   });
 
   ObjectAssign(globalThis.__bootstrap, { core });

core/lib.deno_core.d.ts

@@ -141,5 +141,28 @@ declare namespace Deno {
     ): undefined | UncaughtExceptionCallback;
 
     export type UncaughtExceptionCallback = (err: any) => void;
+
+    /**
+     * Enables collection of stack traces of all async ops. This allows for
+     * debugging of where a given async op was started. Deno CLI uses this for
+     * improving error message in op sanitizer errors for `deno test`.
+     *
+     * **NOTE:** enabling tracing has a significant negative performance impact.
+     * To get high level metrics on async ops with no added performance cost,
+     * use `Deno.core.metrics()`.
+     */
+    function enableOpCallTracing(): void;
+
+    export interface OpCallTrace {
+      opName: string;
+      stack: string;
+    }
+
+    /**
+     * A map containing traces for all ongoing async ops. The key is the op id.
+     * Tracing only occurs when `Deno.core.enableOpCallTracing()` was previously
+     * enabled.
+     */
+    const opCallTraces: Map<number, OpCallTrace>;
   }
 }