From 66e6879b62cb79e921ecaa1e247a9f65f61161fb Mon Sep 17 00:00:00 2001 From: Graydon Hoare Date: Sat, 28 Oct 2023 00:34:29 -0700 Subject: [PATCH] tighten up handling of debug mode --- soroban-env-host/Cargo.toml | 5 +- soroban-env-host/src/auth.rs | 45 ++--- soroban-env-host/src/budget.rs | 47 ++--- soroban-env-host/src/budget/dimension.rs | 6 +- soroban-env-host/src/budget/util.rs | 33 ++-- soroban-env-host/src/events/diagnostic.rs | 188 ++++++++---------- soroban-env-host/src/events/internal.rs | 9 +- soroban-env-host/src/host.rs | 115 +++++++---- soroban-env-host/src/host/error.rs | 195 ++++++++++++------- soroban-env-host/src/host/frame.rs | 32 +-- soroban-env-host/src/test/budget_metering.rs | 11 +- soroban-env-host/src/vm.rs | 24 +-- 12 files changed, 371 insertions(+), 339 deletions(-) diff --git a/soroban-env-host/Cargo.toml b/soroban-env-host/Cargo.toml index 37a778030..029e52318 100644 --- a/soroban-env-host/Cargo.toml +++ b/soroban-env-host/Cargo.toml @@ -26,7 +26,7 @@ rand_chacha = "0.3.1" num-traits = "0.2.15" num-integer = "0.1.45" num-derive = "0.4.0" -backtrace = "0.3" +backtrace = { version = "0.3", optional = true } k256 = {version = "0.13.1", features=["ecdsa", "arithmetic"]} # NB: getrandom is a transitive dependency of k256 which we're not using directly # but we have to specify it here in order to enable its 'js' feature which @@ -55,9 +55,10 @@ expect-test = "1.4.0" more-asserts = "0.3.1" linregress = "0.5.1" pretty_assertions = "1.4.0" +backtrace = "0.3" [features] -testutils = ["soroban-env-common/testutils", "soroban-synth-wasm/testutils", "recording_auth"] +testutils = ["soroban-env-common/testutils", "soroban-synth-wasm/testutils", "recording_auth", "dep:backtrace"] next = ["soroban-env-common/next", "soroban-synth-wasm/next", "soroban-bench-utils/next"] tracy = ["dep:tracy-client", "soroban-env-common/tracy"] recording_auth = [] diff --git a/soroban-env-host/src/auth.rs b/soroban-env-host/src/auth.rs index fe4e35553..f70aacc28 100644 --- a/soroban-env-host/src/auth.rs +++ b/soroban-env-host/src/auth.rs @@ -1304,30 +1304,25 @@ impl AuthorizationManager { &self, host: &Host, ) -> Vec<(ScAddress, xdr::SorobanAuthorizedInvocation)> { - let inv: Option> = - host.as_budget().with_shadow_mode( - || { - let inv = self - .account_trackers - .borrow() - .iter() - .filter(|t| t.borrow().verified) - .map(|t| { - ( - host.scaddress_from_address(t.borrow().address).unwrap(), - t.borrow() - .invocation_tracker - .root_authorized_invocation - .to_xdr(host, true) - .unwrap(), - ) - }) - .metered_collect(host)?; - Ok(Some(inv)) - }, - || None, - ); - inv.unwrap() + host.as_budget() + .with_observable_shadow_mode(|| { + self.account_trackers + .borrow() + .iter() + .filter(|t| t.borrow().verified) + .map(|t| { + ( + host.scaddress_from_address(t.borrow().address).unwrap(), + t.borrow() + .invocation_tracker + .root_authorized_invocation + .to_xdr(host, true) + .unwrap(), + ) + }) + .metered_collect(host) + }) + .unwrap() } } @@ -1695,7 +1690,7 @@ impl AccountAuthorizationTracker { // metering: free for recording #[cfg(any(test, feature = "recording_auth"))] fn get_recorded_auth_payload(&self, host: &Host) -> Result { - host.as_budget().with_shadow_mode_fallible(|| { + host.as_budget().with_observable_shadow_mode(|| { Ok(RecordedAuthPayload { address: if !self.is_invoker { Some(host.visit_obj(self.address, |a: &ScAddress| a.metered_clone(host))?) diff --git a/soroban-env-host/src/budget.rs b/soroban-env-host/src/budget.rs index 4c00aca48..cf9ba7b45 100644 --- a/soroban-env-host/src/budget.rs +++ b/soroban-env-host/src/budget.rs @@ -665,49 +665,36 @@ impl Budget { self.0.try_borrow_mut_or_err()?.charge(ty, 1, input) } - /// Runs a user provided closure in shadow mode -- all metering is done through - /// the shadow budget. + /// Runs a user provided closure in shadow mode -- all metering is done + /// through the shadow budget. /// - /// Because the shadow mode is optional (depending on the configuration, - /// nodes may or may not trigger this path), any error occured during execution - /// is swallowed by running a fallback closure provided by the caller. - /// - /// # Arguments: - /// * `f` - A fallible closure to be run in shadow mode. If error occurs, - /// fallback closure is run immediately afterwards to replace it - /// - /// * `fallback` - A fallback closure to be run in case of any error occuring - /// - /// # Returns: - /// - /// Returns a value of type `T`. Any errors arising during the execution are - /// suppressed. - pub(crate) fn with_shadow_mode(&self, f: F, fallback: E) -> T + /// Because shadow mode is _designed not to be observed_ (indeed it exists + /// primarily to count actions against the shadow budget that are _optional_ + /// on a given host, such as debug logging, and that therefore must strictly + /// must not be observed), any error that occurs during execution is + /// swallowed. + pub(crate) fn with_shadow_mode(&self, f: F) where F: FnOnce() -> Result, - E: FnOnce() -> T, { let mut prev = false; - let mut res = self + if self .mut_budget(|mut b| { prev = b.is_in_shadow_mode; b.is_in_shadow_mode = true; - b.cpu_insns.check_budget_limit(true)?; - b.mem_bytes.check_budget_limit(true) + b.cpu_insns.check_budget_limit(IsShadowMode(true))?; + b.mem_bytes.check_budget_limit(IsShadowMode(true)) }) - .and_then(|_| f()); + .is_ok() + { + let _ = f(); + } - if let Err(_) = self.mut_budget(|mut b| { + let _ = self.mut_budget(|mut b| { b.is_in_shadow_mode = prev; Ok(()) - }) { - res = Err( - Error::from_type_and_code(ScErrorType::Budget, ScErrorCode::InternalError).into(), - ); - } - - res.unwrap_or_else(|_| fallback()) + }); } pub(crate) fn is_in_shadow_mode(&self) -> Result { diff --git a/soroban-env-host/src/budget/dimension.rs b/soroban-env-host/src/budget/dimension.rs index c4afc111e..84350554b 100644 --- a/soroban-env-host/src/budget/dimension.rs +++ b/soroban-env-host/src/budget/dimension.rs @@ -116,8 +116,8 @@ impl BudgetDimension { self.shadow_total_count = 0; } - pub(crate) fn check_budget_limit(&self, is_shadow: bool) -> Result<(), HostError> { - let over_limit = if is_shadow { + pub(crate) fn check_budget_limit(&self, is_shadow: IsShadowMode) -> Result<(), HostError> { + let over_limit = if is_shadow.0 { self.shadow_total_count > self.shadow_limit } else { self.total_count > self.limit @@ -163,7 +163,7 @@ impl BudgetDimension { self.total_count = self.total_count.saturating_add(amount); } - self.check_budget_limit(is_shadow.0) + self.check_budget_limit(is_shadow) } // Resets all model parameters to zero (so that we can override and test individual ones later). diff --git a/soroban-env-host/src/budget/util.rs b/soroban-env-host/src/budget/util.rs index 7fc855377..66027178d 100644 --- a/soroban-env-host/src/budget/util.rs +++ b/soroban-env-host/src/budget/util.rs @@ -142,17 +142,26 @@ impl Budget { #[cfg(any(test, feature = "recording_auth"))] impl Budget { - /// Fallible version of `with_shadow_mode`, enabled only in testing and - /// non-production scenarios. The non-fallible `with_shadow_mode` is the - /// preferred method and should be used if at all possible. + /// Variant of `with_shadow_mode`, enabled only in testing and + /// non-production scenarios, that produces a `Result<>` rather than eating + /// errors and return values the way `with_shadow_mode` does. + /// + /// This is undesirable specifically because it has a return value which may + /// vary between `Ok` and `Err` depending on whether the shadow budget is + /// exhausted, and the shadow budget varies based on debug status -- + /// something that is not identical from one host to the next. + /// /// However, in testing and non-production workflows, sometimes we need the /// convenience of temporarily "turning off" the budget. This can happen for - /// several reasons: we want the some test logic to not affect the production - /// budget, or we want to maintain an accurate prediction of production budget - /// during preflight. In the latter case, we want to exclude preflight-only - /// logic from the budget. By routing metering to the shadow budget instead - /// of turning the budget off completely, it offers some DOS-mitigation. - pub(crate) fn with_shadow_mode_fallible(&self, f: F) -> Result + /// several reasons: we want the some test logic to not affect the + /// production budget, or we want to maintain an accurate prediction of + /// production budget during preflight. In the latter case, we want to + /// exclude preflight-only logic from the budget. By routing metering to the + /// shadow budget instead of turning the budget off completely, it offers + /// some DOS-mitigation. + /// + /// If in doubt, do not use this function. + pub(crate) fn with_observable_shadow_mode(&self, f: F) -> Result where F: FnOnce() -> Result, { @@ -160,8 +169,10 @@ impl Budget { let should_execute = self.mut_budget(|mut b| { prev = b.is_in_shadow_mode; b.is_in_shadow_mode = true; - b.cpu_insns.check_budget_limit(true)?; - b.mem_bytes.check_budget_limit(true) + b.cpu_insns + .check_budget_limit(super::dimension::IsShadowMode(true))?; + b.mem_bytes + .check_budget_limit(super::dimension::IsShadowMode(true)) }); let rt = match should_execute { diff --git a/soroban-env-host/src/events/diagnostic.rs b/soroban-env-host/src/events/diagnostic.rs index 6d63f5511..8f0f7dd4b 100644 --- a/soroban-env-host/src/events/diagnostic.rs +++ b/soroban-env-host/src/events/diagnostic.rs @@ -23,63 +23,40 @@ pub enum DiagnosticLevel { } impl Host { - pub fn set_diagnostic_level(&self, diagnostic_level: DiagnosticLevel) -> Result<(), HostError> { - *self.try_borrow_diagnostic_level_mut()? = diagnostic_level; - Ok(()) - } - - // As above, avoids having to import DiagnosticLevel. - pub fn enable_debug(&self) -> Result<(), HostError> { - self.set_diagnostic_level(DiagnosticLevel::Debug) - } - - pub(crate) fn is_debug(&self) -> Result { - Ok(matches!( - *self.try_borrow_diagnostic_level()?, - DiagnosticLevel::Debug - )) - } - fn record_diagnostic_event( &self, contract_id: Option, topics: Vec, args: Vec, ) -> Result<(), HostError> { - self.with_debug_mode( - || { - let de = Rc::metered_new( - InternalDiagnosticEvent { - contract_id, - topics, - args, - }, - self, - )?; - self.with_events_mut(|events| events.record(InternalEvent::Diagnostic(de), self)) - }, - || (), - ); + self.with_debug_mode(|| { + let de = Rc::metered_new( + InternalDiagnosticEvent { + contract_id, + topics, + args, + }, + self, + )?; + self.with_events_mut(|events| events.record(InternalEvent::Diagnostic(de), self)) + }); Ok(()) } pub fn log_diagnostics(&self, msg: &str, args: &[Val]) { - self.with_debug_mode( - || { - let calling_contract = self.get_current_contract_id_opt_internal()?; - let log_sym = SymbolSmall::try_from_str("log")?; - Vec::::charge_bulk_init_cpy(1, self)?; - let topics = vec![InternalDiagnosticArg::HostVal(log_sym.to_val())]; - let msg = ScVal::String(ScString::from(StringM::try_from( - self.metered_slice_to_vec(msg.as_bytes())?, - )?)); - let args: Vec<_> = std::iter::once(InternalDiagnosticArg::XdrVal(msg)) - .chain(args.iter().map(|rv| InternalDiagnosticArg::HostVal(*rv))) - .metered_collect(self)?; - self.record_diagnostic_event(calling_contract, topics, args) - }, - || (), - ) + self.with_debug_mode(|| { + let calling_contract = self.get_current_contract_id_opt_internal()?; + let log_sym = SymbolSmall::try_from_str("log")?; + Vec::::charge_bulk_init_cpy(1, self)?; + let topics = vec![InternalDiagnosticArg::HostVal(log_sym.to_val())]; + let msg = ScVal::String(ScString::from(StringM::try_from( + self.metered_slice_to_vec(msg.as_bytes())?, + )?)); + let args: Vec<_> = std::iter::once(InternalDiagnosticArg::XdrVal(msg)) + .chain(args.iter().map(|rv| InternalDiagnosticArg::HostVal(*rv))) + .metered_collect(self)?; + self.record_diagnostic_event(calling_contract, topics, args) + }) } pub(crate) fn record_err_diagnostics( @@ -89,80 +66,71 @@ impl Host { msg: &str, args: &[Val], ) { - self.with_debug_mode( - || { - let error_sym = SymbolSmall::try_from_str("error")?; - let contract_id = self.get_current_contract_id_opt_internal()?; - Vec::::charge_bulk_init_cpy(2, self)?; - let topics = vec![ - InternalDiagnosticArg::HostVal(error_sym.to_val()), - InternalDiagnosticArg::HostVal(error.to_val()), - ]; - let msg = ScVal::String(ScString::from(StringM::try_from( - self.metered_slice_to_vec(msg.as_bytes())?, - )?)); - let args: Vec<_> = std::iter::once(InternalDiagnosticArg::XdrVal(msg)) - .chain(args.iter().map(|rv| InternalDiagnosticArg::HostVal(*rv))) - .metered_collect(self)?; + self.with_debug_mode(|| { + let error_sym = SymbolSmall::try_from_str("error")?; + let contract_id = self.get_current_contract_id_opt_internal()?; + Vec::::charge_bulk_init_cpy(2, self)?; + let topics = vec![ + InternalDiagnosticArg::HostVal(error_sym.to_val()), + InternalDiagnosticArg::HostVal(error.to_val()), + ]; + let msg = ScVal::String(ScString::from(StringM::try_from( + self.metered_slice_to_vec(msg.as_bytes())?, + )?)); + let args: Vec<_> = std::iter::once(InternalDiagnosticArg::XdrVal(msg)) + .chain(args.iter().map(|rv| InternalDiagnosticArg::HostVal(*rv))) + .metered_collect(self)?; - // We do the event-recording ourselves here rather than calling - // self.record_system_debug_contract_event because we can/should - // only be called with an already-borrowed events buffer (to - // insulate against double-faulting). - let ce = Rc::metered_new( - InternalDiagnosticEvent { - contract_id, - topics, - args, - }, - self, - )?; - events.record(InternalEvent::Diagnostic(ce), self) - }, - || (), - ) + // We do the event-recording ourselves here rather than calling + // self.record_system_debug_contract_event because we can/should + // only be called with an already-borrowed events buffer (to + // insulate against double-faulting). + let ce = Rc::metered_new( + InternalDiagnosticEvent { + contract_id, + topics, + args, + }, + self, + )?; + events.record(InternalEvent::Diagnostic(ce), self) + }) } // Emits an event with topic = ["fn_call", called_contract_id, function_name] and // data = [arg1, args2, ...] // Should called prior to opening a frame for the next call so the calling contract can be inferred correctly pub fn fn_call_diagnostics(&self, called_contract_id: &Hash, func: &Symbol, args: &[Val]) { - self.with_debug_mode( - || { - let calling_contract = self.get_current_contract_id_opt_internal()?; - Vec::::charge_bulk_init_cpy(3, self)?; - let topics = vec![ - InternalDiagnosticArg::HostVal(SymbolSmall::try_from_str("fn_call")?.into()), - InternalDiagnosticArg::XdrVal(ScVal::Bytes(ScBytes::try_from( - self.metered_slice_to_vec(called_contract_id.as_slice())?, - )?)), - InternalDiagnosticArg::HostVal(func.into()), - ]; - let args = args - .iter() - .map(|rv| InternalDiagnosticArg::HostVal(*rv)) - .metered_collect(self)?; - self.record_diagnostic_event(calling_contract, topics, args) - }, - || (), - ) + self.with_debug_mode(|| { + let calling_contract = self.get_current_contract_id_opt_internal()?; + Vec::::charge_bulk_init_cpy(3, self)?; + let topics = vec![ + InternalDiagnosticArg::HostVal(SymbolSmall::try_from_str("fn_call")?.into()), + InternalDiagnosticArg::XdrVal(ScVal::Bytes(ScBytes::try_from( + self.metered_slice_to_vec(called_contract_id.as_slice())?, + )?)), + InternalDiagnosticArg::HostVal(func.into()), + ]; + let args = args + .iter() + .map(|rv| InternalDiagnosticArg::HostVal(*rv)) + .metered_collect(self)?; + self.record_diagnostic_event(calling_contract, topics, args) + }) } // Emits an event with topic = ["fn_return", function_name] and // data = [return_val] pub fn fn_return_diagnostics(&self, contract_id: &Hash, func: &Symbol, res: &Val) { - self.with_debug_mode( - || { - Vec::::charge_bulk_init_cpy(2, self)?; - let topics = vec![ - InternalDiagnosticArg::HostVal(SymbolSmall::try_from_str("fn_return")?.into()), - InternalDiagnosticArg::HostVal(func.into()), - ]; - Vec::::charge_bulk_init_cpy(1, self)?; - let args = vec![InternalDiagnosticArg::HostVal(*res)]; - self.record_diagnostic_event(Some(contract_id.metered_clone(self)?), topics, args) - }, - || (), - ) + self.with_debug_mode(|| { + Vec::::charge_bulk_init_cpy(2, self)?; + let topics = vec![ + InternalDiagnosticArg::HostVal(SymbolSmall::try_from_str("fn_return")?.into()), + InternalDiagnosticArg::HostVal(func.into()), + ]; + Vec::::charge_bulk_init_cpy(1, self)?; + let args = vec![InternalDiagnosticArg::HostVal(*res)]; + self.record_diagnostic_event(Some(contract_id.metered_clone(self)?), topics, args) + }) } } diff --git a/soroban-env-host/src/events/internal.rs b/soroban-env-host/src/events/internal.rs index fcf7f1b7d..7fdeff101 100644 --- a/soroban-env-host/src/events/internal.rs +++ b/soroban-env-host/src/events/internal.rs @@ -159,9 +159,7 @@ impl InternalEventsBuffer { match &e { InternalEvent::Contract(_) => metered_internal_event_push(e)?, - InternalEvent::Diagnostic(_) => { - host.with_debug_mode(|| metered_internal_event_push(e), || ()) - } + InternalEvent::Diagnostic(_) => host.with_debug_mode(|| metered_internal_event_push(e)), } Ok(()) @@ -211,10 +209,7 @@ impl InternalEventsBuffer { metered_external_event_push(c.to_xdr(host)?, status)?; } InternalEvent::Diagnostic(d) => { - host.with_debug_mode( - || metered_external_event_push(d.to_xdr(host)?, status), - || (), - ); + host.with_debug_mode(|| metered_external_event_push(d.to_xdr(host)?, status)); } } } diff --git a/soroban-env-host/src/host.rs b/soroban-env-host/src/host.rs index 84bafc1a1..c1b39c48b 100644 --- a/soroban-env-host/src/host.rs +++ b/soroban-env-host/src/host.rs @@ -113,6 +113,11 @@ struct HostImpl { budget: Budget, events: RefCell, authorization_manager: RefCell, + // Note: to reduce the risk of future maintainers accidentally adding a new + // way of observing the diagnostic level (which may vary between different + // replicas of the host, thus causing divergence) there are no borrow + // helpers for it and the only method to use it is inside the + // `with_debug_mode` callback that switches to the shadow budget. diagnostic_level: RefCell, base_prng: RefCell>, // Auth-recording mode generates pseudorandom nonces to populate its output. @@ -222,12 +227,12 @@ impl_checked_borrow_helpers!( try_borrow_authorization_manager, try_borrow_authorization_manager_mut ); -impl_checked_borrow_helpers!( - diagnostic_level, - DiagnosticLevel, - try_borrow_diagnostic_level, - try_borrow_diagnostic_level_mut -); + +// Note: diagnostic_mode borrow helpers are _not_ defined here to reduce the +// risk of future maintainers accidentally revealing any way of observing the +// diagnostic level in user code (which may vary between different replicas of +// the host). + impl_checked_borrow_helpers!( base_prng, Option, @@ -471,19 +476,46 @@ impl Host { self.0.budget.set_shadow_limits(cpu, mem) } - /// Wraps the `budget.with_internal_mode` call with the check `host.is_debug`. - /// This wrapper should be used for any work that is part of the production - /// workflow but in debug mode, i.e. diagnostic related work (logging, or any - /// operations on diagnostic event). - pub(crate) fn with_debug_mode(&self, f: F, e: E) -> T + pub fn set_diagnostic_level(&self, diagnostic_level: DiagnosticLevel) -> Result<(), HostError> { + use crate::host::error::TryBorrowOrErr; + *self.0.diagnostic_level.try_borrow_mut_or_err()? = diagnostic_level; + Ok(()) + } + + // As above, avoids having to import DiagnosticLevel. + pub fn enable_debug(&self) -> Result<(), HostError> { + self.set_diagnostic_level(DiagnosticLevel::Debug) + } + + /// Wraps a `budget.with_shadow_mode` call with a check against the + /// diagnostic level. This wrapper should be used for any work that is part + /// of the production workflow but in debug mode, i.e. diagnostic related + /// work (logging, or any operations on diagnostic events). + /// + /// Note: to help minimize the risk of divergence based on accidental + /// observation of the diagnostic level in any context _other_ than this + /// callback, we make two things at least inconvenient enough to maybe cause + /// people to come to this comment and read it: + /// + /// 1. We avoid having any other direct way of observing the flag. + /// 2. We eat all errors and return no values from the closure. + /// + /// If you need to observe a value from the execution of debug mode, you can + /// of course still mutate a mutable reference pointing outside the closure, + /// but be _absolutely certain_ any observation you thereby make of the + /// debug-level _only_ flows into other functions that are themselves + /// debug-mode-guarded and/or only write results into debug state (eg. + /// diagnostic events). + pub(crate) fn with_debug_mode(&self, f: F) where - F: FnOnce() -> Result, - E: Fn() -> T, + F: FnOnce() -> Result<(), HostError>, { - if self.is_debug().ok() != Some(true) { - return e(); + use crate::host::error::TryBorrowOrErr; + if let Ok(cell) = self.0.diagnostic_level.try_borrow_or_err() { + if matches!(*cell, DiagnosticLevel::Debug) { + return self.budget_ref().with_shadow_mode(f); + } } - self.as_budget().with_shadow_mode(f, e) } /// Returns whether the Host can be finished by calling @@ -778,33 +810,30 @@ impl VmCallerEnv for Host { vals_pos: U32Val, vals_len: U32Val, ) -> Result { - self.with_debug_mode( - || { - let VmSlice { vm, pos, len } = self.decode_vmslice(msg_pos, msg_len)?; - Vec::::charge_bulk_init_cpy(len as u64, self)?; - let mut msg: Vec = vec![0u8; len as usize]; - self.metered_vm_read_bytes_from_linear_memory(vmcaller, &vm, pos, &mut msg)?; - // `String::from_utf8_lossy` iternally allocates a `String` which is a `Vec` - Vec::::charge_bulk_init_cpy(len as u64, self)?; - let msg = String::from_utf8_lossy(&msg); - - let VmSlice { vm, pos, len } = self.decode_vmslice(vals_pos, vals_len)?; - Vec::::charge_bulk_init_cpy((len.saturating_add(1)) as u64, self)?; - let mut vals: Vec = vec![Val::VOID.to_val(); len as usize]; - // charge for conversion from bytes to `Val`s - self.charge_budget(ContractCostType::MemCpy, Some(len.saturating_mul(8) as u64))?; - self.metered_vm_read_vals_from_linear_memory::<8, Val>( - vmcaller, - &vm, - pos, - vals.as_mut_slice(), - |buf| self.relative_to_absolute(Val::from_payload(u64::from_le_bytes(*buf))), - )?; - self.log_diagnostics(&msg, &vals); - Ok(()) - }, - || (), - ); + self.with_debug_mode(|| { + let VmSlice { vm, pos, len } = self.decode_vmslice(msg_pos, msg_len)?; + Vec::::charge_bulk_init_cpy(len as u64, self)?; + let mut msg: Vec = vec![0u8; len as usize]; + self.metered_vm_read_bytes_from_linear_memory(vmcaller, &vm, pos, &mut msg)?; + // `String::from_utf8_lossy` iternally allocates a `String` which is a `Vec` + Vec::::charge_bulk_init_cpy(len as u64, self)?; + let msg = String::from_utf8_lossy(&msg); + + let VmSlice { vm, pos, len } = self.decode_vmslice(vals_pos, vals_len)?; + Vec::::charge_bulk_init_cpy(len.saturating_add(1) as u64, self)?; + let mut vals: Vec = vec![Val::VOID.to_val(); len as usize]; + // charge for conversion from bytes to `Val`s + self.charge_budget(ContractCostType::MemCpy, Some(len.saturating_mul(8) as u64))?; + self.metered_vm_read_vals_from_linear_memory::<8, Val>( + vmcaller, + &vm, + pos, + vals.as_mut_slice(), + |buf| self.relative_to_absolute(Val::from_payload(u64::from_le_bytes(*buf))), + )?; + self.log_diagnostics(&msg, &vals); + Ok(()) + }); Ok(Val::VOID) } diff --git a/soroban-env-host/src/host/error.rs b/soroban-env-host/src/host/error.rs index 884863ec1..6e31c65fc 100644 --- a/soroban-env-host/src/host/error.rs +++ b/soroban-env-host/src/host/error.rs @@ -4,6 +4,8 @@ use crate::{ xdr::{self, Hash, LedgerKey, ScAddress, ScError, ScErrorCode, ScErrorType}, ConversionError, EnvBase, Error, Host, TryFromVal, U32Val, Val, }; + +#[cfg(any(test, feature = "testutils"))] use backtrace::{Backtrace, BacktraceFrame}; use core::fmt::Debug; use std::{ @@ -16,8 +18,9 @@ use super::metered_clone::MeteredClone; #[derive(Clone)] pub(crate) struct DebugInfo { - pub(crate) events: Events, - pub(crate) backtrace: Backtrace, + events: Events, + #[cfg(any(test, feature = "testutils"))] + backtrace: Backtrace, } #[derive(Clone)] @@ -34,8 +37,32 @@ impl Into for HostError { } } -impl Debug for HostError { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { +impl DebugInfo { + fn write_events(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + // TODO: maybe make this something users can adjust? + const MAX_EVENTS: usize = 25; + let mut wrote_heading = false; + for (i, e) in self.events.0.iter().rev().take(MAX_EVENTS).enumerate() { + if !wrote_heading { + writeln!(f)?; + writeln!(f, "Event log (newest first):")?; + wrote_heading = true; + } + writeln!(f, " {}: {}", i, e)?; + } + if self.events.0.len() > MAX_EVENTS { + writeln!(f, " {}: ... elided ...", MAX_EVENTS)?; + } + Ok(()) + } + + #[cfg(not(any(test, feature = "testutils")))] + fn write_backtrace(&self, _f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + Ok(()) + } + + #[cfg(any(test, feature = "testutils"))] + fn write_backtrace(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { // We do a little trimming here, skipping the first two frames (which // are always into, from, and one or more Host::err_foo calls) and all // the frames _after_ the short-backtrace marker that rust compiles-in. @@ -64,36 +91,28 @@ impl Debug for HostError { || frame_name_matches(frame, "Host>::err") || frame_name_matches(frame, "::augment_err_result") } + let mut bt = self.backtrace.clone(); + bt.resolve(); + let frames: Vec = bt + .frames() + .iter() + .skip_while(|f| frame_is_initial_error_plumbing(f)) + .take_while(|f| !frame_is_short_backtrace_start(f)) + .cloned() + .collect(); + let bt: Backtrace = frames.into(); + writeln!(f)?; + writeln!(f, "Backtrace (newest first):")?; + writeln!(f, "{:?}", bt) + } +} +impl Debug for HostError { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { writeln!(f, "HostError: {:?}", self.error)?; if let Some(info) = &self.info { - let mut bt = info.backtrace.clone(); - bt.resolve(); - let frames: Vec = bt - .frames() - .iter() - .skip_while(|f| frame_is_initial_error_plumbing(f)) - .take_while(|f| !frame_is_short_backtrace_start(f)) - .cloned() - .collect(); - let bt: Backtrace = frames.into(); - // TODO: maybe make this something users can adjust? - const MAX_EVENTS: usize = 25; - let mut wrote_heading = false; - for (i, e) in info.events.0.iter().rev().take(MAX_EVENTS).enumerate() { - if !wrote_heading { - writeln!(f)?; - writeln!(f, "Event log (newest first):")?; - wrote_heading = true; - } - writeln!(f, " {}: {}", i, e)?; - } - if info.events.0.len() > MAX_EVENTS { - writeln!(f, " {}: ... elided ...", MAX_EVENTS)?; - } - writeln!(f)?; - writeln!(f, "Backtrace (newest first):")?; - writeln!(f, "{:?}", bt) + info.write_events(f)?; + info.write_backtrace(f) } else { writeln!(f, "DebugInfo not available") } @@ -214,40 +233,46 @@ impl Host { /// enriches the returned [Error] with [DebugInfo] in the form of a /// [Backtrace] and snapshot of the [Events] buffer. pub fn error(&self, error: Error, msg: &str, args: &[Val]) -> HostError { - 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 - // log, failing gracefully (just emitting a no-debug-info - // `HostError` wrapping the supplied `Error`) if we cannot acquire - // the refcell. This is to handle the "double fault" case where we - // 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); - } - Ok(HostError { - error, - info: self.maybe_get_debug_info(), - }) - }, - || error.into(), - ) + let mut he = HostError::from(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 + // log, failing gracefully (just emitting a no-debug-info + // `HostError` wrapping the supplied `Error`) if we cannot acquire + // the refcell. This is to handle the "double fault" case where we + // 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); + } + he = HostError { + error, + info: self.maybe_get_debug_info(), + }; + Ok(()) + }); + he } pub(crate) fn maybe_get_debug_info(&self) -> Option> { - self.with_debug_mode( - || { + #[allow(unused_mut)] + let mut res = None; + // DebugInfo should never even be _possible_ to turn on in a production + // environment. It does not contribute to the diagnostics emitted in the + // debug stream -- those happen elsewhere -- DebugInfo only exists for + // users doing local testing to get nice backtraces on their console. + #[cfg(any(test, feature = "testutils"))] + { + self.with_debug_mode(|| { if let Ok(events_ref) = self.0.events.try_borrow() { let events = events_ref.externalize(self)?; let backtrace = Backtrace::new_unresolved(); - Ok(Some(Box::new(DebugInfo { backtrace, events }))) - } else { - Ok(None) + res = Some(Box::new(DebugInfo { backtrace, events })); } - }, - || None, - ) + Ok(()) + }); + } + res } // Some common error patterns here. @@ -303,12 +328,16 @@ impl Host { E: Debug, { res.map_err(|e| { - if let Ok(true) = self.is_debug() { - let msg = format!("{:?}", e); - self.error(e.into(), &msg, &[]) - } else { - self.error(e.into(), "", &[]) - } + use std::borrow::Cow; + let mut msg: Cow<'_, str> = Cow::Borrowed(&""); + // This observes the debug state, but it only causes a different + // (richer) string to be logged as a diagnostic event, which + // is itself not observable outside the debug state. + self.with_debug_mode(|| { + msg = Cow::Owned(format!("{:?}", e)); + Ok(()) + }); + self.error(e.into(), &msg, &[]) }) } @@ -431,14 +460,16 @@ pub(crate) trait DebugArg { fn debug_arg(host: &Host, arg: &Self) -> Val { // We similarly guard against double-faulting here by try-acquiring the event buffer, // which will fail if we're re-entering error reporting _while_ forming a debug argument. + let mut val: Val = + Error::from_type_and_code(ScErrorType::Events, ScErrorCode::InternalError).to_val(); if let Ok(_guard) = host.0.events.try_borrow_mut() { - host.with_debug_mode( - || Self::debug_arg_maybe_expensive_or_fallible(host, arg), - || { - Error::from_type_and_code(ScErrorType::Events, ScErrorCode::InternalError) - .into() - }, - ) + host.with_debug_mode(|| { + if let Ok(v) = Self::debug_arg_maybe_expensive_or_fallible(host, arg) { + val = v; + } + Ok(()) + }); + val } else { Error::from_type_and_code(ScErrorType::Events, ScErrorCode::InternalError).into() } @@ -489,11 +520,25 @@ impl DebugArg for usize { macro_rules! err { ($host:expr, $error:expr, $msg:literal, $($args:expr),*) => { { - if let Ok(true) = $host.is_debug() { - $host.error($error.into(), $msg, &[$(<_ as $crate::host::error::DebugArg>::debug_arg($host, &$args)),*]) - } else { - $host.error($error.into(), $msg, &[]) + const fn voidarg(_: &'static str) -> $crate::Val { + $crate::Val::VOID.to_val() } + // The stringify and voidarg calls here exist just to cause the + // macro to stack-allocate a fixed-size local array with one VOID + // initializer per argument. The arguments themselves are not + // actually used at this point. + let mut buf = [$(voidarg(stringify!($args))),*]; + let mut i = 0; + $host.with_debug_mode(||{ + $( + // Args actually get used here, where we fill in array cells.. + buf[i] = <_ as $crate::host::error::DebugArg>::debug_arg($host, &$args); + // .. and extend the end-index of the args-slice we'll pass. + i += 1; + )* + Ok(()) + }); + $host.error($error.into(), $msg, &buf[0..i]) } }; } diff --git a/soroban-env-host/src/host/frame.rs b/soroban-env-host/src/host/frame.rs index 3c2f1d701..6b92db223 100644 --- a/soroban-env-host/src/host/frame.rs +++ b/soroban-env-host/src/host/frame.rs @@ -647,20 +647,24 @@ impl Host { // payload into the diagnostic event buffer. This // code path will get hit when contracts do // `panic!("some string")` in native testing mode. - if !recovered_error_from_panic_refcell && self.is_debug()? { - if let Some(str) = panic_payload.downcast_ref::<&str>() { - let msg: String = format!( - "caught panic '{}' from contract function '{:?}'", - str, func - ); - let _ = self.log_diagnostics(&msg, args); - } else if let Some(str) = panic_payload.downcast_ref::() { - let msg: String = format!( - "caught panic '{}' from contract function '{:?}'", - str, func - ); - let _ = self.log_diagnostics(&msg, args); - } + if !recovered_error_from_panic_refcell { + self.with_debug_mode(|| { + if let Some(str) = panic_payload.downcast_ref::<&str>() { + let msg: String = format!( + "caught panic '{}' from contract function '{:?}'", + str, func + ); + let _ = self.log_diagnostics(&msg, args); + } else if let Some(str) = panic_payload.downcast_ref::() + { + let msg: String = format!( + "caught panic '{}' from contract function '{:?}'", + str, func + ); + let _ = self.log_diagnostics(&msg, args); + }; + Ok(()) + }) } Err(self.error(error, "caught error from function", &[])) } diff --git a/soroban-env-host/src/test/budget_metering.rs b/soroban-env-host/src/test/budget_metering.rs index 5a969770b..8b8daaf56 100644 --- a/soroban-env-host/src/test/budget_metering.rs +++ b/soroban-env-host/src/test/budget_metering.rs @@ -350,13 +350,10 @@ fn total_amount_charged_from_random_inputs() -> Result<(), HostError> { } for (ty, &(iterations, input)) in tracker.iter().enumerate() { - host.as_budget().with_shadow_mode( - || { - host.as_budget() - .bulk_charge(ContractCostType::VARIANTS[ty], iterations, input) - }, - || (), - ) + host.as_budget().with_shadow_mode(|| { + host.as_budget() + .bulk_charge(ContractCostType::VARIANTS[ty], iterations, input) + }) } let actual = format!("{:?}", host.as_budget()); diff --git a/soroban-env-host/src/vm.rs b/soroban-env-host/src/vm.rs index e4d96b666..b6aae5e2b 100644 --- a/soroban-env-host/src/vm.rs +++ b/soroban-env-host/src/vm.rs @@ -358,6 +358,8 @@ impl Vm { .return_fuel_to_host(host)?; if let Err(e) = res { + use std::borrow::Cow; + // When a call fails with a wasmi::Error::Trap that carries a HostError // we propagate that HostError as is, rather than producing something new. @@ -365,13 +367,12 @@ impl Vm { wasmi::Error::Trap(trap) => { if let Some(code) = trap.trap_code() { let err = code.into(); - return Err(if host.is_debug()? { - // With diagnostics on: log as much detail as we can from wasmi. - let msg = format!("VM call trapped: {:?}", &code); - host.error(err, &msg, &[func_sym.to_val(), err.to_val()]) - } else { - err.into() + let mut msg = Cow::Borrowed("VM call trapped"); + host.with_debug_mode(|| { + msg = Cow::Owned(format!("VM call trapped: {:?}", &code)); + Ok(()) }); + return Err(host.error(err, &msg, &[func_sym.to_val()])); } if let Some(he) = trap.downcast::() { host.log_diagnostics( @@ -388,13 +389,12 @@ impl Vm { )); } e => { - return Err(if host.is_debug()? { - // With diagnostics on: log as much detail as we can from wasmi. - let msg = format!("VM call failed: {:?}", &e); - host.error(e.into(), &msg, &[func_sym.to_val()]) - } else { - host.error(e.into(), "VM call failed", &[func_sym.to_val()]) + let mut msg = Cow::Borrowed("VM call failed"); + host.with_debug_mode(|| { + msg = Cow::Owned(format!("VM call failed: {:?}", &e)); + Ok(()) }); + return Err(host.error(e.into(), &msg, &[func_sym.to_val()])); } } }