Introduce structured, span-based observability through Logger interface

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 {