From b1df2c9d2d4cb1b39106a23e968e855169d6622e Mon Sep 17 00:00:00 2001 From: John Smith Date: Sat, 24 Jun 2023 20:29:36 -0400 Subject: [PATCH] fix traces --- veilid-core/src/rpc_processor/rpc_app_call.rs | 4 +++- .../src/rpc_processor/rpc_app_message.rs | 2 +- .../src/rpc_processor/rpc_find_node.rs | 2 +- .../src/rpc_processor/rpc_get_value.rs | 16 ++++++++++++++- .../src/rpc_processor/rpc_set_value.rs | 20 +++++++++++++++++++ 5 files changed, 40 insertions(+), 4 deletions(-) diff --git a/veilid-core/src/rpc_processor/rpc_app_call.rs b/veilid-core/src/rpc_processor/rpc_app_call.rs index c19b27dd..e5d2215f 100644 --- a/veilid-core/src/rpc_processor/rpc_app_call.rs +++ b/veilid-core/src/rpc_processor/rpc_app_call.rs @@ -3,7 +3,7 @@ use super::*; impl RPCProcessor { // Sends a high level app request and wait for response // Can be sent via all methods including relays and routes - #[instrument(level = "trace", skip(self, message), ret, err)] + #[instrument(level = "trace", skip(self, message), fields(message.len = message.len(), ret.latency, ret.len), err)] pub async fn rpc_call_app_call( self, dest: Destination, @@ -38,6 +38,8 @@ impl RPCProcessor { let a_message = app_call_a.destructure(); + tracing::Span::current().record("ret.latency", latency.as_u64()); + tracing::Span::current().record("ret.len", a_message.len()); Ok(NetworkResult::value(Answer::new(latency, a_message))) } diff --git a/veilid-core/src/rpc_processor/rpc_app_message.rs b/veilid-core/src/rpc_processor/rpc_app_message.rs index d6040e26..988312a1 100644 --- a/veilid-core/src/rpc_processor/rpc_app_message.rs +++ b/veilid-core/src/rpc_processor/rpc_app_message.rs @@ -3,7 +3,7 @@ use super::*; impl RPCProcessor { // Sends a high level app message // Can be sent via all methods including relays and routes - #[instrument(level = "trace", skip(self, message), ret, err)] + #[instrument(level = "trace", skip(self, message), fields(message.len = message.len()), err)] pub async fn rpc_call_app_message( self, dest: Destination, diff --git a/veilid-core/src/rpc_processor/rpc_find_node.rs b/veilid-core/src/rpc_processor/rpc_find_node.rs index fadbefd2..d5b71b3a 100644 --- a/veilid-core/src/rpc_processor/rpc_find_node.rs +++ b/veilid-core/src/rpc_processor/rpc_find_node.rs @@ -7,7 +7,7 @@ impl RPCProcessor { /// Because this leaks information about the identity of the node itself, /// replying to this request received over a private route will leak /// the identity of the node and defeat the private route. - #[instrument(level = "trace", skip(self), ret, err)] + #[instrument(level = "trace", skip(self), err)] pub async fn rpc_call_find_node( self, dest: Destination, diff --git a/veilid-core/src/rpc_processor/rpc_get_value.rs b/veilid-core/src/rpc_processor/rpc_get_value.rs index 611f0e6c..f6414caa 100644 --- a/veilid-core/src/rpc_processor/rpc_get_value.rs +++ b/veilid-core/src/rpc_processor/rpc_get_value.rs @@ -15,7 +15,13 @@ impl RPCProcessor { /// Because this leaks information about the identity of the node itself, /// replying to this request received over a private route will leak /// the identity of the node and defeat the private route. - #[instrument(level = "trace", skip(self), ret, err)] + #[instrument(level = "trace", skip(self, last_descriptor), + fields(ret.value.data.len, + ret.value.data.seq, + ret.value.data.writer, + ret.peers.len, + ret.latency + ),err)] pub async fn rpc_call_get_value( self, dest: Destination, @@ -101,6 +107,14 @@ impl RPCProcessor { return Ok(NetworkResult::invalid_message("non-closer peers returned")); } + tracing::Span::current().record("ret.latency", latency.as_u64()); + if let Some(value) = &value { + tracing::Span::current().record("ret.value.data.len", value.value_data().data().len()); + tracing::Span::current().record("ret.value.data.seq", value.value_data().seq()); + tracing::Span::current().record("ret.value.data.writer", value.value_data().writer().to_string()); + } + tracing::Span::current().record("ret.peers.len", peers.len()); + Ok(NetworkResult::value(Answer::new( latency, GetValueAnswer { diff --git a/veilid-core/src/rpc_processor/rpc_set_value.rs b/veilid-core/src/rpc_processor/rpc_set_value.rs index 17c2ab87..a176d934 100644 --- a/veilid-core/src/rpc_processor/rpc_set_value.rs +++ b/veilid-core/src/rpc_processor/rpc_set_value.rs @@ -14,6 +14,17 @@ impl RPCProcessor { /// Because this leaks information about the identity of the node itself, /// replying to this request received over a private route will leak /// the identity of the node and defeat the private route. + #[instrument(level = "trace", skip(self, value, descriptor), + fields(value.data.len = value.value_data().data().len(), + value.data.seq = value.value_data().seq(), + value.data.writer = value.value_data().writer().to_string(), + ret.set, + ret.value.data.len, + ret.value.data.seq, + ret.value.data.writer, + ret.peers.len, + ret.latency + ), err)] pub async fn rpc_call_set_value( self, dest: Destination, @@ -107,6 +118,15 @@ impl RPCProcessor { return Ok(NetworkResult::invalid_message("non-closer peers returned")); } + tracing::Span::current().record("ret.latency", latency.as_u64()); + tracing::Span::current().record("ret.set", set); + if let Some(value) = &value { + tracing::Span::current().record("ret.value.data.len", value.value_data().data().len()); + tracing::Span::current().record("ret.value.data.seq", value.value_data().seq()); + tracing::Span::current().record("ret.value.data.writer", value.value_data().writer().to_string()); + } + tracing::Span::current().record("ret.peers.len", peers.len()); + Ok(NetworkResult::value(Answer::new( latency, SetValueAnswer { set, value, peers },