diff --git a/CONTEXT.md b/CONTEXT.md index 9364f8a4..230e945f 100644 --- a/CONTEXT.md +++ b/CONTEXT.md @@ -224,7 +224,7 @@ One invocation of thirdshift that does factory work: a **Run** or **Spec run** s _Avoid_: invocation, job **Command log**: -Everything one **Run**, **Spec run**, **Architect run**, **Pickup run** or **Security run** printed, kept in a file of its own with its repository's other logs, stamped like its **Session logs**. An Architect run's, Pickup run's or Security run's covers the Spec runs or Runs it dispatched, and a Spec run's covers its **Tickets**' Runs, as a Run's covers its **Base fix**: none of those keeps one of its own. It is kept once the command starts work: a Pickup run, Architect run or Security run skipped before doing any work keeps none, and neither does a Run that fails before it starts work, such as on **Origin match**. +Everything one **Run**, **Spec run**, **Architect run**, **Pickup run** or **Security run** printed, kept in a file of its own with its repository's other logs, stamped like its **Session logs**. Commands with the same start time still keep separate Command logs and **Command records**. An Architect run's, Pickup run's or Security run's covers the Spec runs or Runs it dispatched, and a Spec run's covers its **Tickets**' Runs, as a Run's covers its **Base fix**: none of those keeps one of its own. It is kept once the command starts work: a Pickup run, Architect run or Security run skipped before doing any work keeps none, and neither does a Run that fails before it starts work, such as on **Origin match**. _Avoid_: cron log, output log, run log (a **Run** is one kind of command) **Activity log**: diff --git a/docs/adr/0011-thirdshift-keeps-a-per-repository-activity-log.md b/docs/adr/0011-thirdshift-keeps-a-per-repository-activity-log.md index f6606d3f..4108d07f 100644 --- a/docs/adr/0011-thirdshift-keeps-a-per-repository-activity-log.md +++ b/docs/adr/0011-thirdshift-keeps-a-per-repository-activity-log.md @@ -15,6 +15,6 @@ This replaces ADR 0009's consequence that a skip leaves only its line in the sch ## Consequences -- The repository in the path is the GitHub repository, `/`, not the name of the local checkout, so log file names drop it: `commands/pickup/41-.log`, `sessions/41--implement.jsonl`. +- The repository in the path is the GitHub repository, `/`, not the name of the local checkout, so log file names drop it: `commands/pickup/41-~.log`. Command logs are exclusively allocated with an immutable random owner token, so Commands sharing a start stamp retain separate output and records. Session writers temporarily retain `commands/pickup/41--implement.jsonl` until the Session-ownership Ticket; readers accept both tokenless and token-bearing Session names. Existing legacy Command logs and records remain readable. - Whether the scheduler is still firing is no longer a line per pass: an idle repository's Activity log ends on one skip line. - Logs written before this, under `/sessions/` and `/commands/`, are not moved by thirdshift. diff --git a/docs/code-navigation.md b/docs/code-navigation.md index c7f25a74..28dd7cec 100644 --- a/docs/code-navigation.md +++ b/docs/code-navigation.md @@ -18,6 +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-log allocation, artifact ownership and filename decoding | `src/logs/owner.rs` — `allocate`, `Owner`, `decode`, `session_matches` | `src/logs/owner/tests.rs`, `src/logs/recording/tests.rs`, `tests/status.rs`, `tests/show_logs.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` | | Command naming, show, logs | `src/logs/status/inspect.rs` — Command resolution, detailed state, Session selection and log following | `tests/show_logs.rs` | | Stop | `src/logs/stop.rs` — request, signaling and waiting; `src/claim.rs` — Stop endings | `tests/stop.rs`; inline Claim and Stop tests | diff --git a/docs/guide.md b/docs/guide.md index 82f12631..e4600a40 100644 --- a/docs/guide.md +++ b/docs/guide.md @@ -624,10 +624,10 @@ Everything thirdshift logs goes under `~/.thirdshift/logs/`, or the `logs.dir` s ├── audits/ each Security audit's report, with its evidence ├── security-reviews/ each Security review's private report of old findings └── commands/ - ├── architect/ .log and Session logs - ├── pickup/ -.log and Session logs - ├── secure/ .log and Session logs - └── issue/ -.log and Session logs + ├── architect/ ~.log and Session logs + ├── pickup/ -~.log and Session logs + ├── secure/ ~.log and Session logs + └── issue/ -~.log and Session logs ``` The folder already names the repository, so no file name repeats it. `audits/` and `security-reviews/` hold vulnerability evidence, so keep the logs private (see [Security runs](#security-runs)). A **Session log** is one session's full transcript, as the Harness's JSON output, such as Claude Code's `stream-json`: @@ -646,11 +646,13 @@ A **Command log** is everything one command printed, stderr and stdout in the or The stamp is the local time the command started, with its UTC offset, as in `20261003T120000-0400`, in the machine's time zone, or `TZ`'s if set, so it agrees with `date` and `ls -l`. A command's Command log and all of its Session logs, its Tickets' Runs' and its Base fix's included, share that one stamp, so they sort together and each can be found from the other. When a Run fails, stderr ends with the path of its most recent Session log, the place to start looking, then that of its Command log. +New Command logs insert `~` immediately after the stamp. The random token gives each Command its own storage even when start times agree; its Command record uses that exact stem followed by `.command.json`. Human Command names stay the same. Session writers still use the tokenless examples above during this transition; readers also accept Session names with `~`. A matching stamp alone does not attach a tokenless Session to a new Command: a record reference or exact Model evidence must establish that ownership. Legacy logs and records remain readable without renaming. + The **Activity log**, `activity.log`, is a short running record of what the factory did on the repository ([ADR-0011](adr/0011-thirdshift-keeps-a-per-repository-activity-log.md)). A Run, a Spec run or a Pass writes a line when it starts work, naming its Command log, and one when it ends, with its outcome; a Run you type by hand writes them too, and the run a Pass dispatched, a Spec run's Tickets and a Base fix write none of their own. A skipped Pass writes a line only when its reason differs from the last line of its own kind, so a repository that sits idle shows one line, not one per pass, and the first skip after a pass that did work always shows: that is when the repository went idle. Every line starts with the local date and time: ``` 2026-10-03 02:00:01 Pickup run skipped: no Ready issue on acme/widgets -2026-10-03 09:30:01 Pickup run #41 started: commands/pickup/41-20261003T093001-0400.log +2026-10-03 09:30:01 Pickup run #41 started: commands/pickup/41-20261003T093001-0400~aB3cD4eF5gH6iJ7k.log 2026-10-03 09:52:17 Pickup run #41 ended: PR https://github.com/acme/widgets/pull/42 is merged 2026-10-03 10:00:01 Pickup run skipped: no Ready issue on acme/widgets ``` @@ -1086,7 +1088,7 @@ thirdshift: 03:00:01 Pickup run starting, 2026-10-03 -0400 thirdshift: 03:00:02 #18 labelled needs-info thirdshift: 03:00:03 #20 blocked by #17 thirdshift: 03:00:04 taking Ready issue #22 "Sharpen the widgets", as thirdshift https://github.com/acme/widgets/issues/22 would -thirdshift: 03:00:04 logging this command to ~/.thirdshift/logs/acme/widgets/commands/pickup/22-20261003T030001-0400.log +thirdshift: 03:00:04 logging this command to ~/.thirdshift/logs/acme/widgets/commands/pickup/22-20261003T030001-0400~aB3cD4eF5gH6iJ7k.log ``` ### One Run notification for the issue taken diff --git a/site/docs/index.html b/site/docs/index.html index a6bc092d..449a9e58 100644 --- a/site/docs/index.html +++ b/site/docs/index.html @@ -522,10 +522,10 @@

