refactor(tracing): Using tracing instead of log for logging (#895)

* feat(tracing): replacing log and env_logger with tracing and tracing_subscriber Signed-off-by: gabrik <[email protected]> * chore(clippy): fixing clippy Signed-off-by: gabrik <[email protected]> * fix(ci): valgrind tests Signed-off-by: gabrik <[email protected]> * chore: removed log from leak tests, added explict docstrings Signed-off-by: gabrik <[email protected]> * feat(tracing): adding loki configuration by env variable, feature gated Signed-off-by: gabrik <[email protected]> * feat(tracing): adding apikey header and value configuration for loki logging Signed-off-by: gabrik <[email protected]> * feat(tracing): added init_log function that does not use the EnvFilter, thus no static leaks Signed-off-by: gabrik <[email protected]> * chore: using right functions in valgrind tests Signed-off-by: gabrik <[email protected]> --------- Signed-off-by: gabrik <[email protected]>
eclipse-zenoh · Apr 11, 2024 · 56a4445 · 56a4445
1 parent d594afb
commit 56a4445
Show file tree

Hide file tree

Showing 167 changed files with 1,695 additions and 1,077 deletions.
diff --git a/Cargo.lock b/Cargo.lock
diff --git a/Cargo.toml b/Cargo.toml
@@ -90,7 +90,8 @@ crc = "3.0.1"
 criterion = "0.5"
 derive_more = "0.99.17"
 derive-new = "0.6.0"
-env_logger = "0.11.0"
+tracing-subscriber = {version = "0.3", features = ["json", "env-filter"]}
+tracing-loki = "0.2"
 event-listener = "4.0.0"
 flume = "0.11"
 form_urlencoded = "1.1.0"
@@ -109,7 +110,7 @@ keyed-set = "0.4.4"
 lazy_static = "1.4.0"
 libc = "0.2.139"
 libloading = "0.8"
-log = "0.4.17"
+tracing = "0.1"
 lz4_flex = "0.11"
 nix = { version = "0.27", features = ["fs"] }
 num_cpus = "1.15.0"

diff --git a/ci/valgrind-check/Cargo.toml b/ci/valgrind-check/Cargo.toml
@@ -23,10 +23,11 @@ description = "Internal crate for zenoh."
 
 [dependencies]
 tokio = { version = "1.35.1",  features = ["rt-multi-thread", "time", "io-std"] }
-env_logger = "0.11.0"
+tracing-subscriber = {version = "0.3", features = ["json", "env-filter"]}
 futures = "0.3.25"
 zenoh = { path = "../../zenoh/" }
 zenoh-runtime = { path = "../../commons/zenoh-runtime/" }
+zenoh-util = { path = "../../commons/zenoh-util/" }
 
 [[bin]]
 name = "pub_sub"

diff --git a/ci/valgrind-check/src/pub_sub/bin/z_pub_sub.rs b/ci/valgrind-check/src/pub_sub/bin/z_pub_sub.rs
@@ -14,11 +14,13 @@
 use std::time::Duration;
 use zenoh::config::Config;
 use zenoh::prelude::r#async::*;
-
+use zenoh_util::init_log;
 #[tokio::main]
 async fn main() {
+
+    init_log();
+
     let _z = zenoh_runtime::ZRuntimePoolGuard;
-    env_logger::init();
 
     let pub_key_expr = KeyExpr::try_from("test/valgrind/data").unwrap();
     let sub_key_expr = KeyExpr::try_from("test/valgrind/**").unwrap();

diff --git a/ci/valgrind-check/src/queryable_get/bin/z_queryable_get.rs b/ci/valgrind-check/src/queryable_get/bin/z_queryable_get.rs
@@ -15,11 +15,13 @@ use std::convert::TryFrom;
 use std::time::Duration;
 use zenoh::config::Config;
 use zenoh::prelude::r#async::*;
+use zenoh_util::init_log;
 
 #[tokio::main]
 async fn main() {
+    init_log();
+
     let _z = zenoh_runtime::ZRuntimePoolGuard;
-    env_logger::init();
 
     let queryable_key_expr = KeyExpr::try_from("test/valgrind/data").unwrap();
     let get_selector = Selector::try_from("test/valgrind/**").unwrap();

diff --git a/commons/zenoh-codec/Cargo.toml b/commons/zenoh-codec/Cargo.toml
@@ -31,7 +31,7 @@ description = "Internal crate for zenoh."
 [features]
 default = ["std"]
 std = [
-    "log",
+    "tracing",
     "serde/std",
     "uhlc/std",
     "zenoh-protocol/std"
@@ -44,7 +44,7 @@ shared-memory = [
 complete_n = ["zenoh-protocol/complete_n"]
 
 [dependencies]
-log = { workspace = true, optional = true }
+tracing = {workspace = true, optional = true }
 serde = { workspace = true, features = ["alloc"] }
 uhlc = { workspace = true }
 zenoh-buffers = { workspace = true, default-features = false }
@@ -54,9 +54,10 @@ zenoh-shm = { workspace = true, optional = true }
 # INFO: May cause problems when testing no_std stuff. Check this tool: https://docs.rs/crate/cargo-no-dev-deps/0.1.0
 [dev-dependencies]
 criterion = { workspace = true }
-env_logger = { workspace = true }
+
 rand = { workspace = true, features = ["default"] }
 zenoh-protocol = { workspace = true, features = ["test"] }
+zenoh-util = {workspace = true }
 
 [[bench]]
 name = "codec"

diff --git a/commons/zenoh-codec/src/common/extension.rs b/commons/zenoh-codec/src/common/extension.rs
@@ -30,11 +30,11 @@ where
     let (u, has_ext): (ZExtUnknown, bool) = codec.read(&mut *reader)?;
     if u.is_mandatory() {
         #[cfg(feature = "std")]
-        log::error!("Unknown {_s} ext: {u:?}");
+        tracing::error!("Unknown {_s} ext: {u:?}");
         return Err(DidntRead);
     } else {
         #[cfg(feature = "std")]
-        log::debug!("Unknown {_s} ext: {u:?}");
+        tracing::debug!("Unknown {_s} ext: {u:?}");
     }
     Ok((u, has_ext))
 }

diff --git a/commons/zenoh-codec/tests/codec.rs b/commons/zenoh-codec/tests/codec.rs
@@ -342,7 +342,7 @@ fn codec_shm_info() {
 // Common
 #[test]
 fn codec_extension() {
-    let _ = env_logger::try_init();
+    zenoh_util::init_log_from_env();
 
     macro_rules! run_extension_single {
         ($ext:ty, $buff:expr) => {

diff --git a/commons/zenoh-config/Cargo.toml b/commons/zenoh-config/Cargo.toml
@@ -24,7 +24,7 @@ categories = { workspace = true }
 description = "Internal crate for zenoh."
 
 [dependencies]
-log = { workspace = true }
+tracing = {workspace = true}
 flume = { workspace = true }
 json5 = { workspace = true }
 num_cpus = { workspace = true }

diff --git a/commons/zenoh-core/src/macros.rs b/commons/zenoh-core/src/macros.rs
@@ -170,7 +170,7 @@ macro_rules! zasync_executor_init {
             .await
             .unwrap();
 
-        log::trace!(
+        tracing::trace!(
             "Spawned {} additional threads in the async global executor",
             count
         );
@@ -186,7 +186,7 @@ macro_rules! zparse {
                 "Failed to read configuration: {} is not a valid value",
                 $str
             );
-            log::warn!("{}", e);
+            tracing::warn!("{}", e);
             e
         })
     };
@@ -204,7 +204,7 @@ macro_rules! zparse_default {
                     "Failed to read configuration: {} is not a valid value",
                     $str
                 );
-                log::warn!("{}", e);
+                tracing::warn!("{}", e);
                 $default
             }
         }

diff --git a/commons/zenoh-shm/Cargo.toml b/commons/zenoh-shm/Cargo.toml
@@ -29,7 +29,7 @@ description = "Internal crate for zenoh."
 # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html
 
 [dependencies]
-log = { workspace = true }
+tracing = {workspace = true}
 serde = { workspace = true, features = ["default"] }
 shared_memory = { workspace = true }
 zenoh-buffers = { workspace = true }

diff --git a/commons/zenoh-shm/src/lib.rs b/commons/zenoh-shm/src/lib.rs
@@ -147,7 +147,7 @@ impl SharedMemoryBuf {
     }
 
     pub fn as_slice(&self) -> &[u8] {
-        log::trace!("SharedMemoryBuf::as_slice() == len = {:?}", self.len);
+        tracing::trace!("SharedMemoryBuf::as_slice() == len = {:?}", self.len);
         let bp = self.buf.load(Ordering::SeqCst);
         unsafe { std::slice::from_raw_parts(bp, self.len) }
     }
@@ -218,7 +218,7 @@ impl SharedMemoryReader {
                     info.shm_manager,
                     e
                 );
-                log::trace!("{}", e);
+                tracing::trace!("{}", e);
                 Err(ShmError(e).into())
             }
         }
@@ -243,7 +243,7 @@ impl SharedMemoryReader {
             }
             None => {
                 let e = zerror!("Unable to find shared memory segment: {}", info.shm_manager);
-                log::trace!("{}", e);
+                tracing::trace!("{}", e);
                 Err(ShmError(e).into())
             }
         }
@@ -298,7 +298,7 @@ impl SharedMemoryManager {
             .to_str()
             .ok_or_else(|| ShmError(zerror!("Unable to parse tmp directory: {:?}", temp_dir)))?
             .to_string();
-        log::trace!("Creating file at: {}", path);
+        tracing::trace!("Creating file at: {}", path);
         let real_size = size + ACCOUNTED_OVERHEAD;
         let shmem = match ShmemConf::new()
             .size(real_size)
@@ -335,7 +335,7 @@ impl SharedMemoryManager {
             busy_list,
             alignment: mem::align_of::<ChunkHeaderType>(),
         };
-        log::trace!(
+        tracing::trace!(
             "Created SharedMemoryManager for {:?}",
             shm.own_segment.as_ptr()
         );
@@ -361,7 +361,7 @@ impl SharedMemoryManager {
     }
 
     pub fn alloc(&mut self, len: usize) -> ZResult<SharedMemoryBuf> {
-        log::trace!("SharedMemoryManager::alloc({})", len);
+        tracing::trace!("SharedMemoryManager::alloc({})", len);
         // Always allocate a size that will keep the proper alignment requirements
         let required_len = align_addr_at(len + CHUNK_HEADER_SIZE, self.alignment);
         if self.available < required_len {
@@ -374,20 +374,23 @@ impl SharedMemoryManager {
             match self.free_list.pop() {
                 Some(mut chunk) if chunk.size >= required_len => {
                     self.available -= required_len;
-                    log::trace!("Allocator selected Chunk ({:?})", &chunk);
+                    tracing::trace!("Allocator selected Chunk ({:?})", &chunk);
                     if chunk.size - required_len >= MIN_FREE_CHUNK_SIZE {
                         let free_chunk = Chunk {
                             base_addr: unsafe { chunk.base_addr.add(required_len) },
                             offset: chunk.offset + required_len,
                             size: chunk.size - required_len,
                         };
-                        log::trace!("The allocation will leave a Free Chunk: {:?}", &free_chunk);
+                        tracing::trace!(
+                            "The allocation will leave a Free Chunk: {:?}",
+                            &free_chunk
+                        );
                         self.free_list.push(free_chunk);
                     }
                     chunk.size = required_len;
                     let shm_buf = self.free_chunk_map_to_shmbuf(&chunk);
-                    log::trace!("The allocated Chunk is ({:?})", &chunk);
-                    log::trace!("Allocated Shared Memory Buffer: {:?}", &shm_buf);
+                    tracing::trace!("The allocated Chunk is ({:?})", &chunk);
+                    tracing::trace!("Allocated Shared Memory Buffer: {:?}", &shm_buf);
                     self.busy_list.push(chunk);
                     Ok(shm_buf)
                 }
@@ -398,13 +401,13 @@ impl SharedMemoryManager {
                 }
                 None => {
                     let e = zerror!("SharedMemoryManager::alloc({}) cannot find any available chunk\nSharedMemoryManager::free_list = {:?}", len, self.free_list);
-                    log::trace!("{}", e);
+                    tracing::trace!("{}", e);
                     Err(e.into())
                 }
             }
         } else {
             let e = zerror!( "SharedMemoryManager does not have sufficient free memory to allocate {} bytes, try de-fragmenting!", len);
-            log::warn!("{}", e);
+            tracing::warn!("{}", e);
             Err(e.into())
         }
     }
@@ -465,7 +468,7 @@ impl SharedMemoryManager {
 
     /// Returns the amount of memory freed
     pub fn garbage_collect(&mut self) -> usize {
-        log::trace!("Running Garbage Collector");
+        tracing::trace!("Running Garbage Collector");
 
         let mut freed = 0;
         let (free, busy) = self
@@ -476,7 +479,7 @@ impl SharedMemoryManager {
 
         for f in free {
             freed += f.size;
-            log::trace!("Garbage Collecting Chunk: {:?}", f);
+            tracing::trace!("Garbage Collecting Chunk: {:?}", f);
             self.free_list.push(f)
         }
         self.available += freed;

diff --git a/commons/zenoh-task/Cargo.toml b/commons/zenoh-task/Cargo.toml
@@ -27,7 +27,7 @@ description = "Internal crate for zenoh."
 [dependencies]
 tokio = { workspace = true, features = ["default", "sync"] }
 futures = { workspace = true }
-log = { workspace = true }
+tracing = {workspace = true}
 zenoh-core = { workspace = true }
 zenoh-runtime = { workspace = true }
 tokio-util = { workspace = true, features = ["rt"] }
diff --git a/commons/zenoh-task/src/lib.rs b/commons/zenoh-task/src/lib.rs
@@ -122,7 +122,7 @@ impl TaskController {
             .await
             .is_err()
         {
-            log::error!("Failed to terminate {} tasks", self.tracker.len());
+            tracing::error!("Failed to terminate {} tasks", self.tracker.len());
             return self.tracker.len();
         }
         0
@@ -183,7 +183,7 @@ impl TerminatableTask {
     pub async fn terminate_async(self, timeout: Duration) -> bool {
         self.token.cancel();
         if tokio::time::timeout(timeout, self.handle).await.is_err() {
-            log::error!("Failed to terminate the task");
+            tracing::error!("Failed to terminate the task");
             return false;
         };
         true

diff --git a/commons/zenoh-util/Cargo.toml b/commons/zenoh-util/Cargo.toml
@@ -44,7 +44,8 @@ home = { workspace = true }
 humantime = { workspace = true }
 lazy_static = { workspace = true }
 libloading = { workspace = true }
-log = { workspace = true }
+tracing = {workspace = true}
+tracing-subscriber = {workspace = true}
 shellexpand = { workspace = true }
 zenoh-core = { workspace = true }
 zenoh-result = { workspace = true, features = ["default"] }

diff --git a/commons/zenoh-util/src/std_only/lib_loader.rs b/commons/zenoh-util/src/std_only/lib_loader.rs
@@ -12,11 +12,11 @@
 //   ZettaScale Zenoh Team, <[email protected]>
 //
 use libloading::Library;
-use log::{debug, warn};
 use std::env::consts::{DLL_PREFIX, DLL_SUFFIX};
 use std::ffi::OsString;
 use std::ops::Deref;
 use std::path::PathBuf;
+use tracing::{debug, warn};
 use zenoh_core::zconfigurable;
 use zenoh_result::{bail, ZResult};
 
@@ -111,7 +111,7 @@ impl LibLoader {
     pub unsafe fn search_and_load(&self, name: &str) -> ZResult<(Library, PathBuf)> {
         let filename = format!("{}{}{}", *LIB_PREFIX, name, *LIB_SUFFIX);
         let filename_ostr = OsString::from(&filename);
-        log::debug!(
+        tracing::debug!(
             "Search for library {} to load in {:?}",
             filename,
             self.search_paths
@@ -150,7 +150,7 @@ impl LibLoader {
         prefix: Option<&str>,
     ) -> Vec<(Library, PathBuf, String)> {
         let lib_prefix = format!("{}{}", *LIB_PREFIX, prefix.unwrap_or(""));
-        log::debug!(
+        tracing::debug!(
             "Search for libraries {}*{} to load in {:?}",
             lib_prefix,
             *LIB_SUFFIX,

diff --git a/commons/zenoh-util/src/std_only/log.rs b/commons/zenoh-util/src/std_only/log.rs
@@ -0,0 +1,36 @@
+use tracing_subscriber::EnvFilter;
+
+/// This is an utility function to enable the tracing formatting subscriber from
+/// the `RUST_LOG` environment variable.
+///
+/// # Safety
+/// Calling this function initializes a `lazy_static` in the `tracing` crate
+/// such static is not deallocated prior to process existing, thus tools such as `valgrind`
+/// will report a memory leak.
+/// Refer to this issue: https://github.com/tokio-rs/tracing/issues/2069
+pub fn init_log_from_env() {
+    let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("z=info"));
+
+    let subscriber = tracing_subscriber::fmt()
+        .with_env_filter(env_filter)
+        .with_thread_ids(true)
+        .with_thread_names(true)
+        .with_level(true)
+        .with_target(true);
+
+    let subscriber = subscriber.finish();
+    let _ = tracing::subscriber::set_global_default(subscriber);
+}
+
+/// This is an utility function to enables the default tracing subscriber with INFO level
+pub fn init_log() {
+    let subscriber = tracing_subscriber::fmt()
+        .with_max_level(tracing::Level::INFO)
+        .with_thread_ids(true)
+        .with_thread_names(true)
+        .with_level(true)
+        .with_target(true);
+
+    let subscriber = subscriber.finish();
+    let _ = tracing::subscriber::set_global_default(subscriber);
+}
diff --git a/commons/zenoh-util/src/std_only/mod.rs b/commons/zenoh-util/src/std_only/mod.rs
@@ -5,6 +5,10 @@ pub mod time_range;
 pub use lib_loader::*;
 pub mod timer;
 pub use timer::*;
+pub mod log;
+pub use log::init_log;
+pub use log::init_log_from_env;
+
 /// The "ZENOH_HOME" environement variable name
 pub const ZENOH_HOME_ENV_VAR: &str = "ZENOH_HOME";