From 0e29a9ebe8fe4036ed6d0dc6fe1c615afb941255 Mon Sep 17 00:00:00 2001 From: Im-Beast Date: Sat, 23 Mar 2024 19:03:37 +0100 Subject: [PATCH 1/9] feat: add sanitization of pending promises --- examples/timer-microtask.js | 11 ++++++ ext/lib.rs | 25 +++++++++---- ext/testing/lib.rs | 64 +++++++++++++++++++++++++++++++--- ext/testing/mod.js | 32 ++++++++++++----- ext/testing/promise_tracker.rs | 62 ++++++++++++++++++++++++++++++++ ext/tsconfig.d.ts | 4 ++- sable/main.rs | 51 ++++++++++++++++++--------- 7 files changed, 212 insertions(+), 37 deletions(-) create mode 100644 examples/timer-microtask.js create mode 100644 ext/testing/promise_tracker.rs diff --git a/examples/timer-microtask.js b/examples/timer-microtask.js new file mode 100644 index 0000000..fbc0676 --- /dev/null +++ b/examples/timer-microtask.js @@ -0,0 +1,11 @@ +const { test } = Sable.testing; + +test("Timers microtask bug", (ctx) => { + return new Promise(resolve => { + setTimeout(() => { + queueMicrotask(() => { + setTimeout(resolve, 0); + }); + }, 0); + }); +}); \ No newline at end of file diff --git a/ext/lib.rs b/ext/lib.rs index 6b6a9a1..213b1e7 100644 --- a/ext/lib.rs +++ b/ext/lib.rs @@ -7,6 +7,14 @@ pub mod extensions { pub use sable_ext_timers as timers; pub use sable_ext_web as web; + use deno_core::OpMetricsSummaryTracker; + use runtime::RuntimeState; + use std::rc::Rc; + use std::time::Instant; + use std::time::SystemTime; + use testing::PromiseMetricsSummaryTracker; + use timers::TimerQueue; + deno_core::extension!( sable, ops = [ @@ -27,7 +35,9 @@ pub mod extensions { timers::op_create_timer, testing::op_bench_fn, testing::op_diff_str, - testing::op_test_async_ops_sanitization, + testing::op_test_sanitization, + testing::op_set_promise_sanitization_hook, + testing::op_set_promise_sanitization_name, web::op_encoding_normalize_label, web::op_encoding_decode_utf8, web::op_encoding_decode_single, @@ -62,23 +72,24 @@ pub mod extensions { ], state = |state| { // sable_ext_runtime - state.put(runtime::RuntimeState::Default); + state.put(RuntimeState::Default); // sable_ext_perf - state.put(std::time::Instant::now()); - state.put(std::time::SystemTime::now()); + state.put(Instant::now()); + state.put(SystemTime::now()); // sable_ext_timers - state.put(timers::TimerQueue::new()); + state.put(TimerQueue::new()); // sable_ext_testing - state.put::>>(None); + state.put::>>(None); + state.put::>>(None); } ); deno_core::extension!( sable_cleanup, esm_entry_point = "ext:sable_cleanup/cleanup.js", - esm = ["cleanup.js",], + esm = ["cleanup.js"], ); } diff --git a/ext/testing/lib.rs b/ext/testing/lib.rs index 58f867f..c162a6c 100644 --- a/ext/testing/lib.rs +++ b/ext/testing/lib.rs @@ -1,7 +1,10 @@ -use deno_core::{op2, v8, OpMetricsSummaryTracker, OpState}; +use deno_core::{op2, v8, JsRuntime, OpMetricsSummaryTracker, OpState}; use diff::{PrettyDiffBuilder, PrettyDiffBuilderConfig}; use std::{rc::Rc, time::Instant}; +mod promise_tracker; +pub use promise_tracker::PromiseMetricsSummaryTracker; + mod diff; use imara_diff::{diff, intern::InternedInput, Algorithm}; @@ -58,13 +61,64 @@ pub fn op_diff_str(#[string] before: &str, #[string] after: &str) -> String { /** Returns whether there are no async ops running in the background */ #[op2(fast)] -pub fn op_test_async_ops_sanitization(state: &OpState) -> bool { - let metrics_tracker = state.borrow::>>(); - match metrics_tracker { +pub fn op_test_sanitization(state: &OpState) -> bool { + let op_metrics_tracker = state.borrow::>>(); + let ops_ok = match op_metrics_tracker { + None => true, + Some(tracker) => { + let summary = tracker.aggregate(); + !summary.has_outstanding_ops() + } + }; + + let promise_metrics_tracker = state.borrow::>>(); + let promises_ok = match promise_metrics_tracker { None => true, Some(tracker) => { let summary = tracker.aggregate(); - summary.ops_completed_async == summary.ops_dispatched_async + !summary.has_pending_promises() + } + }; + + ops_ok && promises_ok +} + +extern "C" fn sanitization_promise_hook<'a, 'b>( + hook_type: v8::PromiseHookType, + promise: v8::Local<'a, v8::Promise>, + _: v8::Local<'b, v8::Value>, +) { + let scope = unsafe { &mut v8::CallbackScope::new(promise) }; + let state = JsRuntime::op_state_from(scope); + let mut state = state.borrow_mut(); // scopes deref into &Isolate + + let metrics_tracker = state + .borrow_mut::>>() + .as_ref() + .unwrap(); + + let mut metrics = metrics_tracker.metrics_mut(); + + match hook_type { + v8::PromiseHookType::Init => { + metrics.promises_initialized += 1; } + v8::PromiseHookType::Resolve => { + metrics.promises_resolved += 1; + } + _ => {} } } + +#[op2(fast)] +pub fn op_set_promise_sanitization_name(state: &mut OpState, #[string] test_name: String) { + let Some(tracker) = state.borrow_mut::>>() else { + return; + }; + tracker.track(test_name); +} + +#[op2] +pub fn op_set_promise_sanitization_hook(scope: &mut v8::HandleScope) { + scope.set_promise_hook(sanitization_promise_hook); +} diff --git a/ext/testing/mod.js b/ext/testing/mod.js index 18b6d73..504adf5 100644 --- a/ext/testing/mod.js +++ b/ext/testing/mod.js @@ -1,4 +1,11 @@ -import { op_test_async_ops_sanitization, op_diff_str, op_runtime_state, op_bench_fn } from "ext:core/ops"; +import { + op_bench_fn, + op_diff_str, + op_runtime_state, + op_set_promise_sanitization_hook, + op_set_promise_sanitization_name, + op_test_sanitization, +} from "ext:core/ops"; import { Printer } from "ext:sable/console/printer.js"; import { styles } from "ext:sable/utils/ansi.js"; @@ -22,23 +29,23 @@ Please make sure they've completed before you create the test.`; if (testContext) { message = ` -At least one asynchronous operation was started in ${testContext.title} but never completed! +At least one asynchronous operation or a Promise was started in ${testContext.title} but never completed! Please await all your promises or resolve test promise when every asynchronous operation has finished:`; if (isAsync) { message += ` test('${testContext.title}', async (ctx) => { ... ---^^^ ops leak somewhere around here, are you sure you awaited every promise? +--^^^ ops or Promises leak somewhere around here, are you sure you awaited every promise? });`; } else { const ptd = "-".repeat(textWidth(testContext.title)); message += ` test('${testContext.title}', (ctx) => { ---------${ptd}^ this test is not asynchronous, but leaks asynchronous ops +--------${ptd}^ this test is not asynchronous, but leaks asynchronous ops or Promises ... ---^^^ ops leak somewhere around here, are you sure this test was meant to be synchronous? +--^^^ ops or Promises leak somewhere around here, are you sure this test was meant to be synchronous? });`; } } @@ -363,6 +370,9 @@ class TestContext { * @param {TestContext | undefined} parent - parent test */ constructor(name, parent) { + op_set_promise_sanitization_hook(); + op_set_promise_sanitization_name(name); + this.name = name; this.parent = parent; @@ -378,7 +388,7 @@ class TestContext { * @throws when async ops are still pending */ static sanitizeAsyncOps(testContext = undefined, async = false) { - if (!op_test_async_ops_sanitization()) { + if (!op_test_sanitization()) { throw new TestContextLeakingAsyncOpsError(testContext, async); } } @@ -424,13 +434,19 @@ class TestContext { if (response instanceof Promise) { return response.then(() => { testContext.finish(); - parent?.unlock(testContext); TestContext.sanitizeAsyncOps(testContext, true); + if (parent) { + parent.unlock(testContext); + op_set_promise_sanitization_name(parent.name); + } }); } else { testContext.finish(); - parent?.unlock(testContext); TestContext.sanitizeAsyncOps(testContext, false); + if (parent) { + parent.unlock(testContext); + op_set_promise_sanitization_name(parent.name); + } } } diff --git a/ext/testing/promise_tracker.rs b/ext/testing/promise_tracker.rs new file mode 100644 index 0000000..a3d4800 --- /dev/null +++ b/ext/testing/promise_tracker.rs @@ -0,0 +1,62 @@ +use std::cell::{Ref, RefCell, RefMut}; + +#[derive(Debug, Default)] +pub struct PromiseMetricsSummary { + pub test_name: String, + pub promises_initialized: u64, + pub promises_resolved: u64, +} + +impl PromiseMetricsSummary { + pub fn with_name(test_name: String) -> Self { + Self { + test_name, + ..Default::default() + } + } + + pub fn has_pending_promises(&self) -> bool { + self.promises_initialized > self.promises_resolved + } +} + +#[derive(Debug, Default)] +pub struct PromiseMetricsSummaryTracker { + tracked: RefCell, + metrics: RefCell>, +} + +impl PromiseMetricsSummaryTracker { + pub fn per_promise(&self) -> Ref<'_, Vec> { + self.metrics.borrow() + } + + pub fn aggregate(&self) -> PromiseMetricsSummary { + let mut sum = PromiseMetricsSummary::default(); + for metrics in self.metrics.borrow().iter() { + sum.promises_initialized += metrics.promises_initialized; + sum.promises_resolved += metrics.promises_resolved; + } + sum + } + + pub fn metrics_mut(&self) -> RefMut { + RefMut::map(self.metrics.borrow_mut(), |metrics| { + &mut metrics[*self.tracked.borrow()] + }) + } + + pub fn track(&self, name: String) { + let mut metrics = self.metrics.borrow_mut(); + + let i = metrics.iter().position(|metrics| name == metrics.test_name); + *self.tracked.borrow_mut() = match i { + Some(i) => i, + None => { + let index = metrics.len(); + metrics.push(PromiseMetricsSummary::with_name(name)); + index + } + }; + } +} diff --git a/ext/tsconfig.d.ts b/ext/tsconfig.d.ts index 116266c..a03c2f2 100644 --- a/ext/tsconfig.d.ts +++ b/ext/tsconfig.d.ts @@ -31,7 +31,9 @@ declare module "ext:core/ops" { export function op_time_origin(): number; // testing - export function op_test_async_ops_sanitization(): boolean; + export function op_set_promise_sanitization_hook(): void; + export function op_set_promise_sanitization_name(testName: string): void; + export function op_test_sanitization(): boolean; export function op_diff_str(a: string, b: string): string; export function op_bench_fn(callback: () => void): number; diff --git a/sable/main.rs b/sable/main.rs index 51f49e0..9ba5399 100644 --- a/sable/main.rs +++ b/sable/main.rs @@ -16,7 +16,9 @@ mod utils; use cli::parse_cli; use module_cache::ModuleCache; -use sable_ext::extensions::{runtime::RuntimeState, sable, sable_cleanup}; +use sable_ext::extensions::{ + runtime::RuntimeState, sable, sable_cleanup, testing::PromiseMetricsSummaryTracker, +}; static RUNTIME_SNAPSHOT: &[u8] = include_bytes!(concat!(env!("OUT_DIR"), "/SABLE_RUNTIME_SNAPSHOT.bin")); @@ -42,28 +44,34 @@ pub async fn sable_run(file_path: &str, options: SableOptions) -> Result<(), Any module_cache.clear().await?; } - let mut maybe_tracker: Option> = None; let mut extensions = vec![sable::init_ops(), sable_cleanup::init_ops_and_esm()]; - match options.state { + let (maybe_op_tracker, maybe_promise_tracker) = match options.state { RuntimeState::Test | RuntimeState::Bench => { - maybe_tracker.replace(Rc::new(OpMetricsSummaryTracker::default())); - let maybe_tracker = maybe_tracker.clone(); - extensions.push(Extension { - name: "sable_testing", - op_state_fn: Some(Box::new(move |state| { - state.put(options.state); - state.put(maybe_tracker) - })), - ..Default::default() - }); + let op_tracker = Some(Rc::new(OpMetricsSummaryTracker::default())); + let promise_tracker = Some(Rc::new(PromiseMetricsSummaryTracker::default())); + + { + let op_tracker = op_tracker.clone(); + let promise_tracker = promise_tracker.clone(); + extensions.push(Extension { + name: "sable_testing", + op_state_fn: Some(Box::new(move |state| { + state.put(options.state); + state.put(op_tracker); + state.put(promise_tracker); + })), + ..Default::default() + }); + } + (op_tracker, promise_tracker) } - _ => {} - } + _ => (None, None), + }; let mut js_runtime = JsRuntime::new(RuntimeOptions { startup_snapshot: Some(RUNTIME_SNAPSHOT), - op_metrics_factory_fn: maybe_tracker + op_metrics_factory_fn: maybe_op_tracker .map(|tracker| tracker.op_metrics_factory_fn(|op| op.is_async)), module_loader: Some(Rc::new(SableModuleLoader { module_cache, @@ -77,6 +85,17 @@ pub async fn sable_run(file_path: &str, options: SableOptions) -> Result<(), Any let result = js_runtime.mod_evaluate(mod_id); js_runtime.run_event_loop(Default::default()).await?; + if let Some(promise_tracker) = maybe_promise_tracker { + for metrics in promise_tracker.per_promise().iter() { + if metrics.has_pending_promises() { + eprintln!( + "Test {:?} has pending promises: {} of them resolved while {} got initialized", + metrics.test_name, metrics.promises_initialized, metrics.promises_resolved + ); + } + } + } + result.await } From 9d62648d7d368412c98ca85e322766b76e625205 Mon Sep 17 00:00:00 2001 From: Im-Beast Date: Sat, 23 Mar 2024 19:11:42 +0100 Subject: [PATCH 2/9] feat: return error instead of just printing to stderr --- sable/main.rs | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/sable/main.rs b/sable/main.rs index 9ba5399..6d9b68a 100644 --- a/sable/main.rs +++ b/sable/main.rs @@ -2,7 +2,9 @@ extern crate deno_core; extern crate sable_ext; use deno_core::{ - error::AnyError, url::Url, Extension, JsRuntime, OpMetricsSummaryTracker, RuntimeOptions, + error::{generic_error, AnyError}, + url::Url, + Extension, JsRuntime, OpMetricsSummaryTracker, RuntimeOptions, }; use loader::SableModuleLoader; use std::{env, path::PathBuf, rc::Rc, sync::Arc}; @@ -88,10 +90,10 @@ pub async fn sable_run(file_path: &str, options: SableOptions) -> Result<(), Any if let Some(promise_tracker) = maybe_promise_tracker { for metrics in promise_tracker.per_promise().iter() { if metrics.has_pending_promises() { - eprintln!( + return Err(generic_error(format!( "Test {:?} has pending promises: {} of them resolved while {} got initialized", - metrics.test_name, metrics.promises_initialized, metrics.promises_resolved - ); + metrics.test_name, metrics.promises_initialized, metrics.promises_resolved, + ))); } } } From d4aec5da3ac66e61460fb3168b201ac61f077676 Mon Sep 17 00:00:00 2001 From: Im-Beast Date: Sat, 23 Mar 2024 20:38:38 +0100 Subject: [PATCH 3/9] . --- examples/fix.js | 15 +++++++++++++++ examples/timer-microtask.js | 11 ----------- ext/testing/lib.rs | 4 ++-- ext/testing/promise_tracker.rs | 2 +- sable/main.rs | 2 +- tests/timers.test.js | 2 +- 6 files changed, 20 insertions(+), 16 deletions(-) create mode 100644 examples/fix.js delete mode 100644 examples/timer-microtask.js diff --git a/examples/fix.js b/examples/fix.js new file mode 100644 index 0000000..a3f9a25 --- /dev/null +++ b/examples/fix.js @@ -0,0 +1,15 @@ +const { test } = Sable.testing; + +await test("a", () => { + return new Promise(resolve => { + queueMicrotask(() => { + resolve() + }); + }); +}); + +test("b", () => { }); + +test("c", () => { + new Promise(() => {}); +}) \ No newline at end of file diff --git a/examples/timer-microtask.js b/examples/timer-microtask.js deleted file mode 100644 index fbc0676..0000000 --- a/examples/timer-microtask.js +++ /dev/null @@ -1,11 +0,0 @@ -const { test } = Sable.testing; - -test("Timers microtask bug", (ctx) => { - return new Promise(resolve => { - setTimeout(() => { - queueMicrotask(() => { - setTimeout(resolve, 0); - }); - }, 0); - }); -}); \ No newline at end of file diff --git a/ext/testing/lib.rs b/ext/testing/lib.rs index c162a6c..7b67845 100644 --- a/ext/testing/lib.rs +++ b/ext/testing/lib.rs @@ -89,8 +89,8 @@ extern "C" fn sanitization_promise_hook<'a, 'b>( _: v8::Local<'b, v8::Value>, ) { let scope = unsafe { &mut v8::CallbackScope::new(promise) }; - let state = JsRuntime::op_state_from(scope); - let mut state = state.borrow_mut(); // scopes deref into &Isolate + let state = JsRuntime::op_state_from(scope); // scopes deref into &Isolate + let mut state = state.borrow_mut(); let metrics_tracker = state .borrow_mut::>>() diff --git a/ext/testing/promise_tracker.rs b/ext/testing/promise_tracker.rs index a3d4800..2f48868 100644 --- a/ext/testing/promise_tracker.rs +++ b/ext/testing/promise_tracker.rs @@ -27,7 +27,7 @@ pub struct PromiseMetricsSummaryTracker { } impl PromiseMetricsSummaryTracker { - pub fn per_promise(&self) -> Ref<'_, Vec> { + pub fn per_test(&self) -> Ref<'_, Vec> { self.metrics.borrow() } diff --git a/sable/main.rs b/sable/main.rs index 6d9b68a..48b1d04 100644 --- a/sable/main.rs +++ b/sable/main.rs @@ -88,7 +88,7 @@ pub async fn sable_run(file_path: &str, options: SableOptions) -> Result<(), Any js_runtime.run_event_loop(Default::default()).await?; if let Some(promise_tracker) = maybe_promise_tracker { - for metrics in promise_tracker.per_promise().iter() { + for metrics in promise_tracker.per_test().iter() { if metrics.has_pending_promises() { return Err(generic_error(format!( "Test {:?} has pending promises: {} of them resolved while {} got initialized", diff --git a/tests/timers.test.js b/tests/timers.test.js index f8a53ed..712499f 100644 --- a/tests/timers.test.js +++ b/tests/timers.test.js @@ -5,7 +5,7 @@ const { test } = Sable.testing; // c // 1 // 2 -test("Timers API", (ctx) => { +await test("Timers API", (ctx) => { return new Promise((resolve) => { const start = performance.now(); const id = setInterval(() => { From 07762db143d065eb3bc278ce01a69723a062a3e7 Mon Sep 17 00:00:00 2001 From: Im-Beast Date: Sun, 24 Mar 2024 17:32:38 +0100 Subject: [PATCH 4/9] feat: track promises by their identity_id --- ext/lib.rs | 5 +- ext/testing/lib.rs | 53 ++++++---- ext/testing/mod.js | 141 ++++++++----------------- ext/testing/promise_tracker.rs | 51 ++++++++- ext/tsconfig.d.ts | 5 +- sable/main.rs | 2 +- tests/testing/microtask_promse_leak.js | 7 ++ tests/testing/promise_leak.js | 5 + tests/testing/promise_tracking.js | 15 +++ tests/testing/returned_promise_leak.js | 5 + 10 files changed, 166 insertions(+), 123 deletions(-) create mode 100644 tests/testing/microtask_promse_leak.js create mode 100644 tests/testing/promise_leak.js create mode 100644 tests/testing/promise_tracking.js create mode 100644 tests/testing/returned_promise_leak.js diff --git a/ext/lib.rs b/ext/lib.rs index 213b1e7..44286a9 100644 --- a/ext/lib.rs +++ b/ext/lib.rs @@ -35,9 +35,10 @@ pub mod extensions { timers::op_create_timer, testing::op_bench_fn, testing::op_diff_str, - testing::op_test_sanitization, + testing::op_get_outstanding_ops, + testing::op_get_pending_promises, testing::op_set_promise_sanitization_hook, - testing::op_set_promise_sanitization_name, + testing::op_set_promise_sanitized_test_name, web::op_encoding_normalize_label, web::op_encoding_decode_utf8, web::op_encoding_decode_single, diff --git a/ext/testing/lib.rs b/ext/testing/lib.rs index 7b67845..3a759cb 100644 --- a/ext/testing/lib.rs +++ b/ext/testing/lib.rs @@ -61,26 +61,34 @@ pub fn op_diff_str(#[string] before: &str, #[string] after: &str) -> String { /** Returns whether there are no async ops running in the background */ #[op2(fast)] -pub fn op_test_sanitization(state: &OpState) -> bool { - let op_metrics_tracker = state.borrow::>>(); - let ops_ok = match op_metrics_tracker { - None => true, +#[bigint] +pub fn op_get_outstanding_ops( + #[state] op_metrics_tracker: &Option>, +) -> u64 { + match op_metrics_tracker { + None => 0, Some(tracker) => { let summary = tracker.aggregate(); - !summary.has_outstanding_ops() + summary.ops_dispatched_async - summary.ops_completed_async } - }; - - let promise_metrics_tracker = state.borrow::>>(); - let promises_ok = match promise_metrics_tracker { - None => true, - Some(tracker) => { - let summary = tracker.aggregate(); - !summary.has_pending_promises() - } - }; + } +} - ops_ok && promises_ok +#[op2(fast)] +#[bigint] +pub fn op_get_pending_promises( + #[state] promise_metrics_tracker: &Option>, +) -> u64 { + match promise_metrics_tracker { + None => 0, + Some(tracker) => tracker.metrics().map_or(0, |metrics| { + debug_assert!( + metrics.promises_initialized >= metrics.promises_resolved, + "Initialized promises should be greater or equal to resolved promises" + ); + metrics.promises_initialized - metrics.promises_resolved + }), + } } extern "C" fn sanitization_promise_hook<'a, 'b>( @@ -97,21 +105,26 @@ extern "C" fn sanitization_promise_hook<'a, 'b>( .as_ref() .unwrap(); - let mut metrics = metrics_tracker.metrics_mut(); + let promise_id = promise.get_identity_hash(); match hook_type { v8::PromiseHookType::Init => { - metrics.promises_initialized += 1; + let mut metrics = metrics_tracker.metrics_mut(); + metrics.initialized(promise_id); } v8::PromiseHookType::Resolve => { - metrics.promises_resolved += 1; + let Some(mut metrics) = metrics_tracker.metrics_mut_with_promise(promise_id) else { + // We don't want to track promises that we didn't initialize + return; + }; + metrics.resolved(promise_id); } _ => {} } } #[op2(fast)] -pub fn op_set_promise_sanitization_name(state: &mut OpState, #[string] test_name: String) { +pub fn op_set_promise_sanitized_test_name(state: &mut OpState, #[string] test_name: String) { let Some(tracker) = state.borrow_mut::>>() else { return; }; diff --git a/ext/testing/mod.js b/ext/testing/mod.js index 504adf5..5179137 100644 --- a/ext/testing/mod.js +++ b/ext/testing/mod.js @@ -3,55 +3,33 @@ import { op_diff_str, op_runtime_state, op_set_promise_sanitization_hook, - op_set_promise_sanitization_name, - op_test_sanitization, + op_set_promise_sanitized_test_name, + op_get_outstanding_ops, + op_get_pending_promises, } from "ext:core/ops"; import { Printer } from "ext:sable/console/printer.js"; import { styles } from "ext:sable/utils/ansi.js"; -import { textWidth } from "ext:sable/utils/text_width.js"; -/** - * Error which gets thrown whenever: - * - TestContext is leaking async ops - * - Test gets started when async ops are still pending - */ -class TestContextLeakingAsyncOpsError extends Error { +class TestContextLeakingPendingPromisesError extends Error { /** - * @param {TestContext=} testContext - * @param {boolean=} isAsync - whether given testContext callback returned a promise + * @param {TestContext} testContext + * @param {number} pendingPromises + * @param {number} promiseLeniency */ - constructor(testContext, isAsync) { - // TODO(Im-Beast): Replace this with pretty errors after they happen - let message = ` -You wanted to create a test, but there are still asynchronous ops running. -Please make sure they've completed before you create the test.`; - - if (testContext) { - message = ` -At least one asynchronous operation or a Promise was started in ${testContext.title} but never completed! -Please await all your promises or resolve test promise when every asynchronous operation has finished:`; - - if (isAsync) { - message += ` -test('${testContext.title}', async (ctx) => { - ... ---^^^ ops or Promises leak somewhere around here, are you sure you awaited every promise? -});`; - } else { - const ptd = "-".repeat(textWidth(testContext.title)); - - message += ` -test('${testContext.title}', (ctx) => { ---------${ptd}^ this test is not asynchronous, but leaks asynchronous ops or Promises - ... ---^^^ ops or Promises leak somewhere around here, are you sure this test was meant to be synchronous? -});`; - } - } - - super(message); + constructor(testContext, pendingPromises, promiseLeniency) { + super(`Test ${testContext.title} is leaking pending promises. ${pendingPromises} promises pending while ${promiseLeniency} have been allowed.`); + this.name = "TestContextPendingPromisesError"; + } +} +class TestContextLeakingAsyncOpsError extends Error { + /** + * @param {TestContext} testContext + */ + constructor(testContext) { + super(`At least one asynchronous operation was started in ${testContext.title} but never completed! +Please await all your promises or resolve test promise when every asynchronous operation has finished:`) this.name = "TestContextLeakingAsyncOpsError"; } } @@ -61,25 +39,10 @@ class TestContextInvalidUsageError extends Error { * @param {TestContext} testContext */ constructor(testContext) { - const ptd = "-".repeat(textWidth(testContext.title)); - const ctd = "-".repeat(textWidth(testContext.currentlyTested.title)); - - // TODO(Im-Beast): Replace this with pretty errors after they happen super( - ` -You're using context from different step! -Please use the step from current callback: -test('${testContext.title}', (ctx) => { -----------${ptd}^^^ you're using this - ... - ctx.test('${testContext.currentlyTested.title}', (ctx) => { -----------------${ctd}^^^ instead of this - ... - }); - ... -});`, + `You're using context from different step in ${testContext.title}! +Please use the context of the current callback.`, ); - this.name = "TestContextInvalidUsageError"; } } @@ -96,30 +59,8 @@ class TestContextInUseError extends Error { const currentTitle = testContext.currentlyTested.title; const triedTitle = tried.title; - const ctd = "-".repeat(textWidth(currentTitle)); - const cts = " ".repeat(textWidth(currentTitle)); - const ttd = "-".repeat(textWidth(triedTitle)); - - // TODO(Im-Beast): Replace this with pretty errors after they happen super( - ` -You started another sub-test when previous one didn't finish! (${parentTitle} is ${locked}) -Please check if you're not awaiting async sub-test: -test('${parentTitle}', async (ctx) => { - ... - vvv${ctd}--- you're not awaiting it | - ctx.test('${currentTitle}', async (ctx) => { | - ${cts}^^^^^------------/ - but this is async - ... - }); - ... - vvvv${ttd}------------- which in turn crashes here - ctx.test('${triedTitle}', (ctx) => { - ... - }); - ... -});`, + `You tried to start another sub-test (${triedTitle}) when previous one (${currentTitle}) didn't finish! (${parentTitle} is ${locked});`, ); this.name = "TestContextInUseError"; @@ -370,9 +311,6 @@ class TestContext { * @param {TestContext | undefined} parent - parent test */ constructor(name, parent) { - op_set_promise_sanitization_hook(); - op_set_promise_sanitization_name(name); - this.name = name; this.parent = parent; @@ -384,12 +322,17 @@ class TestContext { /** * @param {TestContext} testContext - currently evaluated TestContext - * @param {boolean} async - whether TestContext returned a promise + * @param {number} promiseLeniency - maximum amount of allowed pending promises * @throws when async ops are still pending */ - static sanitizeAsyncOps(testContext = undefined, async = false) { - if (!op_test_sanitization()) { - throw new TestContextLeakingAsyncOpsError(testContext, async); + static sanitizeAsyncOps(testContext = undefined, promiseLeniency = 0) { + if (op_get_outstanding_ops()) { + throw new TestContextLeakingAsyncOpsError(testContext); + } + + const pendingPromises = op_get_pending_promises(); + if (pendingPromises > promiseLeniency) { + throw new TestContextLeakingPendingPromisesError(testContext, pendingPromises, promiseLeniency); } } @@ -429,27 +372,32 @@ class TestContext { const testContext = new TestContext(name, parent); parent?.lock(testContext); + op_set_promise_sanitized_test_name(name); + op_set_promise_sanitization_hook(); const response = callback(testContext); - if (response instanceof Promise) { return response.then(() => { + // We allow two pending promises for the test itself + // And second for awaiting the test + // In case this assumption is wrong, program will still throw at the end of the event loop + TestContext.sanitizeAsyncOps(testContext, 2); testContext.finish(); - TestContext.sanitizeAsyncOps(testContext, true); if (parent) { parent.unlock(testContext); - op_set_promise_sanitization_name(parent.name); + op_set_promise_sanitized_test_name(parent.name); } - }); + }) } else { + TestContext.sanitizeAsyncOps(testContext, 0); testContext.finish(); - TestContext.sanitizeAsyncOps(testContext, false); if (parent) { parent.unlock(testContext); - op_set_promise_sanitization_name(parent.name); + op_set_promise_sanitized_test_name(parent.name); } } } + // TODO(Im-Beast): Add TestContext.fails /** * Create new sub-test with given callback * @param {string} name @@ -687,11 +635,10 @@ function test(name, callback) { } if (runtimeState !== "test") { - Sable.bench = noop; + Sable.testing.test = noop; return; } - TestContext.sanitizeAsyncOps(); return TestContext.test(name, callback); } @@ -702,7 +649,7 @@ function bench(name, callback) { } if (runtimeState !== "bench") { - Sable.bench = noop; + Sable.testing.bench = noop; return; } diff --git a/ext/testing/promise_tracker.rs b/ext/testing/promise_tracker.rs index 2f48868..1bff28f 100644 --- a/ext/testing/promise_tracker.rs +++ b/ext/testing/promise_tracker.rs @@ -1,10 +1,15 @@ -use std::cell::{Ref, RefCell, RefMut}; +use std::{ + cell::{Ref, RefCell, RefMut}, + collections::BTreeSet, + num::NonZeroI32, +}; #[derive(Debug, Default)] pub struct PromiseMetricsSummary { pub test_name: String, pub promises_initialized: u64, pub promises_resolved: u64, + promises: BTreeSet, } impl PromiseMetricsSummary { @@ -18,6 +23,28 @@ impl PromiseMetricsSummary { pub fn has_pending_promises(&self) -> bool { self.promises_initialized > self.promises_resolved } + + pub fn contains(&self, promise_id: NonZeroI32) -> bool { + self.promises.contains(&promise_id) + } + + pub fn initialized(&mut self, promise_id: NonZeroI32) { + self.promises_initialized += 1; + debug_assert!( + self.promises.insert(promise_id), + "Promise {promise_id} has been initialized twice" + ); + } + + pub fn resolved(&mut self, promise_id: NonZeroI32) { + self.promises_resolved += 1; + // identity_hash is not guaranteed to be unique + // we remove it in case it would be added again + debug_assert!( + self.promises.remove(&promise_id), + "Promise {promise_id} not found" + ); + } } #[derive(Debug, Default)] @@ -40,12 +67,34 @@ impl PromiseMetricsSummaryTracker { sum } + pub fn metrics(&self) -> Option> { + let metrics = self.metrics.borrow(); + if metrics.is_empty() { + None + } else { + Some(Ref::map(metrics, |metrics| { + &metrics[*self.tracked.borrow()] + })) + } + } + pub fn metrics_mut(&self) -> RefMut { RefMut::map(self.metrics.borrow_mut(), |metrics| { &mut metrics[*self.tracked.borrow()] }) } + pub fn metrics_mut_with_promise( + &self, + promise_id: NonZeroI32, + ) -> Option> { + let metrics = self.metrics.borrow_mut(); + let i = metrics + .iter() + .position(|metrics| metrics.contains(promise_id)); + i.map(|i| RefMut::map(metrics, |metrics| &mut metrics[i])) + } + pub fn track(&self, name: String) { let mut metrics = self.metrics.borrow_mut(); diff --git a/ext/tsconfig.d.ts b/ext/tsconfig.d.ts index a03c2f2..cc757a2 100644 --- a/ext/tsconfig.d.ts +++ b/ext/tsconfig.d.ts @@ -32,8 +32,9 @@ declare module "ext:core/ops" { // testing export function op_set_promise_sanitization_hook(): void; - export function op_set_promise_sanitization_name(testName: string): void; - export function op_test_sanitization(): boolean; + export function op_set_promise_sanitized_test_name(testName: string): void; + export function op_get_outstanding_ops(): number; + export function op_get_pending_promises(): number; export function op_diff_str(a: string, b: string): string; export function op_bench_fn(callback: () => void): number; diff --git a/sable/main.rs b/sable/main.rs index 48b1d04..83c3a1f 100644 --- a/sable/main.rs +++ b/sable/main.rs @@ -92,7 +92,7 @@ pub async fn sable_run(file_path: &str, options: SableOptions) -> Result<(), Any if metrics.has_pending_promises() { return Err(generic_error(format!( "Test {:?} has pending promises: {} of them resolved while {} got initialized", - metrics.test_name, metrics.promises_initialized, metrics.promises_resolved, + metrics.test_name, metrics.promises_resolved, metrics.promises_initialized, ))); } } diff --git a/tests/testing/microtask_promse_leak.js b/tests/testing/microtask_promse_leak.js new file mode 100644 index 0000000..dab6d88 --- /dev/null +++ b/tests/testing/microtask_promse_leak.js @@ -0,0 +1,7 @@ +const { test } = Sable.testing; + +test("Microtask promise leak (should fail)", () => { + new Promise((r) => { + queueMicrotask(r); + }); +}) \ No newline at end of file diff --git a/tests/testing/promise_leak.js b/tests/testing/promise_leak.js new file mode 100644 index 0000000..2fd54d4 --- /dev/null +++ b/tests/testing/promise_leak.js @@ -0,0 +1,5 @@ +const { test } = Sable.testing; + +test("Promise leak (should fail)", () => { + new Promise(() => {}); +}) \ No newline at end of file diff --git a/tests/testing/promise_tracking.js b/tests/testing/promise_tracking.js new file mode 100644 index 0000000..0505e7e --- /dev/null +++ b/tests/testing/promise_tracking.js @@ -0,0 +1,15 @@ +const { test } = Sable.testing; + +await test("Returned microtask promise", () => { + return new Promise((r) => { + queueMicrotask(r); + }); +}) + +test("Empty test", () => { + +}) + +test("Instantly resolved promise", () => { + return Promise.resolve(); +}); \ No newline at end of file diff --git a/tests/testing/returned_promise_leak.js b/tests/testing/returned_promise_leak.js new file mode 100644 index 0000000..622c51a --- /dev/null +++ b/tests/testing/returned_promise_leak.js @@ -0,0 +1,5 @@ +const { test } = Sable.testing; + +test("Returned promise leak (should fail)", () => { + return new Promise(() => {}); +}) From 0c0b3f50910764d34cb62d3c1423318b4cc06928 Mon Sep 17 00:00:00 2001 From: Im-Beast Date: Mon, 25 Mar 2024 09:48:38 +0100 Subject: [PATCH 5/9] fix: don't put promise tracker into the OpState when in bench state --- examples/fix.js | 15 --------------- sable/main.rs | 18 ++++++++++++++++-- 2 files changed, 16 insertions(+), 17 deletions(-) delete mode 100644 examples/fix.js diff --git a/examples/fix.js b/examples/fix.js deleted file mode 100644 index a3f9a25..0000000 --- a/examples/fix.js +++ /dev/null @@ -1,15 +0,0 @@ -const { test } = Sable.testing; - -await test("a", () => { - return new Promise(resolve => { - queueMicrotask(() => { - resolve() - }); - }); -}); - -test("b", () => { }); - -test("c", () => { - new Promise(() => {}); -}) \ No newline at end of file diff --git a/sable/main.rs b/sable/main.rs index 83c3a1f..19aa12f 100644 --- a/sable/main.rs +++ b/sable/main.rs @@ -49,10 +49,9 @@ pub async fn sable_run(file_path: &str, options: SableOptions) -> Result<(), Any let mut extensions = vec![sable::init_ops(), sable_cleanup::init_ops_and_esm()]; let (maybe_op_tracker, maybe_promise_tracker) = match options.state { - RuntimeState::Test | RuntimeState::Bench => { + RuntimeState::Test => { let op_tracker = Some(Rc::new(OpMetricsSummaryTracker::default())); let promise_tracker = Some(Rc::new(PromiseMetricsSummaryTracker::default())); - { let op_tracker = op_tracker.clone(); let promise_tracker = promise_tracker.clone(); @@ -68,6 +67,21 @@ pub async fn sable_run(file_path: &str, options: SableOptions) -> Result<(), Any } (op_tracker, promise_tracker) } + RuntimeState::Bench => { + let op_tracker = Some(Rc::new(OpMetricsSummaryTracker::default())); + { + let op_tracker = op_tracker.clone(); + extensions.push(Extension { + name: "sable_testing", + op_state_fn: Some(Box::new(move |state| { + state.put(options.state); + state.put(op_tracker); + })), + ..Default::default() + }); + } + (op_tracker, None) + } _ => (None, None), }; From e7a4f7f197114a15734429d5d4f7df8ccc496a7c Mon Sep 17 00:00:00 2001 From: Im-Beast Date: Fri, 29 Mar 2024 15:31:07 +0100 Subject: [PATCH 6/9] fix: insert and remove in release mode --- ext/testing/promise_tracker.rs | 12 ++++-------- 1 file changed, 4 insertions(+), 8 deletions(-) diff --git a/ext/testing/promise_tracker.rs b/ext/testing/promise_tracker.rs index 1bff28f..866ba5f 100644 --- a/ext/testing/promise_tracker.rs +++ b/ext/testing/promise_tracker.rs @@ -30,20 +30,16 @@ impl PromiseMetricsSummary { pub fn initialized(&mut self, promise_id: NonZeroI32) { self.promises_initialized += 1; - debug_assert!( - self.promises.insert(promise_id), - "Promise {promise_id} has been initialized twice" - ); + let inserted = self.promises.insert(promise_id); + debug_assert!(inserted, "Promise {promise_id} has been initialized twice"); } pub fn resolved(&mut self, promise_id: NonZeroI32) { self.promises_resolved += 1; // identity_hash is not guaranteed to be unique // we remove it in case it would be added again - debug_assert!( - self.promises.remove(&promise_id), - "Promise {promise_id} not found" - ); + let removed = self.promises.remove(&promise_id); + debug_assert!(removed, "Promise {promise_id} not found"); } } From 36c43d34c3a735d3dad09bfb642a2e15264bdeb2 Mon Sep 17 00:00:00 2001 From: Im-Beast Date: Fri, 29 Mar 2024 15:39:23 +0100 Subject: [PATCH 7/9] chore: add test --- tests/testing/promise_unawaited_test_leak.js | 7 +++++++ 1 file changed, 7 insertions(+) create mode 100644 tests/testing/promise_unawaited_test_leak.js diff --git a/tests/testing/promise_unawaited_test_leak.js b/tests/testing/promise_unawaited_test_leak.js new file mode 100644 index 0000000..7a61310 --- /dev/null +++ b/tests/testing/promise_unawaited_test_leak.js @@ -0,0 +1,7 @@ +const { test } = Sable.testing; + +test("A", () => Promise.resolve(1)); + +await test("B", (ctx) => { + ctx.equals(1, 1); +}) \ No newline at end of file From f1b36671a12fcf4c80a57ec7d5fe1f9ef8f67970 Mon Sep 17 00:00:00 2001 From: Im-Beast Date: Fri, 29 Mar 2024 15:55:32 +0100 Subject: [PATCH 8/9] . --- tests/testing/promise_leak.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/testing/promise_leak.js b/tests/testing/promise_leak.js index 2fd54d4..8e24303 100644 --- a/tests/testing/promise_leak.js +++ b/tests/testing/promise_leak.js @@ -1,5 +1,5 @@ const { test } = Sable.testing; -test("Promise leak (should fail)", () => { +await test("Promise leak (should fail)", () => { new Promise(() => {}); }) \ No newline at end of file From eaea706df4d407d8678edd59d3fb4c6064e1b2c2 Mon Sep 17 00:00:00 2001 From: Im-Beast Date: Fri, 29 Mar 2024 15:57:59 +0100 Subject: [PATCH 9/9] inner leak test --- tests/testing/promise_inner_leak.js | 6 ++++++ 1 file changed, 6 insertions(+) create mode 100644 tests/testing/promise_inner_leak.js diff --git a/tests/testing/promise_inner_leak.js b/tests/testing/promise_inner_leak.js new file mode 100644 index 0000000..8f22d8a --- /dev/null +++ b/tests/testing/promise_inner_leak.js @@ -0,0 +1,6 @@ +const { test } = Sable.testing; + +await test("Inner promise leak (should fail)", () => { + new Promise(() => {}); + return Promise.resolve(1); +}); \ No newline at end of file