Merge pull request #1667 from CosmWasm/debug-harder

Make debug handler customizable

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
 

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
       }
     ]
   },

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
     }
   ]
 }

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<Response, ContractError> {
     Ok(Response::new().set_data(to_binary(&env)?))
 }
 
+fn execute_debug(api: &dyn Api) -> Result<Response, ContractError> {
+    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<QueryResponse> {
     use QueryMsg::*;
@@ -162,3 +190,34 @@ pub fn query(_deps: Deps, env: Env, msg: QueryMsg) -> StdResult<QueryResponse> {
 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<MockStorage, MockApi, MockQuerier> {
+        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();
+    }
+}

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]

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, &[]);

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"