From bff5778f91754b17660f48e64490155c3a82f8c7 Mon Sep 17 00:00:00 2001 From: Enigbe Date: Wed, 19 Feb 2025 08:29:30 +0100 Subject: [PATCH] fix: add logging module and validate log entries Additionally addresses minor issues related to: - Default impl - Verbose TestLogWriter enum - MockLogFacadeLogger and node_config rename --- tests/common/logging.rs | 148 ++++++++++++++++++++++++++++++++ tests/common/mod.rs | 143 ++++-------------------------- tests/integration_tests_rust.rs | 22 +++-- 3 files changed, 179 insertions(+), 134 deletions(-) create mode 100644 tests/common/logging.rs diff --git a/tests/common/logging.rs b/tests/common/logging.rs new file mode 100644 index 000000000..6aec315f1 --- /dev/null +++ b/tests/common/logging.rs @@ -0,0 +1,148 @@ +use chrono::Utc; +use ldk_node::logger::{LogLevel, LogRecord, LogWriter}; +use log::{ + Level as LogFacadeLevel, LevelFilter as LogFacadeLevelFilter, Log as LogFacadeLog, + Record as LogFacadeRecord, +}; +use std::sync::{Arc, Mutex}; + +#[derive(Clone)] +pub(crate) enum TestLogWriter { + FileWriter, + LogFacade(LogLevel), + Custom(Arc), +} + +impl Default for TestLogWriter { + fn default() -> Self { + TestLogWriter::FileWriter + } +} + +pub(crate) struct MockLogFacadeLogger { + logs: Arc>>, +} + +impl MockLogFacadeLogger { + pub fn new() -> Self { + Self { logs: Arc::new(Mutex::new(Vec::new())) } + } + + pub fn retrieve_logs(&self) -> Vec { + self.logs.lock().unwrap().to_vec() + } +} + +impl LogFacadeLog for MockLogFacadeLogger { + fn enabled(&self, _metadata: &log::Metadata) -> bool { + true + } + + fn log(&self, record: &log::Record) { + let message = format!( + "{} {:<5} [{}:{}] {}", + Utc::now().format("%Y-%m-%d %H:%M:%S"), + record.level().to_string(), + record.module_path().unwrap(), + record.line().unwrap(), + record.args() + ); + println!("{message}"); + self.logs.lock().unwrap().push(message); + } + + fn flush(&self) {} +} + +impl LogWriter for MockLogFacadeLogger { + fn log<'a>(&self, record: LogRecord) { + let record = MockLogRecord(record).into(); + LogFacadeLog::log(self, &record); + } +} + +struct MockLogRecord<'a>(LogRecord<'a>); +struct MockLogLevel(LogLevel); + +impl From for LogFacadeLevel { + fn from(level: MockLogLevel) -> Self { + match level.0 { + LogLevel::Gossip | LogLevel::Trace => LogFacadeLevel::Trace, + LogLevel::Debug => LogFacadeLevel::Debug, + LogLevel::Info => LogFacadeLevel::Info, + LogLevel::Warn => LogFacadeLevel::Warn, + LogLevel::Error => LogFacadeLevel::Error, + } + } +} + +impl<'a> From> for LogFacadeRecord<'a> { + fn from(log_record: MockLogRecord<'a>) -> Self { + let log_record = log_record.0; + let level = MockLogLevel(log_record.level).into(); + + let mut record_builder = LogFacadeRecord::builder(); + let record = record_builder + .level(level) + .module_path(Some(log_record.module_path)) + .line(Some(log_record.line)) + .args(log_record.args); + + record.build() + } +} + +pub(crate) fn init_log_logger(level: LogFacadeLevelFilter) -> Arc { + let logger = Arc::new(MockLogFacadeLogger::new()); + log::set_boxed_logger(Box::new(logger.clone())).unwrap(); + log::set_max_level(level); + + logger +} + +pub(crate) fn init_custom_logger() -> Arc { + let logger = Arc::new(MockLogFacadeLogger::new()); + + logger +} + +pub(crate) fn validate_log_entry(entry: &String) { + let parts = entry.splitn(4, ' ').collect::>(); + assert_eq!(parts.len(), 4); + let (day, time, level, path_and_msg) = (parts[0], parts[1], parts[2], parts[3]); + + let day_parts = day.split('-').collect::>(); + assert_eq!(day_parts.len(), 3); + let (year, month, day) = (day_parts[0], day_parts[1], day_parts[2]); + assert!(year.len() == 4 && month.len() == 2 && day.len() == 2); + assert!( + year.chars().all(|c| c.is_digit(10)) + && month.chars().all(|c| c.is_digit(10)) + && day.chars().all(|c| c.is_digit(10)) + ); + + let time_parts = time.split(':').collect::>(); + assert_eq!(time_parts.len(), 3); + let (hour, minute, second) = (time_parts[0], time_parts[1], time_parts[2]); + assert!(hour.len() == 2 && minute.len() == 2 && second.len() == 2); + assert!( + hour.chars().all(|c| c.is_digit(10)) + && minute.chars().all(|c| c.is_digit(10)) + && second.chars().all(|c| c.is_digit(10)) + ); + + assert!(["GOSSIP", "TRACE", "DEBUG", "INFO", "WARN", "ERROR"].contains(&level),); + + let path = path_and_msg.split_whitespace().next().unwrap(); + assert!(path.contains('[') && path.contains(']')); + let module_path = &path[1..path.len() - 1]; + let path_parts = module_path.rsplitn(2, ':').collect::>(); + assert_eq!(path_parts.len(), 2); + let (line_number, module_name) = (path_parts[0], path_parts[1]); + assert!(module_name.chars().all(|c| c.is_alphanumeric() || c == '_' || c == ':')); + assert!(line_number.chars().all(|c| c.is_digit(10))); + + let msg_start_index = path_and_msg.find(']').unwrap() + 1; + let msg = &path_and_msg[msg_start_index..]; + assert!(!msg.is_empty()); +} diff --git a/tests/common/mod.rs b/tests/common/mod.rs index 20a1d3479..e7d31aeab 100644 --- a/tests/common/mod.rs +++ b/tests/common/mod.rs @@ -7,13 +7,14 @@ #![cfg(any(test, cln_test, vss_test))] #![allow(dead_code)] +pub(crate) mod logging; + +use logging::TestLogWriter; -use chrono::Utc; use ldk_node::config::{ Config, EsploraSyncConfig, DEFAULT_LOG_FILENAME, DEFAULT_LOG_LEVEL, DEFAULT_STORAGE_DIR_PATH, }; use ldk_node::io::sqlite_store::SqliteStore; -use ldk_node::logger::{LogLevel, LogRecord, LogWriter}; use ldk_node::payment::{PaymentDirection, PaymentKind, PaymentStatus}; use ldk_node::{ Builder, CustomTlvRecord, Event, LightningBalance, Node, NodeError, PendingSweepBalance, @@ -40,13 +41,12 @@ use bitcoincore_rpc::RpcApi; use electrsd::{bitcoind, bitcoind::BitcoinD, ElectrsD}; use electrum_client::ElectrumApi; -use log::{Level, LevelFilter, Log, Record}; use rand::distributions::Alphanumeric; use rand::{thread_rng, Rng}; use std::env; use std::path::PathBuf; -use std::sync::{Arc, Mutex, RwLock}; +use std::sync::{Arc, RwLock}; use std::time::Duration; macro_rules! expect_event { @@ -220,28 +220,28 @@ pub(crate) fn random_node_alias() -> Option { } pub(crate) fn random_config(anchor_channels: bool) -> TestConfig { - let mut config = Config::default(); + let mut node_config = Config::default(); if !anchor_channels { - config.anchor_channels_config = None; + node_config.anchor_channels_config = None; } - config.network = Network::Regtest; - println!("Setting network: {}", config.network); + node_config.network = Network::Regtest; + println!("Setting network: {}", node_config.network); let rand_dir = random_storage_path(); println!("Setting random LDK storage dir: {}", rand_dir.display()); - config.storage_dir_path = rand_dir.to_str().unwrap().to_owned(); + node_config.storage_dir_path = rand_dir.to_str().unwrap().to_owned(); let rand_listening_addresses = random_listening_addresses(); println!("Setting random LDK listening addresses: {:?}", rand_listening_addresses); - config.listening_addresses = Some(rand_listening_addresses); + node_config.listening_addresses = Some(rand_listening_addresses); let alias = random_node_alias(); println!("Setting random LDK node alias: {:?}", alias); - config.node_alias = alias; + node_config.node_alias = alias; - TestConfig { node_config: config, log_writer: TestLogWriter::default() } + TestConfig { node_config, ..Default::default() } } #[cfg(feature = "uniffi")] @@ -255,34 +255,12 @@ pub(crate) enum TestChainSource<'a> { BitcoindRpc(&'a BitcoinD), } -#[derive(Clone)] -pub(crate) enum TestLogWriter { - FileWriter { file_path: String, max_log_level: LogLevel }, - LogFacade { max_log_level: LogLevel }, - Custom(Arc), -} - -impl Default for TestLogWriter { - fn default() -> Self { - TestLogWriter::FileWriter { - file_path: format!("{}/{}", DEFAULT_STORAGE_DIR_PATH, DEFAULT_LOG_FILENAME), - max_log_level: DEFAULT_LOG_LEVEL, - } - } -} - -#[derive(Clone)] +#[derive(Clone, Default)] pub(crate) struct TestConfig { pub node_config: Config, pub log_writer: TestLogWriter, } -impl Default for TestConfig { - fn default() -> Self { - Self { node_config: Config::default(), log_writer: TestLogWriter::default() } - } -} - macro_rules! setup_builder { ($builder: ident, $config: expr) => { #[cfg(feature = "uniffi")] @@ -343,10 +321,12 @@ pub(crate) fn setup_node( } match &config.log_writer { - TestLogWriter::FileWriter { file_path, max_log_level } => { - builder.set_filesystem_logger(Some(file_path.clone()), Some(*max_log_level)); + TestLogWriter::FileWriter => { + let file_path = format!("{}/{}", DEFAULT_STORAGE_DIR_PATH, DEFAULT_LOG_FILENAME); + let max_log_level = DEFAULT_LOG_LEVEL; + builder.set_filesystem_logger(Some(file_path), Some(max_log_level)); }, - TestLogWriter::LogFacade { max_log_level } => { + TestLogWriter::LogFacade(max_log_level) => { builder.set_log_facade_logger(Some(*max_log_level)); }, TestLogWriter::Custom(custom_log_writer) => { @@ -1209,90 +1189,3 @@ impl KVStore for TestSyncStore { self.do_list(primary_namespace, secondary_namespace) } } - -pub(crate) struct MockLogger { - logs: Arc>>, -} - -impl MockLogger { - pub fn new() -> Self { - Self { logs: Arc::new(Mutex::new(Vec::new())) } - } - - pub fn retrieve_logs(&self) -> Vec { - self.logs.lock().unwrap().to_vec() - } -} - -impl Log for MockLogger { - fn enabled(&self, _metadata: &log::Metadata) -> bool { - true - } - - fn log(&self, record: &log::Record) { - let message = format!( - "{} {:<5} [{}:{}] {}", - Utc::now().format("%Y-%m-%d %H:%M:%S"), - record.level().to_string(), - record.module_path().unwrap(), - record.line().unwrap(), - record.args() - ); - println!("{message}"); - self.logs.lock().unwrap().push(message); - } - - fn flush(&self) {} -} - -impl LogWriter for MockLogger { - fn log<'a>(&self, record: LogRecord) { - let record = MockLogRecord(record).into(); - Log::log(self, &record); - } -} - -struct MockLogRecord<'a>(LogRecord<'a>); -struct MockLogLevel(LogLevel); - -impl From for Level { - fn from(level: MockLogLevel) -> Self { - match level.0 { - LogLevel::Gossip | LogLevel::Trace => Level::Trace, - LogLevel::Debug => Level::Debug, - LogLevel::Info => Level::Info, - LogLevel::Warn => Level::Warn, - LogLevel::Error => Level::Error, - } - } -} - -impl<'a> From> for Record<'a> { - fn from(log_record: MockLogRecord<'a>) -> Self { - let log_record = log_record.0; - let level = MockLogLevel(log_record.level).into(); - - let mut record_builder = Record::builder(); - let record = record_builder - .level(level) - .module_path(Some(log_record.module_path)) - .line(Some(log_record.line)) - .args(log_record.args); - - record.build() - } -} - -pub(crate) fn init_log_logger(level: LevelFilter) -> Arc { - let logger = Arc::new(MockLogger::new()); - log::set_boxed_logger(Box::new(logger.clone())).unwrap(); - log::set_max_level(level); - - logger -} - -pub(crate) fn init_custom_logger() -> Arc { - let logger = Arc::new(MockLogger::new()); - - logger -} diff --git a/tests/integration_tests_rust.rs b/tests/integration_tests_rust.rs index eefc4b48c..fa23bba62 100644 --- a/tests/integration_tests_rust.rs +++ b/tests/integration_tests_rust.rs @@ -7,12 +7,12 @@ mod common; +use common::logging::{init_custom_logger, init_log_logger, validate_log_entry, TestLogWriter}; use common::{ do_channel_full_cycle, expect_channel_ready_event, expect_event, expect_payment_received_event, - expect_payment_successful_event, generate_blocks_and_wait, init_custom_logger, init_log_logger, - open_channel, premine_and_distribute_funds, random_config, setup_bitcoind_and_electrsd, - setup_builder, setup_node, setup_two_nodes, wait_for_tx, TestChainSource, TestLogWriter, - TestSyncStore, + expect_payment_successful_event, generate_blocks_and_wait, open_channel, + premine_and_distribute_funds, random_config, setup_bitcoind_and_electrsd, setup_builder, + setup_node, setup_two_nodes, wait_for_tx, TestChainSource, TestSyncStore, }; use ldk_node::config::EsploraSyncConfig; @@ -1001,13 +1001,15 @@ fn facade_logging() { let logger = init_log_logger(LevelFilter::Trace); let mut config = random_config(false); - config.log_writer = TestLogWriter::LogFacade { max_log_level: LogLevel::Gossip }; + config.log_writer = TestLogWriter::LogFacade(LogLevel::Gossip); - println!("== Facade logging start =="); + println!("== Facade logging starts =="); let _node = setup_node(&chain_source, config, None); - println!("== Facade logging end =="); assert!(!logger.retrieve_logs().is_empty()); + for (_, entry) in logger.retrieve_logs().iter().enumerate() { + validate_log_entry(entry); + } } #[test] @@ -1018,9 +1020,11 @@ fn custom_logging() { let mut config = random_config(false); config.log_writer = TestLogWriter::Custom(logger.clone()); - println!("== Custom logging start =="); + println!("== Custom logging starts =="); let _node = setup_node(&chain_source, config, None); - println!("== Custom logging end =="); assert!(!logger.retrieve_logs().is_empty()); + for (_, entry) in logger.retrieve_logs().iter().enumerate() { + validate_log_entry(entry); + } }