diff --git a/CHANGELOG.md b/CHANGELOG.md index 83e90de..93f3c3a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,16 @@ # Changelog +## Unreleased + +### Fixed + +- The Docker backend no longer reports an exit code 124 or 137 before the time limit as a + timeout. Such a result now keeps its real exit code, stdout and stderr, plus a note with + the elapsed time. A 137 before the limit usually means an outside SIGKILL, for example the + kernel out-of-memory killer, and a 124 can come from a nested `timeout` in the command. +- Error results from code execution tools now include the stdout of the command when it is + not empty, so the partial output of a timed-out command reaches the model. + ## v0.2.1 (2026-10-22) ### Changed diff --git a/src/stirrup/tools/code_backends/base.py b/src/stirrup/tools/code_backends/base.py index a829d72..422566d 100644 --- a/src/stirrup/tools/code_backends/base.py +++ b/src/stirrup/tools/code_backends/base.py @@ -393,6 +393,8 @@ def format_result(result: CommandResult) -> ToolResult[ToolUseCountMetadata]: f"\n{result.error_kind}" f"\n
{truncate_msg(result.stderr, MAX_LENGTH_SHELL_STDERR)}
" ) + if result.stdout: + content += f"\n{truncate_msg(result.stdout, MAX_LENGTH_SHELL_STDOUT)}" if result.advice: content += f"\n{result.advice}" content += "\n" diff --git a/src/stirrup/tools/code_backends/docker.py b/src/stirrup/tools/code_backends/docker.py index 1067dcb..2439926 100644 --- a/src/stirrup/tools/code_backends/docker.py +++ b/src/stirrup/tools/code_backends/docker.py @@ -2,11 +2,13 @@ import contextlib import hashlib +import math import os import shlex import shutil import tempfile from pathlib import Path, PurePosixPath +from time import perf_counter from typing import ClassVar, Self import anyio @@ -19,7 +21,7 @@ import docker from docker.client import DockerClient from docker.errors import APIError, BuildError, ImageNotFound, NotFound - from docker.models.containers import Container + from docker.models.containers import Container, ExecResult except ImportError as e: raise ImportError( "Requires installation of the docker extra. Install with (for example): `uv pip install stirrup[docker]` or `uv add stirrup[docker]`", @@ -619,8 +621,13 @@ async def _run_command_unchecked( # It runs the command in its own process group and sends SIGKILL to the # whole group after --kill-after, so descendants can't leak as orphans # parented to container PID 1 when the client gives up (moby/moby#9098). - # Exit 124 == SIGTERM expiry, 137 == --kill-after SIGKILL; both map to - # error_kind="timeout" for the caller. + # Exit 124 == SIGTERM expiry at the limit. timeout(1) also exits 137 when + # the child dies by SIGKILL after the TERM at the limit (it keeps the + # child's status, and --kill-after sends SIGKILL at limit + 5s). So the + # threshold below is the limit itself, not limit + kill-after. A 124 or + # 137 before the limit is not a timeout. A 124 can come from the command + # itself (e.g. its own nested `timeout`). A 137 usually means a SIGKILL + # from elsewhere, possibly the kernel out-of-memory killer. if argv is not None: exec_cmd = ["timeout", "--kill-after=5s", f"{timeout}s", *argv] else: @@ -630,19 +637,25 @@ async def _run_command_unchecked( try: # Outer fail_after is a safety net for a stalled docker socket; the # in-container timeout(1) should fire first in the normal case. - with fail_after(timeout + 10): - exec_result = await to_thread.run_sync( - lambda: container.exec_run( - cmd=exec_cmd, - workdir=self._working_dir, - demux=True, # Separate stdout/stderr - ) + # The clock runs in the worker thread around exec_run only, so the + # wait for a free thread is not counted. Docker API overhead is + # counted, which can only push a result towards "timeout". + def timed_exec_run() -> tuple[ExecResult, float]: + start_time = perf_counter() + result = container.exec_run( + cmd=exec_cmd, + workdir=self._working_dir, + demux=True, # Separate stdout/stderr ) + return result, perf_counter() - start_time + + with fail_after(timeout + 10): + exec_result, elapsed = await to_thread.run_sync(timed_exec_run) exit_code = exec_result.exit_code stdout_bytes, stderr_bytes = exec_result.output - if exit_code in (124, 137): + if exit_code in (124, 137) and elapsed >= timeout: logger.warning("Command timed out after %d seconds: %s", timeout, cmd[:100]) partial_stderr = (stderr_bytes or b"").decode("utf-8", errors="replace") timeout_msg = f"Command timed out after {timeout} seconds" @@ -656,6 +669,16 @@ async def _run_command_unchecked( stderr_text = (stderr_bytes or b"").decode("utf-8", errors="replace") + if exit_code in (124, 137): + # Round down, so the shown time stays below the limit (29.996 -> "29.99", not "30.00"). + shown = f"{math.floor(elapsed * 100) / 100:.2f}" + early_msg = f"Exit code {exit_code} after {shown} seconds, before the {timeout} second limit. " + ( + "The limit did not stop this command." + if exit_code == 124 + else "This usually means the process was killed with SIGKILL, possibly by the out-of-memory killer." + ) + stderr_text = f"{stderr_text}\n{early_msg}" if stderr_text else early_msg + # Heuristic: exit 127 + a "timeout: ... not found" message from the # shell means coreutils timeout(1) is absent from the base image, so # the wrapper command never ran. Surface a clear pointer instead of diff --git a/tests/test_docker_execution.py b/tests/test_docker_execution.py index b3daaf7..4f34e64 100644 --- a/tests/test_docker_execution.py +++ b/tests/test_docker_execution.py @@ -2,6 +2,7 @@ from __future__ import annotations +import itertools import shlex from pathlib import Path from unittest.mock import AsyncMock, MagicMock, patch @@ -13,7 +14,7 @@ from docker.errors import APIError, ImageNotFound -from stirrup.tools.code_backends.base import SHELL_TIMEOUT, CommandResult +from stirrup.tools.code_backends.base import SHELL_TIMEOUT, CommandResult, format_result from stirrup.tools.code_backends.docker import ( DEFAULT_WORKING_DIR, DockerCodeExecToolProvider, @@ -141,10 +142,11 @@ async def test_run_command_wraps_with_timeout(self, mock_docker_client: MagicMoc async def test_run_command_timeout_exit_codes_map_to_timeout( self, mock_docker_client: MagicMock, tmp_path: Path ) -> None: - """Exit 124 (SIGTERM expiry) and 137 (--kill-after SIGKILL) both surface as timeouts.""" + """Exit 124 or 137 at or past the limit surfaces as a timeout.""" provider = DockerCodeExecToolProvider.from_image("python:3.12-slim", temp_base_dir=tmp_path) - for exit_code in (124, 137): + # Elapsed equal to the 1 second limit is the boundary, and it is a timeout. + for exit_code, elapsed in ((124, 1.0), (124, 1.5), (137, 6.0), (137, 1.0)): mock_exec_result = MagicMock() mock_exec_result.exit_code = exit_code mock_exec_result.output = (b"partial-stdout", b"partial-stderr") @@ -153,18 +155,60 @@ async def test_run_command_timeout_exit_codes_map_to_timeout( with ( patch("stirrup.tools.code_backends.docker.docker.from_env", return_value=mock_docker_client), patch("stirrup.tools.code_backends.docker.to_thread") as mock_to_thread, + patch( + "stirrup.tools.code_backends.docker.perf_counter", + side_effect=itertools.chain([0.0, elapsed], itertools.repeat(elapsed)), + ), ): mock_to_thread.run_sync = AsyncMock(side_effect=lambda fn, *args: fn(*args) if not args else fn) async with provider as _: result = await provider.run_command("sleep 999", timeout=1) - assert result.error_kind == "timeout", f"exit {exit_code} should map to timeout" + case = f"exit {exit_code} after {elapsed}s" + assert result.error_kind == "timeout", f"{case} should map to timeout" assert result.exit_code == exit_code assert "partial-stdout" in result.stdout assert "partial-stderr" in result.stderr assert "timed out" in result.stderr.lower() + async def test_run_command_early_exit_124_or_137_is_not_timeout( + self, mock_docker_client: MagicMock, tmp_path: Path + ) -> None: + """Exit 124 or 137 before the limit is not a timeout (e.g. a nested `timeout`, or the OOM killer).""" + provider = DockerCodeExecToolProvider.from_image("python:3.12-slim", temp_base_dir=tmp_path) + + for exit_code, explanation in ( + (124, "the limit did not stop this command."), + (137, "this usually means the process was killed with sigkill"), + ): + mock_exec_result = MagicMock() + mock_exec_result.exit_code = exit_code + mock_exec_result.output = (b"partial-stdout", b"partial-stderr") + mock_docker_client.containers.run.return_value.exec_run = MagicMock(return_value=mock_exec_result) + + with ( + patch("stirrup.tools.code_backends.docker.docker.from_env", return_value=mock_docker_client), + patch("stirrup.tools.code_backends.docker.to_thread") as mock_to_thread, + patch( + "stirrup.tools.code_backends.docker.perf_counter", + side_effect=itertools.chain([0.0, 2.0], itertools.repeat(2.0)), + ), + ): + mock_to_thread.run_sync = AsyncMock(side_effect=lambda fn, *args: fn(*args) if not args else fn) + + async with provider as _: + result = await provider.run_command("timeout 2 sleep 60", timeout=30) + + stderr = result.stderr.lower() + assert result.error_kind is None, f"exit {exit_code} before the limit is not a timeout" + assert result.exit_code == exit_code + assert "partial-stdout" in result.stdout + assert "partial-stderr" in stderr + assert f"exit code {exit_code} after 2.00 seconds, before the 30 second limit" in stderr + assert explanation in stderr + assert "timed out" not in stderr + async def test_run_command_missing_timeout_binary_advice( self, mock_docker_client: MagicMock, tmp_path: Path ) -> None: @@ -443,3 +487,22 @@ def test_image_prep_lock_is_shared_per_image_name(self) -> None: assert lock_a1 is lock_a2 assert lock_a1 is not lock_b + + +def test_format_result_error_branch_stdout() -> None: + """Error results show non-empty stdout. With empty stdout the text is unchanged.""" + with_stdout = format_result( + CommandResult(exit_code=124, stdout="partial", stderr="Command timed out after 3 seconds", error_kind="timeout") + ) + assert "\npartial" in with_stdout.content + assert "" not in with_stdout.content + + without_stdout = format_result( + CommandResult(exit_code=124, stdout="", stderr="Command timed out after 3 seconds", error_kind="timeout") + ) + assert without_stdout.content == ( + "" + "\ntimeout" + "\n
Command timed out after 3 seconds
" + "\n" + )