Diagnostic GitHub API
the receiver takes longer than 10 seconds and times out
The delivery log has started showing timed out against a handler that, according to your own logs, finished the job perfectly. It ran, it did the work, it wrote the record, it returned 200 — twelve seconds after it started. GitHub stopped listening at ten and filed the delivery as a failure, and the redelivery it may send will do the same twelve seconds of work again.
A webhook receiver gets ten seconds to respond. Anything slower is recorded as a failed delivery whether or not your handler eventually succeeds, because GitHub is not waiting to find out. A handler that does the real work inline — clones a repository, calls three other APIs, waits on a build — sits under that ceiling comfortably at first and crosses it the month the repository grows.
Every record in GET /repos/{owner}/{repo}/hooks/{hook_id}/deliveries carries a duration alongside its status, on the successful deliveries as much as the failed ones, and that column is the one to read. Counting failures tells you the cutoff has already been crossed. Reading the duration distribution — the median, the 95th percentile, and which event types sit at the top of it — tells you how much room is left, which is the only version of this finding that arrives in time to be useful. The repair is structural: verify the signature, acknowledge, enqueue, and do the work somewhere the clock is not running.
The problem in plain words
It looks like a lie, so it gets argued with. Your logs say the handler ran and returned 200; the delivery log says timed out; both are correct and they are describing different moments. The handler did return 200, to a connection GitHub had already abandoned. A morning goes into proving the receiver works, which it does, and none of that work touches the actual constraint, which is when the answer arrived rather than whether it was right.
Then it gets treated as flaky. Timeouts are intermittent by nature: the same handler on a small repository is fine and on the big one is not, so the failures cluster in a way that looks like network weather. Retries are added, alert thresholds are raised, and the timeouts are filed under things that sometimes happen. The population of deliveries that are slow but still inside the limit — the ones that will time out next quarter — is invisible to every one of those responses, because nothing in a failure count looks at them.
The redelivery makes it worse rather than better. A delivery that timed out at ten seconds is a delivery whose work may have completed anyway, so replaying it runs the same expensive job a second time. Handlers that were written on the assumption that a delivery arrives once now run twice under load, which is exactly when they can least afford it, and any part of them that is not idempotent starts producing duplicates at the worst possible moment.
Why it happens
Ten seconds is the whole budget, not the handler's budget. The clock covers DNS, the TLS handshake, any queueing in your ingress, your framework's own startup on a cold instance, the handler, and the response. A handler that measures itself at eight seconds may still be recorded as a timeout, because it was never measuring the part of the ten that it did not control.
The duration is recorded on every delivery, including the good ones. This is what makes the problem forecastable. The deliveries feed is not only a failure log; each record carries how long the attempt took, so a distribution that has crept from two seconds to seven is a finding today, before a single delivery has failed. That is the entire reason this check exists separately from a failure audit.
It is not the same read as the failure audit. The note on failing deliveries reads this same feed and buckets it by status code, because a 401 and a 500 want different repairs. This one throws the status codes away, except the one marker that says the attempt was abandoned, and reads the duration column on everything. The two answer different questions from the same request: what broke, and how close is this to breaking.
The slowness is usually one event type. A push on a monorepo carries a large payload and usually triggers the most work; a check_suite or a status fires far more often than anybody expects. Grouping durations by event tells you which handler to make asynchronous first, and that is a smaller and more achievable change than making the whole receiver asynchronous at once.
You cannot time this from outside. The obvious experiment — send a request at the receiver and measure it — is not available to a read-only script, and it would be a poor measurement anyway: a synthetic payload does not do the work a real one does, and the numbers you want are the ones GitHub already recorded from its own side of the connection. The feed has them. Reasoning from the record beats manufacturing a new one.
The fix, as a flow
The same feed as the failure audit, read for a different column. Statuses are thrown away except the one marker that says the attempt was abandoned, and the duration is kept on every record, including the ones that succeeded. That is what makes the finding arrive early: a tail at nine seconds is a problem today, and a failure count calls that same window healthy. Nothing is ever sent to the receiver, because the clock that decides is not the one this script would be holding.
How to fix it
Pull the deliveries and keep the duration column
GET /repos/{owner}/{repo}/hooks/{hook_id}/deliveries?per_page=100, following the cursor in the Link header. Keep every record, not just the failures. The successful ones are the sample that tells you where the distribution actually sits, and discarding them is how this problem stays invisible until it is an outage.
Normalise the duration before you compare anything
The field is a bare number with no unit attached to it, and in practice deliveries come back with small values that are plainly seconds. Treat anything at or below sixty as seconds and anything above as milliseconds: no delivery survives past ten seconds, and none takes sixty thousand of them, so the rule is unambiguous on real data. Convert once, at the edge, and work in milliseconds after that.
Read the percentiles, not the mean
A mean of three seconds hides a 95th percentile of nine. The number that matters is the tail, because the tail is what crosses the line first, and the headroom worth reporting is ten seconds minus the 95th percentile. Under two seconds of headroom is a finding even when the failure count is zero.
Group by event to find the handler to fix
Compute the same percentile per event type. One event usually dominates, and making that single handler acknowledge-then-queue buys most of the headroom for a fraction of the work. It also makes the change reviewable, which the alternative — restructuring every handler at once — is not.
Make the synchronous path do nothing
Verify the signature, put the raw payload on a queue, return 202. That is the whole handler. Everything else moves behind the queue, where it can take twelve seconds or twelve minutes and retry on its own terms. Do the signature check before the enqueue, so the queue never holds anything unverified, and make the worker idempotent on the delivery guid, because redeliveries are now something you can survive rather than something you fear.
How to check it worked
After the work moves behind a queue, the same read shows the tail collapsing while the delivery count stays exactly where it was.
GITHUB_TOKEN=$READ_ONLY_TOKEN python3 github_hook_delivery_duration.py \
--repo acme-corp/platform
# hook 517238001 -> https://hooks.example.com/github
# 400 delivery/deliveries, 6 timed out, p50 3410ms, p95 9120ms, max 10000ms
# timing-out: 6 deliveries were abandoned at the 10 second cutoff, and the 95th
# percentile is 9120ms, which leaves 880ms of headroom on everything else
# slowest event: push, p95 9740ms across 122 deliveries
# repair: verify the signature, enqueue the payload, return 202
# after the handler is split
# healthy: p95 is 240ms, 9760ms of headroomThe full code
One GET for the hooks and a cursor-paginated GET for the deliveries, and nothing is ever sent to the receiver itself — the numbers this needs were recorded by GitHub from its own side of the connection, and a synthetic request would be both a write and a worse measurement. The pure part is small and does the arguing: a unit normalisation with one defensible rule, a nearest-rank percentile so a short window does not interpolate values that never happened, and a verdict that treats a healthy failure count with a tail at nine seconds as a finding rather than a pass.
"""Report how close a webhook receiver is to the 10 second delivery cutoff.
Read only. GETs the repository's hooks and their delivery records. Nothing is
sent to the receiver: timing it from here would be a write, and it would be a
worse measurement than the one GitHub already recorded from its own side of the
connection.
GitHub allows a receiver ten seconds to respond and files anything slower as a
failed delivery, whatever the handler eventually does. Every delivery record
carries a duration, on the successful attempts as much as the failed ones, so
the slide toward the cutoff is readable before the first failure.
This is a different read from a delivery failure audit. That one buckets by
status code. This one ignores status codes except the abandonment marker and
reads the duration column on everything.
Environment:
GITHUB_TOKEN a read-only token with access to the repository
"""
import argparse
import json
import logging
import os
import sys
import requests
logging.basicConfig(level=logging.INFO, format="%(asctime)s %(levelname)s %(message)s")
log = logging.getLogger("github_hook_delivery_duration")
API = "https://api.github.com"
UA = "github-hook-delivery-duration/1.0"
CUTOFF_MS = 10000
WARN_MS = 8000
SLOW_MS = 5000
# The duration field carries no unit. Nothing survives past ten seconds and
# nothing real takes sixty thousand of them, so a value at or under sixty is
# seconds and anything above it is already milliseconds.
SECONDS_CEILING = 60
def duration_ms(row):
"""A delivery's duration in milliseconds, or None. Pure."""
if not isinstance(row, dict):
return None
raw = row.get("duration")
if raw is None or isinstance(raw, bool):
return None
try:
value = float(raw)
except (TypeError, ValueError):
return None
if value < 0:
return None
return value * 1000.0 if value <= SECONDS_CEILING else value
def timed_out(row):
"""Whether GitHub abandoned this delivery. Pure.
The status text is the reliable marker. A record can also carry a duration
at the cutoff with no status text at all, which counts too, because that is
the same event described by the other column.
"""
if not isinstance(row, dict):
return False
status = " ".join(str(row.get("status") or "").lower().split())
if "timed out" in status or "timeout" in status:
return True
ms = duration_ms(row)
return ms is not None and ms >= CUTOFF_MS
def classify(row):
"""Sort one delivery by how much room it had left. Pure."""
if timed_out(row):
return "timed-out"
ms = duration_ms(row)
if ms is None:
return "unknown"
if ms >= WARN_MS:
return "at-risk"
if ms >= SLOW_MS:
return "slow"
return "fine"
def percentile(values, p):
"""Nearest-rank percentile over a list of numbers, or None. Pure.
Nearest rank rather than interpolation on purpose: a delivery window is
small and every value in it is a real measurement, so reporting a number
that no delivery actually took would be a worse answer than reporting one
that a delivery did.
"""
numbers = sorted(v for v in (values or []) if isinstance(v, (int, float)))
if not numbers:
return None
if p <= 0:
return numbers[0]
if p >= 100:
return numbers[-1]
import math
rank = max(1, math.ceil(p / 100.0 * len(numbers)))
return numbers[min(rank, len(numbers)) - 1]
def stats(rows):
"""The distribution that decides the verdict. Pure."""
rows = [r for r in (rows or []) if isinstance(r, dict)]
measured = [duration_ms(r) for r in rows]
measured = [m for m in measured if m is not None]
p95 = percentile(measured, 95)
return {
"count": len(rows),
"measured": len(measured),
"timed_out": sum(1 for r in rows if timed_out(r)),
"p50": percentile(measured, 50),
"p95": p95,
"max": max(measured) if measured else None,
"headroom_ms": None if p95 is None else CUTOFF_MS - p95,
}
def by_event(rows, min_count=3):
"""The same distribution per event type. Pure."""
groups = {}
for row in rows or []:
if not isinstance(row, dict):
continue
event = str(row.get("event") or "unknown").strip().lower() or "unknown"
groups.setdefault(event, []).append(row)
out = {}
for event, group in groups.items():
measured = [m for m in (duration_ms(r) for r in group) if m is not None]
out[event] = {"count": len(group),
"timed_out": sum(1 for r in group if timed_out(r)),
"p95": percentile(measured, 95)}
return {k: v for k, v in out.items() if v["count"] >= min_count or v["timed_out"]}
def slowest_event(rows, min_count=3):
"""The event type with the worst tail, or None. Pure."""
grouped = by_event(rows, min_count)
ranked = [(v["p95"], k, v) for k, v in grouped.items() if v["p95"] is not None]
if not ranked:
return None
ranked.sort(key=lambda t: (-t[0], t[1]))
p95, event, row = ranked[0]
return {"event": event, "p95": p95, "count": row["count"],
"timed_out": row["timed_out"]}
def verdict(st):
"""Turn the distribution into a finding. Pure."""
if not st or not st.get("count"):
return ("no-data",
"no deliveries in the retained window, so there is nothing to "
"measure. That is not the same as a receiver that is fast.")
if not st.get("measured"):
return ("no-durations",
"%d delivery/deliveries carry no duration, so the tail cannot "
"be measured from this feed." % st["count"])
p95 = st["p95"]
if st["timed_out"]:
return ("timing-out",
"%d deliveries were abandoned at the 10 second cutoff, and the "
"95th percentile is %dms, which leaves %dms of headroom on "
"everything else." % (st["timed_out"], p95, st["headroom_ms"]))
if p95 >= WARN_MS:
return ("at-the-edge",
"nothing has timed out yet and the 95th percentile is %dms, "
"leaving %dms before the cutoff. This fails on the next slow "
"week." % (p95, st["headroom_ms"]))
if p95 >= SLOW_MS:
return ("slow",
"the 95th percentile is %dms against a 10 second cutoff. The "
"handler is doing real work inline and has %dms of room."
% (p95, st["headroom_ms"]))
return ("healthy",
"the 95th percentile is %dms, %dms inside the cutoff."
% (p95, st["headroom_ms"]))
def repair(state, worst=None):
"""The sentence a reader has to act on. Pure."""
if state in ("timing-out", "at-the-edge", "slow"):
target = (" Start with %s, whose 95th percentile is %dms."
% (worst["event"], worst["p95"])) if worst else ""
return ("verify the signature, put the raw payload on a queue, return "
"202, and do the work in a worker keyed on the delivery guid so "
"a redelivery cannot run it twice.%s" % target)
if state == "no-data":
return ("nothing to repair, and nothing proved either. Check the hook "
"is active and that the retention window covers a period when "
"events actually happened.")
if state == "no-durations":
return ("read the durations from a wider page of deliveries; this "
"window has statuses but no timings to work from.")
return "nothing. The receiver answers well inside the cutoff."
def next_link(headers):
"""The rel=next URL from a Link header, or None. Pure."""
link = (headers or {}).get("Link") or (headers or {}).get("link") or ""
for part in str(link).split(","):
section = part.split(";")
if len(section) < 2:
continue
url = section[0].strip()
if 'rel="next"' in part and url.startswith("<") and url.endswith(">"):
return url[1:-1]
return None
def get(session, url):
"""One GET. Returns (status, json-or-None, headers)."""
full = API + url if url.startswith("/") else url
r = session.get(full, timeout=30)
try:
body = r.json()
except ValueError:
body = None
return r.status_code, body, r.headers
def deliveries(session, owner, repo, hook_id, pages=8):
"""Delivery records for one hook, following the cursor. Read only."""
url = "/repos/%s/%s/hooks/%s/deliveries?per_page=100" % (owner, repo, hook_id)
out = []
for _ in range(pages):
status, body, headers = get(session, url)
if status != 200 or not isinstance(body, list):
log.error("deliveries for hook %s returned %d", hook_id, status)
break
out.extend(body)
url = next_link(headers)
if not url:
break
return out
def main():
ap = argparse.ArgumentParser(description=__doc__)
ap.add_argument("--repo", required=True, help="owner/repo")
ap.add_argument("--hook-id", default=None, help="one hook; omit for all")
args = ap.parse_args()
token = os.environ.get("GITHUB_TOKEN")
if not token:
log.error("set GITHUB_TOKEN to a read-only token that can read the "
"repository's hooks")
return 2
if "/" not in args.repo:
log.error("--repo takes owner/repo")
return 2
owner, repo = args.repo.split("/", 1)
session = requests.Session()
session.headers.update({
"Authorization": "Bearer " + token,
"Accept": "application/vnd.github+json",
"X-GitHub-Api-Version": "2022-11-28",
"User-Agent": UA,
})
status, hooks, _ = get(session, "/repos/%s/%s/hooks?per_page=100" % (owner, repo))
if status != 200 or not isinstance(hooks, list):
log.error("GET hooks returned %d", status)
return 2
if args.hook_id:
hooks = [h for h in hooks if str(h.get("id")) == str(args.hook_id)]
report = []
worst_state = "healthy"
for hook in hooks:
hook_id = hook.get("id")
url = (hook.get("config") or {}).get("url", "?")
log.info("hook %s -> %s", hook_id, url)
rows = deliveries(session, owner, repo, hook_id)
st = stats(rows)
state, detail = verdict(st)
worst = slowest_event(rows)
log.info("%d delivery/deliveries, %d timed out, p50 %sms, p95 %sms, "
"max %sms", st["count"], st["timed_out"],
int(st["p50"]) if st["p50"] is not None else "?",
int(st["p95"]) if st["p95"] is not None else "?",
int(st["max"]) if st["max"] is not None else "?")
log.info("%s: %s", state, detail)
if worst:
log.info("slowest event: %s, p95 %dms across %d deliveries",
worst["event"], worst["p95"], worst["count"])
log.info("repair: %s", repair(state, worst))
if state in ("timing-out", "at-the-edge"):
worst_state = state
report.append({"hook_id": hook_id, "url": url, "stats": st,
"state": state, "detail": detail,
"slowest_event": worst,
"by_event": by_event(rows)})
print(json.dumps({"repo": args.repo, "hooks": report}, indent=2, default=str))
return 1 if worst_state != "healthy" else 0
if __name__ == "__main__":
sys.exit(main())
/**
* Report how close a webhook receiver is to the 10 second delivery cutoff.
*
* Read only. GETs the repository's hooks and their delivery records. Nothing is
* sent to the receiver: timing it from here would be a write, and a worse
* measurement than the one GitHub already recorded from its own side.
*
* Environment:
* GITHUB_TOKEN a read-only token with access to the repository
* GITHUB_REPO owner/repo
* GITHUB_HOOK_ID optional, one hook instead of all of them
*/
const API = 'https://api.github.com';
const UA = 'github-hook-delivery-duration/1.0';
export const CUTOFF_MS = 10000;
export const WARN_MS = 8000;
export const SLOW_MS = 5000;
// The duration field carries no unit; at or under sixty it is seconds.
export const SECONDS_CEILING = 60;
/** A delivery's duration in milliseconds, or null. Pure. */
export function durationMs(row) {
if (!row || typeof row !== 'object') return null;
const raw = row.duration;
if (raw === null || raw === undefined || typeof raw === 'boolean') return null;
const value = Number(raw);
if (!Number.isFinite(value) || value < 0) return null;
return value <= SECONDS_CEILING ? value * 1000 : value;
}
/** Whether GitHub abandoned this delivery. Pure. */
export function timedOut(row) {
if (!row || typeof row !== 'object') return false;
const status = String(row.status ?? '').toLowerCase().split(/\s+/).join(' ');
if (status.includes('timed out') || status.includes('timeout')) return true;
const ms = durationMs(row);
return ms !== null && ms >= CUTOFF_MS;
}
/** Sort one delivery by how much room it had left. Pure. */
export function classify(row) {
if (timedOut(row)) return 'timed-out';
const ms = durationMs(row);
if (ms === null) return 'unknown';
if (ms >= WARN_MS) return 'at-risk';
if (ms >= SLOW_MS) return 'slow';
return 'fine';
}
/** Nearest-rank percentile over a list of numbers, or null. Pure. */
export function percentile(values, p) {
const numbers = (values || []).filter((v) => typeof v === 'number' && Number.isFinite(v))
.sort((a, b) => a - b);
if (!numbers.length) return null;
if (p <= 0) return numbers[0];
if (p >= 100) return numbers[numbers.length - 1];
const rank = Math.max(1, Math.ceil((p / 100) * numbers.length));
return numbers[Math.min(rank, numbers.length) - 1];
}
/** The distribution that decides the verdict. Pure. */
export function stats(rows) {
const list = (rows || []).filter((r) => r && typeof r === 'object');
const measured = list.map(durationMs).filter((m) => m !== null);
const p95 = percentile(measured, 95);
return {
count: list.length,
measured: measured.length,
timed_out: list.filter(timedOut).length,
p50: percentile(measured, 50),
p95,
max: measured.length ? Math.max(...measured) : null,
headroom_ms: p95 === null ? null : CUTOFF_MS - p95,
};
}
/** The same distribution per event type. Pure. */
export function byEvent(rows, minCount = 3) {
const groups = {};
for (const row of rows || []) {
if (!row || typeof row !== 'object') continue;
const event = String(row.event ?? 'unknown').trim().toLowerCase() || 'unknown';
(groups[event] = groups[event] || []).push(row);
}
const out = {};
for (const [event, group] of Object.entries(groups)) {
const measured = group.map(durationMs).filter((m) => m !== null);
const row = {
count: group.length,
timed_out: group.filter(timedOut).length,
p95: percentile(measured, 95),
};
if (row.count >= minCount || row.timed_out) out[event] = row;
}
return out;
}
/** The event type with the worst tail, or null. Pure. */
export function slowestEvent(rows, minCount = 3) {
const grouped = byEvent(rows, minCount);
const ranked = Object.entries(grouped).filter(([, v]) => v.p95 !== null);
if (!ranked.length) return null;
ranked.sort((a, b) => b[1].p95 - a[1].p95 || a[0].localeCompare(b[0]));
const [event, row] = ranked[0];
return { event, p95: row.p95, count: row.count, timed_out: row.timed_out };
}
/** Turn the distribution into a finding. Pure. */
export function verdict(st) {
if (!st || !st.count) {
return ['no-data',
'no deliveries in the retained window, so there is nothing to measure. '
+ 'That is not the same as a receiver that is fast.'];
}
if (!st.measured) {
return ['no-durations',
`${st.count} delivery/deliveries carry no duration, so the tail cannot be `
+ 'measured from this feed.'];
}
const p95 = st.p95;
if (st.timed_out) {
return ['timing-out',
`${st.timed_out} deliveries were abandoned at the 10 second cutoff, and `
+ `the 95th percentile is ${Math.trunc(p95)}ms, which leaves `
+ `${Math.trunc(st.headroom_ms)}ms of headroom on everything else.`];
}
if (p95 >= WARN_MS) {
return ['at-the-edge',
`nothing has timed out yet and the 95th percentile is ${Math.trunc(p95)}ms, `
+ `leaving ${Math.trunc(st.headroom_ms)}ms before the cutoff. This fails on `
+ 'the next slow week.'];
}
if (p95 >= SLOW_MS) {
return ['slow',
`the 95th percentile is ${Math.trunc(p95)}ms against a 10 second cutoff. `
+ `The handler is doing real work inline and has ${Math.trunc(st.headroom_ms)}ms of room.`];
}
return ['healthy',
`the 95th percentile is ${Math.trunc(p95)}ms, ${Math.trunc(st.headroom_ms)}ms inside the cutoff.`];
}
/** The sentence a reader has to act on. Pure. */
export function repair(state, worst = null) {
if (['timing-out', 'at-the-edge', 'slow'].includes(state)) {
const target = worst
? ` Start with ${worst.event}, whose 95th percentile is ${Math.trunc(worst.p95)}ms.`
: '';
return 'verify the signature, put the raw payload on a queue, return 202, and '
+ 'do the work in a worker keyed on the delivery guid so a redelivery cannot '
+ `run it twice.${target}`;
}
if (state === 'no-data') {
return 'nothing to repair, and nothing proved either. Check the hook is '
+ 'active and that the retention window covers a period when events '
+ 'actually happened.';
}
if (state === 'no-durations') {
return 'read the durations from a wider page of deliveries; this window has '
+ 'statuses but no timings to work from.';
}
return 'nothing. The receiver answers well inside the cutoff.';
}
/** The rel=next URL from a Link header, or null. Pure. */
export function nextLink(headers) {
const link = (headers && (headers.get ? headers.get('link') : headers.Link || headers.link)) || '';
for (const part of String(link).split(',')) {
const url = part.split(';')[0].trim();
if (part.includes('rel="next"') && url.startsWith('<') && url.endsWith('>')) {
return url.slice(1, -1);
}
}
return null;
}
function headersFor(token) {
return {
Authorization: `Bearer ${token}`,
Accept: 'application/vnd.github+json',
'X-GitHub-Api-Version': '2022-11-28',
'User-Agent': UA,
};
}
async function get(token, url) {
const res = await fetch(url.startsWith('/') ? API + url : url, { headers: headersFor(token) });
let body = null;
try { body = await res.json(); } catch { body = null; }
return { status: res.status, body, headers: res.headers };
}
async function main() {
const token = process.env.GITHUB_TOKEN;
const repo = process.env.GITHUB_REPO;
if (!token || !repo || !repo.includes('/')) {
console.error('set GITHUB_TOKEN and GITHUB_REPO=owner/repo');
process.exitCode = 2;
return;
}
const [owner, name] = repo.split('/');
const hooksRes = await get(token, `/repos/${owner}/${name}/hooks?per_page=100`);
if (hooksRes.status !== 200 || !Array.isArray(hooksRes.body)) {
console.error(`GET hooks returned ${hooksRes.status}`);
process.exitCode = 2;
return;
}
const wanted = process.env.GITHUB_HOOK_ID;
const hooks = wanted
? hooksRes.body.filter((h) => String(h.id) === String(wanted))
: hooksRes.body;
let worstState = 'healthy';
const report = [];
for (const hook of hooks) {
console.log(`hook ${hook.id} -> ${(hook.config || {}).url || '?'}`);
const rows = [];
let url = `/repos/${owner}/${name}/hooks/${hook.id}/deliveries?per_page=100`;
for (let page = 0; page < 8 && url; page += 1) {
const res = await get(token, url);
if (res.status !== 200 || !Array.isArray(res.body)) {
console.error(`deliveries returned ${res.status}`);
break;
}
rows.push(...res.body);
url = nextLink(res.headers);
}
const st = stats(rows);
const [state, detail] = verdict(st);
const worst = slowestEvent(rows);
console.log(`${st.count} delivery/deliveries, ${st.timed_out} timed out, `
+ `p95 ${st.p95 === null ? '?' : Math.trunc(st.p95)}ms`);
console.log(`${state}: ${detail}`);
if (worst) {
console.log(`slowest event: ${worst.event}, p95 ${Math.trunc(worst.p95)}ms `
+ `across ${worst.count} deliveries`);
}
console.log(`repair: ${repair(state, worst)}`);
if (['timing-out', 'at-the-edge'].includes(state)) worstState = state;
report.push({ hook_id: hook.id, stats: st, state, slowest_event: worst });
}
console.log(JSON.stringify({ repo, hooks: report }, null, 2));
process.exitCode = worstState === 'healthy' ? 0 : 1;
}
// 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 unit rule is tested first, because everything downstream is measured in milliseconds and a single delivery read as seconds would move a percentile by three orders of magnitude. Then the finding this note exists for: a window with zero failures and a tail at nine seconds has to come back as a problem, since a failure count calls that window perfectly healthy. The percentile is pinned to nearest rank so it only ever returns a duration some delivery really took, and the grouping has to survive an event type that appears twice and times out both times.
from github_hook_delivery_duration import (
by_event, classify, duration_ms, next_link, percentile, repair,
slowest_event, stats, timed_out, verdict,
)
def d(duration, event="push", status="OK"):
return {"duration": duration, "event": event, "status": status}
def test_seconds_and_milliseconds_both_normalise_to_milliseconds():
assert duration_ms(d(0.62)) == 620.0
assert duration_ms(d(9.87)) == 9870.0
assert duration_ms(d(9870)) == 9870.0
assert duration_ms(d(60)) == 60000.0
assert duration_ms(d(61)) == 61.0
def test_an_unreadable_duration_is_none_rather_than_zero():
assert duration_ms(d(None)) is None
assert duration_ms(d("slow")) is None
assert duration_ms(d(True)) is None
assert duration_ms(d(-1)) is None
assert duration_ms(None) is None
def test_an_abandoned_delivery_is_recognised_from_either_column():
assert timed_out({"status": "timed out", "duration": None})
assert timed_out({"status": "Timed Out", "duration": 2.0})
assert timed_out({"status": "", "duration": 10.0})
assert not timed_out(d(1.0))
assert not timed_out(None)
def test_each_delivery_is_sorted_by_the_room_it_had_left():
assert classify(d(9.5)) == "at-risk"
assert classify(d(6.0)) == "slow"
assert classify(d(0.4)) == "fine"
assert classify(d(10.0)) == "timed-out"
assert classify(d(None)) == "unknown"
def test_the_percentile_is_nearest_rank_and_never_invents_a_value():
values = [100, 200, 300, 400]
assert percentile(values, 50) == 200
assert percentile(values, 95) == 400
assert percentile(values, 0) == 100
assert percentile([], 95) is None
assert percentile([7], 95) == 7
def test_a_window_with_no_failures_and_a_nine_second_tail_is_a_finding():
rows = [d(0.5)] * 18 + [d(9.1)] * 2
st = stats(rows)
assert st["timed_out"] == 0
state, detail = verdict(st)
assert state == "at-the-edge"
assert "fails on the next slow week" in detail
assert "return 202" in repair(state)
def test_a_fast_receiver_is_left_alone():
st = stats([d(0.2)] * 50)
assert verdict(st)[0] == "healthy"
assert repair("healthy").startswith("nothing")
def test_timeouts_are_reported_with_the_headroom_on_everything_else():
rows = [d(0.5)] * 90 + [{"status": "timed out", "event": "push"}] * 10
st = stats(rows)
assert st["timed_out"] == 10
state, detail = verdict(st)
assert state == "timing-out"
assert "10 deliveries were abandoned" in detail
def test_an_empty_window_is_never_reported_as_healthy():
state, detail = verdict(stats([]))
assert state == "no-data"
assert "not the same as a receiver that is fast" in detail
def test_a_window_with_statuses_but_no_timings_says_so():
state, _ = verdict(stats([{"event": "push", "status": "OK"}] * 5))
assert state == "no-durations"
def test_the_grouping_finds_the_handler_to_fix_first():
rows = ([d(9.4, "push")] * 5 + [d(0.3, "issues")] * 5)
worst = slowest_event(rows)
assert worst["event"] == "push"
assert worst["p95"] == 9400.0
assert "Start with push" in repair("slow", worst)
def test_a_rare_event_is_kept_when_it_timed_out():
rows = [d(0.2, "issues")] * 5 + [{"event": "release", "status": "timed out"}]
grouped = by_event(rows)
assert "release" in grouped
assert grouped["release"]["timed_out"] == 1
def test_the_cursor_is_read_from_the_link_header():
header = ('<https://api.github.com/repos/a/b/hooks/1/deliveries?cursor=v2>; '
'rel="next"')
assert next_link({"Link": header}).endswith("cursor=v2")
assert next_link({"Link": '<https://x>; rel="prev"'}) is None
assert next_link({}) is None
import { test } from 'node:test';
import assert from 'node:assert/strict';
import {
byEvent, classify, durationMs, nextLink, percentile, repair,
slowestEvent, stats, timedOut, verdict,
} from './github-hook-delivery-duration.mjs';
const d = (duration, event = 'push', status = 'OK') => ({ duration, event, status });
test('seconds and milliseconds both normalise to milliseconds', () => {
assert.equal(durationMs(d(0.62)), 620);
assert.equal(durationMs(d(9.87)), 9870);
assert.equal(durationMs(d(9870)), 9870);
assert.equal(durationMs(d(60)), 60000);
assert.equal(durationMs(d(61)), 61);
});
test('an unreadable duration is null rather than zero', () => {
assert.equal(durationMs(d(null)), null);
assert.equal(durationMs(d('slow')), null);
assert.equal(durationMs(d(true)), null);
assert.equal(durationMs(d(-1)), null);
assert.equal(durationMs(null), null);
});
test('an abandoned delivery is recognised from either column', () => {
assert.ok(timedOut({ status: 'timed out', duration: null }));
assert.ok(timedOut({ status: 'Timed Out', duration: 2.0 }));
assert.ok(timedOut({ status: '', duration: 10.0 }));
assert.ok(!timedOut(d(1.0)));
assert.ok(!timedOut(null));
});
test('each delivery is sorted by the room it had left', () => {
assert.equal(classify(d(9.5)), 'at-risk');
assert.equal(classify(d(6.0)), 'slow');
assert.equal(classify(d(0.4)), 'fine');
assert.equal(classify(d(10.0)), 'timed-out');
assert.equal(classify(d(null)), 'unknown');
});
test('the percentile is nearest rank and never invents a value', () => {
const values = [100, 200, 300, 400];
assert.equal(percentile(values, 50), 200);
assert.equal(percentile(values, 95), 400);
assert.equal(percentile(values, 0), 100);
assert.equal(percentile([], 95), null);
assert.equal(percentile([7], 95), 7);
});
test('a window with no failures and a nine second tail is a finding', () => {
const rows = [...Array(18).fill(d(0.5)), ...Array(2).fill(d(9.1))];
const st = stats(rows);
assert.equal(st.timed_out, 0);
const [state, detail] = verdict(st);
assert.equal(state, 'at-the-edge');
assert.match(detail, /fails on the next slow week/);
assert.match(repair(state), /return 202/);
});
test('a fast receiver is left alone', () => {
assert.equal(verdict(stats(Array(50).fill(d(0.2))))[0], 'healthy');
assert.ok(repair('healthy').startsWith('nothing'));
});
test('timeouts are reported with the headroom on everything else', () => {
const rows = [
...Array(90).fill(d(0.5)),
...Array(10).fill({ status: 'timed out', event: 'push' }),
];
const st = stats(rows);
assert.equal(st.timed_out, 10);
const [state, detail] = verdict(st);
assert.equal(state, 'timing-out');
assert.match(detail, /10 deliveries were abandoned/);
});
test('an empty window is never reported as healthy', () => {
const [state, detail] = verdict(stats([]));
assert.equal(state, 'no-data');
assert.match(detail, /not the same as a receiver that is fast/);
});
test('a window with statuses but no timings says so', () => {
const rows = Array(5).fill({ event: 'push', status: 'OK' });
assert.equal(verdict(stats(rows))[0], 'no-durations');
});
test('the grouping finds the handler to fix first', () => {
const rows = [...Array(5).fill(d(9.4, 'push')), ...Array(5).fill(d(0.3, 'issues'))];
const worst = slowestEvent(rows);
assert.equal(worst.event, 'push');
assert.equal(worst.p95, 9400);
assert.match(repair('slow', worst), /Start with push/);
});
test('a rare event is kept when it timed out', () => {
const rows = [
...Array(5).fill(d(0.2, 'issues')),
{ event: 'release', status: 'timed out' },
];
const grouped = byEvent(rows);
assert.ok('release' in grouped);
assert.equal(grouped.release.timed_out, 1);
});
test('the cursor is read from the Link header', () => {
const header = '<https://api.github.com/repos/a/b/hooks/1/deliveries?cursor=v2>; rel="next"';
assert.ok(nextLink({ Link: header }).endsWith('cursor=v2'));
assert.equal(nextLink({ Link: '<https://x>; rel="prev"' }), null);
assert.equal(nextLink({}), null);
});
FAQ
Is the ten seconds measured on my handler or on the whole request?
The whole thing, from GitHub's side of the connection. DNS, the TLS handshake, whatever queueing happens in your load balancer or ingress, a cold start if the receiver is serverless, the handler itself, and the response on the way back. That is why a handler which times itself at eight seconds can still be recorded as a timeout, and why the durations in the deliveries feed are the numbers worth arguing from: they are the only ones that include everything the cutoff includes.
How is this different from auditing failed deliveries?
Same request, different column, different question. A failure audit groups by status code and tells you what is broken, which matters because a 401 and a 500 have nothing in common. This one ignores status codes apart from the abandonment marker and reads the duration on every delivery, including the successful ones, so it can tell you a receiver is two seconds from the cutoff while the failure count is still zero. Run both; they catch different halves.
Why not just send a request at the receiver and time it?
Two reasons. It is a write, and these scripts do not write. And it would be a worse measurement even if they did: a synthetic payload does not do the work a real one does, your receiver may reject an unsigned request in a millisecond, and you would be timing from wherever the script runs rather than from wherever GitHub does. Every number this check needs has already been recorded by the party whose clock actually decides.
The handler finished successfully. Does the work count?
Your work happened; the delivery still failed. GitHub stopped waiting at ten seconds and recorded a failure, which means it may redeliver, which means the same expensive work runs again. So the honest answer is that a timed-out delivery leaves you in the worst state available: the side effects happened, nothing acknowledges them, and a replay is on its way. Keying the worker on the delivery guid is what makes that survivable.
What does a good synchronous path actually look like?
Read the body, verify the signature over the raw bytes, write the payload to a queue or a durable table, return 202. Nothing else, and no network call to anything except the queue. Everything the handler used to do moves into a worker that can take as long as it needs, retry on its own schedule, and skip a delivery guid it has already processed. The measurable effect is that the 95th percentile stops tracking the size of the repository, which is the whole reason this problem grows over time.
Related field notes
- Deliveries failing where nobody reads the log
- The same URL registered twice
- Polling where a webhook would do
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.
- Troubleshooting webhooks — GitHub Docs
- Handling failed webhook deliveries — GitHub Docs
- Repository webhooks — GitHub REST API
- Best practices for using webhooks — GitHub Docs
If your setup is misbehaving in a way this note does not cover, message me on LinkedIn with what you are seeing.