X-Git-Url: http://git.bitcoin.ninja/index.cgi?a=blobdiff_plain;f=src%2Fln%2Fpeer_handler.rs;h=b44ddc515b54d96fc35b970eb752c2ca7cfddc56;hb=refs%2Fheads%2F2018-08-peer_handler-trace;hp=45e39846acf3645ab7b2a5f43431b3023baa2114;hpb=587f2b39fc30400ecadcb4145eeac4c896d5f51c;p=rust-lightning

diff --git a/src/ln/peer_handler.rs b/src/ln/peer_handler.rs
index 45e39846..b44ddc51 100644
--- a/src/ln/peer_handler.rs
+++ b/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, 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,
 		}
 	}
 
@@ -286,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)[..]));
+									}
 								}
 							}
 
@@ -295,7 +301,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 +331,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 +343,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;
 										}
 									};
@@ -395,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 });
@@ -631,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)
 							});
@@ -639,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
@@ -648,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
 							});
@@ -660,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
 							});
@@ -671,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
 							});
@@ -680,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
 							});
@@ -689,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
 							});
@@ -697,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);
@@ -721,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);
 
@@ -738,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
 									});
@@ -749,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();
@@ -763,6 +805,9 @@ 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
 									});
@@ -770,6 +815,8 @@ impl<Descriptor: SocketDescriptor> PeerManager<Descriptor> {
 									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;
 					}
@@ -826,6 +873,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 +900,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 +911,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);
 		}