From cad1d266605892c97c08c250f7becf891dfaf3fd Mon Sep 17 00:00:00 2001 From: konard Date: Tue, 4 Aug 2026 03:52:58 +0000 Subject: [PATCH 1/3] Initial commit with task details Adding .gitkeep for PR creation (default mode). This file will be removed when the task is complete. Issue: https://github.com/link-foundation/start/issues/150 --- .gitkeep | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/.gitkeep b/.gitkeep index 215a936..c3e2c48 100644 --- a/.gitkeep +++ b/.gitkeep @@ -1,2 +1,3 @@ # .gitkeep file auto-generated at 2026-06-26T14:21:03.315Z for PR creation at branch issue-144-d8d3fb7dfd56 for issue https://github.com/link-foundation/start/issues/144 -# Updated: 2026-06-26T16:22:21.672Z \ No newline at end of file +# Updated: 2026-06-26T16:22:21.672Z +# Updated: 2026-08-04T03:52:57.895Z \ No newline at end of file From d0656c28efd54c11d65dbf180e45fc91ff2aa029 Mon Sep 17 00:00:00 2001 From: konard Date: Tue, 4 Aug 2026 04:04:49 +0000 Subject: [PATCH 2/3] Anchor the terminal exit-code footer scan to the log tail (issue #150) `$ --status` derived a detached session's exit code from an unanchored `Exit Code: N` scan over the whole session log, so any text the wrapped command printed containing that substring was indistinguishable from the footer `start` appends itself, and the fabricated code was reported as the session's exit code. - Match the three-line footer block (separator / `Finished:` / `Exit Code:`) at line starts instead of a bare substring, in both the JS and Rust implementations. - Read only the last 16 KB of the log (the footer is always last), dropping the partial first line so it cannot act as a line start. This also removes a full-file read from every `--status` call. - Prefer `docker inspect .State.ExitCode` over the log text when a detached session has ended: the backend is authoritative and cannot be spoofed by command output. Adds regression tests (js/test/regression-150.js, rust/tests/regression_150.rs) and an end-to-end CLI reproduction in experiments/. --- experiments/issue-150-forged-exit-code.mjs | 97 +++++++++ .../issue-150-anchored-exit-code-footer.md | 5 + js/src/lib/status-formatter.js | 96 +++++++-- js/test/regression-150.js | 178 +++++++++++++++++ rust/Cargo.lock | 2 +- .../issue-150-anchored-exit-code-footer.md | 5 + rust/src/lib/mod.rs | 2 +- rust/src/lib/status_formatter.rs | 85 ++++++-- rust/tests/regression_150.rs | 184 ++++++++++++++++++ 9 files changed, 629 insertions(+), 25 deletions(-) create mode 100644 experiments/issue-150-forged-exit-code.mjs create mode 100644 js/.changeset/issue-150-anchored-exit-code-footer.md create mode 100644 js/test/regression-150.js create mode 100644 rust/changelog.d/issue-150-anchored-exit-code-footer.md create mode 100644 rust/tests/regression_150.rs diff --git a/experiments/issue-150-forged-exit-code.mjs b/experiments/issue-150-forged-exit-code.mjs new file mode 100644 index 0000000..2ae247e --- /dev/null +++ b/experiments/issue-150-forged-exit-code.mjs @@ -0,0 +1,97 @@ +#!/usr/bin/env bun +/** + * End-to-end reproduction for issue #150, driven through the real `$ --status` + * CLI and no mocks (and no docker daemon required). + * + * It stores a detached-docker execution record whose container name cannot be + * inspected — the exact window from the incident: the container is gone and the + * host-side watcher has not appended the genuine footer yet — and whose log + * contains the substring `Exit Code: 1` inside ordinary command output. + * + * Before the fix, `$ --status` reported `status executed / exitCode 1`. + * After the fix it keeps reporting `status executing / exitCode` unset, and it + * only reports a terminal exit code once the anchored footer is appended. + * + * Usage: bun experiments/issue-150-forged-exit-code.mjs + * Reference: https://github.com/link-foundation/start/issues/150 + */ + +import { spawnSync } from 'child_process'; +import fs from 'fs'; +import os from 'os'; +import path from 'path'; +import { fileURLToPath } from 'url'; + +const here = path.dirname(fileURLToPath(import.meta.url)); +const repoRoot = path.join(here, '..'); +const cliPath = path.join(repoRoot, 'js/src/bin/cli.js'); +const { ExecutionStore, ExecutionRecord } = await import( + path.join(repoRoot, 'js/src/lib/execution-store.js') +); + +const appFolder = fs.mkdtempSync(path.join(os.tmpdir(), 'issue-150-')); +const logPath = path.join(appFolder, 'session.log'); +const sessionName = `issue150-repro-${process.pid}`; + +// The command's own output happens to contain "Exit Code: 1" — here as the tail +// of an unrelated, older session log dumped by `rg -n` into a JSON payload. +const forgedOutput = + '{"type":"item.completed","item":{"aggregated_output":' + + '"40-==================================================\\n' + + '41-Finished: 2026-07-28 20:04:52.316\\n42-Exit Code: 1\\n",' + + '"exit_code":0,"status":"completed"}}\n'; +fs.writeFileSync(logPath, forgedOutput); + +const store = new ExecutionStore({ appFolder, useLinks: false }); +store.save( + new ExecutionRecord({ + command: 'solve.mjs --detached', + logPath, + options: { + sessionName, + isolated: 'docker', + isolationMode: 'detached', + }, + }) +); + +function status() { + const result = spawnSync('bun', [cliPath, '--status', sessionName], { + encoding: 'utf8', + env: { ...process.env, START_APP_FOLDER: appFolder }, + timeout: 30000, + }); + return `${result.stdout || ''}${result.stderr || ''}`; +} + +let failures = 0; +function check(label, condition, output) { + console.log(`${condition ? '✅' : '❌'} ${label}`); + if (!condition) { + failures += 1; + console.log(output); + } +} + +const beforeFooter = status(); +check( + 'forged "Exit Code: 1" in the output does not terminate the session', + /status executing/.test(beforeFooter) && !/exitCode 1/.test(beforeFooter), + beforeFooter +); + +// Now the genuine footer, exactly as `start` appends it. +fs.appendFileSync( + logPath, + `\n${'='.repeat(50)}\nFinished: 2026-07-30 23:36:20.295\nExit Code: 0\n` +); + +const afterFooter = status(); +check( + 'the anchored footer is honored once it is written', + /status executed/.test(afterFooter) && /exitCode 0/.test(afterFooter), + afterFooter +); + +fs.rmSync(appFolder, { recursive: true, force: true }); +process.exit(failures === 0 ? 0 : 1); diff --git a/js/.changeset/issue-150-anchored-exit-code-footer.md b/js/.changeset/issue-150-anchored-exit-code-footer.md new file mode 100644 index 0000000..b1dfc58 --- /dev/null +++ b/js/.changeset/issue-150-anchored-exit-code-footer.md @@ -0,0 +1,5 @@ +--- +'start-command': patch +--- + +Stop `--status` from fabricating a detached session exit code out of the command's own output: the terminal exit code is now read from the anchored three-line footer `start` writes (separator / `Finished:` / `Exit Code:`) in the tail of the log only, and Docker's own `.State.ExitCode` takes precedence over the log text. diff --git a/js/src/lib/status-formatter.js b/js/src/lib/status-formatter.js index 7d9c006..e2adbe7 100644 --- a/js/src/lib/status-formatter.js +++ b/js/src/lib/status-formatter.js @@ -166,20 +166,88 @@ function isDetachedSessionAlive(record) { } } +/** + * Number of trailing bytes scanned for the terminal log footer. The footer is + * always appended at the very end of the log, so there is no reason to read + * (potentially megabytes of) command output on every `--status` call. + */ +const LOG_TAIL_BYTES = 16 * 1024; + +/** + * The three-line terminal footer that `start` itself writes (see + * `createLogFooter()` and `createShellLogFooterSnippet()`): + * + * ================================================== + * Finished: 2026-07-30 23:36:20.295 + * Exit Code: 0 + * + * The whole block is anchored at line starts so that a bare `Exit Code: N` + * substring emitted by the wrapped command (inside a JSON payload, a quoted + * log excerpt, an `rg` dump, ...) can no longer be mistaken for the footer + * `start` appends itself (issue #150). + */ +const LOG_FOOTER_PATTERN = + /^={10,}[ \t]*\r?\n^Finished:[^\r\n]*\r?\n^Exit Code:[ \t]*(-?\d+)[ \t]*(?![^\r\n])/gm; + +/** + * Read the last `bytes` bytes of a file as UTF-8 text. + * + * A partial first line is dropped: the slice can start in the middle of a line, + * and that fragment must not be treated as the beginning of a line by the + * anchored footer pattern. + * + * @param {string} logPath - Path to the log file + * @param {number} [bytes] - Maximum number of trailing bytes to read + * @returns {string|null} Tail content, or null when the file cannot be read + */ +function readLogTail(logPath, bytes = LOG_TAIL_BYTES) { + let fd; + try { + fd = fs.openSync(logPath, 'r'); + const size = fs.fstatSync(fd).size; + const length = Math.min(size, bytes); + const buffer = Buffer.alloc(length); + fs.readSync(fd, buffer, 0, length, size - length); + const tail = buffer.toString('utf8'); + if (size <= bytes) { + return tail; + } + const firstNewline = tail.indexOf('\n'); + return firstNewline === -1 ? '' : tail.slice(firstNewline + 1); + } catch { + return null; + } finally { + if (fd !== undefined) { + try { + fs.closeSync(fd); + } catch { + // ignore + } + } + } +} + +/** + * Read the terminal exit code from the anchored footer at the end of a log. + * Returns null when the log has no footer yet (command still running, or the + * host-side watcher has not appended it yet) — never a number parsed out of the + * command's own output. + * @param {string} logPath - Path to the log file + * @returns {number|null} + */ function readExitCodeFromLog(logPath) { if (!logPath) { return null; } - try { - const content = fs.readFileSync(logPath, 'utf8'); - const matches = [...content.matchAll(/Exit Code:\s*(-?\d+)/g)]; - if (matches.length === 0) { - return null; - } - return parseInt(matches[matches.length - 1][1], 10); - } catch { + const tail = readLogTail(logPath); + if (tail === null) { + return null; + } + const matches = [...tail.matchAll(LOG_FOOTER_PATTERN)]; + if (matches.length === 0) { return null; } + return parseInt(matches[matches.length - 1][1], 10); } /** @@ -265,12 +333,14 @@ function enrichDetachedStatus(record) { // Otherwise keep the recorded/footer exit code - the command has finished. } else if (!alive && enriched.status === 'executing') { // Session ended but record says executing - correct it. Resolve a real exit - // code: prefer the log footer, then the backend's own record (e.g. - // `docker inspect .State.ExitCode`), and only fall back to the `-1` sentinel - // as a last resort when no real code can be obtained (issue #136). + // code: prefer the backend's own record (e.g. `docker inspect + // .State.ExitCode`, which is authoritative and cannot be spoofed by command + // output — issue #150), then the anchored log footer, and only fall back to + // the `-1` sentinel as a last resort when no real code can be obtained + // (issue #136). enriched.status = 'executed'; if (enriched.exitCode === null || enriched.exitCode === undefined) { - enriched.exitCode = footerExit ?? readBackendExitCode(enriched) ?? -1; + enriched.exitCode = readBackendExitCode(enriched) ?? footerExit ?? -1; } if (!enriched.endTime) { enriched.endTime = new Date().toISOString(); @@ -619,6 +689,8 @@ module.exports = { listExecutions, isDetachedSessionAlive, enrichDetachedStatus, + readExitCodeFromLog, + readLogTail, attachCurrentTime, attachProcessIds, }; diff --git a/js/test/regression-150.js b/js/test/regression-150.js new file mode 100644 index 0000000..3a2fb3f --- /dev/null +++ b/js/test/regression-150.js @@ -0,0 +1,178 @@ +#!/usr/bin/env bun +/** + * Regression tests for issue #150: + * "`$ --status` fabricates a detached session exit code from the command's own + * output (unanchored `Exit Code:` scan over the whole log)" + * + * The exit code of a detached session used to be derived from an *unanchored* + * `Exit Code: N` scan over the *whole* session log. Any text the wrapped + * command printed that merely contained the substring `Exit Code: N` was + * indistinguishable from the terminal footer `start` appends itself, so + * `$ --status` could report an exit code the command never produced. + * + * The fix anchors the scan on the three-line footer block `start` writes + * (separator / `Finished:` / `Exit Code:`) and only reads the tail of the log, + * where the footer always is. + * + * Reference: https://github.com/link-foundation/start/issues/150 + */ + +const { describe, it, expect, beforeEach, afterEach } = require('bun:test'); +const fs = require('fs'); +const os = require('os'); +const path = require('path'); + +const { ExecutionRecord } = require('../src/lib/execution-store'); +const { + readExitCodeFromLog, + readLogTail, + enrichDetachedStatus, +} = require('../src/lib/status-formatter'); + +const SEPARATOR = '='.repeat(50); + +function realFooter(exitCode) { + return `\n${SEPARATOR}\nFinished: 2026-07-30 23:36:20.295\nExit Code: ${exitCode}\n`; +} + +describe('anchored log footer parsing (issue #150)', () => { + let tempDir; + let logPath; + + beforeEach(() => { + tempDir = fs.mkdtempSync(path.join(os.tmpdir(), 'start-150-')); + logPath = path.join(tempDir, 'session.log'); + }); + + afterEach(() => { + fs.rmSync(tempDir, { recursive: true, force: true }); + }); + + it('ignores an `Exit Code:` substring inside the command output', () => { + // Exactly the payload from the incident: an older session log dumped by + // `rg -n` into the JSON output of the running command. + fs.writeFileSync( + logPath, + '{"type":"item.completed","item":{"aggregated_output":' + + '"40-==================================================\\n41-Finished: 2026-07-28 20:04:52.316\\n42-Exit Code: 1\\n",' + + '"exit_code":0,"status":"completed"}}\n' + ); + expect(readExitCodeFromLog(logPath)).toBeNull(); + }); + + it('ignores a bare `Exit Code:` line without the footer block around it', () => { + fs.writeFileSync(logPath, 'Exit Code: 1\nstill running\n'); + expect(readExitCodeFromLog(logPath)).toBeNull(); + }); + + it('ignores an `Exit Code:` substring in the middle of a line', () => { + fs.writeFileSync( + logPath, + `${SEPARATOR}\nFinished: now\nlog: Exit Code: 3\n` + ); + expect(readExitCodeFromLog(logPath)).toBeNull(); + }); + + it('reads the real footer that `start` appends', () => { + fs.writeFileSync(logPath, `hello\n${realFooter(0)}`); + expect(readExitCodeFromLog(logPath)).toBe(0); + }); + + it('reads the real footer even when the output forged one earlier', () => { + fs.writeFileSync( + logPath, + `${SEPARATOR}\nFinished: fake\nExit Code: 1\n${realFooter(0)}` + ); + // The last anchored footer wins - here the genuine one, appended last. + expect(readExitCodeFromLog(logPath)).toBe(0); + }); + + it('reads negative and multi-digit codes, and tolerates CRLF logs', () => { + fs.writeFileSync( + logPath, + `${SEPARATOR}\r\nFinished: t\r\nExit Code: 137\r\n` + ); + expect(readExitCodeFromLog(logPath)).toBe(137); + fs.writeFileSync(logPath, realFooter(-1)); + expect(readExitCodeFromLog(logPath)).toBe(-1); + }); + + it('returns null for a log without a footer and for a missing file', () => { + fs.writeFileSync(logPath, 'still running, no footer yet\n'); + expect(readExitCodeFromLog(logPath)).toBeNull(); + expect(readExitCodeFromLog(path.join(tempDir, 'missing.log'))).toBeNull(); + expect(readExitCodeFromLog(null)).toBeNull(); + }); + + it('finds the footer at the end of a large log without reading it all', () => { + fs.writeFileSync( + logPath, + `${'x'.repeat(2 * 1024 * 1024)}\n${realFooter(42)}` + ); + expect(readExitCodeFromLog(logPath)).toBe(42); + // Only the tail is read, so an `Exit Code:` far from the end is invisible. + const tail = readLogTail(logPath); + expect(tail.length).toBeLessThan(32 * 1024); + }); + + it('drops the partial first line of the tail so it cannot be a line start', () => { + const filler = 'y'.repeat(32 * 1024); + fs.writeFileSync( + logPath, + `${filler}${SEPARATOR}\nFinished: t\nExit Code: 7\n` + ); + // The separator is a line *continuation* (the line starts with the filler), + // so it is not a footer even though the tail slice may begin mid-line. + expect(readExitCodeFromLog(logPath)).toBeNull(); + }); +}); + +describe('detached status is not derailed by forged output (issue #150)', () => { + let tempDir; + let logPath; + + beforeEach(() => { + tempDir = fs.mkdtempSync(path.join(os.tmpdir(), 'start-150-enrich-')); + logPath = path.join(tempDir, 'session.log'); + }); + + afterEach(() => { + fs.rmSync(tempDir, { recursive: true, force: true }); + }); + + function makeRecord() { + return new ExecutionRecord({ + command: 'solve.mjs', + logPath, + options: { + // A container name that cannot be inspected: liveness is unknown, the + // exact window in which the incident happened. + sessionName: `issue150-absent-${process.pid}-${Date.now()}`, + isolated: 'docker', + isolationMode: 'detached', + }, + }); + } + + it('keeps an executing record executing when only the output claims an exit code', () => { + fs.writeFileSync( + logPath, + '{"aggregated_output":"41-Finished: x\\n42-Exit Code: 1\\n","exit_code":0}\n' + ); + const enriched = enrichDetachedStatus(makeRecord()); + expect(enriched.status).toBe('executing'); + expect(enriched.exitCode).toBeNull(); + expect(enriched.endTime).toBeNull(); + }); + + it('marks the record executed once the genuine footer is appended', () => { + fs.writeFileSync( + logPath, + `{"aggregated_output":"42-Exit Code: 1\\n"}\n${realFooter(0)}` + ); + const enriched = enrichDetachedStatus(makeRecord()); + expect(enriched.status).toBe('executed'); + expect(enriched.exitCode).toBe(0); + expect(enriched.endTime).not.toBeNull(); + }); +}); diff --git a/rust/Cargo.lock b/rust/Cargo.lock index 7b76404..2a9193b 100644 --- a/rust/Cargo.lock +++ b/rust/Cargo.lock @@ -437,7 +437,7 @@ checksum = "0c790de23124f9ab44544d7ac05d60440adc586479ce501c1d6d7da3cd8c9cf5" [[package]] name = "start-command" -version = "0.17.2" +version = "0.17.3" dependencies = [ "base64", "chrono", diff --git a/rust/changelog.d/issue-150-anchored-exit-code-footer.md b/rust/changelog.d/issue-150-anchored-exit-code-footer.md new file mode 100644 index 0000000..4d51a13 --- /dev/null +++ b/rust/changelog.d/issue-150-anchored-exit-code-footer.md @@ -0,0 +1,5 @@ +--- +bump: patch +--- + +Stop `--status` from fabricating a detached session exit code out of the command's own output: the terminal exit code is now read from the anchored three-line footer `start` writes (separator / `Finished:` / `Exit Code:`) in the tail of the log only, and Docker's own `.State.ExitCode` takes precedence over the log text. diff --git a/rust/src/lib/mod.rs b/rust/src/lib/mod.rs index 71d03b2..e4b02e5 100644 --- a/rust/src/lib/mod.rs +++ b/rust/src/lib/mod.rs @@ -87,7 +87,7 @@ pub use status_formatter::{ format_record_as_text_with_current_time, format_record_list, format_record_list_as_links_notation, format_record_list_as_text, format_record_with_current_time, is_detached_session_alive, list_executions, query_status, - StatusQueryResult, + read_exit_code_from_log, StatusQueryResult, }; pub use substitution::{process_command, ProcessOptions, SubstitutionResult}; pub use usage::print_usage; diff --git a/rust/src/lib/status_formatter.rs b/rust/src/lib/status_formatter.rs index 2eb38a9..2657a3e 100644 --- a/rust/src/lib/status_formatter.rs +++ b/rust/src/lib/status_formatter.rs @@ -11,6 +11,7 @@ use crate::execution_store::{ExecutionRecord, ExecutionStatus, ExecutionStore}; use crate::output_blocks::{escape_for_links_notation, format_value_for_links_notation}; use serde_json::Value; use std::fs; +use std::io::{Read, Seek, SeekFrom}; use std::process::Command; /// Live state of a detached docker container by name. @@ -162,13 +163,73 @@ pub fn is_detached_session_alive(record: &ExecutionRecord) -> Option { } } -fn read_exit_code_from_log(log_path: &str) -> Option { - let content = fs::read_to_string(log_path).ok()?; - content +/// Number of trailing bytes scanned for the terminal log footer. The footer is +/// always appended at the very end of the log, so there is no reason to read +/// (potentially megabytes of) command output on every `--status` call. +const LOG_TAIL_BYTES: u64 = 16 * 1024; + +/// Read the last `bytes` bytes of a file as (lossy) UTF-8 text. +/// +/// A partial first line is dropped: the slice can start in the middle of a +/// line, and that fragment must not be treated as the beginning of a line by +/// the anchored footer matcher. +fn read_log_tail(log_path: &str, bytes: u64) -> Option { + let mut file = fs::File::open(log_path).ok()?; + let size = file.metadata().ok()?.len(); + let length = size.min(bytes); + file.seek(SeekFrom::Start(size - length)).ok()?; + let mut buffer = Vec::with_capacity(length as usize); + file.take(length).read_to_end(&mut buffer).ok()?; + let tail = String::from_utf8_lossy(&buffer).into_owned(); + if size <= bytes { + return Some(tail); + } + Some(match tail.find('\n') { + Some(index) => tail[index + 1..].to_string(), + None => String::new(), + }) +} + +fn is_footer_separator_line(line: &str) -> bool { + line.len() >= 10 && line.chars().all(|c| c == '=') +} + +/// Read the terminal exit code from the anchored footer at the end of a log. +/// +/// The footer `start` itself writes (see `create_log_footer()` and +/// `shell_log_footer_snippet()`) is a three-line block: +/// +/// ```text +/// ================================================== +/// Finished: 2026-07-30 23:36:20.295 +/// Exit Code: 0 +/// ``` +/// +/// Matching the whole block at line starts means a bare `Exit Code: N` +/// substring emitted by the wrapped command (inside a JSON payload, a quoted +/// log excerpt, an `rg` dump, ...) can no longer be mistaken for the footer +/// (issue #150). Returns None when the log has no footer yet — never a number +/// parsed out of the command's own output. +pub fn read_exit_code_from_log(log_path: &str) -> Option { + let tail = read_log_tail(log_path, LOG_TAIL_BYTES)?; + let lines: Vec<&str> = tail .lines() - .rev() - .find_map(|line| line.trim().strip_prefix("Exit Code:")) - .and_then(|value| value.trim().parse::().ok()) + .map(|line| line.trim_end_matches('\r')) + .collect(); + for index in (2..lines.len()).rev() { + let value = match lines[index].strip_prefix("Exit Code:") { + Some(value) => value, + None => continue, + }; + if !lines[index - 1].starts_with("Finished:") || !is_footer_separator_line(lines[index - 2]) + { + continue; + } + if let Ok(code) = value.trim().parse::() { + return Some(code); + } + } + None } /// Enrich execution record with live session status for detached executions. @@ -251,14 +312,16 @@ pub fn enrich_detached_status(record: &ExecutionRecord) -> ExecutionRecord { // Otherwise keep the recorded/footer exit code - the command has finished. } else if !alive && enriched.status == ExecutionStatus::Executing { // Session ended but record says executing - correct it. Resolve a real - // exit code: prefer the log footer, then the backend's own record (e.g. - // `docker inspect .State.ExitCode`), and only fall back to the `-1` - // sentinel as a last resort when no real code can be obtained (issue #136). + // exit code: prefer the backend's own record (e.g. `docker inspect + // .State.ExitCode`, which is authoritative and cannot be spoofed by + // command output — issue #150), then the anchored log footer, and only + // fall back to the `-1` sentinel as a last resort when no real code can + // be obtained (issue #136). enriched.status = ExecutionStatus::Executed; if enriched.exit_code.is_none() { enriched.exit_code = Some( - footer_exit - .or_else(|| read_backend_exit_code(&enriched)) + read_backend_exit_code(&enriched) + .or(footer_exit) .unwrap_or(-1), ); } diff --git a/rust/tests/regression_150.rs b/rust/tests/regression_150.rs new file mode 100644 index 0000000..b78ed79 --- /dev/null +++ b/rust/tests/regression_150.rs @@ -0,0 +1,184 @@ +//! Regression tests for issue #150: +//! "`$ --status` fabricates a detached session exit code from the command's own +//! output (unanchored `Exit Code:` scan over the whole log)" +//! +//! The exit code of a detached session used to be derived from an unanchored +//! `Exit Code: N` scan over the whole session log, so any text the wrapped +//! command printed that merely contained that substring was indistinguishable +//! from the terminal footer `start` appends itself. +//! +//! The fix anchors the scan on the three-line footer block `start` writes +//! (separator / `Finished:` / `Exit Code:`) and only reads the tail of the log, +//! where the footer always is. +//! +//! Reference: https://github.com/link-foundation/start/issues/150 + +use start_command::execution_store::{ExecutionRecord, ExecutionRecordOptions, ExecutionStatus}; +use start_command::{enrich_detached_status, read_exit_code_from_log}; +use std::fs; +use tempfile::TempDir; + +const SEPARATOR: &str = "=================================================="; + +fn real_footer(exit_code: i32) -> String { + format!("\n{SEPARATOR}\nFinished: 2026-07-30 23:36:20.295\nExit Code: {exit_code}\n") +} + +fn write_log(dir: &TempDir, content: &str) -> String { + let log_path = dir.path().join("session.log"); + fs::write(&log_path, content).unwrap(); + log_path.to_string_lossy().to_string() +} + +#[test] +fn test_ignores_exit_code_substring_in_command_output() { + let dir = TempDir::new().unwrap(); + // Exactly the payload from the incident: an older session log dumped by + // `rg -n` into the JSON output of the running command. + let log_path = write_log( + &dir, + "{\"type\":\"item.completed\",\"item\":{\"aggregated_output\":\ + \"40-==================================================\\n41-Finished: 2026-07-28 20:04:52.316\\n42-Exit Code: 1\\n\",\ + \"exit_code\":0,\"status\":\"completed\"}}\n", + ); + assert_eq!(read_exit_code_from_log(&log_path), None); +} + +#[test] +fn test_ignores_bare_exit_code_line_without_footer_block() { + let dir = TempDir::new().unwrap(); + let log_path = write_log(&dir, "Exit Code: 1\nstill running\n"); + assert_eq!(read_exit_code_from_log(&log_path), None); +} + +#[test] +fn test_ignores_exit_code_in_the_middle_of_a_line() { + let dir = TempDir::new().unwrap(); + let log_path = write_log( + &dir, + &format!("{SEPARATOR}\nFinished: now\nlog: Exit Code: 3\n"), + ); + assert_eq!(read_exit_code_from_log(&log_path), None); +} + +#[test] +fn test_reads_the_real_footer() { + let dir = TempDir::new().unwrap(); + let log_path = write_log(&dir, &format!("hello\n{}", real_footer(0))); + assert_eq!(read_exit_code_from_log(&log_path), Some(0)); +} + +#[test] +fn test_last_anchored_footer_wins() { + let dir = TempDir::new().unwrap(); + let log_path = write_log( + &dir, + &format!( + "{SEPARATOR}\nFinished: fake\nExit Code: 1\n{}", + real_footer(0) + ), + ); + assert_eq!(read_exit_code_from_log(&log_path), Some(0)); +} + +#[test] +fn test_reads_crlf_and_negative_codes() { + let dir = TempDir::new().unwrap(); + let log_path = write_log( + &dir, + &format!("{SEPARATOR}\r\nFinished: t\r\nExit Code: 137\r\n"), + ); + assert_eq!(read_exit_code_from_log(&log_path), Some(137)); + + let log_path = write_log(&dir, &real_footer(-1)); + assert_eq!(read_exit_code_from_log(&log_path), Some(-1)); +} + +#[test] +fn test_returns_none_without_footer_or_file() { + let dir = TempDir::new().unwrap(); + let log_path = write_log(&dir, "still running, no footer yet\n"); + assert_eq!(read_exit_code_from_log(&log_path), None); + assert_eq!( + read_exit_code_from_log(&dir.path().join("missing.log").to_string_lossy()), + None + ); +} + +#[test] +fn test_finds_footer_at_the_end_of_a_large_log() { + let dir = TempDir::new().unwrap(); + let log_path = write_log( + &dir, + &format!("{}\n{}", "x".repeat(2 * 1024 * 1024), real_footer(42)), + ); + assert_eq!(read_exit_code_from_log(&log_path), Some(42)); +} + +#[test] +fn test_partial_first_line_of_the_tail_is_dropped() { + let dir = TempDir::new().unwrap(); + // The separator is a line *continuation*: the line starts with the filler, + // so it is not a footer even though the tail slice begins mid-line. + let log_path = write_log( + &dir, + &format!( + "{}{SEPARATOR}\nFinished: t\nExit Code: 7\n", + "y".repeat(32 * 1024) + ), + ); + assert_eq!(read_exit_code_from_log(&log_path), None); +} + +fn make_absent_docker_record(log_path: &str) -> ExecutionRecord { + let mut options = std::collections::HashMap::new(); + // A container name that cannot be inspected: liveness is unknown, the exact + // window in which the incident happened. + options.insert( + "sessionName".to_string(), + serde_json::Value::String(format!("issue150-absent-{}", std::process::id())), + ); + options.insert( + "isolated".to_string(), + serde_json::Value::String("docker".to_string()), + ); + options.insert( + "isolationMode".to_string(), + serde_json::Value::String("detached".to_string()), + ); + ExecutionRecord::with_options(ExecutionRecordOptions { + command: "solve.mjs".to_string(), + log_path: Some(log_path.to_string()), + options: Some(options), + ..Default::default() + }) +} + +#[test] +fn test_forged_output_does_not_terminate_an_executing_record() { + let dir = TempDir::new().unwrap(); + let log_path = write_log( + &dir, + "{\"aggregated_output\":\"41-Finished: x\\n42-Exit Code: 1\\n\",\"exit_code\":0}\n", + ); + let enriched = enrich_detached_status(&make_absent_docker_record(&log_path)); + assert_eq!(enriched.status, ExecutionStatus::Executing); + assert_eq!(enriched.exit_code, None); + assert!(enriched.end_time.is_none()); +} + +#[test] +fn test_genuine_footer_terminates_the_record() { + let dir = TempDir::new().unwrap(); + let log_path = write_log( + &dir, + &format!( + "{{\"aggregated_output\":\"42-Exit Code: 1\\n\"}}\n{}", + real_footer(0) + ), + ); + let enriched = enrich_detached_status(&make_absent_docker_record(&log_path)); + assert_eq!(enriched.status, ExecutionStatus::Executed); + assert_eq!(enriched.exit_code, Some(0)); + assert!(enriched.end_time.is_some()); +} From 08cceb320c0ff26ffdda1609ca5b378a25c4c3f1 Mon Sep 17 00:00:00 2001 From: konard Date: Tue, 4 Aug 2026 04:13:16 +0000 Subject: [PATCH 3/3] Revert "Initial commit with task details" This reverts commit cad1d266605892c97c08c250f7becf891dfaf3fd. --- .gitkeep | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/.gitkeep b/.gitkeep index c3e2c48..215a936 100644 --- a/.gitkeep +++ b/.gitkeep @@ -1,3 +1,2 @@ # .gitkeep file auto-generated at 2026-06-26T14:21:03.315Z for PR creation at branch issue-144-d8d3fb7dfd56 for issue https://github.com/link-foundation/start/issues/144 -# Updated: 2026-06-26T16:22:21.672Z -# Updated: 2026-08-04T03:52:57.895Z \ No newline at end of file +# Updated: 2026-06-26T16:22:21.672Z \ No newline at end of file