debugging

veilid-core/src/routing_table/node_ref.rs

@@ -274,8 +274,17 @@ impl Eq for NodeRef {}
 
 impl fmt::Debug for NodeRef {
     fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        if f.alternate() {
+            write!(
+                f,
+                "{{\n  id: {}\n  filter: {:?}\n}}",
+                self.node_id.encode(),
+                self.filter
+            )
+        } else {
             write!(f, "{}", self.node_id.encode())
         }
+    }
 }
 
 impl Drop for NodeRef {

veilid-core/src/rpc_processor/coders/private_safety_route.rs

@@ -24,6 +24,22 @@ pub struct PrivateRoute {
     pub hops: Option<RouteHop>,
 }
 
+impl fmt::Display for PrivateRoute {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        write!(
+            f,
+            "PR({:?}+{}{})",
+            self.public_key,
+            self.hop_count,
+            if let Some(hops) = &self.hops {
+                format!("->{}", hops.dial_info)
+            } else {
+                "".to_owned()
+            }
+        )
+    }
+}
+
 #[derive(Clone, Debug)]
 pub enum SafetyRouteHops {
     Data(RouteHopData),
@@ -37,6 +53,20 @@ pub struct SafetyRoute {
     pub hops: SafetyRouteHops,
 }
 
+impl fmt::Display for SafetyRoute {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        write!(
+            f,
+            "SR({:?}+{}{})",
+            self.public_key,
+            self.hop_count,
+            match &self.hops {
+                SafetyRouteHops::Data(_) => "".to_owned(),
+                SafetyRouteHops::Private(p) => format!("->{}", p),
+            }
+        )
+    }
+}
 ////////////////////////////////////////////////////////////////////////////////////////////////////
 
 pub fn encode_route_hop_data(

veilid-core/src/rpc_processor/debug.rs

@@ -88,95 +88,6 @@ macro_rules! map_error_panic {
 }
 
 impl RPCProcessor {
-    #[allow(dead_code)]
-    pub(super) fn get_rpc_request_debug_info<T: capnp::message::ReaderSegments>(
-        &self,
-        dest: &Destination,
-        message: &capnp::message::Reader<T>,
-        safety_route_spec: &Option<&SafetyRouteSpec>,
-    ) -> String {
-        format!(
-            "REQ->{:?}{} {}",
-            dest,
-            match safety_route_spec {
-                None => "".to_owned(),
-                Some(srs) => format!("[{:?}]", srs),
-            },
-            self.get_rpc_message_debug_info(message)
-        )
-    }
-    #[allow(dead_code)]
-    pub(super) fn get_rpc_reply_debug_info<T: capnp::message::ReaderSegments>(
-        &self,
-        request_rpcreader: &RPCMessageReader,
-        reply_msg: &capnp::message::Reader<T>,
-        safety_route_spec: &Option<&SafetyRouteSpec>,
-    ) -> String {
-        let request_operation = match request_rpcreader
-            .reader
-            .get_root::<veilid_capnp::operation::Reader>()
-        {
-            Ok(v) => v,
-            Err(e) => {
-                return format!("invalid operation: {}", e);
-            }
-        };
-
-        let respond_to = match request_operation.get_respond_to().which() {
-            Ok(v) => v,
-            Err(e) => {
-                return format!("(respond_to not in schema: {:?})", e);
-            }
-        };
-        let respond_to_str = match respond_to {
-            veilid_capnp::operation::respond_to::None(_) => "(None)".to_owned(),
-            veilid_capnp::operation::respond_to::Sender(_) => "Sender".to_owned(),
-            veilid_capnp::operation::respond_to::SenderWithInfo(sni) => {
-                let sni_reader = match sni {
-                    Ok(snir) => snir,
-                    Err(e) => {
-                        return e.to_string();
-                    }
-                };
-                let signed_node_info = match decode_signed_node_info(
-                    &sni_reader,
-                    &request_rpcreader.header.envelope.get_sender_id(),
-                    true,
-                ) {
-                    Ok(ni) => ni,
-                    Err(e) => {
-                        return e.to_string();
-                    }
-                };
-                format!("Sender({:?})", signed_node_info)
-            }
-            veilid_capnp::operation::respond_to::PrivateRoute(pr) => {
-                let pr_reader = match pr {
-                    Ok(prr) => prr,
-                    Err(e) => {
-                        return e.to_string();
-                    }
-                };
-                let private_route = match decode_private_route(&pr_reader) {
-                    Ok(pr) => pr,
-                    Err(e) => {
-                        return e.to_string();
-                    }
-                };
-                format!("[PR:{:?}]", private_route)
-            }
-        };
-        format!(
-            "REPLY->{:?}{} {}",
-            respond_to_str,
-            match safety_route_spec {
-                None => "".to_owned(),
-                Some(srs) => format!("[SR:{:?}]", srs),
-            },
-            self.get_rpc_message_debug_info(reply_msg)
-        )
-    }
-
     pub(super) fn get_rpc_message_debug_info<T: capnp::message::ReaderSegments>(
         &self,
         message: &capnp::message::Reader<T>,
@@ -201,130 +112,37 @@ impl RPCProcessor {
         )
     }
 
-    #[allow(clippy::useless_format)]
     pub(super) fn get_rpc_operation_detail_debug_info(
         &self,
         detail: &veilid_capnp::operation::detail::WhichReader,
     ) -> String {
         match detail {
-            veilid_capnp::operation::detail::StatusQ(_) => {
+            veilid_capnp::operation::detail::StatusQ(_) => "StatusQ".to_owned(),
-                format!("StatusQ")
+            veilid_capnp::operation::detail::StatusA(_) => "StatusA".to_owned(),
-            }
+            veilid_capnp::operation::detail::ValidateDialInfo(_) => "ValidateDialInfo".to_owned(),
-            veilid_capnp::operation::detail::StatusA(_) => {
+            veilid_capnp::operation::detail::FindNodeQ(_) => "FindNodeQ".to_owned(),
-                format!("StatusA")
+            veilid_capnp::operation::detail::FindNodeA(_) => "FindNodeA".to_owned(),
-            }
+            veilid_capnp::operation::detail::Route(_) => "Route".to_owned(),
-            veilid_capnp::operation::detail::ValidateDialInfo(_) => {
+            veilid_capnp::operation::detail::NodeInfoUpdate(_) => "NodeInfoUpdate".to_owned(),
-                format!("ValidateDialInfo")
+            veilid_capnp::operation::detail::GetValueQ(_) => "GetValueQ".to_owned(),
-            }
+            veilid_capnp::operation::detail::GetValueA(_) => "GetValueA".to_owned(),
-            veilid_capnp::operation::detail::FindNodeQ(d) => {
+            veilid_capnp::operation::detail::SetValueQ(_) => "SetValueQ".to_owned(),
-                let fnqr = match d {
+            veilid_capnp::operation::detail::SetValueA(_) => "SetValueA".to_owned(),
-                    Ok(fnqr) => fnqr,
+            veilid_capnp::operation::detail::WatchValueQ(_) => "WatchValueQ".to_owned(),
-                    Err(e) => {
+            veilid_capnp::operation::detail::WatchValueA(_) => "WatchValueA".to_owned(),
-                        return format!("(invalid detail: {})", e);
+            veilid_capnp::operation::detail::ValueChanged(_) => "ValueChanged".to_owned(),
-                    }
+            veilid_capnp::operation::detail::SupplyBlockQ(_) => "SupplyBlockQ".to_owned(),
-                };
+            veilid_capnp::operation::detail::SupplyBlockA(_) => "SupplyBlockA".to_owned(),
-                let nidr = match fnqr.get_node_id() {
+            veilid_capnp::operation::detail::FindBlockQ(_) => "FindBlockQ".to_owned(),
-                    Ok(nidr) => nidr,
+            veilid_capnp::operation::detail::FindBlockA(_) => "FindBlockA".to_owned(),
-                    Err(e) => {
+            veilid_capnp::operation::detail::Signal(_) => "Signal".to_owned(),
-                        return format!("(invalid node id: {})", e);
+            veilid_capnp::operation::detail::ReturnReceipt(_) => "ReturnReceipt".to_owned(),
-                    }
+            veilid_capnp::operation::detail::StartTunnelQ(_) => "StartTunnelQ".to_owned(),
-                };
+            veilid_capnp::operation::detail::StartTunnelA(_) => "StartTunnelA".to_owned(),
-                let node_id = decode_public_key(&nidr);
+            veilid_capnp::operation::detail::CompleteTunnelQ(_) => "CompleteTunnelQ".to_owned(),
-                format!("FindNodeQ: node_id={}", node_id.encode(),)
+            veilid_capnp::operation::detail::CompleteTunnelA(_) => "CompleteTunnelA".to_owned(),
-            }
+            veilid_capnp::operation::detail::CancelTunnelQ(_) => "CancelTunnelQ".to_owned(),
-            veilid_capnp::operation::detail::FindNodeA(d) => {
+            veilid_capnp::operation::detail::CancelTunnelA(_) => "CancelTunnelA".to_owned(),
-                let fnar = match d {
-                    Ok(fnar) => fnar,
-                    Err(e) => {
-                        return format!("(invalid detail: {})", e);
-                    }
-                };
-
-                let p_reader = match fnar.reborrow().get_peers() {
-                    Ok(pr) => pr,
-                    Err(e) => {
-                        return format!("(invalid peers: {})", e);
-                    }
-                };
-                let mut peers = Vec::<PeerInfo>::with_capacity(match p_reader.len().try_into() {
-                    Ok(v) => v,
-                    Err(e) => return format!("invalid peer count: {}", e),
-                });
-                for p in p_reader.iter() {
-                    let peer_info = match decode_peer_info(&p, true) {
-                        Ok(v) => v,
-                        Err(e) => {
-                            return format!("(unable to decode peer info: {})", e);
-                        }
-                    };
-                    peers.push(peer_info);
-                }
-
-                format!("FindNodeA: peers={:#?}", peers)
-            }
-            veilid_capnp::operation::detail::Route(_) => {
-                format!("Route")
-            }
-            veilid_capnp::operation::detail::NodeInfoUpdate(_) => {
-                format!("NodeInfoUpdate")
-            }
-            veilid_capnp::operation::detail::GetValueQ(_) => {
-                format!("GetValueQ")
-            }
-            veilid_capnp::operation::detail::GetValueA(_) => {
-                format!("GetValueA")
-            }
-            veilid_capnp::operation::detail::SetValueQ(_) => {
-                format!("SetValueQ")
-            }
-            veilid_capnp::operation::detail::SetValueA(_) => {
-                format!("SetValueA")
-            }
-            veilid_capnp::operation::detail::WatchValueQ(_) => {
-                format!("WatchValueQ")
-            }
-            veilid_capnp::operation::detail::WatchValueA(_) => {
-                format!("WatchValueA")
-            }
-            veilid_capnp::operation::detail::ValueChanged(_) => {
-                format!("ValueChanged")
-            }
-            veilid_capnp::operation::detail::SupplyBlockQ(_) => {
-                format!("SupplyBlockQ")
-            }
-            veilid_capnp::operation::detail::SupplyBlockA(_) => {
-                format!("SupplyBlockA")
-            }
-            veilid_capnp::operation::detail::FindBlockQ(_) => {
-                format!("FindBlockQ")
-            }
-            veilid_capnp::operation::detail::FindBlockA(_) => {
-                format!("FindBlockA")
-            }
-            veilid_capnp::operation::detail::Signal(_) => {
-                format!("Signal")
-            }
-            veilid_capnp::operation::detail::ReturnReceipt(_) => {
-                format!("ReturnReceipt")
-            }
-            veilid_capnp::operation::detail::StartTunnelQ(_) => {
-                format!("StartTunnelQ")
-            }
-            veilid_capnp::operation::detail::StartTunnelA(_) => {
-                format!("StartTunnelA")
-            }
-            veilid_capnp::operation::detail::CompleteTunnelQ(_) => {
-                format!("CompleteTunnelQ")
-            }
-            veilid_capnp::operation::detail::CompleteTunnelA(_) => {
-                format!("CompleteTunnelA")
-            }
-            veilid_capnp::operation::detail::CancelTunnelQ(_) => {
-                format!("CancelTunnelQ")
-            }
-            veilid_capnp::operation::detail::CancelTunnelA(_) => {
-                format!("CancelTunnelA")
-            }
         }
     }
 }

veilid-core/src/rpc_processor/mod.rs

@@ -23,9 +23,25 @@ type OperationId = u64;
 
 #[derive(Debug, Clone)]
 pub enum Destination {
-    Direct(NodeRef),            // Send to node
+    Direct(NodeRef),            // Send to node (target noderef)
-    Relay(NodeRef, DHTKey),     // Send to node for relay purposes
+    Relay(NodeRef, DHTKey),     // Send to node for relay purposes (relay noderef, target nodeid)
-    PrivateRoute(PrivateRoute), // Send to private route
+    PrivateRoute(PrivateRoute), // Send to private route (privateroute)
+}
+
+impl fmt::Display for Destination {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        match self {
+            Destination::Direct(nr) => {
+                write!(f, "{:?}", nr)
+            }
+            Destination::Relay(nr, key) => {
+                write!(f, "{:?}@{:?}", key.encode(), nr)
+            }
+            Destination::PrivateRoute(pr) => {
+                write!(f, "{}", pr)
+            }
+        }
+    }
 }
 
 #[derive(Debug, Clone)]
