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()