Route Soroban TraceHook-based tracing into core trace-level tx logging

Author: graydon

Cargo.lock

@@ -22,6 +22,9 @@ include = [
     "std::sys::unix::rand::hashmap_random_keys",
     "hashbrown::raw",
 ]
+no_auto_detect = [
+    "soroban-env-common",
+]
 
 [api.rand]
 include = [

cackle.toml

@@ -21,6 +21,7 @@ rand = "=0.8.5"
 
 petgraph = "=0.6.4"
 toml = "=0.7.8"
+itertools = "=0.11.0"
 
 # This copy of the soroban host is always enabled, and should always point to a
 # version that supports stellar-core's Config::CURRENT_LEDGER_PROTOCOL_VERSION.
@@ -35,7 +36,7 @@ toml = "=0.7.8"
 version = "=20.1.0"
 git = "https://github.com/stellar/rs-soroban-env"
 package = "soroban-env-host"
-rev = "c1b238b65bfd13666be4ac14e0e390c31b549caf"
+rev = "b6ef8e32d86b008b2ecfdb2d7ca958e751190523"
 
 # This copy of the soroban host is _optional_ and only enabled during protocol
 # transitions. When transitioning from protocol N to N+1, the `curr` copy
@@ -64,12 +65,12 @@ rev = "bed170cde09a53c85ae2e02f9278ef0dfa4e0900"
 [dependencies.soroban-test-wasms]
 version = "=20.1.0"
 git = "https://github.com/stellar/rs-soroban-env"
-rev = "c1b238b65bfd13666be4ac14e0e390c31b549caf"
+rev = "b6ef8e32d86b008b2ecfdb2d7ca958e751190523"
 
 [dependencies.soroban-synth-wasm]
 version = "=20.1.0"
 git = "https://github.com/stellar/rs-soroban-env"
-rev = "c1b238b65bfd13666be4ac14e0e390c31b549caf"
+rev = "b6ef8e32d86b008b2ecfdb2d7ca958e751190523"
 
 [dependencies.cargo-lock]
 version = "=9.0.0"

src/rust/Cargo.toml

@@ -10,8 +10,8 @@ use crate::{
         InvokeHostFunctionOutput, RustBuf, XDRFileHash,
     },
 };
-use log::debug;
-use std::{fmt::Display, io::Cursor, panic, time::Instant};
+use log::{debug, trace};
+use std::{fmt::Display, io::Cursor, panic, rc::Rc, time::Instant};
 
 // This module (contract) is bound to _two separate locations_ in the module
 // tree: crate::lo::contract and crate::hi::contract, each of which has a (lo or
@@ -286,6 +286,29 @@ pub(crate) fn invoke_host_function(
     }
 }
 
