Skip to content

Commit 9bc236b

Browse files
amackillopamackillop
committed
wip
1 parent e174f61 commit 9bc236b

4 files changed

Lines changed: 209 additions & 22 deletions

File tree

‎src/event.rs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1220,7 +1220,7 @@ where
12201220
);
12211221
let spendable_amount_sats = self
12221222
.wallet
1223-
.get_spendable_amount_sats(cur_anchor_reserve_sats)
1223+
.get_spendable_amount_sats(cur_anchor_reserve_sats, "anchor_reserve_check")
12241224
.unwrap_or(0);
12251225

12261226
let required_amount_sats = if anchor_channels_config

‎src/lib.rs‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1173,7 +1173,7 @@ impl Node {
11731173
let cur_anchor_reserve_sats =
11741174
total_anchor_channels_reserve_sats(&self.channel_manager, &self.config);
11751175
let spendable_amount_sats =
1176-
self.wallet.get_spendable_amount_sats(cur_anchor_reserve_sats).unwrap_or(0);
1176+
self.wallet.get_spendable_amount_sats(cur_anchor_reserve_sats, "check_channel_funds").unwrap_or(0);
11771177

11781178
// Fail early if we have less than the channel value available.
11791179
if spendable_amount_sats < amount_sats {
@@ -1635,7 +1635,7 @@ impl Node {
16351635
let cur_anchor_reserve_sats =
16361636
total_anchor_channels_reserve_sats(&self.channel_manager, &self.config);
16371637
let (total_onchain_balance_sats, spendable_onchain_balance_sats) =
1638-
self.wallet.get_balances(cur_anchor_reserve_sats).unwrap_or((0, 0));
1638+
self.wallet.get_balances(cur_anchor_reserve_sats, "list_balances").unwrap_or((0, 0));
16391639

16401640
let total_anchor_channels_reserve_sats =
16411641
std::cmp::min(cur_anchor_reserve_sats, total_onchain_balance_sats);

‎src/liquidity.rs‎

Lines changed: 168 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -885,14 +885,20 @@ where
885885
total_anchor_channels_reserve_sats(&self.channel_manager, &self.config);
886886
let w = Arc::clone(&self.wallet);
887887
let spendable_amount_sats = tokio::task::spawn_blocking(move || {
888-
w.get_spendable_amount_sats(cur_anchor_reserve_sats)
888+
w.get_spendable_amount_sats(cur_anchor_reserve_sats, "lsps2_open_channel")
889889
})
890890
.await
891891
.unwrap_or_else(|e| {
892892
log_error!(self.logger, "Failed to get spendable amount: {}", e);
893893
Err(Error::WalletOperationFailed)
894894
})
895895
.unwrap_or(0);
896+
log_info!(
897+
self.logger,
898+
"LSPS2 OpenChannel wallet check returned spendable_amount_sats={} for peer {}",
899+
spendable_amount_sats,
900+
their_network_key,
901+
);
896902
let required_funds_sats = channel_amount_sats
897903
+ self.config.anchor_channels_config.as_ref().map_or(0, |c| {
898904
if init_features.requires_anchors_zero_fee_htlc_tx()
@@ -1196,6 +1202,14 @@ where
11961202
amt_to_forward_msat,
11971203
channel_count
11981204
}) => {
1205+
log_info!(
1206+
self.logger,
1207+
"Handling LSPS4 OpenChannel for peer {} (amt_to_forward_msat={}, channel_count={}, thread_id={:?})",
1208+
their_network_key,
1209+
amt_to_forward_msat,
1210+
channel_count,
1211+
std::thread::current().id(),
1212+
);
11991213
if self.liquidity_manager.lsps4_service_handler().is_none() {
12001214
log_error!(self.logger, "Failed to handle LSPS4ServiceEvent as LSPS4 liquidity service was not configured.",);
12011215
return;
@@ -1232,6 +1246,11 @@ where
12321246
log_error!(self.logger, "Failed to handle LSPS4ServiceEvent as peer manager isn't available. This should never happen.",);
12331247
return;
12341248
};
1249+
log_info!(
1250+
self.logger,
1251+
"LSPS4 OpenChannel peer {} is connected; computing channel size",
1252+
their_network_key,
1253+
);
12351254

12361255
// Fail if we have insufficient onchain funds available.
12371256
let over_provisioning_msat = (amt_to_forward_msat
@@ -1252,18 +1271,63 @@ where
12521271
channel_amount_sats = channel_amount_sats.max(tier_value_sats);
12531272
}
12541273
}
1274+
log_info!(
1275+
self.logger,
1276+
"LSPS4 OpenChannel peer {} computed channel_amount_sats={} (amt_to_forward_msat={}, over_provisioning_ppm={}, min_channel_size_msat={}, tier_count={})",
1277+
their_network_key,
1278+
channel_amount_sats,
1279+
amt_to_forward_msat,
1280+
service_config.channel_over_provisioning_ppm,
1281+
service_config.min_channel_size_msat,
1282+
service_config.channel_size_tiers.len(),
1283+
);
12551284
let cur_anchor_reserve_sats =
12561285
total_anchor_channels_reserve_sats(&self.channel_manager, &self.config);
12571286
let w = Arc::clone(&self.wallet);
1258-
let spendable_amount_sats = tokio::task::spawn_blocking(move || {
1259-
w.get_spendable_amount_sats(cur_anchor_reserve_sats)
1287+
let wallet_check_peer = their_network_key;
1288+
log_info!(
1289+
self.logger,
1290+
"LSPS4 OpenChannel spawning wallet check for peer {} (reserve_sats={}, thread_id={:?})",
1291+
wallet_check_peer,
1292+
cur_anchor_reserve_sats,
1293+
std::thread::current().id(),
1294+
);
1295+
let spendable_amount_result = tokio::task::spawn_blocking(move || {
1296+
let blocking_thread_id = format!("{:?}", std::thread::current().id());
1297+
let result = w.get_spendable_amount_sats(cur_anchor_reserve_sats, "lsps4_open_channel");
1298+
(blocking_thread_id, result)
12601299
})
1261-
.await
1262-
.unwrap_or_else(|e| {
1300+
.await;
1301+
log_info!(
1302+
self.logger,
1303+
"LSPS4 OpenChannel wallet check join completed for peer {} (join_ok={}, thread_id={:?})",
1304+
their_network_key,
1305+
spendable_amount_result.is_ok(),
1306+
std::thread::current().id(),
1307+
);
1308+
let (blocking_thread_id, spendable_amount_result) = spendable_amount_result
1309+
.unwrap_or_else(|e| {
1310+
log_error!(self.logger, "Failed to get spendable amount: {}", e);
1311+
(format!("{:?}", std::thread::current().id()), Err(Error::WalletOperationFailed))
1312+
});
1313+
log_info!(
1314+
self.logger,
1315+
"LSPS4 OpenChannel wallet check blocking task returned for peer {} (blocking_thread_id={}, result={:?})",
1316+
their_network_key,
1317+
blocking_thread_id,
1318+
spendable_amount_result,
1319+
);
1320+
let spendable_amount_sats = spendable_amount_result.unwrap_or_else(|e| {
12631321
log_error!(self.logger, "Failed to get spendable amount: {}", e);
1264-
Err(Error::WalletOperationFailed)
1322+
0
12651323
})
1266-
.unwrap_or(0);
1324+
;
1325+
log_info!(
1326+
self.logger,
1327+
"LSPS4 OpenChannel wallet check returned spendable_amount_sats={} for peer {}",
1328+
spendable_amount_sats,
1329+
their_network_key,
1330+
);
12671331
let required_funds_sats = channel_amount_sats
12681332
+ self.config.anchor_channels_config.as_ref().map_or(0, |c| {
12691333
if init_features.requires_anchors_zero_fee_htlc_tx()
@@ -1274,16 +1338,32 @@ where
12741338
0
12751339
}
12761340
});
1341+
log_info!(
1342+
self.logger,
1343+
"LSPS4 OpenChannel peer {} computed required_funds_sats={} (channel_amount_sats={}, anchor_reserve_applied={})",
1344+
their_network_key,
1345+
required_funds_sats,
1346+
channel_amount_sats,
1347+
required_funds_sats.saturating_sub(channel_amount_sats),
1348+
);
12771349
if spendable_amount_sats < required_funds_sats {
12781350
log_error!(self.logger,
1279-
"Unable to create channel due to insufficient funds. Available: {}sats, Required: {}sats",
1280-
spendable_amount_sats, channel_amount_sats
1351+
"Unable to create channel due to insufficient funds. Available: {}sats, Required: {}sats, Peer: {}",
1352+
spendable_amount_sats, required_funds_sats, their_network_key
12811353
);
12821354
// TODO: We just silently fail here. Eventually we will need to remember
12831355
// the pending requests and regularly retry opening the channel until we
12841356
// succeed.
12851357
return;
12861358
}
1359+
log_info!(
1360+
self.logger,
1361+
"LSPS4 OpenChannel peer {} passed funding checks (channel_amount_sats={}, required_funds_sats={}, spendable_amount_sats={})",
1362+
their_network_key,
1363+
channel_amount_sats,
1364+
required_funds_sats,
1365+
spendable_amount_sats,
1366+
);
12871367

12881368
let mut config = self.channel_manager.get_current_config().clone();
12891369

@@ -1307,6 +1387,13 @@ where
13071387

13081388
// TODO: does LSPS4 service need to track this? seems like no?
13091389
let user_channel_id = 0;
1390+
log_info!(
1391+
self.logger,
1392+
"Calling create_channel for LSPS4 peer {} (channel_amount_sats={}, user_channel_id={})",
1393+
their_network_key,
1394+
channel_amount_sats,
1395+
user_channel_id,
1396+
);
13101397

13111398
match self.channel_manager.create_channel(
13121399
their_network_key,
@@ -1316,7 +1403,14 @@ where
13161403
None,
13171404
Some(config),
13181405
) {
1319-
Ok(_) => {},
1406+
Ok(_) => {
1407+
log_info!(
1408+
self.logger,
1409+
"LSPS4 create_channel accepted for peer {} (channel_amount_sats={})",
1410+
their_network_key,
1411+
channel_amount_sats,
1412+
);
1413+
},
13201414
Err(e) => {
13211415
// TODO: We just silently fail here. Eventually we will need to remember
13221416
// the pending requests and regularly retry opening the channel until we
@@ -2107,6 +2201,14 @@ where
21072201
&self, their_network_key: PublicKey, amt_to_forward_msat: u64,
21082202
channel_count: usize,
21092203
) -> Result<(), Error> {
2204+
log_info!(
2205+
self.logger,
2206+
"Entering open_channel_for_lsps4 for peer {} (amt_to_forward_msat={}, channel_count={}, thread_id={:?})",
2207+
their_network_key,
2208+
amt_to_forward_msat,
2209+
channel_count,
2210+
std::thread::current().id(),
2211+
);
21102212
let service_config = if let Some(service_config) =
21112213
self.lsps4_service.as_ref().map(|s| s.service_config.clone())
21122214
{
@@ -2152,10 +2254,32 @@ where
21522254
channel_amount_sats = channel_amount_sats.max(tier_value_sats);
21532255
}
21542256
}
2257+
log_info!(
2258+
self.logger,
2259+
"open_channel_for_lsps4 peer {} computed channel_amount_sats={} (amt_to_forward_msat={}, over_provisioning_ppm={}, min_channel_size_msat={}, tier_count={})",
2260+
their_network_key,
2261+
channel_amount_sats,
2262+
amt_to_forward_msat,
2263+
service_config.channel_over_provisioning_ppm,
2264+
service_config.min_channel_size_msat,
2265+
service_config.channel_size_tiers.len(),
2266+
);
21552267
let cur_anchor_reserve_sats =
21562268
total_anchor_channels_reserve_sats(&self.channel_manager, &self.config);
2269+
log_info!(
2270+
self.logger,
2271+
"open_channel_for_lsps4 peer {} fetching spendable_amount_sats with reserve_sats={}",
2272+
their_network_key,
2273+
cur_anchor_reserve_sats,
2274+
);
21572275
let spendable_amount_sats =
2158-
self.wallet.get_spendable_amount_sats(cur_anchor_reserve_sats).unwrap_or(0);
2276+
self.wallet.get_spendable_amount_sats(cur_anchor_reserve_sats, "lsps4_fallback").unwrap_or(0);
2277+
log_info!(
2278+
self.logger,
2279+
"open_channel_for_lsps4 peer {} wallet returned spendable_amount_sats={}",
2280+
their_network_key,
2281+
spendable_amount_sats,
2282+
);
21592283
let required_funds_sats = channel_amount_sats
21602284
+ self.config.anchor_channels_config.as_ref().map_or(0, |c| {
21612285
if init_features.requires_anchors_zero_fee_htlc_tx()
@@ -2166,13 +2290,29 @@ where
21662290
0
21672291
}
21682292
});
2293+
log_info!(
2294+
self.logger,
2295+
"open_channel_for_lsps4 peer {} computed required_funds_sats={} (channel_amount_sats={}, anchor_reserve_applied={})",
2296+
their_network_key,
2297+
required_funds_sats,
2298+
channel_amount_sats,
2299+
required_funds_sats.saturating_sub(channel_amount_sats),
2300+
);
21692301
if spendable_amount_sats < required_funds_sats {
21702302
log_error!(self.logger,
2171-
"Unable to create channel due to insufficient funds. Available: {}sats, Required: {}sats",
2172-
spendable_amount_sats, channel_amount_sats
2303+
"Unable to create channel due to insufficient funds. Available: {}sats, Required: {}sats, Peer: {}",
2304+
spendable_amount_sats, required_funds_sats, their_network_key
21732305
);
21742306
return Err(Error::InsufficientFunds);
21752307
}
2308+
log_info!(
2309+
self.logger,
2310+
"open_channel_for_lsps4 peer {} passed funding checks (channel_amount_sats={}, required_funds_sats={}, spendable_amount_sats={})",
2311+
their_network_key,
2312+
channel_amount_sats,
2313+
required_funds_sats,
2314+
spendable_amount_sats,
2315+
);
21762316

21772317
let mut config = self.channel_manager.get_current_config().clone();
21782318
debug_assert_eq!(
@@ -2188,6 +2328,13 @@ where
21882328
config.channel_handshake_config.their_channel_reserve_proportional_millionths = 0;
21892329

21902330
let user_channel_id = 0;
2331+
log_info!(
2332+
self.logger,
2333+
"open_channel_for_lsps4 calling create_channel for peer {} (channel_amount_sats={}, user_channel_id={})",
2334+
their_network_key,
2335+
channel_amount_sats,
2336+
user_channel_id,
2337+
);
21912338

21922339
self.channel_manager
21932340
.create_channel(
@@ -2198,7 +2345,14 @@ where
21982345
None,
21992346
Some(config),
22002347
)
2201-
.map(|_| ())
2348+
.map(|_| {
2349+
log_info!(
2350+
self.logger,
2351+
"open_channel_for_lsps4 create_channel accepted for peer {} (channel_amount_sats={})",
2352+
their_network_key,
2353+
channel_amount_sats,
2354+
);
2355+
})
22022356
.map_err(|e| {
22032357
log_error!(
22042358
self.logger,

‎src/wallet/mod.rs‎

Lines changed: 38 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,7 @@ use std::ops::Deref;
1010
use std::pin::Pin;
1111
use std::str::FromStr;
1212
use std::sync::{Arc, Mutex};
13+
use std::time::Instant;
1314

1415
use bdk_chain::spk_client::{FullScanRequest, SyncRequest};
1516
use bdk_wallet::descriptor::ExtendedDescriptor;
@@ -318,9 +319,33 @@ impl Wallet {
318319
}
319320

320321
pub(crate) fn get_balances(
321-
&self, total_anchor_channels_reserve_sats: u64,
322+
&self, total_anchor_channels_reserve_sats: u64, caller: &str,
322323
) -> Result<(u64, u64), Error> {
323-
let balance = self.inner.lock().unwrap().balance();
324+
let lock_wait_start = Instant::now();
325+
log_info!(
326+
self.logger,
327+
"Wallet get_balances starting (caller={}, reserve_sats={})",
328+
caller,
329+
total_anchor_channels_reserve_sats,
330+
);
331+
let locked_wallet = self.inner.lock().unwrap();
332+
let lock_wait_ms = lock_wait_start.elapsed().as_millis();
333+
log_info!(
334+
self.logger,
335+
"Wallet get_balances acquired wallet lock in {}ms (caller={})",
336+
lock_wait_ms,
337+
caller,
338+
);
339+
let balance_start = Instant::now();
340+
let balance = locked_wallet.balance();
341+
let balance_ms = balance_start.elapsed().as_millis();
342+
log_info!(
343+
self.logger,
344+
"Wallet get_balances fetched BDK balance in {}ms (caller={})",
345+
balance_ms,
346+
caller,
347+
);
348+
drop(locked_wallet);
324349

325350
// Make sure `list_confirmed_utxos` returns at least one `Utxo` we could use to spend/bump
326351
// Anchors if we have any confirmed amounts.
@@ -332,7 +357,15 @@ impl Wallet {
332357
);
333358
}
334359

335-
self.get_balances_inner(balance, total_anchor_channels_reserve_sats)
360+
let balances = self.get_balances_inner(balance, total_anchor_channels_reserve_sats)?;
361+
log_info!(
362+
self.logger,
363+
"Wallet get_balances computed balances total_sats={} spendable_sats={} (caller={})",
364+
balances.0,
365+
balances.1,
366+
caller,
367+
);
368+
Ok(balances)
336369
}
337370

338371
fn get_balances_inner(
@@ -347,9 +380,9 @@ impl Wallet {
347380
}
348381

349382
pub(crate) fn get_spendable_amount_sats(
350-
&self, total_anchor_channels_reserve_sats: u64,
383+
&self, total_anchor_channels_reserve_sats: u64, caller: &str,
351384
) -> Result<u64, Error> {
352-
self.get_balances(total_anchor_channels_reserve_sats).map(|(_, s)| s)
385+
self.get_balances(total_anchor_channels_reserve_sats, caller).map(|(_, s)| s)
353386
}
354387

355388
pub(crate) fn parse_and_validate_address(&self, address: &Address) -> Result<Address, Error> {

0 commit comments

Comments
 (0)