Skip to content

Commit

Permalink
adds logging for simulation and adds JSON string representation of Di…
Browse files Browse the repository at this point in the history
…agnosticEvents
  • Loading branch information
BlaineHeffron committed Jul 29, 2024
1 parent 2d72179 commit 55e9489
Show file tree
Hide file tree
Showing 13 changed files with 139 additions and 23 deletions.
6 changes: 4 additions & 2 deletions Cargo.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

3 changes: 2 additions & 1 deletion Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -53,7 +53,8 @@ path = "cmd/soroban-cli"

[workspace.dependencies.soroban-rpc]
package = "stellar-rpc-client"
version = "21.4.0"
git = "https://github.com/AhaLabs/rs-stellar-rpc-client"
branch = "feat/diagnostic_events_decode"

[workspace.dependencies.stellar-xdr]
version = "21.2.0"
Expand Down
2 changes: 2 additions & 0 deletions cmd/crates/soroban-test/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -43,6 +43,8 @@ tokio = "1.28.1"
walkdir = "2.4.0"
ulid.workspace = true
ed25519-dalek = { workspace = true }
tracing = "0.1.40"
tracing-subscriber = "0.3.18"

[features]
it = []
36 changes: 36 additions & 0 deletions cmd/crates/soroban-test/tests/it/log.rs
Original file line number Diff line number Diff line change
@@ -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")));
}
1 change: 1 addition & 0 deletions cmd/crates/soroban-test/tests/it/main.rs
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@ mod config;
mod help;
#[cfg(feature = "it")]
mod integration;
mod log;
mod plugin;
mod util;
mod version;
4 changes: 2 additions & 2 deletions cmd/soroban-cli/src/commands/contract/deploy/asset.rs
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,7 @@ use crate::{
NetworkRunnable,
},
rpc::{Client, Error as SorobanRpcError},
utils::{contract_id_hash_from_asset, parsing::parse_asset},
utils::{self, contract_id_hash_from_asset, parsing::parse_asset},
};

