Merge pull request #116 from TheBlueMatt/2018-08-peer_handler-trace

TheBlueMatt · web-flow · commit 03c6f84aa82e · 2018-08-16T23:35:09.000-04:00
Add some trace logging in peer_handler
diff --git 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<Logger> = Arc::new(test_logger::TestLogger::new());
+	let logger: Arc<Logger> = 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
@@ -174,7 +174,7 @@ pub fn do_test(data: &[u8]) {
 		Err(_) => return,
 	};
 
-	let logger: Arc<Logger> = Arc::new(test_logger::TestLogger::new());
+	let logger: Arc<Logger> = 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
@@ -105,7 +105,7 @@ pub fn do_test(data: &[u8]) {
 		}
 	}
 
-	let logger: Arc<Logger> = Arc::new(test_logger::TestLogger::new());
+	let logger: Arc<Logger> = 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
@@ -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
@@ -289,7 +289,10 @@ impl<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
 
 							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<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
 										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<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
 					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<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
 						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<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
 						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<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
 						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<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
 						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<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
 						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<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
 						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<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
 						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<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
 						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<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
 						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<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
 									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,13 +805,18 @@ impl<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
 									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
 									});
 									peer.pending_outbound_buffer.push_back(peer.channel_encryptor.encrypt_message(&encode_msg!(msg, 17)));
 									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
@@ -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
@@ -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) {

Original file line number	Diff line number	Diff line change
`@@ -105,7 +105,7 @@ pub fn do_test(data: &[u8]) {`
`105`	`105`	`}`
`106`	`106`	`}`
`107`	`107`
`108`		`- let logger: Arc<Logger> = Arc::new(test_logger::TestLogger::new());`
	`108`	`+ let logger: Arc<Logger> = Arc::new(test_logger::TestLogger{});`
`109`	`109`
`110`	`110`	`let our_pubkey = get_pubkey!();`
`111`	`111`	`let router = Router::new(our_pubkey.clone(), Arc::clone(&logger));`
Original file line number	Diff line number	Diff line change
`@@ -154,7 +154,7 @@ pub struct TestLogger {`
`154`	`154`	`impl TestLogger {`
`155`	`155`	`pub fn new() -> TestLogger {`
`156`	`156`	`TestLogger {`
`157`		`- level: Level::Off,`
	`157`	`+ level: Level::Trace,`
`158`	`158`	`}`
`159`	`159`	`}`
`160`	`160`	`pub fn enable(&mut self, level: Level) {`