Add debug-level Zebra network message tracing (#3170)

* Add debug-level Zebra network message tracing

* Delete redundant spaces

Co-authored-by: Alfredo Garcia <oxarbitrage@gmail.com>

Co-authored-by: Alfredo Garcia <oxarbitrage@gmail.com>

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<Sender>) 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::<Overloaded>() {
                     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");
     }
 }
 

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 {
+        f.write_str(&match self {
-            Message::Version { .. } => "version",
+            Message::Version {
-            Message::Verack => "verack",
+                version,
-            Message::Ping(_) => "ping",
+                address_recv,
-            Message::Pong(_) => "pong",
+                address_from,
-            Message::Reject { .. } => "reject",
+                user_agent,
-            Message::GetAddr => "getaddr",
+                ..
-            Message::Addr(_) => "addr",
+            } => format!(
-            Message::GetBlocks { .. } => "getblocks",
+                "version {{ network: {}, recv: {},_from: {}, user_agent: {:?} }}",
-            Message::Inv(_) => "inv",
+                version,
-            Message::GetHeaders { .. } => "getheaders",
+                address_recv.addr(),
-            Message::Headers(_) => "headers",
+                address_from.addr(),
-            Message::GetData(_) => "getdata",
+                user_agent,
-            Message::Block(_) => "block",
+            ),
-            Message::Tx(_) => "tx",
+            Message::Verack => "verack".to_string(),
-            Message::NotFound(_) => "notfound",
+            Message::Ping(_) => "ping".to_string(),
-            Message::Mempool => "mempool",
+            Message::Pong(_) => "pong".to_string(),
-            Message::FilterLoad { .. } => "filterload",
+            Message::Reject {
-            Message::FilterAdd { .. } => "filteradd",
+                message,
-            Message::FilterClear => "filterclear",
+                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(),
         })
     }
 }