From b913734b3dfdea5862626df379e70cbcd7a49363 Mon Sep 17 00:00:00 2001 From: Jacob Stephens Date: Sun, 18 Oct 2026 11:36:03 -0400 Subject: [PATCH 1/2] Show recent and historical Commands in status (#771) --- README.md | 11 +- docs/code-navigation.md | 2 +- src/args.rs | 23 ++- src/logs/command_record.rs | 3 + src/logs/recording.rs | 1 + src/logs/status.rs | 150 +++++++++++++----- src/logs/status/history.rs | 304 +++++++++++++++++++++++++++++++++++++ src/main.rs | 6 +- tests/status.rs | 247 +++++++++++++++++++++++++++++- 9 files changed, 701 insertions(+), 46 deletions(-) create mode 100644 src/logs/status/history.rs diff --git a/README.md b/README.md index ca3527aef..62ef0ee5e 100644 --- a/README.md +++ b/README.md @@ -71,7 +71,9 @@ The designed behaviour described in this README is implemented. Known gaps and p ## Machine status -`thirdshift status` names this host and lists live Runs started on an Issue URL across every repository in `logs.dir`, with their issue and title, Harness, Model, Effort, current stage and its age. A Command with no outcome whose process has gone shows as `died at `. Process start identifiers distinguish a reused process id on Linux and macOS. Completed Commands leave the live list; their Command records remain beside their Command logs, as `*.command.json`. A record write failure warns once per Command and does not change its outcome. +`thirdshift status` names this host and lists live Runs started on an Issue URL across every repository in `logs.dir`, with their issue and title, Harness, Model, Effort, current stage and its age. After the live Commands it lists those that ended in the last 24 hours, with their outcomes. `thirdshift status --all` lists every Command this machine has logs for, newest start first. A Command record with no outcome whose process has gone shows as `died at ` in either view. Process start identifiers distinguish a reused process id on Linux and macOS. Command records remain beside their Command logs, as `*.command.json`. A record write failure warns once per Command and does not change its outcome. + +History uses each source only for Commands missing from the preceding sources: Command records, then Activity log start/end lines with their Command logs, then Session logs in the current `///commands//` layout. Activity entries have start and end times and outcomes, with no stages. Session entries group logs by issue and Command stamp; they have no known end or outcome and appear only with `--all`. Sessions covered by a Spec run or Pass's stamp belong to that Command. The flat layout from before [ADR 0011](docs/adr/0011-thirdshift-keeps-a-per-repository-activity-log.md) is ignored. `thirdshift status --json` is the versioned API for agents and the coming [Console](docs/adr/0016-the-console-is-a-long-running-reader.md). It runs outside a repository too. Version 1 has this shape: @@ -91,19 +93,24 @@ The designed behaviour described in this README is implemented. Known gaps and p "model": "opus", "effort": "high", "started_at": "2026-10-18T12:00:00-04:00", + "ended_at": null, "stages": [{"name": "implement", "began_at": "2026-10-18T12:00:01-04:00", "session_log": "/logs/acme/widgets/commands/issue/7-stamp-implement.jsonl"}], "session_log": "/logs/acme/widgets/commands/issue/7-stamp-implement.jsonl", "issue_branch": "issue-7", "pull_request": null, "outcome": null, "cause": null, + "source": "command_record", + "command_log": "/logs/acme/widgets/commands/issue/7-stamp.log", "state": "live", "stage": {"name": "implement", "began_at": "2026-10-18T12:00:01-04:00", "age_seconds": 52} }] } ``` -Times are RFC 3339; ages are nonnegative seconds. `model` and `effort` are null when left to the Harness. `session_log`, `issue_branch`, `pull_request`, `outcome` and `cause` are nullable. The retained record has the same Command fields without the computed `state` and `stage`; it ends with its outcome, failure cause (null on success), and the Issue branch and pull request left behind. `state` is `live` or `died`; `stage` is null before the first known stage. Readers skip unknown stage names. Known stages are `implement`, `Resume`, `Security review`, `pull request`, `CI watch`, `Repair`, `Self-merge` and `cleanup`. More Command kinds and history are tracked in [#711](https://github.com/JacobStephens2/thirdshift/issues/711). +Times are RFC 3339; ages are nonnegative seconds. `model` and `effort` are null when left to the Harness. `session_log`, `issue_branch`, `pull_request`, `outcome`, `cause` and `ended_at` are nullable. The retained record has the same Command fields without the computed `state`, `stage`, `source` and `command_log`; it ends with its outcome, end time, failure cause (null on success), and the Issue branch and pull request left behind. Older records without an end time use their last modification time. `state` is `live`, `died`, `ended`, or `unknown` when historical evidence has no ending. `stage` is null before the first known stage. Readers skip unknown stage names. Known stages are `implement`, `Resume`, `Security review`, `pull request`, `CI watch`, `Repair`, `Self-merge` and `cleanup`. + +Every entry has `source`: `command_record`, `activity_log` or `session_log`. The latter two carry `repository`, `kind`, nullable `issue` (number, URL, nullable title), `harness`, `model`, `effort`, `started_at`, nullable `ended_at` and `outcome`, nullable `command_log`, `session_logs` (paths), `state`, `stages: []` and `stage: null`. They omit record-only fields such as process identity and branch information. Activity times use the UTC offset in the Command log's stamp; their outcome is the Activity log's full ending text. A Session entry has null Harness, Model, Effort, end time and outcome, and lists its grouped Session logs. Both flags can be combined as `status --all --json`. ## Install diff --git a/docs/code-navigation.md b/docs/code-navigation.md index 4a1c78a6e..ae7a14d95 100644 --- a/docs/code-navigation.md +++ b/docs/code-navigation.md @@ -18,7 +18,7 @@ Start with the issue's terms in `CONTEXT.md`, then use this index to find their | Session prompt, Factory skills | `src/prompt.rs`; `src/skills.rs`; `skills/` | `src/skills/tests.rs`, `tests/packaging.rs` | | Session log, Resume | `src/session.rs` and `src/session/` | `src/session/execution_tests.rs`, `tests/background_work.rs` | | Command log, Activity log | `src/logs.rs`; `src/logs/recording.rs` — `Record` | `src/logs/recording/tests.rs`, `tests/command_logs.rs`, `tests/activity_log.rs` | -| Command record, status | `src/logs/recording.rs`; `src/logs/command_record.rs`; `src/logs/status.rs`; `src/logs/process_identity.rs` | `tests/status.rs`, `src/logs/recording/tests.rs` | +| Command record, status | `src/logs/recording.rs`; `src/logs/command_record.rs`; `src/logs/status.rs` and `src/logs/status/history.rs`; `src/logs/process_identity.rs` | `tests/status.rs`, `src/logs/recording/tests.rs` | | User config, Setup | `src/config.rs`; `src/setup.rs` | `tests/user_config.rs`, `tests/setup.rs` | | Architecture review, Architect run | `src/architect.rs` | `tests/architect_run.rs` | | Security audit, Security review, Security run | `src/security.rs` and `src/security/` | `tests/security_review.rs`, `tests/security_run.rs` | diff --git a/src/args.rs b/src/args.rs index fe4534484..8ab6b9a22 100644 --- a/src/args.rs +++ b/src/args.rs @@ -24,6 +24,7 @@ pub enum Command { Setup, Status { json: bool, + all: bool, }, /// Internal interface for scripts/release.sh: prompt on stdin. ReleaseSummary, @@ -224,9 +225,25 @@ pub fn parse(args: &[String]) -> Result { Some("update") => return Ok(Command::Update), Some("status") => { return match &args[1..] { - [] => Ok(Command::Status { json: false }), - [flag] if flag == "--json" => Ok(Command::Status { json: true }), - _ => bail!("usage: thirdshift status [--json]"), + [] => Ok(Command::Status { + json: false, + all: false, + }), + [flag] if flag == "--json" => Ok(Command::Status { + json: true, + all: false, + }), + [flag] if flag == "--all" => Ok(Command::Status { + json: false, + all: true, + }), + [a, b] if (a == "--all" && b == "--json") || (a == "--json" && b == "--all") => { + Ok(Command::Status { + json: true, + all: true, + }) + } + _ => bail!("usage: thirdshift status [--all] [--json]"), }; } Some("--release-summary") => { diff --git a/src/logs/command_record.rs b/src/logs/command_record.rs index 903e20771..d0fba4f26 100644 --- a/src/logs/command_record.rs +++ b/src/logs/command_record.rs @@ -21,6 +21,8 @@ pub(super) struct CommandRecord { pub model: Option, pub effort: Option, pub started_at: String, + #[serde(default)] + pub ended_at: Option, pub stages: Vec, pub session_log: Option, pub outcome: Option, @@ -110,6 +112,7 @@ impl CommandRecord { model: harness.model.clone(), effort: harness.effort.clone(), started_at: now.to_rfc3339(), + ended_at: None, stages: Vec::new(), session_log: None, outcome: None, diff --git a/src/logs/recording.rs b/src/logs/recording.rs index 671aab970..b7b934129 100644 --- a/src/logs/recording.rs +++ b/src/logs/recording.rs @@ -228,6 +228,7 @@ impl Record { pub(super) fn finished(&mut self, account: &crate::run_ending::Account<'_>) { if let Some((_, facts)) = &mut self.command_record { + facts.ended_at = Some(self.outside.now().to_rfc3339()); facts.outcome = Some(account.outcome.into()); facts.cause = account .ended diff --git a/src/logs/status.rs b/src/logs/status.rs index a8c6c9a18..07192b850 100644 --- a/src/logs/status.rs +++ b/src/logs/status.rs @@ -1,5 +1,8 @@ //! Read machine-wide Command records without entering a Launch directory. +mod history; + +use std::collections::HashSet; use std::fs; use std::path::{Path, PathBuf}; @@ -15,7 +18,43 @@ use crate::config::UserConfig; struct Status { version: u32, hostname: String, - commands: Vec, + commands: Vec, +} + +#[derive(Serialize)] +#[serde(untagged)] +enum Entry { + Record(Box), + History(Box), +} + +impl Entry { + fn ordering( + &self, + all: bool, + ) -> ( + bool, + std::cmp::Reverse>>, + &str, + ) { + let (state, started, repo) = match self { + Self::Record(command) => ( + command.state, + command.record.started_at.as_str(), + command.record.repository.as_str(), + ), + Self::History(command) => ( + command.state, + command.started_at.as_str(), + command.repository.as_str(), + ), + }; + ( + !all && state != "live", + std::cmp::Reverse(DateTime::parse_from_rfc3339(started).ok()), + repo, + ) + } } #[derive(Serialize)] @@ -24,6 +63,8 @@ struct Command { record: CommandRecord, state: &'static str, stage: Option, + source: &'static str, + command_log: PathBuf, } #[derive(Serialize)] @@ -33,31 +74,53 @@ struct CurrentStage { age_seconds: i64, } -pub fn show(json: bool) -> Result<()> { +pub fn show(json: bool, all: bool) -> Result<()> { let config = UserConfig::load()?; let now = Local::now(); let mut commands = Vec::new(); for owner in directories(&config.logs_dir)? { for repo in directories(&owner)? { + let mut covered = HashSet::new(); for folder in directories(&repo.join("commands"))? { for entry in entries(&folder)? { - if !entry - .file_name() - .to_string_lossy() - .ends_with(".command.json") + if !entry.file_type()?.is_file() + || !entry + .file_name() + .to_string_lossy() + .ends_with(".command.json") { continue; } let path = entry.path(); let bytes = fs::read(&path) .with_context(|| format!("could not read {}", path.display()))?; - let Ok(record) = serde_json::from_slice::(&bytes) else { + let Ok(mut record) = serde_json::from_slice::(&bytes) else { continue; }; - if record.version != 1 || record.outcome.is_some() { + if record.version != 1 { continue; } - let state = if record.live(&mut OnMachine) { + let name = entry.file_name(); + let name = name.to_string_lossy(); + let command_log = path + .with_file_name(format!("{}.log", name.split('.').next().unwrap_or(&name))); + covered.insert(command_log.clone()); + // Records written before completion times existed were last + // replaced when their outcome was recorded. + if record.outcome.is_some() && record.ended_at.is_none() { + record.ended_at = entry + .metadata()? + .modified() + .ok() + .map(|time| DateTime::::from(time).to_rfc3339()); + } + if !all && record.outcome.is_some() && !recent(record.ended_at.as_deref(), now) + { + continue; + } + let state = if record.outcome.is_some() { + "ended" + } else if record.live(&mut OnMachine) { "live" } else { "died" @@ -69,27 +132,24 @@ pub fn show(json: bool) -> Result<()> { .map(|began| now.signed_duration_since(began).num_seconds().max(0)) .unwrap_or(0), }); - commands.push(Command { + commands.push(Entry::Record(Box::new(Command { record, state, stage, - }); + source: "command_record", + command_log, + }))); } } + commands.extend( + history::read(&repo, &covered)? + .into_iter() + .filter(|command| all || recent(command.ended_at.as_deref(), now)) + .map(|command| Entry::History(Box::new(command))), + ); } } - commands.sort_by(|a, b| { - ( - a.state != "live", - &a.record.repository, - &a.record.started_at, - ) - .cmp(&( - b.state != "live", - &b.record.repository, - &b.record.started_at, - )) - }); + commands.sort_by(|a, b| a.ordering(all).cmp(&b.ordering(all))); let status = Status { version: 1, hostname: crate::host::name().unwrap_or_else(|| "unknown".into()), @@ -99,18 +159,32 @@ pub fn show(json: bool) -> Result<()> { println!("{}", serde_json::to_string_pretty(&status)?); } else { println!("{}", status.hostname); - for command in status.commands { - let facts = command.record; - let stage = command.stage.map_or_else( - || "starting".into(), - |stage| { - if command.state == "died" { - format!("died at {}", stage.name) - } else { - format!("{} · {}", stage.name, age(stage.age_seconds)) - } - }, - ); + for entry in status.commands { + let command = match entry { + Entry::Record(command) => command, + Entry::History(command) => { + command.print(); + continue; + } + }; + let Command { + record: facts, + stage, + state, + .. + } = *command; + let stage = facts.outcome.clone().unwrap_or_else(|| { + stage.map_or_else( + || "starting".into(), + |stage| { + if state == "died" { + format!("died at {}", stage.name) + } else { + format!("{} · {}", stage.name, age(stage.age_seconds)) + } + }, + ) + }); println!( "{}#{} {} · {} · {} · {} · {stage}", facts.repository, @@ -129,6 +203,12 @@ pub fn show(json: bool) -> Result<()> { Ok(()) } +fn recent(ended: Option<&str>, now: DateTime) -> bool { + ended + .and_then(|time| DateTime::parse_from_rfc3339(time).ok()) + .is_some_and(|ended| ended >= now - chrono::Duration::hours(24)) +} + fn age(seconds: i64) -> String { if seconds < 60 { format!("{seconds} sec") diff --git a/src/logs/status/history.rs b/src/logs/status/history.rs new file mode 100644 index 000000000..e4e2f390a --- /dev/null +++ b/src/logs/status/history.rs @@ -0,0 +1,304 @@ +//! Recover Commands that predate records, without inventing stages or liveness. + +use std::collections::{BTreeMap, HashSet}; +use std::fs; +use std::path::{Component, Path, PathBuf}; + +use anyhow::{Context, Result}; +use chrono::{DateTime, FixedOffset, NaiveDateTime}; +use serde::Serialize; + +use crate::logs::activity::TIME_FORMAT; +use crate::logs::command_record::Issue; +use crate::progress::ChildLine; + +#[derive(Serialize)] +pub(super) struct Command { + pub repository: String, + kind: String, + issue: Option, + harness: Option, + model: Option, + effort: Option, + pub started_at: String, + pub ended_at: Option, + outcome: Option, + command_log: Option, + session_logs: Vec, + stages: [(); 0], + stage: Option<()>, + source: &'static str, + pub state: &'static str, +} + +impl Command { + pub fn print(&self) { + let issue = self + .issue + .as_ref() + .map(|issue| format!("#{}", issue.number)) + .unwrap_or_default(); + println!( + "{}{issue} {} · {} → {} · {}", + self.repository, + self.kind, + self.started_at, + self.ended_at.as_deref().unwrap_or("unknown end"), + self.outcome.as_deref().unwrap_or("unknown outcome") + ); + } +} + +struct Started { + subject: String, + offset: FixedOffset, + log: String, + command: Command, +} + +pub(super) fn read(repo: &Path, covered: &HashSet) -> Result> { + let repository = format!( + "{}/{}", + repo.parent() + .and_then(Path::file_name) + .unwrap_or_default() + .to_string_lossy(), + repo.file_name().unwrap_or_default().to_string_lossy() + ); + let mut starts: Vec = Vec::new(); + for line in read_optional(&repo.join("activity.log"))?.lines() { + let Some((time, text)) = line.split_once(' ').and_then(|(date, rest)| { + let (clock, text) = rest.split_once(' ')?; + Some(( + NaiveDateTime::parse_from_str(&format!("{date} {clock}"), TIME_FORMAT).ok()?, + text, + )) + }) else { + continue; + }; + if let Some((subject, detail)) = text.split_once(" started: ") { + if let Some(started) = start(repo, &repository, subject, detail, time)? { + starts.push(started); + } + } else if let Some((subject, outcome)) = text.split_once(" ended: ") { + // A subject may have concurrent Commands. Prefer the Command log + // containing this ending over an assumed start/end pairing order. + let candidates: Vec<_> = starts + .iter() + .enumerate() + .filter(|(_, start)| start.subject == subject && start.command.ended_at.is_none()) + .map(|(index, _)| index) + .collect(); + let matched = candidates.iter().copied().find(|&index| starts[index].log.lines().any(|line| matches!(ChildLine::of(line), ChildLine::Own(message) if message == outcome))); + let index = matched.or_else(|| (candidates.len() == 1).then(|| candidates[0])); + if let Some(index) = index { + let start = &mut starts[index]; + start.command.ended_at = time + .and_local_timezone(start.offset) + .single() + .map(|time| time.to_rfc3339()); + start.command.outcome = Some(outcome.into()); + start.command.state = "ended"; + } + } + } + let recorded = covered; + let mut covered = recorded.clone(); + let mut shared_stamps = HashSet::new(); + for start in &starts { + if let Some(path) = &start.command.command_log { + covered.insert(path.clone()); + if start.command.kind != "Run" + && let Some(stamp) = log_stamp(path) + { + shared_stamps.insert((path.parent().unwrap().to_path_buf(), stamp)); + } + } + } + let mut commands: Vec<_> = starts + .into_iter() + .map(|start| start.command) + .filter(|command| { + command + .command_log + .as_ref() + .is_none_or(|path| !recorded.contains(path)) + }) + .collect(); + // Keep Activity entries unless a record covered them; all Activity starts + // still suppress their Session logs, including starts with no end line. + // `covered` above includes both sources for the Session-log pass. + commands.extend(sessions(repo, &repository, &covered, &shared_stamps)?); + Ok(commands) +} + +fn start( + repo: &Path, + repository: &str, + subject: &str, + detail: &str, + time: NaiveDateTime, +) -> Result> { + let (kind, number) = match subject.rsplit_once(" #") { + Some((kind, number)) => (kind, number.parse::().ok()), + None => (subject, None), + }; + if !matches!( + kind, + "Run" | "Spec run" | "Pickup run" | "Architect run" | "Security run" + ) { + return Ok(None); + } + let Some((path, choice)) = detail.rsplit_once(", on ") else { + return Ok(None); + }; + let relative = Path::new(path); + if !relative.starts_with("commands") + || relative + .components() + .any(|part| !matches!(part, Component::Normal(_))) + { + return Ok(None); + } + let Some(stamp) = relative + .file_stem() + .and_then(|name| name.to_str()) + .and_then(|name| name.get(name.len().checked_sub(20)?..)) + .and_then(parse_stamp) + else { + return Ok(None); + }; + let path = repo.join(relative); + let mut choice = choice.split(" · "); + let harness = choice.next().map(String::from); + let model = choice + .next() + .filter(|value| *value != "default model") + .map(String::from); + let effort = choice + .next() + .filter(|value| *value != "default effort") + .map(String::from); + Ok(Some(Started { + subject: subject.into(), + offset: *stamp.offset(), + log: read_optional(&path)?, + command: Command { + repository: repository.into(), + kind: kind.into(), + issue: number.map(|number| Issue { + number, + url: format!("https://github.com/{repository}/issues/{number}"), + title: None, + }), + harness, + model, + effort, + started_at: time + .and_local_timezone(*stamp.offset()) + .single() + .unwrap() + .to_rfc3339(), + ended_at: None, + outcome: None, + command_log: Some(path), + session_logs: Vec::new(), + stages: [], + stage: None, + source: "activity_log", + state: "unknown", + }, + })) +} + +fn log_stamp(path: &Path) -> Option { + let name = path.file_stem()?.to_str()?; + let stamp = name.get(name.len().checked_sub(20)?..)?; + parse_stamp(stamp)?; + Some(stamp.into()) +} + +fn sessions( + repo: &Path, + repository: &str, + covered: &HashSet, + shared_stamps: &HashSet<(PathBuf, String)>, +) -> Result> { + let mut groups: BTreeMap = BTreeMap::new(); + for folder in super::directories(&repo.join("commands"))? { + for entry in super::entries(&folder)? { + if !entry.file_type()?.is_file() { + continue; + } + let name = entry.file_name(); + let Some(name) = name.to_str().and_then(|name| name.strip_suffix(".jsonl")) else { + continue; + }; + let Some((prefix, rest)) = name.split_once('-') else { + continue; + }; + let Some(stamp) = rest.get(..20).and_then(parse_stamp) else { + continue; + }; + if rest + .get(20..) + .and_then(|rest| rest.strip_prefix('-')) + .is_none_or(str::is_empty) + { + continue; + } + let (kind, number) = match prefix.parse::() { + Ok(number) => ("Run", Some(number)), + Err(_) if prefix == "architect" => ("Architect run", None), + Err(_) if prefix == "secure" => ("Security run", None), + Err(_) => continue, + }; + let command_log = folder.join(format!("{prefix}-{}.log", &rest[..20])); + if covered.contains(&command_log) + || shared_stamps.contains(&(folder.clone(), rest[..20].into())) + { + continue; + } + let command = groups + .entry(command_log.clone()) + .or_insert_with(|| Command { + repository: repository.into(), + kind: kind.into(), + issue: number.map(|number| Issue { + number, + url: format!("https://github.com/{repository}/issues/{number}"), + title: None, + }), + harness: None, + model: None, + effort: None, + started_at: stamp.to_rfc3339(), + ended_at: None, + outcome: None, + command_log: command_log.is_file().then_some(command_log), + session_logs: Vec::new(), + stages: [], + stage: None, + source: "session_log", + state: "unknown", + }); + command.session_logs.push(entry.path()); + } + } + for command in groups.values_mut() { + command.session_logs.sort(); + } + Ok(groups.into_values().collect()) +} + +fn parse_stamp(stamp: &str) -> Option> { + DateTime::parse_from_str(stamp, "%Y%m%dT%H%M%S%z").ok() +} + +fn read_optional(path: &Path) -> Result { + match fs::read_to_string(path) { + Ok(text) => Ok(text), + Err(error) if error.kind() == std::io::ErrorKind::NotFound => Ok(String::new()), + Err(error) => Err(error).with_context(|| format!("could not read {}", path.display())), + } +} diff --git a/src/main.rs b/src/main.rs index 08b9d2a96..df8b341da 100644 --- a/src/main.rs +++ b/src/main.rs @@ -75,7 +75,7 @@ usage: thirdshift Run the factory on the iss thirdshift secure base Use as the Base branch thirdshift email-test [
] Send a test email through Resend thirdshift setup Choose defaults and write the User config - thirdshift status [--json] List this machine's live Commands + thirdshift status [--all] [--json] List this machine's Commands thirdshift update Update to the latest release thirdshift version Print the version thirdshift help Print this reference @@ -128,8 +128,8 @@ fn main() -> ExitCode { } Ok(Command::Update) => return outcome(update::update()), Ok(Command::Setup) => return outcome(setup::setup()), - Ok(Command::Status { json }) => { - return match logs::status::show(json) { + Ok(Command::Status { json, all }) => { + return match logs::status::show(json, all) { Ok(()) => ExitCode::SUCCESS, Err(error) => failure(&error), }; diff --git a/tests/status.rs b/tests/status.rs index e43a5edee..dc9b633f9 100644 --- a/tests/status.rs +++ b/tests/status.rs @@ -40,13 +40,18 @@ gh pr create --base main --head issue-7 --title 'Make widgets' --body 'Closes #7 &[], "started", ); + let recent = chrono::Local::now().to_rfc3339(); + write_record(&scenario, 8, &recent, Some(&recent)); let result = scenario.run(&["status", "--json"]); let text = scenario.run(&["status"]); + fs::remove_file(scenario.path(LOGS).join("8-fixture.command.json")).unwrap(); fs::write(scenario.path("release"), "").unwrap(); let ended = held.finish(); assert_eq!(result.code, Some(0), "{}", result.stderr); let status: Value = serde_json::from_str(&result.stdout).unwrap(); assert_eq!(status["version"], 1); + assert_eq!(status["commands"].as_array().unwrap().len(), 2); + assert_eq!(status["commands"][1]["state"], "ended"); assert!(!status["hostname"].as_str().unwrap().is_empty()); let command = &status["commands"][0]; assert_eq!(command["issue"]["number"], 7); @@ -68,7 +73,10 @@ gh pr create --base main --head issue-7 --title 'Make widgets' --body 'Closes #7 assert_eq!(ended.code, Some(0), "{}", ended.stderr); let result = scenario.run(&["status", "--json"]); let status: Value = serde_json::from_str(&result.stdout).unwrap(); - assert_eq!(status["commands"], serde_json::json!([])); + assert_eq!(status["commands"][0]["state"], "ended"); + assert_eq!(status["commands"][0]["source"], "command_record"); + assert_eq!(status["commands"][0]["outcome"], "ready for review"); + assert!(status["commands"][0]["ended_at"].is_string()); let record = retained(&scenario); assert_eq!(record["outcome"], "ready for review"); assert_eq!(record["cause"], Value::Null); @@ -132,11 +140,246 @@ fn a_failed_run_retains_its_cause_and_does_not_stay_live() { assert_eq!(record["pull_request"], Value::Null); let result = scenario.run(&["status", "--json"]); assert_eq!( - serde_json::from_str::(&result.stdout).unwrap()["commands"], + serde_json::from_str::(&result.stdout).unwrap()["commands"][0]["state"], + "ended" + ); +} + +fn write_record(scenario: &Scenario, number: u32, started: &str, ended: Option<&str>) { + fs::create_dir_all(scenario.path(LOGS)).unwrap(); + let record = serde_json::json!({ + "version": 1, "kind": "Run", "repository": "acme/widgets", + "issue": {"number": number, "url": scenario.issue_url(number), "title": "Fixture"}, + "hostname": "factory", "process_id": 0, "process_start": "gone", + "harness": "claude", "model": null, "effort": null, + "started_at": started, "ended_at": ended, "stages": [], "session_log": null, + "outcome": ended.map(|_| "ready for review"), "cause": null, + "issue_branch": null, "pull_request": null + }); + fs::write( + scenario + .path(LOGS) + .join(format!("{number}-fixture.command.json")), + serde_json::to_vec(&record).unwrap(), + ) + .unwrap(); +} + +#[test] +fn status_shows_recent_outcomes_and_all_history_newest_first() { + let scenario = Scenario::new(); + let now = chrono::Local::now(); + let recent = (now - chrono::Duration::hours(1)).to_rfc3339(); + let old = (now - chrono::Duration::days(2)).to_rfc3339(); + // The recent completion began before the old completion: filter by end, + // and order history by start, rather than by directory or end time. + let earliest = (now - chrono::Duration::days(3)).to_rfc3339(); + write_record(&scenario, 7, &earliest, Some(&recent)); + write_record(&scenario, 8, &old, Some(&old)); + let result = scenario.run(&["status", "--json"]); + assert_eq!(result.code, Some(0), "{}", result.stderr); + let status: Value = serde_json::from_str(&result.stdout).unwrap(); + assert_eq!(status["commands"].as_array().unwrap().len(), 1); + assert_eq!(status["commands"][0]["issue"]["number"], 7); + assert_eq!(status["commands"][0]["outcome"], "ready for review"); + let text = scenario.run(&["status"]); + assert!(text.stdout.contains("ready for review"), "{}", text.stdout); + for flags in [["status", "--all", "--json"], ["status", "--json", "--all"]] { + let result = scenario.run(&flags); + assert_eq!(result.code, Some(0), "{}", result.stderr); + let status: Value = serde_json::from_str(&result.stdout).unwrap(); + let issues: Vec<_> = status["commands"] + .as_array() + .unwrap() + .iter() + .map(|c| c["issue"]["number"].as_u64().unwrap()) + .collect(); + assert_eq!(issues, [8, 7]); + } +} + +fn fixture_log(scenario: &Scenario, relative: &str, contents: &str) { + let path = scenario + .path("home/.thirdshift/logs/acme/widgets") + .join(relative); + fs::create_dir_all(path.parent().unwrap()).unwrap(); + fs::write(path, contents).unwrap(); +} + +#[test] +fn status_reads_activity_history_and_command_logs_without_stages() { + let scenario = Scenario::new(); + fixture_log( + &scenario, + "activity.log", + concat!( + "2026-10-01 12:00:00 Run #7 started: commands/issue/7-20261001T120000-0400.log, on claude · opus · high\n", + "2026-10-02 12:00:00 Run #7 started: commands/issue/7-20261002T120000-0400.log, on codex · default model · default effort\n", + "2026-10-02 13:00:00 Run #7 ended: PR https://github.com/acme/widgets/pull/2 is ready for review\n", + "2026-10-03 12:00:00 Run #7 ended: failed: claude exited 3\n", + "2026-10-04 12:00:00 Security run started: commands/secure/20261004T120000-0400.log, on claude · default model · default effort\n", + "2026-10-04 12:30:00 Security run ended: findings recorded\n", + "2026-10-05 12:00:00 Pickup run skipped: no Ready issue on acme/widgets\n" + ), + ); + fixture_log( + &scenario, + "commands/issue/7-20261001T120000-0400.log", + "thirdshift: 12:00:00 failed: claude exited 3\n", + ); + fixture_log( + &scenario, + "commands/issue/7-20261002T120000-0400.log", + "thirdshift: 13:00:00 PR https://github.com/acme/widgets/pull/2 is ready for review\n", + ); + fixture_log( + &scenario, + "commands/secure/20261004T120000-0400.log", + "thirdshift: 12:30:00 findings recorded\n", + ); + let result = scenario.run(&["status", "--all", "--json"]); + assert_eq!(result.code, Some(0), "{}", result.stderr); + let status: Value = serde_json::from_str(&result.stdout).unwrap(); + let commands = status["commands"].as_array().unwrap(); + assert_eq!(commands.len(), 3); + assert_eq!(commands[0]["kind"], "Security run"); + assert_eq!(commands[0]["issue"], Value::Null); + assert_eq!(commands[0]["outcome"], "findings recorded"); + assert_eq!(commands[1]["started_at"], "2026-10-02T12:00:00-04:00"); + assert_eq!(commands[1]["ended_at"], "2026-10-02T13:00:00-04:00"); + assert_eq!( + commands[1]["outcome"], + "PR https://github.com/acme/widgets/pull/2 is ready for review" + ); + assert_eq!(commands[2]["ended_at"], "2026-10-03T12:00:00-04:00"); + assert_eq!(commands[2]["outcome"], "failed: claude exited 3"); + assert_eq!(commands[2]["harness"], "claude"); + assert_eq!(commands[2]["model"], "opus"); + for command in commands { + assert_eq!(command["source"], "activity_log"); + assert_eq!(command["state"], "ended"); + assert_eq!(command["stages"], serde_json::json!([])); + assert_eq!(command["stage"], Value::Null); + assert!(command["command_log"].as_str().unwrap().ends_with(".log")); + } + let text = scenario.run(&["status", "--all"]); + assert_eq!(text.code, Some(0), "{}", text.stderr); + assert!(text.stdout.contains("findings recorded"), "{}", text.stdout); + assert!( + text.stdout.contains("2026-10-02T13:00:00-04:00"), + "{}", + text.stdout + ); +} + +#[test] +fn status_fills_gaps_by_source_and_groups_only_current_layout_sessions() { + let scenario = Scenario::new(); + write_record( + &scenario, + 7, + "2026-10-01T12:00:00-04:00", + Some("2026-10-01T13:00:00-04:00"), + ); + fs::rename( + scenario.path(LOGS).join("7-fixture.command.json"), + scenario + .path(LOGS) + .join("7-20261001T120000-0400.123.command.json"), + ) + .unwrap(); + fixture_log( + &scenario, + "activity.log", + concat!( + "2026-10-01 12:00:00 Run #7 started: commands/issue/7-20261001T120000-0400.log, on claude · default model · default effort\n", + "2026-10-01 13:00:00 Run #7 ended: PR https://github.com/acme/widgets/pull/1 is ready for review\n", + "2026-10-02 12:00:00 Spec run #8 started: commands/issue/8-20261002T120000-0400.log, on claude · default model · default effort\n", + "2026-10-02 13:00:00 Spec run #8 ended: failed: Ticket #10 failed\n" + ), + ); + for name in [ + "7-20261001T120000-0400-implement.jsonl", + "8-20261002T120000-0400-spec-review.jsonl", + "10-20261002T120000-0400-implement.jsonl", // Ticket belongs to Spec #8. + "9-20260901T120000-0400-implement.jsonl", + "9-20260901T120000-0400-implement-resume.jsonl", + "9-20260901T120000-0400-repair-1.jsonl", + "9-20260902T120000-0400-implement.jsonl", + ] { + fixture_log(&scenario, &format!("commands/issue/{name}"), "{}\n"); + } + fixture_log( + &scenario, + "commands/issue/9-20260901T120000-0400-implement.models.json", + "{}", + ); + fixture_log(&scenario, "commands/issue/bad-name.jsonl", "{}"); + for relative in [ + "sessions/widgets-4-20260801T120000-0400-implement.jsonl", + "commands/issue/5-20260801T120000-0400-implement.jsonl", + ] { + let path = scenario.path("home/.thirdshift/logs").join(relative); + fs::create_dir_all(path.parent().unwrap()).unwrap(); + fs::write(path, "{}\n").unwrap(); + } + let result = scenario.run(&["status", "--all", "--json"]); + assert_eq!(result.code, Some(0), "{}", result.stderr); + let status: Value = serde_json::from_str(&result.stdout).unwrap(); + let commands = status["commands"].as_array().unwrap(); + assert_eq!(commands.len(), 4, "{commands:?}"); + assert_eq!(commands[0]["source"], "activity_log"); + assert_eq!(commands[0]["issue"]["number"], 8); + assert_eq!(commands[1]["source"], "command_record"); + assert_eq!(commands[1]["outcome"], "ready for review"); + assert_eq!(commands[2]["started_at"], "2026-09-02T12:00:00-04:00"); + assert_eq!(commands[3]["session_logs"].as_array().unwrap().len(), 3); + for command in &commands[2..] { + assert_eq!(command["source"], "session_log"); + assert_eq!(command["issue"]["number"], 9); + assert_eq!(command["outcome"], Value::Null); + assert_eq!(command["ended_at"], Value::Null); + assert_eq!(command["state"], "unknown"); + } + let recent = scenario.run(&["status", "--json"]); + assert_eq!(recent.code, Some(0), "{}", recent.stderr); + assert_eq!( + serde_json::from_str::(&recent.stdout).unwrap()["commands"], serde_json::json!([]) ); } +#[test] +fn status_recovers_a_real_commands_logs_after_newer_sources_are_removed() { + let scenario = Scenario::new(); + scenario.agent_does(OPENS_PR); + let ended = scenario.run(&[&scenario.issue_url(7)]); + assert_eq!(ended.code, Some(0), "{}", ended.stderr); + for name in scenario + .entries(LOGS) + .into_iter() + .filter(|name| name.ends_with(".command.json")) + { + fs::remove_file(scenario.path(LOGS).join(name)).unwrap(); + } + let result = scenario.run(&["status", "--json"]); + assert_eq!(result.code, Some(0), "{}", result.stderr); + let status: Value = serde_json::from_str(&result.stdout).unwrap(); + assert_eq!(status["commands"].as_array().unwrap().len(), 1); + assert_eq!(status["commands"][0]["source"], "activity_log"); + assert_eq!( + status["commands"][0]["outcome"], + "PR https://github.com/acme/widgets/pull/1 is ready for review" + ); + fs::remove_file(scenario.path("home/.thirdshift/logs/acme/widgets/activity.log")).unwrap(); + let result = scenario.run(&["status", "--all", "--json"]); + assert_eq!(result.code, Some(0), "{}", result.stderr); + let status: Value = serde_json::from_str(&result.stdout).unwrap(); + assert_eq!(status["commands"].as_array().unwrap().len(), 1); + assert_eq!(status["commands"][0]["source"], "session_log"); + assert_eq!(status["commands"][0]["outcome"], Value::Null); +} + #[test] fn failed_acquisition_does_not_claim_a_branch_was_left() { let scenario = Scenario::new(); From 8e4891dcbab77c22bbb7cc272e1f316ce3c98524 Mon Sep 17 00:00:00 2001 From: Jacob Stephens Date: Sun, 18 Oct 2026 11:43:58 -0400 Subject: [PATCH 2/2] Recover older Activity history and concurrent failure endings --- src/logs/status/history.rs | 173 +++++++++++++++++++++++++------------ tests/status.rs | 109 +++++++++++++++++++++++ 2 files changed, 228 insertions(+), 54 deletions(-) diff --git a/src/logs/status/history.rs b/src/logs/status/history.rs index e4e2f390a..563a1f639 100644 --- a/src/logs/status/history.rs +++ b/src/logs/status/history.rs @@ -5,7 +5,7 @@ use std::fs; use std::path::{Component, Path, PathBuf}; use anyhow::{Context, Result}; -use chrono::{DateTime, FixedOffset, NaiveDateTime}; +use chrono::{DateTime, FixedOffset, NaiveDateTime, NaiveTime}; use serde::Serialize; use crate::logs::activity::TIME_FORMAT; @@ -32,6 +32,36 @@ pub(super) struct Command { } impl Command { + fn from_logs( + repository: &str, + kind: &str, + number: Option, + started: DateTime, + source: &'static str, + ) -> Self { + Self { + repository: repository.into(), + kind: kind.into(), + issue: number.map(|number| Issue { + number, + url: format!("https://github.com/{repository}/issues/{number}"), + title: None, + }), + harness: None, + model: None, + effort: None, + started_at: started.to_rfc3339(), + ended_at: None, + outcome: None, + command_log: None, + session_logs: Vec::new(), + stages: [], + stage: None, + source, + state: "unknown", + } + } + pub fn print(&self) { let issue = self .issue @@ -56,6 +86,50 @@ struct Started { command: Command, } +impl Started { + fn ending_distance(&self, time: NaiveDateTime, summary: &str) -> Option { + let ending = summary + .strip_prefix("plan ") + .and_then(|summary| summary.split_once(" dispatched: ")) + .map_or(summary, |(_, ending)| ending); + let ending = ending + .strip_prefix("failed: ") + .or_else(|| ending.strip_prefix("review required: ")) + .unwrap_or(ending); + self.log + .lines() + .filter_map(|line| { + let ChildLine::Own(message) = ChildLine::of(line) else { + return None; + }; + // Activity summaries wrap a failure's first line and append recovery + // facts; terminal output prints the cause and those facts separately. + if message.is_empty() + || !(summary == message + || ending == message + || ending + .strip_prefix(message) + .is_some_and(|suffix| suffix.starts_with("; "))) + { + return None; + } + let clock = line + .strip_prefix("thirdshift: ") + .and_then(|line| line.split_once(' ')) + .and_then(|(clock, _)| NaiveTime::parse_from_str(clock, "%H:%M:%S").ok()); + // The terminal ending follows the Activity write, possibly across a + // second or midnight. Its nearest clock disambiguates equal causes. + Some(clock.map_or(i64::MAX, |clock| { + clock + .signed_duration_since(time.time()) + .num_seconds() + .rem_euclid(24 * 3600) + })) + }) + .min() + } +} + pub(super) fn read(repo: &Path, covered: &HashSet) -> Result> { let repository = format!( "{}/{}", @@ -89,7 +163,25 @@ pub(super) fn read(repo: &Path, covered: &HashSet) -> Result = candidates + .iter() + .filter_map(|&index| { + starts[index] + .ending_distance(time, outcome) + .map(|distance| (index, distance)) + }) + .collect(); + let matched = matches + .iter() + .min_by_key(|(_, distance)| distance) + .filter(|(_, distance)| { + matches + .iter() + .filter(|(_, other)| other == distance) + .count() + == 1 + }) + .map(|&(index, _)| index); let index = matched.or_else(|| (candidates.len() == 1).then(|| candidates[0])); if let Some(index) = index { let start = &mut starts[index]; @@ -149,9 +241,9 @@ fn start( ) { return Ok(None); } - let Some((path, choice)) = detail.rsplit_once(", on ") else { - return Ok(None); - }; + // Early Activity logs named only the Command log, before Harness metadata + // was added. Their known outcome still takes precedence over Session logs. + let (path, choice) = detail.rsplit_once(", on ").unwrap_or((detail, "")); let relative = Path::new(path); if !relative.starts_with("commands") || relative @@ -170,7 +262,10 @@ fn start( }; let path = repo.join(relative); let mut choice = choice.split(" · "); - let harness = choice.next().map(String::from); + let harness = choice + .next() + .filter(|name| !name.is_empty()) + .map(String::from); let model = choice .next() .filter(|value| *value != "default model") @@ -179,35 +274,22 @@ fn start( .next() .filter(|value| *value != "default effort") .map(String::from); + let mut command = Command::from_logs( + repository, + kind, + number, + time.and_local_timezone(*stamp.offset()).single().unwrap(), + "activity_log", + ); + command.harness = harness; + command.model = model; + command.effort = effort; + command.command_log = Some(path.clone()); Ok(Some(Started { subject: subject.into(), offset: *stamp.offset(), log: read_optional(&path)?, - command: Command { - repository: repository.into(), - kind: kind.into(), - issue: number.map(|number| Issue { - number, - url: format!("https://github.com/{repository}/issues/{number}"), - title: None, - }), - harness, - model, - effort, - started_at: time - .and_local_timezone(*stamp.offset()) - .single() - .unwrap() - .to_rfc3339(), - ended_at: None, - outcome: None, - command_log: Some(path), - session_logs: Vec::new(), - stages: [], - stage: None, - source: "activity_log", - state: "unknown", - }, + command, })) } @@ -259,29 +341,12 @@ fn sessions( { continue; } - let command = groups - .entry(command_log.clone()) - .or_insert_with(|| Command { - repository: repository.into(), - kind: kind.into(), - issue: number.map(|number| Issue { - number, - url: format!("https://github.com/{repository}/issues/{number}"), - title: None, - }), - harness: None, - model: None, - effort: None, - started_at: stamp.to_rfc3339(), - ended_at: None, - outcome: None, - command_log: command_log.is_file().then_some(command_log), - session_logs: Vec::new(), - stages: [], - stage: None, - source: "session_log", - state: "unknown", - }); + let command = groups.entry(command_log.clone()).or_insert_with(|| { + let mut command = + Command::from_logs(repository, kind, number, stamp, "session_log"); + command.command_log = command_log.is_file().then_some(command_log); + command + }); command.session_logs.push(entry.path()); } } diff --git a/tests/status.rs b/tests/status.rs index dc9b633f9..230b118ba 100644 --- a/tests/status.rs +++ b/tests/status.rs @@ -206,6 +206,115 @@ fn fixture_log(scenario: &Scenario, relative: &str, contents: &str) { fs::write(path, contents).unwrap(); } +#[test] +fn status_reads_activity_starts_from_before_harness_metadata() { + let scenario = Scenario::new(); + fixture_log( + &scenario, + "activity.log", + concat!( + "2026-10-04 12:00:00 Run #7 started: commands/issue/7-20261004T120000-0400.log\n", + "2026-10-04 13:00:00 Run #7 ended: PR https://github.com/acme/widgets/pull/1 is ready for review\n" + ), + ); + fixture_log( + &scenario, + "commands/issue/7-20261004T120000-0400.log", + "thirdshift: 13:00:00 PR https://github.com/acme/widgets/pull/1 is ready for review\n", + ); + fixture_log( + &scenario, + "commands/issue/7-20261004T120000-0400-implement.jsonl", + "{}\n", + ); + let result = scenario.run(&["status", "--all", "--json"]); + assert_eq!(result.code, Some(0), "{}", result.stderr); + let status: Value = serde_json::from_str(&result.stdout).unwrap(); + assert_eq!(status["commands"].as_array().unwrap().len(), 1); + let command = &status["commands"][0]; + assert_eq!(command["source"], "activity_log"); + assert_eq!(command["started_at"], "2026-10-04T12:00:00-04:00"); + assert_eq!(command["ended_at"], "2026-10-04T13:00:00-04:00"); + assert_eq!( + command["outcome"], + "PR https://github.com/acme/widgets/pull/1 is ready for review" + ); + assert_eq!(command["harness"], Value::Null); + assert_eq!(command["model"], Value::Null); + assert_eq!(command["effort"], Value::Null); +} + +#[test] +fn status_matches_overlapping_failures_using_command_log_endings() { + let scenario = Scenario::new(); + let first = chrono::Local::now() - chrono::Duration::hours(1); + let second = first + chrono::Duration::minutes(1); + let second_end = first + chrono::Duration::minutes(2); + let first_end = first + chrono::Duration::minutes(3); + let first_log = format!("commands/issue/7-{}.log", first.format("%Y%m%dT%H%M%S%z")); + let second_log = format!("commands/issue/7-{}.log", second.format("%Y%m%dT%H%M%S%z")); + // Identical causes require the Command log's ending time to distinguish + // them. Recovery details are part of the Activity summary only. + fixture_log( + &scenario, + "activity.log", + &format!( + "{} Run #7 started: {first_log}, on claude · default model · default effort\n{} Run #7 started: {second_log}, on claude · default model · default effort\n{} Run #7 ended: failed: claude exited 3; Stopped at: Implementation\n{} Run #7 ended: failed: claude exited 3\n", + first.format("%Y-%m-%d %H:%M:%S"), + second.format("%Y-%m-%d %H:%M:%S"), + second_end.format("%Y-%m-%d %H:%M:%S"), + first_end.format("%Y-%m-%d %H:%M:%S") + ), + ); + fixture_log( + &scenario, + &first_log, + &format!( + "thirdshift: {} claude exited 3\n", + first_end.format("%H:%M:%S") + ), + ); + fixture_log( + &scenario, + &second_log, + &format!( + "thirdshift: {} Stopped at: Implementation\nthirdshift: {} claude exited 3\n", + second_end.format("%H:%M:%S"), + second_end.format("%H:%M:%S") + ), + ); + for flags in [vec!["status", "--all", "--json"], vec!["status", "--json"]] { + let result = scenario.run(&flags); + assert_eq!(result.code, Some(0), "{}", result.stderr); + let status: Value = serde_json::from_str(&result.stdout).unwrap(); + let commands = status["commands"].as_array().unwrap(); + assert_eq!(commands.len(), 2); + assert_eq!( + commands[0]["outcome"], + "failed: claude exited 3; Stopped at: Implementation" + ); + assert_eq!(commands[1]["outcome"], "failed: claude exited 3"); + for command in commands { + assert_eq!(command["source"], "activity_log"); + assert_eq!(command["state"], "ended"); + assert!(command["ended_at"].is_string()); + } + // Activity times have second precision. + assert_eq!( + chrono::DateTime::parse_from_rfc3339(commands[0]["ended_at"].as_str().unwrap()) + .unwrap() + .timestamp(), + second_end.timestamp() + ); + assert_eq!( + chrono::DateTime::parse_from_rfc3339(commands[1]["ended_at"].as_str().unwrap()) + .unwrap() + .timestamp(), + first_end.timestamp() + ); + } +} + #[test] fn status_reads_activity_history_and_command_logs_without_stages() { let scenario = Scenario::new();