Files
storkit/server/src/log_buffer.rs

390 lines
12 KiB
Rust
Raw Normal View History

//! Bounded in-memory ring buffer for server log output.
//!
//! Use the [`slog!`] macro (INFO), [`slog_warn!`] (WARN), or [`slog_error!`]
//! (ERROR) as drop-in replacements for `eprintln!`. Each call writes to stderr
//! with an ISO 8601 timestamp + severity prefix, and simultaneously appends
//! the entry to the global ring buffer, making it retrievable via the
//! `get_server_logs` MCP tool.
use std::collections::VecDeque;
use std::fs::OpenOptions;
use std::io::Write;
use std::path::PathBuf;
use std::sync::{Mutex, OnceLock};
const CAPACITY: usize = 1000;
/// Severity level for a log entry.
#[derive(Debug, Clone, PartialEq, Eq)]
pub enum LogLevel {
Error,
Warn,
Info,
}
impl LogLevel {
pub fn as_str(&self) -> &'static str {
match self {
LogLevel::Error => "ERROR",
LogLevel::Warn => "WARN",
LogLevel::Info => "INFO",
}
}
/// Parse from a case-insensitive string. Returns `None` for unknown levels.
pub fn from_str_ci(s: &str) -> Option<Self> {
match s.to_uppercase().as_str() {
"ERROR" => Some(LogLevel::Error),
"WARN" => Some(LogLevel::Warn),
"INFO" => Some(LogLevel::Info),
_ => None,
}
}
}
/// A single captured log entry.
#[derive(Debug, Clone)]
pub struct LogEntry {
pub level: LogLevel,
/// ISO 8601 UTC timestamp.
pub timestamp: String,
pub message: String,
}
impl LogEntry {
/// Format the entry as a single log line: `{timestamp} [{LEVEL}] {message}`.
pub fn formatted(&self) -> String {
format!("{} [{}] {}", self.timestamp, self.level.as_str(), self.message)
}
/// Format with ANSI color codes for terminal output.
/// WARN is yellow, ERROR is red, INFO has no color.
fn colored_formatted(&self) -> String {
let line = self.formatted();
match self.level {
LogLevel::Warn => format!("\x1b[33m{line}\x1b[0m"),
LogLevel::Error => format!("\x1b[31m{line}\x1b[0m"),
LogLevel::Info => line,
}
}
}
pub struct LogBuffer {
entries: Mutex<VecDeque<LogEntry>>,
log_file: Mutex<Option<PathBuf>>,
}
impl LogBuffer {
fn new() -> Self {
Self {
entries: Mutex::new(VecDeque::with_capacity(CAPACITY)),
log_file: Mutex::new(None),
}
}
/// Set the persistent log file path. Call once at startup after the
/// project root is known.
pub fn set_log_file(&self, path: PathBuf) {
if let Ok(mut f) = self.log_file.lock() {
*f = Some(path);
}
}
/// Append a log entry, evicting the oldest when at capacity.
pub fn push_entry(&self, level: LogLevel, message: String) {
let timestamp = chrono::Utc::now().format("%Y-%m-%dT%H:%M:%SZ").to_string();
let entry = LogEntry {
level,
timestamp,
message,
};
eprintln!("{}", entry.colored_formatted());
// Append to persistent log file (best-effort).
if let Ok(guard) = self.log_file.lock()
&& let Some(ref path) = *guard
&& let Ok(mut file) = OpenOptions::new().create(true).append(true).open(path)
{
let _ = writeln!(file, "{}", entry.formatted());
}
if let Ok(mut buf) = self.entries.lock() {
if buf.len() >= CAPACITY {
buf.pop_front();
}
buf.push_back(entry);
}
}
/// Return up to `count` recent log lines as formatted strings,
/// optionally filtered by substring and/or severity level.
/// Lines are returned in chronological order (oldest first).
pub fn get_recent(
&self,
count: usize,
filter: Option<&str>,
severity: Option<&LogLevel>,
) -> Vec<String> {
let buf = match self.entries.lock() {
Ok(b) => b,
Err(_) => return vec![],
};
let filtered: Vec<String> = buf
.iter()
.filter(|entry| {
severity.is_none_or(|s| &entry.level == s)
&& filter.is_none_or(|f| entry.message.contains(f) || entry.formatted().contains(f))
})
.map(|entry| entry.formatted())
.collect();
let start = filtered.len().saturating_sub(count);
filtered[start..].to_vec()
}
}
static GLOBAL: OnceLock<LogBuffer> = OnceLock::new();
/// Access the process-wide log ring buffer.
pub fn global() -> &'static LogBuffer {
GLOBAL.get_or_init(LogBuffer::new)
}
/// Write an INFO log to stderr **and** capture it in the ring buffer.
///
/// Usage is identical to `eprintln!`:
/// ```ignore
/// slog!("agent {} started", name);
/// ```
#[macro_export]
macro_rules! slog {
($($arg:tt)*) => {{
$crate::log_buffer::global().push_entry(
$crate::log_buffer::LogLevel::Info,
format!($($arg)*),
);
}};
}
/// Write a WARN log to stderr **and** capture it in the ring buffer.
#[macro_export]
macro_rules! slog_warn {
($($arg:tt)*) => {{
$crate::log_buffer::global().push_entry(
$crate::log_buffer::LogLevel::Warn,
format!($($arg)*),
);
}};
}
/// Write an ERROR log to stderr **and** capture it in the ring buffer.
#[macro_export]
macro_rules! slog_error {
($($arg:tt)*) => {{
$crate::log_buffer::global().push_entry(
$crate::log_buffer::LogLevel::Error,
format!($($arg)*),
);
}};
}
#[cfg(test)]
mod tests {
use super::*;
fn fresh_buffer() -> LogBuffer {
LogBuffer::new()
}
#[test]
fn push_and_retrieve() {
let buf = fresh_buffer();
buf.push_entry(LogLevel::Info, "line one".into());
buf.push_entry(LogLevel::Info, "line two".into());
let recent = buf.get_recent(10, None, None);
assert_eq!(recent.len(), 2);
assert!(recent[0].contains("[INFO]") && recent[0].contains("line one"));
assert!(recent[1].contains("[INFO]") && recent[1].contains("line two"));
}
#[test]
fn evicts_oldest_at_capacity() {
let buf = LogBuffer {
entries: Mutex::new(VecDeque::with_capacity(CAPACITY)),
log_file: Mutex::new(None),
};
// Fill past capacity
for i in 0..=CAPACITY {
buf.push_entry(LogLevel::Info, format!("line {i}"));
}
let recent = buf.get_recent(CAPACITY + 1, None, None);
// Should have exactly CAPACITY lines
assert_eq!(recent.len(), CAPACITY);
// The oldest (line 0) should have been evicted
assert!(!recent.iter().any(|l| l.contains("line 0") && !l.contains("line 10")));
// The newest should be present
assert!(recent
.iter()
.any(|l| l.contains(&format!("line {CAPACITY}"))));
}
#[test]
fn filter_by_substring() {
let buf = fresh_buffer();
buf.push_entry(LogLevel::Info, "watcher started".into());
buf.push_entry(LogLevel::Info, "mcp call received".into());
buf.push_entry(LogLevel::Info, "watcher event".into());
let filtered = buf.get_recent(100, Some("watcher"), None);
assert_eq!(filtered.len(), 2);
assert!(filtered[0].contains("watcher started"));
assert!(filtered[1].contains("watcher event"));
}
#[test]
fn count_limits_results() {
let buf = fresh_buffer();
for i in 0..10 {
buf.push_entry(LogLevel::Info, format!("line {i}"));
}
let recent = buf.get_recent(3, None, None);
assert_eq!(recent.len(), 3);
// Most recent 3
assert!(recent[0].contains("line 7"));
assert!(recent[1].contains("line 8"));
assert!(recent[2].contains("line 9"));
}
#[test]
fn empty_buffer_returns_empty() {
let buf = fresh_buffer();
assert!(buf.get_recent(10, None, None).is_empty());
}
#[test]
fn log_lines_include_iso8601_timestamp() {
let buf = fresh_buffer();
buf.push_entry(LogLevel::Info, "timestamped message".into());
let recent = buf.get_recent(1, None, None);
assert_eq!(recent.len(), 1);
// Timestamp format: YYYY-MM-DDTHH:MM:SSZ
let line = &recent[0];
assert!(
line.len() > 20,
"Line should have timestamp prefix: {line}"
);
// Check it starts with a 4-digit year
assert!(line.chars().next().unwrap().is_ascii_digit());
assert!(line.contains('T'));
assert!(line.contains('Z'));
}
#[test]
fn filter_by_severity_error_only() {
let buf = fresh_buffer();
buf.push_entry(LogLevel::Info, "info message".into());
buf.push_entry(LogLevel::Warn, "warn message".into());
buf.push_entry(LogLevel::Error, "error message".into());
let errors = buf.get_recent(100, None, Some(&LogLevel::Error));
assert_eq!(errors.len(), 1);
assert!(errors[0].contains("[ERROR]"));
assert!(errors[0].contains("error message"));
}
#[test]
fn filter_by_severity_warn_only() {
let buf = fresh_buffer();
buf.push_entry(LogLevel::Info, "info message".into());
buf.push_entry(LogLevel::Warn, "warn message".into());
buf.push_entry(LogLevel::Error, "error message".into());
let warns = buf.get_recent(100, None, Some(&LogLevel::Warn));
assert_eq!(warns.len(), 1);
assert!(warns[0].contains("[WARN]"));
assert!(warns[0].contains("warn message"));
}
#[test]
fn severity_levels_appear_in_formatted_output() {
let buf = fresh_buffer();
buf.push_entry(LogLevel::Info, "info".into());
buf.push_entry(LogLevel::Warn, "warn".into());
buf.push_entry(LogLevel::Error, "error".into());
let all = buf.get_recent(10, None, None);
assert_eq!(all.len(), 3);
assert!(all[0].contains("[INFO]"));
assert!(all[1].contains("[WARN]"));
assert!(all[2].contains("[ERROR]"));
}
#[test]
fn loglevel_from_str_ci() {
assert_eq!(LogLevel::from_str_ci("ERROR"), Some(LogLevel::Error));
assert_eq!(LogLevel::from_str_ci("error"), Some(LogLevel::Error));
assert_eq!(LogLevel::from_str_ci("WARN"), Some(LogLevel::Warn));
assert_eq!(LogLevel::from_str_ci("warn"), Some(LogLevel::Warn));
assert_eq!(LogLevel::from_str_ci("INFO"), Some(LogLevel::Info));
assert_eq!(LogLevel::from_str_ci("info"), Some(LogLevel::Info));
assert_eq!(LogLevel::from_str_ci("DEBUG"), None);
}
#[test]
fn colored_formatted_warn_has_yellow_ansi() {
let entry = LogEntry {
level: LogLevel::Warn,
timestamp: "2026-01-01T00:00:00Z".into(),
message: "test warning".into(),
};
let colored = entry.colored_formatted();
assert!(colored.starts_with("\x1b[33m"), "WARN should start with yellow ANSI code");
assert!(colored.ends_with("\x1b[0m"), "WARN should end with ANSI reset");
assert!(colored.contains("[WARN]"));
assert!(colored.contains("test warning"));
}
#[test]
fn colored_formatted_error_has_red_ansi() {
let entry = LogEntry {
level: LogLevel::Error,
timestamp: "2026-01-01T00:00:00Z".into(),
message: "test error".into(),
};
let colored = entry.colored_formatted();
assert!(colored.starts_with("\x1b[31m"), "ERROR should start with red ANSI code");
assert!(colored.ends_with("\x1b[0m"), "ERROR should end with ANSI reset");
assert!(colored.contains("[ERROR]"));
assert!(colored.contains("test error"));
}
#[test]
fn colored_formatted_info_has_no_ansi() {
let entry = LogEntry {
level: LogLevel::Info,
timestamp: "2026-01-01T00:00:00Z".into(),
message: "test info".into(),
};
let colored = entry.colored_formatted();
assert!(!colored.contains("\x1b["), "INFO should have no ANSI escape codes");
assert!(colored.contains("[INFO]"));
assert!(colored.contains("test info"));
}
#[test]
fn ring_buffer_entries_have_no_ansi_codes() {
let buf = fresh_buffer();
buf.push_entry(LogLevel::Info, "info msg".into());
buf.push_entry(LogLevel::Warn, "warn msg".into());
buf.push_entry(LogLevel::Error, "error msg".into());
let recent = buf.get_recent(10, None, None);
assert_eq!(recent.len(), 3);
for line in &recent {
assert!(
!line.contains("\x1b["),
"Ring buffer entry should not contain ANSI codes: {line}"
);
}
}
}