feat: Add proper logging of simulation/extend/restore events (#1774)

* feat: Add proper logging of simulation/extend/restore events

* feat: consolidate diagnostic event logging

- Use tracing logs with DEBUG and TRACE for contract events and diagnostic events respectively.
- Use Printer to display the events in a more human readable way.
- Simulate once to determine if an invoke should send and use that result instead of simulating again

* fix: logging test

---------

Co-authored-by: Elizabeth Engelman <[email protected]>

Author: willemneal

Cargo.lock

@@ -42,6 +42,8 @@ walkdir = "2.4.0"
 ulid.workspace = true
 ed25519-dalek = { workspace = true }
 hex = { workspace = true }
+tracing = "0.1.40"
+tracing-subscriber = "0.3.18"
 httpmock = { workspace = true }
 
 [features]

cmd/crates/soroban-test/Cargo.toml

@@ -402,12 +402,9 @@ fn invoke_log(sandbox: &TestEnv, id: &str) {
         .assert()
         .success()
         .stderr(predicates::str::contains(
-            "INFO contract_event: soroban_cli::log::event: 1:",
+            r#"Event: [{"symbol":"hello"},{"symbol":""}] = {"symbol":"world"}"#,
         ))
-        .stderr(predicates::str::contains("hello"))
         .stderr(predicates::str::contains(
-            "INFO log_event: soroban_cli::log::event: 2:",
-        ))
-        .stderr(predicates::str::contains("hello {}"))
-        .stderr(predicates::str::contains("world"));
+            r#"Log: {"vec":[{"string":"hello {}"},{"symbol":"world"}]}"#,
+        ));
 }

cmd/crates/soroban-test/tests/it/integration/hello_world.rs

@@ -0,0 +1,37 @@
+use soroban_cli::xdr::{self, ReadXdr};
+use std::sync::{Arc, Mutex};
+use tracing::{Event, Subscriber};
+use tracing_subscriber::layer::{Context, SubscriberExt};
+
+struct TestSubscriber {
+    logs: Arc<Mutex<Vec<String>>>,
+}
+
+impl<S: Subscriber> tracing_subscriber::Layer<S> for TestSubscriber {
+    fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) {
+        // Capture the event data
+        let mut logs = self.logs.lock().unwrap();
+        logs.push(format!("{event:?}"));
+    }
+}
+
+#[test]
+fn test_diagnostic_events_logging() {
+    let logs = Arc::new(Mutex::new(Vec::new()));
+    let subscriber = TestSubscriber { logs: logs.clone() };
+
+    tracing::subscriber::with_default(tracing_subscriber::registry().with(subscriber), || {
+        let events = [
+                "AAAAAAAAAAAAAAAAAAAAAgAAAAAAAAADAAAADwAAAAdmbl9jYWxsAAAAAA0AAAAgfKvD/pIJPlRnGd3RKaBZSHfoq/nJbJSYxkVTScSbhuYAAAAPAAAABGRlY3IAAAAB",
+                "AAAAAAAAAAAAAAABfKvD/pIJPlRnGd3RKaBZSHfoq/nJbJSYxkVTScSbhuYAAAACAAAAAAAAAAEAAAAPAAAAA2xvZwAAAAAQAAAAAQAAAAIAAAAOAAAACWNvdW50OiB7fQAAAAAAAAMAAAAA",
+                "AAAAAAAAAAAAAAABfKvD/pIJPlRnGd3RKaBZSHfoq/nJbJSYxkVTScSbhuYAAAACAAAAAAAAAAIAAAAPAAAABWVycm9yAAAAAAAAAgAAAAEAAAAGAAAAEAAAAAEAAAACAAAADgAAACdWTSBjYWxsIHRyYXBwZWQ6IFVucmVhY2hhYmxlQ29kZVJlYWNoZWQAAAAADwAAAARkZWNy",
+            ].iter().map(|event| xdr::DiagnosticEvent::from_xdr_base64(event,xdr::Limits::none()).unwrap()).collect::<Vec<_>>();
+        soroban_cli::log::event::all(&events);
+    });
+
+    let captured_logs = logs.lock().unwrap();
+    assert!(captured_logs.iter().any(|log| log.contains(r#"AAAAAAAAAAAAAAAAAAAAAgAAAAAAAAADAAAADwAAAAdmbl9jYWxsAAAAAA0AAAAgfKvD/pIJPlRnGd3RKaBZSHfoq/nJbJSYxkVTScSbhuYAAAAPAAAABGRlY3IAAAAB {"in_successful_contract_call":false,"event":{"ext":"v0","contract_id":null,"type_":"diagnostic","body":{"v0":{"topics":[{"symbol":"fn_call"},{"bytes":"7cabc3fe92093e546719ddd129a0594877e8abf9c96c9498c6455349c49b86e6"},{"symbol":"decr"}],"data":"void"}}}}"#)));
+    assert!(captured_logs
+        .iter()
+        .any(|log| log.contains("VM call trapped")));
+}

cmd/crates/soroban-test/tests/it/log.rs

@@ -5,6 +5,7 @@ mod help;
 mod init;
 // #[cfg(feature = "it")]
 mod integration;
+mod log;
 mod plugin;
 mod rpc_provider;
 mod util;

cmd/crates/soroban-test/tests/it/main.rs

@@ -23,12 +23,12 @@ pub async fn simulate_and_assemble_transaction(
             signatures: VecM::default(),
         }))
         .await?;
-    match sim_res.error {
-        None => Ok(Assembled::new(tx, sim_res)?),
-        Some(e) => {
-            diagnostic_events(&sim_res.events, tracing::Level::ERROR);
-            Err(Error::TransactionSimulationFailed(e))
-        }
+    tracing::trace!("{sim_res:#?}");
+    if let Some(e) = &sim_res.error {
+        crate::log::event::all(&sim_res.events()?);
+        Err(Error::TransactionSimulationFailed(e.clone()))
+    } else {
+        Ok(Assembled::new(tx, sim_res)?)
     }
 }
 
@@ -284,18 +284,6 @@ fn restore(parent: &Transaction, restore: &RestorePreamble) -> Result<Transactio
     })
 }
 
