From 9720bbe52005c42d6c643b9b8f2392e6d9b72227 Mon Sep 17 00:00:00 2001 From: Christien Rioux Date: Wed, 3 Jul 2024 22:25:29 -0400 Subject: [PATCH] more instruments --- .../src/network_manager/connection_manager.rs | 2 +- .../src/network_manager/direct_boot.rs | 4 +- veilid-core/src/network_manager/native/mod.rs | 364 ++++++++++-------- .../network_manager/native/protocol/tcp.rs | 18 +- .../network_manager/native/protocol/udp.rs | 6 +- .../src/network_manager/native/protocol/ws.rs | 13 +- .../src/network_manager/network_connection.rs | 9 +- veilid-core/src/network_manager/send_data.rs | 1 + .../src/network_manager/wasm/protocol/ws.rs | 6 +- veilid-core/src/routing_table/find_peers.rs | 3 + .../src/routing_table/route_spec_store/mod.rs | 71 ++-- .../route_spec_store/permutation.rs | 1 + 12 files changed, 249 insertions(+), 249 deletions(-) diff --git a/veilid-core/src/network_manager/connection_manager.rs b/veilid-core/src/network_manager/connection_manager.rs index a053b0de..ba9e7a68 100644 --- a/veilid-core/src/network_manager/connection_manager.rs +++ b/veilid-core/src/network_manager/connection_manager.rs @@ -283,7 +283,7 @@ impl ConnectionManager { /// This will kill off any connections that are in conflict with the new connection to be made /// in order to make room for the new connection in the system's connection table /// This routine needs to be atomic, or connections may exist in the table that are not established - #[instrument(level = "trace", skip(self), ret, err)] + //#[instrument(level = "trace", skip(self), ret, err)] pub async fn get_or_create_connection( &self, dial_info: DialInfo, diff --git a/veilid-core/src/network_manager/direct_boot.rs b/veilid-core/src/network_manager/direct_boot.rs index 71f87e89..38ec60fe 100644 --- a/veilid-core/src/network_manager/direct_boot.rs +++ b/veilid-core/src/network_manager/direct_boot.rs @@ -2,7 +2,7 @@ use super::*; impl NetworkManager { // Direct bootstrap request handler (separate fallback mechanism from cheaper TXT bootstrap mechanism) - #[instrument(level = "trace", skip(self), ret, err)] + #[instrument(level = "trace", target = "net", skip(self), ret, err)] pub(crate) async fn handle_boot_request(&self, flow: Flow) -> EyreResult> { let routing_table = self.routing_table(); @@ -33,7 +33,7 @@ impl NetworkManager { } // Direct bootstrap request - #[instrument(level = "trace", err, skip(self))] + #[instrument(level = "trace", target = "net", err, skip(self))] pub async fn boot_request(&self, dial_info: DialInfo) -> EyreResult> { let timeout_ms = self.with_config(|c| c.network.rpc.timeout_ms); // Send boot magic to requested peer address diff --git a/veilid-core/src/network_manager/native/mod.rs b/veilid-core/src/network_manager/native/mod.rs index b8bd9a92..fefe2224 100644 --- a/veilid-core/src/network_manager/native/mod.rs +++ b/veilid-core/src/network_manager/native/mod.rs @@ -395,67 +395,72 @@ impl Network { // This creates a short-lived connection in the case of connection-oriented protocols // for the purpose of sending this one message. // This bypasses the connection table as it is not a 'node to node' connection. - #[cfg_attr(feature="verbose-tracing", instrument(level="trace", err, skip(self, data), fields(data.len = data.len())))] + #[instrument(level="trace", target="net", err, skip(self, data), fields(data.len = data.len()))] pub async fn send_data_unbound_to_dial_info( &self, dial_info: DialInfo, data: Vec, ) -> EyreResult> { - self.record_dial_info_failure(dial_info.clone(), async move { - let data_len = data.len(); - let connect_timeout_ms = { - let c = self.config.get(); - c.network.connection_initial_timeout_ms - }; + self.record_dial_info_failure( + dial_info.clone(), + async move { + let data_len = data.len(); + let connect_timeout_ms = { + let c = self.config.get(); + c.network.connection_initial_timeout_ms + }; - if self - .network_manager() - .address_filter() - .is_ip_addr_punished(dial_info.address().ip_addr()) - { - return Ok(NetworkResult::no_connection_other("punished")); - } + if self + .network_manager() + .address_filter() + .is_ip_addr_punished(dial_info.address().ip_addr()) + { + return Ok(NetworkResult::no_connection_other("punished")); + } - match dial_info.protocol_type() { - ProtocolType::UDP => { - let peer_socket_addr = dial_info.to_socket_addr(); - let h = RawUdpProtocolHandler::new_unspecified_bound_handler(&peer_socket_addr) + match dial_info.protocol_type() { + ProtocolType::UDP => { + let peer_socket_addr = dial_info.to_socket_addr(); + let h = + RawUdpProtocolHandler::new_unspecified_bound_handler(&peer_socket_addr) + .await + .wrap_err("create socket failure")?; + let _ = network_result_try!(h + .send_message(data, peer_socket_addr) + .await + .map(NetworkResult::Value) + .wrap_err("send message failure")?); + } + ProtocolType::TCP => { + let peer_socket_addr = dial_info.to_socket_addr(); + let pnc = network_result_try!(RawTcpProtocolHandler::connect( + None, + peer_socket_addr, + connect_timeout_ms + ) .await - .wrap_err("create socket failure")?; - let _ = network_result_try!(h - .send_message(data, peer_socket_addr) + .wrap_err("connect failure")?); + network_result_try!(pnc.send(data).await.wrap_err("send failure")?); + } + ProtocolType::WS | ProtocolType::WSS => { + let pnc = network_result_try!(WebsocketProtocolHandler::connect( + None, + &dial_info, + connect_timeout_ms + ) .await - .map(NetworkResult::Value) - .wrap_err("send message failure")?); + .wrap_err("connect failure")?); + network_result_try!(pnc.send(data).await.wrap_err("send failure")?); + } } - ProtocolType::TCP => { - let peer_socket_addr = dial_info.to_socket_addr(); - let pnc = network_result_try!(RawTcpProtocolHandler::connect( - None, - peer_socket_addr, - connect_timeout_ms - ) - .await - .wrap_err("connect failure")?); - network_result_try!(pnc.send(data).await.wrap_err("send failure")?); - } - ProtocolType::WS | ProtocolType::WSS => { - let pnc = network_result_try!(WebsocketProtocolHandler::connect( - None, - &dial_info, - connect_timeout_ms - ) - .await - .wrap_err("connect failure")?); - network_result_try!(pnc.send(data).await.wrap_err("send failure")?); - } - } - // Network accounting - self.network_manager() - .stats_packet_sent(dial_info.ip_addr(), ByteCount::new(data_len as u64)); + // Network accounting + self.network_manager() + .stats_packet_sent(dial_info.ip_addr(), ByteCount::new(data_len as u64)); - Ok(NetworkResult::Value(())) - }) + Ok(NetworkResult::Value(())) + } + .in_current_span(), + ) .await } @@ -464,103 +469,122 @@ impl Network { // This creates a short-lived connection in the case of connection-oriented protocols // for the purpose of sending this one message. // This bypasses the connection table as it is not a 'node to node' connection. - #[cfg_attr(feature="verbose-tracing", instrument(level="trace", err, skip(self, data), fields(data.len = data.len())))] + #[instrument(level="trace", target="net", err, skip(self, data), fields(data.len = data.len()))] pub async fn send_recv_data_unbound_to_dial_info( &self, dial_info: DialInfo, data: Vec, timeout_ms: u32, ) -> EyreResult>> { - self.record_dial_info_failure(dial_info.clone(), async move { - let data_len = data.len(); - let connect_timeout_ms = { - let c = self.config.get(); - c.network.connection_initial_timeout_ms - }; + self.record_dial_info_failure( + dial_info.clone(), + async move { + let data_len = data.len(); + let connect_timeout_ms = { + let c = self.config.get(); + c.network.connection_initial_timeout_ms + }; - if self - .network_manager() - .address_filter() - .is_ip_addr_punished(dial_info.address().ip_addr()) - { - return Ok(NetworkResult::no_connection_other("punished")); - } - - match dial_info.protocol_type() { - ProtocolType::UDP => { - let peer_socket_addr = dial_info.to_socket_addr(); - let h = RawUdpProtocolHandler::new_unspecified_bound_handler(&peer_socket_addr) - .await - .wrap_err("create socket failure")?; - network_result_try!(h - .send_message(data, peer_socket_addr) - .await - .wrap_err("send message failure")?); - self.network_manager() - .stats_packet_sent(dial_info.ip_addr(), ByteCount::new(data_len as u64)); - - // receive single response - let mut out = vec![0u8; MAX_MESSAGE_SIZE]; - let (recv_len, recv_addr) = network_result_try!(timeout( - timeout_ms, - h.recv_message(&mut out).instrument(Span::current()) - ) - .await - .into_network_result()) - .wrap_err("recv_message failure")?; - - let recv_socket_addr = recv_addr.remote_address().socket_addr(); - self.network_manager() - .stats_packet_rcvd(recv_socket_addr.ip(), ByteCount::new(recv_len as u64)); - - // if the from address is not the same as the one we sent to, then drop this - if recv_socket_addr != peer_socket_addr { - bail!("wrong address"); - } - out.resize(recv_len, 0u8); - Ok(NetworkResult::Value(out)) + if self + .network_manager() + .address_filter() + .is_ip_addr_punished(dial_info.address().ip_addr()) + { + return Ok(NetworkResult::no_connection_other("punished")); } - ProtocolType::TCP | ProtocolType::WS | ProtocolType::WSS => { - let pnc = network_result_try!(match dial_info.protocol_type() { - ProtocolType::UDP => unreachable!(), - ProtocolType::TCP => { - let peer_socket_addr = dial_info.to_socket_addr(); - RawTcpProtocolHandler::connect( - None, - peer_socket_addr, - connect_timeout_ms, - ) + + match dial_info.protocol_type() { + ProtocolType::UDP => { + let peer_socket_addr = dial_info.to_socket_addr(); + let h = + RawUdpProtocolHandler::new_unspecified_bound_handler(&peer_socket_addr) + .await + .wrap_err("create socket failure")?; + network_result_try!(h + .send_message(data, peer_socket_addr) .await - .wrap_err("connect failure")? + .wrap_err("send message failure")?); + self.network_manager().stats_packet_sent( + dial_info.ip_addr(), + ByteCount::new(data_len as u64), + ); + + // receive single response + let mut out = vec![0u8; MAX_MESSAGE_SIZE]; + let (recv_len, recv_addr) = network_result_try!(timeout( + timeout_ms, + h.recv_message(&mut out).instrument(Span::current()) + ) + .await + .into_network_result()) + .wrap_err("recv_message failure")?; + + let recv_socket_addr = recv_addr.remote_address().socket_addr(); + self.network_manager().stats_packet_rcvd( + recv_socket_addr.ip(), + ByteCount::new(recv_len as u64), + ); + + // if the from address is not the same as the one we sent to, then drop this + if recv_socket_addr != peer_socket_addr { + bail!("wrong address"); } - ProtocolType::WS | ProtocolType::WSS => { - WebsocketProtocolHandler::connect(None, &dial_info, connect_timeout_ms) + out.resize(recv_len, 0u8); + Ok(NetworkResult::Value(out)) + } + ProtocolType::TCP | ProtocolType::WS | ProtocolType::WSS => { + let pnc = network_result_try!(match dial_info.protocol_type() { + ProtocolType::UDP => unreachable!(), + ProtocolType::TCP => { + let peer_socket_addr = dial_info.to_socket_addr(); + RawTcpProtocolHandler::connect( + None, + peer_socket_addr, + connect_timeout_ms, + ) .await .wrap_err("connect failure")? - } - }); + } + ProtocolType::WS | ProtocolType::WSS => { + WebsocketProtocolHandler::connect( + None, + &dial_info, + connect_timeout_ms, + ) + .await + .wrap_err("connect failure")? + } + }); - network_result_try!(pnc.send(data).await.wrap_err("send failure")?); - self.network_manager() - .stats_packet_sent(dial_info.ip_addr(), ByteCount::new(data_len as u64)); + network_result_try!(pnc.send(data).await.wrap_err("send failure")?); + self.network_manager().stats_packet_sent( + dial_info.ip_addr(), + ByteCount::new(data_len as u64), + ); - let out = - network_result_try!(network_result_try!(timeout(timeout_ms, pnc.recv()) - .await - .into_network_result()) + let out = network_result_try!(network_result_try!(timeout( + timeout_ms, + pnc.recv() + ) + .await + .into_network_result()) .wrap_err("recv failure")?); - self.network_manager() - .stats_packet_rcvd(dial_info.ip_addr(), ByteCount::new(out.len() as u64)); + self.network_manager().stats_packet_rcvd( + dial_info.ip_addr(), + ByteCount::new(out.len() as u64), + ); - Ok(NetworkResult::Value(out)) + Ok(NetworkResult::Value(out)) + } } } - }) + .in_current_span(), + ) .await } - #[cfg_attr(feature="verbose-tracing", instrument(level="trace", err, skip(self, data), fields(data.len = data.len())))] + #[instrument(level="trace", target="net", err, skip(self, data), fields(data.len = data.len()))] pub async fn send_data_to_existing_flow( &self, flow: Flow, @@ -625,57 +649,61 @@ impl Network { // Send data directly to a dial info, possibly without knowing which node it is going to // Returns a flow for the connection used to send the data - #[cfg_attr(feature="verbose-tracing", instrument(level="trace", err, skip(self, data), fields(data.len = data.len())))] + #[instrument(level="trace", target="net", err, skip(self, data), fields(data.len = data.len()))] pub async fn send_data_to_dial_info( &self, dial_info: DialInfo, data: Vec, ) -> EyreResult> { - self.record_dial_info_failure(dial_info.clone(), async move { - let data_len = data.len(); - let unique_flow; - if dial_info.protocol_type() == ProtocolType::UDP { - // Handle connectionless protocol - let peer_socket_addr = dial_info.to_socket_addr(); - let ph = match self.find_best_udp_protocol_handler(&peer_socket_addr, &None) { - Some(ph) => ph, - None => { - return Ok(NetworkResult::no_connection_other( - "no appropriate UDP protocol handler for dial_info", - )); + self.record_dial_info_failure( + dial_info.clone(), + async move { + let data_len = data.len(); + let unique_flow; + if dial_info.protocol_type() == ProtocolType::UDP { + // Handle connectionless protocol + let peer_socket_addr = dial_info.to_socket_addr(); + let ph = match self.find_best_udp_protocol_handler(&peer_socket_addr, &None) { + Some(ph) => ph, + None => { + return Ok(NetworkResult::no_connection_other( + "no appropriate UDP protocol handler for dial_info", + )); + } + }; + let flow = network_result_try!(ph + .send_message(data, peer_socket_addr) + .await + .wrap_err("failed to send data to dial info")?); + unique_flow = UniqueFlow { + flow, + connection_id: None, + }; + } else { + // Handle connection-oriented protocols + let conn = network_result_try!( + self.connection_manager() + .get_or_create_connection(dial_info.clone()) + .await? + ); + + if let ConnectionHandleSendResult::NotSent(_) = conn.send_async(data).await { + return Ok(NetworkResult::NoConnection(io::Error::new( + io::ErrorKind::ConnectionReset, + "failed to send", + ))); } - }; - let flow = network_result_try!(ph - .send_message(data, peer_socket_addr) - .await - .wrap_err("failed to send data to dial info")?); - unique_flow = UniqueFlow { - flow, - connection_id: None, - }; - } else { - // Handle connection-oriented protocols - let conn = network_result_try!( - self.connection_manager() - .get_or_create_connection(dial_info.clone()) - .await? - ); - - if let ConnectionHandleSendResult::NotSent(_) = conn.send_async(data).await { - return Ok(NetworkResult::NoConnection(io::Error::new( - io::ErrorKind::ConnectionReset, - "failed to send", - ))); + unique_flow = conn.unique_flow(); } - unique_flow = conn.unique_flow(); + + // Network accounting + self.network_manager() + .stats_packet_sent(dial_info.ip_addr(), ByteCount::new(data_len as u64)); + + Ok(NetworkResult::value(unique_flow)) } - - // Network accounting - self.network_manager() - .stats_packet_sent(dial_info.ip_addr(), ByteCount::new(data_len as u64)); - - Ok(NetworkResult::value(unique_flow)) - }) + .in_current_span(), + ) .await } diff --git a/veilid-core/src/network_manager/native/protocol/tcp.rs b/veilid-core/src/network_manager/native/protocol/tcp.rs index 0f213317..90ae9f95 100644 --- a/veilid-core/src/network_manager/native/protocol/tcp.rs +++ b/veilid-core/src/network_manager/native/protocol/tcp.rs @@ -22,10 +22,7 @@ impl RawTcpNetworkConnection { self.flow } - #[cfg_attr( - feature = "verbose-tracing", - instrument(level = "trace", err, skip(self)) - )] + #[instrument(level = "trace", target = "protocol", err, skip_all)] pub async fn close(&self) -> io::Result> { let mut stream = self.stream.clone(); let _ = stream.close().await; @@ -47,6 +44,7 @@ impl RawTcpNetworkConnection { // } } + #[instrument(level = "trace", target = "protocol", err, skip_all)] async fn send_internal( stream: &mut AsyncPeekStream, message: Vec, @@ -63,7 +61,7 @@ impl RawTcpNetworkConnection { stream.flush().await.into_network_result() } - #[cfg_attr(feature="verbose-tracing", instrument(level="trace", err, skip(self, message), fields(network_result, message.len = message.len())))] + #[instrument(level="trace", target="protocol", err, skip(self, message), fields(network_result, message.len = message.len()))] pub async fn send(&self, message: Vec) -> io::Result> { let mut stream = self.stream.clone(); let out = Self::send_internal(&mut stream, message).await?; @@ -72,6 +70,7 @@ impl RawTcpNetworkConnection { Ok(out) } + #[instrument(level = "trace", target = "protocol", err, skip_all)] async fn recv_internal(stream: &mut AsyncPeekStream) -> io::Result>> { let mut header = [0u8; 4]; @@ -95,10 +94,7 @@ impl RawTcpNetworkConnection { Ok(NetworkResult::Value(out)) } - #[cfg_attr( - feature = "verbose-tracing", - instrument(level = "trace", err, skip(self), fields(network_result)) - )] + #[instrument(level = "trace", target = "protocol", err, skip_all)] pub async fn recv(&self) -> io::Result>> { let mut stream = self.stream.clone(); let out = Self::recv_internal(&mut stream).await?; @@ -127,7 +123,7 @@ impl RawTcpProtocolHandler { } } - #[instrument(level = "trace", err, skip(self, ps))] + #[instrument(level = "trace", target = "protocol", err, skip_all)] async fn on_accept_async( self, ps: AsyncPeekStream, @@ -160,7 +156,7 @@ impl RawTcpProtocolHandler { Ok(Some(conn)) } - #[instrument(level = "trace", ret, err)] + #[instrument(level = "trace", target = "protocol", err, skip_all)] pub async fn connect( local_address: Option, socket_addr: SocketAddr, diff --git a/veilid-core/src/network_manager/native/protocol/udp.rs b/veilid-core/src/network_manager/native/protocol/udp.rs index 0faabc14..d21880c7 100644 --- a/veilid-core/src/network_manager/native/protocol/udp.rs +++ b/veilid-core/src/network_manager/native/protocol/udp.rs @@ -17,7 +17,7 @@ impl RawUdpProtocolHandler { } } - #[cfg_attr(feature="verbose-tracing", instrument(level = "trace", err, skip(self, data), fields(data.len = data.len(), ret.len, ret.flow)))] + #[instrument(level = "trace", target = "protocol", err, skip(self, data), fields(data.len = data.len(), ret.len, ret.flow))] pub async fn recv_message(&self, data: &mut [u8]) -> io::Result<(usize, Flow)> { let (message_len, flow) = loop { // Get a packet @@ -80,7 +80,7 @@ impl RawUdpProtocolHandler { Ok((message_len, flow)) } - #[cfg_attr(feature="verbose-tracing", instrument(level = "trace", err, skip(self, data), fields(data.len = data.len(), ret.flow)))] + #[instrument(level = "trace", target = "protocol", err, skip(self, data), fields(data.len = data.len(), ret.flow))] pub async fn send_message( &self, data: Vec, @@ -135,7 +135,7 @@ impl RawUdpProtocolHandler { Ok(NetworkResult::value(flow)) } - #[instrument(level = "trace", err)] + #[instrument(level = "trace", target = "protocol", err)] pub async fn new_unspecified_bound_handler( socket_addr: &SocketAddr, ) -> io::Result { diff --git a/veilid-core/src/network_manager/native/protocol/ws.rs b/veilid-core/src/network_manager/native/protocol/ws.rs index cfab7ff5..36b17e8b 100644 --- a/veilid-core/src/network_manager/native/protocol/ws.rs +++ b/veilid-core/src/network_manager/native/protocol/ws.rs @@ -82,10 +82,7 @@ where self.flow } - #[cfg_attr( - feature = "verbose-tracing", - instrument(level = "trace", err, skip(self)) - )] + #[instrument(level = "trace", target = "protocol", err, skip_all)] pub async fn close(&self) -> io::Result> { // Make an attempt to close the stream normally let mut stream = self.stream.clone(); @@ -127,7 +124,7 @@ where */ } - #[cfg_attr(feature="verbose-tracing", instrument(level = "trace", err, skip(self, message), fields(network_result, message.len = message.len())))] + #[instrument(level = "trace", target="protocol", err, skip(self, message), fields(network_result, message.len = message.len()))] pub async fn send(&self, message: Vec) -> io::Result> { if message.len() > MAX_MESSAGE_SIZE { bail_io_error_other!("sending too large WS message"); @@ -142,7 +139,7 @@ where Ok(out) } - #[cfg_attr(feature="verbose-tracing", instrument(level = "trace", err, skip(self), fields(network_result, ret.len)))] + #[instrument(level = "trace", target="protocol", err, skip(self), fields(network_result, ret.len))] pub async fn recv(&self) -> io::Result>> { let out = match self.stream.clone().next().await { Some(Ok(Message::Binary(v))) => { @@ -212,7 +209,7 @@ impl WebsocketProtocolHandler { } } - #[instrument(level = "trace", err, skip(self, ps))] + #[instrument(level = "trace", target = "protocol", err, skip(self, ps))] pub async fn on_accept_async( self, ps: AsyncPeekStream, @@ -294,7 +291,7 @@ impl WebsocketProtocolHandler { Ok(Some(conn)) } - #[instrument(level = "trace", ret, err)] + #[instrument(level = "trace", target = "protocol", ret, err)] pub async fn connect( local_address: Option, dial_info: &DialInfo, diff --git a/veilid-core/src/network_manager/network_connection.rs b/veilid-core/src/network_manager/network_connection.rs index 4b10c3ea..262a5a3f 100644 --- a/veilid-core/src/network_manager/network_connection.rs +++ b/veilid-core/src/network_manager/network_connection.rs @@ -265,7 +265,7 @@ impl NetworkConnection { // Connection receiver loop #[allow(clippy::too_many_arguments)] - #[instrument(level="trace", target="net", skip_all)] + //#[instrument(level="trace", target="net", skip_all)] fn process_connection( connection_manager: ConnectionManager, local_stop_token: StopToken, @@ -307,10 +307,11 @@ impl NetworkConnection { need_sender = false; let sender_fut = receiver.recv_async().then(|res| async { match res { - Ok((span_id, message)) => { + Ok((_span_id, message)) => { - let span = span!(parent: span_id, Level::TRACE, "process_connection send"); - let _enter = span.enter(); + // let span = span!(Level::TRACE, "process_connection send"); + // span.follows_from(span_id); + // let _enter = span.enter(); // Touch the LRU for this connection connection_manager.touch_connection_by_id(connection_id); diff --git a/veilid-core/src/network_manager/send_data.rs b/veilid-core/src/network_manager/send_data.rs index b3202646..503be4ab 100644 --- a/veilid-core/src/network_manager/send_data.rs +++ b/veilid-core/src/network_manager/send_data.rs @@ -54,6 +54,7 @@ impl NetworkManager { self.try_possibly_relayed_contact_method(possibly_relayed_contact_method, destination_node_ref, data).await } + #[instrument(level="trace", target="net", skip_all)] pub(crate) fn try_possibly_relayed_contact_method(&self, possibly_relayed_contact_method: NodeContactMethod, destination_node_ref: NodeRef, diff --git a/veilid-core/src/network_manager/wasm/protocol/ws.rs b/veilid-core/src/network_manager/wasm/protocol/ws.rs index c9306fb1..d5a9295a 100644 --- a/veilid-core/src/network_manager/wasm/protocol/ws.rs +++ b/veilid-core/src/network_manager/wasm/protocol/ws.rs @@ -69,7 +69,7 @@ impl WebsocketNetworkConnection { Ok(NetworkResult::value(())) } - #[cfg_attr(feature="verbose-tracing", instrument(level = "trace", err, skip(self, message), fields(network_result, message.len = message.len())))] + #[instrument(level = "trace", target="protocol", err, skip(self, message), fields(network_result, message.len = message.len()))] pub async fn send(&self, message: Vec) -> io::Result> { if message.len() > MAX_MESSAGE_SIZE { bail_io_error_other!("sending too large WS message"); @@ -89,7 +89,7 @@ impl WebsocketNetworkConnection { Ok(out) } - #[cfg_attr(feature="verbose-tracing", instrument(level = "trace", err, skip(self), fields(network_result, ret.len)))] + #[instrument(level = "trace", target="protocol", err, skip(self), fields(network_result, ret.len))] pub async fn recv(&self) -> io::Result>> { let out = match SendWrapper::new(self.inner.ws_stream.clone().next()).await { Some(WsMessage::Binary(v)) => { @@ -121,7 +121,7 @@ impl WebsocketNetworkConnection { pub(in crate::network_manager) struct WebsocketProtocolHandler {} impl WebsocketProtocolHandler { - #[instrument(level = "trace", ret, err)] + #[instrument(level = "trace", target = "protocol", ret, err)] pub async fn connect( dial_info: &DialInfo, timeout_ms: u32, diff --git a/veilid-core/src/routing_table/find_peers.rs b/veilid-core/src/routing_table/find_peers.rs index 649e9966..6a7f6377 100644 --- a/veilid-core/src/routing_table/find_peers.rs +++ b/veilid-core/src/routing_table/find_peers.rs @@ -4,6 +4,7 @@ impl RoutingTable { /// Utility to find the closest nodes to a particular key, preferring reliable nodes first, /// including possibly our own node and nodes further away from the key than our own, /// returning their peer info + #[instrument(level = "trace", target = "rtab", skip_all)] pub fn find_preferred_closest_peers( &self, key: TypedKey, @@ -72,6 +73,7 @@ impl RoutingTable { /// Utility to find nodes that are closer to a key than our own node, /// preferring reliable nodes first, and returning their peer info /// Can filter based on a particular set of capabilities + #[instrument(level = "trace", target = "rtab", skip_all)] pub fn find_preferred_peers_closer_to_key( &self, key: TypedKey, @@ -167,6 +169,7 @@ impl RoutingTable { } /// Determine if set of peers is closer to key_near than key_far is to key_near + #[instrument(level = "trace", target = "rtab", skip_all, err)] pub(crate) fn verify_peers_closer( vcrypto: CryptoSystemVersion, key_far: TypedKey, diff --git a/veilid-core/src/routing_table/route_spec_store/mod.rs b/veilid-core/src/routing_table/route_spec_store/mod.rs index e51421ef..2ab4ea52 100644 --- a/veilid-core/src/routing_table/route_spec_store/mod.rs +++ b/veilid-core/src/routing_table/route_spec_store/mod.rs @@ -77,7 +77,7 @@ impl RouteSpecStore { } } - #[instrument(level = "trace", skip(routing_table), err)] + #[instrument(level = "trace", target = "route", skip(routing_table), err)] pub async fn load(routing_table: RoutingTable) -> EyreResult { let (max_route_hop_count, default_route_hop_count) = { let config = routing_table.network_manager().config(); @@ -115,7 +115,7 @@ impl RouteSpecStore { Ok(rss) } - #[instrument(level = "trace", skip(self), err)] + #[instrument(level = "trace", target = "route", skip(self), err)] pub async fn save(&self) -> EyreResult<()> { let content = { let inner = self.inner.lock(); @@ -130,7 +130,7 @@ impl RouteSpecStore { Ok(()) } - #[instrument(level = "trace", skip(self))] + #[instrument(level = "trace", target = "route", skip(self))] pub fn send_route_update(&self) { let (dead_routes, dead_remote_routes) = { let mut inner = self.inner.lock(); @@ -170,7 +170,7 @@ impl RouteSpecStore { /// Returns Err(VeilidAPIError::TryAgain) if no route could be allocated at this time /// Returns other errors on failure /// Returns Ok(route id string) on success - #[instrument(level = "trace", skip(self), ret, err(level=Level::TRACE))] + #[instrument(level = "trace", target="route", skip(self), ret, err(level=Level::TRACE))] #[allow(clippy::too_many_arguments)] pub fn allocate_route( &self, @@ -199,7 +199,7 @@ impl RouteSpecStore { ) } - #[instrument(level = "trace", skip(self, inner, rti), ret, err(level=Level::TRACE))] + #[instrument(level = "trace", target="route", skip(self, inner, rti), ret, err(level=Level::TRACE))] #[allow(clippy::too_many_arguments)] fn allocate_route_inner( &self, @@ -640,10 +640,7 @@ impl RouteSpecStore { } /// validate data using a private route's key and signature chain - #[cfg_attr( - feature = "verbose-tracing", - instrument(level = "trace", skip(self, data, callback), ret) - )] + #[instrument(level = "trace", target = "route", skip(self, data, callback), ret)] pub fn with_signature_validated_route( &self, public_key: &TypedKey, @@ -711,10 +708,7 @@ impl RouteSpecStore { Some(callback(rssd, rsd)) } - #[cfg_attr( - feature = "verbose-tracing", - instrument(level = "trace", skip(self), ret, err) - )] + #[instrument(level = "trace", target = "route", skip(self), ret, err)] async fn test_allocated_route(&self, private_route_id: RouteId) -> VeilidAPIResult { // Make loopback route to test with let (dest, hops) = { @@ -781,7 +775,7 @@ impl RouteSpecStore { Ok(true) } - #[instrument(level = "trace", skip(self), ret, err)] + #[instrument(level = "trace", target = "route", skip(self), ret, err)] async fn test_remote_route(&self, private_route_id: RouteId) -> VeilidAPIResult { // Make private route test let dest = { @@ -825,7 +819,7 @@ impl RouteSpecStore { } /// Release an allocated route that is no longer in use - #[instrument(level = "trace", skip(self), ret)] + #[instrument(level = "trace", target = "route", skip(self), ret)] fn release_allocated_route(&self, id: RouteId) -> bool { let mut inner = self.inner.lock(); let Some(rssd) = inner.content.remove_detail(&id) else { @@ -852,10 +846,7 @@ impl RouteSpecStore { } /// Test an allocated route for continuity - #[cfg_attr( - feature = "verbose-tracing", - instrument(level = "trace", skip(self), ret, err) - )] + #[instrument(level = "trace", target = "route", skip(self), ret, err)] pub async fn test_route(&self, id: RouteId) -> VeilidAPIResult { let is_remote = self.is_route_id_remote(&id); if is_remote { @@ -866,7 +857,7 @@ impl RouteSpecStore { } /// Release an allocated or remote route that is no longer in use - #[instrument(level = "trace", skip(self), ret)] + #[instrument(level = "trace", target = "route", skip(self), ret)] pub fn release_route(&self, id: RouteId) -> bool { let is_remote = self.is_route_id_remote(&id); if is_remote { @@ -879,6 +870,7 @@ impl RouteSpecStore { /// Find first matching unpublished route that fits into the selection criteria /// Don't pick any routes that have failed and haven't been tested yet #[allow(clippy::too_many_arguments)] + #[instrument(level = "trace", target = "route", skip_all)] fn first_available_route_inner( inner: &RouteSpecStoreInner, crypto_kind: CryptoKind, @@ -1002,6 +994,8 @@ impl RouteSpecStore { /// Returns Err(VeilidAPIError::TryAgain) if no allocation could happen at this time (not an error) /// Returns other Err() if the parameters are wrong /// Returns Ok(compiled route) on success + + #[instrument(level = "trace", target = "route", skip_all)] pub fn compile_safety_route( &self, safety_selection: SafetySelection, @@ -1269,10 +1263,7 @@ impl RouteSpecStore { } /// Get an allocated route that matches a particular safety spec - #[cfg_attr( - feature = "verbose-tracing", - instrument(level = "trace", skip(self, inner, rti), ret, err) - )] + #[instrument(level = "trace", target = "route", skip_all)] fn get_route_for_safety_spec_inner( &self, inner: &mut RouteSpecStoreInner, @@ -1353,10 +1344,7 @@ impl RouteSpecStore { } /// Get a private route to use for the answer to question - #[cfg_attr( - feature = "verbose-tracing", - instrument(level = "trace", skip(self), ret, err) - )] + #[instrument(level = "trace", target = "route", skip_all)] pub fn get_private_route_for_safety_spec( &self, crypto_kind: CryptoKind, @@ -1477,10 +1465,7 @@ impl RouteSpecStore { /// Assemble a single private route for publication /// Returns a PrivateRoute object for an allocated private route key - #[cfg_attr( - feature = "verbose-tracing", - instrument(level = "trace", skip(self), err) - )] + #[instrument(level = "trace", target = "route", skip_all)] pub fn assemble_private_route( &self, key: &PublicKey, @@ -1510,10 +1495,7 @@ impl RouteSpecStore { /// Assemble private route set for publication /// Returns a vec of PrivateRoute objects for an allocated private route - #[cfg_attr( - feature = "verbose-tracing", - instrument(level = "trace", skip(self), err) - )] + #[instrument(level = "trace", target = "route", skip_all)] pub fn assemble_private_routes( &self, id: &RouteId, @@ -1541,10 +1523,7 @@ impl RouteSpecStore { /// Import a remote private route set blob for compilation /// It is safe to import the same route more than once and it will return the same route id /// Returns a route set id - #[cfg_attr( - feature = "verbose-tracing", - instrument(level = "trace", skip(self, blob), ret, err) - )] + #[instrument(level = "trace", target = "route", skip_all)] pub fn import_remote_private_route_blob(&self, blob: Vec) -> VeilidAPIResult { let cur_ts = get_aligned_timestamp(); @@ -1581,10 +1560,7 @@ impl RouteSpecStore { /// Add a single remote private route for compilation /// It is safe to add the same route more than once and it will return the same route id /// Returns a route set id - #[cfg_attr( - feature = "verbose-tracing", - instrument(level = "trace", skip(self), ret, err) - )] + #[instrument(level = "trace", target = "route", skip_all)] pub fn add_remote_private_route( &self, private_route: PrivateRoute, @@ -1619,10 +1595,7 @@ impl RouteSpecStore { } /// Release a remote private route that is no longer in use - #[cfg_attr( - feature = "verbose-tracing", - instrument(level = "trace", skip(self), ret) - )] + #[instrument(level = "trace", target = "route", skip_all)] pub fn release_remote_private_route(&self, id: RouteId) -> bool { let inner = &mut *self.inner.lock(); inner.cache.remove_remote_private_route(id) @@ -1739,7 +1712,7 @@ impl RouteSpecStore { } /// Clear caches when local our local node info changes - #[instrument(level = "trace", skip(self))] + #[instrument(level = "trace", target = "route", skip(self))] pub fn reset(&self) { log_rtab!(debug "flushing route spec store"); diff --git a/veilid-core/src/routing_table/route_spec_store/permutation.rs b/veilid-core/src/routing_table/route_spec_store/permutation.rs index 5b0443ae..fd832b92 100644 --- a/veilid-core/src/routing_table/route_spec_store/permutation.rs +++ b/veilid-core/src/routing_table/route_spec_store/permutation.rs @@ -22,6 +22,7 @@ pub type PermFunc<'t> = Box Option + Send /// for a set of 'hop_count' nodes. the first node is always fixed, and the maximum /// number of permutations is given by get_route_permutation_count() +#[instrument(level = "trace", target = "route", skip_all)] pub fn with_route_permutations( hop_count: usize, start: usize,