diff --git a/README.md b/README.md index f25c99c..2789830 100644 --- a/README.md +++ b/README.md @@ -109,9 +109,9 @@ fn main() -> std::io::Result<()> { .poller_interval(Duration::from_millis(1)) .start()?; - ferrilog::logi!("server started on port {}", 8080u32); - ferrilog::logw!("connection pool at {}% capacity", 85u32); - ferrilog::loge!("request failed with code {:#x}", 0xDEADu32); + ferrilog::info!("server started on port {}", 8080u32); + ferrilog::warn!("connection pool at {}% capacity", 85u32); + ferrilog::error!("request failed with code {:#x}", 0xDEADu32); Ok(()) // _guard drops here: stops poller, flushes all pending messages @@ -130,10 +130,10 @@ Output: | Macro | Level | Example | |-------|-------|---------| -| `logd!(...)` | Debug | `logd!("x={}", x)` | -| `logi!(...)` | Info | `logi!("started")` | -| `logw!(...)` | Warning | `logw!("slow query: {}ms", elapsed)` | -| `loge!(...)` | Error | `loge!("failed: {}", err)` | +| `debug!(...)` | Debug | `debug!("x={}", x)` | +| `info!(...)` | Info | `info!("started")` | +| `warn!(...)` | Warning | `warn!("slow query: {}ms", elapsed)` | +| `error!(...)` | Error | `error!("failed: {}", err)` | | `log!(level, ...)` | Any | `log!(Level::WRN, "custom={}", v)` | The `log!` macro **automatically selects the optimal encoding path** at compile time: @@ -143,16 +143,16 @@ The `log!` macro **automatically selects the optimal encoding path** at compile ## Format Specifiers ```rust -ferrilog::logi!("decimal: {}", 255u32); // 255 -ferrilog::logi!("hex: {:x}", 255u32); // ff -ferrilog::logi!("upper hex: {:#X}", 255u32); // 0xFF -ferrilog::logi!("binary: {:#b}", 10u32); // 0b1010 -ferrilog::logi!("octal: {:o}", 255u32); // 377 -ferrilog::logi!("precision: {:.3}", 3.14159f64); // 3.142 -ferrilog::logi!("right-pad: {:>10}", 42u32); // 42 -ferrilog::logi!("left-pad: {:<10}", 42u32); // 42 -ferrilog::logi!("center: {:^10}", 42u32); // 42 -ferrilog::logi!("zero-pad: {:08}", 42u32); // 00000042 +ferrilog::info!("decimal: {}", 255u32); // 255 +ferrilog::info!("hex: {:x}", 255u32); // ff +ferrilog::info!("upper hex: {:#X}", 255u32); // 0xFF +ferrilog::info!("binary: {:#b}", 10u32); // 0b1010 +ferrilog::info!("octal: {:o}", 255u32); // 377 +ferrilog::info!("precision: {:.3}", 3.14159f64); // 3.142 +ferrilog::info!("right-pad: {:>10}", 42u32); // 42 +ferrilog::info!("left-pad: {:<10}", 42u32); // 42 +ferrilog::info!("center: {:^10}", 42u32); // 42 +ferrilog::info!("zero-pad: {:08}", 42u32); // 00000042 ``` ## Custom Types @@ -173,7 +173,7 @@ impl std::fmt::Display for Order { } } -ferrilog::logi!("new order: {}", Order { id: 1001, price: 49.99, qty: 100 }); +ferrilog::info!("new order: {}", Order { id: 1001, price: 49.99, qty: 100 }); // → new order: Order{id=1001, price=49.99, qty=100} ``` @@ -230,7 +230,7 @@ use std::thread; for i in 0..4 { thread::spawn(move || { ferrilog::set_thread_name(&format!("worker-{i}")); - ferrilog::logi!("hello from thread {}", i as u32); + ferrilog::info!("hello from thread {}", i as u32); }); } ``` diff --git a/benches/core_component_bench.rs b/benches/core_component_bench.rs index d9dc910..166dbf3 100644 --- a/benches/core_component_bench.rs +++ b/benches/core_component_bench.rs @@ -41,6 +41,7 @@ fn write_static_complex_header( level: ferrilog_core::Level, thread_name: &[u8], location: &str, + _span_id: u64, ) { output.reserve(37 + thread_name.len() + location.len()); output.extend_from_slice(thread_name); @@ -615,6 +616,7 @@ fn bench_header_output(criterion: &mut Criterion) { INFO, b"bench-thread", "core/benches/core_component_bench.rs:1", + 0u64, ); black_box(output); }, @@ -633,6 +635,7 @@ fn bench_header_output(criterion: &mut Criterion) { INFO, b"bench-thread", "core/benches/core_component_bench.rs:1", + 0u64, ); black_box(output); }, @@ -658,6 +661,7 @@ fn bench_header_output(criterion: &mut Criterion) { INFO, b"bench-thread", "core/benches/core_component_bench.rs:1", + 0u64, ); black_box(output); }, @@ -676,6 +680,7 @@ fn bench_header_output(criterion: &mut Criterion) { INFO, b"bench-thread", "core/benches/core_component_bench.rs:1", + 0u64, ); black_box(output); }, @@ -695,6 +700,7 @@ fn bench_header_output(criterion: &mut Criterion) { INFO, b"bench-thread", "core/benches/core_component_bench.rs:1", + 0u64, ); black_box(output); }, @@ -714,6 +720,7 @@ fn bench_header_output(criterion: &mut Criterion) { INFO, b"bench-thread", "core/benches/core_component_bench.rs:1", + 0u64, ); black_box(output); }, @@ -735,6 +742,7 @@ fn bench_header_output(criterion: &mut Criterion) { INFO, b"bench-thread", "core/benches/core_component_bench.rs:1", + 0u64, |buffer| number_format::append_u32(buffer, 42), ) .unwrap(); @@ -754,7 +762,7 @@ fn bench_header_output(criterion: &mut Criterion) { }, |mut output| { output - .write_record(black_box(0), INFO, b"bench", "bench", |buffer| unsafe { + .write_record(black_box(0), INFO, b"bench", "bench", 0, |buffer| unsafe { decode_static_body(std::ptr::null(), buffer); }) .unwrap(); @@ -779,6 +787,7 @@ fn bench_header_output(criterion: &mut Criterion) { INFO, b"bench-thread", "core/benches/core_component_bench.rs:1", + 0u64, |buffer| number_format::append_u32(buffer, 42), ) .unwrap(); @@ -803,6 +812,7 @@ fn bench_header_output(criterion: &mut Criterion) { INFO, b"bench-thread", "core/benches/core_component_bench.rs:1", + 0u64, |buffer| number_format::append_u32(buffer, 42), ) .unwrap(); @@ -827,6 +837,7 @@ fn bench_header_output(criterion: &mut Criterion) { INFO, b"bench-thread", "core/benches/core_component_bench.rs:1", + 0u64, |buffer| number_format::append_u32(buffer, 42), ) .unwrap(); @@ -848,6 +859,7 @@ fn bench_header_output(criterion: &mut Criterion) { INFO, b"bench-thread", "core/benches/core_component_bench.rs:1", + 0u64, |buffer| number_format::append_u32(buffer, index), ) .unwrap(); diff --git a/core/src/header.rs b/core/src/header.rs index 6831b77..364cee6 100644 --- a/core/src/header.rs +++ b/core/src/header.rs @@ -61,7 +61,20 @@ impl HeaderDateCache { } } -pub type StaticHeaderWriteFn = fn(&mut HeaderDateCache, &mut Vec, i64, Level, &[u8], &str); +/// Appends a span id to `output`, using `-` for the root/no-span id. +#[inline] +pub fn append_span_id(output: &mut Vec, span_id: u64) { + if span_id == 0 { + output.push(b'-'); + return; + } + + let mut buffer = [0u8; 20]; + let len = number_format::format_u64(&mut buffer, span_id); + output.extend_from_slice(&buffer[..len]); +} + +pub type StaticHeaderWriteFn = fn(&mut HeaderDateCache, &mut Vec, i64, Level, &[u8], &str, u64); #[derive(Debug, Clone)] pub struct StaticHeader { @@ -82,8 +95,17 @@ impl StaticHeader { level: Level, thread_name: &[u8], location: &str, + span_id: u64, ) { - (self.write)(&mut self.date_cache, output, nanoseconds, level, thread_name, location); + (self.write)( + &mut self.date_cache, + output, + nanoseconds, + level, + thread_name, + location, + span_id, + ); } } @@ -112,6 +134,7 @@ impl DefaultHeader { level: Level, thread_name: &[u8], location: &str, + _span_id: u64, ) { self.date_cache.ensure_date(nanoseconds); output.reserve(DEFAULT_HEADER_FIXED_LEN + thread_name.len() + location.len()); @@ -148,6 +171,7 @@ impl LevelThreadLocationHeader { level: Level, thread_name: &[u8], location: &str, + _span_id: u64, ) { output.reserve(LEVEL_THREAD_LOCATION_HEADER_FIXED_LEN + thread_name.len() + location.len()); output.extend_from_slice(level.as_bytes()); @@ -172,6 +196,8 @@ pub enum HeaderToken { Nanosecond, /// The log level. Level, + /// The current span id (`-` when no span is active). + SpanId, /// The thread name. ThreadName, /// The source location. @@ -194,8 +220,8 @@ impl TokenizedHeader { /// Parses a header pattern string into a `TokenizedHeader`. /// - /// Supported placeholders: `{date}`, `{time}`, `{ns}`, `{level}`, `{thread}`, `{location}`. - /// Use `{{` and `}}` for literal braces. + /// Supported placeholders: `{date}`, `{time}`, `{ns}`, `{level}`, `{span}`, `{thread}`, + /// `{location}`. Use `{{` and `}}` for literal braces. pub fn parse_pattern(pattern: &str) -> io::Result { let mut pattern_buffer = Vec::new(); let mut tokens = Vec::new(); @@ -269,8 +295,9 @@ impl TokenizedHeader { level: Level, thread_name: &[u8], location: &str, + span_id: u64, ) { - output.reserve(self.pattern_buffer.len() + thread_name.len() + location.len() + 32); + output.reserve(self.pattern_buffer.len() + thread_name.len() + location.len() + 52); for index in 0..self.tokens.len() { match self.tokens[index] { @@ -283,6 +310,7 @@ impl TokenizedHeader { HeaderToken::Time => append_header_time(output, nanoseconds), HeaderToken::Nanosecond => append_header_nanoseconds(output, nanoseconds), HeaderToken::Level => output.extend_from_slice(level.as_bytes()), + HeaderToken::SpanId => append_span_id(output, span_id), HeaderToken::ThreadName => output.extend_from_slice(thread_name), HeaderToken::Location => output.extend_from_slice(location.as_bytes()), } @@ -315,6 +343,7 @@ fn parse_named_token(name: &str) -> io::Result { "time" => Ok(HeaderToken::Time), "ns" => Ok(HeaderToken::Nanosecond), "level" => Ok(HeaderToken::Level), + "span" => Ok(HeaderToken::SpanId), "thread" => Ok(HeaderToken::ThreadName), "location" => Ok(HeaderToken::Location), _ => Err(io::Error::new( @@ -419,6 +448,7 @@ mod tests { Level::INF, b"worker-1", "src/main.rs:10", + 0, ); let string = String::from_utf8(output).unwrap(); assert!(string.contains("INF|worker-1|src/main.rs:10|")); @@ -439,6 +469,7 @@ mod tests { Level::INF, b"worker-1", "src/main.rs:10", + 0, ); specialized.write_header( &mut specialized_output, @@ -446,6 +477,7 @@ mod tests { Level::INF, b"worker-1", "src/main.rs:10", + 0, ); assert_eq!(specialized_output, tokenized_output); @@ -466,6 +498,7 @@ mod tests { Level::INF, b"worker-1", "src/main.rs:10", + 0, ); specialized.write_header( &mut specialized_output, @@ -473,8 +506,21 @@ mod tests { Level::INF, b"worker-1", "src/main.rs:10", + 0, ); assert_eq!(specialized_output, tokenized_output); } + + #[test] + fn span_header_token_renders_dash_for_root_and_decimal_for_span() { + let mut header = TokenizedHeader::parse_pattern("{level}|span={span}|").unwrap(); + let mut root = Vec::new(); + header.write_header(&mut root, 0, Level::TRC, b"worker-1", "src/main.rs:10", 0); + assert_eq!(String::from_utf8(root).unwrap(), "TRC|span=-|"); + + let mut span = Vec::new(); + header.write_header(&mut span, 0, Level::TRC, b"worker-1", "src/main.rs:10", 42); + assert_eq!(String::from_utf8(span).unwrap(), "TRC|span=42|"); + } } diff --git a/core/src/lib.rs b/core/src/lib.rs index dc49c5a..49fd5ab 100644 --- a/core/src/lib.rs +++ b/core/src/lib.rs @@ -8,6 +8,7 @@ pub mod logger; pub mod number_format; pub mod output; pub mod poller; +pub mod span; pub mod spsc_queue; pub mod thread_buffer; pub mod timestamp_counter; @@ -27,7 +28,7 @@ pub use encode::{Encode, EncodeFast}; #[doc(hidden)] pub use header::{ HeaderDateCache, StaticHeader, StaticHeaderWriteFn, append_header_nanoseconds, - append_header_time, + append_header_time, append_span_id, }; #[doc(hidden)] pub use logger::{DecodeFn, StaticInfo, check_level, set_static_header}; @@ -38,9 +39,14 @@ pub use logger::{ start_polling_thread, start_polling_thread_on_core, stop_polling_thread, }; pub use output::RotationConfig; +pub use span::{ + Instrument, Instrumented, ROOT_SPAN_ID, Span, SpanGuard, SpanId, StaticSpanInfo, + current_span_id, current_span_id_u64, +}; #[doc(hidden)] pub use spsc_queue::{ - PAYLOAD_ARGS_OFFSET, PAYLOAD_HEADER_SIZE, PAYLOAD_INFO_OFFSET, PAYLOAD_TIMESTAMP_OFFSET, + PAYLOAD_ARGS_OFFSET, PAYLOAD_HEADER_SIZE, PAYLOAD_INFO_OFFSET, PAYLOAD_SPAN_ID_OFFSET, + PAYLOAD_TIMESTAMP_OFFSET, }; #[doc(hidden)] pub use thread_buffer::alloc_message; @@ -52,16 +58,18 @@ pub use timestamp_counter::TimestampCounter; #[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord)] #[repr(u8)] pub enum Level { + /// Trace level. + TRC = 0, /// Debug level. - DBG = 0, + DBG = 1, /// Info level. - INF = 1, + INF = 2, /// Warning level. - WRN = 2, + WRN = 3, /// Error level. - ERR = 3, + ERR = 4, /// Logging disabled. - OFF = 4, + OFF = 5, } impl Level { @@ -69,6 +77,7 @@ impl Level { #[inline] pub fn as_bytes(&self) -> &'static [u8] { match self { + Level::TRC => b"TRC", Level::DBG => b"DBG", Level::INF => b"INF", Level::WRN => b"WRN", @@ -82,14 +91,17 @@ impl Level { #[inline] pub fn level_from_u8(value: u8) -> Level { match value { - 0 => Level::DBG, - 1 => Level::INF, - 2 => Level::WRN, - 3 => Level::ERR, + 0 => Level::TRC, + 1 => Level::DBG, + 2 => Level::INF, + 3 => Level::WRN, + 4 => Level::ERR, _ => Level::OFF, } } +/// Shorthand constant for [`Level::TRC`]. +pub const TRC: Level = Level::TRC; /// Shorthand constant for [`Level::DBG`]. pub const DBG: Level = Level::DBG; /// Shorthand constant for [`Level::INF`]. @@ -101,6 +113,8 @@ pub const ERR: Level = Level::ERR; /// Shorthand constant for [`Level::OFF`]. pub const OFF: Level = Level::OFF; +/// Alias for [`Level::TRC`]. +pub const TRACE: Level = Level::TRC; /// Alias for [`Level::DBG`]. pub const DEBUG: Level = Level::DBG; /// Alias for [`Level::INF`]. diff --git a/core/src/logger.rs b/core/src/logger.rs index 2c48af9..4f7a895 100644 --- a/core/src/logger.rs +++ b/core/src/logger.rs @@ -13,7 +13,7 @@ use crate::{ Level, StaticHeaderWriteFn, level_from_u8, output::{OutputBuffer, RotationConfig}, poller::{self, PollerState, ReadyMessageHeap}, - spsc_queue::{PAYLOAD_ARGS_OFFSET, PAYLOAD_INFO_OFFSET, SpscVarQueue}, + spsc_queue::{PAYLOAD_ARGS_OFFSET, PAYLOAD_INFO_OFFSET, PAYLOAD_SPAN_ID_OFFSET, SpscVarQueue}, thread_buffer::{THREAD_BUFFER_REGISTRY, ThreadBuffer}, timestamp_counter::TimestampCounter, }; @@ -25,7 +25,7 @@ pub type DecodeFn = unsafe fn(*const u8, &mut Vec); /// The argument is the cumulative count of queue-full events. pub type QueueFullCallback = fn(u64); -/// Default log level (DBG = accept all messages). +/// Default log level (DBG = accept debug and above; trace stays opt-in). const DEFAULT_LEVEL: u8 = Level::DBG as u8; /// Default flush delay (3 seconds in nanoseconds). @@ -425,6 +425,7 @@ fn poll_inner( let timestamp_nanoseconds = timestamp_counter.timestamp_to_nanoseconds(node.raw_timestamp()); + let span_id = unsafe { payload.add(PAYLOAD_SPAN_ID_OFFSET).cast::().read_unaligned() }; let thread_name = unsafe { (*node.thread_buffer()).name_bytes() }; unsafe { output.write_record( @@ -432,6 +433,7 @@ fn poll_inner( info.level, thread_name, info.location, + span_id, |buffer| (info.decode)(payload.add(PAYLOAD_ARGS_OFFSET), buffer), )?; } diff --git a/core/src/number_format.rs b/core/src/number_format.rs index 6849a55..b6538ff 100644 --- a/core/src/number_format.rs +++ b/core/src/number_format.rs @@ -4,29 +4,16 @@ use crate::encode::{ /// ASCII byte pairs for 00-99, totaling 200 bytes. /// `DIGIT_PAIRS[number * 2 .. number * 2 + 2]` gives the two-digit ASCII representation of `number`. -#[rustfmt::skip] -pub static DIGIT_PAIRS: [u8; 200] = [ - b'0',b'0', b'0',b'1', b'0',b'2', b'0',b'3', b'0',b'4', - b'0',b'5', b'0',b'6', b'0',b'7', b'0',b'8', b'0',b'9', - b'1',b'0', b'1',b'1', b'1',b'2', b'1',b'3', b'1',b'4', - b'1',b'5', b'1',b'6', b'1',b'7', b'1',b'8', b'1',b'9', - b'2',b'0', b'2',b'1', b'2',b'2', b'2',b'3', b'2',b'4', - b'2',b'5', b'2',b'6', b'2',b'7', b'2',b'8', b'2',b'9', - b'3',b'0', b'3',b'1', b'3',b'2', b'3',b'3', b'3',b'4', - b'3',b'5', b'3',b'6', b'3',b'7', b'3',b'8', b'3',b'9', - b'4',b'0', b'4',b'1', b'4',b'2', b'4',b'3', b'4',b'4', - b'4',b'5', b'4',b'6', b'4',b'7', b'4',b'8', b'4',b'9', - b'5',b'0', b'5',b'1', b'5',b'2', b'5',b'3', b'5',b'4', - b'5',b'5', b'5',b'6', b'5',b'7', b'5',b'8', b'5',b'9', - b'6',b'0', b'6',b'1', b'6',b'2', b'6',b'3', b'6',b'4', - b'6',b'5', b'6',b'6', b'6',b'7', b'6',b'8', b'6',b'9', - b'7',b'0', b'7',b'1', b'7',b'2', b'7',b'3', b'7',b'4', - b'7',b'5', b'7',b'6', b'7',b'7', b'7',b'8', b'7',b'9', - b'8',b'0', b'8',b'1', b'8',b'2', b'8',b'3', b'8',b'4', - b'8',b'5', b'8',b'6', b'8',b'7', b'8',b'8', b'8',b'9', - b'9',b'0', b'9',b'1', b'9',b'2', b'9',b'3', b'9',b'4', - b'9',b'5', b'9',b'6', b'9',b'7', b'9',b'8', b'9',b'9', -]; +pub static DIGIT_PAIRS: [u8; 200] = *b"00010203040506070809\ +10111213141516171819\ +20212223242526272829\ +30313233343536373839\ +40414243444546474849\ +50515253545556575859\ +60616263646566676869\ +70717273747576777879\ +80818283848586878889\ +90919293949596979899"; // --- Fixed-width formatting (header time fields) --- diff --git a/core/src/output.rs b/core/src/output.rs index 456acd0..eec01e3 100644 --- a/core/src/output.rs +++ b/core/src/output.rs @@ -93,20 +93,21 @@ impl HeaderMode { level: Level, thread_name: &[u8], location: &str, + span_id: u64, ) { match self { Self::Empty => {} Self::Default(header) => { - header.write_header(output, nanoseconds, level, thread_name, location); + header.write_header(output, nanoseconds, level, thread_name, location, span_id); } Self::LevelThreadLocation(header) => { - header.write_header(output, nanoseconds, level, thread_name, location); + header.write_header(output, nanoseconds, level, thread_name, location, span_id); } Self::Static(header) => { - header.write_header(output, nanoseconds, level, thread_name, location); + header.write_header(output, nanoseconds, level, thread_name, location, span_id); } Self::Dynamic(header) => { - header.write_header(output, nanoseconds, level, thread_name, location); + header.write_header(output, nanoseconds, level, thread_name, location, span_id); } } } @@ -186,6 +187,7 @@ impl OutputBuffer { level: Level, thread_name: &[u8], location: &str, + span_id: u64, append_body: F, ) -> io::Result<()> where @@ -197,6 +199,7 @@ impl OutputBuffer { level, thread_name, location, + span_id, ); append_body(&mut self.pending); self.pending.push(b'\n'); diff --git a/core/src/span.rs b/core/src/span.rs new file mode 100644 index 0000000..4346c06 --- /dev/null +++ b/core/src/span.rs @@ -0,0 +1,303 @@ +use std::{ + cell::Cell, + future::Future, + pin::Pin, + sync::atomic::{AtomicU64, Ordering}, + task::{Context, Poll}, +}; + +/// The root span id used when no span is currently entered. +pub const ROOT_SPAN_ID: u64 = 0; + +const MAX_SPAN_DEPTH: usize = 64; + +static NEXT_SPAN_ID: AtomicU64 = AtomicU64::new(1); + +thread_local! { + static SPAN_STACK: Cell = const { Cell::new(SpanStack::new()) }; +} + +/// Numeric identifier for a span. +#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] +pub struct SpanId(u64); + +impl SpanId { + /// The root span id used outside any entered span. + pub const ROOT: Self = Self(ROOT_SPAN_ID); + + /// Creates a span id from its raw numeric representation. + #[inline] + pub const fn from_u64(value: u64) -> Self { + Self(value) + } + + /// Returns the raw numeric representation. + #[inline] + pub const fn as_u64(self) -> u64 { + self.0 + } +} + +impl Default for SpanId { + fn default() -> Self { + Self::ROOT + } +} + +/// Static metadata associated with a span call site. +#[derive(Debug)] +pub struct StaticSpanInfo { + name: &'static str, + location: &'static str, +} + +impl StaticSpanInfo { + /// Creates static span metadata. + #[inline] + pub const fn new(name: &'static str, location: &'static str) -> Self { + Self { name, location } + } + + /// Span name. + #[inline] + pub const fn name(&self) -> &'static str { + self.name + } + + /// Source location where the span was created. + #[inline] + pub const fn location(&self) -> &'static str { + self.location + } +} + +/// A lightweight span handle. +#[derive(Debug, Clone, Copy)] +pub struct Span { + id: SpanId, + parent_id: SpanId, + info: &'static StaticSpanInfo, +} + +impl Span { + /// Creates a new span under the currently entered span. + #[inline] + pub fn new(info: &'static StaticSpanInfo) -> Self { + let id = NEXT_SPAN_ID.fetch_add(1, Ordering::Relaxed); + Self { id: SpanId::from_u64(id), parent_id: current_span_id(), info } + } + + /// Returns this span's id. + #[inline] + pub const fn id(self) -> SpanId { + self.id + } + + /// Returns this span's parent id. + #[inline] + pub const fn parent_id(self) -> SpanId { + self.parent_id + } + + /// Returns this span's static name. + #[inline] + pub const fn name(self) -> &'static str { + self.info.name() + } + + /// Returns this span's creation location. + #[inline] + pub const fn location(self) -> &'static str { + self.info.location() + } + + /// Enters the span on the current thread until the returned guard is dropped. + #[inline] + pub fn enter(self) -> SpanGuard { + push_span(self.id); + SpanGuard { id: self.id } + } + + /// Runs a closure inside this span. + #[inline] + pub fn in_scope(self, f: F) -> R + where + F: FnOnce() -> R, + { + let _guard = self.enter(); + f() + } +} + +/// RAII guard returned by [`Span::enter`]. +#[derive(Debug)] +pub struct SpanGuard { + id: SpanId, +} + +impl Drop for SpanGuard { + #[inline] + fn drop(&mut self) { + pop_span(self.id); + } +} + +/// Returns the current thread's active span id. +#[inline] +pub fn current_span_id() -> SpanId { + SpanId::from_u64(current_span_id_u64()) +} + +/// Returns the current thread's active span id as a raw integer. +/// +/// This is used by the logging macro after level filtering has already passed, +/// keeping the disabled-log hot path to a single level check. +#[inline] +pub fn current_span_id_u64() -> u64 { + SPAN_STACK.with(|stack| stack.get().current()) +} + +#[inline] +fn push_span(id: SpanId) { + SPAN_STACK.with(|cell| { + let mut stack = cell.get(); + stack.push(id.as_u64()); + cell.set(stack); + }); +} + +#[inline] +fn pop_span(id: SpanId) { + SPAN_STACK.with(|cell| { + let mut stack = cell.get(); + stack.pop(id.as_u64()); + cell.set(stack); + }); +} + +#[derive(Clone, Copy)] +struct SpanStack { + ids: [u64; MAX_SPAN_DEPTH], + depth: u8, + overflow_depth: u16, +} + +impl SpanStack { + const fn new() -> Self { + Self { ids: [ROOT_SPAN_ID; MAX_SPAN_DEPTH], depth: 0, overflow_depth: 0 } + } + + #[inline] + fn current(self) -> u64 { + if self.depth == 0 { ROOT_SPAN_ID } else { self.ids[self.depth as usize - 1] } + } + + #[inline] + fn push(&mut self, id: u64) { + let depth = self.depth as usize; + if depth < MAX_SPAN_DEPTH { + self.ids[depth] = id; + self.depth += 1; + } else { + self.overflow_depth = self.overflow_depth.saturating_add(1); + } + } + + #[inline] + fn pop(&mut self, id: u64) { + if self.overflow_depth > 0 { + self.overflow_depth -= 1; + return; + } + + if self.depth == 0 { + return; + } + + let top = self.depth as usize - 1; + if self.ids[top] == id { + self.ids[top] = ROOT_SPAN_ID; + self.depth -= 1; + return; + } + + debug_assert_eq!(self.ids[top], id, "ferrilog span guards must be dropped in LIFO order"); + + if let Some(position) = + self.ids[..self.depth as usize].iter().rposition(|candidate| *candidate == id) + { + for index in position..top { + self.ids[index] = self.ids[index + 1]; + } + self.ids[top] = ROOT_SPAN_ID; + self.depth -= 1; + } + } +} + +/// Extension trait for carrying a span across future polls. +pub trait Instrument: Sized { + /// Wraps `self` so that `span` is entered for each `poll`. + #[inline] + fn instrument(self, span: Span) -> Instrumented { + Instrumented { inner: self, span } + } +} + +impl Instrument for T {} + +/// Future wrapper returned by [`Instrument::instrument`]. +#[derive(Debug)] +#[must_use = "futures do nothing unless polled"] +pub struct Instrumented { + inner: F, + span: Span, +} + +impl Future for Instrumented { + type Output = F::Output; + + #[inline] + fn poll(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll { + // Safety: `inner` is never moved out of the pinned `Instrumented`. + let this = unsafe { self.get_unchecked_mut() }; + let _guard = this.span.enter(); + // Safety: projecting the pin to `inner` is sound because `inner` + // remains in place for the duration of this poll. + unsafe { Pin::new_unchecked(&mut this.inner) }.poll(cx) + } +} + +#[cfg(test)] +mod tests { + use super::*; + + static TEST_SPAN: StaticSpanInfo = StaticSpanInfo::new("test", "span.rs:1"); + + #[test] + fn enter_and_drop_restore_current_span() { + assert_eq!(current_span_id(), SpanId::ROOT); + let outer = Span::new(&TEST_SPAN); + { + let _outer_guard = outer.enter(); + assert_eq!(current_span_id(), outer.id()); + + let inner = Span::new(&TEST_SPAN); + { + let _inner_guard = inner.enter(); + assert_eq!(current_span_id(), inner.id()); + } + + assert_eq!(current_span_id(), outer.id()); + } + assert_eq!(current_span_id(), SpanId::ROOT); + } + + #[test] + fn span_records_parent_id() { + let parent = Span::new(&TEST_SPAN); + let _guard = parent.enter(); + let child = Span::new(&TEST_SPAN); + assert_eq!(child.parent_id(), parent.id()); + } +} diff --git a/core/src/spsc_queue.rs b/core/src/spsc_queue.rs index 76174af..2e14a5b 100644 --- a/core/src/spsc_queue.rs +++ b/core/src/spsc_queue.rs @@ -108,10 +108,13 @@ pub const PAYLOAD_INFO_OFFSET: usize = 0; /// Byte offset of the `i64` timestamp within the payload. pub const PAYLOAD_TIMESTAMP_OFFSET: usize = PAYLOAD_INFO_OFFSET + size_of::(); +/// Byte offset of the `u64` current span id within the payload. +pub const PAYLOAD_SPAN_ID_OFFSET: usize = PAYLOAD_TIMESTAMP_OFFSET + size_of::(); + /// Byte offset where encoded arguments begin within the payload. -pub const PAYLOAD_ARGS_OFFSET: usize = PAYLOAD_TIMESTAMP_OFFSET + size_of::(); +pub const PAYLOAD_ARGS_OFFSET: usize = PAYLOAD_SPAN_ID_OFFSET + size_of::(); -/// Fixed overhead per message (info pointer + timestamp) before encoded arguments. +/// Fixed overhead per message (info pointer + timestamp + span id) before encoded arguments. pub const PAYLOAD_HEADER_SIZE: usize = PAYLOAD_ARGS_OFFSET; /// Message header. `size` is the cross-thread control word (`AtomicU32`). @@ -120,12 +123,12 @@ pub const PAYLOAD_HEADER_SIZE: usize = PAYLOAD_ARGS_OFFSET; /// immediately follows and stores: /// /// ```text -/// [info_ptr: *const StaticInfo (8B)] [timestamp: i64 (8B)] [encoded args...] +/// [info_ptr: *const StaticInfo (8B)] [timestamp: i64 (8B)] [span_id: u64 (8B)] [encoded args...] /// ``` /// /// Layout constants [`PAYLOAD_INFO_OFFSET`], [`PAYLOAD_TIMESTAMP_OFFSET`], -/// [`PAYLOAD_ARGS_OFFSET`], and [`PAYLOAD_HEADER_SIZE`] describe the payload -/// structure. +/// [`PAYLOAD_SPAN_ID_OFFSET`], [`PAYLOAD_ARGS_OFFSET`], and +/// [`PAYLOAD_HEADER_SIZE`] describe the payload structure. #[repr(C)] pub struct MessageHeader { /// Total message size in bytes (header + payload), used as an atomic control word. diff --git a/examples/01_basic.rs b/examples/01_basic.rs index c2769a6..d6fe23b 100644 --- a/examples/01_basic.rs +++ b/examples/01_basic.rs @@ -15,14 +15,14 @@ fn main() -> std::io::Result<()> { ferrilog::set_thread_name("main"); // INFO and above are emitted. - ferrilog::logi!("hello world"); + ferrilog::info!("hello world"); // DBG is below INFO, so this message is silently discarded. - ferrilog::logd!("debug={}", 42u32); + ferrilog::debug!("debug={}", 42u32); // Warnings and errors are always above INFO. - ferrilog::logw!("warning={}", true); - ferrilog::loge!("error code={}", -1i32); + ferrilog::warn!("warning={}", true); + ferrilog::error!("error code={}", -1i32); // When `_guard` goes out of scope here, the poller thread is stopped // and all buffered output is flushed automatically. diff --git a/examples/02_format_spec.rs b/examples/02_format_spec.rs index 407bb90..dbc828a 100644 --- a/examples/02_format_spec.rs +++ b/examples/02_format_spec.rs @@ -16,36 +16,36 @@ fn main() -> std::io::Result<()> { let pi: f64 = std::f64::consts::PI; // --- Hexadecimal --- - ferrilog::logi!("hex lower: {:x}", value); // ff - ferrilog::logi!("hex lower alt: {:#x}", value); // 0xff - ferrilog::logi!("hex upper: {:X}", value); // FF - ferrilog::logi!("hex upper alt: {:#X}", value); // 0xFF + ferrilog::info!("hex lower: {:x}", value); // ff + ferrilog::info!("hex lower alt: {:#x}", value); // 0xff + ferrilog::info!("hex upper: {:X}", value); // FF + ferrilog::info!("hex upper alt: {:#X}", value); // 0xFF // --- Binary --- - ferrilog::logi!("binary: {:b}", value); // 11111111 - ferrilog::logi!("binary alt: {:#b}", value); // 0b11111111 + ferrilog::info!("binary: {:b}", value); // 11111111 + ferrilog::info!("binary alt: {:#b}", value); // 0b11111111 // --- Octal --- - ferrilog::logi!("octal: {:o}", value); // 377 - ferrilog::logi!("octal alt: {:#o}", value); // 0o377 + ferrilog::info!("octal: {:o}", value); // 377 + ferrilog::info!("octal alt: {:#o}", value); // 0o377 // --- Floating point precision --- - ferrilog::logi!("pi 2 decimals: {:.2}", pi); // 3.14 - ferrilog::logi!("pi 6 decimals: {:.6}", pi); // 3.141593 + ferrilog::info!("pi 2 decimals: {:.2}", pi); // 3.14 + ferrilog::info!("pi 6 decimals: {:.6}", pi); // 3.141593 // --- Width and alignment --- // Right-align (default) within 10 characters - ferrilog::logi!("right-aligned: [{:>10}]", 42u32); // [ 42] + ferrilog::info!("right-aligned: [{:>10}]", 42u32); // [ 42] // Left-align within 10 characters - ferrilog::logi!("left-aligned: [{:<10}]", 42u32); // [42 ] + ferrilog::info!("left-aligned: [{:<10}]", 42u32); // [42 ] // Center-align within 10 characters - ferrilog::logi!("center-aligned: [{:^10}]", 42u32); // [ 42 ] + ferrilog::info!("center-aligned: [{:^10}]", 42u32); // [ 42 ] // --- Zero-padding --- - ferrilog::logi!("zero-padded: [{:0>8}]", 42u32); // [00000042] + ferrilog::info!("zero-padded: [{:0>8}]", 42u32); // [00000042] // --- Combined: hex with zero-pad and prefix --- - ferrilog::logi!("hex zero-padded: [{:#010x}]", value); // [0x000000ff] + ferrilog::info!("hex zero-padded: [{:#010x}]", value); // [0x000000ff] Ok(()) } diff --git a/examples/03_custom_type.rs b/examples/03_custom_type.rs index 95b12f5..2f8e3c6 100644 --- a/examples/03_custom_type.rs +++ b/examples/03_custom_type.rs @@ -46,12 +46,12 @@ fn main() -> std::io::Result<()> { let o = Order { id: 100001, price: 49.99, qty: 50 }; // Log custom types with the default {} placeholder. - ferrilog::logi!("point = {}", p); - ferrilog::logi!("order = {}", o); + ferrilog::info!("point = {}", p); + ferrilog::info!("order = {}", o); // Format specifiers are applied through the Display trait. - ferrilog::logi!("padded point: [{:^20}]", p); - ferrilog::logi!("padded order: [{:>40}]", o); + ferrilog::info!("padded point: [{:^20}]", p); + ferrilog::info!("padded order: [{:>40}]", o); Ok(()) } diff --git a/examples/04_multi_thread.rs b/examples/04_multi_thread.rs index 3516498..1f79bee 100644 --- a/examples/04_multi_thread.rs +++ b/examples/04_multi_thread.rs @@ -18,7 +18,7 @@ fn main() -> std::io::Result<()> { .start()?; ferrilog::set_thread_name("main"); - ferrilog::logi!("spawning 4 worker threads"); + ferrilog::info!("spawning 4 worker threads"); let mut handles = Vec::new(); for id in 0..4u32 { @@ -27,7 +27,7 @@ fn main() -> std::io::Result<()> { ferrilog::set_thread_name(&format!("worker-{}", id)); for i in 0..10u32 { - ferrilog::logi!("thread {} message {} value={}", id, i, id * 100 + i); + ferrilog::info!("thread {} message {} value={}", id, i, id * 100 + i); } }); handles.push(handle); @@ -35,7 +35,7 @@ fn main() -> std::io::Result<()> { // Main thread also logs while workers are running. for i in 0..5u32 { - ferrilog::logi!("main message {}", i); + ferrilog::info!("main message {}", i); } // Wait for all workers to finish. @@ -46,7 +46,7 @@ fn main() -> std::io::Result<()> { // The guard flushes all remaining messages on drop. // Output is time-ordered across all threads because the poller's // min-heap merges by timestamp. - ferrilog::logi!("all workers finished"); + ferrilog::info!("all workers finished"); Ok(()) } diff --git a/examples/05_file_rotation.rs b/examples/05_file_rotation.rs index 695cb49..fa3c09e 100644 --- a/examples/05_file_rotation.rs +++ b/examples/05_file_rotation.rs @@ -27,7 +27,7 @@ fn main() -> std::io::Result<()> { // Write enough messages to exceed 1 KB and trigger rotation. for i in 0..100u32 { - ferrilog::logi!( + ferrilog::info!( "rotation demo message {:0>4} -- padding to increase size xxxxxxxxxxxxxxxxxx", i ); diff --git a/examples/06_flush_policy.rs b/examples/06_flush_policy.rs index 95e4d50..4039530 100644 --- a/examples/06_flush_policy.rs +++ b/examples/06_flush_policy.rs @@ -40,7 +40,7 @@ fn main() -> std::io::Result<()> { .start()?; ferrilog::set_thread_name("main"); - ferrilog::logi!("delayed message"); + ferrilog::info!("delayed message"); // After a short sleep the message is still buffered. std::thread::sleep(Duration::from_millis(100)); @@ -67,7 +67,7 @@ fn main() -> std::io::Result<()> { // Write several short messages until the buffer exceeds 128 bytes. for i in 0..10u32 { - ferrilog::logi!("buffer-test message number {}", i); + ferrilog::info!("buffer-test message number {}", i); } std::thread::sleep(Duration::from_millis(100)); let flushed = sink.lock().unwrap().len(); @@ -88,8 +88,8 @@ fn main() -> std::io::Result<()> { .start()?; ferrilog::set_thread_name("main"); - ferrilog::logi!("info -- may be buffered"); - ferrilog::loge!("error -- triggers immediate flush"); + ferrilog::info!("info -- may be buffered"); + ferrilog::error!("error -- triggers immediate flush"); std::thread::sleep(Duration::from_millis(100)); let flushed = sink.lock().unwrap().len(); diff --git a/examples/07_complete.rs b/examples/07_complete.rs index b47bc94..db46fce 100644 --- a/examples/07_complete.rs +++ b/examples/07_complete.rs @@ -84,10 +84,10 @@ fn main() -> std::io::Result<()> { // ------------------------------------------------------------------- // 3. Log levels and filtering // ------------------------------------------------------------------- - ferrilog::logd!("debug: application starting"); - ferrilog::logi!("info: configuration loaded"); - ferrilog::logw!("warn: disk usage at {}%", 87u32); - ferrilog::loge!("error: failed to connect, retrying"); + ferrilog::debug!("debug: application starting"); + ferrilog::info!("info: configuration loaded"); + ferrilog::warn!("warn: disk usage at {}%", 87u32); + ferrilog::error!("error: failed to connect, retrying"); // ------------------------------------------------------------------- // 4. Format specifiers @@ -95,15 +95,15 @@ fn main() -> std::io::Result<()> { let flags: u32 = 0xDEAD; let pi: f64 = std::f64::consts::PI; - ferrilog::logi!("hex: {:#x}", flags); - ferrilog::logi!("upper hex: {:#X}", flags); - ferrilog::logi!("binary: {:#b}", flags); - ferrilog::logi!("octal: {:#o}", flags); - ferrilog::logi!("precision: {:.4}", pi); - ferrilog::logi!("right-pad: [{:>12}]", 42u32); - ferrilog::logi!("left-pad: [{:<12}]", 42u32); - ferrilog::logi!("center-pad: [{:^12}]", 42u32); - ferrilog::logi!("zero-pad: [{:0>8}]", flags); + ferrilog::info!("hex: {:#x}", flags); + ferrilog::info!("upper hex: {:#X}", flags); + ferrilog::info!("binary: {:#b}", flags); + ferrilog::info!("octal: {:#o}", flags); + ferrilog::info!("precision: {:.4}", pi); + ferrilog::info!("right-pad: [{:>12}]", 42u32); + ferrilog::info!("left-pad: [{:<12}]", 42u32); + ferrilog::info!("center-pad: [{:^12}]", 42u32); + ferrilog::info!("zero-pad: [{:0>8}]", flags); // ------------------------------------------------------------------- // 5. Custom types @@ -111,9 +111,9 @@ fn main() -> std::io::Result<()> { let velocity = Vec3 { x: 1.5, y: -0.3, z: 9.81 }; let trade = Trade { symbol_id: 42, price: 123.4567, qty: 100, buy: true }; - ferrilog::logi!("velocity = {}", velocity); - ferrilog::logi!("trade = {}", trade); - ferrilog::logi!("padded trade: [{:>50}]", trade); + ferrilog::info!("velocity = {}", velocity); + ferrilog::info!("trade = {}", trade); + ferrilog::info!("padded trade: [{:>50}]", trade); // ------------------------------------------------------------------- // 6. Multi-threaded logging @@ -123,7 +123,7 @@ fn main() -> std::io::Result<()> { let handle = thread::spawn(move || { ferrilog::set_thread_name(&format!("worker-{}", id)); for i in 0..10u32 { - ferrilog::logi!("worker {} task {} status={}", id, i, id * 10 + i); + ferrilog::info!("worker {} task {} status={}", id, i, id * 10 + i); } }); handles.push(handle); @@ -131,14 +131,14 @@ fn main() -> std::io::Result<()> { // The main thread continues logging concurrently. for i in 0..5u32 { - ferrilog::logd!("main heartbeat {}", i); + ferrilog::debug!("main heartbeat {}", i); } for h in handles { h.join().unwrap(); } - ferrilog::logi!("all workers finished"); + ferrilog::info!("all workers finished"); // ------------------------------------------------------------------- // 7. Guard auto-cleanup: the drop flushes and stops the poller diff --git a/examples/basic.rs b/examples/basic.rs index aeda57a..f89b573 100644 --- a/examples/basic.rs +++ b/examples/basic.rs @@ -81,10 +81,10 @@ fn main() { set_thread_name("main"); // Log at each severity level using the convenience macros. - ferrilog::logd!("application starting, debug mode enabled"); - ferrilog::logi!("server listening on port {}", 8080u32); - ferrilog::logw!("connection pool utilization at {}%", 85u32); - ferrilog::loge!("failed to open config file: {}", "config.toml"); + ferrilog::debug!("application starting, debug mode enabled"); + ferrilog::info!("server listening on port {}", 8080u32); + ferrilog::warn!("connection pool utilization at {}%", 85u32); + ferrilog::error!("failed to open config file: {}", "config.toml"); // Manually poll and flush so we can see the output immediately. poll(true).unwrap(); @@ -99,31 +99,31 @@ fn main() { let pi: f64 = std::f64::consts::PI; // Hexadecimal (lower and upper) - ferrilog::logi!("hex lower: {:x}", value); - ferrilog::logi!("hex upper: {:X}", value); - ferrilog::logi!("hex with prefix: {:#x}", value); - ferrilog::logi!("hex zero-padded: {:#010x}", value); + ferrilog::info!("hex lower: {:x}", value); + ferrilog::info!("hex upper: {:X}", value); + ferrilog::info!("hex with prefix: {:#x}", value); + ferrilog::info!("hex zero-padded: {:#010x}", value); // Floating point precision - ferrilog::logi!("pi 2 decimals: {:.2}", pi); - ferrilog::logi!("pi 6 decimals: {:.6}", pi); + ferrilog::info!("pi 2 decimals: {:.2}", pi); + ferrilog::info!("pi 6 decimals: {:.6}", pi); // Width and alignment - ferrilog::logi!("right-aligned: {:>10}", 42u32); - ferrilog::logi!("left-aligned: {:<10}", 42u32); - ferrilog::logi!("center-aligned:{:^10}", 42u32); + ferrilog::info!("right-aligned: {:>10}", 42u32); + ferrilog::info!("left-aligned: {:<10}", 42u32); + ferrilog::info!("center-aligned:{:^10}", 42u32); // Fill character with alignment - ferrilog::logi!("zero-filled: {:0>8}", 42u32); - ferrilog::logi!("dash-filled: {:->20}", "hello"); + ferrilog::info!("zero-filled: {:0>8}", 42u32); + ferrilog::info!("dash-filled: {:->20}", "hello"); // Scientific notation - ferrilog::logi!("scientific: {:>14.3e}", pi); + ferrilog::info!("scientific: {:>14.3e}", pi); // Binary and octal - ferrilog::logi!("binary: {:b}", 42u32); - ferrilog::logi!("binary with prefix: {:#b}", 42u32); - ferrilog::logi!("octal: {:o}", 42u32); + ferrilog::info!("binary: {:b}", 42u32); + ferrilog::info!("binary with prefix: {:#b}", 42u32); + ferrilog::info!("octal: {:o}", 42u32); poll(true).unwrap(); println!("--- format specifiers done ---\n"); @@ -135,12 +135,12 @@ fn main() { let point = Point { x: 10, y: -3 }; let order = Order { id: 100001, price: 49.99, quantity: 50 }; - ferrilog::logi!("point={}", point); - ferrilog::logi!("order={}", order); + ferrilog::info!("point={}", point); + ferrilog::info!("order={}", order); // Custom types also support format specifiers (applied via Display) - ferrilog::logi!("padded point: {:^20}", point); - ferrilog::logi!("padded order: {:>40}", order); + ferrilog::info!("padded point: {:^20}", point); + ferrilog::info!("padded order: {:>40}", order); // log_fast! variant: only supports bare {} placeholders, but is faster ferrilog::log_fast!(Level::INF, "fast point={}", point); @@ -154,10 +154,10 @@ fn main() { // Only show warnings and above set_level(Level::WRN); - ferrilog::logd!("this debug message is filtered out"); - ferrilog::logi!("this info message is filtered out"); - ferrilog::logw!("this warning IS visible"); - ferrilog::loge!("this error IS visible"); + ferrilog::debug!("this debug message is filtered out"); + ferrilog::info!("this info message is filtered out"); + ferrilog::warn!("this warning IS visible"); + ferrilog::error!("this error IS visible"); poll(true).unwrap(); @@ -173,7 +173,7 @@ fn main() { let log_path_str = log_path.to_str().unwrap(); set_log_file(log_path_str).unwrap(); - ferrilog::logi!("this message goes to the log file"); + ferrilog::info!("this message goes to the log file"); poll(true).unwrap(); println!("Log file written to: {}", log_path.display()); @@ -189,17 +189,17 @@ fn main() { // Minimal header: just level and a separator set_header_pattern("{level} | ").unwrap(); - ferrilog::logi!("minimal header style"); + ferrilog::info!("minimal header style"); poll(true).unwrap(); // Compact header without date/time set_header_pattern("{level} [{thread}] {location} - ").unwrap(); - ferrilog::logi!("compact header without timestamp"); + ferrilog::info!("compact header without timestamp"); poll(true).unwrap(); // Empty header: body only set_header_pattern("").unwrap(); - ferrilog::logi!("body only, no header at all"); + ferrilog::info!("body only, no header at all"); poll(true).unwrap(); // Restore default-style header @@ -213,7 +213,7 @@ fn main() { // Start the background polling thread with a 1ms poll interval (in nanoseconds). start_polling_thread(1_000_000).unwrap(); - ferrilog::logi!("this is written by the background poller"); + ferrilog::info!("this is written by the background poller"); // Give the poller a moment to pick up the message thread::sleep(Duration::from_millis(50)); @@ -236,8 +236,8 @@ fn main() { // flush_on: immediately flush when a message at this level (or above) is logged. flush_on(Level::ERR); // auto-flush on every error - ferrilog::logi!("info message, buffered until delay/size threshold"); - ferrilog::loge!("error message triggers immediate flush"); + ferrilog::info!("info message, buffered until delay/size threshold"); + ferrilog::error!("error message triggers immediate flush"); poll(true).unwrap(); // Reset to defaults @@ -260,7 +260,7 @@ fn main() { set_thread_name(&format!("worker-{}", thread_index)); for message_index in 0..5u32 { - ferrilog::logi!( + ferrilog::info!( "thread {} message {} value={}", thread_index, message_index, @@ -298,7 +298,7 @@ fn main() { eprintln!("queue full event #{}", count); })); - ferrilog::logi!("queue full policy is now Block with a callback"); + ferrilog::info!("queue full policy is now Block with a callback"); poll(true).unwrap(); // Clear the callback and restore default policy diff --git a/macros/src/lib.rs b/macros/src/lib.rs index 9ace333..233e750 100644 --- a/macros/src/lib.rs +++ b/macros/src/lib.rs @@ -1,7 +1,7 @@ //! Procedural macros for the `ferrilog` crate. //! //! Provides the [`log!`] macro, level-specific convenience macros -//! (`logd!`, `logi!`, `logw!`, `loge!`), and the [`Encode`](derive@Encode) +//! (`trace!`, `debug!`, `info!`, `warn!`, `error!`), and the [`Encode`](derive@Encode) //! derive macro. mod derive_encode; diff --git a/macros/src/log_macro.rs b/macros/src/log_macro.rs index e1faf8b..f6bfb0e 100644 --- a/macros/src/log_macro.rs +++ b/macros/src/log_macro.rs @@ -265,6 +265,7 @@ fn expand_log_inner( { let __ferrilog_level: ::ferrilog::Level = #level; if ::ferrilog::check_level(__ferrilog_level) { + let __ferrilog_span_id = ::ferrilog::current_span_id_u64(); #(#arg_bindings)* #make_decoder #encoded_size_fn @@ -298,6 +299,11 @@ fn expand_log_inner( .add(::ferrilog::PAYLOAD_TIMESTAMP_OFFSET) .cast::() .write_unaligned(__ferrilog_timestamp); + // Write current span id + __ferrilog_buffer + .add(::ferrilog::PAYLOAD_SPAN_ID_OFFSET) + .cast::() + .write_unaligned(__ferrilog_span_id); // Write encoded arguments #encode_payload (*__ferrilog_header).push(__ferrilog_payload_size); @@ -347,6 +353,7 @@ pub(crate) fn expand_set_header_pattern_static(input: HeaderPatternInput) -> Tok let reserve_base = Literal::usize_unsuffixed(pattern.fixed_len); let reserve_thread = pattern.uses_thread.then(|| quote!(+ thread_name.len())).into_iter(); let reserve_location = pattern.uses_location.then(|| quote!(+ location.len())).into_iter(); + let reserve_span = pattern.uses_span.then(|| quote!(+ 20usize)).into_iter(); let statements = pattern.segments.iter().map(|segment| match segment { HeaderSegment::Literal(bytes) => { let literal = Literal::byte_string(bytes); @@ -364,6 +371,9 @@ pub(crate) fn expand_set_header_pattern_static(input: HeaderPatternInput) -> Tok HeaderSegment::Level => quote! { output.extend_from_slice(level.as_bytes()); }, + HeaderSegment::Span => quote! { + ::ferrilog::append_span_id(output, span_id); + }, HeaderSegment::ThreadName => quote! { output.extend_from_slice(thread_name); }, @@ -382,8 +392,9 @@ pub(crate) fn expand_set_header_pattern_static(input: HeaderPatternInput) -> Tok level: ::ferrilog::Level, thread_name: &[u8], location: &str, + span_id: u64, ) { - output.reserve(#reserve_base #(#reserve_thread)* #(#reserve_location)*); + output.reserve(#reserve_base #(#reserve_thread)* #(#reserve_location)* #(#reserve_span)*); #(#statements)* } @@ -399,6 +410,7 @@ enum HeaderSegment { Time, Nanosecond, Level, + Span, ThreadName, Location, } @@ -409,6 +421,7 @@ struct ParsedHeaderPattern { fixed_len: usize, uses_thread: bool, uses_location: bool, + uses_span: bool, } fn parse_header_pattern_literal(pattern: &LitStr) -> Result { @@ -420,6 +433,7 @@ fn parse_header_pattern_literal(pattern: &LitStr) -> Result let mut fixed_len = 0usize; let mut uses_thread = false; let mut uses_location = false; + let mut uses_span = false; while index < bytes.len() { match bytes[index] { @@ -461,6 +475,10 @@ fn parse_header_pattern_literal(pattern: &LitStr) -> Result fixed_len += 3; HeaderSegment::Level } + "span" => { + uses_span = true; + HeaderSegment::Span + } "thread" => { uses_thread = true; HeaderSegment::ThreadName @@ -499,5 +517,5 @@ fn parse_header_pattern_literal(pattern: &LitStr) -> Result segments.push(HeaderSegment::Literal(literal)); } - Ok(ParsedHeaderPattern { segments, fixed_len, uses_thread, uses_location }) + Ok(ParsedHeaderPattern { segments, fixed_len, uses_thread, uses_location, uses_span }) } diff --git a/src/lib.rs b/src/lib.rs index 52b0f9d..80296f3 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -6,13 +6,25 @@ extern crate self as ferrilog; pub use ferrilog_core::*; pub use ferrilog_macros::*; +/// Logs a message at the **Trace** level. +/// +/// ```ignore +/// trace!("poll state={}", state); +/// ``` +#[macro_export] +macro_rules! trace { + ($($arguments:tt)*) => { + $crate::log!($crate::Level::TRC, $($arguments)*) + }; +} + /// Logs a message at the **Debug** level. /// /// ```ignore -/// logd!("value={}", x); +/// debug!("value={}", x); /// ``` #[macro_export] -macro_rules! logd { +macro_rules! debug { ($($arguments:tt)*) => { $crate::log!($crate::Level::DBG, $($arguments)*) }; @@ -21,10 +33,10 @@ macro_rules! logd { /// Logs a message at the **Info** level. /// /// ```ignore -/// logi!("server started on port {}", port); +/// info!("server started on port {}", port); /// ``` #[macro_export] -macro_rules! logi { +macro_rules! info { ($($arguments:tt)*) => { $crate::log!($crate::Level::INF, $($arguments)*) }; @@ -33,10 +45,10 @@ macro_rules! logi { /// Logs a message at the **Warning** level. /// /// ```ignore -/// logw!("connection timeout: {} ms", elapsed); +/// warn!("connection timeout: {} ms", elapsed); /// ``` #[macro_export] -macro_rules! logw { +macro_rules! warn { ($($arguments:tt)*) => { $crate::log!($crate::Level::WRN, $($arguments)*) }; @@ -45,11 +57,31 @@ macro_rules! logw { /// Logs a message at the **Error** level. /// /// ```ignore -/// loge!("failed to open file: {}", path); +/// error!("failed to open file: {}", path); /// ``` #[macro_export] -macro_rules! loge { +macro_rules! error { ($($arguments:tt)*) => { $crate::log!($crate::Level::ERR, $($arguments)*) }; } + +/// Creates a lightweight span. +/// +/// The span is not entered until [`Span::enter`](ferrilog_core::Span::enter) +/// is called. Log records emitted while the span is entered carry the span id, +/// which can be rendered with the `{span}` header token. +/// +/// ```ignore +/// let span = ferrilog::span!("connection"); +/// let _guard = span.enter(); +/// trace!("poll"); +/// ``` +#[macro_export] +macro_rules! span { + ($name:literal) => {{ + static INFO: $crate::StaticSpanInfo = + $crate::StaticSpanInfo::new($name, concat!(file!(), ":", line!())); + $crate::Span::new(&INFO) + }}; +} diff --git a/tests/convenience_macros.rs b/tests/convenience_macros.rs index 1cb7836..86fc439 100644 --- a/tests/convenience_macros.rs +++ b/tests/convenience_macros.rs @@ -47,7 +47,7 @@ fn capture_output(level: Level, action: F) -> String { #[test] fn test_logd() { let output = capture_output(Level::DBG, || { - ferrilog::logd!("debug value={}", 42u32); + ferrilog::debug!("debug value={}", 42u32); }); assert!(output.contains("DBG"), "output: {output}"); assert!(output.contains("debug value=42"), "output: {output}"); @@ -56,7 +56,7 @@ fn test_logd() { #[test] fn test_logi() { let output = capture_output(Level::DBG, || { - ferrilog::logi!("info message={}", "hello"); + ferrilog::info!("info message={}", "hello"); }); assert!(output.contains("INF"), "output: {output}"); assert!(output.contains("info message=hello"), "output: {output}"); @@ -65,7 +65,7 @@ fn test_logi() { #[test] fn test_logw() { let output = capture_output(Level::DBG, || { - ferrilog::logw!("warning count={}", 99u64); + ferrilog::warn!("warning count={}", 99u64); }); assert!(output.contains("WRN"), "output: {output}"); assert!(output.contains("warning count=99"), "output: {output}"); @@ -74,7 +74,7 @@ fn test_logw() { #[test] fn test_loge() { let output = capture_output(Level::DBG, || { - ferrilog::loge!("error code={}", -1i32); + ferrilog::error!("error code={}", -1i32); }); assert!(output.contains("ERR"), "output: {output}"); assert!(output.contains("error code=-1"), "output: {output}"); @@ -83,8 +83,8 @@ fn test_loge() { #[test] fn test_logd_filtered_by_level() { let output = capture_output(Level::INF, || { - ferrilog::logd!("should not appear={}", 0u32); - ferrilog::logi!("should appear={}", 1u32); + ferrilog::debug!("should not appear={}", 0u32); + ferrilog::info!("should appear={}", 1u32); }); assert!(!output.contains("should not appear"), "output: {output}"); assert!(output.contains("should appear=1"), "output: {output}"); @@ -93,7 +93,7 @@ fn test_logd_filtered_by_level() { #[test] fn test_no_args() { let output = capture_output(Level::DBG, || { - ferrilog::logi!("plain message no args"); + ferrilog::info!("plain message no args"); }); assert!(output.contains("plain message no args"), "output: {output}"); } diff --git a/tests/log_pipeline.rs b/tests/log_pipeline.rs index 8a94434..65fe9be 100644 --- a/tests/log_pipeline.rs +++ b/tests/log_pipeline.rs @@ -144,7 +144,7 @@ fn log_and_derive_encode_work() { let point = Point { x: 7, y: 9 }; let text = String::from("fast"); ferrilog::log!(INFO, "point={}", point); - ferrilog::logi!("value={} text={}", 64u32, text); + ferrilog::info!("value={} text={}", 64u32, text); poll(true).unwrap(); let output = String::from_utf8(buffer.lock().unwrap().clone()).unwrap(); @@ -379,7 +379,7 @@ fn file_write_multi_thread() { thread::spawn(move || { ferrilog::set_thread_name(&format!("writer-{thread_index}")); for message_index in 0..PER_THREAD as u32 { - ferrilog::logi!("tid={} seq={}", thread_index as u32, message_index); + ferrilog::info!("tid={} seq={}", thread_index as u32, message_index); } }) }) @@ -431,7 +431,7 @@ fn file_flush_on_level() { // Write several INFO messages and poll — they should be buffered, NOT flushed for i in 0..5u32 { - ferrilog::logi!("buffered={}", i); + ferrilog::info!("buffered={}", i); } poll(false).unwrap(); let content_before = fs::read_to_string(&path).unwrap_or_default(); @@ -442,7 +442,7 @@ fn file_flush_on_level() { // Now write an ERR message and poll — this should trigger an immediate flush // of ALL pending output (the 5 INFO messages + the ERR message) - ferrilog::loge!("trigger-flush"); + ferrilog::error!("trigger-flush"); poll(false).unwrap(); let content_after = wait_until_contains(&path, "trigger-flush", Duration::from_secs(2));