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]
+Test case is leaking async ops.
 
-Make sure to await all promises returned from Deno APIs before
-finishing test case.
+- 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]
+Test case is leaking async ops.
 
-Make sure to await all promises returned from Deno APIs before
-finishing test case.
+- 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>;
   }
 }

runtime/js/40_testing.js

@@ -5,26 +5,27 @@
   const core = window.Deno.core;
   const { setExitHandler } = window.__bootstrap.os;
   const { Console, inspectArgs } = window.__bootstrap.console;
-  const { metrics } = core;
   const { serializePermissions } = window.__bootstrap.permissions;
   const { assert } = window.__bootstrap.util;
   const {
     AggregateErrorPrototype,
     ArrayPrototypeFilter,
+    ArrayPrototypeJoin,
     ArrayPrototypePush,
     ArrayPrototypeShift,
     ArrayPrototypeSome,
     DateNow,
     Error,
     FunctionPrototype,
-    ObjectPrototypeIsPrototypeOf,
-    Number,
+    Map,
+    MapPrototypeHas,
     ObjectKeys,
+    ObjectPrototypeIsPrototypeOf,
     Promise,
     RegExp,
     RegExpPrototypeTest,
-    Set,
     SafeArrayIterator,
+    Set,
     StringPrototypeEndsWith,
     StringPrototypeIncludes,
     StringPrototypeSlice,
@@ -57,6 +58,79 @@
     return opSanitizerDelayResolveQueue.length === 0;
   }
 
