Skip to content

Commit

Permalink
Preserve backtraces across secondary error events
Browse files Browse the repository at this point in the history 
Closes stellar#1266
  • Loading branch information
@brson
brson committed Feb 17, 2024
1 parent f035dda commit 8ffc57d
Show file tree
Hide file tree
Showing 8 changed files with 296 additions and 16 deletions.
50 changes: 50 additions & 0 deletions soroban-env-host/observations/test__backtrace__test_backtrace_native.json
View file
Original file line number Diff line number Diff line change
@@ -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:-/-"
}
56 changes: 56 additions & 0 deletions soroban-env-host/observations/test__backtrace__test_backtrace_wasm.json
View file
Original file line number Diff line number Diff line change
@@ -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:-/-"
}
4 changes: 2 additions & 2 deletions soroban-env-host/src/host.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}

Expand Down
27 changes: 23 additions & 4 deletions soroban-env-host/src/host/error.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -254,7 +254,13 @@ 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);
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.
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
Expand All @@ -264,11 +270,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(())
});
Expand Down
33 changes: 24 additions & 9 deletions soroban-env-host/src/host/frame.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -57,7 +57,7 @@ pub(crate) struct TestContractFrame {
pub(crate) id: Hash,
pub(crate) func: Symbol,
pub(crate) args: Vec<Val>,
pub(crate) panic: Rc<RefCell<Option<Error>>>,
pub(crate) panic: Rc<RefCell<Option<HostError>>>,
pub(crate) instance: ScContractInstance,
}

Expand All @@ -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) 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<Self> 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<Val>, instance: ScContractInstance) -> Self {
Expand Down Expand Up @@ -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
Expand All @@ -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();
}
}

Expand Down Expand Up @@ -833,7 +848,7 @@ impl Host {
Ok(())
})
}
Err(self.error(error, "caught error from function", &[]))
Err(self.secondary_error(error, "caught error from function", &[]))
}
}
});
Expand Down
2 changes: 2 additions & 0 deletions soroban-env-host/src/test.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,8 @@ pub(crate) mod observe;

mod address;
mod auth;
#[cfg(feature = "testutils")]
mod backtrace;
mod basic;
mod budget_metering;
mod bytes;
Expand Down
138 changes: 138 additions & 0 deletions soroban-env-host/src/test/backtrace.rs
View file
Original file line number Diff line number Diff line change
@@ -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::<u8>::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<Val> {
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::<u8>::new();
let _ = writeln!(&mut buf, "{:?}", err);
let buf = String::from_utf8_lossy(&buf);
let expected_frame = buf.contains("Storage::extend_ttl");
assert!(expected_frame);
}
Loading

0 comments on commit 8ffc57d

Please sign in to comment.