diff --git a/fuzz/fuzz_targets/channel_target.rs b/fuzz/fuzz_targets/channel_target.rs index d5c483f77..38f898c53 100644 --- a/fuzz/fuzz_targets/channel_target.rs +++ b/fuzz/fuzz_targets/channel_target.rs @@ -107,7 +107,7 @@ pub fn do_test(data: &[u8]) { input: &input, }; - let logger: Arc = Arc::new(test_logger::TestLogger::new()); + let logger: Arc = Arc::new(test_logger::TestLogger{}); macro_rules! get_slice { ($len: expr) => { diff --git a/fuzz/fuzz_targets/full_stack_target.rs b/fuzz/fuzz_targets/full_stack_target.rs index 40336124a..e6515b41e 100644 --- a/fuzz/fuzz_targets/full_stack_target.rs +++ b/fuzz/fuzz_targets/full_stack_target.rs @@ -174,7 +174,7 @@ pub fn do_test(data: &[u8]) { Err(_) => return, }; - let logger: Arc = Arc::new(test_logger::TestLogger::new()); + let logger: Arc = Arc::new(test_logger::TestLogger{}); let monitor = Arc::new(TestChannelMonitor{}); let watch = Arc::new(ChainWatchInterfaceUtil::new(Arc::clone(&logger))); let broadcast = Arc::new(TestBroadcaster{}); diff --git a/fuzz/fuzz_targets/router_target.rs b/fuzz/fuzz_targets/router_target.rs index 759e41ff5..2a7e734ec 100644 --- a/fuzz/fuzz_targets/router_target.rs +++ b/fuzz/fuzz_targets/router_target.rs @@ -105,7 +105,7 @@ pub fn do_test(data: &[u8]) { } } - let logger: Arc = Arc::new(test_logger::TestLogger::new()); + let logger: Arc = Arc::new(test_logger::TestLogger{}); let our_pubkey = get_pubkey!(); let router = Router::new(our_pubkey.clone(), Arc::clone(&logger)); diff --git a/fuzz/fuzz_targets/utils/test_logger.rs b/fuzz/fuzz_targets/utils/test_logger.rs index 4446897be..2ef1196b5 100644 --- a/fuzz/fuzz_targets/utils/test_logger.rs +++ b/fuzz/fuzz_targets/utils/test_logger.rs @@ -1,19 +1,6 @@ -use lightning::util::logger::{Logger, Level, Record}; +use lightning::util::logger::{Logger, 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; - } -} +pub struct TestLogger {} impl Logger for TestLogger { fn log(&self, record: &Record) { diff --git a/src/ln/peer_handler.rs b/src/ln/peer_handler.rs index 273a36daf..b44ddc515 100644 --- a/src/ln/peer_handler.rs +++ b/src/ln/peer_handler.rs @@ -289,7 +289,10 @@ impl PeerManager { macro_rules! encode_and_send_msg { ($msg: expr, $msg_code: expr) => { - peer.pending_outbound_buffer.push_back(peer.channel_encryptor.encrypt_message(&encode_msg!($msg, $msg_code)[..])); + { + log_trace!(self, "Encoding and sending message of type {} to {}", $msg_code, log_pubkey!(peer.their_node_id.unwrap())); + peer.pending_outbound_buffer.push_back(peer.channel_encryptor.encrypt_message(&encode_msg!($msg, $msg_code)[..])); + } } } @@ -396,6 +399,7 @@ impl PeerManager { peer.pending_read_is_header = true; let msg_type = byte_utils::slice_to_be16(&msg_data[0..2]); + log_trace!(self, "Received message of type {} from {}", msg_type, log_pubkey!(peer.their_node_id.unwrap())); if msg_type != 16 && peer.their_global_features.is_none() { // Need an init message as first message return Err(PeerHandleError{ no_connection_possible: false }); @@ -632,6 +636,9 @@ impl PeerManager { Event::PendingHTLCsForwardable {..} => { /* Hand upstream */ }, Event::SendOpenChannel { ref node_id, ref msg } => { + log_trace!(self, "Handling SendOpenChannel event in peer_handler for node {} for channel {}", + log_pubkey!(node_id), + log_bytes!(msg.temporary_channel_id)); let (mut descriptor, peer) = get_peer_for_forwarding!(node_id, { //TODO: Drop the pending channel? (or just let it timeout, but that sucks) }); @@ -640,6 +647,10 @@ impl PeerManager { continue; }, Event::SendFundingCreated { ref node_id, ref msg } => { + log_trace!(self, "Handling SendFundingCreated event in peer_handler for node {} for channel {} (which becomes {})", + log_pubkey!(node_id), + log_bytes!(msg.temporary_channel_id), + log_funding_channel_id!(msg.funding_txid, msg.funding_output_index)); let (mut descriptor, peer) = get_peer_for_forwarding!(node_id, { //TODO: generate a DiscardFunding event indicating to the wallet that //they should just throw away this funding transaction @@ -649,6 +660,10 @@ impl PeerManager { continue; }, Event::SendFundingLocked { ref node_id, ref msg, ref announcement_sigs } => { + log_trace!(self, "Handling SendFundingLocked event in peer_handler for node {}{} for channel {}", + log_pubkey!(node_id), + if announcement_sigs.is_some() { " with announcement sigs" } else { "" }, + log_bytes!(msg.channel_id)); let (mut descriptor, peer) = get_peer_for_forwarding!(node_id, { //TODO: Do whatever we're gonna do for handling dropped messages }); @@ -661,6 +676,10 @@ impl PeerManager { continue; }, Event::SendHTLCs { ref node_id, ref msgs, ref commitment_msg } => { + log_trace!(self, "Handling SendHTLCs event in peer_handler for node {} with {} HTLCs for channel {}", + log_pubkey!(node_id), + msgs.len(), + log_bytes!(commitment_msg.channel_id)); let (mut descriptor, peer) = get_peer_for_forwarding!(node_id, { //TODO: Do whatever we're gonna do for handling dropped messages }); @@ -672,6 +691,10 @@ impl PeerManager { continue; }, Event::SendFulfillHTLC { ref node_id, ref msg, ref commitment_msg } => { + log_trace!(self, "Handling SendFulfillHTLCs event in peer_handler for node {} with payment_preimage {} for channel {}", + log_pubkey!(node_id), + log_bytes!(msg.payment_preimage), + log_bytes!(msg.channel_id)); let (mut descriptor, peer) = get_peer_for_forwarding!(node_id, { //TODO: Do whatever we're gonna do for handling dropped messages }); @@ -681,6 +704,10 @@ impl PeerManager { continue; }, Event::SendFailHTLC { ref node_id, ref msg, ref commitment_msg } => { + log_trace!(self, "Handling SendFailHTLCs event in peer_handler for node {} for HTLC ID {} for channel {}", + log_pubkey!(node_id), + msg.htlc_id, + log_bytes!(msg.channel_id)); let (mut descriptor, peer) = get_peer_for_forwarding!(node_id, { //TODO: Do whatever we're gonna do for handling dropped messages }); @@ -690,6 +717,9 @@ impl PeerManager { continue; }, Event::SendShutdown { ref node_id, ref msg } => { + log_trace!(self, "Handling Shutdown event in peer_handler for node {} for channel {}", + log_pubkey!(node_id), + log_bytes!(msg.channel_id)); let (mut descriptor, peer) = get_peer_for_forwarding!(node_id, { //TODO: Do whatever we're gonna do for handling dropped messages }); @@ -698,6 +728,7 @@ impl PeerManager { continue; }, Event::BroadcastChannelAnnouncement { ref msg, ref update_msg } => { + log_trace!(self, "Handling BroadcastChannelAnnouncement event in peer_handler for short channel id {}", msg.contents.short_channel_id); if self.message_handler.route_handler.handle_channel_announcement(msg).is_ok() && self.message_handler.route_handler.handle_channel_update(update_msg).is_ok() { let encoded_msg = encode_msg!(msg, 256); let encoded_update_msg = encode_msg!(update_msg, 258); @@ -722,6 +753,7 @@ impl PeerManager { continue; }, Event::BroadcastChannelUpdate { ref msg } => { + log_trace!(self, "Handling BroadcastChannelUpdate event in peer_handler for short channel id {}", msg.contents.short_channel_id); if self.message_handler.route_handler.handle_channel_update(msg).is_ok() { let encoded_msg = encode_msg!(msg, 258); @@ -739,6 +771,10 @@ impl PeerManager { if let Some(ref action) = *action { match *action { msgs::ErrorAction::UpdateFailHTLC { ref msg } => { + log_trace!(self, "Handling UpdateFailHTLC HandleError event in peer_handler for node {} for HTLC ID {} for channel {}", + log_pubkey!(node_id), + msg.htlc_id, + log_bytes!(msg.channel_id)); let (mut descriptor, peer) = get_peer_for_forwarding!(node_id, { //TODO: Do whatever we're gonna do for handling dropped messages }); @@ -750,10 +786,15 @@ impl PeerManager { if let Some(mut descriptor) = peers.node_id_to_descriptor.remove(node_id) { if let Some(mut peer) = peers.peers.remove(&descriptor) { if let Some(ref msg) = *msg { + log_trace!(self, "Handling DisconnectPeer HandleError event in peer_handler for node {} with message {}", + log_pubkey!(node_id), + msg.data); peer.pending_outbound_buffer.push_back(peer.channel_encryptor.encrypt_message(&encode_msg!(msg, 17))); // This isn't guaranteed to work, but if there is enough free // room in the send buffer, put the error message there... Self::do_attempt_write_data(&mut descriptor, &mut peer); + } else { + log_trace!(self, "Handling DisconnectPeer HandleError event in peer_handler for node {} with no message", log_pubkey!(node_id)); } } descriptor.disconnect_socket(); @@ -764,6 +805,9 @@ impl PeerManager { continue; }, msgs::ErrorAction::SendErrorMessage { ref msg } => { + log_trace!(self, "Handling SendErrorMessage HandleError event in peer_handler for node {} with message {}", + log_pubkey!(node_id), + msg.data); let (mut descriptor, peer) = get_peer_for_forwarding!(node_id, { //TODO: Do whatever we're gonna do for handling dropped messages }); @@ -771,6 +815,8 @@ impl PeerManager { Self::do_attempt_write_data(&mut descriptor, peer); }, } + } else { + log_error!(self, "Got no-action HandleError Event in peer_handler for node {}, no such events should ever be generated!", log_pubkey!(node_id)); } continue; } diff --git a/src/util/macro_logger.rs b/src/util/macro_logger.rs index 607f8fe4e..fd9a61b39 100644 --- a/src/util/macro_logger.rs +++ b/src/util/macro_logger.rs @@ -1,4 +1,54 @@ -use util::logger::Record; +use chain::transaction::OutPoint; + +use bitcoin::util::hash::Sha256dHash; +use secp256k1::key::PublicKey; + +use std; + +pub(crate) struct DebugPubKey<'a>(pub &'a PublicKey); +impl<'a> std::fmt::Display for DebugPubKey<'a> { + fn fmt(&self, f: &mut std::fmt::Formatter) -> Result<(), std::fmt::Error> { + for i in self.0.serialize().iter() { + write!(f, "{:02x}", i)?; + } + Ok(()) + } +} +macro_rules! log_pubkey { + ($obj: expr) => { + ::util::macro_logger::DebugPubKey(&$obj) + } +} + +pub(crate) struct DebugBytes<'a>(pub &'a [u8; 32]); +impl<'a> std::fmt::Display for DebugBytes<'a> { + fn fmt(&self, f: &mut std::fmt::Formatter) -> Result<(), std::fmt::Error> { + for i in self.0 { + write!(f, "{:02x}", i)?; + } + Ok(()) + } +} +macro_rules! log_bytes { + ($obj: expr) => { + ::util::macro_logger::DebugBytes(&$obj) + } +} + +pub(crate) struct DebugFundingChannelId<'a>(pub &'a Sha256dHash, pub u16); +impl<'a> std::fmt::Display for DebugFundingChannelId<'a> { + fn fmt(&self, f: &mut std::fmt::Formatter) -> Result<(), std::fmt::Error> { + for i in OutPoint::new(self.0.clone(), self.1).to_channel_id().iter() { + write!(f, "{:02x}", i)?; + } + Ok(()) + } +} +macro_rules! log_funding_channel_id { + ($funding_txid: expr, $funding_txo: expr) => { + ::util::macro_logger::DebugFundingChannelId(&$funding_txid, $funding_txo) + } +} macro_rules! log_internal { ($self: ident, $lvl:expr, $($arg:tt)+) => ( diff --git a/src/util/test_utils.rs b/src/util/test_utils.rs index b5fbbd594..aff84735e 100644 --- a/src/util/test_utils.rs +++ b/src/util/test_utils.rs @@ -154,7 +154,7 @@ pub struct TestLogger { impl TestLogger { pub fn new() -> TestLogger { TestLogger { - level: Level::Off, + level: Level::Trace, } } pub fn enable(&mut self, level: Level) {