+  // An async operation to $0 was started in this test, but never completed. This is often caused by not $1.
+  // An async operation to $0 was started in this test, but never completed. Async operations should not complete in a test if they were not started in that test.
+  // deno-fmt-ignore
+  const OP_DETAILS = {
+    "op_blob_read_part": ["read from a Blob or File", "awaiting the result of a Blob or File read"],
+    "op_broadcast_recv": ["receive a message from a BroadcastChannel", "closing the BroadcastChannel"],
+    "op_broadcast_send": ["send a message to a BroadcastChannel", "closing the BroadcastChannel"],
+    "op_chmod_async": ["change the permissions of a file", "awaiting the result of a `Deno.chmod` call"],
+    "op_chown_async": ["change the owner of a file", "awaiting the result of a `Deno.chown` call"],
+    "op_copy_file_async": ["copy a file", "awaiting the result of a `Deno.copyFile` call"],
+    "op_crypto_decrypt": ["decrypt data", "awaiting the result of a `crypto.subtle.decrypt` call"],
+    "op_crypto_derive_bits": ["derive bits from a key", "awaiting the result of a `crypto.subtle.deriveBits` call"],
+    "op_crypto_encrypt": ["encrypt data", "awaiting the result of a `crypto.subtle.encrypt` call"],
+    "op_crypto_generate_key": ["generate a key", "awaiting the result of a `crypto.subtle.generateKey` call"],
+    "op_crypto_sign_key": ["sign data", "awaiting the result of a `crypto.subtle.sign` call"],
+    "op_crypto_subtle_digest": ["digest data", "awaiting the result of a `crypto.subtle.digest` call"],
+    "op_crypto_verify_key": ["verify data", "awaiting the result of a `crypto.subtle.verify` call"],
+    "op_dgram_recv": ["receive a datagram message", "awaiting the result of `Deno.DatagramConn#receive` call, or not breaking out of a for await loop looping over a `Deno.DatagramConn`"],
+    "op_dgram_send": ["send a datagram message", "awaiting the result of `Deno.DatagramConn#send` call"],
+    "op_dns_resolve": ["resolve a DNS name", "awaiting the result of a `Deno.resolveDns` call"],
+    "op_emit": ["transpile code", "awaiting the result of a `Deno.emit` call"],
+    "op_fdatasync_async": ["flush pending data operations for a file to disk", "awaiting the result of a `Deno.fdatasync` call"],
+    "op_fetch_send": ["send a HTTP request", "awaiting the result of a `fetch` call"],
+    "op_ffi_call_nonblocking": ["do a non blocking ffi call", "awaiting the returned promise"] ,
+    "op_ffi_call_ptr_nonblocking": ["do a non blocking ffi call",  "awaiting the returned promise"], 
+    "op_flock_async": ["lock a file", "awaiting the result of a `Deno.flock` call"],
+    "op_fs_events_poll": ["get the next file system event", "breaking out of a for await loop looping over `Deno.FsEvents`"],
+    "op_fstat_async": ["get file metadata", "awaiting the result of a `Deno.File#fstat` call"],
+    "op_fsync_async": ["flush pending data operations for a file to disk", "awaiting the result of a `Deno.fsync` call"],
+    "op_ftruncate_async": ["truncate a file", "awaiting the result of a `Deno.ftruncate` call"],
+    "op_funlock_async": ["unlock a file", "awaiting the result of a `Deno.funlock` call"],
+    "op_futime_async": ["change file timestamps", "awaiting the result of a `Deno.futime` call"],
+    "op_http_accept": ["accept a HTTP request", "closing a `Deno.HttpConn`"],
+    "op_http_read": ["read the body of a HTTP request", "consuming the entire request body"],
+    "op_http_shutdown": ["shutdown a HTTP connection", "awaiting `Deno.HttpEvent#respondWith`"],
+    "op_http_upgrade_websocket": ["upgrade a HTTP connection to a WebSocket", "awaiting `Deno.HttpEvent#respondWith`"],
+    "op_http_write_headers": ["write HTTP response headers", "awaiting `Deno.HttpEvent#respondWith`"],
+    "op_http_write": ["write HTTP response body", "awaiting `Deno.HttpEvent#respondWith`"],
+    "op_link_async": ["create a hard link", "awaiting the result of a `Deno.link` call"],
+    "op_make_temp_dir_async": ["create a temporary directory", "awaiting the result of a `Deno.makeTempDir` call"],
+    "op_make_temp_file_async": ["create a temporary file", "awaiting the result of a `Deno.makeTempFile` call"],
+    "op_message_port_recv_message": ["receive a message from a MessagePort", "awaiting the result of not closing a `MessagePort`"],
+    "op_mkdir_async": ["create a directory", "awaiting the result of a `Deno.mkdir` call"],
+    "op_net_accept": ["accept a TCP connection", "closing a `Deno.Listener`"],
+    "op_net_connect": ["connect to a TCP or UDP server", "awaiting a `Deno.connect` call"],
+    "op_open_async": ["open a file", "awaiting the result of a `Deno.open` call"],
+    "op_read_dir_async": ["read a directory", "collecting all items in the async iterable returned from a `Deno.readDir` call"],
+    "op_read_link_async": ["read a symlink", "awaiting the result of a `Deno.readLink` call"],
+    "op_realpath_async": ["resolve a path", "awaiting the result of a `Deno.realpath` call"],
+    "op_remove_async": ["remove a file or directory", "awaiting the result of a `Deno.remove` call"],
+    "op_rename_async": ["rename a file or directory", "awaiting the result of a `Deno.rename` call"],
+    "op_run_status": ["get the status of a subprocess", "awaiting the result of a `Deno.Process#status` call"],
+    "op_seek_async": ["seek in a file", "awaiting the result of a `Deno.File#seek` call"],
+    "op_signal_poll": ["get the next signal", "un-registering a OS signal handler"],
+    "op_sleep": ["sleep for a duration", "cancelling a `setTimeout` or `setInterval` call"],
+    "op_stat_async": ["get file metadata", "awaiting the result of a `Deno.stat` call"],
+    "op_symlink_async": ["create a symlink", "awaiting the result of a `Deno.symlink` call"],
+    "op_tls_accept": ["accept a TLS connection", "closing a `Deno.TlsListener`"],
+    "op_tls_connect": ["connect to a TLS server", "awaiting a `Deno.connectTls` call"],
+    "op_tls_handshake": ["perform a TLS handshake", "awaiting a `Deno.TlsConn#handshake` call"],
+    "op_tls_start": ["start a TLS connection", "awaiting a `Deno.startTls` call"],
+    "op_truncate_async": ["truncate a file", "awaiting the result of a `Deno.truncate` call"],
+    "op_utime_async": ["change file timestamps", "awaiting the result of a `Deno.utime` call"],
+    "op_webgpu_buffer_get_map_async": ["map a WebGPU buffer", "awaiting the result of a `GPUBuffer#mapAsync` call"],
+    "op_webgpu_request_adapter": ["request a WebGPU adapter", "awaiting the result of a `navigator.gpu.requestAdapter` call"],
+    "op_webgpu_request_device": ["request a WebGPU device", "awaiting the result of a `GPUAdapter#requestDevice` call"],
+    "op_worker_recv_message":  ["receive a message from a web worker", "terminating a `Worker`"],
+    "op_ws_close": ["close a WebSocket", "awaiting until the `close` event is emitted on a `WebSocket`, or the `WebSocketStream#closed` promise resolves"],
+    "op_ws_create": ["create a WebSocket", "awaiting until the `open` event is emitted on a `WebSocket`, or the result of a `WebSocketStream#connection` promise"],
+    "op_ws_next_event": ["receive the next message on a WebSocket", "closing a `WebSocket` or `WebSocketStream`"],
+    "op_ws_send": ["send a message on a WebSocket", "closing a `WebSocket` or `WebSocketStream`"],
+  };
+
   // Wrap test function in additional assertion that makes sure
   // the test case does not leak async "ops" - ie. number of async
   // completed ops after the test is the same as number of dispatched
