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

cmd/crates/soroban-test/Cargo.toml

@@ -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"
 
 [features]
 it = []

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

@@ -0,0 +1,36 @@
+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 = vec![
+                "AAAAAAAAAAAAAAAAAAAAAgAAAAAAAAADAAAADwAAAAdmbl9jYWxsAAAAAA0AAAAgfKvD/pIJPlRnGd3RKaBZSHfoq/nJbJSYxkVTScSbhuYAAAAPAAAABGRlY3IAAAAB".to_string(),
+                "AAAAAAAAAAAAAAABfKvD/pIJPlRnGd3RKaBZSHfoq/nJbJSYxkVTScSbhuYAAAACAAAAAAAAAAEAAAAPAAAAA2xvZwAAAAAQAAAAAQAAAAIAAAAOAAAACWNvdW50OiB7fQAAAAAAAAMAAAAA".to_string(),
+                "AAAAAAAAAAAAAAABfKvD/pIJPlRnGd3RKaBZSHfoq/nJbJSYxkVTScSbhuYAAAACAAAAAAAAAAIAAAAPAAAABWVycm9yAAAAAAAAAgAAAAEAAAAGAAAAEAAAAAEAAAACAAAADgAAACdWTSBjYWxsIHRyYXBwZWQ6IFVucmVhY2hhYmxlQ29kZVJlYWNoZWQAAAAADwAAAARkZWNy".to_string(),
+            ];
+        soroban_cli::log::sim_diagnostic_events(&events, tracing::Level::ERROR);
+    });
+
+    let captured_logs = logs.lock().unwrap();
+    assert!(captured_logs.iter().any(|log| log.contains("0: \"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/main.rs

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

cmd/soroban-cli/src/assembled.rs

@@ -24,9 +24,14 @@ pub async fn simulate_and_assemble_transaction(
         }))
         .await?;
     match sim_res.error {
-        None => Ok(Assembled::new(tx, sim_res)?),
+        None => {
+            if !sim_res.events.is_empty() {
+                crate::log::sim_diagnostic_events(&sim_res.events, tracing::Level::INFO);
+            }
+            Ok(Assembled::new(tx, sim_res)?)
+        }
         Some(e) => {
-            diagnostic_events(&sim_res.events, tracing::Level::ERROR);
+            crate::log::sim_diagnostic_events(&sim_res.events, tracing::Level::ERROR);
             Err(Error::TransactionSimulationFailed(e))
         }
     }
@@ -284,18 +289,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/commands/contract/extend.rs

@@ -184,7 +184,7 @@ impl NetworkRunnable for Cmd {
 
         let events = res.events()?;
         if !events.is_empty() {
-            tracing::info!("Events:\n {events:#?}");
+            crate::log::diagnostic_events(&events, tracing::Level::INFO);
         }
         let meta = res.result_meta.ok_or(Error::MissingOperationResult)?;
 

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

@@ -184,7 +184,7 @@ impl NetworkRunnable for Cmd {
         let events = res.events()?;
         tracing::trace!(?meta);
         if !events.is_empty() {
-            tracing::info!("Events:\n {events:#?}");
+            crate::log::diagnostic_events(&events, tracing::Level::INFO);
         }
 
         // The transaction from core will succeed regardless of whether it actually found &

cmd/soroban-cli/src/log.rs

@@ -2,11 +2,13 @@ use crate::xdr;
 
 pub mod auth;
 pub mod cost;
+pub mod diagnostic_event;
 pub mod event;
 pub mod footprint;
 
 pub use auth::*;
 pub use cost::*;
+pub use diagnostic_event::*;
 pub use event::*;
 pub use footprint::*;
 

cmd/soroban-cli/src/log/diagnostic_event.rs

@@ -0,0 +1,51 @@
+use serde_json;
+use soroban_sdk::xdr::WriteXdr;
+use stellar_xdr::curr::{DiagnosticEvent, Limits, ReadXdr};
+
+pub fn sim_diagnostic_events(events: &[String], level: tracing::Level) {
+    tracing::debug!("test");
+    let diagnostic_events: Vec<Result<DiagnosticEvent, _>> = events
+        .iter()
+        .map(|event_xdr| DiagnosticEvent::from_xdr_base64(event_xdr, Limits::none()))
+        .collect();
+
+    log_diagnostic_events(&diagnostic_events, events, level);
+}
+
+pub fn diagnostic_events(events: &[DiagnosticEvent], level: tracing::Level) {
+    let diagnostic_events: Vec<Result<DiagnosticEvent, std::convert::Infallible>> =
+        events.iter().map(|event| Ok(event.clone())).collect();
+
+    let event_xdrs: Vec<String> = events
+        .iter()
+        .map(|event| event.to_xdr_base64(Limits::none()).unwrap_or_default())
+        .collect();
+
+    log_diagnostic_events(&diagnostic_events, &event_xdrs, level);
+}
+
+fn log_diagnostic_events<E: std::fmt::Debug>(
+    diagnostic_events: &[Result<DiagnosticEvent, E>],
+    event_xdrs: &[String],
+    level: tracing::Level,
+) {
+    for (i, (event_result, event_xdr)) in diagnostic_events.iter().zip(event_xdrs).enumerate() {
+        let json_result = event_result
+            .as_ref()
+            .ok()
+            .and_then(|event| serde_json::to_string(event).ok());
+        let log_message = match (event_result, json_result) {
+            (Ok(_), Some(json)) => format!("{i}: {event_xdr:#?} {json}"),
+            (Err(e), _) => {
+                format!("{i}: {event_xdr:#?} Failed to decode DiagnosticEvent XDR: {e:#?}")
+            }
+            (Ok(_), None) => format!("{i}: {event_xdr:#?} JSON encoding of DiagnosticEvent failed"),
+        };
+        match level {
+            tracing::Level::TRACE => tracing::trace!("{}", log_message),
+            tracing::Level::INFO => tracing::info!("{}", log_message),
+            tracing::Level::ERROR => tracing::error!("{}", log_message),
+            _ => tracing::debug!("{}", log_message), // Default to debug for other levels
+        }
+    }
+}