diff --git a/.github/workflows/ledger-emulator.yml b/.github/workflows/ledger-emulator.yml index 87df86b94..2bf371b63 100644 --- a/.github/workflows/ledger-emulator.yml +++ b/.github/workflows/ledger-emulator.yml @@ -25,4 +25,4 @@ jobs: run: | sudo apt install -y libudev-dev - run: | - cargo test --manifest-path cmd/crates/stellar-ledger/Cargo.toml --features "emulator-tests" \ No newline at end of file + cargo test --manifest-path cmd/crates/stellar-ledger/Cargo.toml --features "emulator-tests" -- --nocapture \ No newline at end of file diff --git a/cmd/crates/soroban-test/tests/it/integration/hello_world.rs b/cmd/crates/soroban-test/tests/it/integration/hello_world.rs index 25e00f093..7cdc77b3e 100644 --- a/cmd/crates/soroban-test/tests/it/integration/hello_world.rs +++ b/cmd/crates/soroban-test/tests/it/integration/hello_world.rs @@ -134,6 +134,7 @@ async fn invoke() { handles_kebab_case(sandbox, id).await; fetch(sandbox, id).await; invoke_prng_u64_in_range_test(sandbox, id).await; + invoke_log(sandbox, id); } fn invoke_hello_world(sandbox: &TestEnv, id: &str) { @@ -381,3 +382,24 @@ async fn invoke_prng_u64_in_range_test(sandbox: &TestEnv, id: &str) { .await .is_ok()); } +fn invoke_log(sandbox: &TestEnv, id: &str) { + sandbox + .new_assert_cmd("contract") + .arg("invoke") + .arg("--id") + .arg(id) + .arg("--") + .arg("log") + .arg("--str=world") + .assert() + .success() + .stderr(predicates::str::contains( + "INFO contract_event: soroban_cli::log::event: 1: DiagnosticEvent {", + )) + .stderr(predicates::str::contains("StringM(hello)")) + .stderr(predicates::str::contains( + "INFO log_event: soroban_cli::log::event: 2: DiagnosticEvent", + )) + .stderr(predicates::str::contains("StringM(hello {})")) + .stderr(predicates::str::contains("StringM(world)")); +} diff --git a/cmd/crates/stellar-ledger/tests/test/emulator_tests.rs b/cmd/crates/stellar-ledger/tests/test/emulator_tests.rs index d22830089..6e9235bb4 100644 --- a/cmd/crates/stellar-ledger/tests/test/emulator_tests.rs +++ b/cmd/crates/stellar-ledger/tests/test/emulator_tests.rs @@ -1,9 +1,13 @@ use ledger_transport::Exchange; +use once_cell::sync::Lazy; use serde::Deserialize; use soroban_env_host::xdr::{self, Operation, OperationBody, Uint256}; use soroban_env_host::xdr::{Hash, Transaction}; +use std::ops::Range; +use std::sync::Mutex; use std::vec; +use std::net::TcpListener; use stellar_ledger::hd_path::HdPath; use stellar_ledger::{Blob, Error, LedgerSigner}; @@ -14,17 +18,19 @@ use stellar_xdr::curr::{ Memo, MuxedAccount, PaymentOp, Preconditions, SequenceNumber, TransactionExt, }; -use testcontainers::clients; +use testcontainers::{clients, core::Port, RunnableImage}; use tokio::time::sleep; +static PORT_RANGE: Lazy>> = Lazy::new(|| Mutex::new(40000..50000)); + pub const TEST_NETWORK_PASSPHRASE: &[u8] = b"Test SDF Network ; September 2015"; pub fn test_network_hash() -> Hash { use sha2::Digest; Hash(sha2::Sha256::digest(TEST_NETWORK_PASSPHRASE).into()) } -fn ledger(host_port: u16) -> LedgerSigner { - LedgerSigner::new(get_http_transport("127.0.0.1", host_port).unwrap()) +async fn ledger(host_port: u16) -> LedgerSigner { + LedgerSigner::new(get_http_transport("127.0.0.1", host_port).await.unwrap()) } mod test_helpers { @@ -44,16 +50,14 @@ use test_helpers::test::{ #[test_case("nanosp".to_string() ; "when the device is NanoS Plus")] #[tokio::test] async fn test_get_public_key(ledger_device_model: String) { - let args = Args { - ledger_device_model, - }; + let runnable_image = get_runnable_image(ledger_device_model.clone()); let docker = clients::Cli::default(); - let node = docker.run((Speculos::new(), args)); + let node = docker.run(runnable_image); let host_port = node.get_host_port_ipv4(9998); let ui_host_port: u16 = node.get_host_port_ipv4(5000); wait_for_emulator_start_text(ui_host_port).await; - let ledger = ledger(host_port); + let ledger = ledger(host_port).await; match ledger.get_public_key(&0.into()).await { Ok(public_key) => { @@ -78,16 +82,14 @@ async fn test_get_public_key(ledger_device_model: String) { #[test_case("nanosp".to_string() ; "when the device is NanoS Plus")] #[tokio::test] async fn test_get_app_configuration(ledger_device_model: String) { - let args = Args { - ledger_device_model, - }; + let runnable_image = get_runnable_image(ledger_device_model.clone()); let docker = clients::Cli::default(); - let node = docker.run((Speculos::new(), args)); + let node = docker.run(runnable_image); let host_port = node.get_host_port_ipv4(9998); let ui_host_port: u16 = node.get_host_port_ipv4(5000); wait_for_emulator_start_text(ui_host_port).await; - let ledger = ledger(host_port); + let ledger = ledger(host_port).await; match ledger.get_app_configuration().await { Ok(config) => { @@ -108,16 +110,14 @@ async fn test_get_app_configuration(ledger_device_model: String) { #[test_case("nanosp".to_string() ; "when the device is NanoS Plus")] #[tokio::test] async fn test_sign_tx(ledger_device_model: String) { - let args = Args { - ledger_device_model, - }; + let runnable_image = get_runnable_image(ledger_device_model.clone()); let docker = clients::Cli::default(); - let node = docker.run((Speculos::new(), args.clone())); + let node = docker.run(runnable_image); let host_port = node.get_host_port_ipv4(9998); let ui_host_port: u16 = node.get_host_port_ipv4(5000); wait_for_emulator_start_text(ui_host_port).await; - let ledger = Arc::new(ledger(host_port)); + let ledger = Arc::new(ledger(host_port).await); let path = HdPath(0); @@ -175,7 +175,7 @@ async fn test_sign_tx(ledger_device_model: String) { let ledger = Arc::clone(&ledger); async move { ledger.sign_transaction(path, tx, test_network_hash()).await } }); - let approve = tokio::task::spawn(approve_tx_signature(ui_host_port, args.ledger_device_model)); + let approve = tokio::task::spawn(approve_tx_signature(ui_host_port, ledger_device_model)); let result = sign.await.unwrap(); let _ = approve.await.unwrap(); @@ -199,17 +199,14 @@ async fn test_sign_tx(ledger_device_model: String) { #[test_case("nanosp".to_string() ; "when the device is NanoS Plus")] #[tokio::test] async fn test_sign_tx_hash_when_hash_signing_is_not_enabled(ledger_device_model: String) { - let args = Args { - ledger_device_model, - }; - + let runnable_image = get_runnable_image(ledger_device_model.clone()); let docker = clients::Cli::default(); - let node = docker.run((Speculos::new(), args)); + let node = docker.run(runnable_image); let host_port = node.get_host_port_ipv4(9998); let ui_host_port: u16 = node.get_host_port_ipv4(5000); wait_for_emulator_start_text(ui_host_port).await; - let ledger = ledger(host_port); + let ledger = ledger(host_port).await; let path = 0; let test_hash = b"313e8447f569233bb8db39aa607c8889"; @@ -231,18 +228,16 @@ async fn test_sign_tx_hash_when_hash_signing_is_not_enabled(ledger_device_model: #[test_case("nanosp".to_string() ; "when the device is NanoS Plus")] #[tokio::test] async fn test_sign_tx_hash_when_hash_signing_is_enabled(ledger_device_model: String) { - let args = Args { - ledger_device_model, - }; + let runnable_image = get_runnable_image(ledger_device_model.clone()); let docker = clients::Cli::default(); - let node = docker.run((Speculos::new(), args.clone())); + let node = docker.run(runnable_image); let host_port = node.get_host_port_ipv4(9998); let ui_host_port: u16 = node.get_host_port_ipv4(5000); wait_for_emulator_start_text(ui_host_port).await; enable_hash_signing(ui_host_port).await; - let ledger = Arc::new(ledger(host_port)); + let ledger = Arc::new(ledger(host_port).await); let path = 0; let mut test_hash = [0u8; 32]; @@ -262,10 +257,7 @@ async fn test_sign_tx_hash_when_hash_signing_is_enabled(ledger_device_model: Str let ledger = Arc::clone(&ledger); async move { ledger.sign_transaction_hash(path, &test_hash).await } }); - let approve = tokio::task::spawn(approve_tx_hash_signature( - ui_host_port, - args.ledger_device_model, - )); + let approve = tokio::task::spawn(approve_tx_hash_signature(ui_host_port, ledger_device_model)); let response = sign.await.unwrap(); let _ = approve.await.unwrap(); @@ -338,8 +330,65 @@ struct EventsResponse { events: Vec, } -fn get_http_transport(host: &str, port: u16) -> Result { - Ok(EmulatorHttpTransport::new(host, port)) +fn get_runnable_image(ledger_device_model: String) -> RunnableImage { + let args = Args { + ledger_device_model, + }; + let runnable_image: RunnableImage = (Speculos::new(), args).into(); + + // doing this to randomize the ports on the host so that parallel tests don't clobber each other + let (tcp_port_1, tcp_port_2) = get_available_ports(2); + runnable_image + .with_mapped_port(Port { + local: tcp_port_1, + internal: 9998, + }) + .with_mapped_port(Port { + local: tcp_port_2, + internal: 5000, + }) +} + +fn get_available_ports(n: usize) -> (u16, u16) { + let mut range = PORT_RANGE.lock().unwrap(); + let mut ports = Vec::with_capacity(n); + while ports.len() < n { + if let Some(port) = range.next() { + if let Ok(listener) = TcpListener::bind(("0.0.0.0", port)) { + ports.push(port); + drop(listener); + } + } else { + panic!("No more available ports"); + } + } + + (ports[0], ports[1]) +} + +async fn get_http_transport(host: &str, port: u16) -> Result { + let max_retries = 5; + let mut retries = 0; + let mut wait_time = Duration::from_secs(1); + // ping the emulator port to make sure it's up and running + // retry with exponential backoff + loop { + match reqwest::get(format!("http://{host}:{port}")).await { + Ok(_) => return Ok(EmulatorHttpTransport::new(host, port)), + Err(e) => { + retries += 1; + if retries >= max_retries { + println!("get_http_transport: Exceeded max retries for connecting to emulated device"); + + return Err(Error::APDUExchangeError(format!( + "Failed to connect to emulator: {e}" + ))); + } + sleep(wait_time).await; + wait_time *= 2; + } + } + } } async fn wait_for_emulator_start_text(ui_host_port: u16) { @@ -365,9 +414,7 @@ async fn get_emulator_events_with_retries( ) -> Vec { let client = reqwest::Client::new(); let mut retries = 0; - let mut wait_time = Duration::from_secs(1); - loop { match client .get(format!("http://localhost:{ui_host_port}/events")) @@ -379,10 +426,10 @@ async fn get_emulator_events_with_retries( return resp.events; } Err(e) => { - println!("this many retries: {retries}"); retries += 1; if retries >= max_retries { - panic!("Failed to get emulator events: {e}"); + println!("get_emulator_events_with_retries: Exceeded max retries"); + panic!("get_emulator_events_with_retries: Failed to get emulator events: {e}"); } sleep(wait_time).await; wait_time *= 2; diff --git a/cmd/soroban-cli/src/commands/contract/invoke.rs b/cmd/soroban-cli/src/commands/contract/invoke.rs index 041613ba2..6d0a0799b 100644 --- a/cmd/soroban-cli/src/commands/contract/invoke.rs +++ b/cmd/soroban-cli/src/commands/contract/invoke.rs @@ -386,10 +386,14 @@ impl NetworkRunnable for Cmd { if !no_cache { data::write(res.clone().try_into()?, &network.rpc_uri()?)?; } - (res.return_value()?, res.contract_events()?) + let events = res + .result_meta + .as_ref() + .map(crate::log::extract_events) + .unwrap_or_default(); + (res.return_value()?, events) }; - - crate::log::diagnostic_events(&events, tracing::Level::INFO); + crate::log::events(&events); output_to_string(&spec, &return_value, &function) } } diff --git a/cmd/soroban-cli/src/log.rs b/cmd/soroban-cli/src/log.rs index 16121982d..28ed4041b 100644 --- a/cmd/soroban-cli/src/log.rs +++ b/cmd/soroban-cli/src/log.rs @@ -1,13 +1,24 @@ +use crate::xdr; pub mod auth; pub mod budget; pub mod cost; -pub mod diagnostic_event; +pub mod event; pub mod footprint; pub mod host_event; pub use auth::*; pub use budget::*; pub use cost::*; -pub use diagnostic_event::*; +pub use event::*; pub use footprint::*; pub use host_event::*; + +pub fn extract_events(tx_meta: &xdr::TransactionMeta) -> Vec { + match tx_meta { + xdr::TransactionMeta::V3(xdr::TransactionMetaV3 { + soroban_meta: Some(meta), + .. + }) => meta.diagnostic_events.to_vec(), + _ => Vec::new(), + } +} diff --git a/cmd/soroban-cli/src/log/diagnostic_event.rs b/cmd/soroban-cli/src/log/diagnostic_event.rs deleted file mode 100644 index 68af67a4e..000000000 --- a/cmd/soroban-cli/src/log/diagnostic_event.rs +++ /dev/null @@ -1,11 +0,0 @@ -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:#?}"); - } - } -} diff --git a/cmd/soroban-cli/src/log/event.rs b/cmd/soroban-cli/src/log/event.rs new file mode 100644 index 000000000..8a4fedfbf --- /dev/null +++ b/cmd/soroban-cli/src/log/event.rs @@ -0,0 +1,44 @@ +use tracing::{debug, info, span, Level}; + +use crate::xdr; + +pub fn events(events: &[xdr::DiagnosticEvent]) { + for (i, event) in events.iter().enumerate() { + let span = if is_contract_event(event) { + span!(Level::INFO, "contract_event") + } else if is_log_event(event) { + span!(Level::INFO, "log_event") + } else { + span!(Level::DEBUG, "diagnostic_event") + }; + + let _enter = span.enter(); + + if span.metadata().unwrap().level() == &Level::INFO { + info!("{i}: {event:#?}"); + } else { + debug!("{i}: {event:#?}"); + } + } +} + +fn is_contract_event(event: &xdr::DiagnosticEvent) -> bool { + matches!(event.event.type_, xdr::ContractEventType::Contract) +} + +fn is_log_event(event: &xdr::DiagnosticEvent) -> bool { + match &event.event.body { + xdr::ContractEventBody::V0(xdr::ContractEventV0 { topics, .. }) + if topics.len() == 1 + && matches!(event.event.type_, xdr::ContractEventType::Diagnostic) => + { + topics[0] == xdr::ScVal::Symbol(str_to_sc_symbol("log")) + } + xdr::ContractEventBody::V0(_) => false, + } +} + +fn str_to_sc_symbol(s: &str) -> xdr::ScSymbol { + let inner: xdr::StringM<32> = s.try_into().unwrap(); + xdr::ScSymbol(inner) +}