Improved error logging in ChannelManager::do_accept_inbound_channel

This commit ensures that all API errors in do_accept_inbound_channel
are logged before they are returned.

Author: Jossec101

ci/check-cfg-flags.py

@@ -39,6 +39,8 @@ def check_feature(feature):
         pass
     elif feature == "electrum":
         pass
+    elif feature == "time":
+        pass
     elif feature == "_test_utils":
         pass
     elif feature == "_test_vectors":

lightning-transaction-sync/Cargo.toml

@@ -14,7 +14,8 @@ all-features = true
 rustdoc-args = ["--cfg", "docsrs"]
 
 [features]
-default = []
+default = ["time"]
+time = []
 esplora-async = ["async-interface", "esplora-client/async", "futures"]
 esplora-async-https = ["esplora-async", "esplora-client/async-https-rustls"]
 esplora-blocking = ["esplora-client/blocking"]

lightning-transaction-sync/src/esplora.rs

@@ -14,7 +14,6 @@ use esplora_client::r#async::AsyncClient;
 #[cfg(not(feature = "async-interface"))]
 use esplora_client::blocking::BlockingClient;
 
-use std::time::Instant;
 use std::collections::HashSet;
 use core::ops::Deref;
 
@@ -91,7 +90,8 @@ where
 		let mut sync_state = self.sync_state.lock().await;
 
 		log_trace!(self.logger, "Starting transaction sync.");
-		let start_time = Instant::now();
+		#[cfg(feature = "time")]
+		let start_time = std::time::Instant::now();
 		let mut num_confirmed = 0;
 		let mut num_unconfirmed = 0;
 
@@ -227,8 +227,12 @@ where
 				sync_state.pending_sync = false;
 			}
 		}
+		#[cfg(feature = "time")]
 		log_debug!(self.logger, "Finished transaction sync at tip {} in {}ms: {} confirmed, {} unconfirmed.",
 				tip_hash, start_time.elapsed().as_millis(), num_confirmed, num_unconfirmed);
+		#[cfg(not(feature = "time"))]
+		log_debug!(self.logger, "Finished transaction sync at tip {}: {} confirmed, {} unconfirmed.",
+				tip_hash, num_confirmed, num_unconfirmed);
 		Ok(())
 	}
 

lightning/src/ln/chan_utils.rs

@@ -485,9 +485,11 @@ impl TxCreationKeys {
 }
 
 /// The maximum length of a script returned by get_revokeable_redeemscript.
-// Calculated as 6 bytes of opcodes, 1 byte push plus 2 bytes for contest_delay, and two public
-// keys of 33 bytes (+ 1 push).
-pub const REVOKEABLE_REDEEMSCRIPT_MAX_LENGTH: usize = 6 + 3 + 34*2;
+// Calculated as 6 bytes of opcodes, 1 byte push plus 3 bytes for contest_delay, and two public
+// keys of 33 bytes (+ 1 push). Generally, pushes are only 2 bytes (for values below 0x7fff, i.e.
+// around 7 months), however, a 7 month contest delay shouldn't result in being unable to reclaim
+// on-chain funds.
+pub const REVOKEABLE_REDEEMSCRIPT_MAX_LENGTH: usize = 6 + 4 + 34*2;
 
 /// A script either spendable by the revocation
 /// key or the broadcaster_delayed_payment_key and satisfying the relative-locktime OP_CSV constrain.

lightning/src/ln/channel.rs

@@ -732,8 +732,8 @@ struct CommitmentStats<'a> {
 	total_fee_sat: u64, // the total fee included in the transaction
 	num_nondust_htlcs: usize,  // the number of HTLC outputs (dust HTLCs *non*-included)
 	htlcs_included: Vec<(HTLCOutputInCommitment, Option<&'a HTLCSource>)>, // the list of HTLCs (dust HTLCs *included*) which were not ignored when building the transaction
-	local_balance_msat: u64, // local balance before fees but considering dust limits
-	remote_balance_msat: u64, // remote balance before fees but considering dust limits
+	local_balance_msat: u64, // local balance before fees *not* considering dust limits
+	remote_balance_msat: u64, // remote balance before fees *not* considering dust limits
 	outbound_htlc_preimages: Vec<PaymentPreimage>, // preimages for successful offered HTLCs since last commitment
 	inbound_htlc_preimages: Vec<PaymentPreimage>, // preimages for successful received HTLCs since last commitment
 }
