425 lines
14 KiB
Rust
425 lines
14 KiB
Rust
//! 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};
|
|
use tokio::sync::broadcast;
|
|
|
|
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>>,
|
|
/// Broadcast channel for live log streaming to WebSocket subscribers.
|
|
broadcast_tx: broadcast::Sender<LogEntry>,
|
|
}
|
|
|
|
impl LogBuffer {
|
|
fn new() -> Self {
|
|
let (broadcast_tx, _) = broadcast::channel(512);
|
|
Self {
|
|
entries: Mutex::new(VecDeque::with_capacity(CAPACITY)),
|
|
log_file: Mutex::new(None),
|
|
broadcast_tx,
|
|
}
|
|
}
|
|
|
|
/// Subscribe to live log entries as they are pushed.
|
|
pub fn subscribe(&self) -> broadcast::Receiver<LogEntry> {
|
|
self.broadcast_tx.subscribe()
|
|
}
|
|
|
|
/// 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.clone());
|
|
}
|
|
|
|
// Best-effort broadcast to WebSocket subscribers.
|
|
let _ = self.broadcast_tx.send(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()
|
|
}
|
|
|
|
/// Return up to `count` recent `LogEntry` structs (not formatted strings),
|
|
/// optionally filtered by substring and/or severity level.
|
|
/// Entries are returned in chronological order (oldest first).
|
|
pub fn get_recent_entries(
|
|
&self,
|
|
count: usize,
|
|
filter: Option<&str>,
|
|
severity: Option<&LogLevel>,
|
|
) -> Vec<LogEntry> {
|
|
let buf = match self.entries.lock() {
|
|
Ok(b) => b,
|
|
Err(_) => return vec![],
|
|
};
|
|
let filtered: Vec<LogEntry> = 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))
|
|
})
|
|
.cloned()
|
|
.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::new();
|
|
// 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}"
|
|
);
|
|
}
|
|
}
|
|
}
|