diff --git a/soroban-env-host/observations/test__backtrace__test_backtrace_native.json b/soroban-env-host/observations/test__backtrace__test_backtrace_native.json new file mode 100644 index 000000000..2f27b1732 --- /dev/null +++ b/soroban-env-host/observations/test__backtrace__test_backtrace_native.json @@ -0,0 +1,50 @@ +{ + " 0 begin": "cpu:14488, mem:0, prngs:-/9b4a753, objs:-/-, vm:-/-, evt:-, store:-/-, foot:-, stk:-, auth:-/-", + " 1 call symbol_new_from_slice(13)": "cpu:29038, mem:1726, objs:-/2@7826ffba, store:-/2@8f53be5d, foot:2@b5543661", + " 2 ret symbol_new_from_slice -> Ok(Symbol(obj#5))": "cpu:30046, mem:1819, objs:-/3@13db8e81", + " 3 call vec_new_from_slice(2)": "", + " 4 ret vec_new_from_slice -> Ok(Vec(obj#7))": "cpu:31011, mem:1915, objs:-/4@7e1b7d3c", + " 5 call try_call(Address(obj#1), Symbol(obj#5), Vec(obj#7))": "", + " 6 call symbol_len(Symbol(obj#5))": "cpu:31887, mem:1947", + " 7 ret symbol_len -> Ok(U32(13))": "cpu:32009", + " 8 call symbol_copy_to_slice(Symbol(obj#5), U32(0), 13)": "", + " 9 ret symbol_copy_to_slice -> Ok(())": "cpu:32113", + " 10 push TEST: 0:sym#5(Symbol(key), U64(1))": "cpu:41841, mem:3075, objs:-/5@8aed2070, stk:1@7d326773, auth:1@9c77a914/-", + " 11 call symbol_new_from_slice(13)": "", + " 12 ret symbol_new_from_slice -> Ok(Symbol(obj#11))": "cpu:42849, mem:3168, objs:-/6@b7c09f27", + " 13 call symbol_new_from_slice(16)": "", + " 14 ret symbol_new_from_slice -> Ok(Symbol(obj#13))": "cpu:43860, mem:3264, objs:-/7@aade354e", + " 15 call obj_cmp(Symbol(obj#5), Symbol(obj#11))": "", + " 16 ret obj_cmp -> Ok(0)": "cpu:44149", + " 17 call put_contract_data(Symbol(key), U64(1), Temporary)": "", + " 18 ret put_contract_data -> Ok(Void)": "cpu:49489, mem:4294, store:-/3@c95e49e7, foot:3@96664895", + " 19 pop TEST: 0:sym#5 -> Ok(Void)": "", + " 20 ret try_call -> Ok(Void)": " stk:-, auth:-/-", + " 21 call get_ledger_sequence()": "", + " 22 ret get_ledger_sequence -> Ok(U32(0))": "", + " 23 call symbol_new_from_slice(16)": "", + " 24 ret symbol_new_from_slice -> Ok(Symbol(obj#15))": "cpu:50500, mem:4390, objs:-/8@4c996cc6", + " 25 call vec_new_from_slice(3)": "", + " 26 ret vec_new_from_slice -> Ok(Vec(obj#17))": "cpu:51467, mem:4494, objs:-/9@29e56213", + " 27 call try_call(Address(obj#1), Symbol(obj#15), Vec(obj#17))": "", + " 28 call symbol_len(Symbol(obj#15))": "cpu:52345, mem:4534", + " 29 ret symbol_len -> Ok(U32(16))": "cpu:52467", + " 30 call symbol_copy_to_slice(Symbol(obj#15), U32(0), 16)": "", + " 31 ret symbol_copy_to_slice -> Ok(())": "cpu:52572", + " 32 push TEST: 0:sym#15(Symbol(key), U32(1), U32(6311999))": "cpu:62316, mem:5730, objs:-/10@980b5b6c, stk:1@cec2ee86, auth:1@b86cb58d/-", + " 33 call symbol_new_from_slice(13)": "", + " 34 ret symbol_new_from_slice -> Ok(Symbol(obj#21))": "cpu:63324, mem:5823, objs:-/11@a3078f63", + " 35 call symbol_new_from_slice(16)": "", + " 36 ret symbol_new_from_slice -> Ok(Symbol(obj#23))": "cpu:64335, mem:5919, objs:-/12@76cf0cad", + " 37 call obj_cmp(Symbol(obj#15), Symbol(obj#21))": "", + " 38 ret obj_cmp -> Ok(-1)": "cpu:64624", + " 39 call obj_cmp(Symbol(obj#15), Symbol(obj#23))": "", + " 40 ret obj_cmp -> Ok(0)": "cpu:64914", + " 41 call extend_contract_data_ttl(Symbol(key), Temporary, U32(1), U32(6311999))": "", + " 42 call get_ledger_sequence()": "cpu:66241, mem:6055, store:-/-, foot:-", + " 43 ret get_ledger_sequence -> Ok(U32(1000000000))": "", + " 44 ret extend_contract_data_ttl -> Err(Error(Storage, InternalError))": " store:-/3@c95e49e7, foot:3@96664895", + " 45 pop TEST: 0:sym#15 -> Err(Error(Storage, InternalError))": " stk:1@27cbf3bc", + " 46 ret try_call -> Err(Error(Storage, InternalError))": " stk:-, auth:-/-", + " 47 end": "cpu:66241, mem:6055, prngs:-/9b4a753, objs:-/12@76cf0cad, vm:-/-, evt:-, store:-/3@c95e49e7, foot:3@96664895, stk:-, auth:-/-" +} \ No newline at end of file diff --git a/soroban-env-host/observations/test__backtrace__test_backtrace_wasm.json b/soroban-env-host/observations/test__backtrace__test_backtrace_wasm.json new file mode 100644 index 000000000..35f48fc0e --- /dev/null +++ b/soroban-env-host/observations/test__backtrace__test_backtrace_wasm.json @@ -0,0 +1,56 @@ +{ + " 0 begin": "cpu:14488, mem:0, prngs:-/9b4a753, objs:-/-, vm:-/-, evt:-, store:-/-, foot:-, stk:-, auth:-/-", + " 1 call bytes_new_from_slice(2926)": "cpu:14535", + " 2 ret bytes_new_from_slice -> Ok(Bytes(obj#1))": "cpu:16226, mem:3006, objs:-/1@59b06c07", + " 3 call upload_wasm(Bytes(obj#1))": "", + " 4 ret upload_wasm -> Ok(Bytes(obj#3))": "cpu:1808452, mem:1301182, objs:-/2@4011c09e, store:-/1@39074ab1, foot:1@32a3b76c", + " 5 call bytes_new_from_slice(32)": "cpu:1808892, mem:1301246, objs:-/3@5e827dcf", + " 6 ret bytes_new_from_slice -> Ok(Bytes(obj#7))": "cpu:1809861, mem:1301358, objs:-/4@965f719a", + " 7 call create_contract(Address(obj#5), Bytes(obj#3), Bytes(obj#7))": "", + " 8 call obj_cmp(Address(obj#9), Address(obj#5))": "cpu:1811504, mem:1301536, objs:-/5@102310eb, auth:1@37cdfd8a/-", + " 9 ret obj_cmp -> Ok(0)": "cpu:1811796", + " 10 call get_ledger_network_id()": "cpu:1811846, auth:1@37cdfd8a/1@ca935ef7", + " 11 ret get_ledger_network_id -> Ok(Bytes(obj#11))": "cpu:1812876, mem:1301648, objs:-/6@6f654453", + " 12 ret create_contract -> Ok(Address(obj#13))": "cpu:1831009, mem:1304722, objs:-/7@fe1adc27, store:-/2@7c97e17d, foot:2@35ccd57a, auth:-/1@dce30087", + " 13 call symbol_new_from_slice(13)": " auth:-/-", + " 14 ret symbol_new_from_slice -> Ok(Symbol(obj#15))": "cpu:1832017, mem:1304815, objs:-/8@4c5585d5", + " 15 call vec_new_from_slice(2)": "", + " 16 ret vec_new_from_slice -> Ok(Vec(obj#17))": "cpu:1832982, mem:1304911, objs:-/9@d8153495", + " 17 call try_call(Address(obj#13), Symbol(obj#15), Vec(obj#17))": "", + " 18 call symbol_len(Symbol(obj#15))": "cpu:1833858, mem:1304943", + " 19 ret symbol_len -> Ok(U32(13))": "cpu:1833980", + " 20 call symbol_copy_to_slice(Symbol(obj#15), U32(0), 13)": "", + " 21 ret symbol_copy_to_slice -> Ok(())": "cpu:1834084", + " 22 push VM:fc644715:sym#15(Symbol(key), U64(1))": "cpu:3467614, mem:2603597, objs:-/10@ba8a4b77, vm:1048576@2434eedc/20@26ecda6, stk:1@2048e896, auth:1@b86cb58d/-", + " 23 call symbol_len(Symbol(obj#15))": "cpu:3470091, mem:2603659", + " 24 ret symbol_len -> Ok(U32(13))": "cpu:3470213", + " 25 call symbol_copy_to_slice(Symbol(obj#15), U32(0), 13)": "", + " 26 ret symbol_copy_to_slice -> Ok(())": "cpu:3470317", + " 27 call put_contract_data(Symbol(key), U64(1), Temporary)": " vm:-/-", + " 28 ret put_contract_data -> Ok(Void)": "cpu:3478555, mem:2604689, store:-/3@cff64dbc, foot:3@ec4df205", + " 29 pop VM:fc644715:sym#15 -> Ok(Void)": " vm:1048576@f7f6eb14/20@26ecda6", + " 30 ret try_call -> Ok(Void)": " vm:-/-, stk:-, auth:-/-", + " 31 call get_ledger_sequence()": "", + " 32 ret get_ledger_sequence -> Ok(U32(0))": "", + " 33 call symbol_new_from_slice(16)": "", + " 34 ret symbol_new_from_slice -> Ok(Symbol(obj#21))": "cpu:3479566, mem:2604785, objs:-/11@1eac391c", + " 35 call vec_new_from_slice(3)": "", + " 36 ret vec_new_from_slice -> Ok(Vec(obj#23))": "cpu:3480533, mem:2604889, objs:-/12@4a5a5128", + " 37 call try_call(Address(obj#13), Symbol(obj#21), Vec(obj#23))": "", + " 38 call symbol_len(Symbol(obj#21))": "cpu:3481411, mem:2604929", + " 39 ret symbol_len -> Ok(U32(16))": "cpu:3481533", + " 40 call symbol_copy_to_slice(Symbol(obj#21), U32(0), 16)": "", + " 41 ret symbol_copy_to_slice -> Ok(())": "cpu:3481638", + " 42 push VM:fc644715:sym#21(Symbol(key), U32(1), U32(6311999))": "cpu:5115186, mem:3903659, objs:-/13@ce7efe42, vm:1048576@2434eedc/20@26ecda6, stk:1@afa4f10, auth:1@4b43f04d/-", + " 43 call symbol_len(Symbol(obj#21))": "cpu:5117667, mem:3903737", + " 44 ret symbol_len -> Ok(U32(16))": "cpu:5117789", + " 45 call symbol_copy_to_slice(Symbol(obj#21), U32(0), 16)": "", + " 46 ret symbol_copy_to_slice -> Ok(())": "cpu:5117894", + " 47 call extend_contract_data_ttl(Symbol(key), Temporary, U32(1), U32(6311999))": " vm:-/-", + " 48 call get_ledger_sequence()": "cpu:5120687, mem:3903873, store:-/-, foot:-", + " 49 ret get_ledger_sequence -> Ok(U32(1000000000))": "", + " 50 ret extend_contract_data_ttl -> Err(Error(Storage, InternalError))": " store:-/3@cff64dbc, foot:3@ec4df205", + " 51 pop VM:fc644715:sym#21 -> Err(Error(Storage, InternalError))": " vm:1048576@146376a2/20@26ecda6", + " 52 ret try_call -> Err(Error(Storage, InternalError))": " vm:-/-, stk:-, auth:-/-", + " 53 end": "cpu:5120687, mem:3903873, prngs:-/9b4a753, objs:-/13@ce7efe42, vm:-/-, evt:-, store:-/3@cff64dbc, foot:3@ec4df205, stk:-, auth:-/-" +} \ No newline at end of file diff --git a/soroban-env-host/src/host.rs b/soroban-env-host/src/host.rs index 67180bfdd..4779ada06 100644 --- a/soroban-env-host/src/host.rs +++ b/soroban-env-host/src/host.rs @@ -697,12 +697,12 @@ impl EnvBase for Host { let _ = self.with_current_frame_opt(|f| { if let Some(Frame::TestContract(frame)) = f { if let Ok(mut panic) = frame.panic.try_borrow_mut() { - *panic = Some(e.error); + *panic = Some(e.clone()); } } Ok(()) }); - let escalation = self.error(e.error, "escalating error to panic", &[]); + let escalation = self.secondary_error(e, "escalating error to panic", &[]); panic!("{:?}", escalation) } diff --git a/soroban-env-host/src/host/error.rs b/soroban-env-host/src/host/error.rs index c1ec27c72..b3b71aabe 100644 --- a/soroban-env-host/src/host/error.rs +++ b/soroban-env-host/src/host/error.rs @@ -254,7 +254,18 @@ impl Host { /// enriches the returned [Error] with [DebugInfo] in the form of a /// [Backtrace] and snapshot of the [Events] buffer. pub(crate) fn error(&self, error: Error, msg: &str, args: &[Val]) -> HostError { - let mut he = HostError::from(error); + // Note that though we are calling `secondary_error`, this is likely the + // "primary" error and this call is an implementation detail to generate + // the initial backtrace. + self.secondary_error(HostError::from(error), msg, args) + } + + /// The same as [Host::error] but it will preserve the original + /// backtrace from `error` instead of generating a new one. + /// + /// This is typically used to raise a new error when we already have an error. + pub(crate) fn secondary_error(&self, error: HostError, msg: &str, args: &[Val]) -> HostError { + let mut he = error; self.with_debug_mode(|| { // We _try_ to take a mutable borrow of the events buffer refcell // while building up the event we're going to emit into the events @@ -264,11 +275,24 @@ impl Host { // get an error _while performing_ any of the steps needed to record // an error as an event, below. if let Ok(mut events_refmut) = self.0.events.try_borrow_mut() { - self.record_err_diagnostics(events_refmut.deref_mut(), error, msg, args); + self.record_err_diagnostics(events_refmut.deref_mut(), he.error, msg, args); } + #[cfg(not(any(test, feature = "testutils")))] + let info = self.maybe_get_debug_info(); + #[cfg(any(test, feature = "testutils"))] + let info = { + let mut info = self.maybe_get_debug_info(); + match (&he.info, &mut info) { + (Some(heinfo), Some(ref mut info)) => { + info.backtrace = heinfo.backtrace.clone(); + } + _ => {} + } + info + }; he = HostError { - error, - info: self.maybe_get_debug_info(), + error: he.error, + info, }; Ok(()) }); diff --git a/soroban-env-host/src/host/frame.rs b/soroban-env-host/src/host/frame.rs index e3afa2bee..4b48611c2 100644 --- a/soroban-env-host/src/host/frame.rs +++ b/soroban-env-host/src/host/frame.rs @@ -57,7 +57,7 @@ pub(crate) struct TestContractFrame { pub(crate) id: Hash, pub(crate) func: Symbol, pub(crate) args: Vec, - pub(crate) panic: Rc>>, + pub(crate) panic: Rc>>, pub(crate) instance: ScContractInstance, } @@ -68,12 +68,26 @@ impl std::hash::Hash for TestContractFrame { self.func.hash(state); self.args.hash(state); if let Some(panic) = self.panic.borrow().as_ref() { - panic.hash(state); + panic.error.hash(state); + // NB: not hashing the (testutils) debuginfo/backtrace in the error. + // At present this hash is only used for capturing the trace state, + // and a hash of the backtrace would be very expensive and platform-specific. + // This function will be incorrect if used in a HashMap; because of this + // we implement Eq to panic. } self.instance.hash(state); } } +#[cfg(any(test, feature = "testutils"))] +impl std::cmp::PartialEq for TestContractFrame { + fn eq(&self, _other: &Self) -> bool { + // This is to prevent accidentally putting TestContractFrame into a HashMap. + // See comments in impl Hash. + unreachable!(); + } +} + #[cfg(any(test, feature = "testutils"))] impl TestContractFrame { pub fn new(id: Hash, func: Symbol, args: Vec, instance: ScContractInstance) -> Self { @@ -781,9 +795,9 @@ impl Host { // panicked. // // If it was a panic generated by a Env-upgraded - // HostError, it had its `Error` captured by + // HostError, it had its error captured by // `VmCallerEnv::escalate_error_to_panic`: fish the - // `Error` stored in the frame back out and + // `HostError` stored in the frame back out and // propagate it. // // If it was a panic generated by user code calling @@ -795,14 +809,15 @@ impl Host { // trap-unreachable code). It's a little weird // because we're not actually running a VM, but we // prioritize emulation fidelity over honesty here. - let mut error: Error = - Error::from(wasmi::core::TrapCode::UnreachableCodeReached); + let mut error: HostError = HostError::from(Error::from( + wasmi::core::TrapCode::UnreachableCodeReached, + )); let mut recovered_error_from_panic_refcell = false; if let Ok(panic) = panic.try_borrow() { - if let Some(err) = *panic { + if let Some(ref err) = *panic { recovered_error_from_panic_refcell = true; - error = err; + error = err.clone(); } } @@ -833,7 +848,7 @@ impl Host { Ok(()) }) } - Err(self.error(error, "caught error from function", &[])) + Err(self.secondary_error(error, "caught error from function", &[])) } } }); diff --git a/soroban-env-host/src/test.rs b/soroban-env-host/src/test.rs index 080b35256..290aed38d 100644 --- a/soroban-env-host/src/test.rs +++ b/soroban-env-host/src/test.rs @@ -2,6 +2,8 @@ pub(crate) mod observe; mod address; mod auth; +#[cfg(feature = "testutils")] +mod backtrace; mod basic; mod budget_metering; mod bytes; diff --git a/soroban-env-host/src/test/backtrace.rs b/soroban-env-host/src/test/backtrace.rs new file mode 100644 index 000000000..4ef73297c --- /dev/null +++ b/soroban-env-host/src/test/backtrace.rs @@ -0,0 +1,138 @@ +use std::cmp::Ordering; +use std::io::Write; +use std::rc::Rc; + +use crate::events::diagnostic::DiagnosticLevel; +use crate::{xdr, ContractFunctionSet, Host, StorageType, Val}; +use soroban_env_common::Compare; +use soroban_env_common::{Env, Symbol, TryFromVal, TryIntoVal}; +use soroban_test_wasms::CONTRACT_STORAGE; + +fn storage_fn_name(host: &Host, fn_name: &str, storage: &str) -> Symbol { + Symbol::try_from_val(host, &format!("{}_{}", fn_name, storage).as_str()).unwrap() +} + +// This is testing that an error (triggered in Storage::extend_ttl) generates +// a backtrace, and that backtrace is carried all the way to the contract call +// site. This involves handing the backtrace off from the original error to +// a secondary error event. +#[test] +fn test_backtrace_wasm() { + let host = observe_host!(Host::test_host_with_recording_footprint()); + host.set_diagnostic_level(DiagnosticLevel::Debug).unwrap(); + let contract_id = host.register_test_contract_wasm(CONTRACT_STORAGE); + + // Create some storage + let key = Symbol::try_from_small_str("key").unwrap(); + let r = host.try_call( + contract_id, + storage_fn_name(&host, "put", "temporary"), + test_vec![&*host, key, 1_u64].into(), + ); + + assert!(r.is_ok()); + + // Advance the ledger but leave the expired storage in the host. + // This will trigger an error about "accessing no-longer-live entry". + let max_live_until_ledger: u32 = host.max_live_until_ledger().unwrap().into(); + let ledger_seq: u32 = host.get_ledger_sequence().unwrap().into(); + let max_extend = max_live_until_ledger - ledger_seq; + let threshold: u32 = 1; + let _ = host.with_mut_ledger_info(|ledger| { + ledger.sequence_number += 1000000000; + ledger.timestamp += 10000000; + }); + + let r = host.try_call( + contract_id, + storage_fn_name(&host, "extend", "temporary"), + test_vec![&*host, key, threshold, max_extend].into(), + ); + + // The error should contain Storage::extend_ttl in the backtrace + let err = r.unwrap_err(); + let mut buf = Vec::::new(); + let _ = writeln!(&mut buf, "{:?}", err); + let buf = String::from_utf8_lossy(&buf); + let expected_frame = buf.contains("Storage::extend_ttl"); + assert!(expected_frame); +} + +struct Contract; + +use soroban_env_common::EnvBase; + +impl ContractFunctionSet for Contract { + fn call(&self, func: &Symbol, host: &Host, args: &[Val]) -> Option { + let put_temporary = Symbol::try_from_val(host, &"put_temporary").unwrap(); + let extend_temporary = Symbol::try_from_val(host, &"extend_temporary").unwrap(); + + if host.compare(func, &put_temporary).unwrap() == Ordering::Equal { + host.put_contract_data(args[0], args[1], StorageType::Temporary) + .unwrap(); + Some(().into()) + } else if host.compare(func, &extend_temporary).unwrap() == Ordering::Equal { + let r = host.extend_contract_data_ttl( + args[0], + StorageType::Temporary, + args[1].try_into().unwrap(), + args[2].try_into().unwrap(), + ); + if let Err(e) = r { + // This is what the SDK does when it generates a HostError while + // calling a contract, and this code path needs to preserve + // the backtrace across the panic. + host.escalate_error_to_panic(e); + } + Some(().into()) + } else { + panic!() + } + } +} + +#[test] +fn test_backtrace_native() { + let host = observe_host!(Host::test_host_with_recording_footprint()); + host.set_diagnostic_level(DiagnosticLevel::Debug).unwrap(); + let contract_id = host + .add_host_object(xdr::ScAddress::Contract(xdr::Hash([0; 32]))) + .unwrap(); + host.register_test_contract(contract_id, Rc::new(Contract)) + .unwrap(); + + // Create some storage + let key = Symbol::try_from_small_str("key").unwrap(); + let r = host.try_call( + contract_id, + storage_fn_name(&host, "put", "temporary"), + test_vec![&*host, key, 1_u64].into(), + ); + + assert!(r.is_ok()); + + // Advance the ledger but leave the expired storage in the host. + // This will trigger an error about "accessing no-longer-live entry". + let max_live_until_ledger: u32 = host.max_live_until_ledger().unwrap().into(); + let ledger_seq: u32 = host.get_ledger_sequence().unwrap().into(); + let max_extend = max_live_until_ledger - ledger_seq; + let threshold: u32 = 1; + let _ = host.with_mut_ledger_info(|ledger| { + ledger.sequence_number += 1000000000; + ledger.timestamp += 10000000; + }); + + let r = host.try_call( + contract_id, + storage_fn_name(&host, "extend", "temporary"), + test_vec![&*host, key, threshold, max_extend].into(), + ); + + // The error should contain Storage::extend_ttl in the backtrace + let err = r.unwrap_err(); + let mut buf = Vec::::new(); + let _ = writeln!(&mut buf, "{:?}", err); + let buf = String::from_utf8_lossy(&buf); + let expected_frame = buf.contains("Storage::extend_ttl"); + assert!(expected_frame); +} diff --git a/soroban-env-host/src/vm/dispatch.rs b/soroban-env-host/src/vm/dispatch.rs index 0b16cf250..8b3630336 100644 --- a/soroban-env-host/src/vm/dispatch.rs +++ b/soroban-env-host/src/vm/dispatch.rs @@ -260,7 +260,7 @@ macro_rules! generate_dispatch_functions { Err(hosterr) => { // We make a new HostError here to capture the escalation event itself. let escalation: HostError = - host.error(hosterr.error, + host.secondary_error(hosterr, concat!("escalating error to VM trap from failed host function call: ", stringify!($fn_id)), &[]); let trap: Trap = escalation.into();