Logging interface

Implement error, warn, info, debug and trace macros, internally calling
an instance of Logger, and passing it to every main structures
Build-time or client-side filtering.
Issue #54

Author: Antoine Riard

Cargo.toml

@@ -15,6 +15,12 @@ build = "build.rs"
 # Supports tracking channels with a non-bitcoin chain hashes. Currently enables all kinds of fun DoS attacks.
 non_bitcoin_chain_hash_routing = []
 fuzztarget = ["secp256k1/fuzztarget", "bitcoin/fuzztarget"]
+# Unlog messages superior at targeted level.
+max_level_off = []
+max_level_error = []
+max_level_warn = []
+max_level_info = []
+max_level_debug = []
 
 [dependencies]
 bitcoin = "0.13"

fuzz/fuzz_targets/channel_target.rs

@@ -14,11 +14,17 @@ use lightning::ln::msgs::{MsgDecodable, ErrorAction};
 use lightning::chain::chaininterface::{FeeEstimator, ConfirmationTarget};
 use lightning::chain::transaction::OutPoint;
 use lightning::util::reset_rng_state;
+use lightning::util::logger::Logger;
+
+mod utils;
+
+use utils::test_logger;
 
 use secp256k1::key::{PublicKey, SecretKey};
 use secp256k1::Secp256k1;
 
 use std::sync::atomic::{AtomicUsize,Ordering};
