From 00758d3146da84f58fda1ff33c679e3fad23e948 Mon Sep 17 00:00:00 2001
From: Christien Rioux <chris@veilid.org>
Date: Tue, 26 Mar 2024 13:06:00 -0500
Subject: [PATCH] clean up rpc logging

---
 veilid-core/src/rpc_processor/mod.rs          | 33 ++++++++++++++-----
 .../src/rpc_processor/operation_waiter.rs     |  2 +-
 veilid-core/src/rpc_processor/rpc_error.rs    | 15 +++++++++
 3 files changed, 41 insertions(+), 9 deletions(-)

diff --git a/veilid-core/src/rpc_processor/mod.rs b/veilid-core/src/rpc_processor/mod.rs
index c32ba413..bbfa4e1d 100644
--- a/veilid-core/src/rpc_processor/mod.rs
+++ b/veilid-core/src/rpc_processor/mod.rs
@@ -1423,7 +1423,7 @@ impl RPCProcessor {
     /// Decoding RPC from the wire
     /// This performs a capnp decode on the data, and if it passes the capnp schema
     /// it performs the cryptographic validation required to pass the operation up for processing
-    #[instrument(skip_all, err)]
+    #[instrument(skip_all)]
     fn decode_rpc_operation(
         &self,
         encoded_msg: &RPCMessageEncoded,
@@ -1492,15 +1492,29 @@ impl RPCProcessor {
                 let sender_node_id = detail.envelope.get_sender_typed_id();
 
                 // Decode and validate the RPC operation
-                let operation = match self.decode_rpc_operation(&encoded_msg) {
+                let decode_res = self.decode_rpc_operation(&encoded_msg);
+                let operation = match decode_res {
                     Ok(v) => v,
                     Err(e) => {
-                        // Punish nodes that send direct undecodable crap
-                        if matches!(e, RPCError::Protocol(_) | RPCError::InvalidFormat(_)) {
-                            address_filter.punish_node_id(sender_node_id);
-                        }
+                        match e {
+                            // Invalid messages that should be punished
+                            RPCError::Protocol(_) | RPCError::InvalidFormat(_) => {
+                                log_rpc!(debug "Invalid RPC Operation: {}", e);
+
+                                // Punish nodes that send direct undecodable crap
+                                address_filter.punish_node_id(sender_node_id);
+                            },
+                            // Ignored messages that should be dropped
+                            RPCError::Ignore(_) | RPCError::Network(_) | RPCError::TryAgain(_) => {
+                                log_rpc!(debug "Dropping RPC Operation: {}", e);
+                            },
+                            // Internal errors that deserve louder logging
+                            RPCError::Unimplemented(_) | RPCError::Internal(_) => {
+                                log_rpc!(error "Error decoding RPC operation: {}", e);
+                            }
+                        };
                         return Ok(NetworkResult::invalid_message(e));
-                    }
+                    },
                 };
 
                 // Get the routing domain this message came over
@@ -1572,7 +1586,10 @@ impl RPCProcessor {
                 let operation = match self.decode_rpc_operation(&encoded_msg) {
                     Ok(v) => v,
                     Err(e) => {
-                        // Punish routes that send routed undecodable crap
+                        // Debug on error
+                        log_rpc!(debug "Dropping RPC operation: {}", e);
+
+                        // XXX: Punish routes that send routed undecodable crap
                         // address_filter.punish_route_id(xxx);
                         return Ok(NetworkResult::invalid_message(e));
                     }
diff --git a/veilid-core/src/rpc_processor/operation_waiter.rs b/veilid-core/src/rpc_processor/operation_waiter.rs
index 3a2e38ed..3c8ab352 100644
--- a/veilid-core/src/rpc_processor/operation_waiter.rs
+++ b/veilid-core/src/rpc_processor/operation_waiter.rs
@@ -116,7 +116,7 @@ where
     pub fn get_op_context(&self, op_id: OperationId) -> Result<C, RPCError> {
         let inner = self.inner.lock();
         let Some(waiting_op) = inner.waiting_op_table.get(&op_id) else {
-            return Err(RPCError::internal("Missing operation id getting op context"));
+            return Err(RPCError::ignore("Missing operation id getting op context"));
         };
         Ok(waiting_op.context.clone())
     }
diff --git a/veilid-core/src/rpc_processor/rpc_error.rs b/veilid-core/src/rpc_processor/rpc_error.rs
index dc339fb7..93ddaa34 100644
--- a/veilid-core/src/rpc_processor/rpc_error.rs
+++ b/veilid-core/src/rpc_processor/rpc_error.rs
@@ -15,6 +15,8 @@ pub enum RPCError {
     Network(String),
     #[error("[RPCError: TryAgain({0})]")]
     TryAgain(String),
+    #[error("[RPCError: Ignore({0})]")]
+    Ignore(String),
 }
 
 impl RPCError {
@@ -48,6 +50,18 @@ impl RPCError {
     pub fn map_network<M: ToString, X: ToString>(message: M) -> impl FnOnce(X) -> Self {
         move |x| Self::Network(format!("{}: {}", message.to_string(), x.to_string()))
     }
+    pub fn try_again<X: ToString>(x: X) -> Self {
+        Self::TryAgain(x.to_string())
+    }
+    pub fn map_try_again<M: ToString, X: ToString>(message: M) -> impl FnOnce(X) -> Self {
+        move |x| Self::TryAgain(format!("{}: {}", message.to_string(), x.to_string()))
+    }
+    pub fn ignore<X: ToString>(x: X) -> Self {
+        Self::Ignore(x.to_string())
+    }
+    pub fn map_ignore<M: ToString, X: ToString>(message: M) -> impl FnOnce(X) -> Self {
+        move |x| Self::Ignore(format!("{}: {}", message.to_string(), x.to_string()))
+    }
 }
 
 impl From<RPCError> for VeilidAPIError {
@@ -59,6 +73,7 @@ impl From<RPCError> for VeilidAPIError {
             RPCError::Internal(message) => VeilidAPIError::Internal { message },
             RPCError::Network(message) => VeilidAPIError::Generic { message },
             RPCError::TryAgain(message) => VeilidAPIError::TryAgain { message },
+            RPCError::Ignore(message) => VeilidAPIError::Generic { message },
         }
     }
 }