diff --git a/README.md b/README.md index 348328742..7e7852be5 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 Commands across every repository in `logs.dir`, with their issue and title when present, Harness, Model, Effort, current stage and its age. Architect runs, Pickup runs and Security runs nest the Run or Spec run they dispatch beneath themselves. A Pass with no issue is named by its kind and Command log stamp, such as `architect-20261018T120000-0400` or `secure-20261018T120000-0400`. 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 Commands across every repository in `logs.dir`, with their issue and title when present, Harness, Model, Effort, current stage and its age. Architect runs, Pickup runs and Security runs nest the Run or Spec run they dispatch beneath themselves. A Pass with no issue is named by its kind and Command log stamp, such as `architect-20261018T120000-0400` or `secure-20261018T120000-0400`. 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. For each repository and kind of Pass whose latest Activity log line is a skip, status also shows that Pass as idle with its reason, even when the skip is older than another kind's activity. A later start or end for that kind clears its idle entry. For example: @@ -98,12 +100,15 @@ Architect run idle on acme/widgets: Ready issue #7 "Make widgets" goes first: ht "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", "dispatched": [], "state": "live", "stage": {"name": "implement", "began_at": "2026-10-18T12:00:01-04:00", "age_seconds": 52} @@ -116,9 +121,11 @@ Architect run idle on acme/widgets: Ready issue #7 "Make widgets" goes first: ht } ``` -Times are RFC 3339; ages are nonnegative seconds. `model` and `effort` are null when left to the Harness. `issue` is null for a Pass with no issue; `session_log`, `issue_branch`, `pull_request`, `outcome` and `cause` are nullable. Command kinds are `Run`, `Spec run`, `Architect run`, `Pickup run` and `Security run`. `name` identifies an issue or a Pass's kind and stamp. `dispatched` is an array of the Run or Spec run a Pass dispatched, with the same fields as its parent (and an empty `dispatched` array); it shares the Pass's process identity. Its `state` may also be `ended`, and it retains its own outcome, cause, Issue branch and pull request. The retained Command record has the same fields, including dispatched work, without the computed `state` and `stage` or empty leaf `dispatched` arrays. `idle_passes` contains one entry per repository and kind whose latest Activity log line is a skip; it is independent of `commands`, and never creates a Command record or log for a skipped Pass. +Times are RFC 3339; ages are nonnegative seconds. `model` and `effort` are null when left to the Harness. `issue` is null for a Pass with no issue; `session_log`, `issue_branch`, `pull_request`, `outcome`, `cause` and `ended_at` are nullable. Command kinds are `Run`, `Spec run`, `Architect run`, `Pickup run` and `Security run`. `name` identifies an issue or a Pass's kind and stamp. `dispatched` is an array of the Run or Spec run a Pass dispatched, with the same fields as its parent (and an empty `dispatched` array); it shares the Pass's process identity and Command log. It retains its own outcome, end time, cause, Issue branch and pull request. The retained Command record has the same fields, including dispatched work, without the computed `state`, `stage`, `source` and `command_log` or empty leaf `dispatched` arrays. Older records without an end time use their last modification time. `idle_passes` contains one entry per repository and kind whose latest Activity log line is a skip; it is independent of `commands`, and never creates a Command record or log for a skipped Pass. + +`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`, `cleanup`, `Tickets`, `Spec review`, `Architecture review`, `Security audit`, `Security reproduction` and `Security fix publishing`. A Pass retains its own stages while its dispatched work records its stages separately. The remaining Command views are tracked in [#711](https://github.com/JacobStephens2/thirdshift/issues/711). -`state` is `live` or `died` for an unfinished Command; `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`, `cleanup`, `Tickets`, `Spec review`, `Architecture review`, `Security audit`, `Security reproduction` and `Security fix publishing`. A Pass retains its own stages while its dispatched work records its stages separately. History and the remaining Command views are tracked in [#711](https://github.com/JacobStephens2/thirdshift/issues/711). +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 a6fce0d22..1924593c9 100644 --- a/src/logs/command_record.rs +++ b/src/logs/command_record.rs @@ -41,6 +41,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, @@ -161,6 +163,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, @@ -178,7 +181,8 @@ impl CommandRecord { .find(|stage| StageName::known(&stage.name)) } - pub fn finish(&mut self, account: &crate::run_ending::Account<'_>) { + pub fn finish(&mut self, account: &crate::run_ending::Account<'_>, now: DateTime) { + self.ended_at = Some(now.to_rfc3339()); self.outcome = Some(account.outcome.into()); self.cause = account .ended diff --git a/src/logs/recording.rs b/src/logs/recording.rs index cdd7bb04d..2c7aca2d0 100644 --- a/src/logs/recording.rs +++ b/src/logs/recording.rs @@ -249,7 +249,7 @@ impl Record { pub(super) fn finished(&mut self, account: &crate::run_ending::Account<'_>) { if let Some((_, tree)) = &mut self.command_record { - tree.command.finish(account); + tree.command.finish(account, self.outside.now()); self.write_record(); } } @@ -258,7 +258,7 @@ impl Record { if let Some((_, tree)) = &mut self.command_record && let Some(dispatched) = tree.dispatched.last_mut() { - dispatched.finish(account); + dispatched.finish(account, self.outside.now()); self.write_record(); } } diff --git a/src/logs/status.rs b/src/logs/status.rs index 04cc2e85d..bc2f4c56a 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}; @@ -16,7 +19,7 @@ use crate::config::UserConfig; struct Status { version: u32, hostname: String, - commands: Vec, + commands: Vec, idle_passes: Vec, } @@ -27,12 +30,50 @@ struct IdlePass { reason: String, } +#[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)] struct Command { #[serde(flatten)] record: CommandRecord, state: &'static str, stage: Option, + source: &'static str, + command_log: PathBuf, dispatched: Vec, } @@ -44,7 +85,7 @@ struct CurrentStage { } impl Command { - fn new(record: CommandRecord, now: DateTime) -> Self { + fn new(record: CommandRecord, command_log: PathBuf, now: DateTime) -> Self { let state = if record.outcome.is_some() { "ended" } else if record.live(&mut OnMachine) { @@ -63,22 +104,26 @@ impl Command { record, state, stage, + source: "command_record", + command_log, dispatched: Vec::new(), } } fn print(&self, indent: &str) { let facts = &self.record; - let stage = self.stage.as_ref().map_or_else( - || "starting".into(), - |stage| { - if self.state == "died" { - format!("died at {}", stage.name) - } else { - format!("{} · {}", stage.name, age(stage.age_seconds)) - } - }, - ); + let stage = facts.outcome.clone().unwrap_or_else(|| { + self.stage.as_ref().map_or_else( + || "starting".into(), + |stage| { + if self.state == "died" { + format!("died at {}", stage.name) + } else { + format!("{} · {}", stage.name, age(stage.age_seconds)) + } + }, + ) + }); let subject = match &facts.issue { Some(issue) => format!( "{}#{} {}", @@ -100,56 +145,71 @@ impl Command { } } -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(); let mut idle_passes = Vec::new(); for owner in directories(&config.logs_dir)? { for repo in directories(&owner)? { + let mut covered = HashSet::new(); idle_passes.extend(read_idle_passes(&repo)?); 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(tree) = serde_json::from_slice::(&bytes) else { + let Ok(mut tree) = serde_json::from_slice::(&bytes) else { continue; }; - let record = tree.command; - if record.version != 1 || record.outcome.is_some() { + let record = &mut tree.command; + if record.version != 1 { + continue; + } + 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 mut command = Command::new(record, now); + let mut command = Command::new(tree.command, command_log.clone(), now); command.dispatched = tree .dispatched .into_iter() - .map(|record| Command::new(record, now)) + .map(|record| Command::new(record, command_log.clone(), now)) .collect(); - commands.push(command); + commands.push(Entry::Record(Box::new(command))); } } + 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))); idle_passes.sort_by(|a, b| (&a.repository, &a.kind).cmp(&(&b.repository, &b.kind))); let status = Status { version: 1, @@ -161,8 +221,11 @@ pub fn show(json: bool) -> Result<()> { println!("{}", serde_json::to_string_pretty(&status)?); } else { println!("{}", status.hostname); - for command in &status.commands { - command.print(""); + for entry in status.commands { + match entry { + Entry::Record(command) => command.print(""), + Entry::History(command) => command.print(), + } } for pass in status.idle_passes { println!("{} idle on {}: {}", pass.kind, pass.repository, pass.reason); @@ -171,6 +234,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 read_idle_passes(repo: &Path) -> Result> { let path = repo.join(activity::FILE); let activity = match fs::read_to_string(&path) { diff --git a/src/logs/status/history.rs b/src/logs/status/history.rs new file mode 100644 index 000000000..563a1f639 --- /dev/null +++ b/src/logs/status/history.rs @@ -0,0 +1,369 @@ +//! 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, NaiveTime}; +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 { + 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 + .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, +} + +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!( + "{}/{}", + 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 matches: Vec<_> = 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]; + 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); + } + // 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 + .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() + .filter(|name| !name.is_empty()) + .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); + 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, + })) +} + +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(|| { + 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()); + } + } + 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 438bc0424..8146cfa08 100644 --- a/tests/status.rs +++ b/tests/status.rs @@ -55,6 +55,35 @@ fn status_shows_each_idle_pass_until_its_own_kind_starts_work() { let idle = status["idle_passes"].as_array().unwrap(); assert_eq!(idle.len(), 2, "{status}"); assert!(!idle.iter().any(|pass| pass["kind"] == "Pickup run")); + for flags in [ + ["status", "--json"].as_slice(), + &["status", "--all", "--json"], + ] { + let result = scenario.run(flags); + 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, "{status}"); + let pass = &status["commands"][0]; + assert_eq!(pass["kind"], "Pickup run"); + let dispatched = &pass["dispatched"][0]; + assert_eq!(dispatched["issue"]["number"], 7); + assert_eq!(dispatched["command_log"], pass["command_log"]); + for command in [pass, dispatched] { + assert_eq!(command["source"], "command_record"); + assert_eq!(command["state"], "ended"); + assert_eq!(command["outcome"], "ready for review"); + assert!( + chrono::DateTime::parse_from_rfc3339(command["ended_at"].as_str().unwrap()).is_ok() + ); + } + } + let text = scenario.run(&["status"]); + let dispatched = text + .stdout + .lines() + .find(|line| line.starts_with(" acme/widgets#7")) + .expect(&text.stdout); + assert!(dispatched.ends_with("ready for review"), "{dispatched}"); } #[test] @@ -80,13 +109,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); @@ -108,7 +142,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 = scenario.command_record(LOGS); assert_eq!(record["outcome"], "ready for review"); assert_eq!(record["cause"], Value::Null); @@ -172,11 +209,355 @@ 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_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(); + 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();