mirrors/rust-lightning
1
0
Fork 0
mirror of https://github.com/lightningdevkit/rust-lightning.git synced 2025-02-24 23:08:36 +01:00
Code Issues Projects Releases Packages Wiki Activity

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

Browse source 
Add some trace logging in peer_handler
This commit is contained in:
Matt Corallo 2018-08-16 23:35:09 -04:00 • committed by GitHub
commit 03c6f84aa8
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
7 changed files with 104 additions and 21 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
fuzz/fuzz_targets/channel_target.rs
View file

@ -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) => {

2
fuzz/fuzz_targets/full_stack_target.rs
View file

@ -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{});

2
fuzz/fuzz_targets/router_target.rs
View file

@ -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));

17
fuzz/fuzz_targets/utils/test_logger.rs
View file

@ -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) {

48
src/ln/peer_handler.rs
View file

@ -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,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
});
@ -771,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;
}

52
src/util/macro_logger.rs
View file

@ -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)+) => (

2
src/util/test_utils.rs
View file

@ -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) {