Log Rust test progress in CI

Enable CI to show Rust integration test logs by running both Rust
test jobs with nocapture and setting RUST_LOG for the SDK,
rebalancer, LDK node, and test harness targets.

Mark the integration tests with the existing test-log attribute and
add progress breadcrumbs around shared setup, polling waits, test
execution, and cleanup. This should make future stalls show the phase
and test location that stopped making progress.

Author: benthecarman

.github/workflows/tests.yml

@@ -11,6 +11,10 @@ concurrency:
   group: ${{ github.workflow }}-${{ github.ref }}
   cancel-in-progress: true
 
+env:
+  RUST_BACKTRACE: 1
+  RUST_LOG: orange_sdk=debug,graduated_rebalancer=debug,ldk_node=info,integration_tests=info,test_utils=info
+
 jobs:
   rust_tests:
     name: Rust Checks
@@ -40,7 +44,7 @@ jobs:
         run: cargo check -p orange-cli
 
       - name: Run tests
-        run: cargo test --features _test-utils -- --test-threads=2
+        run: cargo test --features _test-utils -- --test-threads=2 --nocapture
 
   cashu_tests:
     name: Cashu Tests
@@ -59,4 +63,4 @@ jobs:
       - uses: Swatinem/rust-cache@v2.7.8
 
       - name: Run cashu tests
-        run: cargo test --features _cashu-tests -- --test-threads=2
+        run: cargo test --features _cashu-tests -- --test-threads=2 --nocapture

orange-sdk/tests/integration_tests.rs