Logs

├── audits/ each Security audit's report, with its evidence ├── security-reviews/ each Security review's private report of old findings └── commands/ - ├── architect/ <stamp>.log and Session logs - ├── pickup/ <n>-<stamp>.log and Session logs - ├── secure/ <stamp>.log and Session logs - └── issue/ <n>-<stamp>.log and Session logs + ├── architect/ <stamp>~<token>.log and Session logs + ├── pickup/ <n>-<stamp>~<token>.log and Session logs + ├── secure/ <stamp>~<token>.log and Session logs + └── issue/ <n>-<stamp>~<token>.log and Session logs

The folder already names the repository, so no file name repeats it. audits/ and security-reviews/ hold vulnerability evidence, so keep the logs private (see Security runs). A Session log is one session's full transcript, as the Harness's JSON output, such as Claude Code's stream-json:

~/.thirdshift/logs/<owner>/<repo>/commands/issue/<n>-<stamp>-implement.jsonl
@@ -536,9 +536,10 @@ 
Logs

 
A Resume is logged as its session's kind plus -resume, e.g. implement-resume.jsonl.

 
A Command log is everything one command printed, stderr and stdout in the order printed, while the terminal still shows all of it. Its folder is the command typed: thirdshift <Issue URL>, a Run or a Spec run, in issue/, thirdshift pickup in pickup/, named for the issue it took, and thirdshift architect in architect/. A Spec run's covers its Tickets' Runs, a Run's covers its Base fix, and a Pass's covers the Spec run or Run it dispatched: none of those keeps one of its own. So ls -t ~/.thirdshift/logs/acme/widgets/commands/pickup/*.log | head lists the recent passes on acme/widgets that took an issue. A command keeps its Command log once it starts work: a Pass skipped before doing any work keeps none, nor does a Run that fails before it starts work, as on the Origin match, and setup, email-test, update, version and help never keep one. Lines printed before the Command log's name is known, such as a Pickup run's lines on the issues it passed over before it took one, are written first, and once it is created a progress line says logging this command to <path>. A Command log that can't be written produces one warning: line on stderr. A failure confined to the Command log leaves the outcome, stdout and exit code unchanged; if the shared folder also prevents writing a Session log, the Run fails before starting that session.

 
The stamp is the local time the command started, with its UTC offset, as in 20261003T120000-0400, in the machine's time zone, or TZ's if set, so it agrees with date and ls -l. A command's Command log and all of its Session logs, its Tickets' Runs' and its Base fix's included, share that one stamp, so they sort together and each can be found from the other. When a Run fails, stderr ends with the path of its most recent Session log, the place to start looking, then that of its Command log.

+
New Command logs insert ~<token> immediately after the stamp. The random token gives each Command its own storage even when start times agree; its Command record uses that exact stem followed by .command.json. Human Command names stay the same. Session writers still use the tokenless examples above during this transition; readers also accept Session names with ~<token>. A matching stamp alone does not attach a tokenless Session to a new Command: a record reference or exact Model evidence must establish that ownership. Legacy logs and records remain readable without renaming.

 
The Activity log, activity.log, is a short running record of what the factory did on the repository (ADR-0011). A Run, a Spec run or a Pass writes a line when it starts work, naming its Command log, and one when it ends, with its outcome; a Run you type by hand writes them too, and the run a Pass dispatched, a Spec run's Tickets and a Base fix write none of their own. A skipped Pass writes a line only when its reason differs from the last line of its own kind, so a repository that sits idle shows one line, not one per pass, and the first skip after a pass that did work always shows: that is when the repository went idle. Every line starts with the local date and time:

 
2026-10-03 02:00:01 Pickup run skipped: no Ready issue on acme/widgets
-2026-10-03 09:30:01 Pickup run #41 started: commands/pickup/41-20261003T093001-0400.log
+2026-10-03 09:30:01 Pickup run #41 started: commands/pickup/41-20261003T093001-0400~aB3cD4eF5gH6iJ7k.log
 2026-10-03 09:52:17 Pickup run #41 ended: PR https://github.com/acme/widgets/pull/42 is merged
 2026-10-03 10:00:01 Pickup run skipped: no Ready issue on acme/widgets
 

@@ -840,7 +841,7 @@ 
Why an issue was passed over

 thirdshift: 03:00:02 #18 labelled needs-info
 thirdshift: 03:00:03 #20 blocked by #17
 thirdshift: 03:00:04 taking Ready issue #22 "Sharpen the widgets", as thirdshift https://github.com/acme/widgets/issues/22 would
-thirdshift: 03:00:04 logging this command to ~/.thirdshift/logs/acme/widgets/commands/pickup/22-20261003T030001-0400.log
+thirdshift: 03:00:04 logging this command to ~/.thirdshift/logs/acme/widgets/commands/pickup/22-20261003T030001-0400~aB3cD4eF5gH6iJ7k.log

One Run notification for the issue taken

A Pickup run asked for a Run notification, by email or by email.always = true in the User config without no-email, sends exactly one when it took a Ready issue: the notification the Spec run or Run it dispatched would have sent started by hand. An address after email wins over email.to, as for a Run.

diff --git a/src/logs.rs b/src/logs.rs index 20a82c8d..30f2d54d 100644 --- a/src/logs.rs +++ b/src/logs.rs @@ -12,9 +12,9 @@ //! process-wide interface serializes its operations, including emitted output. mod activity; -mod command_log; mod command_record; mod effects; +mod owner; mod process_identity; mod recording; pub mod status; @@ -356,27 +356,6 @@ impl Work<'_> { Work::ArchitectRun(_) | Work::SecurityRun(_) => None, } } - - /// Where its Command log goes, under its repository's logs at `root`, - /// for the command started at `stamp`: - /// `/commands//.log`, one folder per - /// command typed, so the repository, already in the path, is not in the - /// name. `thirdshift `, a Run or a Spec run, is in `issue/`, - /// `thirdshift pickup` in `pickup/`, both named for the issue, and - /// `thirdshift architect` in `architect/`. - fn command_log(self, root: &Path, stamp: &str) -> PathBuf { - let (folder, prefix) = match self { - Work::Run(issue) | Work::BaseFix(issue) | Work::SpecRun(issue) => { - (CommandKind::Issue, format!("{}-", issue.number)) - } - Work::PickupRun(issue) => (CommandKind::Pickup, format!("{}-", issue.number)), - Work::ArchitectRun(_) => (CommandKind::Architect, String::new()), - Work::SecurityRun(_) => (CommandKind::Secure, String::new()), - }; - root.join("commands") - .join(folder.folder()) - .join(format!("{prefix}{stamp}.log")) - } } /// The [`Record`], locked, even if a thread panicked holding it. diff --git a/src/logs/command_log.rs b/src/logs/command_log.rs deleted file mode 100644 index a92cac21..00000000 --- a/src/logs/command_log.rs +++ /dev/null @@ -1,14 +0,0 @@ -//! Stateless Command log file effects. The recording owner decides its -//! path, held lines, lifetime and warning policy. - -use std::fs::{self, File}; -use std::path::Path; - -use anyhow::{Context, 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()))?; - } - File::create(path).with_context(|| format!("could not create {}", path.display())) -} diff --git a/src/logs/command_record.rs b/src/logs/command_record.rs index 63fbb02d..3cc7b219 100644 --- a/src/logs/command_record.rs +++ b/src/logs/command_record.rs @@ -162,6 +162,15 @@ impl StageName { } impl CommandRecord { + /// Exact retained Session references, including earlier stages. Callers + /// decide whether they need a deduplicated inventory. + pub fn session_references(&self) -> impl Iterator { + self.stages + .iter() + .filter_map(|stage| stage.session_log.as_ref()) + .chain(self.session_log.as_ref()) + } + 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()); diff --git a/src/logs/effects.rs b/src/logs/effects.rs index f74f18c2..ffe1b5b7 100644 --- a/src/logs/effects.rs +++ b/src/logs/effects.rs @@ -8,7 +8,7 @@ use std::path::Path; use anyhow::{Context, Result}; use chrono::{DateTime, FixedOffset, Local}; -use super::{activity, command_log}; +use super::{activity, owner}; #[derive(Clone, Copy, Debug, PartialEq, Eq)] pub(super) enum Stream { @@ -21,13 +21,9 @@ pub(super) struct Tail { pub bytes: Vec, } -pub(super) trait Outside { - type CommandLog: Write + Send; - +pub(super) trait Outside: owner::Files { 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<()>; fn hostname(&mut self) -> String; @@ -38,9 +34,15 @@ pub(super) trait Outside { pub(super) struct OnMachine; -impl Outside for OnMachine { +impl owner::Files for OnMachine { type CommandLog = File; + fn create_command_log(&mut self, path: &Path) -> io::Result { + owner::create(path) + } +} + +impl Outside for OnMachine { fn stop_request(&mut self, record: &Path) -> Option { super::stop::requested(record) } @@ -80,14 +82,6 @@ impl Outside for OnMachine { } } - 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) } diff --git a/src/logs/owner.rs b/src/logs/owner.rs new file mode 100644 index 00000000..74173562 --- /dev/null +++ b/src/logs/owner.rs @@ -0,0 +1,212 @@ +//! Command artifact allocation and the shared legacy/new filename format. +//! A storage owner never changes after allocation, even if its writer fails. + +use std::fs::{self, File, OpenOptions}; +use std::io::{self, Write}; +use std::path::{Path, PathBuf}; + +use anyhow::Result; +use chrono::{DateTime, FixedOffset}; +use serde::Deserialize; + +use super::{CommandKind, Work}; + +pub(super) trait Files { + type CommandLog: Write + Send; + + /// Exclusively acquire a file, reporting AlreadyExists without changing it. + fn create_command_log(&mut self, path: &Path) -> io::Result; +} + +pub(super) struct Owner { + path: PathBuf, +} + +impl Owner { + pub fn log_path(&self) -> &Path { + &self.path + } + + pub fn record_path(&self) -> PathBuf { + self.path.with_extension("command.json") + } +} + +pub(super) struct Allocation { + pub owner: Owner, + pub writer: W, +} + +/// tempfile supplies opaque randomness and collision retries; the adapter +/// supplies exclusive file effects. Only a successful acquisition establishes +/// an owner; a failed candidate must never be exposed through a root record. +pub(super) fn allocate( + files: &mut F, + root: &Path, + work: Work<'_>, + stamp: &str, +) -> Result> { + let (kind, subject) = match work { + Work::Run(issue) | Work::BaseFix(issue) | Work::SpecRun(issue) => { + (CommandKind::Issue, format!("{}-", issue.number)) + } + Work::PickupRun(issue) => (CommandKind::Pickup, format!("{}-", issue.number)), + Work::ArchitectRun(_) => (CommandKind::Architect, String::new()), + Work::SecurityRun(_) => (CommandKind::Secure, String::new()), + }; + let folder = root.join("commands").join(kind.folder()); + let allocated = tempfile::Builder::new() + .prefix(&format!("{subject}{stamp}~")) + .suffix(".log") + .rand_bytes(16) + .disable_cleanup(true) + .make_in(folder, |path| files.create_command_log(path))?; + let (writer, path) = allocated.into_parts(); + Ok(Allocation { + owner: Owner { + path: path.to_path_buf(), + }, + writer, + }) +} + +pub(super) fn create(path: &Path) -> io::Result { + let create = || { + if let Some(parent) = path.parent() { + fs::create_dir_all(parent)?; + } + OpenOptions::new().write(true).create_new(true).open(path) + }; + create().map_err(|error: io::Error| { + io::Error::new( + error.kind(), + format!("could not create {}: {error}", path.display()), + ) + }) +} + +pub(super) fn child_record(parent: &Path, dispatch: Option<&str>, issue: u64) -> PathBuf { + let dispatch = dispatch + .and_then(|issue| crate::issue::IssueUrl::parse(issue).ok()) + .map_or_else(String::new, |issue| format!("dispatch-{}-", issue.number)); + parent.with_extension(format!("{dispatch}issue-{issue}.child.json")) +} + +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub(super) struct Identity<'a> { + pub stamp: &'a str, + pub token: Option<&'a str>, +} + +pub(super) struct Decoded<'a> { + pub subject: &'a str, + pub identity: Identity<'a>, + pub session_kind: Option<&'a str>, +} + +impl Decoded<'_> { + pub fn time(&self) -> DateTime { + parse_stamp(self.identity.stamp).expect("decoded stamp is valid") + } + + pub fn command_log(&self, path: &Path) -> PathBuf { + let subject = match self.subject { + "" | "architect" | "secure" => String::new(), + subject => format!("{subject}-"), + }; + let token = self + .identity + .token + .map(|token| format!("~{token}")) + .unwrap_or_default(); + path.with_file_name(format!("{subject}{}{token}.log", self.identity.stamp)) + } +} + +fn parse_stamp(stamp: &str) -> Option> { + DateTime::parse_from_str(stamp, "%Y%m%dT%H%M%S%z").ok() +} + +/// Read current legacy record suffixes, owned records/logs, and both Session +/// forms. All byte offsets and token syntax live here. +pub(super) fn decode(path: &Path) -> Option> { + let name = path.file_name()?.to_str()?; + let (stem, session) = if let Some(stem) = name.strip_suffix(".jsonl") { + (stem, true) + } else if let Some(stem) = name.strip_suffix(".log") { + (stem, false) + } else { + ( + name.strip_suffix(".command.json") + .or_else(|| name.strip_suffix(".child.json"))? + .split('.') + .next()?, + false, + ) + }; + let (subject, rest) = if stem.get(..20).and_then(parse_stamp).is_some() { + ("", stem) + } else { + stem.split_once('-')? + }; + let stamp = rest.get(..20)?; + parse_stamp(stamp)?; + let tail = rest.get(20..)?; + let (token, tail) = if let Some(tail) = tail.strip_prefix('~') { + let end = tail.find('-').unwrap_or(tail.len()); + let token = &tail[..end]; + if token.is_empty() || !token.bytes().all(|byte| byte.is_ascii_alphanumeric()) { + return None; + } + (Some(token), &tail[end..]) + } else { + (None, tail) + }; + let session_kind = if session { + Some(tail.strip_prefix('-').filter(|kind| !kind.is_empty())?) + } else { + if !tail.is_empty() { + return None; + } + None + }; + Some(Decoded { + subject, + identity: Identity { stamp, token }, + session_kind, + }) +} + +/// Preserve current legacy suffix stripping, including non-stamped fixture +/// records, while keeping an owned stem's entire token. +pub(super) fn record_log(path: &Path) -> PathBuf { + if let Some(decoded) = decode(path) { + return decoded.command_log(path); + } + let name = path.file_name().unwrap_or_default().to_string_lossy(); + path.with_file_name(format!("{}.log", name.split('.').next().unwrap_or(&name))) +} + +/// Explicit Model evidence can link a transitional tokenless Session to its +/// owned Command. Timestamp equality alone cannot establish that link. +pub(super) fn evidenced_log(session: &Path) -> Option { + #[derive(Deserialize)] + struct Evidence { + command_log: Option, + } + let bytes = fs::read(session.with_extension("models.json")).ok()?; + serde_json::from_slice::(&bytes).ok()?.command_log +} + +pub(super) fn session_matches(session: &Path, log: &Path) -> bool { + if let Some(evidence) = evidenced_log(session) { + return evidence == log; + } + match (decode(session), decode(log)) { + (Some(session), Some(command)) => session.identity == command.identity, + _ => false, + } +} + +#[cfg(test)] +mod tests; diff --git a/src/logs/owner/tests.rs b/src/logs/owner/tests.rs new file mode 100644 index 00000000..2093a0b8 --- /dev/null +++ b/src/logs/owner/tests.rs @@ -0,0 +1,146 @@ +use super::*; +use crate::issue::IssueUrl; +use crate::logs::effects::OnMachine; + +const STAMP: &str = "20261003T120000-0400"; + +#[test] +fn real_files_keep_interleaved_command_output_and_records_separate() { + let root = tempfile::tempdir().unwrap(); + let issue = IssueUrl::parse("https://github.com/acme/widgets/issues/7").unwrap(); + let mut files = OnMachine; + let first = allocate(&mut files, root.path(), Work::Run(&issue), STAMP).unwrap(); + let first_path = first.owner.log_path().to_path_buf(); + let mut first_writer = first.writer; + first_writer.write_all(b"first before\n").unwrap(); + let second = allocate(&mut files, root.path(), Work::Run(&issue), STAMP).unwrap(); + let mut second_writer = second.writer; + second_writer.write_all(b"second before\n").unwrap(); + first_writer.write_all(b"first after\n").unwrap(); + second_writer.write_all(b"second after\n").unwrap(); + assert_ne!(first_path, second.owner.log_path()); + assert_ne!(first.owner.record_path(), second.owner.record_path()); + assert_eq!( + fs::read(first_path).unwrap(), + b"first before\nfirst after\n" + ); + assert_eq!( + fs::read(second.owner.log_path()).unwrap(), + b"second before\nsecond after\n" + ); + for owner in [&first.owner, &second.owner] { + assert_eq!(record_log(&owner.record_path()), owner.log_path()); + let decoded = decode(owner.log_path()).unwrap(); + assert_eq!(decoded.identity.stamp, STAMP); + assert!(decoded.identity.token.is_some()); + assert_eq!(decoded.subject, "7"); + } +} + +#[test] +fn a_forced_collision_preserves_the_existing_file_and_retries_with_a_fresh_token() { + struct Colliding { + occupied: Option, + } + impl Files for Colliding { + type CommandLog = File; + fn create_command_log(&mut self, path: &Path) -> io::Result { + if self.occupied.is_none() { + fs::create_dir_all(path.parent().unwrap())?; + fs::write(path, b"another Command's output\n")?; + self.occupied = Some(path.to_path_buf()); + } + create(path) + } + } + let root = tempfile::tempdir().unwrap(); + let issue = IssueUrl::parse("https://github.com/acme/widgets/issues/7").unwrap(); + let mut files = Colliding { occupied: None }; + let mut allocated = allocate(&mut files, root.path(), Work::Run(&issue), STAMP).unwrap(); + allocated.writer.write_all(b"new output\n").unwrap(); + let occupied = files.occupied.unwrap(); + assert_ne!(occupied, allocated.owner.log_path()); + assert_eq!(fs::read(occupied).unwrap(), b"another Command's output\n"); + assert_eq!( + fs::read(allocated.owner.log_path()).unwrap(), + b"new output\n" + ); +} + +#[test] +fn legacy_and_owned_artifacts_share_one_decoder() { + for (name, subject, token, kind, log) in [ + ( + "7-20261003T120000-0400.log", + "7", + None, + None, + "7-20261003T120000-0400.log", + ), + ( + "7-20261003T120000-0400.123-start-1-9.command.json", + "7", + None, + None, + "7-20261003T120000-0400.log", + ), + ( + "7-20261003T120000-0400~ownerA.command.json", + "7", + Some("ownerA"), + None, + "7-20261003T120000-0400~ownerA.log", + ), + ( + "20261003T120000-0400~ownerB.log", + "", + Some("ownerB"), + None, + "20261003T120000-0400~ownerB.log", + ), + ( + "7-20261003T120000-0400-implement.jsonl", + "7", + None, + Some("implement"), + "7-20261003T120000-0400.log", + ), + ( + "7-20261003T120000-0400~ownerA-repair-1-resume.jsonl", + "7", + Some("ownerA"), + Some("repair-1-resume"), + "7-20261003T120000-0400~ownerA.log", + ), + ( + "architect-20261003T120000-0400~ownerB-architecture-review.jsonl", + "architect", + Some("ownerB"), + Some("architecture-review"), + "20261003T120000-0400~ownerB.log", + ), + ( + "secure-20261003T120000+0530~ownerC-security-review.jsonl", + "secure", + Some("ownerC"), + Some("security-review"), + "20261003T120000+0530~ownerC.log", + ), + ] { + let path = Path::new(name); + let decoded = decode(path).unwrap_or_else(|| panic!("{name}")); + assert_eq!(decoded.subject, subject); + assert_eq!(decoded.identity.token, token); + assert_eq!(decoded.session_kind, kind); + assert_eq!(decoded.command_log(path), Path::new(log)); + } + for name in [ + "7-bad.log", + "7-20261003T120000-0400~.log", + "7-20261003T120000-0400~owner-.log", + "7-20261003T120000-0400~owner.jsonl", + "7-20261003T120000-0400-.jsonl", + ] { + assert!(decode(Path::new(name)).is_none(), "{name}"); + } +} diff --git a/src/logs/recording.rs b/src/logs/recording.rs index 6c0cf4e1..3b2a29f9 100644 --- a/src/logs/recording.rs +++ b/src/logs/recording.rs @@ -5,13 +5,13 @@ use std::collections::VecDeque; use std::fmt::Display; use std::io::Write; use std::path::{Path, PathBuf}; -use std::sync::atomic::{AtomicU64, Ordering}; use anyhow::{Context, Result}; use super::activity::{self, Kind}; use super::command_record::{CommandRecord, CommandTree, Stage, StageName, TicketRecord}; use super::effects::{Outside, Stream}; +use super::owner::{self, Owner}; use super::{Begin, CommandKind, Pass, Work, root_under}; use crate::config::UserConfig; use crate::harness::Choice; @@ -19,11 +19,11 @@ use crate::issue::Repo; use crate::progress; const STAMP_FORMAT: &str = "%Y%m%dT%H%M%S%z"; -static NEXT_RECORD: AtomicU64 = AtomicU64::new(0); pub(super) struct Record { outside: O, stamp: Option, + owner: Option, logs_dir: Option, child: bool, command: CommandKind, @@ -72,6 +72,7 @@ impl Record { Self { outside, stamp: None, + owner: None, logs_dir: None, child: false, command: CommandKind::Issue, @@ -148,7 +149,7 @@ impl Record { let root = self.root(&work.repo()); let stamp = self.stamp(); let began = matches!(self.command_log, Log::Held { .. }); - self.keep(work.command_log(&root, &stamp)); + self.keep(&root, work, &stamp); if began { self.start_record(work, harness); } @@ -216,26 +217,16 @@ impl Record { facts.parent_record = self.parent_record.clone(); facts.parent_dispatch = self.parent_dispatch.clone(); let path = if let Some(parent) = &self.parent_record { - let dispatch = self - .parent_dispatch - .as_ref() - .and_then(|issue| crate::issue::IssueUrl::parse(issue).ok()) - .map_or_else(String::new, |issue| format!("dispatch-{}-", issue.number)); - parent.with_extension(format!( - "{dispatch}issue-{}.child.json", - work.issue().unwrap() - )) + owner::child_record( + parent, + self.parent_dispatch.as_deref(), + work.issue().unwrap(), + ) } else { - // Process identity and a serial separate Commands sharing a stamp. - let owner = format!( - "{}-{}-{}", - facts.process_id, - facts.process_start.replace(':', "-"), - NEXT_RECORD.fetch_add(1, Ordering::Relaxed) - ); - let root = self.root(&work.repo()); - work.command_log(&root, &stamp) - .with_extension(format!("{owner}.command.json")) + let Some(owner) = &self.owner else { + return; + }; + owner.record_path() }; self.command_record = Some(( path, @@ -445,7 +436,7 @@ impl Record { } } - fn keep(&mut self, path: PathBuf) { + fn keep(&mut self, root: &Path, work: Work<'_>, stamp: &str) { self.show_held(); if !matches!(self.command_log, Log::Held { .. }) { return; @@ -454,7 +445,10 @@ impl Record { unreachable!() }; let created: Result = (|| { - let mut writer = self.outside.open_command_log(&path)?; + let allocation = owner::allocate(&mut self.outside, root, work, stamp)?; + self.owner = Some(allocation.owner); + let mut writer = allocation.writer; + let path = self.owner.as_ref().unwrap().log_path(); for (_, line) in lines { writeln!(writer, "{line}") .with_context(|| format!("could not write {}", path.display()))?; @@ -464,14 +458,18 @@ impl Record { match created { Ok(writer) => { self.command_log = Log::Kept { - path: path.clone(), + path: self.owner.as_ref().unwrap().log_path().to_path_buf(), writer, }; + let path = self.command_log_path().unwrap(); 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), + path: self + .owner + .as_ref() + .map(|owner| owner.log_path().to_path_buf()), }; self.step(format_args!( "warning: could not keep the Command log: {error:#}" diff --git a/src/logs/recording/tests.rs b/src/logs/recording/tests.rs index 0a3ce6ed..856954d3 100644 --- a/src/logs/recording/tests.rs +++ b/src/logs/recording/tests.rs @@ -10,7 +10,6 @@ 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)] @@ -19,6 +18,7 @@ struct Memory { terminal: Vec<(Stream, String)>, files: BTreeMap, command_open_fails: bool, + existing_on_open_failure: Option, command_bytes_left: Option, activity_read_fails: bool, activity_write_fails: bool, @@ -93,9 +93,32 @@ impl Write for Writer { } } -impl Outside for Scripted { +impl owner::Files for Scripted { type CommandLog = Writer; + fn create_command_log(&mut self, path: &Path) -> io::Result { + let mut memory = self.0.lock().unwrap(); + if memory.command_open_fails { + if memory.existing_on_open_failure.is_some() { + memory + .files + .insert(path.into(), "previous content\n".into()); + memory.existing_on_open_failure = Some(path.into()); + } + return Err(io::Error::other("Command open failed")); + } + if memory.files.contains_key(path) { + return Err(io::ErrorKind::AlreadyExists.into()); + } + memory.files.insert(path.to_path_buf(), String::new()); + Ok(Writer { + memory: self.clone(), + path: path.to_path_buf(), + }) + } +} + +impl Outside for Scripted { fn stop_request(&mut self, record: &Path) -> Option { let memory = self.0.lock().unwrap(); serde_json::from_str(memory.files.get(&record.with_extension("stop.json"))?).ok() @@ -143,22 +166,6 @@ impl Outside for Scripted { 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 { @@ -265,7 +272,7 @@ fn a_reused_process_id_is_not_a_live_command() { } #[test] -fn commands_started_on_the_same_issue_in_one_second_keep_separate_records() { +fn commands_started_on_the_same_issue_in_one_second_keep_separate_output_and_records() { let memory = Scripted::default(); let issue = issue(); let mut first = Record::new(memory.clone()); @@ -273,12 +280,38 @@ fn commands_started_on_the_same_issue_in_one_second_keep_separate_records() { first.configured(&config(false)); first.started(Work::Run(&issue), &harness()); first.issue_title(Some("first Command".into())); + first.print("first before second starts"); + let first_log = first.command_log_path().unwrap(); + let first_record = first.record_path().unwrap(); let mut second = Record::new(memory.clone()); second.begin(Begin::Run(&issue)); second.configured(&config(false)); second.started(Work::Run(&issue), &harness()); second.issue_title(Some("second Command".into())); + second.print("second before interleaving"); + first.print("first after second starts"); + second.print("second after interleaving"); + let second_log = second.command_log_path().unwrap(); + assert!( + memory + .file(&first_log) + .contains("first before second starts\n"), + "starting the second Command erased the first Command output" + ); + assert_ne!(first_log, second_log); + assert_ne!(first_record, second.record_path().unwrap()); + for (path, own, other) in [ + (&first_log, "first", "second"), + (&second_log, "second", "first"), + ] { + let bytes = memory.file(path); + assert_eq!( + bytes.lines().filter(|line| line.starts_with(own)).count(), + 2 + ); + assert!(!bytes.lines().any(|line| line.starts_with(other))); + } // The effects adapter keeps its clock fixed, so both owners have the same // issue, repository, and second-resolution Command-log stamp. @@ -414,13 +447,22 @@ fn a_run_records_its_complete_output_and_activity_under_its_repository() { 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"; + let path = record.command_log_path().unwrap(); + let relative = path + .strip_prefix(record.root(&issue.repo())) + .unwrap() + .display(); + let output = format!( + "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 {}\nthirdshift: 12:00:00 sessions run on claude · opus · high\nhttps://github.com/acme/widgets/pull/8\n", + path.display() + ); assert_eq!(memory.terminal(), output); - assert_eq!(memory.file(COMMAND), output); + assert_eq!(memory.file(&path), 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" + format!( + "2026-10-03 12:00:00 Run #7 started: {relative}, on claude · opus · high\n2026-10-03 12:00:00 Run #7 ended: ready for review\n" + ) ); } @@ -467,14 +509,19 @@ fn each_work_kind_records_only_its_first_start_and_keeps_its_own_command_folder( 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 path = record.command_log_path().unwrap(); + assert_eq!(owner::decode(&path).unwrap().identity.stamp, STAMP); + assert_eq!( + path.parent(), + Path::new("/logs/acme/widgets").join(relative).parent() + ); + let relative = path.strip_prefix("/logs/acme/widgets").unwrap().display(); 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(&path), output); assert_eq!( memory.file(ACTIVITY), format!( @@ -508,7 +555,8 @@ fn held_output_keeps_streams_and_order_through_configuration_release_and_start() record.show_held(); record.print("after start"); record.ended("done"); - let path = "/logs/acme/widgets/commands/pickup/7-20261003T120000-0400.log"; + let path = record.command_log_path().unwrap(); + let path = path.to_str().unwrap(); 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" ); @@ -612,7 +660,13 @@ fn lazy_stamps_are_owned_stable_and_independent_of_other_recordings() { 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_eq!( + owner::decode(&first.command_log_path().unwrap()) + .unwrap() + .identity + .stamp, + STAMP + ); 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 @@ -709,9 +763,21 @@ fn separate_recordings_suppress_skips_from_shared_history_until_their_kind_chang pickup.ended("ready"); skip(&memory, Pass::Pickup, "idle"); skip(&memory, Pass::Architect, "a plan is open"); + let run_path = run.command_log_path().unwrap(); + let run_path = run_path + .strip_prefix("/logs/acme/widgets") + .unwrap() + .display(); + let pickup_path = pickup.command_log_path().unwrap(); + let pickup_path = pickup_path + .strip_prefix("/logs/acme/widgets") + .unwrap() + .display(); 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" + format!( + "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: {run_path}, 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: {pickup_path}, 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" + ) ); } @@ -752,26 +818,21 @@ fn skip_history_uses_the_last_64_kib_and_discards_a_cut_first_line() { } #[test] -fn command_creation_failure_warns_once_and_retains_an_existing_path() { +fn command_creation_failure_warns_once_and_never_adopts_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()); + files.existing_on_open_failure = Some(PathBuf::new()); } } 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)) - ); + assert_eq!(record.command_log_path(), None); // File writes stay disabled even if the underlying problem clears. memory.0.lock().unwrap().command_open_fails = false; record.eprint("carried on"); @@ -788,19 +849,22 @@ fn command_creation_failure_warns_once_and_retains_an_existing_path() { assert!( memory .terminal() - .contains("warning: could not keep the Command log: Command open failed\n") + .contains("warning: could not keep the Command log: Command open failed") ); 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" - }; + if existing { + let path = memory + .0 + .lock() + .unwrap() + .existing_on_open_failure + .clone() + .unwrap(); + assert_eq!(memory.file(&path), "previous content\n"); + assert_eq!(record.record_path(), None); + } + let named = "no Command log"; assert_eq!( memory.file(ACTIVITY), format!( @@ -810,6 +874,40 @@ fn command_creation_failure_warns_once_and_retains_an_existing_path() { } } +#[test] +fn acquisition_failure_does_not_publish_a_record_claiming_the_existing_log() { + let memory = Scripted::default(); + { + let mut files = memory.0.lock().unwrap(); + files.command_open_fails = true; + files.existing_on_open_failure = Some(PathBuf::new()); + } + let mut record = Record::new(memory.clone()); + record.begin(Begin::Run(&issue())); + record.configured(&config(false)); + record.started(Work::Run(&issue()), &harness()); + + let occupied = memory + .0 + .lock() + .unwrap() + .existing_on_open_failure + .clone() + .unwrap(); + assert_eq!(memory.file(&occupied), "previous content\n"); + assert_eq!(record.command_log_path(), None); + + if let Some(path) = record.record_path() { + // status::Command::new uses this exact reconstruction for the log + // returned by status/show and selected by logs. + assert_ne!( + owner::record_log(&path), + occupied, + "a persisted record claims a Command log that was never acquired" + ); + } +} + #[test] fn a_failure_writing_held_lines_retains_the_partial_command_log_path() { let memory = Scripted::default(); @@ -821,8 +919,8 @@ fn a_failure_writing_held_lines_retains_the_partial_command_log_path() { 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"); + let path = record.command_log_path().unwrap(); + assert_eq!(memory.file(&path), "thi"); assert_eq!( memory .terminal() @@ -831,13 +929,13 @@ fn a_failure_writing_held_lines_retains_the_partial_command_log_path() { 1 ); assert!(memory.terminal().contains(&format!( - "warning: could not keep the Command log: could not write {COMMAND}: Command write failed\n" + "warning: could not keep the Command log: could not write {}: Command write failed\n", + path.display() + ))); + assert!(memory.file(ACTIVITY).contains(&format!( + "Run #7 started: {},", + path.strip_prefix("/logs/acme/widgets").unwrap().display() ))); - 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")); } @@ -848,7 +946,8 @@ fn an_activity_warning_can_fail_the_command_append_without_recursion_and_each_wa record.begin(Begin::Run(&issue())); record.configured(&config(false)); record.started(Work::Run(&issue()), &harness()); - let command_before = memory.file(COMMAND); + let path = record.command_log_path().unwrap(); + let command_before = memory.file(&path); { let mut faults = memory.0.lock().unwrap(); faults.command_bytes_left = Some(0); @@ -858,12 +957,13 @@ fn an_activity_warning_can_fail_the_command_append_without_recursion_and_each_wa 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" + "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 write failed\ncarried on\n", + path.display() ); 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))); + assert_eq!(memory.file(&path), command_before); + assert_eq!(record.command_log_path(), Some(path.clone())); { let mut faults = memory.0.lock().unwrap(); faults.command_bytes_left = None; @@ -871,10 +971,13 @@ fn an_activity_warning_can_fail_the_command_append_without_recursion_and_each_wa } record.ended("recovered"); record.print("result"); - assert_eq!(memory.file(COMMAND), command_before); + assert_eq!(memory.file(&path), 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" + format!( + "2026-10-03 12:00:00 Run #7 started: {}, on claude · opus · high\n2026-10-03 12:00:00 Run #7 ended: recovered\n", + path.strip_prefix("/logs/acme/widgets").unwrap().display() + ) ); assert_eq!(memory.terminal().matches("warning:").count(), 2); } @@ -961,7 +1064,8 @@ fn terminal_failures_are_ignored_with_creation_append_and_activity_failure_combi record.begin(Begin::Run(&issue())); record.configured(&config(false)); record.started(Work::Run(&issue()), &harness()); - let created = memory.file(COMMAND); + let path = record.command_log_path(); + let created = path.as_ref().map(|path| memory.file(path)); if command_failure == "append" { memory.0.lock().unwrap().command_bytes_left = Some(0); } @@ -980,17 +1084,17 @@ fn terminal_failures_are_ignored_with_creation_append_and_activity_failure_combi .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); + assert_eq!(record.command_log_path(), path); + if command_failure == "open" { + assert!(path.is_none()); + } else if command_failure != "none" { + assert_eq!(Some(memory.file(path.as_ref().unwrap())), 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")); + let bytes = memory.file(path.as_ref().unwrap()); + assert!(bytes.starts_with("thirdshift: 12:00:00 starting on https://github.com/acme/widgets/issues/7, 2026-10-03 -0400\n")); + assert!(bytes.ends_with("ordinary output\n")); assert_eq!( - memory.file(COMMAND).matches("warning:").count(), + bytes.matches("warning:").count(), usize::from(activity_failure) ); } @@ -1046,10 +1150,10 @@ fn concurrent_output_and_start_have_the_same_terminal_and_command_log_order() { }); 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); + let path = record.lock().unwrap().command_log_path().unwrap(); + 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"))); + assert!(output.contains(&format!("thirdshift: 12:00:00 logging this command to {}\nthirdshift: 12:00:00 sessions run on claude · opus · high\n", path.display()))); for worker in 0..2 { for number in 0..16 { let line = format!("worker {worker} line {number}"); diff --git a/src/logs/status.rs b/src/logs/status.rs index bfe9b2bf..be1d11b2 100644 --- a/src/logs/status.rs +++ b/src/logs/status.rs @@ -181,6 +181,12 @@ fn read(all: bool) -> Result { if record.parent_record.is_none() { covered.insert(command_log(&path)); } + for session in std::iter::once(record) + .chain(&tree.dispatched) + .flat_map(CommandRecord::session_references) + { + covered.insert(session.clone()); + } records.insert(path, tree); } } @@ -272,19 +278,13 @@ pub(super) fn retained_resources(path: &Path) -> Result> { } fn command_log(path: &Path) -> PathBuf { - let name = path.file_name().unwrap().to_string_lossy(); - path.with_file_name(format!("{}.log", name.split('.').next().unwrap_or(&name))) -} - -fn parse_stamp(stamp: &str) -> Option> { - DateTime::parse_from_str(stamp, "%Y%m%dT%H%M%S%z").ok() + super::owner::record_log(path) } /// Keep the filename spelling alongside its parsed time for naming and history. fn command_stamp(path: &Path) -> Option<(&str, DateTime)> { - let stem = path.file_stem()?.to_str()?; - let stamp = stem.get(stem.len().checked_sub(20)?..)?; - Some((stamp, parse_stamp(stamp)?)) + let decoded = super::owner::decode(path)?; + Some((decoded.identity.stamp, decoded.time())) } fn tree( diff --git a/src/logs/status/history.rs b/src/logs/status/history.rs index da0053d8..819d9bbc 100644 --- a/src/logs/status/history.rs +++ b/src/logs/status/history.rs @@ -10,6 +10,7 @@ use serde::Serialize; use crate::logs::activity::TIME_FORMAT; use crate::logs::command_record::Issue; +use crate::logs::owner; use crate::progress::ChildLine; #[derive(Clone, Serialize)] @@ -196,14 +197,12 @@ pub(super) fn read(repo: &Path, covered: &HashSet) -> Result) -> Result, - shared_stamps: &HashSet<(PathBuf, String)>, + shared_owners: &[PathBuf], ) -> Result> { let mut groups: BTreeMap = BTreeMap::new(); for folder in super::directories(&repo.join("commands"))? { @@ -300,32 +299,27 @@ fn sessions( 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(super::parse_stamp) else { + let path = entry.path(); + let Some(decoded) = + owner::decode(&path).filter(|decoded| decoded.session_kind.is_some()) + else { continue; }; - if rest - .get(20..) - .and_then(|rest| rest.strip_prefix('-')) - .is_none_or(str::is_empty) - { - continue; - } + let prefix = decoded.subject; + let stamp = decoded.time(); 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())) + let command_log = + owner::evidenced_log(&path).unwrap_or_else(|| decoded.command_log(&path)); + if covered.contains(&path) + || covered.contains(&command_log) + || shared_owners.iter().any(|log| { + log.parent() == Some(folder.as_path()) && owner::session_matches(&path, log) + }) { continue; } diff --git a/src/logs/status/inspect.rs b/src/logs/status/inspect.rs index 4646a2cf..6049fd14 100644 --- a/src/logs/status/inspect.rs +++ b/src/logs/status/inspect.rs @@ -10,6 +10,7 @@ use serde::Serialize; use super::{Command, Entry}; use crate::issue::IssueUrl; use crate::logs::effects::Outside; +use crate::logs::owner; enum Name { Issue { repository: String, number: u64 }, @@ -144,13 +145,7 @@ impl<'a> Selected<'a> { let (mut paths, issue, kind) = match self { Self::Record(command) => { let mut paths = Vec::new(); - for path in command - .record - .stages - .iter() - .filter_map(|stage| stage.session_log.as_ref()) - .chain(command.record.session_log.as_ref()) - { + for path in command.record.session_references() { if !paths.contains(path) { paths.push(path.clone()); } @@ -170,22 +165,22 @@ impl<'a> Selected<'a> { // A stage can cover several sessions (for example Architecture review // and its Resume), so stage references alone are not a log inventory. if let Some(log) = self.command_log() - && let Some((stamp, _)) = super::command_stamp(log) + && owner::decode(log).is_some() { let prefix = issue .map(|issue| issue.number.to_string()) .or_else(|| pass_prefix(kind).map(String::from)) .context("cannot name Session logs for this Command kind")?; - let prefix = format!("{prefix}-{stamp}-"); for entry in super::entries(log.parent().context("Command log has no directory")?)? { - let name = entry.file_name(); - let name = name.to_string_lossy(); + let path = entry.path(); if entry.file_type()?.is_file() - && name.starts_with(&prefix) - && name.ends_with(".jsonl") - && !paths.contains(&entry.path()) + && owner::decode(&path).is_some_and(|decoded| { + decoded.session_kind.is_some() && decoded.subject == prefix + }) + && owner::session_matches(&path, log) + && !paths.contains(&path) { - paths.push(entry.path()); + paths.push(path); } } } @@ -207,13 +202,7 @@ impl<'a> Selected<'a> { .into_iter() .rev() .find(|path| { - let Some(name) = path.file_name().and_then(|name| name.to_str()) else { - return false; - }; - let Some((_, rest)) = name.split_once('-') else { - return false; - }; - let Some(session) = rest.get(21..).and_then(|rest| rest.strip_suffix(".jsonl")) + let Some(session) = owner::decode(path).and_then(|decoded| decoded.session_kind) else { return false; }; diff --git a/tests/architect_run.rs b/tests/architect_run.rs index f39aaf9b..0d49e264 100644 --- a/tests/architect_run.rs +++ b/tests/architect_run.rs @@ -1833,7 +1833,12 @@ fn status_names_a_live_architecture_review_by_kind_and_command_stamp() { "home/.thirdshift/logs/acme/widgets/commands/architect", "log", ); - let name = format!("architect-{}", log[0].strip_suffix(".log").unwrap()); + let (stamp, _) = log[0] + .strip_suffix(".log") + .unwrap() + .split_once('~') + .expect("owned Command log"); + let name = format!("architect-{stamp}"); assert_eq!(command["name"], name); assert!(text.stdout.contains(&name), "{}", text.stdout); assert!( diff --git a/tests/command_logs.rs b/tests/command_logs.rs index 9a7cd83b..69799150 100644 --- a/tests/command_logs.rs +++ b/tests/command_logs.rs @@ -63,7 +63,7 @@ fn logs_in(scenario: &Scenario, folder: &str) -> Vec { } /// The one Command log in `commands/`, which must be named -/// `.log`, and its stamp. +/// `~.log`, and its display stamp. fn the_one_command_log(scenario: &Scenario, folder: &str, prefix: &str) -> (PathBuf, String) { let logs: Vec<_> = logs_in(scenario, &format!("commands/{folder}")) .into_iter() @@ -74,6 +74,8 @@ fn the_one_command_log(scenario: &Scenario, folder: &str, prefix: &str) -> (Path .strip_prefix(prefix) .and_then(|rest| rest.strip_suffix(".log")) .unwrap_or_else(|| panic!("not {prefix}.log: {}", logs[0])); + let (stamp, token) = stamp.split_once('~').expect("owned Command log"); + assert!(!token.is_empty()); assert_local_stamp(stamp); let path = scenario .path(LOGS) @@ -138,7 +140,7 @@ fn a_run_keeps_a_command_log_of_everything_it_printed_and_its_session_logs_share [ format!("7-{stamp}-implement.jsonl"), format!("7-{stamp}-implement.models.json"), - format!("7-{stamp}.log") + path.file_name().unwrap().to_str().unwrap().to_string() ] ); assert_eq!(logs_in(&scenario, ""), ["activity.log", "commands"]); @@ -204,7 +206,7 @@ fn a_pickup_run_that_takes_an_issue_keeps_a_command_log_from_its_first_line() { [ format!("7-{stamp}-implement.jsonl"), format!("7-{stamp}-implement.models.json"), - format!("7-{stamp}.log") + path.file_name().unwrap().to_str().unwrap().to_string() ] ); } @@ -220,13 +222,13 @@ fn a_pickup_spec_keeps_its_tickets_session_logs_beside_its_command_log() { let result = run_in_zone(&scenario, &["pickup"], &[]); assert_eq!(result.code, Some(0), "stderr: {}", result.stderr); - let (_, stamp) = the_one_command_log(&scenario, "pickup", "20-"); + let (path, stamp) = the_one_command_log(&scenario, "pickup", "20-"); assert_eq!( logs_in(&scenario, "commands/pickup"), [ format!("20-{stamp}-spec-review.jsonl"), format!("20-{stamp}-spec-review.models.json"), - format!("20-{stamp}.log"), + path.file_name().unwrap().to_str().unwrap().to_string(), format!("21-{stamp}-implement.jsonl"), format!("21-{stamp}-implement.models.json"), format!("22-{stamp}-implement.jsonl"), diff --git a/tests/progress_lines.rs b/tests/progress_lines.rs index 48965091..dc34ba5b 100644 --- a/tests/progress_lines.rs +++ b/tests/progress_lines.rs @@ -286,6 +286,7 @@ for log in "{logs}/commands/issue/"*.log; do name=${{log##*/}} stamp=${{name#7-}} stamp=${{stamp%.log}} + stamp=${{stamp%%~*}} done mkdir -p "{logs}/commands/issue" ln -s "{pipe}" "{logs}/commands/issue/7-$stamp-implement.jsonl" diff --git a/tests/run_notification.rs b/tests/run_notification.rs index 32c6faaa..7792d224 100644 --- a/tests/run_notification.rs +++ b/tests/run_notification.rs @@ -143,6 +143,9 @@ fn a_notification_keeps_current_models_when_an_unrelated_record_is_corrupt() { .strip_prefix("7-") .unwrap() .strip_suffix(".log") + .unwrap() + .split('~') + .next() .unwrap(); std::fs::write( scenario @@ -191,6 +194,9 @@ fn a_notification_excludes_an_unrelated_commands_models_with_the_same_stamp() { .strip_prefix("7-") .unwrap() .strip_suffix(".log") + .unwrap() + .split('~') + .next() .unwrap(); let directory = scenario.path(folder); diff --git a/tests/show_logs.rs b/tests/show_logs.rs index 0321be2f..9e933f6d 100644 --- a/tests/show_logs.rs +++ b/tests/show_logs.rs @@ -7,6 +7,99 @@ use support::Scenario; const OPENS_PR: &str = "echo work > work.txt\ngit add work.txt\ngit commit -qm 'Make widgets'\ngh pr create --base main --head issue-7 --title 'Make widgets' --body 'Closes #7'\n"; +#[test] +fn owned_and_legacy_commands_keep_exact_paths_and_record_precedence() { + let scenario = Scenario::new(); + let folder = scenario.path("home/.thirdshift/logs/acme/widgets/commands/issue"); + fs::create_dir_all(&folder).unwrap(); + let mut activity = String::new(); + for (stem, suffix, started, marker) in [ + ( + "7-20261003T120000-0400", + ".123-start-1-0", + "2026-10-03T12:00:00-04:00", + "legacy", + ), + ( + "7-20261003T120000-0400~ownerA", + "", + "2026-10-03T12:00:01-04:00", + "first", + ), + ( + "7-20261003T120000-0400~ownerB", + "", + "2026-10-03T12:00:02-04:00", + "second", + ), + ] { + let log = folder.join(format!("{stem}.log")); + let session = folder.join(format!("{stem}-implement.jsonl")); + fs::write(&log, format!("{marker} Command output\n")).unwrap(); + fs::write(&session, format!("{marker} Session output\n")).unwrap(); + let record = serde_json::json!({ + "version": 1, "kind": "Run", "repository": "acme/widgets", "name": "acme/widgets#7", + "issue": {"number": 7, "url": scenario.issue_url(7), "title": marker}, + "hostname": "factory", "process_id": 0, "process_start": "gone", "harness": "claude", + "model": null, "effort": null, "started_at": started, "ended_at": started, + "stages": [], "session_log": null, "outcome": "ready for review", "cause": null, + "issue_branch": null, "pull_request": null + }); + fs::write( + folder.join(format!("{stem}{suffix}.command.json")), + serde_json::to_vec(&record).unwrap(), + ) + .unwrap(); + activity.push_str(&format!("2026-10-03 12:00:00 Run #7 started: commands/issue/{stem}.log, on claude\n2026-10-03 12:00:01 Run #7 ended: ready for review\n")); + } + fs::write( + folder + .parent() + .unwrap() + .parent() + .unwrap() + .join("activity.log"), + activity, + ) + .unwrap(); + let status = scenario.run(&["status", "--all", "--json"]); + assert_eq!(status.code, Some(0), "{}", status.stderr); + let status: Value = serde_json::from_str(&status.stdout).unwrap(); + assert_eq!(status["version"], 1); + let commands = status["commands"].as_array().unwrap(); + assert_eq!(commands.len(), 3, "{status}"); + for command in commands { + assert_eq!(command["source"], "command_record"); + let output = fs::read_to_string(command["command_log"].as_str().unwrap()).unwrap(); + assert!(output.starts_with(command["issue"]["title"].as_str().unwrap())); + } + let shown = scenario.run(&["show", "widgets#7", "--json"]); + assert_eq!(shown.code, Some(0), "{}", shown.stderr); + let shown: Value = serde_json::from_str(&shown.stdout).unwrap(); + assert_eq!( + shown["command"]["command_log"], + folder + .join("7-20261003T120000-0400~ownerB.log") + .to_str() + .unwrap() + ); + assert_eq!( + shown["command"]["session_logs"], + serde_json::json!([folder.join("7-20261003T120000-0400~ownerB-implement.jsonl")]) + ); + for args in [ + vec!["logs", "widgets#7"], + vec!["logs", "widgets#7", "--follow"], + ] { + let output = scenario.run(&args); + assert_eq!(output.code, Some(0), "{}", output.stderr); + assert_eq!(output.stdout, "second Command output\n"); + } + let session = scenario.run(&["logs", "widgets#7", "--session", "implement"]); + assert_eq!(session.code, Some(0), "{}", session.stderr); + assert_eq!(session.stdout, "second Session output\n"); +} + #[test] fn show_activity_history_lists_its_session_logs() { let scenario = Scenario::new(); diff --git a/tests/status.rs b/tests/status.rs index cf3db3a6..0fb21886 100644 --- a/tests/status.rs +++ b/tests/status.rs @@ -234,6 +234,61 @@ fn write_record(scenario: &Scenario, number: u32, started: &str, ended: Option<& .unwrap(); } +#[test] +fn tokenless_sessions_require_explicit_evidence_to_belong_to_an_owned_command() { + for evidence in ["none", "record", "models"] { + let scenario = Scenario::new(); + write_record( + &scenario, + 7, + "2026-10-03T12:00:01-04:00", + Some("2026-10-03T13:00:00-04:00"), + ); + let folder = scenario.path(LOGS); + let record = folder.join("7-20261003T120000-0400~ownerA.command.json"); + fs::rename(folder.join("7-fixture.command.json"), &record).unwrap(); + let log = folder.join("7-20261003T120000-0400~ownerA.log"); + fs::write(&log, "owned Command output\n").unwrap(); + let session = folder.join("7-20261003T120000-0400-implement.jsonl"); + fs::write(&session, "tokenless Session\n").unwrap(); + match evidence { + "record" => { + let mut facts: Value = serde_json::from_slice(&fs::read(&record).unwrap()).unwrap(); + facts["session_log"] = serde_json::json!(session); + fs::write(&record, serde_json::to_vec(&facts).unwrap()).unwrap(); + } + "models" => fs::write( + session.with_extension("models.json"), + serde_json::json!({"command_log": log}).to_string(), + ) + .unwrap(), + _ => {} + } + let status = scenario.run(&["status", "--all", "--json"]); + assert_eq!(status.code, Some(0), "{}", status.stderr); + let status: Value = serde_json::from_str(&status.stdout).unwrap(); + assert_eq!( + status["commands"].as_array().unwrap().len(), + if evidence == "none" { 2 } else { 1 }, + "{evidence}: {status}" + ); + // The later record start keeps selection independent of equal-stamp + // ordering while we test the inventory of the owned Command. + let shown = scenario.run(&["show", "widgets#7", "--json"]); + assert_eq!(shown.code, Some(0), "{}", shown.stderr); + let shown: Value = serde_json::from_str(&shown.stdout).unwrap(); + assert_eq!(shown["command"]["source"], "command_record"); + assert_eq!( + shown["command"]["session_logs"] + .as_array() + .unwrap() + .contains(&serde_json::json!(session)), + evidence != "none", + "{evidence}: {shown}" + ); + } +} + #[test] fn status_shows_recent_outcomes_and_all_history_newest_first() { let scenario = Scenario::new();