Skip to content

Commit 8267c15

Browse files
amackillopamackillop
committed
wip
1 parent 2809840 commit 8267c15

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
@@ -1176,7 +1176,7 @@ impl Node {
11761176
let cur_anchor_reserve_sats =
11771177
total_anchor_channels_reserve_sats(&self.channel_manager, &self.config);
11781178
let spendable_amount_sats =
1179-
self.wallet.get_spendable_amount_sats(cur_anchor_reserve_sats).unwrap_or(0);
1179+
self.wallet.get_spendable_amount_sats(cur_anchor_reserve_sats, "check_channel_funds").unwrap_or(0);
11801180

11811181
// Fail early if we have less than the channel value available.
11821182
if spendable_amount_sats < amount_sats {
@@ -1638,7 +1638,7 @@ impl Node {
16381638
let cur_anchor_reserve_sats =
16391639
total_anchor_channels_reserve_sats(&self.channel_manager, &self.config);
16401640
let (total_onchain_balance_sats, spendable_onchain_balance_sats) =
1641-
self.wallet.get_balances(cur_anchor_reserve_sats).unwrap_or((0, 0));
1641+
self.wallet.get_balances(cur_anchor_reserve_sats, "list_balances").unwrap_or((0, 0));
16421642

16431643
let total_anchor_channels_reserve_sats =
16441644
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
@@ -889,14 +889,20 @@ where
889889
total_anchor_channels_reserve_sats(&self.channel_manager, &self.config);
890890
let w = Arc::clone(&self.wallet);
891891
let spendable_amount_sats = tokio::task::spawn_blocking(move || {
892-
w.get_spendable_amount_sats(cur_anchor_reserve_sats)
892+
w.get_spendable_amount_sats(cur_anchor_reserve_sats, "lsps2_open_channel")
893893
})
894894
.await
895895
.unwrap_or_else(|e| {
896896
log_error!(self.logger, "Failed to get spendable amount: {}", e);
897897
Err(Error::WalletOperationFailed)
898898
})
899899
.unwrap_or(0);
900+
log_info!(
901+
self.logger,
902+
"LSPS2 OpenChannel wallet check returned spendable_amount_sats={} for peer {}",
903+
spendable_amount_sats,
904+
their_network_key,
905+
);
900906
let required_funds_sats = channel_amount_sats
901907
+ self.config.anchor_channels_config.as_ref().map_or(0, |c| {
902908
if init_features.requires_anchors_zero_fee_htlc_tx()
@@ -1200,6 +1206,14 @@ where
12001206
amt_to_forward_msat,
12011207
channel_count
12021208
}) => {
1209+
log_info!(
1210+
self.logger,
1211+
"Handling LSPS4 OpenChannel for peer {} (amt_to_forward_msat={}, channel_count={}, thread_id={:?})",
1212+
their_network_key,
1213+
amt_to_forward_msat,
1214+
channel_count,
1215+
std::thread::current().id(),
1216+
);
12031217
if self.liquidity_manager.lsps4_service_handler().is_none() {
12041218
log_error!(self.logger, "Failed to handle LSPS4ServiceEvent as LSPS4 liquidity service was not configured.",);
12051219
return;
@@ -1236,6 +1250,11 @@ where
12361250
log_error!(self.logger, "Failed to handle LSPS4ServiceEvent as peer manager isn't available. This should never happen.",);
12371251
return;
12381252
};
1253+
log_info!(
1254+
self.logger,
1255+
"LSPS4 OpenChannel peer {} is connected; computing channel size",
1256+
their_network_key,
1257+
);
12391258

12401259
// Fail if we have insufficient onchain funds available.
12411260
let over_provisioning_msat = (amt_to_forward_msat
@@ -1256,18 +1275,63 @@ where
12561275
channel_amount_sats = channel_amount_sats.max(tier_value_sats);
12571276
}
12581277
}
1278+
log_info!(
1279+
self.logger,
1280+
"LSPS4 OpenChannel peer {} computed channel_amount_sats={} (amt_to_forward_msat={}, over_provisioning_ppm={}, min_channel_size_msat={}, tier_count={})",
1281+
their_network_key,
1282+
channel_amount_sats,
1283+
amt_to_forward_msat,
1284+
service_config.channel_over_provisioning_ppm,
1285+
service_config.min_channel_size_msat,
1286+
service_config.channel_size_tiers.len(),
1287+
);
12591288
let cur_anchor_reserve_sats =
12601289
total_anchor_channels_reserve_sats(&self.channel_manager, &self.config);
12611290
let w = Arc::clone(&self.wallet);
1262-
let spendable_amount_sats = tokio::task::spawn_blocking(move || {
1263-
w.get_spendable_amount_sats(cur_anchor_reserve_sats)
1291+
let wallet_check_peer = their_network_key;
1292+
log_info!(
1293+
self.logger,
1294+
"LSPS4 OpenChannel spawning wallet check for peer {} (reserve_sats={}, thread_id={:?})",
1295+
wallet_check_peer,
1296+
cur_anchor_reserve_sats,
1297+
std::thread::current().id(),
1298+
);
1299+
let spendable_amount_result = tokio::task::spawn_blocking(move || {
1300+
let blocking_thread_id = format!("{:?}", std::thread::current().id());
1301+
let result = w.get_spendable_amount_sats(cur_anchor_reserve_sats, "lsps4_open_channel");
1302+
(blocking_thread_id, result)
12641303
})
1265-
.await
1266-
.unwrap_or_else(|e| {
1304+
.await;
1305+
log_info!(
1306+
self.logger,
1307+
"LSPS4 OpenChannel wallet check join completed for peer {} (join_ok={}, thread_id={:?})",
1308+
their_network_key,
1309+
spendable_amount_result.is_ok(),
1310+
std::thread::current().id(),
1311+
);
1312+
let (blocking_thread_id, spendable_amount_result) = spendable_amount_result
1313+
.unwrap_or_else(|e| {
1314+
log_error!(self.logger, "Failed to get spendable amount: {}", e);
1315+
(format!("{:?}", std::thread::current().id()), Err(Error::WalletOperationFailed))
1316+
});
1317+
log_info!(
1318+
self.logger,
1319+
"LSPS4 OpenChannel wallet check blocking task returned for peer {} (blocking_thread_id={}, result={:?})",
1320+
their_network_key,
1321+
blocking_thread_id,
1322+
spendable_amount_result,
1323+
);
1324+
let spendable_amount_sats = spendable_amount_result.unwrap_or_else(|e| {
12671325
log_error!(self.logger, "Failed to get spendable amount: {}", e);
1268-
Err(Error::WalletOperationFailed)
1326+
0
12691327
})
1270-
.unwrap_or(0);
1328+
;
1329+
log_info!(
1330+
self.logger,
1331+
"LSPS4 OpenChannel wallet check returned spendable_amount_sats={} for peer {}",
1332+
spendable_amount_sats,
1333+
their_network_key,
1334+
);
12711335
let required_funds_sats = channel_amount_sats
12721336
+ self.config.anchor_channels_config.as_ref().map_or(0, |c| {
12731337
if init_features.requires_anchors_zero_fee_htlc_tx()
@@ -1278,16 +1342,32 @@ where
12781342
0
12791343
}
12801344
});
1345+
log_info!(
1346+
self.logger,
1347+
"LSPS4 OpenChannel peer {} computed required_funds_sats={} (channel_amount_sats={}, anchor_reserve_applied={})",
1348+
their_network_key,
1349+
required_funds_sats,
1350+
channel_amount_sats,
1351+
required_funds_sats.saturating_sub(channel_amount_sats),
1352+
);
12811353
if spendable_amount_sats < required_funds_sats {
12821354
log_error!(self.logger,
1283-
"Unable to create channel due to insufficient funds. Available: {}sats, Required: {}sats",
1284-
spendable_amount_sats, channel_amount_sats
1355+
"Unable to create channel due to insufficient funds. Available: {}sats, Required: {}sats, Peer: {}",
1356+
spendable_amount_sats, required_funds_sats, their_network_key
12851357
);
12861358
// TODO: We just silently fail here. Eventually we will need to remember
12871359
// the pending requests and regularly retry opening the channel until we
12881360
// succeed.
12891361
return;
12901362
}
1363+
log_info!(
1364+
self.logger,
1365+
"LSPS4 OpenChannel peer {} passed funding checks (channel_amount_sats={}, required_funds_sats={}, spendable_amount_sats={})",
1366+
their_network_key,
1367+
channel_amount_sats,
1368+
required_funds_sats,
1369+
spendable_amount_sats,
1370+
);
12911371

12921372
let mut config = self.channel_manager.get_current_config().clone();
12931373

@@ -1311,6 +1391,13 @@ where
13111391

13121392
// TODO: does LSPS4 service need to track this? seems like no?
13131393
let user_channel_id = 0;
1394+
log_info!(
1395+
self.logger,
1396+
"Calling create_channel for LSPS4 peer {} (channel_amount_sats={}, user_channel_id={})",
1397+
their_network_key,
1398+
channel_amount_sats,
1399+
user_channel_id,
1400+
);
13141401

13151402
match self.channel_manager.create_channel(
13161403
their_network_key,
@@ -1320,7 +1407,14 @@ where
13201407
None,
13211408
Some(config),
13221409
) {
1323-
Ok(_) => {},
1410+
Ok(_) => {
1411+
log_info!(
1412+
self.logger,
1413+
"LSPS4 create_channel accepted for peer {} (channel_amount_sats={})",
1414+
their_network_key,
1415+
channel_amount_sats,
1416+
);
1417+
},
13241418
Err(e) => {
13251419
// TODO: We just silently fail here. Eventually we will need to remember
13261420
// the pending requests and regularly retry opening the channel until we
@@ -2111,6 +2205,14 @@ where
21112205
&self, their_network_key: PublicKey, amt_to_forward_msat: u64,
21122206
channel_count: usize,
21132207
) -> Result<(), Error> {
2208+
log_info!(
2209+
self.logger,
2210+
"Entering open_channel_for_lsps4 for peer {} (amt_to_forward_msat={}, channel_count={}, thread_id={:?})",
2211+
their_network_key,
2212+
amt_to_forward_msat,
2213+
channel_count,
2214+
std::thread::current().id(),
2215+
);
21142216
let service_config = if let Some(service_config) =
21152217
self.lsps4_service.as_ref().map(|s| s.service_config.clone())
21162218
{
@@ -2156,10 +2258,32 @@ where
21562258
channel_amount_sats = channel_amount_sats.max(tier_value_sats);
21572259
}
21582260
}
2261+
log_info!(
2262+
self.logger,
2263+
"open_channel_for_lsps4 peer {} computed channel_amount_sats={} (amt_to_forward_msat={}, over_provisioning_ppm={}, min_channel_size_msat={}, tier_count={})",
2264+
their_network_key,
2265+
channel_amount_sats,
2266+
amt_to_forward_msat,
2267+
service_config.channel_over_provisioning_ppm,
2268+
service_config.min_channel_size_msat,
2269+
service_config.channel_size_tiers.len(),
2270+
);
21592271
let cur_anchor_reserve_sats =
21602272
total_anchor_channels_reserve_sats(&self.channel_manager, &self.config);
2273+
log_info!(
2274+
self.logger,
2275+
"open_channel_for_lsps4 peer {} fetching spendable_amount_sats with reserve_sats={}",
2276+
their_network_key,
2277+
cur_anchor_reserve_sats,
2278+
);
21612279
let spendable_amount_sats =
2162-
self.wallet.get_spendable_amount_sats(cur_anchor_reserve_sats).unwrap_or(0);
2280+
self.wallet.get_spendable_amount_sats(cur_anchor_reserve_sats, "lsps4_fallback").unwrap_or(0);
2281+
log_info!(
2282+
self.logger,
2283+
"open_channel_for_lsps4 peer {} wallet returned spendable_amount_sats={}",
2284+
their_network_key,
2285+
spendable_amount_sats,
2286+
);
21632287
let required_funds_sats = channel_amount_sats
21642288
+ self.config.anchor_channels_config.as_ref().map_or(0, |c| {
21652289
if init_features.requires_anchors_zero_fee_htlc_tx()
@@ -2170,13 +2294,29 @@ where
21702294
0
21712295
}
21722296
});
2297+
log_info!(
2298+
self.logger,
2299+
"open_channel_for_lsps4 peer {} computed required_funds_sats={} (channel_amount_sats={}, anchor_reserve_applied={})",
2300+
their_network_key,
2301+
required_funds_sats,
2302+
channel_amount_sats,
2303+
required_funds_sats.saturating_sub(channel_amount_sats),
2304+
);
21732305
if spendable_amount_sats < required_funds_sats {
21742306
log_error!(self.logger,
2175-
"Unable to create channel due to insufficient funds. Available: {}sats, Required: {}sats",
2176-
spendable_amount_sats, channel_amount_sats
2307+
"Unable to create channel due to insufficient funds. Available: {}sats, Required: {}sats, Peer: {}",
2308+
spendable_amount_sats, required_funds_sats, their_network_key
21772309
);
21782310
return Err(Error::InsufficientFunds);
21792311
}
2312+
log_info!(
2313+
self.logger,
2314+
"open_channel_for_lsps4 peer {} passed funding checks (channel_amount_sats={}, required_funds_sats={}, spendable_amount_sats={})",
2315+
their_network_key,
2316+
channel_amount_sats,
2317+
required_funds_sats,
2318+
spendable_amount_sats,
2319+
);
21802320

21812321
let mut config = self.channel_manager.get_current_config().clone();
21822322
debug_assert_eq!(
@@ -2192,6 +2332,13 @@ where
21922332
config.channel_handshake_config.their_channel_reserve_proportional_millionths = 0;
21932333

21942334
let user_channel_id = 0;
2335+
log_info!(
2336+
self.logger,
2337+
"open_channel_for_lsps4 calling create_channel for peer {} (channel_amount_sats={}, user_channel_id={})",
2338+
their_network_key,
2339+
channel_amount_sats,
2340+
user_channel_id,
2341+
);
21952342

21962343
self.channel_manager
21972344
.create_channel(
@@ -2202,7 +2349,14 @@ where
22022349
None,
22032350
Some(config),
22042351
)
2205-
.map(|_| ())
2352+
.map(|_| {
2353+
log_info!(
2354+
self.logger,
2355+
"open_channel_for_lsps4 create_channel accepted for peer {} (channel_amount_sats={})",
2356+
their_network_key,
2357+
channel_amount_sats,
2358+
);
2359+
})
22062360
.map_err(|e| {
22072361
log_error!(
22082362
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)