@@ -1728,13 +1728,13 @@ impl<SP: Deref> ChannelContext<SP> where SP::Target: SignerProvider  {
 			}
 		}
 
-		let mut value_to_self_msat: i64 = (self.value_to_self_msat - local_htlc_total_msat) as i64 + value_to_self_msat_offset;
+		let value_to_self_msat: i64 = (self.value_to_self_msat - local_htlc_total_msat) as i64 + value_to_self_msat_offset;
 		assert!(value_to_self_msat >= 0);
 		// Note that in case they have several just-awaiting-last-RAA fulfills in-progress (ie
 		// AwaitingRemoteRevokeToRemove or AwaitingRemovedRemoteRevoke) we may have allowed them to
 		// "violate" their reserve value by couting those against it. Thus, we have to convert
 		// everything to i64 before subtracting as otherwise we can overflow.
-		let mut value_to_remote_msat: i64 = (self.channel_value_satoshis * 1000) as i64 - (self.value_to_self_msat as i64) - (remote_htlc_total_msat as i64) - value_to_self_msat_offset;
+		let value_to_remote_msat: i64 = (self.channel_value_satoshis * 1000) as i64 - (self.value_to_self_msat as i64) - (remote_htlc_total_msat as i64) - value_to_self_msat_offset;
 		assert!(value_to_remote_msat >= 0);
 
 		#[cfg(debug_assertions)]
