diff --git a/lightning-background-processor/Cargo.toml b/lightning-background-processor/Cargo.toml index a515604a112..24e07ce49c9 100644 --- a/lightning-background-processor/Cargo.toml +++ b/lightning-background-processor/Cargo.toml @@ -28,6 +28,7 @@ lightning = { version = "0.2.0", path = "../lightning", default-features = false lightning-rapid-gossip-sync = { version = "0.2.0", path = "../lightning-rapid-gossip-sync", default-features = false } lightning-liquidity = { version = "0.2.0", path = "../lightning-liquidity", default-features = false } possiblyrandom = { version = "0.2", path = "../possiblyrandom", default-features = false } +tracing = "0.1.41" [dev-dependencies] tokio = { version = "1.35", features = [ "macros", "rt", "rt-multi-thread", "sync", "time" ] } diff --git a/lightning-liquidity/Cargo.toml b/lightning-liquidity/Cargo.toml index 3def0798436..fb737ccfd4a 100644 --- a/lightning-liquidity/Cargo.toml +++ b/lightning-liquidity/Cargo.toml @@ -33,6 +33,7 @@ chrono = { version = "0.4", default-features = false, features = ["serde", "allo serde = { version = "1.0", default-features = false, features = ["derive", "alloc"] } serde_json = { version = "1.0", default-features = false, features = ["alloc"] } backtrace = { version = "0.3", optional = true } +tracing = "0.1.41" [dev-dependencies] lightning = { version = "0.2.0", path = "../lightning", default-features = false, features = ["_test_utils"] } diff --git a/lightning-macros/src/lib.rs b/lightning-macros/src/lib.rs index e784acf72fb..79e68a63296 100644 --- a/lightning-macros/src/lib.rs +++ b/lightning-macros/src/lib.rs @@ -25,7 +25,7 @@ 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, Attribute, FnArg, ImplItem, ImplItemFn, ItemImpl, Meta, Token, Visibility}; use syn::{parse_macro_input, Item}; fn add_async_method(mut parsed: ImplItemFn) -> TokenStream { @@ -400,3 +400,30 @@ pub fn xtest_inventory(_input: TokenStream) -> TokenStream { TokenStream::from(expanded) } + +/// Auto-enters the parent span. +#[proc_macro_attribute] +pub fn auto_span_methods(_attr: TokenStream, item: TokenStream) -> TokenStream { + let mut input = parse_macro_input!(item as ItemImpl); + + for item in input.items.iter_mut() { + if let ImplItem::Fn(method) = item { + if let Visibility::Public(_) = method.vis { + // Skip the method that sets the node_span + if method.sig.ident == "set_node_id" { + continue; + } + + if let Some(FnArg::Receiver(_)) = method.sig.inputs.first() { + let block = &method.block; + method.block = syn::parse_quote!({ + let _entered_span = self.node_span.enter(); + #block + }); + } + } + } + } + + TokenStream::from(quote!(#input)) +} diff --git a/lightning-rapid-gossip-sync/Cargo.toml b/lightning-rapid-gossip-sync/Cargo.toml index 1ae9eaeaee2..2cde70d0b5d 100644 --- a/lightning-rapid-gossip-sync/Cargo.toml +++ b/lightning-rapid-gossip-sync/Cargo.toml @@ -19,6 +19,7 @@ lightning = { version = "0.2.0", path = "../lightning", default-features = false bitcoin = { version = "0.32.2", default-features = false } bitcoin_hashes = { version = "0.14.0", default-features = false } bitcoin-io = { version = "0.1.2", default-features = false } +tracing = "0.1.41" [target.'cfg(ldk_bench)'.dependencies] criterion = { version = "0.4", optional = true, default-features = false } diff --git a/lightning/Cargo.toml b/lightning/Cargo.toml index 9df4a725e54..a2a1d030d00 100644 --- a/lightning/Cargo.toml +++ b/lightning/Cargo.toml @@ -50,6 +50,8 @@ backtrace = { version = "0.3", optional = true } libm = { version = "0.2", default-features = false } inventory = { version = "0.3", optional = true } +tracing = "0.1.41" +tracing-subscriber = "0.3.20" [dev-dependencies] regex = "1.5.6" diff --git a/lightning/src/ln/channelmanager.rs b/lightning/src/ln/channelmanager.rs index 644920557d2..95f0bccfc31 100644 --- a/lightning/src/ln/channelmanager.rs +++ b/lightning/src/ln/channelmanager.rs @@ -2927,6 +2927,8 @@ pub struct ChannelManager< signer_provider: SP, logger: L, + + node_span: tracing::Span, } /// Chain-related parameters used to construct a new `ChannelManager`. @@ -3926,6 +3928,7 @@ macro_rules! process_events_body { } } +#[lightning_macros::auto_span_methods] impl< M: Deref, T: Deref, @@ -4043,9 +4046,15 @@ where #[cfg(feature = "_test_utils")] testing_dnssec_proof_offer_resolution_override: Mutex::new(new_hash_map()), + + node_span: tracing::span!(tracing::Level::INFO, "node"), } } + pub fn set_node_id(&mut self, id: String) { + self.node_span = tracing::span!(tracing::Level::INFO, "node", node_id = id); + } + /// Gets the current [`UserConfig`] which controls some global behavior and includes the /// default configuration applied to all new channels. pub fn get_current_config(&self) -> UserConfig { @@ -4126,6 +4135,8 @@ where /// [`Event::ChannelClosed::channel_id`]: events::Event::ChannelClosed::channel_id #[rustfmt::skip] pub fn create_channel(&self, their_network_key: PublicKey, channel_value_satoshis: u64, push_msat: u64, user_channel_id: u128, temporary_channel_id: Option, override_config: Option) -> Result { + tracing::info!("create_channel called"); + if channel_value_satoshis < 1000 { return Err(APIError::APIMisuseError { err: format!("Channel value must be at least 1000 satoshis. It was {}", channel_value_satoshis) }); } @@ -18122,6 +18133,7 @@ where #[cfg(feature = "_test_utils")] testing_dnssec_proof_offer_resolution_override: Mutex::new(new_hash_map()), + node_span: tracing::span!(tracing::Level::INFO, "node"), }; let mut processed_claims: HashSet> = new_hash_set(); diff --git a/lightning/src/ln/functional_test_utils.rs b/lightning/src/ln/functional_test_utils.rs index 45c8e072f8d..e758da41c4e 100644 --- a/lightning/src/ln/functional_test_utils.rs +++ b/lightning/src/ln/functional_test_utils.rs @@ -4572,7 +4572,7 @@ pub fn create_node_chanmgrs<'a, 'b>( let network = Network::Testnet; let genesis_block = bitcoin::constants::genesis_block(network); let params = ChainParameters { network, best_block: BestBlock::from_network(network) }; - let node = ChannelManager::new( + let mut node = ChannelManager::new( cfgs[i].fee_estimator, &cfgs[i].chain_monitor, cfgs[i].tx_broadcaster, @@ -4590,6 +4590,11 @@ pub fn create_node_chanmgrs<'a, 'b>( params, genesis_block.header.time, ); + + // Here we give the node its id. This is used by the auto_span_methods proc macro to enter the span in every pub + // fn. + node.set_node_id(format!("{}", i)); + chanmgrs.push(node); } diff --git a/lightning/src/ln/payment_tests.rs b/lightning/src/ln/payment_tests.rs index 9eb85173a83..d18364fd103 100644 --- a/lightning/src/ln/payment_tests.rs +++ b/lightning/src/ln/payment_tests.rs @@ -46,8 +46,12 @@ use crate::types::features::{Bolt11InvoiceFeatures, ChannelTypeFeatures}; use crate::types::payment::{PaymentHash, PaymentPreimage, PaymentSecret}; use crate::types::string::UntrustedString; use crate::util::errors::APIError; +use crate::util::logger::TracingToLogger; use crate::util::ser::Writeable; -use crate::util::test_utils; +use crate::util::test_utils::{self, TestTracerLayer}; + +use tracing_subscriber::fmt::format::FmtSpan; +use tracing_subscriber::{fmt, prelude::*}; use bitcoin::hashes::sha256::Hash as Sha256; use bitcoin::hashes::Hash; @@ -61,6 +65,7 @@ use crate::ln::functional_test_utils::*; use crate::routing::gossip::NodeId; use core::cmp::Ordering; +use std::sync::Arc; #[cfg(feature = "std")] use std::thread; @@ -428,11 +433,25 @@ fn mpp_receive_timeout() { #[test] fn test_keysend_payments() { + // tracing_subscriber::fmt().init(); + // tracing_subscriber::fmt() + // // .with_span_list(true) // <--- print parent span chain + // .with_span_events(FmtSpan::FULL) + // .init(); + do_test_keysend_payments(false); do_test_keysend_payments(true); } fn do_test_keysend_payments(public_node: bool) { + let layer = TestTracerLayer {}; + let subscriber = tracing_subscriber::registry().with(layer); + let _guard = tracing::subscriber::set_default(subscriber); + { + let _enter = tracing::info_span!("hello").entered(); + tracing::info!("Hello from tracing!"); + } + let chanmon_cfgs = create_chanmon_cfgs(2); let node_cfgs = create_node_cfgs(2, &chanmon_cfgs); let node_chanmgrs = create_node_chanmgrs(2, &node_cfgs, &[None, None]); diff --git a/lightning/src/util/logger.rs b/lightning/src/util/logger.rs index 283d3158144..df2e33b65d0 100644 --- a/lightning/src/util/logger.rs +++ b/lightning/src/util/logger.rs @@ -14,6 +14,11 @@ //! [`Level`] field. Each module may have its own Logger or share one. use bitcoin::secp256k1::PublicKey; +use tracing::Event; +use tracing::Subscriber; +use tracing_subscriber::layer::Context; +use tracing_subscriber::registry::LookupSpan; +use tracing_subscriber::Layer; use core::cmp; use core::fmt; @@ -261,6 +266,81 @@ impl + Clone> fmt::Display fo } } +/// A tracing `Layer` that forwards tracing events to a given `Logger`. +pub struct TracingToLogger +where + L::Target: Logger, +{ + logger: L, +} + +impl TracingToLogger +where + L::Target: Logger, +{ + pub fn new(logger: L) -> Self { + Self { logger } + } +} + +impl Layer for TracingToLogger +where + S: Subscriber + for<'lookup> LookupSpan<'lookup>, + L: Deref + 'static, + L::Target: Logger, +{ + fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) { + let meta = event.metadata(); + let level = *meta.level(); + + // Extract the "message" field from the event + let mut visitor = MessageVisitor::new(); + event.record(&mut visitor); + let message = visitor.message.unwrap_or_else(|| "".to_string()); + + self.logger.log(Record::new( + match level { + tracing::Level::ERROR => Level::Error, + tracing::Level::WARN => Level::Warn, + tracing::Level::INFO => Level::Info, + tracing::Level::DEBUG => Level::Debug, + tracing::Level::TRACE => Level::Trace, + }, + None, + None, + format_args!("{}", message), + meta.module_path().unwrap_or(""), + meta.file().unwrap_or(""), + meta.line().unwrap_or(0), + None, + )); + } +} + +struct MessageVisitor { + message: Option, +} + +impl MessageVisitor { + fn new() -> Self { + Self { message: None } + } +} + +impl tracing::field::Visit for MessageVisitor { + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn fmt::Debug) { + if field.name() == "message" { + self.message = Some(format!("{:?}", value)); + } + } + + fn record_str(&mut self, field: &tracing::field::Field, value: &str) { + if field.name() == "message" { + self.message = Some(value.to_string()); + } + } +} + #[cfg(test)] mod tests { use crate::ln::types::ChannelId; diff --git a/lightning/src/util/macro_logger.rs b/lightning/src/util/macro_logger.rs index ec9eb14ba38..bac32d1df47 100644 --- a/lightning/src/util/macro_logger.rs +++ b/lightning/src/util/macro_logger.rs @@ -183,7 +183,7 @@ macro_rules! log_given_level { #[macro_export] macro_rules! log_error { ($logger: expr, $($arg:tt)*) => ( - $crate::log_given_level!($logger, $crate::util::logger::Level::Error, $($arg)*); + tracing::error!($($arg)*); ) } @@ -191,7 +191,7 @@ macro_rules! log_error { #[macro_export] macro_rules! log_warn { ($logger: expr, $($arg:tt)*) => ( - $crate::log_given_level!($logger, $crate::util::logger::Level::Warn, $($arg)*); + tracing::warn!($($arg)*); ) } @@ -199,7 +199,7 @@ macro_rules! log_warn { #[macro_export] macro_rules! log_info { ($logger: expr, $($arg:tt)*) => ( - $crate::log_given_level!($logger, $crate::util::logger::Level::Info, $($arg)*); + tracing::info!($($arg)*); ) } @@ -207,7 +207,7 @@ macro_rules! log_info { #[macro_export] macro_rules! log_debug { ($logger: expr, $($arg:tt)*) => ( - $crate::log_given_level!($logger, $crate::util::logger::Level::Debug, $($arg)*); + tracing::debug!($($arg)*); ) } @@ -215,7 +215,7 @@ macro_rules! log_debug { #[macro_export] macro_rules! log_trace { ($logger: expr, $($arg:tt)*) => ( - $crate::log_given_level!($logger, $crate::util::logger::Level::Trace, $($arg)*) + tracing::trace!($($arg)*); ) } diff --git a/lightning/src/util/test_utils.rs b/lightning/src/util/test_utils.rs index ad8ea224205..e7d1026ae64 100644 --- a/lightning/src/util/test_utils.rs +++ b/lightning/src/util/test_utils.rs @@ -55,7 +55,7 @@ use crate::util::config::UserConfig; use crate::util::dyn_signer::{ DynKeysInterface, DynKeysInterfaceTrait, DynPhantomKeysInterface, DynSigner, }; -use crate::util::logger::{Logger, Record}; +use crate::util::logger::{Level, Logger, Record}; #[cfg(feature = "std")] use crate::util::mut_global::MutGlobal; use crate::util::persist::{KVStore, KVStoreSync, MonitorName}; @@ -80,6 +80,11 @@ use bitcoin::secp256k1::schnorr; use bitcoin::secp256k1::{self, PublicKey, Scalar, Secp256k1, SecretKey}; use lightning_invoice::RawBolt11Invoice; +use tracing::field::{Field, Visit}; +use tracing::span::{Attributes, Id}; +use tracing::{Event, Metadata, Subscriber}; +use tracing_subscriber::registry::LookupSpan; +use tracing_subscriber::{layer, Layer}; use crate::io; use crate::prelude::*; @@ -87,11 +92,11 @@ use crate::sign::{EntropySource, NodeSigner, RandomBytes, Recipient, SignerProvi use crate::sync::{Arc, Mutex}; use alloc::boxed::Box; use core::future::Future; -use core::mem; use core::pin::Pin; use core::sync::atomic::{AtomicBool, AtomicUsize, Ordering}; use core::task::{Context, Poll, Waker}; use core::time::Duration; +use core::{fmt, mem}; use bitcoin::psbt::Psbt; use bitcoin::Sequence; @@ -1731,6 +1736,132 @@ impl Logger for TestLogger { } } +pub struct TestTracerLayer; + +#[derive(Debug, Default)] +struct NodeInfo { + node_id: Option, +} + +struct NodeVisitor { + node_id: Option, +} + +impl NodeVisitor { + fn new() -> Self { + Self { node_id: None } + } +} + +impl Visit for NodeVisitor { + fn record_str(&mut self, field: &Field, value: &str) { + if field.name() == "node_id" { + self.node_id = Some(value.to_string()); + } + } + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + // if field.name() == "node_id" { + // self.node_id = Some(format!("{:?}", value)); + // } + } +} + +struct MessageVisitor { + message: Option, +} + +impl MessageVisitor { + fn new() -> Self { + Self { message: None } + } +} + +impl Visit for MessageVisitor { + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + if field.name() == "message" { + self.message = Some(format!("{:?}", value)); + } + } +} + +impl Layer for TestTracerLayer +where + S: Subscriber + for<'lookup> LookupSpan<'lookup>, +{ + fn on_new_span( + &self, attrs: &tracing::span::Attributes<'_>, id: &tracing::span::Id, + ctx: tracing_subscriber::layer::Context<'_, S>, + ) { + let mut visitor = NodeVisitor::new(); + attrs.record(&mut visitor); + + let span = ctx.span(id).expect("span exists"); + let mut extensions = span.extensions_mut(); + let mut info = NodeInfo::default(); + info.node_id = visitor.node_id; + extensions.insert(info); + } + + fn on_record( + &self, id: &tracing::span::Id, values: &tracing::span::Record<'_>, + ctx: tracing_subscriber::layer::Context<'_, S>, + ) { + let span = ctx.span(id).expect("span exists"); + let mut visitor = NodeVisitor::new(); + values.record(&mut visitor); + + if let Some(node_id) = visitor.node_id { + let mut extensions = span.extensions_mut(); + if let Some(info) = extensions.get_mut::() { + info.node_id = Some(node_id); + } + } + } + + fn on_event(&self, event: &Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) { + let meta = event.metadata(); + let level = *meta.level(); + + let mut visitor = MessageVisitor::new(); + event.record(&mut visitor); + let message = visitor.message.unwrap_or_else(|| "".to_string()); + + // Walk up the span tree to find a node_id + let mut node_id = "?".to_string(); + if let Some(span) = ctx.event_span(event) { + let mut current = Some(span); + while let Some(s) = current { + let extensions = s.extensions(); + if let Some(info) = extensions.get::() { + if let Some(id_str) = &info.node_id { + node_id = id_str.clone(); + break; + } + } + current = s.parent(); + } + } + + let log_level = match level { + tracing::Level::ERROR => "ERROR", + tracing::Level::WARN => "WARN", + tracing::Level::INFO => "INFO", + tracing::Level::DEBUG => "DEBUG", + tracing::Level::TRACE => "TRACE", + }; + + let context = format!( + "node {} {} [{}:{}]", + node_id, + log_level, + meta.module_path().unwrap_or(""), + meta.line().unwrap_or(0) + ); + + println!("{:<55} {}", context, message); + } +} + pub struct TestNodeSigner { node_secret: SecretKey, }