Skip to content

Commit 43c28eb

Browse files
joostjagerjoostjager
committed
Add logging using a thread-local instance
1 parent de384ff commit 43c28eb

File tree

3 files changed

+188
-6
lines changed

3 files changed

+188
-6
lines changed

‎lightning-macros/src/lib.rs‎

Lines changed: 45 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -20,12 +20,13 @@
2020

2121
extern crate alloc;
2222

23+
use alloc::string::String;
2324
use alloc::string::ToString;
2425
use proc_macro::{Delimiter, Group, TokenStream, TokenTree};
2526
use proc_macro2::TokenStream as TokenStream2;
2627
use quote::quote;
2728
use syn::spanned::Spanned;
28-
use syn::{parse, ImplItemFn, Token};
29+
use syn::{parse, parse2, Expr, ExprLit, ImplItemFn, Lit, Token};
2930
use syn::{parse_macro_input, Item};
3031

3132
fn add_async_method(mut parsed: ImplItemFn) -> TokenStream {
@@ -400,3 +401,46 @@ pub fn xtest_inventory(_input: TokenStream) -> TokenStream {
400401

401402
TokenStream::from(expanded)
402403
}
404+
405+
/// Adds a logging scope at the top of a method.
406+
#[proc_macro_attribute]
407+
pub fn log_scope(attrs: TokenStream, meth: TokenStream) -> TokenStream {
408+
let attrs: TokenStream2 = parse_macro_input!(attrs as TokenStream2);
409+
let mut name_attr: Option<String> = None;
410+
if !attrs.is_empty() {
411+
// Expect something like `name = "foo"`
412+
let expr: Expr = parse2(attrs.clone()).expect("invalid attribute syntax");
413+
414+
if let Expr::Assign(assign) = expr {
415+
// check left-hand side is `name`
416+
if let Expr::Path(path) = *assign.left {
417+
if path.path.is_ident("name") {
418+
if let Expr::Lit(ExprLit { lit: Lit::Str(s), .. }) = *assign.right {
419+
name_attr = Some(s.value());
420+
}
421+
}
422+
}
423+
}
424+
}
425+
let name = name_attr.unwrap();
426+
427+
let mut meth = if let Ok(parsed) = parse::<syn::ItemFn>(meth) {
428+
parsed
429+
} else {
430+
return (quote! {
431+
compile_error!("log_scope can only be set on methods")
432+
})
433+
.into();
434+
};
435+
436+
let init_stmt1 = quote! {
437+
let _logger_wrapper = crate::util::logger::LoggerWrapper(&self.logger);
438+
};
439+
let init_stmt2 = quote! {
440+
let _logging_context = crate::util::logger::LoggerScope::new(&_logger_wrapper, #name);
441+
};
442+
443+
meth.block.stmts.insert(0, parse(init_stmt2.into()).unwrap());
444+
meth.block.stmts.insert(0, parse(init_stmt1.into()).unwrap());
445+
quote! { #meth }.into()
446+
}

‎lightning/src/util/logger.rs‎

Lines changed: 85 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@
1515
1616
use bitcoin::secp256k1::PublicKey;
1717

18+
use core::cell::RefCell;
1819
use core::cmp;
1920
use core::fmt;
2021
use core::fmt::Display;
@@ -130,6 +131,11 @@ pub struct Record<$($args)?> {
130131
/// Note that this is only filled in for logs pertaining to a specific payment, and will be
131132
/// `None` for logs which are not directly related to a payment.
132133
pub payment_hash: Option<PaymentHash>,
134+
135+
/// The names of the surrounding spans, if any.
136+
///
137+
/// TODO: Use fixed size array to avoid allocations?
138+
pub spans: Vec<&'static str>,
133139
}
134140

135141
impl<$($args)?> Record<$($args)?> {
@@ -138,7 +144,7 @@ impl<$($args)?> Record<$($args)?> {
138144
/// This is not exported to bindings users as fmt can't be used in C
139145
#[inline]
140146
pub fn new<$($nonstruct_args)?>(
141-
level: Level, peer_id: Option<PublicKey>, channel_id: Option<ChannelId>,
147+
level: Level, spans: Vec<&'static str>, peer_id: Option<PublicKey>, channel_id: Option<ChannelId>,
142148
args: fmt::Arguments<'a>, module_path: &'static str, file: &'static str, line: u32,
143149
payment_hash: Option<PaymentHash>
144150
) -> Record<$($args)?> {
@@ -154,6 +160,7 @@ impl<$($args)?> Record<$($args)?> {
154160
file,
155161
line,
156162
payment_hash,
163+
spans,
157164
}
158165
}
159166
}
@@ -189,9 +196,22 @@ impl<$($args)?> Display for Record<$($args)?> {
189196

190197
#[cfg(test)]
191198
{
192-
write!(f, " {}", self.args)?;
199+
write!(f, " ")?;
200+
if !self.spans.is_empty() {
201+
write!(f, "[")?;
202+
for (i, span) in self.spans.iter().enumerate() {
203+
if i > 0 {
204+
write!(f, "->")?;
205+
}
206+
write!(f, "{}", span)?;
207+
}
208+
write!(f, "] ")?;
209+
}
210+
211+
write!(f, "{}", self.args)?;
193212

194213
let mut open_bracket_written = false;
214+
195215
if let Some(peer_id) = self.peer_id {
196216
write!(f, " [")?;
197217
open_bracket_written = true;
@@ -384,15 +404,77 @@ impl<T: fmt::Display, I: core::iter::Iterator<Item = T> + Clone> fmt::Display fo
384404
}
385405
}
386406

407+
/// A wrapper to allow getting a dyn Logger from a deref type.
408+
///
409+
/// TODO: Propagate up the dyn Logger type to avoid this wrapper.
410+
pub struct LoggerWrapper<'a, L: Deref>(pub &'a L)
411+
where
412+
L::Target: Logger;
413+
414+
impl<'a, L: Deref> Logger for LoggerWrapper<'a, L>
415+
where
416+
L::Target: Logger,
417+
{
418+
fn log(&self, record: Record) {
419+
self.0.log(record)
420+
}
421+
}
422+
423+
pub struct Span {
424+
pub logger: &'static dyn Logger,
425+
pub name: &'static str,
426+
}
427+
428+
thread_local! {
429+
pub(crate) static TLS_LOGGER: RefCell<Vec<Span>> = RefCell::new(Vec::new());
430+
}
431+
432+
/// A scope which pushes a logger on a thread-local stack for the duration of the scope.
433+
pub struct LoggerScope<'a> {
434+
_marker: std::marker::PhantomData<&'a ()>,
435+
}
436+
437+
impl<'a> LoggerScope<'a> {
438+
/// Pushes a logger onto the thread-local logger stack.
439+
pub fn new(logger: &'a dyn Logger, span: &'static str) -> Self {
440+
TLS_LOGGER.with(|cell| {
441+
let mut stack = cell.borrow_mut();
442+
443+
let logger_ref_static: &'static dyn Logger =
444+
unsafe { std::mem::transmute::<&'a dyn Logger, &'static dyn Logger>(logger) };
445+
446+
stack.push(Span { logger: logger_ref_static, name: span });
447+
});
448+
449+
LoggerScope { _marker: std::marker::PhantomData }
450+
}
451+
}
452+
453+
impl<'a> Drop for LoggerScope<'a> {
454+
fn drop(&mut self) {
455+
TLS_LOGGER.with(|cell| {
456+
let mut stack = cell.borrow_mut();
457+
stack.pop();
458+
});
459+
}
460+
}
461+
387462
#[cfg(test)]
388463
mod tests {
389464
use crate::ln::types::ChannelId;
390465
use crate::sync::Arc;
391466
use crate::types::payment::PaymentHash;
392-
use crate::util::logger::{Level, Logger, WithContext};
467+
use crate::util::logger::{Level, Logger, LoggerScope, WithContext};
393468
use crate::util::test_utils::TestLogger;
394469
use bitcoin::secp256k1::{PublicKey, Secp256k1, SecretKey};
395470

471+
#[test]
472+
fn logger_scope() {
473+
let logger = TestLogger::new();
474+
let _scope = LoggerScope::new(&logger, "test_logger_scope");
475+
log_info!("Info");
476+
}
477+
396478
#[test]
397479
fn test_level_show() {
398480
assert_eq!("INFO", Level::Info.to_string());

‎lightning/src/util/macro_logger.rs‎

Lines changed: 58 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -174,14 +174,40 @@ macro_rules! log_spendable {
174174
#[doc(hidden)]
175175
#[macro_export]
176176
macro_rules! log_given_level {
177-
($logger: expr, $lvl:expr, $($arg:tt)+) => (
178-
$logger.log($crate::util::logger::Record::new($lvl, None, None, format_args!($($arg)+), module_path!(), file!(), line!(), None))
177+
($logger: expr, $lvl:expr, $($arg:tt)+) => {{
178+
let mut spans = Vec::new();
179+
$crate::util::logger::TLS_LOGGER.with(|cell| {
180+
spans = cell.borrow().iter().map(|span| span.name).collect()
181+
});
182+
$logger.log($crate::util::logger::Record::new($lvl, spans, None, None, format_args!($($arg)+), module_path!(), file!(), line!(), None));
183+
}};
184+
}
185+
186+
/// Create a new Record and log it. You probably don't want to use this macro directly,
187+
/// but it needs to be exported so `log_trace` etc can use it in external crates.
188+
#[doc(hidden)]
189+
#[macro_export]
190+
macro_rules! log_given_level_ctx {
191+
($lvl:expr, $($arg:tt)+) => (
192+
$crate::util::logger::TLS_LOGGER.with(|cell| {
193+
let borrowed = cell.borrow();
194+
let spans = borrowed.iter().map(|span| span.name).collect();
195+
if let Some(span) = borrowed.last() {
196+
span.logger.log($crate::util::logger::Record::new($lvl, spans, None, None, format_args!($($arg)+), module_path!(), file!(), line!(), None))
197+
}
198+
})
179199
);
180200
}
181201

182202
/// Log at the `ERROR` level.
183203
#[macro_export]
184204
macro_rules! log_error {
205+
($fmt: literal) => {
206+
$crate::log_given_level_ctx!($crate::util::logger::Level::Error, $fmt);
207+
};
208+
($fmt: literal, $($arg:tt)*) => {
209+
$crate::log_given_level_ctx!($crate::util::logger::Level::Error, $fmt, $($arg)*);
210+
};
185211
($logger: expr, $($arg:tt)*) => (
186212
$crate::log_given_level!($logger, $crate::util::logger::Level::Error, $($arg)*);
187213
)
@@ -190,6 +216,12 @@ macro_rules! log_error {
190216
/// Log at the `WARN` level.
191217
#[macro_export]
192218
macro_rules! log_warn {
219+
($fmt: literal) => {
220+
$crate::log_given_level_ctx!($crate::util::logger::Level::Warn, $fmt);
221+
};
222+
($fmt: literal, $($arg:tt)*) => {
223+
$crate::log_given_level_ctx!($crate::util::logger::Level::Warn, $fmt, $($arg)*);
224+
};
193225
($logger: expr, $($arg:tt)*) => (
194226
$crate::log_given_level!($logger, $crate::util::logger::Level::Warn, $($arg)*);
195227
)
@@ -198,6 +230,12 @@ macro_rules! log_warn {
198230
/// Log at the `INFO` level.
199231
#[macro_export]
200232
macro_rules! log_info {
233+
($fmt: literal) => {
234+
$crate::log_given_level_ctx!($crate::util::logger::Level::Info, $fmt);
235+
};
236+
($fmt: literal, $($arg:tt)*) => {
237+
$crate::log_given_level_ctx!($crate::util::logger::Level::Info, $fmt, $($arg)*);
238+
};
201239
($logger: expr, $($arg:tt)*) => (
202240
$crate::log_given_level!($logger, $crate::util::logger::Level::Info, $($arg)*);
203241
)
@@ -206,6 +244,12 @@ macro_rules! log_info {
206244
/// Log at the `DEBUG` level.
207245
#[macro_export]
208246
macro_rules! log_debug {
247+
($fmt: literal) => {
248+
$crate::log_given_level_ctx!($crate::util::logger::Level::Debug, $fmt);
249+
};
250+
($fmt: literal, $($arg:tt)*) => {
251+
$crate::log_given_level_ctx!($crate::util::logger::Level::Debug, $fmt, $($arg)*);
252+
};
209253
($logger: expr, $($arg:tt)*) => (
210254
$crate::log_given_level!($logger, $crate::util::logger::Level::Debug, $($arg)*);
211255
)
@@ -214,6 +258,12 @@ macro_rules! log_debug {
214258
/// Log at the `TRACE` level.
215259
#[macro_export]
216260
macro_rules! log_trace {
261+
($fmt: literal) => {
262+
$crate::log_given_level_ctx!($crate::util::logger::Level::Trace, $fmt);
263+
};
264+
($fmt: literal, $($arg:tt)*) => {
265+
$crate::log_given_level_ctx!($crate::util::logger::Level::Trace, $fmt, $($arg)*);
266+
};
217267
($logger: expr, $($arg:tt)*) => (
218268
$crate::log_given_level!($logger, $crate::util::logger::Level::Trace, $($arg)*)
219269
)
@@ -222,6 +272,12 @@ macro_rules! log_trace {
222272
/// Log at the `GOSSIP` level.
223273
#[macro_export]
224274
macro_rules! log_gossip {
275+
($fmt: literal) => {
276+
$crate::log_given_level_ctx!($crate::util::logger::Level::Gossip, $fmt);
277+
};
278+
($fmt: literal, $($arg:tt)*) => {
279+
$crate::log_given_level_ctx!($crate::util::logger::Level::Gossip, $fmt, $($arg)*);
280+
};
225281
($logger: expr, $($arg:tt)*) => (
226282
$crate::log_given_level!($logger, $crate::util::logger::Level::Gossip, $($arg)*);
227283
)

0 commit comments

Comments
 (0)