Add trace functionality

CHANGELOG.md

@@ -8,6 +8,7 @@ and this project adheres to
 
 ### Added
 
+- Add `Api::trace` for emitting trace messages during development.
 - cosmwasm-vm: Add `Cache::save_wasm_unchecked` to save Wasm blobs that have
   been checked before. This is useful for state-sync where we know the Wasm code
   was checked when it was first uploaded. ([#1635])

README.md

@@ -245,6 +245,11 @@ extern "C" {
     /// In production environments it is expected that those messages are discarded.
     fn debug(source_ptr: u32);
 
+    /// Writes a trace message (UFT-8 encoded) to the host for tracing purposes.
+    /// The host is free to log or process this in any way it considers appropriate.
+    /// In production environments it is expected that those messages are discarded.
+    fn trace(source_ptr: u32);
+
     /// Executes a query on the chain (import). Not to be confused with the
     /// query export, which queries the state of the contract.
     fn query_chain(request: u32) -> u32;

contracts/hackatom/src/contract.rs

@@ -21,6 +21,7 @@ pub fn instantiate(
     msg: InstantiateMsg,
 ) -> Result<Response, HackError> {
     deps.api.debug("here we go 🚀");
+    deps.api.trace("here we go again 🚀");
 
     deps.storage.set(
         CONFIG_KEY,

packages/std/src/imports.rs

@@ -71,6 +71,11 @@ extern "C" {
     /// In production environments it is expected that those messages are discarded.
     fn debug(source_ptr: u32);
 
+    /// Writes a trace message (UFT-8 encoded) to the host for tracing purposes.
+    /// The host is free to log or process this in any way it considers appropriate.
+    /// In production environments it is expected that those messages are discarded.
+    fn trace(source_ptr: u32);
+
     /// Executes a query on the chain (import). Not to be confused with the
     /// query export, which queries the state of the contract.
     fn query_chain(request: u32) -> u32;
@@ -362,6 +367,13 @@ impl Api for ExternalApi {
         let region_ptr = region.as_ref() as *const Region as u32;
         unsafe { debug(region_ptr) };
     }
+
+    fn trace(&self, message: &str) {
+        // keep the boxes in scope, so we free it at the end (don't cast to pointers same line as build_region)
+        let region = build_region(message.as_bytes());
+        let region_ptr = region.as_ref() as *const Region as u32;
+        unsafe { trace(region_ptr) };
+    }
 }
 
 /// Takes a pointer to a Region and reads the data into a String.

packages/std/src/testing/mock.rs

@@ -228,6 +228,10 @@ impl Api for MockApi {
     fn debug(&self, message: &str) {
         println!("{}", message);
     }
+
+    fn trace(&self, message: &str) {
+        println!("{}, ts: NAµs", message);
+    }
 }
 
 /// Returns a default enviroment with height, time, chain_id, and contract address

packages/std/src/traits.rs

@@ -141,6 +141,11 @@ pub trait Api {
     /// Emits a debugging message that is handled depending on the environment (typically printed to console or ignored).
     /// Those messages are not persisted to chain.
     fn debug(&self, message: &str);
+
+    /// Emits a tracing / time-stamping message that is handled depending on the environment (typically printed to
+    /// console or ignored).
+    /// Those messages are not persisted to chain.
+    fn trace(&self, message: &str);
 }
 
 /// A short-hand alias for the two-level query result (1. accessing the contract, 2. executing query in the contract)

packages/vm/src/compatibility.rs

@@ -22,6 +22,7 @@ const SUPPORTED_IMPORTS: &[&str] = &[
     "env.ed25519_verify",
     "env.ed25519_batch_verify",
     "env.debug",
+    "env.trace",
     "env.query_chain",
     #[cfg(feature = "iterator")]
     "env.db_scan",
@@ -798,6 +799,7 @@ mod tests {
             "env.addr_canonicalize",
             "env.addr_humanize",
             "env.debug",
+            "env.trace",
             "env.query_chain",
         ];
         let result = check_wasm_imports(&deserialize_wasm(&wasm).unwrap(), supported_imports);
@@ -806,7 +808,7 @@ mod tests {
                 println!("{}", msg);
                 assert_eq!(
                     msg,
-                    r#"Wasm contract requires unsupported import: "env.foo". Required imports: {"env.bar", "env.foo", "env.spammyspam01", "env.spammyspam02", "env.spammyspam03", "env.spammyspam04", "env.spammyspam05", "env.spammyspam06", "env.spammyspam07", "env.spammyspam08", ... 2 more}. Available imports: ["env.db_read", "env.db_write", "env.db_remove", "env.addr_canonicalize", "env.addr_humanize", "env.debug", "env.query_chain"]."#
+                    r#"Wasm contract requires unsupported import: "env.foo". Required imports: {"env.bar", "env.foo", "env.spammyspam01", "env.spammyspam02", "env.spammyspam03", "env.spammyspam04", "env.spammyspam05", "env.spammyspam06", "env.spammyspam07", "env.spammyspam08", ... 2 more}. Available imports: ["env.db_read", "env.db_write", "env.db_remove", "env.addr_canonicalize", "env.addr_humanize", "env.debug", "env.trace", "env.query_chain"]."#
                 );
             }
             err => panic!("Unexpected error: {:?}", err),

packages/vm/src/imports.rs

@@ -1,6 +1,7 @@
 //! Import implementations
 
 use std::cmp::max;
+use std::time::{SystemTime, UNIX_EPOCH};
 
 use cosmwasm_crypto::{
     ed25519_batch_verify, ed25519_verify, secp256k1_recover_pubkey, secp256k1_verify, CryptoError,
@@ -395,6 +396,25 @@ pub fn do_debug<A: BackendApi, S: Storage, Q: Querier>(
     Ok(())
 }
 
+/// Prints a trace message to console.
+/// This does not charge gas, so trace printing should be disabled when used in a blockchain module.
+pub fn do_trace<A: BackendApi, S: Storage, Q: Querier>(
+    env: &Environment<A, S, Q>,
+    message_ptr: u32,
+) -> VmResult<()> {
+    if env.print_debug {
+        let message_data = read_region(&env.memory(), message_ptr, MAX_LENGTH_DEBUG)?;
+        let msg = String::from_utf8_lossy(&message_data);
+        // Print message with timestamp [µs]
+        let ts = SystemTime::now()
+            .duration_since(UNIX_EPOCH)
+            .unwrap()
+            .as_micros();
+        println!("{}, ts: {}µs", msg, ts);
+    }
+    Ok(())
+}
+
 /// Aborts the contract and shows the given error message
 pub fn do_abort<A: BackendApi, S: Storage, Q: Querier>(
     env: &Environment<A, S, Q>,
@@ -562,6 +582,7 @@ mod tests {
                 "ed25519_batch_verify" => Function::new_native(store, |_a: u32, _b: u32, _c: u32| -> u32 { 0 }),
                 "debug" => Function::new_native(store, |_a: u32| {}),
                 "abort" => Function::new_native(store, |_a: u32| {}),
+                "trace" => Function::new_native(store, |_a: u32| {}),
             },
         };
         let instance = Box::from(WasmerInstance::new(&module, &import_obj).unwrap());

packages/vm/src/instance.rs

@@ -12,7 +12,7 @@ use crate::errors::{CommunicationError, VmError, VmResult};
 use crate::imports::{
     do_abort, do_addr_canonicalize, do_addr_humanize, do_addr_validate, do_db_read, do_db_remove,
     do_db_write, do_debug, do_ed25519_batch_verify, do_ed25519_verify, do_query_chain,
-    do_secp256k1_recover_pubkey, do_secp256k1_verify,
+    do_secp256k1_recover_pubkey, do_secp256k1_verify, do_trace,
 };
 #[cfg(feature = "iterator")]
 use crate::imports::{do_db_next, do_db_scan};
@@ -181,6 +181,15 @@ where
             Function::new_native_with_env(store, env.clone(), do_debug),
         );
 
+        // Allows the contract to emit trace logs that the host can either process or ignore.
+        // This is never written to chain.
+        // Takes a pointer argument of a memory region that must contain an UTF-8 encoded string.
+        // Ownership of both input and output pointer is not transferred to the host.
+        env_imports.insert(
+            "trace",
+            Function::new_native_with_env(store, env.clone(), do_trace),
+        );
+
         // Aborts the contract execution with an error message provided by the contract.
         // Takes a pointer argument of a memory region that must contain an UTF-8 encoded string.
         // Ownership of both input and output pointer is not transferred to the host.