Add a new host function for reporting fatal errors; make WASM backtraces readable when printing out errors (#10741)

* Add a new host function for reporting fatal errors

* Fix one of the wasmtime executor tests

* Have `#[runtime_interface(wasm_only)]` actually mean WASM-only, and not no_std-only

* Print out errors through `Display` instead of `Debug`

* Switch one more trait to require `Error` for its error instead of only `Debug`

* Align to review comments

substrate/client/executor/common/src/error.rs

@@ -31,9 +31,6 @@ pub enum Error {
 	#[error("Unserializable data encountered")]
 	InvalidData(#[from] sp_serializer::Error),
 
-	#[error(transparent)]
-	Trap(#[from] wasmi::Trap),
-
 	#[error(transparent)]
 	Wasmi(#[from] wasmi::Error),
 
@@ -108,6 +105,12 @@ pub enum Error {
 
 	#[error("Invalid initializer expression provided {0}")]
 	InvalidInitializerExpression(String),
+
+	#[error("Execution aborted due to panic: {0}")]
+	AbortedDueToPanic(MessageWithBacktrace),
+
+	#[error("Execution aborted due to trap: {0}")]
+	AbortedDueToTrap(MessageWithBacktrace),
 }
 
 impl wasmi::HostError for Error {}
@@ -160,3 +163,38 @@ pub enum WasmError {
 	#[error("{0}")]
 	Other(String),
 }
+
+/// An error message with an attached backtrace.
+#[derive(Debug)]
+pub struct MessageWithBacktrace {
+	/// The error message.
+	pub message: String,
+
+	/// The backtrace associated with the error message.
+	pub backtrace: Option<Backtrace>,
+}
+
+impl std::fmt::Display for MessageWithBacktrace {
+	fn fmt(&self, fmt: &mut std::fmt::Formatter) -> std::fmt::Result {
+		fmt.write_str(&self.message)?;
+		if let Some(ref backtrace) = self.backtrace {
+			fmt.write_str("\nWASM backtrace:\n")?;
+			backtrace.backtrace_string.fmt(fmt)?;
+		}
+
+		Ok(())
+	}
+}
+
+/// A WASM backtrace.
+#[derive(Debug)]
+pub struct Backtrace {
+	/// The string containing the backtrace.
+	pub backtrace_string: String,
+}
+
+impl std::fmt::Display for Backtrace {
+	fn fmt(&self, fmt: &mut std::fmt::Formatter) -> std::fmt::Result {
+		fmt.write_str(&self.backtrace_string)
+	}
+}

substrate/client/executor/runtime-test/Cargo.toml

@@ -14,7 +14,7 @@ targets = ["x86_64-unknown-linux-gnu"]
 
 [dependencies]
 sp-core = { version = "5.0.0", default-features = false, path = "../../../primitives/core" }
-sp-io = { version = "5.0.0", default-features = false, path = "../../../primitives/io" }
+sp-io = { version = "5.0.0", default-features = false, path = "../../../primitives/io", features = ["improved_panic_error_reporting"] }
 sp-runtime = { version = "5.0.0", default-features = false, path = "../../../primitives/runtime" }
 sp-sandbox = { version = "0.10.0-dev", default-features = false, path = "../../../primitives/sandbox" }
 sp-std = { version = "4.0.0", default-features = false, path = "../../../primitives/std" }

substrate/client/executor/runtime-test/src/lib.rs

@@ -341,6 +341,14 @@ sp_core::wasm_export_functions! {
 	fn test_take_i8(value: i8) {
 		assert_eq!(value, -66);
 	}
+
+	fn test_abort_on_panic() {
+		sp_io::panic_handler::abort_on_panic("test_abort_on_panic called");
+	}
+
+	fn test_unreachable_intrinsic() {
+		core::arch::wasm32::unreachable()
+	}
 }
 
 #[cfg(not(feature = "std"))]

substrate/client/executor/src/integration_tests/mod.rs

@@ -22,7 +22,7 @@ mod sandbox;
 
 use codec::{Decode, Encode};
 use hex_literal::hex;
-use sc_executor_common::{runtime_blob::RuntimeBlob, wasm_runtime::WasmModule};
+use sc_executor_common::{error::Error, runtime_blob::RuntimeBlob, wasm_runtime::WasmModule};
 use sc_runtime_test::wasm_binary_unwrap;
 use sp_core::{
 	blake2_128, blake2_256, ed25519, map,
@@ -122,7 +122,7 @@ fn call_in_wasm<E: Externalities>(
 	call_data: &[u8],
 	execution_method: WasmExecutionMethod,
 	ext: &mut E,
-) -> Result<Vec<u8>, String> {
+) -> Result<Vec<u8>, Error> {
 	let executor =
 		crate::WasmExecutor::<HostFunctions>::new(execution_method, Some(1024), 8, None, 2);
 	executor.uncached_call(
@@ -148,25 +148,16 @@ fn call_not_existing_function(wasm_method: WasmExecutionMethod) {
 	let mut ext = TestExternalities::default();
 	let mut ext = ext.ext();
 
-	match call_in_wasm(
-		"test_calling_missing_external",
-		&[],
-		wasm_method,
-		&mut ext,
-	) {
-		Ok(_) => panic!("was expected an `Err`"),
-		Err(e) => {
-			match wasm_method {
-				WasmExecutionMethod::Interpreted => assert_eq!(
-					&format!("{:?}", e),
-					"\"Trap: Trap { kind: Host(Other(\\\"Function `missing_external` is only a stub. Calling a stub is not allowed.\\\")) }\""
-				),
+	match call_in_wasm("test_calling_missing_external", &[], wasm_method, &mut ext).unwrap_err() {
+		Error::AbortedDueToTrap(error) => {
+			let expected = match wasm_method {
+				WasmExecutionMethod::Interpreted => "Trap: Host(Other(\"Function `missing_external` is only a stub. Calling a stub is not allowed.\"))",
 				#[cfg(feature = "wasmtime")]
-				WasmExecutionMethod::Compiled => assert!(
-					format!("{:?}", e).contains("Wasm execution trapped: call to a missing function env:missing_external")
-				),
-			}
-		}
+				WasmExecutionMethod::Compiled => "call to a missing function env:missing_external"
+			};
+			assert_eq!(error.message, expected);
+		},
+		error => panic!("unexpected error: {:?}", error),
 	}
 }
 
@@ -175,25 +166,18 @@ fn call_yet_another_not_existing_function(wasm_method: WasmExecutionMethod) {
 	let mut ext = TestExternalities::default();
 	let mut ext = ext.ext();
 
-	match call_in_wasm(
-		"test_calling_yet_another_missing_external",
-		&[],
-		wasm_method,
-		&mut ext,
-	) {
-		Ok(_) => panic!("was expected an `Err`"),
-		Err(e) => {
-			match wasm_method {
-				WasmExecutionMethod::Interpreted => assert_eq!(
-					&format!("{:?}", e),
-					"\"Trap: Trap { kind: Host(Other(\\\"Function `yet_another_missing_external` is only a stub. Calling a stub is not allowed.\\\")) }\""
-				),
+	match call_in_wasm("test_calling_yet_another_missing_external", &[], wasm_method, &mut ext)
+		.unwrap_err()
+	{
+		Error::AbortedDueToTrap(error) => {
+			let expected = match wasm_method {
+				WasmExecutionMethod::Interpreted => "Trap: Host(Other(\"Function `yet_another_missing_external` is only a stub. Calling a stub is not allowed.\"))",
 				#[cfg(feature = "wasmtime")]
-				WasmExecutionMethod::Compiled => assert!(
-					format!("{:?}", e).contains("Wasm execution trapped: call to a missing function env:yet_another_missing_external")
-				),
-			}
-		}
+				WasmExecutionMethod::Compiled => "call to a missing function env:yet_another_missing_external"
+			};
+			assert_eq!(error.message, expected);
+		},
+		error => panic!("unexpected error: {:?}", error),
 	}
 }
 
@@ -485,6 +469,7 @@ fn should_trap_when_heap_exhausted(wasm_method: WasmExecutionMethod) {
 			"test_exhaust_heap",
 			&[0],
 		)
+		.map_err(|e| e.to_string())
 		.unwrap_err();
 
 	assert!(err.contains("Allocator ran out of space"));
@@ -691,7 +676,7 @@ fn panic_in_spawned_instance_panics_on_joining_its_result(wasm_method: WasmExecu
 	let error_result =
 		call_in_wasm("test_panic_in_spawned", &[], wasm_method, &mut ext).unwrap_err();
 
-	assert!(error_result.contains("Spawned task"));
+	assert!(error_result.to_string().contains("Spawned task"));
 }
 
 test_wasm_execution!(memory_is_cleared_between_invocations);
@@ -789,3 +774,32 @@ fn take_i8(wasm_method: WasmExecutionMethod) {
 
 	call_in_wasm("test_take_i8", &(-66_i8).encode(), wasm_method, &mut ext).unwrap();
 }
+
+test_wasm_execution!(abort_on_panic);
+fn abort_on_panic(wasm_method: WasmExecutionMethod) {
+	let mut ext = TestExternalities::default();
+	let mut ext = ext.ext();
+
+	match call_in_wasm("test_abort_on_panic", &[], wasm_method, &mut ext).unwrap_err() {
+		Error::AbortedDueToPanic(error) => assert_eq!(error.message, "test_abort_on_panic called"),
+		error => panic!("unexpected error: {:?}", error),
+	}
+}
+
+test_wasm_execution!(unreachable_intrinsic);
+fn unreachable_intrinsic(wasm_method: WasmExecutionMethod) {
+	let mut ext = TestExternalities::default();
+	let mut ext = ext.ext();
+
+	match call_in_wasm("test_unreachable_intrinsic", &[], wasm_method, &mut ext).unwrap_err() {
+		Error::AbortedDueToTrap(error) => {
+			let expected = match wasm_method {
+				WasmExecutionMethod::Interpreted => "Trap: Unreachable",
+				#[cfg(feature = "wasmtime")]
+				WasmExecutionMethod::Compiled => "wasm trap: wasm `unreachable` instruction executed",
+			};
+			assert_eq!(error.message, expected);
+		},
+		error => panic!("unexpected error: {:?}", error),
+	}
+}

substrate/client/executor/src/native_executor.rs

@@ -220,7 +220,7 @@ where
 		allow_missing_host_functions: bool,
 		export_name: &str,
 		call_data: &[u8],
-	) -> std::result::Result<Vec<u8>, String> {
+	) -> std::result::Result<Vec<u8>, Error> {
 		let module = crate::wasm_runtime::create_wasm_runtime_with_code::<H>(
 			self.method,
 			self.default_heap_pages,
@@ -228,11 +228,10 @@ where
 			allow_missing_host_functions,
 			self.cache_path.as_deref(),
 		)
-		.map_err(|e| format!("Failed to create module: {:?}", e))?;
+		.map_err(|e| format!("Failed to create module: {}", e))?;
 
-		let instance = module
-			.new_instance()
-			.map_err(|e| format!("Failed to create instance: {:?}", e))?;
+		let instance =
+			module.new_instance().map_err(|e| format!("Failed to create instance: {}", e))?;
 
 		let mut instance = AssertUnwindSafe(instance);
 		let mut ext = AssertUnwindSafe(ext);
@@ -243,7 +242,6 @@ where
 			instance.call_export(export_name, call_data)
 		})
 		.and_then(|r| r)
-		.map_err(|e| e.to_string())
 	}
 }
 
@@ -281,6 +279,7 @@ where
 			"Core_version",
 			&[],
 		)
+		.map_err(|e| e.to_string())
 	}
 }
 
@@ -456,12 +455,18 @@ impl RuntimeSpawn for RuntimeInstanceSpawn {
 					// pool of instances should be used.
 					//
 					// https://github.com/paritytech/substrate/issues/7354
-					let mut instance =
-						module.new_instance().expect("Failed to create new instance from module");
+					let mut instance = match module.new_instance() {
+						Ok(instance) => instance,
+						Err(error) =>
+							panic!("failed to create new instance from module: {}", error),
+					};
 
-					instance
+					match instance
 						.call(InvokeMethod::TableWithWrapper { dispatcher_ref, func }, &data[..])
-						.expect("Failed to invoke instance.")
+					{
+						Ok(result) => result,
+						Err(error) => panic!("failed to invoke instance: {}", error),
+					}
 				});
 
 				match result {
@@ -471,7 +476,7 @@ impl RuntimeSpawn for RuntimeInstanceSpawn {
 					Err(error) => {
 						// If execution is panicked, the `join` in the original runtime code will
 						// panic as well, since the sender is dropped without sending anything.
-						log::error!("Call error in spawned task: {:?}", error);
+						log::error!("Call error in spawned task: {}", error);
 					},
 				}
 			}),

substrate/client/executor/src/wasm_runtime.rs

@@ -105,13 +105,13 @@ impl VersionedRuntime {
 					if new_inst {
 						log::warn!(
 							target: "wasm-runtime",
-							"Fresh runtime instance failed with {:?}",
+							"Fresh runtime instance failed with {}",
 							e,
 						)
 					} else {
 						log::warn!(
 							target: "wasm-runtime",
-							"Evicting failed runtime instance: {:?}",
+							"Evicting failed runtime instance: {}",
 							e,
 						);
 					}

substrate/client/executor/wasmi/src/lib.rs

@@ -21,7 +21,7 @@
 use codec::{Decode, Encode};
 use log::{debug, error, trace};
 use sc_executor_common::{
-	error::{Error, WasmError},
+	error::{Error, MessageWithBacktrace, WasmError},
 	runtime_blob::{DataSegmentsSnapshot, RuntimeBlob},
 	sandbox,
 	util::MemoryTransfer,
@@ -48,6 +48,7 @@ struct FunctionExecutor {
 	host_functions: Arc<Vec<&'static dyn Function>>,
 	allow_missing_func_imports: bool,
 	missing_functions: Arc<Vec<String>>,
+	panic_message: Option<String>,
 }
 
 impl FunctionExecutor {
@@ -69,6 +70,7 @@ impl FunctionExecutor {
 			host_functions,
 			allow_missing_func_imports,
 			missing_functions,
+			panic_message: None,
 		})
 	}
 }
@@ -100,7 +102,10 @@ impl<'a> sandbox::SandboxContext for SandboxContext<'a> {
 		match result {
 			Ok(Some(RuntimeValue::I64(val))) => Ok(val),
 			Ok(_) => return Err("Supervisor function returned unexpected result!".into()),
-			Err(err) => Err(Error::Trap(err)),
+			Err(err) => Err(Error::AbortedDueToTrap(MessageWithBacktrace {
+				message: err.to_string(),
+				backtrace: None,
+			})),
 		}
 	}
 
@@ -133,6 +138,10 @@ impl FunctionContext for FunctionExecutor {
 	fn sandbox(&mut self) -> &mut dyn Sandbox {
 		self
 	}
+
+	fn register_panic_error_message(&mut self, message: &str) {
+		self.panic_message = Some(message.to_owned());
+	}
 }
 
 impl Sandbox for FunctionExecutor {
@@ -502,12 +511,31 @@ fn call_in_wasm_module(
 	let offset = function_executor.allocate_memory(data.len() as u32)?;
 	function_executor.write_memory(offset, data)?;
 
+	fn convert_trap(executor: &mut FunctionExecutor, trap: wasmi::Trap) -> Error {
+		if let Some(message) = executor.panic_message.take() {
+			Error::AbortedDueToPanic(MessageWithBacktrace { message, backtrace: None })
+		} else {
+			Error::AbortedDueToTrap(MessageWithBacktrace {
+				message: trap.to_string(),
+				backtrace: None,
+			})
+		}
+	}
+
 	let result = match method {
-		InvokeMethod::Export(method) => module_instance.invoke_export(
-			method,
-			&[I32(u32::from(offset) as i32), I32(data.len() as i32)],
-			&mut function_executor,
-		),
+		InvokeMethod::Export(method) => module_instance
+			.invoke_export(
+				method,
+				&[I32(u32::from(offset) as i32), I32(data.len() as i32)],
+				&mut function_executor,
+			)
+			.map_err(|error| {
+				if let wasmi::Error::Trap(trap) = error {
+					convert_trap(&mut function_executor, trap)
+				} else {
+					error.into()
+				}
+			}),
 		InvokeMethod::Table(func_ref) => {
 			let func = table
 				.ok_or(Error::NoTable)?
@@ -518,7 +546,7 @@ fn call_in_wasm_module(
 				&[I32(u32::from(offset) as i32), I32(data.len() as i32)],
 				&mut function_executor,
 			)
-			.map_err(Into::into)
+			.map_err(|trap| convert_trap(&mut function_executor, trap))
 		},
 		InvokeMethod::TableWithWrapper { dispatcher_ref, func } => {
 			let dispatcher = table
@@ -531,7 +559,7 @@ fn call_in_wasm_module(
 				&[I32(func as _), I32(u32::from(offset) as i32), I32(data.len() as i32)],
 				&mut function_executor,
 			)
-			.map_err(Into::into)
+			.map_err(|trap| convert_trap(&mut function_executor, trap))
 		},
 	};
 

substrate/client/executor/wasmtime/src/host.rs

@@ -45,6 +45,7 @@ unsafe impl Send for SandboxStore {}
 pub struct HostState {
 	sandbox_store: SandboxStore,
 	allocator: FreeingBumpHeapAllocator,
+	panic_message: Option<String>,
 }
 
 impl HostState {
@@ -55,8 +56,14 @@ impl HostState {
 				sandbox::SandboxBackend::TryWasmer,
 			)))),
 			allocator,
+			panic_message: None,
 		}
 	}
