From 13aaf76a94f09c0d8f94a94f20ad171c817f8778 Mon Sep 17 00:00:00 2001 From: Christian Decker Date: Wed, 15 Nov 2023 19:29:29 +0100 Subject: [PATCH] cln-plugin: Switch from `env_logger` to `tracing-subscriber` This switches the logging implementation from using the `log`-facade to using the `tracing-subscriber` instead. This allows us to also tap into the tracing instrumentation if desired, which was not possible with `log`. Changelog-Changed cln-plugin: The logging adapter now uses tracing-subscriber allowing the `tracing` ecosystem to be used. No format changes. --- Cargo.lock | 124 +++++++++++++++++++++++++++++++++++++---- plugins/Cargo.toml | 7 ++- plugins/src/logging.rs | 123 ++++++++++++++++++++++++++++------------ 3 files changed, 205 insertions(+), 49 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 4139333a2998..7d6c272a9a56 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -294,7 +294,6 @@ dependencies = [ "anyhow", "bytes", "cln-grpc", - "env_logger", "futures", "log", "serde", @@ -302,6 +301,8 @@ dependencies = [ "tokio", "tokio-stream", "tokio-util", + "tracing", + "tracing-subscriber", ] [[package]] @@ -748,6 +749,15 @@ version = "0.4.20" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b5e6163cb8c49088c2c36f57875e58ccd8c87c7427f7fbd50ea6710b2f3f2e8f" +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata 0.1.10", +] + [[package]] name = "matchit" version = "0.7.3" @@ -808,6 +818,16 @@ dependencies = [ "minimal-lexical", ] +[[package]] +name = "nu-ansi-term" +version = "0.46.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" +dependencies = [ + "overload", + "winapi", +] + [[package]] name = "num-bigint" version = "0.4.4" @@ -872,6 +892,12 @@ version = "1.18.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "dd8b5dd2ae5ed71462c540258bedcb51965123ad7e7ccf4b9a8cafaa4a63576d" +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "pem" version = "1.1.1" @@ -1077,8 +1103,17 @@ checksum = "697061221ea1b4a94a624f67d0ae2bfe4e22b8a17b6a192afb11046542cc8c47" dependencies = [ "aho-corasick", "memchr", - "regex-automata", - "regex-syntax", + "regex-automata 0.3.8", + "regex-syntax 0.7.5", +] + +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax 0.6.29", ] [[package]] @@ -1089,9 +1124,15 @@ checksum = "c2f401f4955220693b56f8ec66ee9c78abffd8d1c4f23dc41a23839eb88f0795" dependencies = [ "aho-corasick", "memchr", - "regex-syntax", + "regex-syntax 0.7.5", ] +[[package]] +name = "regex-syntax" +version = "0.6.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1" + [[package]] name = "regex-syntax" version = "0.7.5" @@ -1235,6 +1276,15 @@ dependencies = [ "serde", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "slab" version = "0.4.9" @@ -1244,6 +1294,12 @@ dependencies = [ "autocfg", ] +[[package]] +name = "smallvec" +version = "1.11.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4dccd0940a2dcdf68d092b8cbab7dc0ad8fa938bf95787e1b916b0e3d0e8e970" + [[package]] name = "socket2" version = "0.4.9" @@ -1352,6 +1408,16 @@ dependencies = [ "syn 2.0.37", ] +[[package]] +name = "thread_local" +version = "1.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3fdd6f064ccff2d6567adcb3873ca630700f00b5ad3f060c25b5dcfd9a4ce152" +dependencies = [ + "cfg-if", + "once_cell", +] + [[package]] name = "time" version = "0.3.29" @@ -1548,11 +1614,11 @@ checksum = "b6bc1c9ce2b5135ac7f93c72918fc37feb872bdc6a5533a8b85eb4b86bfdae52" [[package]] name = "tracing" -version = "0.1.37" +version = "0.1.40" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "8ce8c33a8d48bd45d624a6e523445fd21ec13d3653cd51f681abf67418f54eb8" +checksum = "c3523ab5a71916ccf420eebdf5521fcef02141234bbc0b8a49f2fdc4544364ef" dependencies = [ - "cfg-if", + "log", "pin-project-lite", "tracing-attributes", "tracing-core", @@ -1560,9 +1626,9 @@ dependencies = [ [[package]] name = "tracing-attributes" -version = "0.1.26" +version = "0.1.27" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "5f4f31f56159e98206da9efd823404b79b6ef3143b4a7ab76e67b1751b25a4ab" +checksum = "34704c8d6ebcbc939824180af020566b01a7c01f80641264eba0999f6c2b6be7" dependencies = [ "proc-macro2", "quote", @@ -1571,11 +1637,12 @@ dependencies = [ [[package]] name = "tracing-core" -version = "0.1.31" +version = "0.1.32" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "0955b8137a1df6f1a2e9a37d8a6656291ff0297c1a97c24e0d8425fe2312f79a" +checksum = "c06d3da6113f116aaee68e4d601191614c9053067f9ab7f6edbcb161237daa54" dependencies = [ "once_cell", + "valuable", ] [[package]] @@ -1588,6 +1655,35 @@ dependencies = [ "tracing", ] +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.18" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b" +dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", +] + [[package]] name = "try-lock" version = "0.2.4" @@ -1612,6 +1708,12 @@ version = "0.7.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a156c684c91ea7d62626509bce3cb4e1d9ed5c4d978f7b4352658f96a4c26b4a" +[[package]] +name = "valuable" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" + [[package]] name = "want" version = "0.3.1" diff --git a/plugins/Cargo.toml b/plugins/Cargo.toml index 1e5b40f4e2ad..c7c457ab1e6e 100644 --- a/plugins/Cargo.toml +++ b/plugins/Cargo.toml @@ -15,14 +15,15 @@ path = "examples/cln-plugin-startup.rs" [dependencies] anyhow = "1.0.51" bytes = "1.1.0" -log = { version = "0.4.14", features = ['std'] } -serde = { version = "1.0.131", features = ["derive"] } +log = { version = "^0.4", features = ['std'] } +serde = { version = "^1", features = ["derive"] } serde_json = "1.0.72" tokio-util = { version = "0.7", features = ["codec"] } tokio = { version="1", features = ['io-std', 'rt', 'sync', 'macros', 'io-util'] } tokio-stream = "0.1" futures = "0.3" -env_logger = "0.10" +tracing-subscriber = { version = "^0.3", features = ["env-filter", "tracing"] } +tracing = { version = "^0.1", features = ["async-await", "log"] } [dev-dependencies] tokio = { version = "1", features = ["macros", "rt-multi-thread", ] } diff --git a/plugins/src/logging.rs b/plugins/src/logging.rs index b752c42916ce..9534fb7f89ec 100644 --- a/plugins/src/logging.rs +++ b/plugins/src/logging.rs @@ -1,10 +1,10 @@ use crate::codec::JsonCodec; -use env_logger::filter; +use anyhow::Context; use futures::SinkExt; -use log::{Metadata, Record}; use serde::Serialize; use std::sync::Arc; use tokio::io::AsyncWrite; +use tokio::sync::mpsc; use tokio::sync::Mutex; use tokio_util::codec::FramedWrite; @@ -35,28 +35,14 @@ impl From for LogLevel { } } -/// A simple logger that just wraps log entries in a JSON-RPC -/// notification and delivers it to `lightningd`. -struct PluginLogger { - // An unbounded mpsc channel we can use to talk to the - // flusher. This avoids having circular locking dependencies if we - // happen to emit a log record while holding the lock on the - // plugin connection. - sender: tokio::sync::mpsc::UnboundedSender, - filter: filter::Filter, -} - -/// Initialize the logger starting a flusher to the passed in sink. -pub async fn init(out: Arc>>) -> Result<(), log::SetLoggerError> +/// Start a listener that receives incoming log events, and then +/// writes them out to `stdout`, after wrapping them in a valid +/// JSON-RPC notification object. +fn start_writer(out: Arc>>) -> mpsc::UnboundedSender where O: AsyncWrite + Send + Unpin + 'static, { - let out = out.clone(); - - let filter_str = std::env::var("CLN_PLUGIN_LOG").unwrap_or("info".to_string()); - let filter = filter::Builder::new().parse(&filter_str).build(); - - let (sender, mut receiver) = tokio::sync::mpsc::unbounded_channel::(); + let (sender, mut receiver) = mpsc::unbounded_channel::(); tokio::spawn(async move { while let Some(i) = receiver.recv().await { // We continue draining the queue, even if we get some @@ -72,25 +58,92 @@ where let _ = out.lock().await.send(payload).await; } }); - log::set_boxed_logger(Box::new(PluginLogger { sender, filter })) - .map(|()| log::set_max_level(log::LevelFilter::Debug)) + sender } -impl log::Log for PluginLogger { - fn enabled(&self, metadata: &Metadata) -> bool { - self.filter.enabled(metadata) +/// Initialize the logger starting a flusher to the passed in sink. +pub async fn init(out: Arc>>) -> Result<(), anyhow::Error> +where + O: AsyncWrite + Send + Unpin + 'static, +{ + return trace::init(out).context("initializing tracing logger"); +} + +mod trace { + use super::*; + use tracing::Level; + use tracing_subscriber::prelude::*; + use tracing_subscriber::Layer; + + /// Initialize the logger starting a flusher to the passed in sink. + pub fn init(out: Arc>>) -> Result<(), log::SetLoggerError> + where + O: AsyncWrite + Send + Unpin + 'static, + { + let filter = tracing_subscriber::filter::EnvFilter::from_env("CLN_PLUGIN_LOG"); + let sender = start_writer(out); + + tracing_subscriber::registry() + .with(filter) + .with(LoggingLayer::new(sender)) + .init(); + + Ok(()) + } + + struct LoggingLayer { + sender: mpsc::UnboundedSender, + } + impl LoggingLayer { + fn new(sender: mpsc::UnboundedSender) -> Self { + LoggingLayer { sender } + } + } + + impl Layer for LoggingLayer + where + S: tracing::Subscriber, + { + fn on_event( + &self, + event: &tracing::Event<'_>, + _ctx: tracing_subscriber::layer::Context<'_, S>, + ) { + let mut extractor = LogExtract::default(); + event.record(&mut extractor); + let message = match extractor.msg { + Some(m) => m, + None => return, + }; + let level = event.metadata().level().into(); + self.sender.send(LogEntry { level, message }).unwrap(); + } } - fn log(&self, record: &Record) { - if self.filter.matches(record) { - self.sender - .send(LogEntry { - level: record.level().into(), - message: record.args().to_string(), - }) - .unwrap(); + impl From<&Level> for LogLevel { + fn from(l: &Level) -> LogLevel { + match l { + &Level::DEBUG => LogLevel::Debug, + &Level::ERROR => LogLevel::Error, + &Level::INFO => LogLevel::Info, + &Level::WARN => LogLevel::Warn, + &Level::TRACE => LogLevel::Debug, + } } } - fn flush(&self) {} + /// Extracts the message from the visitor + #[derive(Default)] + struct LogExtract { + msg: Option, + } + + impl tracing::field::Visit for LogExtract { + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { + if field.name() != "message" { + return; + } + self.msg = Some(format!("{:?}", value)); + } + } }