agent.service exits 1/FAILURE mid-PR-review with 3.1G memory peak #291

New issue

Closed

opened 2026-06-30 03:19:04 +00:00 by igor · 1 comment

igor commented

2026-06-30 03:19:04 +00:00

Collaborator

The 21:45 tick claimed PR review of joshtronic/vps-showdown#22, invoked claude (30m timeout) at 21:46:00, ran ~11 minutes installing deps and running the repo's jest/lint/prettier suites inside the review worktree, then the unit exited nonzero before producing a verdict. Notable: memory peak was 3.1G (normal ticks ~13M; the earlier 21:44 review tick was 157.4M). The timeout was not reached, so the status=1 exit is unexplained. The review work was abandoned and re-started from scratch by the 21:58 tick (reopened + reassigned to bot), so no verdict was lost permanently, but the crash itself is a real fault and fits the "tick dies mid-call" pattern that commit feat(crashlog): preserve the claude stream when a tick dies mid-call (observe #279) only instruments, not fixes.

Jun 29 21:46:00 igor tick.sh[3794286]: [agent] invoking claude for PR review (timeout 30m)
Jun 29 21:57:11 igor tick.sh[3794896]: [tool: Bash]
Jun 29 21:57:11 igor systemd[785]: agent.service: Main process exited, code=exited, status=1/FAILURE
Jun 29 21:57:11 igor systemd[785]: agent.service: Failed with result 'exit-code'.
Jun 29 21:57:11 igor systemd[785]: Failed to start agent.service - Agent -- one tick: claim and work one Forgejo issue across known projects.
Jun 29 21:57:11 igor systemd[785]: agent.service: Consumed 4min 2.429s CPU time, 3.1G memory peak.

Fixed looks like: PR-review claude invocations complete with a logged verdict (or a clean handled timeout) without the unit exiting nonzero; investigate whether the 3.1G spike (npm install + jest run in-worktree) is hitting an OOM/resource ceiling that kills the run, and cap/contain it so a single PR review can't crash the tick.

service: agent.service
severity: medium
window: 2026-06-29 21:00-22:00 (filed by the hourly logwatch pass)

The 21:45 tick claimed PR review of `joshtronic/vps-showdown#22`, invoked claude (30m timeout) at 21:46:00, ran ~11 minutes installing deps and running the repo's jest/lint/prettier suites inside the review worktree, then the unit exited nonzero before producing a verdict. Notable: memory peak was 3.1G (normal ticks ~13M; the earlier 21:44 review tick was 157.4M). The timeout was not reached, so the status=1 exit is unexplained. The review work was abandoned and re-started from scratch by the 21:58 tick (reopened + reassigned to bot), so no verdict was lost permanently, but the crash itself is a real fault and fits the "tick dies mid-call" pattern that commit `feat(crashlog): preserve the claude stream when a tick dies mid-call (observe #279)` only instruments, not fixes. ``` Jun 29 21:46:00 igor tick.sh[3794286]: [agent] invoking claude for PR review (timeout 30m) Jun 29 21:57:11 igor tick.sh[3794896]: [tool: Bash] Jun 29 21:57:11 igor systemd[785]: agent.service: Main process exited, code=exited, status=1/FAILURE Jun 29 21:57:11 igor systemd[785]: agent.service: Failed with result 'exit-code'. Jun 29 21:57:11 igor systemd[785]: Failed to start agent.service - Agent -- one tick: claim and work one Forgejo issue across known projects. Jun 29 21:57:11 igor systemd[785]: agent.service: Consumed 4min 2.429s CPU time, 3.1G memory peak. ``` Fixed looks like: PR-review claude invocations complete with a logged verdict (or a clean handled timeout) without the unit exiting nonzero; investigate whether the 3.1G spike (npm install + jest run in-worktree) is hitting an OOM/resource ceiling that kills the run, and cap/contain it so a single PR review can't crash the tick. --- service: agent.service severity: medium window: 2026-06-29 21:00-22:00 (filed by the hourly logwatch pass)

joshtronic was assigned by igor

2026-06-30 03:19:04 +00:00

igor added spent time

2026-06-30 03:19:05 +00:00

1 minute 10 seconds

igor referenced this issue from a commit

2026-06-30 14:05:13 +00:00

fix(claude): stop claude_run_with_cost leaking errexit into its caller (igor#291)

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

2026-06-30 14:05:32 +00:00

fix(claude): stop claude_run_with_cost leaking errexit into its caller (igor#291) #296

igor commented

2026-06-30 14:05:52 +00:00

Author

Collaborator

Re-scoped + root-caused → fix in #296

The OOM/memory framing in this ticket is wrong (worth recording): the box has 31G total / ~27G free, the service has no memory cap, and there were zero kernel OOM-kill events at either crash time (21:57 and the later 23:44 repeat). Both crashes exited status=1, and one peaked at only 682M. So nothing hit a resource ceiling — the "3.1G peak" was incidental.

Actual root cause (reproduced): an errexit leak in claude_run_with_cost. It runs the stream pipeline under set +e, then restored errexit with an unconditional set -e before its bookkeeping. Every caller wraps the call in set +e to capture a nonzero claude exit — but that internal set -e clobbers the guard, so when claude exits nonzero (a recoverable model crash mid-stream) the nonzero return trips errexit in the caller and kills the tick before it reads $?. That is exactly the "status=1, no claude exited line" signature. Not Node-specific — heavy Node reworks just hit nonzero claude exits most often.

Fix (#296): restore the caller's errexit instead of forcing set -e; the bookkeeping is already || true-guarded. Plus bin/test-claude-errexit.sh, which fails against the old code and passes against the fix.

Status: #294 already handled the emergency (loop-break after 2 crashes + crashlog trap). #296 is the root-cause fix — once it merges, a recoverable model exit stays a handled outcome and the bot can rework Node-repo PRs instead of bouncing every one to you. This issue auto-closes when #296 merges.

## Re-scoped + root-caused → fix in #296 **The OOM/memory framing in this ticket is wrong** (worth recording): the box has 31G total / ~27G free, the service has **no memory cap**, and there were **zero kernel OOM-kill events** at either crash time (21:57 and the later 23:44 repeat). Both crashes exited `status=1`, and one peaked at only **682M**. So nothing hit a resource ceiling — the "3.1G peak" was incidental. **Actual root cause (reproduced):** an **errexit leak** in `claude_run_with_cost`. It runs the stream pipeline under `set +e`, then restored errexit with an *unconditional* `set -e` before its bookkeeping. Every caller wraps the call in `set +e` to capture a nonzero claude exit — but that internal `set -e` clobbers the guard, so when claude exits nonzero (a recoverable model crash mid-stream) the nonzero `return` trips errexit in the **caller** and kills the tick before it reads `$?`. That is exactly the "`status=1`, no `claude exited` line" signature. Not Node-specific — heavy Node reworks just hit nonzero claude exits most often. **Fix (#296):** restore the caller's errexit instead of forcing `set -e`; the bookkeeping is already `|| true`-guarded. Plus `bin/test-claude-errexit.sh`, which fails against the old code and passes against the fix. **Status:** #294 already handled the *emergency* (loop-break after 2 crashes + crashlog trap). #296 is the *root-cause* fix — once it merges, a recoverable model exit stays a handled outcome and the bot can rework Node-repo PRs instead of bouncing every one to you. This issue auto-closes when #296 merges.

joshtronic closed this issue

2026-06-30 15:10:30 +00:00

igor referenced this issue

2026-06-30 15:12:02 +00:00

Set up healthchecks.io heartbeat monitoring (overnight visibility): igor-ticking + task-finished pings #297