logging improvements

veilid-core/src/api_tracing_layer.rs

@@ -47,6 +47,19 @@ impl ApiTracingLayer {
     }
 }
 
+fn simplify_file(file: &str) -> String {
+    let path = std::path::Path::new(file);
+    let path_component_count = path.iter().count();
+    if path.ends_with("mod.rs") && path_component_count >= 2 {
+        let outpath: std::path::PathBuf = path.iter().skip(path_component_count - 2).collect();
+        outpath.to_string_lossy().to_string()
+    } else if let Some(filename) = path.file_name() {
+        filename.to_string_lossy().to_string()
+    } else {
+        file.to_string()
+    }
+}
+
 impl<S: Subscriber + for<'a> registry::LookupSpan<'a>> Layer<S> for ApiTracingLayer {
     fn on_new_span(
         &self,
@@ -86,15 +99,39 @@ impl<S: Subscriber + for<'a> registry::LookupSpan<'a>> Layer<S> for ApiTracingLa
             let mut recorder = StringRecorder::new();
             event.record(&mut recorder);
             let meta = event.metadata();
-            let level = meta.level();
-            let log_level = VeilidLogLevel::from_tracing_level(*level);
+            let level = *meta.level();
+            let target = meta.target();
+            let log_level = VeilidLogLevel::from_tracing_level(level);
 
-            let origin = meta
-                .file()
-                .and_then(|file| meta.line().map(|ln| format!("{}:{}", file, ln)))
-                .unwrap_or_default();
+            let origin = match level {
+                Level::ERROR | Level::WARN => meta
+                    .file()
+                    .and_then(|file| {
+                        meta.line()
+                            .map(|ln| format!("{}:{}", simplify_file(file), ln))
+                    })
+                    .unwrap_or_default(),
+                Level::INFO => "".to_owned(),
+                Level::DEBUG | Level::TRACE => meta
+                    .file()
+                    .and_then(|file| {
+                        meta.line().map(|ln| {
+                            format!(
+                                "{}{}:{}",
+                                if target.is_empty() {
+                                    "".to_owned()
+                                } else {
+                                    format!("[{}]", target)
+                                },
+                                simplify_file(file),
+                                ln
+                            )
+                        })
+                    })
+                    .unwrap_or_default(),
+            };
 
-            let message = format!("{} {}", origin, recorder);
+            let message = format!("{}{}", origin, recorder).trim().to_owned();
 
             let backtrace = if log_level <= VeilidLogLevel::Error {
                 let bt = backtrace::Backtrace::new();

veilid-core/src/rpc_processor/mod.rs

@@ -373,7 +373,7 @@ impl RPCProcessor {
 
     #[instrument(level = "debug", skip_all, err)]
     pub async fn startup(&self) -> EyreResult<()> {
-        debug!("startup rpc processor");
+        log_rpc!(debug "startup rpc processor");
         {
             let mut inner = self.inner.lock();
 
@@ -382,7 +382,7 @@ impl RPCProcessor {
             inner.stop_source = Some(StopSource::new());
 
             // spin up N workers
-            trace!(
+            log_rpc!(
                 "Spinning up {} RPC workers",
                 self.unlocked_inner.concurrency
             );
@@ -408,7 +408,7 @@ impl RPCProcessor {
 
     #[instrument(level = "debug", skip_all)]
     pub async fn shutdown(&self) {
-        debug!("starting rpc processor shutdown");
+        log_rpc!(debug "starting rpc processor shutdown");
 
         // Stop storage manager from using us
         self.storage_manager.set_rpc_processor(None).await;
@@ -424,17 +424,17 @@ impl RPCProcessor {
             // drop the stop
             drop(inner.stop_source.take());
         }
-        debug!("stopping {} rpc worker tasks", unord.len());
+        log_rpc!(debug "stopping {} rpc worker tasks", unord.len());
 
         // Wait for them to complete
         while unord.next().await.is_some() {}
 
-        debug!("resetting rpc processor state");
+        log_rpc!(debug "resetting rpc processor state");
 
         // Release the rpc processor
         *self.inner.lock() = Self::new_inner();
 
-        debug!("finished rpc processor shutdown");
+        log_rpc!(debug "finished rpc processor shutdown");
     }
 
     //////////////////////////////////////////////////////////////////////

veilid-core/src/veilid_api/api.rs

@@ -41,6 +41,8 @@ pub struct VeilidAPI {
 impl VeilidAPI {
     #[instrument(target = "veilid_api", level = "debug", skip_all)]
     pub(crate) fn new(context: VeilidCoreContext) -> Self {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "VeilidAPI::new()");
         Self {
             inner: Arc::new(Mutex::new(VeilidAPIInner {
                 context: Some(context),
@@ -51,6 +53,8 @@ impl VeilidAPI {
     /// Shut down Veilid and terminate the API
     #[instrument(target = "veilid_api", level = "debug", skip_all)]
     pub async fn shutdown(self) {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "VeilidAPI::shutdown()");
         let context = { self.inner.lock().context.take() };
         if let Some(context) = context {
             api_shutdown(context).await;
@@ -168,8 +172,11 @@ impl VeilidAPI {
     }
 
     /// Connect to the network
-    #[instrument(target = "veilid_api", level = "debug", skip_all)]
+    #[instrument(target = "veilid_api", level = "debug", skip_all, ret, err)]
     pub async fn attach(&self) -> VeilidAPIResult<()> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "VeilidAPI::attach()");
+
         let attachment_manager = self.attachment_manager()?;
         if !attachment_manager.attach().await {
             apibail_generic!("Already attached");
@@ -178,8 +185,11 @@ impl VeilidAPI {
     }
 
     /// Disconnect from the network
-    #[instrument(target = "veilid_api", level = "debug", skip_all)]
+    #[instrument(target = "veilid_api", level = "debug", skip_all, ret, err)]
     pub async fn detach(&self) -> VeilidAPIResult<()> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "VeilidAPI::detach()");
+
         let attachment_manager = self.attachment_manager()?;
         if !attachment_manager.detach().await {
             apibail_generic!("Already detached");
@@ -193,6 +203,9 @@ impl VeilidAPI {
     /// Get a new `RoutingContext` object to use to send messages over the Veilid network.
     #[instrument(target = "veilid_api", level = "debug", skip_all, err, ret)]
     pub fn routing_context(&self) -> VeilidAPIResult<RoutingContext> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "VeilidAPI::routing_context()");
+
         RoutingContext::try_new(self.clone())
     }
 
@@ -207,6 +220,9 @@ impl VeilidAPI {
     pub async fn parse_as_target<S: ToString>(&self, s: S) -> VeilidAPIResult<Target> {
         let s = s.to_string();
 
+        event!(target: "veilid_api", Level::DEBUG, 
+            "VeilidAPI::parse_as_target(s: {:?})", s);
+
         // Is this a route id?
         if let Ok(rrid) = RouteId::from_str(&s) {
             let routing_table = self.routing_table()?;
@@ -258,6 +274,12 @@ impl VeilidAPI {
         stability: Stability,
         sequencing: Sequencing,
     ) -> VeilidAPIResult<(RouteId, Vec<u8>)> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "VeilidAPI::new_custom_private_route(crypto_kinds: {:?}, stability: {:?}, sequencing: {:?})", 
+            crypto_kinds, 
+            stability, 
+            sequencing);
+
         for kind in crypto_kinds {
             Crypto::validate_crypto_kind(*kind)?;
         }
@@ -301,6 +323,8 @@ impl VeilidAPI {
     /// 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)]
     pub fn import_remote_private_route(&self, blob: Vec<u8>) -> VeilidAPIResult<RouteId> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "VeilidAPI::import_remote_private_route(blob: {:?})", blob);
         let rss = self.routing_table()?.route_spec_store();
         rss.import_remote_private_route_blob(blob)
     }
@@ -311,6 +335,8 @@ impl VeilidAPI {
     /// or received from.
     #[instrument(target = "veilid_api", level = "debug", skip(self), ret, err)]
     pub fn release_private_route(&self, route_id: RouteId) -> VeilidAPIResult<()> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "VeilidAPI::release_private_route(route_id: {:?})", route_id);
         let rss = self.routing_table()?.route_spec_store();
         if !rss.release_route(route_id) {
             apibail_invalid_argument!("release_private_route", "key", route_id);
@@ -331,6 +357,9 @@ impl VeilidAPI {
         call_id: OperationId,
         message: Vec<u8>,
     ) -> VeilidAPIResult<()> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "VeilidAPI::app_call_reply(call_id: {:?}, message: {:?})", call_id, message);
+
         let rpc_processor = self.rpc_processor()?;
         rpc_processor
             .app_call_reply(call_id, message)

veilid-core/src/veilid_api/routing_context.rs

@@ -74,6 +74,9 @@ impl RoutingContext {
     /// To customize the safety selection in use, use [RoutingContext::with_safety()].
     #[instrument(target = "veilid_api", level = "debug", ret, err)]
     pub fn with_default_safety(self) -> VeilidAPIResult<Self> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "RoutingContext::with_default_safety(self: {:?})", self);
+
         let config = self.api.config()?;
         let c = config.get();
 
@@ -88,6 +91,9 @@ impl RoutingContext {
     /// Use a custom [SafetySelection]. Can be used to disable safety via [SafetySelection::Unsafe]
     #[instrument(target = "veilid_api", level = "debug", ret, err)]
     pub fn with_safety(self, safety_selection: SafetySelection) -> VeilidAPIResult<Self> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "RoutingContext::with_safety(self: {:?}, safety_selection: {:?})", self, safety_selection);
+
         Ok(Self {
             api: self.api.clone(),
             inner: Arc::new(Mutex::new(RoutingContextInner {})),
@@ -98,6 +104,9 @@ impl RoutingContext {
     /// Use a specified [Sequencing] preference, with or without privacy
     #[instrument(target = "veilid_api", level = "debug", ret)]
     pub fn with_sequencing(self, sequencing: Sequencing) -> Self {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "RoutingContext::with_sequencing(self: {:?}, sequencing: {:?})", self, sequencing);
+
         Self {
             api: self.api.clone(),
             inner: Arc::new(Mutex::new(RoutingContextInner {})),
@@ -134,6 +143,9 @@ impl RoutingContext {
 
     #[instrument(target = "veilid_api", level = "debug", ret, err)]
     async fn get_destination(&self, target: Target) -> VeilidAPIResult<rpc_processor::Destination> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "RoutingContext::get_destination(self: {:?}, target: {:?})", self, target);
+
         let rpc_processor = self.api.rpc_processor()?;
         rpc_processor
             .resolve_target_to_destination(target, self.unlocked_inner.safety_selection)
@@ -154,6 +166,9 @@ impl RoutingContext {
     /// Returns an answer blob of up to 32768 bytes
     #[instrument(target = "veilid_api", level = "debug", ret, err)]
     pub async fn app_call(&self, target: Target, message: Vec<u8>) -> VeilidAPIResult<Vec<u8>> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "RoutingContext::app_call(self: {:?}, target: {:?}, message: {:?})", self, target, message);
+
         let rpc_processor = self.api.rpc_processor()?;
 
         // Get destination
@@ -185,6 +200,9 @@ impl RoutingContext {
     /// * `message` - an arbitrary message blob of up to 32768 bytes
     #[instrument(target = "veilid_api", level = "debug", ret, err)]
     pub async fn app_message(&self, target: Target, message: Vec<u8>) -> VeilidAPIResult<()> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "RoutingContext::app_message(self: {:?}, target: {:?}, message: {:?})", self, target, message);
+
         let rpc_processor = self.api.rpc_processor()?;
 
         // Get destination
@@ -221,6 +239,9 @@ impl RoutingContext {
         schema: DHTSchema,
         kind: Option<CryptoKind>,
     ) -> VeilidAPIResult<DHTRecordDescriptor> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "RoutingContext::create_dht_record(self: {:?}, schema: {:?}, kind: {:?})", self, schema, kind);
+
         let kind = kind.unwrap_or(best_crypto_kind());
         Crypto::validate_crypto_kind(kind)?;
         let storage_manager = self.api.storage_manager()?;
@@ -246,6 +267,9 @@ impl RoutingContext {
         key: TypedKey,
         default_writer: Option<KeyPair>,
     ) -> VeilidAPIResult<DHTRecordDescriptor> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "RoutingContext::open_dht_record(self: {:?}, key: {:?}, default_writer: {:?})", self, key, default_writer);
+
         Crypto::validate_crypto_kind(key.kind)?;
         let storage_manager = self.api.storage_manager()?;
         storage_manager
@@ -258,6 +282,9 @@ impl RoutingContext {
     /// Closing a record allows you to re-open it with a different routing context
     #[instrument(target = "veilid_api", level = "debug", ret, err)]
     pub async fn close_dht_record(&self, key: TypedKey) -> VeilidAPIResult<()> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "RoutingContext::close_dht_record(self: {:?}, key: {:?})", self, key);
+
         Crypto::validate_crypto_kind(key.kind)?;
         let storage_manager = self.api.storage_manager()?;
         storage_manager.close_record(key).await
@@ -270,6 +297,9 @@ impl RoutingContext {
     /// locally, and will prevent its value from being refreshed on the network by this node.
     #[instrument(target = "veilid_api", level = "debug", ret, err)]
     pub async fn delete_dht_record(&self, key: TypedKey) -> VeilidAPIResult<()> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "RoutingContext::delete_dht_record(self: {:?}, key: {:?})", self, key);
+
         Crypto::validate_crypto_kind(key.kind)?;
         let storage_manager = self.api.storage_manager()?;
         storage_manager.delete_record(key).await
@@ -288,6 +318,9 @@ impl RoutingContext {
         subkey: ValueSubkey,
         force_refresh: bool,
     ) -> VeilidAPIResult<Option<ValueData>> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "RoutingContext::get_dht_value(self: {:?}, key: {:?}, subkey: {:?}, force_refresh: {:?})", self, key, subkey, force_refresh);
+
         Crypto::validate_crypto_kind(key.kind)?;
         let storage_manager = self.api.storage_manager()?;
         storage_manager.get_value(key, subkey, force_refresh).await
@@ -308,6 +341,9 @@ impl RoutingContext {
         data: Vec<u8>,
         writer: Option<KeyPair>,
     ) -> VeilidAPIResult<Option<ValueData>> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "RoutingContext::set_dht_value(self: {:?}, key: {:?}, subkey: {:?}, data: {:?}, writer: {:?})", self, key, subkey, data, writer);
+
         Crypto::validate_crypto_kind(key.kind)?;
         let storage_manager = self.api.storage_manager()?;
         storage_manager.set_value(key, subkey, data, writer).await
@@ -340,6 +376,9 @@ impl RoutingContext {
         expiration: Timestamp,
         count: u32,
     ) -> VeilidAPIResult<Timestamp> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "RoutingContext::watch_dht_values(self: {:?}, key: {:?}, subkeys: {:?}, expiration: {:?}, count: {:?})", self, key, subkeys, expiration, count);
+
         Crypto::validate_crypto_kind(key.kind)?;
         let storage_manager = self.api.storage_manager()?;
         storage_manager
@@ -358,6 +397,9 @@ impl RoutingContext {
         key: TypedKey,
         subkeys: ValueSubkeyRangeSet,
     ) -> VeilidAPIResult<bool> {
+        event!(target: "veilid_api", Level::DEBUG, 
+            "RoutingContext::cancel_dht_watch(self: {:?}, key: {:?}, subkeys: {:?}", self, key, subkeys);
+
         Crypto::validate_crypto_kind(key.kind)?;
         let storage_manager = self.api.storage_manager()?;
         storage_manager.cancel_watch_values(key, subkeys).await

veilid-core/src/veilid_layer_filter.rs

@@ -16,13 +16,25 @@ pub struct VeilidLayerFilter {
 impl VeilidLayerFilter {
     pub fn new(
         max_level: VeilidConfigLogLevel,
-        ignore_list: Option<Vec<String>>,
+        ignore_log_targets: &[String],
     ) -> VeilidLayerFilter {
+        let mut ignore_list = DEFAULT_LOG_IGNORE_LIST.map(|x| x.to_owned()).to_vec();
+        for igedit in ignore_log_targets {
+            if let Some(rest) = igedit.strip_prefix('-') {
+                for i in 0..ignore_list.len() {
+                    if ignore_list[i] == rest {
+                        ignore_list.remove(i);
+                        break;
+                    }
+                }
+            } else {
+                ignore_list.push(igedit.clone());
+            }
+        }
         Self {
             inner: Arc::new(RwLock::new(VeilidLayerFilterInner {
                 max_level: max_level.to_tracing_level_filter(),
-                ignore_list: ignore_list
-                    .unwrap_or_else(|| DEFAULT_LOG_IGNORE_LIST.map(|x| x.to_owned()).to_vec()),
+                ignore_list,
             })),
         }
     }