diff options
| -rw-r--r-- | cli/tests/testdata/test/ops_sanitizer_multiple_timeout_tests.out | 62 | ||||
| -rw-r--r-- | cli/tests/testdata/test/ops_sanitizer_multiple_timeout_tests.ts | 4 | ||||
| -rw-r--r-- | cli/tests/testdata/test/ops_sanitizer_unstable.out | 22 | ||||
| -rw-r--r-- | cli/tests/testdata/test/ops_sanitizer_unstable.ts | 2 | ||||
| -rw-r--r-- | cli/tests/unit/http_test.ts | 2 | ||||
| -rw-r--r-- | cli/tests/unit/timers_test.ts | 8 | ||||
| -rw-r--r-- | cli/tools/test.rs | 6 | ||||
| -rw-r--r-- | core/01_core.js | 23 | ||||
| -rw-r--r-- | core/lib.deno_core.d.ts | 23 | ||||
| -rw-r--r-- | runtime/js/40_testing.js | 172 |
10 files changed, 220 insertions, 104 deletions
diff --git a/cli/tests/testdata/test/ops_sanitizer_multiple_timeout_tests.out b/cli/tests/testdata/test/ops_sanitizer_multiple_timeout_tests.out index 1981a2500..acab794ab 100644 --- a/cli/tests/testdata/test/ops_sanitizer_multiple_timeout_tests.out +++ b/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: diff --git a/cli/tests/testdata/test/ops_sanitizer_multiple_timeout_tests.ts b/cli/tests/testdata/test/ops_sanitizer_multiple_timeout_tests.ts index f30773cf2..1f52d481f 100644 --- a/cli/tests/testdata/test/ops_sanitizer_multiple_timeout_tests.ts +++ b/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()); diff --git a/cli/tests/testdata/test/ops_sanitizer_unstable.out b/cli/tests/testdata/test/ops_sanitizer_unstable.out index 9d6a903e1..84ea10501 100644 --- a/cli/tests/testdata/test/ops_sanitizer_unstable.out +++ b/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: diff --git a/cli/tests/testdata/test/ops_sanitizer_unstable.ts b/cli/tests/testdata/test/ops_sanitizer_unstable.ts index 92f7bb888..4f409e73c 100644 --- a/cli/tests/testdata/test/ops_sanitizer_unstable.ts +++ b/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); }); diff --git a/cli/tests/unit/http_test.ts b/cli/tests/unit/http_test.ts index 2682ccee6..5ff1475b3 100644 --- a/cli/tests/unit/http_test.ts +++ b/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", )); diff --git a/cli/tests/unit/timers_test.ts b/cli/tests/unit/timers_test.ts index 7312a6440..e85a2effc 100644 --- a/cli/tests/unit/timers_test.ts +++ b/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() { diff --git a/cli/tools/test.rs b/cli/tools/test.rs index 5d99677f2..101dcb6b6 100644 --- a/cli/tools/test.rs +++ b/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 { diff --git a/core/01_core.js b/core/01_core.js index d9a110eea..3a05a0cff 100644 --- a/core/01_core.js +++ b/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 }); diff --git a/core/lib.deno_core.d.ts b/core/lib.deno_core.d.ts index 9f554f12b..37cd33190 100644 --- a/core/lib.deno_core.d.ts +++ b/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>; } } 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 - ")}`; }; } |