Logging interface
authorAntoine Riard <ariard@student.42.fr>
Wed, 25 Jul 2018 02:34:51 +0000 (02:34 +0000)
committerAntoine Riard <ariard@student.42.fr>
Fri, 17 Aug 2018 00:01:15 +0000 (00:01 +0000)
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

16 files changed:
Cargo.toml
fuzz/fuzz_targets/channel_target.rs
fuzz/fuzz_targets/full_stack_target.rs
fuzz/fuzz_targets/router_target.rs
fuzz/fuzz_targets/utils/mod.rs [new file with mode: 0644]
fuzz/fuzz_targets/utils/test_logger.rs [new file with mode: 0644]
src/chain/chaininterface.rs
src/lib.rs
src/ln/channel.rs
src/ln/channelmanager.rs
src/ln/peer_handler.rs
src/ln/router.rs
src/util/logger.rs [new file with mode: 0644]
src/util/macro_logger.rs [new file with mode: 0644]
src/util/mod.rs
src/util/test_utils.rs

index 69c6f44b7bad8dd9c6850902917e8b748db59ab7..088763ccb210159176473b2fbe72f4d49a7b01a1 100644 (file)
@@ -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"
index 683faf0edc65dd30f5b325aaaf72bbaa6023be5f..d5c483f770415047b60cc1888a90c0e7f8c9845a 100644 (file)
@@ -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,
                };
index cf84701d4efd945c687dea6cd6a3d6729ed44e2b..8f7ec2df0a76013918e2ec7b154deceed7057cab 100644 (file)
@@ -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();
index ed4737221670c051df8f09a7295f6811bd3792e5..f9c8d2ba23bf9f99ab9f500cc412a7f02c27fff3 100644 (file)
@@ -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] {
diff --git a/fuzz/fuzz_targets/utils/mod.rs b/fuzz/fuzz_targets/utils/mod.rs
new file mode 100644 (file)
index 0000000..a7d7c32
--- /dev/null
@@ -0,0 +1 @@
+pub(crate) mod test_logger;
diff --git a/fuzz/fuzz_targets/utils/test_logger.rs b/fuzz/fuzz_targets/utils/test_logger.rs
new file mode 100644 (file)
index 0000000..4446897
--- /dev/null
@@ -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);
+       }
+}
index 7e9e9aeff05b902923703846337cc5c9b9666edd..e08c8cdbd47dcff18a9c193356037517d981ae68 100644 (file)
@@ -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,
                }
        }
 
index a5e291d3075e491a4595f2778b4df8b696d261d5..1fa7b21e06aaefbdc8b94c7a24bbfe71c55c392e 100644 (file)
@@ -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;
index 68a23dc67b9348dac07e795e5b8c9d50555470ed..a1ca7e25e65a5ea8cff9f5d0a27710751ea5ae94 100644 (file)
@@ -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;
 
index fe18560caf34b45f8b6ee33f3c078368be145d40..0b6b1663ab47b508e527bd718c3b35d6b88252a1 100644 (file)
@@ -20,6 +20,7 @@ use ln::msgs::{HandleError,ChannelMessageHandler,MsgEncodable,MsgDecodable};
 use util::{byte_utils, events, internal_traits, rng};
 use util::sha2::Sha256;
 use util::chacha20poly1305rfc::ChaCha20;
+use util::logger::{Logger, Record};
 
 use crypto;
 use crypto::mac::{Mac,MacResult};
