Merge branch 'main' into tx-verbose

.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"
+        cargo test --manifest-path cmd/crates/stellar-ledger/Cargo.toml --features "emulator-tests" -- --nocapture

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)"));
+}

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<Mutex<Range<u16>>> = 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<impl Exchange> {
-    LedgerSigner::new(get_http_transport("127.0.0.1", host_port).unwrap())
+async fn ledger(host_port: u16) -> LedgerSigner<impl Exchange> {
+    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<EmulatorEvent>,
 }
 
-fn get_http_transport(host: &str, port: u16) -> Result<impl Exchange, Error> {
-    Ok(EmulatorHttpTransport::new(host, port))
+fn get_runnable_image(ledger_device_model: String) -> RunnableImage<Speculos> {
+    let args = Args {
+        ledger_device_model,
+    };
+    let runnable_image: RunnableImage<Speculos> = (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<impl Exchange, Error> {
+    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<EmulatorEvent> {
     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;

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)
     }
 }

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<xdr::DiagnosticEvent> {
+    match tx_meta {
+        xdr::TransactionMeta::V3(xdr::TransactionMetaV3 {
+            soroban_meta: Some(meta),
+            ..
+        }) => meta.diagnostic_events.to_vec(),
+        _ => Vec::new(),
+    }
+}

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)
+}