test: introduce TestConfig and improve logging tests

General improvements:
- Add TestConfig wrapper around Config to allow per-test
log field overrides while preserving the general test setup.

- Test facade logger.

- Add logging module and validate log entries.

- Improve UniFFI logging adding UniFFI flag for relevant
log objects.

- Remove facade level, because the concrete `Log` impl
controls max log level.

Author: enigbe

bindings/ldk_node.udl

@@ -74,7 +74,7 @@ interface Builder {
 	void set_liquidity_source_lsps2(PublicKey node_id, SocketAddress address, string? token);
 	void set_storage_dir_path(string storage_dir_path);
 	void set_filesystem_logger(string? log_file_path, LogLevel? max_log_level);
-	void set_log_facade_logger(LogLevel? max_log_level);
+	void set_log_facade_logger();
 	void set_custom_logger(LogWriter log_writer);
 	void set_network(Network network);
 	[Throws=BuildError]

src/builder.rs

@@ -113,7 +113,7 @@ struct LiquiditySourceConfig {
 #[derive(Clone)]
 enum LogWriterConfig {
 	File { log_file_path: Option<String>, max_log_level: Option<LogLevel> },
-	Log { max_log_level: Option<LogLevel> },
+	Log,
 	Custom(Arc<dyn LogWriter>),
 }
 
@@ -125,9 +125,7 @@ impl std::fmt::Debug for LogWriterConfig {
 				.field("max_log_level", max_log_level)
 				.field("log_file_path", log_file_path)
 				.finish(),
-			LogWriterConfig::Log { max_log_level } => {
-				f.debug_tuple("Log").field(max_log_level).finish()
-			},
+			LogWriterConfig::Log => write!(f, "LogWriterConfig::Log"),
 			LogWriterConfig::Custom(_) => {
 				f.debug_tuple("Custom").field(&"<config internal to custom log writer>").finish()
 			},
@@ -385,11 +383,8 @@ impl NodeBuilder {
 	}
 
 	/// Configures the [`Node`] instance to write logs to the [`log`](https://crates.io/crates/log) facade.
-	///
-	/// If set, the `max_log_level` sets the maximum log level. Otherwise, the latter defaults to
-	/// [`DEFAULT_LOG_LEVEL`].
-	pub fn set_log_facade_logger(&mut self, max_log_level: Option<LogLevel>) -> &mut Self {
-		self.log_writer_config = Some(LogWriterConfig::Log { max_log_level });
+	pub fn set_log_facade_logger(&mut self) -> &mut Self {
+		self.log_writer_config = Some(LogWriterConfig::Log);
 		self
 	}
 
@@ -750,11 +745,8 @@ impl ArcedNodeBuilder {
 	}
 
 	/// Configures the [`Node`] instance to write logs to the [`log`](https://crates.io/crates/log) facade.
-	///
-	/// If set, the `max_log_level` sets the maximum log level. Otherwise, the latter defaults to
-	/// [`DEFAULT_LOG_LEVEL`].
-	pub fn set_log_facade_logger(&self, log_level: Option<LogLevel>) {
-		self.inner.write().unwrap().set_log_facade_logger(log_level);
+	pub fn set_log_facade_logger(&self) {
+		self.inner.write().unwrap().set_log_facade_logger();
 	}
 
 	/// Configures the [`Node`] instance to write logs to the provided custom [`LogWriter`].
@@ -1421,10 +1413,7 @@ fn setup_logger(
 			Logger::new_fs_writer(log_file_path, max_log_level)
 				.map_err(|_| BuildError::LoggerSetupFailed)?
 		},
-		Some(LogWriterConfig::Log { max_log_level }) => {
-			let max_log_level = max_log_level.unwrap_or_else(|| DEFAULT_LOG_LEVEL);
-			Logger::new_log_facade(max_log_level)
-		},
+		Some(LogWriterConfig::Log) => Logger::new_log_facade(),
 
 		Some(LogWriterConfig::Custom(custom_log_writer)) => {
 			Logger::new_custom_writer(Arc::clone(&custom_log_writer))

src/logger.rs

@@ -108,7 +108,7 @@ pub(crate) enum Writer {
 	/// Writes logs to the file system.
 	FileWriter { file_path: String, max_log_level: LogLevel },
 	/// Forwards logs to the `log` facade.
-	LogFacadeWriter { max_log_level: LogLevel },
+	LogFacadeWriter,
 	/// Forwards logs to a custom writer.
 	CustomWriter(Arc<dyn LogWriter>),
 }
@@ -138,10 +138,7 @@ impl LogWriter for Writer {
 					.write_all(log.as_bytes())
 					.expect("Failed to write to log file")
 			},
-			Writer::LogFacadeWriter { max_log_level } => {
-				if record.level < *max_log_level {
-					return;
-				}
+			Writer::LogFacadeWriter => {
 				macro_rules! log_with_level {
 					($log_level:expr, $target: expr, $($args:tt)*) => {
 						match $log_level {
@@ -186,8 +183,8 @@ impl Logger {
 		Ok(Self { writer: Writer::FileWriter { file_path, max_log_level } })
 	}
 
-	pub fn new_log_facade(max_log_level: LogLevel) -> Self {
-		Self { writer: Writer::LogFacadeWriter { max_log_level } }
+	pub fn new_log_facade() -> Self {
+		Self { writer: Writer::LogFacadeWriter }
 	}
 
 	pub fn new_custom_writer(log_writer: Arc<dyn LogWriter>) -> Self {
@@ -204,10 +201,7 @@ impl LdkLogger for Logger {
 				}
 				self.writer.log(record.into());
 			},
-			Writer::LogFacadeWriter { max_log_level } => {
-				if record.level < *max_log_level {
-					return;
-				}
+			Writer::LogFacadeWriter => {
 				self.writer.log(record.into());
 			},
 			Writer::CustomWriter(_arc) => {

tests/common/logging.rs

@@ -0,0 +1,146 @@
+use chrono::Utc;
+#[cfg(not(feature = "uniffi"))]
+use ldk_node::logger::LogRecord;
+use ldk_node::logger::{LogLevel, LogWriter};
+#[cfg(not(feature = "uniffi"))]
+use log::Record as LogFacadeRecord;
+use log::{Level as LogFacadeLevel, LevelFilter as LogFacadeLevelFilter, Log as LogFacadeLog};
+use std::sync::{Arc, Mutex};
+
+#[derive(Clone)]
+pub(crate) enum TestLogWriter {
+	FileWriter,
+	LogFacade,
+	Custom(Arc<dyn LogWriter>),
+}
+
+impl Default for TestLogWriter {
+	fn default() -> Self {
+		TestLogWriter::FileWriter
+	}
+}
+
+pub(crate) struct MockLogFacadeLogger {
+	logs: Arc<Mutex<Vec<String>>>,
+}
+
+impl MockLogFacadeLogger {
+	pub fn new() -> Self {
+		Self { logs: Arc::new(Mutex::new(Vec::new())) }
+	}
+
+	pub fn retrieve_logs(&self) -> Vec<String> {
+		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) {}
+}
+
+#[cfg(not(feature = "uniffi"))]
+impl LogWriter for MockLogFacadeLogger {
+	fn log<'a>(&self, record: LogRecord) {
+		let record = MockLogRecord(record).into();
+		LogFacadeLog::log(self, &record);
+	}
+}
+
+#[cfg(not(feature = "uniffi"))]
+struct MockLogRecord<'a>(LogRecord<'a>);
+struct MockLogLevel(LogLevel);
+
+impl From<MockLogLevel> 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,
+		}
+	}
+}
+
+#[cfg(not(feature = "uniffi"))]
+impl<'a> From<MockLogRecord<'a>> 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<MockLogFacadeLogger> {
+	let logger = Arc::new(MockLogFacadeLogger::new());
+	log::set_boxed_logger(Box::new(logger.clone())).unwrap();
+	log::set_max_level(level);
+
+	logger
+}
+
+pub(crate) fn validate_log_entry(entry: &String) {
+	let parts = entry.splitn(4, ' ').collect::<Vec<_>>();
+	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::<Vec<_>>();
+	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::<Vec<_>>();
+	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::<Vec<_>>();
+	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());
+}

tests/common/mod.rs

@@ -8,9 +8,12 @@
 #![cfg(any(test, cln_test, vss_test))]
 #![allow(dead_code)]
 
+pub(crate) mod logging;
+
+use logging::TestLogWriter;
+
 use ldk_node::config::{Config, EsploraSyncConfig};
 use ldk_node::io::sqlite_store::SqliteStore;
-use ldk_node::logger::LogLevel;
 use ldk_node::payment::{PaymentDirection, PaymentKind, PaymentStatus};
 use ldk_node::{
 	Builder, CustomTlvRecord, Event, LightningBalance, Node, NodeError, PendingSweepBalance,
@@ -221,29 +224,29 @@ pub(crate) fn random_node_alias() -> Option<NodeAlias> {
 	Some(NodeAlias(bytes))
 }
 
-pub(crate) fn random_config(anchor_channels: bool) -> Config {
-	let mut config = Config::default();
+pub(crate) fn random_config(anchor_channels: bool) -> TestConfig {
+	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;
 
-	config
+	TestConfig { node_config, ..Default::default() }
 }
 
 #[cfg(feature = "uniffi")]
@@ -257,6 +260,12 @@ pub(crate) enum TestChainSource<'a> {
 	BitcoindRpc(&'a BitcoinD),
 }
 
+#[derive(Clone, Default)]
+pub(crate) struct TestConfig {
+	pub node_config: Config,
+	pub log_writer: TestLogWriter,
+}
+
 macro_rules! setup_builder {
 	($builder: ident, $config: expr) => {
 		#[cfg(feature = "uniffi")]
@@ -279,10 +288,11 @@ pub(crate) fn setup_two_nodes(
 	println!("\n== Node B ==");
 	let mut config_b = random_config(anchor_channels);
 	if allow_0conf {
-		config_b.trusted_peers_0conf.push(node_a.node_id());
+		config_b.node_config.trusted_peers_0conf.push(node_a.node_id());
 	}
 	if anchor_channels && anchors_trusted_no_reserve {
 		config_b
+			.node_config
 			.anchor_channels_config
 			.as_mut()
 			.unwrap()
@@ -294,9 +304,9 @@ pub(crate) fn setup_two_nodes(
 }
 
 pub(crate) fn setup_node(
-	chain_source: &TestChainSource, config: Config, seed_bytes: Option<Vec<u8>>,
+	chain_source: &TestChainSource, config: TestConfig, seed_bytes: Option<Vec<u8>>,
 ) -> TestNode {
-	setup_builder!(builder, config);
+	setup_builder!(builder, config.node_config);
 	match chain_source {
 		TestChainSource::Esplora(electrsd) => {
 			let esplora_url = format!("http://{}", electrsd.esplora_url.as_ref().unwrap());
@@ -315,14 +325,23 @@ pub(crate) fn setup_node(
 		},
 	}
 
-	let log_file_path = format!("{}/{}", config.storage_dir_path, "ldk_node.log");
-	builder.set_filesystem_logger(Some(log_file_path), Some(LogLevel::Gossip));
+	match &config.log_writer {
+		TestLogWriter::FileWriter => {
+			builder.set_filesystem_logger(None, None);
+		},
+		TestLogWriter::LogFacade => {
+			builder.set_log_facade_logger();
+		},
+		TestLogWriter::Custom(custom_log_writer) => {
+			builder.set_custom_logger(Arc::clone(custom_log_writer));
+		},
+	}
 
 	if let Some(seed) = seed_bytes {
 		builder.set_entropy_seed_bytes(seed).unwrap();
 	}
 
-	let test_sync_store = Arc::new(TestSyncStore::new(config.storage_dir_path.into()));
+	let test_sync_store = Arc::new(TestSyncStore::new(config.node_config.storage_dir_path.into()));
 	let node = builder.build_with_store(test_sync_store).unwrap();
 	node.start().unwrap();
 	assert!(node.status().is_running);

tests/integration_tests_cln.rs

@@ -45,7 +45,7 @@ fn test_cln() {
 
 	// Setup LDK Node
 	let config = common::random_config(true);
-	let mut builder = Builder::from_config(config);
+	let mut builder = Builder::from_config(config.node_config);
 	builder.set_chain_source_esplora("http://127.0.0.1:3002".to_string(), None);
 
 	let node = builder.build().unwrap();