Diagnostic GitHub API
A GraphQL query times out at 10s and is charged anyway
The nightly job started failing with a 502 about ten seconds into a query that used to take four. The retry logic did the obvious thing and sent it again, three times, with backoff, exactly as it should for a gateway error. By the time somebody looked, the run had produced nothing at all and the hourly point budget was several hundred lighter than a run that produced nothing has any business being.
GitHub terminates a GraphQL request that takes longer than roughly ten seconds and returns a 502 or 504 with a message about not being able to respond in time. It also deducts additional points from the primary rate limit as a penalty, on top of what the query would have cost. So a timed-out query is charged more than a successful one and gives you nothing back.
That makes a blind retry the worst possible response. The same document against the same data will take the same time, hit the same cutoff and pay the same penalty, so three retries is three charges for zero rows. Measure it once by reading resources.graphql.used from GET /rate_limit either side of the call — that endpoint is free — then make the query smaller instead: fewer nested connections and lower first values, paginated.
The problem in plain words
Everything about this failure is dressed as something else. A 502 is a gateway error, and every piece of retry advice ever written says a gateway error is transient and should be retried with backoff. The client is doing what it was told. The one thing that makes this case different — that the request was killed deliberately, for taking too long, and that the cause is entirely inside your own query — is not visible in the status code at all.
It also arrives without a code change. The query that times out today ran in four seconds last month, against the same organisation, with the same shape. What grew was the data underneath it: more repositories, more open pull requests, more comments on the ones that matter. There is nothing to bisect and nothing in a diff, which sends people to GitHub's status page and then to their own network before anybody looks at the query.
Then the budget goes missing and nobody connects the two. Points disappear from a bucket that is shared by every process using that token, during a run that returned no data, so the natural conclusion is that something else on the token is spending them. The idea that a failed call costs more than a successful one is not most people's mental model of an API, and until somebody measures it, the arithmetic never quite adds up.
Why it happens
Ten seconds is a server-side cutoff, not your client's timeout. GitHub stops executing a GraphQL request that runs past its limit and returns an error rather than a partial result. Raising your own HTTP timeout does nothing whatsoever; the connection is not the constraint. The only lever is how much work the document asks for.
The penalty is documented and it is on top of the normal cost. GitHub says explicitly that it deducts additional points from the primary rate limit for queries that time out. That inverts the usual assumption that a failed call is a free call, and it is what makes the retry loop expensive rather than merely useless.
Retrying reproduces it exactly. Nothing about the query changes between attempts, and neither does the data, so the second attempt takes as long as the first and dies in the same place. This is the same reasoning as for a query rejected for its node count, with one difference that matters here: a node-limit rejection is free, and this one is charged every time round.
The measurement is free, and it is a subtraction. GET /rate_limit reports resources.graphql.used and is documented not to consume quota, so reading it immediately before and immediately after the failing call gives you what that call cost. If the delta is larger than the query's normal cost, you have measured the penalty directly rather than believing a document about it.
The bucket is shared, so the subtraction has a caveat and the script states it. Every process holding that token draws on the same budget, and the API never says which one spent what. This script takes two readings with nothing sent between them first: if the bucket moves during that gap, something else is spending and the measurement that follows cannot be attributed. That is reported as a contaminated result rather than quietly presented as a number.
Time is the symptom; the query is the cause. A query at eight seconds is not healthy, it is one busy repository away from this note. The script reports elapsed time against the cutoff even on a successful call, because the interesting moment is before the failure rather than after it, and a query using eighty per cent of the budget is a finding on its own.
The fix, as a flow
The instrument is a subtraction over a free endpoint, and most of the code exists to stop it lying. GET /rate_limit is read twice with nothing sent in between, so a bucket already draining under another process is caught before it can be mistaken for a penalty, and then again either side of one attempt. A reset timestamp that moves between readings voids the measurement rather than producing a negative number. The query is sent exactly once and never retried, because retrying is the behaviour the note exists to stop, and the cost of the retries somebody would have made is printed instead.
How to fix it
Take two free readings with nothing in between
GET /rate_limit does not consume quota, so reading resources.graphql.used twice back to back costs nothing and answers a question that has to be answered first: is anything else spending from this token right now. If the bucket moves while nothing is being sent, every later subtraction is contaminated and the script says so instead of reporting a number.
Send the query once, with a clock on it
One attempt, timed. What comes back is either a result with an elapsed time worth knowing or a 502 or 504 at around ten seconds with a message about not responding in time. The script never retries, on purpose: retrying is the behaviour this note exists to stop.
Read the bucket again and subtract
The difference in used is what that one call cost. If the reset timestamp moved between readings the window rolled over and the measurement is void, which the script detects rather than reporting a nonsense number.
Compare the charge against what the query normally costs
Pass the query's normal cost with --normal-cost; measuring it is what the cost note is for. Anything charged above that on a call that returned nothing is the penalty, stated as a number. That is the sentence that changes a retry policy.
Make the query smaller, and read the clock even when it passes
Fewer nested connections, lower first values, and paginate what you shrank. The script also reports how much of the ten seconds a successful call used, because a query at eight seconds is not a healthy query — it is this failure waiting for the busiest repository in the organisation to get one more pull request.
How to check it worked
The penalty stops being a rumour once it is a subtraction, and the retry projection prices the loop that made it worse.
GITHUB_TOKEN=$READ_ONLY_TOKEN python3 github_graphql_timeout.py \
--login acme --normal-cost 12 --retries 3
# point cost: up to 1 point(s) for the query plus whatever the timeout penalty
# adds, which is the number this run measures. Both /rate_limit reads are free.
# idle check: graphql used 1204 -> 1204 with nothing sent, so the bucket is quiet
# sending one query. This script never retries a timed-out query.
# HTTP 502 after 10.4s: "Something went wrong while executing your query. This
# may be the result of a timeout"
# graphql used 1204 -> 1225, so this call was charged 21 point(s)
# timed-out-and-charged-extra: the query was killed at the 10s cutoff and cost
# 21 point(s) against a normal cost of 12, a penalty of 9 point(s)
# 3 retries of this document would spend 63 more point(s) and return nothing
# repair: lower the first values and split the nested connections. Do not retry
# a timed-out query: the same document reproduces the timeout and the penalty.The full code
The instrument is a subtraction over a free endpoint, and almost all of the code is about not lying with it. GET /rate_limit is read twice with nothing in between to establish that the bucket is quiet, then either side of the single attempt; a reset timestamp that moves between readings voids the measurement rather than producing a negative number, and a bucket that moves while nothing is being sent marks the result unattributable. The query is sent exactly once and never retried, and as everywhere in this section the document is parsed and refused before a socket opens if it contains a mutation or a subscription.
"""Measure what a timed-out GraphQL query is charged, without retrying it.
Read only, and queries only. GitHub's GraphQL endpoint takes a document in the
request body, so a read is carried by POST there just as a write would be; that
is transport, not intent. This script sends queries and refuses any document
containing a mutation or a subscription before it opens a socket. Nothing is
written and the repair is printed rather than performed.
GitHub kills a GraphQL request that runs past roughly ten seconds and returns a
502 or 504, and it deducts additional points from the primary rate limit as a
penalty. A timed-out query therefore costs more than a successful one and
returns nothing, which makes a blind retry the most expensive possible response:
the same document against the same data reproduces the timeout and the charge.
What this can and cannot see: GET /rate_limit is free and reports
resources.graphql.used, so the cost of one call is a subtraction. The bucket is
shared by every process holding the token and the API never says which one spent
what, so this script first reads the bucket twice with nothing in between. If it
moves during that gap the measurement is reported as unattributable rather than
as a number.
Environment:
GITHUB_TOKEN a token with read access to the GraphQL API
"""
import argparse
import json
import logging
import os
import sys
import time
from pathlib import Path
import requests
logging.basicConfig(level=logging.INFO, format="%(asctime)s %(levelname)s %(message)s")
log = logging.getLogger("github_graphql_timeout")
API = "https://api.github.com"
UA = "github-graphql-timeout/1.0"
# The server-side cutoff. Raising the client's own timeout does nothing at all:
# the connection was never the constraint.
TIMEOUT_SECONDS = 10
POINTS_PER_QUERY = 1
# A call using this much of the cutoff is not healthy, it is one busy repository
# away from failing, so it is reported as a finding on a successful run.
NEAR_LIMIT = 0.7
# Substrings GitHub uses when it kills a query for time. Matched case
# insensitively and alongside the status code rather than instead of it.
TIMEOUT_MARKERS = (
"timeout",
"timed out",
"took too long",
"respond in time",
"responding in time",
)
# Deliberately heavy: three connections deep with wide slices, which is the
# shape that runs past the cutoff long before it approaches the node limit.
DEFAULT_QUERY = (
"query($login: String!, $repos: Int = 100, $prs: Int = 40) {"
" repositoryOwner(login: $login) {"
" repositories(first: $repos, orderBy: {field: PUSHED_AT, direction: DESC}) {"
" nodes { name pullRequests(first: $prs, states: OPEN) {"
" nodes { number title comments(first: 20) { totalCount nodes { createdAt } } }"
" } } } } }"
)
def strip_noise(document):
"""Remove GraphQL comments and string literals from a document. Pure."""
src = str(document or "")
out = []
i, n = 0, len(src)
while i < n:
ch = src[i]
if ch == "#":
while i < n and src[i] != "\n":
i += 1
continue
if src.startswith('"""', i):
j = src.find('"""', i + 3)
i = n if j < 0 else j + 3
out.append(" ")
continue
if ch == '"':
i += 1
while i < n and src[i] != '"':
i += 2 if src[i] == "\\" else 1
i += 1
out.append(" ")
continue
out.append(ch)
i += 1
return "".join(out)
def operations(document):
"""The top-level operations in a document, in order. Pure."""
src = strip_noise(document)
ops, depth, word, declared = [], 0, "", None
for ch in src + " ":
if ch.isalnum() or ch == "_":
word += ch
continue
if word:
if depth == 0 and word in ("query", "mutation", "subscription", "fragment"):
declared = word
word = ""
if ch == "{":
if depth == 0:
ops.append(declared or "query")
declared = None
depth += 1
elif ch == "}":
depth = max(0, depth - 1)
return ops
def refusal(document):
"""Why this document will not be sent, or None if it is a read. Pure."""
ops = operations(document)
if not ops:
return "the document contains no operation to send."
for kind in ("mutation", "subscription"):
if kind in ops:
return ("the document contains a %s. This script sends queries only: "
"a query is a read, and the section it belongs to promises "
"its scripts never write." % kind)
return None
def bucket_reading(payload, name="graphql"):
"""One bucket out of a GET /rate_limit body. Pure.
The GraphQL bucket, not the core one. Reading the wrong bucket here would
produce a measurement that never moves and a note that concludes there is no
penalty.
"""
if not isinstance(payload, dict):
return None
resources = payload.get("resources")
if not isinstance(resources, dict):
return None
bucket = resources.get(name)
if not isinstance(bucket, dict):
return None
return {"limit": bucket.get("limit"), "used": bucket.get("used"),
"remaining": bucket.get("remaining"), "reset": bucket.get("reset")}
def charged(before, after):
"""Points spent between two readings. Pure. Returns (points, state).
A reset timestamp that moved means the hourly window rolled over between the
readings and the subtraction is meaningless, which is worth detecting rather
than reporting as a negative number or as zero.
"""
if not isinstance(before, dict) or not isinstance(after, dict):
return (None, "unreadable")
if before.get("reset") != after.get("reset"):
return (None, "window-reset")
start, end = before.get("used"), after.get("used")
if not isinstance(start, int) or not isinstance(end, int):
return (None, "unreadable")
if end < start:
return (None, "window-reset")
return (end - start, "measured")
def net_charge(delta, background):
"""The charge with a known background drain removed. Pure."""
if not isinstance(delta, int):
return None
if not isinstance(background, int) or background <= 0:
return delta
return max(0, delta - background)
def timeout_message(body):
"""The message GitHub returned, or None. Pure."""
if not isinstance(body, dict):
return None
errors = body.get("errors")
if isinstance(errors, list):
for err in errors:
if isinstance(err, dict) and err.get("message"):
return str(err["message"])
if body.get("message"):
return str(body["message"])
return None
def looks_like_timeout(status, body):
"""Whether this response is the server giving up on time. Pure."""
if status in (502, 504):
return True
message = (timeout_message(body) or "").lower()
return any(marker in message for marker in TIMEOUT_MARKERS)
def timing_consistent(elapsed):
"""Whether the elapsed time agrees with the documented cutoff. Pure."""
if not isinstance(elapsed, (int, float)):
return False
return elapsed >= TIMEOUT_SECONDS * 0.8
def headroom(elapsed):
"""How much of the cutoff this call used, as a fraction. Pure."""
if not isinstance(elapsed, (int, float)) or elapsed < 0:
return None
return elapsed / float(TIMEOUT_SECONDS)
def penalty(points, normal_cost):
"""Points charged above what the query would have cost. Pure."""
if not isinstance(points, int) or not isinstance(normal_cost, int):
return None
return points - normal_cost
def retry_projection(points, retries):
"""What retrying this document would spend for nothing. Pure."""
if not isinstance(points, int) or not retries or retries < 1:
return 0
return points * int(retries)
def classify(status, elapsed, points, normal_cost, background=0, body=None):
"""Classify one attempt. Pure. Returns (state, detail)."""
timed_out = looks_like_timeout(status, body)
if points is None:
return ("charge-not-measurable",
"the two rate-limit readings do not support a subtraction, so "
"what this call cost cannot be stated%s."
% (" -- and it did time out" if timed_out else ""))
if timed_out and isinstance(background, int) and background > 0:
return ("timed-out-charge-not-attributable",
"the query was killed and %d point(s) moved, but the bucket was "
"already draining with nothing sent, so the charge belongs to "
"more than this call." % points)
extra = penalty(points, normal_cost)
if timed_out and isinstance(extra, int) and extra > 0:
return ("timed-out-and-charged-extra",
"the query was killed at the %ds cutoff and cost %d point(s) "
"against a normal cost of %d, a penalty of %d point(s)."
% (TIMEOUT_SECONDS, points, normal_cost, extra))
if timed_out:
return ("timed-out-charge-not-proved",
"the query was killed at the %ds cutoff and the bucket moved by "
"%d point(s), which is not more than its normal cost. The "
"timeout is real; the penalty is not demonstrated by this run."
% (TIMEOUT_SECONDS, points))
fraction = headroom(elapsed)
if fraction is not None and fraction >= NEAR_LIMIT:
return ("close-to-the-timeout",
"the query returned, in %.1fs, which is %d%% of the %ds cutoff. "
"This one is one busy repository away from the failure above."
% (elapsed, round(fraction * 100), TIMEOUT_SECONDS))
return ("completed-inside-the-limit",
"the query returned in %.1fs and was charged %d point(s), which is "
"the ordinary case." % (elapsed or 0.0, points))
def repair(state):
"""The sentence a reader has to act on. Pure."""
if state == "timed-out-and-charged-extra":
return ("lower the first values and split the nested connections. Do "
"not retry a timed-out query: the same document reproduces the "
"timeout and the penalty.")
if state == "timed-out-charge-not-proved":
return ("make the query smaller anyway. The timeout is the finding; "
"whether this particular run demonstrated the extra charge does "
"not change the repair.")
if state == "timed-out-charge-not-attributable":
return ("re-run this when nothing else is holding the token, or give "
"the job its own token. A shared bucket cannot attribute a "
"charge to a call.")
if state == "charge-not-measurable":
return ("re-run it away from the top of the hour, when the window is "
"less likely to reset between the two readings.")
if state == "close-to-the-timeout":
return ("shrink it now rather than after the outage. Fewer nested "
"connections and lower first values, paginated.")
if state == "completed-inside-the-limit":
return ("nothing here. Keep the elapsed time in your logs so the day it "
"starts climbing is visible before the day it fails.")
return "point the check at a document this endpoint can answer."
def point_cost(queries):
"""Points this run will spend before any penalty. Pure."""
return int(queries or 0) * POINTS_PER_QUERY
def read_bucket(session):
"""GET /rate_limit, which is free and does not consume quota."""
r = session.get(API + "/rate_limit", timeout=30)
if r.status_code == 401:
raise SystemExit("401 from GitHub: GITHUB_TOKEN is missing, malformed "
"or revoked")
try:
return bucket_reading(r.json())
except ValueError:
return None
def run_query(session, document, variables):
"""Send one query, once. Returns (status, body-or-None, elapsed).
A GraphQL query is a read; POST is only how the document reaches the
endpoint, which is why the verb is written here beside the URL rather than
tucked into a constant where it could be mistaken for a write path. There is
no retry here by design: retrying is the behaviour this script exists to
stop.
"""
started = time.monotonic()
r = session.post(API + "/graphql",
json={"query": document, "variables": variables or {}},
timeout=60)
elapsed = time.monotonic() - started
if r.status_code == 401:
raise SystemExit("401 from GitHub: GITHUB_TOKEN is missing, malformed "
"or revoked")
try:
return r.status_code, r.json(), elapsed
except ValueError:
return r.status_code, {"message": r.text[:300]}, elapsed
def main():
ap = argparse.ArgumentParser(description=__doc__)
ap.add_argument("--login", help="user or organisation for the default query")
ap.add_argument("--file", help="a .graphql file to send instead")
ap.add_argument("--query", help="the document as a string")
ap.add_argument("--variables", default="{}", help="JSON object of variables")
ap.add_argument("--normal-cost", type=int, default=1,
help="what this query costs when it finishes. Measure it "
"with the cost note rather than guessing.")
ap.add_argument("--retries", type=int, default=3,
help="how many retries to price. Nothing is retried.")
args = ap.parse_args()
document = Path(args.file).read_text(encoding="utf-8") if args.file \
else (args.query or DEFAULT_QUERY)
try:
variables = json.loads(args.variables)
except ValueError:
log.error("--variables takes a JSON object")
return 2
if not isinstance(variables, dict):
log.error("--variables takes a JSON object")
return 2
if not args.file and not args.query:
if not args.login:
log.error("--login takes a user or organisation name")
return 2
variables.setdefault("login", args.login)
why_not = refusal(document)
if why_not:
log.error("refusing to send: %s", why_not)
return 2
token = os.environ.get("GITHUB_TOKEN")
if not token:
log.error("set GITHUB_TOKEN (a read-only token is enough)")
return 2
session = requests.Session()
session.headers.update({
"Authorization": "Bearer " + token,
"Accept": "application/vnd.github+json",
# GitHub rejects requests with no User-Agent outright.
"User-Agent": UA,
})
log.info("point cost: up to %d point(s) for the query plus whatever the "
"timeout penalty adds, which is the number this run measures. Both "
"/rate_limit reads are free.", point_cost(1))
idle_before = read_bucket(session)
idle_after = read_bucket(session)
background, idle_state = charged(idle_before, idle_after)
if idle_state == "measured":
log.info("idle check: graphql used %s -> %s with nothing sent, so the "
"bucket is %s", idle_before.get("used"), idle_after.get("used"),
"quiet" if background == 0 else "already draining")
else:
log.info("idle check: %s, so the background drain is unknown", idle_state)
background = 0
log.info("sending one query. This script never retries a timed-out query.")
before = idle_after
status, body, elapsed = run_query(session, document, variables)
after = read_bucket(session)
message = timeout_message(body)
log.info("HTTP %s after %.1fs%s", status, elapsed,
": %s" % message[:160] if message else "")
delta, state_of_charge = charged(before, after)
points = net_charge(delta, background)
if state_of_charge == "measured":
log.info("graphql used %s -> %s, so this call was charged %s point(s)",
before.get("used"), after.get("used"), points)
else:
log.info("the charge could not be measured: %s", state_of_charge)
state, detail = classify(status, elapsed, points, args.normal_cost,
background, body)
log.info("%s: %s", state, detail)
if timing_consistent(elapsed) and looks_like_timeout(status, body):
log.info("the elapsed time agrees with the documented %ds cutoff",
TIMEOUT_SECONDS)
projected = retry_projection(points, args.retries)
if projected and state.startswith("timed-out"):
log.info("%d retries of this document would spend %d more point(s) and "
"return nothing", args.retries, projected)
log.info("repair: %s", repair(state))
print(json.dumps({"status": status, "elapsed_seconds": round(elapsed, 2),
"headroom": headroom(elapsed), "charged": points,
"background_drain": background,
"normal_cost": args.normal_cost,
"penalty": penalty(points, args.normal_cost),
"retry_cost": projected, "state": state,
"detail": detail}, indent=2, default=str))
return 1 if state.startswith("timed-out") or state == "close-to-the-timeout" else 0
if __name__ == "__main__":
sys.exit(main())
/**
* Measure what a timed-out GraphQL query is charged, without retrying it.
*
* Read only, and queries only. GitHub's GraphQL endpoint takes a document in
* the request body, so a read is carried by POST there just as a write would
* be; that is transport, not intent. Any document containing a mutation or a
* subscription is refused before a socket opens, and nothing is ever retried.
*
* Environment:
* GITHUB_TOKEN a token with read access to the GraphQL API
* GITHUB_LOGIN user or organisation for the default query
* GITHUB_QUERY the document as a string
* GITHUB_VARIABLES JSON object of variables
* GITHUB_NORMAL_COST what this query costs when it finishes
* GITHUB_RETRIES how many retries to price. Nothing is retried.
*/
const API = 'https://api.github.com';
const UA = 'github-graphql-timeout/1.0';
/** The server-side cutoff. A longer client timeout changes nothing. */
export const TIMEOUT_SECONDS = 10;
export const POINTS_PER_QUERY = 1;
/** A call using this much of the cutoff is a finding on a successful run. */
export const NEAR_LIMIT = 0.7;
/** Substrings GitHub uses when it kills a query for time. */
export const TIMEOUT_MARKERS = [
'timeout', 'timed out', 'took too long', 'respond in time', 'responding in time',
];
const DEFAULT_QUERY = 'query($login: String!, $repos: Int = 100, $prs: Int = 40) {'
+ ' repositoryOwner(login: $login) {'
+ ' repositories(first: $repos, orderBy: {field: PUSHED_AT, direction: DESC}) {'
+ ' nodes { name pullRequests(first: $prs, states: OPEN) {'
+ ' nodes { number title comments(first: 20) { totalCount nodes { createdAt } } }'
+ ' } } } } }';
/** Remove GraphQL comments and string literals from a document. Pure. */
export function stripNoise(document) {
const src = String(document ?? '');
const out = [];
let i = 0;
while (i < src.length) {
const ch = src[i];
if (ch === '#') {
while (i < src.length && src[i] !== '\n') i += 1;
continue;
}
if (src.startsWith('"""', i)) {
const j = src.indexOf('"""', i + 3);
i = j < 0 ? src.length : j + 3;
out.push(' ');
continue;
}
if (ch === '"') {
i += 1;
while (i < src.length && src[i] !== '"') i += src[i] === '\\' ? 2 : 1;
i += 1;
out.push(' ');
continue;
}
out.push(ch);
i += 1;
}
return out.join('');
}
/** The top-level operations in a document, in order. Pure. */
export function operations(document) {
const src = `${stripNoise(document)} `;
const ops = [];
let depth = 0;
let word = '';
let declared = null;
for (const ch of src) {
if (/[A-Za-z0-9_]/.test(ch)) { word += ch; continue; }
if (word) {
if (depth === 0 && ['query', 'mutation', 'subscription', 'fragment'].includes(word)) {
declared = word;
}
word = '';
}
if (ch === '{') {
if (depth === 0) { ops.push(declared || 'query'); declared = null; }
depth += 1;
} else if (ch === '}') {
depth = Math.max(0, depth - 1);
}
}
return ops;
}
/** Why this document will not be sent, or null if it is a read. Pure. */
export function refusal(document) {
const ops = operations(document);
if (ops.length === 0) return 'the document contains no operation to send.';
for (const kind of ['mutation', 'subscription']) {
if (ops.includes(kind)) {
return `the document contains a ${kind}. This script sends queries only: `
+ 'a query is a read, and the section it belongs to promises its '
+ 'scripts never write.';
}
}
return null;
}
/** One bucket out of a GET /rate_limit body. Pure. */
export function bucketReading(payload, name = 'graphql') {
if (!payload || typeof payload !== 'object') return null;
const resources = payload.resources;
if (!resources || typeof resources !== 'object') return null;
const bucket = resources[name];
if (!bucket || typeof bucket !== 'object') return null;
return {
limit: bucket.limit, used: bucket.used, remaining: bucket.remaining, reset: bucket.reset,
};
}
/** Points spent between two readings. Pure. Returns [points, state]. */
export function charged(before, after) {
if (!before || typeof before !== 'object' || !after || typeof after !== 'object') {
return [null, 'unreadable'];
}
if (before.reset !== after.reset) return [null, 'window-reset'];
if (!Number.isInteger(before.used) || !Number.isInteger(after.used)) {
return [null, 'unreadable'];
}
if (after.used < before.used) return [null, 'window-reset'];
return [after.used - before.used, 'measured'];
}
/** The charge with a known background drain removed. Pure. */
export function netCharge(delta, background) {
if (!Number.isInteger(delta)) return null;
if (!Number.isInteger(background) || background <= 0) return delta;
return Math.max(0, delta - background);
}
/** The message GitHub returned, or null. Pure. */
export function timeoutMessage(body) {
if (!body || typeof body !== 'object') return null;
if (Array.isArray(body.errors)) {
for (const err of body.errors) {
if (err && typeof err === 'object' && err.message) return String(err.message);
}
}
if (body.message) return String(body.message);
return null;
}
/** Whether this response is the server giving up on time. Pure. */
export function looksLikeTimeout(status, body) {
if (status === 502 || status === 504) return true;
const message = (timeoutMessage(body) || '').toLowerCase();
return TIMEOUT_MARKERS.some((marker) => message.includes(marker));
}
/** Whether the elapsed time agrees with the documented cutoff. Pure. */
export function timingConsistent(elapsed) {
if (typeof elapsed !== 'number' || Number.isNaN(elapsed)) return false;
return elapsed >= TIMEOUT_SECONDS * 0.8;
}
/** How much of the cutoff this call used, as a fraction. Pure. */
export function headroom(elapsed) {
if (typeof elapsed !== 'number' || Number.isNaN(elapsed) || elapsed < 0) return null;
return elapsed / TIMEOUT_SECONDS;
}
/** Points charged above what the query would have cost. Pure. */
export function penalty(points, normalCost) {
if (!Number.isInteger(points) || !Number.isInteger(normalCost)) return null;
return points - normalCost;
}
/** What retrying this document would spend for nothing. Pure. */
export function retryProjection(points, retries) {
if (!Number.isInteger(points) || !retries || retries < 1) return 0;
return points * Number(retries);
}
/** Classify one attempt. Pure. Returns [state, detail]. */
export function classify(status, elapsed, points, normalCost, background = 0, body = null) {
const timedOut = looksLikeTimeout(status, body);
if (points === null || points === undefined) {
return ['charge-not-measurable', 'the two rate-limit readings do not support '
+ 'a subtraction, so what this call cost cannot be stated'
+ `${timedOut ? ' -- and it did time out' : ''}.`];
}
if (timedOut && Number.isInteger(background) && background > 0) {
return ['timed-out-charge-not-attributable',
`the query was killed and ${points} point(s) moved, but the bucket was `
+ 'already draining with nothing sent, so the charge belongs to more than '
+ 'this call.'];
}
const extra = penalty(points, normalCost);
if (timedOut && Number.isInteger(extra) && extra > 0) {
return ['timed-out-and-charged-extra',
`the query was killed at the ${TIMEOUT_SECONDS}s cutoff and cost ${points} `
+ `point(s) against a normal cost of ${normalCost}, a penalty of ${extra} point(s).`];
}
if (timedOut) {
return ['timed-out-charge-not-proved',
`the query was killed at the ${TIMEOUT_SECONDS}s cutoff and the bucket `
+ `moved by ${points} point(s), which is not more than its normal cost. `
+ 'The timeout is real; the penalty is not demonstrated by this run.'];
}
const fraction = headroom(elapsed);
if (fraction !== null && fraction >= NEAR_LIMIT) {
return ['close-to-the-timeout',
`the query returned, in ${elapsed.toFixed(1)}s, which is `
+ `${Math.round(fraction * 100)}% of the ${TIMEOUT_SECONDS}s cutoff. This `
+ 'one is one busy repository away from the failure above.'];
}
return ['completed-inside-the-limit',
`the query returned in ${(elapsed || 0).toFixed(1)}s and was charged `
+ `${points} point(s), which is the ordinary case.`];
}
/** The sentence a reader has to act on. Pure. */
export function repair(state) {
if (state === 'timed-out-and-charged-extra') {
return 'lower the first values and split the nested connections. Do not '
+ 'retry a timed-out query: the same document reproduces the timeout and '
+ 'the penalty.';
}
if (state === 'timed-out-charge-not-proved') {
return 'make the query smaller anyway. The timeout is the finding; whether '
+ 'this particular run demonstrated the extra charge does not change the '
+ 'repair.';
}
if (state === 'timed-out-charge-not-attributable') {
return 're-run this when nothing else is holding the token, or give the job '
+ 'its own token. A shared bucket cannot attribute a charge to a call.';
}
if (state === 'charge-not-measurable') {
return 're-run it away from the top of the hour, when the window is less '
+ 'likely to reset between the two readings.';
}
if (state === 'close-to-the-timeout') {
return 'shrink it now rather than after the outage. Fewer nested '
+ 'connections and lower first values, paginated.';
}
if (state === 'completed-inside-the-limit') {
return 'nothing here. Keep the elapsed time in your logs so the day it '
+ 'starts climbing is visible before the day it fails.';
}
return 'point the check at a document this endpoint can answer.';
}
/** Points this run will spend before any penalty. Pure. */
export function pointCost(queries) {
return Number(queries || 0) * POINTS_PER_QUERY;
}
function headers(token) {
return {
Authorization: `Bearer ${token}`,
Accept: 'application/vnd.github+json',
'Content-Type': 'application/json',
'User-Agent': UA,
};
}
async function readBucket(token) {
const res = await fetch(`${API}/rate_limit`, { headers: headers(token) });
if (res.status === 401) throw new Error('401 from GitHub: GITHUB_TOKEN is missing or revoked');
try { return bucketReading(await res.json()); } catch { return null; }
}
async function runQuery(token, document, variables) {
const started = Date.now();
const res = await fetch(`${API}/graphql`, {
// A GraphQL query is a read. POST is only how the document reaches the
// endpoint, and refusal() has already rejected anything that is not a read.
method: 'POST',
headers: headers(token),
body: JSON.stringify({ query: document, variables: variables || {} }),
});
const elapsed = (Date.now() - started) / 1000;
let body = null;
try { body = await res.json(); } catch { body = { message: 'no JSON body' }; }
return { status: res.status, body, elapsed };
}
async function main() {
const token = process.env.GITHUB_TOKEN;
if (!token) {
console.error('set GITHUB_TOKEN (a read-only token is enough)');
process.exitCode = 2;
return;
}
const document = process.env.GITHUB_QUERY || DEFAULT_QUERY;
let variables = {};
try { variables = JSON.parse(process.env.GITHUB_VARIABLES || '{}'); } catch {
console.error('GITHUB_VARIABLES takes a JSON object');
process.exitCode = 2;
return;
}
if (!process.env.GITHUB_QUERY) {
if (!process.env.GITHUB_LOGIN) {
console.error('set GITHUB_LOGIN to a user or organisation name');
process.exitCode = 2;
return;
}
variables.login = process.env.GITHUB_LOGIN;
}
const whyNot = refusal(document);
if (whyNot) {
console.error(`refusing to send: ${whyNot}`);
process.exitCode = 2;
return;
}
const normalCost = Number(process.env.GITHUB_NORMAL_COST || 1);
const retries = Number(process.env.GITHUB_RETRIES || 3);
console.log(`point cost: up to ${pointCost(1)} point(s) for the query plus `
+ 'whatever the timeout penalty adds, which is the number this run '
+ 'measures. Both /rate_limit reads are free.');
const idleBefore = await readBucket(token);
const idleAfter = await readBucket(token);
let [background, idleState] = charged(idleBefore, idleAfter);
if (idleState === 'measured') {
console.log(`idle check: graphql used ${idleBefore.used} -> ${idleAfter.used} `
+ `with nothing sent, so the bucket is ${background === 0 ? 'quiet' : 'already draining'}`);
} else {
console.log(`idle check: ${idleState}, so the background drain is unknown`);
background = 0;
}
console.log('sending one query. This script never retries a timed-out query.');
const { status, body, elapsed } = await runQuery(token, document, variables);
const after = await readBucket(token);
const message = timeoutMessage(body);
console.log(`HTTP ${status} after ${elapsed.toFixed(1)}s`
+ `${message ? `: ${message.slice(0, 160)}` : ''}`);
const [delta, chargeState] = charged(idleAfter, after);
const points = netCharge(delta, background);
if (chargeState === 'measured') {
console.log(`graphql used ${idleAfter.used} -> ${after.used}, so this call `
+ `was charged ${points} point(s)`);
} else {
console.log(`the charge could not be measured: ${chargeState}`);
}
const [state, detail] = classify(status, elapsed, points, normalCost, background, body);
console.log(`${state}: ${detail}`);
if (timingConsistent(elapsed) && looksLikeTimeout(status, body)) {
console.log(`the elapsed time agrees with the documented ${TIMEOUT_SECONDS}s cutoff`);
}
const projected = retryProjection(points, retries);
if (projected && state.startsWith('timed-out')) {
console.log(`${retries} retries of this document would spend ${projected} `
+ 'more point(s) and return nothing');
}
console.log(`repair: ${repair(state)}`);
console.log(JSON.stringify({
status,
elapsed_seconds: Number(elapsed.toFixed(2)),
headroom: headroom(elapsed),
charged: points,
background_drain: background,
normal_cost: normalCost,
penalty: penalty(points, normalCost),
retry_cost: projected,
state,
detail,
}, null, 2));
process.exitCode = (state.startsWith('timed-out') || state === 'close-to-the-timeout') ? 1 : 0;
}
// Guarded so importing this file from the test runner does not start a run.
if (import.meta.url === `file://${process.argv[1]}`) {
main().catch((err) => { console.error(err.message); process.exitCode = 2; });
}
Add a test
The subtraction gets tested harder than anything else, because a measurement that quietly returns a wrong number is worse than one that refuses. A window that reset between the readings, a used counter that went backwards, a body that is not a rate-limit payload and a bucket that moved while nothing was being sent all produce a refusal rather than a figure. Then the classifier: a timeout charged more than its normal cost, a timeout that did not demonstrate the penalty, a timeout nobody can attribute, and a successful call that used eighty per cent of the ten seconds and is therefore still a finding.
from github_graphql_timeout import (
NEAR_LIMIT, POINTS_PER_QUERY, TIMEOUT_SECONDS, bucket_reading, charged,
classify, headroom, looks_like_timeout, net_charge, operations, penalty,
point_cost, refusal, repair, retry_projection, timeout_message,
timing_consistent,
)
PAYLOAD = {"resources": {
"core": {"limit": 5000, "used": 900, "remaining": 4100, "reset": 1780000000},
"graphql": {"limit": 5000, "used": 1204, "remaining": 3796, "reset": 1780000000},
}}
TIMED_OUT = {"errors": [{"message": "Something went wrong while executing your "
"query. This may be the result of a timeout"}]}
BEFORE = {"limit": 5000, "used": 1204, "remaining": 3796, "reset": 1780000000}
AFTER = {"limit": 5000, "used": 1225, "remaining": 3775, "reset": 1780000000}
def test_the_reading_comes_from_the_graphql_bucket_and_not_core():
reading = bucket_reading(PAYLOAD)
assert reading["used"] == 1204
assert bucket_reading(PAYLOAD, "core")["used"] == 900
assert bucket_reading({}) is None
assert bucket_reading(None) is None
def test_the_charge_is_a_subtraction_over_one_window():
assert charged(BEFORE, AFTER) == (21, "measured")
assert charged(BEFORE, BEFORE) == (0, "measured")
def test_a_window_that_reset_between_readings_voids_the_measurement():
rolled = dict(AFTER, reset=1780003600, used=3)
assert charged(BEFORE, rolled) == (None, "window-reset")
backwards = dict(AFTER, used=1100)
assert charged(BEFORE, backwards) == (None, "window-reset")
assert charged(BEFORE, None) == (None, "unreadable")
assert charged({"used": "many", "reset": 1}, {"used": 2, "reset": 1}) == (None, "unreadable")
def test_a_known_background_drain_is_subtracted_rather_than_ignored():
assert net_charge(21, 0) == 21
assert net_charge(21, 5) == 16
assert net_charge(3, 9) == 0
assert net_charge(None, 0) is None
def test_a_timeout_is_recognised_by_status_or_by_message():
assert looks_like_timeout(502, None)
assert looks_like_timeout(504, None)
assert looks_like_timeout(200, TIMED_OUT)
assert not looks_like_timeout(200, {"data": {"viewer": {"login": "x"}}})
assert timeout_message(TIMED_OUT).startswith("Something went wrong")
assert timeout_message({"message": "Bad gateway"}) == "Bad gateway"
assert timeout_message(None) is None
def test_the_clock_is_checked_against_the_documented_cutoff():
assert TIMEOUT_SECONDS == 10
assert timing_consistent(10.4)
assert timing_consistent(8.0)
assert not timing_consistent(3.2)
assert not timing_consistent(None)
assert round(headroom(8.0), 2) == 0.8
assert headroom(-1) is None
def test_a_timeout_charged_above_its_normal_cost_is_the_headline():
state, detail = classify(502, 10.4, 21, 12, 0, None)
assert state == "timed-out-and-charged-extra"
assert "penalty of 9 point(s)" in detail
assert penalty(21, 12) == 9
assert "Do not retry" in repair(state)
def test_a_timeout_that_did_not_prove_the_penalty_says_so():
state, detail = classify(504, 10.1, 12, 12, 0, None)
assert state == "timed-out-charge-not-proved"
assert "not demonstrated by this run" in detail
assert "smaller anyway" in repair(state)
def test_a_bucket_that_was_already_draining_makes_the_charge_unattributable():
state, detail = classify(502, 10.2, 40, 12, 7, None)
assert state == "timed-out-charge-not-attributable"
assert "belongs to more than this call" in detail
assert "its own token" in repair(state)
def test_an_unmeasurable_charge_is_never_reported_as_zero():
state, detail = classify(502, 10.2, None, 12, 0, None)
assert state == "charge-not-measurable"
assert "did time out" in detail
def test_a_successful_call_near_the_cutoff_is_still_a_finding():
state, detail = classify(200, 8.2, 12, 12, 0, {"data": {"x": 1}})
assert state == "close-to-the-timeout"
assert "82%" in detail
assert NEAR_LIMIT == 0.7
assert "rather than after the outage" in repair(state)
def test_an_ordinary_call_is_not_dressed_up_as_a_problem():
state, detail = classify(200, 3.4, 12, 12, 0, {"data": {"x": 1}})
assert state == "completed-inside-the-limit"
assert "ordinary case" in detail
def test_the_retry_loop_is_priced_but_never_run():
assert retry_projection(21, 3) == 63
assert retry_projection(21, 0) == 0
assert retry_projection(None, 3) == 0
def test_the_script_refuses_to_send_a_mutation():
assert operations("query Q { viewer { login } }") == ["query"]
assert refusal("mutation M { addStar(input: {}) { clientMutationId } }")
assert refusal("subscription S { thing { id } }")
assert refusal("query Q { viewer { login } }") is None
def test_the_run_says_what_it_will_spend_before_the_penalty():
assert POINTS_PER_QUERY == 1
assert point_cost(1) == 1
assert point_cost(0) == 0
import { test } from 'node:test';
import assert from 'node:assert/strict';
import {
NEAR_LIMIT, POINTS_PER_QUERY, TIMEOUT_SECONDS, bucketReading, charged,
classify, headroom, looksLikeTimeout, netCharge, operations, penalty,
pointCost, refusal, repair, retryProjection, timeoutMessage, timingConsistent,
} from './github-graphql-timeout.mjs';
const PAYLOAD = {
resources: {
core: {
limit: 5000, used: 900, remaining: 4100, reset: 1780000000,
},
graphql: {
limit: 5000, used: 1204, remaining: 3796, reset: 1780000000,
},
},
};
const TIMED_OUT = {
errors: [{
message: 'Something went wrong while executing your query. This may be the '
+ 'result of a timeout',
}],
};
const BEFORE = {
limit: 5000, used: 1204, remaining: 3796, reset: 1780000000,
};
const AFTER = {
limit: 5000, used: 1225, remaining: 3775, reset: 1780000000,
};
test('the reading comes from the graphql bucket and not core', () => {
assert.equal(bucketReading(PAYLOAD).used, 1204);
assert.equal(bucketReading(PAYLOAD, 'core').used, 900);
assert.equal(bucketReading({}), null);
assert.equal(bucketReading(null), null);
});
test('the charge is a subtraction over one window', () => {
assert.deepEqual(charged(BEFORE, AFTER), [21, 'measured']);
assert.deepEqual(charged(BEFORE, BEFORE), [0, 'measured']);
});
test('a window that reset between readings voids the measurement', () => {
assert.deepEqual(charged(BEFORE, { ...AFTER, reset: 1780003600, used: 3 }),
[null, 'window-reset']);
assert.deepEqual(charged(BEFORE, { ...AFTER, used: 1100 }), [null, 'window-reset']);
assert.deepEqual(charged(BEFORE, null), [null, 'unreadable']);
assert.deepEqual(charged({ used: 'many', reset: 1 }, { used: 2, reset: 1 }),
[null, 'unreadable']);
});
test('a known background drain is subtracted rather than ignored', () => {
assert.equal(netCharge(21, 0), 21);
assert.equal(netCharge(21, 5), 16);
assert.equal(netCharge(3, 9), 0);
assert.equal(netCharge(null, 0), null);
});
test('a timeout is recognised by status or by message', () => {
assert.ok(looksLikeTimeout(502, null));
assert.ok(looksLikeTimeout(504, null));
assert.ok(looksLikeTimeout(200, TIMED_OUT));
assert.ok(!looksLikeTimeout(200, { data: { viewer: { login: 'x' } } }));
assert.ok(timeoutMessage(TIMED_OUT).startsWith('Something went wrong'));
assert.equal(timeoutMessage({ message: 'Bad gateway' }), 'Bad gateway');
assert.equal(timeoutMessage(null), null);
});
test('the clock is checked against the documented cutoff', () => {
assert.equal(TIMEOUT_SECONDS, 10);
assert.ok(timingConsistent(10.4));
assert.ok(timingConsistent(8.0));
assert.ok(!timingConsistent(3.2));
assert.ok(!timingConsistent(null));
assert.equal(Number(headroom(8.0).toFixed(2)), 0.8);
assert.equal(headroom(-1), null);
});
test('a timeout charged above its normal cost is the headline', () => {
const [state, detail] = classify(502, 10.4, 21, 12, 0, null);
assert.equal(state, 'timed-out-and-charged-extra');
assert.match(detail, /penalty of 9 point\(s\)/);
assert.equal(penalty(21, 12), 9);
assert.match(repair(state), /not retry/);
});
test('a timeout that did not prove the penalty says so', () => {
const [state, detail] = classify(504, 10.1, 12, 12, 0, null);
assert.equal(state, 'timed-out-charge-not-proved');
assert.match(detail, /not demonstrated by this run/);
assert.match(repair(state), /smaller anyway/);
});
test('a bucket that was already draining makes the charge unattributable', () => {
const [state, detail] = classify(502, 10.2, 40, 12, 7, null);
assert.equal(state, 'timed-out-charge-not-attributable');
assert.match(detail, /belongs to more than this call/);
assert.match(repair(state), /its own token/);
});
test('an unmeasurable charge is never reported as zero', () => {
const [state, detail] = classify(502, 10.2, null, 12, 0, null);
assert.equal(state, 'charge-not-measurable');
assert.match(detail, /did time out/);
});
test('a successful call near the cutoff is still a finding', () => {
const [state, detail] = classify(200, 8.2, 12, 12, 0, { data: { x: 1 } });
assert.equal(state, 'close-to-the-timeout');
assert.match(detail, /82%/);
assert.equal(NEAR_LIMIT, 0.7);
assert.match(repair(state), /rather than after the outage/);
});
test('an ordinary call is not dressed up as a problem', () => {
const [state, detail] = classify(200, 3.4, 12, 12, 0, { data: { x: 1 } });
assert.equal(state, 'completed-inside-the-limit');
assert.match(detail, /ordinary case/);
});
test('the retry loop is priced but never run', () => {
assert.equal(retryProjection(21, 3), 63);
assert.equal(retryProjection(21, 0), 0);
assert.equal(retryProjection(null, 3), 0);
});
test('the script refuses to send a mutation', () => {
assert.deepEqual(operations('query Q { viewer { login } }'), ['query']);
assert.ok(refusal('mutation M { addStar(input: {}) { clientMutationId } }'));
assert.ok(refusal('subscription S { thing { id } }'));
assert.equal(refusal('query Q { viewer { login } }'), null);
});
test('the run says what it will spend before the penalty', () => {
assert.equal(POINTS_PER_QUERY, 1);
assert.equal(pointCost(1), 1);
assert.equal(pointCost(0), 0);
});
FAQ
Can I raise the ten-second limit or ask for more time?
No. It is a server-side execution limit, applied to the query rather than to the connection, and there is no header, parameter or plan that extends it. Raising your own HTTP client timeout has no effect at all, because your client is not the thing giving up. The only lever available is the amount of work the document asks for: fewer nested connections, lower first values, and pagination in place of one large traversal.
Is retrying really that bad? Every other 502 should be retried.
For a genuine gateway error, yes, retry. For this one the retry is worse than useless, because the query is deterministic: the same document over the same data takes the same time and dies at the same cutoff, and each attempt is charged with the penalty on top. Three retries is three charges for nothing. The distinction a client can act on is elapsed time — a 502 that arrives after ten seconds is a timeout, and a 502 that arrives in 200 milliseconds is the gateway error you should retry.
How do I know the penalty is real rather than something else spending the budget?
You measure it, and the script is careful about exactly this. GET /rate_limit is free, so it reads resources.graphql.used twice with nothing sent between them first: if the bucket moves during that gap, another process is holding the same token and the result is reported as unattributable rather than as a number. When the bucket is quiet, the delta across the failing call is that call's charge, and anything above the query's normal cost is the penalty.
What counts as the query's normal cost for the comparison?
What the same document costs when it finishes, which is a number you measure rather than guess: add rateLimit { cost } to the query and read it back on a run that succeeds, usually against a smaller target. That is a separate note in this section. Pass the figure with --normal-cost so the subtraction has something to compare against; left at the default of 1, the script will still report the charge but the penalty it names will be an overestimate.
The query returns in eight seconds and never fails. Is that fine?
It is a finding, and the script reports it as one. Eight seconds is eighty per cent of the cutoff on a limit you do not control, against data that only grows, so the query is one busy repository away from failing every night. It will also fail at the least convenient moment, since the slowest runs are the ones with the most to report. Shrinking it while it still works is very much cheaper than shrinking it during an incident.
Related field notes
- What the query costs when it does finish
- The budget the penalty is deducted from
- The REST version of a request that ran too long
Sources
Every figure in this note is traced to one of these. Prices are list rates and change — check them for your own region before acting.
- Resource limitations — GitHub GraphQL API
- Rate limits and node limits for the GraphQL API — GitHub Docs
- Rate limit — GitHub REST API
- Using the GraphQL API — GitHub Docs
If your setup is misbehaving in a way this note does not cover, message me on LinkedIn with what you are seeing.