+
+	/// Takes the error message out of the host state, leaving a `None` in its place.
+	pub fn take_panic_message(&mut self) -> Option<String> {
+		self.panic_message.take()
+	}
 }
 
 /// A `HostContext` implements `FunctionContext` for making host calls from a Wasmtime
@@ -134,6 +141,14 @@ impl<'a> sp_wasm_interface::FunctionContext for HostContext<'a> {
 	fn sandbox(&mut self) -> &mut dyn Sandbox {
 		self
 	}
+
+	fn register_panic_error_message(&mut self, message: &str) {
+		self.caller
+			.data_mut()
+			.host_state_mut()
+			.expect("host state is not empty when calling a function in wasm; qed")
+			.panic_message = Some(message.to_owned());
+	}
 }
 
 impl<'a> Sandbox for HostContext<'a> {

substrate/client/executor/wasmtime/src/instance_wrapper.rs

@@ -21,7 +21,7 @@
 
 use crate::runtime::{Store, StoreData};
 use sc_executor_common::{
-	error::{Error, Result},
+	error::{Backtrace, Error, MessageWithBacktrace, Result},
 	wasm_runtime::InvokeMethod,
 };
 use sp_wasm_interface::{HostFunctions, Pointer, Value, WordSize};
@@ -53,25 +53,51 @@ pub struct EntryPoint {
 
 impl EntryPoint {
 	/// Call this entry point.
-	pub fn call(
+	pub(crate) fn call(
 		&self,
-		ctx: impl AsContextMut,
+		store: &mut Store,
 		data_ptr: Pointer<u8>,
 		data_len: WordSize,
 	) -> Result<u64> {
 		let data_ptr = u32::from(data_ptr);
 		let data_len = u32::from(data_len);
 
-		fn handle_trap(err: wasmtime::Trap) -> Error {
-			Error::from(format!("Wasm execution trapped: {}", err))
-		}
-
 		match self.call_type {
 			EntryPointType::Direct { ref entrypoint } =>
-				entrypoint.call(ctx, (data_ptr, data_len)).map_err(handle_trap),
+				entrypoint.call(&mut *store, (data_ptr, data_len)),
 			EntryPointType::Wrapped { func, ref dispatcher } =>
-				dispatcher.call(ctx, (func, data_ptr, data_len)).map_err(handle_trap),
+				dispatcher.call(&mut *store, (func, data_ptr, data_len)),
 		}
+		.map_err(|trap| {
+			let host_state = store
+				.data_mut()
+				.host_state
+				.as_mut()
+				.expect("host state cannot be empty while a function is being called; qed");
+
+			// The logic to print out a backtrace is somewhat complicated,
+			// so let's get wasmtime to print it out for us.
+			let mut backtrace_string = trap.to_string();
+			let suffix = "\nwasm backtrace:";
+			if let Some(index) = backtrace_string.find(suffix) {
+				// Get rid of the error message and just grab the backtrace,
+				// since we're storing the error message ourselves separately.
+				backtrace_string.replace_range(0..index + suffix.len(), "");
+			}
+
+			let backtrace = Backtrace { backtrace_string };
+			if let Some(error) = host_state.take_panic_message() {
+				Error::AbortedDueToPanic(MessageWithBacktrace {
+					message: error,
+					backtrace: Some(backtrace),
+				})
+			} else {
+				Error::AbortedDueToTrap(MessageWithBacktrace {
+					message: trap.display_reason().to_string(),
+					backtrace: Some(backtrace),
+				})
+			}
+		})
 	}
 
 	pub fn direct(

substrate/client/executor/wasmtime/src/tests.rs

@@ -17,7 +17,7 @@
 // along with this program. If not, see <https://www.gnu.org/licenses/>.
 
 use codec::{Decode as _, Encode as _};
-use sc_executor_common::{runtime_blob::RuntimeBlob, wasm_runtime::WasmModule};
+use sc_executor_common::{error::Error, runtime_blob::RuntimeBlob, wasm_runtime::WasmModule};
 use sc_runtime_test::wasm_binary_unwrap;
 use std::sync::Arc;
 
@@ -158,11 +158,13 @@ fn test_stack_depth_reaching() {
 	};
 	let mut instance = runtime.new_instance().expect("failed to instantiate a runtime");
 
-	let err = instance.call_export("test-many-locals", &[]).unwrap_err();
-
-	assert!(format!("{:?}", err).starts_with(
-		"Other(\"Wasm execution trapped: wasm trap: wasm `unreachable` instruction executed"
-	));
+	match instance.call_export("test-many-locals", &[]).unwrap_err() {
+		Error::AbortedDueToTrap(error) => {
+			let expected = "wasm trap: wasm `unreachable` instruction executed";
+			assert_eq!(error.message, expected);
+		},
+		error => panic!("unexpected error: {:?}", error),
+	}
 }
 
 #[test]