fix(e2e): bound docker lifecycle hangs

This commit is contained in:
Vincent Koc 2026-05-26 21:02:26 +02:00
parent 0ea7871e53
commit 71cb60706b
No known key found for this signature in database
6 changed files with 343 additions and 19 deletions

View file

@ -11,6 +11,14 @@ if (!summaryPath || !phase || separator !== "--" || !command) {
const pageSize = Number.parseInt(process.env.OPENCLAW_PROC_PAGE_SIZE || "4096", 10);
const clockTicks = Number.parseInt(process.env.OPENCLAW_PROC_CLK_TCK || "100", 10);
const pollMs = Number.parseInt(process.env.OPENCLAW_PLUGIN_LIFECYCLE_METRIC_POLL_MS || "100", 10);
const timeoutMs = Number.parseInt(
process.env.OPENCLAW_PLUGIN_LIFECYCLE_PHASE_TIMEOUT_MS || "300000",
10,
);
const timeoutKillGraceMs = Number.parseInt(
process.env.OPENCLAW_PLUGIN_LIFECYCLE_TIMEOUT_KILL_GRACE_MS || "2000",
10,
);
if (!fs.existsSync("/proc")) {
console.error("plugin lifecycle resource sampler requires Linux /proc");
@ -99,11 +107,16 @@ const started = performance.now();
const child = spawn(command, args, {
cwd: process.cwd(),
env: process.env,
detached: true,
stdio: "inherit",
});
let maxRssBytes = 0;
let maxCpuTicks = 0;
let timedOut = false;
let finished = false;
let parentSignalInFlight = false;
let killTimer;
const updateMetrics = () => {
if (!child.pid) {
return;
@ -115,24 +128,119 @@ const updateMetrics = () => {
updateMetrics();
const interval = setInterval(updateMetrics, pollMs);
const timeoutTimer =
Number.isFinite(timeoutMs) && timeoutMs > 0
? setTimeout(() => {
timedOut = true;
terminateChildGroup("SIGTERM");
killTimer = setTimeout(() => {
terminateChildGroup("SIGKILL");
finish(124);
}, timeoutKillGraceMs);
killTimer.unref?.();
}, timeoutMs)
: null;
timeoutTimer?.unref?.();
child.on("exit", (code, signal) => {
updateMetrics();
function terminateChildGroup(signal) {
if (!child.pid) {
return;
}
try {
process.kill(-child.pid, signal);
return;
} catch {}
try {
child.kill(signal);
} catch {}
}
function clearRuntimeTimers() {
clearInterval(interval);
if (timeoutTimer) {
clearTimeout(timeoutTimer);
}
if (killTimer) {
clearTimeout(killTimer);
}
}
function rethrowParentSignal(signal) {
process.removeAllListeners(signal);
process.kill(process.pid, signal);
process.exit(128);
}
function handleParentSignal(signal) {
if (parentSignalInFlight) {
terminateChildGroup("SIGKILL");
rethrowParentSignal(signal);
return;
}
parentSignalInFlight = true;
if (finished) {
rethrowParentSignal(signal);
return;
}
finished = true;
clearRuntimeTimers();
terminateChildGroup(signal);
setTimeout(() => {
terminateChildGroup("SIGKILL");
rethrowParentSignal(signal);
}, timeoutKillGraceMs);
}
for (const signal of ["SIGHUP", "SIGINT", "SIGTERM"]) {
process.once(signal, () => handleParentSignal(signal));
}
process.once("exit", () => {
if (!finished) {
terminateChildGroup("SIGTERM");
}
});
function finish(code, signal) {
if (finished) {
return;
}
finished = true;
updateMetrics();
clearRuntimeTimers();
const wallMs = performance.now() - started;
const cpuSeconds = maxCpuTicks / clockTicks;
const maxRssKb = Math.round(maxRssBytes / 1024);
const cpuCoreRatio = wallMs > 0 ? cpuSeconds / (wallMs / 1000) : 0;
const summarySignal = timedOut ? "timeout" : (signal ?? "");
fs.appendFileSync(
summaryPath,
`${phase}\t${maxRssKb}\t${cpuSeconds.toFixed(3)}\t${wallMs.toFixed(0)}\t${cpuCoreRatio.toFixed(3)}\t${signal ?? ""}\n`,
`${phase}\t${maxRssKb}\t${cpuSeconds.toFixed(3)}\t${wallMs.toFixed(0)}\t${cpuCoreRatio.toFixed(3)}\t${summarySignal}\n`,
);
console.log(
`plugin lifecycle resource: phase=${phase} max_rss_kb=${maxRssKb} cpu_s=${cpuSeconds.toFixed(3)} wall_ms=${wallMs.toFixed(0)} cpu_core_ratio=${cpuCoreRatio.toFixed(3)}`,
`plugin lifecycle resource: phase=${phase} max_rss_kb=${maxRssKb} cpu_s=${cpuSeconds.toFixed(3)} wall_ms=${wallMs.toFixed(0)} cpu_core_ratio=${cpuCoreRatio.toFixed(3)} signal=${summarySignal}`,
);
if (timedOut) {
process.exit(124);
return;
}
if (signal) {
process.kill(process.pid, signal);
return;
}
process.exit(code ?? 0);
}
child.on("error", (error) => {
finished = true;
clearRuntimeTimers();
console.error(error instanceof Error ? error.message : String(error));
process.exit(1);
});
child.on("exit", (code, signal) => {
if (timedOut && killTimer) {
return;
}
finish(code, signal);
});

View file

@ -18,13 +18,22 @@ docker_e2e_package_mount_args "$PACKAGE_TGZ"
docker_e2e_build_or_reuse "$IMAGE_NAME" plugin-lifecycle-matrix "$ROOT_DIR/scripts/e2e/Dockerfile" "$ROOT_DIR" "bare" "$SKIP_BUILD"
OPENCLAW_TEST_STATE_SCRIPT_B64="$(docker_e2e_test_state_shell_b64 plugin-lifecycle-matrix empty)"
DOCKER_ENV_ARGS=(
-e COREPACK_ENABLE_DOWNLOAD_PROMPT=0
-e OPENCLAW_SKIP_CHANNELS=1
-e OPENCLAW_SKIP_PROVIDERS=1
-e "OPENCLAW_TEST_STATE_SCRIPT_B64=$OPENCLAW_TEST_STATE_SCRIPT_B64"
)
if [ -n "${OPENCLAW_PLUGIN_LIFECYCLE_PHASE_TIMEOUT_MS:-}" ]; then
DOCKER_ENV_ARGS+=(-e "OPENCLAW_PLUGIN_LIFECYCLE_PHASE_TIMEOUT_MS=$OPENCLAW_PLUGIN_LIFECYCLE_PHASE_TIMEOUT_MS")
fi
if [ -n "${OPENCLAW_PLUGIN_LIFECYCLE_TIMEOUT_KILL_GRACE_MS:-}" ]; then
DOCKER_ENV_ARGS+=(-e "OPENCLAW_PLUGIN_LIFECYCLE_TIMEOUT_KILL_GRACE_MS=$OPENCLAW_PLUGIN_LIFECYCLE_TIMEOUT_KILL_GRACE_MS")
fi
echo "Running plugin lifecycle matrix Docker E2E..."
docker_e2e_run_with_harness \
-e COREPACK_ENABLE_DOWNLOAD_PROMPT=0 \
-e OPENCLAW_SKIP_CHANNELS=1 \
-e OPENCLAW_SKIP_PROVIDERS=1 \
-e "OPENCLAW_TEST_STATE_SCRIPT_B64=$OPENCLAW_TEST_STATE_SCRIPT_B64" \
"${DOCKER_ENV_ARGS[@]}" \
"${DOCKER_E2E_PACKAGE_ARGS[@]}" \
"$IMAGE_NAME" \
bash scripts/e2e/lib/plugin-lifecycle-matrix/sweep.sh

View file

@ -22,11 +22,7 @@ docker_e2e_docker_cmd() {
}
docker_e2e_docker_run_cmd() {
if [ -n "${DOCKER_COMMAND_TIMEOUT:-}" ]; then
docker_e2e_timeout_cmd "$DOCKER_COMMAND_TIMEOUT" docker "$@"
return
fi
docker "$@"
docker_e2e_timeout_cmd "${DOCKER_COMMAND_TIMEOUT:-${OPENCLAW_DOCKER_E2E_RUN_TIMEOUT:-3600s}}" docker "$@"
}
docker_e2e_container_running() {

View file

@ -15,15 +15,16 @@ if ! declare -F docker_e2e_docker_cmd >/dev/null 2>&1; then
fi
if ! declare -F docker_e2e_docker_run_cmd >/dev/null 2>&1; then
docker_e2e_docker_run_cmd() {
if [ -n "${DOCKER_COMMAND_TIMEOUT:-}" ] && declare -F docker_e2e_timeout_cmd >/dev/null 2>&1; then
docker_e2e_timeout_cmd "$DOCKER_COMMAND_TIMEOUT" docker "$@"
if declare -F docker_e2e_timeout_cmd >/dev/null 2>&1; then
docker_e2e_timeout_cmd "${DOCKER_COMMAND_TIMEOUT:-${OPENCLAW_DOCKER_E2E_RUN_TIMEOUT:-3600s}}" docker "$@"
return
fi
if [ -n "${DOCKER_COMMAND_TIMEOUT:-}" ] && command -v timeout >/dev/null 2>&1; then
local timeout_value="${DOCKER_COMMAND_TIMEOUT:-${OPENCLAW_DOCKER_E2E_RUN_TIMEOUT:-3600s}}"
if command -v timeout >/dev/null 2>&1; then
if timeout --kill-after=1s 1s true >/dev/null 2>&1; then
timeout --kill-after=30s "$DOCKER_COMMAND_TIMEOUT" docker "$@"
timeout --kill-after=30s "$timeout_value" docker "$@"
else
timeout "$DOCKER_COMMAND_TIMEOUT" docker "$@"
timeout "$timeout_value" docker "$@"
fi
return
fi

View file

@ -54,6 +54,7 @@ const PLUGIN_UPDATE_SCENARIO_PATH = "scripts/e2e/lib/plugin-update/unchanged-sce
const PLUGIN_UPDATE_CORRUPT_SCENARIO_PATH =
"scripts/e2e/lib/plugin-update/corrupt-update-scenario.sh";
const PLUGIN_UPDATE_PROBE_PATH = "scripts/e2e/lib/plugin-update/probe.mjs";
const PLUGIN_LIFECYCLE_MATRIX_DOCKER_E2E_PATH = "scripts/e2e/plugin-lifecycle-matrix-docker.sh";
const DOCTOR_SWITCH_DOCKER_E2E_PATH = "scripts/e2e/doctor-install-switch-docker.sh";
const DOCTOR_SWITCH_SCENARIO_PATH = "scripts/e2e/lib/doctor-install-switch/scenario.sh";
const PACKAGE_COMPAT_PATH = "scripts/e2e/lib/package-compat.mjs";
@ -490,7 +491,7 @@ docker_e2e_package_mount_args "$external_dir/openclaw-current.tgz"
unset DOCKER_COMMAND_TIMEOUT
rm -f "$TMPDIR/docker-timeout-seen"
docker_e2e_run_with_harness image-name bash -lc true
test ! -e "$TMPDIR/docker-timeout-seen"
test "$(cat "$TMPDIR/docker-timeout-seen")" = "--kill-after=30s 3600s"
test -f "$external_dir/openclaw-current.tgz"
`;
@ -529,6 +530,20 @@ grep -qx -- "OPENCLAW_E2E_NPM_INSTALL_TIMEOUT=42s" "$TMPDIR/package-args"
}
});
it("passes plugin lifecycle sampler timeout overrides into Docker", () => {
const runner = readFileSync(PLUGIN_LIFECYCLE_MATRIX_DOCKER_E2E_PATH, "utf8");
expect(runner).toContain('if [ -n "${OPENCLAW_PLUGIN_LIFECYCLE_PHASE_TIMEOUT_MS:-}" ]; then');
expect(runner).toContain(
'DOCKER_ENV_ARGS+=(-e "OPENCLAW_PLUGIN_LIFECYCLE_PHASE_TIMEOUT_MS=$OPENCLAW_PLUGIN_LIFECYCLE_PHASE_TIMEOUT_MS")',
);
expect(runner).toContain('if [ -n "${OPENCLAW_PLUGIN_LIFECYCLE_TIMEOUT_KILL_GRACE_MS:-}" ]; then');
expect(runner).toContain(
'DOCKER_ENV_ARGS+=(-e "OPENCLAW_PLUGIN_LIFECYCLE_TIMEOUT_KILL_GRACE_MS=$OPENCLAW_PLUGIN_LIFECYCLE_TIMEOUT_KILL_GRACE_MS")',
);
expect(runner).toContain('docker_e2e_run_with_harness \\\n "${DOCKER_ENV_ARGS[@]}"');
});
it("wraps direct Docker E2E npm installs with the shared timeout helper", () => {
const multiNode = readFileSync(MULTI_NODE_UPDATE_DOCKER_E2E_PATH, "utf8");
const updateChannel = readFileSync(UPDATE_CHANNEL_SWITCH_DOCKER_E2E_PATH, "utf8");
@ -584,6 +599,25 @@ ROOT_DIR=${shellQuote(rootDir)}
TMPDIR=${shellQuote(workDir)}
export ROOT_DIR TMPDIR
mkdir -p "$TMPDIR/bin"
cat >"$TMPDIR/bin/timeout" <<'SH'
#!/usr/bin/env bash
case "$1" in
--kill-after=1s)
exit 0
;;
--kill-after=30s)
shift 2
;;
*)
shift
;;
esac
"$@"
SH
chmod +x "$TMPDIR/bin/timeout"
export PATH="$TMPDIR/bin:$PATH"
docker_e2e_docker_cmd() {
printf "%s\\n" "$*" >"$TMPDIR/docker-cmd-seen"
}

View file

@ -0,0 +1,176 @@
import { spawnSync } from "node:child_process";
import { mkdtempSync, readFileSync, rmSync } from "node:fs";
import { tmpdir } from "node:os";
import path from "node:path";
import { afterEach, describe, expect, it } from "vitest";
const tempDirs: string[] = [];
const scriptPath = "scripts/e2e/lib/plugin-lifecycle-matrix/measure.mjs";
const hasTimeoutCommand =
process.platform === "linux" &&
spawnSync("bash", ["-lc", "command -v timeout >/dev/null 2>&1"]).status === 0;
function makeTempDir(): string {
const dir = mkdtempSync(path.join(tmpdir(), "openclaw-plugin-lifecycle-measure-"));
tempDirs.push(dir);
return dir;
}
function pidExists(pid: number): boolean {
try {
process.kill(pid, 0);
return true;
} catch {
return false;
}
}
function waitForPidExit(pid: number, timeoutMs: number): boolean {
const waitBuffer = new SharedArrayBuffer(4);
const waitView = new Int32Array(waitBuffer);
const deadline = Date.now() + timeoutMs;
while (Date.now() < deadline) {
if (!pidExists(pid)) {
return true;
}
Atomics.wait(waitView, 0, 0, 25);
}
return !pidExists(pid);
}
afterEach(() => {
for (const dir of tempDirs.splice(0)) {
rmSync(dir, { recursive: true, force: true });
}
});
describe("plugin lifecycle resource sampler", () => {
it("configures a phase timeout with process-group cleanup", () => {
const script = readFileSync(scriptPath, "utf8");
expect(script).toContain("OPENCLAW_PLUGIN_LIFECYCLE_PHASE_TIMEOUT_MS");
expect(script).toContain("OPENCLAW_PLUGIN_LIFECYCLE_TIMEOUT_KILL_GRACE_MS");
expect(script).toContain("detached: true");
expect(script).toContain('process.kill(-child.pid, signal)');
expect(script).toContain('const summarySignal = timedOut ? "timeout"');
expect(script).toContain("process.exit(124)");
});
it.runIf(process.platform === "linux")(
"times out wedged phases and records the timeout signal",
() => {
const dir = makeTempDir();
const summary = path.join(dir, "summary.tsv");
const result = spawnSync(
"node",
[scriptPath, summary, "wedged", "--", "node", "-e", "setInterval(() => {}, 1000)"],
{
cwd: process.cwd(),
encoding: "utf8",
env: {
...process.env,
OPENCLAW_PLUGIN_LIFECYCLE_PHASE_TIMEOUT_MS: "150",
OPENCLAW_PLUGIN_LIFECYCLE_TIMEOUT_KILL_GRACE_MS: "50",
},
timeout: 5000,
},
);
expect(result.status).toBe(124);
expect(result.stdout).toContain("signal=timeout");
expect(readFileSync(summary, "utf8")).toMatch(/^wedged\t\d+\t[\d.]+\t\d+\t[\d.]+\ttimeout$/mu);
},
);
it.runIf(process.platform === "linux")(
"kills stubborn descendants after the timeout grace period",
() => {
const dir = makeTempDir();
const summary = path.join(dir, "summary.tsv");
const pidFile = path.join(dir, "descendant.pid");
let descendantPid = 0;
try {
const result = spawnSync(
"node",
[
scriptPath,
summary,
"stubborn-descendant",
"--",
"bash",
"-lc",
'bash -c \'trap "" TERM; printf "%s\\n" "$$" >"$PID_FILE"; while :; do sleep 1; done\' & wait',
],
{
cwd: process.cwd(),
encoding: "utf8",
env: {
...process.env,
OPENCLAW_PLUGIN_LIFECYCLE_PHASE_TIMEOUT_MS: "150",
OPENCLAW_PLUGIN_LIFECYCLE_TIMEOUT_KILL_GRACE_MS: "100",
PID_FILE: pidFile,
},
timeout: 5000,
},
);
descendantPid = Number.parseInt(readFileSync(pidFile, "utf8"), 10);
expect(result.status).toBe(124);
expect(result.stdout).toContain("signal=timeout");
expect(readFileSync(summary, "utf8")).toMatch(
/^stubborn-descendant\t\d+\t[\d.]+\t\d+\t[\d.]+\ttimeout$/mu,
);
expect(waitForPidExit(descendantPid, 1000)).toBe(true);
} finally {
if (descendantPid > 0 && pidExists(descendantPid)) {
process.kill(descendantPid, "SIGKILL");
}
}
},
);
it.runIf(hasTimeoutCommand)("forwards external termination to the measured process group", () => {
const dir = makeTempDir();
const summary = path.join(dir, "summary.tsv");
const pidFile = path.join(dir, "descendant.pid");
let descendantPid = 0;
try {
const result = spawnSync(
"timeout",
[
"--kill-after=1s",
"0.2s",
"node",
scriptPath,
summary,
"external-stop",
"--",
"bash",
"-lc",
'bash -c \'trap "" TERM; printf "%s\\n" "$$" >"$PID_FILE"; while :; do sleep 1; done\' & wait',
],
{
cwd: process.cwd(),
encoding: "utf8",
env: {
...process.env,
OPENCLAW_PLUGIN_LIFECYCLE_PHASE_TIMEOUT_MS: "5000",
OPENCLAW_PLUGIN_LIFECYCLE_TIMEOUT_KILL_GRACE_MS: "100",
PID_FILE: pidFile,
},
timeout: 5000,
},
);
descendantPid = Number.parseInt(readFileSync(pidFile, "utf8"), 10);
expect(result.status).toBe(124);
expect(waitForPidExit(descendantPid, 1000)).toBe(true);
} finally {
if (descendantPid > 0 && pidExists(descendantPid)) {
process.kill(descendantPid, "SIGKILL");
}
}
});
});