+use std::sync::Arc;
 
 #[inline]
 pub fn slice_to_be16(v: &[u8]) -> u16 {
@@ -101,6 +107,8 @@ pub fn do_test(data: &[u8]) {
 		input: &input,
 	};
 
+	let logger: Arc<Logger> = Arc::new(test_logger::TestLogger::new());
+
 	macro_rules! get_slice {
 		($len: expr) => {
 			match input.get_slice($len as usize) {
@@ -191,7 +199,7 @@ pub fn do_test(data: &[u8]) {
 	let mut channel = if get_slice!(1)[0] != 0 {
 		let chan_value = slice_to_be24(get_slice!(3));
 
-		let mut chan = Channel::new_outbound(&fee_est, chan_keys!(), their_pubkey, chan_value, get_slice!(1)[0] == 0, slice_to_be64(get_slice!(8)));
+		let mut chan = Channel::new_outbound(&fee_est, chan_keys!(), their_pubkey, chan_value, get_slice!(1)[0] == 0, slice_to_be64(get_slice!(8)), Arc::clone(&logger));
 		chan.get_open_channel(Sha256dHash::from(get_slice!(32)), &fee_est).unwrap();
 		let accept_chan = if get_slice!(1)[0] == 0 {
 			decode_msg_with_len16!(msgs::AcceptChannel, 270, 1)
@@ -213,7 +221,7 @@ pub fn do_test(data: &[u8]) {
 		} else {
 			decode_msg!(msgs::OpenChannel, 2*32+6*8+4+2*2+6*33+1)
 		};
-		let mut chan = match Channel::new_from_req(&fee_est, chan_keys!(), their_pubkey, &open_chan, slice_to_be64(get_slice!(8)), false, get_slice!(1)[0] == 0) {
+		let mut chan = match Channel::new_from_req(&fee_est, chan_keys!(), their_pubkey, &open_chan, slice_to_be64(get_slice!(8)), false, get_slice!(1)[0] == 0, Arc::clone(&logger)) {
 			Ok(chan) => chan,
 			Err(_) => return,
 		};

fuzz/fuzz_targets/full_stack_target.rs

@@ -21,6 +21,11 @@ use lightning::ln::peer_handler::{MessageHandler,PeerManager,SocketDescriptor};
 use lightning::ln::router::Router;
 use lightning::util::events::{EventsProvider,Event};
 use lightning::util::reset_rng_state;
+use lightning::util::logger::Logger;
+
+mod utils;
+
+use utils::test_logger;
 
 use secp256k1::key::{PublicKey,SecretKey};
 use secp256k1::Secp256k1;
@@ -169,18 +174,19 @@ pub fn do_test(data: &[u8]) {
 		Err(_) => return,
 	};
 
+	let logger: Arc<Logger> = Arc::new(test_logger::TestLogger::new());
 	let monitor = Arc::new(TestChannelMonitor{});
-	let watch = Arc::new(ChainWatchInterfaceUtil::new());
+	let watch = Arc::new(ChainWatchInterfaceUtil::new(Arc::clone(&logger)));
 	let broadcast = Arc::new(TestBroadcaster{});
 
-	let channelmanager = ChannelManager::new(our_network_key, slice_to_be32(get_slice!(4)), get_slice!(1)[0] != 0, Network::Bitcoin, fee_est.clone(), monitor.clone(), watch.clone(), broadcast.clone()).unwrap();
-	let router = Arc::new(Router::new(PublicKey::from_secret_key(&secp_ctx, &our_network_key).unwrap()));
+	let channelmanager = ChannelManager::new(our_network_key, slice_to_be32(get_slice!(4)), get_slice!(1)[0] != 0, Network::Bitcoin, fee_est.clone(), monitor.clone(), watch.clone(), broadcast.clone(), Arc::clone(&logger)).unwrap();
+	let router = Arc::new(Router::new(PublicKey::from_secret_key(&secp_ctx, &our_network_key).unwrap(), Arc::clone(&logger)));
 
 	let peers = RefCell::new([false; 256]);
 	let handler = PeerManager::new(MessageHandler {
 		chan_handler: channelmanager.clone(),
 		route_handler: router.clone(),
-	}, our_network_key);
+	}, our_network_key, Arc::clone(&logger));
 
 	let mut should_forward = false;
 	let mut payments_received = Vec::new();

fuzz/fuzz_targets/router_target.rs

@@ -7,10 +7,17 @@ use lightning::ln::msgs;
 use lightning::ln::msgs::{MsgDecodable, RoutingMessageHandler};
 use lightning::ln::router::{Router, RouteHint};
 use lightning::util::reset_rng_state;
+use lightning::util::logger::Logger;
 
 use secp256k1::key::PublicKey;
 use secp256k1::Secp256k1;
 
+mod utils;
+
+use utils::test_logger;
+
+use std::sync::Arc;
+
 #[inline]
 pub fn slice_to_be16(v: &[u8]) -> u16 {
 	((v[0] as u16) << 8*1) |
@@ -98,8 +105,10 @@ pub fn do_test(data: &[u8]) {
 		}
 	}
 
+	let logger: Arc<Logger> = Arc::new(test_logger::TestLogger::new());
+
 	let our_pubkey = get_pubkey!();
-	let router = Router::new(our_pubkey.clone());
+	let router = Router::new(our_pubkey.clone(), Arc::clone(&logger));
 
 	loop {
 		match get_slice!(1)[0] {

fuzz/fuzz_targets/utils/mod.rs

@@ -0,0 +1 @@
+pub(crate) mod test_logger;

fuzz/fuzz_targets/utils/test_logger.rs

@@ -0,0 +1,23 @@
+use lightning::util::logger::{Logger, Level, Record};
+
+pub struct TestLogger {
+	level: Level,
+}
+
+impl TestLogger {
+	pub fn new() -> TestLogger {
+		TestLogger {
+			level: Level::Off,
+		}
+	}
+	pub fn enable(&mut self, level: Level) {
+		self.level = level;
+	}
+}
+
+impl Logger for TestLogger {
+	fn log(&self, record: &Record) {
+		#[cfg(any(test, not(feature = "fuzztarget")))]
+		println!("{:<5} [{} : {}, {}] {}", record.level.to_string(), record.module_path, record.file, record.line, record.args);
+	}
+}

src/chain/chaininterface.rs

@@ -2,7 +2,8 @@ use bitcoin::blockdata::block::{Block, BlockHeader};
 use bitcoin::blockdata::transaction::Transaction;
 use bitcoin::blockdata::script::Script;
 use bitcoin::util::hash::Sha256dHash;
-use std::sync::{Mutex,Weak,MutexGuard};
+use util::logger::Logger;
+use std::sync::{Mutex,Weak,MutexGuard,Arc};
 use std::sync::atomic::{AtomicUsize, Ordering};
 
 /// An interface to request notification of certain scripts as they appear the
@@ -70,7 +71,8 @@ pub trait FeeEstimator: Sync + Send {
 pub struct ChainWatchInterfaceUtil {
 	watched: Mutex<(Vec<Script>, Vec<(Sha256dHash, u32)>, bool)>, //TODO: Something clever to optimize this
 	listeners: Mutex<Vec<Weak<ChainListener>>>,
-	reentered: AtomicUsize
+	reentered: AtomicUsize,
+	logger: Arc<Logger>,
 }
 
 /// Register listener
@@ -100,11 +102,12 @@ impl ChainWatchInterface for ChainWatchInterfaceUtil {
 }
 
 impl ChainWatchInterfaceUtil {
-	pub fn new() -> ChainWatchInterfaceUtil {
+	pub fn new(logger: Arc<Logger>) -> ChainWatchInterfaceUtil {
 		ChainWatchInterfaceUtil {
 			watched: Mutex::new((Vec::new(), Vec::new(), false)),
 			listeners: Mutex::new(Vec::new()),
-			reentered: AtomicUsize::new(1)
+			reentered: AtomicUsize::new(1),
+			logger: logger,
 		}
 	}
 

src/lib.rs

@@ -6,6 +6,7 @@ extern crate rand;
 extern crate secp256k1;
 #[cfg(test)] extern crate hex;
 
+#[macro_use]
+pub mod util;
 pub mod chain;
 pub mod ln;
-pub mod util;

src/ln/channel.rs

@@ -23,11 +23,13 @@ use chain::chaininterface::{FeeEstimator,ConfirmationTarget};
 use chain::transaction::OutPoint;
 use util::{transaction_utils,rng};
 use util::sha2::Sha256;
+use util::logger::{Logger, Record};
 
 use std;
 use std::default::Default;
 use std::{cmp,mem};
 use std::time::Instant;
+use std::sync::{Arc};
 
 pub struct ChannelKeys {
 	pub funding_key: SecretKey,
@@ -303,6 +305,8 @@ pub struct Channel {
 	their_shutdown_scriptpubkey: Option<Script>,
 
 	channel_monitor: ChannelMonitor,
+
+	logger: Arc<Logger>,
 }
 
 const OUR_MAX_HTLCS: u16 = 5; //TODO
@@ -361,7 +365,7 @@ impl Channel {
 	// Constructors:
 
 	/// panics if channel_value_satoshis is >= `MAX_FUNDING_SATOSHIS`
-	pub fn new_outbound(fee_estimator: &FeeEstimator, chan_keys: ChannelKeys, their_node_id: PublicKey, channel_value_satoshis: u64, announce_publicly: bool, user_id: u64) -> Channel {
+	pub fn new_outbound(fee_estimator: &FeeEstimator, chan_keys: ChannelKeys, their_node_id: PublicKey, channel_value_satoshis: u64, announce_publicly: bool, user_id: u64, logger: Arc<Logger>) -> Channel {
 		if channel_value_satoshis >= MAX_FUNDING_SATOSHIS {
 			panic!("funding value > 2^24");
 		}
@@ -429,6 +433,8 @@ impl Channel {
 			their_shutdown_scriptpubkey: None,
 
 			channel_monitor: channel_monitor,
+
+			logger,
 		}
 	}
 
@@ -446,7 +452,7 @@ impl Channel {
 	/// Assumes chain_hash has already been checked and corresponds with what we expect!
 	/// Generally prefers to take the DisconnectPeer action on failure, as a notice to the sender
 	/// that we're rejecting the new channel.
-	pub fn new_from_req(fee_estimator: &FeeEstimator, chan_keys: ChannelKeys, their_node_id: PublicKey, msg: &msgs::OpenChannel, user_id: u64, require_announce: bool, allow_announce: bool) -> Result<Channel, HandleError> {
+	pub fn new_from_req(fee_estimator: &FeeEstimator, chan_keys: ChannelKeys, their_node_id: PublicKey, msg: &msgs::OpenChannel, user_id: u64, require_announce: bool, allow_announce: bool, logger: Arc<Logger>) -> Result<Channel, HandleError> {
 		// Check sanity of message fields:
 		if msg.funding_satoshis >= MAX_FUNDING_SATOSHIS {
 			return Err(HandleError{err: "funding value > 2^24", action: Some(msgs::ErrorAction::DisconnectPeer{ msg: None })});
@@ -548,6 +554,8 @@ impl Channel {
 			their_shutdown_scriptpubkey: None,
 
 			channel_monitor: channel_monitor,
+
+			logger,
 		};
 
 		let obscure_factor = chan.get_commitment_transaction_number_obscure_factor();
@@ -1748,7 +1756,7 @@ impl Channel {
 
 		match self.secp_ctx.verify(&sighash, &msg.signature, &self.their_funding_pubkey) {
 			Ok(_) => {},
-			Err(_) => {
+			Err(_e) => {
 				// The remote end may have decided to revoke their output due to inconsistent dust
 				// limits, so check for that case by re-checking the signature here.
 				closing_tx = self.build_closing_transaction(msg.fee_satoshis, true).0;
@@ -2111,6 +2119,7 @@ impl Channel {
 		let (our_signature, commitment_tx) = match self.get_outbound_funding_created_signature() {
 			Ok(res) => res,
 			Err(e) => {
+				log_error!(self, "Got bad signatures: {}!", e.err);
 				self.channel_monitor.unset_funding_info();
 				return Err(e);
 			}
@@ -2409,10 +2418,13 @@ mod tests {
 	use ln::chan_utils;
 	use chain::chaininterface::{FeeEstimator,ConfirmationTarget};
 	use chain::transaction::OutPoint;
+	use util::test_utils;
+	use util::logger::Logger;
 	use secp256k1::{Secp256k1,Message,Signature};
 	use secp256k1::key::{SecretKey,PublicKey};
 	use crypto::sha2::Sha256;
 	use crypto::digest::Digest;
+	use std::sync::Arc;
 
 	struct TestFeeEstimator {
 		fee_est: u64
@@ -2433,6 +2445,7 @@ mod tests {
 	fn outbound_commitment_test() {
 		// Test vectors from BOLT 3 Appendix C:
 		let feeest = TestFeeEstimator{fee_est: 15000};
+		let logger : Arc<Logger> = Arc::new(test_utils::TestLogger::new());
 		let secp_ctx = Secp256k1::new();
 
 		let chan_keys = ChannelKeys {
@@ -2450,7 +2463,7 @@ mod tests {
 		assert_eq!(PublicKey::from_secret_key(&secp_ctx, &chan_keys.funding_key).unwrap().serialize()[..],
 				hex::decode("023da092f6980e58d2c037173180e9a465476026ee50f96695963e8efe436f54eb").unwrap()[..]);
 
-		let mut chan = Channel::new_outbound(&feeest, chan_keys, PublicKey::new(), 10000000, false, 42); // Nothing uses their network key in this test
+		let mut chan = Channel::new_outbound(&feeest, chan_keys, PublicKey::new(), 10000000, false, 42, Arc::clone(&logger)); // Nothing uses their network key in this test
 		chan.their_to_self_delay = 144;
 		chan.our_dust_limit_satoshis = 546;