diff --git a/README.md b/README.md index ae1e299e..65e8f7af 100644 --- a/README.md +++ b/README.md @@ -684,7 +684,7 @@ All tracedecay users contribute to an anonymous aggregate counter. `tracedecay s ## Index Freshness -tracedecay keeps the graph up to date without a background daemon or an OS-level file watcher. +tracedecay keeps the graph up to date without an OS-level file watcher. The optional MCP daemon reuses server state across clients; it does not watch files in the background. **On-demand staleness check.** Every MCP tool call checks whether any indexed files have been modified since the last sync. If stale files are found, they are re-extracted before the tool response is returned. A 30-second cooldown prevents back-to-back calls from re-walking the tree on every keystroke. @@ -699,13 +699,23 @@ cp scripts/post-commit .git/hooks/post-commit chmod +x .git/hooks/post-commit ``` +### Daemon Debugging + +The daemon is a long-running MCP server for clients that share one local socket. Its logs go to stderr; when installed as a Linux user service, systemd captures them in journald. + +```bash +tracedecay daemon install-service # install/start Linux systemd user service +tracedecay daemon status # service path, socket state, log command +systemctl --user status tracedecay.service --no-pager +journalctl --user -u tracedecay.service -f +tracedecay status --runtime --json # process + DB/WAL/SHM telemetry snapshot +``` + +Scheduler logs use stable `event=... key=value` fields such as `event=scheduler_tick`, `event=scheduler_task`, `task=memory_curator`, `outcome=skipped`, and `reason=not_configured`, so they can be filtered directly from journald. + ### Upgrading from 5.x -The standalone daemon command from 5.x-era installs and its -launchd/systemd/Windows Service autostart were removed in 6.0.0. The embedded -OS-level file watcher that replaced the daemon was itself removed in 6.1.0 (it -caused runaway CPU and memory on large monorepos with deep `node_modules` or -`target` trees). The on-demand staleness model above is the current design. +The old cross-platform watcher/autostart daemon from 5.x-era installs was removed in 6.0.0. The embedded OS-level file watcher that replaced it was itself removed in 6.1.0 (it caused runaway CPU and memory on large monorepos with deep `node_modules` or `target` trees). The current daemon is MCP transport/process reuse, not file watching; the on-demand staleness model above is still the freshness design. --- @@ -732,6 +742,7 @@ tracedecay sync --doctor [path] # Sync and list added/modified/removed files tracedecay status [path] # Show statistics + cost summary tracedecay status [path] --json # Show statistics (JSON output) tracedecay status --details # Include node-kind breakdown +tracedecay status --runtime # Capture process + DB/WAL/SHM telemetry tracedecay dashboard # Start local web dashboard (default port 7341) tracedecay dashboard --port 8080 # Start dashboard on custom port tracedecay dashboard --port 0 # Auto-select a free port @@ -748,7 +759,10 @@ tracedecay reinstall # Refresh settings for all installed agents tracedecay update-plugin # Refresh generated plugin code/assets only; never writes agent configs tracedecay uninstall [--agent NAME] [--profile NAME] # Remove agent integration tracedecay serve # Start MCP server +tracedecay daemon status # Show daemon service/socket/log hints +tracedecay daemon install-service # Install/start Linux systemd user service tracedecay monitor # Live TUI showing MCP calls across all projects +tracedecay update # Refresh binary, generated plugins, and daemon tracedecay upgrade # Self-update to latest version tracedecay channel [stable|beta] # Show or switch update channel tracedecay doctor [--agent NAME] # Check installation health @@ -1013,6 +1027,7 @@ Large projects take longer on the first full index. | `TRACEDECAY_BIN` | Path to the tracedecay binary (used by Hermes wrapper for spawn mode). | | `TRACEDECAY_DASHBOARD_PROJECT` | Project root path for Hermes dashboard spawn mode (defaults to Hermes' cwd). | | `TRACEDECAY_DASHBOARD_URL` | Full URL to an already-running dashboard (Hermes external URL mode). | +| `TRACEDECAY_DAEMON_SOCKET` | Override the Unix socket used by MCP daemon clients. | | `HERMES_HOME` | Path to Hermes profile directory for profile-scoped plugin installation. | | `TRACEDECAY_OFFLINE` | Set to `1` to skip network requests for pricing data (Savings & Cost tab uses bundled fallback). | | `DISABLE_TRACEDECAY` | Set to `true` to disable the MCP server entirely (exits cleanly without initializing). | diff --git a/docs/dashboard.md b/docs/dashboard.md index db99649a..9fedeba5 100644 --- a/docs/dashboard.md +++ b/docs/dashboard.md @@ -529,6 +529,20 @@ Returns feature flags and server configuration. Used by the UI and wrappers to d - `features.llm_curation`: Whether TraceDecay can run LLM-backed curation through standalone automation. Delegated hosts keep planning host-owned and submit ops through `POST /curate/apply`. - `automation.mode`: `"disabled"`, `"standalone_backend"`, or `"delegated_host"`; `delegated_host` is provider-neutral and may be used by Hermes, Codex app-server orchestration, Claude Code CLI, Cursor Agent CLI, or another host that owns the intelligence layer. +### Automation Scheduler Debugging + +The dashboard scheduler panel reads `GET /api/automation/scheduler/status` and can pause or resume the scheduler with `/pause` and `/resume`. The status response includes the effective automation config, control file path, tick cadence, and per-task due/skip reasons. + +When the daemon runs the scheduler, its stderr/journald logs use stable `event=... key=value` fields: + +```bash +tracedecay daemon status +journalctl --user -u tracedecay.service -f +journalctl --user -u tracedecay.service --since "1 hour ago" | grep 'event=scheduler' +``` + +Useful events include `event=scheduler_tick`, `event=scheduler_sleep`, `event=scheduler_task`, and `event=scheduler_task_error`. + --- ### Holographic Memory API @@ -1333,6 +1347,22 @@ export TRACEDECAY_GLOBAL_DB=/path/to/sessions.db tracedecay dashboard ``` +### Automation Scheduler Not Running + +```bash +# Check effective automation config and backend availability +tracedecay automation config explain --json + +# Check run history for memory_curator/session_reflector/skill_writer +tracedecay automation runs list --json + +# Check daemon socket/service/log path +tracedecay daemon status +journalctl --user -u tracedecay.service --since "1 hour ago" | grep 'event=scheduler' +``` + +If the config shows `enabled: false`, `backend: "disabled"`, `host_mode: "delegated_host"`, or task schedules set to `manual`, the daemon scheduler will skip work. The scheduler status panel shows the same skip reasons without requiring shell access. + ### Frontend Assets Not Updating ```bash diff --git a/src/automation/backend.rs b/src/automation/backend.rs index e54b14e4..b447f038 100644 --- a/src/automation/backend.rs +++ b/src/automation/backend.rs @@ -350,11 +350,7 @@ impl AgentTaskBackend for CodexAppServerBackend { let output_json = request .contract .strict_json - .then(|| { - let value = extract_single_json_object(&summary.text)?; - validate_response_schema(&value, &request.contract)?; - Ok::(value) - }) + .then(|| extract_response_json_object(&summary.text, &request.contract)) .transpose()?; Ok(AgentTaskResponse { run_id: request.run_id.clone(), @@ -368,11 +364,53 @@ impl AgentTaskBackend for CodexAppServerBackend { } } -pub fn extract_single_json_object(text: &str) -> Result { +pub fn extract_json_object_prefix(text: &str) -> Result { let candidate = strip_optional_json_fence(text)?; - let mut deserializer = serde_json::Deserializer::from_str(candidate); - let value = Value::deserialize(&mut deserializer)?; - deserializer.end()?; + parse_json_object_prefix(candidate) +} + +fn extract_response_json_object(text: &str, contract: &AgentTaskContract) -> Result { + let mut schema_error = None; + for (start, _) in text.char_indices().filter(|(_, ch)| *ch == '{') { + if !is_json_object_candidate_boundary(&text[..start]) { + continue; + } + let Ok(value) = parse_json_object_prefix(&text[start..]) else { + continue; + }; + if let Err(err) = validate_response_schema(&value, contract) { + if schema_error.is_none() { + schema_error = Some(err); + } + continue; + } + + return Ok(value); + } + + if let Some(err) = schema_error { + return Err(err); + } + + let value = extract_json_object_prefix(text)?; + validate_response_schema(&value, contract)?; + Ok(value) +} + +fn is_json_object_candidate_boundary(prefix: &str) -> bool { + prefix + .chars() + .rev() + .find(|ch| !ch.is_whitespace()) + .is_none_or(|ch| matches!(ch, '}' | ']')) +} + +fn parse_json_object_prefix(candidate: &str) -> Result { + let mut stream = serde_json::Deserializer::from_str(candidate).into_iter::(); + let value = match stream.next() { + Some(value) => value?, + None => return config_error("automation backend output must be a JSON object"), + }; if !value.is_object() { return config_error("automation backend output must be a JSON object"); } @@ -405,10 +443,6 @@ fn strip_optional_json_fence(text: &str) -> Result<&str> { let Some(closing_start) = after_opening.rfind("```") else { return config_error("automation backend JSON fence is missing closing fence"); }; - let trailing = after_opening[closing_start + "```".len()..].trim(); - if !trailing.is_empty() { - return config_error("automation backend JSON fence has trailing content"); - } let mut inner = &after_opening[..closing_start]; if let Some(rest) = inner.strip_prefix("json") { inner = rest; diff --git a/src/automation/lifecycle.rs b/src/automation/lifecycle.rs index 0d4028e1..269332f8 100644 --- a/src/automation/lifecycle.rs +++ b/src/automation/lifecycle.rs @@ -7,7 +7,7 @@ use serde_json::{json, Value}; use super::artifacts::{sha256_json, write_improvement_artifacts}; use super::backend::{ - agent_task_contract, classify_agent_task_error_message, extract_single_json_object, + agent_task_contract, classify_agent_task_error_message, extract_json_object_prefix, prompt_version, task_key, AgentTaskKind, AgentTaskRequest, AgentTaskResponse, }; use super::config::{AutomationBackend, AutomationConfig, AutomationHostMode}; @@ -450,7 +450,7 @@ impl<'a> AgentRunFinalizer<'a> { match response .output_json .clone() - .map_or_else(|| extract_single_json_object(&response.output_text), Ok) + .map_or_else(|| extract_json_object_prefix(&response.output_text), Ok) { Ok(output) => Ok(output), Err(err) => { diff --git a/src/daemon.rs b/src/daemon.rs index 7e59b4f7..095ceafa 100644 --- a/src/daemon.rs +++ b/src/daemon.rs @@ -1,5 +1,6 @@ #[cfg(unix)] use std::collections::HashMap; +use std::fmt::Write; #[cfg(unix)] use std::os::unix::fs::PermissionsExt; use std::path::{Path, PathBuf}; @@ -298,16 +299,163 @@ pub fn service_status(socket_path: &Path) -> String { "missing" }; format!( - "service: {}\nsocket: {} ({})\n", + "service: {}\nsocket: {} ({})\nlogs: journalctl --user -u {} -f\n", systemd_user_service_path().map_or_else( |e| format!("unavailable: {e}"), |path| path.display().to_string() ), socket_path.display(), - socket_state + socket_state, + SERVICE_NAME ) } +fn format_daemon_log_line(event: &str, fields: &[(&str, String)]) -> String { + let mut line = format!("[tracedecay] event={}", quote_log_value(event)); + for (key, value) in fields { + line.push(' '); + line.push_str(key); + line.push('='); + line.push_str("e_log_value(value)); + } + line +} + +fn quote_log_value(value: &str) -> String { + if !value.is_empty() + && value + .bytes() + .all(|b| b.is_ascii_alphanumeric() || matches!(b, b'_' | b'-' | b'.' | b'/' | b':')) + { + return value.to_string(); + } + + let mut escaped = String::with_capacity(value.len()); + for ch in value.chars() { + match ch { + '\\' => escaped.push_str("\\\\"), + '"' => escaped.push_str("\\\""), + '\n' => escaped.push_str("\\n"), + '\r' => escaped.push_str("\\r"), + '\t' => escaped.push_str("\\t"), + ch if ch.is_control() => { + let _ = write!(escaped, "\\u{{{:x}}}", ch as u32); + } + ch => escaped.push(ch), + } + } + format!("\"{escaped}\"") +} + +fn log_daemon_event(event: &str, fields: &[(&str, String)]) { + eprintln!("{}", format_daemon_log_line(event, fields)); +} + +#[cfg(unix)] +fn scheduler_task_log_fields( + project_path: &Path, + task: crate::automation::backend::AgentTaskKind, + outcome: &str, +) -> Vec<(&'static str, String)> { + vec![ + ("project", project_path.display().to_string()), + ( + "task", + crate::automation::backend::task_key(task).to_string(), + ), + ("outcome", outcome.to_string()), + ] +} + +#[cfg(unix)] +fn log_scheduler_task_start(project_path: &Path, task: crate::automation::backend::AgentTaskKind) { + log_daemon_event( + "scheduler_task", + &scheduler_task_log_fields(project_path, task, "start"), + ); +} + +#[cfg(unix)] +fn scheduler_task_error_log_fields( + project_path: &Path, + task: crate::automation::backend::AgentTaskKind, + error: &TraceDecayError, +) -> Vec<(&'static str, String)> { + vec![ + ("project", project_path.display().to_string()), + ( + "task", + crate::automation::backend::task_key(task).to_string(), + ), + ("error", error.to_string()), + ] +} + +#[cfg(unix)] +fn log_scheduler_task_error( + project_path: &Path, + task: crate::automation::backend::AgentTaskKind, + error: &TraceDecayError, +) { + log_daemon_event( + "scheduler_task_error", + &scheduler_task_error_log_fields(project_path, task, error), + ); +} + +#[cfg(unix)] +fn scheduler_record_log_fields( + project_path: &Path, + record: &crate::automation::run_ledger::AutomationRunLedgerRecord, +) -> Vec<(&'static str, String)> { + use crate::automation::run_ledger::AutomationRunStatus; + + let outcome = match record.status { + AutomationRunStatus::Succeeded => "complete", + AutomationRunStatus::Failed => "error", + AutomationRunStatus::Skipped => "skipped", + AutomationRunStatus::Queued => "queued", + AutomationRunStatus::Running => "running", + }; + let task = record + .task_key + .as_deref() + .unwrap_or_else(|| crate::automation::backend::task_key(record.task)) + .to_string(); + let mut fields = vec![ + ("project", project_path.display().to_string()), + ("task", task), + ("outcome", outcome.to_string()), + ("run_id", record.run_id.clone()), + ]; + if let Some(reason) = record.fallback_status.as_ref().or(record.error.as_ref()) { + fields.push(("reason", reason.clone())); + } + fields +} + +#[cfg(all(unix, test))] +fn daemon_scheduler_record_log_line( + project_path: &Path, + record: &crate::automation::run_ledger::AutomationRunLedgerRecord, +) -> String { + format_daemon_log_line( + "scheduler_task", + &scheduler_record_log_fields(project_path, record), + ) +} + +#[cfg(unix)] +fn log_daemon_scheduler_record( + project_path: &Path, + record: &crate::automation::run_ledger::AutomationRunLedgerRecord, +) { + log_daemon_event( + "scheduler_task", + &scheduler_record_log_fields(project_path, record), + ); +} + pub fn unavailable_error(socket_path: &Path) -> TraceDecayError { TraceDecayError::Config { message: format!( @@ -391,7 +539,13 @@ async fn proxy_request_line_to_daemon( transport.write_line("\n").await?; transport.flush().await?; } else { - eprintln!("[tracedecay] daemon proxy dropped notification after error: {err}"); + log_daemon_event( + "daemon_proxy_drop", + &[ + ("outcome", "dropped_notification".to_string()), + ("error", err.to_string()), + ], + ); } } } @@ -565,7 +719,10 @@ async fn run_foreground_unix(socket_path: PathBuf) -> Result<()> { let listener = UnixListener::bind(&socket_path)?; set_owner_only_permissions(&socket_path, 0o600)?; - eprintln!("[tracedecay] daemon listening on {}", socket_path.display()); + log_daemon_event( + "daemon_listening", + &[("socket", socket_path.display().to_string())], + ); let engine = DaemonEngine::default(); let mut sigterm = tokio::signal::unix::signal(tokio::signal::unix::SignalKind::terminate())?; @@ -578,10 +735,17 @@ async fn run_foreground_unix(socket_path: PathBuf) -> Result<()> { let engine = engine.clone(); tokio::spawn(async move { if let Err(e) = Box::pin(serve_socket_client(stream, engine)).await { - eprintln!("[tracedecay] daemon client error: {e}"); + log_daemon_event( + "daemon_client", + &[("outcome", "error".to_string()), ("error", e.to_string())], + ); } }); } + log_daemon_event( + "daemon_shutdown", + &[("socket", socket_path.display().to_string())], + ); engine.shutdown_all().await; let _ = std::fs::remove_file(&socket_path); Ok(()) @@ -670,7 +834,11 @@ impl DaemonEngine { return Ok(server); } - let cg = open_project_for_handshake(&canonical_project_path, handshake).await?; + let cg = Box::pin(open_project_for_handshake( + &canonical_project_path, + handshake, + )) + .await?; let accounting_db = accounting_db_for_handshake(handshake).await; let registry_db = registry_db_for_handshake(handshake).await; let server = crate::mcp::McpServer::new_with_dbs( @@ -705,7 +873,14 @@ impl DaemonEngine { match automation_scheduler_configured_for_project(&project_path, &handshake).await { Ok(configured) => configured, Err(e) => { - eprintln!("[tracedecay] automation scheduler config error: {e}"); + log_daemon_event( + "scheduler_config", + &[ + ("project", project_path.display().to_string()), + ("outcome", "error".to_string()), + ("error", e.to_string()), + ], + ); false } }; @@ -754,14 +929,35 @@ impl DaemonEngine { #[cfg(unix)] async fn run_automation_scheduler_loop(project_path: PathBuf, handshake: DaemonHandshake) { loop { + log_daemon_event( + "scheduler_tick", + &[ + ("project", project_path.display().to_string()), + ("outcome", "start".to_string()), + ], + ); if let Err(e) = Box::pin(run_automation_scheduler_tick(&project_path, &handshake)).await { - eprintln!("[tracedecay] automation scheduler tick failed: {e}"); + log_daemon_event( + "scheduler_tick", + &[ + ("project", project_path.display().to_string()), + ("outcome", "error".to_string()), + ("error", e.to_string()), + ], + ); } let tick_secs = Box::pin(automation_scheduler_tick_secs_for_project( &project_path, &handshake, )) .await; + log_daemon_event( + "scheduler_sleep", + &[ + ("project", project_path.display().to_string()), + ("next_tick_secs", tick_secs.to_string()), + ], + ); tokio::time::sleep(Duration::from_secs(tick_secs)).await; } } @@ -776,13 +972,27 @@ async fn automation_scheduler_tick_secs_for_project( match effective_automation_config_for_project(&cg, &handshake.client_identity).await { Ok(config) => config.scheduler_tick_secs, Err(e) => { - eprintln!("[tracedecay] automation scheduler config error: {e}"); + log_daemon_event( + "scheduler_config", + &[ + ("project", project_path.display().to_string()), + ("outcome", "error".to_string()), + ("error", e.to_string()), + ], + ); crate::automation::config::DEFAULT_SCHEDULER_TICK_SECS } } } Err(e) => { - eprintln!("[tracedecay] automation scheduler project open failed: {e}"); + log_daemon_event( + "scheduler_project_open", + &[ + ("project", project_path.display().to_string()), + ("outcome", "error".to_string()), + ("error", e.to_string()), + ], + ); crate::automation::config::DEFAULT_SCHEDULER_TICK_SECS } } @@ -793,7 +1003,7 @@ async fn run_automation_scheduler_tick( project_path: &Path, handshake: &DaemonHandshake, ) -> Result<()> { - use crate::automation::backend::CodexAppServerBackend; + use crate::automation::backend::{AgentTaskKind, CodexAppServerBackend}; use crate::automation::run_ledger::AutomationTrigger; use crate::automation::runner::{ run_memory_curator_with_backend, run_session_reflector_with_backend, @@ -806,16 +1016,33 @@ async fn run_automation_scheduler_tick( crate::automation::scheduler::load_scheduler_control(&cg.store_layout().dashboard_root) .await?; if control.paused { + log_daemon_event( + "scheduler_tick", + &[ + ("project", project_path.display().to_string()), + ("outcome", "skipped".to_string()), + ("reason", "paused".to_string()), + ], + ); return Ok(()); } let config = effective_automation_config_for_project(&cg, &handshake.client_identity).await?; if !automation_scheduler_configured(&config) { + log_daemon_event( + "scheduler_tick", + &[ + ("project", project_path.display().to_string()), + ("outcome", "skipped".to_string()), + ("reason", "not_configured".to_string()), + ], + ); return Ok(()); } let backend = CodexAppServerBackend::from_automation_config(&config); let mut first_error: Option = None; - if let Err(e) = run_memory_curator_with_backend( + log_scheduler_task_start(project_path, AgentTaskKind::MemoryCurator); + match run_memory_curator_with_backend( &cg, &config, &backend, @@ -826,10 +1053,14 @@ async fn run_automation_scheduler_tick( ) .await { - eprintln!("[tracedecay] automation scheduler memory_curator failed: {e}"); - first_error.get_or_insert(e); + Ok(run) => log_daemon_scheduler_record(project_path, &run.ledger_record), + Err(e) => { + log_scheduler_task_error(project_path, AgentTaskKind::MemoryCurator, &e); + first_error.get_or_insert(e); + } } - if let Err(e) = run_session_reflector_with_backend( + log_scheduler_task_start(project_path, AgentTaskKind::SessionReflector); + match run_session_reflector_with_backend( &cg, &config, &backend, @@ -840,10 +1071,14 @@ async fn run_automation_scheduler_tick( ) .await { - eprintln!("[tracedecay] automation scheduler session_reflector failed: {e}"); - first_error.get_or_insert(e); + Ok(run) => log_daemon_scheduler_record(project_path, &run.ledger_record), + Err(e) => { + log_scheduler_task_error(project_path, AgentTaskKind::SessionReflector, &e); + first_error.get_or_insert(e); + } } - if let Err(e) = run_skill_writer_with_backend( + log_scheduler_task_start(project_path, AgentTaskKind::SkillWriter); + match run_skill_writer_with_backend( &cg, &config, &backend, @@ -854,8 +1089,11 @@ async fn run_automation_scheduler_tick( ) .await { - eprintln!("[tracedecay] automation scheduler skill_writer failed: {e}"); - first_error.get_or_insert(e); + Ok(run) => log_daemon_scheduler_record(project_path, &run.ledger_record), + Err(e) => { + log_scheduler_task_error(project_path, AgentTaskKind::SkillWriter, &e); + first_error.get_or_insert(e); + } } match first_error { Some(err) => Err(err), @@ -1314,6 +1552,120 @@ mod tests { } } + #[test] + fn daemon_log_line_formats_stable_key_value_fields() { + let line = super::format_daemon_log_line( + "scheduler_task", + &[ + ("task", "memory_curator".to_string()), + ("outcome", "not due yet".to_string()), + ("project", "/tmp/example project".to_string()), + ], + ); + + assert_eq!( + line, + "[tracedecay] event=scheduler_task task=memory_curator outcome=\"not due yet\" project=\"/tmp/example project\"" + ); + } + + #[test] + fn daemon_log_line_escapes_quotes_and_backslashes() { + let line = super::format_daemon_log_line( + "client_error", + &[("error", r#"failed at "step" \ retry"#.to_string())], + ); + + assert_eq!( + line, + r#"[tracedecay] event=client_error error="failed at \"step\" \\ retry""# + ); + } + + #[test] + fn daemon_log_line_escapes_control_characters() { + let line = super::format_daemon_log_line( + "client_error", + &[("error", "first\nsecond\rthird\tfourth".to_string())], + ); + + assert_eq!( + line, + r#"[tracedecay] event=client_error error="first\nsecond\rthird\tfourth""# + ); + } + + #[test] + fn service_status_includes_journalctl_debug_command() { + let status = super::service_status(&PathBuf::from("/tmp/tracedecay.sock")); + + assert!(status.contains("logs: journalctl --user -u tracedecay.service -f")); + } + + #[cfg(unix)] + #[test] + fn scheduler_task_start_log_uses_task_key_and_project() { + let line = super::format_daemon_log_line( + "scheduler_task", + &super::scheduler_task_log_fields( + std::path::Path::new("/tmp/project with spaces"), + crate::automation::backend::AgentTaskKind::SkillWriter, + "start", + ), + ); + + assert_eq!( + line, + "[tracedecay] event=scheduler_task project=\"/tmp/project with spaces\" task=skill_writer outcome=start" + ); + } + + #[cfg(unix)] + #[test] + fn scheduler_record_log_preserves_skipped_status_and_reason() { + let record = crate::automation::run_ledger::AutomationRunLedgerRecord { + schema_version: 2, + run_id: "run-123".to_string(), + trigger: crate::automation::run_ledger::AutomationTrigger::Scheduler, + task: crate::automation::backend::AgentTaskKind::MemoryCurator, + task_key: Some("memory_curator".to_string()), + backend: "codex_app_server".to_string(), + host_mode: Some("standalone".to_string()), + prompt_version: Some("memory_curator:v1".to_string()), + response_schema: None, + strict_json: None, + model: None, + status: crate::automation::run_ledger::AutomationRunStatus::Skipped, + evidence_hash: None, + input_hash: None, + output_hash: None, + proposed_ops: None, + applied_ops: None, + rejected_ops: None, + validation_report: None, + reviewed_count: 0, + accepted_count: 0, + rejected_count: 0, + skipped_count: 1, + error: None, + error_classification: None, + error_retryable: None, + fallback_status: Some("scheduler_interval_not_elapsed".to_string()), + report_ref: None, + artifacts: Vec::new(), + started_at: "1000".to_string(), + completed_at: "1001".to_string(), + }; + + let line = + super::daemon_scheduler_record_log_line(std::path::Path::new("/tmp/project"), &record); + + assert_eq!( + line, + "[tracedecay] event=scheduler_task project=/tmp/project task=memory_curator outcome=skipped run_id=run-123 reason=scheduler_interval_not_elapsed" + ); + } + #[test] fn user_service_runs_daemon_with_socket_path() { let spec = DaemonServiceSpec { diff --git a/tests/automation_backend_test.rs b/tests/automation_backend_test.rs index e4cbbde9..abacda88 100644 --- a/tests/automation_backend_test.rs +++ b/tests/automation_backend_test.rs @@ -8,7 +8,7 @@ use serde_json::json; use tempfile::TempDir; use tracedecay::automation::backend::{ - backend_availability, classify_agent_task_error_message, extract_single_json_object, + backend_availability, classify_agent_task_error_message, extract_json_object_prefix, AgentTaskBackend, AgentTaskFailureClass, AgentTaskKind, AgentTaskRequest, AgentTaskResponse, CodexAppServerBackend, }; @@ -46,7 +46,7 @@ impl AgentTaskBackend for EchoBackend { run_id: request.run_id.clone(), task: request.task, output_text: request.prompt.clone(), - output_json: extract_single_json_object(&request.prompt).ok(), + output_json: extract_json_object_prefix(&request.prompt).ok(), model: Some("test-model".to_string()), input_tokens: Some(12), output_tokens: Some(34), @@ -84,26 +84,55 @@ fn backend_contract_round_trips_structured_task_output() { #[test] fn extracts_one_plain_or_fenced_json_object() { assert_eq!( - extract_single_json_object(r#" { "ok": true } "#).unwrap()["ok"], + extract_json_object_prefix(r#" { "ok": true } "#).unwrap()["ok"], true ); assert_eq!( - extract_single_json_object("```json\n{\"task\":\"skill_writer\"}\n```").unwrap()["task"], + extract_json_object_prefix("```json\n{\"task\":\"skill_writer\"}\n```").unwrap()["task"], "skill_writer" ); } #[test] -fn rejects_non_object_extra_text_and_multiple_json_values() { - for text in [ - r#"[{"ok":true}]"#, - r#"prefix {"ok":true}"#, - r#"{"ok":true} suffix"#, - r#"{"ok":true} {"again":true}"#, - "```json\n{\"ok\":true}\n```\nextra", - ] { +fn extracts_first_json_object_with_trailing_explanation() { + assert_eq!( + extract_json_object_prefix("{\"ops\": []}\n\nNo changes were needed.").unwrap()["ops"], + json!([]) + ); + assert_eq!( + extract_json_object_prefix("```json\n{\"facts\":[]}\n```\n\nSummary: no facts.").unwrap() + ["facts"], + json!([]) + ); + assert_eq!( + extract_json_object_prefix("{\"skills\": []}\n{\"ignored\": true}").unwrap()["skills"], + json!([]) + ); +} + +#[test] +fn extracts_fenced_json_with_nested_markdown_fence_in_string() { + let body = json!({ + "skills": [{ + "name": "shell-example", + "body_markdown": "Run:\n```sh\ntracedecay status\n```" + }] + }); + let response = format!("```json\n{body}\n```\n\nCreated a skill."); + + let extracted = extract_json_object_prefix(&response).unwrap(); + + assert_eq!( + extracted["skills"][0]["body_markdown"], + "Run:\n```sh\ntracedecay status\n```" + ); +} + +#[test] +fn rejects_non_object_and_prefix_text() { + for text in [r#"[{"ok":true}]"#, r#"prefix {"ok":true}"#] { assert!( - extract_single_json_object(text).is_err(), + extract_json_object_prefix(text).is_err(), "accepted non-strict JSON output: {text}" ); } @@ -241,6 +270,42 @@ fn codex_app_server_backend_run_task_uses_injected_config() { assert_eq!(backend_request["context"], json!({"kind":"test"})); } +#[test] +fn codex_app_server_backend_uses_first_schema_matching_json_object() { + let fake = FakeCodexAppServer::new_with_behavior("json_after_echo"); + let backend = CodexAppServerBackend::from_config(CodexAppServerSummaryConfig { + codex_bin: fake.bin.display().to_string(), + model: Some("configured-model".to_string()), + timeout: fake_codex_response_timeout(), + max_tokens: None, + temperature: None, + }); + let request = AgentTaskRequest::new( + "run_app_server_echo".to_string(), + AgentTaskKind::MemoryCurator, + r#"{"ops":[]}"#.to_string(), + None, + json!({}), + ); + + let response = backend.run_task(&request).unwrap(); + + assert_eq!(response.output_json.unwrap()["ops"], json!([])); + assert_process_gone(fake.child_pid()); +} + +#[test] +fn codex_app_server_backend_rejects_nested_schema_matching_json_object() { + let (err, pid) = + backend_error_for_behavior("json_wrapped_response", fake_codex_response_timeout()); + + assert!( + err.contains("automation backend output must include a ops array"), + "unexpected error: {err}" + ); + assert_process_gone(pid); +} + #[test] fn codex_app_server_backend_falls_back_to_configured_model_when_server_omits_model() { let fake = FakeCodexAppServer::new_with_behavior("no_model"); @@ -638,6 +703,14 @@ with open(log_path, "a", encoding="utf-8") as log: payload = json.dumps(dict(ops=[])) print(json.dumps(dict(method="item/agentMessage/delta", params=dict(delta=payload, model="actual-model"))), flush=True) print(json.dumps(dict(method="turn/completed")), flush=True) + elif behavior == "json_after_echo": + payload = json.dumps(dict(run_id="echo", task="memory_curator")) + "\n" + json.dumps(dict(ops=[])) + print(json.dumps(dict(method="item/agentMessage/delta", params=dict(delta=payload, model="actual-model"))), flush=True) + print(json.dumps(dict(method="turn/completed")), flush=True) + elif behavior == "json_wrapped_response": + payload = json.dumps(dict(result=dict(ops=[]))) + print(json.dumps(dict(method="item/agentMessage/delta", params=dict(delta=payload, model="actual-model"))), flush=True) + print(json.dumps(dict(method="turn/completed")), flush=True) else: print(json.dumps(dict(method="item/agentMessage/delta", params=dict(delta="hidesummary ", model="actual-model"))), flush=True) print(json.dumps(dict(method="item/agentMessage/delta", params=dict(delta="text"))), flush=True)