diff --git a/ext/lib.rs b/ext/lib.rs index 6b6a9a1..44286a9 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,10 @@ pub mod extensions { timers::op_create_timer, testing::op_bench_fn, testing::op_diff_str, - testing::op_test_async_ops_sanitization, + testing::op_get_outstanding_ops, + testing::op_get_pending_promises, + testing::op_set_promise_sanitization_hook, + testing::op_set_promise_sanitized_test_name, web::op_encoding_normalize_label, web::op_encoding_decode_utf8, web::op_encoding_decode_single, @@ -62,23 +73,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..3a759cb 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,77 @@ 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 { - 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.ops_completed_async == summary.ops_dispatched_async + summary.ops_dispatched_async - summary.ops_completed_async } } } + +#[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>( + 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); // scopes deref into &Isolate + let mut state = state.borrow_mut(); + + let metrics_tracker = state + .borrow_mut::>>() + .as_ref() + .unwrap(); + + let promise_id = promise.get_identity_hash(); + + match hook_type { + v8::PromiseHookType::Init => { + let mut metrics = metrics_tracker.metrics_mut(); + metrics.initialized(promise_id); + } + v8::PromiseHookType::Resolve => { + 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_sanitized_test_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..5179137 100644 --- a/ext/testing/mod.js +++ b/ext/testing/mod.js @@ -1,50 +1,35 @@ -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_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 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? -});`; - } else { - const ptd = "-".repeat(textWidth(testContext.title)); - - message += ` -test('${testContext.title}', (ctx) => { ---------${ptd}^ this test is not asynchronous, but leaks asynchronous ops - ... ---^^^ ops 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"; } } @@ -54,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"; } } @@ -89,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"; @@ -374,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_async_ops_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); } } @@ -419,21 +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(); - parent?.unlock(testContext); - TestContext.sanitizeAsyncOps(testContext, true); - }); + if (parent) { + parent.unlock(testContext); + op_set_promise_sanitized_test_name(parent.name); + } + }) } else { + TestContext.sanitizeAsyncOps(testContext, 0); testContext.finish(); - parent?.unlock(testContext); - TestContext.sanitizeAsyncOps(testContext, false); + if (parent) { + parent.unlock(testContext); + op_set_promise_sanitized_test_name(parent.name); + } } } + // TODO(Im-Beast): Add TestContext.fails /** * Create new sub-test with given callback * @param {string} name @@ -671,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); } @@ -686,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 new file mode 100644 index 0000000..866ba5f --- /dev/null +++ b/ext/testing/promise_tracker.rs @@ -0,0 +1,107 @@ +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 { + 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 + } + + 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; + 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 + let removed = self.promises.remove(&promise_id); + debug_assert!(removed, "Promise {promise_id} not found"); + } +} + +#[derive(Debug, Default)] +pub struct PromiseMetricsSummaryTracker { + tracked: RefCell, + metrics: RefCell>, +} + +impl PromiseMetricsSummaryTracker { + pub fn per_test(&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(&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(); + + 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..cc757a2 100644 --- a/ext/tsconfig.d.ts +++ b/ext/tsconfig.d.ts @@ -31,7 +31,10 @@ 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_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 51f49e0..19aa12f 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}; @@ -16,7 +18,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 +46,48 @@ 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 { - 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 (maybe_op_tracker, maybe_promise_tracker) = match options.state { + 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(); + 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) } - _ => {} - } + 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), + }; 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 +101,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_test().iter() { + 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_resolved, metrics.promises_initialized, + ))); + } + } + } + result.await } 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_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 diff --git a/tests/testing/promise_leak.js b/tests/testing/promise_leak.js new file mode 100644 index 0000000..8e24303 --- /dev/null +++ b/tests/testing/promise_leak.js @@ -0,0 +1,5 @@ +const { test } = Sable.testing; + +await 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/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 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(() => {}); +}) 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(() => {