@@ -166,6 +167,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?
@@ -211,7 +214,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 {
@@ -236,6 +239,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);
@@ -270,7 +275,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) {
@@ -766,6 +771,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) => {
                                {
@@ -784,6 +790,7 @@ impl ChannelManager {
                                                        (chan, funding_msg.0, funding_msg.1)
                                                },
                                                Err(e) => {
+                                                       log_error!(self, "Got bad signatures: {}!", e.err);
                                                        mem::drop(channel_state);
                                                        add_pending_event!(events::Event::HandleError {
                                                                node_id: chan.get_their_node_id(),
@@ -879,7 +886,7 @@ impl ChannelManager {
                                        if !add_htlc_msgs.is_empty() {
                                                let (commitment_msg, monitor) = match forward_chan.send_commitment() {
                                                        Ok(res) => res,
-                                                       Err(_) => {
+                                                       Err(_e) => {
                                                                //TODO: Handle...this is bad!
                                                                continue;
                                                        },
@@ -1145,7 +1152,8 @@ impl ChainListener for ChannelManager {
                                if let Ok(Some(funding_locked)) = chan_res {
                                        let announcement_sigs = match self.get_announcement_sigs(channel) {
                                                Ok(res) => res,
-                                               Err(_e) => {
+                                               Err(e) => {
+                                                       log_error!(self, "Got error handling message: {}!", e.err);
                                                        //TODO: push e on events and blow up the channel (it has bad keys)
                                                        return true;
                                                }
@@ -1284,7 +1292,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, false, 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)
@@ -1970,6 +1978,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::hash::Sha256dHash;
        use bitcoin::blockdata::block::{Block, BlockHeader};
@@ -2684,10 +2693,11 @@ 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 = {
@@ -2695,8 +2705,8 @@ mod tests {
                                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 });
                }
 
index 45e39846acf3645ab7b2a5f43431b3023baa2114..273a36dafd4369f7092c42b5ccc26a523823c32a 100644 (file)
@@ -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, Record};
 
 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,
                }
        }
 
@@ -295,7 +298,6 @@ impl<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
                                                                        match $thing {
                                                                                Ok(x) => x,
                                                                                Err(e) => {
-                                                                                       println!("Got error handling message: {}!", e.err);
                                                                                        if let Some(action) = e.action {
                                                                                                match action {
                                                                                                        msgs::ErrorAction::UpdateFailHTLC { msg } => {
@@ -326,7 +328,6 @@ impl<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
                                                                        match $thing {
                                                                                Ok(x) => x,
                                                                                Err(_e) => {
-                                                                                       println!("Error decoding message");
                                                                                        //TODO: Handle e?
                                                                                        return Err(PeerHandleError{ no_connection_possible: false });
                                                                                }
@@ -339,7 +340,7 @@ impl<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
                                                                        match $thing {
                                                                                Ok(x) => x,
                                                                                Err(_e) => {
-                                                                                       println!("Error decoding message, ignoring due to lnd spec incompatibility. See https://github.com/lightningnetwork/lnd/issues/1407");
+                                                                                       log_debug!(self, "Error decoding message, ignoring due to lnd spec incompatibility. See https://github.com/lightningnetwork/lnd/issues/1407");
                                                                                        continue;
                                                                                }
                                                                        };
@@ -826,6 +827,7 @@ mod tests {
        use ln::msgs;
        use util::events;
        use util::test_utils;
+       use util::logger::Logger;
 
        use secp256k1::Secp256k1;
        use secp256k1::key::{SecretKey, PublicKey};
@@ -852,6 +854,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();
@@ -862,7 +865,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);
                }
 
index 880944a97c22b81d8d944f4dc0795be08d2563c4..229682bd03a837479e0e38bff61fc39eb3ec04d7 100644 (file)
@@ -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,6 +557,8 @@ 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::hash::Sha256dHash;
 
@@ -562,11 +567,14 @@ mod tests {
        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::decode("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:
                //
diff --git a/src/util/logger.rs b/src/util/logger.rs
new file mode 100644 (file)
index 0000000..bccc8cd
--- /dev/null
@@ -0,0 +1,168 @@
+// Pruned copy of crate rust log, without global logger
+// https://github.com/rust-lang-nursery/log #7a60286
+//
+// Licensed under the Apache License, Version 2.0 <LICENSE-APACHE or
+// http://www.apache.org/licenses/LICENSE-2.0> or the MIT license
+// <LICENSE-MIT or http://opensource.org/licenses/MIT>, at your
+// option. This file may not be copied, modified, or distributed
+// except according to those terms.
+
+/// There is currently 2 ways to filter log messages. First one, by using compilation flag, e.g "max_level_off".
+/// The second one, client-side by implementing check against Record Level field, e.g TestLogger in test_utils.
+/// Each module may have its own Logger or share one.
+
+use std::cmp;
+use std::fmt;
+
+static LOG_LEVEL_NAMES: [&'static str; 6] = ["OFF", "ERROR", "WARN", "INFO", "DEBUG", "TRACE"];
+
+/// An enum representing the available verbosity levels of the logger.
+#[derive(Copy, Clone, Eq, Debug, Hash)]
+pub enum Level {
+       ///Designates logger being silent
+       Off,
+       /// Designates very serious errors
+       Error,
+       /// Designates hazardous situations
+       Warn,
+       /// Designates useful information
+       Info,
+       /// Designates lower priority information
+       Debug,
+       /// Designates very low priority, often extremely verbose, information
+       Trace,
+}
+
+impl PartialEq for Level {
+       #[inline]
+       fn eq(&self, other: &Level) -> bool {
+               *self as usize == *other as usize
+       }
+}
+
+impl PartialOrd for Level {
+       #[inline]
+       fn partial_cmp(&self, other: &Level) -> Option<cmp::Ordering> {
+               Some(self.cmp(other))
+       }
+
+       #[inline]
+       fn lt(&self, other: &Level) -> bool {
+               (*self as usize) < *other as usize
+       }
+
+       #[inline]
+       fn le(&self, other: &Level) -> bool {
+               *self as usize <= *other as usize
+       }
+
+       #[inline]
+       fn gt(&self, other: &Level) -> bool {
+               *self as usize > *other as usize
+       }
+
+       #[inline]
+       fn ge(&self, other: &Level) -> bool {
+               *self as usize >= *other as usize
+       }
+}
+
+impl Ord for Level {
+       #[inline]
+       fn cmp(&self, other: &Level) -> cmp::Ordering {
+               (*self as usize).cmp(&(*other as usize))
+       }
+}
+
+impl fmt::Display for Level {
+       fn fmt(&self, fmt: &mut fmt::Formatter) -> fmt::Result {
+               fmt.pad(LOG_LEVEL_NAMES[*self as usize])
+       }
+}
+
+impl Level {
+       /// Returns the most verbose logging level.
+       #[inline]
+       pub fn max() -> Level {
+               Level::Trace
+       }
+}
+
+/// A Record, unit of logging output with Metadata to enable filtering
+/// Module_path, file, line to inform on log's source
+#[derive(Clone,Debug)]
+pub struct Record<'a> {
+       /// The verbosity level of the message.
+       pub level: Level,
+       /// The message body.
+       pub args: fmt::Arguments<'a>,
+       /// The module path of the message.
+       pub module_path: &'a str,
+       /// The source file containing the message.
+       pub file: &'a str,
+       /// The line containing the message.
+       pub line: u32,
+}
+
+impl<'a> Record<'a> {
+       /// Returns a new Record.
+       #[inline]
+       pub fn new(level: Level, args: fmt::Arguments<'a>, module_path: &'a str, file: &'a str, line: u32) -> Record<'a> {
+               Record {
+                       level,
+                       args,
+                       module_path,
+                       file,
+                       line
+               }
+       }
+}
+
+/// A trait encapsulating the operations required of a logger
+pub trait Logger: Sync + Send {
+       /// Logs the `Record`
+       fn log(&self, record: &Record);
+}
+
+#[cfg(test)]
+mod tests {
+       use util::logger::{Logger, Level, Record};
+       use util::test_utils::TestLogger;
+       use std::sync::{Arc};
+
+       #[test]
+       fn test_level_show() {
+               assert_eq!("INFO", Level::Info.to_string());
+               assert_eq!("ERROR", Level::Error.to_string());
+               assert_ne!("WARN", Level::Error.to_string());
+       }
+
+       struct WrapperLog {
+               logger: Arc<Logger>
+       }
+
+       impl WrapperLog {
+               fn new(logger: Arc<Logger>) -> WrapperLog {
+                       WrapperLog {
+                               logger,
+                       }
+               }
+
+               fn call_macros(&self) {
+                       log_error!(self, "This is an error");
+                       log_warn!(self, "This is a warning");
+                       log_info!(self, "This is an info");
+                       log_debug!(self, "This is a debug");
+                       log_trace!(self, "This is a trace");
+               }
+       }
+
+       #[test]
+       fn test_logging_macros() {
+               let mut logger = TestLogger::new();
+               logger.enable(Level::Trace);
+               let logger : Arc<Logger> = Arc::new(logger);
+               let wrapper = WrapperLog::new(Arc::clone(&logger));
+               wrapper.call_macros();
+       }
+}
diff --git a/src/util/macro_logger.rs b/src/util/macro_logger.rs
new file mode 100644 (file)
index 0000000..607f8fe
--- /dev/null
@@ -0,0 +1,42 @@
+use util::logger::Record;
+
+macro_rules! log_internal {
+       ($self: ident, $lvl:expr, $($arg:tt)+) => (
+               &$self.logger.log(&Record::new($lvl, format_args!($($arg)+), module_path!(), file!(), line!()));
+       );
+}
+
+macro_rules! log_error {
+       ($self: ident, $($arg:tt)*) => (
+               #[cfg(not(any(feature = "max_level_off")))]
+               log_internal!($self, $crate::util::logger::Level::Error, $($arg)*);
+       )
+}
+
+macro_rules! log_warn {
+       ($self: ident, $($arg:tt)*) => (
+               #[cfg(not(any(feature = "max_level_off", feature = "max_level_error")))]
+               log_internal!($self, $crate::util::logger::Level::Warn, $($arg)*);
+       )
+}
+
+macro_rules! log_info {
+       ($self: ident, $($arg:tt)*) => (
+               #[cfg(not(any(feature = "max_level_off", feature = "max_level_error", feature = "max_level_warn")))]
+               log_internal!($self, $crate::util::logger::Level::Info, $($arg)*);
+       )
+}
+
+macro_rules! log_debug {
+       ($self: ident, $($arg:tt)*) => (
+               #[cfg(not(any(feature = "max_level_off", feature = "max_level_error", feature = "max_level_warn", feature = "max_level_info")))]
+               log_internal!($self, $crate::util::logger::Level::Debug, $($arg)*);
+       )
+}
+
+macro_rules! log_trace {
+       ($self: ident, $($arg:tt)*) => (
+               #[cfg(not(any(feature = "max_level_off", feature = "max_level_error", feature = "max_level_warn", feature = "max_level_info", feature = "max_level_debug")))]
+               log_internal!($self, $crate::util::logger::Level::Trace, $($arg)*);
+       )
+}
index 008a9e1d7e1e0649b4fe07d92f1f2e142751adcc..766557e3ca52805379e4b5618243ac4f06ed2a76 100644 (file)
@@ -12,3 +12,8 @@ pub use self::rng::reset_rng_state;
 
 #[cfg(test)]
 pub(crate) mod test_utils;
+
+#[macro_use]
+pub(crate) mod macro_logger;
+
+pub mod logger;
index 9646754f2d0097f51358cf5be9d86c8519acfcd4..b5fbbd5940924483545fb5d11c298658dc75feda 100644 (file)
@@ -5,6 +5,7 @@ use ln::channelmonitor;
 use ln::msgs;
 use ln::msgs::{HandleError};
 use util::events;
+use util::logger::{Logger, Level, Record};
 
 use bitcoin::blockdata::transaction::Transaction;
 
@@ -145,3 +146,26 @@ impl msgs::RoutingMessageHandler for TestRoutingMessageHandler {
        }
        fn handle_htlc_fail_channel_update(&self, _update: &msgs::HTLCFailChannelUpdate) {}
 }
+
+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) {
+               if self.level >= record.level {
+                       println!("{:<5} [{} : {}, {}] {}", record.level.to_string(), record.module_path, record.file, record.line, record.args);
+               }
+       }
+}