trace: dirty attempt at instrumenting ldk-node

Author: enigbe

Cargo.toml

@@ -75,6 +75,13 @@ serde = { version = "1.0.210", default-features = false, features = ["std", "der
 serde_json = { version = "1.0.128", default-features = false, features = ["std"] }
 log = { version = "0.4.22", default-features = false, features = ["std"]}
 
+tracing ={ version = "0.1.43" , default-features = false, features = ["log", "attributes"]}
+tracing-subscriber = {version = "0.3.22", default-features = false, features = ["std", "fmt", "json"]}
+tracing-opentelemetry ={ version = "0.32.0", default-features = false}
+opentelemetry ={ version = "0.31.0", default-features = false}
+opentelemetry_sdk ={ version = "0.31.0", default-features = false}
+opentelemetry-otlp ={ version = "0.31.0", default-features = false, features = ["trace", "grpc-tonic"]}
+
 vss-client = { package = "vss-client-ng", version = "0.4" }
 prost = { version = "0.11.6", default-features = false}
 

docker-compose.yml

@@ -48,6 +48,16 @@ services:
     networks:
       - bitcoin-electrs
 
+  jaeger:
+    image: jaegertracing/all-in-one:1.54
+    container_name: jaeger
+    ports:
+      - "6831:6831/udp"
+      - "16686:16686"
+      - "14268:14268"
+      - "4317:4317"
+      - "4318:4318"
+
 networks:
   bitcoin-electrs:
     driver: bridge

src/chain/electrum.rs

@@ -22,6 +22,7 @@ use electrum_client::{
 use lightning::chain::{Confirm, Filter, WatchedOutput};
 use lightning::util::ser::Writeable;
 use lightning_transaction_sync::ElectrumSyncClient;
+use tracing::instrument;
 
 use super::{periodically_archive_fully_resolved_monitors, WalletSyncStatus};
 use crate::config::{
@@ -79,6 +80,7 @@ impl ElectrumChainSource {
 		}
 	}
 
+	#[instrument(name = "electrum_chain_source.start", skip(self, runtime))]
 	pub(super) fn start(&self, runtime: Arc<Runtime>) -> Result<(), Error> {
 		self.electrum_runtime_status.write().unwrap().start(
 			self.server_url.clone(),

src/chain/mod.rs

@@ -15,6 +15,7 @@ use std::time::Duration;
 
 use bitcoin::{Script, Txid};
 use lightning::chain::{BestBlock, Filter};
+use tracing::instrument;
 
 use crate::chain::bitcoind::{BitcoindChainSource, UtxoSourceClient};
 use crate::chain::electrum::ElectrumChainSource;
@@ -180,6 +181,7 @@ impl ChainSource {
 		(Self { kind, tx_broadcaster, logger }, best_block)
 	}
 
+	#[instrument(name = "chain_source.start", skip(self, runtime))]
 	pub(crate) fn start(&self, runtime: Arc<Runtime>) -> Result<(), Error> {
 		match &self.kind {
 			ChainSourceKind::Electrum(electrum_chain_source) => {

src/lib.rs

@@ -102,6 +102,7 @@ pub mod payment;
 mod peer_store;
 mod runtime;
 mod scoring;
+mod tracing;
 mod tx_broadcaster;
 mod types;
 mod wallet;
@@ -111,6 +112,8 @@ use std::net::ToSocketAddrs;
 use std::sync::{Arc, Mutex, RwLock};
 use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH};
 
+pub use crate::tracing::{initialize_tracing_subscriber, TracingLogWriter};
+use ::tracing::instrument;
 pub use balance::{BalanceDetails, LightningBalance, PendingSweepBalance};
 use bitcoin::secp256k1::PublicKey;
 use bitcoin::{Address, Amount};
@@ -217,6 +220,7 @@ impl Node {
 	///
 	/// After this returns, the [`Node`] instance can be controlled via the provided API methods in
 	/// a thread-safe manner.
+	#[instrument(name = "node.start", skip(self), fields(node_id = %self.node_id()))]
 	pub fn start(&self) -> Result<(), Error> {
 		// Acquire a run lock and hold it until we're setup.
 		let mut is_running_lock = self.is_running.write().unwrap();

src/tracing.rs

@@ -0,0 +1,63 @@
+use opentelemetry::trace::TracerProvider;
+use opentelemetry_otlp::{SpanExporter, WithExportConfig};
+use opentelemetry_sdk::{trace::SdkTracerProvider, Resource};
+
+use tracing::{debug, error, info, level_filters::LevelFilter, trace, warn};
+use tracing_opentelemetry::OpenTelemetryLayer;
+use tracing_subscriber::{filter::Targets, fmt, layer::SubscriberExt, util::SubscriberInitExt};
+
+use crate::logger::{LogRecord, LogWriter};
+
+/// Tracing adapter
+pub struct TracingLogWriter {}
+
+impl LogWriter for TracingLogWriter {
+	fn log(&self, record: LogRecord) {
+		match record.level {
+			lightning::util::logger::Level::Gossip => {
+				trace!(target: "ldk_node", module = record.module_path, line = record.line, "{}", record.args)
+			},
+			lightning::util::logger::Level::Trace => {
+				trace!(target: "ldk_node", module = record.module_path, line = record.line, "{}", record.args)
+			},
+			lightning::util::logger::Level::Debug => {
+				debug!(target: "ldk_node", module = record.module_path, line = record.line, "{}", record.args)
+			},
+			lightning::util::logger::Level::Info => {
+				info!(target: "ldk_node", module = record.module_path, line = record.line, "{}", record.args)
+			},
+			lightning::util::logger::Level::Warn => {
+				warn!(target: "ldk_node", module = record.module_path, line = record.line, "{}", record.args)
+			},
+			lightning::util::logger::Level::Error => {
+				error!(target: "ldk_node", module = record.module_path, line = record.line, "{}", record.args)
+			},
+		}
+	}
+}
+
+/// Initialize tracing subscriber with Jaeger backend
+pub fn initialize_tracing_subscriber() {
+	let otlp_exporter = SpanExporter::builder()
+		.with_tonic()
+		.with_endpoint("http://localhost:4317")
+		.build()
+		.expect("Failed to create OTLP exporter");
+
+	let tracer_provider = SdkTracerProvider::builder()
+		.with_batch_exporter(otlp_exporter)
+		.with_resource(Resource::builder().with_service_name("ldk-node").build())
+		.build();
+
+	let tracer = tracer_provider.tracer("ldk_node");
+
+	tracing_subscriber::registry()
+		.with(
+			Targets::new()
+				.with_default(LevelFilter::WARN)
+				.with_target("ldk_node", LevelFilter::INFO),
+		)
+		.with(fmt::layer().json())
+		.with(OpenTelemetryLayer::new(tracer))
+		.init();
+}

tests/integration_tests_vss.rs

@@ -10,19 +10,27 @@
 mod common;
 
 use std::collections::HashMap;
+use std::sync::Arc;
 
 use ldk_node::entropy::NodeEntropy;
 use ldk_node::Builder;
+use ldk_node::{initialize_tracing_subscriber, TracingLogWriter};
 use rand::{rng, Rng};
 
 #[tokio::test(flavor = "multi_thread", worker_threads = 1)]
 async fn channel_full_cycle_with_vss_store() {
 	let (bitcoind, electrsd) = common::setup_bitcoind_and_electrsd();
 	println!("== Node A ==");
 	let esplora_url = format!("http://{}", electrsd.esplora_url.as_ref().unwrap());
+
+	initialize_tracing_subscriber();
+	tracing::info!("tracing initialized");
 	let config_a = common::random_config(true);
+	let tracing_writer = Arc::new(TracingLogWriter {});
+
 	let mut builder_a = Builder::from_config(config_a.node_config);
 	builder_a.set_chain_source_esplora(esplora_url.clone(), None);
+	builder_a.set_custom_logger(tracing_writer);
 	let vss_base_url = std::env::var("TEST_VSS_BASE_URL").unwrap();
 	let node_a = builder_a
 		.build_with_vss_store_and_fixed_headers(