@@ -1800,10 +1800,6 @@ impl<SP: Deref> ChannelContext<SP> where SP::Target: SignerProvider  {
 		htlcs_included.sort_unstable_by_key(|h| h.0.transaction_output_index.unwrap());
 		htlcs_included.append(&mut included_dust_htlcs);
 
-		// For the stats, trimmed-to-0 the value in msats accordingly
-		value_to_self_msat = if (value_to_self_msat * 1000) < broadcaster_dust_limit_satoshis as i64 { 0 } else { value_to_self_msat };
-		value_to_remote_msat = if (value_to_remote_msat * 1000) < broadcaster_dust_limit_satoshis as i64 { 0 } else { value_to_remote_msat };
-
 		CommitmentStats {
 			tx,
 			feerate_per_kw,
@@ -1876,7 +1872,8 @@ impl<SP: Deref> ChannelContext<SP> where SP::Target: SignerProvider  {
 		if let Some(feerate) = outbound_feerate_update {
 			feerate_per_kw = cmp::max(feerate_per_kw, feerate);
 		}
-		cmp::max(2530, feerate_per_kw * 1250 / 1000)
+		let feerate_plus_quarter = feerate_per_kw.checked_mul(1250).map(|v| v / 1000);
+		cmp::max(2530, feerate_plus_quarter.unwrap_or(u32::max_value()))
 	}
 
 	/// Get forwarding information for the counterparty.
@@ -6848,6 +6845,41 @@ pub(super) struct InboundV1Channel<SP: Deref> where SP::Target: SignerProvider {
 	pub unfunded_context: UnfundedChannelContext,
 }
 
+/// Fetches the [`ChannelTypeFeatures`] that will be used for a channel built from a given
+/// [`msgs::OpenChannel`].
+pub(super) fn channel_type_from_open_channel(
+	msg: &msgs::OpenChannel, their_features: &InitFeatures,
+	our_supported_features: &ChannelTypeFeatures
+) -> Result<ChannelTypeFeatures, ChannelError> {
+	if let Some(channel_type) = &msg.channel_type {
+		if channel_type.supports_any_optional_bits() {
+			return Err(ChannelError::Close("Channel Type field contained optional bits - this is not allowed".to_owned()));
+		}
+
+		// We only support the channel types defined by the `ChannelManager` in
+		// `provided_channel_type_features`. The channel type must always support
+		// `static_remote_key`.
+		if !channel_type.requires_static_remote_key() {
+			return Err(ChannelError::Close("Channel Type was not understood - we require static remote key".to_owned()));
+		}
+		// Make sure we support all of the features behind the channel type.
+		if !channel_type.is_subset(our_supported_features) {
+			return Err(ChannelError::Close("Channel Type contains unsupported features".to_owned()));
+		}
+		let announced_channel = if (msg.channel_flags & 1) == 1 { true } else { false };
+		if channel_type.requires_scid_privacy() && announced_channel {
+			return Err(ChannelError::Close("SCID Alias/Privacy Channel Type cannot be set on a public channel".to_owned()));
+		}
+		Ok(channel_type.clone())
+	} else {
+		let channel_type = ChannelTypeFeatures::from_init(&their_features);
+		if channel_type != ChannelTypeFeatures::only_static_remote_key() {
+			return Err(ChannelError::Close("Only static_remote_key is supported for non-negotiated channel types".to_owned()));
+		}
+		Ok(channel_type)
+	}
+}
+
 impl<SP: Deref> InboundV1Channel<SP> where SP::Target: SignerProvider {
 	/// Creates a new channel from a remote sides' request for one.
 	/// Assumes chain_hash has already been checked and corresponds with what we expect!
@@ -6866,32 +6898,7 @@ impl<SP: Deref> InboundV1Channel<SP> where SP::Target: SignerProvider {
 
 		// First check the channel type is known, failing before we do anything else if we don't
 		// support this channel type.
-		let channel_type = if let Some(channel_type) = &msg.channel_type {
-			if channel_type.supports_any_optional_bits() {
-				return Err(ChannelError::Close("Channel Type field contained optional bits - this is not allowed".to_owned()));
-			}
-
-			// We only support the channel types defined by the `ChannelManager` in
-			// `provided_channel_type_features`. The channel type must always support
-			// `static_remote_key`.
-			if !channel_type.requires_static_remote_key() {
-				return Err(ChannelError::Close("Channel Type was not understood - we require static remote key".to_owned()));
-			}
-			// Make sure we support all of the features behind the channel type.
-			if !channel_type.is_subset(our_supported_features) {
-				return Err(ChannelError::Close("Channel Type contains unsupported features".to_owned()));
-			}
-			if channel_type.requires_scid_privacy() && announced_channel {
-				return Err(ChannelError::Close("SCID Alias/Privacy Channel Type cannot be set on a public channel".to_owned()));
-			}
-			channel_type.clone()
-		} else {
-			let channel_type = ChannelTypeFeatures::from_init(&their_features);
-			if channel_type != ChannelTypeFeatures::only_static_remote_key() {
-				return Err(ChannelError::Close("Only static_remote_key is supported for non-negotiated channel types".to_owned()));
-			}
-			channel_type
-		};
+		let channel_type = channel_type_from_open_channel(msg, their_features, our_supported_features)?;
 
 		let channel_keys_id = signer_provider.generate_channel_keys_id(true, msg.funding_satoshis, user_id);
 		let holder_signer = signer_provider.derive_channel_signer(msg.funding_satoshis, channel_keys_id);

lightning/src/ln/channelmanager.rs

@@ -43,7 +43,7 @@ use crate::events::{Event, EventHandler, EventsProvider, MessageSendEvent, Messa
 // Since this struct is returned in `list_channels` methods, expose it here in case users want to
 // construct one themselves.
 use crate::ln::{inbound_payment, ChannelId, PaymentHash, PaymentPreimage, PaymentSecret};
-use crate::ln::channel::{Channel, ChannelPhase, ChannelContext, ChannelError, ChannelUpdateStatus, ShutdownResult, UnfundedChannelContext, UpdateFulfillCommitFetch, OutboundV1Channel, InboundV1Channel, WithChannelContext};
+use crate::ln::channel::{self, Channel, ChannelPhase, ChannelContext, ChannelError, ChannelUpdateStatus, ShutdownResult, UnfundedChannelContext, UpdateFulfillCommitFetch, OutboundV1Channel, InboundV1Channel, WithChannelContext};
 use crate::ln::features::{Bolt12InvoiceFeatures, ChannelFeatures, ChannelTypeFeatures, InitFeatures, NodeFeatures};
 #[cfg(any(feature = "_test_utils", test))]
 use crate::ln::features::Bolt11InvoiceFeatures;
@@ -6002,13 +6002,20 @@ where
 	}
 
 	fn do_accept_inbound_channel(&self, temporary_channel_id: &ChannelId, counterparty_node_id: &PublicKey, accept_0conf: bool, user_channel_id: u128) -> Result<(), APIError> {
+
+		let logger = WithContext::from(&self.logger, Some(*counterparty_node_id), Some(*temporary_channel_id));
 		let _persistence_guard = PersistenceNotifierGuard::notify_on_drop(self);
 
 		let peers_without_funded_channels =
 			self.peers_without_funded_channels(|peer| { peer.total_channel_count() > 0 });
 		let per_peer_state = self.per_peer_state.read().unwrap();
 		let peer_state_mutex = per_peer_state.get(counterparty_node_id)
-			.ok_or_else(|| APIError::ChannelUnavailable { err: format!("Can't find a peer matching the passed counterparty node_id {}", counterparty_node_id) })?;
+		.ok_or_else(|| {
+			let err_str = format!("Can't find a peer matching the passed counterparty node_id {}", counterparty_node_id); 
+			log_error!(logger, "{}", err_str);
+
+			APIError::ChannelUnavailable { err: err_str } 
+		})?;
 		let mut peer_state_lock = peer_state_mutex.lock().unwrap();
 		let peer_state = &mut *peer_state_lock;
 		let is_only_peer_channel = peer_state.total_channel_count() == 1;
@@ -6023,9 +6030,19 @@ where
 				InboundV1Channel::new(&self.fee_estimator, &self.entropy_source, &self.signer_provider,
 					counterparty_node_id.clone(), &self.channel_type_features(), &peer_state.latest_features,
 					&unaccepted_channel.open_channel_msg, user_channel_id, &self.default_configuration, best_block_height,
-					&self.logger, accept_0conf).map_err(|e| APIError::ChannelUnavailable { err: e.to_string() })
+					&self.logger, accept_0conf).map_err(|e| {
+						let err_str = e.to_string();
+						log_error!(logger, "{}", err_str);
+
+						APIError::ChannelUnavailable { err: err_str }
+					})
+				}
+			_ => { 
+				let err_str = "No such channel awaiting to be accepted.".to_owned();
+				log_error!(logger, "{}", err_str);
+
+				Err(APIError::APIMisuseError { err: err_str })
 			}
-			_ => Err(APIError::APIMisuseError { err: "No such channel awaiting to be accepted.".to_owned() })
 		}?;
 
 		if accept_0conf {
@@ -6039,7 +6056,10 @@ where
 				}
 			};
 			peer_state.pending_msg_events.push(send_msg_err_event);
-			return Err(APIError::APIMisuseError { err: "Please use accept_inbound_channel_from_trusted_peer_0conf to accept channels with zero confirmations.".to_owned() });
+			let err_str = "Please use accept_inbound_channel_from_trusted_peer_0conf to accept channels with zero confirmations.".to_owned();
+			log_error!(logger, "{}", err_str);
+
+			return Err(APIError::APIMisuseError { err: err_str });
 		} else {
 			// If this peer already has some channels, a new channel won't increase our number of peers
 			// with unfunded channels, so as long as we aren't over the maximum number of unfunded
@@ -6052,7 +6072,10 @@ where
 					}
 				};
 				peer_state.pending_msg_events.push(send_msg_err_event);
