Transient curl timeout in the PR-review pickup path aborts the whole tick (status=28) #425

New issue

Closed

opened 2026-07-25 16:59:59 +00:00 by igor · 0 comments

igor commented

2026-07-25 16:59:59 +00:00

Collaborator

Symptom

A tick dies with status=28/n/a (curl "operation timed out"), the cleanup() EXIT trap fires hc_ping task fail, and healthchecks.io sends a "DOWN (received a failure signal)" page. The next tick runs clean and the check self-recovers ~2 min later. Cost is one lost tick plus a page — often overnight.

Occurrences

Two on 2026-07-25, against zero exit-28 aborts in the preceding six days (the only other exit-code failure in 7 days is an unrelated status=3 on 07-21):

Jul 25 00:32:37 igor.sherver.org systemd[805]: agent.service: Main process exited, code=exited, status=28/n/a
Jul 25 11:54:35 igor.sherver.org systemd[805]: agent.service: Main process exited, code=exited, status=28/n/a

Where it actually dies

Both aborts land 8-11s after the [agent] recovery sweep ($BOT_USER) log line and before [agent] maintenance:. That log line is misleading as an attribution:

Neither tick printed a single recovery: ... line, so ORPHAN_COUNT was 0 and the sweep loop never executed.
The sweep's own fetch is already guarded — ORPHANS=$(forgejo_my_assigned || echo '[]') — so a curl failure there cannot abort the tick.

That puts the failing call downstream of the sweep, in the PR-review pickup block (bin/tick.sh ~3227+), where _fj callers are unguarded and a non-zero curl exit propagates fatally under set -e.

Timeouts are FORGEJO_CONNECT_TIMEOUT=5 / FORGEJO_MAX_TIME=15 (lib/forgejo.sh:21-22). Death at 8-11s is consistent with a request that connected and then stalled, not with a connect failure.

Ruled out

IPv6 is not the cause here. git.sherver.org resolves to both 2600:3c03::2000:4fff:fe34:6f12 and 45.33.72.135; the v6 path refuses fast rather than blackholing, so happy-eyeballs falls through to v4 cleanly:

v6: FAILED (exit 7) after 0.06s
v4: 200, connect=0.063s, total=0.305s

This is distinct from the earlier ssh/git IPv6 blackhole, which is already pinned via AddressFamily inet.

Fixed looks like

A single transient stall costs a retry, not a tick and a page.

Bounded retry on idempotent _fj requests (GET/HEAD) — e.g. --retry 2 --retry-delay 1 plus retry-on-timeout — so one stalled read is absorbed.
Do not blindly retry non-idempotent calls. forgejo_comment, assign/unassign, merge, and review submissions can succeed server-side and still time out client-side; a naive retry double-posts. Those either stay single-shot or need an explicit "did it land?" re-check before a second attempt.
Separately, audit the unguarded _fj callers in the pickup path: decide per call whether failure should be fatal or best-effort. A read that only decides whether there is review work to pick up should not be able to kill the tick.

Tests

_fj GET retries on a simulated timeout and succeeds on the retry.
_fj GET gives up after the bound and returns non-zero rather than retrying forever.
Non-idempotent helpers are NOT retried (assert no duplicate POST on a timed-out comment).
A timed-out best-effort read in the pickup path leaves the tick running rather than aborting it.

## Symptom A tick dies with `status=28/n/a` (curl "operation timed out"), the `cleanup()` EXIT trap fires `hc_ping task fail`, and healthchecks.io sends a "DOWN (received a failure signal)" page. The next tick runs clean and the check self-recovers ~2 min later. Cost is one lost tick plus a page — often overnight. ## Occurrences Two on 2026-07-25, against **zero exit-28 aborts in the preceding six days** (the only other exit-code failure in 7 days is an unrelated `status=3` on 07-21): ``` Jul 25 00:32:37 igor.sherver.org systemd[805]: agent.service: Main process exited, code=exited, status=28/n/a Jul 25 11:54:35 igor.sherver.org systemd[805]: agent.service: Main process exited, code=exited, status=28/n/a ``` ## Where it actually dies Both aborts land 8-11s after the `[agent] recovery sweep ($BOT_USER)` log line and before `[agent] maintenance:`. That log line is misleading as an attribution: - Neither tick printed a single `recovery: ...` line, so `ORPHAN_COUNT` was 0 and the sweep loop never executed. - The sweep's own fetch is already guarded — `ORPHANS=$(forgejo_my_assigned || echo '[]')` — so a curl failure there cannot abort the tick. That puts the failing call **downstream of the sweep, in the PR-review pickup block** (`bin/tick.sh` ~3227+), where `_fj` callers are unguarded and a non-zero curl exit propagates fatally under `set -e`. Timeouts are `FORGEJO_CONNECT_TIMEOUT=5` / `FORGEJO_MAX_TIME=15` (`lib/forgejo.sh:21-22`). Death at 8-11s is consistent with a request that connected and then stalled, not with a connect failure. ## Ruled out IPv6 is not the cause here. `git.sherver.org` resolves to both `2600:3c03::2000:4fff:fe34:6f12` and `45.33.72.135`; the v6 path **refuses fast** rather than blackholing, so happy-eyeballs falls through to v4 cleanly: ``` v6: FAILED (exit 7) after 0.06s v4: 200, connect=0.063s, total=0.305s ``` This is distinct from the earlier ssh/git IPv6 blackhole, which is already pinned via `AddressFamily inet`. ## Fixed looks like A single transient stall costs a retry, not a tick and a page. - Bounded retry on **idempotent** `_fj` requests (GET/HEAD) — e.g. `--retry 2 --retry-delay 1` plus retry-on-timeout — so one stalled read is absorbed. - **Do not blindly retry non-idempotent calls.** `forgejo_comment`, assign/unassign, merge, and review submissions can succeed server-side and still time out client-side; a naive retry double-posts. Those either stay single-shot or need an explicit "did it land?" re-check before a second attempt. - Separately, audit the unguarded `_fj` callers in the pickup path: decide per call whether failure should be fatal or best-effort. A read that only decides whether there is review work to pick up should not be able to kill the tick. ## Tests - `_fj` GET retries on a simulated timeout and succeeds on the retry. - `_fj` GET gives up after the bound and returns non-zero rather than retrying forever. - Non-idempotent helpers are NOT retried (assert no duplicate POST on a timed-out comment). - A timed-out best-effort read in the pickup path leaves the tick running rather than aborting it.

igor added the

Kind/Bug

label

2026-07-25 16:59:59 +00:00

igor self-assigned this

2026-07-25 17:03:26 +00:00

igor referenced this issue from a pull request that will close it,

2026-07-25 17:18:09 +00:00

fix: absorb transient curl timeouts in the PR-review pickup scan instead of aborting the tick #426

igor added spent time

2026-07-25 17:18:10 +00:00

14 minutes 16 seconds