Introduce structured, span-based observability through Logger interface

This change allows users to create hierarchical span objects through the
Logger interface for specific computations, such as the handling of
HTLCs. These span objects will be held in LDK across the corresponding
lifetimes before being dropped, providing insight in durations and
latencies.

Author: wvanlint

fuzz/src/chanmon_consistency.rs

@@ -177,7 +177,7 @@ struct LatestMonitorState {
 }
 
 struct TestChainMonitor {
-	pub logger: Arc<dyn Logger>,
+	pub logger: Arc<dyn Logger<UserSpan = ()>>,
 	pub keys: Arc<KeyProvider>,
 	pub persister: Arc<TestPersister>,
 	pub chain_monitor: Arc<
@@ -186,16 +186,16 @@ struct TestChainMonitor {
 			Arc<dyn chain::Filter>,
 			Arc<TestBroadcaster>,
 			Arc<FuzzEstimator>,
-			Arc<dyn Logger>,
+			Arc<dyn Logger<UserSpan = ()>>,
 			Arc<TestPersister>,
 		>,
 	>,
 	pub latest_monitors: Mutex<HashMap<ChannelId, LatestMonitorState>>,
 }
 impl TestChainMonitor {
 	pub fn new(
-		broadcaster: Arc<TestBroadcaster>, logger: Arc<dyn Logger>, feeest: Arc<FuzzEstimator>,
-		persister: Arc<TestPersister>, keys: Arc<KeyProvider>,
+		broadcaster: Arc<TestBroadcaster>, logger: Arc<dyn Logger<UserSpan = ()>>,
+		feeest: Arc<FuzzEstimator>, persister: Arc<TestPersister>, keys: Arc<KeyProvider>,
 	) -> Self {
 		Self {
 			chain_monitor: Arc::new(chainmonitor::ChainMonitor::new(
@@ -445,7 +445,7 @@ type ChanMan<'a> = ChannelManager<
 	Arc<FuzzEstimator>,
 	&'a FuzzRouter,
 	&'a FuzzRouter,
-	Arc<dyn Logger>,
+	Arc<dyn Logger<UserSpan = ()>>,
 >;
 
 #[inline]
@@ -621,7 +621,7 @@ pub fn do_test<Out: Output>(data: &[u8], underlying_out: Out, anchors: bool) {
 
 	macro_rules! make_node {
 		($node_id: expr, $fee_estimator: expr) => {{
-			let logger: Arc<dyn Logger> =
+			let logger: Arc<dyn Logger<UserSpan = ()>> =
 				Arc::new(test_logger::TestLogger::new($node_id.to_string(), out.clone()));
 			let node_secret = SecretKey::from_slice(&[
 				0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
@@ -677,7 +677,7 @@ pub fn do_test<Out: Output>(data: &[u8], underlying_out: Out, anchors: bool) {
 	macro_rules! reload_node {
 		($ser: expr, $node_id: expr, $old_monitors: expr, $keys_manager: expr, $fee_estimator: expr) => {{
 			let keys_manager = Arc::clone(&$keys_manager);
-			let logger: Arc<dyn Logger> =
+			let logger: Arc<dyn Logger<UserSpan = ()>> =
 				Arc::new(test_logger::TestLogger::new($node_id.to_string(), out.clone()));
 			let chain_monitor = Arc::new(TestChainMonitor::new(
 				broadcast.clone(),

fuzz/src/full_stack.rs

@@ -221,7 +221,7 @@ type ChannelMan<'a> = ChannelManager<
 			Arc<dyn chain::Filter>,
 			Arc<TestBroadcaster>,
 			Arc<FuzzEstimator>,
-			Arc<dyn Logger>,
+			Arc<dyn Logger<UserSpan = ()>>,
 			Arc<TestPersister>,
 		>,
 	>,
@@ -232,14 +232,20 @@ type ChannelMan<'a> = ChannelManager<
 	Arc<FuzzEstimator>,
 	&'a FuzzRouter,
 	&'a FuzzRouter,
-	Arc<dyn Logger>,
+	Arc<dyn Logger<UserSpan = ()>>,
 >;
 type PeerMan<'a> = PeerManager<
 	Peer<'a>,
 	Arc<ChannelMan<'a>>,
-	Arc<P2PGossipSync<Arc<NetworkGraph<Arc<dyn Logger>>>, Arc<dyn UtxoLookup>, Arc<dyn Logger>>>,
+	Arc<
+		P2PGossipSync<
+			Arc<NetworkGraph<Arc<dyn Logger<UserSpan = ()>>>>,
+			Arc<dyn UtxoLookup>,
+			Arc<dyn Logger<UserSpan = ()>>,
+		>,
+	>,
 	IgnoringMessageHandler,
-	Arc<dyn Logger>,
+	Arc<dyn Logger<UserSpan = ()>>,
 	IgnoringMessageHandler,
 	Arc<KeyProvider>,
 >;
@@ -252,7 +258,7 @@ struct MoneyLossDetector<'a> {
 			Arc<dyn chain::Filter>,
 			Arc<TestBroadcaster>,
 			Arc<FuzzEstimator>,
-			Arc<dyn Logger>,
+			Arc<dyn Logger<UserSpan = ()>>,
 			Arc<TestPersister>,
 		>,
 	>,
@@ -276,7 +282,7 @@ impl<'a> MoneyLossDetector<'a> {
 				Arc<dyn chain::Filter>,
 				Arc<TestBroadcaster>,
 				Arc<FuzzEstimator>,
-				Arc<dyn Logger>,
+				Arc<dyn Logger<UserSpan = ()>>,
 				Arc<TestPersister>,
 			>,
 		>,
@@ -556,7 +562,7 @@ impl SignerProvider for KeyProvider {
 }
 
 #[inline]
-pub fn do_test(mut data: &[u8], logger: &Arc<dyn Logger>) {
+pub fn do_test(mut data: &[u8], logger: &Arc<dyn Logger<UserSpan = ()>>) {
 	if data.len() < 32 {
 		return;
 	}
@@ -1060,13 +1066,14 @@ pub fn do_test(mut data: &[u8], logger: &Arc<dyn Logger>) {
 }
 
 pub fn full_stack_test<Out: test_logger::Output>(data: &[u8], out: Out) {
-	let logger: Arc<dyn Logger> = Arc::new(test_logger::TestLogger::new("".to_owned(), out));
+	let logger: Arc<dyn Logger<UserSpan = ()>> =
+		Arc::new(test_logger::TestLogger::new("".to_owned(), out));
 	do_test(data, &logger);
 }
 
 #[no_mangle]
 pub extern "C" fn full_stack_run(data: *const u8, datalen: usize) {
-	let logger: Arc<dyn Logger> =
+	let logger: Arc<dyn Logger<UserSpan = ()>> =
 		Arc::new(test_logger::TestLogger::new("".to_owned(), test_logger::DevNull {}));
 	do_test(unsafe { std::slice::from_raw_parts(data, datalen) }, &logger);
 }
@@ -1695,7 +1702,7 @@ pub fn write_fst_seeds(path: &str) {
 
 #[cfg(test)]
 mod tests {
-	use lightning::util::logger::{Logger, Record};
+	use lightning::util::logger::{Logger, Record, Span};
 	use std::collections::HashMap;
 	use std::sync::{Arc, Mutex};
 
@@ -1704,6 +1711,8 @@ mod tests {
 		pub lines: Mutex<HashMap<(String, String), usize>>,
 	}
 	impl Logger for TrackingLogger {
+		type UserSpan = ();
+
 		fn log(&self, record: Record) {
 			*self
 				.lines
@@ -1720,6 +1729,8 @@ mod tests {
 				record.args
 			);
 		}
+
+		fn start(&self, _span: Span, _parent: Option<&()>) -> () {}
 	}
 
 	#[test]
@@ -1733,7 +1744,7 @@ mod tests {
 		let test = super::two_peer_forwarding_seed();
 
 		let logger = Arc::new(TrackingLogger { lines: Mutex::new(HashMap::new()) });
-		super::do_test(&test, &(Arc::clone(&logger) as Arc<dyn Logger>));
+		super::do_test(&test, &(Arc::clone(&logger) as Arc<dyn Logger<UserSpan = ()>>));
 
 		let log_entries = logger.lines.lock().unwrap();
 		// 1
@@ -1769,7 +1780,7 @@ mod tests {
 		let test = super::gossip_exchange_seed();
 
 		let logger = Arc::new(TrackingLogger { lines: Mutex::new(HashMap::new()) });
-		super::do_test(&test, &(Arc::clone(&logger) as Arc<dyn Logger>));
+		super::do_test(&test, &(Arc::clone(&logger) as Arc<dyn Logger<UserSpan = ()>>));
 
 		let log_entries = logger.lines.lock().unwrap();
 		assert_eq!(log_entries.get(&("lightning::ln::peer_handler".to_string(), "Sending message to all peers except Some(PublicKey(0000000000000000000000000000000000000000000000000000000000000002ff00000000000000000000000000000000000000000000000000000000000002)) or the announced channel's counterparties: ChannelAnnouncement { node_signature_1: 3026020200b202200303030303030303030303030303030303030303030303030303030303030303, node_signature_2: 3026020200b202200202020202020202020202020202020202020202020202020202020202020202, bitcoin_signature_1: 3026020200b202200303030303030303030303030303030303030303030303030303030303030303, bitcoin_signature_2: 3026020200b202200202020202020202020202020202020202020202020202020202020202020202, contents: UnsignedChannelAnnouncement { features: [], chain_hash: 6fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d6190000000000, short_channel_id: 42, node_id_1: NodeId(030303030303030303030303030303030303030303030303030303030303030303), node_id_2: NodeId(020202020202020202020202020202020202020202020202020202020202020202), bitcoin_key_1: NodeId(030303030303030303030303030303030303030303030303030303030303030303), bitcoin_key_2: NodeId(020202020202020202020202020202020202020202020202020202020202020202), excess_data: [] } }".to_string())), Some(&1));

fuzz/src/onion_message.rs

@@ -276,7 +276,7 @@ impl SignerProvider for KeyProvider {
 #[cfg(test)]
 mod tests {
 	use bitcoin::hex::FromHex;
-	use lightning::util::logger::{Logger, Record};
+	use lightning::util::logger::{Logger, Record, Span};
 	use std::collections::HashMap;
 	use std::sync::Mutex;
 
@@ -285,6 +285,8 @@ mod tests {
 		pub lines: Mutex<HashMap<(String, String), usize>>,
 	}
 	impl Logger for TrackingLogger {
+		type UserSpan = ();
+
 		fn log(&self, record: Record) {
 			let mut lines_lock = self.lines.lock().unwrap();
 			let key = (record.module_path.to_string(), format!("{}", record.args));
@@ -298,6 +300,8 @@ mod tests {
 				record.args
 			);
 		}
+
+		fn start(&self, _span: Span, _parent: Option<&()>) -> () {}
 	}
 
 	#[test]

fuzz/src/process_onion_failure.rs

@@ -63,7 +63,8 @@ fn do_test<Out: test_logger::Output>(data: &[u8], out: Out) {
 	}
 
 	let secp_ctx = Secp256k1::new();
-	let logger: Arc<dyn Logger> = Arc::new(test_logger::TestLogger::new("".to_owned(), out));
+	let logger: Arc<dyn Logger<UserSpan = ()>> =
+		Arc::new(test_logger::TestLogger::new("".to_owned(), out));
 
 	let session_priv = SecretKey::from_slice(&usize_to_32_bytes(213127)).unwrap();
 	let payment_id = PaymentId(usize_to_32_bytes(232299));

fuzz/src/utils/test_logger.rs

@@ -7,7 +7,7 @@
 // You may not use this file except in accordance with one or both of these
 // licenses.
 
-use lightning::util::logger::{Logger, Record};
+use lightning::util::logger::{Logger, Record, Span};
 use std::io::Write;
 use std::sync::{Arc, Mutex};
 
@@ -58,6 +58,8 @@ impl<'a, Out: Output> Write for LockedWriteAdapter<'a, Out> {
 }
 
 impl<Out: Output> Logger for TestLogger<Out> {
+	type UserSpan = ();
+
 	fn log(&self, record: Record) {
 		write!(
 			LockedWriteAdapter(&self.out),
@@ -70,4 +72,6 @@ impl<Out: Output> Logger for TestLogger<Out> {
 		)
 		.unwrap();
 	}
+
+	fn start(&self, _span: Span, _parent: Option<&()>) -> () {}
 }

lightning-background-processor/src/lib.rs

@@ -633,7 +633,9 @@ use futures_util::{dummy_waker, OptionalSelector, Selector, SelectorOutput};
 /// # use lightning_background_processor::{process_events_async, GossipSync};
 /// # struct Logger {}
 /// # impl lightning::util::logger::Logger for Logger {
+/// #     type UserSpan = ();
 /// #     fn log(&self, _record: lightning::util::logger::Record) {}
+/// #     fn start(&self, _span: lightning::util::logger::Span, _parent: Option<&()>) -> () {}
 /// # }
 /// # struct Store {}
 /// # impl lightning::util::persist::KVStore for Store {

lightning-dns-resolver/src/lib.rs

@@ -176,7 +176,7 @@ mod test {
 	use lightning::sign::{KeysManager, NodeSigner, Recipient};
 	use lightning::types::features::InitFeatures;
 	use lightning::types::payment::PaymentHash;
-	use lightning::util::logger::Logger;
+	use lightning::util::logger::{Logger, Span};
 
 	use lightning::{
 		commitment_signed_dance, expect_payment_claimed, expect_pending_htlcs_forwardable,
@@ -191,9 +191,13 @@ mod test {
 		node: &'static str,
 	}
 	impl Logger for TestLogger {
+		type UserSpan = ();
+
 		fn log(&self, record: lightning::util::logger::Record) {
 			eprintln!("{}: {}", self.node, record.args);
 		}
+
+		fn start(&self, _span: Span, _parent: Option<&()>) -> () {}
 	}
 	impl Deref for TestLogger {
 		type Target = TestLogger;

lightning-net-tokio/src/lib.rs

@@ -640,6 +640,8 @@ mod tests {
 
 	pub struct TestLogger();
 	impl lightning::util::logger::Logger for TestLogger {
+		type UserSpan = ();
+
 		fn log(&self, record: lightning::util::logger::Record) {
 			println!(
 				"{:<5} [{} : {}, {}] {}",
@@ -650,6 +652,8 @@ mod tests {
 				record.args
 			);
 		}
+
+		fn start(&self, _span: lightning::util::logger::Span, _parent: Option<&()>) -> () {}
 	}
 
 	struct MsgHandler {

lightning-rapid-gossip-sync/src/lib.rs

@@ -51,10 +51,12 @@
 //! use lightning::routing::gossip::NetworkGraph;
 //! use lightning_rapid_gossip_sync::RapidGossipSync;
 //!
-//! # use lightning::util::logger::{Logger, Record};
+//! # use lightning::util::logger::{Logger, Record, Span};
 //! # struct FakeLogger {}
 //! # impl Logger for FakeLogger {
+//! #     type UserSpan = ();
 //! #     fn log(&self, record: Record) { }
+//! #     fn start(&self, _span: Span, parent: Option<&()>) -> () {}
 //! # }
 //! # let logger = FakeLogger {};
 //!

lightning/src/chain/channelmonitor.rs

@@ -48,7 +48,7 @@ use crate::sign::{ChannelDerivationParameters, HTLCDescriptor, SpendableOutputDe
 use crate::chain::onchaintx::{ClaimEvent, FeerateStrategy, OnchainTxHandler};
 use crate::chain::package::{CounterpartyOfferedHTLCOutput, CounterpartyReceivedHTLCOutput, HolderFundingOutput, HolderHTLCOutput, PackageSolvingData, PackageTemplate, RevokedOutput, RevokedHTLCOutput};
 use crate::chain::Filter;
-use crate::util::logger::{Logger, Record};
+use crate::util::logger::{Logger, Record, Span};
 use crate::util::persist::MonitorName;
 use crate::util::ser::{Readable, ReadableArgs, RequiredWrapper, MaybeReadable, UpgradableRequired, Writer, Writeable, U48};
 use crate::util::byte_utils;
@@ -1471,12 +1471,18 @@ pub(crate) struct WithChannelMonitor<'a, L: Deref> where L::Target: Logger {
 }
 
 impl<'a, L: Deref> Logger for WithChannelMonitor<'a, L> where L::Target: Logger {
+	type UserSpan = <<L as Deref>::Target as Logger>::UserSpan;
+
 	fn log(&self, mut record: Record) {
 		record.peer_id = self.peer_id;
 		record.channel_id = self.channel_id;
 		record.payment_hash = self.payment_hash;
 		self.logger.log(record)
 	}
+
+	fn start(&self, span: Span, parent: Option<&Self::UserSpan>) -> Self::UserSpan {
+		self.logger.start(span, parent)
+	}
 }
 
 impl<'a, L: Deref> WithChannelMonitor<'a, L> where L::Target: Logger {