use std::sync::atomic::{AtomicBool, Ordering};
use std::sync::Arc;
use crate::encode::{FIXED_SIZES, TAG_COUNT, TAG_STR};
use crate::format::{self, FormatSpec};
use crate::level::Level;
use crate::record::{
END_OF_BUFFER, FLAG_COMPLEX, FLAG_FORMAT, FLAG_PROCESS, FLAG_SOURCE, FLAG_THREAD, LOG_RECORD,
VERSION,
};
use crate::ring::{align_up, RingBuffer, RING_SIZE, SLOT_SIZE};
use crate::sink::LogSink;
use crate::thread_buf::REGISTRY;
use crate::timestamp::{format_iso8601, ticks_to_ns, Calibration};
const SPIN_MIN: u32 = 8;
const SPIN_CAP: u32 = 256;
const SYNC_EVERY: u32 = 1024;
const SYNC_MASK: u32 = SYNC_EVERY - 1;
const _: () = assert!(SYNC_EVERY.is_power_of_two());
struct Cursor {
ptr: *const u8,
end: *const u8,
}
impl Cursor {
#[inline(always)]
unsafe fn new(base: *const u8, len: usize) -> Self {
Self {
ptr: base,
end: unsafe { base.add(len) },
}
}
#[inline(always)]
fn remaining(&self) -> usize {
self.end as usize - self.ptr as usize
}
#[inline(always)]
unsafe fn read_array<const N: usize>(&mut self) -> [u8; N] {
if self.remaining() < N {
return [0; N];
}
let v = unsafe { *(self.ptr as *const [u8; N]) };
self.ptr = unsafe { self.ptr.add(N) };
v
}
#[inline(always)]
unsafe fn read_u8(&mut self) -> u8 {
u8::from_le_bytes(unsafe { self.read_array() })
}
#[inline(always)]
unsafe fn read_u16(&mut self) -> u16 {
u16::from_le_bytes(unsafe { self.read_array() })
}
#[inline(always)]
unsafe fn read_u32(&mut self) -> u32 {
u32::from_le_bytes(unsafe { self.read_array() })
}
#[inline(always)]
unsafe fn read_u64(&mut self) -> u64 {
u64::from_le_bytes(unsafe { self.read_array() })
}
#[inline(always)]
unsafe fn skip(&mut self, n: usize) {
let n = n.min(self.remaining());
self.ptr = unsafe { self.ptr.add(n) };
}
#[inline(always)]
unsafe fn read_bytes(&mut self, n: usize) -> &[u8] {
let n = n.min(self.remaining());
let data = unsafe { std::slice::from_raw_parts(self.ptr, n) };
self.ptr = unsafe { self.ptr.add(n) };
data
}
#[inline(always)]
unsafe fn read_len_prefixed(&mut self) -> (&[u8], u16) {
let len = unsafe { self.read_u16() };
let data = unsafe { self.read_bytes(len as usize) };
(data, len)
}
}
type Formatter = fn(&[u8], &FormatSpec, &mut Vec<u8>);
static FORMATTERS: [Formatter; TAG_COUNT] = [
fmt_u64, fmt_i64, fmt_f64, fmt_u32, fmt_i32, fmt_f32, fmt_u16, fmt_i16, fmt_u8, fmt_i8, fmt_bool, fmt_str, ];
fn fmt_u64(data: &[u8], spec: &FormatSpec, buf: &mut Vec<u8>) {
let bytes: [u8; 8] = data
.try_into()
.expect("invariant: u64 argument must be 8 bytes");
format::format_u64(u64::from_le_bytes(bytes), spec, buf);
}
fn fmt_i64(data: &[u8], spec: &FormatSpec, buf: &mut Vec<u8>) {
let bytes: [u8; 8] = data
.try_into()
.expect("invariant: i64 argument must be 8 bytes");
format::format_i64(i64::from_le_bytes(bytes), spec, buf);
}
fn fmt_f64(data: &[u8], spec: &FormatSpec, buf: &mut Vec<u8>) {
let bytes: [u8; 8] = data
.try_into()
.expect("invariant: f64 argument must be 8 bytes");
format::format_f64(f64::from_le_bytes(bytes), spec, buf);
}
fn fmt_u32(data: &[u8], spec: &FormatSpec, buf: &mut Vec<u8>) {
let bytes: [u8; 4] = data
.try_into()
.expect("invariant: u32 argument must be 4 bytes");
format::format_u32(u32::from_le_bytes(bytes), spec, buf);
}
fn fmt_i32(data: &[u8], spec: &FormatSpec, buf: &mut Vec<u8>) {
let bytes: [u8; 4] = data
.try_into()
.expect("invariant: i32 argument must be 4 bytes");
format::format_i32(i32::from_le_bytes(bytes), spec, buf);
}
fn fmt_f32(data: &[u8], spec: &FormatSpec, buf: &mut Vec<u8>) {
let bytes: [u8; 4] = data
.try_into()
.expect("invariant: f32 argument must be 4 bytes");
format::format_f32(f32::from_le_bytes(bytes), spec, buf);
}
fn fmt_u16(data: &[u8], spec: &FormatSpec, buf: &mut Vec<u8>) {
let bytes: [u8; 2] = data
.try_into()
.expect("invariant: u16 argument must be 2 bytes");
format::format_u16(u16::from_le_bytes(bytes), spec, buf);
}
fn fmt_i16(data: &[u8], spec: &FormatSpec, buf: &mut Vec<u8>) {
let bytes: [u8; 2] = data
.try_into()
.expect("invariant: i16 argument must be 2 bytes");
format::format_i16(i16::from_le_bytes(bytes), spec, buf);
}
fn fmt_u8(data: &[u8], spec: &FormatSpec, buf: &mut Vec<u8>) {
format::format_u8(data[0], spec, buf);
}
fn fmt_i8(data: &[u8], spec: &FormatSpec, buf: &mut Vec<u8>) {
format::format_i8(data[0] as i8, spec, buf);
}
fn fmt_bool(data: &[u8], spec: &FormatSpec, buf: &mut Vec<u8>) {
format::format_bool(data[0] != 0, spec, buf);
}
fn fmt_str(data: &[u8], spec: &FormatSpec, buf: &mut Vec<u8>) {
let s = String::from_utf8_lossy(data);
format::format_str(&s, spec, buf);
}
pub(crate) struct LogMetadata {
pub(crate) file: bool,
pub(crate) line_number: bool,
}
impl Default for LogMetadata {
fn default() -> Self {
Self {
file: true,
line_number: true,
}
}
}
pub(crate) struct Drain {
sink: Box<dyn LogSink>,
timezone_offset: i32,
metadata: LogMetadata,
shutdown: Arc<AtomicBool>,
rings: Vec<Arc<RingBuffer>>,
calibration: Calibration,
}
impl Drain {
pub(crate) fn new(
sink: Box<dyn LogSink>,
timezone_offset: i32,
metadata: LogMetadata,
shutdown: Arc<AtomicBool>,
calibration: Calibration,
) -> Self {
Self {
sink,
timezone_offset,
metadata,
shutdown,
rings: Vec::new(),
calibration,
}
}
pub(crate) fn run(&mut self) {
let mask = (RING_SIZE - 1) as u64;
let mut buf = Vec::with_capacity(4096);
let mut spin = SPIN_MIN;
let mut since_sync: u32 = 0;
let mut dirty = false;
loop {
if self.shutdown.load(Ordering::Acquire) {
break;
}
if (since_sync & SYNC_MASK) == 0 {
self.sync_rings(mask, &mut buf);
}
since_sync = since_sync.wrapping_add(1);
if self.poll_once(mask, &mut buf) {
spin = SPIN_MIN; dirty = true;
continue;
}
if dirty {
self.flush_sink();
dirty = false;
}
for _ in 0..spin {
std::hint::spin_loop();
}
spin = (spin << 1).min(SPIN_CAP); }
self.sync_rings(mask, &mut buf);
self.poll_once(mask, &mut buf);
self.flush_sink();
}
fn flush_sink(&mut self) {
if let Err(e) = self.sink.flush() {
eprintln!("ticklog: sink flush failed: {}", e);
}
}
fn sync_rings(&mut self, mask: u64, buf: &mut Vec<u8>) {
let mut registry = REGISTRY
.get()
.expect("invariant: ring registry must be initialized by Builder::build before the drain starts")
.lock()
.expect("invariant: ring registry mutex poisoned by a panic in another thread");
for ring in registry.iter() {
if !self.rings.iter().any(|r| Arc::ptr_eq(r, ring)) {
self.rings.push(Arc::clone(ring));
}
}
registry.retain(|r| r.live.load(Ordering::Acquire));
drop(registry);
let mut i = 0;
while i < self.rings.len() {
if self.rings[i].live.load(Ordering::Acquire) {
i += 1;
} else {
let ring = self.rings.swap_remove(i);
drain_ring(
&ring,
mask,
self.sink.as_mut(),
self.timezone_offset,
&self.metadata,
&self.calibration,
buf,
);
}
}
}
fn poll_once(&mut self, mask: u64, buf: &mut Vec<u8>) -> bool {
let mut had_work = false;
for ring in &self.rings {
if drain_ring(
ring,
mask,
self.sink.as_mut(),
self.timezone_offset,
&self.metadata,
&self.calibration,
buf,
) {
had_work = true;
}
}
had_work
}
}
fn drain_ring(
ring: &RingBuffer,
mask: u64,
sink: &mut dyn LogSink,
timezone_offset: i32,
metadata: &LogMetadata,
calibration: &Calibration,
buf: &mut Vec<u8>,
) -> bool {
let mut tail = ring.tail.load(Ordering::Relaxed);
let mut head_cache = unsafe { *ring.head_cache.get() };
if tail == head_cache {
head_cache = ring.head.load(Ordering::Acquire);
if tail == head_cache {
return false; }
}
let base = ring.data.as_ptr() as *const u8;
while tail < head_cache {
let offset = (tail & mask) as usize;
let (version, rectype, total_size) = unsafe {
let mut c = Cursor::new(base.add(offset), RING_SIZE - offset);
let version = c.read_u8();
let rectype = c.read_u8();
let total_size = c.read_u16() as u64;
(version, rectype, total_size)
};
if total_size == 0 {
break; }
if version != VERSION
|| (rectype != LOG_RECORD && rectype != END_OF_BUFFER)
|| offset + total_size as usize > RING_SIZE
{
eprintln!(
"ticklog: drain discarded a corrupt record \
(version={version}, type={rectype}, size={total_size}); resyncing to head"
);
tail = head_cache;
break;
}
if rectype == END_OF_BUFFER {
tail += align_up(total_size, SLOT_SIZE as u64);
continue; }
let record = unsafe { std::slice::from_raw_parts(base.add(offset), total_size as usize) };
let level = record
.get(4)
.and_then(|&b| Level::from_u8(b))
.unwrap_or(Level::Error);
buf.clear();
decode_and_format(record, timezone_offset, metadata, calibration, buf);
if let Err(e) = sink.accept(buf, level) {
eprintln!("ticklog: sink accept failed: {}", e);
}
tail += align_up(total_size, SLOT_SIZE as u64);
}
ring.tail.store(tail, Ordering::Release);
unsafe {
*ring.head_cache.get() = head_cache;
}
true
}
fn decode_and_format(
record: &[u8],
timezone_offset: i32,
metadata: &LogMetadata,
calibration: &Calibration,
buf: &mut Vec<u8>,
) {
let mut c = unsafe { Cursor::new(record.as_ptr(), record.len()) };
let (level_byte, flags, timestamp) = unsafe {
c.skip(4); let level_byte = c.read_u8();
let flags = c.read_u16();
c.skip(1); let timestamp = c.read_u64();
(level_byte, flags, timestamp)
};
let level = Level::from_u8(level_byte).unwrap_or(Level::Error);
let ns = ticks_to_ns(timestamp, calibration);
format_iso8601(ns, timezone_offset, buf);
buf.extend_from_slice(b" ");
buf.extend_from_slice(level.as_str().as_bytes());
buf.push(b' ');
let mut fmt: &str = "";
if flags & FLAG_FORMAT != 0 {
let (fmt_ptr, fmt_len) = unsafe {
let p = c.read_u64() as *const u8;
let l = c.read_u16() as usize;
(p, l)
};
let fmt_bytes = unsafe { std::slice::from_raw_parts(fmt_ptr, fmt_len) };
fmt = std::str::from_utf8(fmt_bytes).unwrap_or("");
}
if flags & FLAG_SOURCE != 0 {
let (file_ptr, file_len, line) = unsafe {
let p = c.read_u64() as *const u8;
let l = c.read_u16() as usize;
let ln = c.read_u32();
(p, l, ln)
};
if metadata.file {
let file_bytes = unsafe { std::slice::from_raw_parts(file_ptr, file_len) };
let file = std::str::from_utf8(file_bytes).unwrap_or("<file>");
buf.extend_from_slice(file.as_bytes());
if metadata.line_number {
buf.push(b':');
append_u32(line, buf);
}
buf.push(b' ');
}
}
if flags & FLAG_THREAD != 0 {
unsafe {
c.skip(8);
let _ = c.read_len_prefixed();
}
}
if flags & FLAG_PROCESS != 0 {
unsafe {
c.skip(4);
}
}
if flags & FLAG_COMPLEX != 0 {
unsafe {
c.skip(8);
}
}
let n_args = unsafe { c.read_u8() } as usize;
let mut tag_buf = [0u8; 256];
let n_tags = unsafe {
let tags = c.read_bytes(n_args);
tag_buf[..tags.len()].copy_from_slice(tags);
tags.len()
};
interleave(fmt, &tag_buf[..n_tags], &mut c, buf);
}
fn interleave(fmt: &str, tags: &[u8], c: &mut Cursor, buf: &mut Vec<u8>) {
let bytes = fmt.as_bytes();
let mut i = 0;
let mut arg_idx = 0;
let mut parse_ok = true;
while i < bytes.len() {
match bytes[i] {
b'{' => {
if i + 1 < bytes.len() && bytes[i + 1] == b'{' {
buf.push(b'{');
i += 2;
continue;
}
let start = i + 1;
let mut j = start;
while j < bytes.len() && bytes[j] != b'}' {
j += 1;
}
let spec = format::parse_spec(&fmt[start..j]);
i = if j < bytes.len() { j + 1 } else { j };
match tags.get(arg_idx).copied() {
Some(tag) if parse_ok => {
if !format_arg(tag, &spec, c, buf) {
parse_ok = false;
write_unknown_tag(tag, buf);
}
}
Some(tag) => write_unknown_tag(tag, buf),
None => buf.extend_from_slice(b"<missing arg>"),
}
arg_idx += 1;
}
b'}' => {
debug_assert!(
i + 1 < bytes.len() && bytes[i + 1] == b'}',
"invariant: lone '}}' in validated format string"
);
buf.push(b'}');
i += 2;
}
other => {
buf.push(other);
i += 1;
}
}
}
}
fn format_arg(tag: u8, spec: &FormatSpec, c: &mut Cursor, buf: &mut Vec<u8>) -> bool {
if tag == TAG_STR {
let (data, _) = unsafe { c.read_len_prefixed() };
fmt_str(data, spec, buf);
return true;
}
let idx = tag as usize;
if idx < FIXED_SIZES.len() {
let size = FIXED_SIZES[idx];
let data = unsafe { c.read_bytes(size) };
FORMATTERS[idx](data, spec, buf);
return true;
}
false
}
fn write_unknown_tag(tag: u8, buf: &mut Vec<u8>) {
const HEX: &[u8; 16] = b"0123456789ABCDEF";
buf.extend_from_slice(b"<unknown tag 0x");
buf.push(HEX[(tag >> 4) as usize]);
buf.push(HEX[(tag & 0x0F) as usize]);
buf.push(b'>');
}
fn append_u32(mut v: u32, buf: &mut Vec<u8>) {
let mut tmp = [0u8; 10];
let mut i = tmp.len();
loop {
i -= 1;
tmp[i] = b'0' + (v % 10) as u8;
v /= 10;
if v == 0 {
break;
}
}
buf.extend_from_slice(&tmp[i..]);
}
#[cfg(test)]
mod tests {
use super::*;
use crate::encode::{TAG_BOOL, TAG_F64, TAG_I64, TAG_U16, TAG_U64};
use crate::record::{FORMAT_SECTION_SIZE, HEADER_SIZE, LOG_RECORD, VERSION};
use std::io;
use std::sync::{Mutex, OnceLock};
type CaptureCalls = Arc<Mutex<Vec<(String, Level)>>>;
fn identity_calibration() -> Calibration {
Calibration {
counter_to_ns: 1.0,
counter_base: 0,
wall_base_ns: 0,
}
}
fn le_bytes(tag: u8, value: u64) -> (u8, Vec<u8>) {
let bytes = match tag {
TAG_U64 | TAG_I64 | TAG_F64 => value.to_le_bytes().to_vec(),
TAG_U16 => (value as u16).to_le_bytes().to_vec(),
TAG_BOOL => vec![value as u8],
_ => panic!("unsupported tag in helper"),
};
(tag, bytes)
}
fn str_arg(s: &str) -> (u8, Vec<u8>) {
let mut v = (s.len() as u16).to_le_bytes().to_vec();
v.extend_from_slice(s.as_bytes());
(TAG_STR, v)
}
fn build_record(
level: Level,
timestamp: u64,
fmt: &'static str,
source: Option<(&'static str, u32)>,
args: &[(u8, Vec<u8>)],
) -> Vec<u8> {
let mut flags: u16 = FLAG_FORMAT;
if source.is_some() {
flags |= FLAG_SOURCE;
}
let mut payload: Vec<u8> = Vec::new();
payload.extend_from_slice(&(fmt.as_ptr() as u64).to_le_bytes());
payload.extend_from_slice(&(fmt.len() as u16).to_le_bytes());
if let Some((file, line)) = source {
payload.extend_from_slice(&(file.as_ptr() as u64).to_le_bytes());
payload.extend_from_slice(&(file.len() as u16).to_le_bytes());
payload.extend_from_slice(&line.to_le_bytes());
}
payload.push(args.len() as u8);
for (tag, _) in args {
payload.push(*tag);
}
for (_, data) in args {
payload.extend_from_slice(data);
}
let total_size = (HEADER_SIZE + payload.len()) as u16;
let mut record = Vec::with_capacity(total_size as usize);
record.push(VERSION); record.push(LOG_RECORD); record.extend_from_slice(&total_size.to_le_bytes());
record.push(level.to_u8());
record.extend_from_slice(&flags.to_le_bytes());
record.push(0); record.extend_from_slice(×tamp.to_le_bytes());
record.extend_from_slice(&payload);
record
}
fn format_line(record: &[u8], metadata: LogMetadata) -> String {
let mut buf = Vec::new();
decode_and_format(record, 0, &metadata, &identity_calibration(), &mut buf);
String::from_utf8(buf).unwrap()
}
struct CaptureSink {
calls: CaptureCalls,
}
impl LogSink for CaptureSink {
fn accept(&mut self, line: &[u8], level: Level) -> io::Result<()> {
self.calls
.lock()
.unwrap()
.push((String::from_utf8_lossy(line).into_owned(), level));
Ok(())
}
}
fn capture_drain() -> (Drain, CaptureCalls) {
let calls = Arc::new(Mutex::new(Vec::new()));
let sink = CaptureSink {
calls: Arc::clone(&calls),
};
let drain = Drain::new(
Box::new(sink),
0,
LogMetadata::default(),
Arc::new(AtomicBool::new(false)),
identity_calibration(),
);
(drain, calls)
}
fn place_record(ring: &RingBuffer, offset: u64, bytes: &[u8]) {
let data =
unsafe { std::slice::from_raw_parts_mut(ring.data.as_ptr() as *mut u8, RING_SIZE) };
let start = offset as usize;
data[start..start + bytes.len()].copy_from_slice(bytes);
let new_head = offset + align_up(bytes.len() as u64, SLOT_SIZE as u64);
ring.head.store(new_head, Ordering::Release);
}
#[test]
fn cursor_reads_types_and_advances() {
let mut data = Vec::new();
data.push(0xABu8);
data.extend_from_slice(&0xBEEFu16.to_le_bytes());
data.extend_from_slice(&0xDEAD_BEEFu32.to_le_bytes());
data.extend_from_slice(&0x0102_0304_0506_0708u64.to_le_bytes());
unsafe {
let mut c = Cursor::new(data.as_ptr(), data.len());
assert_eq!(c.read_u8(), 0xAB);
assert_eq!(c.read_u16(), 0xBEEF);
assert_eq!(c.read_u32(), 0xDEAD_BEEF);
assert_eq!(c.read_u64(), 0x0102_0304_0506_0708);
}
}
#[test]
fn cursor_skip_and_read_bytes() {
let data = [1u8, 2, 3, 4, 5, 6];
unsafe {
let mut c = Cursor::new(data.as_ptr(), data.len());
c.skip(2);
assert_eq!(c.read_bytes(3), &[3, 4, 5]);
assert_eq!(c.read_u8(), 6);
}
}
#[test]
fn cursor_read_len_prefixed() {
let mut data = (5u16).to_le_bytes().to_vec();
data.extend_from_slice(b"hello");
data.push(0x99); unsafe {
let mut c = Cursor::new(data.as_ptr(), data.len());
let (s, len) = c.read_len_prefixed();
assert_eq!(len, 5);
assert_eq!(s, b"hello");
assert_eq!(c.read_u8(), 0x99);
}
}
#[test]
fn cursor_read_len_prefixed_empty() {
let data = (0u16).to_le_bytes().to_vec();
unsafe {
let mut c = Cursor::new(data.as_ptr(), data.len());
let (s, len) = c.read_len_prefixed();
assert_eq!(len, 0);
assert!(s.is_empty());
}
}
#[test]
fn cursor_clamps_reads_at_end() {
let data = [1u8, 2, 3];
unsafe {
let mut c = Cursor::new(data.as_ptr(), data.len());
assert_eq!(c.read_u64(), 0);
assert_eq!(c.remaining(), 3);
assert_eq!(c.read_bytes(100), &[1, 2, 3]);
assert_eq!(c.remaining(), 0);
assert_eq!(c.read_u16(), 0);
}
}
#[test]
fn cursor_len_prefix_clamps_when_string_overruns() {
let mut data = (9u16).to_le_bytes().to_vec();
data.extend_from_slice(b"abc");
unsafe {
let mut c = Cursor::new(data.as_ptr(), data.len());
let (s, len) = c.read_len_prefixed();
assert_eq!(len, 9);
assert_eq!(s, b"abc");
}
}
#[test]
fn formatter_u64_roundtrip() {
let mut buf = Vec::new();
fmt_u64(&42u64.to_le_bytes(), &FormatSpec::default(), &mut buf);
assert_eq!(buf, b"42");
}
#[test]
fn formatter_i64_negative() {
let mut buf = Vec::new();
fmt_i64(&(-7i64).to_le_bytes(), &FormatSpec::default(), &mut buf);
assert_eq!(buf, b"-7");
}
#[test]
fn formatter_f64_roundtrip() {
let mut buf = Vec::new();
fmt_f64(&3.5f64.to_le_bytes(), &FormatSpec::default(), &mut buf);
assert_eq!(buf, b"3.5");
}
#[test]
fn formatter_bool_and_str() {
let mut buf = Vec::new();
fmt_bool(&[1], &FormatSpec::default(), &mut buf);
assert_eq!(buf, b"true");
buf.clear();
fmt_str(b"hi", &FormatSpec::default(), &mut buf);
assert_eq!(buf, b"hi");
}
#[test]
fn formatter_str_invalid_utf8_is_lossy() {
let mut buf = Vec::new();
fmt_str(&[0xFF], &FormatSpec::default(), &mut buf);
assert_eq!(buf, "\u{FFFD}".as_bytes());
}
#[test]
fn decode_full_line() {
let record = build_record(
Level::Info,
0,
"x={}",
Some(("a.rs", 7)),
&[le_bytes(TAG_U64, 42)],
);
let line = format_line(&record, LogMetadata::default());
assert_eq!(line, "1970-01-01T00:00:00.000000000Z INFO a.rs:7 x=42");
}
#[test]
fn decode_hides_source_when_disabled() {
let record = build_record(Level::Warn, 0, "hi", Some(("a.rs", 7)), &[]);
let meta = LogMetadata {
file: false,
line_number: false,
};
let line = format_line(&record, meta);
assert_eq!(line, "1970-01-01T00:00:00.000000000Z WARN hi");
}
#[test]
fn decode_file_without_line_number() {
let record = build_record(Level::Info, 0, "m", Some(("a.rs", 7)), &[]);
let meta = LogMetadata {
file: true,
line_number: false,
};
let line = format_line(&record, meta);
assert_eq!(line, "1970-01-01T00:00:00.000000000Z INFO a.rs m");
}
#[test]
fn decode_multiple_args_and_types() {
let record = build_record(
Level::Error,
0,
"{} {} {}",
None,
&[le_bytes(TAG_U16, 5), str_arg("ok"), le_bytes(TAG_BOOL, 1)],
);
let line = format_line(&record, LogMetadata::default());
assert_eq!(line, "1970-01-01T00:00:00.000000000Z ERROR 5 ok true");
}
#[test]
fn decode_escaped_braces() {
let record = build_record(Level::Info, 0, "{{{}}}", None, &[le_bytes(TAG_U64, 9)]);
let line = format_line(&record, LogMetadata::default());
assert_eq!(line, "1970-01-01T00:00:00.000000000Z INFO {9}");
}
#[test]
fn decode_unknown_tag_emits_placeholder() {
let record = build_record(Level::Info, 0, "v={}", None, &[(0x7F, vec![0u8])]);
let line = format_line(&record, LogMetadata::default());
assert_eq!(
line,
"1970-01-01T00:00:00.000000000Z INFO v=<unknown tag 0x7F>"
);
}
#[test]
fn decode_missing_arg_placeholder() {
let record = build_record(Level::Info, 0, "{} {}", None, &[le_bytes(TAG_U64, 1)]);
let line = format_line(&record, LogMetadata::default());
assert_eq!(line, "1970-01-01T00:00:00.000000000Z INFO 1 <missing arg>");
}
#[test]
fn decode_tolerates_count_byte_exceeding_tags_present() {
let mut record = build_record(Level::Info, 0, "v={}", None, &[]);
record[HEADER_SIZE + FORMAT_SECTION_SIZE] = 200;
let line = format_line(&record, LogMetadata::default());
assert!(
line.ends_with("v=<missing arg>"),
"expected a missing-arg placeholder, got {line:?}"
);
}
#[test]
fn decode_timestamp_conversion() {
let record = build_record(Level::Info, 1_234_567_890, "t", None, &[]);
let line = format_line(&record, LogMetadata::default());
assert_eq!(line, "1970-01-01T00:00:01.234567890Z INFO t");
}
#[test]
fn poll_empty_ring_no_accepts() {
let (mut drain, calls) = capture_drain();
drain.rings.push(Arc::new(RingBuffer::new()));
let mask = (RING_SIZE - 1) as u64;
let mut buf = Vec::new();
assert!(!drain.poll_once(mask, &mut buf));
assert!(calls.lock().unwrap().is_empty());
}
#[test]
fn poll_one_record_accepts_and_advances_tail() {
let (mut drain, calls) = capture_drain();
let ring = Arc::new(RingBuffer::new());
let record = build_record(
Level::Info,
0,
"x={}",
Some(("a.rs", 7)),
&[le_bytes(TAG_U64, 42)],
);
place_record(&ring, 0, &record);
let head = ring.head.load(Ordering::Acquire);
drain.rings.push(Arc::clone(&ring));
let mask = (RING_SIZE - 1) as u64;
let mut buf = Vec::new();
assert!(drain.poll_once(mask, &mut buf));
let recorded = calls.lock().unwrap();
assert_eq!(recorded.len(), 1);
assert_eq!(
recorded[0].0,
"1970-01-01T00:00:00.000000000Z INFO a.rs:7 x=42"
);
assert_eq!(recorded[0].1, Level::Info);
assert_eq!(ring.tail.load(Ordering::Relaxed), head);
drop(recorded);
assert!(!drain.poll_once(mask, &mut buf));
}
#[test]
fn poll_discards_corrupt_record_and_resyncs_to_head() {
let (mut drain, calls) = capture_drain();
let ring = Arc::new(RingBuffer::new());
let r1 = build_record(Level::Info, 0, "first", None, &[]);
place_record(&ring, 0, &r1);
let off2 = align_up(r1.len() as u64, SLOT_SIZE as u64);
let mut bad = build_record(Level::Info, 0, "corrupt", None, &[]);
bad[1] = 0x7F; place_record(&ring, off2, &bad);
let off3 = off2 + align_up(bad.len() as u64, SLOT_SIZE as u64);
let r2 = build_record(Level::Info, 0, "second", None, &[]);
place_record(&ring, off3, &r2);
drain.rings.push(Arc::clone(&ring));
let mask = (RING_SIZE - 1) as u64;
let mut buf = Vec::new();
drain.poll_once(mask, &mut buf);
let recorded = calls.lock().unwrap();
assert_eq!(recorded.len(), 1, "got {recorded:?}");
assert!(recorded[0].0.ends_with("first"), "got {:?}", recorded[0].0);
}
#[test]
fn poll_skips_end_of_buffer_record() {
let (mut drain, calls) = capture_drain();
let ring = Arc::new(RingBuffer::new());
let mut eob = Vec::new();
eob.push(0x01); eob.push(END_OF_BUFFER); eob.extend_from_slice(&(SLOT_SIZE as u16).to_le_bytes()); eob.resize(SLOT_SIZE, 0); place_record(&ring, 0, &eob);
let record = build_record(Level::Info, 0, "hi", None, &[]);
place_record(&ring, SLOT_SIZE as u64, &record);
drain.rings.push(Arc::clone(&ring));
let mask = (RING_SIZE - 1) as u64;
let mut buf = Vec::new();
assert!(drain.poll_once(mask, &mut buf));
let recorded = calls.lock().unwrap();
assert_eq!(recorded.len(), 1);
assert_eq!(recorded[0].0, "1970-01-01T00:00:00.000000000Z INFO hi");
}
#[test]
fn poll_multiple_records_in_one_ring() {
let (mut drain, calls) = capture_drain();
let ring = Arc::new(RingBuffer::new());
let r1 = build_record(Level::Info, 0, "a", None, &[]);
let r2 = build_record(Level::Warn, 0, "b", None, &[]);
let slot = SLOT_SIZE as u64;
{
let data =
unsafe { std::slice::from_raw_parts_mut(ring.data.as_ptr() as *mut u8, RING_SIZE) };
data[..r1.len()].copy_from_slice(&r1);
let off2 = slot as usize;
data[off2..off2 + r2.len()].copy_from_slice(&r2);
}
ring.head.store(2 * slot, Ordering::Release);
drain.rings.push(Arc::clone(&ring));
let mask = (RING_SIZE - 1) as u64;
let mut buf = Vec::new();
assert!(drain.poll_once(mask, &mut buf));
let recorded = calls.lock().unwrap();
assert_eq!(recorded.len(), 2);
assert_eq!(recorded[0].1, Level::Info);
assert_eq!(recorded[1].1, Level::Warn);
}
fn init_registry() {
static INIT: OnceLock<()> = OnceLock::new();
INIT.get_or_init(|| {
let _ = REGISTRY.set(Mutex::new(Vec::new()));
});
}
#[test]
fn sync_picks_up_and_drops_rings() {
init_registry();
let (mut drain, _calls) = capture_drain();
let ring = Arc::new(RingBuffer::new());
REGISTRY
.get()
.unwrap()
.lock()
.unwrap()
.push(Arc::clone(&ring));
let mask = (RING_SIZE - 1) as u64;
let mut buf = Vec::new();
drain.sync_rings(mask, &mut buf);
assert!(drain.rings.iter().any(|r| Arc::ptr_eq(r, &ring)));
ring.live.store(false, Ordering::Release);
drain.sync_rings(mask, &mut buf);
assert!(!drain.rings.iter().any(|r| Arc::ptr_eq(r, &ring)));
}
#[test]
fn sync_does_not_add_same_ring_twice() {
init_registry();
let (mut drain, _calls) = capture_drain();
let ring = Arc::new(RingBuffer::new());
REGISTRY
.get()
.unwrap()
.lock()
.unwrap()
.push(Arc::clone(&ring));
let mask = (RING_SIZE - 1) as u64;
let mut buf = Vec::new();
drain.sync_rings(mask, &mut buf);
drain.sync_rings(mask, &mut buf);
let count = drain.rings.iter().filter(|r| Arc::ptr_eq(r, &ring)).count();
assert_eq!(count, 1);
ring.live.store(false, Ordering::Release);
drain.sync_rings(mask, &mut buf);
}
#[test]
fn sync_drains_dead_ring_before_dropping_it() {
init_registry();
let (mut drain, calls) = capture_drain();
let ring = Arc::new(RingBuffer::new());
let record = build_record(Level::Info, 0, "bye", None, &[]);
place_record(&ring, 0, &record);
ring.live.store(false, Ordering::Release);
drain.rings.push(Arc::clone(&ring));
let mask = (RING_SIZE - 1) as u64;
let mut buf = Vec::new();
drain.sync_rings(mask, &mut buf);
let recorded = calls.lock().unwrap();
assert_eq!(recorded.len(), 1);
assert_eq!(recorded[0].0, "1970-01-01T00:00:00.000000000Z INFO bye");
drop(recorded);
assert!(!drain.rings.iter().any(|r| Arc::ptr_eq(r, &ring)));
}
#[test]
fn producer_and_drain_concurrent_no_aliasing_ub() {
use crate::builder::Backpressure;
use std::sync::Barrier;
const N: usize = 8;
let ring = Arc::new(RingBuffer::new());
let mask = (RING_SIZE - 1) as u64;
let record = build_record(
Level::Info,
0x1234,
"hello {}",
Some(("f.rs", 1)),
&[le_bytes(TAG_U64, 42)],
);
let barrier = Arc::new(Barrier::new(2));
let producer = {
let ring = Arc::clone(&ring);
let barrier = Arc::clone(&barrier);
let record = record.clone();
std::thread::spawn(move || {
barrier.wait();
for _ in 0..N {
assert!(ring.write_record(&record, Backpressure::Block));
}
})
};
let calls = Arc::new(Mutex::new(Vec::new()));
let mut sink = CaptureSink {
calls: Arc::clone(&calls),
};
let metadata = LogMetadata::default();
let calibration = identity_calibration();
let mut buf = Vec::new();
barrier.wait();
let mut guard = 0;
while calls.lock().unwrap().len() < N {
drain_ring(&ring, mask, &mut sink, 0, &metadata, &calibration, &mut buf);
guard += 1;
assert!(guard < 1_000_000, "drain stalled before consuming all records");
}
producer.join().unwrap();
assert_eq!(calls.lock().unwrap().len(), N);
}
}