diff --git a/Cargo.lock b/Cargo.lock index d338c4dc0..3f09d8906 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -520,6 +520,29 @@ version = "1.0.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "34aa73646ffb006b8f5147f3dc182bd4bcb190227ce861fc4a4844bf8e3cb2c0" +[[package]] +name = "env_filter" +version = "0.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1bf3c259d255ca70051b30e2e95b5446cdb8949ac4cd22c0d7fd634d89f568e2" +dependencies = [ + "log", + "regex", +] + +[[package]] +name = "env_logger" +version = "0.11.8" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "13c863f0904021b108aa8b2f55046443e6b1ebde8fd4a15c399893aae4fa069f" +dependencies = [ + "anstream", + "anstyle", + "env_filter", + "jiff", + "log", +] + [[package]] name = "equator" version = "0.4.2" @@ -546,6 +569,17 @@ version = "1.0.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "877a4ace8713b0bcf2a4e7eec82529c029f1d0619886d18145fea96c3ffe5c0f" +[[package]] +name = "erased-serde" +version = "0.4.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "89e8918065695684b2b0702da20382d5ae6065cf3327bc2d6436bd49a71ce9f3" +dependencies = [ + "serde", + "serde_core", + "typeid", +] + [[package]] name = "errno" version = "0.3.14" @@ -746,6 +780,30 @@ version = "1.0.15" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "4a5f13b858c8d314ee3e8f639011f7ccefe71f97f96e50151fb991f267928e2c" +[[package]] +name = "jiff" +version = "0.2.18" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e67e8da4c49d6d9909fe03361f9b620f58898859f5c7aded68351e85e71ecf50" +dependencies = [ + "jiff-static", + "log", + "portable-atomic", + "portable-atomic-util", + "serde_core", +] + +[[package]] +name = "jiff-static" +version = "0.2.18" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e0c84ee7f197eca9a86c6fd6cb771e55eb991632f15f2bc3ca6ec838929e6e78" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + [[package]] name = "lazy_static" version = "1.5.0" @@ -1069,6 +1127,26 @@ dependencies = [ "zerocopy", ] +[[package]] +name = "litebox_util_log" +version = "0.1.0" +dependencies = [ + "env_logger", + "litebox_util_log_macros", + "log", + "tracing", + "tracing-subscriber", +] + +[[package]] +name = "litebox_util_log_macros" +version = "0.1.0" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + [[package]] name = "lock_api" version = "0.4.14" @@ -1083,6 +1161,12 @@ name = "log" version = "0.4.28" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "34080505efa8e45a4b816c349525ebe327ceaa8559756f0356cba97ef3bf7432" +dependencies = [ + "serde", + "sval", + "sval_ref", + "value-bag", +] [[package]] name = "managed" @@ -1603,6 +1687,15 @@ dependencies = [ "syn", ] +[[package]] +name = "serde_fmt" +version = "1.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6e497af288b3b95d067a23a4f749f2861121ffcb2f6d8379310dcda040c345ed" +dependencies = [ + "serde_core", +] + [[package]] name = "serde_json" version = "1.0.145" @@ -1747,6 +1840,84 @@ version = "2.6.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "13c2bddecc57b384dee18652358fb23172facb8a2c51ccc10d74c157bdea3292" +[[package]] +name = "sval" +version = "2.16.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "502b8906c4736190684646827fbab1e954357dfe541013bbd7994d033d53a1ca" + +[[package]] +name = "sval_buffer" +version = "2.16.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c4b854348b15b6c441bdd27ce9053569b016a0723eab2d015b1fd8e6abe4f708" +dependencies = [ + "sval", + "sval_ref", +] + +[[package]] +name = "sval_dynamic" +version = "2.16.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a0bd9e8b74410ddad37c6962587c5f9801a2caadba9e11f3f916ee3f31ae4a1f" +dependencies = [ + "sval", +] + +[[package]] +name = "sval_fmt" +version = "2.16.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6fe17b8deb33a9441280b4266c2d257e166bafbaea6e66b4b34ca139c91766d9" +dependencies = [ + "itoa", + "ryu", + "sval", +] + +[[package]] +name = "sval_json" +version = "2.16.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "854addb048a5bafb1f496c98e0ab5b9b581c3843f03ca07c034ae110d3b7c623" +dependencies = [ + "itoa", + "ryu", + "sval", +] + +[[package]] +name = "sval_nested" +version = "2.16.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "96cf068f482108ff44ae8013477cb047a1665d5f1a635ad7cf79582c1845dce9" +dependencies = [ + "sval", + "sval_buffer", + "sval_ref", +] + +[[package]] +name = "sval_ref" +version = "2.16.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ed02126365ffe5ab8faa0abd9be54fbe68d03d607cd623725b0a71541f8aaa6f" +dependencies = [ + "sval", +] + +[[package]] +name = "sval_serde" +version = "2.16.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a263383c6aa2076c4ef6011d3bae1b356edf6ea2613e3d8e8ebaa7b57dd707d5" +dependencies = [ + "serde_core", + "sval", + "sval_nested", +] + [[package]] name = "syn" version = "2.0.106" @@ -1884,6 +2055,12 @@ dependencies = [ "tracing-log", ] +[[package]] +name = "typeid" +version = "1.0.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bc7d623258602320d5c55d1bc22793b57daff0ec7efc270ea7d55ce1d5f5471c" + [[package]] name = "typenum" version = "1.19.0" @@ -1908,6 +2085,42 @@ version = "0.1.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65" +[[package]] +name = "value-bag" +version = "1.11.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "943ce29a8a743eb10d6082545d861b24f9d1b160b7d741e0f2cdf726bec909c5" +dependencies = [ + "value-bag-serde1", + "value-bag-sval2", +] + +[[package]] +name = "value-bag-serde1" +version = "1.12.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "16530907bfe2999a1773ca5900a65101e092c70f642f25cc23ca0c43573262c5" +dependencies = [ + "erased-serde", + "serde_core", + "serde_fmt", +] + +[[package]] +name = "value-bag-sval2" +version = "1.12.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d00ae130edd690eaa877e4f40605d534790d1cf1d651e7685bd6a144521b251f" +dependencies = [ + "sval", + "sval_buffer", + "sval_dynamic", + "sval_fmt", + "sval_json", + "sval_ref", + "sval_serde", +] + [[package]] name = "version_check" version = "0.9.5" diff --git a/Cargo.toml b/Cargo.toml index 44d7eb5f3..a23e0e7e1 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -16,6 +16,8 @@ members = [ "litebox_shim_linux", "litebox_syscall_rewriter", "litebox_runner_snp", + "litebox_util_log", + "litebox_util_log_macros", # The CI tests are not meant to be released (thus are not prefixed with # `litebox_`), but exist purely to better manage development on LiteBox. "dev_tests", @@ -35,6 +37,8 @@ default-members = [ "litebox_shim_linux", "litebox_shim_optee", "litebox_syscall_rewriter", + "litebox_util_log", + "litebox_util_log_macros", "dev_tests", "dev_bench", ] diff --git a/litebox_util_log/Cargo.toml b/litebox_util_log/Cargo.toml new file mode 100644 index 000000000..7f05fba24 --- /dev/null +++ b/litebox_util_log/Cargo.toml @@ -0,0 +1,27 @@ +[package] +name = "litebox_util_log" +version = "0.1.0" +edition = "2024" +description = "Logging facade for LiteBox that supports multiple backends" + +[features] +default = ["backend_log"] +backend_log = ["dep:log", "log/kv"] +backend_tracing = ["dep:tracing"] + +# Key-value capture features (mirrors log's kv features) +kv_std = ["log?/kv_std"] +kv_sval = ["log?/kv_sval"] +kv_serde = ["log?/kv_serde"] + +[dependencies] +log = { version = "0.4", optional = true, default-features = false } +tracing = { version = "0.1", optional = true, default-features = false } +litebox_util_log_macros = { path = "../litebox_util_log_macros" } + +[dev-dependencies] +env_logger = { version = "0.11", features = ["unstable-kv"] } +tracing-subscriber = { version = "0.3", features = ["env-filter"] } + +[lints] +workspace = true diff --git a/litebox_util_log/src/backend_log.rs b/litebox_util_log/src/backend_log.rs new file mode 100644 index 000000000..1dd61a6c8 --- /dev/null +++ b/litebox_util_log/src/backend_log.rs @@ -0,0 +1,108 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT license. + +//! Log backend implementation. +//! +//! This module provides the backend implementation when using the `log` crate +//! with proper structured key-value logging via the `kv` feature. +//! +//! Since `log` does not have native span support, spans are emulated by: +//! - Logging a `[SPAN ENTER]` message when the span is created +//! - Logging a `[SPAN EXIT]` message when the span guard is dropped +//! +//! This allows log subscribers to correlate related log messages, though it +//! lacks the full hierarchical context that `tracing` provides. + +impl crate::Level { + /// Converts this level to the corresponding `log::Level`. + #[doc(hidden)] + pub const fn to_log_level(self) -> log::Level { + match self { + crate::Level::Error => log::Level::Error, + crate::Level::Warn => log::Level::Warn, + crate::Level::Info => log::Level::Info, + crate::Level::Debug => log::Level::Debug, + crate::Level::Trace => log::Level::Trace, + } + } +} + +/// RAII guard that logs span exit when dropped. +/// +/// This type is returned by span macros (e.g., [`info_span!`](crate::info_span)) when +/// using the `backend_log` feature. Holding this guard keeps the logical span "active". +/// When the guard is dropped (either explicitly or when it goes out of scope), +/// a `[SPAN EXIT]` message is logged at the same level as the span entry. +/// +/// # Example +/// +/// ```ignore +/// let _guard = info_span!("my_operation"); +/// // ... do work ... +/// // [SPAN EXIT] is logged here when _guard goes out of scope +/// ``` +pub struct SpanGuard { + /// The name of the span, used in the exit log message. + #[doc(hidden)] + pub name: &'static str, + /// The log level at which to emit the exit message. + #[doc(hidden)] + pub level: crate::Level, + /// The module path for the log target. + #[doc(hidden)] + pub module_path: &'static str, +} + +impl Drop for SpanGuard { + fn drop(&mut self) { + log::log!(target: self.module_path, self.level.to_log_level(), span = self.name; "[SPAN EXIT]"); + } +} + +/// Internal macro for log backend implementation. +/// +/// This macro dispatches log events to the `log` crate, properly using log's `kv` +/// feature to pass structured key-value pairs. The match converts from our +/// [`Level`](crate::Level) enum to [`log::Level`]. +/// +/// Not intended for direct use; called by the public logging macros. +#[doc(hidden)] +#[macro_export] +macro_rules! __log_impl { + ($level:expr, $($key:tt $(:$cap:tt)? $(= $value:expr)?),+ ; $msg:literal) => {{ + $crate::__private::log::log!( + $crate::Level::to_log_level($level), + $($key $(:$cap)? $(= $value)?),+; + $msg + ) + }}; + ($level:expr, $msg:literal) => { + $crate::__private::log::log!($crate::Level::to_log_level($level), $msg) + }; +} + +/// Internal macro for span implementation with log backend. +/// +/// Creates a [`SpanGuard`] and emits a `[SPAN ENTER]` log message. The guard +/// will emit `[SPAN EXIT]` when dropped. Key-value pairs are included in the +/// entry message using log's `kv` syntax. +/// +/// Not intended for direct use; called by the public span macros. +#[doc(hidden)] +#[macro_export] +macro_rules! __span_impl { + ($level:expr, $name:expr, $($key:tt $(:$cap:tt)? $(= $value:expr)?),+) => {{ + let __level = $level; + $crate::__private::log::log!( + $crate::Level::to_log_level(__level), + span = $name, $($key $(:$cap)? $(= $value)?),+; + "[SPAN ENTER]" + ); + $crate::SpanGuard { name: $name, level: __level, module_path: module_path!() } + }}; + ($level:expr, $name:expr) => {{ + let __level = $level; + $crate::__private::log::log!($crate::Level::to_log_level(__level), span = $name; "[SPAN ENTER]"); + $crate::SpanGuard { name: $name, level: __level, module_path: module_path!() } + }}; +} diff --git a/litebox_util_log/src/backend_tracing.rs b/litebox_util_log/src/backend_tracing.rs new file mode 100644 index 000000000..1d15a086a --- /dev/null +++ b/litebox_util_log/src/backend_tracing.rs @@ -0,0 +1,210 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT license. + +//! Tracing backend implementation. +//! +//! This module provides the backend implementation when using the `tracing` crate. +//! Unlike the log backend, this provides full native span support with proper +//! hierarchical context propagation. +//! +//! The macros in this module transform our unified key-value syntax into +//! tracing's native field syntax using a tt-muncher pattern. + +impl crate::Level { + /// Converts this level to the corresponding `tracing::Level`. + #[doc(hidden)] + pub const fn to_tracing_level(self) -> tracing::Level { + match self { + crate::Level::Error => tracing::Level::ERROR, + crate::Level::Warn => tracing::Level::WARN, + crate::Level::Info => tracing::Level::INFO, + crate::Level::Debug => tracing::Level::DEBUG, + crate::Level::Trace => tracing::Level::TRACE, + } + } +} + +/// RAII guard that wraps a tracing span's entered guard. +/// +/// This type is returned by span macros (e.g., [`info_span!`](crate::info_span)) when +/// using the `backend_tracing` feature. The span remains "entered" (active) as long +/// as this guard exists. When dropped, the span is exited. +/// +/// Unlike the log backend's `SpanGuard`, this provides full tracing semantics +/// including hierarchical span relationships and context propagation. +/// +/// # Example +/// +/// ```ignore +/// let _guard = info_span!("my_operation"); +/// // Span is now entered and active +/// info!("This log is inside the span"); +/// // Span exits when _guard goes out of scope +/// ``` +pub struct SpanGuard { + /// The wrapped tracing span guard. Public for macro access but not part of + /// the public API. + #[doc(hidden)] + #[allow(dead_code)] + pub inner: tracing::span::EnteredSpan, +} + +/// Internal macro for tracing backend implementation. +/// +/// This macro transforms our unified key-value syntax into tracing's native +/// event syntax. The transformation is handled by [`__tracing_dispatch`]. +/// +/// Not intended for direct use; called by the public logging macros. +#[doc(hidden)] +#[macro_export] +macro_rules! __log_impl { + ($level:expr, $($key:ident $(:$cap:tt)? $(= $value:expr)?),+ ; $msg:literal) => {{ + $crate::__tracing_dispatch!( + [event] + [$level] + [$msg] + [] + [$($key $(:$cap)? $(= $value)?),+] + ) + }}; + ($level:expr, $msg:literal) => { + $crate::__private::tracing::event!($crate::Level::to_tracing_level($level), $msg) + }; +} + +/// Unified internal macro to dispatch and process key-value pairs for tracing. +/// +/// Uses a tt-muncher pattern to transform fields from our unified syntax +/// (e.g., `key:? = value`) into tracing's native syntax (e.g., `key = ?value`). +/// +/// The macro processes fields one at a time, accumulating transformed fields +/// until no input remains, then emits the final event or span based on mode. +/// +/// Arguments: `[mode] [level] [msg_or_name] [accumulated_fields] [remaining_input]` +/// +/// Where `mode` is either `event` or `span`. +#[doc(hidden)] +#[macro_export] +macro_rules! __tracing_dispatch { + // Field: key:? = value (Debug with explicit value) + ([$mode:ident] [$level:expr] [$target:tt] [$($acc:tt)*] [$key:ident :? = $value:expr $(, $($rest:tt)*)?]) => { + $crate::__tracing_dispatch!( + [$mode] [$level] [$target] + [$($acc)* $key = ?$value,] + [$($($rest)*)?] + ) + }; + + // Field: key:debug = value + ([$mode:ident] [$level:expr] [$target:tt] [$($acc:tt)*] [$key:ident :debug = $value:expr $(, $($rest:tt)*)?]) => { + $crate::__tracing_dispatch!( + [$mode] [$level] [$target] + [$($acc)* $key = ?$value,] + [$($($rest)*)?] + ) + }; + + // Field: key:% = value (Display with explicit value) + ([$mode:ident] [$level:expr] [$target:tt] [$($acc:tt)*] [$key:ident :% = $value:expr $(, $($rest:tt)*)?]) => { + $crate::__tracing_dispatch!( + [$mode] [$level] [$target] + [$($acc)* $key = %$value,] + [$($($rest)*)?] + ) + }; + + // Field: key:display = value + ([$mode:ident] [$level:expr] [$target:tt] [$($acc:tt)*] [$key:ident :display = $value:expr $(, $($rest:tt)*)?]) => { + $crate::__tracing_dispatch!( + [$mode] [$level] [$target] + [$($acc)* $key = %$value,] + [$($($rest)*)?] + ) + }; + + // Field: key:err = value (errors use Display) + ([$mode:ident] [$level:expr] [$target:tt] [$($acc:tt)*] [$key:ident :err = $value:expr $(, $($rest:tt)*)?]) => { + $crate::__tracing_dispatch!( + [$mode] [$level] [$target] + [$($acc)* $key = %$value,] + [$($($rest)*)?] + ) + }; + + // Field: key:sval = value (fallback to Debug) + ([$mode:ident] [$level:expr] [$target:tt] [$($acc:tt)*] [$key:ident :sval = $value:expr $(, $($rest:tt)*)?]) => { + $crate::__tracing_dispatch!( + [$mode] [$level] [$target] + [$($acc)* $key = ?$value,] + [$($($rest)*)?] + ) + }; + + // Field: key:serde = value (fallback to Debug) + ([$mode:ident] [$level:expr] [$target:tt] [$($acc:tt)*] [$key:ident :serde = $value:expr $(, $($rest:tt)*)?]) => { + $crate::__tracing_dispatch!( + [$mode] [$level] [$target] + [$($acc)* $key = ?$value,] + [$($($rest)*)?] + ) + }; + + // Field: key = value (no capture mode) + ([$mode:ident] [$level:expr] [$target:tt] [$($acc:tt)*] [$key:ident = $value:expr $(, $($rest:tt)*)?]) => { + $crate::__tracing_dispatch!( + [$mode] [$level] [$target] + [$($acc)* $key = $value,] + [$($($rest)*)?] + ) + }; + + // Field: key:cap (shorthand with capture mode) -> delegates to key:cap = key + ([$mode:ident] [$level:expr] [$target:tt] [$($acc:tt)*] [$key:ident :$cap:tt $(, $($rest:tt)*)?]) => { + $crate::__tracing_dispatch!( + [$mode] [$level] [$target] + [$($acc)*] + [$key :$cap = $key $(, $($rest)*)?] + ) + }; + + // Field: key (bare identifier) -> delegates to key = key + ([$mode:ident] [$level:expr] [$target:tt] [$($acc:tt)*] [$key:ident $(, $($rest:tt)*)?]) => { + $crate::__tracing_dispatch!( + [$mode] [$level] [$target] + [$($acc)*] + [$key = $key $(, $($rest)*)?] + ) + }; + + ([event] [$level:expr] [$msg:literal] [$($acc:tt)*] []) => { + $crate::__private::tracing::event!($crate::Level::to_tracing_level($level), $($acc)* $msg) + }; + ([span] [$level:expr] [$name:expr] [$($acc:tt)*] []) => {{ + let span = $crate::__private::tracing::span!($crate::Level::to_tracing_level($level), $name, $($acc)*); + $crate::SpanGuard { inner: span.entered() } + }}; +} + +/// Internal macro for span implementation with tracing backend. +/// +/// Creates a tracing span with the given name and fields, enters it, and +/// returns a [`SpanGuard`] wrapping the entered span. +/// +/// Not intended for direct use; called by the public span macros. +#[doc(hidden)] +#[macro_export] +macro_rules! __span_impl { + ($level:expr, $name:expr, $($key:ident $(:$cap:tt)? $(= $value:expr)?),+) => {{ + $crate::__tracing_dispatch!( + [span] + [$level] + [$name] + [] + [$($key $(:$cap)? $(= $value)?),+] + ) + }}; + ($level:expr, $name:expr) => {{ + let span = $crate::__private::tracing::span!($crate::Level::to_tracing_level($level), $name,); + $crate::SpanGuard { inner: span.entered() } + }}; +} diff --git a/litebox_util_log/src/lib.rs b/litebox_util_log/src/lib.rs new file mode 100644 index 000000000..9b89b4ffa --- /dev/null +++ b/litebox_util_log/src/lib.rs @@ -0,0 +1,116 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT license. + +//! # LiteBox Logging Utilities +//! +//! A unified logging facade for LiteBox that abstracts over different logging backends. +//! +//! This crate provides macros for structured logging and tracing spans that work +//! consistently regardless of whether the underlying backend is `log` or `tracing`. +//! +//! ## Features +//! +//! - `backend_log` (default): Uses the [`log`](https://docs.rs/log) crate for logging events. +//! Spans are emulated by logging events at span entry and exit. +//! +//! - `backend_tracing`: Uses the [`tracing`](https://docs.rs/tracing) crate with full span support. +//! However, since `tracing` does not natively support `sval` or `serde` key-value capture, +//! values captured with `:sval` or `:serde` are silently downgraded to their `Debug` (`{:?}`) +//! representations. +//! +//! When both features are enabled, `backend_tracing` takes precedence. +//! +//! ## Key-Value Capture Modes +//! +//! This crate supports the same capture modes as `log`'s `kv` feature: +//! +//! - `:?` or `:debug` - Capture the value using `Debug` +//! - `:%` or `:display` - Capture the value using `Display` +//! - `:err` - Capture the value using `std::error::Error` (requires `kv_std`) +//! - `:sval` - Capture the value using `sval::Value` (requires `kv_sval`) +//! - `:serde` - Capture the value using `serde::Serialize` (requires `kv_serde`) +//! +//! ## Example +//! +//! ```ignore +//! use litebox_util_log::{info, debug, info_span, instrument}; +//! +//! // Simple logging +//! info!("Hello, world!"); +//! +//! // Logging with key-value pairs +//! let user_id = 42; +//! info!(user_id:? = user_id; "User logged in"); +//! +//! // Using spans (returns a guard, exits when dropped) +//! let _span = info_span!("my_operation", request_id:? = req_id); +//! // ... do work ... +//! debug!("Processing request"); +//! // span exits when _span is dropped +//! +//! // Using the instrument attribute macro +//! #[instrument(level = debug, fields(user_id:?))] +//! fn process_user(user_id: u64, data: &str) { +//! info!("Processing user"); +//! } +//! ``` + +#![no_std] + +#[cfg(not(any(feature = "backend_log", feature = "backend_tracing")))] +compile_error!("Either `backend_log` or `backend_tracing` feature must be enabled."); + +#[macro_use] +mod macros; + +#[cfg(all(feature = "backend_log", not(feature = "backend_tracing")))] +#[macro_use] +mod backend_log; + +#[cfg(feature = "backend_tracing")] +#[macro_use] +mod backend_tracing; + +pub use litebox_util_log_macros::instrument; + +/// Log level that abstracts over backend-specific level types. +/// +/// Levels are ordered from most severe to least severe: `Error` > `Warn` > `Info` > `Debug` > `Trace`. +/// This ordering is used by logging implementations to filter messages. +#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)] +pub enum Level { + /// Serious problems that need immediate attention. + Error, + /// Potential issues or unexpected situations. + Warn, + /// General informational messages. + Info, + /// Debugging information useful during development. + Debug, + /// Very verbose debugging, typically disabled in production. + Trace, +} + +#[cfg(all(feature = "backend_log", not(feature = "backend_tracing")))] +pub use backend_log::SpanGuard; + +#[cfg(feature = "backend_tracing")] +pub use backend_tracing::SpanGuard; + +/// Internal module exposing backend types for use by exported macros. +/// +/// This module is public only because macros need access to backend types at the +/// call site. It is not part of the public API and should not be used directly. +/// Breaking changes to this module are not considered semver violations. +#[doc(hidden)] +pub mod __private { + #[cfg(all(feature = "backend_log", not(feature = "backend_tracing")))] + pub use log; + #[cfg(all(feature = "backend_log", not(feature = "backend_tracing")))] + pub use log::Level; + + #[cfg(feature = "backend_tracing")] + pub use tracing; + #[cfg(feature = "backend_tracing")] + pub use tracing::Level; +} diff --git a/litebox_util_log/src/macros.rs b/litebox_util_log/src/macros.rs new file mode 100644 index 000000000..ceb7fa37a --- /dev/null +++ b/litebox_util_log/src/macros.rs @@ -0,0 +1,88 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT license. + +//! Public logging and span macros. +//! +//! All macros support two forms: +//! - Simple message: `info!("message")` +//! - Key-value pairs with message: `info!(key:? = value; "message")` + +/// Log at the specified level. +#[macro_export] +macro_rules! log { + ($level:expr, $($key:ident $(:$cap:tt)? $(= $value:expr)?),+ ; $msg:literal) => { + $crate::__log_impl!($level, $($key $(:$cap)? $(= $value)?),+ ; $msg) + }; + ($level:expr, $msg:literal) => { + $crate::__log_impl!($level, $msg) + }; +} + +/// Create a span at the specified level. Returns a guard that exits the span when dropped. +#[macro_export] +macro_rules! span { + ($level:expr, $name:expr, $($key:ident $(:$cap:tt)? $(= $value:expr)?),+) => { + $crate::__span_impl!($level, $name, $($key $(:$cap)? $(= $value)?),+) + }; + ($level:expr, $name:expr) => { + $crate::__span_impl!($level, $name) + }; +} + +/// Helper macro to work around the inability to use `$` in nested macro definitions. +macro_rules! with_dollar_sign { + ($($body:tt)*) => { + macro_rules! __with_dollar_sign { $($body)* } + __with_dollar_sign!($); + } +} + +macro_rules! define_log_macro { + ($name:ident, $level:ident) => { + with_dollar_sign! { + ($d:tt) => { + #[doc = concat!("Log at the ", stringify!($level), " level.")] + #[macro_export] + macro_rules! $name { + ($d( $d key:ident $d(:$d cap:tt)? $d(= $d value:expr)?),+ ; $d msg:literal) => { + $crate::__log_impl!($crate::Level::$level, $d( $d key $d(:$d cap)? $d(= $d value)?),+ ; $d msg) + }; + ($d msg:literal) => { + $crate::__log_impl!($crate::Level::$level, $d msg) + }; + } + } + } + }; +} + +macro_rules! define_span_macro { + ($name:ident, $level:ident) => { + with_dollar_sign! { + ($d:tt) => { + #[doc = concat!("Create a ", stringify!($level), "-level span.")] + #[macro_export] + macro_rules! $name { + ($d name_arg:expr, $d( $d key:ident $d(:$d cap:tt)? $d(= $d value:expr)?),+) => { + $crate::span!($crate::Level::$level, $d name_arg, $d( $d key $d(:$d cap)? $d(= $d value)?),+) + }; + ($d name_arg:expr) => { + $crate::span!($crate::Level::$level, $d name_arg) + }; + } + } + } + }; +} + +define_log_macro!(error, Error); +define_log_macro!(warn, Warn); +define_log_macro!(info, Info); +define_log_macro!(debug, Debug); +define_log_macro!(trace, Trace); + +define_span_macro!(error_span, Error); +define_span_macro!(warn_span, Warn); +define_span_macro!(info_span, Info); +define_span_macro!(debug_span, Debug); +define_span_macro!(trace_span, Trace); diff --git a/litebox_util_log/tests/facade.rs b/litebox_util_log/tests/facade.rs new file mode 100644 index 000000000..a2147a6b7 --- /dev/null +++ b/litebox_util_log/tests/facade.rs @@ -0,0 +1,195 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT license. + +//! Tests for the litebox_util_log facade. +//! +//! These tests exercise the unified API and work with either backend. + +use litebox_util_log::{ + Level, debug, debug_span, error, error_span, info, info_span, instrument, log, span, trace, + trace_span, warn, warn_span, +}; + +#[test] +fn test_log_macro_simple() { + log!(Level::Info, "simple log message"); + log!(Level::Error, "error level message"); + log!(Level::Warn, "warning level message"); + log!(Level::Debug, "debug level message"); + log!(Level::Trace, "trace level message"); +} + +#[test] +fn test_log_macro_with_kv() { + let value = 42; + log!(Level::Info, value:?; "message with debug capture"); + log!(Level::Info, value:debug; "message with explicit debug"); + + let value = "hello"; + log!(Level::Info, value:%; "message with display capture"); + log!(Level::Info, value:display; "message with explicit display"); + + log!(Level::Info, count:? = 100; "explicit value"); + log!(Level::Info, name:% = "test"; "explicit display value"); + + let x = 1; + let y = 2; + log!(Level::Info, x, y:?; "multiple key-values"); + + let debug_val = vec![1, 2, 3]; + let display_val = "hello"; + log!(Level::Info, debug_val:?, display_val:%; "mixed captures"); + + let implicit = 42; + log!(Level::Info, implicit:?, explicit:? = 100; "mixed implicit and explicit"); +} + +#[test] +#[cfg(feature = "kv_std")] +fn test_log_macro_with_kv_err() { + let error = "something went wrong"; + log!(Level::Error, error:err; "error capture"); +} + +#[test] +#[cfg(feature = "kv_sval")] +fn test_log_macro_with_kv_sval() { + let data = vec![1, 2, 3]; + log!(Level::Debug, data:sval; "sval capture"); +} + +#[test] +#[cfg(feature = "kv_serde")] +fn test_log_macro_with_kv_serde() { + let data = (1, "two", 3.0); + log!(Level::Debug, data:serde; "serde capture"); +} + +#[test] +fn test_level_specific_macros() { + error!("error message"); + warn!("warn message"); + info!("info message"); + debug!("debug message"); + trace!("trace message"); + + let value = 42; + error!(value:?; "error with kv"); + warn!(value:?; "warn with kv"); + info!(value:?; "info with kv"); + debug!(value:?; "debug with kv"); + trace!(value:?; "trace with kv"); +} + +#[test] +fn test_span_macros() { + let _guard = span!(Level::Info, "test_span"); + + let request_id = 12345; + let _guard = span!(Level::Info, "request_handler", request_id:?); + + let _e = error_span!("error_span"); + let _w = warn_span!("warn_span"); + let _i = info_span!("info_span"); + let _d = debug_span!("debug_span"); + let _t = trace_span!("trace_span"); + + let id = 1; + let _e = error_span!("error_span", id:?); + let _w = warn_span!("warn_span", id:?); + let _i = info_span!("info_span", id:?); + let _d = debug_span!("debug_span", id:?); + let _t = trace_span!("trace_span", id:?); +} + +#[test] +fn test_span_scoping() { + { + let _guard = info_span!("scoped_span"); + info!("inside span"); + } + info!("after span dropped"); + + let _outer = info_span!("outer"); + { + let _inner = debug_span!("inner"); + debug!("in inner span"); + } + info!("back in outer span"); +} + +#[instrument(level = info)] +fn instrumented_simple() { + info!("inside instrumented function"); +} + +#[instrument(level = debug)] +fn instrumented_with_args(x: u32, y: &str) { + debug!("processing"); + let _ = (x, y); +} + +#[instrument(level = trace, fields(id:?, name:%))] +fn instrumented_with_specific_fields(id: u64, name: &str, _secret: &str) { + trace!("handling request"); + let _ = (id, name); +} + +#[instrument(level = info, skip(password))] +fn instrumented_with_skip(username: &str, password: &str) { + info!("authenticating user"); + let _ = (username, password); +} + +#[instrument(level = debug, skip_all)] +fn instrumented_skip_all(sensitive: &str, also_sensitive: u64) { + debug!("doing something sensitive"); + let _ = (sensitive, also_sensitive); +} + +#[instrument(level = warn, name = "custom_span_name")] +fn instrumented_with_custom_name() { + warn!("inside custom named span"); +} + +#[instrument(level = info)] +fn instrumented_returning_value(x: i32) -> i32 { + x * 2 +} + +#[instrument(level = debug, fields(a:debug, b:display))] +fn instrumented_with_explicit_capture_modes(a: i32, b: &str) { + debug!("explicit modes"); + let _ = (a, b); +} + +#[derive(Debug)] +struct TestStruct { + value: i32, +} + +impl TestStruct { + #[instrument(level = info, fields(self.value:?, self:?, test = 5, test2 = self))] + fn instrumented_method(&self) { + info!("in method"); + } +} + +#[test] +fn test_instrument() { + #[instrument(level = debug)] + fn nested() { + debug!("in nested"); + } + + instrumented_simple(); + instrumented_with_args(42, "hello"); + instrumented_with_specific_fields(123, "test", "secret_value"); + instrumented_with_skip("alice", "hunter2"); + instrumented_skip_all("secret", 42); + instrumented_with_custom_name(); + assert_eq!(instrumented_returning_value(21), 42); + instrumented_with_explicit_capture_modes(42, "hello"); + nested(); + TestStruct { value: 7 }.instrumented_method(); +} diff --git a/litebox_util_log_macros/Cargo.toml b/litebox_util_log_macros/Cargo.toml new file mode 100644 index 000000000..ca048f06a --- /dev/null +++ b/litebox_util_log_macros/Cargo.toml @@ -0,0 +1,16 @@ +[package] +name = "litebox_util_log_macros" +version = "0.1.0" +edition = "2024" +description = "Procedural macros for litebox_util_log" + +[lib] +proc-macro = true + +[dependencies] +proc-macro2 = "1" +quote = "1" +syn = { version = "2", features = ["full", "parsing", "extra-traits"] } + +[lints] +workspace = true diff --git a/litebox_util_log_macros/src/lib.rs b/litebox_util_log_macros/src/lib.rs new file mode 100644 index 000000000..3128e48ab --- /dev/null +++ b/litebox_util_log_macros/src/lib.rs @@ -0,0 +1,376 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT license. + +//! Procedural macros for `litebox_util_log`. Not to be imported directly. +//! +//! This crate provides the `#[instrument]` attribute macro for automatically +//! instrumenting functions with spans. + +use proc_macro::TokenStream; +use proc_macro2::TokenStream as TokenStream2; +use quote::{ToTokens, quote}; +use syn::{ + Expr, FnArg, Ident, ItemFn, Pat, Token, + parse::{Parse, ParseStream}, + parse_macro_input, + punctuated::Punctuated, + token, +}; + +/// Specifies which arguments to capture and how. +#[derive(Debug, Clone)] +struct CapturedArg { + /// The source of the value to capture (and implicit key when no explicit key/value). + source: CaptureSource, + /// The capture mode (e.g., `?` for Debug, `%` for Display). + capture_mode: Option, + /// Explicit value expression when `= ` is provided. + /// When `Some`, `source` holds the explicit key ident as `CaptureSource::Arg`. + value_expr: Option, +} + +/// Where the captured value comes from. +#[derive(Debug, Clone)] +enum CaptureSource { + /// A plain function argument, captured by name (also used as explicit key when + /// `value_expr` is `Some`). + Arg(Ident), + /// A field on `self`, e.g. `self.value`. The key in the span is the field name. + SelfField(Ident), + /// The entirety of `&self`. The key in the span is `self_`. + Self_, +} + +#[derive(Debug, Clone, Copy)] +enum CaptureMode { + Debug, + Display, +} + +impl Parse for CapturedArg { + fn parse(input: ParseStream) -> syn::Result { + let source = if input.peek(Token![self]) { + input.parse::()?; + if input.peek(Token![.]) { + input.parse::()?; + CaptureSource::SelfField(input.parse()?) + } else { + CaptureSource::Self_ + } + } else { + CaptureSource::Arg(input.parse()?) + }; + let capture_mode = if input.peek(Token![:]) { + input.parse::()?; + if input.peek(Token![?]) { + input.parse::()?; + Some(CaptureMode::Debug) + } else if input.peek(Token![%]) { + input.parse::()?; + Some(CaptureMode::Display) + } else { + let ident: Ident = input.parse()?; + match ident.to_string().as_str() { + "debug" => Some(CaptureMode::Debug), + "display" => Some(CaptureMode::Display), + other => { + return Err(syn::Error::new( + ident.span(), + format!( + "unknown capture mode `{other}`, expected `?`, `%`, `debug`, or `display`" + ), + )); + } + } + } + } else { + None + }; + + // Optional `= ` for an explicit value. Only valid when the key is a + // plain ident (i.e. not a bare `self` or `self.field` source). + let value_expr = if input.peek(Token![=]) { + match &source { + CaptureSource::Arg(_) => { + input.parse::()?; + Some(input.parse::()?) + } + CaptureSource::SelfField(field) => { + return Err(syn::Error::new( + field.span(), + "`self.field = expr` is not valid; use `key = self.field` instead", + )); + } + CaptureSource::Self_ => { + return Err(syn::Error::new( + proc_macro2::Span::call_site(), + "`self = expr` is not valid; use `key = self` instead", + )); + } + } + } else { + None + }; + + Ok(CapturedArg { + source, + capture_mode, + value_expr, + }) + } +} + +/// Arguments to the `#[instrument]` attribute. +#[derive(Default)] +struct InstrumentArgs { + /// The log level for the span. + level: Option, + /// Arguments to capture. If None, capture all non-skipped arguments with Debug. + /// Supports plain argument names and `self.field` references for methods. + fields: Option>, + /// Custom span name. If None, use the function name. + name: Option, + /// Arguments to skip from automatic capture. + skip: Vec, + /// Skip all arguments. + skip_all: bool, +} + +impl Parse for InstrumentArgs { + fn parse(input: ParseStream) -> syn::Result { + let mut args = InstrumentArgs::default(); + + while !input.is_empty() { + let key: Ident = input.parse()?; + + match key.to_string().as_str() { + "level" => { + input.parse::()?; + args.level = Some(input.parse()?); + } + "fields" => { + let content; + syn::parenthesized!(content in input); + let fields: Punctuated = + content.parse_terminated(CapturedArg::parse, Token![,])?; + args.fields = Some(fields.into_iter().collect()); + } + "name" => { + input.parse::()?; + let lit: syn::LitStr = input.parse()?; + args.name = Some(lit.value()); + } + "skip" => { + let content; + syn::parenthesized!(content in input); + let skipped: Punctuated = + content.parse_terminated(Ident::parse, Token![,])?; + args.skip = skipped.into_iter().collect(); + } + "skip_all" => { + args.skip_all = true; + } + other => { + return Err(syn::Error::new( + key.span(), + format!("unknown argument `{other}`"), + )); + } + } + + if !input.is_empty() { + input.parse::()?; + } + } + + Ok(args) + } +} + +/// Instruments a function with a span that is entered on function entry and +/// exited on function return. +/// +/// # Arguments +/// +/// - `level` - The log level for the span (e.g., `info`, `debug`, `trace`). +/// Defaults to `debug` if not specified. +/// - `fields(...)` - Specific fields to capture as span fields. When `fields(...)` is provided, +/// only the listed fields are captured; unlisted arguments (including `self` and its fields) are +/// ignored. Each entry has the form `key [':' mode] ['=' expr]`: +/// - `key` is an ident, `self`, or `self.field`. +/// - `mode` is `?`/`debug` for `Debug` or `%`/`display` for `Display` +/// (defaults to `Debug`). +/// - When `= expr` is omitted the value is inferred from `key`: a plain +/// ident reads the same-named fn argument, `self.field` reads that field, +/// and `self` captures `&self` under the span key `self_`. +/// - When `= expr` is present, `key` must be a plain ident and `expr` can +/// be any Rust expression (e.g. `self.bar`, `self`, `some_fn()`). +/// - `name` - Custom span name. Defaults to the function name. +/// - `skip(...)` - Arguments to skip from automatic capture. Has no effect on +/// `self` fields, which are never captured automatically. +/// - `skip_all` - Skip capturing all arguments. +/// +/// # Example +/// +/// ```ignore +/// use litebox_util_log::instrument; +/// +/// // Basic usage - captures all arguments with Debug at info level +/// #[instrument(level = info)] +/// fn process_request(request_id: u64, data: &str) { +/// // ... +/// } +/// +/// // Capture specific fields with custom modes +/// #[instrument(level = debug, fields(id:?, name:%))] +/// fn handle_user(id: u64, name: &str, password: &str) { +/// // password is not captured +/// } +/// +/// // Capture self fields on a method +/// #[instrument(level = info, fields(self.id:?, self.name:%))] +/// fn process(&self) { +/// // ... +/// } +/// +/// // Capture &self entirely on a method +/// #[instrument(level = debug, fields(self:?))] +/// fn process(&self) { +/// // ... +/// } +/// +/// // Explicit key with an arbitrary value expression +/// #[instrument(level = debug, fields(user_id = self.id, name:% = self.name))] +/// fn process(&self) { +/// // user_id key uses Debug (default), name key uses Display +/// } +/// +/// // Rename an argument in the span +/// #[instrument(level = info, fields(request = req))] +/// fn handle(req: &Request) { +/// // ... +/// } +/// +/// // Skip specific arguments +/// #[instrument(level = trace, skip(sensitive_data))] +/// fn process(input: &str, sensitive_data: &[u8]) { +/// // ... +/// } +/// +/// // Custom span name +/// #[instrument(level = info, name = "my_custom_span")] +/// fn my_function() { +/// // ... +/// } +/// ``` +#[proc_macro_attribute] +pub fn instrument(attr: TokenStream, item: TokenStream) -> TokenStream { + let args = parse_macro_input!(attr as InstrumentArgs); + let input_fn = parse_macro_input!(item as ItemFn); + + instrument_impl(args, input_fn).into() +} + +fn instrument_impl(args: InstrumentArgs, mut input_fn: ItemFn) -> TokenStream2 { + let fn_name = &input_fn.sig.ident; + let span_name = args.name.unwrap_or_else(|| fn_name.to_string()); + + // Determine the level + let level = args.level.map_or_else( + || quote! { ::litebox_util_log::Level::Debug }, + |l| { + let level_str = l.to_string().to_lowercase(); + match level_str.as_str() { + "error" => quote! { ::litebox_util_log::Level::Error }, + "warn" => quote! { ::litebox_util_log::Level::Warn }, + "info" => quote! { ::litebox_util_log::Level::Info }, + "debug" => quote! { ::litebox_util_log::Level::Debug }, + "trace" => quote! { ::litebox_util_log::Level::Trace }, + _ => quote! { ::litebox_util_log::Level::#l }, + } + }, + ); + + // Extract function arguments that can be captured + let fn_args: Vec<(Ident, bool)> = input_fn + .sig + .inputs + .iter() + .filter_map(|arg| { + if let FnArg::Typed(pat_type) = arg + && let Pat::Ident(pat_ident) = &*pat_type.pat + { + let is_ref = matches!(&*pat_type.ty, syn::Type::Reference(_)); + return Some((pat_ident.ident.clone(), is_ref)); + } + None + }) + .collect(); + + // Determine which fields to capture + let captured_fields: Vec = if args.skip_all { + Vec::new() + } else if let Some(fields) = args.fields { + fields + } else { + // Capture all non-skipped arguments with Debug + fn_args + .iter() + .filter(|(name, _)| !args.skip.iter().any(|s| s == name)) + .map(|(name, _)| CapturedArg { + source: CaptureSource::Arg(name.clone()), + capture_mode: None, + value_expr: None, + }) + .collect() + }; + + // Generate the span creation code + let span_creation = if captured_fields.is_empty() { + quote! { + let __litebox_span = ::litebox_util_log::span!(#level, #span_name); + } + } else { + let field_tokens: Vec = captured_fields + .iter() + .map(|arg| { + let mode_token = match arg.capture_mode.unwrap_or(CaptureMode::Debug) { + CaptureMode::Debug => quote! { :? }, + CaptureMode::Display => quote! { :% }, + }; + if let Some(expr) = &arg.value_expr { + // Explicit `key [mode] = expr` + let CaptureSource::Arg(key) = &arg.source else { + unreachable!("parser rejects self/self.field with = expr") + }; + quote! { #key #mode_token = #expr } + } else { + match &arg.source { + CaptureSource::Arg(name) => quote! { #name #mode_token }, + CaptureSource::SelfField(name) => { + quote! { #name #mode_token = self.#name } + } + CaptureSource::Self_ => quote! { self_ #mode_token = &self }, + } + } + }) + .collect(); + + quote! { + let __litebox_span = ::litebox_util_log::span!(#level, #span_name, #(#field_tokens),*); + } + }; + + // Wrap the function body + let original_body = &input_fn.block; + let new_body: syn::Block = syn::parse_quote! { + { + #span_creation + #original_body + } + }; + + input_fn.block = Box::new(new_body); + + input_fn.into_token_stream() +}