Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
86 changes: 70 additions & 16 deletions .github/scripts/run-bounded.sh
Original file line number Diff line number Diff line change
Expand Up @@ -3,17 +3,28 @@
#
# Usage: run-bounded.sh <seconds> <command> [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

Expand All @@ -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/<pid>/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"
23 changes: 19 additions & 4 deletions bleep-bsp-tests/src/scala/bleep/analysis/CancellationTest.scala
Original file line number Diff line number Diff line change
Expand Up @@ -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)

Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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()
Expand Down
Loading