From e7e08f162df5c184de78f5cbe3e2442f69b7a6e1 Mon Sep 17 00:00:00 2001 From: Alex Crichton Date: Wed, 15 Jan 2020 15:30:17 -0600 Subject: [PATCH] Preserve full native stack traces in errors (#823) * Preserve full native stack traces in errors This commit builds on #759 by performing a few refactorings: * The `backtrace` crate is updated to 0.3.42 which incorporates the Windows-specific stack-walking code, so that's no longer needed. * A full `backtrace::Backtrace` type is held in a trap at all times. * The trap structures in the `wasmtime-*` internal crates were refactored a bit to preserve more information and deal with raw values rather than converting between various types and strings. * The `wasmtime::Trap` type has been updated with these various changes. Eventually I think we'll want to likely render full stack traces (and/or partial wasm ones) into error messages, but for now that's left as-is and we can always improve it later. I suspect the most relevant thing we need to do is to implement function name symbolication for wasm functions first, and then afterwards we can incorporate native function names! * Fix some test suite assertions --- Cargo.lock | 5 +- crates/api/Cargo.toml | 1 + crates/api/src/callable.rs | 7 +- crates/api/src/instance.rs | 4 +- crates/api/src/trap.rs | 49 +++++----- crates/jit/src/action.rs | 16 +--- crates/runtime/Cargo.toml | 2 +- crates/runtime/src/backtrace.rs | 148 ----------------------------- crates/runtime/src/instance.rs | 8 +- crates/runtime/src/lib.rs | 4 +- crates/runtime/src/traphandlers.rs | 73 ++++++++------ tests/custom_signal_handler.rs | 11 ++- 12 files changed, 89 insertions(+), 239 deletions(-) delete mode 100644 crates/runtime/src/backtrace.rs diff --git a/Cargo.lock b/Cargo.lock index 0b60270a40..1f24462c3b 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -76,9 +76,9 @@ checksum = "f8aac770f1885fd7e387acedd76065302551364496e46b3dd00860b2f8359b9d" [[package]] name = "backtrace" -version = "0.3.40" +version = "0.3.42" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "924c76597f0d9ca25d762c25a4d369d51267536465dc5064bdf0eb073ed477ea" +checksum = "b4b1549d804b6c73f4817df2ba073709e96e426f12987127c48e6745568c350b" dependencies = [ "backtrace-sys", "cfg-if", @@ -1986,6 +1986,7 @@ name = "wasmtime" version = "0.9.0" dependencies = [ "anyhow", + "backtrace", "cfg-if", "file-per-thread-logger", "libc", diff --git a/crates/api/Cargo.toml b/crates/api/Cargo.toml index f524f3d036..66d2e42024 100644 --- a/crates/api/Cargo.toml +++ b/crates/api/Cargo.toml @@ -18,6 +18,7 @@ anyhow = "1.0.19" region = "2.0.0" libc = "0.2" cfg-if = "0.1.9" +backtrace = "0.3.42" [target.'cfg(target_os = "windows")'.dependencies] winapi = "0.3.7" diff --git a/crates/api/src/callable.rs b/crates/api/src/callable.rs index 545eafde80..8425d1d571 100644 --- a/crates/api/src/callable.rs +++ b/crates/api/src/callable.rs @@ -156,12 +156,7 @@ impl WrappedCallable for WasmtimeFn { ) }) } { - let message = error.0; - let backtrace = error.1; - - let trap = take_api_trap().unwrap_or_else(|| { - Trap::new_with_trace(format!("call error: {}", message), backtrace) - }); + let trap = take_api_trap().unwrap_or_else(|| Trap::from_jit(error)); return Err(trap); } diff --git a/crates/api/src/instance.rs b/crates/api/src/instance.rs index 48b080528b..82e125b5a5 100644 --- a/crates/api/src/instance.rs +++ b/crates/api/src/instance.rs @@ -52,8 +52,8 @@ fn instantiate_in_context( let instance = compiled_module.instantiate().map_err(|e| -> Error { if let Some(trap) = take_api_trap() { trap.into() - } else if let InstantiationError::StartTrap(msg) = e { - Trap::new(msg).into() + } else if let InstantiationError::StartTrap(trap) = e { + Trap::from_jit(trap).into() } else { e.into() } diff --git a/crates/api/src/trap.rs b/crates/api/src/trap.rs index ae74c00af3..0672b661f4 100644 --- a/crates/api/src/trap.rs +++ b/crates/api/src/trap.rs @@ -1,7 +1,7 @@ use crate::instance::Instance; +use backtrace::Backtrace; use std::fmt; use std::sync::Arc; -use wasmtime_runtime::{get_backtrace, Backtrace, BacktraceFrame}; /// A struct representing an aborted instruction execution, with a message /// indicating the cause. @@ -12,7 +12,8 @@ pub struct Trap { struct TrapInner { message: String, - trace: Vec, + wasm_trace: Vec, + native_trace: Backtrace, } fn _assert_trap_is_sync_and_send(t: &Trap) -> (&dyn Sync, &dyn Send) { @@ -27,21 +28,29 @@ impl Trap { /// assert_eq!("unexpected error", trap.message()); /// ``` pub fn new>(message: I) -> Self { - Self::new_with_trace(message, get_backtrace()) + Trap::new_with_trace(message.into(), Backtrace::new_unresolved()) } - pub(crate) fn new_with_trace>(message: I, backtrace: Backtrace) -> Self { - let mut trace = Vec::with_capacity(backtrace.len()); - for i in 0..backtrace.len() { - // Don't include frames without backtrace info. - if let Some(info) = FrameInfo::try_from(backtrace[i]) { - trace.push(info); + pub(crate) fn from_jit(jit: wasmtime_runtime::Trap) -> Self { + Trap::new_with_trace(jit.to_string(), jit.backtrace) + } + + fn new_with_trace(message: String, native_trace: Backtrace) -> Self { + let mut wasm_trace = Vec::new(); + for frame in native_trace.frames() { + let pc = frame.ip() as usize; + if let Some(info) = wasmtime_runtime::jit_function_registry::find(pc) { + wasm_trace.push(FrameInfo { + func_index: info.func_index as u32, + module_name: info.module_id.clone(), + }) } } Trap { inner: Arc::new(TrapInner { - message: message.into(), - trace, + message, + wasm_trace, + native_trace, }), } } @@ -52,7 +61,7 @@ impl Trap { } pub fn trace(&self) -> &[FrameInfo] { - &self.inner.trace + &self.inner.wasm_trace } } @@ -60,7 +69,8 @@ impl fmt::Debug for Trap { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { f.debug_struct("Trap") .field("message", &self.inner.message) - .field("trace", &self.inner.trace) + .field("wasm_trace", &self.inner.wasm_trace) + .field("native_trace", &self.inner.native_trace) .finish() } } @@ -99,17 +109,4 @@ impl FrameInfo { pub fn module_name(&self) -> Option<&str> { self.module_name.as_deref() } - - pub(crate) fn try_from(backtrace: BacktraceFrame) -> Option { - if let Some(tag) = backtrace.tag() { - let func_index = tag.func_index as u32; - let module_name = tag.module_id.clone(); - Some(FrameInfo { - func_index, - module_name, - }) - } else { - None - } - } } diff --git a/crates/jit/src/action.rs b/crates/jit/src/action.rs index 385ff32aa3..c836da8b26 100644 --- a/crates/jit/src/action.rs +++ b/crates/jit/src/action.rs @@ -6,10 +6,7 @@ use std::cmp::max; use std::{fmt, mem, ptr, slice}; use thiserror::Error; use wasmtime_environ::ir; -use wasmtime_runtime::{ - wasmtime_call_trampoline, Backtrace, Export, InstanceHandle, TrapMessageAndStack, - VMInvokeArgument, -}; +use wasmtime_runtime::{wasmtime_call_trampoline, Export, InstanceHandle, Trap, VMInvokeArgument}; /// A runtime value. #[derive(Copy, Clone, Debug, Eq, PartialEq)] @@ -103,12 +100,7 @@ pub enum ActionOutcome { }, /// A trap occurred while the action was executing. - Trapped { - /// The trap message. - message: String, - /// Backtrace. - trace: Backtrace, - }, + Trapped(Trap), } /// An error detected while invoking a wasm function or reading a wasm global. @@ -196,7 +188,7 @@ pub fn invoke( compiler.publish_compiled_code(); // Call the trampoline. - if let Err(TrapMessageAndStack(message, trace)) = unsafe { + if let Err(trap) = unsafe { instance.with_signals_on(|| { wasmtime_call_trampoline( callee_vmctx, @@ -205,7 +197,7 @@ pub fn invoke( ) }) } { - return Ok(ActionOutcome::Trapped { message, trace }); + return Ok(ActionOutcome::Trapped(trap)); } // Load the return values out of `values_vec`. diff --git a/crates/runtime/Cargo.toml b/crates/runtime/Cargo.toml index edee855abd..d37f6cc9a5 100644 --- a/crates/runtime/Cargo.toml +++ b/crates/runtime/Cargo.toml @@ -20,7 +20,7 @@ indexmap = "1.0.2" thiserror = "1.0.4" more-asserts = "0.2.1" cfg-if = "0.1.9" -backtrace = "0.3.40" +backtrace = "0.3.42" [target.'cfg(target_os = "windows")'.dependencies] winapi = { version = "0.3.7", features = ["winbase", "memoryapi"] } diff --git a/crates/runtime/src/backtrace.rs b/crates/runtime/src/backtrace.rs deleted file mode 100644 index c8cba1eb89..0000000000 --- a/crates/runtime/src/backtrace.rs +++ /dev/null @@ -1,148 +0,0 @@ -//! Backtrace object and utilities. - -use crate::jit_function_registry; -use std::sync::Arc; - -/// Information about backtrace frame. -#[derive(Debug, Copy, Clone, PartialEq, Eq)] -pub struct BacktraceFrame { - pc: usize, -} - -impl Default for BacktraceFrame { - fn default() -> Self { - Self { pc: 0 } - } -} - -impl BacktraceFrame { - /// Current PC or IP pointer for the frame. - pub fn pc(&self) -> usize { - self.pc - } - /// Additinal frame information. - pub fn tag(&self) -> Option> { - jit_function_registry::find(self.pc) - } -} - -const BACKTRACE_LIMIT: usize = 32; - -/// Backtrace during WebAssembly trap. -#[derive(Copy, Clone, PartialEq, Eq)] -pub struct Backtrace { - len: usize, - frames: [BacktraceFrame; BACKTRACE_LIMIT], -} - -impl Backtrace { - fn new() -> Self { - Self { - len: 0, - frames: [Default::default(); BACKTRACE_LIMIT], - } - } - fn full(&self) -> bool { - self.len >= BACKTRACE_LIMIT - } - fn push(&mut self, frame: BacktraceFrame) { - assert!(self.len < BACKTRACE_LIMIT); - self.frames[self.len] = frame; - self.len += 1; - } - /// Amount of the backtrace frames. - pub fn len(&self) -> usize { - self.len - } -} - -impl std::ops::Index for Backtrace { - type Output = BacktraceFrame; - fn index(&self, index: usize) -> &Self::Output { - assert!(index < self.len); - &self.frames[index] - } -} - -impl std::fmt::Debug for Backtrace { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { - writeln!(f, "Backtrace![")?; - for i in 0..self.len() { - let frame = &self.frames[i]; - writeln!(f, " {:x}: {:?}", frame.pc(), frame.tag())?; - } - write!(f, "]")?; - Ok(()) - } -} - -#[cfg(not(all(target_os = "windows", target_arch = "x86_64")))] -fn capture_stack(mut f: F) -where - F: FnMut(usize) -> bool, -{ - use backtrace::trace; - trace(|frame| { - let pc = frame.ip() as usize; - f(pc) - }); -} - -#[cfg(all(target_os = "windows", target_arch = "x86_64"))] -fn capture_stack(mut f: F) -where - F: FnMut(usize) -> bool, -{ - use std::mem::MaybeUninit; - use std::ptr; - use winapi::um::winnt::{ - RtlCaptureContext, RtlLookupFunctionEntry, RtlVirtualUnwind, CONTEXT, UNW_FLAG_NHANDLER, - }; - - #[repr(C, align(16))] - struct WrappedContext(CONTEXT); - - unsafe { - let mut ctx = WrappedContext(MaybeUninit::uninit().assume_init()); - RtlCaptureContext(&mut ctx.0); - let mut unwind_history_table = MaybeUninit::zeroed().assume_init(); - while ctx.0.Rip != 0 { - let cont = f(ctx.0.Rip as usize); - if !cont { - break; - } - - let mut image_base: u64 = 0; - let mut handler_data: *mut core::ffi::c_void = ptr::null_mut(); - let mut establisher_frame: u64 = 0; - let rf = RtlLookupFunctionEntry(ctx.0.Rip, &mut image_base, &mut unwind_history_table); - if rf.is_null() { - ctx.0.Rip = ptr::read(ctx.0.Rsp as *const u64); - ctx.0.Rsp += 8; - } else { - RtlVirtualUnwind( - UNW_FLAG_NHANDLER, - image_base, - ctx.0.Rip, - rf, - &mut ctx.0, - &mut handler_data, - &mut establisher_frame, - ptr::null_mut(), - ); - } - } - } -} - -/// Returns current backtrace. Only registered wasmtime functions will be listed. -pub fn get_backtrace() -> Backtrace { - let mut frames = Backtrace::new(); - capture_stack(|pc| { - if let Some(_) = jit_function_registry::find(pc) { - frames.push(BacktraceFrame { pc }); - } - !frames.full() - }); - frames -} diff --git a/crates/runtime/src/instance.rs b/crates/runtime/src/instance.rs index 2c7710e433..d6032faec5 100644 --- a/crates/runtime/src/instance.rs +++ b/crates/runtime/src/instance.rs @@ -9,7 +9,7 @@ use crate::memory::LinearMemory; use crate::mmap::Mmap; use crate::signalhandlers::{wasmtime_init_eager, wasmtime_init_finish}; use crate::table::Table; -use crate::traphandlers::{wasmtime_call, TrapMessageAndStack}; +use crate::traphandlers::{wasmtime_call, Trap}; use crate::vmcontext::{ VMBuiltinFunctionsArray, VMCallerCheckedAnyfunc, VMContext, VMFunctionBody, VMFunctionImport, VMGlobalDefinition, VMGlobalImport, VMMemoryDefinition, VMMemoryImport, VMSharedSignatureIndex, @@ -568,7 +568,7 @@ impl Instance { // Make the call. unsafe { wasmtime_call(callee_vmctx, callee_address) } - .map_err(|TrapMessageAndStack(msg, _)| InstantiationError::StartTrap(msg)) + .map_err(InstantiationError::StartTrap) } /// Invoke the WebAssembly start function of the instance, if one is present. @@ -1398,6 +1398,6 @@ pub enum InstantiationError { Link(#[from] LinkError), /// A compilation error occured. - #[error("Trap occurred while invoking start function: {0}")] - StartTrap(String), + #[error("Trap occurred while invoking start function")] + StartTrap(#[source] Trap), } diff --git a/crates/runtime/src/lib.rs b/crates/runtime/src/lib.rs index 29996f8550..6d5dac0ca7 100644 --- a/crates/runtime/src/lib.rs +++ b/crates/runtime/src/lib.rs @@ -21,7 +21,6 @@ ) )] -mod backtrace; mod export; mod imports; mod instance; @@ -38,7 +37,6 @@ mod vmcontext; pub mod jit_function_registry; pub mod libcalls; -pub use crate::backtrace::{get_backtrace, Backtrace, BacktraceFrame}; pub use crate::export::Export; pub use crate::imports::Imports; pub use crate::instance::{InstanceHandle, InstantiationError, LinkError}; @@ -47,7 +45,7 @@ pub use crate::mmap::Mmap; pub use crate::sig_registry::SignatureRegistry; pub use crate::signalhandlers::{wasmtime_init_eager, wasmtime_init_finish}; pub use crate::trap_registry::{get_mut_trap_registry, get_trap_registry, TrapRegistrationGuard}; -pub use crate::traphandlers::{wasmtime_call, wasmtime_call_trampoline, TrapMessageAndStack}; +pub use crate::traphandlers::{wasmtime_call, wasmtime_call_trampoline, Trap}; pub use crate::vmcontext::{ VMCallerCheckedAnyfunc, VMContext, VMFunctionBody, VMFunctionImport, VMGlobalDefinition, VMGlobalImport, VMInvokeArgument, VMMemoryDefinition, VMMemoryImport, VMSharedSignatureIndex, diff --git a/crates/runtime/src/traphandlers.rs b/crates/runtime/src/traphandlers.rs index ae89138172..a055ebc722 100644 --- a/crates/runtime/src/traphandlers.rs +++ b/crates/runtime/src/traphandlers.rs @@ -1,11 +1,12 @@ //! WebAssembly trap handling, which is built on top of the lower-level //! signalhandling mechanisms. -use crate::backtrace::{get_backtrace, Backtrace}; use crate::trap_registry::get_trap_registry; use crate::trap_registry::TrapDescription; use crate::vmcontext::{VMContext, VMFunctionBody}; +use backtrace::Backtrace; use std::cell::Cell; +use std::fmt; use std::ptr; use wasmtime_environ::ir; @@ -19,7 +20,7 @@ extern "C" { } thread_local! { - static RECORDED_TRAP: Cell> = Cell::new(None); + static RECORDED_TRAP: Cell> = Cell::new(None); static JMP_BUF: Cell<*const u8> = Cell::new(ptr::null()); static RESET_GUARD_PAGE: Cell = Cell::new(false); } @@ -44,26 +45,26 @@ pub extern "C" fn CheckIfTrapAtAddress(_pc: *const u8) -> i8 { pub extern "C" fn RecordTrap(pc: *const u8, reset_guard_page: bool) { // TODO: please see explanation in CheckIfTrapAtAddress. let registry = get_trap_registry(); - let trap_desc = registry - .get_trap(pc as usize) - .unwrap_or_else(|| TrapDescription { - source_loc: ir::SourceLoc::default(), - trap_code: ir::TrapCode::StackOverflow, - }); - - let trap_backtrace = get_backtrace(); + let trap = Trap { + desc: registry + .get_trap(pc as usize) + .unwrap_or_else(|| TrapDescription { + source_loc: ir::SourceLoc::default(), + trap_code: ir::TrapCode::StackOverflow, + }), + backtrace: Backtrace::new_unresolved(), + }; if reset_guard_page { RESET_GUARD_PAGE.with(|v| v.set(true)); } RECORDED_TRAP.with(|data| { - assert_eq!( - data.get(), - None, + let prev = data.replace(Some(trap)); + assert!( + prev.is_none(), "Only one trap per thread can be recorded at a moment!" ); - data.set(Some((trap_desc, trap_backtrace))) }); } @@ -113,21 +114,31 @@ fn reset_guard_page() {} /// Stores trace message with backtrace. #[derive(Debug)] -pub struct TrapMessageAndStack(pub String, pub Backtrace); - -fn trap_message_and_stack() -> TrapMessageAndStack { - let trap_desc = RECORDED_TRAP - .with(|data| data.replace(None)) - .expect("trap_message must be called after trap occurred"); +pub struct Trap { + /// What sort of trap happened, as well as where in the original wasm module + /// it happened. + pub desc: TrapDescription, + /// Native stack backtrace at the time the trap occurred + pub backtrace: Backtrace, +} - TrapMessageAndStack( - format!( +impl fmt::Display for Trap { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!( + f, "wasm trap: {}, source location: {}", - trap_code_to_expected_string(trap_desc.0.trap_code), - trap_desc.0.source_loc, - ), - trap_desc.1, - ) + trap_code_to_expected_string(self.desc.trap_code), + self.desc.source_loc + ) + } +} + +impl std::error::Error for Trap {} + +fn last_trap() -> Trap { + RECORDED_TRAP + .with(|data| data.replace(None)) + .expect("trap_message must be called after trap occurred") } fn trap_code_to_expected_string(trap_code: ir::TrapCode) -> String { @@ -156,9 +167,9 @@ pub unsafe extern "C" fn wasmtime_call_trampoline( vmctx: *mut VMContext, callee: *const VMFunctionBody, values_vec: *mut u8, -) -> Result<(), TrapMessageAndStack> { +) -> Result<(), Trap> { if WasmtimeCallTrampoline(vmctx as *mut u8, callee, values_vec) == 0 { - Err(trap_message_and_stack()) + Err(last_trap()) } else { Ok(()) } @@ -170,9 +181,9 @@ pub unsafe extern "C" fn wasmtime_call_trampoline( pub unsafe extern "C" fn wasmtime_call( vmctx: *mut VMContext, callee: *const VMFunctionBody, -) -> Result<(), TrapMessageAndStack> { +) -> Result<(), Trap> { if WasmtimeCall(vmctx as *mut u8, callee) == 0 { - Err(trap_message_and_stack()) + Err(last_trap()) } else { Ok(()) } diff --git a/tests/custom_signal_handler.rs b/tests/custom_signal_handler.rs index 40f9080998..3bbb590424 100644 --- a/tests/custom_signal_handler.rs +++ b/tests/custom_signal_handler.rs @@ -128,9 +128,12 @@ mod tests { { println!("calling read_out_of_bounds..."); let trap = invoke_export(&instance, "read_out_of_bounds").unwrap_err(); - assert!(trap - .message() - .starts_with("call error: wasm trap: out of bounds memory access")); + assert!( + trap.message() + .starts_with("wasm trap: out of bounds memory access"), + "bad trap message: {:?}", + trap.message() + ); } // these invoke wasmtime_call_trampoline from callable.rs @@ -151,7 +154,7 @@ mod tests { let trap = read_out_of_bounds_func.call(&[]).unwrap_err(); assert!(trap .message() - .starts_with("call error: wasm trap: out of bounds memory access")); + .starts_with("wasm trap: out of bounds memory access")); } Ok(()) }