From 51c1d4bbd6dc2985e8f2ad00731012df071d928b Mon Sep 17 00:00:00 2001 From: Alex Crichton Date: Tue, 1 Dec 2020 16:56:23 -0600 Subject: [PATCH] Provide filename/line number information in `Trap` (#2452) * Provide filename/line number information in `Trap` This commit extends the `Trap` type and `Store` to retain DWARF debug information found in a wasm file unconditionally, if it's present. This then enables us to print filenames and line numbers which point back to actual source code when a trap backtrace is printed. Additionally the `FrameInfo` type has been souped up to return filename/line number information as well. The implementation here is pretty simplistic currently. The meat of all the work happens in `gimli` and `addr2line`, and otherwise wasmtime is just schlepping around bytes of dwarf debuginfo here and there! The general goal here is to assist with debugging when using wasmtime because filenames and line numbers are generally orders of magnitude better even when you already have a stack trace. Another nicety here is that backtraces will display inlined frames (learned through debug information), improving the experience in release mode as well. An example of this is that with this file: ```rust fn main() { panic!("hello"); } ``` we get this stack trace: ``` $ rustc foo.rs --target wasm32-wasi -g $ cargo run foo.wasm Finished dev [unoptimized + debuginfo] target(s) in 0.16s Running `target/debug/wasmtime foo.wasm` thread 'main' panicked at 'hello', foo.rs:2:5 note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace Error: failed to run main module `foo.wasm` Caused by: 0: failed to invoke command default 1: wasm trap: unreachable wasm backtrace: 0: 0x6c1c - panic_abort::__rust_start_panic::abort::h2d60298621b1ccbf at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/panic_abort/src/lib.rs:77:17 - __rust_start_panic at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/panic_abort/src/lib.rs:32:5 1: 0x68c7 - rust_panic at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:626:9 2: 0x65a1 - std::panicking::rust_panic_with_hook::h2345fb0909b53e12 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:596:5 3: 0x1436 - std::panicking::begin_panic::{{closure}}::h106f151a6db8c8fb at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:506:9 4: 0xda8 - std::sys_common::backtrace::__rust_end_short_backtrace::he55aa13f22782798 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:153:18 5: 0x1324 - std::panicking::begin_panic::h1727e7d1d719c76f at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:505:12 6: 0xfde - foo::main::h2db1313a64510850 at /Users/acrichton/code/wasmtime/foo.rs:2:5 7: 0x11d5 - core::ops::function::FnOnce::call_once::h20ee1cc04aeff1fc at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/ops/function.rs:227:5 8: 0xddf - std::sys_common::backtrace::__rust_begin_short_backtrace::h054493e41e27e69c at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:137:18 9: 0x1d5a - std::rt::lang_start::{{closure}}::hd83784448d3fcb42 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/rt.rs:66:18 10: 0x69d8 - core::ops::function::impls:: for &F>::call_once::h564d3dad35014917 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/ops/function.rs:259:13 - std::panicking::try::do_call::hdca4832ace5a8603 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:381:40 - std::panicking::try::ha8624a1a6854b456 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:345:19 - std::panic::catch_unwind::h71421f57cf2bc688 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panic.rs:382:14 - std::rt::lang_start_internal::h260050c92cd470af at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/rt.rs:51:25 11: 0x1d0c - std::rt::lang_start::h0b4bcf3c5e498224 at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/rt.rs:65:5 12: 0xffc - !__original_main 13: 0x393 - __muloti4 at /cargo/registry/src/github.com-1ecc6299db9ec823/compiler_builtins-0.1.35/src/macros.rs:269 ``` This is relatively noisy by default but there's filenames and line numbers! Additionally frame 10 can be seen to have lots of frames inlined into it. All information is always available to the embedder but we could try to handle the `__rust_begin_short_backtrace` and `__rust_end_short_backtrace` markers to trim the backtrace by default as well. The only gotcha here is that it looks like `__muloti4` is out of place. That's because the libc that Rust ships with doesn't have dwarf information, although I'm not sure why we land in that function for symbolizing it... * Add a configuration switch for debuginfo * Control debuginfo by default with `WASM_BACKTRACE_DETAILS` * Try cpp_demangle on demangling as well * Rename to WASMTIME_BACKTRACE_DETAILS --- Cargo.lock | 12 ++ crates/cranelift/src/lib.rs | 4 +- crates/environ/src/module_environ.rs | 20 ++-- crates/environ/src/tunables.rs | 10 +- crates/jit/Cargo.toml | 1 + crates/jit/src/compiler.rs | 2 +- crates/jit/src/instantiate.rs | 159 +++++++++++++++++++++++++-- crates/jit/src/lib.rs | 4 +- crates/lightbeam/wasmtime/src/lib.rs | 2 +- crates/wasmtime/Cargo.toml | 1 + crates/wasmtime/src/config.rs | 55 ++++++++- crates/wasmtime/src/frame_info.rs | 127 +++++++++++++++++++-- crates/wasmtime/src/lib.rs | 2 +- crates/wasmtime/src/trap.rs | 71 ++++++++++-- src/obj.rs | 3 +- tests/all/traps.rs | 157 +++++++++++++++++++++++--- 16 files changed, 568 insertions(+), 62 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index aabea2ee2b..40c4034ef9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -331,6 +331,16 @@ version = "0.1.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "245097e9a4535ee1e3e3931fcfcd55a796a44c643e8596ff6566d68f09b87bbc" +[[package]] +name = "cpp_demangle" +version = "0.3.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "44919ecaf6f99e8e737bc239408931c9a01e9a6c74814fee8242dd2506b65390" +dependencies = [ + "cfg-if 1.0.0", + "glob", +] + [[package]] name = "cpu-time" version = "1.0.0" @@ -2342,6 +2352,7 @@ dependencies = [ "backtrace", "bincode", "cfg-if 1.0.0", + "cpp_demangle", "libc", "log", "region", @@ -2522,6 +2533,7 @@ dependencies = [ name = "wasmtime-jit" version = "0.21.0" dependencies = [ + "addr2line", "anyhow", "cfg-if 1.0.0", "cranelift-codegen", diff --git a/crates/cranelift/src/lib.rs b/crates/cranelift/src/lib.rs index a0e241572e..1837ba02d1 100644 --- a/crates/cranelift/src/lib.rs +++ b/crates/cranelift/src/lib.rs @@ -355,7 +355,7 @@ impl Compiler for Cranelift { context.func.name = get_func_name(func_index); let sig_index = module.functions[func_index]; context.func.signature = translation.native_signatures[sig_index].clone(); - if tunables.debug_info { + if tunables.generate_native_debuginfo { context.func.collect_debug_info(); } @@ -434,7 +434,7 @@ impl Compiler for Cranelift { let address_transform = get_function_address_map(&context, &input, code_buf.len() as u32, isa); - let ranges = if tunables.debug_info { + let ranges = if tunables.generate_native_debuginfo { let ranges = context.build_value_labels_ranges(isa).map_err(|error| { CompileError::Codegen(pretty_error(&context.func, Some(isa), error)) })?; diff --git a/crates/environ/src/module_environ.rs b/crates/environ/src/module_environ.rs index e085751d77..128cc71b31 100644 --- a/crates/environ/src/module_environ.rs +++ b/crates/environ/src/module_environ.rs @@ -62,6 +62,10 @@ pub struct ModuleTranslation<'data> { /// this module. pub submodules: PrimaryMap, + /// Set if debuginfo was found but it was not parsed due to `Tunables` + /// configuration. + pub has_unparsed_debuginfo: bool, + code_index: u32, } @@ -81,8 +85,8 @@ pub struct DebugInfoData<'a> { pub wasm_file: WasmFileInfo, debug_loc: gimli::DebugLoc>, debug_loclists: gimli::DebugLocLists>, - debug_ranges: gimli::DebugRanges>, - debug_rnglists: gimli::DebugRngLists>, + pub debug_ranges: gimli::DebugRanges>, + pub debug_rnglists: gimli::DebugRngLists>, } #[allow(missing_docs)] @@ -152,9 +156,11 @@ impl<'data> ModuleEnvironment<'data> { } fn register_dwarf_section(&mut self, name: &str, data: &'data [u8]) { - if !self.tunables.debug_info { + if !self.tunables.generate_native_debuginfo && !self.tunables.parse_wasm_debuginfo { + self.result.has_unparsed_debuginfo = true; return; } + if !name.starts_with(".debug_") { return; } @@ -493,7 +499,7 @@ impl<'data> cranelift_wasm::ModuleEnvironment<'data> for ModuleEnvironment<'data validator: FuncValidator, body: FunctionBody<'data>, ) -> WasmResult<()> { - if self.tunables.debug_info { + if self.tunables.generate_native_debuginfo { let func_index = self.result.code_index + self.result.module.num_imported_funcs as u32; let func_index = FuncIndex::from_u32(func_index); let sig_index = self.result.module.functions[func_index]; @@ -563,7 +569,7 @@ impl<'data> cranelift_wasm::ModuleEnvironment<'data> for ModuleEnvironment<'data fn declare_module_name(&mut self, name: &'data str) { self.result.module.name = Some(name.to_string()); - if self.tunables.debug_info { + if self.tunables.generate_native_debuginfo { self.result.debuginfo.name_section.module_name = Some(name); } } @@ -573,7 +579,7 @@ impl<'data> cranelift_wasm::ModuleEnvironment<'data> for ModuleEnvironment<'data .module .func_names .insert(func_index, name.to_string()); - if self.tunables.debug_info { + if self.tunables.generate_native_debuginfo { self.result .debuginfo .name_section @@ -583,7 +589,7 @@ impl<'data> cranelift_wasm::ModuleEnvironment<'data> for ModuleEnvironment<'data } fn declare_local_name(&mut self, func_index: FuncIndex, local: u32, name: &'data str) { - if self.tunables.debug_info { + if self.tunables.generate_native_debuginfo { self.result .debuginfo .name_section diff --git a/crates/environ/src/tunables.rs b/crates/environ/src/tunables.rs index 3e1907611d..939861504d 100644 --- a/crates/environ/src/tunables.rs +++ b/crates/environ/src/tunables.rs @@ -10,8 +10,11 @@ pub struct Tunables { /// The size in bytes of the offset guard for dynamic heaps. pub dynamic_memory_offset_guard_size: u64, - /// Whether or not to generate DWARF debug information. - pub debug_info: bool, + /// Whether or not to generate native DWARF debug information. + pub generate_native_debuginfo: bool, + + /// Whether or not to retain DWARF sections in compiled modules. + pub parse_wasm_debuginfo: bool, /// Whether or not to enable the ability to interrupt wasm code dynamically. /// @@ -51,7 +54,8 @@ impl Default for Tunables { /// wasting too much memory. dynamic_memory_offset_guard_size: 0x1_0000, - debug_info: false, + generate_native_debuginfo: false, + parse_wasm_debuginfo: true, interruptable: false, } } diff --git a/crates/jit/Cargo.toml b/crates/jit/Cargo.toml index 5af2425c2d..4f4ceba8e9 100644 --- a/crates/jit/Cargo.toml +++ b/crates/jit/Cargo.toml @@ -36,6 +36,7 @@ log = "0.4" gimli = { version = "0.23.0", default-features = false, features = ["write"] } object = { version = "0.22.0", default-features = false, features = ["write"] } serde = { version = "1.0.94", features = ["derive"] } +addr2line = { version = "0.14", default-features = false } [target.'cfg(target_os = "windows")'.dependencies] winapi = { version = "0.3.8", features = ["winnt", "impl-default"] } diff --git a/crates/jit/src/compiler.rs b/crates/jit/src/compiler.rs index 48fcb2c688..a9a2587c84 100644 --- a/crates/jit/src/compiler.rs +++ b/crates/jit/src/compiler.rs @@ -139,7 +139,7 @@ impl Compiler { .into_iter() .collect::(); - let dwarf_sections = if self.tunables.debug_info && !funcs.is_empty() { + let dwarf_sections = if self.tunables.generate_native_debuginfo && !funcs.is_empty() { transform_dwarf_data( &*self.isa, &translation.module, diff --git a/crates/jit/src/instantiate.rs b/crates/jit/src/instantiate.rs index 3ec6f04bf1..4bff020519 100644 --- a/crates/jit/src/instantiate.rs +++ b/crates/jit/src/instantiate.rs @@ -12,6 +12,7 @@ use object::File as ObjectFile; use rayon::prelude::*; use serde::{Deserialize, Serialize}; use std::any::Any; +use std::ops::Range; use std::sync::Arc; use thiserror::Error; use wasmtime_debug::create_gdbjit_image; @@ -19,8 +20,8 @@ use wasmtime_environ::entity::PrimaryMap; use wasmtime_environ::isa::TargetIsa; use wasmtime_environ::wasm::{DefinedFuncIndex, ModuleIndex, SignatureIndex}; use wasmtime_environ::{ - CompileError, DataInitializer, DataInitializerLocation, FunctionAddressMap, Module, - ModuleEnvironment, ModuleTranslation, StackMapInformation, TrapInformation, + CompileError, DataInitializer, DataInitializerLocation, DebugInfoData, FunctionAddressMap, + Module, ModuleEnvironment, ModuleTranslation, StackMapInformation, TrapInformation, }; use wasmtime_profiling::ProfilingAgent; use wasmtime_runtime::{ @@ -69,12 +70,35 @@ pub struct CompilationArtifacts { /// Descriptions of compiled functions funcs: PrimaryMap, - /// Debug info presence flags. - debug_info: bool, - /// Where to find this module's submodule code in the top-level list of /// modules. submodules: PrimaryMap, + + /// Whether or not native debug information is available in `obj` + native_debug_info_present: bool, + + /// Whether or not the original wasm module contained debug information that + /// we skipped and did not parse. + has_unparsed_debuginfo: bool, + + /// Debug information found in the wasm file, used for symbolicating + /// backtraces. + debug_info: Option, +} + +#[derive(Serialize, Deserialize)] +struct DebugInfo { + data: Box<[u8]>, + code_section_offset: u64, + debug_abbrev: Range, + debug_addr: Range, + debug_info: Range, + debug_line: Range, + debug_line_str: Range, + debug_ranges: Range, + debug_rnglists: Range, + debug_str: Range, + debug_str_offsets: Range, } impl CompilationArtifacts { @@ -103,6 +127,8 @@ impl CompilationArtifacts { module, data_initializers, submodules, + debuginfo, + has_unparsed_debuginfo, .. } = translation; @@ -132,7 +158,13 @@ impl CompilationArtifacts { address_map: func.address_map, }) .collect(), - debug_info: compiler.tunables().debug_info, + native_debug_info_present: compiler.tunables().generate_native_debuginfo, + debug_info: if compiler.tunables().parse_wasm_debuginfo { + Some(debuginfo.into()) + } else { + None + }, + has_unparsed_debuginfo, }) }) .collect::, SetupError>>() @@ -202,7 +234,7 @@ impl CompiledModule { })?; // Register GDB JIT images; initialize profiler and load the wasm module. - let dbg_jit_registration = if artifacts.debug_info { + let dbg_jit_registration = if artifacts.native_debug_info_present { let bytes = create_dbg_image( artifacts.obj.to_vec(), code_range, @@ -348,6 +380,85 @@ impl CompiledModule { pub fn submodule_idx(&self, idx: ModuleIndex) -> usize { self.artifacts.submodules[idx] } + + /// Creates a new symbolication context which can be used to further + /// symbolicate stack traces. + /// + /// Basically this makes a thing which parses debuginfo and can tell you + /// what filename and line number a wasm pc comes from. + pub fn symbolize_context(&self) -> Result, gimli::Error> { + use gimli::EndianSlice; + let info = match &self.artifacts.debug_info { + Some(info) => info, + None => return Ok(None), + }; + // For now we clone the data into the `SymbolizeContext`, but if this + // becomes prohibitive we could always `Arc` it with our own allocation + // here. + let data = info.data.clone(); + let endian = gimli::LittleEndian; + let cx = addr2line::Context::from_sections( + EndianSlice::new(&data[info.debug_abbrev.clone()], endian).into(), + EndianSlice::new(&data[info.debug_addr.clone()], endian).into(), + EndianSlice::new(&data[info.debug_info.clone()], endian).into(), + EndianSlice::new(&data[info.debug_line.clone()], endian).into(), + EndianSlice::new(&data[info.debug_line_str.clone()], endian).into(), + EndianSlice::new(&data[info.debug_ranges.clone()], endian).into(), + EndianSlice::new(&data[info.debug_rnglists.clone()], endian).into(), + EndianSlice::new(&data[info.debug_str.clone()], endian).into(), + EndianSlice::new(&data[info.debug_str_offsets.clone()], endian).into(), + EndianSlice::new(&[], endian), + )?; + Ok(Some(SymbolizeContext { + // See comments on `SymbolizeContext` for why we do this static + // lifetime promotion. + inner: unsafe { + std::mem::transmute::, Addr2LineContext<'static>>(cx) + }, + code_section_offset: info.code_section_offset, + _data: data, + })) + } + + /// Returns whether the original wasm module had unparsed debug information + /// based on the tunables configuration. + pub fn has_unparsed_debuginfo(&self) -> bool { + self.artifacts.has_unparsed_debuginfo + } +} + +type Addr2LineContext<'a> = addr2line::Context>; + +/// A context which contains dwarf debug information to translate program +/// counters back to filenames and line numbers. +pub struct SymbolizeContext { + // Note the `'static` lifetime on `inner`. That's actually a bunch of slices + // which point back into the `_data` field. We currently unsafely manage + // this by saying that when inside the struct it's `'static` (since we own + // the referenced data just next to it) and we only loan out borrowed + // references. + _data: Box<[u8]>, + inner: Addr2LineContext<'static>, + code_section_offset: u64, +} + +impl SymbolizeContext { + /// Returns access to the [`addr2line::Context`] which can be used to query + /// frame information with. + pub fn addr2line(&self) -> &Addr2LineContext<'_> { + // Here we demote our synthetic `'static` lifetime which doesn't + // actually exist back to a lifetime that's tied to `&self`, which + // should be safe. + unsafe { + std::mem::transmute::<&Addr2LineContext<'static>, &Addr2LineContext<'_>>(&self.inner) + } + } + + /// Returns the offset of the code section in the original wasm file, used + /// to calculate lookup values into the DWARF. + pub fn code_section_offset(&self) -> u64 { + self.code_section_offset + } } /// Similar to `DataInitializer`, but owns its own copy of the data rather @@ -432,3 +543,37 @@ fn build_code_memory( Ok((code_memory, code_range, finished_functions, trampolines)) } + +impl From> for DebugInfo { + fn from(raw: DebugInfoData<'_>) -> DebugInfo { + use gimli::Section; + + let mut data = Vec::new(); + let mut push = |section: &[u8]| { + data.extend_from_slice(section); + data.len() - section.len()..data.len() + }; + let debug_abbrev = push(raw.dwarf.debug_abbrev.reader().slice()); + let debug_addr = push(raw.dwarf.debug_addr.reader().slice()); + let debug_info = push(raw.dwarf.debug_info.reader().slice()); + let debug_line = push(raw.dwarf.debug_line.reader().slice()); + let debug_line_str = push(raw.dwarf.debug_line_str.reader().slice()); + let debug_ranges = push(raw.debug_ranges.reader().slice()); + let debug_rnglists = push(raw.debug_rnglists.reader().slice()); + let debug_str = push(raw.dwarf.debug_str.reader().slice()); + let debug_str_offsets = push(raw.dwarf.debug_str_offsets.reader().slice()); + DebugInfo { + data: data.into(), + debug_abbrev, + debug_addr, + debug_info, + debug_line, + debug_line_str, + debug_ranges, + debug_rnglists, + debug_str, + debug_str_offsets, + code_section_offset: raw.wasm_file.code_section_offset, + } + } +} diff --git a/crates/jit/src/lib.rs b/crates/jit/src/lib.rs index 94f268de82..1421ed0544 100644 --- a/crates/jit/src/lib.rs +++ b/crates/jit/src/lib.rs @@ -46,7 +46,9 @@ pub mod trampoline; pub use crate::code_memory::CodeMemory; pub use crate::compiler::{Compilation, CompilationStrategy, Compiler}; -pub use crate::instantiate::{CompilationArtifacts, CompiledModule, ModuleCode, SetupError}; +pub use crate::instantiate::{ + CompilationArtifacts, CompiledModule, ModuleCode, SetupError, SymbolizeContext, +}; pub use crate::link::link_module; /// Version number of this crate. diff --git a/crates/lightbeam/wasmtime/src/lib.rs b/crates/lightbeam/wasmtime/src/lib.rs index ed09e04550..e38e48f20d 100644 --- a/crates/lightbeam/wasmtime/src/lib.rs +++ b/crates/lightbeam/wasmtime/src/lib.rs @@ -29,7 +29,7 @@ impl Compiler for Lightbeam { isa: &dyn isa::TargetIsa, tunables: &Tunables, ) -> Result { - if tunables.debug_info { + if tunables.generate_native_debuginfo { return Err(CompileError::DebugInfoNotSupported); } let func_index = translation.module.func_index(i); diff --git a/crates/wasmtime/Cargo.toml b/crates/wasmtime/Cargo.toml index e0c0d3302c..28de26001e 100644 --- a/crates/wasmtime/Cargo.toml +++ b/crates/wasmtime/Cargo.toml @@ -23,6 +23,7 @@ libc = "0.2" cfg-if = "1.0" backtrace = "0.3.42" rustc-demangle = "0.1.16" +cpp_demangle = "0.3.2" log = "0.4.8" wat = { version = "1.0.18", optional = true } smallvec = "1.4.0" diff --git a/crates/wasmtime/src/config.rs b/crates/wasmtime/src/config.rs index 0cb776ffdc..5a0686de91 100644 --- a/crates/wasmtime/src/config.rs +++ b/crates/wasmtime/src/config.rs @@ -32,6 +32,7 @@ pub struct Config { pub(crate) memory_creator: Option, pub(crate) max_wasm_stack: usize, pub(crate) features: WasmFeatures, + pub(crate) wasm_backtrace_details_env_used: bool, } impl Config { @@ -61,7 +62,7 @@ impl Config { .set("enable_probestack", "false") .expect("should be valid flag"); - Config { + let mut ret = Config { tunables: Tunables::default(), flags, isa_flags: native::builder(), @@ -71,13 +72,16 @@ impl Config { profiler: Arc::new(NullProfilerAgent), memory_creator: None, max_wasm_stack: 1 << 20, + wasm_backtrace_details_env_used: false, features: WasmFeatures { reference_types: true, bulk_memory: true, multi_value: true, ..WasmFeatures::default() }, - } + }; + ret.wasm_backtrace_details(WasmBacktraceDetails::Environment); + return ret; } /// Configures whether DWARF debug information will be emitted during @@ -85,7 +89,33 @@ impl Config { /// /// By default this option is `false`. pub fn debug_info(&mut self, enable: bool) -> &mut Self { - self.tunables.debug_info = enable; + self.tunables.generate_native_debuginfo = enable; + self + } + + /// Configures backtraces in `Trap` will parse debuginfo in the wasm file to + /// have filename/line number information. + /// + /// When enabled this will causes modules to retain debugging information + /// found in wasm binaries. This debug information will be used when a trap + /// happens to symbolicate each stack frame and attempt to print a + /// filename/line number for each wasm frame in the stack trace. + /// + /// By default this option is `WasmBacktraceDetails::Environment`, meaning + /// that wasm will read `WASMTIME_BACKTRACE_DETAILS` to indicate whether details + /// should be parsed. + pub fn wasm_backtrace_details(&mut self, enable: WasmBacktraceDetails) -> &mut Self { + self.wasm_backtrace_details_env_used = false; + self.tunables.parse_wasm_debuginfo = match enable { + WasmBacktraceDetails::Enable => true, + WasmBacktraceDetails::Disable => false, + WasmBacktraceDetails::Environment => { + self.wasm_backtrace_details_env_used = true; + std::env::var("WASMTIME_BACKTRACE_DETAILS") + .map(|s| s == "1") + .unwrap_or(false) + } + }; self } @@ -640,7 +670,8 @@ impl Default for Config { impl fmt::Debug for Config { fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { f.debug_struct("Config") - .field("debug_info", &self.tunables.debug_info) + .field("debug_info", &self.tunables.generate_native_debuginfo) + .field("parse_wasm_debuginfo", &self.tunables.parse_wasm_debuginfo) .field("strategy", &self.strategy) .field("wasm_threads", &self.features.threads) .field("wasm_reference_types", &self.features.reference_types) @@ -712,3 +743,19 @@ pub enum ProfilingStrategy { /// Collect profiling info using the "ittapi", used with `VTune` on Linux. VTune, } + +/// Select how wasm backtrace detailed information is handled. +#[derive(Debug, Clone, Copy)] +pub enum WasmBacktraceDetails { + /// Support is unconditionally enabled and wasmtime will parse and read + /// debug information. + Enable, + + /// Support is disabled, and wasmtime will not parse debug information for + /// backtrace details. + Disable, + + /// Support for backtrace details is conditional on the + /// `WASMTIME_BACKTRACE_DETAILS` environment variable. + Environment, +} diff --git a/crates/wasmtime/src/frame_info.rs b/crates/wasmtime/src/frame_info.rs index 6a64ec78ec..fbea477d28 100644 --- a/crates/wasmtime/src/frame_info.rs +++ b/crates/wasmtime/src/frame_info.rs @@ -5,7 +5,7 @@ use wasmtime_environ::entity::EntityRef; use wasmtime_environ::ir; use wasmtime_environ::wasm::FuncIndex; use wasmtime_environ::{FunctionAddressMap, Module, TrapInformation}; -use wasmtime_jit::CompiledModule; +use wasmtime_jit::{CompiledModule, SymbolizeContext}; #[derive(Default)] pub struct StoreFrameInfo { @@ -25,6 +25,8 @@ struct ModuleFrameInfo { start: usize, functions: BTreeMap, module: Arc, + symbolize: Option, + has_unparsed_debuginfo: bool, } struct FunctionInfo { @@ -38,8 +40,10 @@ impl StoreFrameInfo { /// Fetches frame information about a program counter in a backtrace. /// /// Returns an object if this `pc` is known to some previously registered - /// module, or returns `None` if no information can be found. - pub fn lookup_frame_info(&self, pc: usize) -> Option { + /// module, or returns `None` if no information can be found. The boolean + /// returned indicates whether the original module has unparsed debug + /// information due to the compiler's configuration. + pub fn lookup_frame_info(&self, pc: usize) -> Option<(FrameInfo, bool)> { let (module, func) = self.func(pc)?; // Use our relative position from the start of the function to find the @@ -72,13 +76,49 @@ impl StoreFrameInfo { Some(pos) => func.instr_map.instructions[pos].srcloc, None => func.instr_map.start_srcloc, }; - Some(FrameInfo { - module_name: module.module.name.clone(), - func_index: func.index.index() as u32, - func_name: module.module.func_names.get(&func.index).cloned(), - instr, - func_start: func.instr_map.start_srcloc, - }) + + // Use our wasm-relative pc to symbolize this frame. If there's a + // symbolication context (dwarf debug info) available then we can try to + // look this up there. + // + // Note that dwarf pcs are code-section-relative, hence the subtraction + // from the location of `instr`. Also note that all errors are ignored + // here for now since technically wasm modules can always have any + // custom section contents. + let mut symbols = Vec::new(); + if let Some(s) = &module.symbolize { + let to_lookup = (instr.bits() as u64) - s.code_section_offset(); + if let Ok(mut frames) = s.addr2line().find_frames(to_lookup) { + while let Ok(Some(frame)) = frames.next() { + symbols.push(FrameSymbol { + name: frame + .function + .as_ref() + .and_then(|l| l.raw_name().ok()) + .map(|s| s.to_string()), + file: frame + .location + .as_ref() + .and_then(|l| l.file) + .map(|s| s.to_string()), + line: frame.location.as_ref().and_then(|l| l.line), + column: frame.location.as_ref().and_then(|l| l.column), + }); + } + } + } + + Some(( + FrameInfo { + module_name: module.module.name.clone(), + func_index: func.index.index() as u32, + func_name: module.module.func_names.get(&func.index).cloned(), + instr, + func_start: func.instr_map.start_srcloc, + symbols, + }, + module.has_unparsed_debuginfo, + )) } /// Returns whether the `pc` specified is contaained within some module's @@ -160,6 +200,8 @@ impl StoreFrameInfo { start: min, functions, module: module.module().clone(), + symbolize: module.symbolize_context().ok().and_then(|c| c), + has_unparsed_debuginfo: module.has_unparsed_debuginfo(), }, ); assert!(prev.is_none()); @@ -180,6 +222,20 @@ pub struct FrameInfo { func_name: Option, func_start: ir::SourceLoc, instr: ir::SourceLoc, + symbols: Vec, +} + +/// Debug information for a symbol that is attached to a [`FrameInfo`]. +/// +/// When DWARF debug information is present in a wasm file then this structure +/// can be found on a [`FrameInfo`] and can be used to learn about filenames, +/// line numbers, etc, which are the origin of a function in a stack trace. +#[derive(Debug)] +pub struct FrameSymbol { + name: Option, + file: Option, + line: Option, + column: Option, } impl FrameInfo { @@ -240,6 +296,55 @@ impl FrameInfo { pub fn func_offset(&self) -> usize { (self.instr.bits() - self.func_start.bits()) as usize } + + /// Returns the debug symbols found, if any, for this function frame. + /// + /// When a wasm program is compiled with DWARF debug information then this + /// function may be populated to return symbols which contain extra debug + /// information about a frame including the filename and line number. If no + /// debug information was found or if it was malformed then this will return + /// an empty array. + pub fn symbols(&self) -> &[FrameSymbol] { + &self.symbols + } +} + +impl FrameSymbol { + /// Returns the function name associated with this symbol. + /// + /// Note that this may not be present with malformed debug information, or + /// the debug information may not include it. Also note that the symbol is + /// frequently mangled, so you might need to run some form of demangling + /// over it. + pub fn name(&self) -> Option<&str> { + self.name.as_deref() + } + + /// Returns the source code filename this symbol was defined in. + /// + /// Note that this may not be present with malformed debug information, or + /// the debug information may not include it. + pub fn file(&self) -> Option<&str> { + self.file.as_deref() + } + + /// Returns the 1-indexed source code line number this symbol was defined + /// on. + /// + /// Note that this may not be present with malformed debug information, or + /// the debug information may not include it. + pub fn line(&self) -> Option { + self.line + } + + /// Returns the 1-indexed source code column number this symbol was defined + /// on. + /// + /// Note that this may not be present with malformed debug information, or + /// the debug information may not include it. + pub fn column(&self) -> Option { + self.column + } } #[test] @@ -270,7 +375,7 @@ fn test_frame_info() -> Result<(), anyhow::Error> { (ptr as usize, ptr as usize + len) }; for pc in start..end { - let frame = info.lookup_frame_info(pc).unwrap(); + let (frame, _) = info.lookup_frame_info(pc).unwrap(); assert!(frame.func_index() == i.as_u32()); } } diff --git a/crates/wasmtime/src/lib.rs b/crates/wasmtime/src/lib.rs index cf2d69e01b..2248eec5a7 100644 --- a/crates/wasmtime/src/lib.rs +++ b/crates/wasmtime/src/lib.rs @@ -253,7 +253,7 @@ mod values; pub use crate::config::*; pub use crate::engine::*; pub use crate::externals::*; -pub use crate::frame_info::FrameInfo; +pub use crate::frame_info::{FrameInfo, FrameSymbol}; pub use crate::func::*; pub use crate::instance::Instance; pub use crate::linker::*; diff --git a/crates/wasmtime/src/trap.rs b/crates/wasmtime/src/trap.rs index 4e5f2b4de4..acbca71dbe 100644 --- a/crates/wasmtime/src/trap.rs +++ b/crates/wasmtime/src/trap.rs @@ -122,6 +122,7 @@ struct TrapInner { reason: TrapReason, wasm_trace: Vec, native_trace: Backtrace, + hint_wasm_backtrace_details_env: bool, } fn _assert_trap_is_sync_and_send(t: &Trap) -> (&dyn Sync, &dyn Send) { @@ -214,6 +215,7 @@ impl Trap { native_trace: Backtrace, ) -> Self { let mut wasm_trace = Vec::new(); + let mut hint_wasm_backtrace_details_env = false; wasmtime_runtime::with_last_info(|last| { // If the `store` passed in is `None` then we look at the `last` // store configured to call wasm, and if that's a `Store` we use @@ -236,9 +238,22 @@ impl Trap { // want to lookup information for the previous instruction // (the call instruction) so we subtract one as the lookup. let pc_to_lookup = if Some(pc) == trap_pc { pc } else { pc - 1 }; - if let Some(info) = store.frame_info().borrow().lookup_frame_info(pc_to_lookup) + if let Some((info, has_unparsed_debuginfo)) = + store.frame_info().borrow().lookup_frame_info(pc_to_lookup) { wasm_trace.push(info); + + // If this frame has unparsed debug information and the + // store's configuration indicates that we were + // respecting the environment variable of whether to + // do this then we will print out a helpful note in + // `Display` to indicate that more detailed information + // in a trap may be available. + if has_unparsed_debuginfo + && store.engine().config().wasm_backtrace_details_env_used + { + hint_wasm_backtrace_details_env = true; + } } } } @@ -248,6 +263,7 @@ impl Trap { reason, wasm_trace, native_trace, + hint_wasm_backtrace_details_env, }), } } @@ -297,15 +313,52 @@ impl fmt::Display for Trap { writeln!(f, "\nwasm backtrace:")?; for (i, frame) in self.trace().iter().enumerate() { let name = frame.module_name().unwrap_or(""); - write!(f, " {}: {:#6x} - {}!", i, frame.module_offset(), name)?; - match frame.func_name() { - Some(name) => match rustc_demangle::try_demangle(name) { - Ok(name) => write!(f, "{}", name)?, - Err(_) => write!(f, "{}", name)?, - }, - None => write!(f, "", frame.func_index())?, + write!(f, " {:>3}: {:#6x} - ", i, frame.module_offset())?; + + let demangle = + |f: &mut fmt::Formatter<'_>, name: &str| match rustc_demangle::try_demangle(name) { + Ok(name) => write!(f, "{}", name), + Err(_) => match cpp_demangle::Symbol::new(name) { + Ok(name) => write!(f, "{}", name), + Err(_) => write!(f, "{}", name), + }, + }; + let write_raw_func_name = |f: &mut fmt::Formatter<'_>| match frame.func_name() { + Some(name) => demangle(f, name), + None => write!(f, "", frame.func_index()), + }; + if frame.symbols().is_empty() { + write!(f, "{}!", name)?; + write_raw_func_name(f)?; + writeln!(f, "")?; + } else { + for (i, symbol) in frame.symbols().iter().enumerate() { + if i > 0 { + write!(f, " - ")?; + } else { + // ... + } + match symbol.name() { + Some(name) => demangle(f, name)?, + None if i == 0 => write_raw_func_name(f)?, + None => write!(f, "")?, + } + writeln!(f, "")?; + if let Some(file) = symbol.file() { + write!(f, " at {}", file)?; + if let Some(line) = symbol.line() { + write!(f, ":{}", line)?; + if let Some(col) = symbol.column() { + write!(f, ":{}", col)?; + } + } + } + writeln!(f, "")?; + } } - writeln!(f, "")?; + } + if self.inner.hint_wasm_backtrace_details_env { + writeln!(f, "note: run with `WASMTIME_BACKTRACE_DETAILS=1` environment variable to display more information")?; } Ok(()) } diff --git a/src/obj.rs b/src/obj.rs index 8e3ebc6b61..a14f79a8f8 100644 --- a/src/obj.rs +++ b/src/obj.rs @@ -46,7 +46,8 @@ pub fn compile_to_obj( // TODO: Expose the tunables as command-line flags. let mut tunables = Tunables::default(); - tunables.debug_info = debug_info; + tunables.generate_native_debuginfo = debug_info; + tunables.parse_wasm_debuginfo = debug_info; let compiler = Compiler::new( isa, diff --git a/tests/all/traps.rs b/tests/all/traps.rs index cd9b4b38d7..3f91229e6b 100644 --- a/tests/all/traps.rs +++ b/tests/all/traps.rs @@ -1,5 +1,6 @@ use anyhow::Result; use std::panic::{self, AssertUnwindSafe}; +use std::process::Command; use wasmtime::*; #[test] @@ -167,10 +168,10 @@ fn trap_display_pretty() -> Result<()> { "\ wasm trap: unreachable wasm backtrace: - 0: 0x23 - m!die - 1: 0x27 - m! - 2: 0x2c - m!foo - 3: 0x31 - m! + 0: 0x23 - m!die + 1: 0x27 - m! + 2: 0x2c - m!foo + 3: 0x31 - m! " ); Ok(()) @@ -211,12 +212,12 @@ fn trap_display_multi_module() -> Result<()> { "\ wasm trap: unreachable wasm backtrace: - 0: 0x23 - a!die - 1: 0x27 - a! - 2: 0x2c - a!foo - 3: 0x31 - a! - 4: 0x29 - b!middle - 5: 0x2e - b! + 0: 0x23 - a!die + 1: 0x27 - a! + 2: 0x2c - a!foo + 3: 0x31 - a! + 4: 0x29 - b!middle + 5: 0x2e - b! " ); Ok(()) @@ -422,10 +423,10 @@ fn start_trap_pretty() -> Result<()> { "\ wasm trap: unreachable wasm backtrace: - 0: 0x1d - m!die - 1: 0x21 - m! - 2: 0x26 - m!foo - 3: 0x2b - m!start + 0: 0x1d - m!die + 1: 0x21 - m! + 2: 0x26 - m!foo + 3: 0x2b - m!start " ); Ok(()) @@ -489,3 +490,131 @@ fn heap_out_of_bounds_trap() { TrapCode::MemoryOutOfBounds, ); } + +fn rustc(src: &str) -> Vec { + let td = tempfile::TempDir::new().unwrap(); + let output = td.path().join("foo.wasm"); + let input = td.path().join("input.rs"); + std::fs::write(&input, src).unwrap(); + let result = Command::new("rustc") + .arg(&input) + .arg("-o") + .arg(&output) + .arg("--target") + .arg("wasm32-wasi") + .arg("-g") + .output() + .unwrap(); + if result.status.success() { + return std::fs::read(&output).unwrap(); + } + panic!( + "rustc failed: {}\n{}", + result.status, + String::from_utf8_lossy(&result.stderr) + ); +} + +#[test] +fn parse_dwarf_info() -> Result<()> { + let wasm = rustc( + " + fn main() { + panic!(); + } + ", + ); + let mut config = Config::new(); + config.wasm_backtrace_details(WasmBacktraceDetails::Enable); + let engine = Engine::new(&config); + let store = Store::new(&engine); + let module = Module::new(&engine, &wasm)?; + let mut linker = Linker::new(&store); + wasmtime_wasi::Wasi::new(&store, wasmtime_wasi::WasiCtxBuilder::new().build()?) + .add_to_linker(&mut linker)?; + linker.module("", &module)?; + let run = linker.get_default("")?; + let trap = run.call(&[]).unwrap_err().downcast::()?; + + let mut found = false; + for frame in trap.trace() { + for symbol in frame.symbols() { + if let Some(file) = symbol.file() { + if file.ends_with("input.rs") { + found = true; + assert!(symbol.name().unwrap().contains("main")); + assert_eq!(symbol.line(), Some(3)); + } + } + } + } + assert!(found); + Ok(()) +} + +#[test] +fn no_hint_even_with_dwarf_info() -> Result<()> { + let mut config = Config::new(); + config.wasm_backtrace_details(WasmBacktraceDetails::Disable); + let engine = Engine::new(&config); + let store = Store::new(&engine); + let module = Module::new( + &engine, + r#" + (module + (@custom ".debug_info" (after last) "") + (func $start + unreachable) + (start $start) + ) + "#, + )?; + let trap = Instance::new(&store, &module, &[]) + .err() + .unwrap() + .downcast::()?; + assert_eq!( + trap.to_string(), + "\ +wasm trap: unreachable +wasm backtrace: + 0: 0x1a - !start +" + ); + Ok(()) +} + +#[test] +fn hint_with_dwarf_info() -> Result<()> { + // Skip this test if the env var is already configure, but in CI we're sure + // to run tests without this env var configured. + if std::env::var("WASMTIME_BACKTRACE_DETAILS").is_ok() { + return Ok(()); + } + let store = Store::default(); + let module = Module::new( + store.engine(), + r#" + (module + (@custom ".debug_info" (after last) "") + (func $start + unreachable) + (start $start) + ) + "#, + )?; + let trap = Instance::new(&store, &module, &[]) + .err() + .unwrap() + .downcast::()?; + assert_eq!( + trap.to_string(), + "\ +wasm trap: unreachable +wasm backtrace: + 0: 0x1a - !start +note: run with `WASMTIME_BACKTRACE_DETAILS=1` environment variable to display more information +" + ); + Ok(()) +}