+fn make_trace_hook_fn<'a>() -> super::soroban_env_host::TraceHook {
+    let prev_state = std::cell::RefCell::new(String::new());
+    Rc::new(move |host, traceevent| {
+        if traceevent.is_begin() || traceevent.is_end() {
+            prev_state.replace(String::new());
+        }
+        match super::soroban_env_host::TraceRecord::new(host, traceevent) {
+            Ok(tr) => {
+                let state_str = format!("{}", tr.state);
+                if prev_state.borrow().is_empty() {
+                    trace!(target: TX, "{}: {}", tr.event, state_str);
+                } else {
+                    let diff = crate::log::diff_line(&prev_state.borrow(), &state_str);
+                    trace!(target: TX, "{}: {}", tr.event, diff);
+                }
+                prev_state.replace(state_str);
+            }
+            Err(e) => trace!(target: TX, "{}", e),
+        }
+        Ok(())
+    })
+}
+
 fn invoke_host_function_or_maybe_panic(
     enable_diagnostics: bool,
     instruction_limit: u32,
@@ -314,10 +337,16 @@ fn invoke_host_function_or_maybe_panic(
     )?;
     let mut diagnostic_events = vec![];
     let ledger_seq_num = ledger_info.sequence_number;
+    let trace_hook: Option<super::soroban_env_host::TraceHook> =
+        if crate::log::is_tx_tracing_enabled() {
+            Some(make_trace_hook_fn())
+        } else {
+            None
+        };
     let (res, time_nsecs) = {
         let _span1 = tracy_span!("e2e_invoke::invoke_function");
         let start_time = Instant::now();
-        let res = e2e_invoke::invoke_host_function(
+        let res = e2e_invoke::invoke_host_function_with_trace_hook(
             &budget,
             enable_diagnostics,
             hf_buf,
@@ -329,6 +358,7 @@ fn invoke_host_function_or_maybe_panic(
             ttl_entries.iter(),
             base_prng_seed,
             &mut diagnostic_events,
+            trace_hook,
         );
         let stop_time = Instant::now();
         let time_nsecs = stop_time.duration_since(start_time).as_nanos() as u64;

src/rust/src/contract.rs

@@ -1,4 +1,4 @@
-soroban-env-host 20.1.0 git+https://github.com/stellar/rs-soroban-env?rev=c1b238b65bfd13666be4ac14e0e390c31b549caf#c1b238b65bfd13666be4ac14e0e390c31b549caf
+soroban-env-host 20.1.0 git+https://github.com/stellar/rs-soroban-env?rev=b6ef8e32d86b008b2ecfdb2d7ca958e751190523#b6ef8e32d86b008b2ecfdb2d7ca958e751190523
 ├── tracy-client 0.15.2 checksum:434ecabbda9f67eeea1eab44d52f4a20538afa3e2c2770f2efc161142b25b608
 │   ├── tracy-client-sys 0.20.0 checksum:e8cf8aeb20e40d13be65a0b134f8d82d360e72b2793a11de8867d7fbc0f9d6f6
 │   │   └── cc 1.0.79 checksum:50d30906286121d95be3d479533b458f87493b30a4b5f79a607db8f5d11aa91f
@@ -97,7 +97,7 @@ soroban-env-host 20.1.0 git+https://github.com/stellar/rs-soroban-env?rev=c1b238
 │   ├── wasmi_arena 0.4.0 git+https://github.com/stellar/wasmi?rev=ab29800224d85ee64d4ac127bac84cdbb0276721#ab29800224d85ee64d4ac127bac84cdbb0276721
 │   ├── spin 0.9.8 checksum:6980e8d7511241f8acf4aebddbb1ff938df5eebe98691418c4468d0b72a96a67
 │   └── smallvec 1.10.0 checksum:a507befe795404456341dfab10cef66ead4c041f62b8b11bbb92bffe5d0953e0
-├── soroban-env-common 20.1.0 git+https://github.com/stellar/rs-soroban-env?rev=c1b238b65bfd13666be4ac14e0e390c31b549caf#c1b238b65bfd13666be4ac14e0e390c31b549caf
+├── soroban-env-common 20.1.0 git+https://github.com/stellar/rs-soroban-env?rev=b6ef8e32d86b008b2ecfdb2d7ca958e751190523#b6ef8e32d86b008b2ecfdb2d7ca958e751190523
 │   ├── tracy-client 0.15.2 checksum:434ecabbda9f67eeea1eab44d52f4a20538afa3e2c2770f2efc161142b25b608
 │   ├── stellar-xdr 20.0.2 checksum:e9f00a85bd9b1617d4cb7e741733889c9940e6bdeca360db81752b0ef04fe3a5
 │   │   ├── stellar-strkey 0.0.8 checksum:12d2bf45e114117ea91d820a846fd1afbe3ba7d717988fee094ce8227a3bf8bd
@@ -107,7 +107,7 @@ soroban-env-host 20.1.0 git+https://github.com/stellar/rs-soroban-env?rev=c1b238
 │   │   └── base64 0.13.1 checksum:9e1b586273c5702936fe7b7d6896644d8be71e6314cfe09d3167c95f712589e8
 │   ├── static_assertions 1.1.0 checksum:a2eb9349b6444b326872e140eb1cf5e7c522154d69e7a0ffb0fb81c06b37543f
 │   ├── soroban-wasmi 0.31.1-soroban.20.0.0 git+https://github.com/stellar/wasmi?rev=ab29800224d85ee64d4ac127bac84cdbb0276721#ab29800224d85ee64d4ac127bac84cdbb0276721
-│   ├── soroban-env-macros 20.1.0 git+https://github.com/stellar/rs-soroban-env?rev=c1b238b65bfd13666be4ac14e0e390c31b549caf#c1b238b65bfd13666be4ac14e0e390c31b549caf
+│   ├── soroban-env-macros 20.1.0 git+https://github.com/stellar/rs-soroban-env?rev=b6ef8e32d86b008b2ecfdb2d7ca958e751190523#b6ef8e32d86b008b2ecfdb2d7ca958e751190523
 │   │   ├── syn 2.0.39 checksum:23e78b90f2fcf45d3e842032ce32e3f2d1545ba6636271dcbf24fa306d87be7a
 │   │   ├── stellar-xdr 20.0.2 checksum:e9f00a85bd9b1617d4cb7e741733889c9940e6bdeca360db81752b0ef04fe3a5
 │   │   ├── serde_json 1.0.108 checksum:3d1c7e3eac408d115102c4c24ad393e0821bb3a5df4d506a80f85f7a742a526b
@@ -123,7 +123,7 @@ soroban-env-host 20.1.0 git+https://github.com/stellar/rs-soroban-env?rev=c1b238
 │   │   └── proc-macro2 1.0.69 checksum:134c189feb4956b20f6f547d2cf727d4c0fe06722b20a0eec87ed445a97f92da
 │   ├── ethnum 1.5.0 checksum:b90ca2580b73ab6a1f724b76ca11ab632df820fd6040c336200d2c1df7b3c82c
 │   └── crate-git-revision 0.0.6 checksum:c521bf1f43d31ed2f73441775ed31935d77901cb3451e44b38a1c1612fcbaf98
-├── soroban-builtin-sdk-macros 20.1.0 git+https://github.com/stellar/rs-soroban-env?rev=c1b238b65bfd13666be4ac14e0e390c31b549caf#c1b238b65bfd13666be4ac14e0e390c31b549caf
+├── soroban-builtin-sdk-macros 20.1.0 git+https://github.com/stellar/rs-soroban-env?rev=b6ef8e32d86b008b2ecfdb2d7ca958e751190523#b6ef8e32d86b008b2ecfdb2d7ca958e751190523
 │   ├── syn 2.0.39 checksum:23e78b90f2fcf45d3e842032ce32e3f2d1545ba6636271dcbf24fa306d87be7a
 │   ├── quote 1.0.33 checksum:5267fca4496028628a95160fc423a33e8b2e6af8a5302579e322e4b520293cae
 │   ├── proc-macro2 1.0.69 checksum:134c189feb4956b20f6f547d2cf727d4c0fe06722b20a0eec87ed445a97f92da

src/rust/src/host-dep-tree-curr.txt

@@ -3,6 +3,7 @@
 // of this distribution or at http://www.apache.org/licenses/LICENSE-2.0
 
 use cxx::let_cxx_string;
+use itertools::Itertools;
 use log::{Level, LevelFilter, Metadata, Record, SetLoggerError};
 use std::sync::atomic::{AtomicBool, Ordering};
 
@@ -55,6 +56,19 @@ pub fn init_logging(maxLevel: LogLevel) -> Result<(), SetLoggerError> {
     Ok(())
 }
 
+pub(crate) fn is_tx_tracing_enabled() -> bool {
+    let_cxx_string!(partition = partition::TX);
+    shim_isLogLevelAtLeast(&partition, LogLevel::LVL_TRACE)
+}
+
+pub(crate) fn diff_line(last: &String, new: &String) -> String {
+    last.split(',')
+        .zip(new.split(','))
+        .filter(|(a, b)| a != b)
+        .map(|(_, b)| b)
+        .join(",")
+}
+
 fn convertLogLevel(lvl: Level) -> LogLevel {
     match lvl {
         Level::Error => LogLevel::LVL_ERROR,