From 7ca202440b1bf72893c8e44d04859c29f1327904 Mon Sep 17 00:00:00 2001 From: John Smith Date: Tue, 24 May 2022 22:46:30 -0400 Subject: [PATCH] debugging --- veilid-core/src/routing_table/node_ref.rs | 11 +- .../coders/private_safety_route.rs | 30 +++ veilid-core/src/rpc_processor/debug.rs | 234 ++---------------- veilid-core/src/rpc_processor/mod.rs | 51 +++- veilid-core/src/xx/log_thru.rs | 8 + 5 files changed, 114 insertions(+), 220 deletions(-) diff --git a/veilid-core/src/routing_table/node_ref.rs b/veilid-core/src/routing_table/node_ref.rs index d7f336fa..0f2b2bcb 100644 --- a/veilid-core/src/routing_table/node_ref.rs +++ b/veilid-core/src/routing_table/node_ref.rs @@ -274,7 +274,16 @@ impl Eq for NodeRef {} impl fmt::Debug for NodeRef { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - write!(f, "{}", self.node_id.encode()) + if f.alternate() { + write!( + f, + "{{\n id: {}\n filter: {:?}\n}}", + self.node_id.encode(), + self.filter + ) + } else { + write!(f, "{}", self.node_id.encode()) + } } } diff --git a/veilid-core/src/rpc_processor/coders/private_safety_route.rs b/veilid-core/src/rpc_processor/coders/private_safety_route.rs index 60e22a71..6920ff75 100644 --- a/veilid-core/src/rpc_processor/coders/private_safety_route.rs +++ b/veilid-core/src/rpc_processor/coders/private_safety_route.rs @@ -24,6 +24,22 @@ pub struct PrivateRoute { pub hops: Option, } +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( diff --git a/veilid-core/src/rpc_processor/debug.rs b/veilid-core/src/rpc_processor/debug.rs index 708226c3..29c4f637 100644 --- a/veilid-core/src/rpc_processor/debug.rs +++ b/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( - &self, - dest: &Destination, - message: &capnp::message::Reader, - 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( - &self, - request_rpcreader: &RPCMessageReader, - reply_msg: &capnp::message::Reader, - safety_route_spec: &Option<&SafetyRouteSpec>, - ) -> String { - let request_operation = match request_rpcreader - .reader - .get_root::() - { - 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( &self, message: &capnp::message::Reader, @@ -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(_) => { - format!("StatusQ") - } - veilid_capnp::operation::detail::StatusA(_) => { - format!("StatusA") - } - veilid_capnp::operation::detail::ValidateDialInfo(_) => { - format!("ValidateDialInfo") - } - veilid_capnp::operation::detail::FindNodeQ(d) => { - let fnqr = match d { - Ok(fnqr) => fnqr, - Err(e) => { - return format!("(invalid detail: {})", e); - } - }; - let nidr = match fnqr.get_node_id() { - Ok(nidr) => nidr, - Err(e) => { - return format!("(invalid node id: {})", e); - } - }; - let node_id = decode_public_key(&nidr); - format!("FindNodeQ: node_id={}", node_id.encode(),) - } - veilid_capnp::operation::detail::FindNodeA(d) => { - 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::::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_capnp::operation::detail::StatusQ(_) => "StatusQ".to_owned(), + veilid_capnp::operation::detail::StatusA(_) => "StatusA".to_owned(), + veilid_capnp::operation::detail::ValidateDialInfo(_) => "ValidateDialInfo".to_owned(), + veilid_capnp::operation::detail::FindNodeQ(_) => "FindNodeQ".to_owned(), + veilid_capnp::operation::detail::FindNodeA(_) => "FindNodeA".to_owned(), + veilid_capnp::operation::detail::Route(_) => "Route".to_owned(), + veilid_capnp::operation::detail::NodeInfoUpdate(_) => "NodeInfoUpdate".to_owned(), + veilid_capnp::operation::detail::GetValueQ(_) => "GetValueQ".to_owned(), + veilid_capnp::operation::detail::GetValueA(_) => "GetValueA".to_owned(), + veilid_capnp::operation::detail::SetValueQ(_) => "SetValueQ".to_owned(), + veilid_capnp::operation::detail::SetValueA(_) => "SetValueA".to_owned(), + veilid_capnp::operation::detail::WatchValueQ(_) => "WatchValueQ".to_owned(), + veilid_capnp::operation::detail::WatchValueA(_) => "WatchValueA".to_owned(), + veilid_capnp::operation::detail::ValueChanged(_) => "ValueChanged".to_owned(), + veilid_capnp::operation::detail::SupplyBlockQ(_) => "SupplyBlockQ".to_owned(), + veilid_capnp::operation::detail::SupplyBlockA(_) => "SupplyBlockA".to_owned(), + veilid_capnp::operation::detail::FindBlockQ(_) => "FindBlockQ".to_owned(), + veilid_capnp::operation::detail::FindBlockA(_) => "FindBlockA".to_owned(), + veilid_capnp::operation::detail::Signal(_) => "Signal".to_owned(), + veilid_capnp::operation::detail::ReturnReceipt(_) => "ReturnReceipt".to_owned(), + veilid_capnp::operation::detail::StartTunnelQ(_) => "StartTunnelQ".to_owned(), + veilid_capnp::operation::detail::StartTunnelA(_) => "StartTunnelA".to_owned(), + veilid_capnp::operation::detail::CompleteTunnelQ(_) => "CompleteTunnelQ".to_owned(), + veilid_capnp::operation::detail::CompleteTunnelA(_) => "CompleteTunnelA".to_owned(), + veilid_capnp::operation::detail::CancelTunnelQ(_) => "CancelTunnelQ".to_owned(), + veilid_capnp::operation::detail::CancelTunnelA(_) => "CancelTunnelA".to_owned(), } } } diff --git a/veilid-core/src/rpc_processor/mod.rs b/veilid-core/src/rpc_processor/mod.rs index 15e21f50..4fbffb45 100644 --- a/veilid-core/src/rpc_processor/mod.rs +++ b/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 - Relay(NodeRef, DHTKey), // Send to node for relay purposes - PrivateRoute(PrivateRoute), // Send to private route + Direct(NodeRef), // Send to node (target noderef) + Relay(NodeRef, DHTKey), // Send to node for relay purposes (relay noderef, target nodeid) + 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) -> Result, RPCError> +fn reader_to_vec<'a, T>(reader: &capnp::message::Reader) -> Result, RPCError> where T: capnp::message::ReaderSegments + 'a, { @@ -392,7 +408,6 @@ impl RPCProcessor { message: capnp::message::Reader, safety_route_spec: Option<&SafetyRouteSpec>, ) -> Result, 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, 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 = 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 diff --git a/veilid-core/src/xx/log_thru.rs b/veilid-core/src/xx/log_thru.rs index 166c966e..feedfcbf 100644 --- a/veilid-core/src/xx/log_thru.rs +++ b/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", "{}",