Merge pull request #2895 from TheBlueMatt/2024-02-logging-tweaks
[rust-lightning] / lightning / src / ln / peer_handler.rs
index 6d46558b188b60c2433f51f002121bad268df60c..8d83763715c83326b61cdf83f2faeec6f721d795 100644 (file)
@@ -24,20 +24,16 @@ use crate::ln::ChannelId;
 use crate::ln::features::{InitFeatures, NodeFeatures};
 use crate::ln::msgs;
 use crate::ln::msgs::{ChannelMessageHandler, LightningError, SocketAddress, OnionMessageHandler, RoutingMessageHandler};
-#[cfg(not(c_bindings))]
-use crate::ln::channelmanager::{SimpleArcChannelManager, SimpleRefChannelManager};
 use crate::util::ser::{VecWriter, Writeable, Writer};
 use crate::ln::peer_channel_encryptor::{PeerChannelEncryptor, NextNoiseStep, MessageBuf, MSG_BUF_ALLOC_SIZE};
 use crate::ln::wire;
 use crate::ln::wire::{Encode, Type};
-#[cfg(not(c_bindings))]
-use crate::onion_message::messenger::{SimpleArcOnionMessenger, SimpleRefOnionMessenger};
 use crate::onion_message::messenger::{CustomOnionMessageHandler, PendingOnionMessage};
 use crate::onion_message::offers::{OffersMessage, OffersMessageHandler};
 use crate::onion_message::packet::OnionMessageContents;
 use crate::routing::gossip::{NodeId, NodeAlias};
 use crate::util::atomic_counter::AtomicCounter;
-use crate::util::logger::{Logger, WithContext};
+use crate::util::logger::{Level, Logger, WithContext};
 use crate::util::string::PrintableString;
 
 use crate::prelude::*;
