From c55753d5bdd64f6f38cf08f5d8b7a8f4d5d1a0bf Mon Sep 17 00:00:00 2001 From: teor Date: Thu, 9 Dec 2021 11:09:23 +1000 Subject: [PATCH] Add debug-level Zebra network message tracing (#3170) * Add debug-level Zebra network message tracing * Delete redundant spaces Co-authored-by: Alfredo Garcia Co-authored-by: Alfredo Garcia --- zebra-network/src/peer/connection.rs | 24 +++++- .../src/protocol/external/message.rs | 78 +++++++++++++------ 2 files changed, 76 insertions(+), 26 deletions(-) diff --git a/zebra-network/src/peer/connection.rs b/zebra-network/src/peer/connection.rs index e7ce38fb..3d4786c7 100644 --- a/zebra-network/src/peer/connection.rs +++ b/zebra-network/src/peer/connection.rs @@ -110,6 +110,8 @@ impl Handler { // XXX can this be avoided? let tmp_state = std::mem::replace(self, Handler::Finished(Ok(Response::Nil))); + debug!(handler = %tmp_state, %msg, "received peer response to Zebra request"); + *self = match (tmp_state, msg) { (Handler::Ping(req_nonce), Message::Pong(rsp_nonce)) => { if req_nonce == rsp_nonce { @@ -311,6 +313,10 @@ impl Handler { Handler::Finished(Err(PeerError::NotFound(items))) } } + + // TODO: + // - add NotFound cases for blocks, transactions, and headers (#2726) + // - use `any(inv)` rather than `all(inv)`? (Handler::FindBlocks, Message::Inv(items)) if items .iter() @@ -533,6 +539,12 @@ where tx, .. } => { + if let Ok(response) = response.as_ref() { + debug!(%response, "finished receiving peer response to Zebra request"); + } else { + debug!(error = ?response, "error in peer response to Zebra request"); + } + let _ = tx.send(response.map_err(Into::into)); State::AwaitingRequest } @@ -693,10 +705,12 @@ where if tx.is_canceled() { metrics::counter!("peer.canceled", 1); - tracing::debug!("ignoring canceled request"); + debug!(state = %self.state, %request, "ignoring canceled request"); return; } + debug!(state = %self.state, %request, "sending request from Zebra to peer"); + // These matches return a Result with (new_state, Option) or an (error, Sender) let new_state_result = match (&self.state, request) { (Failed, request) => panic!( @@ -884,6 +898,8 @@ where #[instrument(name = "msg_as_req", skip(self, msg), fields(%msg))] async fn handle_message_as_request(&mut self, msg: Message) { trace!(?msg); + debug!(state = %self.state, %msg, "received peer request to Zebra"); + let req = match msg { Message::Ping(nonce) => { trace!(?nonce, "responding to heartbeat"); @@ -1031,7 +1047,7 @@ where return; } - let rsp = match self.svc.call(req).await { + let rsp = match self.svc.call(req.clone()).await { Err(e) => { if e.is::() { tracing::warn!("inbound service is overloaded, closing connection"); @@ -1052,7 +1068,7 @@ where Ok(rsp) => rsp, }; - match rsp { + match rsp.clone() { Response::Nil => { /* generic success, do nothing */ } Response::Peers(addrs) => { if let Err(e) = self.peer_tx.send(Message::Addr(addrs)).await { @@ -1101,6 +1117,8 @@ where } } } + + debug!(state = %self.state, %req, %rsp, "sent Zebra response to peer"); } } diff --git a/zebra-network/src/protocol/external/message.rs b/zebra-network/src/protocol/external/message.rs index 89a2ea6c..1f046ca2 100644 --- a/zebra-network/src/protocol/external/message.rs +++ b/zebra-network/src/protocol/external/message.rs @@ -84,6 +84,11 @@ pub enum Message { /// Whether the remote peer should announce relayed /// transactions or not, see [BIP 0037](https://github.com/bitcoin/bips/blob/master/bip-0037.mediawiki) + /// + /// Zebra does not implement the bloom filters in BIP 0037. + /// Instead, it only relays: + /// - newly verified best chain block hashes and mempool transaction IDs, + /// - after it reaches the chain tip. relay: bool, }, @@ -127,9 +132,6 @@ pub enum Message { // Currently, all errors which provide this field fill it with // the TXID or block header hash of the object being rejected, // so the field is 32 bytes. - // - // Q: can we tell Rust that this field is optional? Or just - // default its value to an empty array, I guess. data: Option<[u8; 32]>, }, @@ -371,26 +373,56 @@ pub enum RejectReason { impl fmt::Display for Message { fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { - f.write_str(match self { - Message::Version { .. } => "version", - Message::Verack => "verack", - Message::Ping(_) => "ping", - Message::Pong(_) => "pong", - Message::Reject { .. } => "reject", - Message::GetAddr => "getaddr", - Message::Addr(_) => "addr", - Message::GetBlocks { .. } => "getblocks", - Message::Inv(_) => "inv", - Message::GetHeaders { .. } => "getheaders", - Message::Headers(_) => "headers", - Message::GetData(_) => "getdata", - Message::Block(_) => "block", - Message::Tx(_) => "tx", - Message::NotFound(_) => "notfound", - Message::Mempool => "mempool", - Message::FilterLoad { .. } => "filterload", - Message::FilterAdd { .. } => "filteradd", - Message::FilterClear => "filterclear", + f.write_str(&match self { + Message::Version { + version, + address_recv, + address_from, + user_agent, + .. + } => format!( + "version {{ network: {}, recv: {},_from: {}, user_agent: {:?} }}", + version, + address_recv.addr(), + address_from.addr(), + user_agent, + ), + Message::Verack => "verack".to_string(), + Message::Ping(_) => "ping".to_string(), + Message::Pong(_) => "pong".to_string(), + Message::Reject { + message, + reason, + data, + .. + } => format!( + "reject {{ message: {:?}, reason: {:?}, data: {} }}", + message, + reason, + if data.is_some() { "Some" } else { "None" }, + ), + Message::GetAddr => "getaddr".to_string(), + Message::Addr(addrs) => format!("addr {{ addrs: {} }}", addrs.len()), + Message::GetBlocks { known_blocks, stop } => format!( + "getblocks {{ known_blocks: {}, stop: {} }}", + known_blocks.len(), + if stop.is_some() { "Some" } else { "None" }, + ), + Message::Inv(invs) => format!("inv {{ invs: {} }}", invs.len()), + Message::GetHeaders { known_blocks, stop } => format!( + "getheaders {{ known_blocks: {}, stop: {} }}", + known_blocks.len(), + if stop.is_some() { "Some" } else { "None" }, + ), + Message::Headers(headers) => format!("headers {{ headers: {} }}", headers.len()), + Message::GetData(invs) => format!("getdata {{ invs: {} }}", invs.len()), + Message::Block(_) => "block".to_string(), + Message::Tx(_) => "tx".to_string(), + Message::NotFound(invs) => format!("notfound {{ invs: {} }}", invs.len()), + Message::Mempool => "mempool".to_string(), + Message::FilterLoad { .. } => "filterload".to_string(), + Message::FilterAdd { .. } => "filteradd".to_string(), + Message::FilterClear => "filterclear".to_string(), }) } }