Add logging the probe handlers

Increae timeout of probing tests

Author: randomlogin

src/probing.rs

@@ -513,6 +513,14 @@ pub struct Prober {
 	pub(crate) locked_msat: Arc<AtomicU64>,
 }
 
+fn fmt_path(path: &lightning::routing::router::Path) -> String {
+	path.hops
+		.iter()
+		.map(|h| format!("{}(scid={})", h.pubkey, h.short_channel_id))
+		.collect::<Vec<_>>()
+		.join(" -> ")
+}
+
 impl Prober {
 	/// Returns the total millisatoshis currently locked in in-flight probes.
 	pub fn locked_msat(&self) -> u64 {
@@ -521,16 +529,34 @@ impl Prober {
 
 	pub(crate) fn handle_probe_successful(&self, path: &lightning::routing::router::Path) {
 		let amount: u64 = path.hops.iter().map(|h| h.fee_msat).sum();
-		let _ = self
+		let prev = self
 			.locked_msat
-			.fetch_update(Ordering::AcqRel, Ordering::Acquire, |v| Some(v.saturating_sub(amount)));
+			.fetch_update(Ordering::AcqRel, Ordering::Acquire, |v| Some(v.saturating_sub(amount)))
+			.unwrap_or(0);
+		log_debug!(
+			self.logger,
+			"Probe successful: released {} msat (locked_msat {} -> {}), path: {}",
+			amount,
+			prev,
+			prev.saturating_sub(amount),
+			fmt_path(path)
+		);
 	}
 
 	pub(crate) fn handle_probe_failed(&self, path: &lightning::routing::router::Path) {
 		let amount: u64 = path.hops.iter().map(|h| h.fee_msat).sum();
-		let _ = self
+		let prev = self
 			.locked_msat
-			.fetch_update(Ordering::AcqRel, Ordering::Acquire, |v| Some(v.saturating_sub(amount)));
+			.fetch_update(Ordering::AcqRel, Ordering::Acquire, |v| Some(v.saturating_sub(amount)))
+			.unwrap_or(0);
+		log_debug!(
+			self.logger,
+			"Probe failed: released {} msat (locked_msat {} -> {}), path: {}",
+			amount,
+			prev,
+			prev.saturating_sub(amount),
+			fmt_path(path)
+		);
 	}
 }
 

tests/probing_tests.rs

@@ -291,7 +291,7 @@ async fn probe_budget_increments_and_decrements() {
 	tokio::time::sleep(Duration::from_secs(3)).await;
 	strategy.start_probing();
 
-	let went_up = tokio::time::timeout(Duration::from_secs(10), async {
+	let went_up = tokio::time::timeout(Duration::from_secs(30), async {
 		loop {
 			if node_a.prober().map_or(0, |p| p.locked_msat()) > 0 {
 				break;
@@ -304,7 +304,7 @@ async fn probe_budget_increments_and_decrements() {
 	assert!(went_up, "locked_msat never increased — no probe was dispatched");
 	println!("First probe dispatched; locked_msat = {}", node_a.prober().unwrap().locked_msat());
 
-	let cleared = tokio::time::timeout(Duration::from_secs(20), async {
+	let cleared = tokio::time::timeout(Duration::from_secs(30), async {
 		loop {
 			if node_a.prober().map_or(1, |p| p.locked_msat()) == 0 {
 				break;
@@ -315,7 +315,6 @@ async fn probe_budget_increments_and_decrements() {
 	.await
 	.is_ok();
 	assert!(cleared, "locked_msat never returned to zero after probe resolved");
-	println!("Probe resolved; locked_msat = 0");
 
 	node_a.stop().unwrap();
 	node_b.stop().unwrap();
@@ -335,12 +334,11 @@ async fn exhausted_probe_budget_blocks_new_probes() {
 	let node_b = setup_node(&chain_source, random_config(false));
 	let node_c = setup_node(&chain_source, random_config(false));
 
-	// Use a slow probing interval so we can read capacity before the first probe fires.
 	let mut config_a = random_config(false);
 	let strategy = FixedDestStrategy::new(node_c.node_id(), PROBE_AMOUNT_MSAT);
 	config_a.probing = Some(
 		ProbingConfig::custom(strategy.clone())
-			.interval(Duration::from_secs(10))
+			.interval(Duration::from_millis(PROBING_INTERVAL_MILLISECONDS))
 			.max_locked_msat(PROBE_AMOUNT_MSAT)
 			.build(),
 	);
@@ -373,7 +371,6 @@ async fn exhausted_probe_budget_blocks_new_probes() {
 	expect_event!(node_b, ChannelReady);
 	expect_event!(node_c, ChannelReady);
 
-	// Record capacity before the first probe fires (interval is 3s, so we have time).
 	let capacity_at_open = node_a
 		.list_channels()
 		.iter()
@@ -382,10 +379,12 @@ async fn exhausted_probe_budget_blocks_new_probes() {
 		.expect("A→B channel not found");
 
 	assert_eq!(node_a.prober().map_or(1, |p| p.locked_msat()), 0, "initial locked_msat is nonzero");
+
+	tokio::time::sleep(Duration::from_secs(3)).await;
 	strategy.start_probing();
 
-	// Give gossip time to propagate to A, then wait for the first probe.
-	let locked = tokio::time::timeout(Duration::from_secs(15), async {
+	// Wait for the first probe to be in-flight.
+	let locked = tokio::time::timeout(Duration::from_secs(30), async {
 		loop {
 			if node_a.prober().map_or(0, |p| p.locked_msat()) > 0 {
 				break;
@@ -395,7 +394,7 @@ async fn exhausted_probe_budget_blocks_new_probes() {
 	})
 	.await
 	.is_ok();
-	assert!(locked, "no probe dispatched within 15 s");
+	assert!(locked, "no probe dispatched within 30 s");
 
 	// Capacity should have decreased due to the in-flight probe HTLC.
 	let capacity_with_probe = node_a
@@ -412,8 +411,6 @@ async fn exhausted_probe_budget_blocks_new_probes() {
 	// Stop B while the probe HTLC is in-flight.
 	node_b.stop().unwrap();
 
-	// Let several Prober ticks fire (interval is 3s); the budget is exhausted so
-	// they must be skipped. Wait, then check both conditions at once.
 	tokio::time::sleep(Duration::from_secs(5)).await;
 	assert!(
 		node_a.prober().map_or(0, |p| p.locked_msat()) > 0,
@@ -438,7 +435,7 @@ async fn exhausted_probe_budget_blocks_new_probes() {
 	node_b.connect(node_a.node_id(), node_a_addr, false).unwrap();
 	node_b.connect(node_c.node_id(), node_c_addr, false).unwrap();
 
-	let cleared = tokio::time::timeout(Duration::from_secs(15), async {
+	let cleared = tokio::time::timeout(Duration::from_secs(30), async {
 		loop {
 			if node_a.prober().map_or(1, |p| p.locked_msat()) == 0 {
 				break;
@@ -451,7 +448,7 @@ async fn exhausted_probe_budget_blocks_new_probes() {
 	assert!(cleared, "locked_msat never cleared after B came back online");
 
 	// Once the budget is freed, a new probe should be dispatched within a few ticks.
-	let new_probe = tokio::time::timeout(Duration::from_secs(10), async {
+	let new_probe = tokio::time::timeout(Duration::from_secs(30), async {
 		loop {
 			if node_a.prober().map_or(0, |p| p.locked_msat()) > 0 {
 				break;