From 7d93eb8e9d54d356f9aaf218ec2ebe814fd1782f Mon Sep 17 00:00:00 2001 From: "zhansheng.lzs" Date: Thu, 17 Sep 2026 17:34:57 +0800 Subject: [PATCH 1/2] sync(acli): give run_command a real timeout and kill the whole tree The 30s default killed ordinary test and build commands, and nothing told the model the limit existed -- so it burned turns rediscovering it by experiment (`sleep 25` fits, `sleep 150` does not). Raise the default to 600s, allow ACLI_COMMAND_TIMEOUT to move it, advertise the `timeout` argument in the tool description, and name it in the timeout message. On expiry only the direct child died. proc.kill() reaches the shell, not the pipeline it started, so the work kept running with its stdout pipe open and asyncio later logged "Exception ignored in BaseSubprocessTransport.__del__ ... Event loop is closed". Start every child in its own process group (start_new_session / CREATE_NEW_PROCESS_GROUP), kill the group, then reap it. Ctrl-C takes the same path. /info printed config.timeout as "Timeout", but that field is the LLM request timeout (providers/profile.py), so the one place a user could look reported a limit nothing enforced. Split it into two labelled lines. --- dashscope/acli/cli/dispatch.py | 10 +- dashscope/acli/config.py | 2 + dashscope/acli/tools/shell.py | 178 +++++++++++++++++++++++++-------- 3 files changed, 145 insertions(+), 45 deletions(-) diff --git a/dashscope/acli/cli/dispatch.py b/dashscope/acli/cli/dispatch.py index d38c525..9a1d8dc 100644 --- a/dashscope/acli/cli/dispatch.py +++ b/dashscope/acli/cli/dispatch.py @@ -200,7 +200,15 @@ def _handle_slash_command( ) console.print(f" Loop mode: [cyan]{config.loop_mode}[/cyan]") console.print(f" Max turns: [cyan]{config.max_turns}[/cyan]") - console.print(f" Timeout: [cyan]{config.timeout}s[/cyan]") + # config.timeout is the LLM request timeout; run_command enforces its + # own, so showing one "Timeout" line reported a limit nothing used. + from dashscope.acli.tools.shell import default_timeout + + console.print(f" LLM timeout: [cyan]{config.timeout}s[/cyan]") + console.print( + f" Cmd timeout: [cyan]{default_timeout()}s " + f"(ACLI_COMMAND_TIMEOUT)[/cyan]", + ) console.print( f" TUI: {'[green]on' if config.tui else '[dim]off'}[/]", ) diff --git a/dashscope/acli/config.py b/dashscope/acli/config.py index 6309778..c390a86 100644 --- a/dashscope/acli/config.py +++ b/dashscope/acli/config.py @@ -253,6 +253,8 @@ class Config: # "dangerous" - only DANGEROUS prompts; CONFIRM auto-passes confirm_mode: str = "dangerous" max_turns: int = 50 + # LLM request timeout (providers/profile.py). run_command has its own, + # separate limit: see acli.tools.shell.default_timeout(). timeout: int = 30 mcp_servers: list[MCPServerConfig] = field(default_factory=list) memory_enabled: bool = True diff --git a/dashscope/acli/tools/shell.py b/dashscope/acli/tools/shell.py index d273c7b..58897fd 100644 --- a/dashscope/acli/tools/shell.py +++ b/dashscope/acli/tools/shell.py @@ -8,14 +8,38 @@ import re import shlex import shutil +import signal +import subprocess import sys from dashscope.acli.tools.registry import PermissionLevel, tool MAX_OUTPUT_LENGTH = 10000 MAX_OUTPUT_BYTES = 5 * 1024 * 1024 # 5 MB hard limit before truncation -DEFAULT_TIMEOUT = 30 +# Sized for real work: a project's test or build command. The previous 30s +# silently killed both, and since the model could not see the limit it spent +# turns guessing at it (e.g. discovering `sleep 25` works and `sleep 150` +# does not). Callers override per call with the ``timeout`` argument. +DEFAULT_TIMEOUT = 600 +TIMEOUT_ENV = "ACLI_COMMAND_TIMEOUT" IS_WINDOWS = os.name == "nt" +# Windows has no setsid/killpg; a new process group is the closest thing, and +# what lets ``taskkill /T`` reach grandchildren. The flag does not exist on +# POSIX, hence getattr. +_NEW_GROUP_FLAGS = getattr(subprocess, "CREATE_NEW_PROCESS_GROUP", 0) + + +def default_timeout() -> int: + """Seconds a run_command call gets before it is killed. + + Resolved per call rather than at import, so exporting + ``ACLI_COMMAND_TIMEOUT`` takes effect without a restart. + """ + try: + value = int(os.environ.get(TIMEOUT_ENV, "") or DEFAULT_TIMEOUT) + except ValueError: + return DEFAULT_TIMEOUT + return value if value > 0 else DEFAULT_TIMEOUT def _resolve_output_encoding() -> str: @@ -519,11 +543,101 @@ def _is_safe_single(chunk: str) -> bool: return False +def _signal_tree(proc: asyncio.subprocess.Process | None) -> None: + """Kill the process group. Synchronous: no awaits, so it is safe to call + from a ``CancelledError`` handler where awaiting is unreliable. + """ + if proc is None or proc.returncode is not None: + return + if IS_WINDOWS: + try: + subprocess.run( + ["taskkill", "/F", "/T", "/PID", str(proc.pid)], + stdout=subprocess.DEVNULL, + stderr=subprocess.DEVNULL, + check=False, + timeout=10, + ) + except Exception: # pylint: disable=broad-except + pass + return + try: + # proc.pid is the group id: the child was started with + # start_new_session, which is what makes this reach grandchildren. + os.killpg(proc.pid, signal.SIGKILL) + except OSError: + try: + proc.kill() + except Exception: # pylint: disable=broad-except + pass + + +async def _kill_tree(proc: asyncio.subprocess.Process | None) -> None: + """Kill the tree, then reap it. + + Without the reap the transport stays open until GC, which asyncio reports + as "Exception ignored in BaseSubprocessTransport.__del__ ... Event loop is + closed" when the process exits first. + """ + if proc is None: + # The spawn itself failed, so there is nothing to clean up. + return + _signal_tree(proc) + try: + await proc.wait() + except Exception: # pylint: disable=broad-except + pass + + +async def _spawn(command: str) -> asyncio.subprocess.Process: + """Start the command in its own process group. + + The group is what lets ``_signal_tree`` reach grandchildren. Without it a + timeout killed only the shell, so ``cmd | slow`` kept running after the + caller was told the command had timed out. + """ + if IS_WINDOWS: + # argv form, never a shell string: interpolating into + # 'powershell -Command "..."' routes it through cmd.exe first and + # any embedded double quote corrupts the command. + return await asyncio.create_subprocess_exec( + *WIN_SHELL, + command, + stdout=asyncio.subprocess.PIPE, + stderr=asyncio.subprocess.PIPE, + cwd=os.getcwd(), + creationflags=_NEW_GROUP_FLAGS, + ) + # Optional OS sandbox (opt-in; degrades to normal execution + # when disabled or when no backend is available). + from dashscope.acli import sandbox + + sandbox_argv = None + if sandbox.is_enabled(): + sandbox_argv = sandbox.build_argv(command, os.getcwd()) + if sandbox_argv is not None: + return await asyncio.create_subprocess_exec( + *sandbox_argv, + stdout=asyncio.subprocess.PIPE, + stderr=asyncio.subprocess.PIPE, + cwd=os.getcwd(), + start_new_session=True, + ) + return await asyncio.create_subprocess_shell( + command, + stdout=asyncio.subprocess.PIPE, + stderr=asyncio.subprocess.PIPE, + cwd=os.getcwd(), + start_new_session=True, + ) + + @tool( name="run_command", description=( "Execute a shell command and return its output. " - "Dangerous commands are blocked." + "Dangerous commands are blocked. Pass timeout (seconds) to override " + f"the {DEFAULT_TIMEOUT}s default for long builds or test runs." ), permission=PermissionLevel.CONFIRM, ) @@ -555,57 +669,33 @@ async def run_command(command: str, timeout: int | None = None) -> str: # fall back to the default instead of letting asyncio.wait_for raise # TypeError on `<= 0`. try: - timeout = ( - int(timeout) if timeout not in (None, "", 0) else DEFAULT_TIMEOUT - ) + timeout = int(timeout) if timeout not in (None, "", 0) else 0 except (TypeError, ValueError): - timeout = DEFAULT_TIMEOUT + timeout = 0 + if timeout <= 0: + timeout = default_timeout() + proc = None try: - if IS_WINDOWS: - # argv form, never a shell string: interpolating into - # 'powershell -Command "..."' routes it through cmd.exe first and - # any embedded double quote corrupts the command. - proc = await asyncio.create_subprocess_exec( - *WIN_SHELL, - command, - stdout=asyncio.subprocess.PIPE, - stderr=asyncio.subprocess.PIPE, - cwd=os.getcwd(), - ) - else: - # Optional OS sandbox (opt-in; degrades to normal execution - # when disabled or when no backend is available). - from dashscope.acli import sandbox - - sandbox_argv = None - if sandbox.is_enabled(): - sandbox_argv = sandbox.build_argv(command, os.getcwd()) - if sandbox_argv is not None: - proc = await asyncio.create_subprocess_exec( - *sandbox_argv, - stdout=asyncio.subprocess.PIPE, - stderr=asyncio.subprocess.PIPE, - cwd=os.getcwd(), - ) - else: - proc = await asyncio.create_subprocess_shell( - command, - stdout=asyncio.subprocess.PIPE, - stderr=asyncio.subprocess.PIPE, - cwd=os.getcwd(), - ) + proc = await _spawn(command) stdout, stderr = await asyncio.wait_for( proc.communicate(), timeout=timeout, ) except asyncio.TimeoutError: - try: - proc.kill() - except Exception: - pass - return f"Error: command timed out ({timeout}s)" + await _kill_tree(proc) + return ( + f"Error: command timed out after {timeout}s and was killed. " + "Pass a larger timeout argument (seconds) if it needs longer; " + f"the default is {default_timeout()}s." + ) + except asyncio.CancelledError: + # Ctrl-C: kill synchronously, because awaiting inside a cancellation + # handler can be interrupted before the kill lands. + _signal_tree(proc) + raise except Exception as e: + await _kill_tree(proc) return f"Error: execution failed - {e}" # Enforce hard size limits to prevent OOM on huge outputs From 1a11c262f3b129f21fdeef4735a7e411631f0e8b Mon Sep 17 00:00:00 2001 From: "zhansheng.lzs" Date: Thu, 17 Sep 2026 17:35:19 +0800 Subject: [PATCH 2/2] test(acli): pin the command timeout and the process-group kill in the vendored tree Orphan coverage is marker-based rather than pid-based: a SIGKILLed child nobody reaps is a zombie, and os.kill(pid, 0) still succeeds on a zombie, so the pid alone says nothing about whether the tree died. Each fix was falsified by reverting it and confirming exactly the intended tests fail. Two results worth recording: reverting 600 -> 30 fails only test_default_covers_a_real_test_run, because the other timeout assertions are self-referential to DEFAULT_TIMEOUT; and dropping the `proc is None` guard in _kill_tree fails nothing, since the AttributeError from None.wait() is swallowed by the broad except. The guard stays so the intent does not depend on an exception being swallowed, but it is not claimed as covered. --- tests/unit/test_acli_command_timeout.py | 270 ++++++++++++++++++++++++ 1 file changed, 270 insertions(+) create mode 100644 tests/unit/test_acli_command_timeout.py diff --git a/tests/unit/test_acli_command_timeout.py b/tests/unit/test_acli_command_timeout.py new file mode 100644 index 0000000..ea21768 --- /dev/null +++ b/tests/unit/test_acli_command_timeout.py @@ -0,0 +1,270 @@ +# -*- coding: utf-8 -*- +"""run_command's timeout in the vendored tree: the limit and what it kills. + +Two defects, both observed while acli was resolving a GitHub PR conflict: + +* The default was 30s -- shorter than a project's test or build command, and + invisible to the model. `sleep 150 && gh pr checks 162` came back "command + timed out (30s)" and acli spent further turns rediscovering by experiment + that `sleep 25` fits. `/info` made it worse by printing an unrelated + ``config.timeout`` under the bare label "Timeout". +* On timeout only the direct child was killed. ``proc.kill()`` reaches the + shell, not the pipeline it started, so the work kept running with its + stdout pipe still open -- and asyncio later logged "Exception ignored in + BaseSubprocessTransport.__del__ ... Event loop is closed". + +The orphan tests are marker-based, not pid-based: a SIGKILLed child nobody +reaps is a zombie, and ``os.kill(pid, 0)`` still succeeds on a zombie, so the +pid alone says nothing about whether the tree died. +""" + +# pylint: disable=protected-access,redefined-outer-name + +from __future__ import annotations + +import asyncio +from unittest.mock import AsyncMock, MagicMock, patch + +import pytest + +from dashscope.acli.tools import shell + + +def _fake_proc(stdout: bytes = b"", stderr: bytes = b"") -> MagicMock: + proc = MagicMock() + proc.communicate = AsyncMock(return_value=(stdout, stderr)) + proc.returncode = 0 + return proc + + +@pytest.fixture +def marker(tmp_path): + """Path a surviving grandchild would create.""" + path = tmp_path / "orphan-marker" + yield path + if path.exists(): + path.unlink() + + +def _orphan_command(marker) -> str: + """Backgrounds a writer that only fires if the kill misses the group. + + Non-interactive sh leaves background jobs in its own process group, so a + group kill takes the writer with it and a child-only kill does not. + """ + return f"(sleep 2; touch '{marker}') & sleep 30" + + +@pytest.fixture +def spy_wait_for(monkeypatch): + """Record the timeout run_command hands to asyncio.wait_for.""" + seen: dict = {} + real = asyncio.wait_for + + async def spy(awaitable, timeout=None): + seen["timeout"] = timeout + return await real(awaitable, timeout=timeout) + + monkeypatch.setattr(asyncio, "wait_for", spy) + return seen + + +class TestDefaultTimeout: + def test_default_covers_a_real_test_run(self, monkeypatch): + """The regression: 30s killed ordinary test and build commands.""" + monkeypatch.delenv(shell.TIMEOUT_ENV, raising=False) + assert shell.default_timeout() >= 300 + + def test_env_override_wins(self, monkeypatch): + monkeypatch.setenv(shell.TIMEOUT_ENV, "45") + assert shell.default_timeout() == 45 + + @pytest.mark.parametrize("raw", ["", "bogus", "0", "-5"]) + def test_unusable_override_falls_back(self, monkeypatch, raw): + """A bad override must not become a zero or negative deadline.""" + monkeypatch.setenv(shell.TIMEOUT_ENV, raw) + assert shell.default_timeout() == shell.DEFAULT_TIMEOUT + + async def test_argument_overrides_default(self, spy_wait_for): + await shell.run_command("true", timeout=7) + assert spy_wait_for["timeout"] == 7 + + @pytest.mark.parametrize("value", [None, "", 0, "auto"]) + async def test_absent_argument_uses_default( + self, + monkeypatch, + spy_wait_for, + value, + ): + monkeypatch.delenv(shell.TIMEOUT_ENV, raising=False) + await shell.run_command("true", timeout=value) + assert spy_wait_for["timeout"] == shell.DEFAULT_TIMEOUT + + +class TestTimeoutIsDiscoverable: + def test_tool_description_advertises_the_argument(self): + """The model cannot pass a knob it has never been told exists.""" + description = shell.run_command._tool_definition.description + assert "timeout" in description + + async def test_timeout_message_names_the_escape_hatch(self, monkeypatch): + """A bare "timed out (30s)" left the model guessing magic numbers.""" + monkeypatch.delenv(shell.TIMEOUT_ENV, raising=False) + out = await shell.run_command("sleep 30", timeout=1) + assert "timed out" in out + assert "timeout argument" in out + assert f"{shell.DEFAULT_TIMEOUT}s" in out + + +class TestChildGetsItsOwnProcessGroup: + async def test_posix_shell_branch_starts_a_new_session(self, monkeypatch): + monkeypatch.setattr(shell, "IS_WINDOWS", False) + with patch( + "asyncio.create_subprocess_shell", + new=AsyncMock(return_value=_fake_proc()), + ) as spawn: + await shell.run_command("true") + assert spawn.await_args.kwargs["start_new_session"] is True + + async def test_sandbox_branch_starts_a_new_session(self, monkeypatch): + monkeypatch.setattr(shell, "IS_WINDOWS", False) + with ( + patch("dashscope.acli.sandbox.is_enabled", return_value=True), + patch( + "dashscope.acli.sandbox.build_argv", + return_value=["/usr/bin/sandbox-exec", "-f", "p", "true"], + ), + patch( + "asyncio.create_subprocess_exec", + new=AsyncMock(return_value=_fake_proc()), + ) as spawn, + ): + await shell.run_command("true") + assert spawn.await_args.kwargs["start_new_session"] is True + + async def test_windows_branch_creates_a_new_group(self, monkeypatch): + """Without the flag, taskkill /T has no tree to walk.""" + monkeypatch.setattr(shell, "IS_WINDOWS", True) + monkeypatch.setattr(shell, "_NEW_GROUP_FLAGS", 0x200) + with patch( + "asyncio.create_subprocess_exec", + new=AsyncMock(return_value=_fake_proc()), + ) as spawn: + await shell.run_command("true") + assert spawn.await_args.kwargs["creationflags"] == 0x200 + + +class TestTimeoutKillsTheWholeTree: + async def test_no_orphan_survives_a_timeout(self, marker): + out = await shell.run_command(_orphan_command(marker), timeout=1) + assert "timed out" in out + # past t=2s, when the backgrounded writer would fire if it survived + await asyncio.sleep(2.5) + assert not marker.exists() + + async def test_cancellation_also_kills_the_tree(self, marker): + """Ctrl-C must not leave the command running either.""" + task = asyncio.create_task(shell.run_command(_orphan_command(marker))) + await asyncio.sleep(0.5) + task.cancel() + with pytest.raises(asyncio.CancelledError): + await task + await asyncio.sleep(2.5) + assert not marker.exists() + + +class TestKillIsBestEffort: + def test_gone_process_group_falls_back_to_child_kill(self): + proc = MagicMock() + proc.returncode = None + proc.pid = 4242 + with patch("os.killpg", side_effect=ProcessLookupError): + shell._signal_tree(proc) + proc.kill.assert_called_once_with() + + def test_already_exited_process_is_left_alone(self): + proc = MagicMock() + proc.returncode = 0 + with patch("os.killpg") as killpg: + shell._signal_tree(proc) + killpg.assert_not_called() + proc.kill.assert_not_called() + + def test_windows_kill_uses_taskkill_with_the_tree_flag(self, monkeypatch): + monkeypatch.setattr(shell, "IS_WINDOWS", True) + proc = MagicMock() + proc.returncode = None + proc.pid = 4242 + with patch("subprocess.run") as run: + shell._signal_tree(proc) + argv = run.call_args.args[0] + assert argv[0] == "taskkill" + assert "/F" in argv and "/T" in argv + assert argv[-1] == "4242" + + async def test_spawn_failure_still_returns_an_error(self): + """proc stays None, so the cleanup path must tolerate having nothing.""" + with patch( + "asyncio.create_subprocess_shell", + new=AsyncMock(side_effect=OSError("no such shell")), + ): + out = await shell.run_command("true") + assert "execution failed" in out + + +class TestInfoReportsTheEnforcedTimeout: + """/info used to print config.timeout as "Timeout". + + That field is the LLM request timeout consumed by providers/profile.py. + run_command enforced a different number entirely, so the one place a user + could look reported a limit nothing used. + """ + + @staticmethod + def _config(**overrides): + from types import SimpleNamespace + + defaults = { + "provider": "tongyi", + "model": "qwen3.7-max", + "protocol": "openai", + "base_url": "", + "user_name": "tester", + "memory_enabled": True, + "enabled_capabilities": ["bailian.mcp"], + "loop_mode": "auto", + "max_turns": 1000, + "timeout": 30, + "tui": True, + "privacy_mode": False, + "tongyi_api_key": "", + "anthropic_api_key": "", + "openai_api_key": "", + "fallback_providers": None, + } + defaults.update(overrides) + return SimpleNamespace(**defaults) + + @staticmethod + def _agent(): + from types import SimpleNamespace + + return SimpleNamespace( + provider_name="tongyi", + model_name="qwen3.7-max", + json_mode=False, + ) + + def test_command_timeout_is_shown_separately(self, monkeypatch): + from dashscope.acli.cli.dispatch import _handle_slash_command + + monkeypatch.setenv(shell.TIMEOUT_ENV, "45") + console = MagicMock() + monkeypatch.setattr("dashscope.acli.cli.dispatch.console", console) + + _handle_slash_command("/info", self._agent(), self._config()) + + printed = " ".join(str(c) for c in console.print.call_args_list) + assert "LLM timeout" in printed + assert "Cmd timeout" in printed + assert "45s" in printed