@@ -106,7 +122,7 @@ where
         .map_err(logthru_rpc!())?;
     Ok(capnp::Word::words_to_bytes(wordvec.as_slice()).to_vec())
 }
-fn reader_to_vec<'a, T>(reader: capnp::message::Reader<T>) -> Result<Vec<u8>, RPCError>
+fn reader_to_vec<'a, T>(reader: &capnp::message::Reader<T>) -> Result<Vec<u8>, RPCError>
 where
     T: capnp::message::ReaderSegments + 'a,
 {
@@ -392,7 +408,6 @@ impl RPCProcessor {
         message: capnp::message::Reader<T>,
         safety_route_spec: Option<&SafetyRouteSpec>,
     ) -> Result<Option<WaitableReply>, RPCError> {
-        //log_rpc!(self.get_rpc_request_debug_info(&dest, &message, &safety_route_spec));
 
         let (op_id, wants_answer) = {
             let operation = message
@@ -432,7 +447,7 @@ impl RPCProcessor {
                         None => {
                             // If no safety route is being used, and we're not sending to a private
                             // route, we can use a direct envelope instead of routing
-                            out = reader_to_vec(message)?;
+                            out = reader_to_vec(&message)?;
 
                             // Message goes directly to the node
                             out_node_id = node_id;
@@ -446,7 +461,7 @@ impl RPCProcessor {
                             let private_route =
                                 self.new_stub_private_route(node_id, &mut pr_builder)?;
 
-                            let message_vec = reader_to_vec(message)?;
+                            let message_vec = reader_to_vec(&message)?;
                             // first
                             out_node_id = sr
                                 .hops
@@ -472,7 +487,7 @@ impl RPCProcessor {
                     let pr_reader = pr_builder.into_reader();
 
                     // Reply with 'route' operation
-                    let message_vec = reader_to_vec(message)?;
+                    let message_vec = reader_to_vec(&message)?;
                     out_node_id = match safety_route_spec {
                         None => {
                             // If no safety route, the first node is the first hop of the private route
@@ -534,6 +549,8 @@ impl RPCProcessor {
         };
 
         // send question
+        log_rpc!(debug "==>> REQUEST({}) -> {:?}", self.get_rpc_message_debug_info(&message), dest);
+
         let bytes = out.len() as u64;
         let send_ts = get_timestamp();
         let send_data_kind = match self
@@ -586,8 +603,6 @@ impl RPCProcessor {
         reply_msg: capnp::message::Reader<T>,
         safety_route_spec: Option<&SafetyRouteSpec>,
     ) -> Result<(), RPCError> {
-        // log_rpc!(self.get_rpc_reply_debug_info(&request_rpcreader, &reply_msg, &safety_route_spec));
-
         //
         let out_node_id;
         let mut out_noderef: Option<NodeRef> = None;
@@ -601,7 +616,7 @@ impl RPCProcessor {
                 .map_err(map_error_capnp_error!())
                 .map_err(logthru_rpc!())?;
 
-            let reply_vec = reader_to_vec(reply_msg)?;
+            let reply_vec = reader_to_vec(&reply_msg)?;
 
             // To where should we respond?
             match request_operation
@@ -720,6 +735,14 @@ impl RPCProcessor {
         };
 
         // Send the reply
+        log_rpc!(debug "==>> REPLY({}) -> {}{:?}", 
+            self.get_rpc_message_debug_info(&reply_msg), 
+            if out_node_id == node_ref.node_id() {
+                "".to_owned() 
+            } else {
+                format!("{} via ", out_node_id)
+            }, 
+            node_ref);
         let bytes = out.len() as u64;
         let send_ts = get_timestamp();
         self.network_manager()
@@ -1236,6 +1259,12 @@ impl RPCProcessor {
                 veilid_capnp::operation::detail::CancelTunnelA(_) => (25u32, false),
             };
 
+            log_rpc!(debug "<<== {}({}) <- {}", 
+                if is_q { "REQUEST" } else { "REPLY" }, 
+                self.get_rpc_message_debug_info(&reader), 
+                msg.header.envelope.get_sender_id()
+            );
+
             // Accounting for questions we receive
             if is_q {
                 // See if we have some Sender NodeInfo to incorporate

veilid-core/src/xx/log_thru.rs

@@ -69,6 +69,14 @@ macro_rules! log_rpc {
     (warn $fmt:literal, $($arg:expr),+) => {
         warn!(target:"rpc", $fmt, $($arg),+);
     };
+    (debug $text:expr) => { error!(
+        target: "rpc",
+        "{}",
+        $text,
+    )};
+    (debug $fmt:literal, $($arg:expr),+) => {
+        debug!(target:"rpc", $fmt, $($arg),+);
+    };
     ($text:expr) => {trace!(
         target: "rpc",
         "{}",