diff --git a/docs/reference/environment-variables.md b/docs/reference/environment-variables.md index b45309687..2d6c84095 100644 --- a/docs/reference/environment-variables.md +++ b/docs/reference/environment-variables.md @@ -249,6 +249,17 @@ See [Tool Execution Safety](../data-sources/tool-execution-safety.md) for the fu export TOOL_MEMORY_LIMIT_MB=2000 ``` +### TOOL_SUBPROCESS_TIMEOUT_SECONDS +**Default:** `300` + +Wall-clock timeout (in seconds) for every `command:`/`script:` toolset tool Holmes runs as a subprocess (e.g. `kubectl`, `jq`). If the command has not finished by the deadline, Holmes kills the entire process group it spawned — not just the immediate shell — so a stalled grandchild process (for example a `kubectl` call stuck on a hung apiserver connection) cannot be left running forever. On timeout, the tool returns exit code `124` (matching GNU `timeout`) with any output produced so far plus a note that the command was killed. + +**Example:** +```bash +# Allow long-running tool commands up to 10 minutes before Holmes kills them +export TOOL_SUBPROCESS_TIMEOUT_SECONDS=600 +``` + ## HolmesGPT Configuration ### MODEL_LIST_FILE_LOCATION diff --git a/holmes/common/env_vars.py b/holmes/common/env_vars.py index 7f6c4a4bc..33212faa4 100644 --- a/holmes/common/env_vars.py +++ b/holmes/common/env_vars.py @@ -98,6 +98,15 @@ def _load_temperature() -> Optional[float]: os.environ.get("TOOL_MEMORY_LIMIT_MB", _default_memory_limit) ) +# Wall-clock timeout (seconds) for `command:`/`script:` toolset tools run via +# subprocess (e.g. kubectl, jq). Without this, a stalled child process (e.g. an +# apiserver connection that accepts the TCP handshake but never responds) blocks +# the calling thread and leaks a process forever. On timeout the entire process +# group spawned for the command is killed, not just the immediate shell child. +TOOL_SUBPROCESS_TIMEOUT_SECONDS = int( + os.environ.get("TOOL_SUBPROCESS_TIMEOUT_SECONDS", 300) +) + STREAM_CHUNKS_PER_PARSE = int( os.environ.get("STREAM_CHUNKS_PER_PARSE", 80) ) # Empirical value with 6~ parsing calls. Consider using larger value if LLM response is long as to reduce markdown to section calls. diff --git a/holmes/core/tools.py b/holmes/core/tools.py index d0f3d0c2d..efc2cd509 100644 --- a/holmes/core/tools.py +++ b/holmes/core/tools.py @@ -4,6 +4,7 @@ import os import re import shlex +import signal import subprocess import tempfile import threading @@ -40,6 +41,7 @@ from rich.console import Console from rich.table import Table +from holmes.common.env_vars import TOOL_SUBPROCESS_TIMEOUT_SECONDS from holmes.core.llm import LLM from holmes.core.openai_formatting import format_tool_to_open_ai_standard from holmes.core.transformers import ( @@ -658,20 +660,42 @@ def __execute_subprocess(self, cmd: str) -> Tuple[str, int]: logger.debug(f"Running `{cmd}`") protected_cmd = get_ulimit_prefix() + cmd - result = subprocess.run( + # start_new_session=True puts the shell (and everything it spawns, + # e.g. `kubectl`) in its own process group so a timeout can kill the + # whole tree with os.killpg() instead of leaving orphaned + # grandchildren running forever if the shell's direct child exits + # but a subprocess it started does not. + process = subprocess.Popen( protected_cmd, shell=True, executable="/bin/bash", text=True, - check=False, # do not throw error, we just return the error code stdin=subprocess.DEVNULL, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, + start_new_session=True, ) + try: + stdout, _ = process.communicate(timeout=TOOL_SUBPROCESS_TIMEOUT_SECONDS) + return_code = process.returncode + except subprocess.TimeoutExpired: + logger.warning( + f"Command `{cmd}` did not complete within " + f"{TOOL_SUBPROCESS_TIMEOUT_SECONDS}s, killing it" + ) + stdout = self.__kill_process_group_and_collect_output(process) + # 124 is the conventional timeout exit code (matches GNU `timeout`) + return_code = 124 + timeout_notice = ( + f"Command timed out after {TOOL_SUBPROCESS_TIMEOUT_SECONDS} " + "seconds and was killed." + ) + output = f"{stdout}\n{timeout_notice}" if stdout else timeout_notice + return output, return_code - output = result.stdout.strip() - output = check_oom_and_append_hint(output, result.returncode) - return output, result.returncode + output = (stdout or "").strip() + output = check_oom_and_append_hint(output, return_code) + return output, return_code except Exception as e: logger.error( f"An unexpected error occurred while running '{cmd}': {e}", @@ -680,6 +704,25 @@ def __execute_subprocess(self, cmd: str) -> Tuple[str, int]: output = f"Command execution failed with error: {e}" return output, 1 + @staticmethod + def __kill_process_group_and_collect_output( + process: "subprocess.Popen[str]", + ) -> str: + """Kill a timed-out process's entire process group and return whatever + output it had produced. Best-effort: the process group may already be + gone (race with natural exit), which is not an error.""" + try: + os.killpg(os.getpgid(process.pid), signal.SIGKILL) + except ProcessLookupError: + pass # process (group) already exited on its own + + try: + stdout, _ = process.communicate(timeout=5) + except subprocess.TimeoutExpired: + # Extremely unlikely after SIGKILL, but never block forever here. + stdout = "" + return (stdout or "").strip() + class StaticPrerequisite(BaseModel): enabled: bool diff --git a/tests/core/test_tool_subprocess_timeout.py b/tests/core/test_tool_subprocess_timeout.py new file mode 100644 index 000000000..68c6629ce --- /dev/null +++ b/tests/core/test_tool_subprocess_timeout.py @@ -0,0 +1,136 @@ +""" +Tests for the subprocess timeout added to Tool.__execute_subprocess(). + +Regression coverage for: a script/command tool (e.g. kubernetes/core's +kubectl-based tools) whose underlying subprocess stalls forever (for example +an apiserver connection that accepts the TCP handshake but never responds) +used to block the calling thread indefinitely and leak the child process. +`__execute_subprocess()` now bounds every run with `TOOL_SUBPROCESS_TIMEOUT_SECONDS` +and kills the whole process group on timeout, not just the immediate shell +child, so any grandchild process (e.g. `kubectl`) spawned by the command is +also reaped. +""" + +import os +import time +from unittest.mock import patch + +import pytest + +from holmes.common.env_vars import TOOL_SUBPROCESS_TIMEOUT_SECONDS +from holmes.core.tools import StructuredToolResultStatus, YAMLTool +from tests.conftest import create_mock_tool_invoke_context + + +def _make_tool(command: str) -> YAMLTool: + return YAMLTool(name="test-tool", description="test tool", command=command) + + +class TestSubprocessTimeoutConfig: + def test_default_timeout_is_positive(self): + assert TOOL_SUBPROCESS_TIMEOUT_SECONDS > 0 + + +class TestExecuteSubprocessTimeout: + def test_fast_command_completes_normally(self): + tool = _make_tool("echo hello") + context = create_mock_tool_invoke_context() + + result = tool._invoke(params={}, context=context) + + assert result.return_code == 0 + assert result.status == StructuredToolResultStatus.SUCCESS + assert "hello" in result.data + + def test_slow_command_is_killed_after_timeout(self, monkeypatch): + monkeypatch.setattr("holmes.core.tools.TOOL_SUBPROCESS_TIMEOUT_SECONDS", 0.5) + tool = _make_tool("sleep 30") + context = create_mock_tool_invoke_context() + + start = time.time() + result = tool._invoke(params={}, context=context) + elapsed = time.time() - start + + # Must not have blocked anywhere near the full 30s sleep. + assert elapsed < 10 + assert result.return_code == 124 + assert result.status == StructuredToolResultStatus.ERROR + assert "timed out" in result.data.lower() + + def test_partial_output_before_timeout_is_preserved(self, monkeypatch): + monkeypatch.setattr("holmes.core.tools.TOOL_SUBPROCESS_TIMEOUT_SECONDS", 0.5) + tool = _make_tool("echo partial-output; sleep 30") + context = create_mock_tool_invoke_context() + + result = tool._invoke(params={}, context=context) + + assert result.return_code == 124 + assert "partial-output" in result.data + assert "timed out" in result.data.lower() + + def test_grandchild_process_is_also_killed(self, tmp_path, monkeypatch): + """Regression test for the reported bug: killing only the direct shell + child (as plain subprocess.run(timeout=...) + .kill() would do) leaves + a backgrounded grandchild (e.g. a stalled kubectl call) running + forever. The whole process group must be killed.""" + monkeypatch.setattr("holmes.core.tools.TOOL_SUBPROCESS_TIMEOUT_SECONDS", 0.5) + pid_file = tmp_path / "grandchild.pid" + command = f"sleep 30 & echo $! > {pid_file}; wait" + tool = _make_tool(command) + context = create_mock_tool_invoke_context() + + result = tool._invoke(params={}, context=context) + assert result.return_code == 124 + + # Give the kernel a brief moment to finish delivering SIGKILL. + deadline = time.time() + 2 + grandchild_pid = int(pid_file.read_text().strip()) + alive = True + while time.time() < deadline: + try: + os.kill(grandchild_pid, 0) + alive = True + except ProcessLookupError: + alive = False + break + time.sleep(0.1) + assert ( + not alive + ), f"grandchild process {grandchild_pid} survived the timeout kill" + + def test_kill_race_condition_does_not_raise(self, monkeypatch): + """If the process happens to exit on its own right before we signal + it, os.killpg raises ProcessLookupError — this must be swallowed, not + propagated as an unhandled exception.""" + monkeypatch.setattr("holmes.core.tools.TOOL_SUBPROCESS_TIMEOUT_SECONDS", 0.3) + tool = _make_tool("sleep 30") + context = create_mock_tool_invoke_context() + + # Perform the real kill so the spawned `sleep 30` process group is + # actually reaped (avoiding an orphaned process), then raise + # ProcessLookupError to simulate the race where the process had + # already exited by the time killpg was called. + real_killpg = os.killpg + + def killpg_then_raise(pgid, sig): + try: + real_killpg(pgid, sig) + except ProcessLookupError: + pass + raise ProcessLookupError() + + with patch("os.killpg", side_effect=killpg_then_raise): + result = tool._invoke(params={}, context=context) + + assert result.return_code == 124 + assert "timed out" in result.data.lower() + + @pytest.mark.parametrize("command", ["sleep 30"]) + def test_timeout_does_not_raise_unexpected_exception(self, monkeypatch, command): + monkeypatch.setattr("holmes.core.tools.TOOL_SUBPROCESS_TIMEOUT_SECONDS", 0.3) + tool = _make_tool(command) + context = create_mock_tool_invoke_context() + + # Should never raise — the caller always gets back a StructuredToolResult. + result = tool._invoke(params={}, context=context) + assert result.return_code == 124