[ci skip] fix veilid_api duration logging, add keyed spans to veilid-api tracing so they show up

This commit is contained in:
Christien Rioux 2025-03-11 13:30:12 -04:00
parent 67eeb87c28
commit 6018d385e8
3 changed files with 77 additions and 59 deletions

View File

@ -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<RoutingContext> {
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<S: ToString>(&self, s: S) -> VeilidAPIResult<Target> {
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<u8>)> {
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<u8>) -> VeilidAPIResult<RouteId> {
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<u8>,
) -> 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<bool> {
panic!("unimplemented");
}

View File

@ -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<Self> {
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<Self> {
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<rpc_processor::Destination> {
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<u8>) -> VeilidAPIResult<Vec<u8>> {
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<u8>) -> 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<CryptoKind>,
) -> VeilidAPIResult<TypedKey> {
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<KeyPair>,
kind: Option<CryptoKind>,
) -> VeilidAPIResult<DHTRecordDescriptor> {
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<KeyPair>,
) -> VeilidAPIResult<DHTRecordDescriptor> {
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<Option<ValueData>> {
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<u8>,
writer: Option<KeyPair>,
) -> VeilidAPIResult<Option<ValueData>> {
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<Timestamp> {
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<bool> {
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<DHTRecordReport> {
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<Vec<u8>> {
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<bool> {
panic!("unimplemented");
}

View File

@ -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()