-fn diagnostic_events(events: &[impl std::fmt::Debug], level: tracing::Level) {
-    for (i, event) in events.iter().enumerate() {
-        if level == tracing::Level::TRACE {
-            tracing::trace!("{i}: {event:#?}");
-        } else if level == tracing::Level::INFO {
-            tracing::info!("{i}: {event:#?}");
-        } else if level == tracing::Level::ERROR {
-            tracing::error!("{i}: {event:#?}");
-        }
-    }
-}
-
 #[cfg(test)]
 mod tests {
     use super::*;

cmd/soroban-cli/src/assembled.rs

@@ -52,6 +52,7 @@ pub async fn main() {
         let mut e_filter = EnvFilter::from_default_env()
             .add_directive("hyper=off".parse().unwrap())
             .add_directive(format!("stellar_cli={level}").parse().unwrap())
+            .add_directive("stellar_rpc_client=off".parse().unwrap())
             .add_directive(format!("soroban_cli={level}").parse().unwrap());
 
         for filter in &root.global_args.filter_logs {

cmd/soroban-cli/src/cli.rs

@@ -1,10 +1,13 @@
 use std::{fmt::Debug, path::Path, str::FromStr};
 
-use crate::xdr::{
-    Error as XdrError, ExtendFootprintTtlOp, ExtensionPoint, LedgerEntry, LedgerEntryChange,
-    LedgerEntryData, LedgerFootprint, Limits, Memo, Operation, OperationBody, Preconditions,
-    SequenceNumber, SorobanResources, SorobanTransactionData, Transaction, TransactionExt,
-    TransactionMeta, TransactionMetaV3, TtlEntry, WriteXdr,
+use crate::{
+    print::Print,
+    xdr::{
+        Error as XdrError, ExtendFootprintTtlOp, ExtensionPoint, LedgerEntry, LedgerEntryChange,
+        LedgerEntryData, LedgerFootprint, Limits, Memo, Operation, OperationBody, Preconditions,
+        SequenceNumber, SorobanResources, SorobanTransactionData, Transaction, TransactionExt,
+        TransactionMeta, TransactionMetaV3, TtlEntry, WriteXdr,
+    },
 };
 use clap::{command, Parser};
 
@@ -127,6 +130,7 @@ impl NetworkRunnable for Cmd {
         config: Option<&config::Args>,
     ) -> Result<TxnResult<u32>, Self::Error> {
         let config = config.unwrap_or(&self.config);
+        let print = Print::new(args.map_or(false, |a| a.quiet));
         let network = config.get_network()?;
         tracing::trace!(?network);
         let keys = self.key.parse_keys(&config.locator, &network)?;
@@ -184,7 +188,8 @@ impl NetworkRunnable for Cmd {
 
         let events = res.events()?;
         if !events.is_empty() {
-            tracing::info!("Events:\n {events:#?}");
+            crate::log::event::all(&events);
+            crate::log::event::contract(&events, &print);
         }
         let meta = res.result_meta.ok_or(Error::MissingOperationResult)?;
 

cmd/soroban-cli/src/commands/contract/extend.rs

@@ -12,6 +12,7 @@ use soroban_spec::read::FromWasmError;
 
 use super::super::events;
 use super::arg_parsing;
+use crate::assembled::Assembled;
 use crate::{
     assembled::simulate_and_assemble_transaction,
     commands::{
@@ -179,25 +180,23 @@ impl Cmd {
     }
 
     // uses a default account to check if the tx should be sent after the simulation
-    async fn should_send_after_sim(
+    async fn simulate(
         &self,
-        host_function_params: InvokeContractArgs,
-        rpc_client: Client,
-    ) -> Result<ShouldSend, Error> {
-        let account_details = default_account_entry();
-        let sequence: i64 = account_details.seq_num.into();
-        let AccountId(PublicKey::PublicKeyTypeEd25519(account_id)) = account_details.account_id;
+        host_function_params: &InvokeContractArgs,
+        account_details: &AccountEntry,
+        rpc_client: &Client,
+    ) -> Result<Assembled, Error> {
+        let sequence: i64 = account_details.seq_num.0;
+        let AccountId(PublicKey::PublicKeyTypeEd25519(account_id)) =
+            account_details.account_id.clone();
 
         let tx = build_invoke_contract_tx(
             host_function_params.clone(),
             sequence + 1,
             self.fee.fee,
             account_id,
         )?;
-        let txn = simulate_and_assemble_transaction(&rpc_client, &tx).await?;
-        let txn = self.fee.apply_to_assembled_txn(txn); // do we need this part?
-        let sim_res = txn.sim_response();
-        self.should_send_tx(sim_res)
+        Ok(simulate_and_assemble_transaction(rpc_client, &tx).await?)
     }
 }
 
@@ -212,6 +211,7 @@ impl NetworkRunnable for Cmd {
         config: Option<&config::Args>,
     ) -> Result<TxnResult<String>, Error> {
         let config = config.unwrap_or(&self.config);
+        let print = print::Print::new(global_args.map_or(false, |g| g.quiet));
         let network = config.get_network()?;
         tracing::trace!(?network);
         let contract_id = self
@@ -238,11 +238,12 @@ impl NetworkRunnable for Cmd {
         let (function, spec, host_function_params, signers) =
             build_host_function_parameters(&contract_id, &self.slop, &spec_entries, config)?;
 
-        let should_send_tx = self
-            .should_send_after_sim(host_function_params.clone(), client.clone())
+        let assembled = self
+            .simulate(&host_function_params, &default_account_entry(), &client)
             .await?;
+        let should_send = self.should_send_tx(&assembled.sim_res)?;
 
-        let account_details = if should_send_tx == ShouldSend::Yes {
+        let account_details = if should_send == ShouldSend::Yes {
             client
                 .verify_network_passphrase(Some(&network.network_passphrase))
                 .await?;
@@ -251,7 +252,16 @@ impl NetworkRunnable for Cmd {
                 .get_account(&config.source_account()?.to_string())
                 .await?
         } else {
-            default_account_entry()
+            if should_send == ShouldSend::DefaultNo {
+                print.infoln(
+                    "Simulation identified as read-only. Send by rerunning with `--send=yes`.",
+                );
+            }
+            let sim_res = assembled.sim_response();
+            let (return_value, events) = (sim_res.results()?, sim_res.events()?);
+            crate::log::event::all(&events);
+            crate::log::event::contract(&events, &print);
+            return Ok(output_to_string(&spec, &return_value[0].xdr, &function)?);
         };
         let sequence: i64 = account_details.seq_num.into();
         let AccountId(PublicKey::PublicKeyTypeEd25519(account_id)) = account_details.account_id;
@@ -275,69 +285,32 @@ impl NetworkRunnable for Cmd {
         if global_args.map_or(true, |a| !a.no_cache) {
             data::write(sim_res.clone().into(), &network.rpc_uri()?)?;
         }
-        let should_send = self.should_send_tx(sim_res)?;
-        let (return_value, events) = match should_send {
-            ShouldSend::Yes => {
-                let global::Args { no_cache, .. } = global_args.cloned().unwrap_or_default();
-                // Need to sign all auth entries
-                if let Some(tx) = config.sign_soroban_authorizations(&txn, &signers).await? {
-                    txn = Box::new(tx);
-                }
-                let res = client
-                    .send_transaction_polling(&config.sign_with_local_key(*txn).await?)
-                    .await?;
-                if !no_cache {
-                    data::write(res.clone().try_into()?, &network.rpc_uri()?)?;
-                }
-                let events = res
-                    .result_meta
-                    .as_ref()
-                    .map(crate::log::extract_events)
-                    .unwrap_or_default();
-                (res.return_value()?, events)
-            }
-            ShouldSend::No => (sim_res.results()?[0].xdr.clone(), sim_res.events()?),
-            ShouldSend::DefaultNo => {
-                let print = print::Print::new(global_args.map_or(false, |g| g.quiet));
-                print.infoln("Send skipped because simulation identified as read-only. Send by rerunning with `--send=yes`.");
-                (sim_res.results()?[0].xdr.clone(), sim_res.events()?)
-            }
-        };
-        crate::log::events(&events);
+        let global::Args { no_cache, .. } = global_args.cloned().unwrap_or_default();
+        // Need to sign all auth entries
+        if let Some(tx) = config.sign_soroban_authorizations(&txn, &signers).await? {
+            txn = Box::new(tx);
+        }
+        let res = client
+            .send_transaction_polling(&config.sign_with_local_key(*txn).await?)
+            .await?;
+        if !no_cache {
+            data::write(res.clone().try_into()?, &network.rpc_uri()?)?;
+        }
+        let events = res
+            .result_meta
+            .as_ref()
+            .map(crate::log::extract_events)
+            .unwrap_or_default();
+        let return_value = res.return_value()?;
+
+        crate::log::event::all(&events);
+        crate::log::event::contract(&events, &print);
         Ok(output_to_string(&spec, &return_value, &function)?)
     }
 }
 
 const DEFAULT_ACCOUNT_ID: AccountId = AccountId(PublicKey::PublicKeyTypeEd25519(Uint256([0; 32])));
 
-// fn log_auth_cost_and_footprint(resources: Option<&SorobanResources>) {
-//     if let Some(resources) = resources {
-//         crate::log::footprint(&resources.footprint);
-//         crate::log::cost(resources);
-//     }
-// }
-
-// fn resources(tx: &Transaction) -> Option<&SorobanResources> {
-//     let TransactionExt::V1(SorobanTransactionData { resources, .. }) = &tx.ext else {
-//         return None;
-//     };
-//     Some(resources)
-// }
-
-// fn auth_entries(tx: &Transaction) -> VecM<SorobanAuthorizationEntry> {
-//     tx.operations
-//         .first()
-//         .and_then(|op| match op.body {
-//             OperationBody::InvokeHostFunction(ref body) => (matches!(
-//                 body.auth.first().map(|x| &x.root_invocation.function),
-//                 Some(&SorobanAuthorizedFunction::ContractFn(_))
-//             ))
-//             .then_some(body.auth.clone()),
-//             _ => None,
-//         })
-//         .unwrap_or_default()
-// }
-
 fn default_account_entry() -> AccountEntry {
     AccountEntry {
         account_id: DEFAULT_ACCOUNT_ID,

cmd/soroban-cli/src/commands/contract/invoke.rs

@@ -129,6 +129,7 @@ impl NetworkRunnable for Cmd {
         config: Option<&config::Args>,
     ) -> Result<TxnResult<u32>, Error> {
         let config = config.unwrap_or(&self.config);
+        let print = crate::print::Print::new(args.map_or(true, |a| a.quiet));
         let network = config.get_network()?;
         tracing::trace!(?network);
         let entry_keys = self.key.parse_keys(&config.locator, &network)?;
@@ -184,7 +185,8 @@ impl NetworkRunnable for Cmd {
         let events = res.events()?;
         tracing::trace!(?meta);
         if !events.is_empty() {
-            tracing::info!("Events:\n {events:#?}");
+            crate::log::event::all(&events);
+            crate::log::event::contract(&events, &print);
         }
 
         // The transaction from core will succeed regardless of whether it actually found &