diff --git a/src/child_run.rs b/src/child_run.rs index a3de55f5b..8a9d0b7bc 100644 --- a/src/child_run.rs +++ b/src/child_run.rs @@ -302,7 +302,7 @@ pub fn start( ) -> Result { let given = Given { kind, - stamp: logs::stamp().to_string(), + stamp: logs::stamp(), base_fix, harness: harness.clone(), }; diff --git a/src/logs.rs b/src/logs.rs index b4150d19e..fffe9cd67 100644 --- a/src/logs.rs +++ b/src/logs.rs @@ -8,22 +8,25 @@ //! skipped pass shows. Everything it prints goes through [`print`] and //! [`eprint`], which keep it in the Command log too. //! -//! The state is process-wide, as a command is one process: the stamp, the -//! lines held so far, the logs directory and the work started. +//! One owned recording implementation holds the complete lifecycle. The +//! process-wide interface serializes its operations, including emitted output. mod activity; mod command_log; +mod effects; +mod recording; use std::fmt::Display; use std::path::{Path, PathBuf}; -use std::sync::{Mutex, MutexGuard, PoisonError}; +use std::sync::{LazyLock, Mutex, MutexGuard, PoisonError}; use crate::config::UserConfig; use crate::harness::Choice; use crate::issue::{IssueUrl, Repo}; -use crate::progress; use activity::Kind; +use effects::OnMachine; +use recording::Record; /// How a command begins. pub enum Begin<'a> { @@ -59,22 +62,9 @@ pub enum Pass { PickupRun, } -/// What this command has recorded so far, beyond its Command log. -struct Record { - /// The User config's `logs.dir`, once [`configured`]. - logs_dir: Option, - /// Whether this is a child Run, which records no work. - child: bool, - /// Whether [`started`] has been called. - started: bool, -} - -/// This command's [`Record`]. -static RECORD: Mutex = Mutex::new(Record { - logs_dir: None, - child: false, - started: false, -}); +/// The production command's complete record, shared with reader threads. +static RECORD: LazyLock>> = + LazyLock::new(|| Mutex::new(Record::new(OnMachine))); /// Begin the command as `begin` says. A Run or a pass makes its stamp now /// and prints its first line, dated, as in `starting on , @@ -83,15 +73,7 @@ static RECORD: Mutex = Mutex::new(Record { /// shows them, so a skipped pass may print nothing. A child Run prints no /// such line, and takes the stamp it was given. pub fn begin(begin: Begin) { - match begin { - Begin::Run(issue) => command_log::begin(format_args!("starting on {}", issue.url), false), - Begin::ChildRun(stamp) => { - record().child = true; - command_log::begin_child(stamp); - } - Begin::ArchitectRun => command_log::begin("Architect run starting", true), - Begin::PickupRun => command_log::begin("Pickup run starting", true), - } + record().begin(begin); } /// Take `config`'s `logs.dir` as the root of the logs, and, unless its @@ -100,10 +82,7 @@ pub fn begin(begin: Begin) { /// held until it starts work, ends or fails, so a skipped pass prints /// nothing. pub fn configured(config: &UserConfig) { - record().logs_dir = Some(config.logs_dir.clone()); - if !config.quiet_skips { - command_log::show_held(); - } + record().configured(config); } /// Record that the command starts `work`, its sessions on `harness`: keep its @@ -114,13 +93,7 @@ pub fn configured(config: &UserConfig) { /// covers the Run it dispatches, and a child Run records nothing, as the /// command that started it does. pub fn started(work: Work, harness: &Choice) { - if !record().take_start() { - return; - } - let root = work.root(); - command_log::keep(work.command_log(&root, command_log::stamp())); - progress::step(format_args!("sessions run on {harness}")); - activity::start(&root, work.kind(), work.issue(), harness); + record().started(work, harness); } /// Record that `pass` was skipped on `repo` for `reason`, unless the last @@ -128,11 +101,7 @@ pub fn started(work: Work, harness: &Choice) { /// under `activity.quiet_skips`, whatever the pass prints about its skip /// stays held, and is dropped with the Command log it never kept. pub fn skipped(pass: Pass, repo: &Repo, reason: impl Display) { - let kind = match pass { - Pass::ArchitectRun => Kind::ArchitectRun, - Pass::PickupRun => Kind::PickupRun, - }; - activity::skip(&root(repo), kind, reason); + record().skipped(pass, repo, reason); } /// Record how the command ended, `outcome` in short: show any lines held @@ -140,14 +109,13 @@ pub fn skipped(pass: Pass, repo: &Repo, reason: impl Display) { /// work. A skipped pass never calls it, so that under /// `activity.quiet_skips` its lines stay held. pub fn ended(outcome: impl Display) { - command_log::show_held(); - activity::end(outcome); + record().ended(outcome); } /// Print the lines held from the terminal, as before a failure, and print /// every line from here on. pub fn show_held() { - command_log::show_held(); + record().show_held(); } /// The root of `repo`'s logs: `///`, named for the @@ -159,33 +127,28 @@ pub fn show_held() { /// /// Before [`configured`], which is a programming error. pub fn root(repo: &Repo) -> PathBuf { - let record = record(); - let logs_dir = record - .logs_dir - .as_deref() - .expect("the root of a repository's logs is asked for before the User config is loaded"); - root_under(logs_dir, repo) + record().root(repo) } /// The command's start stamp, as in `20261003T120000-0400`, which names its /// Command log and its Session logs. -pub fn stamp() -> &'static str { - command_log::stamp() +pub fn stamp() -> String { + record().stamp() } /// Where the Command log is, if this command created one. pub fn command_log_path() -> Option { - command_log::path() + record().command_log_path() } /// Print `line` on stderr, and keep it in the Command log. pub fn eprint(line: &str) { - command_log::eprint(line); + record().eprint(line); } /// Print `line` on stdout, and keep it in the Command log. pub fn print(line: &str) { - command_log::print(line); + record().print(line); } /// [`root`], under `logs_dir`. @@ -193,22 +156,12 @@ fn root_under(logs_dir: &Path, repo: &Repo) -> PathBuf { logs_dir.join(&repo.owner).join(&repo.name) } -impl Record { - /// Take note that work started, and say whether it is the work to - /// record: the first, and not in a child Run. - fn take_start(&mut self) -> bool { - let first = !self.started; - self.started = true; - first && !self.child - } -} - impl Work<'_> { - /// The root of its repository's logs. - fn root(self) -> PathBuf { + /// The repository whose work it records. + fn repo(self) -> Repo { match self { - Work::Run(issue) | Work::SpecRun(issue) | Work::PickupRun(issue) => root(&issue.repo()), - Work::ArchitectRun(repo) => root(repo), + Work::Run(issue) | Work::SpecRun(issue) | Work::PickupRun(issue) => issue.repo(), + Work::ArchitectRun(repo) => repo.clone(), } } @@ -250,74 +203,6 @@ impl Work<'_> { } /// The [`Record`], locked, even if a thread panicked holding it. -fn record() -> MutexGuard<'static, Record> { +fn record() -> MutexGuard<'static, Record> { RECORD.lock().unwrap_or_else(PoisonError::into_inner) } - -#[cfg(test)] -mod tests { - use super::*; - - const STAMP: &str = "20261003T120000-0400"; - - fn issue(number: u64) -> IssueUrl { - IssueUrl::parse(&format!("https://github.com/acme/widgets/issues/{number}")).unwrap() - } - - #[test] - fn each_kind_of_works_command_log_is_in_its_commands_folder_with_the_stamp() { - let root = Path::new("/logs/acme/widgets"); - let issue = issue(7); - let repo = issue.repo(); - for (work, path) in [ - ( - Work::Run(&issue), - "commands/issue/7-20261003T120000-0400.log", - ), - ( - Work::SpecRun(&issue), - "commands/issue/7-20261003T120000-0400.log", - ), - ( - Work::PickupRun(&issue), - "commands/pickup/7-20261003T120000-0400.log", - ), - ( - Work::ArchitectRun(&repo), - "commands/architect/20261003T120000-0400.log", - ), - ] { - assert_eq!(work.command_log(root, STAMP), root.join(path)); - } - } - - #[test] - fn the_root_of_a_repositorys_logs_is_named_for_its_owner_and_name() { - assert_eq!( - root_under(Path::new("/logs"), &issue(7).repo()), - Path::new("/logs/acme/widgets") - ); - } - - #[test] - fn only_the_first_work_started_is_recorded() { - let mut record = Record { - logs_dir: None, - child: false, - started: false, - }; - assert!(record.take_start()); - assert!(!record.take_start()); - } - - #[test] - fn a_child_run_records_no_work_it_take_start() { - let mut record = Record { - logs_dir: None, - child: true, - started: false, - }; - assert!(!record.take_start()); - assert!(!record.take_start()); - } -} diff --git a/src/logs/activity.rs b/src/logs/activity.rs index a6847d70a..c34c287ef 100644 --- a/src/logs/activity.rs +++ b/src/logs/activity.rs @@ -1,45 +1,20 @@ -//! The Activity log: one running record per repository, `activity.log` at -//! the root of its logs, of what the factory did there. A Run, a Spec run, -//! an Architect run or a Pickup run writes a line when it starts work, -//! naming its Command log, and one when it ends, with its outcome. A skipped -//! Architect run or Pickup run writes one only when its reason differs from -//! the last line of its own kind in the file, so a repository that sits idle -//! shows one line, not one per pass. Which work writes its lines is -//! [`super::started`]'s to say. -//! -//! Every line starts with the local date and time, then the kind. Each is -//! appended whole, in one write, so passes on one repository that run at -//! once never interleave within a line. A line that can't be written is one -//! `warning:` line, and changes nothing else. +//! Stateless Activity log formatting and file effects. The recording owner +//! decides starts, endings, shared skip history and warning suppression. use std::fmt::{self, Display}; use std::fs::{self, File, OpenOptions}; -use std::io::{Read, Seek, SeekFrom, Write}; -use std::path::{Path, PathBuf}; -use std::sync::OnceLock; -use std::sync::atomic::{AtomicBool, Ordering}; +use std::io::{Read, Seek, SeekFrom}; +use std::path::Path; use anyhow::{Context, Result}; -use chrono::Local; -use super::command_log; -use crate::harness::Choice; -use crate::progress; +use super::effects::Tail; -/// The file's name, at the root of a repository's logs. -const FILE: &str = "activity.log"; - -/// How a line's time is written: local, as in `2026-10-03 10:41:01`. -const TIME_FORMAT: &str = "%Y-%m-%d %H:%M:%S"; - -/// How long a line's time is, as [`TIME_FORMAT`] writes it. +pub(super) const FILE: &str = "activity.log"; +pub(super) const TIME_FORMAT: &str = "%Y-%m-%d %H:%M:%S"; +pub(super) const TAIL: u64 = 64 * 1024; const TIME_FORMAT_LENGTH: usize = "2026-10-03 10:41:01".len(); -/// How much of the end of the file is read to find a kind's last line. A -/// pass writes a line or two, so this reaches back over thousands of passes. -const TAIL: u64 = 64 * 1024; - -/// What a line is about: the command that wrote it. #[derive(Debug, Clone, Copy, PartialEq, Eq)] pub(super) enum Kind { Run, @@ -59,125 +34,33 @@ impl Display for Kind { } } -/// The work this command started, once it has: where its end line goes. -struct Started { - root: PathBuf, - kind: Kind, - issue: Option, -} - -/// The work this command started, once [`start`] has recorded it. -static STARTED: OnceLock = OnceLock::new(); - -/// Whether the warning that the Activity log can't be written was given. -static WARNED: AtomicBool = AtomicBool::new(false); - -/// Record that this command, a `kind` on `issue`, if it has one, starts work -/// on the repository whose logs are at `root`, naming its Command log, if it -/// keeps one, and the Harness, Model and Effort of `harness`, as in -/// `Run #7 started: commands/issue/7-.log, on claude · opus · high`. -/// Only once: [`end`] then writes its end line. -pub(super) fn start(root: &Path, kind: Kind, issue: Option, harness: &Choice) { - let command_log = match command_log::path() { - Some(path) => path - .strip_prefix(root) - .unwrap_or(&path) - .display() - .to_string(), - None => "no Command log".to_string(), - }; - let started = Started { - root: root.to_path_buf(), - kind, - issue, - }; - let line = format!("{} started: {command_log}, on {harness}", started.subject()); - if STARTED.set(started).is_ok() { - write(root, &line, None); - } -} - -/// Record how the work [`start`] recorded ended, `outcome` in short. Nothing -/// if this command started none. -pub(super) fn end(outcome: impl Display) { - if let Some(started) = STARTED.get() { - let line = format!("{} ended: {outcome}", started.subject()); - write(&started.root, &line, None); - } -} - -/// Record that this command, a `kind`, was skipped on the repository whose -/// logs are at `root`, for `reason`, unless the last line of its kind there -/// already says so. -pub(super) fn skip(root: &Path, kind: Kind, reason: impl Display) { - write(root, &format!("{kind} skipped: {reason}"), Some(kind)); -} - -impl Started { - /// What its lines start with, after the time: its kind, and its issue. - fn subject(&self) -> String { - match self.issue { - Some(number) => format!("{} #{number}", self.kind), - None => self.kind.to_string(), - } - } -} - -/// Append `line`, stamped with the time now, to the Activity log at `root`, -/// creating its folder if missing. With `unless_last_of`, not if it is -/// already the last line of that kind. A failure is the one warning. -fn write(root: &Path, line: &str, unless_last_of: Option) { - let appended = append(&root.join(FILE), line, unless_last_of); - if let Err(error) = appended - && !WARNED.swap(true, Ordering::Relaxed) - { - // A warning shows even on a pass that holds its lines quiet. - command_log::show_held(); - progress::step(format_args!( - "warning: could not keep the Activity log: {error:#}" - )); - } -} - -/// [`write`], its error returned. -fn append(path: &Path, line: &str, unless_last_of: Option) -> Result<()> { +pub(super) fn open(path: &Path) -> Result { if let Some(dir) = path.parent() { fs::create_dir_all(dir).with_context(|| format!("could not create {}", dir.display()))?; } - let mut file = OpenOptions::new() + OpenOptions::new() .read(true) .append(true) .create(true) .open(path) - .with_context(|| format!("could not open {}", path.display()))?; - if let Some(kind) = unless_last_of { - let tail = tail(&mut file).with_context(|| format!("could not read {}", path.display()))?; - if last_of(&tail, kind) == Some(line) { - return Ok(()); - } - } - let stamped = format!("{} {line}\n", Local::now().format(TIME_FORMAT)); - file.write_all(stamped.as_bytes()) - .with_context(|| format!("could not write {}", path.display())) + .with_context(|| format!("could not open {}", path.display())) } -/// The whole lines in the last [`TAIL`] bytes of `file`. -fn tail(file: &mut File) -> std::io::Result { - let length = file.metadata()?.len(); - let from = length.saturating_sub(TAIL); - file.seek(SeekFrom::Start(from))?; - let mut bytes = Vec::new(); - file.read_to_end(&mut bytes)?; - let text = String::from_utf8_lossy(&bytes).into_owned(); - Ok(match (from, text.split_once('\n')) { - // Read from mid-file: the first line may be cut short. - (1.., Some((_, rest))) => rest.to_string(), - _ => text, - }) +/// Raw bytes at the end of the file. The owner discards a cut first line. +pub(super) fn tail(path: &Path, limit: u64) -> Result { + let mut file = open(path)?; + let mut read = || -> std::io::Result { + let from = file.metadata()?.len().saturating_sub(limit); + file.seek(SeekFrom::Start(from))?; + let mut bytes = Vec::new(); + file.read_to_end(&mut bytes)?; + Ok(Tail { from, bytes }) + }; + read().with_context(|| format!("could not read {}", path.display())) } -/// The last line of `kind` in `tail`, without its time. -fn last_of(tail: &str, kind: Kind) -> Option<&str> { +/// The last line of `kind` in whole lines from the tail, without its time. +pub(super) fn last_of(tail: &str, kind: Kind) -> Option<&str> { let kind = kind.to_string(); tail.lines().rev().find_map(|line| { let unstamped = line.get(TIME_FORMAT_LENGTH + 1..)?; @@ -185,36 +68,3 @@ fn last_of(tail: &str, kind: Kind) -> Option<&str> { (rest.starts_with(' ') || rest.starts_with(':')).then_some(unstamped) }) } - -#[cfg(test)] -mod tests { - use super::*; - - #[test] - fn a_kinds_last_line_is_found_past_other_kinds_without_its_time() { - let tail = "\ -2026-10-03 10:00:00 Pickup run skipped: no Ready issue on acme/widgets -2026-10-03 10:00:01 Architect run skipped: a plan is open -2026-10-03 10:01:00 Run #7 started: commands/issue/7-x.log -"; - assert_eq!( - last_of(tail, Kind::PickupRun), - Some("Pickup run skipped: no Ready issue on acme/widgets") - ); - assert_eq!( - last_of(tail, Kind::ArchitectRun), - Some("Architect run skipped: a plan is open") - ); - assert_eq!( - last_of(tail, Kind::Run), - Some("Run #7 started: commands/issue/7-x.log") - ); - assert_eq!(last_of(tail, Kind::SpecRun), None); - } - - #[test] - fn a_line_cut_short_or_with_no_time_is_never_a_kinds_last_line() { - assert_eq!(last_of("Pickup run skipped\n", Kind::PickupRun), None); - assert_eq!(last_of("", Kind::PickupRun), None); - } -} diff --git a/src/logs/command_log.rs b/src/logs/command_log.rs index da90181b7..a92cac215 100644 --- a/src/logs/command_log.rs +++ b/src/logs/command_log.rs @@ -1,226 +1,14 @@ -//! The command this process runs, when it is a Run, a Spec run, an Architect -//! run or a Pickup run: the stamp it started at, which names its Command log -//! and every Session log under it, and its Command log, a file of everything -//! it printed, stderr and stdout in the order printed. The terminal shows -//! everything as it would without one. -//! -//! The process the user or cron started keeps the Command log. A child Run -//! keeps none, but takes the stamp of the command that started it: its lines -//! reach that command's stderr through the relay, and from there its Command -//! log. A command's lines are held from its start until it starts work and -//! the file's name is known, then written first, so a command that ends -//! before then, as a skipped Pickup run or a Run that fails on Origin match -//! does, never creates the file. A Command log that can't be written is one -//! `warning:` line, and changes nothing else. -//! -//! An Architect run or a Pickup run, which may yet be skipped, holds its -//! lines from the terminal too, until it knows it will print them: a -//! skipped pass with `activity.quiet_skips` set prints nothing at all. +//! Stateless Command log file effects. The recording owner decides its +//! path, held lines, lifetime and warning policy. -use std::fmt::Display; use std::fs::{self, File}; -use std::io::Write; -use std::path::{Path, PathBuf}; -use std::sync::{Mutex, MutexGuard, OnceLock, PoisonError}; +use std::path::Path; use anyhow::{Context, Result}; -use chrono::Local; -use crate::progress; - -/// How a stamp is written: local time with its UTC offset, as in -/// `20261003T120000-0400`. -const STAMP_FORMAT: &str = "%Y%m%dT%H%M%S%z"; - -/// The command's start stamp, made once. -static STARTED: OnceLock = OnceLock::new(); - -/// The Command log, if this command keeps one. -static LOG: Mutex = Mutex::new(Log::NotKept); - -/// Where a Command log stands. -enum Log { - /// The command keeps none: a child Run, or a command such as `setup`. - NotKept, - /// Its lines so far, held until its name is known, each with the - /// stream it is for, and whether they have been printed there yet. - Held { - lines: Vec<(Stream, String)>, - shown: bool, - }, - /// Being written to `file`, at `path`. - Kept { path: PathBuf, file: File }, - /// It could not be written, and the warning has been given. `path` is - /// the file, if it was created. - Failed { path: Option }, -} - -/// Begin a command that keeps a Command log: make its stamp now, hold its -/// lines from here on, from the terminal too if `from_terminal`, until -/// [`show_held`] or [`keep`] prints them, and print its first progress line, -/// `, ` followed by the date and UTC offset, as in `Pickup run -/// starting, 2026-10-03 -0400`. -pub(super) fn begin(starting: impl Display, from_terminal: bool) { - let now = Local::now(); - let _ = STARTED.set(now.format(STAMP_FORMAT).to_string()); - *log() = Log::Held { - lines: Vec::new(), - shown: !from_terminal, - }; - progress::step(format_args!("{starting}, {}", now.format("%Y-%m-%d %z"))); -} - -/// Print the lines held from the terminal, if any, and print lines as they -/// come from here on. -pub(super) fn show_held() { - if let Log::Held { lines, shown } = &mut *log() - && !*shown - { - for (stream, line) in lines.iter() { - stream.print(line); - } - *shown = true; - } -} - -/// Begin a child Run, which keeps no Command log, with the `stamp` the -/// command that started it gave it. -pub(super) fn begin_child(stamp: &str) { - let _ = STARTED.set(stamp.to_string()); -} - -/// The command's start stamp, as in `20261003T120000-0400`: made by -/// [`begin`], given by [`begin_child`], or else made now. -pub(super) fn stamp() -> &'static str { - STARTED.get_or_init(|| Local::now().format(STAMP_FORMAT).to_string()) -} - -/// Create the Command log at `path`, its folder too if missing, with the -/// lines held so far, and say where it is. Only a command [`begin`] began, -/// and only once: any later call does nothing. One that can't be created is -/// a warning, and the command carries on without it. -pub(super) fn keep(path: PathBuf) { - show_held(); - let created = { - let mut log = log(); - let Log::Held { lines, .. } = &*log else { - return; - }; - let created = create(&path, lines.iter().map(|(_, line)| line)); - *log = match &created { - Ok(file) => Log::Kept { - path: path.clone(), - file: file.try_clone().expect("a created file can be cloned"), - }, - // A file created but not written is still where to look. - Err(_) => Log::Failed { - path: path.exists().then(|| path.clone()), - }, - }; - created - }; - match created { - Ok(_) => progress::step(format_args!("logging this command to {}", path.display())), - Err(error) => warn(&error), - } -} - -/// The file at `path`, created with its folder, and the `held` lines written. -fn create<'a>(path: &Path, held: impl Iterator) -> Result { +pub(super) fn open(path: &Path) -> Result { if let Some(dir) = path.parent() { fs::create_dir_all(dir).with_context(|| format!("could not create {}", dir.display()))?; } - let mut file = - File::create(path).with_context(|| format!("could not create {}", path.display()))?; - for line in held { - writeln!(file, "{line}").with_context(|| format!("could not write {}", path.display()))?; - } - Ok(file) -} - -/// Where the Command log is, if this command created one. -pub(super) fn path() -> Option { - match &*log() { - Log::Kept { path, .. } => Some(path.clone()), - Log::Failed { path } => path.clone(), - Log::NotKept | Log::Held { .. } => None, - } -} - -/// Print `line` on stderr, and keep it in the Command log. -pub(super) fn eprint(line: &str) { - print_to(Stream::Stderr, line); -} - -/// Print `line` on stdout, and keep it in the Command log. -pub(super) fn print(line: &str) { - print_to(Stream::Stdout, line); -} - -/// Where on the terminal a line goes. -#[derive(Clone, Copy)] -enum Stream { - Stdout, - Stderr, -} - -impl Stream { - /// Print `line` here. Ignored if it fails, as it does once the terminal - /// has closed: the Run still has to clean up and send its Run - /// notification. - fn print(self, line: &str) { - fn to(mut terminal: impl Write, line: &str) { - let _ = writeln!(terminal, "{line}"); - let _ = terminal.flush(); - } - match self { - Stream::Stdout => to(std::io::stdout(), line), - Stream::Stderr => to(std::io::stderr(), line), - } - } -} - -/// Print `line` to `stream`, unless it is held from the terminal, and keep it -/// in the Command log, both under the one lock, so the file has the lines in -/// the order they were printed. -fn print_to(stream: Stream, line: &str) { - let failed = { - let mut log = log(); - if !matches!(&*log, Log::Held { shown: false, .. }) { - stream.print(line); - } - match &mut *log { - Log::NotKept | Log::Failed { .. } => None, - Log::Held { lines, .. } => { - lines.push((stream, line.to_string())); - None - } - Log::Kept { path, file } => match writeln!(file, "{line}") { - Ok(()) => None, - Err(error) => { - let error = anyhow::Error::new(error) - .context(format!("could not write {}", path.display())); - *log = Log::Failed { - path: Some(path.clone()), - }; - Some(error) - } - }, - } - }; - if let Some(error) = failed { - warn(&error); - } -} - -/// The one warning that the Command log can't be written, for `error`. -fn warn(error: &anyhow::Error) { - progress::step(format_args!( - "warning: could not keep the Command log: {error:#}" - )); -} - -/// The Command log, locked, even if a thread panicked holding it. -fn log() -> MutexGuard<'static, Log> { - LOG.lock().unwrap_or_else(PoisonError::into_inner) + File::create(path).with_context(|| format!("could not create {}", path.display())) } diff --git a/src/logs/effects.rs b/src/logs/effects.rs new file mode 100644 index 000000000..ca958e8e9 --- /dev/null +++ b/src/logs/effects.rs @@ -0,0 +1,73 @@ +//! The complete record's private clock, terminal and file seam. Adapters +//! perform effects only; none can call the process-wide recording interface. + +use std::fs::File; +use std::io::{self, Write}; +use std::path::Path; + +use anyhow::{Context, Result}; +use chrono::{DateTime, FixedOffset, Local}; + +use super::{activity, command_log}; + +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub(super) enum Stream { + Stdout, + Stderr, +} + +pub(super) struct Tail { + pub from: u64, + pub bytes: Vec, +} + +pub(super) trait Outside { + type CommandLog: Write + Send; + + fn now(&mut self) -> DateTime; + fn emit(&mut self, stream: Stream, line: &str) -> io::Result<()>; + fn open_command_log(&mut self, path: &Path) -> Result; + fn command_log_exists(&mut self, path: &Path) -> bool; + fn activity_tail(&mut self, path: &Path, limit: u64) -> Result; + fn append_activity(&mut self, path: &Path, line: &str) -> Result<()>; +} + +pub(super) struct OnMachine; + +impl Outside for OnMachine { + type CommandLog = File; + + fn now(&mut self) -> DateTime { + Local::now().fixed_offset() + } + + fn emit(&mut self, stream: Stream, line: &str) -> io::Result<()> { + fn to(mut terminal: impl Write, line: &str) -> io::Result<()> { + let written = writeln!(terminal, "{line}"); + let flushed = terminal.flush(); + written.and(flushed) + } + match stream { + Stream::Stdout => to(io::stdout(), line), + Stream::Stderr => to(io::stderr(), line), + } + } + + fn open_command_log(&mut self, path: &Path) -> Result { + command_log::open(path) + } + + fn command_log_exists(&mut self, path: &Path) -> bool { + path.exists() + } + + fn activity_tail(&mut self, path: &Path, limit: u64) -> Result { + activity::tail(path, limit) + } + + fn append_activity(&mut self, path: &Path, line: &str) -> Result<()> { + activity::open(path)? + .write_all(line.as_bytes()) + .with_context(|| format!("could not write {}", path.display())) + } +} diff --git a/src/logs/recording.rs b/src/logs/recording.rs new file mode 100644 index 000000000..094d94dd7 --- /dev/null +++ b/src/logs/recording.rs @@ -0,0 +1,306 @@ +//! One Command's owned recording implementation. Production and tests use +//! these same operations; only the effects adapter differs. + +use std::collections::VecDeque; +use std::fmt::Display; +use std::io::Write; +use std::path::{Path, PathBuf}; + +use anyhow::{Context, Result}; + +use super::activity::{self, Kind}; +use super::effects::{Outside, Stream}; +use super::{Begin, Pass, Work, root_under}; +use crate::config::UserConfig; +use crate::harness::Choice; +use crate::issue::Repo; +use crate::progress; + +const STAMP_FORMAT: &str = "%Y%m%dT%H%M%S%z"; + +pub(super) struct Record { + outside: O, + stamp: Option, + logs_dir: Option, + child: bool, + started: bool, + command_log: Log, + activity_started: Option, + activity_warned: bool, +} + +enum Log { + NotKept, + Held { + lines: Vec<(Stream, String)>, + shown: bool, + }, + Kept { + path: PathBuf, + writer: W, + }, + Failed { + path: Option, + }, +} + +struct Started { + root: PathBuf, + kind: Kind, + issue: Option, +} + +impl Started { + fn subject(&self) -> String { + match self.issue { + Some(number) => format!("{} #{number}", self.kind), + None => self.kind.to_string(), + } + } +} + +impl Record { + pub(super) fn new(outside: O) -> Self { + Self { + outside, + stamp: None, + logs_dir: None, + child: false, + started: false, + command_log: Log::NotKept, + activity_started: None, + activity_warned: false, + } + } + + pub(super) fn begin(&mut self, begin: Begin) { + let (starting, quiet) = match begin { + Begin::ChildRun(stamp) => { + self.child = true; + self.stamp.get_or_insert_with(|| stamp.to_string()); + return; + } + Begin::Run(issue) => (format!("starting on {}", issue.url), false), + Begin::ArchitectRun => ("Architect run starting".into(), true), + Begin::PickupRun => ("Pickup run starting".into(), true), + }; + let now = self.outside.now(); + self.stamp + .get_or_insert_with(|| now.format(STAMP_FORMAT).to_string()); + self.command_log = Log::Held { + lines: Vec::new(), + shown: !quiet, + }; + self.step(format_args!("{starting}, {}", now.format("%Y-%m-%d %z"))); + } + + pub(super) fn configured(&mut self, config: &UserConfig) { + self.logs_dir = Some(config.logs_dir.clone()); + if !config.quiet_skips { + self.show_held(); + } + } + + pub(super) fn started(&mut self, work: Work, harness: &Choice) { + let first = !self.started; + self.started = true; + if !first || self.child { + return; + } + let root = self.root(&work.repo()); + let stamp = self.stamp(); + self.keep(work.command_log(&root, &stamp)); + self.step(format_args!("sessions run on {harness}")); + let command_log = match self.command_log_path() { + Some(path) => path + .strip_prefix(&root) + .unwrap_or(&path) + .display() + .to_string(), + None => "no Command log".into(), + }; + let started = Started { + root: root.clone(), + kind: work.kind(), + issue: work.issue(), + }; + let line = format!("{} started: {command_log}, on {harness}", started.subject()); + if self.activity_started.is_none() { + self.activity_started = Some(started); + self.activity_write(&root, &line, None); + } + } + + pub(super) fn skipped(&mut self, pass: Pass, repo: &Repo, reason: impl Display) { + let kind = match pass { + Pass::ArchitectRun => Kind::ArchitectRun, + Pass::PickupRun => Kind::PickupRun, + }; + self.activity_write( + &self.root(repo), + &format!("{kind} skipped: {reason}"), + Some(kind), + ); + } + + pub(super) fn ended(&mut self, outcome: impl Display) { + self.show_held(); + if let Some(started) = &self.activity_started { + let root = started.root.clone(); + let line = format!("{} ended: {outcome}", started.subject()); + self.activity_write(&root, &line, None); + } + } + + pub(super) fn show_held(&mut self) { + if let Log::Held { lines, shown } = &mut self.command_log + && !*shown + { + for (stream, line) in lines.iter() { + let _ = self.outside.emit(*stream, line); + } + *shown = true; + } + } + + pub(super) fn root(&self, repo: &Repo) -> PathBuf { + let logs_dir = self.logs_dir.as_deref().expect( + "the root of a repository's logs is asked for before the User config is loaded", + ); + root_under(logs_dir, repo) + } + + pub(super) fn stamp(&mut self) -> String { + self.stamp + .get_or_insert_with(|| self.outside.now().format(STAMP_FORMAT).to_string()) + .clone() + } + + pub(super) fn command_log_path(&self) -> Option { + match &self.command_log { + Log::Kept { path, .. } => Some(path.clone()), + Log::Failed { path } => path.clone(), + Log::NotKept | Log::Held { .. } => None, + } + } + + pub(super) fn print(&mut self, line: &str) { + self.output(Stream::Stdout, line.to_string()); + } + pub(super) fn eprint(&mut self, line: &str) { + self.output(Stream::Stderr, line.to_string()); + } + + fn step(&mut self, message: impl Display) { + let line = self.progress_line(message); + self.output(Stream::Stderr, line); + } + + fn progress_line(&mut self, message: impl Display) -> String { + progress::progress_line(self.outside.now().format("%H:%M:%S"), message) + } + + /// Warnings enter the same ordered output path without recursion. A + /// failed writer is disabled before its warning is queued. + fn output(&mut self, stream: Stream, line: String) { + let mut pending = VecDeque::from([(stream, line)]); + while let Some((stream, line)) = pending.pop_front() { + if !matches!(self.command_log, Log::Held { shown: false, .. }) { + let _ = self.outside.emit(stream, &line); + } + match &mut self.command_log { + Log::NotKept | Log::Failed { .. } => {} + Log::Held { lines, .. } => lines.push((stream, line)), + Log::Kept { path, writer } => { + if let Err(error) = writeln!(writer, "{line}") { + let error = anyhow::Error::new(error) + .context(format!("could not write {}", path.display())); + self.command_log = Log::Failed { + path: Some(path.clone()), + }; + let warning = self.progress_line(format_args!( + "warning: could not keep the Command log: {error:#}" + )); + pending.push_back((Stream::Stderr, warning)); + } + } + } + } + } + + fn keep(&mut self, path: PathBuf) { + self.show_held(); + if !matches!(self.command_log, Log::Held { .. }) { + return; + } + let Log::Held { lines, .. } = std::mem::replace(&mut self.command_log, Log::NotKept) else { + unreachable!() + }; + let created: Result = (|| { + let mut writer = self.outside.open_command_log(&path)?; + for (_, line) in lines { + writeln!(writer, "{line}") + .with_context(|| format!("could not write {}", path.display()))?; + } + Ok(writer) + })(); + match created { + Ok(writer) => { + self.command_log = Log::Kept { + path: path.clone(), + writer, + }; + self.step(format_args!("logging this command to {}", path.display())); + } + Err(error) => { + self.command_log = Log::Failed { + path: self.outside.command_log_exists(&path).then_some(path), + }; + self.step(format_args!( + "warning: could not keep the Command log: {error:#}" + )); + } + } + } + + fn activity_write(&mut self, root: &Path, line: &str, unless_last_of: Option) { + let appended = self.activity_append(&root.join(activity::FILE), line, unless_last_of); + if let Err(error) = appended + && !self.activity_warned + { + self.activity_warned = true; + self.show_held(); + self.step(format_args!( + "warning: could not keep the Activity log: {error:#}" + )); + } + } + + fn activity_append( + &mut self, + path: &Path, + line: &str, + unless_last_of: Option, + ) -> Result<()> { + if let Some(kind) = unless_last_of { + let tail = self.outside.activity_tail(path, activity::TAIL)?; + let text = String::from_utf8_lossy(&tail.bytes); + let whole = if tail.from > 0 { + text.split_once('\n').map_or("", |(_, rest)| rest) + } else { + &text + }; + if activity::last_of(whole, kind) == Some(line) { + return Ok(()); + } + } + let stamped = format!( + "{} {line}\n", + self.outside.now().format(activity::TIME_FORMAT) + ); + self.outside.append_activity(path, &stamped) + } +} + +#[cfg(test)] +mod tests; diff --git a/src/logs/recording/tests.rs b/src/logs/recording/tests.rs new file mode 100644 index 000000000..1949060d6 --- /dev/null +++ b/src/logs/recording/tests.rs @@ -0,0 +1,836 @@ +use std::collections::BTreeMap; +use std::io::{self, Write}; +use std::sync::{Arc, Mutex}; + +use chrono::{DateTime, FixedOffset}; + +use super::*; +use crate::harness::{ChosenBy, Harness}; +use crate::issue::IssueUrl; +use crate::logs::effects::Tail; + +const STAMP: &str = "20261003T120000-0400"; +const COMMAND: &str = "/logs/acme/widgets/commands/issue/7-20261003T120000-0400.log"; +const ACTIVITY: &str = "/logs/acme/widgets/activity.log"; + +#[derive(Default)] +struct Memory { + now: Option>, + terminal: Vec<(Stream, String)>, + files: BTreeMap, + command_open_fails: bool, + command_bytes_left: Option, + activity_read_fails: bool, + activity_write_fails: bool, + terminal_fails: bool, +} + +#[derive(Clone, Default)] +struct Scripted(Arc>); + +impl Scripted { + fn terminal(&self) -> String { + self.0 + .lock() + .unwrap() + .terminal + .iter() + .map(|(_, line)| line.as_str()) + .collect() + } + + fn file(&self, path: impl AsRef) -> String { + self.0 + .lock() + .unwrap() + .files + .get(path.as_ref()) + .cloned() + .unwrap_or_default() + } +} + +struct Writer { + memory: Scripted, + path: PathBuf, +} + +impl Write for Writer { + fn write(&mut self, bytes: &[u8]) -> io::Result { + let mut memory = self.memory.0.lock().unwrap(); + let length = match &mut memory.command_bytes_left { + Some(0) => return Err(io::Error::other("Command write failed")), + Some(left) => { + let length = bytes.len().min(*left); + *left -= length; + length + } + None => bytes.len(), + }; + memory + .files + .get_mut(&self.path) + .unwrap() + .push_str(std::str::from_utf8(&bytes[..length]).unwrap()); + Ok(length) + } + + fn flush(&mut self) -> io::Result<()> { + Ok(()) + } +} + +impl Outside for Scripted { + type CommandLog = Writer; + + fn now(&mut self) -> DateTime { + self.0 + .lock() + .unwrap() + .now + .unwrap_or_else(|| DateTime::parse_from_rfc3339("2026-10-03T12:00:00-04:00").unwrap()) + } + + fn emit(&mut self, stream: Stream, line: &str) -> io::Result<()> { + let mut memory = self.0.lock().unwrap(); + if memory.terminal_fails { + return Err(io::Error::other("terminal closed")); + } + memory.terminal.push((stream, format!("{line}\n"))); + Ok(()) + } + + fn open_command_log(&mut self, path: &Path) -> Result { + let mut memory = self.0.lock().unwrap(); + if memory.command_open_fails { + anyhow::bail!("Command open failed"); + } + memory.files.insert(path.to_path_buf(), String::new()); + Ok(Writer { + memory: self.clone(), + path: path.to_path_buf(), + }) + } + + fn command_log_exists(&mut self, path: &Path) -> bool { + self.0.lock().unwrap().files.contains_key(path) + } + + fn activity_tail(&mut self, path: &Path, limit: u64) -> Result { + let mut memory = self.0.lock().unwrap(); + if memory.activity_read_fails { + anyhow::bail!("Activity read failed"); + } + let file = memory.files.entry(path.to_path_buf()).or_default(); + let from = file.len().saturating_sub(limit as usize); + Ok(Tail { + from: from as u64, + bytes: file.as_bytes()[from..].to_vec(), + }) + } + + fn append_activity(&mut self, path: &Path, line: &str) -> Result<()> { + let mut memory = self.0.lock().unwrap(); + if memory.activity_write_fails { + anyhow::bail!("Activity write failed"); + } + memory + .files + .entry(path.to_path_buf()) + .or_default() + .push_str(line); + Ok(()) + } +} + +fn issue() -> IssueUrl { + IssueUrl::parse("https://github.com/acme/widgets/issues/7").unwrap() +} + +fn config(quiet: bool) -> UserConfig { + UserConfig::parse( + &format!("[logs]\ndir = '/logs'\n[activity]\nquiet_skips = {quiet}\n"), + Path::new("/home/config.toml"), + Path::new("/home"), + ) + .unwrap() +} + +fn harness() -> Choice { + Choice { + harness: Harness::Claude, + model: Some("opus".into()), + effort: Some("high".into()), + chosen_by: ChosenBy::Command, + } +} + +#[test] +fn a_run_records_its_complete_output_and_activity_under_its_repository() { + let memory = Scripted::default(); + let mut record = Record::new(memory.clone()); + let issue = issue(); + record.begin(Begin::Run(&issue)); + record.eprint("checking Origin match"); + record.configured(&config(false)); + assert_eq!(record.root(&issue.repo()), Path::new("/logs/acme/widgets")); + record.started(Work::Run(&issue), &harness()); + record.print("https://github.com/acme/widgets/pull/8"); + record.ended("ready for review"); + + assert_eq!(record.stamp(), STAMP); + assert_eq!(record.command_log_path(), Some(PathBuf::from(COMMAND))); + let output = "thirdshift: 12:00:00 starting on https://github.com/acme/widgets/issues/7, 2026-10-03 -0400\nchecking Origin match\nthirdshift: 12:00:00 logging this command to /logs/acme/widgets/commands/issue/7-20261003T120000-0400.log\nthirdshift: 12:00:00 sessions run on claude · opus · high\nhttps://github.com/acme/widgets/pull/8\n"; + assert_eq!(memory.terminal(), output); + assert_eq!(memory.file(COMMAND), output); + assert_eq!( + memory.file(ACTIVITY), + "2026-10-03 12:00:00 Run #7 started: commands/issue/7-20261003T120000-0400.log, on claude · opus · high\n2026-10-03 12:00:00 Run #7 ended: ready for review\n" + ); +} + +#[test] +fn each_work_kind_records_only_its_first_start_and_keeps_its_own_command_folder() { + let issue = issue(); + let repo = issue.repo(); + let dispatched = IssueUrl::parse("https://github.com/other/repo/issues/8").unwrap(); + for (begin, work, beginning, subject, relative) in [ + ( + Begin::Run(&issue), + Work::Run(&issue), + "starting on https://github.com/acme/widgets/issues/7", + "Run #7", + "commands/issue/7-20261003T120000-0400.log", + ), + ( + Begin::Run(&issue), + Work::SpecRun(&issue), + "starting on https://github.com/acme/widgets/issues/7", + "Spec run #7", + "commands/issue/7-20261003T120000-0400.log", + ), + ( + Begin::PickupRun, + Work::PickupRun(&issue), + "Pickup run starting", + "Pickup run #7", + "commands/pickup/7-20261003T120000-0400.log", + ), + ( + Begin::ArchitectRun, + Work::ArchitectRun(&repo), + "Architect run starting", + "Architect run", + "commands/architect/20261003T120000-0400.log", + ), + ] { + let memory = Scripted::default(); + let mut record = Record::new(memory.clone()); + record.begin(begin); + record.configured(&config(true)); + record.started(work, &harness()); + record.started(Work::Run(&dispatched), &Choice::default()); + record.started(Work::SpecRun(&dispatched), &Choice::default()); + record.ended("ready"); + let path = Path::new("/logs/acme/widgets").join(relative); + assert_eq!(record.command_log_path(), Some(path.clone())); + let output = format!( + "thirdshift: 12:00:00 {beginning}, 2026-10-03 -0400\nthirdshift: 12:00:00 logging this command to {}\nthirdshift: 12:00:00 sessions run on claude · opus · high\n", + path.display() + ); + assert_eq!(memory.terminal(), output); + assert_eq!(memory.file(path), output); + assert_eq!( + memory.file(ACTIVITY), + format!( + "2026-10-03 12:00:00 {subject} started: {relative}, on claude · opus · high\n2026-10-03 12:00:00 {subject} ended: ready\n" + ) + ); + assert_eq!(memory.0.lock().unwrap().files.len(), 2); + } +} + +#[test] +fn held_output_keeps_streams_and_order_through_configuration_release_and_start() { + let issue = issue(); + for quiet in [false, true] { + let memory = Scripted::default(); + let mut record = Record::new(memory.clone()); + record.begin(Begin::PickupRun); + record.print("before configuration\nsecond line"); + record.eprint("diagnostic"); + assert_eq!(memory.terminal(), ""); + assert_eq!(record.command_log_path(), None); + record.configured(&config(quiet)); + let held = "thirdshift: 12:00:00 Pickup run starting, 2026-10-03 -0400\nbefore configuration\nsecond line\ndiagnostic\n"; + assert_eq!(memory.terminal(), if quiet { "" } else { held }); + record.show_held(); + record.show_held(); + assert_eq!(memory.terminal(), held); + record.print(""); + record.eprint("thirdshift: 09:08:07 #21: relayed unchanged"); + record.started(Work::PickupRun(&issue), &harness()); + record.show_held(); + record.print("after start"); + record.ended("done"); + let path = "/logs/acme/widgets/commands/pickup/7-20261003T120000-0400.log"; + let expected = format!( + "{held}\nthirdshift: 09:08:07 #21: relayed unchanged\nthirdshift: 12:00:00 logging this command to {path}\nthirdshift: 12:00:00 sessions run on claude · opus · high\nafter start\n" + ); + assert_eq!(memory.terminal(), expected); + assert_eq!(memory.file(path), expected); + let streams: Vec<_> = memory + .0 + .lock() + .unwrap() + .terminal + .iter() + .map(|(stream, _)| *stream) + .collect(); + assert_eq!( + streams, + [ + Stream::Stderr, + Stream::Stdout, + Stream::Stderr, + Stream::Stdout, + Stream::Stderr, + Stream::Stderr, + Stream::Stderr, + Stream::Stdout + ] + ); + } +} + +#[test] +fn endings_without_work_reveal_held_output_once_and_create_no_logs() { + let issue = issue(); + for begin in [ + None, + Some(Begin::Run(&issue)), + Some(Begin::ArchitectRun), + Some(Begin::PickupRun), + ] { + let memory = Scripted::default(); + let mut record = Record::new(memory.clone()); + if let Some(begin) = begin { + record.begin(begin); + } + record.configured(&config(true)); + record.eprint("failed before work"); + record.print("detail"); + record.ended("failed"); + let expected = memory.terminal(); + assert!(expected.ends_with("failed before work\ndetail\n")); + record.ended("failed again"); + record.show_held(); + assert_eq!(memory.terminal(), expected); + assert_eq!(record.command_log_path(), None); + assert!(memory.0.lock().unwrap().files.is_empty()); + } +} + +#[test] +fn a_child_inherits_its_parent_stamp_and_relays_output_without_a_beginning_or_logs() { + let memory = Scripted::default(); + let mut record = Record::new(memory.clone()); + let issue = issue(); + let repo = issue.repo(); + record.begin(Begin::ChildRun("parent-stamp")); + assert_eq!(record.stamp(), "parent-stamp"); + // Child starts are ignored even before configuration. + for work in [ + Work::Run(&issue), + Work::SpecRun(&issue), + Work::PickupRun(&issue), + Work::ArchitectRun(&repo), + ] { + record.started(work, &harness()); + } + record.configured(&config(true)); + record.eprint("thirdshift: 09:08:07 implement: session started"); + record.print("child result"); + record.show_held(); + record.ended("ready"); + assert_eq!( + memory.terminal(), + "thirdshift: 09:08:07 implement: session started\nchild result\n" + ); + assert_eq!(record.command_log_path(), None); + assert!(memory.0.lock().unwrap().files.is_empty()); +} + +#[test] +fn lazy_stamps_are_owned_stable_and_independent_of_other_recordings() { + let memory = Scripted::default(); + let mut first = Record::new(memory.clone()); + let mut stamp = first.stamp(); + assert_eq!(stamp, STAMP); + stamp.clear(); + memory.0.lock().unwrap().now = + Some(DateTime::parse_from_rfc3339("2026-10-04T13:01:02+05:30").unwrap()); + first.begin(Begin::Run(&issue())); + first.configured(&config(false)); + first.started(Work::Run(&issue()), &harness()); + assert_eq!(first.stamp(), STAMP); + assert_eq!(first.command_log_path(), Some(PathBuf::from(COMMAND))); + assert!(memory.terminal().starts_with("thirdshift: 13:01:02 starting on https://github.com/acme/widgets/issues/7, 2026-10-04 +0530\n")); + assert!( + memory + .file(ACTIVITY) + .starts_with("2026-10-04 13:01:02 Run #7 started:") + ); + + let mut second = Record::new(memory.clone()); + assert_eq!(second.stamp(), "20261004T130102+0530"); + second.begin(Begin::ChildRun("ignored-after-lazy-query")); + assert_eq!(second.stamp(), "20261004T130102+0530"); + assert_eq!(second.command_log_path(), None); + let mut other_config = config(true); + other_config.logs_dir = PathBuf::from("/other"); + second.configured(&other_config); + assert_eq!( + second.root(&issue().repo()), + Path::new("/other/acme/widgets") + ); + assert_eq!(first.root(&issue().repo()), Path::new("/logs/acme/widgets")); +} + +#[test] +#[should_panic( + expected = "the root of a repository's logs is asked for before the User config is loaded" +)] +fn a_root_query_before_configuration_still_refuses() { + Record::new(Scripted::default()).root(&issue().repo()); +} + +#[test] +fn output_and_start_without_a_factory_beginning_keep_no_command_log() { + let memory = Scripted::default(); + let mut record = Record::new(memory.clone()); + record.print("setup result"); + record.eprint("diagnostic"); + record.configured(&config(false)); + record.started(Work::Run(&issue()), &harness()); + record.ended("done"); + record.ended("done again"); + assert_eq!( + memory.terminal(), + "setup result\ndiagnostic\nthirdshift: 12:00:00 sessions run on claude · opus · high\n" + ); + assert_eq!(record.command_log_path(), None); + assert_eq!(record.stamp(), STAMP); + assert_eq!( + memory.file(ACTIVITY), + "2026-10-03 12:00:00 Run #7 started: no Command log, on claude · opus · high\n2026-10-03 12:00:00 Run #7 ended: done\n2026-10-03 12:00:00 Run #7 ended: done again\n" + ); + assert_eq!(memory.0.lock().unwrap().files.len(), 1); +} + +fn skip(memory: &Scripted, pass: Pass, reason: &str) { + let mut record = Record::new(memory.clone()); + record.begin(match pass { + Pass::PickupRun => Begin::PickupRun, + Pass::ArchitectRun => Begin::ArchitectRun, + }); + record.configured(&config(true)); + record.eprint(reason); + let before = memory.terminal(); + record.skipped(pass, &issue().repo(), reason); + assert_eq!(memory.terminal(), before); + assert_eq!(record.command_log_path(), None); +} + +#[test] +fn separate_recordings_suppress_skips_from_shared_history_until_their_kind_changes() { + let memory = Scripted::default(); + skip(&memory, Pass::PickupRun, "idle"); + skip(&memory, Pass::ArchitectRun, "a plan is open"); + skip(&memory, Pass::PickupRun, "idle"); + // A Run's lines do not reset the Pickup run's skip. + let mut run = Record::new(memory.clone()); + run.begin(Begin::Run(&issue())); + run.configured(&config(false)); + run.started(Work::Run(&issue()), &harness()); + run.ended("ready"); + skip(&memory, Pass::PickupRun, "idle"); + skip(&memory, Pass::PickupRun, "at the Claim limit"); + skip(&memory, Pass::PickupRun, "at the Claim limit"); + skip(&memory, Pass::PickupRun, "idle"); + let mut pickup = Record::new(memory.clone()); + pickup.begin(Begin::PickupRun); + pickup.configured(&config(true)); + pickup.started(Work::PickupRun(&issue()), &harness()); + // Even just an intervening start permits the same skip again. + skip(&memory, Pass::PickupRun, "idle"); + pickup.ended("ready"); + skip(&memory, Pass::PickupRun, "idle"); + skip(&memory, Pass::ArchitectRun, "a plan is open"); + assert_eq!( + memory.file(ACTIVITY), + "2026-10-03 12:00:00 Pickup run skipped: idle\n2026-10-03 12:00:00 Architect run skipped: a plan is open\n2026-10-03 12:00:00 Run #7 started: commands/issue/7-20261003T120000-0400.log, on claude · opus · high\n2026-10-03 12:00:00 Run #7 ended: ready\n2026-10-03 12:00:00 Pickup run skipped: at the Claim limit\n2026-10-03 12:00:00 Pickup run skipped: idle\n2026-10-03 12:00:00 Pickup run #7 started: commands/pickup/7-20261003T120000-0400.log, on claude · opus · high\n2026-10-03 12:00:00 Pickup run skipped: idle\n2026-10-03 12:00:00 Pickup run #7 ended: ready\n2026-10-03 12:00:00 Pickup run skipped: idle\n" + ); +} + +#[test] +fn skip_history_uses_the_last_64_kib_and_discards_a_cut_first_line() { + let line = "2026-10-03 12:00:00 Pickup run skipped: idle\n"; + // At exactly 64 KiB the first line is whole. With one extra byte it + // looks valid in the tail but belongs to a line cut at the beginning. + for prefix in ["", "x"] { + let memory = Scripted::default(); + let seed = format!("{prefix}{line}{}\n", "x".repeat(64 * 1024 - line.len() - 1)); + memory + .0 + .lock() + .unwrap() + .files + .insert(PathBuf::from(ACTIVITY), seed.clone()); + skip(&memory, Pass::PickupRun, "idle"); + let expected = if prefix.is_empty() { + seed + } else { + format!("{seed}{line}") + }; + assert_eq!(memory.file(ACTIVITY), expected); + skip(&memory, Pass::PickupRun, "idle"); + assert_eq!(memory.file(ACTIVITY), expected); + } + let memory = Scripted::default(); + let seed = "Pickup run skipped: idle\n2026-10-03 12:00:00 Pickup runner skipped: idle\n2026-10-03 12:00:00 Architect run skipped: idle\n"; + memory + .0 + .lock() + .unwrap() + .files + .insert(PathBuf::from(ACTIVITY), seed.into()); + skip(&memory, Pass::PickupRun, "idle"); + assert_eq!(memory.file(ACTIVITY), format!("{seed}{line}")); +} + +#[test] +fn command_creation_failure_warns_once_and_retains_an_existing_path() { + for existing in [false, true] { + let memory = Scripted::default(); + { + let mut files = memory.0.lock().unwrap(); + files.command_open_fails = true; + if existing { + files + .files + .insert(PathBuf::from(COMMAND), "previous content\n".into()); + } + } + let mut record = Record::new(memory.clone()); + record.begin(Begin::Run(&issue())); + record.configured(&config(false)); + record.started(Work::Run(&issue()), &harness()); + assert_eq!( + record.command_log_path(), + existing.then(|| PathBuf::from(COMMAND)) + ); + // File writes stay disabled even if the underlying problem clears. + memory.0.lock().unwrap().command_open_fails = false; + record.eprint("carried on"); + record.print("result"); + record.started(Work::Run(&issue()), &harness()); + record.ended("ready"); + assert_eq!( + memory + .terminal() + .matches("warning: could not keep the Command log:") + .count(), + 1 + ); + assert!( + memory + .terminal() + .contains("warning: could not keep the Command log: Command open failed\n") + ); + assert!(!memory.terminal().contains("logging this command to")); + assert!(memory.terminal().ends_with("carried on\nresult\n")); + assert_eq!( + memory.file(COMMAND), + if existing { "previous content\n" } else { "" } + ); + let named = if existing { + "commands/issue/7-20261003T120000-0400.log" + } else { + "no Command log" + }; + assert_eq!( + memory.file(ACTIVITY), + format!( + "2026-10-03 12:00:00 Run #7 started: {named}, on claude · opus · high\n2026-10-03 12:00:00 Run #7 ended: ready\n" + ) + ); + } +} + +#[test] +fn a_failure_writing_held_lines_retains_the_partial_command_log_path() { + let memory = Scripted::default(); + memory.0.lock().unwrap().command_bytes_left = Some(3); + let mut record = Record::new(memory.clone()); + record.begin(Begin::Run(&issue())); + record.configured(&config(false)); + record.eprint("held detail"); + record.started(Work::Run(&issue()), &harness()); + record.eprint("after failure"); + record.ended("done"); + assert_eq!(record.command_log_path(), Some(PathBuf::from(COMMAND))); + assert_eq!(memory.file(COMMAND), "thi"); + assert_eq!( + memory + .terminal() + .matches("warning: could not keep the Command log:") + .count(), + 1 + ); + assert!(memory.terminal().contains(&format!( + "warning: could not keep the Command log: could not write {COMMAND}: Command write failed\n" + ))); + assert!( + memory + .file(ACTIVITY) + .contains("Run #7 started: commands/issue/7-20261003T120000-0400.log,") + ); + assert!(memory.file(ACTIVITY).ends_with("Run #7 ended: done\n")); +} + +#[test] +fn an_activity_warning_can_fail_the_command_append_without_recursion_and_each_warns_once() { + let memory = Scripted::default(); + let mut record = Record::new(memory.clone()); + record.begin(Begin::Run(&issue())); + record.configured(&config(false)); + record.started(Work::Run(&issue()), &harness()); + let command_before = memory.file(COMMAND); + { + let mut faults = memory.0.lock().unwrap(); + faults.command_bytes_left = Some(0); + faults.activity_write_fails = true; + } + record.ended("failed"); + record.ended("failed again"); + record.eprint("carried on"); + let warning = format!( + "thirdshift: 12:00:00 warning: could not keep the Activity log: Activity write failed\nthirdshift: 12:00:00 warning: could not keep the Command log: could not write {COMMAND}: Command write failed\ncarried on\n" + ); + assert!(memory.terminal().ends_with(&warning)); + assert_eq!(memory.terminal().matches("warning:").count(), 2); + assert_eq!(memory.file(COMMAND), command_before); + assert_eq!(record.command_log_path(), Some(PathBuf::from(COMMAND))); + { + let mut faults = memory.0.lock().unwrap(); + faults.command_bytes_left = None; + faults.activity_write_fails = false; + } + record.ended("recovered"); + record.print("result"); + assert_eq!(memory.file(COMMAND), command_before); + assert_eq!( + memory.file(ACTIVITY), + "2026-10-03 12:00:00 Run #7 started: commands/issue/7-20261003T120000-0400.log, on claude · opus · high\n2026-10-03 12:00:00 Run #7 ended: recovered\n" + ); + assert_eq!(memory.terminal().matches("warning:").count(), 2); +} + +#[test] +fn activity_read_and_append_warnings_reveal_quiet_output_and_reset_in_fresh_instances() { + for read_failure in [false, true] { + let memory = Scripted::default(); + for (begin, pass, kind) in [ + (Begin::PickupRun, Pass::PickupRun, "Pickup run"), + (Begin::ArchitectRun, Pass::ArchitectRun, "Architect run"), + ] { + { + let mut faults = memory.0.lock().unwrap(); + faults.activity_read_fails = read_failure; + faults.activity_write_fails = !read_failure; + } + let before = memory.terminal(); + let mut record = Record::new(memory.clone()); + record.begin(begin); + record.configured(&config(true)); + record.print("held stdout"); + record.eprint("held stderr"); + assert_eq!(memory.terminal(), before); + record.skipped(pass, &issue().repo(), "idle"); + record.skipped(pass, &issue().repo(), "idle"); + let error = if read_failure { + "Activity read failed" + } else { + "Activity write failed" + }; + let expected = format!( + "{before}thirdshift: 12:00:00 {kind} starting, 2026-10-03 -0400\nheld stdout\nheld stderr\nthirdshift: 12:00:00 warning: could not keep the Activity log: {error}\n" + ); + assert_eq!(memory.terminal(), expected); + { + let mut faults = memory.0.lock().unwrap(); + faults.activity_read_fails = false; + faults.activity_write_fails = false; + } + record.skipped(pass, &issue().repo(), "idle"); + record.print("after warning"); + assert!( + memory + .file(ACTIVITY) + .ends_with(&format!("{kind} skipped: idle\n")) + ); + assert!(memory.terminal().ends_with("after warning\n")); + assert_eq!(record.command_log_path(), None); + } + assert_eq!( + memory + .terminal() + .matches("warning: could not keep the Activity log:") + .count(), + 2 + ); + assert_eq!( + memory + .terminal() + .matches("warning: could not keep the Command log:") + .count(), + 0 + ); + } +} + +#[test] +fn terminal_failures_are_ignored_with_creation_append_and_activity_failure_combinations() { + for terminal_failure in [false, true] { + for activity_failure in [false, true] { + for command_failure in ["none", "open", "held", "append"] { + let memory = Scripted::default(); + { + let mut faults = memory.0.lock().unwrap(); + faults.terminal_fails = terminal_failure; + faults.activity_write_fails = activity_failure; + faults.command_open_fails = command_failure == "open"; + if command_failure == "held" { + faults.command_bytes_left = Some(3); + } + } + let mut record = Record::new(memory.clone()); + record.begin(Begin::Run(&issue())); + record.configured(&config(false)); + record.started(Work::Run(&issue()), &harness()); + let created = memory.file(COMMAND); + if command_failure == "append" { + memory.0.lock().unwrap().command_bytes_left = Some(0); + } + record.eprint("ordinary output"); + record.ended("done"); + let output = memory.terminal(); + assert_eq!( + output + .matches("warning: could not keep the Command log:") + .count(), + usize::from(!terminal_failure && command_failure != "none") + ); + assert_eq!( + output + .matches("warning: could not keep the Activity log:") + .count(), + usize::from(!terminal_failure && activity_failure) + ); + assert_eq!( + record.command_log_path(), + (command_failure != "open").then(|| PathBuf::from(COMMAND)) + ); + if command_failure != "none" { + assert_eq!(memory.file(COMMAND), created); + } else { + assert!(memory.file(COMMAND).starts_with("thirdshift: 12:00:00 starting on https://github.com/acme/widgets/issues/7, 2026-10-03 -0400\n")); + assert!(memory.file(COMMAND).ends_with("ordinary output\n")); + assert_eq!( + memory.file(COMMAND).matches("warning:").count(), + usize::from(activity_failure) + ); + } + if activity_failure { + assert_eq!(memory.file(ACTIVITY), ""); + } else { + assert!(memory.file(ACTIVITY).ends_with("Run #7 ended: done\n")); + } + if terminal_failure { + assert_eq!(output, ""); + memory.0.lock().unwrap().terminal_fails = false; + record.ended("still done"); + record.eprint("terminal reopened"); + assert_eq!(memory.terminal(), "terminal reopened\n"); + } + } + } + } +} + +#[test] +fn concurrent_output_and_start_have_the_same_terminal_and_command_log_order() { + let memory = Scripted::default(); + let mut record = Record::new(memory.clone()); + record.begin(Begin::PickupRun); + record.configured(&config(true)); + let record = Arc::new(Mutex::new(record)); + let ready = std::sync::Barrier::new(3); + std::thread::scope(|threads| { + for worker in 0..2 { + let record = record.clone(); + let ready = &ready; + threads.spawn(move || { + ready.wait(); + for number in 0..16 { + let line = format!("worker {worker} line {number}"); + let mut record = record.lock().unwrap(); + if worker == 0 { + record.print(&line); + } else { + record.eprint(&line); + } + } + }); + } + threads.spawn(|| { + ready.wait(); + record + .lock() + .unwrap() + .started(Work::PickupRun(&issue()), &harness()); + }); + }); + record.lock().unwrap().ended("done"); + let output = memory.terminal(); + let path = "/logs/acme/widgets/commands/pickup/7-20261003T120000-0400.log"; + assert_eq!(memory.file(path), output); + assert_eq!(output.lines().count(), 35); + assert!(output.contains(&format!("thirdshift: 12:00:00 logging this command to {path}\nthirdshift: 12:00:00 sessions run on claude · opus · high\n"))); + for worker in 0..2 { + for number in 0..16 { + let line = format!("worker {worker} line {number}"); + assert_eq!(output.lines().filter(|found| *found == line).count(), 1); + } + } +} + +#[test] +fn a_pass_can_reveal_output_before_configuration_when_loading_it_fails() { + let memory = Scripted::default(); + let mut record = Record::new(memory.clone()); + record.begin(Begin::ArchitectRun); + record.eprint("checking User config"); + assert_eq!(memory.terminal(), ""); + record.show_held(); + record.eprint("invalid User config"); + record.show_held(); + record.ended("failed"); + assert_eq!( + memory.terminal(), + "thirdshift: 12:00:00 Architect run starting, 2026-10-03 -0400\nchecking User config\ninvalid User config\n" + ); + assert_eq!(record.command_log_path(), None); + assert!(memory.0.lock().unwrap().files.is_empty()); +} diff --git a/src/progress.rs b/src/progress.rs index 8e1271d65..f4a925bf2 100644 --- a/src/progress.rs +++ b/src/progress.rs @@ -90,7 +90,7 @@ pub fn relayed(number: u64, line: &str) -> String { } /// The progress line for `message`, stamped with `time`. -fn progress_line(time: impl Display, message: impl Display) -> String { +pub(crate) fn progress_line(time: impl Display, message: impl Display) -> String { format!("{PREFIX}{time} {message}") } diff --git a/tests/activity_log.rs b/tests/activity_log.rs index 0831d2b6a..68d22aa16 100644 --- a/tests/activity_log.rs +++ b/tests/activity_log.rs @@ -215,61 +215,6 @@ fn the_first_skip_on_a_repository_creates_its_folder_and_repeated_skips_write_on ); } -#[test] -fn a_skip_whose_reason_changes_writes_a_new_line() { - let scenario = Scenario::new(); - scenario.user_config_is("[pickup]\nlimit = 1\n"); - - run_in_zone(&scenario, &["pickup"]); - scenario.issue_is(9, "OPEN"); - scenario.issue_labelled(9, &["in-progress"]); - run_in_zone(&scenario, &["pickup"]); - run_in_zone(&scenario, &["pickup"]); - scenario.issue_is(9, "CLOSED"); - run_in_zone(&scenario, &["pickup"]); - - assert_eq!( - activity(&scenario), - [ - "Pickup run skipped: no Ready issue on acme/widgets", - "Pickup run skipped: at the Claim limit on acme/widgets: 1 open issue(s) labelled \ - in-progress, pickup.limit is 1", - "Pickup run skipped: no Ready issue on acme/widgets", - ] - ); -} - -#[test] -fn a_pass_that_works_resets_its_kinds_skips_and_the_other_kinds_lines_do_not() { - let scenario = Scenario::new(); - scenario.agent_does_for(7, &agent_opens_pr(7, "main")); - - run_in_zone(&scenario, &["pickup"]); - open_plan(&scenario, 5); - run_in_zone(&scenario, &["architect"]); - run_in_zone(&scenario, &["pickup"]); - ready_issue(&scenario, 7); - run_in_zone(&scenario, &["pickup"]); - run_in_zone(&scenario, &["architect"]); - scenario.issue_is(7, "CLOSED"); - run_in_zone(&scenario, &["pickup"]); - - let command_log = the_one_command_log(&scenario, "pickup"); - let open_plan = "Architect run skipped: Architect plan #5 "; - let lines = activity(&scenario); - assert_eq!( - lines, - [ - "Pickup run skipped: no Ready issue on acme/widgets".to_string(), - lines[1].clone(), - format!("Pickup run #7 started: {command_log}, {ON_CLAUDE}"), - format!("Pickup run #7 ended: PR {PR_URL} is ready for review"), - "Pickup run skipped: no Ready issue on acme/widgets".to_string(), - ] - ); - assert!(lines[1].starts_with(open_plan), "{lines:?}"); -} - #[test] fn a_skip_because_another_pass_is_running_is_recorded_like_any_other() { let scenario = Scenario::new(); diff --git a/tests/command_logs.rs b/tests/command_logs.rs index e9d5ef629..07132f126 100644 --- a/tests/command_logs.rs +++ b/tests/command_logs.rs @@ -200,35 +200,6 @@ fn a_pickup_run_that_takes_an_issue_keeps_a_command_log_from_its_first_line() { ); } -#[test] -fn a_skipped_pickup_run_keeps_no_command_log() { - let scenario = Scenario::new(); - - let result = run_in_zone(&scenario, &["pickup"], &[]); - - assert_eq!(result.code, Some(0), "stderr: {}", result.stderr); - assert_dated_first_line(&result, "Pickup run starting"); - assert_eq!(logs_in(&scenario, ""), ["activity.log"]); -} - -#[test] -fn a_skipped_architect_run_keeps_no_command_log() { - let scenario = Scenario::new(); - scenario.issue_is(7, "OPEN"); - scenario.issue_labelled(7, &["ready-for-agent", "architect-plan"]); - - let result = run_in_zone(&scenario, &["architect"], &[]); - - assert_eq!(result.code, Some(0), "stderr: {}", result.stderr); - assert!( - result.stderr.contains("is still open"), - "stderr: {}", - result.stderr - ); - assert_dated_first_line(&result, "Architect run starting"); - assert_eq!(logs_in(&scenario, ""), ["activity.log"]); -} - #[test] fn an_architect_runs_command_log_covers_the_run_its_plan_was_dispatched_as() { let scenario = Scenario::new();