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; }