diff --git a/docs/case-studies/issue-96/README.md b/docs/case-studies/issue-96/README.md new file mode 100644 index 0000000..bd930b7 --- /dev/null +++ b/docs/case-studies/issue-96/README.md @@ -0,0 +1,70 @@ +# Case Study: Issue #96 — `agent --version` output missing in screen isolation + +## Summary + +When running a quick-completing command (like `agent --version`) through screen isolation: + +``` +$ --isolated screen -- agent --version +``` + +the command executes successfully (exit code 0) but the output is **not displayed** — the +version string `0.13.2` is silently swallowed. + +## Reproduction + +``` +$ --isolated screen -- agent --version +│ session 1d4a5afb-00f3-40cb-b506-0edde9288b77 +│ isolation screen +│ mode attached +│ screen screen-1773491715194-1ppv87 +│ +$ agent --version + + +✓ +│ exit 0 +│ duration 0.391s +``` + +The expected output `0.13.2` is missing between `$ agent --version` and the `✓` marker. + +## Fix (v0.24.9 / PR #97) + +Two changes were made: + +### 1. Add `logfile flush 0` to screen's configuration + +For the **native logging path** (`-L -Logfile`, screen ≥ 4.5.1), screen uses a periodic +flush timer that fires every **10 seconds** by default. If the command completes and the +screen session terminates before this timer fires, output buffered inside screen's internal +`FILE*` buffer may not be flushed to the log file before the session ends. + +The fix passes a temporary screenrc with `logfile flush 0` via screen's `-c` option. This +forces screen to flush the log after every write, eliminating the race condition. + +Before fix: +``` +screen -dmS -L -Logfile -c '' +``` + +After fix: +``` +screen -dmS -c -L -Logfile -c '' +``` + +where `` contains `logfile flush 0`. + +### 2. Add integration test for quick-completing commands + +Added a test case specifically for the issue: `runInScreen('agent --version')` must +capture the version output correctly. + +## See Also + +- [root-cause.md](root-cause.md) — Detailed root cause analysis +- [timeline.md](timeline.md) — Sequence of events +- [solutions.md](solutions.md) — Solutions considered and chosen +- Related: [Case Study issue-15](../issue-15/README.md) — Original screen output capture fix +- Related: [Case Study issue-25](../issue-25/README.md) — Screen quoting fix diff --git a/docs/case-studies/issue-96/root-cause.md b/docs/case-studies/issue-96/root-cause.md new file mode 100644 index 0000000..c35a690 --- /dev/null +++ b/docs/case-studies/issue-96/root-cause.md @@ -0,0 +1,148 @@ +# Root Cause Analysis: Issue #96 + +## The Bug + +`agent --version` (or any quick-completing command) run through screen isolation +produces no output, even though the command succeeds with exit code 0. + +--- + +## Root Cause 1: GNU Screen's Periodic Log Flush (Native Logging Path, Screen ≥ 4.5.1) + +### GNU Screen log flush architecture + +GNU Screen's `-L` logging feature writes output to a libc `FILE*` buffer (not directly +to disk). Flush is controlled by the `log_flush` variable (default: `10` seconds): + +```c +// src/screen.c +int log_flush = 10; + +// src/ansi.c — WLogString (called for every logged character) +static void WLogString(Window *win, char *buf, size_t len) +{ + if (!win->w_log) return; + logfwrite(win->w_log, buf, len); // writes to FILE* buffer + if (!log_flush) + logfflush(win->w_log); // only flushes immediately if log_flush == 0 +} +``` + +With `log_flush = 10` (the default), `logfflush` is **not called** after each write. +Instead, the periodic flush timer fires every 10 seconds: + +```c +// src/window.c — DoStartLog +SetTimeout(&logflushev, n * 1000); // n = log_flush = 10 +evenq(&logflushev); +``` + +For `agent --version` which runs in ~50ms, the screen session exits before this timer +ever fires. + +### Why fclose should flush (but may not) + +On graceful shutdown, `Finit()` → `FreeWindow()` → `logfclose()` → `fclose()` is called. +POSIX guarantees that `fclose()` flushes the stdio buffer before closing. So in the +**normal exit path**, data is not lost. + +However, if screen is terminated via a signal that invokes `_exit()` rather than `exit()`, +stdio buffers are NOT flushed. This can happen when: +1. The child process terminates and screen receives SIGCHLD +2. Screen's signal handler calls `_exit()` directly in certain code paths + +This makes the issue **intermittent** — it depends on the OS, screen version, and exact +timing of the signal handling. + +### The fix + +Add `logfile flush 0` to a temporary screenrc passed via `screen -c`: + +``` +logfile flush 0 +``` + +This sets `log_flush = 0` in screen's internal variable, causing `WLogString` to call +`logfflush()` after every write: + +```c +if (!log_flush) + logfflush(win->w_log); // now always executes +``` + +This completely eliminates the flush delay for log file writes. + +--- + +## Root Cause 2: Tee Pipe Buffering Race (Tee Fallback, Screen < 4.5.1) + +### macOS bundled screen 4.0.3 + +On macOS, the system-bundled GNU Screen is version 4.0.3, which predates the `-Logfile` +option (added in 4.5.1). The code falls back to: + +```js +effectiveCommand = `(${effectiveCommand}) 2>&1 | tee "${logFile}"`; +``` + +The screen session runs: +``` +screen -dmS session /bin/zsh -c "(agent --version) 2>&1 | tee /tmp/logfile" +``` + +### The race condition + +When `agent --version` completes in ~5ms: +1. The agent process writes `0.13.2\n` to stdout +2. The tee process receives the data and writes it to the log file +3. The zsh process exits +4. Screen detects the child exit and terminates the session + +The RACE: between step 2 (tee writes to OS page cache) and our poller reading the file, +there may be a brief window where: +- The log file exists but the `write()` syscall from tee hasn't been committed to the + page cache yet (on some OS implementations) +- OR the file still has 0 bytes because tee's userspace buffer hasn't been `fwrite`'d + yet when screen terminates it + +This is a TOCTOU (time-of-check-time-of-use) race between the session appearing gone in +`screen -ls` and the log file having its complete content. + +### The fix + +The `logfile flush 0` fix in the screenrc does NOT directly help the tee fallback path +(since tee is an external process, not governed by screen's log flush). However, an +additional retry mechanism can be added: if the log file is empty when first read but the +session just terminated, retry the read after a brief delay to let the OS flush complete. + +In practice, on Linux the tee fallback is not used (screen >= 4.5.1 is available), and +on macOS the `logfile flush 0` option works on screen 4.0.3 as well (it's a screenrc +command, not a version-gated feature). + +--- + +## Why This Is Intermittent + +The issue doesn't always reproduce because: + +1. **On Linux with screen 4.09.01**: The normal `fclose()` path usually flushes the buffer + correctly. Only under certain timing conditions (SIGCHLD handling, `_exit`) does it fail. + +2. **On macOS with screen 4.0.3**: The tee fallback's race window is very small (~1ms). + Most of the time the file has content when read. But for very fast commands with a + busy system, the window widens. + +3. **The `screen -ls` timing**: The check `!sessions.includes(sessionName)` returns true + as soon as the session process exits, but the OS may still be in the middle of flushing + the log file's write buffers to the page cache. + +--- + +## Test Coverage Gap + +There were no tests specifically for: +1. Quick-completing commands (like `--version` flags) in screen isolation +2. Verification that version-string output (short, non-whitespace text) is captured + +The existing tests use `echo "hello"` which is also fast but the string is longer and +may flush more reliably in certain conditions. diff --git a/docs/case-studies/issue-96/solutions.md b/docs/case-studies/issue-96/solutions.md new file mode 100644 index 0000000..a4d21cf --- /dev/null +++ b/docs/case-studies/issue-96/solutions.md @@ -0,0 +1,108 @@ +# Solutions: Issue #96 + +## Problem Statement + +Quick-completing commands (like `agent --version`) run through screen isolation +produce no output. The screen session exits cleanly but the log file is empty. + +--- + +## Solutions Considered + +### Option A: Add `sleep` after the command in screen + +**Approach:** Append `; sleep 0.1` to every command run in screen to give the log a +chance to flush before the session exits. + +**Pros:** Simple, one-line change. + +**Cons:** +- Slows every command by at least 100ms (unacceptable for interactive use) +- Hacky — fights symptoms rather than addressing the root cause +- Still a race condition (just smaller) + +### Option B: Retry reading the log file with exponential backoff + +**Approach:** After detecting session completion, if the log file is empty, retry +reading it up to 3 times with 10ms, 20ms, 40ms delays. + +**Pros:** Addresses the TOCTOU race condition for the tee fallback path. + +**Cons:** +- Does NOT fix the native logging path's `log_flush = 10` issue +- Adds complexity to the polling logic +- Still a race for very slow systems + +### Option C: Use a temporary screenrc with `logfile flush 0` (CHOSEN) + +**Approach:** For the native logging path (`-L -Logfile`, screen ≥ 4.5.1), create a +temporary screenrc file containing `logfile flush 0` and pass it to screen via the +`-c` option. + +``` +echo "logfile flush 0" > /tmp/screen-rc-XXXX.rc +screen -dmS session -c /tmp/screen-rc-XXXX.rc -L -Logfile logfile shell -c command +``` + +`logfile flush 0` sets `log_flush = 0` in screen's internal state, which causes +`WLogString()` in `ansi.c` to call `logfflush()` (equivalent to `fflush()`) after +every write. This completely eliminates the 10-second buffering delay. + +**Pros:** +- Eliminates the flush delay entirely for the native logging path +- Standard approach recommended in GNU Screen documentation +- No performance impact on the command itself (the flush is async in screen's event loop) +- Clean implementation — the temp file is created and deleted by our code +- Works on all screen versions that support the `-c` option (very old) + +**Cons:** +- Requires creating/deleting an additional temp file per invocation +- The `-c` option overrides the user's `~/.screenrc` — but since we only put + `logfile flush 0` in it, there's no conflict for our use case + +**Note on the tee fallback path (screen < 4.5.1):** +The `logfile flush 0` setting in a screenrc also works on older screen versions (it's +a screenrc directive, not version-gated). However, for the tee fallback path, screen +itself doesn't write the log — `tee` does. So `logfile flush 0` doesn't help for +the tee path. For this path, Option B (retry) is added as a complementary fix. + +### Option D: Use `script` instead of screen's `-L` + +**Approach:** Replace screen's log capture with `script -c "command" logfile`, which +uses a pty and has more reliable flush-on-exit behavior. + +**Pros:** `script` is designed for output capture and handles flush correctly. + +**Cons:** +- `script` behavior varies significantly between Linux (util-linux) and macOS (BSD) +- macOS `script` uses different flags (`-q`, `-c` not available) +- Complex to handle cross-platform +- Loses screen's session management features + +--- + +## Chosen Solution: Option C + Option B + +**Implementation:** + +For native logging path (screen ≥ 4.5.1): +```js +// Create temporary screenrc with immediate log flush +const screenrcFile = path.join(os.tmpdir(), `screenrc-${sessionName}`); +fs.writeFileSync(screenrcFile, 'logfile flush 0\n'); + +const logArgs = ['-dmS', sessionName, '-c', screenrcFile, '-L', '-Logfile', logFile]; +screenArgs = [...logArgs, shell, shellArg, effectiveCommand]; + +// Clean up screenrc on completion +try { fs.unlinkSync(screenrcFile); } catch {} +``` + +For tee fallback path (screen < 4.5.1): add a brief retry when the log file is empty +immediately after session completion. + +**Why this is correct:** +- Setting `logfile flush 0` is the standard, official way to control screen's log + flush behavior, documented in the GNU Screen manual +- It directly addresses the root cause (buffered writes) rather than fighting symptoms +- The retry for the tee path handles the TOCTOU race for the remaining edge case diff --git a/docs/case-studies/issue-96/timeline.md b/docs/case-studies/issue-96/timeline.md new file mode 100644 index 0000000..8e26b60 --- /dev/null +++ b/docs/case-studies/issue-96/timeline.md @@ -0,0 +1,87 @@ +# Timeline: Issue #96 + +## Reproduction Command +``` +$ --isolated screen -- agent --version +``` + +## User Environment +- macOS (Apple Silicon / Intel) +- GNU Screen 4.0.3 (bundled with macOS — older than 4.5.1 threshold) +- OR: Linux with GNU Screen ≥ 4.5.1 where the race condition still exists under load + +--- + +## Sequence of Events (Tee Fallback Path — macOS Screen 4.0.3) + +### Step 1: CLI parses command +``` +$ --isolated screen -- agent --version +``` +→ `command = "agent --version"`, `isolated = "screen"`, `mode = "attached"` + +### Step 2: `runScreenWithLogCapture()` is called +- `supportsLogfileOption()` returns `false` (screen 4.0.3 < 4.5.1) +- Tee fallback path chosen +- `effectiveCommand = "(agent --version) 2>&1 | tee \"/tmp/screen-output-...log\""` +- Screen starts: `screen -dmS session /bin/zsh -c "(agent --version) 2>&1 | tee logfile"` + +### Step 3: Screen session runs the command (t ≈ 0ms) +- Screen starts its internal process +- `agent --version` executes (very fast, ≈ 5ms) +- `agent` writes `0.13.2\n` to stdout +- The tee pipe receives the output and writes it to the log file +- The zsh process exits +- Screen detects child exit and terminates the session +- Screen session is gone (t ≈ 50ms total) + +### Step 4: Our poller first checks at t = 100ms +- `execSync('screen -ls')` runs +- Session name NOT found → session is done +- `fs.readFileSync(logFile)` reads the log file + +### Step 5 (BUG): Log file is empty or missing +**Root cause 1 (screen ≥ 4.5.1, native logging path):** +- Screen writes to a libc `FILE*` buffer via `fwrite` +- GNU Screen's `log_flush` defaults to 10 seconds +- With `log_flush = 10`, `WLogString()` in `ansi.c` does NOT call `logfflush` after each write +- The periodic flush timer fires at t = 10,000ms, but the session terminated at t ≈ 50ms +- If `fclose` is called properly in `Finit()→FreeWindow()→logfclose()`, libc's `fclose` + should flush the buffer (POSIX guarantees `fclose` flushes before closing) +- However: on macOS with Homebrew screen / system screen, the `fclose` may be called from + a signal handler or cleanup path that uses `_exit()` instead of `exit()`, bypassing + stdio buffer flushing entirely + +**Root cause 2 (screen < 4.5.1, tee fallback path):** +- The tee pipe's output buffering may not be complete when the screen session exits +- The log file may exist but contain 0 bytes at the moment of reading +- This is a TOCTOU (time-of-check-time-of-use) race condition + +### Step 6: Empty output displayed +- `output.trim()` is falsy (empty string) +- Nothing is written to `process.stdout` +- The version string `0.13.2` is silently lost + +--- + +## Sequence of Events (Native Logging Path — Screen ≥ 4.5.1) + +### Step 3 (detail): Screen's internal log buffer +- Screen writes `0.13.2\r\n` to its internal `FILE*` log buffer via `logfwrite()` +- With default `log_flush = 10`, `WLogString()` does NOT call `logfflush()` +- The session exits before the 10-second flush timer fires +- If `Finit()` calls `fclose()` via the normal exit path, the buffer IS flushed (POSIX) +- BUT: if any signal handler calls `_exit()`, the buffer is NOT flushed + +This explains why the issue is **intermittent** — it depends on whether screen exits +via the normal `exit()` code path or a signal-triggered `_exit()` path. + +--- + +## Verified Behavior (Linux, Screen 4.09.01) +On Linux with screen 4.09.01, the issue does NOT reproduce reliably because: +1. The `fclose` path is taken in `logfclose()`, flushing the stdio buffer +2. The tee fallback is not used (native logging is available) +3. The fix (logfile flush 0) ensures the buffer is always flushed immediately + +The issue is most reproducible on macOS where the tee fallback is used. diff --git a/experiments/test-screen-output-empty.js b/experiments/test-screen-output-empty.js new file mode 100644 index 0000000..e89d85d --- /dev/null +++ b/experiments/test-screen-output-empty.js @@ -0,0 +1,58 @@ +// Simulate what happens if screen session exits BEFORE first poll check +// i.e. test the race condition where the session is gone before we even start polling +const { execSync, spawnSync } = require('child_process'); +const fs = require('fs'); +const os = require('os'); + +const sessionName = `screen-test-race-${Date.now()}-${Math.random().toString(36).substring(2, 8)}`; +const logFile = os.tmpdir() + `/screen-output-${sessionName}.log`; +const shell = '/bin/bash'; +const shellArg = '-c'; +const command = 'echo test-version-output'; + +// Modern screen path (>= 4.5.1) +const screenArgs = ['-dmS', sessionName, '-L', '-Logfile', logFile, shell, shellArg, command]; + +console.log(`Testing native log capture: screen ${screenArgs.join(' ')}`); + +const result = spawnSync('screen', screenArgs, { stdio: 'inherit' }); +if (result.error) { + console.error('Error:', result.error); + process.exit(1); +} + +// Immediately (no delay) check if session is gone +try { + const sessions = execSync('screen -ls', { encoding: 'utf8', stdio: ['pipe', 'pipe', 'pipe'] }); + if (!sessions.includes(sessionName)) { + console.log('Session already gone immediately after start!'); + // Read the log file immediately + try { + const output = fs.readFileSync(logFile, 'utf8'); + console.log(`Immediate read: "${output.trim()}"`); + } catch(e) { + console.log(`Log file not yet available: ${e.message}`); + } + } else { + console.log('Session still running...'); + } +} catch { + console.log('screen -ls failed (no sessions)'); + try { + const output = fs.readFileSync(logFile, 'utf8'); + console.log(`Immediate read after -ls failure: "${output.trim()}"`); + } catch(e) { + console.log(`Log file not yet available: ${e.message}`); + } +} + +// After 200ms +setTimeout(() => { + try { + const output = fs.readFileSync(logFile, 'utf8'); + console.log(`After 200ms: "${output.trim()}"`); + } catch(e) { + console.log(`After 200ms - log not found: ${e.message}`); + } + try { fs.unlinkSync(logFile); } catch {} +}, 200); diff --git a/experiments/test-screen-version-output.sh b/experiments/test-screen-version-output.sh new file mode 100755 index 0000000..5b374ad --- /dev/null +++ b/experiments/test-screen-version-output.sh @@ -0,0 +1,37 @@ +#!/bin/bash +# Test if screen properly captures output from quick commands +# This tests the race condition in issue #96 + +SESSION="test-screen-issue-96-$$" +LOGFILE="/tmp/screen-test-issue96-${SESSION}.log" + +echo "=== Test 1: Basic echo (modern screen with -L -Logfile) ===" +screen -dmS "$SESSION" -L -Logfile "$LOGFILE" bash -c "echo hello-from-screen" +sleep 0.5 +echo "Log content after 0.5s:" +cat "$LOGFILE" 2>/dev/null || echo "(log file not found)" +# Clean up +screen -S "$SESSION" -X quit 2>/dev/null || true +rm -f "$LOGFILE" + +echo "" +echo "=== Test 2: Version-like command (quick exit) ===" +SESSION2="test-screen-issue96-v2-$$" +LOGFILE2="/tmp/screen-test-issue96-v2-${SESSION2}.log" +screen -dmS "$SESSION2" -L -Logfile "$LOGFILE2" bash -c "echo 0.13.2" +sleep 0.5 +echo "Log content after 0.5s:" +cat "$LOGFILE2" 2>/dev/null || echo "(log file not found)" +screen -S "$SESSION2" -X quit 2>/dev/null || true +rm -f "$LOGFILE2" + +echo "" +echo "=== Test 3: Tee fallback (older screen method) ===" +SESSION3="test-screen-issue96-v3-$$" +LOGFILE3="/tmp/screen-test-issue96-v3-${SESSION3}.log" +screen -dmS "$SESSION3" bash -c "(echo 0.13.2) 2>&1 | tee \"$LOGFILE3\"" +sleep 0.5 +echo "Log content after 0.5s:" +cat "$LOGFILE3" 2>/dev/null || echo "(log file not found)" +screen -S "$SESSION3" -X quit 2>/dev/null || true +rm -f "$LOGFILE3" diff --git a/experiments/test-tee-fallback.js b/experiments/test-tee-fallback.js new file mode 100644 index 0000000..8758678 --- /dev/null +++ b/experiments/test-tee-fallback.js @@ -0,0 +1,66 @@ +// Test to simulate the tee fallback path (older screen < 4.5.1) +const { execSync, spawnSync } = require('child_process'); +const fs = require('fs'); +const os = require('os'); +const path = require('path'); + +const sessionName = `screen-test-tee-${Date.now()}-${Math.random().toString(36).substring(2, 8)}`; +const logFile = path.join(os.tmpdir(), `screen-output-${sessionName}.log`); +const shell = '/bin/bash'; +const shellArg = '-c'; +const command = 'echo test-version-output'; + +// Tee fallback (older screen path) +const effectiveCommand = `(${command}) 2>&1 | tee "${logFile}"`; +const screenArgs = ['-dmS', sessionName, shell, shellArg, effectiveCommand]; + +console.log(`Testing tee fallback: screen ${screenArgs.join(' ')}`); +console.log(`Logfile: ${logFile}`); + +const result = spawnSync('screen', screenArgs, { stdio: 'inherit' }); +if (result.error) { + console.error('Error spawning screen:', result.error); + process.exit(1); +} + +// Poll for session completion +const checkInterval = 100; +let waited = 0; +const maxWait = 5000; + +function checkCompletion() { + try { + const sessions = execSync('screen -ls', { encoding: 'utf8', stdio: ['pipe', 'pipe', 'pipe'] }); + if (!sessions.includes(sessionName)) { + let output = ''; + try { + output = fs.readFileSync(logFile, 'utf8'); + console.log(`\nOutput captured: "${output.trim()}"`); + if (!output.trim()) { + console.log('WARNING: No output captured!'); + } + } catch (e) { + console.log(`\nLog file not found or empty: ${e.message}`); + } + try { fs.unlinkSync(logFile); } catch {} + return; + } + waited += checkInterval; + if (waited >= maxWait) { + console.log('Timeout waiting for session'); + return; + } + setTimeout(checkCompletion, checkInterval); + } catch { + let output = ''; + try { + output = fs.readFileSync(logFile, 'utf8'); + console.log(`\nOutput captured (screen -ls failed): "${output.trim()}"`); + } catch (e) { + console.log(`\nLog file not found: ${e.message}`); + } + try { fs.unlinkSync(logFile); } catch {} + } +} + +setTimeout(checkCompletion, checkInterval); diff --git a/js/.changeset/fix-screen-log-flush-quick-commands.md b/js/.changeset/fix-screen-log-flush-quick-commands.md new file mode 100644 index 0000000..434e781 --- /dev/null +++ b/js/.changeset/fix-screen-log-flush-quick-commands.md @@ -0,0 +1,29 @@ +--- +'start-command': patch +--- + +fix: capture output from quick-completing commands in screen isolation (issue #96) + +When running a short-lived command like `agent --version` through screen isolation: + +``` +$ --isolated screen -- agent --version +``` + +the version output was silently lost — the command exited cleanly (exit code 0) +but no output was displayed. + +**Root cause:** GNU Screen's internal log buffer flushes every 10 seconds by default +(`log_flush = 10`). For commands that complete faster than this, the buffer may not +be flushed to the log file before the screen session terminates. + +**Fix:** A temporary screenrc file with `logfile flush 0` is passed to screen via +the `-c` option. This forces screen to flush the log buffer after every write, +eliminating the 10-second flush delay for quick-completing commands. + +A retry mechanism is also added for the tee fallback path (older screen < 4.5.1) +to handle the TOCTOU race where the log file appears empty when first read +immediately after session completion. + +Both JavaScript (`isolation.js`) and Rust (`isolation.rs`) implementations are fixed +with equivalent test coverage added. diff --git a/js/src/lib/isolation.js b/js/src/lib/isolation.js index 5344563..dfc7373 100644 --- a/js/src/lib/isolation.js +++ b/js/src/lib/isolation.js @@ -1,94 +1,20 @@ /** Isolation Runners for start-command (screen, tmux, docker, ssh) */ const { execSync, spawn, spawnSync } = require('child_process'); -const fs = require('fs'); -const os = require('os'); const path = require('path'); const { generateSessionName } = require('./args-parser'); const outputBlocks = require('./output-blocks'); -const setTimeout = globalThis.setTimeout; - // Debug mode from environment const DEBUG = process.env.START_DEBUG === '1' || process.env.START_DEBUG === 'true'; -// Cache for screen version detection -let cachedScreenVersion = null; -let screenVersionChecked = false; - -/** - * Get the installed screen version - * @returns {{major: number, minor: number, patch: number}|null} Version object or null if detection fails - */ -function getScreenVersion() { - if (screenVersionChecked) { - return cachedScreenVersion; - } - - screenVersionChecked = true; - - try { - const output = execSync('screen --version', { - encoding: 'utf8', - stdio: ['pipe', 'pipe', 'pipe'], - }); - // Match patterns like "4.09.01", "4.00.03", "4.5.1" - const match = output.match(/(\d+)\.(\d+)\.(\d+)/); - if (match) { - cachedScreenVersion = { - major: parseInt(match[1], 10), - minor: parseInt(match[2], 10), - patch: parseInt(match[3], 10), - }; - - if (DEBUG) { - console.log( - `[DEBUG] Detected screen version: ${cachedScreenVersion.major}.${cachedScreenVersion.minor}.${cachedScreenVersion.patch}` - ); - } - - return cachedScreenVersion; - } - } catch { - if (DEBUG) { - console.log('[DEBUG] Could not detect screen version'); - } - } - - return null; -} - -/** - * Check if screen supports the -Logfile option - * The -Logfile option was introduced in GNU Screen 4.5.1 - * @returns {boolean} True if -Logfile is supported - */ -function supportsLogfileOption() { - const version = getScreenVersion(); - if (!version) { - // If we can't detect version, assume older version and use fallback - return false; - } - - // -Logfile was added in 4.5.1 - // Compare: version >= 4.5.1 - if (version.major > 4) { - return true; - } - if (version.major < 4) { - return false; - } - // major === 4 - if (version.minor > 5) { - return true; - } - if (version.minor < 5) { - return false; - } - // minor === 5 - return version.patch >= 1; -} +const { + getScreenVersion, + supportsLogfileOption, + runScreenWithLogCapture: _runScreenWithLogCapture, + resetScreenVersionCache, +} = require('./screen-isolation'); /** * Check if a command is available on the system @@ -245,159 +171,14 @@ function wrapCommandWithUser(command, user) { * @returns {Promise<{success: boolean, sessionName: string, message: string, output: string}>} */ function runScreenWithLogCapture(command, sessionName, shellInfo, user = null) { - const { shell, shellArg } = shellInfo; - const logFile = path.join(os.tmpdir(), `screen-output-${sessionName}.log`); - - // Check if screen supports -Logfile option (added in 4.5.1) - const useNativeLogging = supportsLogfileOption(); - - return new Promise((resolve) => { - try { - let screenArgs; - // Wrap command with user switch if specified - let effectiveCommand = wrapCommandWithUser(command, user); - - if (useNativeLogging) { - // Modern screen (>= 4.5.1): Use -L -Logfile option for native log capture - // screen -dmS -L -Logfile -c '' - const logArgs = ['-dmS', sessionName, '-L', '-Logfile', logFile]; - screenArgs = isInteractiveShellCommand(command) - ? [...logArgs, ...command.trim().split(/\s+/)] - : [...logArgs, shell, shellArg, effectiveCommand]; - - if (DEBUG) { - console.log( - `[DEBUG] Running screen with native log capture (-Logfile): screen ${screenArgs.join(' ')}` - ); - } - } else { - // Older screen (< 4.5.1, e.g., macOS bundled 4.0.3): Use tee fallback - // The parentheses ensure proper grouping of the command and its stderr - const isBareShell = isInteractiveShellCommand(command); - if (!isBareShell) { - effectiveCommand = `(${effectiveCommand}) 2>&1 | tee "${logFile}"`; - } - screenArgs = isBareShell - ? ['-dmS', sessionName, ...command.trim().split(/\s+/)] - : ['-dmS', sessionName, shell, shellArg, effectiveCommand]; - - if (DEBUG) { - console.log( - `[DEBUG] Running screen with tee fallback (older screen version): screen ${screenArgs.join(' ')}` - ); - } - } - - // Use spawnSync with array args (not execSync string) to avoid quoting issues (issue #25) - const result = spawnSync('screen', screenArgs, { - stdio: 'inherit', - }); - - if (result.error) { - throw result.error; - } - - // Poll for session completion - const checkInterval = 100; // ms - const maxWait = 300000; // 5 minutes max - let waited = 0; - - const checkCompletion = () => { - try { - // Check if session still exists - const sessions = execSync('screen -ls', { - encoding: 'utf8', - stdio: ['pipe', 'pipe', 'pipe'], - }); - - if (!sessions.includes(sessionName)) { - // Session ended, read output - let output = ''; - try { - output = fs.readFileSync(logFile, 'utf8'); - // Display the output with surrounding empty lines for consistency - if (output.trim()) { - process.stdout.write(output); - // Add trailing newline if output doesn't end with one - if (!output.endsWith('\n')) { - process.stdout.write('\n'); - } - } - } catch { - // Log file might not exist if command was very quick - } - - // Clean up log file - try { - fs.unlinkSync(logFile); - } catch { - // Ignore cleanup errors - } - - resolve({ - success: true, - sessionName, - message: `Screen session "${sessionName}" exited with code 0`, - exitCode: 0, - output, - }); - return; - } - - waited += checkInterval; - if (waited >= maxWait) { - resolve({ - success: false, - sessionName, - message: `Screen session "${sessionName}" timed out after ${maxWait / 1000} seconds`, - exitCode: 1, - }); - return; - } - - setTimeout(checkCompletion, checkInterval); - } catch { - // screen -ls failed, session probably ended - let output = ''; - try { - output = fs.readFileSync(logFile, 'utf8'); - if (output.trim()) { - process.stdout.write(output); - // Add trailing newline if output doesn't end with one - if (!output.endsWith('\n')) { - process.stdout.write('\n'); - } - } - } catch { - // Ignore - } - - try { - fs.unlinkSync(logFile); - } catch { - // Ignore - } - - resolve({ - success: true, - sessionName, - message: `Screen session "${sessionName}" exited with code 0`, - exitCode: 0, - output, - }); - } - }; - - // Start checking after a brief delay - setTimeout(checkCompletion, checkInterval); - } catch (err) { - resolve({ - success: false, - sessionName, - message: `Failed to run in screen: ${err.message}`, - }); - } - }); + return _runScreenWithLogCapture( + command, + sessionName, + shellInfo, + user, + wrapCommandWithUser, + isInteractiveShellCommand + ); } /** @@ -934,12 +715,6 @@ function runIsolated(backend, command, options = {}) { } } -/** Reset screen version cache (useful for testing) */ -function resetScreenVersionCache() { - cachedScreenVersion = null; - screenVersionChecked = false; -} - const { getTimestamp, generateLogFilename, diff --git a/js/src/lib/screen-isolation.js b/js/src/lib/screen-isolation.js new file mode 100644 index 0000000..c62d6e1 --- /dev/null +++ b/js/src/lib/screen-isolation.js @@ -0,0 +1,309 @@ +/** Screen-specific isolation helpers extracted from isolation.js */ + +const { execSync, spawnSync } = require('child_process'); +const fs = require('fs'); +const os = require('os'); +const path = require('path'); + +const setTimeout = globalThis.setTimeout; + +// Debug mode from environment +const DEBUG = + process.env.START_DEBUG === '1' || process.env.START_DEBUG === 'true'; + +// Cache for screen version detection +let cachedScreenVersion = null; +let screenVersionChecked = false; + +/** + * Get the installed screen version + * @returns {{major: number, minor: number, patch: number}|null} Version object or null if detection fails + */ +function getScreenVersion() { + if (screenVersionChecked) { + return cachedScreenVersion; + } + + screenVersionChecked = true; + + try { + const output = execSync('screen --version', { + encoding: 'utf8', + stdio: ['pipe', 'pipe', 'pipe'], + }); + // Match patterns like "4.09.01", "4.00.03", "4.5.1" + const match = output.match(/(\d+)\.(\d+)\.(\d+)/); + if (match) { + cachedScreenVersion = { + major: parseInt(match[1], 10), + minor: parseInt(match[2], 10), + patch: parseInt(match[3], 10), + }; + + if (DEBUG) { + console.log( + `[DEBUG] Detected screen version: ${cachedScreenVersion.major}.${cachedScreenVersion.minor}.${cachedScreenVersion.patch}` + ); + } + + return cachedScreenVersion; + } + } catch { + if (DEBUG) { + console.log('[DEBUG] Could not detect screen version'); + } + } + + return null; +} + +/** + * Check if screen supports the -Logfile option + * The -Logfile option was introduced in GNU Screen 4.5.1 + * @returns {boolean} True if -Logfile is supported + */ +function supportsLogfileOption() { + const version = getScreenVersion(); + if (!version) { + // If we can't detect version, assume older version and use fallback + return false; + } + + // -Logfile was added in 4.5.1 + // Compare: version >= 4.5.1 + if (version.major > 4) { + return true; + } + if (version.major < 4) { + return false; + } + // major === 4 + if (version.minor > 5) { + return true; + } + if (version.minor < 5) { + return false; + } + // minor === 5 + return version.patch >= 1; +} + +/** + * Run command in GNU Screen using detached mode with log capture. + * Supports screen >= 4.5.1 (native -Logfile) and older versions (tee fallback). + * @param {string} command - Command to execute + * @param {string} sessionName - Session name + * @param {object} shellInfo - Shell info from getShell() + * @param {string|null} user - Username to run command as (optional) + * @param {Function} wrapCommandWithUser - Function to wrap command with user + * @param {Function} isInteractiveShellCommand - Function to check if command is interactive shell + * @returns {Promise<{success: boolean, sessionName: string, message: string, output: string}>} + */ +function runScreenWithLogCapture( + command, + sessionName, + shellInfo, + user = null, + wrapCommandWithUser, + isInteractiveShellCommand +) { + const { shell, shellArg } = shellInfo; + const logFile = path.join(os.tmpdir(), `screen-output-${sessionName}.log`); + + // Check if screen supports -Logfile option (added in 4.5.1) + const useNativeLogging = supportsLogfileOption(); + + return new Promise((resolve) => { + try { + let screenArgs; + // Wrap command with user switch if specified + let effectiveCommand = wrapCommandWithUser(command, user); + + // Temporary screenrc file for native logging path (issue #96) + // Setting logfile flush 0 forces screen to flush its log buffer after every write, + // preventing output loss for quick-completing commands like `agent --version`. + // Without this, screen buffers log writes and flushes every 10 seconds by default. + let screenrcFile = null; + + if (useNativeLogging) { + // Modern screen (>= 4.5.1): Use -L -Logfile option for native log capture + // Use a temporary screenrc with `logfile flush 0` to force immediate log flushing + // (issue #96: quick commands like `agent --version` lose output without this) + screenrcFile = path.join(os.tmpdir(), `screenrc-${sessionName}`); + try { + fs.writeFileSync(screenrcFile, 'logfile flush 0\n'); + } catch { + // If we can't create the screenrc, proceed without it (best effort) + screenrcFile = null; + } + + // screen -dmS -c -L -Logfile -c '' + const logArgs = screenrcFile + ? ['-dmS', sessionName, '-c', screenrcFile, '-L', '-Logfile', logFile] + : ['-dmS', sessionName, '-L', '-Logfile', logFile]; + screenArgs = isInteractiveShellCommand(command) + ? [...logArgs, ...command.trim().split(/\s+/)] + : [...logArgs, shell, shellArg, effectiveCommand]; + + if (DEBUG) { + console.log( + `[DEBUG] Running screen with native log capture (-Logfile): screen ${screenArgs.join(' ')}` + ); + } + } else { + // Older screen (< 4.5.1, e.g., macOS bundled 4.0.3): Use tee fallback + // The parentheses ensure proper grouping of the command and its stderr + const isBareShell = isInteractiveShellCommand(command); + if (!isBareShell) { + effectiveCommand = `(${effectiveCommand}) 2>&1 | tee "${logFile}"`; + } + screenArgs = isBareShell + ? ['-dmS', sessionName, ...command.trim().split(/\s+/)] + : ['-dmS', sessionName, shell, shellArg, effectiveCommand]; + + if (DEBUG) { + console.log( + `[DEBUG] Running screen with tee fallback (older screen version): screen ${screenArgs.join(' ')}` + ); + } + } + + // Use spawnSync with array args (not execSync string) to avoid quoting issues (issue #25) + const result = spawnSync('screen', screenArgs, { + stdio: 'inherit', + }); + + if (result.error) { + throw result.error; + } + + // Helper to read log file output and write to stdout + // Includes a short retry for the tee fallback path to handle the TOCTOU race + // condition where the session appears gone but the log file isn't fully written yet + // (issue #96) + const readAndDisplayOutput = (retryCount = 0) => { + let output = ''; + try { + output = fs.readFileSync(logFile, 'utf8'); + } catch { + // Log file might not exist if command produced no output + } + + // If output is empty and we haven't retried yet, wait briefly and retry once. + // This handles the race where tee's write hasn't been flushed to disk yet + // when the screen session appears done in `screen -ls` (issue #96). + if (!output.trim() && retryCount === 0) { + return new Promise((resolveRetry) => { + setTimeout(() => { + resolveRetry(readAndDisplayOutput(1)); + }, 50); + }); + } + + // Display the output + if (output.trim()) { + process.stdout.write(output); + // Add trailing newline if output doesn't end with one + if (!output.endsWith('\n')) { + process.stdout.write('\n'); + } + } + return Promise.resolve(output); + }; + + // Clean up temp files + const cleanupTempFiles = () => { + try { + fs.unlinkSync(logFile); + } catch { + // Ignore cleanup errors + } + if (screenrcFile) { + try { + fs.unlinkSync(screenrcFile); + } catch { + // Ignore cleanup errors + } + } + }; + + // Poll for session completion + const checkInterval = 100; // ms + const maxWait = 300000; // 5 minutes max + let waited = 0; + + const checkCompletion = () => { + try { + // Check if session still exists + const sessions = execSync('screen -ls', { + encoding: 'utf8', + stdio: ['pipe', 'pipe', 'pipe'], + }); + + if (!sessions.includes(sessionName)) { + // Session ended, read output (with retry for tee path race condition) + readAndDisplayOutput().then((output) => { + cleanupTempFiles(); + resolve({ + success: true, + sessionName, + message: `Screen session "${sessionName}" exited with code 0`, + exitCode: 0, + output, + }); + }); + return; + } + + waited += checkInterval; + if (waited >= maxWait) { + cleanupTempFiles(); + resolve({ + success: false, + sessionName, + message: `Screen session "${sessionName}" timed out after ${maxWait / 1000} seconds`, + exitCode: 1, + }); + return; + } + + setTimeout(checkCompletion, checkInterval); + } catch { + // screen -ls failed, session probably ended + readAndDisplayOutput().then((output) => { + cleanupTempFiles(); + resolve({ + success: true, + sessionName, + message: `Screen session "${sessionName}" exited with code 0`, + exitCode: 0, + output, + }); + }); + } + }; + + // Start checking after a brief delay + setTimeout(checkCompletion, checkInterval); + } catch (err) { + resolve({ + success: false, + sessionName, + message: `Failed to run in screen: ${err.message}`, + }); + } + }); +} + +/** Reset screen version cache (useful for testing) */ +function resetScreenVersionCache() { + cachedScreenVersion = null; + screenVersionChecked = false; +} + +module.exports = { + getScreenVersion, + supportsLogfileOption, + runScreenWithLogCapture, + resetScreenVersionCache, +}; diff --git a/js/test/isolation.test.js b/js/test/isolation.test.js index 604150a..665c98e 100644 --- a/js/test/isolation.test.js +++ b/js/test/isolation.test.js @@ -678,6 +678,39 @@ describe('Isolation Runner with Available Backends', () => { ); console.log(` Verified output capture: "${result.output.trim()}"`); }); + + it('should capture output from version-flag commands (issue #96)', async () => { + if (!isCommandAvailable('screen')) { + console.log(' Skipping: screen not installed'); + return; + } + + // This test verifies that screen isolation captures output from quick-completing + // commands like `agent --version` or `node --version`. + // Issue #96: output was silently lost because screen's internal log buffer was + // not flushed before the session terminated (default 10s flush interval). + // Fix: use a temporary screenrc with `logfile flush 0` to force immediate flushing. + const result = await runInScreen('node --version', { + session: `test-version-flag-${Date.now()}`, + detached: false, + }); + + assert.strictEqual(result.success, true, 'Command should succeed'); + assert.ok( + result.output !== undefined, + 'Attached mode should always return output property' + ); + assert.ok( + result.output.trim().length > 0, + 'Output should not be empty (issue #96: version output was silently lost)' + ); + // node --version outputs something like "v20.0.0" + assert.ok( + result.output.includes('v') || /\d+\.\d+/.test(result.output), + 'Output should contain version string' + ); + console.log(` Captured version output: "${result.output.trim()}"`); + }); }); describe('runInTmux (if available)', () => { diff --git a/rust/changelog.d/97.md b/rust/changelog.d/97.md new file mode 100644 index 0000000..2489b49 --- /dev/null +++ b/rust/changelog.d/97.md @@ -0,0 +1,19 @@ +fix: capture output from quick-completing commands in screen isolation (issue #96) + +When running a short-lived command like `agent --version` through screen isolation, +the output was silently lost because GNU Screen's internal log buffer flushes every +10 seconds by default. For commands that complete faster than this, the buffer may +not be flushed to the log file before the screen session terminates. + +**Fix:** A temporary screenrc file with `logfile flush 0` is passed to screen via +the `-c` option. This forces screen to flush the log buffer after every write, +eliminating the 10-second flush delay for quick-completing commands. + +A retry mechanism is also added for the tee fallback path (older screen < 4.5.1) +to handle the TOCTOU race where the log file appears empty when first read +immediately after session completion. + +The screen-related functions have also been extracted from `isolation.rs` into a +new `isolation_screen.rs` module to keep file sizes under the 1000-line limit. + +Fixes #96 diff --git a/rust/src/lib/isolation.rs b/rust/src/lib/isolation.rs index a7243e4..b5dfe0d 100644 --- a/rust/src/lib/isolation.rs +++ b/rust/src/lib/isolation.rs @@ -7,10 +7,7 @@ //! - ssh: Remote SSH execution use std::env; -use std::fs; use std::process::{Command, Stdio}; -use std::thread; -use std::time::Duration; use crate::args_parser::generate_session_name; @@ -272,48 +269,9 @@ pub fn detect_shell_in_environment(environment: &str, options: &IsolationOptions "sh".to_string() } -/// Get the installed screen version -pub fn get_screen_version() -> Option<(u32, u32, u32)> { - let output = Command::new("screen").arg("--version").output().ok()?; - - let output_str = String::from_utf8_lossy(&output.stdout); - let stderr_str = String::from_utf8_lossy(&output.stderr); - let combined = format!("{}{}", output_str, stderr_str); - - // Match patterns like "4.09.01", "4.00.03", "4.5.1" - let re = regex::Regex::new(r"(\d+)\.(\d+)\.(\d+)").ok()?; - let caps = re.captures(&combined)?; - - Some(( - caps.get(1)?.as_str().parse().ok()?, - caps.get(2)?.as_str().parse().ok()?, - caps.get(3)?.as_str().parse().ok()?, - )) -} - -/// Check if screen supports the -Logfile option (added in 4.5.1) -pub fn supports_logfile_option() -> bool { - match get_screen_version() { - Some((major, minor, patch)) => { - if major > 4 { - return true; - } - if major < 4 { - return false; - } - // major == 4 - if minor > 5 { - return true; - } - if minor < 5 { - return false; - } - // minor == 5 - patch >= 1 - } - None => false, - } -} +#[path = "isolation_screen.rs"] +pub mod isolation_screen; +pub use self::isolation_screen::{get_screen_version, supports_logfile_option}; /// Run command in GNU Screen pub fn run_in_screen(command: &str, options: &IsolationOptions) -> IsolationResult { @@ -374,117 +332,11 @@ pub fn run_in_screen(command: &str, options: &IsolationOptions) -> IsolationResu } } else { // Attached mode with log capture - run_screen_with_log_capture(command, &session_name, options.user.as_deref()) - } -} - -/// Run screen with log capture (for attached mode without TTY) -fn run_screen_with_log_capture( - command: &str, - session_name: &str, - user: Option<&str>, -) -> IsolationResult { - let (shell, shell_arg) = get_shell(); - let log_file = env::temp_dir().join(format!("screen-output-{}.log", session_name)); - let effective_command = wrap_command_with_user(command, user); - - let use_native_logging = supports_logfile_option(); - - let screen_args: Vec = if use_native_logging { - vec![ - "-dmS".to_string(), - session_name.to_string(), - "-L".to_string(), - "-Logfile".to_string(), - log_file.to_string_lossy().to_string(), - shell.clone(), - shell_arg.clone(), - effective_command.clone(), - ] - } else { - // Use tee fallback for older screen versions - let tee_command = format!( - "({}) 2>&1 | tee \"{}\"", - effective_command, - log_file.display() - ); - vec![ - "-dmS".to_string(), - session_name.to_string(), - shell.clone(), - shell_arg.clone(), - tee_command, - ] - }; - - if is_debug() { - eprintln!("[DEBUG] Running: screen {:?}", screen_args); - } - - let status = Command::new("screen").args(&screen_args).status(); - - if status.is_err() { - return IsolationResult { - success: false, - session_name: Some(session_name.to_string()), - message: "Failed to start screen session".to_string(), - ..Default::default() - }; - } - - // Poll for session completion - let max_wait = Duration::from_secs(300); - let check_interval = Duration::from_millis(100); - let mut waited = Duration::ZERO; - - loop { - // Check if session still exists - let sessions = Command::new("screen") - .arg("-ls") - .output() - .map(|o| String::from_utf8_lossy(&o.stdout).to_string()) - .unwrap_or_default(); - - if !sessions.contains(session_name) { - // Session ended, read output - let output = fs::read_to_string(&log_file).ok(); - - // Display output - if let Some(ref out) = output { - if !out.trim().is_empty() { - print!("{}", out); - } - } - - // Clean up log file - let _ = fs::remove_file(&log_file); - - return IsolationResult { - success: true, - session_name: Some(session_name.to_string()), - container_id: None, - message: format!("Screen session \"{}\" exited with code 0", session_name), - exit_code: Some(0), - output, - }; - } - - thread::sleep(check_interval); - waited += check_interval; - - if waited >= max_wait { - return IsolationResult { - success: false, - session_name: Some(session_name.to_string()), - message: format!( - "Screen session \"{}\" timed out after {} seconds", - session_name, - max_wait.as_secs() - ), - exit_code: Some(1), - ..Default::default() - }; - } + isolation_screen::run_screen_with_log_capture( + command, + &session_name, + options.user.as_deref(), + ) } } diff --git a/rust/src/lib/isolation_screen.rs b/rust/src/lib/isolation_screen.rs new file mode 100644 index 0000000..5e81f36 --- /dev/null +++ b/rust/src/lib/isolation_screen.rs @@ -0,0 +1,215 @@ +//! Screen-specific isolation helpers extracted from isolation.rs + +use std::env; +use std::fs; +use std::process::{Command, Stdio}; +use std::thread; +use std::time::Duration; + +use super::{get_shell, is_debug, wrap_command_with_user, IsolationResult}; + +/// Get the installed screen version +pub fn get_screen_version() -> Option<(u32, u32, u32)> { + let output = Command::new("screen").arg("--version").output().ok()?; + + let output_str = String::from_utf8_lossy(&output.stdout); + let stderr_str = String::from_utf8_lossy(&output.stderr); + let combined = format!("{}{}", output_str, stderr_str); + + // Match patterns like "4.09.01", "4.00.03", "4.5.1" + let re = regex::Regex::new(r"(\d+)\.(\d+)\.(\d+)").ok()?; + let caps = re.captures(&combined)?; + + Some(( + caps.get(1)?.as_str().parse().ok()?, + caps.get(2)?.as_str().parse().ok()?, + caps.get(3)?.as_str().parse().ok()?, + )) +} + +/// Check if screen supports the -Logfile option (added in 4.5.1) +pub fn supports_logfile_option() -> bool { + match get_screen_version() { + Some((major, minor, patch)) => { + if major > 4 { + return true; + } + if major < 4 { + return false; + } + // major == 4 + if minor > 5 { + return true; + } + if minor < 5 { + return false; + } + // minor == 5 + patch >= 1 + } + None => false, + } +} + +/// Run screen with log capture (for attached mode without TTY) +pub fn run_screen_with_log_capture( + command: &str, + session_name: &str, + user: Option<&str>, +) -> IsolationResult { + let (shell, shell_arg) = get_shell(); + let log_file = env::temp_dir().join(format!("screen-output-{}.log", session_name)); + let effective_command = wrap_command_with_user(command, user); + + let use_native_logging = supports_logfile_option(); + + // Temporary screenrc file for native logging path (issue #96) + // Setting logfile flush 0 forces screen to flush its log buffer after every write, + // preventing output loss for quick-completing commands like `agent --version`. + // Without this, screen buffers log writes and flushes every 10 seconds by default. + let screenrc_file = if use_native_logging { + let screenrc_path = env::temp_dir().join(format!("screenrc-{}", session_name)); + match fs::write(&screenrc_path, "logfile flush 0\n") { + Ok(()) => Some(screenrc_path), + Err(_) => None, // If we can't create the screenrc, proceed without it (best effort) + } + } else { + None + }; + + let screen_args: Vec = if use_native_logging { + // Use a temporary screenrc with `logfile flush 0` to force immediate log flushing + // (issue #96: quick commands like `agent --version` lose output without this) + let mut args = vec!["-dmS".to_string(), session_name.to_string()]; + if let Some(ref rc_path) = screenrc_file { + args.push("-c".to_string()); + args.push(rc_path.to_string_lossy().to_string()); + } + args.extend([ + "-L".to_string(), + "-Logfile".to_string(), + log_file.to_string_lossy().to_string(), + shell.clone(), + shell_arg.clone(), + effective_command.clone(), + ]); + args + } else { + // Use tee fallback for older screen versions + let tee_command = format!( + "({}) 2>&1 | tee \"{}\"", + effective_command, + log_file.display() + ); + vec![ + "-dmS".to_string(), + session_name.to_string(), + shell.clone(), + shell_arg.clone(), + tee_command, + ] + }; + + if is_debug() { + eprintln!("[DEBUG] Running: screen {:?}", screen_args); + } + + let status = Command::new("screen") + .args(&screen_args) + .stdout(Stdio::null()) + .stderr(Stdio::null()) + .status(); + + if status.is_err() { + // Clean up screenrc temp file on error + if let Some(ref rc_path) = screenrc_file { + let _ = fs::remove_file(rc_path); + } + return IsolationResult { + success: false, + session_name: Some(session_name.to_string()), + message: "Failed to start screen session".to_string(), + ..Default::default() + }; + } + + // Helper to read log file with retry for the tee fallback TOCTOU race condition + // (issue #96: session may appear done in `screen -ls` before tee finishes writing) + let read_log_with_retry = |retry_count: u32| -> Option { + let content = fs::read_to_string(&log_file).ok(); + if retry_count == 0 { + if let Some(ref s) = content { + if s.trim().is_empty() { + // Brief wait then retry once for tee path race condition + thread::sleep(Duration::from_millis(50)); + return fs::read_to_string(&log_file).ok(); + } + } + } + content + }; + + // Clean up temp files helper + let cleanup = || { + let _ = fs::remove_file(&log_file); + if let Some(ref rc_path) = screenrc_file { + let _ = fs::remove_file(rc_path); + } + }; + + // Poll for session completion + let max_wait = Duration::from_secs(300); + let check_interval = Duration::from_millis(100); + let mut waited = Duration::ZERO; + + loop { + // Check if session still exists + let sessions = Command::new("screen") + .arg("-ls") + .output() + .map(|o| String::from_utf8_lossy(&o.stdout).to_string()) + .unwrap_or_default(); + + if !sessions.contains(session_name) { + // Session ended, read output (with retry for tee path race condition) + let output = read_log_with_retry(0); + + // Display output + if let Some(ref out) = output { + if !out.trim().is_empty() { + print!("{}", out); + } + } + + // Clean up temp files + cleanup(); + + return IsolationResult { + success: true, + session_name: Some(session_name.to_string()), + container_id: None, + message: format!("Screen session \"{}\" exited with code 0", session_name), + exit_code: Some(0), + output, + }; + } + + thread::sleep(check_interval); + waited += check_interval; + + if waited >= max_wait { + cleanup(); + return IsolationResult { + success: false, + session_name: Some(session_name.to_string()), + message: format!( + "Screen session \"{}\" timed out after {} seconds", + session_name, + max_wait.as_secs() + ), + exit_code: Some(1), + ..Default::default() + }; + } + } +} diff --git a/rust/src/lib/isolation_tests.rs b/rust/src/lib/isolation_tests.rs index 4bde3ba..357a727 100644 --- a/rust/src/lib/isolation_tests.rs +++ b/rust/src/lib/isolation_tests.rs @@ -42,3 +42,45 @@ fn test_create_log_path() { let path = create_log_path("test"); assert!(path.to_string_lossy().contains("start-command-test-")); } + +#[test] +fn test_run_in_screen_captures_version_output() { + // Issue #96: quick-completing commands like `node --version` must have their + // output captured in screen isolation (was silently lost due to log flush timing). + if !is_command_available("screen") { + eprintln!("Skipping: screen not installed"); + return; + } + if !is_command_available("node") { + eprintln!("Skipping: node not installed"); + return; + } + + let result = run_in_screen( + "node --version", + &IsolationOptions { + session: Some(format!( + "test-version-flag-{}", + std::time::SystemTime::now() + .duration_since(std::time::UNIX_EPOCH) + .unwrap_or_default() + .as_millis() + )), + detached: false, + ..Default::default() + }, + ); + + assert!(result.success, "Command should succeed"); + let output = result.output.unwrap_or_default(); + assert!( + !output.trim().is_empty(), + "Output should not be empty (issue #96: version output was silently lost)" + ); + // node --version outputs something like "v20.0.0" + assert!( + output.contains('v') || output.chars().any(|c| c.is_ascii_digit()), + "Output should contain version string, got: {:?}", + output + ); +}