@@ -16,6 +16,7 @@ use std::time::Duration;
 mod test_utils;
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_node_start() {
 	test_utils::run_test(|params| async move {
 		let bal = params.wallet.get_balance().await.unwrap();
@@ -84,6 +85,7 @@ async fn test_receive_to_trusted() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_pay_from_trusted() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -168,6 +170,7 @@ async fn test_pay_from_trusted() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_sweep_to_ln() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -327,6 +330,7 @@ async fn test_sweep_to_ln() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_receive_to_ln() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -694,6 +698,7 @@ async fn run_test_pay_lightning_from_self_custody(amountless: bool) {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_pay_lightning_from_self_custody() {
 	run_test_pay_lightning_from_self_custody(false).await;
 	run_test_pay_lightning_from_self_custody(true).await;
@@ -788,12 +793,14 @@ async fn run_test_pay_bolt12_from_self_custody(amountless: bool) {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_pay_bolt12_from_self_custody() {
 	run_test_pay_bolt12_from_self_custody(false).await;
 	run_test_pay_bolt12_from_self_custody(true).await;
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_pay_onchain_from_self_custody() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -1009,6 +1016,7 @@ async fn test_pay_onchain_from_channel() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_force_close_handling() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -1058,6 +1066,7 @@ async fn test_force_close_handling() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_close_all_channels() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -1099,6 +1108,7 @@ async fn test_close_all_channels() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_threshold_boundary_trusted_balance_limit() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -1182,6 +1192,7 @@ async fn test_threshold_boundary_trusted_balance_limit() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_threshold_boundary_rebalance_min() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -1260,6 +1271,7 @@ async fn test_threshold_boundary_rebalance_min() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_threshold_boundary_onchain_receive_threshold() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -1329,6 +1341,7 @@ async fn test_threshold_boundary_onchain_receive_threshold() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_threshold_combinations_and_edge_cases() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -1393,6 +1406,7 @@ async fn test_threshold_combinations_and_edge_cases() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_invalid_payment_instructions() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -1459,6 +1473,7 @@ async fn test_invalid_payment_instructions() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_payment_with_expired_invoice() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -1492,6 +1507,7 @@ async fn test_payment_with_expired_invoice() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_payment_network_mismatch() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -1554,6 +1570,7 @@ async fn test_payment_network_mismatch() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_concurrent_payments() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -1750,6 +1767,7 @@ async fn test_concurrent_payments() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_concurrent_receive_operations() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -1809,6 +1827,7 @@ async fn test_concurrent_receive_operations() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_balance_consistency_under_load() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -1864,6 +1883,7 @@ async fn test_balance_consistency_under_load() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_invalid_tunables_relationships() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -1956,6 +1976,7 @@ async fn test_invalid_tunables_relationships() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_extreme_amount_handling() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -2027,6 +2048,7 @@ async fn test_extreme_amount_handling() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_wallet_configuration_validation() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -2093,6 +2115,7 @@ async fn test_wallet_configuration_validation() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_edge_case_payment_instruction_parsing() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);
@@ -2149,6 +2172,7 @@ async fn test_edge_case_payment_instruction_parsing() {
 }
 
 #[tokio::test(flavor = "multi_thread")]
+#[test_log::test]
 async fn test_lsp_connectivity_fallback() {
 	test_utils::run_test(|params| async move {
 		let wallet = Arc::clone(&params.wallet);

orange-sdk/tests/test_utils.rs

@@ -45,11 +45,14 @@ where
 	};
 	let start = tokio::time::Instant::now();
 	let mut delay = Duration::from_millis(50);
+	log::info!("waiting for condition: {condition_name}");
 	loop {
 		if condition().await {
+			log::info!("condition met: {condition_name} after {:?}", start.elapsed());
 			return;
 		}
 		if start.elapsed() >= timeout {
+			log::warn!("condition timed out: {condition_name} after {:?}", start.elapsed());
 			panic!("Timeout waiting for condition: {condition_name}");
 		}
 		tokio::time::sleep(delay).await;
@@ -312,14 +315,63 @@ pub(crate) async fn stop_ldk_node(name: &'static str, node: Arc<Node>) {
 /// Runs a test with automatically managed TestParams lifecycle.
 /// The test closure receives TestParams and must return it when done.
 /// Cleanup happens automatically after the test completes.
-pub async fn run_test<F, Fut>(test: F)
+#[track_caller]
+pub fn run_test<F, Fut>(test: F) -> impl Future<Output = ()>
 where
 	F: FnOnce(TestParams) -> Fut + Send + 'static,
 	Fut: Future<Output = ()> + Send + 'static,
 {
+	let caller = std::panic::Location::caller();
+	let test_name = format!("{}:{}", caller.file(), caller.line());
+
+	async move { run_test_with_name(test_name, test).await }
+}
+
+async fn run_test_with_name<F, Fut>(test_name: String, test: F)
+where
+	F: FnOnce(TestParams) -> Fut + Send + 'static,
+	Fut: Future<Output = ()> + Send + 'static,
+{
+	let lifecycle_timeout = if std::env::var("CI").is_ok() {
+		Duration::from_secs(20 * 60)
+	} else {
+		Duration::from_secs(10 * 60)
+	};
+
+	log::info!("spawning test lifecycle for {test_name}");
+
+	let (sender, receiver) = tokio::sync::oneshot::channel();
+	let lifecycle_name = test_name.clone();
+	std::thread::spawn(move || {
+		let result = std::panic::catch_unwind(std::panic::AssertUnwindSafe(|| {
+			let runtime = tokio::runtime::Builder::new_multi_thread()
+				.enable_all()
+				.build()
+				.expect("failed to create test runtime");
+			runtime.block_on(run_test_inner(lifecycle_name, test));
+		}));
+		let _ = sender.send(result);
+	});
+
+	match tokio::time::timeout(lifecycle_timeout, receiver).await {
+		Ok(Ok(Ok(()))) => {},
+		Ok(Ok(Err(panic))) => std::panic::resume_unwind(panic),
+		Ok(Err(_)) => panic!("test lifecycle thread exited without a result"),
+		Err(_) => panic!("test lifecycle timed out after {lifecycle_timeout:?} for {test_name}"),
+	}
+}
+
+async fn run_test_inner<F, Fut>(test_name: String, test: F)
+where
+	F: FnOnce(TestParams) -> Fut + Send + 'static,
+	Fut: Future<Output = ()> + Send + 'static,
+{
+	log::info!("test lifecycle started for {test_name}");
+	log::info!("building test nodes for {test_name}");
 	let params = build_test_nodes().await;
 
-	println!("=== test start ===");
+	log::info!("test body starting for {test_name}");
+	println!("=== test start: {test_name} ===");
 
 	let test_timeout = if std::env::var("CI").is_ok() {
 		Duration::from_secs(15 * 60)
@@ -334,6 +386,7 @@ where
 	let test_result = tokio::select! {
 		res = &mut test_task => Ok(res),
 		_ = tokio::time::sleep(test_timeout) => {
+			log::warn!("test body timed out for {test_name} after {test_timeout:?}");
 			test_task.abort();
 			let _ = tokio::time::timeout(Duration::from_secs(5), &mut test_task).await;
 			Err(())
@@ -342,9 +395,12 @@ where
 
 	// Always clean up
 	let timeout = Duration::from_secs(45);
+	log::info!("test cleanup starting for {test_name}");
 	if tokio::time::timeout(timeout, params.stop()).await.is_err() {
+		log::warn!("test cleanup timed out for {test_name} after {timeout:?}");
 		eprintln!("Warning: params stop timed out after {timeout:?}");
 	}
+	log::info!("test cleanup finished for {test_name}");
 
 	match test_result {
 		Ok(Ok(())) => {},
@@ -356,11 +412,14 @@ where
 
 async fn build_test_nodes() -> TestParams {
 	let test_id = Uuid::now_v7();
+	log::info!("creating bitcoind and electrsd for {test_id}");
 	let (bitcoind, electrsd) = create_bitcoind(test_id).await;
 
+	log::info!("creating LSP and third-party nodes for {test_id}");
 	let lsp = create_lsp(test_id, &bitcoind);
 	let third_party = create_third_party(test_id, &bitcoind);
 	let start_bal = third_party.list_balances().total_onchain_balance_sats;
+	log::info!("funding LSP and third-party nodes for {test_id}");
 	fund_two_nodes(&lsp, &third_party, &bitcoind, &electrsd).await;
 
 	// wait for node to sync (needs blocking wait as we are not in async context here)
@@ -374,6 +433,7 @@ async fn build_test_nodes() -> TestParams {
 	let lsp_listen = lsp.listening_addresses().unwrap().first().unwrap().clone();
 
 	// open a channel from payer to LSP
+	log::info!("opening third-party channel to LSP for {test_id}");
 	third_party.open_channel(lsp.node_id(), lsp_listen.clone(), 10_000_000, None, None).unwrap();
 	wait_for_tx_broadcast(&bitcoind).await;
 	generate_blocks(&bitcoind, &electrsd, 6).await;
@@ -395,6 +455,7 @@ async fn build_test_nodes() -> TestParams {
 
 	#[cfg(not(feature = "_cashu-tests"))]
 	let wallet = {
+		log::info!("creating dummy trusted wallet for {test_id}");
 		let dummy_wallet_config = DummyTrustedWalletExtraConfig {
 			uuid: test_id,
 			lsp: Arc::clone(&lsp),
@@ -427,6 +488,7 @@ async fn build_test_nodes() -> TestParams {
 	#[cfg(feature = "_cashu-tests")]
 	{
 		let tmp = temp_dir().join(format!("orange-test-{test_id}/cashu-ldk-node"));
+		log::info!("creating Cashu trusted wallet fixtures for {test_id}");
 		let cookie = bitcoind.params.get_cookie_values().unwrap().unwrap();
 		let bitcoind_port = bitcoind.params.rpc_socket.port();
 		let cdk_port = {
@@ -569,11 +631,15 @@ async fn build_test_nodes() -> TestParams {
 		};
 		let wallet = Arc::new(Wallet::new(wallet_config).await.unwrap());
 
+		log::info!("finished building test nodes for {test_id}");
 		return TestParams { wallet, lsp, third_party, bitcoind, electrsd, _mint: mint };
 	};
 
 	#[cfg(not(feature = "_cashu-tests"))]
-	TestParams { wallet, lsp, third_party, bitcoind, electrsd }
+	{
+		log::info!("finished building test nodes for {test_id}");
+		TestParams { wallet, lsp, third_party, bitcoind, electrsd }
+	}
 }
 
 pub async fn open_channel_from_lsp(wallet: &orange_sdk::Wallet, payer: Arc<Node>) -> Amount {
@@ -626,12 +692,15 @@ async fn wait_for_tx_broadcast(bitcoind: &Bitcoind) {
 	};
 	let start = tokio::time::Instant::now();
 	let mut delay = Duration::from_millis(50);
+	log::info!("waiting for tx broadcast");
 	loop {
 		let num_txs = bitcoind.client.get_mempool_info().unwrap().size;
 		if num_txs > 0 {
+			log::info!("tx broadcast observed after {:?}", start.elapsed());
 			break;
 		}
 		if start.elapsed() >= timeout {
+			log::warn!("tx broadcast timed out after {:?}", start.elapsed());
 			panic!("Timeout waiting for tx broadcast");
 		}
 		tokio::time::sleep(delay).await;