diff --git a/CHANGELOG.md b/CHANGELOG.md index 08dbcc5e15..eff24ae6e2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -25,11 +25,16 @@ and this project adheres to - cosmwasm-vm: Add target (triple + CPU features) into the module cache directory to avoid using modules compiled for a different system. Bump `MODULE_SERIALIZATION_VERSION` to "v5". ([#1664]) +- cosmwasm-vm: When enabling `print_debug` the debug logs are now printed to + STDERR instead of STDOUT by default ([#1667]). +- cosmwasm-vm: Add `Instance::set_debug_handler`/`unset_debug_handler` to allow + customizing the handling of debug messages emitted by the contract ([#1667]). [#1511]: https://github.com/CosmWasm/cosmwasm/issues/1511 [#1629]: https://github.com/CosmWasm/cosmwasm/pull/1629 [#1631]: https://github.com/CosmWasm/cosmwasm/pull/1631 [#1664]: https://github.com/CosmWasm/cosmwasm/pull/1664 +[#1667]: https://github.com/CosmWasm/cosmwasm/pull/1667 ## [1.2.4] - 2023-04-17 diff --git a/Cargo.lock b/Cargo.lock index f327920bd0..908cd9a779 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -387,6 +387,7 @@ dependencies = [ "cosmwasm-std", "crc32fast", "criterion", + "derivative", "enumset", "glob", "hex", diff --git a/contracts/burner/Cargo.lock b/contracts/burner/Cargo.lock index 34e6a44f5c..7c79465c26 100644 --- a/contracts/burner/Cargo.lock +++ b/contracts/burner/Cargo.lock @@ -238,6 +238,7 @@ dependencies = [ "cosmwasm-crypto", "cosmwasm-std", "crc32fast", + "derivative", "enumset", "hex", "loupe", diff --git a/contracts/crypto-verify/Cargo.lock b/contracts/crypto-verify/Cargo.lock index cb0b85462e..1d15e1a799 100644 --- a/contracts/crypto-verify/Cargo.lock +++ b/contracts/crypto-verify/Cargo.lock @@ -241,6 +241,7 @@ dependencies = [ "cosmwasm-crypto", "cosmwasm-std", "crc32fast", + "derivative", "enumset", "hex", "loupe", diff --git a/contracts/cyberpunk/Cargo.lock b/contracts/cyberpunk/Cargo.lock index 670c06f60e..81b6eb4876 100644 --- a/contracts/cyberpunk/Cargo.lock +++ b/contracts/cyberpunk/Cargo.lock @@ -264,6 +264,7 @@ dependencies = [ "cosmwasm-crypto", "cosmwasm-std", "crc32fast", + "derivative", "enumset", "hex", "loupe", diff --git a/contracts/cyberpunk/schema/cyberpunk.json b/contracts/cyberpunk/schema/cyberpunk.json index 1584ac900e..dcce96d609 100644 --- a/contracts/cyberpunk/schema/cyberpunk.json +++ b/contracts/cyberpunk/schema/cyberpunk.json @@ -165,6 +165,20 @@ } }, "additionalProperties": false + }, + { + "description": "Does a bit of work and calls debug", + "type": "object", + "required": [ + "debug" + ], + "properties": { + "debug": { + "type": "object", + "additionalProperties": false + } + }, + "additionalProperties": false } ] }, diff --git a/contracts/cyberpunk/schema/raw/execute.json b/contracts/cyberpunk/schema/raw/execute.json index e096feab6f..8ea521b97f 100644 --- a/contracts/cyberpunk/schema/raw/execute.json +++ b/contracts/cyberpunk/schema/raw/execute.json @@ -155,6 +155,20 @@ } }, "additionalProperties": false + }, + { + "description": "Does a bit of work and calls debug", + "type": "object", + "required": [ + "debug" + ], + "properties": { + "debug": { + "type": "object", + "additionalProperties": false + } + }, + "additionalProperties": false } ] } diff --git a/contracts/cyberpunk/src/contract.rs b/contracts/cyberpunk/src/contract.rs index f5f1b98655..55acddaf6b 100644 --- a/contracts/cyberpunk/src/contract.rs +++ b/contracts/cyberpunk/src/contract.rs @@ -1,5 +1,5 @@ use cosmwasm_std::{ - entry_point, to_binary, Deps, DepsMut, Empty, Env, MessageInfo, QueryResponse, Response, + entry_point, to_binary, Api, Deps, DepsMut, Empty, Env, MessageInfo, QueryResponse, Response, StdError, StdResult, WasmMsg, }; @@ -38,6 +38,7 @@ pub fn execute( Panic {} => execute_panic(), Unreachable {} => execute_unreachable(), MirrorEnv {} => execute_mirror_env(env), + Debug {} => execute_debug(deps.api), } } @@ -150,6 +151,33 @@ fn execute_mirror_env(env: Env) -> Result { Ok(Response::new().set_data(to_binary(&env)?)) } +fn execute_debug(api: &dyn Api) -> Result { + api.debug("Hey, ho – let's go"); + + let password = b"password"; + let salt = b"othersalt"; + + for r in 1..10 { + api.debug(&format!("Round {r} starting")); + let config = argon2::Config { + variant: argon2::Variant::Argon2i, + version: argon2::Version::Version13, + mem_cost: 32, + time_cost: r, + lanes: 4, + thread_mode: argon2::ThreadMode::Sequential, + secret: &[], + ad: &[], + hash_length: 32, + }; + let _hash = argon2::hash_encoded(password, salt, &config).unwrap(); + api.debug(&format!("Round {r} done")); + } + + api.debug("Work completed, bye"); + Ok(Response::default()) +} + #[entry_point] pub fn query(_deps: Deps, env: Env, msg: QueryMsg) -> StdResult { use QueryMsg::*; @@ -162,3 +190,34 @@ pub fn query(_deps: Deps, env: Env, msg: QueryMsg) -> StdResult { fn query_mirror_env(env: Env) -> Env { env } + +#[cfg(test)] +mod tests { + use super::*; + use cosmwasm_std::testing::{ + mock_dependencies, mock_env, mock_info, MockApi, MockQuerier, MockStorage, + }; + use cosmwasm_std::OwnedDeps; + + fn setup() -> OwnedDeps { + let mut deps = mock_dependencies(); + let msg = Empty {}; + let info = mock_info("creator", &[]); + let res = instantiate(deps.as_mut(), mock_env(), info, msg).unwrap(); + assert_eq!(0, res.messages.len()); + deps + } + + #[test] + fn instantiate_works() { + setup(); + } + + #[test] + fn debug_works() { + let mut deps = setup(); + + let msg = ExecuteMsg::Debug {}; + execute(deps.as_mut(), mock_env(), mock_info("caller", &[]), msg).unwrap(); + } +} diff --git a/contracts/cyberpunk/src/msg.rs b/contracts/cyberpunk/src/msg.rs index 33d73a51b1..7abb882009 100644 --- a/contracts/cyberpunk/src/msg.rs +++ b/contracts/cyberpunk/src/msg.rs @@ -28,6 +28,8 @@ pub enum ExecuteMsg { Unreachable {}, /// Returns the env for testing MirrorEnv {}, + /// Does a bit of work and calls debug + Debug {}, } #[cw_serde] diff --git a/contracts/cyberpunk/tests/integration.rs b/contracts/cyberpunk/tests/integration.rs index 3de369d239..c05e061dea 100644 --- a/contracts/cyberpunk/tests/integration.rs +++ b/contracts/cyberpunk/tests/integration.rs @@ -21,6 +21,7 @@ use cosmwasm_std::{from_binary, Empty, Env, Response}; use cosmwasm_vm::testing::{ execute, instantiate, mock_env, mock_info, mock_instance, mock_instance_with_gas_limit, query, }; +use std::time::SystemTime; use cyberpunk::msg::{ExecuteMsg, QueryMsg}; @@ -53,6 +54,35 @@ fn execute_argon2() { assert!(gas_used < expected * 120 / 100, "Gas used: {}", gas_used); } +// Test with +// cargo integration-test debug_works -- --nocapture +#[test] +fn debug_works() { + let mut deps = mock_instance_with_gas_limit(WASM, 100_000_000_000_000); + + let _res: Response = + instantiate(&mut deps, mock_env(), mock_info("admin", &[]), Empty {}).unwrap(); + + let msg = ExecuteMsg::Debug {}; + let _res: Response = execute(&mut deps, mock_env(), mock_info("caller", &[]), msg).unwrap(); + + let start = SystemTime::now(); + deps.set_debug_handler(move |msg, info| { + let gas = info.gas_remaining; + let runtime = SystemTime::now().duration_since(start).unwrap().as_micros(); + eprintln!("{msg} (gas: {gas}, runtime: {runtime}µs)"); + }); + + let msg = ExecuteMsg::Debug {}; + let _res: Response = execute(&mut deps, mock_env(), mock_info("caller", &[]), msg).unwrap(); + + eprintln!("Unsetting debug handler. From here nothing is printed anymore."); + deps.unset_debug_handler(); + + let msg = ExecuteMsg::Debug {}; + let _res: Response = execute(&mut deps, mock_env(), mock_info("caller", &[]), msg).unwrap(); +} + #[test] fn test_env() { let mut deps = mock_instance(WASM, &[]); diff --git a/contracts/floaty/Cargo.lock b/contracts/floaty/Cargo.lock index adb80440c3..9a99000538 100644 --- a/contracts/floaty/Cargo.lock +++ b/contracts/floaty/Cargo.lock @@ -235,6 +235,7 @@ dependencies = [ "cosmwasm-crypto", "cosmwasm-std", "crc32fast", + "derivative", "enumset", "hex", "loupe", diff --git a/contracts/hackatom/Cargo.lock b/contracts/hackatom/Cargo.lock index 6a6f8b1f75..452f2fa57b 100644 --- a/contracts/hackatom/Cargo.lock +++ b/contracts/hackatom/Cargo.lock @@ -235,6 +235,7 @@ dependencies = [ "cosmwasm-crypto", "cosmwasm-std", "crc32fast", + "derivative", "enumset", "hex", "loupe", diff --git a/contracts/ibc-reflect-send/Cargo.lock b/contracts/ibc-reflect-send/Cargo.lock index 635c031955..da048e234c 100644 --- a/contracts/ibc-reflect-send/Cargo.lock +++ b/contracts/ibc-reflect-send/Cargo.lock @@ -235,6 +235,7 @@ dependencies = [ "cosmwasm-crypto", "cosmwasm-std", "crc32fast", + "derivative", "enumset", "hex", "loupe", diff --git a/contracts/ibc-reflect/Cargo.lock b/contracts/ibc-reflect/Cargo.lock index 5f7eaa7c25..20148d0bc9 100644 --- a/contracts/ibc-reflect/Cargo.lock +++ b/contracts/ibc-reflect/Cargo.lock @@ -235,6 +235,7 @@ dependencies = [ "cosmwasm-crypto", "cosmwasm-std", "crc32fast", + "derivative", "enumset", "hex", "loupe", diff --git a/contracts/queue/Cargo.lock b/contracts/queue/Cargo.lock index 9331333d93..7687cbe7e0 100644 --- a/contracts/queue/Cargo.lock +++ b/contracts/queue/Cargo.lock @@ -227,6 +227,7 @@ dependencies = [ "cosmwasm-crypto", "cosmwasm-std", "crc32fast", + "derivative", "enumset", "hex", "loupe", diff --git a/contracts/reflect/Cargo.lock b/contracts/reflect/Cargo.lock index cfe2547ef8..45197abab8 100644 --- a/contracts/reflect/Cargo.lock +++ b/contracts/reflect/Cargo.lock @@ -235,6 +235,7 @@ dependencies = [ "cosmwasm-crypto", "cosmwasm-std", "crc32fast", + "derivative", "enumset", "hex", "loupe", diff --git a/contracts/staking/Cargo.lock b/contracts/staking/Cargo.lock index cd8b5c088e..ef63f9f593 100644 --- a/contracts/staking/Cargo.lock +++ b/contracts/staking/Cargo.lock @@ -235,6 +235,7 @@ dependencies = [ "cosmwasm-crypto", "cosmwasm-std", "crc32fast", + "derivative", "enumset", "hex", "loupe", diff --git a/contracts/virus/Cargo.lock b/contracts/virus/Cargo.lock index 9a0324f83c..577a77cba6 100644 --- a/contracts/virus/Cargo.lock +++ b/contracts/virus/Cargo.lock @@ -227,6 +227,7 @@ dependencies = [ "cosmwasm-crypto", "cosmwasm-std", "crc32fast", + "derivative", "enumset", "hex", "loupe", diff --git a/packages/vm/Cargo.toml b/packages/vm/Cargo.toml index 74a5ac1a00..331a04eb0d 100644 --- a/packages/vm/Cargo.toml +++ b/packages/vm/Cargo.toml @@ -40,6 +40,7 @@ crc32fast = "1.3.2" # Uses the path when built locally; uses the given version from crates.io when published cosmwasm-std = { path = "../std", version = "1.2.4", default-features = false } cosmwasm-crypto = { path = "../crypto", version = "1.2.4" } +derivative = "2" hex = "0.4" parity-wasm = "0.45" schemars = "0.8.3" diff --git a/packages/vm/src/environment.rs b/packages/vm/src/environment.rs index 02270726ec..e9be792609 100644 --- a/packages/vm/src/environment.rs +++ b/packages/vm/src/environment.rs @@ -1,8 +1,11 @@ //! Internal details to be used by instance.rs only use std::borrow::{Borrow, BorrowMut}; +use std::marker::PhantomData; use std::ptr::NonNull; +use std::rc::Rc; use std::sync::{Arc, RwLock}; +use derivative::Derivative; use wasmer::{HostEnvInitError, Instance as WasmerInstance, Memory, Val, WasmerEnv}; use wasmer_middlewares::metering::{get_remaining_points, set_remaining_points, MeteringPoints}; @@ -79,11 +82,34 @@ impl GasState { } } +/// Additional environmental information in a debug call. +/// +/// The currently unused lifetime parameter 'a allows accessing referenced data in the debug implementation +/// without cloning it. +#[derive(Derivative)] +#[derivative(Debug)] +#[non_exhaustive] +pub struct DebugInfo<'a> { + pub gas_remaining: u64, + // This field is just to allow us to add the unused lifetime parameter. It can be removed + // at any time. + #[doc(hidden)] + #[derivative(Debug = "ignore")] + pub(crate) __lifetime: PhantomData<&'a ()>, +} + +// Unfortunately we cannot create an alias for the trait (https://github.com/rust-lang/rust/issues/41517). +// So we need to copy it in a few places. +// +// /- BEGIN TRAIT END TRAIT \ +// | | +// v v +pub type DebugHandlerFn = dyn for<'a> Fn(/* msg */ &'a str, DebugInfo<'a>); + /// A environment that provides access to the ContextData. /// The environment is clonable but clones access the same underlying data. pub struct Environment { pub api: A, - pub print_debug: bool, pub gas_config: GasConfig, data: Arc>>, } @@ -96,7 +122,6 @@ impl Clone for Environment { fn clone(&self) -> Self { Environment { api: self.api, - print_debug: self.print_debug, gas_config: self.gas_config.clone(), data: self.data.clone(), } @@ -110,15 +135,27 @@ impl WasmerEnv for Environment { } impl Environment { - pub fn new(api: A, gas_limit: u64, print_debug: bool) -> Self { + pub fn new(api: A, gas_limit: u64) -> Self { Environment { api, - print_debug, gas_config: GasConfig::default(), data: Arc::new(RwLock::new(ContextData::new(gas_limit))), } } + pub fn set_debug_handler(&self, debug_handler: Option>) { + self.with_context_data_mut(|context_data| { + context_data.debug_handler = debug_handler; + }) + } + + pub fn debug_handler(&self) -> Option> { + self.with_context_data(|context_data| { + // This clone here requires us to wrap the function in Rc instead of Box + context_data.debug_handler.clone() + }) + } + fn with_context_data_mut(&self, callback: C) -> R where C: FnOnce(&mut ContextData) -> R, @@ -353,6 +390,7 @@ pub struct ContextData { storage_readonly: bool, call_depth: usize, querier: Option, + debug_handler: Option>, /// A non-owning link to the wasmer instance wasmer_instance: Option>, } @@ -365,6 +403,7 @@ impl ContextData { storage_readonly: true, call_depth: 0, querier: None, + debug_handler: None, wasmer_instance: None, } } @@ -429,7 +468,7 @@ mod tests { Environment, Box, ) { - let env = Environment::new(MockApi::default(), gas_limit, false); + let env = Environment::new(MockApi::default(), gas_limit); let module = compile(CONTRACT, TESTING_MEMORY_LIMIT, &[]).unwrap(); let store = module.store(); diff --git a/packages/vm/src/imports.rs b/packages/vm/src/imports.rs index bae11f403c..91e35f59b8 100644 --- a/packages/vm/src/imports.rs +++ b/packages/vm/src/imports.rs @@ -1,6 +1,7 @@ //! Import implementations use std::cmp::max; +use std::marker::PhantomData; use cosmwasm_crypto::{ ed25519_batch_verify, ed25519_verify, secp256k1_recover_pubkey, secp256k1_verify, CryptoError, @@ -14,7 +15,7 @@ use cosmwasm_std::Order; use crate::backend::{BackendApi, BackendError, Querier, Storage}; use crate::conversion::{ref_to_u32, to_u32}; -use crate::environment::{process_gas_info, Environment}; +use crate::environment::{process_gas_info, DebugInfo, Environment}; use crate::errors::{CommunicationError, VmError, VmResult}; #[cfg(feature = "iterator")] use crate::memory::maybe_read_region; @@ -387,10 +388,17 @@ pub fn do_debug( env: &Environment, message_ptr: u32, ) -> VmResult<()> { - if env.print_debug { + if let Some(debug_handler) = env.debug_handler() { let message_data = read_region(&env.memory(), message_ptr, MAX_LENGTH_DEBUG)?; let msg = String::from_utf8_lossy(&message_data); - println!("{}", msg); + let gas_remaining = env.get_gas_left(); + (*debug_handler)( + &msg, + DebugInfo { + gas_remaining, + __lifetime: PhantomData::default(), + }, + ); } Ok(()) } @@ -540,7 +548,7 @@ mod tests { Box, ) { let gas_limit = TESTING_GAS_LIMIT; - let env = Environment::new(api, gas_limit, false); + let env = Environment::new(api, gas_limit); let module = compile(CONTRACT, TESTING_MEMORY_LIMIT, &[]).unwrap(); let store = module.store(); diff --git a/packages/vm/src/instance.rs b/packages/vm/src/instance.rs index dd33e90b2c..92679422a2 100644 --- a/packages/vm/src/instance.rs +++ b/packages/vm/src/instance.rs @@ -1,5 +1,6 @@ use std::collections::{HashMap, HashSet}; use std::ptr::NonNull; +use std::rc::Rc; use std::sync::Mutex; use wasmer::{Exports, Function, ImportObject, Instance as WasmerInstance, Module, Val}; @@ -20,6 +21,8 @@ use crate::memory::{read_region, write_region}; use crate::size::Size; use crate::wasm_backend::compile; +pub use crate::environment::DebugInfo; // Re-exported as public via to be usable for set_debug_handler + #[derive(Copy, Clone, Debug)] pub struct GasReport { /// The original limit the instance was created with @@ -85,7 +88,12 @@ where ) -> VmResult { let store = module.store(); - let env = Environment::new(backend.api, gas_limit, print_debug); + let env = Environment::new(backend.api, gas_limit); + if print_debug { + env.set_debug_handler(Some(Rc::new(|msg: &str, _gas_remaining| { + eprintln!("{msg}"); + }))) + } let mut import_obj = ImportObject::new(); let mut env_imports = Exports::new(); @@ -265,6 +273,17 @@ where } } + pub fn set_debug_handler(&mut self, debug_handler: H) + where + H: for<'a> Fn(/* msg */ &'a str, DebugInfo<'a>) + 'static, + { + self.env.set_debug_handler(Some(Rc::new(debug_handler))); + } + + pub fn unset_debug_handler(&mut self) { + self.env.set_debug_handler(None); + } + /// Returns the features required by this contract. /// /// This is not needed for production because we can do static analysis @@ -386,6 +405,7 @@ where mod tests { use std::sync::atomic::{AtomicBool, Ordering}; use std::sync::Arc; + use std::time::SystemTime; use super::*; use crate::backend::Storage; @@ -405,6 +425,44 @@ mod tests { const MIB: usize = 1024 * 1024; const DEFAULT_QUERY_GAS_LIMIT: u64 = 300_000; static CONTRACT: &[u8] = include_bytes!("../testdata/hackatom.wasm"); + static CYBERPUNK: &[u8] = include_bytes!("../testdata/cyberpunk.wasm"); + + #[test] + fn set_debug_handler_and_unset_debug_handler_work() { + const LIMIT: u64 = 70_000_000_000_000; + let mut instance = mock_instance_with_gas_limit(CYBERPUNK, LIMIT); + + // init contract + let info = mock_info("creator", &coins(1000, "earth")); + call_instantiate::<_, _, _, Empty>(&mut instance, &mock_env(), &info, br#"{}"#) + .unwrap() + .unwrap(); + + let info = mock_info("caller", &[]); + call_execute::<_, _, _, Empty>(&mut instance, &mock_env(), &info, br#"{"debug":{}}"#) + .unwrap() + .unwrap(); + + let start = SystemTime::now(); + instance.set_debug_handler(move |msg, info| { + let gas = info.gas_remaining; + let runtime = SystemTime::now().duration_since(start).unwrap().as_micros(); + eprintln!("{msg} (gas: {gas}, runtime: {runtime}µs)"); + }); + + let info = mock_info("caller", &[]); + call_execute::<_, _, _, Empty>(&mut instance, &mock_env(), &info, br#"{"debug":{}}"#) + .unwrap() + .unwrap(); + + eprintln!("Unsetting debug handler. From here nothing is printed anymore."); + instance.unset_debug_handler(); + + let info = mock_info("caller", &[]); + call_execute::<_, _, _, Empty>(&mut instance, &mock_env(), &info, br#"{"debug":{}}"#) + .unwrap() + .unwrap(); + } #[test] fn required_capabilities_works() { diff --git a/packages/vm/src/lib.rs b/packages/vm/src/lib.rs index 19bb888f82..1e5ba03837 100644 --- a/packages/vm/src/lib.rs +++ b/packages/vm/src/lib.rs @@ -45,7 +45,7 @@ pub use crate::errors::{ CommunicationError, CommunicationResult, RegionValidationError, RegionValidationResult, VmError, VmResult, }; -pub use crate::instance::{GasReport, Instance, InstanceOptions}; +pub use crate::instance::{DebugInfo, GasReport, Instance, InstanceOptions}; pub use crate::serde::{from_slice, to_vec}; pub use crate::size::Size; diff --git a/packages/vm/testdata/cyberpunk.wasm b/packages/vm/testdata/cyberpunk.wasm index 96737a3388..68aa44257f 100644 Binary files a/packages/vm/testdata/cyberpunk.wasm and b/packages/vm/testdata/cyberpunk.wasm differ