@@ -65,7 +139,8 @@
   function assertOps(fn) {
     /** @param step {TestStep} */
     return async function asyncOpSanitizer(step) {
-      const pre = metrics();
+      const pre = core.metrics();
+      const preTraces = new Map(core.opCallTraces);
       try {
         await fn(step);
       } finally {
@@ -75,56 +150,67 @@
         await opSanitizerDelay();
       }
 
-      if (step.shouldSkipSanitizers) {
-        return;
-      }
+      if (step.shouldSkipSanitizers) return;
 
-      const post = metrics();
+      const post = core.metrics();
+      const postTraces = new Map(core.opCallTraces);
 
       // We're checking diff because one might spawn HTTP server in the background
       // that will be a pending async op before test starts.
       const dispatchedDiff = post.opsDispatchedAsync - pre.opsDispatchedAsync;
       const completedDiff = post.opsCompletedAsync - pre.opsCompletedAsync;
 
+      if (dispatchedDiff === completedDiff) return;
+
       const details = [];
       for (const key in post.ops) {
-        const dispatchedDiff = Number(
-          post.ops[key]?.opsDispatchedAsync -
-            (pre.ops[key]?.opsDispatchedAsync ?? 0),
-        );
-        const completedDiff = Number(
-          post.ops[key]?.opsCompletedAsync -
-            (pre.ops[key]?.opsCompletedAsync ?? 0),
-        );
+        const preOp = pre.ops[key] ??
+          { opsDispatchedAsync: 0, opsCompletedAsync: 0 };
+        const postOp = post.ops[key];
+        const dispatchedDiff = postOp.opsDispatchedAsync -
+          preOp.opsDispatchedAsync;
+        const completedDiff = postOp.opsCompletedAsync -
+          preOp.opsCompletedAsync;
 
-        if (dispatchedDiff !== completedDiff) {
-          details.push(`
-  ${key}:
-    Before:
-      - dispatched: ${pre.ops[key]?.opsDispatchedAsync ?? 0}
-      - completed: ${pre.ops[key]?.opsCompletedAsync ?? 0}
-    After:
-      - dispatched: ${post.ops[key].opsDispatchedAsync}
-      - completed: ${post.ops[key].opsCompletedAsync}`);
+        if (dispatchedDiff > completedDiff) {
+          const [name, hint] = OP_DETAILS[key];
+          const count = dispatchedDiff - completedDiff;
+          let message = `${count} async operation${
+            count === 1 ? "" : "s"
+          } to ${name} ${
+            count === 1 ? "was" : "were"
+          } started in this test, but never completed. This is often caused by not ${hint}.`;
+          const traces = [];
+          for (const [id, { opName, stack }] of postTraces) {
+            if (opName !== key) continue;
+            if (MapPrototypeHas(preTraces, id)) continue;
+            ArrayPrototypePush(traces, stack);
+          }
+          if (traces.length === 1) {
+            message += " The operation was started here:\n";
+            message += traces[0];
+          } else if (traces.length > 1) {
+            message += " The operations were started here:\n";
+            message += ArrayPrototypeJoin(traces, "\n\n");
+          }
+          ArrayPrototypePush(details, message);
+        } else if (dispatchedDiff < completedDiff) {
+          const [name] = OP_DETAILS[key];
+          const count = completedDiff - dispatchedDiff;
+          ArrayPrototypePush(
+            details,
+            `${count} async operation${count === 1 ? "" : "s"} to ${name} ${
+              count === 1 ? "was" : "were"
+            } started before this test, but ${
+              count === 1 ? "was" : "were"
+            } completed during the test. Async operations should not complete in a test if they were not started in that test.`,
+          );
         }
       }
 
-      const message = `Test case is leaking async ops.
-Before:
-  - dispatched: ${pre.opsDispatchedAsync}
-  - completed: ${pre.opsCompletedAsync}
-After:
-  - dispatched: ${post.opsDispatchedAsync}
-  - completed: ${post.opsCompletedAsync}
-${details.length > 0 ? "Ops:" + details.join("") : ""}
+      throw `Test case is leaking async ops.
 
-Make sure to await all promises returned from Deno APIs before
-finishing test case.`;
-
-      assert(
-        dispatchedDiff === completedDiff,
-        message,
-      );
+- ${ArrayPrototypeJoin(details, "\n - ")}`;
     };
   }