wip

Author: amackillop

src/liquidity.rs

@@ -1196,6 +1196,13 @@ where
 				amt_to_forward_msat,
 				channel_count
 			}) => {
+				log_info!(
+					self.logger,
+					"Handling LSPS4 OpenChannel for peer {} (amt_to_forward_msat={}, channel_count={})",
+					their_network_key,
+					amt_to_forward_msat,
+					channel_count,
+				);
 				if self.liquidity_manager.lsps4_service_handler().is_none() {
 					log_error!(self.logger, "Failed to handle LSPS4ServiceEvent as LSPS4 liquidity service was not configured.",);
 					return;
@@ -1232,6 +1239,11 @@ where
 					log_error!(self.logger, "Failed to handle LSPS4ServiceEvent as peer manager isn't available. This should never happen.",);
 					return;
 				};
+				log_info!(
+					self.logger,
+					"LSPS4 OpenChannel peer {} is connected; computing channel size",
+					their_network_key,
+				);
 
 				// Fail if we have insufficient onchain funds available.
 				let over_provisioning_msat = (amt_to_forward_msat
@@ -1284,6 +1296,14 @@ where
 					// succeed.
 					return;
 				}
+				log_info!(
+					self.logger,
+					"LSPS4 OpenChannel peer {} passed funding checks (channel_amount_sats={}, required_funds_sats={}, spendable_amount_sats={})",
+					their_network_key,
+					channel_amount_sats,
+					required_funds_sats,
+					spendable_amount_sats,
+				);
 
 				let mut config = self.channel_manager.get_current_config().clone();
 
@@ -1307,6 +1327,13 @@ where
 
 				// TODO: does LSPS4 service need to track this? seems like no?
 				let user_channel_id = 0;
+				log_info!(
+					self.logger,
+					"Calling create_channel for LSPS4 peer {} (channel_amount_sats={}, user_channel_id={})",
+					their_network_key,
+					channel_amount_sats,
+					user_channel_id,
+				);
 
 				match self.channel_manager.create_channel(
 					their_network_key,
@@ -1316,7 +1343,14 @@ where
 					None,
 					Some(config),
 				) {
-					Ok(_) => {},
+					Ok(_) => {
+						log_info!(
+							self.logger,
+							"LSPS4 create_channel accepted for peer {} (channel_amount_sats={})",
+							their_network_key,
+							channel_amount_sats,
+						);
+					},
 					Err(e) => {
 						// TODO: We just silently fail here. Eventually we will need to remember
 						// the pending requests and regularly retry opening the channel until we

src/wallet/mod.rs

@@ -10,6 +10,7 @@ use std::ops::Deref;
 use std::pin::Pin;
 use std::str::FromStr;
 use std::sync::{Arc, Mutex};
+use std::time::Instant;
 
 use bdk_chain::spk_client::{FullScanRequest, SyncRequest};
 use bdk_wallet::descriptor::ExtendedDescriptor;
@@ -320,7 +321,28 @@ impl Wallet {
 	pub(crate) fn get_balances(
 		&self, total_anchor_channels_reserve_sats: u64,
 	) -> Result<(u64, u64), Error> {
-		let balance = self.inner.lock().unwrap().balance();
+		let lock_wait_start = Instant::now();
+		log_info!(
+			self.logger,
+			"Wallet get_balances starting (reserve_sats={})",
+			total_anchor_channels_reserve_sats,
+		);
+		let locked_wallet = self.inner.lock().unwrap();
+		let lock_wait_ms = lock_wait_start.elapsed().as_millis();
+		log_info!(
+			self.logger,
+			"Wallet get_balances acquired wallet lock in {}ms",
+			lock_wait_ms,
+		);
+		let balance_start = Instant::now();
+		let balance = locked_wallet.balance();
+		let balance_ms = balance_start.elapsed().as_millis();
+		log_info!(
+			self.logger,
+			"Wallet get_balances fetched BDK balance in {}ms",
+			balance_ms,
+		);
+		drop(locked_wallet);
 
 		// Make sure `list_confirmed_utxos` returns at least one `Utxo` we could use to spend/bump
 		// Anchors if we have any confirmed amounts.
@@ -332,7 +354,14 @@ impl Wallet {
 			);
 		}
 
-		self.get_balances_inner(balance, total_anchor_channels_reserve_sats)
+		let balances = self.get_balances_inner(balance, total_anchor_channels_reserve_sats)?;
+		log_info!(
+			self.logger,
+			"Wallet get_balances computed balances total_sats={} spendable_sats={}",
+			balances.0,
+			balances.1,
+		);
+		Ok(balances)
 	}
 
 	fn get_balances_inner(