From 6018d385e84143309a064643dfcd5713a77be29d Mon Sep 17 00:00:00 2001 From: Christien Rioux Date: Tue, 11 Mar 2025 13:30:12 -0400 Subject: [PATCH] [ci skip] fix veilid_api duration logging, add keyed spans to veilid-api tracing so they show up --- veilid-core/src/veilid_api/api.rs | 59 ++++++++------- veilid-core/src/veilid_api/routing_context.rs | 75 ++++++++++--------- veilid-python/tests/test_dht.py | 2 + 3 files changed, 77 insertions(+), 59 deletions(-) diff --git a/veilid-core/src/veilid_api/api.rs b/veilid-core/src/veilid_api/api.rs index e0a0790d..5e1fb4bb 100644 --- a/veilid-core/src/veilid_api/api.rs +++ b/veilid-core/src/veilid_api/api.rs @@ -1,5 +1,7 @@ use super::*; +impl_veilid_log_facility!("veilid_api"); + ///////////////////////////////////////////////////////////////////////////////////////////////////// pub(super) struct VeilidAPIInner { @@ -41,10 +43,9 @@ pub struct VeilidAPI { } impl VeilidAPI { - #[instrument(target = "veilid_api", level = "debug", skip_all)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = context.log_key()), skip_all)] pub(crate) fn new(context: VeilidCoreContext) -> Self { - event!(target: "veilid_api", Level::DEBUG, - "VeilidAPI::new()"); + veilid_log!(context debug "VeilidAPI::new()"); Self { inner: Arc::new(Mutex::new(VeilidAPIInner { context: Some(context), @@ -59,10 +60,9 @@ impl VeilidAPI { } /// Shut down Veilid and terminate the API. - #[instrument(target = "veilid_api", level = "debug", skip_all)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), skip_all)] pub async fn shutdown(self) { - event!(target: "veilid_api", Level::DEBUG, - "VeilidAPI::shutdown()"); + veilid_log!(self debug "VeilidAPI::shutdown()"); let context = { self.inner.lock().context.take() }; if let Some(context) = context { api_shutdown(context).await; @@ -152,6 +152,15 @@ impl VeilidAPI { callback(&mut inner.debug_cache) } + #[must_use] + pub(crate) fn log_key(&self) -> &str { + let inner = self.inner.lock(); + let Some(context) = &inner.context else { + return ""; + }; + context.log_key() + } + //////////////////////////////////////////////////////////////// // Attach/Detach @@ -174,9 +183,9 @@ impl VeilidAPI { } /// Connect to the network. - #[instrument(target = "veilid_api", level = "debug", skip_all, ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), skip_all, ret, err)] pub async fn attach(&self) -> VeilidAPIResult<()> { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "VeilidAPI::attach()"); let attachment_manager = self.core_context()?.attachment_manager(); @@ -187,9 +196,9 @@ impl VeilidAPI { } /// Disconnect from the network. - #[instrument(target = "veilid_api", level = "debug", skip_all, ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), skip_all, ret, err)] pub async fn detach(&self) -> VeilidAPIResult<()> { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "VeilidAPI::detach()"); let attachment_manager = self.core_context()?.attachment_manager(); @@ -203,9 +212,9 @@ impl VeilidAPI { // Routing Context /// Get a new `RoutingContext` object to use to send messages over the Veilid network with default safety, sequencing, and stability parameters. - #[instrument(target = "veilid_api", level = "debug", skip_all, err, ret)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), skip_all, err, ret)] pub fn routing_context(&self) -> VeilidAPIResult { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "VeilidAPI::routing_context()"); RoutingContext::try_new(self.clone()) @@ -218,11 +227,11 @@ impl VeilidAPI { /// `VLD0:XmnGyJrjMJBRC5ayJZRPXWTBspdX36-pbLb98H3UMeE` but if the prefix is left off /// `XmnGyJrjMJBRC5ayJZRPXWTBspdX36-pbLb98H3UMeE` will be parsed with the 'best' cryptosystem /// available (at the time of this writing this is `VLD0`). - #[instrument(target = "veilid_api", level = "debug", skip(self), fields(s=s.to_string()), ret, err)] + #[instrument(target = "veilid_api", level = "debug", skip(self), fields(__VEILID_LOG_KEY = self.log_key(), s=s.to_string()), ret, err)] pub fn parse_as_target(&self, s: S) -> VeilidAPIResult { let s = s.to_string(); - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "VeilidAPI::parse_as_target(s: {:?})", s); // Is this a route id? @@ -272,14 +281,14 @@ impl VeilidAPI { /// /// Returns a route id and 'blob' that can be published over some means (DHT or otherwise) to be /// imported by another Veilid node. - #[instrument(target = "veilid_api", level = "debug", skip(self), ret)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), skip(self), ret)] pub async fn new_custom_private_route( &self, crypto_kinds: &[CryptoKind], stability: Stability, sequencing: Sequencing, ) -> VeilidAPIResult<(RouteId, Vec)> { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "VeilidAPI::new_custom_private_route(crypto_kinds: {:?}, stability: {:?}, sequencing: {:?})", crypto_kinds, stability, @@ -336,9 +345,9 @@ impl VeilidAPI { /// Import a private route blob as a remote private route. /// /// Returns a route id that can be used to send private messages to the node creating this route. - #[instrument(target = "veilid_api", level = "debug", skip(self), ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), skip(self), ret, err)] pub fn import_remote_private_route(&self, blob: Vec) -> VeilidAPIResult { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "VeilidAPI::import_remote_private_route(blob: {:?})", blob); let routing_table = self.core_context()?.routing_table(); let rss = routing_table.route_spec_store(); @@ -349,9 +358,9 @@ impl VeilidAPI { /// /// This will deactivate the route and free its resources and it can no longer be sent to /// or received from. - #[instrument(target = "veilid_api", level = "debug", skip(self), ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), skip(self), ret, err)] pub fn release_private_route(&self, route_id: RouteId) -> VeilidAPIResult<()> { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "VeilidAPI::release_private_route(route_id: {:?})", route_id); let routing_table = self.core_context()?.routing_table(); let rss = routing_table.route_spec_store(); @@ -368,13 +377,13 @@ impl VeilidAPI { /// /// * `call_id` - specifies which call to reply to, and it comes from a [VeilidUpdate::AppCall], specifically the [VeilidAppCall::id()] value. /// * `message` - is an answer blob to be returned by the remote node's [RoutingContext::app_call()] function, and may be up to 32768 bytes. - #[instrument(target = "veilid_api", level = "debug", skip(self), ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), skip(self), ret, err)] pub async fn app_call_reply( &self, call_id: OperationId, message: Vec, ) -> VeilidAPIResult<()> { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "VeilidAPI::app_call_reply(call_id: {:?}, message: {:?})", call_id, message); let rpc_processor = self.core_context()?.rpc_processor(); @@ -387,7 +396,7 @@ impl VeilidAPI { // Tunnel Building #[cfg(feature = "unstable-tunnels")] - #[instrument(target = "veilid_api", level = "debug", skip(self), ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), skip(self), ret, err)] pub async fn start_tunnel( &self, _endpoint_mode: TunnelMode, @@ -397,7 +406,7 @@ impl VeilidAPI { } #[cfg(feature = "unstable-tunnels")] - #[instrument(target = "veilid_api", level = "debug", skip(self), ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), skip(self), ret, err)] pub async fn complete_tunnel( &self, _endpoint_mode: TunnelMode, @@ -408,7 +417,7 @@ impl VeilidAPI { } #[cfg(feature = "unstable-tunnels")] - #[instrument(target = "veilid_api", level = "debug", skip(self), ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), skip(self), ret, err)] pub async fn cancel_tunnel(&self, _tunnel_id: TunnelId) -> VeilidAPIResult { panic!("unimplemented"); } diff --git a/veilid-core/src/veilid_api/routing_context.rs b/veilid-core/src/veilid_api/routing_context.rs index 5e212bf4..07d90a85 100644 --- a/veilid-core/src/veilid_api/routing_context.rs +++ b/veilid-core/src/veilid_api/routing_context.rs @@ -1,5 +1,7 @@ use super::*; +impl_veilid_log_facility!("veilid_api"); + /////////////////////////////////////////////////////////////////////////////////////// /// Valid destinations for a message sent over a routing context. @@ -62,6 +64,11 @@ impl RoutingContext { }) } + #[must_use] + pub(crate) fn log_key(&self) -> &str { + self.api.log_key() + } + /// Turn on sender privacy, enabling the use of safety routes. This is the default and /// calling this function is only necessary if you have previously disable safety or used other parameters. /// @@ -72,9 +79,9 @@ impl RoutingContext { /// * Sequencing default is to prefer ordered before unordered message delivery. /// /// To customize the safety selection in use, use [RoutingContext::with_safety()]. - #[instrument(target = "veilid_api", level = "debug", ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret, err)] pub fn with_default_safety(self) -> VeilidAPIResult { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "RoutingContext::with_default_safety(self: {:?})", self); let config = self.api.config()?; @@ -89,9 +96,9 @@ impl RoutingContext { } /// Use a custom [SafetySelection]. Can be used to disable safety via [SafetySelection::Unsafe]. - #[instrument(target = "veilid_api", level = "debug", ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret, err)] pub fn with_safety(self, safety_selection: SafetySelection) -> VeilidAPIResult { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "RoutingContext::with_safety(self: {:?}, safety_selection: {:?})", self, safety_selection); Ok(Self { @@ -101,9 +108,9 @@ impl RoutingContext { } /// Use a specified [Sequencing] preference, with or without privacy. - #[instrument(target = "veilid_api", level = "debug", ret)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret)] pub fn with_sequencing(self, sequencing: Sequencing) -> Self { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "RoutingContext::with_sequencing(self: {:?}, sequencing: {:?})", self, sequencing); Self { @@ -140,9 +147,9 @@ impl RoutingContext { self.api.clone() } - #[instrument(target = "veilid_api", level = "debug", ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret, err)] async fn get_destination(&self, target: Target) -> VeilidAPIResult { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "RoutingContext::get_destination(self: {:?}, target: {:?})", self, target); let rpc_processor = self.api.core_context()?.rpc_processor(); @@ -165,9 +172,9 @@ impl RoutingContext { /// * `message` - an arbitrary message blob of up to 32768 bytes. /// /// Returns an answer blob of up to 32768 bytes. - #[instrument(target = "veilid_api", level = "debug", ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret, err)] pub async fn app_call(&self, target: Target, message: Vec) -> VeilidAPIResult> { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "RoutingContext::app_call(self: {:?}, target: {:?}, message: {:?})", self, target, message); let rpc_processor = self.api.core_context()?.rpc_processor(); @@ -199,9 +206,9 @@ impl RoutingContext { /// /// * `target` - can be either a direct node id or a private route. /// * `message` - an arbitrary message blob of up to 32768 bytes. - #[instrument(target = "veilid_api", level = "debug", ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret, err)] pub async fn app_message(&self, target: Target, message: Vec) -> VeilidAPIResult<()> { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "RoutingContext::app_message(self: {:?}, target: {:?}, message: {:?})", self, target, message); let rpc_processor = self.api.core_context()?.rpc_processor(); @@ -230,14 +237,14 @@ impl RoutingContext { /// DHT Records /// Deterministicly builds the record key for a given schema and owner public key - #[instrument(target = "veilid_api", level = "debug", ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret, err)] pub fn get_dht_record_key( &self, schema: DHTSchema, owner_key: &PublicKey, kind: Option, ) -> VeilidAPIResult { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "RoutingContext::get_dht_record_key(self: {:?}, schema: {:?}, owner_key: {:?}, kind: {:?})", self, schema, owner_key, kind); schema.validate()?; @@ -256,14 +263,14 @@ impl RoutingContext { /// Returns the newly allocated DHT record's key if successful. /// /// Note: if you pass in an owner keypair this call is a deterministic! This means that if you try to create a new record for a given owner and schema that already exists it *will* fail. - #[instrument(target = "veilid_api", level = "debug", ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret, err)] pub async fn create_dht_record( &self, schema: DHTSchema, owner: Option, kind: Option, ) -> VeilidAPIResult { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "RoutingContext::create_dht_record(self: {:?}, schema: {:?}, owner: {:?}, kind: {:?})", self, schema, owner, kind); schema.validate()?; @@ -291,13 +298,13 @@ impl RoutingContext { /// safety selection. /// /// Returns the DHT record descriptor for the opened record if successful. - #[instrument(target = "veilid_api", level = "debug", ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret, err)] pub async fn open_dht_record( &self, key: TypedKey, default_writer: Option, ) -> VeilidAPIResult { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "RoutingContext::open_dht_record(self: {:?}, key: {:?}, default_writer: {:?})", self, key, default_writer); Crypto::validate_crypto_kind(key.kind)?; @@ -311,9 +318,9 @@ impl RoutingContext { /// Closes a DHT record at a specific key that was opened with create_dht_record or open_dht_record. /// /// Closing a record allows you to re-open it with a different routing context. - #[instrument(target = "veilid_api", level = "debug", ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret, err)] pub async fn close_dht_record(&self, key: TypedKey) -> VeilidAPIResult<()> { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "RoutingContext::close_dht_record(self: {:?}, key: {:?})", self, key); Crypto::validate_crypto_kind(key.kind)?; @@ -327,9 +334,9 @@ impl RoutingContext { /// If the record is opened, it must be closed before it is deleted. /// Deleting a record does not delete it from the network, but will remove the storage of the record /// locally, and will prevent its value from being refreshed on the network by this node. - #[instrument(target = "veilid_api", level = "debug", ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret, err)] pub async fn delete_dht_record(&self, key: TypedKey) -> VeilidAPIResult<()> { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "RoutingContext::delete_dht_record(self: {:?}, key: {:?})", self, key); Crypto::validate_crypto_kind(key.kind)?; @@ -344,14 +351,14 @@ impl RoutingContext { /// /// Returns `None` if the value subkey has not yet been set. /// Returns `Some(data)` if the value subkey has valid data. - #[instrument(target = "veilid_api", level = "debug", ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret, err)] pub async fn get_dht_value( &self, key: TypedKey, subkey: ValueSubkey, force_refresh: bool, ) -> VeilidAPIResult> { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "RoutingContext::get_dht_value(self: {:?}, key: {:?}, subkey: {:?}, force_refresh: {:?})", self, key, subkey, force_refresh); Crypto::validate_crypto_kind(key.kind)?; @@ -367,7 +374,7 @@ impl RoutingContext { /// /// Returns `None` if the value was successfully put. /// Returns `Some(data)` if the value put was older than the one available on the network. - #[instrument(target = "veilid_api", level = "debug", skip(data), fields(data = print_data(&data, Some(64))), ret, err)] + #[instrument(target = "veilid_api", level = "debug", skip(data), fields(__VEILID_LOG_KEY = self.log_key(), data = print_data(&data, Some(64))), ret, err)] pub async fn set_dht_value( &self, key: TypedKey, @@ -375,7 +382,7 @@ impl RoutingContext { data: Vec, writer: Option, ) -> VeilidAPIResult> { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "RoutingContext::set_dht_value(self: {:?}, key: {:?}, subkey: {:?}, data: len={}, writer: {:?})", self, key, subkey, data.len(), writer); Crypto::validate_crypto_kind(key.kind)?; @@ -404,7 +411,7 @@ impl RoutingContext { /// * If a member (either the owner or a SMPL schema member) has opened the key for writing (even if no writing is performed) then the watch will be signed and guaranteed network.dht.member_watch_limit per writer. /// /// Members can be specified via the SMPL schema and do not need to allocate writable subkeys in order to offer a member watch capability. - #[instrument(target = "veilid_api", level = "debug", ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret, err)] pub async fn watch_dht_values( &self, key: TypedKey, @@ -412,7 +419,7 @@ impl RoutingContext { expiration: Timestamp, count: u32, ) -> VeilidAPIResult { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "RoutingContext::watch_dht_values(self: {:?}, key: {:?}, subkeys: {:?}, expiration: {}, count: {})", self, key, subkeys, expiration, count); Crypto::validate_crypto_kind(key.kind)?; @@ -430,13 +437,13 @@ impl RoutingContext { /// /// Returns Ok(true) if there is any remaining watch for this record. /// Returns Ok(false) if the entire watch has been cancelled. - #[instrument(target = "veilid_api", level = "debug", ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret, err)] pub async fn cancel_dht_watch( &self, key: TypedKey, subkeys: ValueSubkeyRangeSet, ) -> VeilidAPIResult { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "RoutingContext::cancel_dht_watch(self: {:?}, key: {:?}, subkeys: {:?}", self, key, subkeys); Crypto::validate_crypto_kind(key.kind)?; @@ -484,14 +491,14 @@ impl RoutingContext { /// Useful for determine which subkeys would change with an SetValue operation. /// /// Returns a DHTRecordReport with the subkey ranges that were returned that overlapped the schema, and sequence numbers for each of the subkeys in the range. - #[instrument(target = "veilid_api", level = "debug", ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret, err)] pub async fn inspect_dht_record( &self, key: TypedKey, subkeys: ValueSubkeyRangeSet, scope: DHTReportScope, ) -> VeilidAPIResult { - event!(target: "veilid_api", Level::DEBUG, + veilid_log!(self debug "RoutingContext::inspect_dht_record(self: {:?}, key: {:?}, subkeys: {:?}, scope: {:?})", self, key, subkeys, scope); Crypto::validate_crypto_kind(key.kind)?; @@ -504,13 +511,13 @@ impl RoutingContext { /// Block Store #[cfg(feature = "unstable-blockstore")] - #[instrument(target = "veilid_api", level = "debug", ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret, err)] pub async fn find_block(&self, _block_id: PublicKey) -> VeilidAPIResult> { panic!("unimplemented"); } #[cfg(feature = "unstable-blockstore")] - #[instrument(target = "veilid_api", level = "debug", ret, err)] + #[instrument(target = "veilid_api", level = "debug", fields(__VEILID_LOG_KEY = self.log_key()), ret, err)] pub async fn supply_block(&self, _block_id: PublicKey) -> VeilidAPIResult { panic!("unimplemented"); } diff --git a/veilid-python/tests/test_dht.py b/veilid-python/tests/test_dht.py index 7cd46c62..7d9a2eae 100644 --- a/veilid-python/tests/test_dht.py +++ b/veilid-python/tests/test_dht.py @@ -824,6 +824,8 @@ async def sync_win( win.addstr(n+2, 1, " " * subkey_count, curses.color_pair(1)) win.refresh() + time.sleep(.5) + curses.endwin()