Logging interface

Implement error, warn, info, debug and trace macros, internally calling
an instance of Logger, and passing it to every main structures
Issue #54

Author: Antoine Riard

Cargo.toml

@@ -15,6 +15,11 @@ 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"]
+max_level_error = []
+max_level_warn = []
+max_level_info = []
+max_level_debug = []
+max_level_trace = []
 
 [dependencies]
 bitcoin = "0.13"

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,10 +23,12 @@ use chain::chaininterface::{FeeEstimator,ConfirmationTarget};
 use chain::transaction::OutPoint;
 use util::{transaction_utils,rng};
 use util::sha2::Sha256;
+use util::logger::Logger;
 
 use std::default::Default;
 use std::{cmp,mem};
 use std::time::Instant;
+use std::sync::{Arc};
 
 pub struct ChannelKeys {
 	pub funding_key: SecretKey,
@@ -302,6 +304,8 @@ pub struct Channel {
 	their_shutdown_scriptpubkey: Option<Script>,
 
 	channel_monitor: ChannelMonitor,
+
+	logger: Arc<Logger>,
 }
 
 const OUR_MAX_HTLCS: u16 = 5; //TODO
@@ -360,7 +364,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");
 		}
@@ -428,6 +432,8 @@ impl Channel {
 			their_shutdown_scriptpubkey: None,
 
 			channel_monitor: channel_monitor,
+
+			logger,
 		}
 	}
 
@@ -445,7 +451,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, announce_publicly: 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 })});
@@ -547,6 +553,8 @@ impl Channel {
 			their_shutdown_scriptpubkey: None,
 
 			channel_monitor: channel_monitor,
+
+			logger,
 		};
 
 		let obscure_factor = chan.get_commitment_transaction_number_obscure_factor();
