From f96b7297860deb5cd7035aeb2c8a30fcf96836d7 Mon Sep 17 00:00:00 2001 From: Willem Wyndham Date: Tue, 3 Dec 2024 13:37:39 -0500 Subject: [PATCH] feat: Add proper logging of simulation/extend/restore events --- Cargo.lock | 2 + cmd/crates/soroban-test/Cargo.toml | 2 + cmd/crates/soroban-test/tests/it/log.rs | 36 +++++++++++++ cmd/crates/soroban-test/tests/it/main.rs | 1 + cmd/soroban-cli/src/assembled.rs | 21 +++----- .../src/commands/contract/extend.rs | 2 +- .../src/commands/contract/restore.rs | 2 +- cmd/soroban-cli/src/log.rs | 2 + cmd/soroban-cli/src/log/diagnostic_event.rs | 51 +++++++++++++++++++ 9 files changed, 103 insertions(+), 16 deletions(-) create mode 100644 cmd/crates/soroban-test/tests/it/log.rs create mode 100644 cmd/soroban-cli/src/log/diagnostic_event.rs diff --git a/Cargo.lock b/Cargo.lock index 6789ea504..57e2c938c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4614,6 +4614,8 @@ dependencies = [ "thiserror", "tokio", "toml", + "tracing", + "tracing-subscriber", "ulid", "walkdir", "which", diff --git a/cmd/crates/soroban-test/Cargo.toml b/cmd/crates/soroban-test/Cargo.toml index d035652d1..233c7b39e 100644 --- a/cmd/crates/soroban-test/Cargo.toml +++ b/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 = [] diff --git a/cmd/crates/soroban-test/tests/it/log.rs b/cmd/crates/soroban-test/tests/it/log.rs new file mode 100644 index 000000000..0f26a049b --- /dev/null +++ b/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>>, +} + +impl tracing_subscriber::Layer 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"))); +} diff --git a/cmd/crates/soroban-test/tests/it/main.rs b/cmd/crates/soroban-test/tests/it/main.rs index 5a0b2a07f..fef9b36e0 100644 --- a/cmd/crates/soroban-test/tests/it/main.rs +++ b/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; diff --git a/cmd/soroban-cli/src/assembled.rs b/cmd/soroban-cli/src/assembled.rs index 312863d52..4ff6198df 100644 --- a/cmd/soroban-cli/src/assembled.rs +++ b/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> = 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> = + events.iter().map(|event| Ok(event.clone())).collect(); + + let event_xdrs: Vec = 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( + diagnostic_events: &[Result], + 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 + } + } +}