-				return Err(APIError::APIMisuseError { err: "Too many peers with unfunded channels, refusing to accept new ones".to_owned() });
+				let err_str = "Too many peers with unfunded channels, refusing to accept new ones".to_owned();
+				log_error!(logger, "{}", err_str);
+
+				return Err(APIError::APIMisuseError { err: err_str });
 			}
 		}
 
@@ -6175,13 +6198,18 @@ where
 
 		// If we're doing manual acceptance checks on the channel, then defer creation until we're sure we want to accept.
 		if self.default_configuration.manually_accept_inbound_channels {
+			let channel_type = channel::channel_type_from_open_channel(
+					&msg, &peer_state.latest_features, &self.channel_type_features()
+				).map_err(|e|
+					MsgHandleErrInternal::from_chan_no_close(e, msg.temporary_channel_id)
+				)?;
 			let mut pending_events = self.pending_events.lock().unwrap();
 			pending_events.push_back((events::Event::OpenChannelRequest {
 				temporary_channel_id: msg.temporary_channel_id.clone(),
 				counterparty_node_id: counterparty_node_id.clone(),
 				funding_satoshis: msg.funding_satoshis,
 				push_msat: msg.push_msat,
-				channel_type: msg.channel_type.clone().unwrap(),
+				channel_type,
 			}, None));
 			peer_state.inbound_channel_request_by_id.insert(channel_id, InboundChannelRequest {
 				open_channel_msg: msg.clone(),
@@ -8984,13 +9012,7 @@ where
 				let pending_msg_events = &mut peer_state.pending_msg_events;
 
 				peer_state.channel_by_id.iter_mut().filter_map(|(_, phase)|
-					if let ChannelPhase::Funded(chan) = phase { Some(chan) } else {
-						// Since unfunded channel maps are cleared upon disconnecting a peer, and they're not persisted
-						// (so won't be recovered after a crash), they shouldn't exist here and we would never need to
-						// worry about closing and removing them.
-						debug_assert!(false);
-						None
-					}
+					if let ChannelPhase::Funded(chan) = phase { Some(chan) } else { None }
 				).for_each(|chan| {
 					let logger = WithChannelContext::from(&self.logger, &chan.context);
 					pending_msg_events.push(events::MessageSendEvent::SendChannelReestablish {

lightning/src/ln/features.rs

@@ -469,12 +469,24 @@ impl<T: sealed::Context> Clone for Features<T> {
 }
 impl<T: sealed::Context> Hash for Features<T> {
 	fn hash<H: Hasher>(&self, hasher: &mut H) {
-		self.flags.hash(hasher);
+		let mut nonzero_flags = &self.flags[..];
+		while nonzero_flags.last() == Some(&0) {
+			nonzero_flags = &nonzero_flags[..nonzero_flags.len() - 1];
+		}
+		nonzero_flags.hash(hasher);
 	}
 }
 impl<T: sealed::Context> PartialEq for Features<T> {
 	fn eq(&self, o: &Self) -> bool {
-		self.flags.eq(&o.flags)
+		let mut o_iter = o.flags.iter();
+		let mut self_iter = self.flags.iter();
+		loop {
+			match (o_iter.next(), self_iter.next()) {
+				(Some(o), Some(us)) => if o != us { return false },
+				(Some(b), None) | (None, Some(b)) => if *b != 0 { return false },
+				(None, None) => return true,
+			}
+		}
 	}
 }
 impl<T: sealed::Context> PartialOrd for Features<T> {
@@ -1215,4 +1227,26 @@ mod tests {
 		assert!(!converted_features.supports_any_optional_bits());
 		assert!(converted_features.requires_static_remote_key());
 	}
+
+	#[test]
+	#[cfg(feature = "std")]
+	fn test_excess_zero_bytes_ignored() {
+		// Checks that `Hash` and `PartialEq` ignore excess zero bytes, which may appear due to
+		// feature conversion or because a peer serialized their feature poorly.
+		use std::collections::hash_map::DefaultHasher;
+		use std::hash::{Hash, Hasher};
+
+		let mut zerod_features = InitFeatures::empty();
+		zerod_features.flags = vec![0];
+		let empty_features = InitFeatures::empty();
+		assert!(empty_features.flags.is_empty());
+
+		assert_eq!(zerod_features, empty_features);
+
+		let mut zerod_hash = DefaultHasher::new();
+		zerod_features.hash(&mut zerod_hash);
+		let mut empty_hash = DefaultHasher::new();
+		empty_features.hash(&mut empty_hash);
+		assert_eq!(zerod_hash.finish(), empty_hash.finish());
+	}
 }