diff --git a/mutiny-core/src/auth.rs b/mutiny-core/src/auth.rs index 7088b2d31..3d985bd88 100644 --- a/mutiny-core/src/auth.rs +++ b/mutiny-core/src/auth.rs @@ -8,8 +8,8 @@ use crate::{ }; use async_lock::RwLock; use jwt_compact::UntrustedToken; -use lightning::util::logger::*; use lightning::{log_debug, log_error, log_info}; +use lightning::{log_trace, util::logger::*}; use lnurl::{lnurl::LnUrl, AsyncClient as LnUrlClient}; use reqwest::Client; use reqwest::{Method, StatusCode, Url}; @@ -92,6 +92,8 @@ impl MutinyAuthClient { url: Url, body: Option, ) -> Result { + log_trace!(self.logger, "Doing an authenticated request {url:?}"); + let mut request = self.http_client.request(method, url); let mut jwt = self.is_authenticated().await; diff --git a/mutiny-core/src/ldkstorage.rs b/mutiny-core/src/ldkstorage.rs index f4db75082..3825a3772 100644 --- a/mutiny-core/src/ldkstorage.rs +++ b/mutiny-core/src/ldkstorage.rs @@ -18,8 +18,6 @@ use esplora_client::AsyncClient; use futures::{try_join, TryFutureExt}; use futures_util::lock::Mutex; use hex_conservative::DisplayHex; -use lightning::chain::chainmonitor::{MonitorUpdateId, Persist}; -use lightning::chain::channelmonitor::{ChannelMonitor, ChannelMonitorUpdate}; use lightning::chain::transaction::OutPoint; use lightning::chain::{BestBlock, ChannelMonitorUpdateStatus}; use lightning::io::Cursor; @@ -30,6 +28,14 @@ use lightning::sign::{InMemorySigner, SpendableOutputDescriptor}; use lightning::util::logger::Logger; use lightning::util::persist::Persister; use lightning::util::ser::{Readable, ReadableArgs, Writeable}; +use lightning::{ + chain::chainmonitor::{MonitorUpdateId, Persist}, + log_trace, +}; +use lightning::{ + chain::channelmonitor::{ChannelMonitor, ChannelMonitorUpdate}, + log_warn, +}; use lightning::{log_debug, log_error}; use serde::{Deserialize, Serialize}; use std::collections::HashMap; @@ -213,6 +219,11 @@ impl MutinyNodePersister { let key = self.get_key(CHANNEL_MANAGER_KEY); match self.storage.get_data::(&key) { Ok(Some(versioned_value)) => { + log_trace!( + mutiny_logger, + "Got versioned value: {}", + versioned_value.version + ); // new encoding is in hex let hex: String = serde_json::from_value(versioned_value.value.clone())?; let bytes = FromHex::from_hex(&hex)?; @@ -222,12 +233,14 @@ impl MutinyNodePersister { chain_monitor, mutiny_chain, fee_estimator, - mutiny_logger, + mutiny_logger.clone(), keys_manager, router, channel_monitors, )?; + log_trace!(mutiny_logger, "parsed channel manager, swapping it"); + self.manager_version .swap(versioned_value.version, Ordering::SeqCst); @@ -235,6 +248,7 @@ impl MutinyNodePersister { } Ok(None) => { // no key manager stored, start a new one + log_debug!(mutiny_logger, "Creating a new channel manager"); Self::create_new_channel_manager( network, @@ -252,6 +266,11 @@ impl MutinyNodePersister { } Err(_) => { // old encoding with no version number and as an array of numbers + log_warn!( + mutiny_logger, + "A very old encoding of channel manager with no version number, parsing it" + ); + let bytes = self.read_value(CHANNEL_MANAGER_KEY)?; Self::parse_channel_manager( bytes, @@ -280,6 +299,8 @@ impl MutinyNodePersister { router: Arc, mut channel_monitors: Vec<(BlockHash, ChannelMonitor)>, ) -> Result, MutinyError> { + log_debug!(mutiny_logger, "Parsing channel manager"); + let mut channel_monitor_mut_references = Vec::new(); for (_, channel_monitor) in channel_monitors.iter_mut() { channel_monitor_mut_references.push(channel_monitor); @@ -292,18 +313,23 @@ impl MutinyNodePersister { chain_monitor, mutiny_chain, router, - mutiny_logger, + mutiny_logger.clone(), default_user_config(accept_underpaying_htlcs), channel_monitor_mut_references, ); + + log_trace!(mutiny_logger, "Read channel manager arguments"); let mut readable_kv_value = Cursor::new(bytes); let Ok((_, channel_manager)) = <(BlockHash, PhantomChannelManager)>::read(&mut readable_kv_value, read_args) else { + log_error!(mutiny_logger, "Could not read channel manager"); return Err(MutinyError::ReadError { source: MutinyStorageError::Other(anyhow!("could not read manager")), }); }; + + log_debug!(mutiny_logger, "Read channel manager okay"); Ok(ReadChannelManager { channel_manager, is_restarting: true, diff --git a/mutiny-core/src/lib.rs b/mutiny-core/src/lib.rs index 58da86cc9..2f1ca827a 100644 --- a/mutiny-core/src/lib.rs +++ b/mutiny-core/src/lib.rs @@ -902,6 +902,7 @@ impl MutinyWalletBuilder { )); // Need to prevent other devices from running at the same time + log_trace!(logger, "checking device lock"); if !config.skip_device_lock { let start = Instant::now(); log_trace!(logger, "Checking device lock"); @@ -915,8 +916,10 @@ impl MutinyWalletBuilder { start.elapsed().as_millis() ); } + log_trace!(logger, "finished checking device lock"); // spawn thread to claim device lock + log_trace!(logger, "spawning claim device lock"); let storage_clone = self.storage.clone(); let logger_clone = logger.clone(); let stop_clone = stop.clone(); @@ -931,13 +934,16 @@ impl MutinyWalletBuilder { } } }); + log_trace!(logger, "finished spawning claim device lock"); + log_trace!(logger, "setting up esplora"); let esplora_server_url = get_esplora_url(network, config.user_esplora_url.clone()); let esplora = esplora_client::Builder::new(&esplora_server_url).build_async()?; let esplora = Arc::new(esplora); + log_trace!(logger, "finished setting up esplora"); + log_trace!(logger, "setting up node manager"); let start = Instant::now(); - let mut nm_builder = NodeManagerBuilder::new(self.xprivkey, self.storage.clone()) .with_config(config.clone()); nm_builder.with_logger(logger.clone()); @@ -951,18 +957,22 @@ impl MutinyWalletBuilder { ); // start syncing node manager + log_trace!(logger, "starting node manager sync"); NodeManager::start_sync(node_manager.clone()); + log_trace!(logger, "finished node manager sync"); + log_trace!(logger, "creating primal client"); let primal_client = PrimalClient::new( config .primal_url .clone() .unwrap_or("https://primal-cache.mutinywallet.com/api".to_string()), ); - - let client = Client::default(); + log_trace!(logger, "finished creating primal client"); // create nostr manager + log_trace!(logger, "creating nostr client"); + let client = Client::default(); let nostr = Arc::new( NostrManager::from_mnemonic( self.xprivkey, @@ -975,12 +985,14 @@ impl MutinyWalletBuilder { ) .await?, ); + log_trace!(logger, "finished creating nostr client"); // connect to relays when not in tests #[cfg(not(test))] nostr.connect().await?; // create federation module if any exist + log_trace!(logger, "creating federation modules"); let federation_storage = self.storage.get_federations()?; let federations = if !federation_storage.federations.is_empty() { let start = Instant::now(); @@ -1004,6 +1016,7 @@ impl MutinyWalletBuilder { Arc::new(RwLock::new(HashMap::new())) }; let federation_storage = Arc::new(RwLock::new(federation_storage)); + log_trace!(logger, "finished creating federation modules"); if !self.skip_hodl_invoices { log_warn!( @@ -1014,20 +1027,25 @@ impl MutinyWalletBuilder { let start = Instant::now(); + log_trace!(logger, "creating lnurl client"); let lnurl_client = Arc::new( lnurl::Builder::default() .build_async() .expect("failed to make lnurl client"), ); + log_trace!(logger, "finished creating lnurl client"); // auth manager, take from auth_client if it already exists + log_trace!(logger, "creating auth manager"); let auth = if let Some(auth_client) = self.auth_client.clone() { auth_client.auth.clone() } else { AuthManager::new(self.xprivkey)? }; + log_trace!(logger, "finished creating auth manager"); // Subscription client, only usable if we have an auth client + log_trace!(logger, "creating subscription client"); let subscription_client = if let Some(auth_client) = self.auth_client.clone() { if let Some(subscription_url) = self.subscription_url { let s = Arc::new(MutinySubscriptionClient::new( @@ -1042,8 +1060,10 @@ impl MutinyWalletBuilder { } else { None }; + log_trace!(logger, "finished creating subscription client"); // Blind auth client, only usable if we have an auth client + log_trace!(logger, "creating blind auth client"); let blind_auth_client = if let Some(auth_client) = self.auth_client.clone() { if let Some(blind_auth_url) = self.blind_auth_url { let s = Arc::new(BlindAuthClient::new( @@ -1061,8 +1081,10 @@ impl MutinyWalletBuilder { } else { None }; + log_trace!(logger, "finished creating blind auth client"); // Hermes client, only usable if we have the blind auth client + log_trace!(logger, "creating hermes client"); let hermes_client = if let Some(blind_auth_client) = blind_auth_client.clone() { if let Some(hermes_url) = self.hermes_url { let s = Arc::new( @@ -1084,8 +1106,10 @@ impl MutinyWalletBuilder { } else { None }; + log_trace!(logger, "finished creating hermes client"); // populate the activity index + log_trace!(logger, "populating activity index"); let mut activity_index = node_manager .wallet .list_transactions(false)? @@ -1158,14 +1182,18 @@ impl MutinyWalletBuilder { let mut read = index.try_write()?; read.extend(activity_index); } + log_trace!(logger, "finished populating activity index"); + log_trace!(logger, "creating price cache"); let price_cache = self .storage .get_bitcoin_price_cache()? .into_iter() .map(|(k, v)| (k, (v, Duration::from_secs(0)))) .collect(); + log_trace!(logger, "finished creating price cache"); + log_trace!(logger, "creating mutiny wallet"); let mw = MutinyWallet { xprivkey: self.xprivkey, config, @@ -1181,14 +1209,14 @@ impl MutinyWalletBuilder { esplora, auth, stop, - logger, + logger: logger.clone(), network, skip_hodl_invoices: self.skip_hodl_invoices, safe_mode: self.safe_mode, cashu_client: CashuHttpClient::new(), bitcoin_price_cache: Arc::new(Mutex::new(price_cache)), }; - + log_trace!(logger, "finished creating mutiny wallet"); // if we are in safe mode, don't create any nodes or // start any nostr services if self.safe_mode { @@ -1196,7 +1224,9 @@ impl MutinyWalletBuilder { } // if we don't have any nodes, create one + log_trace!(logger, "listing nodes"); if mw.node_manager.list_nodes().await?.is_empty() { + log_trace!(logger, "going to create first node"); let nm = mw.node_manager.clone(); // spawn in background, this can take a while and we don't want to block utils::spawn(async move { @@ -1205,24 +1235,36 @@ impl MutinyWalletBuilder { } }) }; + log_trace!(logger, "finished listing nodes"); // start the nostr background process + log_trace!(logger, "starting nostr"); mw.start_nostr().await; + log_trace!(logger, "finished starting nostr"); // start the federation background processor + log_trace!(logger, "starting fedimint background checker"); mw.start_fedimint_background_checker().await; + log_trace!(logger, "finished starting fedimint background checker"); // start the blind auth fetching process + log_trace!(logger, "checking blind tokens"); mw.check_blind_tokens(); + log_trace!(logger, "finsihed checking blind tokens"); // start the hermes background process // get profile key if we have it, we need this to decrypt private zaps + log_trace!(logger, "getting nostr profile key"); let profile_key = match &mw.nostr.nostr_keys.read().await.signer { NostrSigner::Keys(keys) => Some(keys.clone()), #[cfg(target_arch = "wasm32")] NostrSigner::NIP07(_) => None, }; + log_trace!(logger, "finished getting nostr profile key"); + + log_trace!(logger, "starting hermes"); mw.start_hermes(profile_key).await?; + log_trace!(logger, "finished starting hermes"); log_info!( mw.logger, @@ -1265,6 +1307,8 @@ impl MutinyWallet { /// Starts up all the nodes again. /// Not needed after [NodeManager]'s `new()` function. pub async fn start(&mut self) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling start"); + self.storage.start().await?; let mut nm_builder = NodeManagerBuilder::new(self.xprivkey, self.storage.clone()) @@ -1275,11 +1319,14 @@ impl MutinyWallet { self.node_manager = Arc::new(nm_builder.build().await?); NodeManager::start_sync(self.node_manager.clone()); + log_trace!(self.logger, "finished calling start"); Ok(()) } /// Starts a background process that will watch for nostr events pub(crate) async fn start_nostr(&self) { + log_trace!(self.logger, "calling start_nostr"); + // spawn thread to fetch nostr events for NWC, DMs, etc. let nostr = self.nostr.clone(); let logger = self.logger.clone(); @@ -1449,6 +1496,8 @@ impl MutinyWallet { }; } }); + + log_trace!(self.logger, "finished calling start_nostr"); } /// Pays a lightning invoice from a federation (preferred) or node. @@ -1461,6 +1510,8 @@ impl MutinyWallet { amt_sats: Option, labels: Vec, ) -> Result { + log_trace!(self.logger, "calling pay_invoice"); + if inv.network() != self.network { return Err(MutinyError::IncorrectNetwork); } @@ -1505,10 +1556,14 @@ impl MutinyWallet { log_warn!(logger, "Failed to remove pending NWC invoice: {e}"); } }); + log_trace!(self.logger, "finished calling pay_invoice"); return Ok(r); } Err(e) => match e { - MutinyError::PaymentTimeout => return Err(e), + MutinyError::PaymentTimeout => { + log_trace!(self.logger, "finished calling pay_invoice"); + return Err(e); + } MutinyError::RoutingFailed => { log_debug!( self.logger, @@ -1531,7 +1586,7 @@ impl MutinyWallet { // If any balance at all, then fallback to node manager for payment. // Take the error from the node manager as the priority. - if self + let res = if self .node_manager .nodes .read() @@ -1560,7 +1615,10 @@ impl MutinyWallet { Ok(res) } else { Err(last_federation_error.unwrap_or(MutinyError::InsufficientBalance)) - } + }; + log_trace!(self.logger, "finished calling pay_invoice"); + + res } /// Estimates the lightning fee for a transaction. Amount is either from the invoice @@ -1573,6 +1631,8 @@ impl MutinyWallet { inv: Option<&Bolt11Invoice>, amt_sats: Option, ) -> Result, MutinyError> { + log_trace!(self.logger, "calling estimate_ln_fee"); + let amt = amt_sats .or(inv.and_then(|i| i.amount_milli_satoshis())) .ok_or(MutinyError::BadAmountError)?; @@ -1601,11 +1661,14 @@ impl MutinyWallet { / 1_000_000.0; let total_fee = fees.base_msat as f64 + prop_fee_msat; + log_trace!(self.logger, "finished calling estimate_ln_fee"); + return Ok(Some((total_fee / 1_000.0).floor() as u64)); } } } } + log_trace!(self.logger, "finished calling estimate_ln_fee"); if total_balances.lightning > amt { // TODO try something to try to get lightning fee @@ -1646,6 +1709,8 @@ impl MutinyWallet { amount: Option, labels: Vec, ) -> Result { + log_trace!(self.logger, "calling create_bip21"); + let invoice = if self.safe_mode || amount.is_none() { None } else { @@ -1660,6 +1725,7 @@ impl MutinyWallet { let Ok(address) = self.create_address(labels.clone()).await else { return Err(MutinyError::WalletOperationFailed); }; + log_trace!(self.logger, "finished calling create_bip21"); Ok(MutinyBip21RawMaterials { address, @@ -1674,6 +1740,8 @@ impl MutinyWallet { from_federation_id: Option, bolt_11: Bolt11Invoice, ) -> Result { + log_trace!(self.logger, "calling sweep_federation_balance_to_invoice"); + // invoice must have an amount if bolt_11.amount_milli_satoshis().is_none() { return Err(MutinyError::BadAmountError); @@ -1724,6 +1792,11 @@ impl MutinyWallet { .unwrap_or(0); let total_fees = outgoing_fee + incoming_fee; + log_trace!( + self.logger, + "finished calling sweep_federation_balance_to_invoice" + ); + Ok(FedimintSweepResult { amount: bolt_11.amount_milli_satoshis().unwrap_or_default() / 1_000, fees: Some(total_fees), @@ -1737,6 +1810,8 @@ impl MutinyWallet { from_federation_id: Option, to_federation_id: Option, ) -> Result { + log_trace!(self.logger, "calling create_sweep_federation_invoice"); + if let Some(0) = amount { return Err(MutinyError::BadAmountError); } @@ -1757,7 +1832,7 @@ impl MutinyWallet { }; let fees = fedimint_client.gateway_fee().await?; - if let Some(amt) = amount { + let res = if let Some(amt) = amount { // if the user provided amount, this is easy let (mut invoice, incoming_fee) = if let Some(fed_client) = to_federation_client { let invoice = fed_client @@ -1802,7 +1877,13 @@ impl MutinyWallet { invoice.fees_paid = Some(incoming_fee + outgoing_fee); Ok(invoice) - } + }; + log_trace!( + self.logger, + "finished calling create_sweep_federation_invoice" + ); + + res } pub async fn send_to_address( @@ -1812,6 +1893,8 @@ impl MutinyWallet { labels: Vec, fee_rate: Option, ) -> Result { + log_trace!(self.logger, "calling send_to_address"); + // Try each federation first let federation_ids = self.list_federation_ids().await?; let mut last_federation_error = None; @@ -1844,7 +1927,7 @@ impl MutinyWallet { // If any balance at all, then fallback to node manager for payment. // Take the error from the node manager as the priority. let b = self.node_manager.get_balance().await?; - if b.confirmed + b.unconfirmed > 0 { + let res = if b.confirmed + b.unconfirmed > 0 { let res = self .node_manager .send_to_address(send_to, amount, labels, fee_rate) @@ -1852,7 +1935,10 @@ impl MutinyWallet { Ok(res) } else { Err(last_federation_error.unwrap_or(MutinyError::InsufficientBalance)) - } + }; + log_trace!(self.logger, "finished calling send_to_address"); + + res } /// Estimates the onchain fee for a transaction sending to the given address. @@ -1863,6 +1949,8 @@ impl MutinyWallet { amount: u64, fee_rate: Option, ) -> Result { + log_trace!(self.logger, "calling estimate_tx_fee"); + if amount < DUST_LIMIT { return Err(MutinyError::WalletOperationFailed); } @@ -1894,7 +1982,7 @@ impl MutinyWallet { } let b = self.node_manager.get_balance().await?; - if b.confirmed + b.unconfirmed > 0 { + let res = if b.confirmed + b.unconfirmed > 0 { let res = self .node_manager .estimate_tx_fee(destination_address, amount, fee_rate)?; @@ -1902,7 +1990,10 @@ impl MutinyWallet { Ok(res) } else { Err(last_federation_error.unwrap_or(MutinyError::InsufficientBalance)) - } + }; + log_trace!(self.logger, "finished calling estimate_tx_fee"); + + res } /// Estimates the onchain fee for a transaction sweep our on-chain balance @@ -1915,6 +2006,8 @@ impl MutinyWallet { destination_address: Address, fee_rate: Option, ) -> Result { + log_trace!(self.logger, "calling estimate_sweep_tx_fee"); + // Try each federation first let federation_ids = self.list_federation_ids().await?; for federation_id in federation_ids { @@ -1936,7 +2029,7 @@ impl MutinyWallet { } let b = self.node_manager.get_balance().await?; - if b.confirmed + b.unconfirmed > 0 { + let res = if b.confirmed + b.unconfirmed > 0 { let res = self .node_manager .estimate_sweep_tx_fee(destination_address, fee_rate)?; @@ -1945,7 +2038,10 @@ impl MutinyWallet { } else { log_error!(self.logger, "node manager doesn't have a balance"); Err(MutinyError::InsufficientBalance) - } + }; + log_trace!(self.logger, "calling estimate_sweep_tx_fee"); + + res } /// Sweeps all the funds from the wallet to the given address. @@ -1958,6 +2054,8 @@ impl MutinyWallet { labels: Vec, fee_rate: Option, ) -> Result { + log_trace!(self.logger, "calling sweep_wallet"); + // Try each federation first let federation_ids = self.list_federation_ids().await?; for federation_id in federation_ids { @@ -1988,7 +2086,7 @@ impl MutinyWallet { } let b = self.node_manager.get_balance().await?; - if b.confirmed + b.unconfirmed > 0 { + let res = if b.confirmed + b.unconfirmed > 0 { let res = self .node_manager .sweep_wallet(send_to.clone(), labels, fee_rate) @@ -1998,13 +2096,18 @@ impl MutinyWallet { } else { log_error!(self.logger, "node manager doesn't have a balance"); Err(MutinyError::InsufficientBalance) - } + }; + log_trace!(self.logger, "finished calling sweep_wallet"); + + res } pub async fn create_address( &self, labels: Vec, ) -> Result { + log_trace!(self.logger, "calling create_address"); + // Attempt to create federation invoice if available let federation_ids = self.list_federation_ids().await?; if !federation_ids.is_empty() { @@ -2024,6 +2127,7 @@ impl MutinyWallet { return Err(MutinyError::WalletOperationFailed); }; + log_trace!(self.logger, "finished calling create_address"); Ok(addr) } @@ -2032,6 +2136,8 @@ impl MutinyWallet { amount: u64, labels: Vec, ) -> Result { + log_trace!(self.logger, "calling create_lightning_invoice"); + // Attempt to create federation invoice if available let federation_ids = self.list_federation_ids().await?; if !federation_ids.is_empty() { @@ -2050,6 +2156,7 @@ impl MutinyWallet { // Fallback to node_manager invoice creation if no federation invoice created let (inv, _fee) = self.node_manager.create_invoice(amount, labels).await?; + log_trace!(self.logger, "finished calling create_lightning_invoice"); Ok(inv) } @@ -2058,8 +2165,11 @@ impl MutinyWallet { /// /// This will not include any funds in an unconfirmed lightning channel. pub async fn get_balance(&self) -> Result { + log_trace!(self.logger, "calling get_balance"); + let ln_balance = self.node_manager.get_balance().await?; let federation_balance = self.get_total_federation_balance().await?; + log_trace!(self.logger, "finished calling get_balance"); Ok(MutinyBalance::new(ln_balance, federation_balance)) } @@ -2094,6 +2204,8 @@ impl MutinyWallet { limit: Option, offset: Option, ) -> Result, MutinyError> { + log_trace!(self.logger, "calling get_activity"); + let index = { let index = self.storage.activity_index(); let vec = index.try_read()?.clone().into_iter().collect_vec(); @@ -2174,19 +2286,25 @@ impl MutinyWallet { } } } + log_trace!(self.logger, "finished calling get_activity"); Ok(activities) } pub fn get_transaction(&self, txid: Txid) -> Result, MutinyError> { + log_trace!(self.logger, "calling get_transaction"); + // check our local cache/state for fedimint first - match get_transaction_details(&self.storage, txid, &self.logger) { + let res = match get_transaction_details(&self.storage, txid, &self.logger) { Some(t) => Ok(Some(t)), None => { // fall back to node manager self.node_manager.get_transaction(txid) } - } + }; + log_trace!(self.logger, "finished calling get_transaction"); + + res } /// Returns all the lightning activity for a given label @@ -2194,6 +2312,8 @@ impl MutinyWallet { &self, label: &String, ) -> Result, MutinyError> { + log_trace!(self.logger, "calling get_label_activity"); + let Some(label_item) = self.node_manager.get_label(label)? else { return Ok(Vec::new()); }; @@ -2238,14 +2358,19 @@ impl MutinyWallet { } } } + log_trace!(self.logger, "finished calling get_label_activity"); Ok(activities) } pub fn list_invoices(&self) -> Result, MutinyError> { + log_trace!(self.logger, "calling list_invoices"); + let mut inbound_invoices = self.list_payment_info_from_persisters(true)?; let mut outbound_invoices = self.list_payment_info_from_persisters(false)?; inbound_invoices.append(&mut outbound_invoices); + log_trace!(self.logger, "finished calling list_invoices"); + Ok(inbound_invoices) } @@ -2277,7 +2402,12 @@ impl MutinyWallet { /// Gets an invoice. /// This includes sent and received invoices. pub async fn get_invoice(&self, invoice: &Bolt11Invoice) -> Result { - self.get_invoice_by_hash(invoice.payment_hash()).await + log_trace!(self.logger, "calling get_invoice"); + + let res = self.get_invoice_by_hash(invoice.payment_hash()).await; + log_trace!(self.logger, "finished calling get_invoice"); + + res } /// Looks up an invoice by hash. @@ -2286,7 +2416,12 @@ impl MutinyWallet { &self, hash: &sha256::Hash, ) -> Result { - get_invoice_by_hash(hash, &self.storage, &self.logger) + log_trace!(self.logger, "calling get_invoice_by_hash"); + + let res = get_invoice_by_hash(hash, &self.storage, &self.logger); + log_trace!(self.logger, "finished calling get_invoice_by_hash"); + + res } /// Checks whether or not the user is subscribed to Mutiny+. @@ -2296,7 +2431,9 @@ impl MutinyWallet { /// Returns Some(u64) for their unix expiration timestamp, which may be in the /// past or in the future, depending on whether or not it is currently active. pub async fn check_subscribed(&self) -> Result, MutinyError> { - if let Some(ref subscription_client) = self.subscription_client { + log_trace!(self.logger, "calling check_subscribed"); + + let res = if let Some(ref subscription_client) = self.subscription_client { let now = utils::now().as_secs(); match self.storage.get_data::(SUBSCRIPTION_TIMESTAMP) { Ok(Some(timestamp)) if timestamp > now => { @@ -2320,27 +2457,40 @@ impl MutinyWallet { } } else { Ok(None) - } + }; + log_trace!(self.logger, "finished calling check_subscribed"); + + res } /// Gets the subscription plans for Mutiny+ subscriptions pub async fn get_subscription_plans(&self) -> Result, MutinyError> { - if let Some(subscription_client) = self.subscription_client.clone() { + log_trace!(self.logger, "calling get_subscription_plans"); + + let res = if let Some(subscription_client) = self.subscription_client.clone() { Ok(subscription_client.get_plans().await?) } else { Ok(vec![]) - } + }; + log_trace!(self.logger, "finished calling get_subscription_plans"); + + res } /// Subscribes to a Mutiny+ plan with a specific plan id. /// /// Returns a lightning invoice so that the plan can be paid for to start it. pub async fn subscribe_to_plan(&self, id: u8) -> Result { - if let Some(subscription_client) = self.subscription_client.clone() { + log_trace!(self.logger, "calling subscribe_to_plan"); + + let res = if let Some(subscription_client) = self.subscription_client.clone() { Ok(Bolt11Invoice::from_str(&subscription_client.subscribe_to_plan(id).await?)?.into()) } else { Err(MutinyError::SubscriptionClientNotConfigured) - } + }; + log_trace!(self.logger, "finished calling subscribe_to_plan"); + + res } /// Pay the subscription invoice. This will post a NWC automatically afterwards. @@ -2349,7 +2499,9 @@ impl MutinyWallet { inv: &Bolt11Invoice, autopay: bool, ) -> Result<(), MutinyError> { - if let Some(subscription_client) = self.subscription_client.as_ref() { + log_trace!(self.logger, "calling pay_subscription_invoice"); + + let res = if let Some(subscription_client) = self.subscription_client.as_ref() { // TODO if this times out, we should make the next part happen in EventManager self.pay_invoice(inv, None, vec![MUTINY_PLUS_SUBSCRIPTION_LABEL.to_string()]) .await?; @@ -2365,7 +2517,10 @@ impl MutinyWallet { Ok(()) } else { Err(MutinyError::SubscriptionClientNotConfigured) - } + }; + log_trace!(self.logger, "finished calling pay_subscription_invoice"); + + res } async fn ensure_mutiny_nwc_profile( @@ -2437,6 +2592,8 @@ impl MutinyWallet { /// Uploads a profile pic to nostr.build and returns the uploaded file's URL pub async fn upload_profile_pic(&self, image_bytes: Vec) -> Result { + log_trace!(self.logger, "calling upload_profile_pic"); + let client = reqwest::Client::new(); let hash = sha256::Hash::hash(&image_bytes); let form = Form::new().part("fileToUpload", Part::bytes(image_bytes)); @@ -2485,6 +2642,7 @@ impl MutinyWallet { ); return Err(MutinyError::NostrError); } + log_trace!(self.logger, "finished calling upload_profile_pic"); // get url from response body if let Some(value) = res.data.first() { @@ -2504,6 +2662,8 @@ impl MutinyWallet { keys: Option, #[cfg(target_arch = "wasm32")] extension_pk: Option<::nostr::PublicKey>, ) -> Result<::nostr::PublicKey, MutinyError> { + log_trace!(self.logger, "calling change_nostr_keys"); + #[cfg(target_arch = "wasm32")] let source = utils::build_nostr_key_source(keys, extension_pk)?; @@ -2515,11 +2675,14 @@ impl MutinyWallet { // re-sync nostr profile data self.sync_nostr().await?; + log_trace!(self.logger, "finished calling change_nostr_keys"); Ok(new_pk) } /// Syncs all of our nostr data from the configured primal instance pub async fn sync_nostr(&self) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling sync_nostr"); + let npub = self.nostr.get_npub().await; let contacts_fut = self.sync_nostr_contacts(npub); let profile_fut = self.sync_nostr_profile(); @@ -2529,6 +2692,7 @@ impl MutinyWallet { contacts_res?; profile_res?; + log_trace!(self.logger, "finished calling sync_nostr"); Ok(()) } @@ -2544,6 +2708,8 @@ impl MutinyWallet { /// Get contacts from the given npub and sync them to the wallet pub async fn sync_nostr_contacts(&self, npub: ::nostr::PublicKey) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling sync_nostr_contacts"); + let (contact_list, mut metadata) = self.nostr.primal_client.get_nostr_contacts(npub).await?; @@ -2610,6 +2776,7 @@ impl MutinyWallet { } self.storage.set(updated_contacts)?; + log_trace!(self.logger, "finished calling sync_nostr_contacts"); Ok(()) } @@ -2623,6 +2790,8 @@ impl MutinyWallet { until: Option, since: Option, ) -> Result, MutinyError> { + log_trace!(self.logger, "calling get_dm_conversation"); + let self_key = self.nostr.get_npub().await; let events = self .nostr @@ -2653,12 +2822,15 @@ impl MutinyWallet { // sort messages, newest first messages.sort_by(|a, b| b.cmp(a)); + log_trace!(self.logger, "finished calling get_dm_conversation"); Ok(messages) } /// Stops all of the nodes and background processes. /// Returns after node has been stopped. pub async fn stop(&self) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling stop"); + self.stop.store(true, Ordering::Relaxed); self.node_manager.stop().await?; @@ -2670,6 +2842,7 @@ impl MutinyWallet { log_debug!(self.logger, "stopped storage"); } + log_trace!(self.logger, "finished calling stop"); Ok(()) } @@ -2678,6 +2851,8 @@ impl MutinyWallet { old: Option, new: Option, ) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling change_password"); + // check if old password is correct if old != self.storage.password().map(|s| s.to_owned()) { return Err(MutinyError::IncorrectPassword); @@ -2704,6 +2879,7 @@ impl MutinyWallet { // the user has saved their seed already. sleep(5_000).await; + log_trace!(self.logger, "finished calling change_password"); Ok(()) } @@ -2711,6 +2887,8 @@ impl MutinyWallet { /// /// This can be useful if you get stuck in a bad state. pub async fn reset_onchain_tracker(&mut self) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling reset_onchain_tracker"); + self.node_manager.reset_onchain_tracker().await?; // sleep for 250ms to give time for the storage to write utils::sleep(250).await; @@ -2727,12 +2905,17 @@ impl MutinyWallet { .full_sync(FULL_SYNC_STOP_GAP) .await?; + log_trace!(self.logger, "finished calling reset_onchain_tracker"); Ok(()) } /// Deletes all the storage pub async fn delete_all(&self) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling delete_all"); + self.storage.delete_all().await?; + log_trace!(self.logger, "finished calling delete_all"); + Ok(()) } @@ -2762,11 +2945,16 @@ impl MutinyWallet { invoice: Bolt11Invoice, network: Option, ) -> Result { + log_trace!(self.logger, "calling decode_invoice"); + if invoice.network() != network.unwrap_or(self.network) { return Err(MutinyError::IncorrectNetwork); } - Ok(invoice.into()) + let res = invoice.into(); + log_trace!(self.logger, "finished calling decode_invoice"); + + Ok(res) } /// Adds a new federation based on its federation code @@ -2774,7 +2962,9 @@ impl MutinyWallet { &mut self, federation_code: InviteCode, ) -> Result { - create_new_federation( + log_trace!(self.logger, "calling new_federation"); + + let res = create_new_federation( self.xprivkey, self.storage.clone(), self.network, @@ -2786,32 +2976,45 @@ impl MutinyWallet { federation_code, self.stop.clone(), ) - .await + .await; + log_trace!(self.logger, "finished calling new_federation"); + + res } /// Lists the federation id's of the federation clients in the manager. pub async fn list_federations(&self) -> Result, MutinyError> { + log_trace!(self.logger, "calling list_federations"); + let federations = self.federations.read().await; let mut federation_identities = Vec::new(); for f in federations.iter() { let i = f.1.get_mutiny_federation_identity().await; federation_identities.push(i); } + + log_trace!(self.logger, "finished calling list_federations"); Ok(federation_identities) } /// Lists the federation id's of the federation clients in the manager. pub async fn list_federation_ids(&self) -> Result, MutinyError> { + log_trace!(self.logger, "calling list_federation_ids"); + let federations = self.federations.read().await; let federation_identities = federations .iter() .map(|(_, n)| n.fedimint_client.federation_id()) .collect(); + + log_trace!(self.logger, "finished calling list_federation_ids"); Ok(federation_identities) } /// Removes a federation by removing it from the user's federation list. pub async fn remove_federation(&self, federation_id: FederationId) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling remove_federation"); + let mut federations_guard = self.federations.write().await; if let Some(fedimint_client) = federations_guard.get(&federation_id) { @@ -2855,11 +3058,14 @@ impl MutinyWallet { } } } + log_trace!(self.logger, "finshed calling remove_federation"); Ok(()) } pub async fn get_total_federation_balance(&self) -> Result { + log_trace!(self.logger, "calling get_total_federation_balance"); + let federation_ids = self.list_federation_ids().await?; let mut total_balance = 0; @@ -2874,10 +3080,13 @@ impl MutinyWallet { total_balance += balance; } + log_trace!(self.logger, "finsihed calling get_total_federation_balance"); Ok(total_balance) } pub async fn get_federation_balances(&self) -> Result { + log_trace!(self.logger, "calling get_federation_balances"); + let federation_lock = self.federations.read().await; let federation_ids = self.list_federation_ids().await?; @@ -2891,11 +3100,14 @@ impl MutinyWallet { balances.push(FederationBalance { identity, balance }); } + log_trace!(self.logger, "finsihed calling get_federation_balances"); Ok(FederationBalances { balances }) } /// Starts a background process that will check pending fedimint operations pub(crate) async fn start_fedimint_background_checker(&self) { + log_trace!(self.logger, "calling start_fedimint_background_checker"); + let logger = self.logger.clone(); let self_clone = self.clone(); utils::spawn(async move { @@ -2931,12 +3143,19 @@ impl MutinyWallet { } } }); + + log_trace!( + self.logger, + "finsihed calling start_fedimint_background_checker" + ); } /// Calls upon a LNURL to get the parameters for it. /// This contains what kind of LNURL it is (pay, withdrawal, auth, etc). // todo revamp LnUrlParams to be well designed pub async fn decode_lnurl(&self, lnurl: LnUrl) -> Result { + log_trace!(self.logger, "calling decode_lnurl"); + // handle LNURL-AUTH if lnurl.is_lnurl_auth() { return Ok(LnUrlParams { @@ -2966,6 +3185,7 @@ impl MutinyWallet { }, }; + log_trace!(self.logger, "finished calling decode_lnurl"); Ok(params) } @@ -2980,9 +3200,11 @@ impl MutinyWallet { comment: Option, privacy_level: PrivacyLevel, ) -> Result { + log_trace!(self.logger, "calling lnurl_pay"); + let response = self.lnurl_client.make_request(&lnurl.url).await?; - match response { + let res = match response { LnUrlResponse::LnUrlPayResponse(pay) => { let msats = amount_sats * 1000; @@ -3116,7 +3338,10 @@ impl MutinyWallet { } LnUrlResponse::LnUrlWithdrawResponse(_) => Err(MutinyError::IncorrectLnUrlFunction), LnUrlResponse::LnUrlChannelResponse(_) => Err(MutinyError::IncorrectLnUrlFunction), - } + }; + log_trace!(self.logger, "finished calling lnurl_pay"); + + res } /// Calls upon a LNURL and withdraws from it. @@ -3126,9 +3351,11 @@ impl MutinyWallet { lnurl: &LnUrl, amount_sats: u64, ) -> Result { + log_trace!(self.logger, "calling lnurl_withdraw"); + let response = self.lnurl_client.make_request(&lnurl.url).await?; - match response { + let res = match response { LnUrlResponse::LnUrlPayResponse(_) => Err(MutinyError::IncorrectLnUrlFunction), LnUrlResponse::LnUrlChannelResponse(_) => Err(MutinyError::IncorrectLnUrlFunction), LnUrlResponse::LnUrlWithdrawResponse(withdraw) => { @@ -3147,18 +3374,26 @@ impl MutinyWallet { Response::Error { .. } => Ok(false), } } - } + }; + log_trace!(self.logger, "finished calling lnurl_withdraw"); + + res } /// Authenticate with a LNURL-auth pub async fn lnurl_auth(&self, lnurl: LnUrl) -> Result<(), MutinyError> { - make_lnurl_auth_connection( + log_trace!(self.logger, "calling lnurl_auth"); + + let res = make_lnurl_auth_connection( self.auth.clone(), self.lnurl_client.clone(), lnurl, self.logger.clone(), ) - .await + .await; + log_trace!(self.logger, "finished calling lnurl_auth"); + + res } pub fn is_safe_mode(&self) -> bool { @@ -3170,6 +3405,8 @@ impl MutinyWallet { &self, token_v3: TokenV3, ) -> Result, MutinyError> { + log_trace!(self.logger, "calling melt_cashu_token"); + let mut invoices: Vec = Vec::with_capacity(token_v3.tokens.len()); for token in token_v3.tokens { @@ -3231,44 +3468,67 @@ impl MutinyWallet { invoices.push(mutiny_invoice); } } + log_trace!(self.logger, "finished calling melt_cashu_token"); + Ok(invoices) } pub async fn check_available_lnurl_name(&self, name: String) -> Result { - if let Some(hermes_client) = self.hermes_client.clone() { + log_trace!(self.logger, "calling check_available_lnurl_name"); + + let res = if let Some(hermes_client) = self.hermes_client.clone() { Ok(hermes_client.check_available_name(name).await?) } else { Err(MutinyError::NotFound) - } + }; + log_trace!(self.logger, "calling check_available_lnurl_name"); + + res } pub async fn reserve_lnurl_name(&self, name: String) -> Result<(), MutinyError> { - if let Some(hermes_client) = self.hermes_client.clone() { + log_trace!(self.logger, "calling reserve_lnurl_name"); + + let res = if let Some(hermes_client) = self.hermes_client.clone() { Ok(hermes_client.reserve_name(name).await?) } else { Err(MutinyError::NotFound) - } + }; + log_trace!(self.logger, "calling reserve_lnurl_name"); + + res } pub async fn check_lnurl_name(&self) -> Result, MutinyError> { - if let Some(hermes_client) = self.hermes_client.as_ref() { + log_trace!(self.logger, "calling check_lnurl_name"); + + let res = if let Some(hermes_client) = self.hermes_client.as_ref() { hermes_client.check_username().await } else { Err(MutinyError::NotFound) - } + }; + log_trace!(self.logger, "finished calling check_lnurl_name"); + + res } /// Starts up the hermes client if available pub async fn start_hermes(&self, profile_key: Option) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling start_hermes"); + if let Some(hermes_client) = self.hermes_client.as_ref() { hermes_client.start(profile_key).await? } + + log_trace!(self.logger, "finished calling start_hermes"); Ok(()) } /// Checks available blind tokens /// Only needs to be ran once successfully on startup pub fn check_blind_tokens(&self) { + log_trace!(self.logger, "calling check_blind_tokens"); + if let Some(blind_auth_client) = self.blind_auth_client.clone() { let logger = self.logger.clone(); let stop = self.stop.clone(); @@ -3292,10 +3552,13 @@ impl MutinyWallet { } }); } + log_trace!(self.logger, "finished calling check_blind_tokens"); } /// Gets the current bitcoin price in USD. pub async fn get_bitcoin_price(&self, fiat: Option) -> Result { + log_trace!(self.logger, "calling get_bitcoin_price"); + let now = crate::utils::now(); let fiat = fiat.unwrap_or("usd".to_string()); @@ -3304,7 +3567,7 @@ impl MutinyWallet { cache.get(&fiat).cloned() }; - match cache_result { + let res = match cache_result { Some((price, timestamp)) if timestamp == Duration::from_secs(0) => { // Cache is from previous run, return it but fetch a new price in the background let cache = self.bitcoin_price_cache.clone(); @@ -3336,7 +3599,10 @@ impl MutinyWallet { ) .await } - } + }; + log_trace!(self.logger, "finished calling get_bitcoin_price"); + + res } async fn fetch_and_cache_price( diff --git a/mutiny-core/src/node.rs b/mutiny-core/src/node.rs index 99985ccd9..e8ab0e6e2 100644 --- a/mutiny-core/src/node.rs +++ b/mutiny-core/src/node.rs @@ -312,8 +312,44 @@ impl NodeBuilder { self.do_not_connect_peers = true; } + pub fn log_params(&self, logger: &Arc) { + log_debug!(logger, "build parameters:"); + log_debug!(logger, "- xprivkey: {:?}", self.xprivkey); + log_debug!(logger, "- uuid: {:?}", self.uuid); + log_debug!(logger, "- node_index: {:?}", self.node_index); + log_debug!(logger, "- gossip_sync: {:#?}", self.gossip_sync.is_some()); + log_debug!(logger, "- scorer: {:#?}", self.scorer.is_some()); + log_debug!(logger, "- chain: {:#?}", self.chain.is_some()); + log_debug!( + logger, + "- fee_estimator: {:#?}", + self.fee_estimator.is_some() + ); + log_debug!(logger, "- wallet: {:#?}", self.wallet.is_some()); + log_debug!(logger, "- esplora: {:?}", self.esplora); + #[cfg(target_arch = "wasm32")] + log_debug!( + logger, + "- websocket_proxy_addr: {:?}", + self.websocket_proxy_addr + ); + log_debug!(logger, "- network: {:?}", self.network); + log_debug!( + logger, + "- has_done_initial_sync: {:?}", + self.has_done_initial_sync + ); + log_debug!(logger, "- lsp_config: {:?}", self.lsp_config); + log_debug!( + logger, + "- do_not_connect_peers: {}", + self.do_not_connect_peers + ); + } + pub async fn build(self) -> Result, MutinyError> { let node_start = Instant::now(); + // check for all required parameters let node_index = self.node_index.as_ref().map_or_else( || Err(MutinyError::InvalidArgumentsError), @@ -352,7 +388,12 @@ impl NodeBuilder { |v| Ok(v.clone()), )?; - let logger = self.logger.unwrap_or(Arc::new(MutinyLogger::default())); + let logger = self + .logger + .clone() + .unwrap_or(Arc::new(MutinyLogger::default())); + + self.log_params(&logger); log_info!(logger, "initializing a new node: {:?}", self.uuid); @@ -414,7 +455,7 @@ impl NodeBuilder { scoring_params(), )); - log_info!(logger, "creating lsp client"); + log_trace!(logger, "creating lsp config"); let lsp_config: Option = match node_index.lsp { None => { log_info!(logger, "no lsp saved, using configured one if present"); @@ -435,8 +476,10 @@ impl NodeBuilder { } } }; + log_trace!(logger, "finished creating lsp config"); // init channel manager + log_trace!(logger, "initializing channel manager"); let accept_underpaying_htlcs = lsp_config .as_ref() .is_some_and(|l| l.accept_underpaying_htlcs()); @@ -454,12 +497,14 @@ impl NodeBuilder { &esplora, ) .await?; + log_trace!(logger, "finished initializing channel manager"); let channel_manager: Arc> = Arc::new(read_channel_manager.channel_manager); let stop = Arc::new(AtomicBool::new(false)); + log_trace!(logger, "creating lsp client"); let (lsp_client, lsp_client_pubkey, liquidity) = match lsp_config { Some(LspConfig::VoltageFlow(config)) => { let lsp = AnyLsp::new_voltage_flow(config, logger.clone()).await?; @@ -492,7 +537,9 @@ impl NodeBuilder { } None => (None, None, None), }; + log_trace!(logger, "finished creating lsp client"); + log_trace!(logger, "creating onion routers"); let message_router = Arc::new(LspMessageRouter::new(lsp_client_pubkey)); let onion_message_handler = Arc::new(OnionMessenger::new( keys_manager.clone(), @@ -508,8 +555,10 @@ impl NodeBuilder { network_graph: gossip_sync.network_graph().clone(), logger: logger.clone(), }); + log_trace!(logger, "finished creating onion routers"); // init peer manager + log_trace!(logger, "creating peer manager"); let ln_msg_handler = MessageHandler { chan_handler: channel_manager.clone(), route_handler, @@ -518,15 +567,19 @@ impl NodeBuilder { liquidity: liquidity.clone(), }), }; + log_trace!(logger, "finished creating peer manager"); + log_trace!(logger, "creating bump tx event handler"); let bump_tx_event_handler = Arc::new(BumpTransactionEventHandler::new( Arc::clone(&chain), Arc::new(Wallet::new(Arc::clone(&wallet), Arc::clone(&logger))), Arc::clone(&keys_manager), Arc::clone(&logger), )); + log_trace!(logger, "finished creating bump tx event handler"); // init event handler + log_trace!(logger, "creating event handler"); let event_handler = EventHandler::new( channel_manager.clone(), fee_estimator.clone(), @@ -537,27 +590,34 @@ impl NodeBuilder { lsp_client.clone(), logger.clone(), ); + log_trace!(logger, "finished creating event handler"); + log_trace!(logger, "creating peer manager"); let peer_man = Arc::new(create_peer_manager( keys_manager.clone(), ln_msg_handler, logger.clone(), )); + log_trace!(logger, "finished creating peer manager"); if let Some(liquidity) = liquidity { + log_trace!(logger, "setting liqudity callback"); let process_msgs_pm = peer_man.clone(); liquidity.set_process_msgs_callback(move || { process_msgs_pm.process_events(); }); + log_trace!(logger, "finished setting liqudity callback"); } // sync to chain tip + log_trace!(logger, "syncing chain to tip"); if read_channel_manager.is_restarting { let start = Instant::now(); let mut chain_listener_channel_monitors = Vec::with_capacity(read_channel_manager.channel_monitors.len()); for (blockhash, channel_monitor) in read_channel_manager.channel_monitors.drain(..) { // Get channel monitor ready to sync + log_trace!(logger, "loading outputs to watch"); channel_monitor.load_outputs_to_watch(&chain, &logger); let outpoint = channel_monitor.get_funding_txo().0; @@ -574,6 +634,7 @@ impl NodeBuilder { } // give channel monitors to chain monitor + log_trace!(logger, "giving channel monitors to chain monitor"); for item in chain_listener_channel_monitors.drain(..) { let channel_monitor = item.1 .0; let funding_outpoint = item.2; @@ -589,12 +650,14 @@ impl NodeBuilder { start.elapsed().as_millis() ); } + log_trace!(logger, "finished syncing chain to tip"); // Before we start the background processor, retry previously failed // spendable outputs. We should do this before we start the background // processor so we prevent any race conditions. // if we fail to read the spendable outputs, just log a warning and // continue + log_trace!(logger, "retrying spendable outputs"); let retry_spendable_outputs = persister .get_failed_spendable_outputs() .map_err(|e| MutinyError::ReadError { @@ -660,10 +723,12 @@ impl NodeBuilder { ); }); } + log_trace!(logger, "finished retrying spendable outputs"); // Check all existing channels against default configs. // If we have default config changes, those should apply // to all existing and new channels. + log_trace!(logger, "checking default user config against channels"); let default_config = default_user_config(accept_underpaying_htlcs).channel_config; for channel in channel_manager.list_channels() { // unwrap is safe after LDK.0.0.109 @@ -690,7 +755,12 @@ impl NodeBuilder { }; } } + log_trace!( + logger, + "finished checking default user config against channels" + ); + log_trace!(logger, "spawning ldk background thread"); let background_persister = persister.clone(); let background_event_handler = event_handler.clone(); let background_processor_logger = logger.clone(); @@ -748,11 +818,13 @@ impl NodeBuilder { } } }); + log_trace!(logger, "finished spawning ldk background thread"); if !self.do_not_connect_peers { #[cfg(target_arch = "wasm32")] let reconnection_proxy_addr = websocket_proxy_addr.clone(); + log_trace!(logger, "spawning ldk reconnect thread"); let reconnection_storage = persister.storage.clone(); let reconnection_pubkey = pubkey; let reconnection_peer_man = peer_man.clone(); @@ -780,6 +852,7 @@ impl NodeBuilder { ) .await; }); + log_trace!(logger, "finished spawning ldk reconnect thread"); } log_info!( @@ -791,6 +864,7 @@ impl NodeBuilder { let sync_lock = Arc::new(Mutex::new(())); // Here we re-attempt to persist any monitors that failed to persist previously. + log_trace!(logger, "reattempt monitor persistance thread"); let retry_logger = logger.clone(); let retry_persister = persister.clone(); let retry_stop = stop.clone(); @@ -847,6 +921,10 @@ impl NodeBuilder { }; if let Some((key, object, version)) = data_opt { + log_debug!( + retry_logger, + "Persisting monitor for output: {funding_txo:?}" + ); let res = persist_monitor( retry_persister.storage.clone(), key, @@ -863,7 +941,12 @@ impl NodeBuilder { .channel_monitor_updated(funding_txo, id) { log_error!(retry_logger, "Error notifying chain monitor of channel monitor update: {e:?}"); - } + } else { + log_debug!( + retry_logger, + "notified channel monitor updated: {funding_txo:?}" + ); + } } } Err(e) => log_error!( @@ -878,6 +961,7 @@ impl NodeBuilder { sleep(3_000).await; } }); + log_trace!(logger, "finished reattempt monitor persistance thread"); log_trace!( logger, @@ -937,13 +1021,21 @@ pub(crate) struct Node { impl Node { pub async fn stop(&self) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling stop"); + self.stop.store(true, Ordering::Relaxed); - self.stopped().await + self.stopped().await?; + + log_trace!(self.logger, "finished calling stop"); + + Ok(()) } /// stopped will await until the node is fully shut down pub async fn stopped(&self) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling stopped"); + loop { let all_stopped = { let stopped_components = self @@ -959,19 +1051,28 @@ impl Node { sleep(500).await; } + + log_trace!(self.logger, "finished calling stopped"); Ok(()) } pub async fn node_index(&self) -> NodeIndex { + log_trace!(self.logger, "calling node_index"); + let lsp = match self.lsp_client.as_ref() { Some(lsp) => Some(lsp.get_config().await), None => None, }; - NodeIndex { + + let n = NodeIndex { child_index: self.child_index, lsp, archived: Some(false), - } + }; + + log_trace!(self.logger, "finished calling node_index"); + + n } pub async fn connect_peer( @@ -979,6 +1080,8 @@ impl Node { peer_connection_info: PubkeyConnectionInfo, label: Option, ) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling connect_peer"); + let connect_res = connect_peer_if_necessary( #[cfg(target_arch = "wasm32")] &self.websocket_proxy_addr, @@ -990,7 +1093,7 @@ impl Node { self.stop.clone(), ) .await; - match connect_res { + let res = match connect_res { Ok(_) => { let node_id = NodeId::from_pubkey(&peer_connection_info.pubkey); @@ -1033,18 +1136,30 @@ impl Node { Ok(()) } Err(e) => Err(e), - } + }; + + log_trace!(self.logger, "finished calling connect_peer"); + + res } pub fn disconnect_peer(&self, peer_id: PublicKey) { + log_trace!(self.logger, "calling disconnect_peer"); self.peer_manager.disconnect_by_node_id(peer_id); + log_trace!(self.logger, "finished calling disconnect_peer"); } pub fn get_phantom_route_hint(&self) -> PhantomRouteHints { - self.channel_manager.get_phantom_route_hints() + log_trace!(self.logger, "calling get_phantom_route_hint"); + let res = self.channel_manager.get_phantom_route_hints(); + log_trace!(self.logger, "calling get_phantom_route_hint"); + + res } + pub async fn get_lsp_fee(&self, amount_sat: u64) -> Result { - match self.lsp_client.as_ref() { + log_trace!(self.logger, "calling get_lsp_fee"); + let res = match self.lsp_client.as_ref() { Some(lsp) => { let connect = lsp.get_lsp_connection_string().await; self.connect_peer(PubkeyConnectionInfo::new(&connect)?, None) @@ -1085,7 +1200,10 @@ impl Node { Ok(lsp_fee.fee_amount_msat / 1000) } None => Ok(0), - } + }; + log_trace!(self.logger, "finished calling get_lsp_fee"); + + res } pub async fn create_invoice( @@ -1094,7 +1212,9 @@ impl Node { route_hints: Option>, labels: Vec, ) -> Result<(Bolt11Invoice, u64), MutinyError> { - match self.lsp_client.as_ref() { + log_trace!(self.logger, "calling create_invoice"); + + let res = match self.lsp_client.as_ref() { Some(lsp) => { let connect = lsp.get_lsp_connection_string().await; self.connect_peer(PubkeyConnectionInfo::new(&connect)?, None) @@ -1230,7 +1350,10 @@ impl Node { .await?, 0, )), - } + }; + log_trace!(self.logger, "finished calling create_invoice"); + + res } async fn create_internal_invoice( @@ -1341,12 +1464,20 @@ impl Node { &self, user_channel_id: u128, ) -> Result, MutinyError> { - self.persister.get_channel_closure(user_channel_id) + log_trace!(self.logger, "calling get_channel_closure"); + let res = self.persister.get_channel_closure(user_channel_id); + log_trace!(self.logger, "finished calling get_channel_closure"); + + res } /// Gets all the closed channels for this node pub fn get_channel_closures(&self) -> Result, MutinyError> { - self.persister.list_channel_closures() + log_trace!(self.logger, "calling get_channel_closures"); + let res = self.persister.list_channel_closures(); + log_trace!(self.logger, "finished calling get_channel_closures"); + + res } fn retry_strategy() -> Retry { @@ -1360,6 +1491,8 @@ impl Node { invoice: &Bolt11Invoice, amt_sats: Option, ) -> Result<(PaymentId, PaymentHash), MutinyError> { + log_trace!(self.logger, "calling init_invoice_payment"); + let payment_hash = invoice.payment_hash().into_32(); if read_payment_info(&self.persister.storage, &payment_hash, false, &self.logger) @@ -1450,7 +1583,7 @@ impl Node { persist_payment_info(&self.persister.storage, &payment_hash, &payment_info, false)?; - match pay_result { + let res = match pay_result { Ok(id) => Ok((id, PaymentHash(payment_hash))), Err(error) => { log_error!(self.logger, "failed to make payment: {error:?}"); @@ -1467,7 +1600,10 @@ impl Node { Err(map_sending_failure(error, amt_msat, ¤t_channels)) } - } + }; + log_trace!(self.logger, "finished calling init_invoice_payment"); + + res } // copied from LDK, modified to change a couple params @@ -1557,12 +1693,18 @@ impl Node { timeout_secs: Option, labels: Vec, ) -> Result { + log_trace!(self.logger, "calling pay_invoice_with_timeout"); + // initiate payment let (payment_id, payment_hash) = self.init_invoice_payment(invoice, amt_sats).await?; let timeout: u64 = timeout_secs.unwrap_or(DEFAULT_PAYMENT_TIMEOUT); - self.await_payment(payment_id, payment_hash, timeout, labels) - .await + let res = self + .await_payment(payment_id, payment_hash, timeout, labels) + .await; + log_trace!(self.logger, "finished calling pay_invoice_with_timeout"); + + res } /// init_keysend_payment sends off the payment but does not wait for results @@ -1575,6 +1717,8 @@ impl Node { labels: Vec, payment_id: PaymentId, ) -> Result { + log_trace!(self.logger, "calling init_keysend_payment"); + let amt_msats = amt_sats * 1_000; // check if we have enough balance to send @@ -1665,7 +1809,7 @@ impl Node { false, )?; - match pay_result { + let res = match pay_result { Ok(_) => { let mutiny_invoice = MutinyInvoice::from(payment_info, payment_hash, false, labels)?; @@ -1682,7 +1826,10 @@ impl Node { let current_channels = self.channel_manager.list_channels(); Err(map_sending_failure(error, amt_msats, ¤t_channels)) } - } + }; + log_trace!(self.logger, "finished calling init_keysend_payment"); + + res } pub async fn keysend_with_timeout( @@ -1693,6 +1840,8 @@ impl Node { labels: Vec, timeout_secs: Option, ) -> Result { + log_trace!(self.logger, "calling keysend_with_timeout"); + let mut entropy = [0u8; 32]; getrandom::getrandom(&mut entropy).map_err(|_| MutinyError::SeedGenerationFailed)?; let payment_id = PaymentId(entropy); @@ -1705,8 +1854,12 @@ impl Node { let timeout: u64 = timeout_secs.unwrap_or(DEFAULT_PAYMENT_TIMEOUT); let payment_hash = PaymentHash(pay.payment_hash.into_32()); - self.await_payment(payment_id, payment_hash, timeout, labels) - .await + let res = self + .await_payment(payment_id, payment_hash, timeout, labels) + .await; + log_trace!(self.logger, "finished calling keysend_with_timeout"); + + res } async fn await_chan_funding_tx( @@ -1777,6 +1930,8 @@ impl Node { fee_rate: Option, user_channel_id: Option, ) -> Result { + log_trace!(self.logger, "calling init_open_channel"); + let accept_underpaying_htlcs = self .lsp_client .as_ref() @@ -1803,7 +1958,7 @@ impl Node { self.persister .persist_channel_open_params(user_channel_id, params)?; - match self.channel_manager.create_channel( + let res = match self.channel_manager.create_channel( pubkey, amount_sat, 0, @@ -1825,7 +1980,11 @@ impl Node { ); Err(MutinyError::ChannelCreationFailed) } - } + }; + + log_trace!(self.logger, "finished calling init_open_channel"); + + res } pub async fn open_channel_with_timeout( @@ -1836,11 +1995,16 @@ impl Node { user_channel_id: Option, timeout: u64, ) -> Result { + log_trace!(self.logger, "calling open_channel_with_timeout"); + let init = self .init_open_channel(pubkey, amount_sat, fee_rate, user_channel_id) .await?; - self.await_chan_funding_tx(init, &pubkey, timeout).await + let res = self.await_chan_funding_tx(init, &pubkey, timeout).await; + log_trace!(self.logger, "finished calling open_channel_with_timeout"); + + res } pub async fn init_sweep_utxos_to_channel( @@ -1849,6 +2013,8 @@ impl Node { utxos: &[OutPoint], pubkey: PublicKey, ) -> Result { + log_trace!(self.logger, "calling init_sweep_utxos_to_channel"); + // Calculate the total value of the selected utxos let utxo_value: u64 = { // find the wallet utxos @@ -1897,7 +2063,7 @@ impl Node { self.persister .persist_channel_open_params(user_channel_id, params)?; - match self.channel_manager.create_channel( + let res = match self.channel_manager.create_channel( pubkey, channel_value_satoshis, 0, @@ -1921,7 +2087,10 @@ impl Node { self.persister.delete_channel_open_params(user_channel_id)?; Err(MutinyError::ChannelCreationFailed) } - } + }; + log_trace!(self.logger, "finished calling init_sweep_utxos_to_channel"); + + res } pub async fn sweep_utxos_to_channel_with_timeout( @@ -1931,11 +2100,19 @@ impl Node { pubkey: PublicKey, timeout: u64, ) -> Result { + log_trace!(self.logger, "calling sweep_utxos_to_channel_with_timeout"); + let init = self .init_sweep_utxos_to_channel(user_chan_id, utxos, pubkey) .await?; - self.await_chan_funding_tx(init, &pubkey, timeout).await + let res = self.await_chan_funding_tx(init, &pubkey, timeout).await; + log_trace!( + self.logger, + "finished calling sweep_utxos_to_channel_with_timeout" + ); + + res } } diff --git a/mutiny-core/src/nodemanager.rs b/mutiny-core/src/nodemanager.rs index 15d24e79d..f7eb9b0c1 100644 --- a/mutiny-core/src/nodemanager.rs +++ b/mutiny-core/src/nodemanager.rs @@ -301,17 +301,22 @@ impl NodeManagerBuilder { let start = Instant::now(); log_info!(logger, "Building node manager components"); + log_trace!(logger, "creating tx sync client"); let tx_sync = Arc::new(EsploraSyncClient::from_client( esplora.as_ref().clone(), logger.clone(), )); + log_trace!(logger, "finished creating tx sync client"); + log_trace!(logger, "creating fee estimator"); let fee_estimator = Arc::new(MutinyFeeEstimator::new( self.storage.clone(), esplora.clone(), logger.clone(), )); + log_trace!(logger, "finished creating fee estimator"); + log_trace!(logger, "creating on chain wallet"); let wallet = Arc::new(OnChainWallet::new( self.xprivkey, self.storage.clone(), @@ -321,23 +326,34 @@ impl NodeManagerBuilder { stop.clone(), logger.clone(), )?); + log_trace!(logger, "finished creating on chain wallet"); + log_trace!(logger, "creating chain"); let chain = Arc::new(MutinyChain::new(tx_sync, wallet.clone(), logger.clone())); + log_trace!(logger, "finished creating chain"); + log_trace!(logger, "creating gossip sync"); let (gossip_sync, scorer) = get_gossip_sync(&self.storage, c.network, logger.clone()).await?; + log_trace!(logger, "finished creating gossip sync"); + log_trace!(logger, "creating scorer"); let scorer = Arc::new(utils::Mutex::new(scorer)); + log_trace!(logger, "finished creating scorer"); let gossip_sync = Arc::new(gossip_sync); + log_trace!(logger, "creating lsp config"); let lsp_config = if c.safe_mode { None } else { create_lsp_config(c.lsp_url, c.lsp_connection_string, c.lsp_token)? }; + log_trace!(logger, "finished creating lsp config"); + log_trace!(logger, "getting nodes from storage"); let node_storage = self.storage.get_nodes()?; + log_trace!(logger, "finished getting nodes from storage"); log_trace!( logger, @@ -352,6 +368,8 @@ impl NodeManagerBuilder { log_warn!(logger, "Safe mode enabled, not starting any nodes"); Arc::new(RwLock::new(HashMap::new())) } else { + log_trace!(logger, "going through nodes"); + // Remove the archived nodes, we don't need to start them up. let unarchived_nodes = node_storage .clone() @@ -514,17 +532,24 @@ impl NodeManager { &self, pk: Option<&PublicKey>, ) -> Result>, MutinyError> { + log_trace!(self.logger, "calling get_node_by_key_or_first"); + let nodes = self.nodes.read().await; let node = match pk { Some(pubkey) => nodes.get(pubkey), None => nodes.iter().next().map(|(_, node)| node), }; - node.cloned().ok_or(MutinyError::NotFound) + let res = node.cloned().ok_or(MutinyError::NotFound); + log_trace!(self.logger, "finished calling get_node_by_key_or_first"); + + res } /// Stops all of the nodes and background processes. /// Returns after node has been stopped. pub async fn stop(&self) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling stop"); + self.stop.swap(true, Ordering::Relaxed); let mut nodes = self.nodes.write().await; let node_futures = nodes.iter().map(|(_, n)| async { @@ -540,7 +565,7 @@ impl NodeManager { log_debug!(self.logger, "stopping all nodes"); join_all(node_futures).await; nodes.clear(); - log_debug!(self.logger, "stopped all nodes"); + log_debug!(self.logger, "finished calling stop"); Ok(()) } @@ -548,6 +573,8 @@ impl NodeManager { /// Creates a background process that will sync the wallet with the blockchain. /// This will also update the fee estimates every 10 minutes. pub fn start_sync(nm: Arc>) { + log_trace!(nm.logger, "calling start_sync"); + // sync every second on regtest, this makes testing easier let sync_interval_secs = match nm.network { Network::Bitcoin | Network::Testnet | Network::Signet => 60, @@ -606,7 +633,11 @@ impl NodeManager { /// Broadcast a transaction to the network. /// The transaction is broadcast through the configured esplora server. pub async fn broadcast_transaction(&self, tx: Transaction) -> Result<(), MutinyError> { - self.wallet.broadcast_transaction(tx).await + log_trace!(self.logger, "calling broadcast_transaction"); + let res = self.wallet.broadcast_transaction(tx).await; + log_trace!(self.logger, "finished calling broadcast_transaction"); + + res } /// Returns the network of the wallet. @@ -617,9 +648,13 @@ impl NodeManager { /// Gets a new bitcoin address from the wallet. /// Will generate the last unused address in our bdk wallet. pub fn get_new_address(&self, labels: Vec) -> Result { + log_trace!(self.logger, "calling get_new_address"); + if let Ok(mut wallet) = self.wallet.wallet.try_write() { let address = wallet.try_get_address(AddressIndex::LastUnused)?.address; self.set_address_labels(address.clone(), labels)?; + log_trace!(self.logger, "finished calling get_new_address"); + return Ok(address); } @@ -629,7 +664,10 @@ impl NodeManager { /// Gets the current balance of the on-chain wallet. pub fn get_wallet_balance(&self) -> Result { + log_trace!(self.logger, "calling get_wallet_balance"); + if let Ok(wallet) = self.wallet.wallet.try_read() { + log_trace!(self.logger, "finished calling get_wallet_balance"); return Ok(wallet.get_balance().total()); } @@ -647,6 +685,8 @@ impl NodeManager { labels: Vec, fee_rate: Option, ) -> Result { + log_trace!(self.logger, "calling send_payjoin"); + let uri = uri .require_network(self.network) .map_err(|_| MutinyError::IncorrectNetwork)?; @@ -711,6 +751,8 @@ impl NodeManager { let txid = tx.txid(); self.broadcast_transaction(tx).await?; log_debug!(self.logger, "Payjoin broadcast! TXID: {txid}"); + + log_trace!(self.logger, "finished calling send_payjoin"); Ok(txid) } @@ -725,7 +767,11 @@ impl NodeManager { labels: Vec, fee_rate: Option, ) -> Result { - self.wallet.send(send_to, amount, labels, fee_rate).await + log_trace!(self.logger, "calling send_to_address"); + let res = self.wallet.send(send_to, amount, labels, fee_rate).await; + log_trace!(self.logger, "finished calling send_to_address"); + + res } /// Sweeps all the funds from the wallet to the given address. @@ -738,7 +784,11 @@ impl NodeManager { labels: Vec, fee_rate: Option, ) -> Result { - self.wallet.sweep(send_to, labels, fee_rate).await + log_trace!(self.logger, "calling sweep_wallet"); + let res = self.wallet.sweep(send_to, labels, fee_rate).await; + log_trace!(self.logger, "calling sweep_wallet"); + + res } /// Estimates the onchain fee for a transaction sending to the given address. @@ -749,8 +799,13 @@ impl NodeManager { amount: u64, fee_rate: Option, ) -> Result { - self.wallet - .estimate_tx_fee(destination_address.script_pubkey(), amount, fee_rate) + log_trace!(self.logger, "calling estimate_tx_fee"); + let res = + self.wallet + .estimate_tx_fee(destination_address.script_pubkey(), amount, fee_rate); + log_trace!(self.logger, "calling estimate_tx_fee"); + + res } /// Estimates the onchain fee for a transaction sweep our on-chain balance @@ -773,12 +828,17 @@ impl NodeManager { amount: u64, fee_rate: Option, ) -> Result { + log_trace!(self.logger, "calling estimate_channel_open_fee"); + // Dummy p2wsh script for the channel output let script = script::Builder::new() .push_int(0) .push_slice([0; 32]) .into_script(); - self.wallet.estimate_tx_fee(script, amount, fee_rate) + let res = self.wallet.estimate_tx_fee(script, amount, fee_rate); + log_trace!(self.logger, "calling estimate_channel_open_fee"); + + res } /// Estimates the onchain fee for sweeping our on-chain balance to open a lightning channel. @@ -787,17 +847,24 @@ impl NodeManager { &self, fee_rate: Option, ) -> Result { + log_trace!(self.logger, "calling estimate_sweep_channel_open_fee"); + // Dummy p2wsh script for the channel output let script = script::Builder::new() .push_int(0) .push_slice([0; 32]) .into_script(); - self.wallet.estimate_sweep_tx_fee(script, fee_rate) + let res = self.wallet.estimate_sweep_tx_fee(script, fee_rate); + log_trace!(self.logger, "calling estimate_sweep_channel_open_fee"); + + res } /// Bumps the given transaction by replacing the given tx with a transaction at /// the new given fee rate in sats/vbyte pub async fn bump_fee(&self, txid: Txid, new_fee_rate: f32) -> Result { + log_trace!(self.logger, "calling bump_fee"); + // check that this is not a funding tx for any channels, // bumping those can cause loss of funds let channels = self.list_channels().await?; @@ -808,7 +875,10 @@ impl NodeManager { return Err(MutinyError::ChannelCreationFailed); } - self.wallet.bump_fee(txid, new_fee_rate).await + let res = self.wallet.bump_fee(txid, new_fee_rate).await; + log_trace!(self.logger, "finished calling bump_fee"); + + res } /// Checks if the given address has any transactions. @@ -819,6 +889,8 @@ impl NodeManager { &self, address: Address, ) -> Result, MutinyError> { + log_trace!(self.logger, "calling check_address"); + let address = address.require_network(self.network)?; let script = address.payload.script_pubkey(); @@ -885,6 +957,7 @@ impl NodeManager { }); } + log_trace!(self.logger, "finished calling check_address"); Ok(details_opt.map(|(d, _)| d)) } @@ -919,6 +992,8 @@ impl NodeManager { /// Lists all the on-chain transactions in the wallet. /// These are sorted by confirmation time. pub fn list_onchain(&self) -> Result, MutinyError> { + log_trace!(self.logger, "calling list_onchain"); + let mut txs = self.wallet.list_transactions(true)?; txs.sort(); let address_labels = self.get_address_labels()?; @@ -927,19 +1002,25 @@ impl NodeManager { .map(|tx| self.add_onchain_labels(&address_labels, tx)) .collect(); + log_trace!(self.logger, "finished calling list_onchain"); Ok(txs) } /// Gets the details of a specific on-chain transaction. pub fn get_transaction(&self, txid: Txid) -> Result, MutinyError> { - match self.wallet.get_transaction(txid)? { + log_trace!(self.logger, "calling get_transaction"); + + let res = match self.wallet.get_transaction(txid)? { Some(tx) => { let address_labels = self.get_address_labels()?; let tx_details = self.add_onchain_labels(&address_labels, tx); Ok(Some(tx_details)) } None => Ok(None), - } + }; + log_trace!(self.logger, "finished calling get_transaction"); + + res } /// Gets the current balance of the wallet. @@ -947,6 +1028,8 @@ impl NodeManager { /// /// This will not include any funds in an unconfirmed lightning channel. pub(crate) async fn get_balance(&self) -> Result { + log_trace!(self.logger, "calling get_balance"); + let onchain = if let Ok(wallet) = self.wallet.wallet.try_read() { wallet.get_balance() } else { @@ -981,6 +1064,8 @@ impl NodeManager { .map(|bal| bal.claimable_amount_satoshis()) .sum(); + log_trace!(self.logger, "finished calling get_balance"); + Ok(NodeBalance { confirmed: onchain.confirmed + onchain.trusted_pending, unconfirmed: onchain.untrusted_pending + onchain.immature, @@ -991,7 +1076,11 @@ impl NodeManager { /// Lists all the UTXOs in the wallet. pub fn list_utxos(&self) -> Result, MutinyError> { - self.wallet.list_utxos() + log_trace!(self.logger, "calling list_utxos"); + let res = self.wallet.list_utxos(); + log_trace!(self.logger, "calling list_utxos"); + + res } /// Syncs the lightning wallet with the blockchain. @@ -1001,6 +1090,8 @@ impl NodeManager { /// This should be called before syncing the on-chain wallet /// to ensure that new on-chain transactions are picked up. async fn sync_ldk(&self) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling sync_ldk"); + // get nodes hashmap, immediately drop lock because sync can take a while let nodes = { let nodes = self.nodes.read().await; @@ -1030,12 +1121,15 @@ impl NodeManager { .await .map_err(|_e| MutinyError::ChainAccessFailed)?; + log_trace!(self.logger, "finished calling sync_ldk"); Ok(()) } /// Syncs the rapid gossip sync data. /// Will be skipped if in safe mode. async fn sync_rgs(&self) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling sync_rgs"); + // Skip syncing RGS if we are in safe mode. if self.safe_mode { log_info!(self.logger, "Skipping rgs sync in safe mode"); @@ -1065,12 +1159,15 @@ impl NodeManager { } } + log_trace!(self.logger, "finished calling sync_rgs"); Ok(()) } /// Downloads the latest score data from the server and replaces the current scorer. /// Will be skipped if in safe mode. async fn sync_scorer(&self) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling sync_scorer"); + // Skip syncing scorer if we are in safe mode. if self.safe_mode { log_info!(self.logger, "Skipping scorer sync in safe mode"); @@ -1098,6 +1195,7 @@ impl NodeManager { *lock = scorer; } + log_trace!(self.logger, "finished calling sync_scorer"); Ok(()) } @@ -1106,6 +1204,8 @@ impl NodeManager { /// transactions and update the lightning wallet with /// any channels that have been opened or closed. async fn sync(&self) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling sync"); + // If we are stopped, don't sync if self.stop.load(Ordering::Relaxed) { return Ok(()); @@ -1127,40 +1227,59 @@ impl NodeManager { self.has_done_initial_ldk_sync.swap(true, Ordering::SeqCst); // sync bdk wallet - match self.wallet.sync().await { + let res = match self.wallet.sync().await { Ok(()) => Ok(log_info!(self.logger, "We are synced!")), Err(e) => { log_error!(self.logger, "Failed to sync on-chain wallet: {e}"); Err(e) } - } + }; + log_trace!(self.logger, "finished calling sync"); + + res } /// Gets a fee estimate for a very low priority transaction. /// Value is in sat/vbyte. pub fn estimate_fee_low(&self) -> u32 { - max(self.fee_estimator.get_low_fee_rate() / 250, 1) + log_trace!(self.logger, "calling estimate_fee_low"); + let res = max(self.fee_estimator.get_low_fee_rate() / 250, 1); + log_trace!(self.logger, "finished calling estimate_fee_low"); + + res } /// Gets a fee estimate for an average priority transaction. /// Value is in sat/vbyte. pub fn estimate_fee_normal(&self) -> u32 { - max(self.fee_estimator.get_normal_fee_rate() / 250, 1) + log_trace!(self.logger, "calling estimate_fee_normal"); + let res = max(self.fee_estimator.get_normal_fee_rate() / 250, 1); + log_trace!(self.logger, "finished calling estimate_fee_normal"); + + res } /// Gets a fee estimate for an high priority transaction. /// Value is in sat/vbyte. pub fn estimate_fee_high(&self) -> u32 { - max(self.fee_estimator.get_high_fee_rate() / 250, 1) + log_trace!(self.logger, "calling estimate_fee_high"); + let res = max(self.fee_estimator.get_high_fee_rate() / 250, 1); + log_trace!(self.logger, "finished calling estimate_fee_high"); + + res } /// Creates a new lightning node and adds it to the manager. pub async fn new_node(&self) -> Result { + log_trace!(self.logger, "calling new_node"); if self.safe_mode { return Err(MutinyError::NotRunning); } - create_new_node_from_node_manager(self).await + let res = create_new_node_from_node_manager(self).await; + log_trace!(self.logger, "finished calling new_node"); + + res } /// Archives a node so it will not be started up next time the node manager is created. @@ -1206,8 +1325,12 @@ impl NodeManager { /// Lists the pubkeys of the lightning node in the manager. pub async fn list_nodes(&self) -> Result, MutinyError> { + log_trace!(self.logger, "calling list_nodes"); + let nodes = self.nodes.read().await; let peers = nodes.iter().map(|(_, n)| n.pubkey).collect(); + + log_trace!(self.logger, "finished calling list_nodes"); Ok(peers) } @@ -1216,6 +1339,8 @@ impl NodeManager { /// /// Requires a restart of the node manager to take effect. pub async fn change_lsp(&self, lsp_config: Option) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling change_lsp"); + // if we are in safe mode we don't load the lightning state so we can't know if it is safe to change the LSP. if self.safe_mode { return Err(MutinyError::NotRunning); @@ -1246,6 +1371,7 @@ impl NodeManager { // save updated lsp to storage self.storage.insert_nodes(&node_storage).await?; + log_trace!(self.logger, "finished calling change_lsp"); Ok(()) } @@ -1257,11 +1383,14 @@ impl NodeManager { connection_string: &str, label: Option, ) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling connect_to_peer"); + let node = self.get_node_by_key_or_first(self_node_pubkey).await?; let connect_info = PubkeyConnectionInfo::new(connection_string)?; let label_opt = label.filter(|s| !s.is_empty()); // filter out empty strings let res = node.connect_peer(connect_info, label_opt).await; + log_trace!(self.logger, "finished calling connect_to_peer"); match res { Ok(_) => { log_info!(self.logger, "Connected to peer: {connection_string}"); @@ -1283,8 +1412,12 @@ impl NodeManager { self_node_pubkey: Option<&PublicKey>, peer: PublicKey, ) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling disconnect_peer"); + let node = self.get_node_by_key_or_first(self_node_pubkey).await?; node.disconnect_peer(peer); + log_trace!(self.logger, "finished calling disconnect_peer"); + Ok(()) } @@ -1295,14 +1428,21 @@ impl NodeManager { self_node_pubkey: Option<&PublicKey>, peer: &NodeId, ) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling delete_peer"); + let node = self.get_node_by_key_or_first(self_node_pubkey).await?; gossip::delete_peer_info(&self.storage, &node.uuid, peer)?; + log_trace!(self.logger, "finished calling delete_peer"); + Ok(()) } /// Sets the label of a peer from the selected node. pub fn label_peer(&self, node_id: &NodeId, label: Option) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling label_peer"); gossip::set_peer_label(&self.storage, node_id, label)?; + log_trace!(self.logger, "finished calling label_peer"); + Ok(()) } @@ -1318,6 +1458,8 @@ impl NodeManager { amount: u64, labels: Vec, ) -> Result<(MutinyInvoice, u64), MutinyError> { + log_trace!(self.logger, "calling create_invoice"); + let nodes = self.nodes.read().await; let use_phantom = nodes.len() > 1 && self.lsp_config.is_none(); if nodes.len() == 0 { @@ -1343,6 +1485,7 @@ impl NodeManager { let invoice = first_node .create_invoice(amount, route_hints, labels) .await?; + log_trace!(self.logger, "finished calling create_invoice"); Ok((invoice.0.into(), invoice.1)) } @@ -1351,8 +1494,14 @@ impl NodeManager { /// This could include the fee if a channel open is necessary. Otherwise the fee /// will be low or non-existant. pub async fn get_lsp_fee(&self, amount: u64) -> Result { + log_trace!(self.logger, "calling get_lsp_fee"); + let node = self.get_node_by_key_or_first(None).await?; - node.get_lsp_fee(amount).await + let res = node.get_lsp_fee(amount).await; + + log_trace!(self.logger, "finished calling get_lsp_fee"); + + res } /// Pays a lightning invoice from either a specified node or the first available node. @@ -1365,9 +1514,15 @@ impl NodeManager { amt_sats: Option, labels: Vec, ) -> Result { + log_trace!(self.logger, "calling pay_invoice"); + let node = self.get_node_by_key_or_first(self_node_pubkey).await?; - node.pay_invoice_with_timeout(invoice, amt_sats, None, labels) - .await + let res = node + .pay_invoice_with_timeout(invoice, amt_sats, None, labels) + .await; + log_trace!(self.logger, "finished calling pay_invoice"); + + res } /// Sends a spontaneous payment to a node from either a specified node or the first available node. @@ -1380,27 +1535,39 @@ impl NodeManager { message: Option, labels: Vec, ) -> Result { + log_trace!(self.logger, "calling keysend"); + let node = self.get_node_by_key_or_first(self_node_pubkey).await?; log_debug!(self.logger, "Keysending to {to_node}"); - node.keysend_with_timeout(to_node, amt_sats, message, labels, None) - .await + let res = node + .keysend_with_timeout(to_node, amt_sats, message, labels, None) + .await; + log_trace!(self.logger, "finished calling keysend"); + + res } pub async fn get_channel_closure( &self, user_channel_id: u128, ) -> Result { + log_trace!(self.logger, "calling get_channel_closure"); + let nodes = self.nodes.read().await; for (_, node) in nodes.iter() { if let Ok(Some(closure)) = node.get_channel_closure(user_channel_id) { + log_trace!(self.logger, "finished calling get_channel_closure"); return Ok(closure); } } + log_trace!(self.logger, "finished calling get_channel_closure"); Err(MutinyError::NotFound) } pub async fn list_channel_closures(&self) -> Result, MutinyError> { + log_trace!(self.logger, "calling list_channel_closures"); + let mut channels: Vec = vec![]; let nodes = self.nodes.read().await; for (_, node) in nodes.iter() { @@ -1408,6 +1575,8 @@ impl NodeManager { channels.append(&mut invs) } } + + log_trace!(self.logger, "finished calling list_channel_closures"); Ok(channels) } @@ -1424,6 +1593,8 @@ impl NodeManager { fee_rate: Option, user_channel_id: Option, ) -> Result { + log_trace!(self.logger, "calling open_channel"); + let node = self.get_node_by_key_or_first(self_node_pubkey).await?; let to_pubkey = match to_pubkey { Some(pubkey) => pubkey, @@ -1445,6 +1616,7 @@ impl NodeManager { .iter() .find(|chan| chan.funding_txo.map(|a| a.into_bitcoin_outpoint()) == Some(outpoint)); + log_trace!(self.logger, "finished calling open_channel"); match found_channel { Some(channel) => Ok(channel.into()), None => Err(MutinyError::ChannelCreationFailed), @@ -1461,6 +1633,8 @@ impl NodeManager { utxos: &[OutPoint], to_pubkey: Option, ) -> Result { + log_trace!(self.logger, "calling sweep_utxos_to_channel"); + let node = self.get_node_by_key_or_first(None).await?; let to_pubkey = match to_pubkey { Some(pubkey) => pubkey, @@ -1482,6 +1656,7 @@ impl NodeManager { .iter() .find(|chan| chan.funding_txo.map(|a| a.into_bitcoin_outpoint()) == Some(outpoint)); + log_trace!(self.logger, "finished calling sweep_utxos_to_channel"); match found_channel { Some(channel) => Ok(channel.into()), None => Err(MutinyError::ChannelCreationFailed), @@ -1496,13 +1671,18 @@ impl NodeManager { &self, to_pubkey: Option, ) -> Result { + log_trace!(self.logger, "calling sweep_all_to_channel"); + let utxos = self .list_utxos()? .iter() .map(|u| u.outpoint) .collect::>(); - self.sweep_utxos_to_channel(&utxos, to_pubkey).await + let res = self.sweep_utxos_to_channel(&utxos, to_pubkey).await; + log_trace!(self.logger, "finished calling sweep_all_to_channel"); + + res } /// Closes a channel with the given outpoint. @@ -1521,6 +1701,8 @@ impl NodeManager { force: bool, abandon: bool, ) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling close_channel"); + if force && abandon { return Err(MutinyError::ChannelClosingFailed); } @@ -1535,7 +1717,7 @@ impl NodeManager { .map(|c| (n.clone(), c.clone())) }); - match channel_opt { + let res = match channel_opt { Some((node, channel)) => { if force { node.channel_manager @@ -1606,11 +1788,16 @@ impl NodeManager { ); Err(MutinyError::NotFound) } - } + }; + log_trace!(self.logger, "finished calling close_channel"); + + res } /// Lists all the channels for all the nodes in the node manager. pub async fn list_channels(&self) -> Result, MutinyError> { + log_trace!(self.logger, "calling list_channels"); + let nodes = self.nodes.read().await; let channels: Vec = nodes .iter() @@ -1620,11 +1807,14 @@ impl NodeManager { let mutiny_channels: Vec = channels.iter().map(MutinyChannel::from).collect(); + log_trace!(self.logger, "finished calling list_channels"); Ok(mutiny_channels) } /// Lists all the peers for all the nodes in the node manager. pub async fn list_peers(&self) -> Result, MutinyError> { + log_trace!(self.logger, "calling list_peers"); + let peer_data = gossip::get_all_peers(&self.storage)?; // get peers saved in storage @@ -1676,6 +1866,7 @@ impl NodeManager { storage_peers.append(&mut missing); storage_peers.sort(); + log_trace!(self.logger, "finished calling list_peers"); Ok(storage_peers) } @@ -1689,6 +1880,8 @@ impl NodeManager { /// Resets the scorer and network graph. This can be useful if you get stuck in a bad state. pub async fn reset_router(&self) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling reset_router"); + // if we're not connected to the db, start it up let needs_db_connection = !self.storage.clone().connected().unwrap_or(true); if needs_db_connection { @@ -1704,6 +1897,7 @@ impl NodeManager { self.storage.clone().stop(); } + log_trace!(self.logger, "finished calling reset_router"); Ok(()) } @@ -1711,6 +1905,8 @@ impl NodeManager { /// /// This can be useful if you get stuck in a bad state. pub async fn reset_onchain_tracker(&self) -> Result<(), MutinyError> { + log_trace!(self.logger, "calling reset_onchain_tracker"); + // if we're not connected to the db, start it up let needs_db_connection = !self.storage.clone().connected().unwrap_or(true); if needs_db_connection { @@ -1727,6 +1923,7 @@ impl NodeManager { self.storage.clone().stop(); } + log_trace!(self.logger, "finished calling reset_onchain_tracker"); Ok(()) }