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

@@ -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",

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"

crates/api/src/callable.rs

@@ -156,12 +156,7 @@ impl WrappedCallable for WasmtimeFn {
                 )
             })
         } {
-            let message = error.0;
+            let trap = take_api_trap().unwrap_or_else(|| Trap::from_jit(error));
-            let backtrace = error.1;
-
-            let trap = take_api_trap().unwrap_or_else(|| {
-                Trap::new_with_trace(format!("call error: {}", message), backtrace)
-            });
             return Err(trap);
         }
 

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 {
+        } else if let InstantiationError::StartTrap(trap) = e {
-            Trap::new(msg).into()
+            Trap::from_jit(trap).into()
         } else {
             e.into()
         }

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<FrameInfo>,
+    wasm_trace: Vec<FrameInfo>,
+    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<I: Into<String>>(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<I: Into<String>>(message: I, backtrace: Backtrace) -> Self {
+    pub(crate) fn from_jit(jit: wasmtime_runtime::Trap) -> Self {
-        let mut trace = Vec::with_capacity(backtrace.len());
+        Trap::new_with_trace(jit.to_string(), jit.backtrace)
-        for i in 0..backtrace.len() {
+    }
-            // Don't include frames without backtrace info.
+
-            if let Some(info) = FrameInfo::try_from(backtrace[i]) {
+    fn new_with_trace(message: String, native_trace: Backtrace) -> Self {
-                trace.push(info);
+        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(),
+                message,
-                trace,
+                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<FrameInfo> {
-        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
-        }
-    }
 }

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::{
+use wasmtime_runtime::{wasmtime_call_trampoline, Export, InstanceHandle, Trap, VMInvokeArgument};
-    wasmtime_call_trampoline, Backtrace, Export, InstanceHandle, TrapMessageAndStack,
-    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 {
+    Trapped(Trap),
-        /// The trap message.
-        message: String,
-        /// Backtrace.
-        trace: Backtrace,
-    },
 }
 
 /// 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`.

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"] }

crates/runtime/src/backtrace.rs

@@ -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<Arc<jit_function_registry::JITFunctionTag>> {
-        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<usize> 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<F>(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<F>(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
-}

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}")]
+    #[error("Trap occurred while invoking start function")]
-    StartTrap(String),
+    StartTrap(#[source] Trap),
 }

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,

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<Option<(TrapDescription, Backtrace)>> = Cell::new(None);
+    static RECORDED_TRAP: Cell<Option<Trap>> = Cell::new(None);
     static JMP_BUF: Cell<*const u8> = Cell::new(ptr::null());
     static RESET_GUARD_PAGE: Cell<bool> = 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
+    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(),
-    let trap_backtrace = get_backtrace();
+    };
 
     if reset_guard_page {
         RESET_GUARD_PAGE.with(|v| v.set(true));
     }
 
     RECORDED_TRAP.with(|data| {
-        assert_eq!(
+        let prev = data.replace(Some(trap));
-            data.get(),
+        assert!(
-            None,
+            prev.is_none(),
             "Only one trap per thread can be recorded at a moment!"
         );
-        data.set(Some((trap_desc, trap_backtrace)))
     });
 }
 
@@ -113,22 +114,32 @@ fn reset_guard_page() {}
 
 /// Stores trace message with backtrace.
 #[derive(Debug)]
-pub struct TrapMessageAndStack(pub String, pub Backtrace);
+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,
+}
 
-fn trap_message_and_stack() -> TrapMessageAndStack {
+impl fmt::Display for Trap {
-    let trap_desc = RECORDED_TRAP
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
-        .with(|data| data.replace(None))
+        write!(
-        .expect("trap_message must be called after trap occurred");
+            f,
-
-    TrapMessageAndStack(
-        format!(
             "wasm trap: {}, source location: {}",
-            trap_code_to_expected_string(trap_desc.0.trap_code),
+            trap_code_to_expected_string(self.desc.trap_code),
-            trap_desc.0.source_loc,
+            self.desc.source_loc
-        ),
-        trap_desc.1,
         )
     }
+}
+
+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 {
     use ir::TrapCode::*;
@@ -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(())
     }

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
+            assert!(
-                .message()
+                trap.message()
-                .starts_with("call error: wasm trap: out of bounds memory access"));
+                    .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(())
     }