From ee9dc646793a3617f40c2c9a7a3d3cb1aaf0fc4e Mon Sep 17 00:00:00 2001 From: Gabe Goodhart Date: Wed, 5 Aug 2026 14:16:19 -0600 Subject: [PATCH 01/15] chore: Set up build infra and readme for rust implementation Branch: Rust AI-usage: full (Claude + Sonnet 5) Signed-off-by: Gabe Goodhart --- src/rust/.gitignore | 2 + src/rust/Cargo.toml | 26 ++++++ src/rust/README.md | 220 ++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 248 insertions(+) create mode 100644 src/rust/.gitignore create mode 100644 src/rust/Cargo.toml create mode 100644 src/rust/README.md diff --git a/src/rust/.gitignore b/src/rust/.gitignore new file mode 100644 index 0000000..96ef6c0 --- /dev/null +++ b/src/rust/.gitignore @@ -0,0 +1,2 @@ +/target +Cargo.lock diff --git a/src/rust/Cargo.toml b/src/rust/Cargo.toml new file mode 100644 index 0000000..483cd8e --- /dev/null +++ b/src/rust/Cargo.toml @@ -0,0 +1,26 @@ +[package] +name = "alchemy-logging" +version = "0.1.0" +edition = "2021" +rust-version = "1.70" +description = "Multi-language logging framework with configurable channels and levels" +license = "MIT" +repository = "https://github.com/IBM/alchemy-logging" +readme = "README.md" +keywords = ["logging", "log", "alog"] +categories = ["development-tools::debugging"] + +[lib] +name = "alog" +path = "src/lib.rs" + +[dependencies] +serde = { version = "1", features = ["derive"] } +serde_json = "1" + +[features] +# Strips every logging macro down to a no-op at compile time. See the note +# at the top of src/lib.rs for exactly what this does and does not cover. +disable-logging = [] + +[dev-dependencies] diff --git a/src/rust/README.md b/src/rust/README.md new file mode 100644 index 0000000..efbac27 --- /dev/null +++ b/src/rust/README.md @@ -0,0 +1,220 @@ +# Alchemy Logging (alog) - Rust +The `alog` framework provides tunable logging with easy-to-use defaults and power-user capabilities. The mantra of `alog` is **"Log Early And Often"**. To accomplish this goal, `alog` makes it easy to enable verbose logging at develop/debug time and trim the verbosity at production run time. + +## Dependencies +The `alog` crate is intentionally light on dependencies. The only dependencies are [`serde`](https://crates.io/crates/serde) and [`serde_json`](https://crates.io/crates/serde_json), used for the JSON formatter and for structured extra data attached to log records. + +## Channels and Levels +The primary components of the system are **channels** and **levels** which allow for each log statement to be enabled or disabled when appropriate. + +1. **Channels**: Each logging statement is made to a specific channel. Channels are independent of one another and allow for logical grouping of log messages by functionality. A channel can be any string. + +1. **Levels**: Each logging statement is made at a specific level. Levels provide sequential granularity, allowing detailed debugging statements to be placed in the code without clogging up the logs at runtime. The sequence of levels and their general usage is as follows: + + 1. `off`: Disable the given channel completely + 1. `fatal`: A fatal error has occurred. Any behavior after this statement should be regarded as undefined. + 1. `error`: An unrecoverable error has occurred. Any behavior after this statement should be regarded as undefined unless the error is explicitly handled. + 1. `warning`: A recoverable error condition has come up that the service maintainer should be aware of. + 1. `info`: High-level information that is valuable at runtime under moderate load. + 1. `trace`: Used to log begin/end of functions for debugging code paths. + 1. `debug`: High-level debugging statements such as function parameters. + 1. `debug1`: High-level debugging statements. + 1. `debug2`: Mid-level debugging statements such as computed values. + 1. `debug3`: Low-level debugging statements such as computed values inside loops. + 1. `debug4`: Ultra-low-level debugging statements such as data dumps and/or statements inside multiple nested loops. + +Using this combination of **Channels** and **Levels**, you can fine-tune what log statements are enabled when you run your application under different circumstances. + +`alog` models this with two enums instead of C++'s single level type: [`Level`] includes `Off` and is used for configuration/filtering, while [`MessageLevel`] excludes `Off` and is what the logging macros accept. This means attempting to log a message "at" `Off` is a compile error rather than a silent no-op at runtime. + +## Configuration +There are two primary pieces of configuration when setting up the `alog` environment: + +1. **default_level**: This is the level that will be enabled for a given channel when a specific level has not been set in the **filters**. + +1. **filters**: This is a mapping from channel name to level that allows levels to be set on a per-channel basis. + +The `alog::configure(...)` function allows both the default level and filters to be set at once. For example: + +```rust +use alog::{alog, Config, Filters, MessageLevel}; + +fn main() { + alog::configure(Config { + default_level: "info".parse().unwrap(), + filters: Filters::Spec("FOO:debug2,BAR:off".to_string()), + ..Default::default() + }); + alog!("MAIN", MessageLevel::Info, "Hello world"); +} +``` + +If you only want to adjust the level/filters after initial setup (leaving the formatter and sink untouched), use `alog::adjust_levels(default_level, filters)`. + +## Structured Logging +As `alog` has grown, its use has tended towards usage as part of a multi-replica cluster of servers. In such an environment, it can be very beneficial to provide structure in your log messages so that they can be aggregated between replicas and used for operational visibility. The simplest way to do this is to log lines as `json` rather than the traditional pretty-print formatting. By default `alog` uses the pretty-printer output formatter. To enable JSON output, set `formatter: FormatterKind::Json` in `Config`. + +```rust +use alog::{Config, FormatterKind}; + +alog::configure(Config { + formatter: FormatterKind::Json, + ..Default::default() +}); +``` + +While printing logs as `json` allows them to be filtered by `channel`, `level`, and `message` quite easily, some times more structure is needed. In these cases, `alog` also supports logging arbitrary key/value pairs via `alog_map!`, using a [`MapData`] (a `serde_json::Map`). For example: + +```rust +use alog::{alog_map, MapData, MessageLevel}; +use serde_json::json; + +let mut extra = MapData::new(); +extra.insert("foo".to_string(), json!("bar")); +extra.insert("baz".to_string(), json!(1234)); +alog_map!("MAIN", MessageLevel::Info, extra, "some data"); +``` + +## Metadata +In addition to the content of an individual log message, you may want to attach some metadata to all log lines that occur within a given thread of execution. For example, this can be used to attach a request ID to all log lines created in the course of processing a given server request. This can come in very handy when you have a multi-threaded and/or multi-replica environment. + +The metadata feature in `alog` is implemented as a thread-local key/value map. Keys and values are added to the map using [`ScopedMetadata`], a guard that adds its keys on construction and removes exactly those keys when it drops, so metadata is always cleaned up even if the scope exits early (including by panic). + +Here's a brief example of how you might use metadata: + +```rust +use alog::{alog, MapData, MessageLevel, ScopedMetadata}; +use serde_json::json; + +fn add(a: i32, b: i32) -> i32 { + alog!("MATH", MessageLevel::Info, "Adding {a} + {b}"); + a + b +} + +fn handler(request_id: &str, a: i32, b: i32) -> i32 { + let mut metadata = MapData::new(); + metadata.insert("request_id".to_string(), json!(request_id)); + let _scope = ScopedMetadata::new(metadata); + add(a, b) +} +``` + +In this example, `add` doesn't need (or want) to know that it's part of handling some sort of request, but the developer would like to attach the request ID to the log line printed in its implementation in case there's a bug. + +The `let _scope = ScopedMetadata::new(metadata);` binding above can also be written as `alog_scoped_metadata!(metadata);` — see [Log Scopes](#log-scopes) below. + +## Logging Macros +The standard logging macros each take a channel, a level, and message arguments: + +* `alog!(channel, level, ...)`: Log a single message line using `format!`-style arguments. + ```rust + use alog::{alog, MessageLevel}; + alog!("MAIN", MessageLevel::Debug, "This is the {}st test", 1); + ``` + +* `alog_map!(channel, level, map, ...)`: Log a single message line with an arbitrary [`MapData`] attached. + ```rust + use alog::{alog_map, MapData, MessageLevel}; + alog_map!("MAIN", MessageLevel::Debug, MapData::new(), "map data"); + ``` + +* `alog_is_enabled!(channel, level)`: Check whether a channel/level combination is enabled without logging, useful for guarding expensive message construction that doesn't fit in a single `format!` call. + ```rust + use alog::{alog, alog_is_enabled, MessageLevel}; + if alog_is_enabled!("MAIN", MessageLevel::Debug2) { + let msg = (0..100).map(|n| n.to_string()).collect::>().join(","); + alog!("MAIN", MessageLevel::Debug2, "{msg}"); + } + ``` + +In every case, the message/map arguments are only evaluated if the channel/level combination is enabled, so there is no runtime cost to leaving verbose logging statements in performance-critical code paths. + +Every macro above that takes a channel has an `_channel`-suffixed sibling (`alog_map_channel!`, `alog_is_enabled_channel!`) that instead uses the channel bound by `use_channel!` in the enclosing module — see [Use Channel](#use-channel) below. + +## Log Scopes +One of the most common uses for logging is to note when a certain block of code starts and ends. To facilitate this, `alog` provides scope guards: types whose `Drop` implementation logs when the scope ends. All logging statements which occur between construction and drop are indented, making for a highly readable log, even with very verbose logging. + +Each guard type can be used directly via `::new(...)`, bound to a `let _foo = ...;` variable you name yourself, or via a statement-form macro that binds a hidden, hygienic variable for you (so multiple guards can coexist in the same block without you having to invent distinct names for each one). The macro forms are generally preferred; the direct types remain useful when you need to hold onto the guard explicitly (e.g. store it in a struct field) or when working under the [`disable-logging`](#disabling-logging-entirely) feature, where the macros become no-ops but the types stay fully functional. + +* [`ScopedLog::new(channel, level, msg)`] / `alog_scoped_block!(channel, level, ...)`: Logs `"BEGIN: {msg}"` immediately and `"END: {msg}"` when the guard drops, indenting everything logged in between. + ```rust + use alog::{alog, alog_scoped_block, MessageLevel}; + fn foo(bar: bool) { + if bar { + alog_scoped_block!("MAIN", MessageLevel::Debug, "Bar is true!"); + alog!("MAIN", MessageLevel::Debug2, "Getting it done"); + } + } + ``` + +* [`ScopedTimer::new(channel, level, msg)`] / `alog_scoped_timer!(channel, level, ...)`: Times the work done in the current scope and logs the elapsed time with a `duration_ms` field attached when the guard drops. + ```rust + use alog::{alog_scoped_timer, MessageLevel}; + fn foo() { + alog_scoped_timer!("MAIN", MessageLevel::Debug, "heavy_lifting took: "); + heavy_lifting(); + } + # fn heavy_lifting() {} + ``` + +* `alog_fn!(channel)`: Adds a BEGIN/END indented block at `Trace` level using the enclosing function's name as the message. Unlike the other scope guards, this one is macro-only — there's no separate named type to construct directly, since the function name is captured at the macro's call site. + ```rust + use alog::alog_fn; + fn foo() { + alog_fn!("MAIN"); + // ... + } + ``` + +* [`ScopedMetadata::new(map)`] / `alog_scoped_metadata!(map)`: Adds a [`MapData`] of key/value pairs that will be attached to every subsequent log line on this thread until the guard drops. See [Metadata](#metadata) above. + +* [`ScopedIndent::new()`] / `alog_scoped_indent!()`: Adds a level of indentation to all logging lines within the current scope, without logging anything itself. + ```rust + use alog::{alog, alog_scoped_block, alog_scoped_indent, MessageLevel}; + fn foo(bar: bool) { + if bar { + alog_scoped_block!("MAIN", MessageLevel::Debug, "Bar is true!"); + alog_scoped_indent!(); + alog!("MAIN", MessageLevel::Debug2, "Getting it done"); + } + } + ``` + +`alog_fn!`, `alog_scoped_block!`, and `alog_scoped_timer!` each have an `_channel`-suffixed sibling (`alog_fn_channel!`, `alog_scoped_block_channel!`, `alog_scoped_timer_channel!`) that drops the explicit channel argument in favor of the one bound by `use_channel!` — see [Use Channel](#use-channel) below. `alog_scoped_indent!` and `alog_scoped_metadata!` have no `_channel` variant since they don't take a channel argument in the first place. + +## Use Channel +In the spirit of channels, log entries should be grouped by logical function. To avoid repeating a channel name at every call site, `alog` provides a module-level binding: + +* `use_channel!(channel)`: Declares a function in the enclosing module that fixes the channel name for use with the `_channel`-suffixed macros below. +* `alog_channel!(level, ...)`: Like `alog!`, but uses the channel bound by `use_channel!` in the enclosing module instead of taking one explicitly. + +```rust +use alog::{alog_channel, use_channel, MessageLevel}; + +use_channel!("FOO"); + +fn doit() { + alog_channel!(MessageLevel::Debug2, "We're doing this!"); +} +``` + +This pattern extends to every user-facing macro that takes a channel argument: `alog_map_channel!`, `alog_is_enabled_channel!`, `alog_fn_channel!`, `alog_scoped_block_channel!`, and `alog_scoped_timer_channel!` are the channel-bound equivalents of `alog_map!`, `alog_is_enabled!`, `alog_fn!`, `alog_scoped_block!`, and `alog_scoped_timer!` respectively, each dropping the leading `channel` argument in favor of the one declared by `use_channel!`. + +## Disabling Logging Entirely +For builds where logging should be compiled out entirely (e.g. a size- or performance-sensitive release build), enable the `disable-logging` Cargo feature: + +```toml +[dependencies] +alog = { package = "alchemy-logging", version = "...", features = ["disable-logging"] } +``` + +With this feature enabled, every logging macro (`alog!`, `alog_map!`, `alog_channel!`, `alog_fn!`, `alog_scoped_block!`, `alog_scoped_timer!`, `alog_scoped_indent!`, `alog_scoped_metadata!`, and all of their `_channel` siblings) becomes a no-op, and `alog_is_enabled!`/`alog_is_enabled_channel!` become the compile-time constant `false`. This is a purely additive, opt-in feature — it is off by default, and turning it on never changes behavior beyond silencing these macros. + +The `Scoped*` guard types (`ScopedLog`, `ScopedTimer`, `ScopedIndent`, `ScopedMetadata`) are deliberately **not** gated by this feature and remain fully functional when constructed directly, since they're ordinary values your code may depend on structurally (e.g. holding one in a struct field), not just a logging side effect. + +## Example +See [`examples/fib.rs`](examples/fib.rs) for a full feature-tour example that exercises channels, levels, filters, both formatters, scoped logs/timers/metadata, and multi-threaded logging. Run it with: + +```sh +cargo run --example fib -- 5 8 3 +``` From 7145a74e63f35fdfbabb6a1000289081afb2522a Mon Sep 17 00:00:00 2001 From: Gabe Goodhart Date: Wed, 5 Aug 2026 14:16:53 -0600 Subject: [PATCH 02/15] feat: Full implementation of rust alog Branch: Rust AI-usage: full (Claude + Sonnet 5) Signed-off-by: Gabe Goodhart --- src/rust/src/core.rs | 255 ++++++++++++++++++++++++ src/rust/src/formatter.rs | 117 +++++++++++ src/rust/src/level.rs | 213 ++++++++++++++++++++ src/rust/src/lib.rs | 401 ++++++++++++++++++++++++++++++++++++++ src/rust/src/record.rs | 44 +++++ src/rust/src/scope.rs | 211 ++++++++++++++++++++ 6 files changed, 1241 insertions(+) create mode 100644 src/rust/src/core.rs create mode 100644 src/rust/src/formatter.rs create mode 100644 src/rust/src/level.rs create mode 100644 src/rust/src/lib.rs create mode 100644 src/rust/src/record.rs create mode 100644 src/rust/src/scope.rs diff --git a/src/rust/src/core.rs b/src/rust/src/core.rs new file mode 100644 index 0000000..c2822e5 --- /dev/null +++ b/src/rust/src/core.rs @@ -0,0 +1,255 @@ +//! The global singleton: configuration, filtering, and record dispatch. + +use std::collections::HashMap; +use std::io::{self, Write}; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::sync::{Mutex, OnceLock, RwLock}; +use std::time::{SystemTime, UNIX_EPOCH}; + +use serde_json::Value; + +use crate::formatter::{Formatter, JsonFormatter, PrettyFormatter}; +use crate::level::{Level, MessageLevel}; +use crate::record::{LogRecord, MapData}; +use crate::scope; + +/// Per-channel level filters, either as an explicit map or as a spec string +/// of the form `"CHAN1:info,CHAN2:debug"`. +#[derive(Debug, Clone, Default)] +pub enum Filters { + Map(HashMap), + Spec(String), + #[default] + None, +} + +impl Filters { + fn into_map(self) -> HashMap { + match self { + Filters::Map(m) => m, + Filters::None => HashMap::new(), + Filters::Spec(s) => parse_filter_spec(&s), + } + } +} + +fn parse_filter_spec(spec: &str) -> HashMap { + let mut map = HashMap::new(); + for entry in spec.split(',') { + if entry.is_empty() { + continue; + } + let mut parts = entry.splitn(2, ':'); + if let (Some(chan), Some(level_str)) = (parts.next(), parts.next()) { + if let Ok(level) = level_str.parse::() { + map.insert(chan.to_string(), level); + } + } + } + map +} + +/// The output formatter to configure the crate with. +#[derive(Default)] +pub enum FormatterKind { + #[default] + Pretty, + Json, + Custom(Box), +} + +impl FormatterKind { + fn into_formatter(self) -> Box { + match self { + FormatterKind::Pretty => Box::new(PrettyFormatter::default()), + FormatterKind::Json => Box::new(JsonFormatter), + FormatterKind::Custom(f) => f, + } + } +} + +/// The sink that formatted records are written to. +#[derive(Default)] +pub enum Writer { + #[default] + Stdout, + Custom(Box), +} + +/// Top-level configuration for the crate. Construct with [`Config::default`] +/// and override only the fields you need. +/// +/// ``` +/// alog::configure(alog::Config { +/// default_level: alog::Level::Debug, +/// ..Default::default() +/// }); +/// ``` +#[derive(Default)] +pub struct Config { + pub default_level: Level, + pub filters: Filters, + pub formatter: FormatterKind, + pub writer: Writer, + pub thread_id: bool, +} + +struct ConfigState { + default_level: Level, + filters: HashMap, + thread_id_enabled: bool, +} + +struct SinkState { + formatter: Box, + sink: Box, +} + +static CONFIG: OnceLock> = OnceLock::new(); +static SINK: OnceLock> = OnceLock::new(); + +fn config() -> &'static RwLock { + CONFIG.get_or_init(|| { + RwLock::new(ConfigState { + default_level: Level::Info, + filters: HashMap::new(), + thread_id_enabled: false, + }) + }) +} + +fn sink() -> &'static Mutex { + SINK.get_or_init(|| { + Mutex::new(SinkState { + formatter: Box::new(PrettyFormatter::default()), + sink: Box::new(io::stdout()), + }) + }) +} + +/// Configure the crate's global logging behavior. May be called multiple +/// times at runtime; each call fully replaces the previous configuration. +pub fn configure(cfg: Config) { + let filters = cfg.filters.into_map(); + let formatter = cfg.formatter.into_formatter(); + let writer: Box = match cfg.writer { + Writer::Stdout => Box::new(io::stdout()), + Writer::Custom(w) => w, + }; + + { + let mut state = config().write().unwrap(); + state.default_level = cfg.default_level; + state.filters = filters; + state.thread_id_enabled = cfg.thread_id; + } + { + let mut sink_state = sink().lock().unwrap(); + sink_state.formatter = formatter; + sink_state.sink = writer; + } +} + +/// Adjust only the default level and per-channel filters, leaving the +/// configured formatter and sink untouched. +pub fn adjust_levels(default_level: Level, filters: Filters) { + let filters = filters.into_map(); + let mut state = config().write().unwrap(); + state.default_level = default_level; + state.filters = filters; +} + +/// Returns true if `channel` is enabled at `level` under the current +/// configuration. +pub fn is_enabled(channel: &str, level: MessageLevel) -> bool { + let state = config().read().unwrap(); + let filter_level = state + .filters + .get(channel) + .copied() + .unwrap_or(state.default_level); + filter_level >= Level::from(level) +} + +thread_local! { + static THREAD_ID: u64 = next_thread_id(); +} +static THREAD_ID_COUNTER: AtomicU64 = AtomicU64::new(1); + +fn next_thread_id() -> u64 { + THREAD_ID_COUNTER.fetch_add(1, Ordering::Relaxed) +} + +/// The function every logging macro funnels into. Not part of the public +/// API: use the `alog!`/`alog_map!` macros instead. +#[doc(hidden)] +pub fn __log_impl(channel: &str, level: MessageLevel, message: String, extra: Option) { + let thread_id_enabled = config().read().unwrap().thread_id_enabled; + let thread_id_str = thread_id_enabled.then(|| THREAD_ID.with(|id| id.to_string())); + + let mut merged = extra.unwrap_or_default(); + if let Some(metadata) = scope::metadata_snapshot() { + merged.insert("metadata".to_string(), Value::Object(metadata)); + } + let final_extra = if merged.is_empty() { + None + } else { + Some(merged) + }; + + let timestamp = iso8601_now(); + let record = LogRecord { + channel, + level, + timestamp: ×tamp, + message: &message, + num_indent: scope::indent_level(), + thread_id: thread_id_str.as_deref(), + extra: final_extra.as_ref(), + }; + + let mut sink_state = sink().lock().unwrap(); + let formatted = sink_state.formatter.format(&record); + let _ = sink_state.sink.write_all(formatted.as_bytes()); +} + +/// Formats the current time as an ISO 8601 timestamp with millisecond +/// precision (`YYYY-MM-DDTHH:mm:ss.sssZ`), hand-rolled from [`SystemTime`] +/// to avoid a date/time dependency. +fn iso8601_now() -> String { + let since_epoch = SystemTime::now() + .duration_since(UNIX_EPOCH) + .unwrap_or_default(); + let secs = since_epoch.as_secs(); + let millis = since_epoch.subsec_millis(); + + let days = (secs / 86400) as i64; + let rem = secs % 86400; + let hour = rem / 3600; + let minute = (rem % 3600) / 60; + let second = rem % 60; + + let (year, month, day) = civil_from_days(days); + format!( + "{:04}-{:02}-{:02}T{:02}:{:02}:{:02}.{:03}Z", + year, month, day, hour, minute, second, millis + ) +} + +/// Converts a count of days since the Unix epoch into a (year, month, day) +/// civil calendar date. Adapted from Howard Hinnant's public-domain +/// `civil_from_days` algorithm +/// (). +fn civil_from_days(z: i64) -> (i64, u32, u32) { + let z = z + 719468; + let era = if z >= 0 { z } else { z - 146096 } / 146097; + let doe = (z - era * 146097) as u64; + let yoe = (doe - doe / 1460 + doe / 36524 - doe / 146096) / 365; + let y = yoe as i64 + era * 400; + let doy = doe - (365 * yoe + yoe / 4 - yoe / 100); + let mp = (5 * doy + 2) / 153; + let d = (doy - (153 * mp + 2) / 5 + 1) as u32; + let m = if mp < 10 { mp + 3 } else { mp - 9 } as u32; + let year = y + if m <= 2 { 1 } else { 0 }; + (year, m, d) +} diff --git a/src/rust/src/formatter.rs b/src/rust/src/formatter.rs new file mode 100644 index 0000000..2815bc1 --- /dev/null +++ b/src/rust/src/formatter.rs @@ -0,0 +1,117 @@ +//! Formatters that turn a [`LogRecord`] into one or more lines of output. + +use serde_json::{json, Value}; + +use crate::record::LogRecord; + +/// The fixed number of space characters used for a single indentation level, +/// matching the `cpp` and `python` implementations. +const INDENT: &str = " "; + +/// A formatter turns a single log record into the text that should be +/// written to the configured sink, including the trailing newline. +pub trait Formatter: Send + Sync { + fn format(&self, record: &LogRecord<'_>) -> String; +} + +/// Formats records as human-readable, aligned lines of text, intended for +/// use while actively developing. +/// +/// Header format (per the implementation spec): +/// `"timestamp [channel:level(:thread_id)] (indentation)"` +#[derive(Debug, Clone)] +pub struct PrettyFormatter { + /// The fixed width that channel names are padded/truncated to. + pub channel_width: usize, +} + +impl Default for PrettyFormatter { + fn default() -> Self { + Self { channel_width: 5 } + } +} + +impl PrettyFormatter { + pub fn new(channel_width: usize) -> Self { + Self { channel_width } + } + + /// Builds the header for `record`, including the trailing separator + /// space and indentation, so that message/map lines can simply be + /// appended directly after it. + fn header(&self, record: &LogRecord<'_>) -> String { + let channel = pad_or_truncate(record.channel, self.channel_width); + let mut header = format!( + "{} [{}:{}", + record.timestamp, + channel, + record.level.abbrev() + ); + if let Some(thread_id) = record.thread_id { + header.push(':'); + header.push_str(thread_id); + } + header.push_str("] "); + header.push_str(&INDENT.repeat(record.num_indent as usize)); + header + } +} + +fn pad_or_truncate(s: &str, width: usize) -> String { + if s.len() > width { + s[..width].to_string() + } else { + format!("{:width$}", s, width = width) + } +} + +impl Formatter for PrettyFormatter { + fn format(&self, record: &LogRecord<'_>) -> String { + let header = self.header(record); + + let mut lines: Vec = record + .message + .split('\n') + .map(|line| format!("{}{}", header, line)) + .collect(); + + if let Some(extra) = record.extra { + for (key, value) in extra.iter() { + lines.push(format!("{} * {}: {}", header, key, value)); + } + } + + let mut out = lines.join("\n"); + out.push('\n'); + out + } +} + +/// Formats records as single-line JSON objects, intended for consumption by +/// log aggregation systems. +#[derive(Debug, Clone, Default)] +pub struct JsonFormatter; + +impl Formatter for JsonFormatter { + fn format(&self, record: &LogRecord<'_>) -> String { + let mut map = serde_json::Map::new(); + map.insert("channel".to_string(), json!(record.channel)); + map.insert("level".to_string(), json!(record.level().ordinal())); + map.insert("level_str".to_string(), json!(record.level_str())); + map.insert("timestamp".to_string(), json!(record.timestamp)); + map.insert("message".to_string(), json!(record.message)); + map.insert("num_indent".to_string(), json!(record.num_indent)); + if let Some(thread_id) = record.thread_id { + map.insert("thread_id".to_string(), json!(thread_id)); + } + if let Some(extra) = record.extra { + for (key, value) in extra.iter() { + map.insert(key.clone(), value.clone()); + } + } + + let mut out = Value::Object(map).to_string(); + out.push('\n'); + out + } +} diff --git a/src/rust/src/level.rs b/src/rust/src/level.rs new file mode 100644 index 0000000..967be0b --- /dev/null +++ b/src/rust/src/level.rs @@ -0,0 +1,213 @@ +//! Log levels. +//! +//! Two enums are exposed rather than one: [`Level`] is filter-facing and +//! includes [`Level::Off`], while [`MessageLevel`] is what every logging +//! macro accepts and cannot represent `Off`. This makes "you can't log a +//! message at `Off`" a compile-time property instead of a runtime check. + +use std::error::Error; +use std::fmt; +use std::str::FromStr; + +/// A level that can be used to configure a channel's filter, including the +/// special `Off` level which disables a channel entirely. +/// +/// Variants are declared in ascending order of verbosity so that the derived +/// [`Ord`] implementation can be used directly for filtering: a channel is +/// enabled for a given message level if `filter_level >= message_level`. +#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)] +pub enum Level { + Off, + Fatal, + Error, + Warning, + Info, + Trace, + Debug, + Debug1, + Debug2, + Debug3, + Debug4, +} + +/// A level that a log record may be created at. This is identical to +/// [`Level`] except that it has no `Off` variant, since it never makes sense +/// to create a log record "at" the off level. +#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)] +pub enum MessageLevel { + Fatal, + Error, + Warning, + Info, + Trace, + Debug, + Debug1, + Debug2, + Debug3, + Debug4, +} + +impl Level { + /// The full lowercase name of the level, used for the `level_str` record + /// field and for parsing configuration strings. + pub const fn name(&self) -> &'static str { + match self { + Level::Off => "off", + Level::Fatal => "fatal", + Level::Error => "error", + Level::Warning => "warning", + Level::Info => "info", + Level::Trace => "trace", + Level::Debug => "debug", + Level::Debug1 => "debug1", + Level::Debug2 => "debug2", + Level::Debug3 => "debug3", + Level::Debug4 => "debug4", + } + } + + /// The fixed-width (4 character) abbreviation used in the pretty header, + /// matching the abbreviations used by the `cpp` and `python` + /// implementations (e.g. `"INFO"`, `"DBG1"`). + pub const fn abbrev(&self) -> &'static str { + match self { + Level::Off => "OFF ", + Level::Fatal => "FATL", + Level::Error => "ERRR", + Level::Warning => "WARN", + Level::Info => "INFO", + Level::Trace => "TRCE", + Level::Debug => "DBUG", + Level::Debug1 => "DBG1", + Level::Debug2 => "DBG2", + Level::Debug3 => "DBG3", + Level::Debug4 => "DBG4", + } + } + + /// The numeric enumeration value for this level, as required by the + /// record spec's `level` field. Ascends with verbosity. + pub const fn ordinal(&self) -> u8 { + match self { + Level::Off => 0, + Level::Fatal => 1, + Level::Error => 2, + Level::Warning => 3, + Level::Info => 4, + Level::Trace => 5, + Level::Debug => 6, + Level::Debug1 => 7, + Level::Debug2 => 8, + Level::Debug3 => 9, + Level::Debug4 => 10, + } + } +} + +impl MessageLevel { + pub const fn name(&self) -> &'static str { + message_level_to_level(*self).name() + } + + pub const fn abbrev(&self) -> &'static str { + message_level_to_level(*self).abbrev() + } + + pub const fn ordinal(&self) -> u8 { + message_level_to_level(*self).ordinal() + } +} + +const fn message_level_to_level(level: MessageLevel) -> Level { + match level { + MessageLevel::Fatal => Level::Fatal, + MessageLevel::Error => Level::Error, + MessageLevel::Warning => Level::Warning, + MessageLevel::Info => Level::Info, + MessageLevel::Trace => Level::Trace, + MessageLevel::Debug => Level::Debug, + MessageLevel::Debug1 => Level::Debug1, + MessageLevel::Debug2 => Level::Debug2, + MessageLevel::Debug3 => Level::Debug3, + MessageLevel::Debug4 => Level::Debug4, + } +} + +impl From for Level { + fn from(level: MessageLevel) -> Self { + message_level_to_level(level) + } +} + +impl Default for Level { + /// The default filter level used when the crate has not been explicitly + /// configured, matching every other language's implementation. + fn default() -> Self { + Level::Info + } +} + +impl fmt::Display for Level { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.write_str(self.name()) + } +} + +impl fmt::Display for MessageLevel { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.write_str(self.name()) + } +} + +/// Error returned when a string does not correspond to a known [`Level`]. +#[derive(Debug, Clone, PartialEq, Eq)] +pub struct ParseLevelError(String); + +impl fmt::Display for ParseLevelError { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "invalid log level: {}", self.0) + } +} + +impl Error for ParseLevelError {} + +impl FromStr for Level { + type Err = ParseLevelError; + + fn from_str(s: &str) -> Result { + match s.to_ascii_lowercase().as_str() { + "off" => Ok(Level::Off), + "fatal" | "critical" => Ok(Level::Fatal), + "error" => Ok(Level::Error), + "warning" | "warn" => Ok(Level::Warning), + "info" => Ok(Level::Info), + "trace" => Ok(Level::Trace), + "debug" => Ok(Level::Debug), + "debug1" => Ok(Level::Debug1), + "debug2" => Ok(Level::Debug2), + "debug3" => Ok(Level::Debug3), + "debug4" => Ok(Level::Debug4), + other => Err(ParseLevelError(other.to_string())), + } + } +} + +impl FromStr for MessageLevel { + type Err = ParseLevelError; + + fn from_str(s: &str) -> Result { + match Level::from_str(s)? { + Level::Off => Err(ParseLevelError(s.to_string())), + Level::Fatal => Ok(MessageLevel::Fatal), + Level::Error => Ok(MessageLevel::Error), + Level::Warning => Ok(MessageLevel::Warning), + Level::Info => Ok(MessageLevel::Info), + Level::Trace => Ok(MessageLevel::Trace), + Level::Debug => Ok(MessageLevel::Debug), + Level::Debug1 => Ok(MessageLevel::Debug1), + Level::Debug2 => Ok(MessageLevel::Debug2), + Level::Debug3 => Ok(MessageLevel::Debug3), + Level::Debug4 => Ok(MessageLevel::Debug4), + } + } +} diff --git a/src/rust/src/lib.rs b/src/rust/src/lib.rs new file mode 100644 index 0000000..bf8ae05 --- /dev/null +++ b/src/rust/src/lib.rs @@ -0,0 +1,401 @@ +//! `alog` is the Rust implementation of [Alchemy +//! Logging](https://github.com/IBM/alchemy-logging), a structured logging +//! framework with independently filterable channels and fine-grained levels, +//! implemented consistently across many languages. +//! +//! ``` +//! use alog::{alog, MessageLevel}; +//! +//! alog::configure(alog::Config::default()); +//! alog!("TEST", MessageLevel::Info, "Hello, {}!", "world"); +//! ``` +//! +//! Enabling the `disable-logging` feature strips every logging macro down to +//! a no-op at compile time — channel, level, and message arguments are +//! discarded unevaluated, so logging has zero footprint in the compiled +//! binary. This is the Rust analog of `cpp`'s `-D ALOG_DISABLE_LOGGING`. It +//! only affects the macros below; directly constructing a [`ScopedLog`], +//! [`ScopedTimer`], [`ScopedIndent`], or [`ScopedMetadata`] (e.g. to hold a +//! named [`ScopedTimer`] and query its elapsed time mid-scope) still works +//! and still logs normally, since that form can't be erased without leaving +//! a dangling reference to the binding. + +mod core; +pub mod formatter; +pub mod level; +pub mod record; +mod scope; + +pub use crate::core::{ + __log_impl, adjust_levels, configure, is_enabled, Config, Filters, FormatterKind, Writer, +}; +pub use crate::formatter::{Formatter, JsonFormatter, PrettyFormatter}; +pub use crate::level::{Level, MessageLevel, ParseLevelError}; +pub use crate::record::{LogRecord, MapData}; +pub use crate::scope::{ScopedIndent, ScopedLog, ScopedMetadata, ScopedTimer}; + +/// Creates a single log record on `channel` at `level` with a message built +/// from `format!`-style arguments. The arguments are only evaluated if +/// `channel`/`level` is enabled under the current configuration. +/// +/// ``` +/// use alog::{alog, MessageLevel}; +/// alog!("TEST", MessageLevel::Info, "the value is {}", 42); +/// ``` +/// +/// A [`MessageLevel`] must be given — [`Level::Off`] has no `MessageLevel` +/// counterpart, so attempting to log "at" it fails to compile rather than +/// silently doing nothing at runtime: +/// +/// ```compile_fail +/// use alog::{alog, Level}; +/// alog!("TEST", Level::Off, "unreachable"); +/// ``` +#[cfg(not(feature = "disable-logging"))] +#[macro_export] +macro_rules! alog { + ($channel:expr, $level:expr, $($arg:tt)+) => { + if $crate::is_enabled($channel, $level) { + $crate::__log_impl($channel, $level, format!($($arg)+), None); + } + }; +} + +#[cfg(feature = "disable-logging")] +#[macro_export] +macro_rules! alog { + ($($arg:tt)*) => {}; +} + +/// Like [`alog!`], but additionally attaches an arbitrary map of +/// JSON-compatible key/value pairs (a [`MapData`]) to the record. The map +/// expression and the message arguments are only evaluated if +/// `channel`/`level` is enabled. +/// +/// ``` +/// use alog::{alog_map, MapData, MessageLevel}; +/// let mut extra = MapData::new(); +/// extra.insert("request_id".to_string(), "abc-123".into()); +/// alog_map!("TEST", MessageLevel::Info, extra, "handled request"); +/// ``` +#[cfg(not(feature = "disable-logging"))] +#[macro_export] +macro_rules! alog_map { + ($channel:expr, $level:expr, $map:expr, $($arg:tt)+) => { + if $crate::is_enabled($channel, $level) { + $crate::__log_impl($channel, $level, format!($($arg)+), Some($map)); + } + }; +} + +#[cfg(feature = "disable-logging")] +#[macro_export] +macro_rules! alog_map { + ($($arg:tt)*) => {}; +} + +/// Like [`alog_map!`], but uses the channel name declared by +/// [`use_channel!`] in the enclosing scope instead of taking one explicitly. +#[cfg(not(feature = "disable-logging"))] +#[macro_export] +macro_rules! alog_map_channel { + ($level:expr, $map:expr, $($arg:tt)+) => { + $crate::alog_map!(__alog_channel(), $level, $map, $($arg)+) + }; +} + +#[cfg(feature = "disable-logging")] +#[macro_export] +macro_rules! alog_map_channel { + ($($arg:tt)*) => {}; +} + +/// Returns whether `channel` is enabled at `level`, without creating a +/// record. Useful for guarding expensive multi-statement message +/// construction that doesn't fit neatly into a single `format!` call. +/// +/// Always `false` when the `disable-logging` feature is enabled. +#[cfg(not(feature = "disable-logging"))] +#[macro_export] +macro_rules! alog_is_enabled { + ($channel:expr, $level:expr) => { + $crate::is_enabled($channel, $level) + }; +} + +#[cfg(feature = "disable-logging")] +#[macro_export] +macro_rules! alog_is_enabled { + ($($arg:tt)*) => { + false + }; +} + +/// Like [`alog_is_enabled!`], but uses the channel name declared by +/// [`use_channel!`] in the enclosing scope instead of taking one explicitly. +#[cfg(not(feature = "disable-logging"))] +#[macro_export] +macro_rules! alog_is_enabled_channel { + ($level:expr) => { + $crate::is_enabled(__alog_channel(), $level) + }; +} + +#[cfg(feature = "disable-logging")] +#[macro_export] +macro_rules! alog_is_enabled_channel { + ($($arg:tt)*) => { + false + }; +} + +/// Declares a free function, `__alog_channel`, in the enclosing module which +/// returns a fixed channel name for use by [`alog_channel!`]. This is +/// intended for module-level (free-function) use, analogous to `cpp`'s +/// `ALOG_USE_CHANNEL_FREE`. +/// +/// ``` +/// alog::use_channel!("TEST"); +/// +/// fn do_thing() { +/// alog::alog_channel!(alog::MessageLevel::Debug, "doing the thing"); +/// } +/// ``` +#[macro_export] +macro_rules! use_channel { + ($channel:expr) => { + // `#[allow(dead_code)]` covers both a module that binds a channel + // but never calls `alog_channel!`, and every module in a crate built + // with the `disable-logging` feature, where `alog_channel!` never + // references this function at all. + #[inline] + #[allow(dead_code)] + fn __alog_channel() -> &'static str { + $channel + } + }; +} + +/// Like [`alog!`], but uses the channel name declared by [`use_channel!`] in +/// the enclosing scope instead of taking one explicitly. +#[cfg(not(feature = "disable-logging"))] +#[macro_export] +macro_rules! alog_channel { + ($level:expr, $($arg:tt)+) => { + $crate::alog!(__alog_channel(), $level, $($arg)+) + }; +} + +#[cfg(feature = "disable-logging")] +#[macro_export] +macro_rules! alog_channel { + ($($arg:tt)*) => {}; +} + +/// Not part of the public API: computes the dot/colon-path name of the +/// enclosing function using the standard stable-Rust `fn`-pointer + +/// `type_name` trick. +#[doc(hidden)] +#[macro_export] +macro_rules! __alog_function_name { + () => {{ + fn __alog_f() {} + fn __alog_type_name_of(_: T) -> &'static str { + ::std::any::type_name::() + } + let name = __alog_type_name_of(__alog_f); + match name.strip_suffix("::__alog_f") { + Some(stripped) => stripped, + None => name, + } + }}; +} + +/// Function-trace convenience: creates a [`ScopedLog`] at `Trace` level on +/// `channel` whose message is the enclosing function's name, optionally +/// followed by a `format!`-style description of its arguments. +/// +/// ``` +/// fn do_thing() { +/// alog::alog_fn!("TEST"); +/// // ... do the thing ... +/// } +/// ``` +#[cfg(not(feature = "disable-logging"))] +#[macro_export] +macro_rules! alog_fn { + ($channel:expr) => { + let _alog_fn_scope = $crate::ScopedLog::new( + $channel, + $crate::MessageLevel::Trace, + format!("{}()", $crate::__alog_function_name!()), + ); + }; + ($channel:expr, $($arg:tt)+) => { + let _alog_fn_scope = $crate::ScopedLog::new( + $channel, + $crate::MessageLevel::Trace, + format!("{}({})", $crate::__alog_function_name!(), format!($($arg)+)), + ); + }; +} + +#[cfg(feature = "disable-logging")] +#[macro_export] +macro_rules! alog_fn { + ($($arg:tt)*) => {}; +} + +/// Like [`alog_fn!`], but uses the channel name declared by +/// [`use_channel!`] in the enclosing scope instead of taking one explicitly. +#[cfg(not(feature = "disable-logging"))] +#[macro_export] +macro_rules! alog_fn_channel { + () => { + let _alog_fn_scope = $crate::ScopedLog::new( + __alog_channel(), + $crate::MessageLevel::Trace, + format!("{}()", $crate::__alog_function_name!()), + ); + }; + ($($arg:tt)+) => { + let _alog_fn_scope = $crate::ScopedLog::new( + __alog_channel(), + $crate::MessageLevel::Trace, + format!("{}({})", $crate::__alog_function_name!(), format!($($arg)+)), + ); + }; +} + +#[cfg(feature = "disable-logging")] +#[macro_export] +macro_rules! alog_fn_channel { + ($($arg:tt)*) => {}; +} + +/// Statement form of [`ScopedLog::new`] that binds the guard to a hidden +/// variable for you, analogous to `cpp`'s `ALOG_SCOPED_BLOCK`. Rust's macro +/// hygiene gives each expansion its own binding, so multiple uses in the +/// same block (or nested blocks) never collide — no C++-style unique-name +/// trick needed. If you need to control exactly when the guard drops, +/// construct a [`ScopedLog`] directly and bind it to a name instead. +/// +/// ``` +/// use alog::{alog_scoped_block, MessageLevel}; +/// alog_scoped_block!("TEST", MessageLevel::Info, "doing work"); +/// ``` +#[cfg(not(feature = "disable-logging"))] +#[macro_export] +macro_rules! alog_scoped_block { + ($channel:expr, $level:expr, $($arg:tt)+) => { + let _alog_scoped_block = $crate::ScopedLog::new($channel, $level, format!($($arg)+)); + }; +} + +#[cfg(feature = "disable-logging")] +#[macro_export] +macro_rules! alog_scoped_block { + ($($arg:tt)*) => {}; +} + +/// Like [`alog_scoped_block!`], but uses the channel name declared by +/// [`use_channel!`] in the enclosing scope instead of taking one explicitly. +#[cfg(not(feature = "disable-logging"))] +#[macro_export] +macro_rules! alog_scoped_block_channel { + ($level:expr, $($arg:tt)+) => { + let _alog_scoped_block = + $crate::ScopedLog::new(__alog_channel(), $level, format!($($arg)+)); + }; +} + +#[cfg(feature = "disable-logging")] +#[macro_export] +macro_rules! alog_scoped_block_channel { + ($($arg:tt)*) => {}; +} + +/// Statement form of [`ScopedTimer::new`] that binds the guard to a hidden +/// variable for you, analogous to `cpp`'s `ALOG_SCOPED_TIMER`. If you need +/// to query the elapsed time mid-scope, construct a [`ScopedTimer`] directly +/// and bind it to a name instead (analogous to `cpp`'s +/// `ALOG_NEW_SCOPED_TIMER`) — that form can't be compiled out by the +/// `disable-logging` feature, since other code refers to it by name. +/// +/// ``` +/// use alog::{alog_scoped_timer, MessageLevel}; +/// alog_scoped_timer!("TEST", MessageLevel::Info, "did work in "); +/// ``` +#[cfg(not(feature = "disable-logging"))] +#[macro_export] +macro_rules! alog_scoped_timer { + ($channel:expr, $level:expr, $($arg:tt)+) => { + let _alog_scoped_timer = $crate::ScopedTimer::new($channel, $level, format!($($arg)+)); + }; +} + +#[cfg(feature = "disable-logging")] +#[macro_export] +macro_rules! alog_scoped_timer { + ($($arg:tt)*) => {}; +} + +/// Like [`alog_scoped_timer!`], but uses the channel name declared by +/// [`use_channel!`] in the enclosing scope instead of taking one explicitly. +#[cfg(not(feature = "disable-logging"))] +#[macro_export] +macro_rules! alog_scoped_timer_channel { + ($level:expr, $($arg:tt)+) => { + let _alog_scoped_timer = + $crate::ScopedTimer::new(__alog_channel(), $level, format!($($arg)+)); + }; +} + +#[cfg(feature = "disable-logging")] +#[macro_export] +macro_rules! alog_scoped_timer_channel { + ($($arg:tt)*) => {}; +} + +/// Statement form of [`ScopedIndent::new`] that binds the guard to a hidden +/// variable for you, analogous to `cpp`'s `ALOG_SCOPED_INDENT`. +/// +/// ``` +/// alog::alog_scoped_indent!(); +/// ``` +#[cfg(not(feature = "disable-logging"))] +#[macro_export] +macro_rules! alog_scoped_indent { + () => { + let _alog_scoped_indent = $crate::ScopedIndent::new(); + }; +} + +#[cfg(feature = "disable-logging")] +#[macro_export] +macro_rules! alog_scoped_indent { + () => {}; +} + +/// Statement form of [`ScopedMetadata::new`] that binds the guard to a +/// hidden variable for you, analogous to `cpp`'s `ALOG_SCOPED_METADATA`. +/// +/// ``` +/// use alog::{alog_scoped_metadata, MapData}; +/// let mut extra = MapData::new(); +/// extra.insert("request_id".to_string(), "abc-123".into()); +/// alog_scoped_metadata!(extra); +/// ``` +#[cfg(not(feature = "disable-logging"))] +#[macro_export] +macro_rules! alog_scoped_metadata { + ($map:expr) => { + let _alog_scoped_metadata = $crate::ScopedMetadata::new($map); + }; +} + +#[cfg(feature = "disable-logging")] +#[macro_export] +macro_rules! alog_scoped_metadata { + ($($arg:tt)*) => {}; +} diff --git a/src/rust/src/record.rs b/src/rust/src/record.rs new file mode 100644 index 0000000..47d8179 --- /dev/null +++ b/src/rust/src/record.rs @@ -0,0 +1,44 @@ +//! The log record type passed to formatters. + +use crate::level::{Level, MessageLevel}; + +/// A JSON object used to carry arbitrary structured data attached to a log +/// record, either via `alog_map!` or via metadata scopes. +pub type MapData = serde_json::Map; + +/// A single log record, built by the core singleton immediately before being +/// handed to the configured [`crate::formatter::Formatter`]. +/// +/// This borrows from the call site rather than owning its data since it only +/// needs to live for the duration of a single `format` call. +#[derive(Debug, Clone)] +pub struct LogRecord<'a> { + /// The channel this record was logged on. + pub channel: &'a str, + /// The severity level this record was logged at. + pub level: MessageLevel, + /// ISO 8601 formatted timestamp of when the record was created. + pub timestamp: &'a str, + /// The free-text message for this record. + pub message: &'a str, + /// The number of indentation levels active when this record was created. + pub num_indent: u32, + /// The id of the thread that created this record, if thread id logging + /// is enabled. + pub thread_id: Option<&'a str>, + /// Arbitrary structured data attached to this record, merged from any + /// map passed at the call site and any active metadata scopes. + pub extra: Option<&'a MapData>, +} + +impl<'a> LogRecord<'a> { + /// The filter-facing level for this record. + pub fn level(&self) -> Level { + self.level.into() + } + + /// The string label for this record's severity level. + pub fn level_str(&self) -> &'static str { + self.level.name() + } +} diff --git a/src/rust/src/scope.rs b/src/rust/src/scope.rs new file mode 100644 index 0000000..ab44deb --- /dev/null +++ b/src/rust/src/scope.rs @@ -0,0 +1,211 @@ +//! RAII scope guards: indentation, begin/end scoped logs, and metadata. + +use std::cell::RefCell; +use std::collections::HashMap; +use std::time::Instant; + +use serde_json::{json, Value}; + +use crate::core; +use crate::level::MessageLevel; +use crate::record::MapData; + +thread_local! { + static INDENT: RefCell = const { RefCell::new(0) }; + static METADATA: RefCell> = RefCell::new(HashMap::new()); +} + +pub(crate) fn indent_level() -> u32 { + INDENT.with(|indent| *indent.borrow()) +} + +fn push_indent() { + INDENT.with(|indent| *indent.borrow_mut() += 1); +} + +fn pop_indent() { + INDENT.with(|indent| { + let mut indent = indent.borrow_mut(); + if *indent > 0 { + *indent -= 1; + } + }); +} + +pub(crate) fn metadata_snapshot() -> Option { + METADATA.with(|metadata| { + let metadata = metadata.borrow(); + if metadata.is_empty() { + None + } else { + let mut map = MapData::new(); + for (key, value) in metadata.iter() { + map.insert(key.clone(), value.clone()); + } + Some(map) + } + }) +} + +/// Inserts every key/value pair from `map` into the current thread's +/// metadata, returning the keys that were inserted so they can later be +/// removed by [`metadata_remove`]. +fn metadata_set(map: MapData) -> Vec { + METADATA.with(|metadata| { + let mut metadata = metadata.borrow_mut(); + let mut keys = Vec::with_capacity(map.len()); + for (key, value) in map.into_iter() { + keys.push(key.clone()); + metadata.insert(key, value); + } + keys + }) +} + +fn metadata_remove(keys: &[String]) { + METADATA.with(|metadata| { + let mut metadata = metadata.borrow_mut(); + for key in keys { + metadata.remove(key); + } + }); +} + +/// Increments the current thread's indentation level at construction and +/// decrements it at destruction. Indentation is thread-local, so it composes +/// safely with concurrent logging from other threads. +pub struct ScopedIndent(()); + +impl ScopedIndent { + pub fn new() -> Self { + push_indent(); + ScopedIndent(()) + } +} + +impl Default for ScopedIndent { + fn default() -> Self { + Self::new() + } +} + +impl Drop for ScopedIndent { + fn drop(&mut self) { + pop_indent(); + } +} + +/// Logs a `"BEGIN: {message}"` record at construction and a +/// `"END: {message}"` record at destruction, indenting everything logged in +/// between. Both records (and the indentation change) are skipped entirely +/// if `channel`/`level` is not enabled at construction time. +pub struct ScopedLog { + channel: &'static str, + level: MessageLevel, + message: String, + enabled: bool, + indent: Option, +} + +impl ScopedLog { + pub fn new(channel: &'static str, level: MessageLevel, message: impl Into) -> Self { + let message = message.into(); + let enabled = core::is_enabled(channel, level); + if enabled { + core::__log_impl(channel, level, format!("BEGIN: {message}"), None); + } + Self { + channel, + level, + message, + enabled, + indent: enabled.then(ScopedIndent::new), + } + } +} + +impl Drop for ScopedLog { + fn drop(&mut self) { + if self.enabled { + // Drop the indent before logging the end message so that it is + // logged back at the outer indentation level. + self.indent = None; + core::__log_impl( + self.channel, + self.level, + format!("END: {}", self.message), + None, + ); + } + } +} + +/// Starts a clock at construction (only if `channel`/`level` is enabled) and, +/// at destruction, logs the elapsed time as a human-readable message with a +/// `duration_ms` field attached (per the spec, always the floating-point +/// number of milliseconds elapsed). +pub struct ScopedTimer { + channel: &'static str, + level: MessageLevel, + message: String, + start: Option, +} + +impl ScopedTimer { + pub fn new(channel: &'static str, level: MessageLevel, message: impl Into) -> Self { + let message = message.into(); + let start = core::is_enabled(channel, level).then(Instant::now); + Self { + channel, + level, + message, + start, + } + } +} + +impl Drop for ScopedTimer { + fn drop(&mut self) { + let Some(start) = self.start else { return }; + let elapsed = start.elapsed(); + let nanos = elapsed.as_nanos() as f64; + + let (value, suffix) = if nanos >= 100_000_000.0 { + (elapsed.as_secs_f64(), "s") + } else if nanos >= 1_000_000.0 { + (nanos / 1_000_000.0, "ms") + } else if nanos >= 1_000.0 { + (nanos / 1_000.0, "us") + } else { + (nanos, "ns") + }; + + let mut extra = MapData::new(); + extra.insert("duration_ms".to_string(), json!(nanos / 1_000_000.0)); + + let message = format!("{}{:.3}{}", self.message, value, suffix); + core::__log_impl(self.channel, self.level, message, Some(extra)); + } +} + +/// Adds a set of key/value pairs to the current thread's metadata at +/// construction, and removes exactly those keys (by name) at destruction. +/// Metadata is merged into every record's `extra` data (under a nested +/// `"metadata"` key) for as long as any `ScopedMetadata` guard is alive. +pub struct ScopedMetadata { + keys: Vec, +} + +impl ScopedMetadata { + pub fn new(map: MapData) -> Self { + Self { + keys: metadata_set(map), + } + } +} + +impl Drop for ScopedMetadata { + fn drop(&mut self) { + metadata_remove(&self.keys); + } +} From 498d5ca08fd925e2193929d02db835f1568adcb8 Mon Sep 17 00:00:00 2001 From: Gabe Goodhart Date: Wed, 5 Aug 2026 14:17:55 -0600 Subject: [PATCH 03/15] test: Full unit testing Branch: Rust AI-usage: full (Claude + Sonnet 5) Signed-off-by: Gabe Goodhart --- src/rust/tests/channel_test.rs | 142 ++++++++++++++++ src/rust/tests/common/mod.rs | 48 ++++++ src/rust/tests/configure_test.rs | 88 ++++++++++ src/rust/tests/disable_logging_test.rs | 92 +++++++++++ src/rust/tests/filter_test.rs | 82 ++++++++++ src/rust/tests/formatter_json_test.rs | 83 ++++++++++ src/rust/tests/formatter_pretty_test.rs | 105 ++++++++++++ src/rust/tests/lazy_eval_test.rs | 55 +++++++ src/rust/tests/scope_test.rs | 206 ++++++++++++++++++++++++ src/rust/tests/scoped_macros_test.rs | 161 ++++++++++++++++++ src/rust/tests/thread_test.rs | 62 +++++++ 11 files changed, 1124 insertions(+) create mode 100644 src/rust/tests/channel_test.rs create mode 100644 src/rust/tests/common/mod.rs create mode 100644 src/rust/tests/configure_test.rs create mode 100644 src/rust/tests/disable_logging_test.rs create mode 100644 src/rust/tests/filter_test.rs create mode 100644 src/rust/tests/formatter_json_test.rs create mode 100644 src/rust/tests/formatter_pretty_test.rs create mode 100644 src/rust/tests/lazy_eval_test.rs create mode 100644 src/rust/tests/scope_test.rs create mode 100644 src/rust/tests/scoped_macros_test.rs create mode 100644 src/rust/tests/thread_test.rs diff --git a/src/rust/tests/channel_test.rs b/src/rust/tests/channel_test.rs new file mode 100644 index 0000000..a49d059 --- /dev/null +++ b/src/rust/tests/channel_test.rs @@ -0,0 +1,142 @@ +// Excluded under `disable-logging`: every macro exercised here becomes a +// no-op (or, for `alog_is_enabled_channel!`, an unconditional `false`) under +// that feature, which would make these assertions fail by design rather than +// by bug. See `disable_logging_test.rs` for that feature's own coverage. +#![cfg(not(feature = "disable-logging"))] + +mod common; + +use alog::{ + alog, alog_channel, alog_fn_channel, alog_is_enabled_channel, alog_map_channel, + alog_scoped_block_channel, alog_scoped_timer_channel, use_channel, Config, Filters, Level, + MapData, MessageLevel, Writer, +}; +use common::{test_lock, CaptureSink}; +use serde_json::Value; +use std::collections::HashMap; + +use_channel!("CHANTEST"); + +fn log_via_channel_macro() { + alog_channel!(MessageLevel::Info, "via channel macro"); +} + +fn traced_via_channel_macro() { + alog_fn_channel!(); +} + +#[test] +fn channel_macro_matches_explicit_channel() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + log_via_channel_macro(); + alog!("CHANTEST", MessageLevel::Info, "via explicit channel"); + + let lines = sink.lines(); + assert_eq!(lines.len(), 2); + assert!(lines[0].contains("CHANT")); + assert!(lines[0].contains("via channel macro")); + assert!(lines[1].contains("via explicit channel")); +} + +#[test] +fn filtering_out_channel_blocks_channel_macro() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + let mut filters = HashMap::new(); + filters.insert("CHANTEST".to_string(), Level::Off); + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + filters: Filters::Map(filters), + ..Default::default() + }); + + log_via_channel_macro(); + + assert!(sink.contents().is_empty()); +} + +#[test] +fn alog_map_channel_matches_bound_channel() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + formatter: alog::FormatterKind::Json, + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + let mut extra = MapData::new(); + extra.insert("k".to_string(), serde_json::json!("v")); + alog_map_channel!(MessageLevel::Info, extra, "via map channel macro"); + + let parsed: Value = serde_json::from_str(sink.contents().trim_end()).unwrap(); + assert_eq!(parsed["channel"], "CHANTEST"); + assert_eq!(parsed["k"], "v"); + assert_eq!(parsed["message"], "via map channel macro"); +} + +#[test] +fn alog_is_enabled_channel_matches_bound_channel() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + let mut filters = HashMap::new(); + filters.insert("CHANTEST".to_string(), Level::Warning); + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + filters: Filters::Map(filters), + ..Default::default() + }); + + assert!(alog_is_enabled_channel!(MessageLevel::Warning)); + assert!(!alog_is_enabled_channel!(MessageLevel::Info)); +} + +#[test] +fn alog_fn_channel_uses_bound_channel() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + default_level: Level::Trace, + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + traced_via_channel_macro(); + + let lines = sink.lines(); + assert_eq!(lines.len(), 2); + assert!(lines[0].contains("CHANT")); + assert!(lines[0].ends_with("] BEGIN: channel_test::traced_via_channel_macro()")); + assert!(lines[1].ends_with("] END: channel_test::traced_via_channel_macro()")); +} + +#[test] +fn alog_scoped_block_channel_and_scoped_timer_channel_use_bound_channel() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + { + alog_scoped_block_channel!(MessageLevel::Info, "block via channel"); + } + { + alog_scoped_timer_channel!(MessageLevel::Info, "timer via channel"); + } + + let lines = sink.lines(); + assert_eq!(lines.len(), 4); + assert!(lines[0].contains("CHANT")); + assert!(lines[0].ends_with("] BEGIN: block via channel")); + assert!(lines[1].ends_with("] END: block via channel")); + assert!(lines[2].contains("] timer via channel")); + assert!(lines[3].contains("duration_ms")); +} diff --git a/src/rust/tests/common/mod.rs b/src/rust/tests/common/mod.rs new file mode 100644 index 0000000..0c06742 --- /dev/null +++ b/src/rust/tests/common/mod.rs @@ -0,0 +1,48 @@ +//! Shared test helpers: an in-memory capture sink and a lock that serializes +//! tests mutating `alog`'s global configuration within a single test binary. + +use std::io::{self, Write}; +use std::sync::{Arc, Mutex, MutexGuard}; + +static TEST_LOCK: Mutex<()> = Mutex::new(()); + +/// Acquires the process-wide test lock. Hold the returned guard for the +/// duration of any test that calls `alog::configure`/`adjust_levels`, since +/// those mutate state shared by every test in this binary. +pub fn test_lock() -> MutexGuard<'static, ()> { + match TEST_LOCK.lock() { + Ok(guard) => guard, + Err(poisoned) => poisoned.into_inner(), + } +} + +/// An in-memory sink that can be handed to `alog::configure` as a +/// `Writer::Custom` and inspected afterwards via `contents()`/`lines()`. +#[derive(Clone, Default)] +pub struct CaptureSink(Arc>>); + +impl CaptureSink { + pub fn new() -> Self { + Self::default() + } + + pub fn contents(&self) -> String { + String::from_utf8(self.0.lock().unwrap().clone()).expect("capture sink was not valid utf8") + } + + #[allow(dead_code)] + pub fn lines(&self) -> Vec { + self.contents().lines().map(|s| s.to_string()).collect() + } +} + +impl Write for CaptureSink { + fn write(&mut self, buf: &[u8]) -> io::Result { + self.0.lock().unwrap().extend_from_slice(buf); + Ok(buf.len()) + } + + fn flush(&mut self) -> io::Result<()> { + Ok(()) + } +} diff --git a/src/rust/tests/configure_test.rs b/src/rust/tests/configure_test.rs new file mode 100644 index 0000000..7a0cb92 --- /dev/null +++ b/src/rust/tests/configure_test.rs @@ -0,0 +1,88 @@ +// Excluded under `disable-logging`: `alog!` becomes a no-op under that +// feature, which would make these assertions fail by design rather than by +// bug. See `disable_logging_test.rs` for that feature's own coverage. +#![cfg(not(feature = "disable-logging"))] + +mod common; + +use alog::{alog, Config, Filters, FormatterKind, Level, MessageLevel, Writer}; +use common::{test_lock, CaptureSink}; +use std::sync::atomic::{AtomicBool, Ordering}; +use std::sync::Arc; + +#[test] +fn reconfigure_fully_replaces_state() { + let _guard = test_lock(); + let sink1 = CaptureSink::new(); + alog::configure(Config { + default_level: Level::Debug, + formatter: FormatterKind::Pretty, + writer: Writer::Custom(Box::new(sink1.clone())), + ..Default::default() + }); + alog!("TEST", MessageLevel::Debug, "goes to sink1"); + assert!(sink1.contents().contains("goes to sink1")); + + let sink2 = CaptureSink::new(); + alog::configure(Config { + default_level: Level::Error, + formatter: FormatterKind::Json, + writer: Writer::Custom(Box::new(sink2.clone())), + ..Default::default() + }); + alog!("TEST", MessageLevel::Debug, "should not appear anywhere"); + alog!("TEST", MessageLevel::Error, "goes to sink2 as json"); + + assert!(!sink1.contents().contains("should not appear")); + assert!(!sink2.contents().contains("should not appear")); + let out = sink2.contents(); + assert!(out.trim_end().starts_with('{')); + assert!(out.contains("goes to sink2 as json")); +} + +#[test] +fn adjust_levels_leaves_formatter_and_sink_untouched() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + default_level: Level::Info, + formatter: FormatterKind::Json, + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + alog::adjust_levels(Level::Debug, Filters::None); + alog!("TEST", MessageLevel::Debug, "now visible"); + + let out = sink.contents(); + assert!(out.trim_end().starts_with('{')); + assert!(out.contains("now visible")); +} + +#[test] +fn concurrent_configure_and_logging_does_not_panic() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + let stop = Arc::new(AtomicBool::new(false)); + let logger_stop = stop.clone(); + let logger = std::thread::spawn(move || { + while !logger_stop.load(Ordering::Relaxed) { + alog!("TEST", MessageLevel::Info, "logging"); + } + }); + + for _ in 0..50 { + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + } + + stop.store(true, Ordering::Relaxed); + logger.join().unwrap(); +} diff --git a/src/rust/tests/disable_logging_test.rs b/src/rust/tests/disable_logging_test.rs new file mode 100644 index 0000000..58a4c53 --- /dev/null +++ b/src/rust/tests/disable_logging_test.rs @@ -0,0 +1,92 @@ +//! Verifies the Rust analog of `cpp`'s `-D ALOG_DISABLE_LOGGING`: with the +//! `disable-logging` feature enabled, every logging macro becomes a no-op, +//! but directly constructing a `Scoped*` guard (the escape hatch for named +//! instances, e.g. a `ScopedTimer` queried mid-scope) still logs normally. +//! +//! Gated on the feature so this file is entirely excluded from a default +//! build - it would otherwise assert on output the default build's macros +//! actually produce. +#![cfg(feature = "disable-logging")] + +mod common; + +use alog::{ + alog, alog_channel, alog_fn, alog_fn_channel, alog_is_enabled, alog_is_enabled_channel, + alog_map, alog_map_channel, alog_scoped_block, alog_scoped_block_channel, alog_scoped_indent, + alog_scoped_metadata, alog_scoped_timer, alog_scoped_timer_channel, use_channel, Config, Level, + MapData, MessageLevel, ScopedIndent, ScopedLog, ScopedMetadata, ScopedTimer, Writer, +}; +use common::{test_lock, CaptureSink}; + +use_channel!("TEST"); + +#[test] +fn every_macro_is_a_no_op_when_disabled() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + default_level: Level::Trace, + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + alog!("TEST", MessageLevel::Info, "message"); + alog_map!("TEST", MessageLevel::Info, MapData::new(), "message"); + alog_channel!(MessageLevel::Info, "message"); + alog_map_channel!(MessageLevel::Info, MapData::new(), "message"); + alog_fn!("TEST"); + alog_fn_channel!(); + alog_scoped_block!("TEST", MessageLevel::Info, "message"); + alog_scoped_block_channel!(MessageLevel::Info, "message"); + alog_scoped_timer!("TEST", MessageLevel::Info, "message"); + alog_scoped_timer_channel!(MessageLevel::Info, "message"); + alog_scoped_indent!(); + alog_scoped_metadata!(MapData::new()); + + assert!(sink.contents().is_empty()); +} + +#[test] +#[allow(clippy::assertions_on_constants)] +fn alog_is_enabled_macros_are_always_false_when_disabled() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + default_level: Level::Trace, + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + assert!(!alog_is_enabled!("TEST", MessageLevel::Info)); + assert!(!alog_is_enabled_channel!(MessageLevel::Info)); +} + +#[test] +fn directly_constructed_scoped_guards_still_log_when_disabled() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + default_level: Level::Trace, + formatter: alog::FormatterKind::Json, + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + { + let _indent = ScopedIndent::new(); + let _scope = ScopedLog::new("TEST", MessageLevel::Info, "still works"); + let timer = ScopedTimer::new("TEST", MessageLevel::Info, "timed "); + let mut map = MapData::new(); + map.insert("k".to_string(), serde_json::json!("v")); + let _meta = ScopedMetadata::new(map); + drop(timer); + } + + let lines = sink.lines(); + assert_eq!(lines.len(), 3, "expected BEGIN, timer, END"); + assert!(lines[0].contains("BEGIN: still works")); + assert!(lines[1].contains("duration_ms")); + assert!(lines[1].contains("\"k\":\"v\"")); + assert!(lines[2].contains("END: still works")); + assert!(!lines[2].contains("metadata")); +} diff --git a/src/rust/tests/filter_test.rs b/src/rust/tests/filter_test.rs new file mode 100644 index 0000000..383e221 --- /dev/null +++ b/src/rust/tests/filter_test.rs @@ -0,0 +1,82 @@ +// Excluded under `disable-logging`: `alog!` becomes a no-op under that +// feature, which would make these assertions fail by design rather than by +// bug. See `disable_logging_test.rs` for that feature's own coverage. +#![cfg(not(feature = "disable-logging"))] + +mod common; + +use alog::{alog, Config, Filters, Level, MessageLevel, Writer}; +use common::{test_lock, CaptureSink}; +use std::collections::HashMap; + +#[test] +fn default_level_allows_info_blocks_debug() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + alog!("TEST", MessageLevel::Info, "visible"); + alog!("TEST", MessageLevel::Debug, "hidden"); + + let contents = sink.contents(); + assert!(contents.contains("visible")); + assert!(!contents.contains("hidden")); +} + +#[test] +fn per_channel_override() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + let mut filters = HashMap::new(); + filters.insert("VERBOSE".to_string(), Level::Debug); + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + filters: Filters::Map(filters), + ..Default::default() + }); + + alog!("VERBOSE", MessageLevel::Debug, "verbose debug"); + alog!("TEST", MessageLevel::Debug, "default debug"); + + let contents = sink.contents(); + assert!(contents.contains("verbose debug")); + assert!(!contents.contains("default debug")); +} + +#[test] +fn off_blocks_channel_entirely() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + let mut filters = HashMap::new(); + filters.insert("SILENT".to_string(), Level::Off); + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + filters: Filters::Map(filters), + ..Default::default() + }); + + alog!("SILENT", MessageLevel::Fatal, "should never appear"); + + assert!(sink.contents().is_empty()); +} + +#[test] +fn filter_spec_string_parses() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + filters: Filters::Spec("SPEC:debug".to_string()), + ..Default::default() + }); + + alog!("SPEC", MessageLevel::Debug, "spec debug"); + alog!("OTHER", MessageLevel::Debug, "other debug"); + + let contents = sink.contents(); + assert!(contents.contains("spec debug")); + assert!(!contents.contains("other debug")); +} diff --git a/src/rust/tests/formatter_json_test.rs b/src/rust/tests/formatter_json_test.rs new file mode 100644 index 0000000..e7c0fc1 --- /dev/null +++ b/src/rust/tests/formatter_json_test.rs @@ -0,0 +1,83 @@ +use alog::{Formatter, JsonFormatter, Level, LogRecord, MapData, MessageLevel}; +use serde_json::Value; + +#[test] +fn required_fields_present_with_correct_types() { + let formatter = JsonFormatter; + let record = LogRecord { + channel: "TEST", + level: MessageLevel::Info, + timestamp: "2024-01-01T00:00:00.000Z", + message: "hello", + num_indent: 1, + thread_id: None, + extra: None, + }; + + let out = formatter.format(&record); + let parsed: Value = serde_json::from_str(out.trim_end()).unwrap(); + + assert_eq!(parsed["channel"], "TEST"); + assert_eq!(parsed["level"], Level::Info.ordinal()); + assert_eq!(parsed["level_str"], "info"); + assert_eq!(parsed["timestamp"], "2024-01-01T00:00:00.000Z"); + assert_eq!(parsed["message"], "hello"); + assert_eq!(parsed["num_indent"], 1); + assert!(parsed.get("thread_id").is_none()); +} + +#[test] +fn thread_id_present_when_set() { + let formatter = JsonFormatter; + let record = LogRecord { + channel: "TEST", + level: MessageLevel::Info, + timestamp: "TS", + message: "msg", + num_indent: 0, + thread_id: Some("3"), + extra: None, + }; + + let out = formatter.format(&record); + let parsed: Value = serde_json::from_str(out.trim_end()).unwrap(); + assert_eq!(parsed["thread_id"], "3"); +} + +#[test] +fn extra_keys_are_flattened_to_top_level() { + let formatter = JsonFormatter; + let mut extra = MapData::new(); + extra.insert("request_id".to_string(), serde_json::json!("abc-123")); + let record = LogRecord { + channel: "TEST", + level: MessageLevel::Info, + timestamp: "TS", + message: "msg", + num_indent: 0, + thread_id: None, + extra: Some(&extra), + }; + + let out = formatter.format(&record); + let parsed: Value = serde_json::from_str(out.trim_end()).unwrap(); + assert_eq!(parsed["request_id"], "abc-123"); + assert!(!parsed.as_object().unwrap().contains_key("extra")); +} + +#[test] +fn output_is_single_line() { + let formatter = JsonFormatter; + let record = LogRecord { + channel: "TEST", + level: MessageLevel::Info, + timestamp: "TS", + message: "multi\nline", + num_indent: 0, + thread_id: None, + extra: None, + }; + + let out = formatter.format(&record); + assert_eq!(out.trim_end().lines().count(), 1); +} diff --git a/src/rust/tests/formatter_pretty_test.rs b/src/rust/tests/formatter_pretty_test.rs new file mode 100644 index 0000000..af512fe --- /dev/null +++ b/src/rust/tests/formatter_pretty_test.rs @@ -0,0 +1,105 @@ +use alog::{Formatter, LogRecord, MapData, MessageLevel, PrettyFormatter}; + +#[test] +fn header_includes_padded_channel_and_level_abbrev() { + let formatter = PrettyFormatter::default(); + let record = LogRecord { + channel: "TEST", + level: MessageLevel::Info, + timestamp: "2024-01-01T00:00:00.000Z", + message: "hello", + num_indent: 0, + thread_id: None, + extra: None, + }; + + let out = formatter.format(&record); + assert_eq!(out, "2024-01-01T00:00:00.000Z [TEST :INFO] hello\n"); +} + +#[test] +fn multiline_message_repeats_header_per_line() { + let formatter = PrettyFormatter::default(); + let record = LogRecord { + channel: "TEST", + level: MessageLevel::Info, + timestamp: "TS", + message: "line one\nline two", + num_indent: 0, + thread_id: None, + extra: None, + }; + + let out = formatter.format(&record); + assert_eq!(out, "TS [TEST :INFO] line one\nTS [TEST :INFO] line two\n"); +} + +#[test] +fn indentation_repeats_two_spaces_per_level() { + let formatter = PrettyFormatter::default(); + let record = LogRecord { + channel: "TEST", + level: MessageLevel::Info, + timestamp: "TS", + message: "nested", + num_indent: 2, + thread_id: None, + extra: None, + }; + + let out = formatter.format(&record); + assert_eq!(out, "TS [TEST :INFO] nested\n"); +} + +#[test] +fn thread_id_appears_in_header_when_present() { + let formatter = PrettyFormatter::default(); + let record = LogRecord { + channel: "TEST", + level: MessageLevel::Info, + timestamp: "TS", + message: "msg", + num_indent: 0, + thread_id: Some("7"), + extra: None, + }; + + let out = formatter.format(&record); + assert_eq!(out, "TS [TEST :INFO:7] msg\n"); +} + +#[test] +fn channel_longer_than_width_is_truncated() { + let formatter = PrettyFormatter::default(); + let record = LogRecord { + channel: "LONGCHANNEL", + level: MessageLevel::Info, + timestamp: "TS", + message: "msg", + num_indent: 0, + thread_id: None, + extra: None, + }; + + let out = formatter.format(&record); + assert_eq!(out, "TS [LONGC:INFO] msg\n"); +} + +#[test] +fn extra_map_renders_as_bulleted_lines() { + let formatter = PrettyFormatter::default(); + let mut extra = MapData::new(); + extra.insert("count".to_string(), serde_json::json!(3)); + let record = LogRecord { + channel: "TEST", + level: MessageLevel::Info, + timestamp: "TS", + message: "msg", + num_indent: 0, + thread_id: None, + extra: Some(&extra), + }; + + let out = formatter.format(&record); + assert_eq!(out, "TS [TEST :INFO] msg\nTS [TEST :INFO] * count: 3\n"); +} diff --git a/src/rust/tests/lazy_eval_test.rs b/src/rust/tests/lazy_eval_test.rs new file mode 100644 index 0000000..2ab3d0b --- /dev/null +++ b/src/rust/tests/lazy_eval_test.rs @@ -0,0 +1,55 @@ +// Excluded under `disable-logging`: `alog!` becomes a no-op under that +// feature, which would trivially defeat this file's whole purpose (proving +// arguments are lazily evaluated by a macro that, under this feature, +// evaluates nothing at all). +#![cfg(not(feature = "disable-logging"))] + +mod common; + +use alog::{alog, Config, Level, MessageLevel, Writer}; +use common::{test_lock, CaptureSink}; +use std::sync::atomic::{AtomicUsize, Ordering}; + +#[test] +fn disabled_channel_never_evaluates_arguments() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + default_level: Level::Info, + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + static CALLS: AtomicUsize = AtomicUsize::new(0); + fn expensive() -> usize { + CALLS.fetch_add(1, Ordering::SeqCst); + 42 + } + + alog!("TEST", MessageLevel::Debug, "value is {}", expensive()); + + assert_eq!(CALLS.load(Ordering::SeqCst), 0); + assert!(sink.contents().is_empty()); +} + +#[test] +fn enabled_channel_evaluates_arguments_exactly_once() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + default_level: Level::Debug, + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + static CALLS: AtomicUsize = AtomicUsize::new(0); + fn expensive() -> usize { + CALLS.fetch_add(1, Ordering::SeqCst); + 42 + } + + alog!("TEST", MessageLevel::Debug, "value is {}", expensive()); + + assert_eq!(CALLS.load(Ordering::SeqCst), 1); + assert!(sink.contents().contains("value is 42")); +} diff --git a/src/rust/tests/scope_test.rs b/src/rust/tests/scope_test.rs new file mode 100644 index 0000000..f3020cb --- /dev/null +++ b/src/rust/tests/scope_test.rs @@ -0,0 +1,206 @@ +// Excluded under `disable-logging`: `alog!` becomes a no-op under that +// feature, which would make these assertions fail by design rather than by +// bug. See `disable_logging_test.rs` for proof that the `Scoped*` types +// themselves (constructed directly, as they are here) keep working under +// that feature. +#![cfg(not(feature = "disable-logging"))] + +mod common; + +use alog::{ + alog, Config, FormatterKind, Level, MapData, MessageLevel, ScopedIndent, ScopedLog, + ScopedMetadata, ScopedTimer, Writer, +}; +use common::{test_lock, CaptureSink}; +use serde_json::Value; + +#[test] +fn scoped_log_emits_begin_and_end_with_indentation() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + { + let _scope = ScopedLog::new("TEST", MessageLevel::Info, "doing work"); + alog!("TEST", MessageLevel::Info, "inside"); + } + alog!("TEST", MessageLevel::Info, "outside"); + + let lines = sink.lines(); + assert_eq!(lines.len(), 4); + assert!(lines[0].ends_with("] BEGIN: doing work")); + assert!(lines[1].ends_with("] inside")); + assert!(lines[2].ends_with("] END: doing work")); + assert!(lines[3].ends_with("] outside")); +} + +#[test] +fn scoped_log_indentation_is_symmetric_across_panic() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + let result = std::panic::catch_unwind(|| { + let _scope = ScopedLog::new("TEST", MessageLevel::Info, "will panic"); + panic!("boom"); + }); + assert!(result.is_err()); + + alog!("TEST", MessageLevel::Info, "after panic"); + let lines = sink.lines(); + let last = lines.last().unwrap(); + assert!(last.ends_with("] after panic")); +} + +#[test] +fn disabled_scoped_log_emits_nothing() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + default_level: Level::Error, + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + { + let _scope = ScopedLog::new("TEST", MessageLevel::Info, "quiet"); + } + + assert!(sink.contents().is_empty()); +} + +#[test] +fn scoped_indent_nests_and_unwinds() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + alog!("TEST", MessageLevel::Info, "level0"); + { + let _i1 = ScopedIndent::new(); + alog!("TEST", MessageLevel::Info, "level1"); + { + let _i2 = ScopedIndent::new(); + alog!("TEST", MessageLevel::Info, "level2"); + } + alog!("TEST", MessageLevel::Info, "level1-again"); + } + alog!("TEST", MessageLevel::Info, "level0-again"); + + let lines = sink.lines(); + assert_eq!(lines.len(), 5); + assert!(lines[0].ends_with("] level0")); + assert!(lines[1].ends_with("] level1")); + assert!(lines[2].ends_with("] level2")); + assert!(lines[3].ends_with("] level1-again")); + assert!(lines[4].ends_with("] level0-again")); +} + +#[test] +fn scoped_timer_logs_duration_ms_extra() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + formatter: FormatterKind::Json, + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + { + let _timer = ScopedTimer::new("TEST", MessageLevel::Info, "did work in "); + std::thread::sleep(std::time::Duration::from_millis(5)); + } + + let out = sink.contents(); + let parsed: Value = serde_json::from_str(out.trim_end()).unwrap(); + let duration_ms = parsed["duration_ms"] + .as_f64() + .expect("duration_ms present as f64"); + assert!( + duration_ms >= 4.0, + "expected at least ~5ms, got {duration_ms}" + ); +} + +#[test] +fn disabled_scoped_timer_emits_nothing() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + default_level: Level::Error, + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + { + let _timer = ScopedTimer::new("TEST", MessageLevel::Info, "quiet"); + } + + assert!(sink.contents().is_empty()); +} + +#[test] +fn scoped_metadata_attaches_and_removes_keys() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + formatter: FormatterKind::Json, + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + let mut map = MapData::new(); + map.insert("request_id".to_string(), serde_json::json!("abc")); + { + let _meta = ScopedMetadata::new(map); + alog!("TEST", MessageLevel::Info, "inside metadata scope"); + } + alog!("TEST", MessageLevel::Info, "outside metadata scope"); + + let lines = sink.lines(); + assert_eq!(lines.len(), 2); + let inside: Value = serde_json::from_str(&lines[0]).unwrap(); + assert_eq!(inside["metadata"]["request_id"], "abc"); + let outside: Value = serde_json::from_str(&lines[1]).unwrap(); + assert!(outside.get("metadata").is_none()); +} + +#[test] +fn nested_scoped_metadata_is_robust_to_nesting() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + formatter: FormatterKind::Json, + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + let mut outer_map = MapData::new(); + outer_map.insert("outer_key".to_string(), serde_json::json!("outer")); + let _outer = ScopedMetadata::new(outer_map); + { + let mut inner_map = MapData::new(); + inner_map.insert("inner_key".to_string(), serde_json::json!("inner")); + let _inner = ScopedMetadata::new(inner_map); + alog!("TEST", MessageLevel::Info, "nested"); + } + alog!("TEST", MessageLevel::Info, "outer only"); + + let lines = sink.lines(); + let nested: Value = serde_json::from_str(&lines[0]).unwrap(); + assert_eq!(nested["metadata"]["outer_key"], "outer"); + assert_eq!(nested["metadata"]["inner_key"], "inner"); + + let outer_only: Value = serde_json::from_str(&lines[1]).unwrap(); + assert_eq!(outer_only["metadata"]["outer_key"], "outer"); + assert!(outer_only["metadata"].get("inner_key").is_none()); +} diff --git a/src/rust/tests/scoped_macros_test.rs b/src/rust/tests/scoped_macros_test.rs new file mode 100644 index 0000000..0305932 --- /dev/null +++ b/src/rust/tests/scoped_macros_test.rs @@ -0,0 +1,161 @@ +//! Covers the statement-form `alog_scoped_*!` macros, which bind their guard +//! to a hidden variable for you. `scope_test.rs` covers the underlying +//! `Scoped*` types directly; this file covers the macro plumbing on top, +//! including that multiple invocations in the same lexical scope coexist +//! without a variable-name collision (Rust's macro hygiene, not a +//! `__LINE__`-style trick). +//! +//! Excluded under `disable-logging`: every macro exercised here becomes a +//! no-op under that feature, which would make these assertions fail by +//! design rather than by bug. See `disable_logging_test.rs` for that +//! feature's own coverage. +#![cfg(not(feature = "disable-logging"))] + +mod common; + +use alog::{ + alog, alog_scoped_block, alog_scoped_indent, alog_scoped_metadata, alog_scoped_timer, Config, + Level, MapData, MessageLevel, Writer, +}; +use common::{test_lock, CaptureSink}; +use serde_json::Value; + +#[test] +fn alog_scoped_block_emits_begin_and_end() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + { + alog_scoped_block!("TEST", MessageLevel::Info, "doing work"); + alog!("TEST", MessageLevel::Info, "inside"); + } + alog!("TEST", MessageLevel::Info, "outside"); + + let lines = sink.lines(); + assert_eq!(lines.len(), 4); + assert!(lines[0].ends_with("] BEGIN: doing work")); + assert!(lines[1].ends_with("] inside")); + assert!(lines[2].ends_with("] END: doing work")); + assert!(lines[3].ends_with("] outside")); +} + +#[test] +fn two_scoped_blocks_in_the_same_lexical_scope_do_not_collide() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + { + // Two hidden `_alog_scoped_block` bindings live in the same block. + // Hygiene keeps them distinct; both must still log their own + // BEGIN/END, dropping in reverse (LIFO) order at the end of the + // block. + alog_scoped_block!("TEST", MessageLevel::Info, "outer"); + alog_scoped_block!("TEST", MessageLevel::Info, "inner"); + } + + let lines = sink.lines(); + assert_eq!(lines.len(), 4); + assert!(lines[0].ends_with("] BEGIN: outer")); + assert!(lines[1].ends_with("] BEGIN: inner")); + assert!(lines[2].ends_with("] END: inner")); + assert!(lines[3].ends_with("] END: outer")); +} + +#[test] +fn disabled_scoped_block_emits_nothing() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + default_level: Level::Error, + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + { + alog_scoped_block!("TEST", MessageLevel::Info, "quiet"); + } + + assert!(sink.contents().is_empty()); +} + +#[test] +fn alog_scoped_timer_logs_duration_ms_extra() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + formatter: alog::FormatterKind::Json, + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + { + alog_scoped_timer!("TEST", MessageLevel::Info, "did work in "); + std::thread::sleep(std::time::Duration::from_millis(5)); + } + + let parsed: Value = serde_json::from_str(sink.contents().trim_end()).unwrap(); + let duration_ms = parsed["duration_ms"] + .as_f64() + .expect("duration_ms present as f64"); + assert!( + duration_ms >= 4.0, + "expected at least ~5ms, got {duration_ms}" + ); +} + +#[test] +fn alog_scoped_indent_nests_within_the_macro() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + alog!("TEST", MessageLevel::Info, "level0"); + { + alog_scoped_indent!(); + alog!("TEST", MessageLevel::Info, "level1"); + } + alog!("TEST", MessageLevel::Info, "level0-again"); + + let lines = sink.lines(); + assert_eq!(lines.len(), 3); + assert!(lines[0].ends_with("] level0")); + assert!(lines[1].ends_with("] level1")); + assert!(lines[2].ends_with("] level0-again")); +} + +#[test] +fn alog_scoped_metadata_attaches_and_removes_keys() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + formatter: alog::FormatterKind::Json, + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + let mut map = MapData::new(); + map.insert("request_id".to_string(), serde_json::json!("abc")); + { + alog_scoped_metadata!(map); + alog!("TEST", MessageLevel::Info, "inside metadata scope"); + } + alog!("TEST", MessageLevel::Info, "outside metadata scope"); + + let lines = sink.lines(); + assert_eq!(lines.len(), 2); + let inside: Value = serde_json::from_str(&lines[0]).unwrap(); + assert_eq!(inside["metadata"]["request_id"], "abc"); + let outside: Value = serde_json::from_str(&lines[1]).unwrap(); + assert!(outside.get("metadata").is_none()); +} diff --git a/src/rust/tests/thread_test.rs b/src/rust/tests/thread_test.rs new file mode 100644 index 0000000..79ae32f --- /dev/null +++ b/src/rust/tests/thread_test.rs @@ -0,0 +1,62 @@ +// Excluded under `disable-logging`: `alog!` becomes a no-op under that +// feature, which would make these assertions fail by design rather than by +// bug. See `disable_logging_test.rs` for that feature's own coverage. +#![cfg(not(feature = "disable-logging"))] + +mod common; + +use alog::{alog, Config, FormatterKind, MessageLevel, ScopedIndent, Writer}; +use common::{test_lock, CaptureSink}; + +#[test] +fn thread_id_field_is_opt_in() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + formatter: FormatterKind::Json, + writer: Writer::Custom(Box::new(sink.clone())), + thread_id: false, + ..Default::default() + }); + alog!("TEST", MessageLevel::Info, "no thread id"); + let parsed: serde_json::Value = serde_json::from_str(sink.contents().trim_end()).unwrap(); + assert!(parsed.get("thread_id").is_none()); +} + +#[test] +fn thread_id_field_present_when_enabled() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + formatter: FormatterKind::Json, + writer: Writer::Custom(Box::new(sink.clone())), + thread_id: true, + ..Default::default() + }); + alog!("TEST", MessageLevel::Info, "with thread id"); + let parsed: serde_json::Value = serde_json::from_str(sink.contents().trim_end()).unwrap(); + assert!(parsed.get("thread_id").is_some()); +} + +#[test] +fn indentation_is_isolated_per_thread() { + let _guard = test_lock(); + let sink = CaptureSink::new(); + alog::configure(Config { + writer: Writer::Custom(Box::new(sink.clone())), + ..Default::default() + }); + + let _outer_indent = ScopedIndent::new(); + alog!("TEST", MessageLevel::Info, "main thread indented"); + + let handle = std::thread::spawn(|| { + alog!("TEST", MessageLevel::Info, "spawned thread not indented"); + }); + handle.join().unwrap(); + + let lines = sink.lines(); + assert_eq!(lines.len(), 2); + assert!(lines[0].ends_with("] main thread indented")); + assert!(lines[1].ends_with("] spawned thread not indented")); +} From 49cba416b0de532ca7be262dee39098780cb1c40 Mon Sep 17 00:00:00 2001 From: Gabe Goodhart Date: Wed, 5 Aug 2026 14:18:33 -0600 Subject: [PATCH 04/15] feat: Add tutorial example Branch: Rust AI-usage: full (Claude + Sonnet 5) Signed-off-by: Gabe Goodhart --- src/rust/examples/fib.rs | 250 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 250 insertions(+) create mode 100644 src/rust/examples/fib.rs diff --git a/src/rust/examples/fib.rs b/src/rust/examples/fib.rs new file mode 100644 index 0000000..eb14b1f --- /dev/null +++ b/src/rust/examples/fib.rs @@ -0,0 +1,250 @@ +//! A feature-tour example: computes Fibonacci sequences while demonstrating +//! most of `alog`'s features (channels, levels, filters, scoped logs, +//! timers, metadata, and map data). +//! +//! Configure it via environment variables: +//! +//! ALOG_DEFAULT_LEVEL - default level for all channels (default: "info") +//! ALOG_FILTERS - per-channel overrides, e.g. "FIB:debug4" +//! ALOG_USE_JSON - "true" to use the JSON formatter (default: pretty) +//! ALOG_ENABLE_THREAD_ID - "true" to include a thread id on every record +//! +//! Run it with, e.g.: +//! +//! ALOG_DEFAULT_LEVEL=debug4 cargo run --example fib -- 5 8 3 +//! +//! With the `disable-logging` feature enabled, every macro call below +//! becomes a no-op, which leaves several bindings computed only for logging +//! (e.g. `start_msg`, `rendered`) genuinely unused - hence the blanket +//! `allow` below for that feature only. +#![cfg_attr(feature = "disable-logging", allow(unused))] + +use alog::{ + alog, alog_channel, alog_fn_channel, alog_is_enabled, alog_map, alog_scoped_block, + alog_scoped_metadata, alog_scoped_timer, alog_scoped_timer_channel, use_channel, +}; +use alog::{Config, Filters, FormatterKind, Level, MapData, MessageLevel, Writer}; +use serde_json::json; +use std::env; +use std::process::ExitCode; +use std::thread::JoinHandle; + +// TUTORIAL: `use_channel!` declares a free function, `__alog_channel()`, in +// this module. `alog_channel!` calls it implicitly, so call sites in this +// module don't need to repeat the channel name. +use_channel!("FIB"); + +/// Computes the first `n` terms of the Fibonacci sequence, sleeping briefly +/// on each term to simulate real work. +fn fib(n: u32) -> Vec { + // TUTORIAL: `alog_fn_channel!` opens a Trace-level scope named after the + // enclosing function, using the channel bound by `use_channel!` above + // instead of repeating it. It logs "BEGIN: fib(n)" now and "END: fib(n)" + // when the scope drops - including on an early return or unwind. Every + // user-facing macro that takes a channel has one of these `_channel` + // siblings; use `alog_fn!(channel, ...)` instead when you want an + // explicit channel, as `main` does below with "MAIN". + alog_fn_channel!("{n}"); + + // TUTORIAL: `alog_scoped_timer_channel!` binds a `ScopedTimer` to a + // hidden variable for you, using the bound "FIB" channel: it starts a + // clock now and, when dropped, logs the elapsed time with a + // `duration_ms` field attached. + let start_msg = format!("Computed sequence of length {n} in "); + alog_scoped_timer_channel!(MessageLevel::Debug, "{start_msg}"); + + let mut first: u64 = 0; + let mut second: u64 = 1; + let mut out = Vec::with_capacity(n as usize); + + for c in 0..n { + // TUTORIAL: `alog_map!` attaches an arbitrary JSON map to a single + // log record. We use `debug4` here since this fires on every loop + // iteration and would otherwise be very noisy. + alog_map!( + "FIB", + MessageLevel::Debug4, + MapData::from_iter([ + ("c".to_string(), json!(c)), + ("first".to_string(), json!(first)), + ("second".to_string(), json!(second)), + ]), + "loop iteration" + ); + + let next = if c <= 1 { + c as u64 + } else { + let next = first + second; + first = second; + second = next; + next + }; + // Simulate this being expensive. + std::thread::sleep(std::time::Duration::from_millis(next.min(20))); + out.push(next); + } + + alog_map!( + "FIB", + MessageLevel::Debug3, + MapData::from_iter([ + ("first".to_string(), json!(first)), + ("second".to_string(), json!(second)), + ]), + "final variable state" + ); + + out +} + +/// Fans work out across threads and collects the results, mirroring the +/// `cpp` example's `std::async`-based `FibonacciCalculator`. +struct FibonacciCalculator { + handles: Vec>>, +} + +impl FibonacciCalculator { + fn new() -> Self { + Self { + handles: Vec::new(), + } + } + + fn add_sequence_length(&mut self, n: u32) { + // TUTORIAL: `ScopedMetadata` attaches key/value pairs to every + // record logged *on this thread* while the guard is alive - like + // indentation, metadata is thread-local. `fib` runs on a freshly + // spawned thread below, so this won't appear on its records, but it + // will appear on the "queuing job" record logged right here. + let job_number = self.handles.len() + 1; + let mut metadata = MapData::new(); + metadata.insert("job_number".to_string(), json!(job_number)); + alog_scoped_metadata!(metadata); + + alog_channel!(MessageLevel::Debug, "queuing job"); + + // TUTORIAL: Top-level interface functions use `alog_fn_channel!` to + // add a Trace-level BEGIN/END pair around the whole call. Since this + // file bound `use_channel!("FIB")` at module scope, both `fib` and + // `FibonacciCalculator`'s methods log on the "FIB" channel; only + // `main`, below, logs on "MAIN" explicitly. + alog_fn_channel!("{n}"); + self.handles.push(std::thread::spawn(move || fib(n))); + } + + fn get_results(mut self) -> Vec> { + alog_fn_channel!(); + alog_scoped_timer_channel!(MessageLevel::Info, "Finished all jobs in "); + + let mut out = Vec::new(); + for (i, handle) in self.handles.drain(..).enumerate() { + alog_channel!(MessageLevel::Debug2, "waiting on job {}", i + 1); + out.push(handle.join().expect("fib worker thread panicked")); + } + out + } +} + +fn load_env_string(key: &str, default: &str) -> String { + env::var(key).unwrap_or_else(|_| default.to_string()) +} + +fn load_env_bool(key: &str, default: bool) -> bool { + env::var(key) + .map(|v| v.eq_ignore_ascii_case("true")) + .unwrap_or(default) +} + +fn main() -> ExitCode { + // Read configuration from the environment. + let default_level_str = load_env_string("ALOG_DEFAULT_LEVEL", "info"); + let filters_str = load_env_string("ALOG_FILTERS", ""); + let use_json = load_env_bool("ALOG_USE_JSON", false); + let enable_thread_id = load_env_bool("ALOG_ENABLE_THREAD_ID", false); + + // TUTORIAL: This demonstrates all of the standard configuration + // features of `alog`: + // * default_level: the level enabled for any channel not named below + // * filters: per-channel level overrides, e.g. "FIB:debug4" + // * formatter: Pretty (for humans) or Json (for aggregation) + // * thread_id: if true, every record includes the thread id + let default_level: Level = default_level_str.parse().unwrap_or(Level::Info); + let filters = if filters_str.is_empty() { + Filters::None + } else { + Filters::Spec(filters_str) + }; + alog::configure(Config { + default_level, + filters, + formatter: if use_json { + FormatterKind::Json + } else { + FormatterKind::Pretty + }, + writer: Writer::Stdout, + thread_id: enable_thread_id, + }); + + // TUTORIAL: When logging with no channel bound via `use_channel!`, + // simply provide the channel name as `alog!`'s first argument. + alog!("MAIN", MessageLevel::Info, "Logging Configured"); + alog!("MAIN", MessageLevel::Debug, "Hello World"); + + // Parse command line args as sequence lengths. + let mut sequence_lengths = Vec::new(); + { + // TUTORIAL: `alog_scoped_block!` binds a `ScopedLog` to a hidden + // variable for you, wrapping a logically grouped set of actions in + // BEGIN/END log lines - here, parsing the command line. + alog_scoped_block!("MAIN", MessageLevel::Debug, "Parsing Command Line"); + + for (i, arg) in env::args().skip(1).enumerate() { + alog!("MAIN", MessageLevel::Debug2, "Parsing argument {}", i + 1); + match arg.parse::() { + Ok(val) => { + alog!("MAIN", MessageLevel::Debug2, "Parsed value [{val}]"); + sequence_lengths.push(val); + } + Err(_) => { + alog!("MAIN", MessageLevel::Fatal, "Invalid argument [{arg}]"); + return ExitCode::FAILURE; + } + } + } + if sequence_lengths.is_empty() { + alog!( + "MAIN", + MessageLevel::Fatal, + "Must provide at least one sequence length argument" + ); + return ExitCode::FAILURE; + } + } + + let mut calculator = FibonacciCalculator::new(); + { + alog_scoped_timer!("MAIN", MessageLevel::Debug, "Done adding sequences in "); + for length in sequence_lengths { + calculator.add_sequence_length(length); + } + } + + let results = calculator.get_results(); + for sequence in results { + // TUTORIAL: When constructing a log message requires more than a + // single expression, guard the work with `alog_is_enabled!` so it's + // skipped entirely when the channel/level isn't enabled. + if alog_is_enabled!("MAIN", MessageLevel::Info) { + let rendered = sequence + .iter() + .map(|n| n.to_string()) + .collect::>() + .join(" "); + alog!("MAIN", MessageLevel::Info, "[ {rendered} ]"); + } + } + + ExitCode::SUCCESS +} From 25cbbdd18eadc7e21af5d722ae7cdcc03b2d34cd Mon Sep 17 00:00:00 2001 From: Gabe Goodhart Date: Wed, 5 Aug 2026 14:19:11 -0600 Subject: [PATCH 05/15] build: Add dockerized build setup This is still need for release workflow Branch: Rust AI-usage: full (Claude + Sonnet 5) Signed-off-by: Gabe Goodhart --- src/rust/.dockerignore | 1 + src/rust/Dockerfile | 48 ++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 49 insertions(+) create mode 100644 src/rust/.dockerignore create mode 100644 src/rust/Dockerfile diff --git a/src/rust/.dockerignore b/src/rust/.dockerignore new file mode 100644 index 0000000..eb5a316 --- /dev/null +++ b/src/rust/.dockerignore @@ -0,0 +1 @@ +target diff --git a/src/rust/Dockerfile b/src/rust/Dockerfile new file mode 100644 index 0000000..1d24b4e --- /dev/null +++ b/src/rust/Dockerfile @@ -0,0 +1,48 @@ +## Base ####################################################################### +# +# This phase sets up dependencies for the other phases +## +FROM rust:1.70 as base +WORKDIR /src +RUN rustup component add rustfmt clippy + +## Test ######################################################################## +# +# This phase runs the unit tests, lints, and formatting checks for the library +## +FROM base as test +COPY . /src +# NOTE: deliberately not `--all-features` - the `disable-logging` feature +# strips every logging macro down to a no-op, which would break the +# assertions in most of the functional test suite (by design, not by bug). +# It gets its own clippy/test pass instead; see the crate-level docs on +# `disable-logging` in src/lib.rs for the full story. +RUN true && \ + cargo fmt --check && \ + cargo clippy --all-targets -- -D warnings && \ + cargo test && \ + cargo clippy --all-targets --features disable-logging -- -D warnings && \ + cargo test --features disable-logging && \ + cargo build --release --examples && \ + cargo build --release --examples --features disable-logging && \ + true + +## Release ##################################################################### +# +# This phase publishes the crate to crates.io +## +FROM base as release +ARG CARGO_REGISTRY_TOKEN +COPY . /src +RUN cargo publish --token ${CARGO_REGISTRY_TOKEN} + +## Release Test ################################################################ +# +# This phase builds and runs the fibonacci example against the tagged release +# version pulled from crates.io +## +FROM base as release_test +ARG RUST_RELEASE_VERSION +COPY ./examples/fib.rs /src/examples/fib.rs +COPY ./ci/test_release.sh /src/ci/test_release.sh +RUN ./ci/test_release.sh From 5366d30ec60813901f620b0fe48059ecab99d372 Mon Sep 17 00:00:00 2001 From: Gabe Goodhart Date: Wed, 5 Aug 2026 14:19:33 -0600 Subject: [PATCH 06/15] test: Add test_release.sh script Branch: Rust AI-usage: full (Claude + Sonnet 5) Signed-off-by: Gabe Goodhart --- src/rust/ci/test_release.sh | 48 +++++++++++++++++++++++++++++++++++++ 1 file changed, 48 insertions(+) create mode 100755 src/rust/ci/test_release.sh diff --git a/src/rust/ci/test_release.sh b/src/rust/ci/test_release.sh new file mode 100755 index 0000000..fbceaa5 --- /dev/null +++ b/src/rust/ci/test_release.sh @@ -0,0 +1,48 @@ +#!/usr/bin/env bash + +################################################################################ +# This script tests a given release to make sure it has propagated through +# crates.io and can successfully build and run the fibonacci example. It is +# designed to be run inside the docker build only! +################################################################################ + +set -e +cd $(dirname ${BASH_SOURCE[0]})/.. + +# Set up a throwaway crate that depends on the tagged release and builds the +# fibonacci example against it +cat > Cargo.toml < Date: Wed, 5 Aug 2026 14:20:20 -0600 Subject: [PATCH 07/15] ci: Add rust to release.sh Branch: Rust AI-usage: full (Claude + Sonnet 5) Signed-off-by: Gabe Goodhart --- ci/release.sh | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/ci/release.sh b/ci/release.sh index 5ad6ce3..60a739a 100755 --- a/ci/release.sh +++ b/ci/release.sh @@ -36,6 +36,14 @@ then --target=release_test \ --build-arg CPP_RELEASE_VERSION=$tag +elif [ "$release_type" == "rs" ] +then + cd src/rust + docker build . \ + --target=release_test \ + --build-arg RUST_RELEASE_VERSION=$version \ + --build-arg CARGO_REGISTRY_TOKEN=$CARGO_REGISTRY_TOKEN + # Go is special and requires valid semantic versioning for its version tags and # those tags must be scoped by the subdirectory where the go.mod file lives elif [[ "$tag" =~ src/go/v[0-9]+\.[0-9]+\.[0-9]+.* ]] From 42681b6e9cf52760c68c30844cc655673664c96c Mon Sep 17 00:00:00 2001 From: Gabe Goodhart Date: Wed, 5 Aug 2026 14:20:42 -0600 Subject: [PATCH 08/15] ci: Add rust test CI Branch: Rust AI-usage: full (Claude + Sonnet 5) Signed-off-by: Gabe Goodhart --- .github/workflows/rust-tests.yaml | 46 +++++++++++++++++++++++++++++++ 1 file changed, 46 insertions(+) create mode 100644 .github/workflows/rust-tests.yaml diff --git a/.github/workflows/rust-tests.yaml b/.github/workflows/rust-tests.yaml new file mode 100644 index 0000000..8c145bb --- /dev/null +++ b/.github/workflows/rust-tests.yaml @@ -0,0 +1,46 @@ +# This workflow runs the rust implementation unit tests +name: rust-tests +on: + push: + branches: [ main ] + pull_request: + branches: [ main ] + workflow_dispatch: {} +jobs: + build: + runs-on: ubuntu-latest + strategy: + matrix: + toolchain: [stable, "1.70"] + steps: + - uses: actions/checkout@v7 + - name: Set up Rust ${{ matrix.toolchain }} + uses: dtolnay/rust-toolchain@master + with: + toolchain: ${{ matrix.toolchain }} + components: rustfmt, clippy + - name: Check formatting + working-directory: src/rust + run: cargo fmt --check + - name: Lint + working-directory: src/rust + run: cargo clippy --all-targets -- -D warnings + - name: Run unit tests + working-directory: src/rust + run: cargo test + # NOTE: deliberately not `--all-features` above - the `disable-logging` + # feature strips every logging macro down to a no-op, which would break + # most of the functional test suite's assertions (by design, not by + # bug). It gets its own lint/test pass instead. + - name: Lint (disable-logging feature) + working-directory: src/rust + run: cargo clippy --all-targets --features disable-logging -- -D warnings + - name: Run unit tests (disable-logging feature) + working-directory: src/rust + run: cargo test --features disable-logging + - name: Build examples + working-directory: src/rust + run: cargo build --release --examples + - name: Build examples (disable-logging feature) + working-directory: src/rust + run: cargo build --release --examples --features disable-logging From 9e6f5e421aa19018e72f9476a339d611c0aa3ea9 Mon Sep 17 00:00:00 2001 From: Gabe Goodhart Date: Wed, 5 Aug 2026 14:21:09 -0600 Subject: [PATCH 09/15] ci: Add CARGO_REGISTRY_TOKEN secret in release workflow Branch: Rust AI-usage: full (Claude + Sonnet 5) Signed-off-by: Gabe Goodhart --- .github/workflows/release.yml | 1 + 1 file changed, 1 insertion(+) diff --git a/.github/workflows/release.yml b/.github/workflows/release.yml index c446447..2293966 100644 --- a/.github/workflows/release.yml +++ b/.github/workflows/release.yml @@ -14,3 +14,4 @@ jobs: env: PYPI_TOKEN: ${{ secrets.PYPI_TOKEN }} NPM_TOKEN: ${{ secrets.NPM_TOKEN }} + CARGO_REGISTRY_TOKEN: ${{ secrets.CARGO_REGISTRY_TOKEN }} From eae95af8d11938200673a31116533e063058d288 Mon Sep 17 00:00:00 2001 From: Gabe Goodhart Date: Wed, 5 Aug 2026 14:52:28 -0600 Subject: [PATCH 10/15] ci: Use git tag version for publication Branch: Rust AI-usage: full (Claude + Sonnet 5) Signed-off-by: Gabe Goodhart --- src/rust/Cargo.toml | 4 +++- src/rust/Dockerfile | 7 ++++++- 2 files changed, 9 insertions(+), 2 deletions(-) diff --git a/src/rust/Cargo.toml b/src/rust/Cargo.toml index 483cd8e..3ba33f4 100644 --- a/src/rust/Cargo.toml +++ b/src/rust/Cargo.toml @@ -1,6 +1,8 @@ [package] name = "alchemy-logging" -version = "0.1.0" +# Sentinel value overwritten with the real version (derived from the git tag) +# during the release build. See the `release` stage in ./Dockerfile. +version = "0.0.0" edition = "2021" rust-version = "1.70" description = "Multi-language logging framework with configurable channels and levels" diff --git a/src/rust/Dockerfile b/src/rust/Dockerfile index 1d24b4e..0f7321f 100644 --- a/src/rust/Dockerfile +++ b/src/rust/Dockerfile @@ -32,9 +32,14 @@ RUN true && \ # This phase publishes the crate to crates.io ## FROM base as release +ARG RUST_RELEASE_VERSION ARG CARGO_REGISTRY_TOKEN COPY . /src -RUN cargo publish --token ${CARGO_REGISTRY_TOKEN} +# Overwrite the sentinel version in Cargo.toml with the real version derived +# from the git tag before publishing. +RUN sed -i.bak "s/^version = \"0\.0\.0\"/version = \"${RUST_RELEASE_VERSION}\"/" Cargo.toml && \ + rm Cargo.toml.bak && \ + cargo publish --token ${CARGO_REGISTRY_TOKEN} ## Release Test ################################################################ # From af15937d84d6a37090a2dacd56b380a0d017a19f Mon Sep 17 00:00:00 2001 From: Gabe Goodhart Date: Wed, 5 Aug 2026 16:50:29 -0600 Subject: [PATCH 11/15] ci: Use native rust tooling in GHA Branch: Rust AI-usage: full (Claude + Sonnet 5) Signed-off-by: Gabe Goodhart --- .github/workflows/rust-tests.yaml | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/.github/workflows/rust-tests.yaml b/.github/workflows/rust-tests.yaml index 8c145bb..bf9ae51 100644 --- a/.github/workflows/rust-tests.yaml +++ b/.github/workflows/rust-tests.yaml @@ -15,10 +15,9 @@ jobs: steps: - uses: actions/checkout@v7 - name: Set up Rust ${{ matrix.toolchain }} - uses: dtolnay/rust-toolchain@master - with: - toolchain: ${{ matrix.toolchain }} - components: rustfmt, clippy + run: | + rustup toolchain install ${{ matrix.toolchain }} --profile minimal --component rustfmt --component clippy + rustup default ${{ matrix.toolchain }} - name: Check formatting working-directory: src/rust run: cargo fmt --check From 2e4b835a38834222b8842f08cc80bae92672f3df Mon Sep 17 00:00:00 2001 From: Gabe Goodhart Date: Wed, 5 Aug 2026 16:54:38 -0600 Subject: [PATCH 12/15] build: Bump minimum to 1.71 for dependencies Branch: Rust AI-usage: none Signed-off-by: Gabe Goodhart --- src/rust/Cargo.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/rust/Cargo.toml b/src/rust/Cargo.toml index 3ba33f4..24b961d 100644 --- a/src/rust/Cargo.toml +++ b/src/rust/Cargo.toml @@ -4,7 +4,7 @@ name = "alchemy-logging" # during the release build. See the `release` stage in ./Dockerfile. version = "0.0.0" edition = "2021" -rust-version = "1.70" +rust-version = "1.71" description = "Multi-language logging framework with configurable channels and levels" license = "MIT" repository = "https://github.com/IBM/alchemy-logging" From 444d7a7ec183cfeab9b23dd6345c852d05d91024 Mon Sep 17 00:00:00 2001 From: Gabe Goodhart Date: Wed, 5 Aug 2026 16:55:57 -0600 Subject: [PATCH 13/15] fix: Update dockerfile base to 1.71 Branch: Rust AI-usage: none Signed-off-by: Gabe Goodhart --- src/rust/Dockerfile | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/rust/Dockerfile b/src/rust/Dockerfile index 0f7321f..7292102 100644 --- a/src/rust/Dockerfile +++ b/src/rust/Dockerfile @@ -2,7 +2,7 @@ # # This phase sets up dependencies for the other phases ## -FROM rust:1.70 as base +FROM rust:1.71 as base WORKDIR /src RUN rustup component add rustfmt clippy From 5d1bbbd64dcd82cff255fdd30aa5b8e2a6a34b49 Mon Sep 17 00:00:00 2001 From: Gabe Goodhart Date: Wed, 5 Aug 2026 16:58:46 -0600 Subject: [PATCH 14/15] ci: Fix GHA workflow config for 1.71 Branch: Rust AI-usage: none Signed-off-by: Gabe Goodhart --- .github/workflows/rust-tests.yaml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/rust-tests.yaml b/.github/workflows/rust-tests.yaml index bf9ae51..cb88afe 100644 --- a/.github/workflows/rust-tests.yaml +++ b/.github/workflows/rust-tests.yaml @@ -11,7 +11,7 @@ jobs: runs-on: ubuntu-latest strategy: matrix: - toolchain: [stable, "1.70"] + toolchain: [stable, "1.71"] steps: - uses: actions/checkout@v7 - name: Set up Rust ${{ matrix.toolchain }} From b70aa58450b0349c85430d05a8352e00d3fd36a3 Mon Sep 17 00:00:00 2001 From: Gabe Goodhart Date: Wed, 5 Aug 2026 17:02:31 -0600 Subject: [PATCH 15/15] style: Clippy fix Branch: Rust AI-usage: none Signed-off-by: Gabe Goodhart --- src/rust/src/core.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/rust/src/core.rs b/src/rust/src/core.rs index c2822e5..3c2b188 100644 --- a/src/rust/src/core.rs +++ b/src/rust/src/core.rs @@ -61,7 +61,7 @@ pub enum FormatterKind { impl FormatterKind { fn into_formatter(self) -> Box { match self { - FormatterKind::Pretty => Box::new(PrettyFormatter::default()), + FormatterKind::Pretty => Box::::default(), FormatterKind::Json => Box::new(JsonFormatter), FormatterKind::Custom(f) => f, } @@ -121,7 +121,7 @@ fn config() -> &'static RwLock { fn sink() -> &'static Mutex { SINK.get_or_init(|| { Mutex::new(SinkState { - formatter: Box::new(PrettyFormatter::default()), + formatter: Box::::default(), sink: Box::new(io::stdout()), }) })