Add TLS logger

Author: joostjager

lightning-invoice/src/lib.rs

@@ -460,6 +460,7 @@ impl From<Network> for Currency {
 			Network::Testnet4 => Currency::BitcoinTestnet,
 			Network::Regtest => Currency::Regtest,
 			Network::Signet => Currency::Signet,
+			_ => todo!(),
 		}
 	}
 }

lightning-macros/src/lib.rs

@@ -20,12 +20,13 @@
 
 extern crate alloc;
 
+use alloc::string::String;
 use alloc::string::ToString;
 use proc_macro::{Delimiter, Group, TokenStream, TokenTree};
 use proc_macro2::TokenStream as TokenStream2;
 use quote::quote;
 use syn::spanned::Spanned;
-use syn::{parse, ImplItemFn, Token};
+use syn::{parse, parse2, Expr, ExprLit, ImplItemFn, Lit, Token};
 use syn::{parse_macro_input, Item};
 
 fn add_async_method(mut parsed: ImplItemFn) -> TokenStream {
@@ -400,3 +401,46 @@ pub fn xtest_inventory(_input: TokenStream) -> TokenStream {
 
 	TokenStream::from(expanded)
 }
+
+/// Adds a logging scope at the top of a method.
+#[proc_macro_attribute]
+pub fn log_scope(attrs: TokenStream, meth: TokenStream) -> TokenStream {
+	let attrs: TokenStream2 = parse_macro_input!(attrs as TokenStream2);
+	let mut name_attr: Option<String> = None;
+	if !attrs.is_empty() {
+		// Expect something like `name = "foo"`
+		let expr: Expr = parse2(attrs.clone()).expect("invalid attribute syntax");
+
+		if let Expr::Assign(assign) = expr {
+			// check left-hand side is `name`
+			if let Expr::Path(path) = *assign.left {
+				if path.path.is_ident("name") {
+					if let Expr::Lit(ExprLit { lit: Lit::Str(s), .. }) = *assign.right {
+						name_attr = Some(s.value());
+					}
+				}
+			}
+		}
+	}
+	let name = name_attr.unwrap();
+
+	let mut meth = if let Ok(parsed) = parse::<syn::ItemFn>(meth) {
+		parsed
+	} else {
+		return (quote! {
+			compile_error!("log_scope can only be set on methods")
+		})
+		.into();
+	};
+
+	let init_stmt1 = quote! {
+		let _logger_wrapper = crate::util::logger::LoggerWrapper(&self.logger);
+	};
+	let init_stmt2 = quote! {
+		let _logging_context = crate::util::logger::LoggerScope::new(&_logger_wrapper, #name);
+	};
+
+	meth.block.stmts.insert(0, parse(init_stmt2.into()).unwrap());
+	meth.block.stmts.insert(0, parse(init_stmt1.into()).unwrap());
+	quote! { #meth }.into()
+}

lightning/src/util/logger.rs

@@ -15,6 +15,7 @@
 
 use bitcoin::secp256k1::PublicKey;
 
+use core::cell::RefCell;
 use core::cmp;
 use core::fmt;
 use core::fmt::Display;
@@ -130,6 +131,9 @@ pub struct Record<$($args)?> {
 	/// Note that this is only filled in for logs pertaining to a specific payment, and will be
 	/// `None` for logs which are not directly related to a payment.
 	pub payment_hash: Option<PaymentHash>,
+
+	/// The names of the surrounding spans, if any.
+	pub spans: Vec<&'static str>,
 }
 
 impl<$($args)?> Record<$($args)?> {
@@ -138,7 +142,7 @@ impl<$($args)?> Record<$($args)?> {
 	/// This is not exported to bindings users as fmt can't be used in C
 	#[inline]
 	pub fn new<$($nonstruct_args)?>(
-		level: Level, peer_id: Option<PublicKey>, channel_id: Option<ChannelId>,
+		level: Level, spans: Vec<&'static str>, peer_id: Option<PublicKey>, channel_id: Option<ChannelId>,
 		args: fmt::Arguments<'a>, module_path: &'static str, file: &'static str, line: u32,
 		payment_hash: Option<PaymentHash>
 	) -> Record<$($args)?> {
@@ -154,6 +158,7 @@ impl<$($args)?> Record<$($args)?> {
 			file,
 			line,
 			payment_hash,
+			spans,
 		}
 	}
 }
@@ -189,9 +194,22 @@ impl<$($args)?> Display for Record<$($args)?> {
 
 		#[cfg(test)]
 		{
-			write!(f, " {}", self.args)?;
+			write!(f, " ")?;
+			if !self.spans.is_empty() {
+				write!(f, "[")?;
+				for (i, span) in self.spans.iter().enumerate() {
+					if i > 0 {
+						write!(f, "->")?;
+					}
+					write!(f, "{}", span)?;
+				}
+				write!(f, "] ")?;
+			}
+
+			write!(f, "{}", self.args)?;
 
 			let mut open_bracket_written = false;
+
 			if let Some(peer_id) = self.peer_id {
 				write!(f, " [")?;
 				open_bracket_written = true;
@@ -384,15 +402,75 @@ impl<T: fmt::Display, I: core::iter::Iterator<Item = T> + Clone> fmt::Display fo
 	}
 }
 
+/// A wrapper to allow getting a dyn Logger from a deref type.
+pub struct LoggerWrapper<'a, L: Deref>(pub &'a L)
+where
+	L::Target: Logger;
+
+impl<'a, L: Deref> Logger for LoggerWrapper<'a, L>
+where
+	L::Target: Logger,
+{
+	fn log(&self, record: Record) {
+		self.0.log(record)
+	}
+}
+
+pub struct Span {
+	pub logger: &'static dyn Logger,
+	pub name: &'static str,
+}
+
+thread_local! {
+	pub(crate) static TLS_LOGGER: RefCell<Vec<Span>> = RefCell::new(Vec::new());
+}
+
+/// A scope which pushes a logger on a thread-local stack for the duration of the scope.
+pub struct LoggerScope<'a> {
+	_marker: std::marker::PhantomData<&'a ()>,
+}
+
+impl<'a> LoggerScope<'a> {
+	/// Pushes a logger onto the thread-local logger stack.
+	pub fn new(logger: &'a dyn Logger, span: &'static str) -> Self {
+		TLS_LOGGER.with(|cell| {
+			let mut stack = cell.borrow_mut();
+
+			let logger_ref_static: &'static dyn Logger =
+				unsafe { std::mem::transmute::<&'a dyn Logger, &'static dyn Logger>(logger) };
+
+			stack.push(Span { logger: logger_ref_static, name: span });
+		});
+
+		LoggerScope { _marker: std::marker::PhantomData }
+	}
+}
+
+impl<'a> Drop for LoggerScope<'a> {
+	fn drop(&mut self) {
+		TLS_LOGGER.with(|cell| {
+			let mut stack = cell.borrow_mut();
+			stack.pop();
+		});
+	}
+}
+
 #[cfg(test)]
 mod tests {
 	use crate::ln::types::ChannelId;
 	use crate::sync::Arc;
 	use crate::types::payment::PaymentHash;
-	use crate::util::logger::{Level, Logger, WithContext};
+	use crate::util::logger::{Level, Logger, LoggerScope, WithContext};
 	use crate::util::test_utils::TestLogger;
 	use bitcoin::secp256k1::{PublicKey, Secp256k1, SecretKey};
 
+	#[test]
+	fn logger_scope() {
+		let logger = TestLogger::new();
+		let _scope = LoggerScope::new(&logger, "test_logger_scope");
+		log_info_ctx!("Info");
+	}
+
 	#[test]
 	fn test_level_show() {
 		assert_eq!("INFO", Level::Info.to_string());

lightning/src/util/macro_logger.rs

@@ -174,8 +174,28 @@ macro_rules! log_spendable {
 #[doc(hidden)]
 #[macro_export]
 macro_rules! log_given_level {
-	($logger: expr, $lvl:expr, $($arg:tt)+) => (
-		$logger.log($crate::util::logger::Record::new($lvl, None, None, format_args!($($arg)+), module_path!(), file!(), line!(), None))
+	($logger: expr, $lvl:expr, $($arg:tt)+) => {{
+		let mut spans = Vec::new();
+		$crate::util::logger::TLS_LOGGER.with(|cell| {
+			spans = cell.borrow().iter().map(|span| span.name).collect()
+		});
+		$logger.log($crate::util::logger::Record::new($lvl, spans, None, None, format_args!($($arg)+), module_path!(), file!(), line!(), None));
+	}};
+}
+
+/// Create a new Record and log it. You probably don't want to use this macro directly,
+/// but it needs to be exported so `log_trace` etc can use it in external crates.
+#[doc(hidden)]
+#[macro_export]
+macro_rules! log_given_level_ctx {
+	($lvl:expr, $($arg:tt)+) => (
+		$crate::util::logger::TLS_LOGGER.with(|cell| {
+			let borrowed = cell.borrow();
+			let spans = borrowed.iter().map(|span| span.name).collect();
+            if let Some(span) = borrowed.last() {
+				span.logger.log($crate::util::logger::Record::new($lvl, spans, None, None, format_args!($($arg)+), module_path!(), file!(), line!(), None))
+			}
+		})
 	);
 }
 
@@ -187,6 +207,14 @@ macro_rules! log_error {
 	)
 }
 
+// Log at the `ERROR` level using the thread-local logger.
+#[macro_export]
+macro_rules! log_error_ctx {
+    ($($arg:tt)+) => {
+		$crate::log_given_level_ctx!($crate::util::logger::Level::Error, $($arg)*);
+    };
+}
+
 /// Log at the `WARN` level.
 #[macro_export]
 macro_rules! log_warn {
@@ -195,6 +223,14 @@ macro_rules! log_warn {
 	)
 }
 
+// Log at the `WARN` level using the thread-local logger.
+#[macro_export]
+macro_rules! log_warn_ctx {
+    ($($arg:tt)+) => {
+		$crate::log_given_level_ctx!($crate::util::logger::Level::Warn, $($arg)*);
+    };
+}
+
 /// Log at the `INFO` level.
 #[macro_export]
 macro_rules! log_info {
@@ -203,6 +239,14 @@ macro_rules! log_info {
 	)
 }
 
+/// Log at the `INFO` level using the thread-local logger.
+#[macro_export]
+macro_rules! log_info_ctx {
+    ($($arg:tt)+) => {
+		$crate::log_given_level_ctx!($crate::util::logger::Level::Info, $($arg)*);
+    };
+}
+
 /// Log at the `DEBUG` level.
 #[macro_export]
 macro_rules! log_debug {
@@ -211,6 +255,14 @@ macro_rules! log_debug {
 	)
 }
 
+// Log at the `DEBUG` level using the thread-local logger.
+#[macro_export]
+macro_rules! log_debug_ctx {
+    ($($arg:tt)+) => {
+		$crate::log_given_level_ctx!($crate::util::logger::Level::Debug, $($arg)*);
+    };
+}
+
 /// Log at the `TRACE` level.
 #[macro_export]
 macro_rules! log_trace {
@@ -219,10 +271,26 @@ macro_rules! log_trace {
 	)
 }
 
+// Log at the `TRACE` level using the thread-local logger.
+#[macro_export]
+macro_rules! log_trace_ctx {
+    ($($arg:tt)+) => {
+        $crate::log_given_level_ctx!($crate::util::logger::Level::Trace, $($arg)*);
+    };
+}
+
 /// Log at the `GOSSIP` level.
 #[macro_export]
 macro_rules! log_gossip {
 	($logger: expr, $($arg:tt)*) => (
 		$crate::log_given_level!($logger, $crate::util::logger::Level::Gossip, $($arg)*);
 	)
 }
+
+// Log at the `GOSSIP` level using the thread-local logger.
+#[macro_export]
+macro_rules! log_gossip_ctx {
+    ($($arg:tt)+) => {
+        $crate::log_given_level_ctx!($crate::util::logger::Level::Gossip, $($arg)*);
+    };
+}