Skip to content

Commit 63c448d

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

File tree

4 files changed

+187
-6
lines changed

4 files changed

+187
-6
lines changed

‎lightning-invoice/src/lib.rs‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -460,6 +460,7 @@ impl From<Network> for Currency {
460460
Network::Testnet4 => Currency::BitcoinTestnet,
461461
Network::Regtest => Currency::Regtest,
462462
Network::Signet => Currency::Signet,
463+
_ => todo!(),
463464
}
464465
}
465466
}

‎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: 83 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,9 @@ 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+
pub spans: Vec<&'static str>,
133137
}
134138

135139
impl<$($args)?> Record<$($args)?> {
@@ -138,7 +142,7 @@ impl<$($args)?> Record<$($args)?> {
138142
/// This is not exported to bindings users as fmt can't be used in C
139143
#[inline]
140144
pub fn new<$($nonstruct_args)?>(
141-
level: Level, peer_id: Option<PublicKey>, channel_id: Option<ChannelId>,
145+
level: Level, spans: Vec<&'static str>, peer_id: Option<PublicKey>, channel_id: Option<ChannelId>,
142146
args: fmt::Arguments<'a>, module_path: &'static str, file: &'static str, line: u32,
143147
payment_hash: Option<PaymentHash>
144148
) -> Record<$($args)?> {
@@ -154,6 +158,7 @@ impl<$($args)?> Record<$($args)?> {
154158
file,
155159
line,
156160
payment_hash,
161+
spans,
157162
}
158163
}
159164
}
@@ -189,9 +194,22 @@ impl<$($args)?> Display for Record<$($args)?> {
189194

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

194211
let mut open_bracket_written = false;
212+
195213
if let Some(peer_id) = self.peer_id {
196214
write!(f, " [")?;
197215
open_bracket_written = true;
@@ -384,15 +402,77 @@ impl<T: fmt::Display, I: core::iter::Iterator<Item = T> + Clone> fmt::Display fo
384402
}
385403
}
386404

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

469+
#[test]
470+
fn logger_scope() {
471+
let logger = TestLogger::new();
472+
let _scope = LoggerScope::new(&logger, "test_logger_scope");
473+
log_info!("Info");
474+
}
475+
396476
#[test]
397477
fn test_level_show() {
398478
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)