#[derive(thiserror::Error, Debug)]
Expand Down Expand Up @@ -118,7 +118,7 @@ impl NetworkRunnable for Cmd {
if self.fee.build_only {
return Ok(TxnResult::Txn(tx));
}
let txn = client.simulate_and_assemble_transaction(&tx).await?;
let txn = utils::log_simulation_result(&client, &tx).await?;
let txn = self.fee.apply_to_assembled_txn(txn).transaction().clone();
if self.fee.sim_only {
return Ok(TxnResult::Txn(txn));
Expand Down
2 changes: 1 addition & 1 deletion cmd/soroban-cli/src/commands/contract/deploy/wasm.rs
Original file line number Diff line number Diff line change
Expand Up @@ -222,7 +222,7 @@ impl NetworkRunnable for Cmd {
return Ok(TxnResult::Txn(txn));
}

let txn = client.simulate_and_assemble_transaction(&txn).await?;
let txn = utils::log_simulation_result(&client, &txn).await?;
let txn = self.fee.apply_to_assembled_txn(txn).transaction().clone();
if self.fee.sim_only {
return Ok(TxnResult::Txn(txn));
Expand Down
5 changes: 2 additions & 3 deletions cmd/soroban-cli/src/commands/contract/extend.rs
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,7 @@ use crate::{
},
key,
rpc::{self, Client},
wasm, Pwd,
utils, wasm, Pwd,
};

const MAX_LEDGERS_TO_EXTEND: u32 = 535_679;
Expand Down Expand Up @@ -177,8 +177,7 @@ impl NetworkRunnable for Cmd {
if self.fee.build_only {
return Ok(TxnResult::Txn(tx));
}
let tx = client
.simulate_and_assemble_transaction(&tx)
let tx = utils::log_simulation_result(&client, &tx)
.await?
.transaction()
.clone();
Expand Down
4 changes: 1 addition & 3 deletions cmd/soroban-cli/src/commands/contract/install.rs
Original file line number Diff line number Diff line change
Expand Up @@ -163,9 +163,7 @@ impl NetworkRunnable for Cmd {
}
}
}
let txn = client
.simulate_and_assemble_transaction(&tx_without_preflight)
.await?;
let txn = utils::log_simulation_result(&client, &tx_without_preflight).await?;
let txn = self.fee.apply_to_assembled_txn(txn).transaction().clone();
if self.fee.sim_only {
return Ok(TxnResult::Txn(txn));
Expand Down
3 changes: 2 additions & 1 deletion cmd/soroban-cli/src/commands/contract/invoke.rs
Original file line number Diff line number Diff line change
Expand Up @@ -30,6 +30,7 @@ use super::super::{
use crate::commands::txn_result::{TxnEnvelopeResult, TxnResult};
use crate::commands::NetworkRunnable;
use crate::get_spec::{self, get_remote_contract_spec};
use crate::utils;
use crate::{
commands::{config::data, global, network},
rpc, Pwd,
Expand Down Expand Up @@ -359,7 +360,7 @@ impl NetworkRunnable for Cmd {
if self.fee.build_only {
return Ok(TxnResult::Txn(tx));
}
let txn = client.simulate_and_assemble_transaction(&tx).await?;
let txn = utils::log_simulation_result(&client, &tx).await?;
let txn = self.fee.apply_to_assembled_txn(txn);
if self.fee.sim_only {
return Ok(TxnResult::Txn(txn.transaction().clone()));
Expand Down
7 changes: 5 additions & 2 deletions cmd/soroban-cli/src/commands/tx/simulate.rs
Original file line number Diff line number Diff line change
@@ -1,4 +1,7 @@
use crate::xdr::{self, TransactionEnvelope, WriteXdr};
use crate::{
utils,
xdr::{self, TransactionEnvelope, WriteXdr},
};
use async_trait::async_trait;
use soroban_rpc::Assembled;

Expand Down Expand Up @@ -50,6 +53,6 @@ impl NetworkRunnable for Cmd {
let network = config.get_network()?;
let client = crate::rpc::Client::new(&network.rpc_url)?;
let tx = super::xdr::unwrap_envelope_v1(super::xdr::tx_envelope_from_stdin()?)?;
Ok(client.simulate_and_assemble_transaction(&tx).await?)
Ok(utils::log_simulation_result(&client, &tx).await?)
}
}
59 changes: 51 additions & 8 deletions cmd/soroban-cli/src/log/diagnostic_event.rs
Original file line number Diff line number Diff line change
@@ -1,11 +1,54 @@
pub 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:#?}");
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"),
};
eprintln!("{log_message}");

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
}
}
}
30 changes: 30 additions & 0 deletions cmd/soroban-cli/src/utils.rs
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
use ed25519_dalek::Signer;
use sha2::{Digest, Sha256};
use soroban_rpc::{Assembled, Client, Error as RPCError};
use stellar_strkey::ed25519::PrivateKey;

use soroban_env_host::xdr::{
Expand All @@ -11,6 +12,35 @@ use soroban_env_host::xdr::{

pub use soroban_spec_tools::contract as contract_spec;

/// # Errors
///
/// If the Simulation failed and there is no `Assembled`, it will return the error contained within
/// the `SimulateTransactionResult`. It will also log any events.
pub async fn log_simulation_result(
client: &Client,
tx: &Transaction,
) -> Result<Assembled, RPCError> {
match client.simulate_and_assemble_transaction(tx).await {
Ok(outcome) => {
if !&outcome.sim_res.events.is_empty() {
crate::log::sim_diagnostic_events(&outcome.sim_res.events, tracing::Level::INFO);
}
outcome.assembled.ok_or_else(|| {
if let Some(error) = outcome.sim_res.error {
RPCError::TransactionSimulationFailed(error)
} else {
RPCError::TransactionSimulationFailed(
"Failed to simulate transaction.".to_string(),
)
}
})
}
Err(e) => Err(RPCError::TransactionSimulationFailed(format!(
"Failed to simulate transaction: {e:#?}"
))),
}
}

/// # Errors
///
/// Might return an error
Expand Down

0 comments on commit 55e9489

Please sign in to comment.