From 602afc58b5374567bf4969d2e51388b77f7b96a0 Mon Sep 17 00:00:00 2001 From: Erdem Yerebasmaz Date: Wed, 20 Mar 2024 00:59:29 +0300 Subject: [PATCH] Consolidate loggers under `logger.rs` --- libs/Cargo.lock | 1 + libs/sdk-bindings/src/uniffi_binding.rs | 37 +-- libs/sdk-core/Cargo.toml | 1 + libs/sdk-core/src/binding.rs | 37 +-- libs/sdk-core/src/breez_services.rs | 110 --------- libs/sdk-core/src/lib.rs | 1 + libs/sdk-core/src/logger.rs | 293 ++++++++++++++++++++++++ tools/sdk-cli/Cargo.lock | 1 + tools/sdk-cli/src/main.rs | 4 +- 9 files changed, 305 insertions(+), 180 deletions(-) create mode 100644 libs/sdk-core/src/logger.rs diff --git a/libs/Cargo.lock b/libs/Cargo.lock index 53790bbeb..7a13caf9c 100644 --- a/libs/Cargo.lock +++ b/libs/Cargo.lock @@ -533,6 +533,7 @@ dependencies = [ "mockito", "once_cell", "openssl", + "parking_lot", "prost", "querystring", "rand", diff --git a/libs/sdk-bindings/src/uniffi_binding.rs b/libs/sdk-bindings/src/uniffi_binding.rs index 7a602eabd..fb8a6ba47 100644 --- a/libs/sdk-bindings/src/uniffi_binding.rs +++ b/libs/sdk-bindings/src/uniffi_binding.rs @@ -1,4 +1,5 @@ use anyhow::Result; +use breez_sdk_core::logger::init_uniffi_logger; use breez_sdk_core::{ error::*, mnemonic_to_seed as sdk_mnemonic_to_seed, parse as sdk_parse_input, parse_invoice as sdk_parse_invoice, AesSuccessActionDataDecrypted, AesSuccessActionDataResult, @@ -27,39 +28,10 @@ use breez_sdk_core::{ SwapAmountType, SwapInfo, SwapStatus, Symbol, TlvEntry, UnspentTransactionOutput, UrlSuccessActionData, }; -use log::{Level, LevelFilter, Metadata, Record}; -use once_cell::sync::{Lazy, OnceCell}; +use once_cell::sync::Lazy; use std::sync::Arc; static RT: Lazy = Lazy::new(|| tokio::runtime::Runtime::new().unwrap()); -static LOG_INIT: OnceCell = OnceCell::new(); - -struct BindingLogger { - log_stream: Box, -} - -impl BindingLogger { - fn init(log_stream: Box) { - let binding_logger = BindingLogger { log_stream }; - log::set_boxed_logger(Box::new(binding_logger)).unwrap(); - log::set_max_level(LevelFilter::Trace); - } -} - -impl log::Log for BindingLogger { - fn enabled(&self, m: &Metadata) -> bool { - // ignore the internal uniffi log to prevent infinite loop. - return m.level() <= Level::Trace && *m.target() != *"breez_sdk_bindings::uniffi_binding"; - } - - fn log(&self, record: &Record) { - self.log_stream.log(LogEntry { - line: record.args().to_string(), - level: record.level().as_str().to_string(), - }); - } - fn flush(&self) {} -} /// Create a new SDK config with default values pub fn default_config( @@ -107,10 +79,7 @@ pub fn connect( /// If used, this must be called before `connect` pub fn set_log_stream(log_stream: Box) -> SdkResult<()> { - LOG_INIT.set(true).map_err(|_| SdkError::Generic { - err: "Log stream already created".into(), - })?; - BindingLogger::init(log_stream); + init_uniffi_logger(log_stream); Ok(()) } diff --git a/libs/sdk-core/Cargo.toml b/libs/sdk-core/Cargo.toml index c06ad6526..17eaf213f 100644 --- a/libs/sdk-core/Cargo.toml +++ b/libs/sdk-core/Cargo.toml @@ -29,6 +29,7 @@ ripemd = "0.1" rand = "0.8" tiny-bip39 = "1" tokio = { version = "1", features = ["full"] } +parking_lot = "0.12.1" prost = "^0.11" querystring = "1" rusqlite = { version = "0.29", features = [ diff --git a/libs/sdk-core/src/binding.rs b/libs/sdk-core/src/binding.rs index c00bc6732..5a1f1c948 100644 --- a/libs/sdk-core/src/binding.rs +++ b/libs/sdk-core/src/binding.rs @@ -15,7 +15,6 @@ use std::sync::Arc; use anyhow::{anyhow, Result}; use flutter_rust_bridge::StreamSink; -use log::{Level, LevelFilter, Metadata, Record}; use once_cell::sync::{Lazy, OnceCell}; use tokio::sync::Mutex; @@ -29,6 +28,7 @@ use crate::fiat::{FiatCurrency, Rate}; use crate::input_parser::{self, InputType, LnUrlAuthRequestData}; use crate::invoice::{self, LNInvoice}; use crate::lnurl::pay::model::LnUrlPayResult; +use crate::logger::{init_dart_logger, DartLogger}; use crate::lsp::LspInformation; use crate::models::{Config, LogEntry, NodeState, Payment, SwapInfo}; use crate::{ @@ -55,7 +55,6 @@ static BREEZ_SERVICES_INSTANCE: Lazy>>> = Lazy::new(|| Mutex::new(None)); static NOTIFICATION_STREAM: OnceCell> = OnceCell::new(); static RT: Lazy = Lazy::new(|| tokio::runtime::Runtime::new().unwrap()); -static LOG_INIT: OnceCell = OnceCell::new(); /* Breez Services API's */ @@ -180,10 +179,8 @@ pub fn breez_events_stream(s: StreamSink) -> Result<()> { /// If used, this must be called before `connect`. It can only be called once. pub fn breez_log_stream(s: StreamSink) -> Result<()> { - LOG_INIT - .set(true) - .map_err(|_| anyhow!("Log stream already created"))?; - BindingLogger::init(s); + init_dart_logger(); + DartLogger::set_stream_sink(s); Ok(()) } @@ -535,34 +532,6 @@ impl EventListener for BindingEventListener { } } -struct BindingLogger { - log_stream: StreamSink, -} - -impl BindingLogger { - fn init(log_stream: StreamSink) { - let binding_logger = BindingLogger { log_stream }; - log::set_boxed_logger(Box::new(binding_logger)).unwrap(); - log::set_max_level(LevelFilter::Trace); - } -} - -impl log::Log for BindingLogger { - fn enabled(&self, m: &Metadata) -> bool { - m.level() <= Level::Trace - } - - fn log(&self, record: &Record) { - if self.enabled(record.metadata()) { - self.log_stream.add(LogEntry { - line: record.args().to_string(), - level: record.level().as_str().to_string(), - }); - } - } - fn flush(&self) {} -} - async fn get_breez_services() -> Result, SdkError> { match BREEZ_SERVICES_INSTANCE.lock().await.as_ref() { None => Err(SdkError::Generic { diff --git a/libs/sdk-core/src/breez_services.rs b/libs/sdk-core/src/breez_services.rs index 840a00d23..a48d683e3 100644 --- a/libs/sdk-core/src/breez_services.rs +++ b/libs/sdk-core/src/breez_services.rs @@ -1,6 +1,4 @@ use std::cmp::min; -use std::fs::OpenOptions; -use std::io::Write; use std::str::FromStr; use std::sync::Arc; use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH}; @@ -10,9 +8,7 @@ use bip39::*; use bitcoin::hashes::hex::ToHex; use bitcoin::hashes::{sha256, Hash}; use bitcoin::util::bip32::ChildNumber; -use chrono::Local; use futures::TryFutureExt; -use log::{LevelFilter, Metadata, Record}; use reqwest::{header::CONTENT_TYPE, Body}; use serde_json::json; use tokio::sync::{mpsc, watch, Mutex}; @@ -1592,86 +1588,6 @@ impl BreezServices { }); } - /// Configures a global SDK logger that will log to file and will forward log events to - /// an optional application-specific logger. - /// - /// If called, it should be called before any SDK methods (for example, before `connect`). - /// - /// It must be called only once in the application lifecycle. Alternatively, If the application - /// already uses a globally-registered logger, this method shouldn't be called at all. - /// - /// ### Arguments - /// - /// - `log_dir`: Location where the the SDK log file will be created. The directory must already exist. - /// - /// - `app_logger`: Optional application logger. - /// - /// If the application is to use it's own logger, but would also like the SDK to log SDK-specific - /// log output to a file in the configured `log_dir`, then do not register the - /// app-specific logger as a global logger and instead call this method with the app logger as an arg. - /// - /// ### Logging Configuration - /// - /// Setting `breez_sdk_core::input_parser=debug` will include in the logs the raw payloads received - /// when interacting with JSON endpoints, for example those used during all LNURL workflows. - /// - /// ### Errors - /// - /// An error is thrown if the log file cannot be created in the working directory. - /// - /// An error is thrown if a global logger is already configured. - pub fn init_logging(log_dir: &str, app_logger: Option>) -> Result<()> { - let target_log_file = Box::new( - OpenOptions::new() - .create(true) - .append(true) - .open(format!("{log_dir}/sdk.log")) - .map_err(|e| anyhow!("Can't create log file: {e}"))?, - ); - let logger = env_logger::Builder::new() - .target(env_logger::Target::Pipe(target_log_file)) - .parse_filters( - r#" - debug, - breez_sdk_core::input_parser=warn, - breez_sdk_core::backup=info, - breez_sdk_core::persist::reverseswap=info, - breez_sdk_core::reverseswap=info, - gl_client=debug, - h2=warn, - hyper=warn, - lightning_signer=warn, - reqwest=warn, - rustls=warn, - rustyline=warn, - vls_protocol_signer=warn - "#, - ) - .format(|buf, record| { - writeln!( - buf, - "[{} {} {}:{}] {}", - Local::now().format("%Y-%m-%d %H:%M:%S%.3f"), - record.level(), - record.module_path().unwrap_or("unknown"), - record.line().unwrap_or(0), - record.args() - ) - }) - .build(); - - let global_logger = GlobalSdkLogger { - logger, - log_listener: app_logger, - }; - - log::set_boxed_logger(Box::new(global_logger)) - .map_err(|e| anyhow!("Failed to set global logger: {e}"))?; - log::set_max_level(LevelFilter::Trace); - - Ok(()) - } - async fn lookup_chain_service_closing_outspend( &self, channel: crate::models::Channel, @@ -1852,32 +1768,6 @@ impl BreezServices { } } -struct GlobalSdkLogger { - /// SDK internal logger, which logs to file - logger: env_logger::Logger, - /// Optional external log listener, that can receive a stream of log statements - log_listener: Option>, -} -impl log::Log for GlobalSdkLogger { - fn enabled(&self, metadata: &Metadata) -> bool { - metadata.level() <= log::Level::Trace - } - - fn log(&self, record: &Record) { - if self.enabled(record.metadata()) { - self.logger.log(record); - - if let Some(s) = &self.log_listener.as_ref() { - if s.enabled(record.metadata()) { - s.log(record); - } - } - } - } - - fn flush(&self) {} -} - /// A helper struct to configure and build BreezServices struct BreezServicesBuilder { config: Config, diff --git a/libs/sdk-core/src/lib.rs b/libs/sdk-core/src/lib.rs index 5300cfde2..448a83cc9 100644 --- a/libs/sdk-core/src/lib.rs +++ b/libs/sdk-core/src/lib.rs @@ -168,6 +168,7 @@ mod breez_services; mod chain; mod crypt; pub mod error; +pub mod logger; #[rustfmt::skip] mod node_api; // flutter_rust_bridge_codegen: has to be defined before greenlight; greenlight::node_api mod greenlight; diff --git a/libs/sdk-core/src/logger.rs b/libs/sdk-core/src/logger.rs new file mode 100644 index 000000000..b8c798e99 --- /dev/null +++ b/libs/sdk-core/src/logger.rs @@ -0,0 +1,293 @@ +use crate::{LogEntry, LogStream}; +use anyhow::{anyhow, Result}; +use chrono::Local; +use env_logger::{Builder, Logger, Target}; +use flutter_rust_bridge::StreamSink; +use lazy_static::lazy_static; +use log::{ + max_level, set_boxed_logger, set_max_level, warn, LevelFilter, Log, Metadata, Record, + STATIC_MAX_LEVEL, +}; +use parking_lot::RwLock; +use std::fs::OpenOptions; +use std::io::Write; + +use std::sync::Once; + +/* Dart */ + +static INIT_DART_LOGGER: Once = Once::new(); + +pub fn init_dart_logger() { + INIT_DART_LOGGER.call_once(|| { + let level = LevelFilter::Info; + + assert!( + level <= STATIC_MAX_LEVEL, + "Should respect STATIC_MAX_LEVEL={:?}, which is done in compile time. level{:?}", + STATIC_MAX_LEVEL, + level + ); + let env_logger = Builder::new() + .target(Target::Stdout) + .filter_level(level) + .format(|buf, record| { + writeln!( + buf, + "[{} {} {}:{}] {}", + Local::now().format("%Y-%m-%d %H:%M:%S%.3f"), + record.level(), + record.module_path().unwrap_or("unknown"), + record.line().unwrap_or(0), + record.args() + ) + }) + .build(); + + let dart_logger = DartLogger { env_logger, level }; + set_boxed_logger(Box::new(dart_logger)) + .unwrap_or_else(|_| error!("Log stream already created.")); + set_max_level(level); + }); +} + +lazy_static! { + static ref DART_LOGGER_STREAM_SINK: RwLock>> = RwLock::new(None); +} + +pub struct DartLogger { + level: LevelFilter, + env_logger: Logger, +} + +impl DartLogger { + pub fn set_stream_sink(stream_sink: StreamSink) { + let mut guard = DART_LOGGER_STREAM_SINK.write(); + if guard.is_some() { + warn!( + "BindingLogger::set_stream_sink but already exist a sink, thus overriding. \ + (This may or may not be a problem. It will happen normally if hot-reload Flutter app.)" + ); + } + *guard = Some(stream_sink); + drop(guard) + } + + fn record_to_entry(record: &Record) -> LogEntry { + LogEntry { + line: format!("{}", record.args()), + level: format!("{}", record.level()), + } + } +} + +impl Log for DartLogger { + fn enabled(&self, _metadata: &Metadata) -> bool { + _metadata.level() <= self.level + } + + fn log(&self, record: &Record) { + if self.enabled(record.metadata()) { + self.env_logger.log(record); + + let entry = Self::record_to_entry(record); + if let Some(sink) = &*DART_LOGGER_STREAM_SINK.read() { + sink.add(entry); + } + } + } + + fn flush(&self) { + // no need + } +} + +/* UniFFI */ + +static INIT_UNIFFI_LOGGER: Once = Once::new(); + +pub fn init_uniffi_logger(log_stream: Box) { + INIT_UNIFFI_LOGGER.call_once(|| { + UniFFILogger::set_log_stream(log_stream); + }); +} + +pub struct UniFFILogger { + log_stream: Box, +} + +impl UniFFILogger { + fn set_log_stream(log_stream: Box) { + let level = LevelFilter::Trace; + + assert!( + level <= STATIC_MAX_LEVEL, + "Should respect STATIC_MAX_LEVEL={:?}, which is done in compile time. level{:?}", + STATIC_MAX_LEVEL, + level + ); + let uniffi_logger = UniFFILogger { log_stream }; + set_boxed_logger(Box::new(uniffi_logger)) + .unwrap_or_else(|_| error!("Log stream already created.")); + set_max_level(level); + } + + fn record_to_entry(record: &Record) -> LogEntry { + LogEntry { + line: format!("{}", record.args()), + level: format!("{}", record.level()), + } + } +} + +impl Log for UniFFILogger { + fn enabled(&self, metadata: &Metadata) -> bool { + // ignore the internal uniffi log to prevent infinite loop. + return metadata.level() <= max_level() + && *metadata.target() != *"breez_sdk_bindings::uniffi_binding"; + } + + fn log(&self, record: &Record) { + let entry = Self::record_to_entry(record); + self.log_stream.log(entry); + } + fn flush(&self) {} +} + +/* Rust */ + +const ENV_LOGGER_FILTER: &str = r#" +debug, +breez_sdk_core::backup=info, +breez_sdk_core::breez_services=info, +breez_sdk_core::input_parser=warn, +breez_sdk_core::persist::reverseswap=info, +breez_sdk_core::reverseswap=info, +gl_client::node=info, +gl_client::node::service=info, +gl_client::tls=info, +gl_client::scheduler=info, +gl_client::signer=info, +gl_client=debug, +h2=warn, +h2::client=info, +h2::codec::framed_read=warn, +h2::codec::framed_write=warn, +h2::proto::connection=info, +h2::proto::settings=info, +hyper=warn, +hyper::client::connect::dns=info, +hyper::client::connect::https=info, +lightning_signer=warn, +lightning_signer::node=warn, +reqwest=warn, +reqwest::connect=warn, +rustls=warn, +rustls::anchors=warn, +rustls::conn=warn, +rustls::client::common=warn, +rustls::client::hs=warn, +rustls::client::tls13=warn, +rustyline=warn, +rusqlite_migration=warn, +tower::buffer::worker=warn, +vls_protocol_signer=warn +"#; + +/// Configures a global SDK logger that will log to file and will forward log events to +/// an optional application-specific logger. +/// +/// If called, it should be called before any SDK methods (for example, before `connect`). +/// +/// It must be called only once in the application lifecycle. Alternatively, If the application +/// already uses a globally-registered logger, this method shouldn't be called at all. +/// +/// ### Arguments +/// +/// - `log_dir`: Location where the the SDK log file will be created. The directory must already exist. +/// +/// - `app_logger`: Optional application logger. +/// +/// If the application is to use it's own logger, but would also like the SDK to log SDK-specific +/// log output to a file in the configured `log_dir`, then do not register the +/// app-specific logger as a global logger and instead call this method with the app logger as an arg. +/// +/// ### Logging Configuration +/// +/// Setting `breez_sdk_core::input_parser=debug` will include in the logs the raw payloads received +/// when interacting with JSON endpoints, for example those used during all LNURL workflows. +/// +/// ### Errors +/// +/// An error is thrown if the log file cannot be created in the working directory. +/// +/// An error is thrown if a global logger is already configured. +pub fn init_sdk_logger(log_dir: &str, app_logger: Option>) -> Result<()> { + let target_log_file = Box::new( + OpenOptions::new() + .create(true) + .append(true) + .open(format!("{log_dir}/sdk.log")) + .map_err(|e| anyhow!("Can't create log file: {e}"))?, + ); + let logger = init_env_logger(Some(target_log_file)); + + let global_logger = GlobalSdkLogger { + logger, + log_listener: app_logger, + }; + + set_boxed_logger(Box::new(global_logger)) + .map_err(|e| anyhow!("Failed to set global logger: {e}"))?; + set_max_level(LevelFilter::Trace); + + Ok(()) +} + +fn init_env_logger(target_log_file: Option>) -> Logger { + let mut binding = Builder::new(); + let builder = binding + .parse_filters(ENV_LOGGER_FILTER) + .format(|buf, record| { + writeln!( + buf, + "[{} {} {}:{}] {}", + Local::now().format("%Y-%m-%d %H:%M:%S%.3f"), + record.level(), + record.module_path().unwrap_or("unknown"), + record.line().unwrap_or(0), + record.args() + ) + }); + if let Some(target_log_file) = target_log_file { + builder.target(Target::Pipe(target_log_file)); + } + builder.build() +} + +pub struct GlobalSdkLogger { + /// SDK internal logger, which logs to file + logger: Logger, + /// Optional external log listener, that can receive a stream of log statements + log_listener: Option>, +} + +impl Log for GlobalSdkLogger { + fn enabled(&self, metadata: &Metadata) -> bool { + metadata.level() <= max_level() + } + + fn log(&self, record: &Record) { + if self.enabled(record.metadata()) { + self.logger.log(record); + + if let Some(s) = &self.log_listener.as_ref() { + if s.enabled(record.metadata()) { + s.log(record); + } + } + } + } + + fn flush(&self) {} +} diff --git a/tools/sdk-cli/Cargo.lock b/tools/sdk-cli/Cargo.lock index 482f14f4c..1f0878876 100644 --- a/tools/sdk-cli/Cargo.lock +++ b/tools/sdk-cli/Cargo.lock @@ -478,6 +478,7 @@ dependencies = [ "miniz_oxide", "once_cell", "openssl", + "parking_lot", "prost", "querystring", "rand", diff --git a/tools/sdk-cli/src/main.rs b/tools/sdk-cli/src/main.rs index 78c50a223..59c2c6129 100644 --- a/tools/sdk-cli/src/main.rs +++ b/tools/sdk-cli/src/main.rs @@ -7,7 +7,7 @@ mod persist; use crate::command_handlers::CliHelper; use anyhow::{anyhow, ensure, Result}; -use breez_sdk_core::BreezServices; +use breez_sdk_core::logger::init_sdk_logger; use clap::Parser; use command_handlers::handle_command; use commands::{Commands, SdkCli}; @@ -27,7 +27,7 @@ async fn main() -> Result<()> { "Error: data directory doesn't exist" ); - BreezServices::init_logging(&data_dir, None)?; + init_sdk_logger(&data_dir, None)?; let persistence = CliPersistence { data_dir }; let history_file = &persistence.history_file();