diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 47d400f..f1268e1 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -53,3 +53,5 @@ jobs: run: tests/scheduler-agent-path.sh - name: pool settling window run: tests/pool-settling-window.sh + - name: stuck queue guard + run: tests/stuck-queue-guard.sh diff --git a/AGENTS.md b/AGENTS.md index 1d4515a..8eff6f2 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -31,7 +31,7 @@ lib/scheduler.sh status, doctor, autoscale, sweep, clean, schedule lib/notify.sh the optional notifier hook and what triggers it lib/stats.sh job durations from recorded telemetry, and queue times via contrib/telemetry-join.sh -tests/ offline test scripts, all four run by CI +tests/ offline test scripts, every one of them run by CI contrib/ optional pieces the user opts into: job hook, webhook notifier, demo status fixture skills/runpool/ agent skill for *using* runpool, shipped with the tool @@ -59,6 +59,16 @@ assets/icon.svg the icon, source of truth; PNGs are rendered from it **The consequence is that an agent already loaded is not necessarily an agent that behaves correctly.** A plist rewritten on disk changes nothing until the pool cycles. Anything depending on agent behaviour must therefore read the *loaded* environment with `launchctl print`, not the file. `_rp_agent_traps_signals` is the example, and `_rp_drain_pool` refuses per runner on the strength of it. The file on disk is what somebody intended; the loaded environment is what is true. +## The stuck-queue guard subtracts, it does not suppress + +**A queued run that never starts would otherwise wake a pool for ever**, every `RUNPOOL_IDLE_SECS` plus a tick, and nothing reports it because a pool that wakes and stands down is behaving as designed. `_rp_autoscale` therefore computes `queued > held` rather than deciding whether the pool is allowed to wake. + +- **Never suppress the pool.** An org pool watches many repositories, and one dead run in one of them must not blind it to the rest. Subtracting is what keeps the blast radius to the single run. +- **A strike is earned only when `state/pools/.started` has changed** since that run was last judged. That is the only available proof that waking for it achieved nothing. A tick count would give three strikes in three minutes to a pool that cannot start at all, and then refuse it real work once its agents were repaired; elapsed time would punish a laptop that slept through the night with work genuinely queued. +- **`_rp_stuck_advance`, `_rp_stuck_held` and `_rp_stuck_new_holds` are pure**, for the same reason `_rp_unwatched_repos` is: the rule is only testable at all when it is separate from the caller that needs GitHub. +- **The job count is corroboration, never a branch.** Zero jobs is the signature of the zombie case and it reads well in the message, but making the decision depend on a second API shape buys nothing the local rule does not already get right. +- **A held run says nothing on later ticks.** Only `_rp_stuck_new_holds` logs or notifies, or the loop this exists to end is replaced by a line a minute. + ## The reconfiguration lock **One per-pool lock covers resize and drain, and `up` and autoscale both respect it.** It was originally a resize lock; a drain needs the same exclusion for longer, so the concept widened rather than gaining a second flag to get out of step with. @@ -80,10 +90,7 @@ Environment, then config file, then built-in default. The config file uses plain /bin/bash -n bin/runpool lib/*.sh contrib/*.sh tests/*.sh install.sh shellcheck --severity=warning bin/runpool lib/*.sh contrib/*.sh tests/*.sh install.sh -tests/storage-migration.sh -tests/set-count-guards.sh -tests/watch-list-staleness.sh -tests/drain-guards.sh +for t in tests/*.sh; do "$t" || break; done ``` Without shellcheck installed, Docker gives the same result and leaves nothing behind. Skipping the check is how CI goes red unnoticed: @@ -93,7 +100,7 @@ docker run --rm -v "$PWD:/mnt" -w /mnt koalaman/shellcheck:stable \ --severity=warning bin/runpool lib/*.sh contrib/*.sh tests/*.sh install.sh ``` -**The tests run offline and make no API calls**, which is what makes them safe anywhere. A new test must keep that: fabricate pool configs under a scratch `RUNPOOL_BASE`, stub `gh` where a path needs it, and prefer a guard refused early over one that reaches the network. `tests/set-count-guards.sh` probes its lock case with a mismatched `--if-count` for that reason, since a real resize fetches the runner tarball first. +**The tests run offline and make no API calls**, which is what makes them safe anywhere. A new test must keep that: fabricate pool configs under a scratch `RUNPOOL_BASE`, stub `gh` where a path needs it, and prefer a guard refused early over one that reaches the network. `tests/set-count-guards.sh` probes its lock case with a mismatched `--if-count` for that reason, since a real resize fetches the runner tarball first. `tests/stuck-queue-guard.sh` stubs `_rp_up` to move the started stamp by a counter rather than the clock, because the rule it exercises turns on that stamp changing and real seconds would mean sleeping through every cycle. **Test against a scratch directory, never a real installation:** diff --git a/README.md b/README.md index c263760..d2ea679 100644 --- a/README.md +++ b/README.md @@ -48,7 +48,7 @@ runs-on: ${{ vars.CI_RUNNER || 'ubuntu-latest' }} - **A pool is a set of runners bound to one GitHub scope.** GitHub offers repository, organisation and enterprise scopes and **no user-account scope**, which is the most surprising thing about self-hosted runners. An organisation shares one pool across its repositories; a personal repository needs its own and cannot borrow an organisation's. - **Capacity and routing stay separate.** A workflow's `runs-on` decides where a job lands. RunPool decides only whether the runners are up, so a workflow pointed at a pool that is down waits for it rather than quietly rerouting to a hosted runner that costs ten times as much. -- **Two launch agents drive everything.** A tick every 60 seconds brings up pools with queued work, stands down idle ones, and checks their registrations are still live. A clean at 04:00 prunes work directories, caches and superseded binaries, skipping any pool mid-job. Only stopped pools are polled, so active work costs no API calls at all. +- **Two launch agents drive everything.** A tick every 60 seconds brings up pools with queued work, stands down idle ones, and checks their registrations are still live. A run that stays queued across several wake cycles stops counting as work, so a run GitHub will never start cannot wake the pool for ever. A clean at 04:00 prunes work directories, caches and superseded binaries, skipping any pool mid-job. Only stopped pools are polled, so active work costs no API calls at all. The first job after a quiet spell waits about a minute for its pool to come up. Everything after that is immediate. diff --git a/bin/runpool b/bin/runpool index 226bde5..5190559 100755 --- a/bin/runpool +++ b/bin/runpool @@ -43,7 +43,7 @@ export RUNPOOL_INVOKED # The released version, and the only place it is written. The Homebrew formula # builds from a git tag, so a tag without a matching bump here ships a binary # that misreports itself. -RUNPOOL_VERSION="0.10.4" +RUNPOOL_VERSION="0.11.0" # shellcheck source=lib/common.sh . "${RUNPOOL_ROOT}/lib/common.sh" diff --git a/lib/common.sh b/lib/common.sh index c5f59de..aa2ed19 100644 --- a/lib/common.sh +++ b/lib/common.sh @@ -23,6 +23,7 @@ _rp_env_POOLS_FILE="${RUNPOOL_POOLS_FILE:-}" _rp_env_LOG_DIR="${RUNPOOL_LOG_DIR:-}" _rp_env_LABEL_NS="${RUNPOOL_LABEL_NS:-}" _rp_env_IDLE_SECS="${RUNPOOL_IDLE_SECS:-}" +_rp_env_STUCK_WAKES="${RUNPOOL_STUCK_WAKES:-}" _rp_env_LOAD_WARN="${RUNPOOL_LOAD_WARN:-}" _rp_env_NOTIFY_CMD="${RUNPOOL_NOTIFY_CMD:-}" _rp_env_JOB_HOOK="${RUNPOOL_JOB_HOOK:-}" @@ -46,6 +47,7 @@ set +a [ -n "${_rp_env_LOG_DIR}" ] && RUNPOOL_LOG_DIR="${_rp_env_LOG_DIR}" [ -n "${_rp_env_LABEL_NS}" ] && RUNPOOL_LABEL_NS="${_rp_env_LABEL_NS}" [ -n "${_rp_env_IDLE_SECS}" ] && RUNPOOL_IDLE_SECS="${_rp_env_IDLE_SECS}" +[ -n "${_rp_env_STUCK_WAKES}" ] && RUNPOOL_STUCK_WAKES="${_rp_env_STUCK_WAKES}" [ -n "${_rp_env_LOAD_WARN}" ] && RUNPOOL_LOAD_WARN="${_rp_env_LOAD_WARN}" [ -n "${_rp_env_NOTIFY_CMD}" ] && RUNPOOL_NOTIFY_CMD="${_rp_env_NOTIFY_CMD}" [ -n "${_rp_env_JOB_HOOK}" ] && RUNPOOL_JOB_HOOK="${_rp_env_JOB_HOOK}" @@ -53,12 +55,13 @@ set +a [ -n "${_rp_env_TELEMETRY}" ] && RUNPOOL_TELEMETRY="${_rp_env_TELEMETRY}" [ -n "${_rp_env_DRAIN_TIMEOUT}" ] && RUNPOOL_DRAIN_TIMEOUT="${_rp_env_DRAIN_TIMEOUT}" unset _rp_env_BASE _rp_env_CACHE_DIR _rp_env_POOLS_FILE _rp_env_LOG_DIR _rp_env_LABEL_NS \ - _rp_env_IDLE_SECS _rp_env_LOAD_WARN _rp_env_NOTIFY_CMD _rp_env_JOB_HOOK \ + _rp_env_IDLE_SECS _rp_env_STUCK_WAKES _rp_env_LOAD_WARN _rp_env_NOTIFY_CMD _rp_env_JOB_HOOK \ _rp_env_HOOK_DIR _rp_env_TELEMETRY _rp_env_DRAIN_TIMEOUT # Restored values need exporting again: the restore above is a plain assignment # and happens after 'set -a' was turned off. export RUNPOOL_BASE RUNPOOL_CACHE_DIR RUNPOOL_LOG_DIR RUNPOOL_LABEL_NS RUNPOOL_IDLE_SECS \ + RUNPOOL_STUCK_WAKES \ RUNPOOL_LOAD_WARN RUNPOOL_NOTIFY_CMD RUNPOOL_JOB_HOOK RUNPOOL_HOOK_DIR RUNPOOL_TELEMETRY \ RUNPOOL_DRAIN_TIMEOUT \ RUNPOOL_CONFIG RUNPOOL_POOLS_FILE @@ -135,6 +138,13 @@ RUNPOOL_IDLE_SECS="${RUNPOOL_IDLE_SECS:-1200}" # window reports every healthy start as an outage. RUNPOOL_SETTLE_SECS="${RUNPOOL_SETTLE_SECS:-120}" +# How many fruitless wake cycles a queued run is given before it stops counting +# as work. A run can sit `queued` forever with no jobs ever attached, and +# autoscale counting it wakes the pool, finds nothing, idles out and wakes +# again for as long as the run exists. Three cycles is roughly an hour of +# proof at the default idle threshold. Set to 0 to disable the guard. +RUNPOOL_STUCK_WAKES="${RUNPOOL_STUCK_WAKES:-3}" + # How long `--drain` waits for running jobs to finish before giving up. # # Derive this from the longest job the pool could serve plus the runner's own @@ -376,13 +386,45 @@ _rp_pool_paused() { [ -f "$(_rp_pool_pause_flag "$1")" ]; } # reason as the activity stamp above. _rp_pool_started_flag() { echo "${RUNPOOL_POOL_STATE_DIR}/$1.started"; } _rp_touch_pool_started() { _rp_now >| "$(_rp_pool_started_flag "$1")"; } -_rp_pool_settling() { +_rp_pool_started_at() { local started started=$(cat "$(_rp_pool_started_flag "$1")" 2>/dev/null || echo 0) - case "${started}" in ''|*[!0-9]*) return 1 ;; esac + case "${started}" in ''|*[!0-9]*) started=0 ;; esac + echo "${started}" +} +_rp_pool_settling() { + local started + started="$(_rp_pool_started_at "$1")" + [ "${started}" != "0" ] || return 1 [ $(( $(_rp_now) - started )) -lt "${RUNPOOL_SETTLE_SECS}" ] } +# Queued runs this pool has stopped counting as work, one record per line: +# +# +# +# The started stamp is what the pool's `.started` flag held when that run was +# last judged, and it is the whole of the rule: a strike is earned only once +# the pool has come up and back down since, which is the only evidence that +# waking for this run achieved nothing. A tick count would punish a pool that +# cannot start at all, and elapsed time would punish a laptop that slept. +# +# Rewritten only when it changes, so an idle machine is not writing this file +# sixty times an hour, and removed outright once nothing is queued. +_rp_pool_stuck_file() { echo "${RUNPOOL_POOL_STATE_DIR}/$1.stuck"; } +_rp_read_pool_stuck() { cat "$(_rp_pool_stuck_file "$1")" 2>/dev/null || true; } +_rp_write_pool_stuck() { + local f cur + f="$(_rp_pool_stuck_file "$1")" + cur="$(cat "${f}" 2>/dev/null || true)" + if [ -z "$2" ]; then + rm -f "${f}" + return 0 + fi + [ "${cur}" = "$2" ] && return 0 + printf '%s\n' "$2" >| "${f}" +} + _rp_runner_cache_dir() { echo "${POOL_CACHE_DIR}/runner-$2"; } _rp_runner_work_dir() { if [ "${POOL_LEGACY_LAYOUT}" = "1" ]; then diff --git a/lib/lifecycle.sh b/lib/lifecycle.sh index 2e28bcf..5843923 100644 --- a/lib/lifecycle.sh +++ b/lib/lifecycle.sh @@ -881,7 +881,12 @@ _rp_remove() { case "${POOL_DIR}" in "${RUNPOOL_BASE}/"*) rm -rf "${POOL_DIR}" ;; esac fi [ "${POOL_LEGACY_LAYOUT}" = "1" ] || rm -rf "${POOL_CACHE_DIR}" + # Every per-pool state file, not just the pause flag. A pool registered again + # under the same name inherits whatever is left here, and inheriting strikes + # would mean a brand-new pool refusing to wake. rm -f "$(_rp_pool_pause_flag "$1")" + rm -f "$(_rp_pool_started_flag "$1")" + rm -f "$(_rp_pool_stuck_file "$1")" rm -f "$(_rp_pool_conf "$1")" _rp_log "pool '$1' removed" diff --git a/lib/notify.sh b/lib/notify.sh index 16aab99..9e96a17 100644 --- a/lib/notify.sh +++ b/lib/notify.sh @@ -102,3 +102,30 @@ _rp_health_check() { esac done } + +# A run autoscale has stopped counting as work, reported once per hold. +# +# `warning`, not `critical`: the two criticals above are pools that cannot take +# work at all, and nobody needs waking for a pool that has just stopped burning +# a wake cycle every twenty minutes. The key carries the run id rather than +# only the pool, deliberately breaking the three-segment shape of the others, +# because the run is the incident: a receiver deduping per pool would swallow +# the next stuck run in that pool a week later. +# +# $1 pool, $2 the new holds as " ..." lines. Fires nothing when +# there are none, and the caller is what guarantees each run appears once. +_rp_notify_stuck_queue() { + local p="$1" repo id jobs + [ -n "${RUNPOOL_NOTIFY_CMD}" ] || return 0 + [ -n "${2:-}" ] || return 0 + printf '%s\n' "$2" | while read -r repo id _; do + [ -n "${repo}" ] && [ -n "${id}" ] || continue + jobs="$(_rp_run_job_count "${repo}" "${id}")" + case "${jobs}" in ''|*[!0-9]*) jobs="an unknown number of" ;; esac + _rp_notify warning \ + "Pool '${p}' has stopped waking for a stuck queued run" \ + "runpool/stuck-queue/${p}/${id}" \ + "Run ${id} in ${repo} stayed queued across ${RUNPOOL_STUCK_WAKES} wake cycles, so it no longer counts as work. GitHub reports ${jobs} job(s) for it. The pool is healthy; this run will never start." \ + "\"Pool\":\"${p}\",\"Repository\":\"${repo}\",\"Run\":\"${id}\",\"Jobs\":\"${jobs}\",\"Fix\":\"gh run cancel ${id} --repo ${repo}\"" + done +} diff --git a/lib/scheduler.sh b/lib/scheduler.sh index 3339dd3..395ce04 100644 --- a/lib/scheduler.sh +++ b/lib/scheduler.sh @@ -66,7 +66,7 @@ _rp_running_in() { # cleanly, looks healthy in every local check, and picks up nothing. Reporting # only the local view hid exactly that for three weeks. _rp_status() { - local as_json=0 local_only=0 arg total_running=0 total_busy=0 p running busy gh reg online gh_display note settling warn=0 + local as_json=0 local_only=0 arg total_running=0 total_busy=0 p running busy gh reg online gh_display note settling stuck warn=0 for arg in "$@"; do case "${arg}" in --json) as_json=1 ;; @@ -102,6 +102,12 @@ _rp_status() { esac fi + # Outside the local_only branch above: this is local state, so --local + # shows it too, and it is the only visible sign that a queued run has + # stopped waking the pool. + stuck="$(_rp_stuck_held "$(_rp_read_pool_stuck "${p}")" "${RUNPOOL_STUCK_WAKES}" | awk 'NF { n++ } END { print n + 0 }')" + [ "${stuck}" -gt 0 ] && note="${note} (${stuck} stuck queued run(s) ignored)" + _rp_pool_paused "${p}" && note=" (paused)${note}" printf " %-10s %-6s %-20s %7s %5s %s%s\n" \ "${p}" "${POOL_SCOPE}" "${POOL_TARGET}" "${running}/${POOL_COUNT}" \ @@ -131,7 +137,7 @@ _rp_status() { # is thousands a day, and it makes a passive readout fail whenever the network # does, which is the opposite of what a passive readout is for. _rp_status_json() { - local local_only="${1:-0}" p running busy gh reg online first=1 paused="false" pool_paused="false" reconfiguring="false" wr wfirst + local local_only="${1:-0}" p running busy gh reg online first=1 paused="false" pool_paused="false" reconfiguring="false" wr wfirst sr sid sfirst _rp_paused && paused="true" # Machine state belongs here rather than being recomputed by every caller. # The load threshold is configurable, so a status consumer that derived it @@ -172,6 +178,17 @@ _rp_status_json() { wfirst=0 printf '"%s"' "${wr}" done + # Runs autoscale has stopped counting as work, as "owner/repo#id". Safe to + # hand-assemble for the same reason as everything above: the repository is + # a validated GitHub identifier and the id is digits. + printf '],"stuck":[' + sfirst=1 + while read -r sr sid _; do + [ -n "${sr}" ] && [ -n "${sid}" ] || continue + [ "${sfirst}" = "1" ] || printf ',' + sfirst=0 + printf '"%s#%s"' "${sr}" "${sid}" + done < <(_rp_stuck_held "$(_rp_read_pool_stuck "${p}")" "${RUNPOOL_STUCK_WAKES}") printf ']}' done printf ']}\n' @@ -235,7 +252,7 @@ _rp_doctor() { local gh_ok=1 pools=0 seen_orgs="" p running gh reg online settling local tick clean i missing avail_kb cache_avail_kb free mode other phase hook_fails - local all_repos unwatched drain_stale + local all_repos unwatched drain_stale stuck_repo stuck_id stuck_at stuck_jobs _rp_doctor_fails=0 _rp_doctor_warns=0 @@ -452,6 +469,24 @@ _rp_doctor() { "fix: it clears on the next 'runpool set-count' or 'runpool down --drain'; or remove $(_rp_resize_lock_dir "${p}")" fi + # Before the gh_ok gate below, because this state is local: the pool has + # already decided, and the operator needs to hear it whether or not GitHub + # can be reached now. Read and never cleared, per the boundary at the top + # of this file; the next autoscale pass tidies it for free once the run + # leaves the queued set. + # + # `done < <(...)` and not a pipeline: `_rp_doctor_warns` is file-scope and + # a pipeline subshell would discard every increment. + while read -r stuck_repo stuck_id _ _ stuck_at; do + [ -n "${stuck_repo}" ] && [ -n "${stuck_id}" ] || continue + stuck_jobs="" + [ "${gh_ok}" = "1" ] && stuck_jobs="$(_rp_run_job_count "${stuck_repo}" "${stuck_id}")" + case "${stuck_jobs}" in ''|*[!0-9]*) stuck_jobs="" ;; *) stuck_jobs=" (github reports ${stuck_jobs} job(s) for it)" ;; esac + _rp_doctor_warn \ + "${p}: ${stuck_repo} run ${stuck_id} has been queued for $(( ( $(_rp_now) - stuck_at ) / 3600 ))h and never starts, so it no longer wakes this pool${stuck_jobs}" \ + "fix: gh run cancel ${stuck_id} --repo ${stuck_repo}; a run with no jobs that refuses to cancel takes 'gh api -X DELETE /repos/${stuck_repo}/actions/runs/${stuck_id}'" + done < <(_rp_stuck_held "$(_rp_read_pool_stuck "${p}")" "${RUNPOOL_STUCK_WAKES}") + if [ "${gh_ok}" = "0" ]; then _rp_doctor_note "${p}: ${POOL_SCOPE} ${POOL_TARGET}, ${running}/${POOL_COUNT} running locally (github not checked)" continue @@ -619,6 +654,97 @@ _rp_unwatched_repos() { done } +# --------------------------------------------------------------------------- +# the stuck-queue rule +# --------------------------------------------------------------------------- +# A run can enter `queued` and stay there permanently with no jobs ever +# attached. Autoscale counts queued runs, so it wakes the pool, finds nothing +# to run, idles out and wakes again, for as long as the run exists. Nothing +# reports it, because a pool that wakes and stands down is behaving exactly as +# designed. +# +# The rule subtracts known-fruitless runs from the queued count rather than +# suppressing the pool. Suppressing would blind an org pool to every other +# repository it watches on account of one stuck run in one of them, and every +# other run still has to wake it normally. +# +# How long a stuck run is given a second chance before it is judged again. +# Not a setting: it exists so a run held by something transient, a concurrency +# group upstream being the realistic case, cannot be held for ever. On expiry +# the strike count drops to one below the threshold, so exactly one wake +# re-checks it and it goes straight back to held if nothing has changed. +RUNPOOL_STUCK_RETRY=86400 + +# The three functions below are pure: strings in, a string out, no files, no +# clock and no `gh`. That is what makes the rule testable at all, for the same +# reason `_rp_unwatched_repos` above is pure. + +# $1 previous records, $2 currently-queued " " lines, +# $3 the pool's started stamp, $4 now, $5 threshold, $6 retry seconds. +_rp_stuck_advance() { + awk -v started="$3" -v now="$4" -v thresh="$5" -v retry="$6" ' + NR == FNR { + if (NF >= 5 && $3 ~ /^[0-9]+$/ && $4 ~ /^[0-9]+$/ && $5 ~ /^[0-9]+$/) { + k = $1 " " $2; strikes[k] = $3; seen[k] = $4; at[k] = $5 + } + next + } + NF >= 2 { + k = $1 " " $2 + if (k in strikes) { + s = strikes[k]; p = seen[k]; t = at[k] + if (p != started) { s = s + 1; p = started; t = now } + if (thresh > 0 && s >= thresh && retry > 0 && now - t >= retry) { s = thresh - 1; t = now } + } else { + s = 0; p = started; t = now + } + print $1, $2, s, p, t + } + ' <(printf '%s\n' "$1") <(printf '%s\n' "$2") +} + +# $1 records, $2 threshold. The runs that no longer count as work. +_rp_stuck_held() { + awk -v thresh="$2" ' + thresh > 0 && NF >= 5 && $3 ~ /^[0-9]+$/ && $3 >= thresh { print } + ' <(printf '%s\n' "$1") +} + +# $1 previous records, $2 new records, $3 threshold. Held now and not before, +# which is what makes the log line and the notification fire exactly once per +# hold rather than on every tick. +_rp_stuck_new_holds() { + awk -v thresh="$3" ' + NR == FNR { + if (NF >= 5 && $3 ~ /^[0-9]+$/ && $3 >= thresh) was[$1 " " $2] = 1 + next + } + thresh > 0 && NF >= 5 && $3 ~ /^[0-9]+$/ && $3 >= thresh && !(($1 " " $2) in was) { print } + ' <(printf '%s\n' "$1") <(printf '%s\n' "$2") +} + +# The queued runs in one repository, as " ". One call, the +# same as the count alone used to cost. A failed call yields an empty string, +# so every caller degrades to the behaviour that predates this rule. +_rp_queued_runs() { + local out + # The body, not just the status, has to be discarded on failure: gh prints + # GitHub's error JSON to stdout, so a watch list naming a repository that has + # been renamed or made private would otherwise hand the caller a line + # beginning '{"message":"Not Found"'. That used to reach an arithmetic + # expansion and abort it. + out="$(gh api "/repos/$1/actions/runs?status=queued&per_page=100&exclude_pull_requests=true" \ + --jq '"\(.total_count) \([.workflow_runs[].id] | sort | map(tostring) | join(","))"' 2>/dev/null)" || return 0 + printf '%s\n' "${out}" +} + +# How many jobs GitHub says a run has. Corroboration for a message, never a +# branch: zero jobs is the signature of the zombie case, but the local strike +# rule already reaches the right answer without a second API shape. +_rp_run_job_count() { + gh api "/repos/$1/actions/runs/$2/jobs?per_page=1" --jq '.total_count' 2>/dev/null +} + # --------------------------------------------------------------------------- # autoscale: bring a pool up when it has queued work # --------------------------------------------------------------------------- @@ -628,7 +754,7 @@ _rp_unwatched_repos() { # per organisation. _rp_autoscale() { _rp_paused && return 0 - local p up queued q wr + local p up queued held repos wr line n id ids started now prev fresh note for p in $(_rp_pool_names); do _rp_load_pool "${p}" || continue _rp_pool_paused "${p}" && continue @@ -638,20 +764,46 @@ _rp_autoscale() { _rp_resize_locked_by_other "${p}" && continue up="$(_rp_running_in "${p}" "${POOL_COUNT}")" [ "${up}" -gt 0 ] && continue + + # One repository at repo scope, the watch list at org scope. GitHub + # exposes queued runs per repository rather than per organisation, which + # is why the watch list is the wake mechanism and not merely advisory. + if [ "${POOL_SCOPE}" = "repo" ]; then repos="${POOL_TARGET}" + else repos="$(echo "${POOL_WATCH:-}" | tr ',' ' ')" + fi + queued=0 - if [ "${POOL_SCOPE}" = "repo" ]; then - q=$(gh api "/repos/${POOL_TARGET}/actions/runs?status=queued&per_page=1" --jq '.total_count' 2>/dev/null) - queued="${q:-0}" - else - for wr in $(echo "${POOL_WATCH:-}" | tr ',' ' '); do - [ -n "${wr}" ] || continue - q=$(gh api "/repos/${wr}/actions/runs?status=queued&per_page=1" --jq '.total_count' 2>/dev/null) - queued=$(( queued + ${q:-0} )) + ids="" + for wr in ${repos}; do + [ -n "${wr}" ] || continue + line="$(_rp_queued_runs "${wr}")" + n="${line%% *}" + case "${n}" in ''|*[!0-9]*) n=0 ;; esac + queued=$(( queued + n )) + [ "${line}" = "${n}" ] && continue + for id in $(echo "${line#* }" | tr ',' ' '); do + case "${id}" in ''|*[!0-9]*) continue ;; esac + ids="${ids}${wr} ${id} +" done - fi - case "${queued}" in ''|*[!0-9]*) queued=0 ;; esac - if [ "${queued}" -gt 0 ]; then - _rp_log "autoscale: '${p}' has ${queued} queued job(s), bringing up" + done + + started="$(_rp_pool_started_at "${p}")" + now="$(_rp_now)" + prev="$(_rp_read_pool_stuck "${p}")" + fresh="$(_rp_stuck_advance "${prev}" "${ids}" "${started}" "${now}" \ + "${RUNPOOL_STUCK_WAKES}" "${RUNPOOL_STUCK_RETRY}")" + _rp_write_pool_stuck "${p}" "${fresh}" + + # Reported once per hold. A held pool logs nothing on subsequent ticks, + # or the loop this rule exists to end is replaced by a line a minute. + _rp_notify_stuck_queue "${p}" "$(_rp_stuck_new_holds "${prev}" "${fresh}" "${RUNPOOL_STUCK_WAKES}")" + + held="$(_rp_stuck_held "${fresh}" "${RUNPOOL_STUCK_WAKES}" | awk 'NF { n++ } END { print n + 0 }')" + if [ "${queued}" -gt "${held}" ]; then + note="" + [ "${held}" -gt 0 ] && note=", ${held} held down" + _rp_log "autoscale: '${p}' has ${queued} queued run(s)${note}, bringing up" _rp_up "${p}" fi done diff --git a/runpool.conf.example b/runpool.conf.example index 5c8855c..564eadb 100644 --- a/runpool.conf.example +++ b/runpool.conf.example @@ -44,6 +44,13 @@ # until the window passes. Raise it if this machine starts runners slowly. # RUNPOOL_SETTLE_SECS=120 +# How many fruitless wake cycles a queued run is given before it stops counting +# as work. A run can sit `queued` for ever with no jobs attached, and without +# this the pool wakes for it, finds nothing, idles out and wakes again for as +# long as the run exists. `doctor` names any run this is holding down, and +# `status` says how many there are. Set to 0 to disable the guard. +# RUNPOOL_STUCK_WAKES=3 + # Load threshold exposed in structured status. It does not send an alert. # Defaults to six times core count, which sits clear of ordinary work. # Raise this as the pool grows: a busy pool of N runners reaches about N times diff --git a/skills/runpool/SKILL.md b/skills/runpool/SKILL.md index 27971d2..209ba3b 100644 --- a/skills/runpool/SKILL.md +++ b/skills/runpool/SKILL.md @@ -125,12 +125,14 @@ It works down the whole list below in one pass, prints a remedy against each fai - **an org pool with no watched repositories:** it never autoscales. Fix: give it `--watch` and `runpool apply`. - **an org pool watching only some of its repositories:** a note rather than a failure, because a repository may legitimately route its jobs elsewhere and nothing readable tells the difference. A job queued by an unwatched one waits until a watched one happens to wake the pool. **`doctor` makes a stale list audible; it does not maintain one.** The list stays hand-maintained, so a repository added to the organisation is still a change somebody has to make here too. - **runner(s) started before graceful shutdown was available:** a note, not a failure. The pool runs and takes work normally; only `--drain` is affected, and it refuses safely rather than killing the job. Fix: `runpool rewrite-agents`, then let the pool cycle. **This is how to check drain readiness without attempting a drain**, which on a busy pool means risking real jobs to answer a question. +- **a queued run that no longer wakes the pool:** a warning naming the run. A run can stay `queued` for ever with no jobs attached, and counting it would wake the pool every twenty minutes for as long as it exists, so after three fruitless cycles it stops counting as work. **Every other queued run still wakes the pool normally**, including others in the same repository, so this narrows nothing but the one dead run. Fix: cancel it, `gh run cancel --repo `; a run with no jobs sometimes refuses to cancel and takes `gh api -X DELETE /repos//actions/runs/`. - **disk, config permissions, the organisation's runner-group setting:** each with its own remedy. None of these stops a job being picked up, but they are the things nothing else ever looks at. -**Two situations `doctor` deliberately reports as healthy, because they are.** +**Three situations `doctor` deliberately reports as healthy, because they are.** - **`running 0/N` with a job genuinely queued:** the tick brings a pool up within about a minute. Wait before intervening; `runpool up ` forces it. - **A clean report and the job still waits:** the problem is routing, not capacity. The workflow's `runs-on` may not resolve to `self-hosted`, or its labels may not match the pool's. RunPool controls only whether the runners are up and cannot see either. +- **a run held down and the rest of the queue moving:** intended. The guard subtracts held runs from the queued count rather than silencing the pool, and a run that is merely waiting its turn behind another gets a fresh chance once a day. ```bash runpool status # the same picture as a table, one row per pool diff --git a/tests/stuck-queue-guard.sh b/tests/stuck-queue-guard.sh new file mode 100755 index 0000000..dad2209 --- /dev/null +++ b/tests/stuck-queue-guard.sh @@ -0,0 +1,227 @@ +#!/bin/bash +# The guard that stops autoscale waking a pool for a run that will never start. +# +# Two halves. The first exercises the pure rule directly, because that is where +# every judgement lives and none of it needs GitHub. The second drives one +# autoscale loop with `_rp_up` and `_rp_running_in` stubbed, which is what +# makes a wake cycle deterministic and keeps launchd out of it. +# +# Offline: gh is stubbed and nothing here reaches GitHub. +set -uo pipefail + +repo_dir=$(cd -P "$(dirname "$0")/.." && pwd) +scratch_dir=$(mktemp -d) +bin_dir="${scratch_dir}/bin" +trap 'rm -rf "${scratch_dir}"' EXIT INT TERM + +export RUNPOOL_BASE="${scratch_dir}/base" +export RUNPOOL_STATE_DIR="${scratch_dir}/base/state" +export RUNPOOL_CACHE_DIR="${scratch_dir}/cache" +export RUNPOOL_CONFIG="${scratch_dir}/runpool.conf" +export RUNPOOL_POOLS_FILE="${scratch_dir}/pools" +export RUNPOOL_LOG_DIR="${scratch_dir}/logs" +export RUNPOOL_LOG="${scratch_dir}/logs/runpool.log" +export RUNPOOL_AGENT_DIR="${scratch_dir}/agents" +mkdir -p "${RUNPOOL_BASE}/pools" "${RUNPOOL_STATE_DIR}/pools" "${RUNPOOL_CACHE_DIR}" \ + "${RUNPOOL_LOG_DIR}" "${RUNPOOL_AGENT_DIR}" "${bin_dir}" + +# shellcheck source=/dev/null +. "${repo_dir}/lib/common.sh" 2>/dev/null || true +# shellcheck source=/dev/null +. "${repo_dir}/lib/scheduler.sh" +# shellcheck source=/dev/null +. "${repo_dir}/lib/notify.sh" +mkdir -p "${RUNPOOL_POOL_STATE_DIR}" + +fail() { echo "FAIL: $*" >&2; exit 1; } +pass=0 +check() { + local label="$1" expected="$2" actual="$3" + if [ "${expected}" = "${actual}" ]; then + pass=$(( pass + 1 )) + else + fail "${label}: expected '${expected}', got '${actual}'" + fi +} +strikes_for() { printf '%s\n' "$1" | awk -v k="$2" '$2 == k { print $3 }'; } +count() { printf '%s\n' "$1" | awk 'NF { n++ } END { print n + 0 }'; } + +# --------------------------------------------------------------------------- +# the pure rule +# --------------------------------------------------------------------------- +NOW=1000000 +ONE=$'acme/widget 111' +TWO=$'acme/widget 111\nacme/gadget 222' + +# First sight is never a strike: a run nobody has judged yet is work, and the +# pool must wake for it however old it is. This is the overnight case, where a +# laptop that slept comes back to a genuinely queued job hours old. +s1="$(_rp_stuck_advance "" "${ONE}" 500 "${NOW}" 3 86400)" +check "first sight earns no strike" "0" "$(strikes_for "${s1}" 111)" +check "first sight is not held" "0" "$(count "$(_rp_stuck_held "${s1}" 3)")" + +# The regression that matters most. A pool that cannot start at all, a missing +# launch agent being the way that happens, never changes its started stamp. If +# strikes accrued per pass it would reach the threshold in three minutes and +# then refuse real work once the agents were repaired. +s="${s1}" +for _ in 1 2 3 4 5; do + s="$(_rp_stuck_advance "${s}" "${ONE}" 500 "${NOW}" 3 86400)" +done +check "an unchanged started stamp earns nothing" "0" "$(strikes_for "${s}" 111)" + +# One strike per cycle, and held at the threshold. +s="$(_rp_stuck_advance "${s1}" "${ONE}" 501 "${NOW}" 3 86400)" +check "one cycle, one strike" "1" "$(strikes_for "${s}" 111)" +s="$(_rp_stuck_advance "${s}" "${ONE}" 502 "${NOW}" 3 86400)" +s="$(_rp_stuck_advance "${s}" "${ONE}" 503 "${NOW}" 3 86400)" +check "three cycles reach the threshold" "3" "$(strikes_for "${s}" 111)" +check "and the run is held" "1" "$(count "$(_rp_stuck_held "${s}" 3)")" +held="${s}" + +# The org case, and the reason this subtracts rather than suppressing. One +# stuck run in one repository must not blind the pool to another repository: +# queued is 2, held is 1, so the pool still wakes. +s="$(_rp_stuck_advance "${held}" "${TWO}" 504 "${NOW}" 3 86400)" +check "a new run alongside a held one is not held" "1" "$(count "$(_rp_stuck_held "${s}" 3)")" +check "and the new run starts at zero" "0" "$(strikes_for "${s}" 222)" + +# Leaving the queued set drops the record, so cancelling the run is all the +# cleanup there is. +s="$(_rp_stuck_advance "${held}" "acme/gadget 222" 505 "${NOW}" 3 86400)" +check "a run that stops being queued is forgotten" "" "$(strikes_for "${s}" 111)" + +# The re-arm, so a run held by something transient cannot be held for ever. +# It buys exactly one wake, and goes straight back to held if nothing changed. +s="$(_rp_stuck_advance "${held}" "${ONE}" 503 $(( NOW + 90000 )) 3 86400)" +check "retry drops it below the threshold" "2" "$(strikes_for "${s}" 111)" +check "so it is not held" "0" "$(count "$(_rp_stuck_held "${s}" 3)")" +s="$(_rp_stuck_advance "${s}" "${ONE}" 506 $(( NOW + 90000 )) 3 86400)" +check "and one cycle later it is held again" "1" "$(count "$(_rp_stuck_held "${s}" 3)")" + +# New holds fire once, which is what keeps the log and the notifier quiet. +check "the hold is announced once" "1" "$(count "$(_rp_stuck_new_holds "${s1}" "${held}" 3)")" +s="$(_rp_stuck_advance "${held}" "${ONE}" 507 "${NOW}" 3 86400)" +check "and not again on the next pass" "0" "$(count "$(_rp_stuck_new_holds "${held}" "${s}" 3)")" + +# Nought disables the guard outright. +check "threshold 0 holds nothing" "0" "$(count "$(_rp_stuck_held "${held}" 0)")" + +# A truncated or hand-mangled record is ignored rather than becoming a hold. +check "a short record is not a hold" "0" "$(count "$(_rp_stuck_held 'acme/widget 111 3' 3)")" +check "a non-numeric strike is not a hold" "0" "$(count "$(_rp_stuck_held 'acme/widget 111 x 1 1' 3)")" +check "and it is treated as unseen" "0" "$(strikes_for "$(_rp_stuck_advance 'acme/widget 111 x 1 1' "${ONE}" 999 "${NOW}" 3 86400)" 111)" + +# --------------------------------------------------------------------------- +# one autoscale loop end to end +# --------------------------------------------------------------------------- +cat >"${RUNPOOL_BASE}/pools/alpha.conf" <"${bin_dir}/gh" <<'STUB' +#!/bin/bash +echo "$2" >> "${GH_CALLS}" +case "$2" in + */jobs*) echo 0 ;; + *) n=0; for i in ${QUEUED_IDS}; do n=$(( n + 1 )); done + echo "${n} $(echo ${QUEUED_IDS} | tr ' ' ',')" ;; +esac +STUB +chmod +x "${bin_dir}/gh" +export PATH="${bin_dir}:${PATH}" +export GH_CALLS="${scratch_dir}/calls" +: >"${GH_CALLS}" +calls() { awk 'NF { n++ } END { print n + 0 }' "${GH_CALLS}"; } + +wakes="${scratch_dir}/wakes" +: >"${wakes}" +tick=0 +# The pool is always down, and a wake records itself and moves the started +# stamp, which is exactly what a real `_rp_up` does and the only thing the +# rule reads from it. The stamp is a counter rather than the clock so a cycle +# is instant: real seconds would mean sleeping through every wake. +_rp_running_in() { echo 0; } +_rp_up() { + printf '%s\n' "$1" >>"${wakes}" + tick=$(( tick + 1 )) + printf '%s\n' "$(( 1000 + tick ))" >| "$(_rp_pool_started_flag "$1")" +} +wakes_seen() { awk 'NF { n++ } END { print n + 0 }' "${wakes}"; } + +# The tool logs to stderr as well as its log file, and a passing test should +# say only that it passed. Per call rather than `exec 2>`, which would also +# swallow `fail`, and a test whose failure message is invisible is worse than +# a noisy one. +quietly() { "$@" 2>>"${RUNPOOL_LOG}"; } + +export QUEUED_IDS="111" +quietly _rp_autoscale; quietly _rp_autoscale; quietly _rp_autoscale; quietly _rp_autoscale +check "three fruitless wakes, then silence" "3" "$(wakes_seen)" + +before=$(calls) +quietly _rp_autoscale +check "a held pool still costs exactly one call" "1" "$(( $(calls) - before ))" + +# A second run arriving is work the pool has never judged, so it wakes at once +# even though the first run is still held. +export QUEUED_IDS="111 222" +quietly _rp_autoscale +check "a new run wakes a held pool" "4" "$(wakes_seen)" + +# GitHub's error JSON arrives on stdout, not stderr, so a watch entry naming a +# repository that has been renamed or made private hands the helper a line +# starting '{'. It must count as nothing rather than reaching the arithmetic. +cat >"${bin_dir}/gh" <<'STUB' +#!/bin/bash +echo "$2" >> "${GH_CALLS}" +echo '{"message":"Not Found","documentation_url":"https://docs.github.com/rest","status":"404"}' +exit 1 +STUB +chmod +x "${bin_dir}/gh" +rm -f "$(_rp_pool_stuck_file alpha)" +before_wakes=$(wakes_seen) +quietly _rp_autoscale +check "a repository gh cannot read does not wake the pool" "${before_wakes}" "$(wakes_seen)" +check "and leaves no stuck record" "0" "$(count "$(_rp_read_pool_stuck alpha)")" + +cat >"${bin_dir}/gh" <<'STUB' +#!/bin/bash +echo "$2" >> "${GH_CALLS}" +case "$2" in + */jobs*) echo 0 ;; + *) n=0; for i in ${QUEUED_IDS}; do n=$(( n + 1 )); done + echo "${n} $(echo ${QUEUED_IDS} | tr ' ' ',')" ;; +esac +STUB +chmod +x "${bin_dir}/gh" + +# The notification fires once and carries the run, not just the pool. +notes="${scratch_dir}/notes" +: >"${notes}" +cat >"${bin_dir}/notify" <> "${notes}" +echo >> "${notes}" +STUB +chmod +x "${bin_dir}/notify" +export RUNPOOL_NOTIFY_CMD="${bin_dir}/notify" +export QUEUED_IDS="333" +rm -f "$(_rp_pool_stuck_file alpha)" +quietly _rp_autoscale; quietly _rp_autoscale; quietly _rp_autoscale; quietly _rp_autoscale +check "one notification for one stuck run" "1" "$(awk 'NF { n++ } END { print n + 0 }' "${notes}")" +case "$(cat "${notes}")" in + *'"key":"runpool/stuck-queue/alpha/333"'*) pass=$(( pass + 1 )) ;; + *) fail "the notification does not carry the run: $(cat "${notes}")" ;; +esac + +echo "ok: ${pass} case(s)"