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.

1 files changed, 129 insertions, 43 deletions

diff --git a/runtime/js/40_testing.js b/runtime/js/40_testing.js
index 5ff5c6e15..b15b28c9e 100644
--- a/runtime/js/40_testing.js
+++ b/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),
-        );
-
-        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}`);
+        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) {
+          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("") : ""}
-
-Make sure to await all promises returned from Deno APIs before
-finishing test case.`;
-
-      assert(
-        dispatchedDiff === completedDiff,
-        message,
-      );
+      throw `Test case is leaking async ops.
+
+- ${ArrayPrototypeJoin(details, "\n - ")}`;
     };
   }