X-Git-Url: http://git.bitcoin.ninja/index.cgi?a=blobdiff_plain;f=src%2Fln%2Fpeer_handler.rs;h=9315f56902d767339285d146235c18f62cffb982;hb=7d6aab7f22e8191b1838c3132cd8188c48f2796b;hp=bf0052d0236cdb69a469b0fa53a456c3bde8c55c;hpb=bdd77ae1fadfef084f90ed259ba00d614ff1c326;p=rust-lightning diff --git a/src/ln/peer_handler.rs b/src/ln/peer_handler.rs index bf0052d0..9315f569 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; use std::collections::{HashMap,LinkedList}; use std::sync::{Arc, Mutex}; @@ -96,6 +97,7 @@ pub struct PeerManager { pending_events: Mutex>, our_node_secret: SecretKey, initial_syncs_sent: AtomicUsize, + logger: Arc, } @@ -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 PeerManager { - pub fn new(message_handler: MessageHandler, our_node_secret: SecretKey) -> PeerManager { + pub fn new(message_handler: MessageHandler, our_node_secret: SecretKey, logger: Arc) -> PeerManager { 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 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)[..])); + } } } @@ -295,25 +301,25 @@ impl PeerManager { 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 } => { - encode_and_send_msg!(msg, 131); - continue; - }, msgs::ErrorAction::DisconnectPeer { msg: _ } => { + //TODO: Try to push msg + log_trace!(self, "Got Err handling message, disconnecting peer because {}", e.err); return Err(PeerHandleError{ no_connection_possible: false }); }, msgs::ErrorAction::IgnoreError => { + log_trace!(self, "Got Err handling message, ignoring because {}", e.err); continue; }, msgs::ErrorAction::SendErrorMessage { msg } => { + log_trace!(self, "Got Err handling message, sending Error message because {}", e.err); encode_and_send_msg!(msg, 17); continue; }, } } else { + log_debug!(self, "Got Err handling message, action not yet filled in: {}", e.err); return Err(PeerHandleError{ no_connection_possible: false }); } } @@ -326,7 +332,6 @@ impl PeerManager { match $thing { Ok(x) => x, Err(_e) => { - println!("Error decoding message"); //TODO: Handle e? return Err(PeerHandleError{ no_connection_possible: false }); } @@ -339,7 +344,7 @@ impl PeerManager { 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 +400,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 }); @@ -425,7 +431,24 @@ impl PeerManager { } }, 17 => { - // Error msg + let msg = try_potential_decodeerror!(msgs::ErrorMessage::decode(&msg_data[2..])); + let mut data_is_printable = true; + for b in msg.data.bytes() { + if b < 32 || b > 126 { + data_is_printable = false; + break; + } + } + + if data_is_printable { + log_debug!(self, "Got Err message from {}: {}", log_pubkey!(peer.their_node_id.unwrap()), msg.data); + } else { + log_debug!(self, "Got Err message from {} with non-ASCII error message", log_pubkey!(peer.their_node_id.unwrap())); + } + self.message_handler.chan_handler.handle_error(&peer.their_node_id.unwrap(), &msg); + if msg.channel_id == [0; 32] { + return Err(PeerHandleError{ no_connection_possible: true }); + } }, 18 => { @@ -615,6 +638,10 @@ impl PeerManager { }; match peers.peers.get_mut(&descriptor) { Some(peer) => { + if peer.their_global_features.is_none() { + $handle_no_such_peer; + continue; + } (descriptor, peer) }, None => panic!("Inconsistent peers set state!"), @@ -631,6 +658,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) }); @@ -639,6 +669,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 @@ -648,6 +682,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 }); @@ -659,36 +697,36 @@ impl PeerManager { Self::do_attempt_write_data(&mut descriptor, peer); continue; }, - Event::SendHTLCs { ref node_id, ref msgs, ref commitment_msg } => { + Event::UpdateHTLCs { ref node_id, updates: msgs::CommitmentUpdate { ref update_add_htlcs, ref update_fulfill_htlcs, ref update_fail_htlcs, ref update_fail_malformed_htlcs, ref commitment_signed } } => { + log_trace!(self, "Handling UpdateHTLCs event in peer_handler for node {} with {} adds, {} fulfills, {} fails for channel {}", + log_pubkey!(node_id), + update_add_htlcs.len(), + update_fulfill_htlcs.len(), + update_fail_htlcs.len(), + log_bytes!(commitment_signed.channel_id)); let (mut descriptor, peer) = get_peer_for_forwarding!(node_id, { //TODO: Do whatever we're gonna do for handling dropped messages }); - for msg in msgs { + for msg in update_add_htlcs { peer.pending_outbound_buffer.push_back(peer.channel_encryptor.encrypt_message(&encode_msg!(msg, 128))); } - peer.pending_outbound_buffer.push_back(peer.channel_encryptor.encrypt_message(&encode_msg!(commitment_msg, 132))); - Self::do_attempt_write_data(&mut descriptor, peer); - continue; - }, - Event::SendFulfillHTLC { ref node_id, ref msg, ref commitment_msg } => { - 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, 130))); - peer.pending_outbound_buffer.push_back(peer.channel_encryptor.encrypt_message(&encode_msg!(commitment_msg, 132))); - Self::do_attempt_write_data(&mut descriptor, peer); - continue; - }, - Event::SendFailHTLC { ref node_id, ref msg, ref commitment_msg } => { - 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, 131))); - peer.pending_outbound_buffer.push_back(peer.channel_encryptor.encrypt_message(&encode_msg!(commitment_msg, 132))); + for msg in update_fulfill_htlcs { + peer.pending_outbound_buffer.push_back(peer.channel_encryptor.encrypt_message(&encode_msg!(msg, 130))); + } + for msg in update_fail_htlcs { + peer.pending_outbound_buffer.push_back(peer.channel_encryptor.encrypt_message(&encode_msg!(msg, 131))); + } + for msg in update_fail_malformed_htlcs { + peer.pending_outbound_buffer.push_back(peer.channel_encryptor.encrypt_message(&encode_msg!(msg, 135))); + } + peer.pending_outbound_buffer.push_back(peer.channel_encryptor.encrypt_message(&encode_msg!(commitment_signed, 132))); Self::do_attempt_write_data(&mut descriptor, peer); 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,12 +735,13 @@ 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); for (ref descriptor, ref mut peer) in peers.peers.iter_mut() { - if !peer.channel_encryptor.is_ready_for_encryption() { + if !peer.channel_encryptor.is_ready_for_encryption() || peer.their_global_features.is_none() { continue } match peer.their_node_id { @@ -721,11 +760,12 @@ 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); for (ref descriptor, ref mut peer) in peers.peers.iter_mut() { - if !peer.channel_encryptor.is_ready_for_encryption() { + if !peer.channel_encryptor.is_ready_for_encryption() || peer.their_global_features.is_none() { continue } peer.pending_outbound_buffer.push_back(peer.channel_encryptor.encrypt_message(&encoded_msg[..])); @@ -734,21 +774,47 @@ impl PeerManager { } continue; }, - Event::DisconnectPeer { ref node_id, ref msg } => { - 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 { + Event::HandleError { ref node_id, ref action } => { + if let Some(ref action) = *action { + match *action { + msgs::ErrorAction::DisconnectPeer { ref msg } => { + 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(); + self.message_handler.chan_handler.peer_disconnected(&node_id, false); + } + }, + msgs::ErrorAction::IgnoreError => { + 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))); - // 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); - } + Self::do_attempt_write_data(&mut descriptor, peer); + }, } - descriptor.disconnect_socket(); - self.message_handler.chan_handler.peer_disconnected(&node_id, false); + } 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; - }, + } } upstream_events.push(event); @@ -799,8 +865,10 @@ impl EventsProvider for PeerManager { #[cfg(test)] mod tests { use ln::peer_handler::{PeerManager, MessageHandler, SocketDescriptor}; + use ln::msgs; use util::events; use util::test_utils; + use util::logger::Logger; use secp256k1::Secp256k1; use secp256k1::key::{SecretKey, PublicKey}; @@ -827,6 +895,7 @@ mod tests { let secp_ctx = Secp256k1::new(); let mut peers = Vec::new(); let mut rng = thread_rng(); + let logger : Arc = Arc::new(test_utils::TestLogger::new()); for _ in 0..peer_count { let chan_handler = test_utils::TestChannelMessageHandler::new(); @@ -837,7 +906,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); } @@ -846,7 +915,7 @@ mod tests { fn establish_connection(peer_a: &PeerManager, peer_b: &PeerManager) { let secp_ctx = Secp256k1::new(); - let their_id = PublicKey::from_secret_key(&secp_ctx, &peer_b.our_node_secret).unwrap(); + let their_id = PublicKey::from_secret_key(&secp_ctx, &peer_b.our_node_secret); let fd = FileDescriptor { fd: 1}; peer_a.new_inbound_connection(fd.clone()).unwrap(); peer_a.peers.lock().unwrap().node_id_to_descriptor.insert(their_id, fd.clone()); @@ -861,12 +930,12 @@ mod tests { assert_eq!(peers[0].peers.lock().unwrap().peers.len(), 1); let secp_ctx = Secp256k1::new(); - let their_id = PublicKey::from_secret_key(&secp_ctx, &peers[1].our_node_secret).unwrap(); + let their_id = PublicKey::from_secret_key(&secp_ctx, &peers[1].our_node_secret); let chan_handler = test_utils::TestChannelMessageHandler::new(); - chan_handler.pending_events.lock().unwrap().push(events::Event::DisconnectPeer { + chan_handler.pending_events.lock().unwrap().push(events::Event::HandleError { node_id: their_id, - msg: None, + action: Some(msgs::ErrorAction::DisconnectPeer { msg: None }), }); assert_eq!(chan_handler.pending_events.lock().unwrap().len(), 1); peers[0].message_handler.chan_handler = Arc::new(chan_handler);