From f526513d74d34ac254aa40ef9b73238cb21c395b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bartek=20Iwa=C5=84czuk?= Date: Mon, 28 Nov 2022 23:07:23 +0100 Subject: [PATCH] feat(core): show unresolved promise origin (#16650) This commit updates unhelpful messages that are raised when event loop stalls on unresolved top-level promises. Instead of "Module evaluation is still pending but there are no pending ops or dynamic imports. This situation is often caused by unresolved promises." and "Dynamically imported module evaluation is still pending but there are no pending ops. This situation is often caused by unresolved promises." we are now printing a message like: error: Top-level await promise never resolved [SOURCE LINE] ^ at [FUNCTION NAME] ([FILENAME]) eg: error: Top-level await promise never resolved await new Promise((_resolve, _reject) => {}); ^ at (file:///Users/ib/dev/deno/cli/tests/testdata/test/unresolved_promise.ts:1:1) Co-authored-by: David Sherret --- .../testdata/bench/unresolved_promise.out | 5 +- .../testdata/run/top_level_await/circular.out | 7 +- .../run/top_level_await/unresolved.out | 5 +- .../testdata/test/unresolved_promise.out | 15 ++- core/error.rs | 79 +++++++++++++++- core/modules.rs | 4 +- core/runtime.rs | 93 ++++++++++++++++--- 7 files changed, 180 insertions(+), 28 deletions(-) diff --git a/cli/tests/testdata/bench/unresolved_promise.out b/cli/tests/testdata/bench/unresolved_promise.out index d544d77e77..b601e9b70f 100644 --- a/cli/tests/testdata/bench/unresolved_promise.out +++ b/cli/tests/testdata/bench/unresolved_promise.out @@ -1,2 +1,5 @@ Check [WILDCARD]/bench/unresolved_promise.ts -error: Module evaluation is still pending but there are no pending ops or dynamic imports. This situation is often caused by unresolved promises. +error: Top-level await promise never resolved +await new Promise((_resolve, _reject) => {}); +^ + at ([WILDCARD]bench/unresolved_promise.ts:1:1) diff --git a/cli/tests/testdata/run/top_level_await/circular.out b/cli/tests/testdata/run/top_level_await/circular.out index 72072071ed..c889789613 100644 --- a/cli/tests/testdata/run/top_level_await/circular.out +++ b/cli/tests/testdata/run/top_level_await/circular.out @@ -4,6 +4,7 @@ timeout loop 2 timeout loop 3 timeout loop 4 timeout loop 5 -error: Dynamically imported module evaluation is still pending but there are no pending ops. This situation is often caused by unresolved promises. -Pending dynamic modules: -- [WILDCARD]/tla3/b.js +error: Top-level await promise never resolved +const mod = await import("./tla3/b.js"); + ^ + at ([WILDCARD]/top_level_await/circular.js:5:13) diff --git a/cli/tests/testdata/run/top_level_await/unresolved.out b/cli/tests/testdata/run/top_level_await/unresolved.out index d5291f833d..1f4ea5d382 100644 --- a/cli/tests/testdata/run/top_level_await/unresolved.out +++ b/cli/tests/testdata/run/top_level_await/unresolved.out @@ -1 +1,4 @@ -error: Module evaluation is still pending but there are no pending ops or dynamic imports. This situation is often caused by unresolved promises. +error: Top-level await promise never resolved +await new Promise(() => {}); +^ + at ([WILDCARD]top_level_await/unresolved.js:1:1) diff --git a/cli/tests/testdata/test/unresolved_promise.out b/cli/tests/testdata/test/unresolved_promise.out index 92eb16bed1..88535e1714 100644 --- a/cli/tests/testdata/test/unresolved_promise.out +++ b/cli/tests/testdata/test/unresolved_promise.out @@ -1,5 +1,10 @@ -Check [WILDCARD]/test/unresolved_promise.ts - -ok | 0 passed | 0 failed ([WILDCARD]) - -error: Module evaluation is still pending but there are no pending ops or dynamic imports. This situation is often caused by unresolved promises. +[WILDCARD] +./test/unresolved_promise.ts (uncaught error) +error: Top-level await promise never resolved +await new Promise((_resolve, _reject) => {}); +^ + at ([WILDCARD]/test/unresolved_promise.ts:1:1) +This error was not caught from a test and caused the test runner to fail on the referenced module. +It most likely originated from a dangling promise, event/timeout handler or top-level code. +[WILDCARD] +error: Test failed diff --git a/core/error.rs b/core/error.rs index d71da31641..fb9bdf8e40 100644 --- a/core/error.rs +++ b/core/error.rs @@ -207,6 +207,84 @@ impl JsError { Self::inner_from_v8_exception(scope, exception, Default::default()) } + pub fn from_v8_message<'a>( + scope: &'a mut v8::HandleScope, + msg: v8::Local<'a, v8::Message>, + ) -> Self { + // Create a new HandleScope because we're creating a lot of new local + // handles below. + let scope = &mut v8::HandleScope::new(scope); + + let exception_message = msg.get(scope).to_rust_string_lossy(scope); + let state_rc = JsRuntime::state(scope); + + // Convert them into Vec + let mut frames: Vec = vec![]; + + let mut source_line = None; + let mut source_line_frame_index = None; + { + let state = &mut *state_rc.borrow_mut(); + + let script_resource_name = msg + .get_script_resource_name(scope) + .and_then(|v| v8::Local::::try_from(v).ok()) + .map(|v| v.to_rust_string_lossy(scope)); + let line_number: Option = + msg.get_line_number(scope).and_then(|v| v.try_into().ok()); + let column_number: Option = msg.get_start_column().try_into().ok(); + if let (Some(f), Some(l), Some(c)) = + (script_resource_name, line_number, column_number) + { + // V8's column numbers are 0-based, we want 1-based. + let c = c + 1; + if let Some(source_map_getter) = &state.source_map_getter { + let (f, l, c) = apply_source_map( + f, + l, + c, + &mut state.source_map_cache, + source_map_getter.as_ref(), + ); + frames = vec![JsStackFrame::from_location(Some(f), Some(l), Some(c))]; + } else { + frames = vec![JsStackFrame::from_location(Some(f), Some(l), Some(c))]; + } + } + + if let Some(source_map_getter) = &state.source_map_getter { + for (i, frame) in frames.iter().enumerate() { + if let (Some(file_name), Some(line_number)) = + (&frame.file_name, frame.line_number) + { + if !file_name.trim_start_matches('[').starts_with("deno:") { + source_line = get_source_line( + file_name, + line_number, + &mut state.source_map_cache, + source_map_getter.as_ref(), + ); + source_line_frame_index = Some(i); + break; + } + } + } + } + } + + Self { + name: None, + message: None, + exception_message, + cause: None, + source_line, + source_line_frame_index, + frames, + stack: None, + aggregated: None, + } + } + fn inner_from_v8_exception<'a>( scope: &'a mut v8::HandleScope, exception: v8::Local<'a, v8::Value>, @@ -330,7 +408,6 @@ impl JsError { (&frame.file_name, frame.line_number) { if !file_name.trim_start_matches('[').starts_with("deno:") { - // Source lookup expects a 0-based line number, ours are 1-based. source_line = get_source_line( file_name, line_number, diff --git a/core/modules.rs b/core/modules.rs index 8d0ae97334..1041f44f86 100644 --- a/core/modules.rs +++ b/core/modules.rs @@ -754,8 +754,8 @@ pub(crate) enum ModuleError { pub(crate) struct ModuleMap { // Handling of specifiers and v8 objects ids_by_handle: HashMap, ModuleId>, - handles_by_id: HashMap>, - info: HashMap, + pub handles_by_id: HashMap>, + pub info: HashMap, by_name: HashMap<(String, AssertedModuleType), SymbolicModule>, next_module_id: ModuleId, next_load_id: ModuleLoadId, diff --git a/core/runtime.rs b/core/runtime.rs index 5272266260..4647160c9c 100644 --- a/core/runtime.rs +++ b/core/runtime.rs @@ -1168,7 +1168,7 @@ impl JsRuntime { return Poll::Ready(Ok(())); } - let mut state = self.state.borrow_mut(); + let state = self.state.borrow(); // Check if more async ops have been dispatched // during this turn of event loop. @@ -1185,6 +1185,8 @@ impl JsRuntime { state.waker.wake(); } + drop(state); + if pending_state.has_pending_module_evaluation { if pending_state.has_pending_refed_ops || pending_state.has_pending_dyn_imports @@ -1195,8 +1197,16 @@ impl JsRuntime { { // pass, will be polled again } else { - let msg = "Module evaluation is still pending but there are no pending ops or dynamic imports. This situation is often caused by unresolved promises."; - return Poll::Ready(Err(generic_error(msg))); + let scope = &mut self.handle_scope(); + let messages = find_stalled_top_level_await(scope); + // We are gonna print only a single message to provide a nice formatting + // with source line of offending promise shown. Once user fixed it, then + // they will get another error message for the next promise (but this + // situation is gonna be very rare, if ever happening). + assert!(!messages.is_empty()); + let msg = v8::Local::new(scope, messages[0].clone()); + let js_error = JsError::from_v8_message(scope, msg); + return Poll::Ready(Err(js_error.into())); } } @@ -1207,19 +1217,19 @@ impl JsRuntime { || pending_state.has_tick_scheduled { // pass, will be polled again - } else if state.dyn_module_evaluate_idle_counter >= 1 { - let mut msg = "Dynamically imported module evaluation is still pending but there are no pending ops. This situation is often caused by unresolved promises. -Pending dynamic modules:\n".to_string(); - let module_map = self.module_map.as_mut().unwrap().borrow_mut(); - for pending_evaluate in &state.pending_dyn_mod_evaluate { - let module_info = module_map - .get_info_by_id(&pending_evaluate.module_id) - .unwrap(); - msg.push_str("- "); - msg.push_str(module_info.name.as_str()); - } - return Poll::Ready(Err(generic_error(msg))); + } else if self.state.borrow().dyn_module_evaluate_idle_counter >= 1 { + let scope = &mut self.handle_scope(); + let messages = find_stalled_top_level_await(scope); + // We are gonna print only a single message to provide a nice formatting + // with source line of offending promise shown. Once user fixed it, then + // they will get another error message for the next promise (but this + // situation is gonna be very rare, if ever happening). + assert!(!messages.is_empty()); + let msg = v8::Local::new(scope, messages[0].clone()); + let js_error = JsError::from_v8_message(scope, msg); + return Poll::Ready(Err(js_error.into())); } else { + let mut state = self.state.borrow_mut(); // Delay the above error by one spin of the event loop. A dynamic import // evaluation may complete during this, in which case the counter will // reset. @@ -1269,6 +1279,59 @@ Pending dynamic modules:\n".to_string(); } } +fn get_stalled_top_level_await_message_for_module<'s>( + scope: &'s mut v8::HandleScope, + module_id: ModuleId, +) -> Vec> { + let module_map = JsRuntime::module_map(scope); + let module_map = module_map.borrow(); + let module_handle = module_map.handles_by_id.get(&module_id).unwrap(); + + let module = v8::Local::new(scope, module_handle); + let stalled = module.get_stalled_top_level_await_message(scope); + let mut messages = vec![]; + for (_, message) in stalled { + messages.push(v8::Global::new(scope, message)); + } + messages +} + +fn find_stalled_top_level_await<'s>( + scope: &'s mut v8::HandleScope, +) -> Vec> { + let module_map = JsRuntime::module_map(scope); + let module_map = module_map.borrow(); + + // First check if that's root module + let root_module_id = module_map + .info + .values() + .filter(|m| m.main) + .map(|m| m.id) + .next(); + + if let Some(root_module_id) = root_module_id { + let messages = + get_stalled_top_level_await_message_for_module(scope, root_module_id); + if !messages.is_empty() { + return messages; + } + } + + // It wasn't a top module, so iterate over all modules and try to find + // any with stalled top level await + let module_ids = module_map.handles_by_id.keys().copied().collect::>(); + for module_id in module_ids { + let messages = + get_stalled_top_level_await_message_for_module(scope, module_id); + if !messages.is_empty() { + return messages; + } + } + + unreachable!() +} + #[derive(Clone, Copy, PartialEq, Eq, Debug)] pub(crate) struct EventLoopPendingState { has_pending_refed_ops: bool,