Skip to content

Preserve backtraces across secondary error events #1349

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
brson wants to merge 2 commits into
base: main
Choose a base branch
from
Open

Preserve backtraces across secondary error events #1349

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
95edbe4
Preserve backtraces across secondary error events
brson Feb 17, 2024
72a2e06
Add comments about 'secondary_error'
brson Feb 26, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
50 changes: 50 additions & 0 deletions soroban-env-host/observations/test__backtrace__test_backtrace_native.json
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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)
}
Comment thread
dmkozh marked this conversation as resolved.

/// 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
Open in desktop
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) 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<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
Open in desktop
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
Open in desktop
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