From 04d50ae60c7160e9f9d3c12c34ff5a624b8b289f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=98yvind=20Raddum=20Berg?= Date: Sun, 2 Aug 2026 18:48:51 +0200 Subject: [PATCH] ci: the windows hang was stdout inheritance, not a surviving process MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The bound added in #639 did not work: run 30752489661 hung the same 55 minutes with the same missing bsp-diagnostics-windows-latest artifact, despite run-bounded.sh being in effect. The reason is that it bounded the wrong thing. Reproduced locally, with a fixture that spawns a daemon which escapes a process group kill and then hangs, both scripts given a 5-8s bound: old (child inherits stdout): still blocked after 20s new (child writes to a file): finished in 12s, WITH the survivor still alive So killing the process was never the missing piece. GitHub waits for the step's output PIPES to close, not for the shell to exit — and `bleep` spawns a BSP daemon which spawns forked test JVMs, all inheriting stdout. Kill the child and the pipe is still held by a grandchild, so a 20-minute bound produced a 45-minute step and the runner was destroyed with the telemetry steps pending. Two changes, and the second is the one that matters: 1. Kill the process GROUP (`set -m` so the child leads its own), plus `taskkill //F //T` on Windows, where processes are not in POSIX groups. 2. Redirect the child to a FILE. Descendants then inherit the file, not the pipe. Only `tail` holds the pipe, and `tail` is ours to kill — so the step ends even when something survives, which is precisely the case that hung. On timeout the last 200 lines are printed in a collapsed group, since the whole point is to still have the evidence. Verified: exit 0 on success, 7 propagated from the child, 124 on expiry, grandchildren reaped, streaming intact during a normal run, and the pipe closed with a deliberate survivor left running. Also fixes the second flaky cancellation test, `Kotlin: fiber cancellation interrupts compilation`, which failed the same run with `TimeoutException: 30 seconds`. These compile through `IO.interruptible`, whose cancellation interrupts the thread and then WAITS for the block to return — and kotlinc does not promise to notice. So `fiber.cancel` can take as long as the whole compile, which each of these tests already accepts explicitly ("completed before cancellation took effect"). The bound only rules out waiting forever, and 30s did not clear a full compile of a deliberately huge generated source on a contended runner: the suite is 3.8s healthy, so this was an 8x outlier, the shape of "never reached an interruptible point" rather than of a slightly tight bound. Named `CancellationHangGuard`, 120s, applied to all four sites — they share the pattern, and the other three would fail next time a runner is busy. Co-Authored-By: Claude Opus 5 (1M context) --- .github/scripts/run-bounded.sh | 86 +++++++++++++++---- .../bleep/analysis/CancellationTest.scala | 23 ++++- 2 files changed, 89 insertions(+), 20 deletions(-) diff --git a/.github/scripts/run-bounded.sh b/.github/scripts/run-bounded.sh index 05010ff83..4fe5d8f99 100755 --- a/.github/scripts/run-bounded.sh +++ b/.github/scripts/run-bounded.sh @@ -3,17 +3,28 @@ # # Usage: run-bounded.sh [args...] # -# Why this exists rather than `timeout-minutes:` on the step. When a step exceeds its GitHub-side cap, the runner has to -# reap the step's process tree — and on windows-latest it could not. Observed on run 30697246865: the test step declared -# `timeout-minutes: 20` and ran 45m07s, the job then blew through its own 45-minute ceiling at 55m00s, and the runner was -# destroyed with both telemetry steps still pending. The one hang worth diagnosing produced no diagnostics at all, which -# is the exact failure #627 added the step cap to prevent. The cap did not hold. +# Why this exists rather than `timeout-minutes:` on the step. When a step exceeds its GitHub-side cap the runner has to +# reap the step's process tree, and on windows-latest it cannot: the test step declared 20 minutes and ran 45m07s, the +# job blew its own 45-minute ceiling at 55m00s, and the runner was destroyed with both telemetry steps still pending. So +# the one hang worth diagnosing produced no diagnostics — twice. # -# Why not `timeout(1)`. It is GNU coreutils, absent from macOS, which is two of the five arches in this matrix. Doing it -# in bash keeps one code path for every OS, which is the same reason the surrounding steps unified on `shell: bash`. +# TWO things have to be true for the step to actually end, and the first version of this script only did the first. +# That is why the hang came back on run 30752489661 with the bound already in place. # -# On expiry we SIGKILL rather than SIGTERM: the process being bounded is a build that has already proven it is not -# responding, and a graceful signal it might ignore would put us back to waiting on a tree that will not die. +# 1. The bounded command must die. Killing the direct child is not enough: `bleep` spawns a BSP daemon, which spawns +# forked test JVMs. Those are grandchildren and outlive their parent. So the whole process GROUP is killed, and on +# Windows `taskkill /T` as well, because Windows processes are not in POSIX process groups. +# +# 2. Nothing may still hold the step's stdout. GitHub waits for the step's output pipes to close, not merely for the +# shell to exit — so a surviving daemon that inherited stdout keeps the step alive no matter what happened to the +# process we were watching. The child therefore writes to a FILE, and its descendants inherit that file instead of +# the pipe. Only `tail` holds the pipe, and `tail` is ours to kill. +# +# `timeout(1)` is not used: it is GNU coreutils, absent on macOS, which is two of the five arches in this matrix. Doing +# it in bash keeps one code path per OS, the same reason the surrounding steps unified on `shell: bash`. +# +# SIGKILL rather than SIGTERM on expiry: the thing being bounded has already proven it is not responding, and a signal +# it may ignore puts us back to waiting on a tree that will not die. set -uo pipefail @@ -25,24 +36,67 @@ fi limit_seconds="$1" shift -"$@" & +log_file="$(mktemp -t run-bounded.XXXXXX)" +is_windows=false +case "$(uname -s)" in + MINGW* | MSYS* | CYGWIN*) is_windows=true ;; +esac + +# Job control, so the background child leads its own process group and `kill -- -PID` reaches everything it spawned. +# Without it the child shares our group and a group kill would take this script down with it. +set -m +"$@" >"$log_file" 2>&1 & child_pid=$! +set +m + +# Stream the log, so the step is not silent for the ~13 minutes this normally takes. `tail` holding the step's stdout is +# fine and is the point: it is ours, it has no children, and it is killed below. +tail -n +1 -f "$log_file" & +tail_pid=$! + +stop_tail() { + kill "$tail_pid" 2>/dev/null || true + wait "$tail_pid" 2>/dev/null || true +} + +kill_tree() { + if [ "$is_windows" = true ]; then + # MSYS pids are not Windows pids; /proc//winpid is the translation. Doubled slashes stop MSYS mangling the + # arguments into paths. + local winpid + winpid="$(cat "/proc/$child_pid/winpid" 2>/dev/null || true)" + if [ -n "$winpid" ]; then + taskkill //F //T //PID "$winpid" >/dev/null 2>&1 || true + fi + fi + kill -9 -- "-$child_pid" 2>/dev/null || true + kill -9 "$child_pid" 2>/dev/null || true +} waited=0 poll_interval=5 while kill -0 "$child_pid" 2>/dev/null; do if [ "$waited" -ge "$limit_seconds" ]; then - # A GitHub workflow command, so this lands as an annotation on the job rather than only in the log. + # A workflow command, so this lands as an annotation on the job rather than only in the log. echo "::error title=Timed out::'$*' exceeded ${limit_seconds}s and was killed" - kill -9 "$child_pid" 2>/dev/null || true - wait "$child_pid" 2>/dev/null || true + kill_tree + sleep 2 # let tail drain what the child wrote before it died + stop_tail + echo "::group::last 200 lines before the kill" + tail -n 200 "$log_file" 2>/dev/null || true + echo "::endgroup::" + rm -f "$log_file" # 124 is what timeout(1) reports for this, so the number means the same thing here as everywhere else. exit 124 fi sleep "$poll_interval" - waited=$(( waited + poll_interval )) + waited=$((waited + poll_interval)) done -# The loop only ends when the child is gone, so this reports its real exit status rather than blocking. wait "$child_pid" -exit $? +exit_code=$? + +sleep 1 +stop_tail +rm -f "$log_file" +exit "$exit_code" diff --git a/bleep-bsp-tests/src/scala/bleep/analysis/CancellationTest.scala b/bleep-bsp-tests/src/scala/bleep/analysis/CancellationTest.scala index c3962eeb7..be64f9607 100644 --- a/bleep-bsp-tests/src/scala/bleep/analysis/CancellationTest.scala +++ b/bleep-bsp-tests/src/scala/bleep/analysis/CancellationTest.scala @@ -18,6 +18,21 @@ import scala.concurrent.duration.* */ class CancellationTest extends AnyFunSuite with Matchers { + /** Hang guard for the fiber-cancellation tests, not a measurement of how fast cancellation is. + * + * These compile through `IO.interruptible`, whose cancellation interrupts the worker thread and then WAITS for the block to return. Neither scalac, kotlinc + * nor javac promises to notice an interrupt promptly, so `fiber.cancel` can legitimately take as long as the whole compile — and each of these tests already + * accepts that outcome explicitly ("compilation completed before cancellation took effect"). The only thing the bound rules out is waiting forever. + * + * So it has to clear a FULL uncancelled compile of a deliberately huge generated source on a contended runner, and 30s did not: the whole suite runs in 3.8s + * healthy, and CI still saw one of these blow through 30s while the other suites had the machine busy. That is a 8x outlier against healthy, which is the + * shape of "kotlinc never reached an interruptible point", not of "the bound is slightly tight". + * + * Applied to all four sites rather than the one that failed, on the same reasoning as the wall-clock bounds loosened in #623: they share the pattern and the + * flaw, and the other three would fail the next time a runner is busy. + */ + private val CancellationHangGuard = 120.seconds + def createTempDir(prefix: String): Path = Files.createTempDirectory(prefix) @@ -170,7 +185,7 @@ class CancellationTest extends AnyFunSuite with Matchers { _ <- IO(cancellation.cancel()) // Signal cancellation to the compiler _ <- fiber.cancel // Cancel the fiber outcome <- fiber.join - } yield outcome).timeout(30.seconds) + } yield outcome).timeout(CancellationHangGuard) val startTime = System.currentTimeMillis() val outcome = program.unsafeRunSync() @@ -221,7 +236,7 @@ class CancellationTest extends AnyFunSuite with Matchers { _ <- IO(cancellation.cancel()) _ <- fiber.cancel outcome <- fiber.join - } yield outcome).timeout(30.seconds) + } yield outcome).timeout(CancellationHangGuard) val startTime = System.currentTimeMillis() val outcome = program.unsafeRunSync() @@ -296,7 +311,7 @@ class CancellationTest extends AnyFunSuite with Matchers { _ <- IO(cancellation.cancel()) _ <- fiber.cancel outcome <- fiber.join - } yield outcome).timeout(30.seconds) + } yield outcome).timeout(CancellationHangGuard) val startTime = System.currentTimeMillis() val outcome = program.unsafeRunSync() @@ -371,7 +386,7 @@ class CancellationTest extends AnyFunSuite with Matchers { _ <- IO(cancellation.cancel()) _ <- fiber.cancel outcome <- fiber.join - } yield outcome).timeout(30.seconds) + } yield outcome).timeout(CancellationHangGuard) val startTime = System.currentTimeMillis() val outcome = program.unsafeRunSync()