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

@@ -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-automata 0.3.8",
- "regex-syntax",
+ "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"

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'] }
+log = { version = "^0.4", features = ['std'] }
-serde = { version = "1.0.131", features = ["derive"] }
+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", ] }

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<log::Level> for LogLevel {
     }
 }
 
-/// A simple logger that just wraps log entries in a JSON-RPC
+/// Start a listener that receives incoming log events, and then
-/// notification and delivers it to `lightningd`.
+/// writes them out to `stdout`, after wrapping them in a valid
-struct PluginLogger {
+/// JSON-RPC notification object.
-    // An unbounded mpsc channel we can use to talk to the
+fn start_writer<O>(out: Arc<Mutex<FramedWrite<O, JsonCodec>>>) -> mpsc::UnboundedSender<LogEntry>
-    // 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<LogEntry>,
-    filter: filter::Filter,
-}
-
-/// Initialize the logger starting a flusher to the passed in sink.
-pub async fn init<O>(out: Arc<Mutex<FramedWrite<O, JsonCodec>>>) -> Result<(), log::SetLoggerError>
 where
     O: AsyncWrite + Send + Unpin + 'static,
 {
-    let out = out.clone();
+    let (sender, mut receiver) = mpsc::unbounded_channel::<LogEntry>();
-
-    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::<LogEntry>();
     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 }))
+    sender
-        .map(|()| log::set_max_level(log::LevelFilter::Debug))
 }
 
-impl log::Log for PluginLogger {
+/// Initialize the logger starting a flusher to the passed in sink.
-    fn enabled(&self, metadata: &Metadata) -> bool {
+pub async fn init<O>(out: Arc<Mutex<FramedWrite<O, JsonCodec>>>) -> Result<(), anyhow::Error>
-        self.filter.enabled(metadata)
+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<O>(out: Arc<Mutex<FramedWrite<O, JsonCodec>>>) -> 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(())
     }
 
-    fn log(&self, record: &Record) {
+    struct LoggingLayer {
-        if self.filter.matches(record) {
+        sender: mpsc::UnboundedSender<LogEntry>,
-            self.sender
+    }
-                .send(LogEntry {
+    impl LoggingLayer {
-                    level: record.level().into(),
+        fn new(sender: mpsc::UnboundedSender<LogEntry>) -> Self {
-                    message: record.args().to_string(),
+            LoggingLayer { sender }
-                })
-                .unwrap();
         }
     }
 
-    fn flush(&self) {}
+    impl<S> Layer<S> 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();
+        }
+    }
+
+    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,
+            }
+        }
+    }
+
+    /// Extracts the message from the visitor
+    #[derive(Default)]
+    struct LogExtract {
+        msg: Option<String>,
+    }
+
+    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));
+        }
+    }
 }