@@ -52,6 +48,8 @@ use core::convert::Infallible;
 use std::error;
 #[cfg(not(c_bindings))]
 use {
+       crate::ln::channelmanager::{SimpleArcChannelManager, SimpleRefChannelManager},
+       crate::onion_message::messenger::{SimpleArcOnionMessenger, SimpleRefOnionMessenger},
        crate::routing::gossip::{NetworkGraph, P2PGossipSync},
        crate::sign::KeysManager,
        crate::sync::Arc,
@@ -224,10 +222,10 @@ impl ChannelMessageHandler for ErroringMessageHandler {
        // Any messages which are related to a specific channel generate an error message to let the
        // peer know we don't care about channels.
        fn handle_open_channel(&self, their_node_id: &PublicKey, msg: &msgs::OpenChannel) {
-               ErroringMessageHandler::push_error(self, their_node_id, msg.temporary_channel_id);
+               ErroringMessageHandler::push_error(self, their_node_id, msg.common_fields.temporary_channel_id);
        }
        fn handle_accept_channel(&self, their_node_id: &PublicKey, msg: &msgs::AcceptChannel) {
-               ErroringMessageHandler::push_error(self, their_node_id, msg.temporary_channel_id);
+               ErroringMessageHandler::push_error(self, their_node_id, msg.common_fields.temporary_channel_id);
        }
        fn handle_funding_created(&self, their_node_id: &PublicKey, msg: &msgs::FundingCreated) {
                ErroringMessageHandler::push_error(self, their_node_id, msg.temporary_channel_id);
@@ -317,11 +315,11 @@ impl ChannelMessageHandler for ErroringMessageHandler {
        }
 
        fn handle_open_channel_v2(&self, their_node_id: &PublicKey, msg: &msgs::OpenChannelV2) {
-               ErroringMessageHandler::push_error(self, their_node_id, msg.temporary_channel_id);
+               ErroringMessageHandler::push_error(self, their_node_id, msg.common_fields.temporary_channel_id);
        }
 
        fn handle_accept_channel_v2(&self, their_node_id: &PublicKey, msg: &msgs::AcceptChannelV2) {
-               ErroringMessageHandler::push_error(self, their_node_id, msg.temporary_channel_id);
+               ErroringMessageHandler::push_error(self, their_node_id, msg.common_fields.temporary_channel_id);
        }
 
        fn handle_tx_add_input(&self, their_node_id: &PublicKey, msg: &msgs::TxAddInput) {
@@ -946,8 +944,8 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, OM: Deref, L: Deref, CM
 
                PeerManager {
                        message_handler,
-                       peers: FairRwLock::new(HashMap::new()),
-                       node_id_to_descriptor: Mutex::new(HashMap::new()),
+                       peers: FairRwLock::new(new_hash_map()),
+                       node_id_to_descriptor: Mutex::new(new_hash_map()),
                        event_processing_state: AtomicI32::new(0),
                        ephemeral_key_midstate,
                        peer_counter: AtomicCounter::new(),
@@ -1272,7 +1270,7 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, OM: Deref, L: Deref, CM
 
        /// Append a message to a peer's pending outbound/write buffer
        fn enqueue_message<M: wire::Type>(&self, peer: &mut Peer, message: &M) {
-               let logger = WithContext::from(&self.logger, Some(peer.their_node_id.unwrap().0), None);
+               let logger = WithContext::from(&self.logger, peer.their_node_id.map(|p| p.0), None);
                if is_gossip_msg(message.type_id()) {
                        log_gossip!(logger, "Enqueueing message {:?} to {}", message, log_pubkey!(peer.their_node_id.unwrap().0));
                } else {
@@ -1331,7 +1329,9 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, OM: Deref, L: Deref, CM
                                                                                        return Err(PeerHandleError { });
                                                                                },
                                                                                msgs::ErrorAction::IgnoreAndLog(level) => {
-                                                                                       log_given_level!(logger, level, "Error handling message{}; ignoring: {}", OptionalFromDebugger(&peer_node_id), e.err);
+                                                                                       log_given_level!(logger, level, "Error handling {}message{}; ignoring: {}",
+                                                                                               if level == Level::Gossip { "gossip " } else { "" },
+                                                                                               OptionalFromDebugger(&peer_node_id), e.err);
                                                                                        continue
                                                                                },
                                                                                msgs::ErrorAction::IgnoreDuplicateGossip => continue, // Don't even bother logging these
@@ -1377,7 +1377,7 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, OM: Deref, L: Deref, CM
 
                                                macro_rules! insert_node_id {
                                                        () => {
-                                                               let logger = WithContext::from(&self.logger, Some(peer.their_node_id.unwrap().0), None);
+                                                               let logger = WithContext::from(&self.logger, peer.their_node_id.map(|p| p.0), None);
                                                                match self.node_id_to_descriptor.lock().unwrap().entry(peer.their_node_id.unwrap().0) {
                                                                        hash_map::Entry::Occupied(e) => {
                                                                                log_trace!(logger, "Got second connection with {}, closing", log_pubkey!(peer.their_node_id.unwrap().0));
@@ -1457,7 +1457,7 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, OM: Deref, L: Deref, CM
                                                                        peer.pending_read_buffer.resize(18, 0);
                                                                        peer.pending_read_is_header = true;
 
-                                                                       let logger = WithContext::from(&self.logger, Some(peer.their_node_id.unwrap().0), None);
+                                                                       let logger = WithContext::from(&self.logger, peer.their_node_id.map(|p| p.0), None);
                                                                        let message = match message_result {
                                                                                Ok(x) => x,
                                                                                Err(e) => {
@@ -1835,13 +1835,13 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, OM: Deref, L: Deref, CM
 
                                for (_, peer_mutex) in peers.iter() {
                                        let mut peer = peer_mutex.lock().unwrap();
-                                       let logger = WithContext::from(&self.logger, Some(peer.their_node_id.unwrap().0), None);
                                        if !peer.handshake_complete() ||
                                                        !peer.should_forward_channel_announcement(msg.contents.short_channel_id) {
                                                continue
                                        }
                                        debug_assert!(peer.their_node_id.is_some());
                                        debug_assert!(peer.channel_encryptor.is_ready_for_encryption());
+                                       let logger = WithContext::from(&self.logger, peer.their_node_id.map(|p| p.0), None);
                                        if peer.buffer_full_drop_gossip_broadcast() {
                                                log_gossip!(logger, "Skipping broadcast message to {:?} as its outbound buffer is full", peer.their_node_id);
                                                continue;
@@ -1863,13 +1863,13 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, OM: Deref, L: Deref, CM
 
                                for (_, peer_mutex) in peers.iter() {
                                        let mut peer = peer_mutex.lock().unwrap();
-                                       let logger = WithContext::from(&self.logger, Some(peer.their_node_id.unwrap().0), None);
                                        if !peer.handshake_complete() ||
                                                        !peer.should_forward_node_announcement(msg.contents.node_id) {
                                                continue
                                        }
                                        debug_assert!(peer.their_node_id.is_some());
                                        debug_assert!(peer.channel_encryptor.is_ready_for_encryption());
+                                       let logger = WithContext::from(&self.logger, peer.their_node_id.map(|p| p.0), None);
                                        if peer.buffer_full_drop_gossip_broadcast() {
                                                log_gossip!(logger, "Skipping broadcast message to {:?} as its outbound buffer is full", peer.their_node_id);
                                                continue;
@@ -1891,13 +1891,13 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, OM: Deref, L: Deref, CM
 
                                for (_, peer_mutex) in peers.iter() {
                                        let mut peer = peer_mutex.lock().unwrap();
-                                       let logger = WithContext::from(&self.logger, Some(peer.their_node_id.unwrap().0), None);
                                        if !peer.handshake_complete() ||
                                                        !peer.should_forward_channel_announcement(msg.contents.short_channel_id)  {
                                                continue
                                        }
                                        debug_assert!(peer.their_node_id.is_some());
                                        debug_assert!(peer.channel_encryptor.is_ready_for_encryption());
+                                       let logger = WithContext::from(&self.logger, peer.their_node_id.map(|p| p.0), None);
                                        if peer.buffer_full_drop_gossip_broadcast() {
                                                log_gossip!(logger, "Skipping broadcast message to {:?} as its outbound buffer is full", peer.their_node_id);
                                                continue;
@@ -1940,7 +1940,7 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, OM: Deref, L: Deref, CM
                        self.update_gossip_backlogged();
                        let flush_read_disabled = self.gossip_processing_backlog_lifted.swap(false, Ordering::Relaxed);
 
-                       let mut peers_to_disconnect = HashMap::new();
+                       let mut peers_to_disconnect = new_hash_map();
 
                        {
                                let peers_lock = self.peers.read().unwrap();
@@ -1981,34 +1981,34 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, OM: Deref, L: Deref, CM
                                for event in events_generated.drain(..) {
                                        match event {
                                                MessageSendEvent::SendAcceptChannel { ref node_id, ref msg } => {
-                                                       log_debug!(WithContext::from(&self.logger, Some(*node_id), Some(msg.temporary_channel_id)), "Handling SendAcceptChannel event in peer_handler for node {} for channel {}",
+                                                       log_debug!(WithContext::from(&self.logger, Some(*node_id), Some(msg.common_fields.temporary_channel_id)), "Handling SendAcceptChannel event in peer_handler for node {} for channel {}",
                                                                        log_pubkey!(node_id),
-                                                                       &msg.temporary_channel_id);
+                                                                       &msg.common_fields.temporary_channel_id);
                                                        self.enqueue_message(&mut *get_peer_for_forwarding!(node_id), msg);
                                                },
                                                MessageSendEvent::SendAcceptChannelV2 { ref node_id, ref msg } => {
-                                                       log_debug!(WithContext::from(&self.logger, Some(*node_id), Some(msg.temporary_channel_id)), "Handling SendAcceptChannelV2 event in peer_handler for node {} for channel {}",
+                                                       log_debug!(WithContext::from(&self.logger, Some(*node_id), Some(msg.common_fields.temporary_channel_id)), "Handling SendAcceptChannelV2 event in peer_handler for node {} for channel {}",
                                                                        log_pubkey!(node_id),
-                                                                       &msg.temporary_channel_id);
+                                                                       &msg.common_fields.temporary_channel_id);
                                                        self.enqueue_message(&mut *get_peer_for_forwarding!(node_id), msg);
                                                },
                                                MessageSendEvent::SendOpenChannel { ref node_id, ref msg } => {
-                                                       log_debug!(WithContext::from(&self.logger, Some(*node_id), Some(msg.temporary_channel_id)), "Handling SendOpenChannel event in peer_handler for node {} for channel {}",
+                                                       log_debug!(WithContext::from(&self.logger, Some(*node_id), Some(msg.common_fields.temporary_channel_id)), "Handling SendOpenChannel event in peer_handler for node {} for channel {}",
                                                                        log_pubkey!(node_id),
-                                                                       &msg.temporary_channel_id);
+                                                                       &msg.common_fields.temporary_channel_id);
                                                        self.enqueue_message(&mut *get_peer_for_forwarding!(node_id), msg);
                                                },
                                                MessageSendEvent::SendOpenChannelV2 { ref node_id, ref msg } => {
-                                                       log_debug!(WithContext::from(&self.logger, Some(*node_id), Some(msg.temporary_channel_id)), "Handling SendOpenChannelV2 event in peer_handler for node {} for channel {}",
+                                                       log_debug!(WithContext::from(&self.logger, Some(*node_id), Some(msg.common_fields.temporary_channel_id)), "Handling SendOpenChannelV2 event in peer_handler for node {} for channel {}",
                                                                        log_pubkey!(node_id),
-                                                                       &msg.temporary_channel_id);
+                                                                       &msg.common_fields.temporary_channel_id);
                                                        self.enqueue_message(&mut *get_peer_for_forwarding!(node_id), msg);
                                                },
                                                MessageSendEvent::SendFundingCreated { ref node_id, ref msg } => {
                                                        log_debug!(WithContext::from(&self.logger, Some(*node_id), Some(msg.temporary_channel_id)), "Handling SendFundingCreated event in peer_handler for node {} for channel {} (which becomes {})",
                                                                        log_pubkey!(node_id),
                                                                        &msg.temporary_channel_id,
-                                                                       log_funding_channel_id!(msg.funding_txid, msg.funding_output_index));
+                                                                       ChannelId::v1_from_funding_txid(msg.funding_txid.as_byte_array(), msg.funding_output_index));
                                                        // TODO: If the peer is gone we should generate a DiscardFunding event
                                                        // indicating to the wallet that they should just throw away this funding transaction
                                                        self.enqueue_message(&mut *get_peer_for_forwarding!(node_id), msg);