2026-04-12 13:11:23 +00:00
|
|
|
//! Agent log persistence — reads and writes JSONL agent event logs to disk.
|
2026-03-22 19:07:07 +00:00
|
|
|
use crate::agents::AgentEvent;
|
|
|
|
|
use chrono::Utc;
|
|
|
|
|
use serde::{Deserialize, Serialize};
|
|
|
|
|
use std::fs::{self, File, OpenOptions};
|
|
|
|
|
use std::io::{BufRead, BufReader, Write};
|
|
|
|
|
use std::path::{Path, PathBuf};
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
/// A single line in the agent log file (JSONL format).
|
|
|
|
|
#[derive(Debug, Serialize, Deserialize)]
|
|
|
|
|
pub struct LogEntry {
|
|
|
|
|
pub timestamp: String,
|
|
|
|
|
#[serde(flatten)]
|
|
|
|
|
pub event: serde_json::Value,
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
/// Writes agent events to a persistent log file (JSONL format).
|
|
|
|
|
///
|
|
|
|
|
/// Each agent session gets its own log file at:
|
2026-04-03 16:12:52 +01:00
|
|
|
/// `.huskies/logs/{story_id}/{agent_name}-{session_id}.log`
|
2026-03-22 19:07:07 +00:00
|
|
|
pub struct AgentLogWriter {
|
|
|
|
|
file: File,
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
impl AgentLogWriter {
|
|
|
|
|
/// Create a new log writer, creating the directory structure as needed.
|
|
|
|
|
///
|
|
|
|
|
/// The log file is opened in append mode so that a restart mid-session
|
|
|
|
|
/// won't overwrite earlier output.
|
|
|
|
|
pub fn new(
|
|
|
|
|
project_root: &Path,
|
|
|
|
|
story_id: &str,
|
|
|
|
|
agent_name: &str,
|
|
|
|
|
session_id: &str,
|
|
|
|
|
) -> Result<Self, String> {
|
|
|
|
|
let dir = log_dir(project_root, story_id);
|
|
|
|
|
fs::create_dir_all(&dir)
|
|
|
|
|
.map_err(|e| format!("Failed to create log directory {}: {e}", dir.display()))?;
|
|
|
|
|
|
|
|
|
|
let path = dir.join(format!("{agent_name}-{session_id}.log"));
|
|
|
|
|
let file = OpenOptions::new()
|
|
|
|
|
.create(true)
|
|
|
|
|
.append(true)
|
|
|
|
|
.open(&path)
|
|
|
|
|
.map_err(|e| format!("Failed to open log file {}: {e}", path.display()))?;
|
|
|
|
|
|
|
|
|
|
Ok(Self { file })
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
/// Write an agent event as a JSONL line with an ISO 8601 timestamp.
|
|
|
|
|
pub fn write_event(&mut self, event: &AgentEvent) -> Result<(), String> {
|
|
|
|
|
let event_value =
|
|
|
|
|
serde_json::to_value(event).map_err(|e| format!("Failed to serialize event: {e}"))?;
|
|
|
|
|
|
|
|
|
|
let entry = LogEntry {
|
|
|
|
|
timestamp: Utc::now().to_rfc3339(),
|
|
|
|
|
event: event_value,
|
|
|
|
|
};
|
|
|
|
|
|
|
|
|
|
let mut line =
|
|
|
|
|
serde_json::to_string(&entry).map_err(|e| format!("Failed to serialize entry: {e}"))?;
|
|
|
|
|
line.push('\n');
|
|
|
|
|
|
|
|
|
|
self.file
|
|
|
|
|
.write_all(line.as_bytes())
|
|
|
|
|
.map_err(|e| format!("Failed to write log entry: {e}"))?;
|
|
|
|
|
|
|
|
|
|
Ok(())
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
/// Return the log directory for a story.
|
|
|
|
|
fn log_dir(project_root: &Path, story_id: &str) -> PathBuf {
|
|
|
|
|
project_root
|
2026-04-03 16:12:52 +01:00
|
|
|
.join(".huskies")
|
2026-03-22 19:07:07 +00:00
|
|
|
.join("logs")
|
|
|
|
|
.join(story_id)
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
/// Return the path to a specific log file.
|
2026-04-10 13:05:04 +00:00
|
|
|
#[allow(dead_code)]
|
2026-03-22 19:07:07 +00:00
|
|
|
pub fn log_file_path(
|
|
|
|
|
project_root: &Path,
|
|
|
|
|
story_id: &str,
|
|
|
|
|
agent_name: &str,
|
|
|
|
|
session_id: &str,
|
|
|
|
|
) -> PathBuf {
|
|
|
|
|
log_dir(project_root, story_id).join(format!("{agent_name}-{session_id}.log"))
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
/// Read all log entries from a log file.
|
|
|
|
|
pub fn read_log(path: &Path) -> Result<Vec<LogEntry>, String> {
|
|
|
|
|
let file =
|
|
|
|
|
File::open(path).map_err(|e| format!("Failed to open log file {}: {e}", path.display()))?;
|
|
|
|
|
let reader = BufReader::new(file);
|
|
|
|
|
let mut entries = Vec::new();
|
|
|
|
|
|
|
|
|
|
for line in reader.lines() {
|
|
|
|
|
let line = line.map_err(|e| format!("Failed to read log line: {e}"))?;
|
|
|
|
|
let trimmed = line.trim();
|
|
|
|
|
if trimmed.is_empty() {
|
|
|
|
|
continue;
|
|
|
|
|
}
|
|
|
|
|
let entry: LogEntry = serde_json::from_str(trimmed)
|
|
|
|
|
.map_err(|e| format!("Failed to parse log entry: {e}"))?;
|
|
|
|
|
entries.push(entry);
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
Ok(entries)
|
|
|
|
|
}
|
|
|
|
|
|
2026-04-10 13:05:04 +00:00
|
|
|
/// List all log files for a story, optionally filtered by agent name prefix.
|
|
|
|
|
///
|
|
|
|
|
/// Returns files sorted by modification time (oldest first) so that when all
|
|
|
|
|
/// sessions are concatenated the timeline reads chronologically.
|
|
|
|
|
pub fn list_story_log_files(
|
|
|
|
|
project_root: &Path,
|
|
|
|
|
story_id: &str,
|
|
|
|
|
agent_name_filter: Option<&str>,
|
|
|
|
|
) -> Vec<PathBuf> {
|
|
|
|
|
let dir = log_dir(project_root, story_id);
|
|
|
|
|
if !dir.is_dir() {
|
|
|
|
|
return Vec::new();
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
let prefix = agent_name_filter.map(|n| format!("{n}-"));
|
|
|
|
|
let mut files: Vec<(PathBuf, std::time::SystemTime)> = Vec::new();
|
|
|
|
|
|
|
|
|
|
if let Ok(entries) = fs::read_dir(&dir) {
|
|
|
|
|
for entry in entries.flatten() {
|
|
|
|
|
let path = entry.path();
|
|
|
|
|
let name = match path.file_name().and_then(|n| n.to_str()) {
|
|
|
|
|
Some(n) => n.to_string(),
|
|
|
|
|
None => continue,
|
|
|
|
|
};
|
|
|
|
|
if !name.ends_with(".log") {
|
|
|
|
|
continue;
|
|
|
|
|
}
|
|
|
|
|
if let Some(ref pfx) = prefix
|
|
|
|
|
&& !name.starts_with(pfx.as_str())
|
|
|
|
|
{
|
|
|
|
|
continue;
|
|
|
|
|
}
|
|
|
|
|
let modified = entry
|
|
|
|
|
.metadata()
|
|
|
|
|
.and_then(|m| m.modified())
|
|
|
|
|
.unwrap_or(std::time::SystemTime::UNIX_EPOCH);
|
|
|
|
|
files.push((path, modified));
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
files.sort_by_key(|(_, t)| *t);
|
|
|
|
|
files.into_iter().map(|(p, _)| p).collect()
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
/// Format a single log entry as a human-readable text line.
|
|
|
|
|
///
|
|
|
|
|
/// `timestamp` is an ISO 8601 string; `event` is the flattened `AgentEvent`
|
|
|
|
|
/// value (has `type`, `agent_name`, etc. at the top level).
|
|
|
|
|
///
|
|
|
|
|
/// Returns `None` for entries that should be skipped (raw streaming noise,
|
|
|
|
|
/// trivial status changes, empty output, etc.).
|
|
|
|
|
pub fn format_log_entry_as_text(timestamp: &str, event: &serde_json::Value) -> Option<String> {
|
|
|
|
|
let agent_name = event
|
|
|
|
|
.get("agent_name")
|
|
|
|
|
.and_then(|v| v.as_str())
|
|
|
|
|
.unwrap_or("?");
|
|
|
|
|
// Extract HH:MM:SS from ISO 8601 "2026-04-10T12:48:02.123456789+00:00"
|
|
|
|
|
let ts_short = if timestamp.len() >= 19 {
|
|
|
|
|
×tamp[11..19]
|
|
|
|
|
} else {
|
|
|
|
|
timestamp
|
|
|
|
|
};
|
|
|
|
|
let pfx = format!("[{ts_short}][{agent_name}]");
|
|
|
|
|
|
|
|
|
|
match event.get("type").and_then(|v| v.as_str()) {
|
|
|
|
|
Some("output") => {
|
|
|
|
|
let text = event
|
|
|
|
|
.get("text")
|
|
|
|
|
.and_then(|v| v.as_str())
|
|
|
|
|
.unwrap_or("")
|
|
|
|
|
.trim();
|
|
|
|
|
if text.is_empty() {
|
|
|
|
|
None
|
|
|
|
|
} else {
|
|
|
|
|
Some(format!("{pfx} {text}"))
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
Some("error") => {
|
|
|
|
|
let msg = event
|
|
|
|
|
.get("message")
|
|
|
|
|
.and_then(|v| v.as_str())
|
|
|
|
|
.unwrap_or("(unknown error)");
|
|
|
|
|
Some(format!("{pfx} ERROR: {msg}"))
|
|
|
|
|
}
|
|
|
|
|
Some("done") => Some(format!("{pfx} DONE")),
|
|
|
|
|
Some("status") => {
|
|
|
|
|
// Skip trivial running/started noise
|
|
|
|
|
let status = event
|
|
|
|
|
.get("status")
|
|
|
|
|
.and_then(|v| v.as_str())
|
|
|
|
|
.unwrap_or("?");
|
|
|
|
|
match status {
|
|
|
|
|
"running" | "started" => None,
|
|
|
|
|
_ => Some(format!("{pfx} STATUS: {status}")),
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
Some("agent_json") => {
|
|
|
|
|
let data = event.get("data")?;
|
|
|
|
|
match data.get("type").and_then(|v| v.as_str()) {
|
|
|
|
|
Some("assistant") => {
|
|
|
|
|
let mut parts: Vec<String> = Vec::new();
|
|
|
|
|
if let Some(arr) = data
|
|
|
|
|
.pointer("/message/content")
|
|
|
|
|
.and_then(|v| v.as_array())
|
|
|
|
|
{
|
|
|
|
|
for item in arr {
|
|
|
|
|
match item.get("type").and_then(|v| v.as_str()) {
|
|
|
|
|
Some("text") => {
|
|
|
|
|
let text = item
|
|
|
|
|
.get("text")
|
|
|
|
|
.and_then(|v| v.as_str())
|
|
|
|
|
.unwrap_or("")
|
|
|
|
|
.trim();
|
|
|
|
|
if !text.is_empty() {
|
|
|
|
|
parts.push(format!("{pfx} {text}"));
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
Some("tool_use") => {
|
|
|
|
|
let name = item
|
|
|
|
|
.get("name")
|
|
|
|
|
.and_then(|v| v.as_str())
|
|
|
|
|
.unwrap_or("?");
|
|
|
|
|
let input = item
|
|
|
|
|
.get("input")
|
|
|
|
|
.map(|v| {
|
|
|
|
|
serde_json::to_string(v).unwrap_or_default()
|
|
|
|
|
})
|
|
|
|
|
.unwrap_or_default();
|
|
|
|
|
let display = if input.len() > 200 {
|
|
|
|
|
format!("{}...", &input[..200])
|
|
|
|
|
} else {
|
|
|
|
|
input
|
|
|
|
|
};
|
|
|
|
|
parts.push(format!("{pfx} TOOL: {name}({display})"));
|
|
|
|
|
}
|
|
|
|
|
_ => {}
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
if parts.is_empty() {
|
|
|
|
|
None
|
|
|
|
|
} else {
|
|
|
|
|
Some(parts.join("\n"))
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
Some("user") => {
|
|
|
|
|
let mut parts: Vec<String> = Vec::new();
|
|
|
|
|
if let Some(arr) = data
|
|
|
|
|
.pointer("/message/content")
|
|
|
|
|
.and_then(|v| v.as_array())
|
|
|
|
|
{
|
|
|
|
|
for item in arr {
|
|
|
|
|
if item.get("type").and_then(|v| v.as_str())
|
|
|
|
|
!= Some("tool_result")
|
|
|
|
|
{
|
|
|
|
|
continue;
|
|
|
|
|
}
|
|
|
|
|
let content_str = match item.get("content") {
|
|
|
|
|
Some(serde_json::Value::String(s)) => s.clone(),
|
|
|
|
|
Some(v) => v.to_string(),
|
|
|
|
|
None => String::new(),
|
|
|
|
|
};
|
|
|
|
|
let display = if content_str.len() > 500 {
|
|
|
|
|
format!(
|
|
|
|
|
"{}... [{} chars total]",
|
|
|
|
|
&content_str[..500],
|
|
|
|
|
content_str.len()
|
|
|
|
|
)
|
|
|
|
|
} else {
|
|
|
|
|
content_str
|
|
|
|
|
};
|
|
|
|
|
if !display.trim().is_empty() {
|
|
|
|
|
parts.push(format!("{pfx} RESULT: {display}"));
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
if parts.is_empty() {
|
|
|
|
|
None
|
|
|
|
|
} else {
|
|
|
|
|
Some(parts.join("\n"))
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
_ => None, // Skip stream_event, system init, etc.
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
_ => None,
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
/// Read log entries from a file and convert them to human-readable text lines,
|
|
|
|
|
/// stripping raw streaming noise and JSON internals.
|
|
|
|
|
pub fn read_log_as_readable_lines(path: &Path) -> Result<Vec<String>, String> {
|
|
|
|
|
let entries = read_log(path)?;
|
|
|
|
|
let mut result = Vec::new();
|
|
|
|
|
for entry in &entries {
|
|
|
|
|
if let Some(line) = format_log_entry_as_text(&entry.timestamp, &entry.event) {
|
|
|
|
|
result.push(line);
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
Ok(result)
|
|
|
|
|
}
|
|
|
|
|
|
2026-03-22 19:07:07 +00:00
|
|
|
/// Find the most recent log file for a given story+agent combination.
|
|
|
|
|
///
|
2026-04-03 16:12:52 +01:00
|
|
|
/// Scans `.huskies/logs/{story_id}/` for files matching `{agent_name}-*.log`
|
2026-03-22 19:07:07 +00:00
|
|
|
/// and returns the one with the most recent modification time.
|
|
|
|
|
pub fn find_latest_log(
|
|
|
|
|
project_root: &Path,
|
|
|
|
|
story_id: &str,
|
|
|
|
|
agent_name: &str,
|
|
|
|
|
) -> Option<PathBuf> {
|
|
|
|
|
let dir = log_dir(project_root, story_id);
|
|
|
|
|
if !dir.is_dir() {
|
|
|
|
|
return None;
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
let prefix = format!("{agent_name}-");
|
|
|
|
|
let mut best: Option<(PathBuf, std::time::SystemTime)> = None;
|
|
|
|
|
|
|
|
|
|
let entries = fs::read_dir(&dir).ok()?;
|
|
|
|
|
for entry in entries.flatten() {
|
|
|
|
|
let path = entry.path();
|
|
|
|
|
let name = match path.file_name().and_then(|n| n.to_str()) {
|
|
|
|
|
Some(n) => n.to_string(),
|
|
|
|
|
None => continue,
|
|
|
|
|
};
|
|
|
|
|
if !name.starts_with(&prefix) || !name.ends_with(".log") {
|
|
|
|
|
continue;
|
|
|
|
|
}
|
|
|
|
|
let modified = match entry.metadata().and_then(|m| m.modified()) {
|
|
|
|
|
Ok(t) => t,
|
|
|
|
|
Err(_) => continue,
|
|
|
|
|
};
|
|
|
|
|
if best.as_ref().is_none_or(|(_, t)| modified > *t) {
|
|
|
|
|
best = Some((path, modified));
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
best.map(|(p, _)| p)
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[cfg(test)]
|
|
|
|
|
mod tests {
|
|
|
|
|
use super::*;
|
|
|
|
|
use crate::agents::AgentEvent;
|
|
|
|
|
use tempfile::tempdir;
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_log_writer_creates_directory_and_file() {
|
|
|
|
|
let tmp = tempdir().unwrap();
|
|
|
|
|
let root = tmp.path();
|
|
|
|
|
|
|
|
|
|
let _writer =
|
|
|
|
|
AgentLogWriter::new(root, "42_story_foo", "coder-1", "sess-abc123").unwrap();
|
|
|
|
|
|
|
|
|
|
let expected_path = root
|
2026-04-03 16:12:52 +01:00
|
|
|
.join(".huskies")
|
2026-03-22 19:07:07 +00:00
|
|
|
.join("logs")
|
|
|
|
|
.join("42_story_foo")
|
|
|
|
|
.join("coder-1-sess-abc123.log");
|
|
|
|
|
assert!(expected_path.exists(), "Log file should exist");
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_log_writer_writes_jsonl_with_timestamps() {
|
|
|
|
|
let tmp = tempdir().unwrap();
|
|
|
|
|
let root = tmp.path();
|
|
|
|
|
|
|
|
|
|
let mut writer =
|
|
|
|
|
AgentLogWriter::new(root, "42_story_foo", "coder-1", "sess-001").unwrap();
|
|
|
|
|
|
|
|
|
|
let event = AgentEvent::Status {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "coder-1".to_string(),
|
|
|
|
|
status: "running".to_string(),
|
|
|
|
|
};
|
|
|
|
|
writer.write_event(&event).unwrap();
|
|
|
|
|
|
|
|
|
|
let event2 = AgentEvent::Output {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "coder-1".to_string(),
|
|
|
|
|
text: "Hello world".to_string(),
|
|
|
|
|
};
|
|
|
|
|
writer.write_event(&event2).unwrap();
|
|
|
|
|
|
|
|
|
|
// Read the file and verify
|
|
|
|
|
let path = log_file_path(root, "42_story_foo", "coder-1", "sess-001");
|
|
|
|
|
let content = fs::read_to_string(&path).unwrap();
|
|
|
|
|
let lines: Vec<&str> = content.lines().collect();
|
|
|
|
|
assert_eq!(lines.len(), 2, "Should have 2 log lines");
|
|
|
|
|
|
|
|
|
|
// Parse each line as valid JSON with a timestamp
|
|
|
|
|
for line in &lines {
|
|
|
|
|
let entry: LogEntry = serde_json::from_str(line).unwrap();
|
|
|
|
|
assert!(!entry.timestamp.is_empty(), "Timestamp should be present");
|
|
|
|
|
// Verify it's a valid ISO 8601 timestamp
|
|
|
|
|
chrono::DateTime::parse_from_rfc3339(&entry.timestamp)
|
|
|
|
|
.expect("Timestamp should be valid RFC3339");
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
// Verify the first entry is a status event
|
|
|
|
|
let entry1: LogEntry = serde_json::from_str(lines[0]).unwrap();
|
|
|
|
|
assert_eq!(entry1.event["type"], "status");
|
|
|
|
|
assert_eq!(entry1.event["status"], "running");
|
|
|
|
|
|
|
|
|
|
// Verify the second entry is an output event
|
|
|
|
|
let entry2: LogEntry = serde_json::from_str(lines[1]).unwrap();
|
|
|
|
|
assert_eq!(entry2.event["type"], "output");
|
|
|
|
|
assert_eq!(entry2.event["text"], "Hello world");
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_read_log_parses_written_events() {
|
|
|
|
|
let tmp = tempdir().unwrap();
|
|
|
|
|
let root = tmp.path();
|
|
|
|
|
|
|
|
|
|
let mut writer =
|
|
|
|
|
AgentLogWriter::new(root, "42_story_foo", "coder-1", "sess-002").unwrap();
|
|
|
|
|
|
|
|
|
|
let events = vec![
|
|
|
|
|
AgentEvent::Status {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "coder-1".to_string(),
|
|
|
|
|
status: "running".to_string(),
|
|
|
|
|
},
|
|
|
|
|
AgentEvent::Output {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "coder-1".to_string(),
|
|
|
|
|
text: "Processing...".to_string(),
|
|
|
|
|
},
|
|
|
|
|
AgentEvent::AgentJson {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "coder-1".to_string(),
|
|
|
|
|
data: serde_json::json!({"type": "tool_use", "name": "read_file"}),
|
|
|
|
|
},
|
|
|
|
|
AgentEvent::Done {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "coder-1".to_string(),
|
|
|
|
|
session_id: Some("sess-002".to_string()),
|
|
|
|
|
},
|
|
|
|
|
];
|
|
|
|
|
|
|
|
|
|
for event in &events {
|
|
|
|
|
writer.write_event(event).unwrap();
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
let path = log_file_path(root, "42_story_foo", "coder-1", "sess-002");
|
|
|
|
|
let entries = read_log(&path).unwrap();
|
|
|
|
|
assert_eq!(entries.len(), 4, "Should read back all 4 events");
|
|
|
|
|
|
|
|
|
|
// Verify event types round-trip correctly
|
|
|
|
|
assert_eq!(entries[0].event["type"], "status");
|
|
|
|
|
assert_eq!(entries[1].event["type"], "output");
|
|
|
|
|
assert_eq!(entries[2].event["type"], "agent_json");
|
|
|
|
|
assert_eq!(entries[3].event["type"], "done");
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_separate_sessions_produce_separate_files() {
|
|
|
|
|
let tmp = tempdir().unwrap();
|
|
|
|
|
let root = tmp.path();
|
|
|
|
|
|
|
|
|
|
let mut writer1 =
|
|
|
|
|
AgentLogWriter::new(root, "42_story_foo", "coder-1", "sess-aaa").unwrap();
|
|
|
|
|
let mut writer2 =
|
|
|
|
|
AgentLogWriter::new(root, "42_story_foo", "coder-1", "sess-bbb").unwrap();
|
|
|
|
|
|
|
|
|
|
writer1
|
|
|
|
|
.write_event(&AgentEvent::Output {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "coder-1".to_string(),
|
|
|
|
|
text: "from session aaa".to_string(),
|
|
|
|
|
})
|
|
|
|
|
.unwrap();
|
|
|
|
|
|
|
|
|
|
writer2
|
|
|
|
|
.write_event(&AgentEvent::Output {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "coder-1".to_string(),
|
|
|
|
|
text: "from session bbb".to_string(),
|
|
|
|
|
})
|
|
|
|
|
.unwrap();
|
|
|
|
|
|
|
|
|
|
let path1 = log_file_path(root, "42_story_foo", "coder-1", "sess-aaa");
|
|
|
|
|
let path2 = log_file_path(root, "42_story_foo", "coder-1", "sess-bbb");
|
|
|
|
|
|
|
|
|
|
assert_ne!(path1, path2, "Different sessions should use different files");
|
|
|
|
|
|
|
|
|
|
let entries1 = read_log(&path1).unwrap();
|
|
|
|
|
let entries2 = read_log(&path2).unwrap();
|
|
|
|
|
|
|
|
|
|
assert_eq!(entries1.len(), 1);
|
|
|
|
|
assert_eq!(entries2.len(), 1);
|
|
|
|
|
assert_eq!(entries1[0].event["text"], "from session aaa");
|
|
|
|
|
assert_eq!(entries2[0].event["text"], "from session bbb");
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_find_latest_log_returns_most_recent() {
|
|
|
|
|
let tmp = tempdir().unwrap();
|
|
|
|
|
let root = tmp.path();
|
|
|
|
|
|
|
|
|
|
// Create two log files with a small delay
|
|
|
|
|
let mut writer1 =
|
|
|
|
|
AgentLogWriter::new(root, "42_story_foo", "coder-1", "sess-old").unwrap();
|
|
|
|
|
writer1
|
|
|
|
|
.write_event(&AgentEvent::Output {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "coder-1".to_string(),
|
|
|
|
|
text: "old".to_string(),
|
|
|
|
|
})
|
|
|
|
|
.unwrap();
|
|
|
|
|
drop(writer1);
|
|
|
|
|
|
|
|
|
|
// Touch the second file to ensure it's newer
|
|
|
|
|
std::thread::sleep(std::time::Duration::from_millis(50));
|
|
|
|
|
|
|
|
|
|
let mut writer2 =
|
|
|
|
|
AgentLogWriter::new(root, "42_story_foo", "coder-1", "sess-new").unwrap();
|
|
|
|
|
writer2
|
|
|
|
|
.write_event(&AgentEvent::Output {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "coder-1".to_string(),
|
|
|
|
|
text: "new".to_string(),
|
|
|
|
|
})
|
|
|
|
|
.unwrap();
|
|
|
|
|
drop(writer2);
|
|
|
|
|
|
|
|
|
|
let latest = find_latest_log(root, "42_story_foo", "coder-1").unwrap();
|
|
|
|
|
assert!(
|
|
|
|
|
latest.to_string_lossy().contains("sess-new"),
|
|
|
|
|
"Should find the newest log file, got: {}",
|
|
|
|
|
latest.display()
|
|
|
|
|
);
|
|
|
|
|
}
|
|
|
|
|
|
2026-04-10 13:05:04 +00:00
|
|
|
#[test]
|
|
|
|
|
fn test_list_story_log_files_returns_empty_for_missing_dir() {
|
|
|
|
|
let tmp = tempdir().unwrap();
|
|
|
|
|
let files = list_story_log_files(tmp.path(), "nonexistent", None);
|
|
|
|
|
assert!(files.is_empty());
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_list_story_log_files_no_filter_returns_all_logs() {
|
|
|
|
|
let tmp = tempdir().unwrap();
|
|
|
|
|
let root = tmp.path();
|
|
|
|
|
|
|
|
|
|
let mut w1 = AgentLogWriter::new(root, "42_story_foo", "coder-1", "sess-aaa").unwrap();
|
|
|
|
|
w1.write_event(&AgentEvent::Output {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "coder-1".to_string(),
|
|
|
|
|
text: "from coder-1".to_string(),
|
|
|
|
|
})
|
|
|
|
|
.unwrap();
|
|
|
|
|
drop(w1);
|
|
|
|
|
std::thread::sleep(std::time::Duration::from_millis(10));
|
|
|
|
|
|
|
|
|
|
let mut w2 =
|
|
|
|
|
AgentLogWriter::new(root, "42_story_foo", "mergemaster", "sess-bbb").unwrap();
|
|
|
|
|
w2.write_event(&AgentEvent::Output {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "mergemaster".to_string(),
|
|
|
|
|
text: "from mergemaster".to_string(),
|
|
|
|
|
})
|
|
|
|
|
.unwrap();
|
|
|
|
|
drop(w2);
|
|
|
|
|
|
|
|
|
|
let files = list_story_log_files(root, "42_story_foo", None);
|
|
|
|
|
assert_eq!(files.len(), 2, "Should find both log files");
|
|
|
|
|
// Oldest first
|
|
|
|
|
assert!(
|
|
|
|
|
files[0].to_string_lossy().contains("coder-1"),
|
|
|
|
|
"coder-1 should be first (older)"
|
|
|
|
|
);
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_list_story_log_files_with_agent_filter() {
|
|
|
|
|
let tmp = tempdir().unwrap();
|
|
|
|
|
let root = tmp.path();
|
|
|
|
|
|
|
|
|
|
let mut w1 = AgentLogWriter::new(root, "42_story_foo", "coder-1", "sess-a").unwrap();
|
|
|
|
|
w1.write_event(&AgentEvent::Output {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "coder-1".to_string(),
|
|
|
|
|
text: "from coder-1".to_string(),
|
|
|
|
|
})
|
|
|
|
|
.unwrap();
|
|
|
|
|
drop(w1);
|
|
|
|
|
|
|
|
|
|
let mut w2 =
|
|
|
|
|
AgentLogWriter::new(root, "42_story_foo", "mergemaster", "sess-b").unwrap();
|
|
|
|
|
w2.write_event(&AgentEvent::Output {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "mergemaster".to_string(),
|
|
|
|
|
text: "from mergemaster".to_string(),
|
|
|
|
|
})
|
|
|
|
|
.unwrap();
|
|
|
|
|
drop(w2);
|
|
|
|
|
|
|
|
|
|
let files = list_story_log_files(root, "42_story_foo", Some("coder-1"));
|
|
|
|
|
assert_eq!(files.len(), 1, "Should find only coder-1 log");
|
|
|
|
|
assert!(files[0].to_string_lossy().contains("coder-1"));
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_format_log_entry_output_event() {
|
|
|
|
|
let ts = "2026-04-10T12:48:02.123456789+00:00";
|
|
|
|
|
let event = serde_json::json!({
|
|
|
|
|
"type": "output",
|
|
|
|
|
"story_id": "42_story",
|
|
|
|
|
"agent_name": "coder-1",
|
|
|
|
|
"text": "Hello world"
|
|
|
|
|
});
|
|
|
|
|
let result = format_log_entry_as_text(ts, &event).unwrap();
|
|
|
|
|
assert!(result.contains("12:48:02"), "should include timestamp");
|
|
|
|
|
assert!(result.contains("coder-1"), "should include agent name");
|
|
|
|
|
assert!(result.contains("Hello world"), "should include text");
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_format_log_entry_skips_empty_output() {
|
|
|
|
|
let ts = "2026-04-10T12:48:02.123456789+00:00";
|
|
|
|
|
let event = serde_json::json!({
|
|
|
|
|
"type": "output",
|
|
|
|
|
"story_id": "42_story",
|
|
|
|
|
"agent_name": "coder-1",
|
|
|
|
|
"text": " "
|
|
|
|
|
});
|
|
|
|
|
assert!(format_log_entry_as_text(ts, &event).is_none());
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_format_log_entry_error_event() {
|
|
|
|
|
let ts = "2026-04-10T12:48:02.123+00:00";
|
|
|
|
|
let event = serde_json::json!({
|
|
|
|
|
"type": "error",
|
|
|
|
|
"story_id": "42_story",
|
|
|
|
|
"agent_name": "coder-1",
|
|
|
|
|
"message": "Something went wrong"
|
|
|
|
|
});
|
|
|
|
|
let result = format_log_entry_as_text(ts, &event).unwrap();
|
|
|
|
|
assert!(result.contains("ERROR"));
|
|
|
|
|
assert!(result.contains("Something went wrong"));
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_format_log_entry_done_event() {
|
|
|
|
|
let ts = "2026-04-10T12:48:02.123+00:00";
|
|
|
|
|
let event = serde_json::json!({
|
|
|
|
|
"type": "done",
|
|
|
|
|
"story_id": "42_story",
|
|
|
|
|
"agent_name": "coder-1",
|
|
|
|
|
"session_id": null
|
|
|
|
|
});
|
|
|
|
|
let result = format_log_entry_as_text(ts, &event).unwrap();
|
|
|
|
|
assert!(result.contains("DONE"));
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_format_log_entry_skips_running_status() {
|
|
|
|
|
let ts = "2026-04-10T12:48:02.123+00:00";
|
|
|
|
|
let event = serde_json::json!({
|
|
|
|
|
"type": "status",
|
|
|
|
|
"story_id": "42_story",
|
|
|
|
|
"agent_name": "coder-1",
|
|
|
|
|
"status": "running"
|
|
|
|
|
});
|
|
|
|
|
assert!(format_log_entry_as_text(ts, &event).is_none());
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_format_log_entry_agent_json_tool_use() {
|
|
|
|
|
let ts = "2026-04-10T12:48:03.000+00:00";
|
|
|
|
|
let event = serde_json::json!({
|
|
|
|
|
"type": "agent_json",
|
|
|
|
|
"story_id": "42_story",
|
|
|
|
|
"agent_name": "coder-1",
|
|
|
|
|
"data": {
|
|
|
|
|
"type": "assistant",
|
|
|
|
|
"message": {
|
|
|
|
|
"content": [
|
|
|
|
|
{
|
|
|
|
|
"type": "tool_use",
|
|
|
|
|
"id": "tool-1",
|
|
|
|
|
"name": "Read",
|
|
|
|
|
"input": {"file_path": "/some/file.rs"}
|
|
|
|
|
}
|
|
|
|
|
]
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
});
|
|
|
|
|
let result = format_log_entry_as_text(ts, &event).unwrap();
|
|
|
|
|
assert!(result.contains("TOOL: Read"), "should show tool call: {result}");
|
|
|
|
|
assert!(result.contains("file_path"), "should show input: {result}");
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_format_log_entry_agent_json_text() {
|
|
|
|
|
let ts = "2026-04-10T12:48:04.000+00:00";
|
|
|
|
|
let event = serde_json::json!({
|
|
|
|
|
"type": "agent_json",
|
|
|
|
|
"story_id": "42_story",
|
|
|
|
|
"agent_name": "coder-1",
|
|
|
|
|
"data": {
|
|
|
|
|
"type": "assistant",
|
|
|
|
|
"message": {
|
|
|
|
|
"content": [
|
|
|
|
|
{
|
|
|
|
|
"type": "text",
|
|
|
|
|
"text": "Now I will read the file."
|
|
|
|
|
}
|
|
|
|
|
]
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
});
|
|
|
|
|
let result = format_log_entry_as_text(ts, &event).unwrap();
|
|
|
|
|
assert!(result.contains("Now I will read the file."), "should show text: {result}");
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_format_log_entry_skips_stream_events() {
|
|
|
|
|
let ts = "2026-04-10T12:48:04.000+00:00";
|
|
|
|
|
let event = serde_json::json!({
|
|
|
|
|
"type": "agent_json",
|
|
|
|
|
"story_id": "42_story",
|
|
|
|
|
"agent_name": "coder-1",
|
|
|
|
|
"data": {
|
|
|
|
|
"type": "stream_event",
|
|
|
|
|
"event": {"type": "content_block_delta", "delta": {"type": "text_delta", "text": "chunk"}}
|
|
|
|
|
}
|
|
|
|
|
});
|
|
|
|
|
assert!(format_log_entry_as_text(ts, &event).is_none(), "stream events should be skipped");
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_read_log_as_readable_lines_produces_formatted_output() {
|
|
|
|
|
let tmp = tempdir().unwrap();
|
|
|
|
|
let root = tmp.path();
|
|
|
|
|
|
|
|
|
|
let mut writer =
|
|
|
|
|
AgentLogWriter::new(root, "42_story_foo", "coder-1", "sess-readable").unwrap();
|
|
|
|
|
writer
|
|
|
|
|
.write_event(&AgentEvent::Output {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "coder-1".to_string(),
|
|
|
|
|
text: "Let me read the file".to_string(),
|
|
|
|
|
})
|
|
|
|
|
.unwrap();
|
|
|
|
|
writer
|
|
|
|
|
.write_event(&AgentEvent::Done {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "coder-1".to_string(),
|
|
|
|
|
session_id: Some("sess-readable".to_string()),
|
|
|
|
|
})
|
|
|
|
|
.unwrap();
|
|
|
|
|
|
|
|
|
|
let path = log_file_path(root, "42_story_foo", "coder-1", "sess-readable");
|
|
|
|
|
let lines = read_log_as_readable_lines(&path).unwrap();
|
|
|
|
|
assert_eq!(lines.len(), 2, "Should produce 2 readable lines");
|
|
|
|
|
assert!(lines[0].contains("Let me read the file"), "first line: {}", lines[0]);
|
|
|
|
|
assert!(lines[1].contains("DONE"), "second line: {}", lines[1]);
|
|
|
|
|
}
|
|
|
|
|
|
2026-03-22 19:07:07 +00:00
|
|
|
#[test]
|
|
|
|
|
fn test_find_latest_log_returns_none_for_missing_dir() {
|
|
|
|
|
let tmp = tempdir().unwrap();
|
|
|
|
|
let result = find_latest_log(tmp.path(), "nonexistent", "coder-1");
|
|
|
|
|
assert!(result.is_none());
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
|
fn test_log_files_persist_on_disk() {
|
|
|
|
|
let tmp = tempdir().unwrap();
|
|
|
|
|
let root = tmp.path();
|
|
|
|
|
|
|
|
|
|
let path = {
|
|
|
|
|
let mut writer =
|
|
|
|
|
AgentLogWriter::new(root, "42_story_foo", "coder-1", "sess-persist").unwrap();
|
|
|
|
|
writer
|
|
|
|
|
.write_event(&AgentEvent::Status {
|
|
|
|
|
story_id: "42_story_foo".to_string(),
|
|
|
|
|
agent_name: "coder-1".to_string(),
|
|
|
|
|
status: "running".to_string(),
|
|
|
|
|
})
|
|
|
|
|
.unwrap();
|
|
|
|
|
log_file_path(root, "42_story_foo", "coder-1", "sess-persist")
|
|
|
|
|
// writer is dropped here
|
|
|
|
|
};
|
|
|
|
|
|
|
|
|
|
// File should still exist and be readable
|
|
|
|
|
assert!(path.exists(), "Log file should persist after writer is dropped");
|
|
|
|
|
let entries = read_log(&path).unwrap();
|
|
|
|
|
assert_eq!(entries.len(), 1);
|
|
|
|
|
assert_eq!(entries[0].event["type"], "status");
|
|
|
|
|
}
|
|
|
|
|
}
|