@@ -2347,10 +2355,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
@@ -2371,6 +2382,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 {
@@ -2388,7 +2400,7 @@ mod tests {
 		assert_eq!(PublicKey::from_secret_key(&secp_ctx, &chan_keys.funding_key).unwrap().serialize()[..],
 				hex_bytes("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;
 

src/ln/channelmanager.rs

@@ -19,6 +19,7 @@ use ln::msgs;
 use ln::msgs::{HandleError,ChannelMessageHandler,MsgEncodable,MsgDecodable};
 use util::{byte_utils, events, internal_traits, rng};
 use util::sha2::Sha256;
+use util::logger::Logger;
 
 use crypto;
 use crypto::mac::{Mac,MacResult};
@@ -159,6 +160,8 @@ pub struct ChannelManager {
 	our_network_key: SecretKey,
 
 	pending_events: Mutex<Vec<events::Event>>,
+
+	logger: Arc<Logger>,
 }
 
 const CLTV_EXPIRY_DELTA: u16 = 6 * 24 * 2; //TODO?
@@ -204,7 +207,7 @@ impl ChannelManager {
 	/// fee_proportional_millionths is an optional fee to charge any payments routed through us.
 	/// Non-proportional fees are fixed according to our risk using the provided fee estimator.
 	/// panics if channel_value_satoshis is >= `MAX_FUNDING_SATOSHIS`!
-	pub fn new(our_network_key: SecretKey, fee_proportional_millionths: u32, announce_channels_publicly: bool, network: Network, feeest: Arc<FeeEstimator>, monitor: Arc<ManyChannelMonitor>, chain_monitor: Arc<ChainWatchInterface>, tx_broadcaster: Arc<BroadcasterInterface>) -> Result<Arc<ChannelManager>, secp256k1::Error> {
+	pub fn new(our_network_key: SecretKey, fee_proportional_millionths: u32, announce_channels_publicly: bool, network: Network, feeest: Arc<FeeEstimator>, monitor: Arc<ManyChannelMonitor>, chain_monitor: Arc<ChainWatchInterface>, tx_broadcaster: Arc<BroadcasterInterface>, logger: Arc<Logger>) -> Result<Arc<ChannelManager>, secp256k1::Error> {
 		let secp_ctx = Secp256k1::new();
 
 		let res = Arc::new(ChannelManager {
@@ -229,6 +232,8 @@ impl ChannelManager {
 			our_network_key,
 
 			pending_events: Mutex::new(Vec::new()),
+
+			logger,
 		});
 		let weak_res = Arc::downgrade(&res);
 		res.chain_monitor.register_listener(weak_res);
@@ -263,7 +268,7 @@ impl ChannelManager {
 			}
 		};
 
-		let channel = Channel::new_outbound(&*self.fee_estimator, chan_keys, their_network_key, channel_value_satoshis, self.announce_channels_publicly, user_id);
+		let channel = Channel::new_outbound(&*self.fee_estimator, chan_keys, their_network_key, channel_value_satoshis, self.announce_channels_publicly, user_id, Arc::clone(&self.logger));
 		let res = channel.get_open_channel(self.genesis_hash.clone(), &*self.fee_estimator)?;
 		let mut channel_state = self.channel_state.lock().unwrap();
 		match channel_state.by_id.insert(channel.channel_id(), channel) {
@@ -718,6 +723,7 @@ impl ChannelManager {
 	/// Call this upon creation of a funding transaction for the given channel.
 	/// Panics if a funding transaction has already been provided for this channel.
 	pub fn funding_transaction_generated(&self, temporary_channel_id: &[u8; 32], funding_txo: OutPoint) {
+
 		macro_rules! add_pending_event {
 			($event: expr) => {
 				{
@@ -1195,7 +1201,7 @@ impl ChannelMessageHandler for ChannelManager {
 			}
 		};
 
-		let channel = Channel::new_from_req(&*self.fee_estimator, chan_keys, their_node_id.clone(), msg, 0, false, self.announce_channels_publicly)?;
+		let channel = Channel::new_from_req(&*self.fee_estimator, chan_keys, their_node_id.clone(), msg, 0, self.announce_channels_publicly, Arc::clone(&self.logger))?;
 		let accept_msg = channel.get_accept_channel()?;
 		channel_state.by_id.insert(channel.channel_id(), channel);
 		Ok(accept_msg)
@@ -1892,6 +1898,7 @@ mod tests {
 	use ln::msgs::{MsgEncodable,ChannelMessageHandler,RoutingMessageHandler};
 	use util::test_utils;
 	use util::events::{Event, EventsProvider};
+	use util::logger::Logger;
 
 	use bitcoin::util::misc::hex_bytes;
 	use bitcoin::util::hash::Sha256dHash;
@@ -2606,19 +2613,20 @@ mod tests {
 		let mut nodes = Vec::new();
 		let mut rng = thread_rng();
 		let secp_ctx = Secp256k1::new();
+		let logger: Arc<Logger> = Arc::new(test_utils::TestLogger::new());
 
 		for _ in 0..node_count {
 			let feeest = Arc::new(test_utils::TestFeeEstimator { sat_per_kw: 253 });
-			let chain_monitor = Arc::new(chaininterface::ChainWatchInterfaceUtil::new());
+			let chain_monitor = Arc::new(chaininterface::ChainWatchInterfaceUtil::new(Arc::clone(&logger)));
 			let tx_broadcaster = Arc::new(test_utils::TestBroadcaster{txn_broadcasted: Mutex::new(Vec::new())});
 			let chan_monitor = Arc::new(test_utils::TestChannelMonitor::new(chain_monitor.clone(), tx_broadcaster.clone()));
 			let node_id = {
 				let mut key_slice = [0; 32];
 				rng.fill_bytes(&mut key_slice);
 				SecretKey::from_slice(&secp_ctx, &key_slice).unwrap()
 			};
-			let node = ChannelManager::new(node_id.clone(), 0, true, Network::Testnet, feeest.clone(), chan_monitor.clone(), chain_monitor.clone(), tx_broadcaster.clone()).unwrap();
-			let router = Router::new(PublicKey::from_secret_key(&secp_ctx, &node_id).unwrap());
+			let node = ChannelManager::new(node_id.clone(), 0, true, Network::Testnet, feeest.clone(), chan_monitor.clone(), chain_monitor.clone(), tx_broadcaster.clone(), Arc::clone(&logger)).unwrap();
+			let router = Router::new(PublicKey::from_secret_key(&secp_ctx, &node_id).unwrap(), Arc::clone(&logger));
 			nodes.push(Node { feeest, chain_monitor, tx_broadcaster, chan_monitor, node_id, node, router });
 		}
 

src/ln/peer_handler.rs

@@ -5,6 +5,7 @@ use ln::msgs::{MsgEncodable,MsgDecodable};
 use ln::peer_channel_encryptor::{PeerChannelEncryptor,NextNoiseStep};
 use util::byte_utils;
 use util::events::{EventsProvider,Event};
+use util::logger::Logger;
 
 use std::collections::{HashMap,LinkedList};
 use std::sync::{Arc, Mutex};
@@ -96,6 +97,7 @@ pub struct PeerManager<Descriptor: SocketDescriptor> {
 	pending_events: Mutex<Vec<Event>>,
 	our_node_secret: SecretKey,
 	initial_syncs_sent: AtomicUsize,
+	logger: Arc<Logger>,
 }
 
 
@@ -117,13 +119,14 @@ const INITIAL_SYNCS_TO_SEND: usize = 5;
 /// Manages and reacts to connection events. You probably want to use file descriptors as PeerIds.
 /// PeerIds may repeat, but only after disconnect_event() has been called.
 impl<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
-	pub fn new(message_handler: MessageHandler, our_node_secret: SecretKey) -> PeerManager<Descriptor> {
+	pub fn new(message_handler: MessageHandler, our_node_secret: SecretKey, logger: Arc<Logger>) -> PeerManager<Descriptor> {
 		PeerManager {
 			message_handler: message_handler,
 			peers: Mutex::new(PeerHolder { peers: HashMap::new(), node_id_to_descriptor: HashMap::new() }),
 			pending_events: Mutex::new(Vec::new()),
 			our_node_secret: our_node_secret,
 			initial_syncs_sent: AtomicUsize::new(0),
+			logger,
 		}
 	}
 
@@ -801,6 +804,7 @@ mod tests {
 	use ln::peer_handler::{PeerManager, MessageHandler, SocketDescriptor};
 	use util::events;
 	use util::test_utils;
+	use util::logger::Logger;
 
 	use secp256k1::Secp256k1;
 	use secp256k1::key::{SecretKey, PublicKey};
@@ -827,6 +831,7 @@ mod tests {
 		let secp_ctx = Secp256k1::new();
 		let mut peers = Vec::new();
 		let mut rng = thread_rng();
+		let logger : Arc<Logger> = Arc::new(test_utils::TestLogger::new());
 
 		for _ in 0..peer_count {
 			let chan_handler = test_utils::TestChannelMessageHandler::new();
@@ -837,7 +842,7 @@ mod tests {
 				SecretKey::from_slice(&secp_ctx, &key_slice).unwrap()
 			};
 			let msg_handler = MessageHandler { chan_handler: Arc::new(chan_handler), route_handler: Arc::new(router) };
-			let peer = PeerManager::new(msg_handler, node_id);
+			let peer = PeerManager::new(msg_handler, node_id, Arc::clone(&logger));
 			peers.push(peer);
 		}
 

src/ln/router.rs

@@ -6,9 +6,10 @@ use bitcoin::util::hash::Sha256dHash;
 use ln::channelmanager;
 use ln::msgs::{ErrorAction,HandleError,RoutingMessageHandler,MsgEncodable,NetAddress,GlobalFeatures};
 use ln::msgs;
+use util::logger::Logger;
 
 use std::cmp;
-use std::sync::RwLock;
+use std::sync::{RwLock,Arc};
 use std::collections::{HashMap,BinaryHeap};
 use std::collections::hash_map::Entry;
 
@@ -105,6 +106,7 @@ pub struct RouteHint {
 pub struct Router {
 	secp_ctx: Secp256k1,
 	network_map: RwLock<NetworkMap>,
+	logger: Arc<Logger>,
 }
 
 macro_rules! secp_verify_sig {
@@ -325,7 +327,7 @@ struct DummyDirectionalChannelInfo {
 }
 
 impl Router {
-	pub fn new(our_pubkey: PublicKey) -> Router {
+	pub fn new(our_pubkey: PublicKey, logger: Arc<Logger>) -> Router {
 		let mut nodes = HashMap::new();
 		nodes.insert(our_pubkey.clone(), NodeInfo {
 			channels: Vec::new(),
@@ -344,6 +346,7 @@ impl Router {
 				our_node_id: our_pubkey,
 				nodes: nodes,
 			}),
+			logger,
 		}
 	}
 
@@ -554,18 +557,23 @@ mod tests {
 	use ln::channelmanager;
 	use ln::router::{Router,NodeInfo,NetworkMap,ChannelInfo,DirectionalChannelInfo,RouteHint};
 	use ln::msgs::GlobalFeatures;
+	use util::test_utils;
+	use util::logger::Logger;
 
 	use bitcoin::util::misc::hex_bytes;
 	use bitcoin::util::hash::Sha256dHash;
 
 	use secp256k1::key::{PublicKey,SecretKey};
 	use secp256k1::Secp256k1;
 
+	use std::sync::Arc;
+
 	#[test]
 	fn route_test() {
 		let secp_ctx = Secp256k1::new();
 		let our_id = PublicKey::from_secret_key(&secp_ctx, &SecretKey::from_slice(&secp_ctx, &hex_bytes("0101010101010101010101010101010101010101010101010101010101010101").unwrap()[..]).unwrap()).unwrap();
-		let router = Router::new(our_id);
+		let logger: Arc<Logger> = Arc::new(test_utils::TestLogger::new());
+		let router = Router::new(our_id, Arc::clone(&logger));
 
 		// Build network from our_id to node8:
 		//