use crate::turso;
use crate::util::UnwrapPoison;
use crate::util::json;
use anyhow::Context;
use futures_util::FutureExt;
use serde::{Deserialize, Serialize};
use std::io;
use std::panic::AssertUnwindSafe;
use std::path::Path;
use std::sync::Arc;
use std::sync::atomic::{AtomicU64, Ordering};
use tokio::sync::OnceCell;
use tokio::sync::mpsc::{UnboundedReceiver, UnboundedSender};
use tracing::warn;
use tracing_subscriber::fmt::MakeWriter;
use tracing_subscriber::{EnvFilter, fmt, layer::SubscriberExt, util::SubscriberInitExt};
use turso::{Row, Value, params};
#[derive(Debug, Clone, Serialize, Deserialize)]
pub struct LogEntry {
pub timestamp: String,
pub level: String,
pub target: String,
pub message: String,
#[serde(default)]
pub fields: serde_json::Value,
#[serde(default)]
pub agent_id: String,
#[serde(default)]
pub agent_role: String,
#[serde(default)]
pub workspace: String,
}
crate::columns! {
LOGS_COLUMNS [LOGS] {
TIMESTAMP => "timestamp",
LEVEL => "level",
TARGET => "target",
MESSAGE => "message",
FIELDS => "fields",
AGENT_ID => "agent_id",
AGENT_ROLE => "agent_role",
WORKSPACE => "workspace",
}
}
#[derive(Clone, Debug)]
pub struct LogStore {
pub(crate) conn: crate::turso::Connection,
}
pub static LOG_STORE: OnceCell<LogStore> = OnceCell::const_new();
const LOGS_SCHEMA: &str = "\
CREATE TABLE IF NOT EXISTS logs (
id INTEGER PRIMARY KEY AUTOINCREMENT,
timestamp TEXT NOT NULL,
level TEXT NOT NULL,
target TEXT NOT NULL,
message TEXT NOT NULL,
fields TEXT NOT NULL DEFAULT '{}',
agent_id TEXT NOT NULL DEFAULT '',
agent_role TEXT NOT NULL DEFAULT '',
workspace TEXT NOT NULL DEFAULT ''
);
CREATE INDEX IF NOT EXISTS idx_logs_timestamp ON logs(timestamp);
CREATE INDEX IF NOT EXISTS idx_logs_level ON logs(level);
CREATE INDEX IF NOT EXISTS idx_logs_target ON logs(target);
CREATE INDEX IF NOT EXISTS idx_logs_agent_role ON logs(agent_role);
CREATE INDEX IF NOT EXISTS idx_logs_agent_id ON logs(agent_id);
CREATE INDEX IF NOT EXISTS idx_logs_workspace ON logs(workspace);
-- Consolidated tool-call stats (formerly stats.db). Both the
-- normal open path and the quarantine-recreate branch execute this schema, so
-- a quarantine silently recreates the stats tables too.
CREATE TABLE IF NOT EXISTS tool_calls (
id INTEGER PRIMARY KEY AUTOINCREMENT,
agent_id TEXT NOT NULL,
role TEXT NOT NULL,
tool_name TEXT NOT NULL,
arguments TEXT NOT NULL DEFAULT '{}',
duration_ms INTEGER NOT NULL DEFAULT 0,
success INTEGER NOT NULL DEFAULT 1,
error_message TEXT,
workspace TEXT NOT NULL DEFAULT '',
recorded_at TEXT NOT NULL
);
CREATE INDEX IF NOT EXISTS idx_tool_calls_agent_id ON tool_calls(agent_id);
CREATE INDEX IF NOT EXISTS idx_tool_calls_role ON tool_calls(role);
CREATE INDEX IF NOT EXISTS idx_tool_calls_tool_name ON tool_calls(tool_name);
CREATE INDEX IF NOT EXISTS idx_tool_calls_recorded_at ON tool_calls(recorded_at);
CREATE INDEX IF NOT EXISTS idx_tool_calls_workspace ON tool_calls(workspace);
CREATE INDEX IF NOT EXISTS idx_tool_calls_error_message ON tool_calls(error_message);
-- Per-operation LLM request stats (all purposes: agent runs, verdict
-- extraction, summarization, consolidation). Metadata only — no request
-- inputs/outputs are stored. Auto-created on existing databases at next
-- store open (CREATE TABLE IF NOT EXISTS), including quarantine recreation.
CREATE TABLE IF NOT EXISTS llm_requests (
id INTEGER PRIMARY KEY AUTOINCREMENT,
recorded_at TEXT NOT NULL,
purpose TEXT NOT NULL,
agent_id TEXT NOT NULL DEFAULT '',
role TEXT NOT NULL DEFAULT '',
workspace TEXT NOT NULL DEFAULT '',
ticket_id TEXT,
model TEXT NOT NULL,
routing TEXT NOT NULL DEFAULT '',
input_tokens INTEGER,
output_tokens INTEGER,
cached_input_tokens INTEGER,
cache_miss_tokens INTEGER,
duration_ms INTEGER NOT NULL,
retry_attempts INTEGER NOT NULL,
finish_reason TEXT,
failure_class TEXT,
success INTEGER NOT NULL DEFAULT 1,
-- Observability additions: billed cost (the invoice amount), raw
-- cost_details, serving upstream provider, system_fingerprint. All
-- telemetry fields are parsed generically from the response envelope,
-- so cost/upstream_provider/system_fingerprint are NULL on failures
-- and whenever the provider omits them.
cost REAL,
cost_details TEXT,
upstream_provider TEXT,
system_fingerprint TEXT
);
CREATE INDEX IF NOT EXISTS idx_llm_requests_recorded_at ON llm_requests(recorded_at);
CREATE INDEX IF NOT EXISTS idx_llm_requests_agent_id ON llm_requests(agent_id);
CREATE INDEX IF NOT EXISTS idx_llm_requests_model ON llm_requests(model);
CREATE INDEX IF NOT EXISTS idx_llm_requests_purpose ON llm_requests(purpose);";
impl LogStore {
pub(crate) async fn open(root: &Path) -> anyhow::Result<Self> {
let store = match open_verified_logs_store(root).await {
Ok(conn) => Self { conn },
Err(OpenFailure::Corrupt(reason)) => {
warn!(
error = %reason,
"logs store failed integrity verification — quarantining artifact family \
and recreating a fresh store",
);
quarantine_logs_artifacts(root);
let conn = crate::turso::open_with_schema(
&turso::store_db_path(root, "logs"),
LOGS_SCHEMA,
)
.await
.context("Failed to recreate logs store after quarantine")?;
Self { conn }
}
Err(OpenFailure::Other(e)) => return Err(e),
};
Ok(store)
}
async fn insert_batch(&self, entries: &[LogEntry]) -> anyhow::Result<()> {
if entries.is_empty() {
return Ok(());
}
let tx = self
.conn
.begin_tx()
.await
.context("Failed to begin log insert transaction")?;
for entry in entries {
tx.execute(
"INSERT INTO logs (timestamp, level, target, message, fields, agent_id, agent_role, workspace) VALUES (?1, ?2, ?3, ?4, ?5, ?6, ?7, ?8)",
params![
entry.timestamp.clone(),
entry.level.clone(),
entry.target.clone(),
entry.message.clone(),
serde_json::to_string(&entry.fields)
.expect("log entry fields serialization failed; this should not happen"),
entry.agent_id.clone(),
entry.agent_role.clone(),
entry.workspace.clone(),
],
)
.await
.context("Failed to insert log entry in batch")?;
}
tx.commit()
.await
.context("Failed to commit log insert transaction")?;
Ok(())
}
pub async fn delete_older_than(&self, level: &str, cutoff: &str) -> anyhow::Result<u64> {
let n = self
.conn
.execute(
"DELETE FROM logs WHERE level = ?1 AND timestamp < ?2",
params![level, cutoff],
)
.await
.context("Failed to delete old log entries")?;
Ok(n)
}
pub async fn query(&self, filters: &LogQuery) -> anyhow::Result<(Vec<LogEntry>, usize)> {
let (where_sql, values) = build_where_clause(filters);
let count_sql = format!("SELECT COUNT(*) FROM logs {where_sql}");
let total = self
.conn
.query_row(&count_sql, values.clone(), |row| row.get::<i64>(0))
.await
.map(|n| usize::try_from(n).unwrap_or(0))?;
if total == 0 {
return Ok((vec![], 0));
}
let limit: i64 = i64::try_from(filters.limit.unwrap_or(100).min(1000))
.expect("log query limit overflowed i64; limit must be <= i64::MAX");
let offset: i64 = i64::try_from(filters.offset.unwrap_or(0))
.expect("log query offset overflowed i64; offset must be <= i64::MAX");
let mut data_values = values;
data_values.push(Value::Integer(limit));
data_values.push(Value::Integer(offset));
let data_sql = format!(
"SELECT {LOGS_COLUMNS} FROM logs {where_sql} ORDER BY id DESC LIMIT ? OFFSET ?",
);
let rows = self
.conn
.query(&data_sql, data_values)
.await
.context("Data query failed")?;
let mut entries = Vec::new();
for row in rows {
entries.push(log_entry_from_row(&row)?);
}
Ok((entries, total))
}
}
enum OpenFailure {
Corrupt(String),
Other(anyhow::Error),
}
async fn open_verified_logs_store(root: &Path) -> Result<crate::turso::Connection, OpenFailure> {
let db_path = turso::store_db_path(root, "logs");
let boot_verified = crate::wal_guard::has_boot_diagnosis(&db_path);
let open = AssertUnwindSafe(crate::turso::open_store(root, "logs", LOGS_SCHEMA))
.catch_unwind()
.await;
let conn = match open {
Ok(Ok(conn)) => conn,
Ok(Err(e)) => {
if let Some(crate::turso::RecreateFailed(inner)) =
e.downcast_ref::<crate::turso::RecreateFailed>()
{
return Err(OpenFailure::Other(anyhow::anyhow!("{inner:#}")));
}
if db_path.exists() && crate::turso::is_corruption_class(&e) {
return Err(OpenFailure::Corrupt(format!("open failed: {e:#}")));
}
return Err(OpenFailure::Other(e));
}
Err(payload) => {
return Err(OpenFailure::Corrupt(format!(
"open panicked: {}",
crate::util::panic_message(&*payload)
)));
}
};
if boot_verified {
return Ok(conn);
}
let verify = AssertUnwindSafe(conn.quick_check()).catch_unwind().await;
match verify {
Ok(Ok(())) => Ok(conn),
Ok(Err(e)) if crate::turso::is_corruption_class(&e) => {
Err(OpenFailure::Corrupt(format!("{e:#}")))
}
Ok(Err(e)) => Err(OpenFailure::Other(e)),
Err(payload) => Err(OpenFailure::Corrupt(format!(
"integrity check panicked: {}",
crate::util::panic_message(&*payload)
))),
}
}
fn quarantine_logs_artifacts(root: &Path) {
let _ = turso::quarantine_store_artifacts(&turso::store_db_path(root, "logs"));
}
#[derive(Debug, Clone, Default, Deserialize)]
pub struct LogQuery {
pub level: Option<String>,
pub target: Option<String>,
pub search: Option<String>,
pub since: Option<String>,
pub limit: Option<usize>,
pub offset: Option<usize>,
}
fn build_where_clause(filters: &LogQuery) -> (String, Vec<Value>) {
let mut conditions: Vec<String> = Vec::new();
let mut values: Vec<Value> = Vec::new();
if let Some(ref levels_str) = filters.level
&& !levels_str.is_empty()
{
let levels: Vec<Value> = levels_str
.split(',')
.map(str::trim)
.filter(|s| !s.is_empty())
.map(|s| Value::Text(s.to_string()))
.collect();
if !levels.is_empty() {
conditions.push(format!(
"level IN ({})",
turso::sql_in_placeholders(levels.len()),
));
values.extend(levels);
}
}
if let Some(ref target) = filters.target {
conditions.push("target LIKE ?".into());
values.push(Value::Text(format!("{target}%")));
}
if let Some(ref search) = filters.search
&& !search.is_empty()
{
let val = Value::Text(format!("%{search}%"));
conditions.push("(target LIKE ? OR message LIKE ?)".into());
values.push(val.clone());
values.push(val);
}
if let Some(ref since) = filters.since {
conditions.push("timestamp >= ?".into());
values.push(Value::Text(since.clone()));
}
if conditions.is_empty() {
(String::new(), values)
} else {
(format!("WHERE {}", conditions.join(" AND ")), values)
}
}
fn log_entry_from_row(row: &Row) -> anyhow::Result<LogEntry> {
let timestamp = row.get::<String>(COL_LOGS_TIMESTAMP)?;
let level = row.get::<String>(COL_LOGS_LEVEL)?;
let target = row.get::<String>(COL_LOGS_TARGET)?;
let message = row.get::<String>(COL_LOGS_MESSAGE)?;
let fields_str = row.get::<String>(COL_LOGS_FIELDS)?;
let fields: serde_json::Value =
serde_json::from_str(&fields_str).unwrap_or(serde_json::Value::Null);
let agent_id = row.get::<String>(COL_LOGS_AGENT_ID)?;
let agent_role = row.get::<String>(COL_LOGS_AGENT_ROLE)?;
let workspace = row.get::<String>(COL_LOGS_WORKSPACE)?;
Ok(LogEntry {
timestamp,
level,
target,
message,
fields,
agent_id,
agent_role,
workspace,
})
}
pub async fn init_tracing(
storage_root: &Path,
) -> anyhow::Result<(Arc<LogStore>, tokio::sync::broadcast::Sender<String>)> {
let store = match LogStore::open(storage_root).await {
Ok(store) => store,
Err(e) => {
crate::boot::clear_boot_diagnostics();
return Err(e);
}
};
LOG_STORE
.set(store.clone())
.map_err(|_| anyhow::anyhow!("LOG_STORE already initialized"))?;
let log_store = Arc::new(store);
let (log_tx, log_rx) = tokio::sync::mpsc::unbounded_channel();
let (broadcast_tx, _) = tokio::sync::broadcast::channel(256);
spawn_log_writer(Arc::clone(&log_store), log_rx, broadcast_tx.clone());
let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| {
EnvFilter::new(
"info,turso_core=warn,tantivy=warn,ort=warn,fff_search=error,fff_search::grep=error",
)
});
tracing_subscriber::registry()
.with(env_filter)
.with(
fmt::Layer::new()
.json()
.with_writer(make_log_writer(log_tx))
.with_ansi(false),
)
.init();
crate::boot::mark_tracing_initialized();
crate::boot::replay_boot_diagnostics();
Ok((log_store, broadcast_tx))
}
const fn make_log_writer(tx: UnboundedSender<String>) -> LogWriter {
LogWriter { tx }
}
#[derive(Clone)]
struct LogWriter {
tx: UnboundedSender<String>,
}
impl io::Write for LogWriter {
fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
let line = String::from_utf8_lossy(buf).to_string();
let _ = self.tx.send(line);
Ok(buf.len())
}
fn flush(&mut self) -> io::Result<()> {
Ok(())
}
}
impl MakeWriter<'_> for LogWriter {
type Writer = Self;
fn make_writer(&self) -> Self::Writer {
self.clone()
}
}
const LOG_BATCH_MAX: usize = 50;
const LOG_FLUSH_INTERVAL: std::time::Duration = std::time::Duration::from_millis(500);
fn spawn_log_writer(
store: Arc<LogStore>,
rx: UnboundedReceiver<String>,
broadcast: tokio::sync::broadcast::Sender<String>,
) {
spawn_log_writer_with_interval(store, rx, broadcast, LOG_FLUSH_INTERVAL);
}
fn spawn_log_writer_with_interval(
store: Arc<LogStore>,
mut rx: UnboundedReceiver<String>,
broadcast: tokio::sync::broadcast::Sender<String>,
flush_interval: std::time::Duration,
) {
tokio::spawn(async move {
let mut batch: Vec<LogEntry> = Vec::new();
let mut flush_timer = tokio::time::interval(flush_interval);
flush_timer.set_missed_tick_behavior(tokio::time::MissedTickBehavior::Delay);
flush_timer.tick().await;
loop {
tokio::select! {
maybe_line = rx.recv() => {
let Some(line) = maybe_line else {
if !log_writer_stopped() {
absorb_flush(&store, &mut batch).await;
}
break;
};
let trimmed = line.trim();
if trimmed.is_empty() {
continue;
}
let Some(entry) = parse_tracing_json(trimmed) else {
continue;
};
let _ = broadcast.send(serde_json::to_string(&entry).expect(
"log entry broadcast serialization failed; this should not happen",
));
if log_writer_stopped() {
continue;
}
batch.push(entry);
if batch.len() >= LOG_BATCH_MAX {
absorb_flush(&store, &mut batch).await;
}
}
_ = flush_timer.tick() => {
if !batch.is_empty() && !log_writer_stopped() {
absorb_flush(&store, &mut batch).await;
}
}
}
}
});
}
async fn absorb_flush(store: &LogStore, batch: &mut Vec<LogEntry>) {
let result = AssertUnwindSafe(flush_log_batch(store, batch))
.catch_unwind()
.await;
match result {
Ok(()) => reset_log_writer_panic_state(),
Err(payload) => {
batch.clear();
let message = format!(
"log writer storage panic: {}",
crate::util::panic_message(&*payload)
);
let consecutive = record_log_writer_panic(&message);
if log_writer_stopped() {
eprintln!(
"[mahbot] log store writer stopped after {consecutive} consecutive storage \
panics: {message}"
);
} else {
tokio::time::sleep(log_writer_panic_backoff(consecutive)).await;
}
}
}
}
async fn flush_log_batch(store: &LogStore, batch: &mut Vec<LogEntry>) {
if batch.is_empty() {
return;
}
let mut last_error: Option<anyhow::Error> = None;
for attempt in 0..LOG_INSERT_MAX_ATTEMPTS {
match store.insert_batch(batch).await {
Ok(()) => {
batch.clear();
return;
}
Err(e) => {
last_error = Some(e);
if attempt + 1 < LOG_INSERT_MAX_ATTEMPTS {
tokio::time::sleep(LOG_INSERT_RETRY_BACKOFF).await;
}
}
}
}
record_log_write_failure(last_error);
batch.clear();
}
const LOG_INSERT_MAX_ATTEMPTS: usize = 3;
const LOG_INSERT_RETRY_BACKOFF: std::time::Duration = std::time::Duration::from_millis(250);
const LOG_WRITE_STDERR_WARN_INTERVAL_MS: u64 = 60_000;
const LOG_WRITER_MAX_CONSECUTIVE_PANICS: u32 = 5;
const LOG_WRITER_PANIC_BACKOFF_MS: u64 = 500;
#[derive(Debug, Clone, PartialEq, Eq, Default)]
pub struct LogWriterPanicState {
pub consecutive_panics: u32,
pub writer_stopped: bool,
}
impl LogWriterPanicState {
#[must_use]
pub fn record_panic(&mut self) -> u32 {
self.consecutive_panics += 1;
if self.consecutive_panics >= LOG_WRITER_MAX_CONSECUTIVE_PANICS {
self.writer_stopped = true;
}
self.consecutive_panics
}
pub fn reset(&mut self) {
self.consecutive_panics = 0;
}
}
#[derive(Debug, Clone, PartialEq, Eq, Default)]
pub struct LogWriteErrorInfo {
pub count: u64,
pub last_timestamp: Option<String>,
pub last_message: Option<String>,
pub panic_state: LogWriterPanicState,
}
static LOG_WRITE_LAST_ERROR: std::sync::Mutex<LogWriteErrorInfo> =
std::sync::Mutex::new(LogWriteErrorInfo {
count: 0,
last_timestamp: None,
last_message: None,
panic_state: LogWriterPanicState {
consecutive_panics: 0,
writer_stopped: false,
},
});
static LOG_WRITE_LAST_STDERR_WARN_MS: AtomicU64 = AtomicU64::new(0);
#[must_use]
pub fn log_write_error_info() -> LogWriteErrorInfo {
LOG_WRITE_LAST_ERROR.lock().unwrap_poison().clone()
}
fn record_log_write_failure(error: Option<anyhow::Error>) {
let message = error.map_or_else(
|| "unknown log insert failure".to_string(),
|e| format!("{e:#}"),
);
record_log_write_failure_impl(&message, LogFailureKind::Insert);
}
fn record_log_writer_panic(message: &str) -> u32 {
record_log_write_failure_impl(message, LogFailureKind::WriterPanic)
}
#[derive(Clone, Copy)]
enum LogFailureKind {
Insert,
WriterPanic,
}
impl LogFailureKind {
fn label(self) -> &'static str {
match self {
Self::Insert => "insert failure",
Self::WriterPanic => "writer panic",
}
}
fn records_panic(self) -> bool {
matches!(self, Self::WriterPanic)
}
}
fn record_log_write_failure_impl(message: &str, kind: LogFailureKind) -> u32 {
let (count, consecutive) = {
let mut guard = LOG_WRITE_LAST_ERROR.lock().unwrap_poison();
guard.count += 1;
guard.last_timestamp = Some(turso::now());
guard.last_message = Some(message.to_string());
let consecutive = if kind.records_panic() {
guard.panic_state.record_panic()
} else {
guard.panic_state.consecutive_panics
};
(guard.count, consecutive)
};
emit_stderr_warning(count, message, kind.label());
consecutive
}
fn reset_log_writer_panic_state() {
let mut guard = LOG_WRITE_LAST_ERROR.lock().unwrap_poison();
guard.panic_state.reset();
}
fn log_writer_stopped() -> bool {
LOG_WRITE_LAST_ERROR
.lock()
.unwrap_poison()
.panic_state
.writer_stopped
}
fn log_writer_panic_backoff(consecutive: u32) -> std::time::Duration {
let shift = consecutive.saturating_sub(1).min(6);
let ms = LOG_WRITER_PANIC_BACKOFF_MS.saturating_mul(1 << shift);
std::time::Duration::from_millis(ms.min(30_000))
}
fn emit_stderr_warning(count: u64, message: &str, kind: &str) {
let now_ms = crate::util::unix_millis();
let last_warn_ms = LOG_WRITE_LAST_STDERR_WARN_MS.load(Ordering::SeqCst);
if now_ms.saturating_sub(last_warn_ms) >= LOG_WRITE_STDERR_WARN_INTERVAL_MS {
LOG_WRITE_LAST_STDERR_WARN_MS.store(now_ms, Ordering::SeqCst);
eprintln!("[mahbot] log store {kind} #{count}: {message}");
}
}
fn get_str_or_empty(val: &serde_json::Value, key: &str) -> String {
json::get_opt_str(val, key).unwrap_or("").to_string()
}
fn parse_tracing_json(line: &str) -> Option<LogEntry> {
let val: serde_json::Value = serde_json::from_str(line).ok()?;
let timestamp = get_str_or_empty(&val, "timestamp");
let level = get_str_or_empty(&val, "level");
let target = get_str_or_empty(&val, "target");
let mut fields = val
.get("fields")
.cloned()
.unwrap_or(serde_json::Value::Null);
let message = get_str_or_empty(&fields, "message");
if let Some(obj) = fields.as_object_mut() {
obj.remove("message");
}
let fields = if fields.as_object().is_some_and(serde_json::Map::is_empty) {
serde_json::Value::Null
} else {
fields
};
let (agent_id, agent_role, workspace) = extract_agent_from_span(&val);
Some(LogEntry {
timestamp,
level,
target,
message,
fields,
agent_id,
agent_role,
workspace,
})
}
fn extract_agent_fields(span: &serde_json::Value) -> (String, String, String) {
(
get_str_or_empty(span, "agent_id"),
get_str_or_empty(span, "role"),
get_str_or_empty(span, "workspace"),
)
}
fn extract_agent_from_span(val: &serde_json::Value) -> (String, String, String) {
let mut agent_id = String::new();
let mut role = String::new();
let mut workspace = String::new();
for candidate in std::iter::once(val.get("fields"))
.chain(std::iter::once(val.get("span")))
.chain(std::iter::once(
val.get("spans")
.and_then(|v| v.as_array())
.and_then(|a| a.last()),
))
.flatten()
{
let (id, r, ws) = extract_agent_fields(candidate);
if agent_id.is_empty() {
agent_id = id;
}
if role.is_empty() {
role = r;
}
if workspace.is_empty() {
workspace = ws;
}
if !agent_id.is_empty() && !role.is_empty() && !workspace.is_empty() {
break;
}
}
(agent_id, role, workspace)
}
#[cfg(test)]
mod tests {
use super::*;
#[test]
fn test_parse_tracing_json_full() {
let line = r#"{"timestamp":"2025-05-06T12:34:56.000000Z","level":"INFO","target":"mahbot::orchestrator","span":{"name":"agent","agent_id":"00000000-0000-0000-0000-000000000000","role":"lead","workspace":"/some/workspace"},"fields":{"message":"Hello world","key":"value"}}"#;
let entry = parse_tracing_json(line).unwrap();
assert_eq!(entry.timestamp, "2025-05-06T12:34:56.000000Z");
assert_eq!(entry.level, "INFO");
assert_eq!(entry.target, "mahbot::orchestrator");
assert_eq!(entry.message, "Hello world");
assert_eq!(entry.fields, serde_json::json!({"key": "value"}));
assert_eq!(entry.agent_id, "00000000-0000-0000-0000-000000000000");
assert_eq!(entry.agent_role, "lead");
assert_eq!(entry.workspace, "/some/workspace");
}
#[test]
fn test_parse_tracing_json_no_fields() {
let line = r#"{"timestamp":"2025-05-06T12:34:56.000000Z","level":"WARN","target":"test","fields":{"message":"warning"}}"#;
let entry = parse_tracing_json(line).unwrap();
assert_eq!(entry.message, "warning");
assert_eq!(entry.fields, serde_json::Value::Null);
assert_eq!(entry.agent_id, "");
assert_eq!(entry.agent_role, "");
assert_eq!(entry.workspace, "");
}
#[test]
fn test_parse_tracing_json_lenient() {
let entry = parse_tracing_json(r#"{"incomplete": true}"#).unwrap();
assert_eq!(entry.timestamp, "");
assert_eq!(entry.level, "");
assert_eq!(entry.target, "");
assert_eq!(entry.message, "");
assert_eq!(entry.fields, serde_json::Value::Null);
assert_eq!(entry.agent_id, "");
assert_eq!(entry.agent_role, "");
assert_eq!(entry.workspace, "");
}
#[test]
fn test_parse_tracing_json_agent_attribution() {
let cases = [
(
"span only",
r#"{"timestamp":"...","level":"INFO","target":"test","span":{"name":"agent","agent_id":"abc-123","role":"analyst"},"fields":{"message":"researching"}}"#,
"abc-123",
"analyst",
"",
),
(
"spans array",
r#"{"timestamp":"...","level":"INFO","target":"test","spans":[{"name":"parent"},{"name":"agent","agent_id":"xyz-456","role":"coder","workspace":"/ws"}],"fields":{"message":"writing code"}}"#,
"xyz-456",
"coder",
"/ws",
),
(
"event fields without span",
r#"{"timestamp":"...","level":"ERROR","target":"mahbot::agent","fields":{"message":"Agent failed","agent_id":"ticket_123_engineer","role":"engineer","workspace":"my-ws","classification":"transport"}}"#,
"ticket_123_engineer",
"engineer",
"my-ws",
),
(
"event beats inherited span",
r#"{"timestamp":"...","level":"ERROR","target":"mahbot::agent","span":{"name":"agent","agent_id":"caller_42","role":"engineer","workspace":"parent-ws"},"fields":{"message":"Agent failed","agent_id":"analyze_ws_1_2_analyst","role":"analyst","workspace":"my-ws","classification":"runtime"}}"#,
"analyze_ws_1_2_analyst",
"analyst",
"my-ws",
),
(
"workspace-only event keeps span agent",
r#"{"timestamp":"...","level":"WARN","target":"mahbot::tools::edit","span":{"name":"agent","agent_id":"ticket_7_engineer","role":"engineer","workspace":"my-ws"},"fields":{"message":"Search index capacity exhausted","workspace":"my-ws","path":"src/a.rs"}}"#,
"ticket_7_engineer",
"engineer",
"my-ws",
),
(
"agent_id-only event merges span role/workspace",
r#"{"timestamp":"...","level":"WARN","target":"mahbot::agent","span":{"name":"agent","agent_id":"ticket_7_engineer","role":"engineer","workspace":"my-ws"},"fields":{"message":"Failed to persist incoming messages to session DB","agent_id":"ticket_7_engineer","error":"io"}}"#,
"ticket_7_engineer",
"engineer",
"my-ws",
),
];
for (name, line, id, role, ws) in cases {
let entry = parse_tracing_json(line).unwrap();
assert_eq!(entry.agent_id, id, "{name}: agent_id");
assert_eq!(entry.agent_role, role, "{name}: agent_role");
assert_eq!(entry.workspace, ws, "{name}: workspace");
}
}
async fn test_store() -> (Arc<LogStore>, tempfile::TempDir) {
let (store, dir) = crate::open_test_store!(LogStore, "log");
(Arc::new(store), dir)
}
async fn seed_entries(store: &LogStore, entries: &[LogEntry]) {
store.insert_batch(entries).await.unwrap();
}
#[tokio::test]
async fn test_spawn_log_writer_writes_to_store() {
let (store, _dir) = test_store().await;
let (tx, rx) = tokio::sync::mpsc::unbounded_channel();
let (broadcast_tx, _) = tokio::sync::broadcast::channel(256);
spawn_log_writer(store.clone(), rx, broadcast_tx);
tx.send(
r#"{"timestamp":"2025-01-01T00:00:00Z","level":"INFO","target":"test","fields":{"message":"hi"}}"#
.to_string(),
)
.unwrap();
tx.send(
r#"{"timestamp":"2025-01-01T00:00:01Z","level":"ERROR","target":"test","fields":{"message":"oh no","err":"boom"}}"#
.to_string(),
)
.unwrap();
tokio::time::sleep(std::time::Duration::from_millis(200)).await;
drop(tx);
tokio::time::sleep(std::time::Duration::from_millis(100)).await;
let (entries, total) = store.query(&LogQuery::default()).await.unwrap();
assert_eq!(total, 2);
assert_eq!(entries.len(), 2);
assert_eq!(entries[0].message, "oh no");
assert_eq!(entries[1].message, "hi");
}
async fn wait_for_total(store: &LogStore, expected: usize, timeout: std::time::Duration) {
let deadline = std::time::Instant::now() + timeout;
loop {
let (_, total) = store.query(&LogQuery::default()).await.unwrap();
if total == expected {
return;
}
assert!(
std::time::Instant::now() < deadline,
"timed out waiting for total == {expected}, got {total}"
);
tokio::time::sleep(std::time::Duration::from_millis(20)).await;
}
}
#[tokio::test]
async fn test_flush_log_batch_records_failure_on_surface() {
let (store, _dir) = test_store().await;
let baseline = log_write_error_info().count;
let entry = LogEntry {
timestamp: "2025-01-01T00:00:00Z".to_string(),
level: "INFO".to_string(),
target: "test".to_string(),
message: "should not persist".to_string(),
fields: serde_json::Value::Null,
agent_id: String::new(),
agent_role: String::new(),
workspace: String::new(),
};
store
.conn
.execute("DROP TABLE logs", ())
.await
.expect("drop logs table for failure test");
let mut batch = vec![entry];
flush_log_batch(&store, &mut batch).await;
assert!(batch.is_empty(), "failed batch must still be cleared");
let info = log_write_error_info();
assert!(
info.count > baseline,
"failure count must advance: baseline {baseline}, now {}",
info.count
);
assert!(
info.last_message.is_some(),
"last-error message must be recorded"
);
}
#[tokio::test]
async fn test_flush_log_batch_retries_then_records() {
let (store, _dir) = test_store().await;
let baseline = log_write_error_info().count;
let mut batch = vec![LogEntry {
timestamp: "2025-01-01T00:00:01Z".to_string(),
level: "INFO".to_string(),
target: "test".to_string(),
message: "persisted".to_string(),
fields: serde_json::Value::Null,
agent_id: String::new(),
agent_role: String::new(),
workspace: String::new(),
}];
flush_log_batch(&store, &mut batch).await;
assert!(batch.is_empty());
assert_eq!(
log_write_error_info().count,
baseline,
"no failure recorded"
);
let (entries, total) = store.query(&LogQuery::default()).await.unwrap();
assert_eq!(total, 1);
assert_eq!(entries[0].message, "persisted");
}
#[tokio::test]
async fn test_log_writer_batches_and_timer_flushes() {
let (store, _dir) = test_store().await;
let (tx, rx) = tokio::sync::mpsc::unbounded_channel();
let (broadcast_tx, _) = tokio::sync::broadcast::channel(256);
spawn_log_writer_with_interval(
store.clone(),
rx,
broadcast_tx,
std::time::Duration::from_mins(1),
);
tx.send(
r#"{"timestamp":"2025-01-01T00:00:02Z","level":"INFO","target":"test","fields":{"message":"timer flush"}}"#
.to_string(),
)
.unwrap();
for i in 0..LOG_BATCH_MAX {
tx.send(
format!(
r#"{{"timestamp":"2025-01-01T00:00:03Z","level":"INFO","target":"test","fields":{{"message":"batch {i}"}}}}"#
),
)
.unwrap();
}
wait_for_total(&store, LOG_BATCH_MAX, std::time::Duration::from_secs(10)).await;
let (store2, _dir2) = test_store().await;
let (tx2, rx2) = tokio::sync::mpsc::unbounded_channel();
let (broadcast_tx2, _) = tokio::sync::broadcast::channel(256);
spawn_log_writer_with_interval(
store2.clone(),
rx2,
broadcast_tx2,
std::time::Duration::from_millis(50),
);
tx2.send(
r#"{"timestamp":"2025-01-01T00:00:04Z","level":"INFO","target":"test","fields":{"message":"timer fired"}}"#
.to_string(),
)
.unwrap();
wait_for_total(&store2, 1, std::time::Duration::from_secs(10)).await;
drop(tx);
drop(tx2);
tokio::time::sleep(std::time::Duration::from_millis(100)).await;
}
#[tokio::test]
async fn test_like_search_substring() {
let (store, _dir) = test_store().await;
let entries = vec![
LogEntry {
timestamp: "2025-01-01T00:00:00Z".into(),
level: "INFO".into(),
target: "module_a".into(),
message: "processing request".into(),
fields: serde_json::Value::Null,
agent_id: String::new(),
agent_role: String::new(),
workspace: String::new(),
},
LogEntry {
timestamp: "2025-01-01T00:00:01Z".into(),
level: "ERROR".into(),
target: "module_b".into(),
message: "failed to process".into(),
fields: serde_json::Value::Null,
agent_id: String::new(),
agent_role: String::new(),
workspace: String::new(),
},
LogEntry {
timestamp: "2025-01-01T00:00:02Z".into(),
level: "INFO".into(),
target: "module_c".into(),
message: "started".into(),
fields: serde_json::Value::Null,
agent_id: String::new(),
agent_role: String::new(),
workspace: String::new(),
},
];
seed_entries(&store, &entries).await;
let (results, total) = store
.query(&LogQuery {
search: Some("proc".into()),
..Default::default()
})
.await
.unwrap();
assert_eq!(total, 2, "substring 'proc' should match both entries");
assert_eq!(results.len(), 2);
let (results, total) = store
.query(&LogQuery {
search: Some("request".into()),
..Default::default()
})
.await
.unwrap();
assert_eq!(total, 1);
assert_eq!(results[0].message, "processing request");
let (_results, total) = store
.query(&LogQuery {
search: Some("module".into()),
..Default::default()
})
.await
.unwrap();
assert_eq!(total, 3, "all targets contain 'module'");
}
#[tokio::test]
async fn test_like_search_combined_filters() {
let (store, _dir) = test_store().await;
let entries = vec![
LogEntry {
timestamp: "2025-01-01T00:00:00Z".into(),
level: "INFO".into(),
target: "mahbot::orchestrator".into(),
message: "processing request".into(),
fields: serde_json::Value::Null,
agent_id: String::new(),
agent_role: String::new(),
workspace: String::new(),
},
LogEntry {
timestamp: "2025-01-01T00:00:01Z".into(),
level: "ERROR".into(),
target: "mahbot::tools".into(),
message: "failed to process".into(),
fields: serde_json::json!({"code": 1}),
agent_id: String::new(),
agent_role: String::new(),
workspace: String::new(),
},
LogEntry {
timestamp: "2025-01-01T00:00:02Z".into(),
level: "INFO".into(),
target: "mahbot::api".into(),
message: "started".into(),
fields: serde_json::Value::Null,
agent_id: String::new(),
agent_role: String::new(),
workspace: String::new(),
},
];
seed_entries(&store, &entries).await;
let (results, total) = store
.query(&LogQuery {
level: Some("ERROR".into()),
search: Some("process".into()),
..Default::default()
})
.await
.unwrap();
assert_eq!(total, 1, "only ERROR log matching 'process'");
assert_eq!(results[0].message, "failed to process");
let (_results, total) = store
.query(&LogQuery {
target: Some("mahbot::tools".into()),
search: Some("process".into()),
..Default::default()
})
.await
.unwrap();
assert_eq!(total, 1, "only tools target entry matching 'process'");
let (_results, total) = store
.query(&LogQuery {
since: Some("2025-01-01T00:00:01Z".into()),
search: Some("process".into()),
..Default::default()
})
.await
.unwrap();
assert_eq!(total, 1, "only entry after timestamp matching 'process'");
}
#[tokio::test]
async fn test_like_search_with_special_chars() {
let (store, _dir) = test_store().await;
let entries = vec![
LogEntry {
timestamp: "2025-01-01T00:00:00Z".into(),
level: "INFO".into(),
target: "module_a".into(),
message: "processing `Hello ${name}` template".into(),
fields: serde_json::Value::Null,
agent_id: String::new(),
agent_role: String::new(),
workspace: String::new(),
},
LogEntry {
timestamp: "2025-01-01T00:00:01Z".into(),
level: "ERROR".into(),
target: "module_b".into(),
message: "normal log entry".into(),
fields: serde_json::Value::Null,
agent_id: String::new(),
agent_role: String::new(),
workspace: String::new(),
},
];
seed_entries(&store, &entries).await;
let (results, total) = store
.query(&LogQuery {
search: Some("template".into()),
..Default::default()
})
.await
.unwrap();
assert_eq!(total, 1, "LIKE should match partial word in message");
assert!(
results[0].message.contains("template"),
"should match the correct entry"
);
let (_results, total) = store
.query(&LogQuery {
search: None,
..Default::default()
})
.await
.unwrap();
assert_eq!(total, 2, "no search filter should return all entries");
}
#[test]
fn test_log_writer_panic_state_machine() {
let mut state = LogWriterPanicState::default();
assert!(!state.writer_stopped);
for i in 1..=LOG_WRITER_MAX_CONSECUTIVE_PANICS {
let _ = state.record_panic();
assert_eq!(state.consecutive_panics, i);
}
assert!(
state.writer_stopped,
"writer must stop after the consecutive-panic bound"
);
state.reset();
assert_eq!(state.consecutive_panics, 0);
assert!(
state.writer_stopped,
"terminal stopped state is sticky across reset"
);
}
#[tokio::test]
async fn test_log_store_open_quarantines_corrupt_store() {
let tmp = tempfile::TempDir::new().expect("temp dir for test");
let root = tmp.path();
{
let store = LogStore::open(root).await.expect("open healthy store");
store
.insert_batch(&[LogEntry {
timestamp: "2025-01-01T00:00:00Z".into(),
level: "INFO".into(),
target: "test".into(),
message: "pre-corruption".into(),
fields: serde_json::Value::Null,
agent_id: String::new(),
agent_role: String::new(),
workspace: String::new(),
}])
.await
.expect("seed entry");
store
.conn
.checkpoint()
.await
.expect("checkpoint so pages land in the main DB file");
}
let db_path = turso::store_db_path(root, "logs");
let bytes = std::fs::read(&db_path).expect("read db file");
assert!(bytes.len() > 8192, "test needs a multi-page db file");
let mut corrupted = bytes.clone();
corrupted[4096..8192].fill(0);
std::fs::write(&db_path, corrupted).expect("corrupt db file");
let store = LogStore::open(root).await.expect("open must not fail");
let (_, total) = store
.query(&LogQuery::default())
.await
.expect("fresh store query");
assert_eq!(total, 0, "fresh store must be empty");
let stats_tables: i64 = store
.conn
.query_row(
"SELECT COUNT(*) FROM sqlite_master \
WHERE type='table' AND name IN ('tool_calls')",
params![],
|row| row.get::<i64>(0),
)
.await
.expect("count consolidated stats tables");
assert_eq!(
stats_tables, 1,
"consolidated stats tables must exist after quarantine recreate"
);
let quarantined: Vec<_> = std::fs::read_dir(root.join("db"))
.expect("read db dir")
.filter_map(std::result::Result::ok)
.map(|e| e.file_name().to_string_lossy().to_string())
.filter(|n| n.contains("quarantine-"))
.collect();
assert!(
!quarantined.is_empty(),
"corrupt artifact family must be quarantined, found: {quarantined:?}"
);
}
#[tokio::test]
async fn test_log_store_open_quarantines_unopenable_store() {
let tmp = tempfile::TempDir::new().expect("temp dir for test");
let root = tmp.path();
{
let store = LogStore::open(root).await.expect("open healthy store");
store
.insert_batch(&[LogEntry {
timestamp: "2025-01-01T00:00:00Z".into(),
level: "INFO".into(),
target: "test".into(),
message: "pre-corruption".into(),
fields: serde_json::Value::Null,
agent_id: String::new(),
agent_role: String::new(),
workspace: String::new(),
}])
.await
.expect("seed entry");
store
.conn
.checkpoint()
.await
.expect("checkpoint so pages land in the main DB file");
}
let db_path = turso::store_db_path(root, "logs");
let mut bytes = std::fs::read(&db_path).expect("read db file");
bytes[16] = 0;
bytes[17] = 0;
std::fs::write(&db_path, bytes).expect("corrupt db file");
let store = LogStore::open(root).await.expect("open must not fail");
let (_, total) = store
.query(&LogQuery::default())
.await
.expect("fresh store query");
assert_eq!(total, 0, "fresh store must be empty");
let quarantined: Vec<_> = std::fs::read_dir(root.join("db"))
.expect("read db dir")
.filter_map(std::result::Result::ok)
.map(|e| e.file_name().to_string_lossy().to_string())
.filter(|n| n.contains("quarantine-"))
.collect();
assert!(
!quarantined.is_empty(),
"unopenable store must be quarantined, found: {quarantined:?}"
);
}
}