From e19b155f0c70597662cfa6d8146f0149ae2982ab Mon Sep 17 00:00:00 2001 From: Kyle Sexton <153232337+kyle-sexton@users.noreply.github.com> Date: Wed, 28 Oct 2026 17:26:07 -0400 Subject: [PATCH] ci: count every GitHub request gh makes, pages and subcommands included The gh wrapper in api-budget.bash counted one reading per `gh api` call and passed every other call through uncounted: each page of --paginate, --slurp and --silent, and every non-api subcommand (gh pr view, gh run list, gh pr edit). In the GITHUB_TOKEN pool that trips the breaker about 2,900 requests an hour went unlogged. Every gh call the wrapper makes now runs with GH_DEBUG=1, which logs a `* Request to ` line per HTTP request and no headers or bodies. Each request to a GitHub API URL is a `request` line in the token's file, less the one a -i header block already records, so api-calls counts pages, redirects and subcommands. gh's stderr reaches the caller without the lines the debug level adds, byte for byte otherwise. 304s still come from the header reading, so not-modified is unchanged. ci-status carries the same file in API_BUDGET_SH. Co-Authored-By: Claude Opus 5.5 --- .github/actions/log-api-budget/action.yml | 4 +- .../actions/log-api-budget/api-budget.bash | 67 ++++++++-- .../log-api-budget/log-api-budget.test.mjs | 121 ++++++++++++++++++ .github/workflows/pr-require-checks.yml | 67 ++++++++-- 4 files changed, 237 insertions(+), 22 deletions(-) diff --git a/.github/actions/log-api-budget/action.yml b/.github/actions/log-api-budget/action.yml index 14adac8f67c..e49a9c1bab1 100644 --- a/.github/actions/log-api-budget/action.yml +++ b/.github/actions/log-api-budget/action.yml @@ -5,7 +5,7 @@ description: > in $RUNNER_TEMP/api-budget (api-budget.bash): one per refused (403/429) response and one for the last. GET /rate_limit is never read: it reports a different bucket from the one the job spends. Then an `api-calls` notice, - `=N not-modified=M`: N is this job's own calls, which cost (the rise in a + `=N not-modified=M`: N is this job's own requests, which cost (the rise in a counter every concurrent job shares) is not, and M its 304 answers, which GitHub does not count. Then one line for the job's content-creating writes (count and most in any 60 s). Also writes each line and a `-cost=N` @@ -43,7 +43,7 @@ runs: printf '%s\n' "$lines" sed 's/^::notice title=api-budget::/api-budget: /' <<<"$lines" >>"$GITHUB_STEP_SUMMARY" fi - # This job's own calls, one reading each: unlike cost, no other job's. + # This job's own requests, every page and gh subcommand: unlike cost, no other job's. # A notice, as the hub reads annotations, not the log; 0 with no reading. calls=$(api_budget_emit_calls "$name") printf '%s\n' "$calls" diff --git a/.github/actions/log-api-budget/api-budget.bash b/.github/actions/log-api-budget/api-budget.bash index 81c6ae6ef21..beb55d0e9ec 100644 --- a/.github/actions/log-api-budget/api-budget.bash +++ b/.github/actions/log-api-budget/api-budget.bash @@ -5,8 +5,10 @@ # is one line in $RUNNER_TEMP/api-budget/: # # (`na` for a missing value). api-budget.mjs and babysit_gh.py append the same -# lines. Never fails the caller, except that a stop the rate guard below -# cannot record ends the step. +# lines. A request the gh wrapper counts with no header block to read (each +# page of --paginate, a call that is not `gh api`) is a line `request`. Never +# fails the caller, except that a stop the rate guard below cannot record ends +# the step. # # api_budget_read # gh api -i output: the header block at the start @@ -16,7 +18,8 @@ # api_budget_read, keeping stdout, stderr and the # exit status as they were (not --paginate, whose # per-page header blocks are left out), behind -# the rate guard below +# the rate guard below; every gh call also counts +# each request it sends (api_budget_traced) # # The rate guard, rate-guard.mjs's shell port: once a response shows a pool # exhausted, no gh call goes to that pool before its reset for the rest of the @@ -73,8 +76,8 @@ # api_budget_emit_calls ... # the hub's api-calls notice for each token, # `=N not-modified=M`: N is the job's own -# calls, M its 304 answers, which GitHub does not -# count; 0 for a token with no reading +# requests, M its 304 answers, which GitHub does +# not count; 0 for a token with no reading # # pr-require-checks.yml's ci-status job carries this file verbatim in its # API_BUDGET_SH env (it has no checkout of this directory); @@ -131,13 +134,13 @@ api_budget_wrap_gh() { for arg; do case $arg in # --paginate prints a header block per page, which could not be told - # from body text that looks like one: left as it is. + # from body text that looks like one: no reading, only its requests. --silent | --slurp | --paginate) api_budget_pass "$@"; return ;; # The caller reads the headers itself: the guard reads them too, and # the output goes on unchanged. -i | --include) out=$(mktemp 2>/dev/null) || { api_budget_pass "$@"; return; } - command gh "$@" >"$out" || rc=$? + api_budget_traced "$out" "$@" || rc=$? api_budget_observe "$out" "$pool" "gh $*" || rc=1 api_budget_read "$API_BUDGET_GH_TOKEN" "$out" >/dev/null cat "$out" @@ -148,8 +151,8 @@ api_budget_wrap_gh() { esac done out=$(mktemp 2>/dev/null) || { api_budget_pass "$@"; return; } - # gh-read-exempt: the wrapper under every call, gh_read included: the same call with -i. - command gh api -i "${@:2}" >"$out" || rc=$? + # The wrapper under every call, gh_read included: the same call with -i. + api_budget_traced "$out" api -i "${@:2}" || rc=$? api_budget_observe "$out" "$pool" "gh $*" || rc=1 api_budget_read "$API_BUDGET_GH_TOKEN" "$out" rm -f "$out" @@ -164,7 +167,7 @@ api_budget_wrap_gh() { api_budget_pass() { local err rc=0 seconds=3600 err=$(mktemp 2>/dev/null) || { command gh "$@"; return; } - command gh "$@" 2>"$err" || rc=$? + api_budget_traced - "$@" 2>"$err" || rc=$? cat "$err" >&2 if ((rc != 0)) && grep -qiE 'rate limit|RATE_LIMITED|abuse detection|\(HTTP 429\)' "$err"; then ! grep -qiE 'secondary rate limit|abuse detection' "$err" || seconds=60 @@ -174,6 +177,50 @@ api_budget_pass() { return "$rc" } +# api_budget_traced : gh with GH_DEBUG=1, stdout to +# (`-`: left as it is). That level logs only head lines per request (`* Request +# at`, `* Request to `, `* Request took`), never headers or bodies, which +# GH_DEBUG=api adds and which no filter could tell from gh's own text. Each +# request to a GitHub API URL (a redirect to a download host is not one) is a +# `request` line in the token's file, less the one an header block +# already gives a reading. Once gh exits, its stderr goes on without what the +# debug level adds: those lines, a `* ` line while a request is open, +# `[git ...]` command lines, and the `lookup ...` line under `error connecting +# to`. Returns gh's status. +api_budget_traced() { + local out=$1 log rc=0 skip=0 nl=0 first state=${RUNNER_TEMP:-}/api-budget/${API_BUDGET_GH_TOKEN:-} + shift + log=$(mktemp 2>/dev/null) || { + if [[ $out == - ]]; then command gh "$@"; else command gh "$@" >"$out"; fi + return + } + if [[ $out == - ]]; then + GH_DEBUG=1 command gh "$@" 2>"$log" || rc=$? + else + GH_DEBUG=1 command gh "$@" >"$out" 2>"$log" || rc=$? + read -r first <"$out" 2>/dev/null + [[ ! ${first:-} =~ ^HTTP/[0-9.]+\ [0-9]{3} ]] || skip=1 + fi + if [[ -z ${RUNNER_TEMP:-} || ! ${API_BUDGET_GH_TOKEN:-} =~ ^[a-z][a-z0-9-]{0,39}$ ]] || ! mkdir -p "${state%/*}" 2>/dev/null; then + state=/dev/null + fi + [[ $(tail -c 1 "$log" | od -An -c) != *'\n'* ]] || nl=1 + awk -v state="$state" -v skip="$skip" -v nl="$nl" ' + /^\* Request at / { open++; next } + /^\* Request took / { if (open) open--; next } + /^\* Request to / { + if ($4 ~ /^https:\/\/((api|uploads)\.github\.com|[^\/]+\/api)\// && ++n > skip) print "request" >>state + next + } + /^\* (Using proxy|Skipping TLS verification): / || (open && /^\* /) || /^\[git[] ]/ { next } + /^lookup / && kept ~ /^error connecting to / { kept = ""; next } + { printf "%s%s", sep, $0; sep = "\n"; kept = $0; last = NR } + END { close(state); if (sep != "" && (nl || last != NR)) printf "\n" } + ' "$log" >&2 + rm -f "$log" + return "$rc" +} + api_budget_pool() { local arg [[ ${1:-} == api ]] || { echo any; return; } diff --git a/.github/actions/log-api-budget/log-api-budget.test.mjs b/.github/actions/log-api-budget/log-api-budget.test.mjs index 3f2fdb1539d..b0c70815612 100644 --- a/.github/actions/log-api-budget/log-api-budget.test.mjs +++ b/.github/actions/log-api-budget/log-api-budget.test.mjs @@ -375,6 +375,127 @@ test("gh guard: a -i call is counted in api-calls, and a 304 as not-modified", ( assert.equal(out.stdout, "::notice title=api-calls::github-token=1 not-modified=1\n"); })); +// A gh that plays $RUNNER_TEMP/script, one ` ` line each: `o` +// stdout, `e` stderr, `n` stderr with no newline, `d` stderr only under +// GH_DEBUG=1, `x` its exit status. The `d` lines are gh 2.103.3's GH_DEBUG=1 +// output, recorded from `gh api --paginate repos//labels?per_page=20` +// (three pages), `gh run list --limit 1` (two git lines, two requests) and a +// refused proxy connect. +function scriptedGh(dir, lines) { + writeFileSync( + join(dir, "gh"), + `#!/usr/bin/env bash +echo "$*" >>"$RUNNER_TEMP/calls" +rc=0 +while IFS= read -r line; do + text=\${line:2} + case \${line:0:1} in + o) printf '%s\\n' "$text" ;; + e) printf '%s\\n' "$text" >&2 ;; + n) printf '%s' "$text" >&2 ;; + d) [[ \${GH_DEBUG:-} != 1 ]] || printf '%s\\n' "$text" >&2 ;; + x) rc=$text ;; + esac +done <"$RUNNER_TEMP/script" +exit "$rc" +`, + ); + chmodSync(join(dir, "gh"), 0o755); + writeFileSync(join(dir, "script"), lines.map((line) => `${line}\n`).join("")); + writeFileSync(join(dir, "calls"), ""); +} + +const request = (url) => [ + "d * Request at 2026-10-28 17:14:16.342958108 +0000 UTC m=+0.118696845", + `d * Request to ${url}`, + "d * Request took 353.479902ms", +]; +const LABELS = "https://api.github.com/repositories/1277265216/labels?per_page=20"; + +// stdout, stderr and status from the same scripted gh, wrapped and bare. +function wrappedAndBare(dir, lines, args) { + scriptedGh(dir, lines); + const path = `${dir}:${process.env.PATH}`; + const wrapped = bash(dir, `api_budget_wrap_gh github-token\ngh ${args}\necho "rc=$?"\napi_budget_emit_calls github-token`, { path }); + rmSync(join(dir, "api-budget"), { recursive: true, force: true }); + const bare = bash(dir, `command gh ${args}\necho "rc=$?"`, { path }); + return { wrapped, bare }; +} + +test("gh guard: a paginated call of three pages counts three requests, with stdout and stderr as gh wrote them", () => + withDir((dir) => { + const { wrapped, bare } = wrappedAndBare( + dir, + [...request("https://api.github.com/repos/o/r/labels?per_page=20"), "o 20", ...request(`${LABELS}&page=2`), "o 20", ...request(`${LABELS}&page=3`), "o 9"], + "api --paginate repos/o/r/labels --jq length", + ); + assert.equal(wrapped.stdout, "20\n20\n9\nrc=0\n::notice title=api-calls::github-token=3 not-modified=0\n"); + assert.equal(bare.stdout, "20\n20\n9\nrc=0\n"); + assert.equal(wrapped.stderr, ""); + // A page line is a request, never a reading: no api-budget notice. + assert.equal(bash(dir, "api_budget_emit github-token").stdout, ""); + })); + +test("gh guard: a call that is not gh api counts its requests and drops the git lines debug adds", () => + withDir((dir) => { + const { wrapped, bare } = wrappedAndBare( + dir, + [ + "d [git remote -v]", + "d [git config --get-regexp ^remote\\..*\\.gh-resolved$]", + ...request("https://api.github.com/repos/o/r/actions/runs?exclude_pull_requests=true&per_page=1"), + ...request("https://api.github.com/repos/o/r/actions/workflows?page=1&per_page=100"), + "o []", + ], + "run list --limit 1 --json databaseId", + ); + assert.equal(wrapped.stdout, "[]\nrc=0\n::notice title=api-calls::github-token=2 not-modified=0\n"); + assert.equal(wrapped.stderr, bare.stderr); + })); + +test("gh guard: a failing call keeps gh's stderr byte for byte and its status", () => + withDir((dir) => { + const { wrapped, bare } = wrappedAndBare( + dir, + [ + "d * Request at 2026-10-28 17:23:22.386063392 +0000 UTC m=+0.074866727", + "d * Request to https://api.github.com/rate_limit", + "d * proxyconnect tcp: dial tcp 127.0.0.1:9: connect: connection refused", + "d * Request took 293.912µs", + 'e Get "https://api.github.com/rate_limit": proxyconnect tcp: dial tcp 127.0.0.1:9: connect: connection refused', + "e error connecting to api.github.com", + "d lookup api.github.com: no such host", + "e check your internet connection or https://githubstatus.com", + "e * a line of gh's own, outside any request", + "e ", + "n gh: Not Found (HTTP 404)", + "x 1", + ], + "pr view 7", + ); + assert.equal(bare.stderr.endsWith("gh: Not Found (HTTP 404)"), true); + assert.equal(wrapped.stderr, bare.stderr); + assert.equal(wrapped.stdout, "rc=1\n::notice title=api-calls::github-token=1 not-modified=0\n"); + })); + +test("gh guard: a header-read call counts each request once, a 304 still as not-modified, and a download host not at all", () => + withDir((dir) => { + const head304 = "o HTTP/2.0 304 Not Modified"; + // One request, read from its header block: one call, not two. + let out = wrappedAndBare(dir, [...request("https://api.github.com/repos/o/r"), head304, "o ", "x 1"], 'api -i -H "If-None-Match: x" repos/o/r').wrapped; + assert.equal(out.stdout.split("\n").at(-2), "::notice title=api-calls::github-token=0 not-modified=1"); + // A redirect the header block does not show is a second request. + out = wrappedAndBare(dir, [...request("https://api.github.com/repos/o/old"), ...request("https://api.github.com/repositories/1"), "o HTTP/2.0 200 OK", "o ", "o {}"], "api repos/o/old").wrapped; + assert.equal(out.stdout, "{}\nrc=0\n::notice title=api-calls::github-token=2 not-modified=0\n"); + // A download redirect leaves GitHub's API, so it spends nothing there. + out = wrappedAndBare( + dir, + [...request("https://api.github.com/repos/o/r/actions/runs/1/logs"), ...request("https://results-receiver.actions.githubusercontent.com/x")], + "run view 1 --log", + ).wrapped; + assert.equal(out.stdout, "rc=0\n::notice title=api-calls::github-token=1 not-modified=0\n"); + })); + test("gh guard: a stop-file line whose reset is not a number stops nothing", () => withDir((dir) => { mkdirSync(join(dir, "api-budget"), { recursive: true }); diff --git a/.github/workflows/pr-require-checks.yml b/.github/workflows/pr-require-checks.yml index 05e2e23ede2..1e0215e8701 100644 --- a/.github/workflows/pr-require-checks.yml +++ b/.github/workflows/pr-require-checks.yml @@ -3301,8 +3301,10 @@ jobs: # is one line in $RUNNER_TEMP/api-budget/: # # (`na` for a missing value). api-budget.mjs and babysit_gh.py append the same - # lines. Never fails the caller, except that a stop the rate guard below - # cannot record ends the step. + # lines. A request the gh wrapper counts with no header block to read (each + # page of --paginate, a call that is not `gh api`) is a line `request`. Never + # fails the caller, except that a stop the rate guard below cannot record ends + # the step. # # api_budget_read # gh api -i output: the header block at the start @@ -3312,7 +3314,8 @@ jobs: # api_budget_read, keeping stdout, stderr and the # exit status as they were (not --paginate, whose # per-page header blocks are left out), behind - # the rate guard below + # the rate guard below; every gh call also counts + # each request it sends (api_budget_traced) # # The rate guard, rate-guard.mjs's shell port: once a response shows a pool # exhausted, no gh call goes to that pool before its reset for the rest of the @@ -3369,8 +3372,8 @@ jobs: # api_budget_emit_calls ... # the hub's api-calls notice for each token, # `=N not-modified=M`: N is the job's own - # calls, M its 304 answers, which GitHub does not - # count; 0 for a token with no reading + # requests, M its 304 answers, which GitHub does + # not count; 0 for a token with no reading # # pr-require-checks.yml's ci-status job carries this file verbatim in its # API_BUDGET_SH env (it has no checkout of this directory); @@ -3427,13 +3430,13 @@ jobs: for arg; do case $arg in # --paginate prints a header block per page, which could not be told - # from body text that looks like one: left as it is. + # from body text that looks like one: no reading, only its requests. --silent | --slurp | --paginate) api_budget_pass "$@"; return ;; # The caller reads the headers itself: the guard reads them too, and # the output goes on unchanged. -i | --include) out=$(mktemp 2>/dev/null) || { api_budget_pass "$@"; return; } - command gh "$@" >"$out" || rc=$? + api_budget_traced "$out" "$@" || rc=$? api_budget_observe "$out" "$pool" "gh $*" || rc=1 api_budget_read "$API_BUDGET_GH_TOKEN" "$out" >/dev/null cat "$out" @@ -3444,8 +3447,8 @@ jobs: esac done out=$(mktemp 2>/dev/null) || { api_budget_pass "$@"; return; } - # gh-read-exempt: the wrapper under every call, gh_read included: the same call with -i. - command gh api -i "${@:2}" >"$out" || rc=$? + # The wrapper under every call, gh_read included: the same call with -i. + api_budget_traced "$out" api -i "${@:2}" || rc=$? api_budget_observe "$out" "$pool" "gh $*" || rc=1 api_budget_read "$API_BUDGET_GH_TOKEN" "$out" rm -f "$out" @@ -3460,7 +3463,7 @@ jobs: api_budget_pass() { local err rc=0 seconds=3600 err=$(mktemp 2>/dev/null) || { command gh "$@"; return; } - command gh "$@" 2>"$err" || rc=$? + api_budget_traced - "$@" 2>"$err" || rc=$? cat "$err" >&2 if ((rc != 0)) && grep -qiE 'rate limit|RATE_LIMITED|abuse detection|\(HTTP 429\)' "$err"; then ! grep -qiE 'secondary rate limit|abuse detection' "$err" || seconds=60 @@ -3470,6 +3473,50 @@ jobs: return "$rc" } + # api_budget_traced : gh with GH_DEBUG=1, stdout to + # (`-`: left as it is). That level logs only head lines per request (`* Request + # at`, `* Request to `, `* Request took`), never headers or bodies, which + # GH_DEBUG=api adds and which no filter could tell from gh's own text. Each + # request to a GitHub API URL (a redirect to a download host is not one) is a + # `request` line in the token's file, less the one an header block + # already gives a reading. Once gh exits, its stderr goes on without what the + # debug level adds: those lines, a `* ` line while a request is open, + # `[git ...]` command lines, and the `lookup ...` line under `error connecting + # to`. Returns gh's status. + api_budget_traced() { + local out=$1 log rc=0 skip=0 nl=0 first state=${RUNNER_TEMP:-}/api-budget/${API_BUDGET_GH_TOKEN:-} + shift + log=$(mktemp 2>/dev/null) || { + if [[ $out == - ]]; then command gh "$@"; else command gh "$@" >"$out"; fi + return + } + if [[ $out == - ]]; then + GH_DEBUG=1 command gh "$@" 2>"$log" || rc=$? + else + GH_DEBUG=1 command gh "$@" >"$out" 2>"$log" || rc=$? + read -r first <"$out" 2>/dev/null + [[ ! ${first:-} =~ ^HTTP/[0-9.]+\ [0-9]{3} ]] || skip=1 + fi + if [[ -z ${RUNNER_TEMP:-} || ! ${API_BUDGET_GH_TOKEN:-} =~ ^[a-z][a-z0-9-]{0,39}$ ]] || ! mkdir -p "${state%/*}" 2>/dev/null; then + state=/dev/null + fi + [[ $(tail -c 1 "$log" | od -An -c) != *'\n'* ]] || nl=1 + awk -v state="$state" -v skip="$skip" -v nl="$nl" ' + /^\* Request at / { open++; next } + /^\* Request took / { if (open) open--; next } + /^\* Request to / { + if ($4 ~ /^https:\/\/((api|uploads)\.github\.com|[^\/]+\/api)\// && ++n > skip) print "request" >>state + next + } + /^\* (Using proxy|Skipping TLS verification): / || (open && /^\* /) || /^\[git[] ]/ { next } + /^lookup / && kept ~ /^error connecting to / { kept = ""; next } + { printf "%s%s", sep, $0; sep = "\n"; kept = $0; last = NR } + END { close(state); if (sep != "" && (nl || last != NR)) printf "\n" } + ' "$log" >&2 + rm -f "$log" + return "$rc" + } + api_budget_pool() { local arg [[ ${1:-} == api ]] || { echo any; return; }