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 58374c4..1c3af33 100644 --- a/js/src/lib/status-formatter.js +++ b/js/src/lib/status-formatter.js @@ -175,20 +175,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); } /** @@ -280,15 +348,17 @@ 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`), then `137` when the only evidence left - // is the OOM observation, and only fall back to the `-1` sentinel as a last - // resort when no real code can be obtained (issues #136, #151). + // 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, then `137` when the + // only evidence left is the OOM observation, and only fall back to the `-1` + // sentinel as a last resort when no real code can be obtained (issues #136, + // #151). enriched.status = 'executed'; if (enriched.exitCode === null || enriched.exitCode === undefined) { enriched.exitCode = - footerExit ?? backendExitCode(dockerState) ?? + footerExit ?? (oomKilled === true ? 137 : -1); } if (!enriched.endTime) { @@ -638,6 +708,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/js/test/session-name-status.js b/js/test/session-name-status.js index f2a519d..0bc7970 100644 --- a/js/test/session-name-status.js +++ b/js/test/session-name-status.js @@ -846,7 +846,12 @@ describe('Issue #151: OOMKilled is an observation, not a verdict', () => { }); it('prefers the log footer exit code over the OOM fallback when the container is gone', () => { - fs.writeFileSync(logPath, 'Finished: now\nExit Code: 0\n', 'utf8'); + // The anchored footer block `start` itself writes (issue #150). + fs.writeFileSync( + logPath, + `${'='.repeat(50)}\nFinished: now\nExit Code: 0\n`, + 'utf8' + ); const record = saveDockerRecord({ oomKilled: true }); withFakeDockerMissingContainer(() => { diff --git a/rust/Cargo.lock b/rust/Cargo.lock index 2a9193b..aabd0b1 100644 --- a/rust/Cargo.lock +++ b/rust/Cargo.lock @@ -437,7 +437,7 @@ checksum = "0c790de23124f9ab44544d7ac05d60440adc586479ce501c1d6d7da3cd8c9cf5" [[package]] name = "start-command" -version = "0.17.3" +version = "0.17.4" 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 073813a..0c3491d 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. @@ -172,13 +173,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. @@ -270,15 +331,17 @@ 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`), then `137` when the only evidence - // left is the OOM observation, and only fall back to the `-1` sentinel - // as a last resort when no real code can be obtained (issues #136, #151). + // 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, then + // `137` when the only evidence left is the OOM observation, and only + // fall back to the `-1` sentinel as a last resort when no real code can + // be obtained (issues #136, #151). enriched.status = ExecutionStatus::Executed; if enriched.exit_code.is_none() { enriched.exit_code = Some( - footer_exit - .or_else(|| backend_exit_code(docker_state)) + backend_exit_code(docker_state) + .or(footer_exit) .or(if oom_killed == Some(true) { Some(137) } else { 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()); +} diff --git a/rust/tests/status_formatter.rs b/rust/tests/status_formatter.rs index 752fba3..a8b6ab6 100644 --- a/rust/tests/status_formatter.rs +++ b/rust/tests/status_formatter.rs @@ -516,7 +516,12 @@ fn docker_oom_killed_uses_the_container_exit_code_when_it_stops() { fn docker_oom_killed_prefers_the_log_footer_over_the_137_fallback() { let temp_dir = TempDir::new().unwrap(); let log_path = temp_dir.path().join("issue-151.log"); - std::fs::write(&log_path, "Finished: now\nExit Code: 0\n").unwrap(); + // The anchored footer block `start` itself writes (issue #150). + std::fs::write( + &log_path, + "==================================================\nFinished: now\nExit Code: 0\n", + ) + .unwrap(); let store = ExecutionStore::with_options(ExecutionStoreOptions { app_folder: Some(temp_dir.path().to_path_buf()), use_links: Some(false),