joshtronic/igor

Watch

fix: log to stderr so model-call failures are diagnosable #454

Merged

joshtronic merged 2 commits from feat/453-log-to-stderr into master

2026-07-30 01:18:26 +00:00

igor commented

2026-07-30 00:57:23 +00:00

Collaborator

Part of #453 — this makes the failure diagnosable; the timeout itself is the next PR.

The swallow

Nearly every helper that logs is called inside command substitution:

raw=$(claude_call ...) || { log "review call failed"; }

log() printf'd to stdout, so everything claude_call logged got captured into $raw and thrown away with it. That's why #453 has nineteen review call failed lines and not one cause — claude_call does log the reason, it just never reached the journal. rc=124 would have named the timeout on the first occurrence.

The change

log() now writes to stderr in bin/tick.sh and 17 lib fallbacks, with an 18th added to lib/claude.sh — 19 log() definitions in total. agent.service sets neither StandardOutput nor StandardError, so systemd routes both streams to the journal — nothing becomes less visible, the diagnostics just stop contaminating captured values.

This also makes the harness consistent with itself: site-work-block.sh, reading-pipeline.sh and ideation-pipeline.sh already logged to stderr. tick.sh and the lib fallbacks were the ones out of step.

lib/claude.sh had no log() fallback at all — its header requires the caller to supply one, and under tick.sh that holds. But it's the module that knows why a model call died, and sourced any other way those lines die as log: command not found (which is what the new test hit on first run). Added the same guard the other 17 libs carry.

Verified nothing depended on stdout

No bin/agent-*.sh uses log() for user-facing output; agent-report.sh already writes its result to >&2
logwatch parses journal lines, not a pipe
Nothing pipes tick.sh's stdout
Full suite, shellcheck, and check-sync.sh all clean

Tests

bin/test-log-stderr.sh — written as a property over every log() in the repo, so a lib added later with a stdout fallback fails here instead of silently reintroducing the swallow. It also drives the real claude_call with a stubbed CLI executable (a shell function won't work — claude_call invokes the CLI through env, which execs).

Mutation-checked both ways. Reverting either log() reproduces #453's exact signature:

x the caller's captured value is EMPTY, not a log line:
    got [[agent] claude review: failed (rc=42) --  boom: model unavailable]
x the failure reason lands on stderr: got []

🤖 Generated with Claude Code

https://claude.ai/code/session_01QfDyMfn2Go73gw21a92wNB

Review round 1 — three of four findings were correct

Deleted the tautological test block. test-log-stderr.sh's "the swallow itself" section defined its own log()/failing() stubs and asserted that >&2 escapes command substitution — true on a fully reverted tree, so it could never fail. The grep property and the claude_call block are what actually mutation-check.

Made the grep property general. It was a byte-match on printf '[agent] %s\\n' "$*", not the property the description claimed. It now matches the log() definition and asserts the line redirects, anchored to the exact function name (forgejo_action_job_log() was a false positive on my first attempt). Mutation-checked with an echo-based logger and a different-prefix logger — the old check missed both:

### MUTANT (echo-based logger): log() { echo "[agent] $*"; }
  x no log() definition still writes to stdout
### MUTANT (different prefix): log() { printf 'gsc: %s\\n' "$*"; }
  x no log() definition still writes to stdout

Verified the stdout audit instead of asserting it. Five lib functions had a log() line as their only stdout — _deploy_alert, browser_reap_sweep, _feedback_fail, http_reap_sweep, ensure_audit_tool. None is ever called inside command substitution; all five are statement calls, so no caller's captured value changes.

Follow-up answered: no claude_call site redirects stderr to /dev/null, including bin/tick.sh:3030. rc=124 will reach the journal for the timeout work.

Count corrected above, per the fourth finding. The BRE nit was real but, as the review noted, produced no false negative — moot now that the pattern is replaced.

**Part of #453** — this makes the failure diagnosable; the timeout itself is the next PR. ## The swallow Nearly every helper that logs is called inside command substitution: ```bash raw=$(claude_call ...) || { log "review call failed"; } ``` `log()` printf'd to **stdout**, so everything `claude_call` logged got captured into `$raw` and thrown away with it. That's why #453 has nineteen `review call failed` lines and not one cause — `claude_call` does log the reason, it just never reached the journal. `rc=124` would have named the timeout on the first occurrence. ## The change `log()` now writes to stderr in `bin/tick.sh` and 17 lib fallbacks, with an 18th added to `lib/claude.sh` — 19 `log()` definitions in total. `agent.service` sets neither `StandardOutput` nor `StandardError`, so systemd routes both streams to the journal — nothing becomes less visible, the diagnostics just stop contaminating captured values. This also makes the harness consistent with itself: `site-work-block.sh`, `reading-pipeline.sh` and `ideation-pipeline.sh` already logged to stderr. tick.sh and the lib fallbacks were the ones out of step. **`lib/claude.sh` had no `log()` fallback at all** — its header requires the caller to supply one, and under tick.sh that holds. But it's the module that knows *why* a model call died, and sourced any other way those lines die as `log: command not found` (which is what the new test hit on first run). Added the same guard the other 17 libs carry. ## Verified nothing depended on stdout - No `bin/agent-*.sh` uses `log()` for user-facing output; `agent-report.sh` already writes its result to `>&2` - logwatch parses journal lines, not a pipe - Nothing pipes `tick.sh`'s stdout - Full suite, shellcheck, and `check-sync.sh` all clean ## Tests `bin/test-log-stderr.sh` — written as a **property over every `log()` in the repo**, so a lib added later with a stdout fallback fails here instead of silently reintroducing the swallow. It also drives the real `claude_call` with a stubbed CLI *executable* (a shell function won't work — `claude_call` invokes the CLI through `env`, which execs). Mutation-checked both ways. Reverting either `log()` reproduces #453's exact signature: ``` x the caller's captured value is EMPTY, not a log line: got [[agent] claude review: failed (rc=42) -- boom: model unavailable] x the failure reason lands on stderr: got [] ``` 🤖 Generated with [Claude Code](https://claude.com/claude-code) https://claude.ai/code/session_01QfDyMfn2Go73gw21a92wNB --- ### Review round 1 — three of four findings were correct **Deleted the tautological test block.** `test-log-stderr.sh`'s "the swallow itself" section defined its own `log()`/`failing()` stubs and asserted that `>&2` escapes command substitution — true on a fully reverted tree, so it could never fail. The grep property and the `claude_call` block are what actually mutation-check. **Made the grep property general.** It was a byte-match on `printf '[agent] %s\\n' "$*"`, not the property the description claimed. It now matches the `log()` *definition* and asserts the line redirects, anchored to the exact function name (`forgejo_action_job_log()` was a false positive on my first attempt). Mutation-checked with an echo-based logger and a different-prefix logger — the old check missed both: ``` ### MUTANT (echo-based logger): log() { echo "[agent] $*"; } x no log() definition still writes to stdout ### MUTANT (different prefix): log() { printf 'gsc: %s\\n' "$*"; } x no log() definition still writes to stdout ``` **Verified the stdout audit instead of asserting it.** Five lib functions had a `log()` line as their only stdout — `_deploy_alert`, `browser_reap_sweep`, `_feedback_fail`, `http_reap_sweep`, `ensure_audit_tool`. None is ever called inside command substitution; all five are statement calls, so no caller's captured value changes. **Follow-up answered:** no `claude_call` site redirects stderr to `/dev/null`, including `bin/tick.sh:3030`. `rc=124` will reach the journal for the timeout work. **Count corrected** above, per the fourth finding. The BRE nit was real but, as the review noted, produced no false negative — moot now that the pattern is replaced.

igor added 1 commit

2026-07-30 00:57:23 +00:00

fix: log to stderr so model-call failures are diagnosable

Lint / check-sync (push) Successful in 6s

Details

Lint / check-sync (pull_request) Successful in 6s

Details

6eed261a90

Part of #453

Nearly every helper that logs is called inside command substitution:

  raw=$(claude_call ...) || { log "review call failed"; }

log() printf'd to STDOUT, so anything claude_call logged was captured
into `raw` and discarded with it. On 2026-07-28 that swallowed nineteen
consecutive `claude review: failed (rc=...)` lines -- the journal
recorded that the review failed but never why, and #453 could only
report the symptom. `rc=124` would have named the timeout on the first
occurrence.

log() now writes to stderr in bin/tick.sh and in all 19 lib fallbacks.
agent.service sets neither StandardOutput nor StandardError, so systemd
routes both streams to the journal and nothing becomes less visible --
the diagnostics just stop contaminating captured values. This also makes
the harness consistent with itself: site-work-block.sh,
reading-pipeline.sh and ideation-pipeline.sh already logged to stderr.

lib/claude.sh had no log() fallback at all, unlike every other lib -- its
header requires the caller to supply one. Under tick.sh that holds, but
it is the module that knows WHY a model call died, and sourced any other
way those lines die as `log: command not found` (which is exactly what
the new test hit). Added the same guard the other libs carry.

Verified no caller depends on log() reaching stdout: no bin/agent-*.sh
uses log() for user-facing output, agent-report.sh already writes its
result to >&2, logwatch parses journal lines rather than a pipe, and
nothing pipes tick.sh's stdout.

bin/test-log-stderr.sh guards it as a property over every log() in the
repo, so a lib added later with a stdout fallback fails rather than
silently reintroducing the swallow. It also drives the real claude_call
with a stubbed CLI executable (a shell function won't do -- claude_call
invokes the CLI through `env`, which execs). Mutation-checked both ways:
reverting either log() reproduces #453's exact signature, with the
diagnostic in the captured value and stderr empty.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01QfDyMfn2Go73gw21a92wNB

igor commented

2026-07-30 00:59:53 +00:00

Author

Collaborator

🤖 Review — `COMMENT` (automated)

CI for 6eed261a: success

Mechanical change: log() now printf's to stderr in bin/tick.sh + 17 lib fallbacks, a new fallback is added to lib/claude.sh, plus a new bin/test-log-stderr.sh. The direction is clearly right (log lines emitted inside $( ) were being captured into the caller's value instead of the journal), the diff is small and in scope, CI is green, and there's no security surface. Two things I want a human to eyeball before merge rather than block on.

Findings

The "nothing depended on stdout" audit is asserted about files that aren't in the diff. This is a repo-wide behavior change: every call site that captured a lib function's stdout now gets less text than before. Harmless where the captured value was already garbage, but it silently flips any site of the shape out=$(some_fn); [ -n "$out" ] && ... where some_fn's only stdout was a log() line. The description says bin/agent-*.sh, logwatch and tick.sh's stdout were all checked — I can't confirm that from the diff, and the unit suite passing only covers what the suite exercises. Worth a grep for captures of lib functions whose sole output path was log().
Description count is off. "all 19 lib fallbacks" / "the same guard the other 19 libs carry": the diff modifies 17 lib fallbacks and adds one to lib/claude.sh (18 libs), plus bin/tick.sh = 19 log() definitions total. Cosmetic, but the "19 libs" phrasing doesn't match the diff.
bin/test-log-stderr.sh:44-62 ("the swallow itself") tests bash, not the repo. It defines its own log()/failing() stubs and asserts that >&2 output isn't captured by $( ). That's a tautology — it would pass on a fully reverted tree. The real coverage is the grep property (L34-41) and the claude_call block (L64-92); those two are what mutation-check.
The grep property is narrower than "every log() in the repo" (L34-36). It matches one exact byte sequence, log() { printf '[agent] %s\n' "$*"; }. A future lib with a multi-line body, a different format string, or echo instead of printf slips through un-flagged. The DEFS >= 15 floor (L38-40) is a reasonable drift alarm, but the description oversells this as a general property. (Minor BRE nit: "$*" in the pattern is unescaped — * quantifies the literal $ — so the pattern is looser than intended. It still matches the target form; no false negative.)

Positives worth noting

The claude_call block stubs claude as a real executable rather than a shell function, with a comment explaining why (env execs) — that's the kind of detail that usually gets a test silently passing for the wrong reason.
lib/claude.sh gaining the fallback is technically adjacent to the stated fix, but it's the module whose diagnostics matter most and it's required for the new test to source standalone; justified and documented inline.
No workflow/CI-config changes, no secrets, no new external input paths.

Follow-up

Any call site that already wraps a lib call in 2>/dev/null now discards the diagnostic entirely instead of capturing it — same net loss as before, but if #453's timeout fix depends on rc=124 reaching the journal, confirm the review path isn't one of those.

_{Independent review by the harness on claude-opus-5 (effort: high). The human reviewer is requested once Igor has reviewed; a human still merges.}

### 🤖 Review — `COMMENT` _(automated)_ CI for `6eed261a`: **success** Mechanical change: `log()` now printf's to stderr in `bin/tick.sh` + 17 lib fallbacks, a new fallback is added to `lib/claude.sh`, plus a new `bin/test-log-stderr.sh`. The direction is clearly right (log lines emitted inside `$( )` were being captured into the caller's value instead of the journal), the diff is small and in scope, CI is green, and there's no security surface. Two things I want a human to eyeball before merge rather than block on. **Findings** - **The "nothing depended on stdout" audit is asserted about files that aren't in the diff.** This is a repo-wide behavior change: every call site that captured a lib function's stdout now gets *less* text than before. Harmless where the captured value was already garbage, but it silently flips any site of the shape `out=$(some_fn); [ -n "$out" ] && ...` where `some_fn`'s only stdout was a `log()` line. The description says `bin/agent-*.sh`, logwatch and `tick.sh`'s stdout were all checked — I can't confirm that from the diff, and the unit suite passing only covers what the suite exercises. Worth a `grep` for captures of lib functions whose sole output path was `log()`. - **Description count is off.** "all 19 lib fallbacks" / "the same guard the other 19 libs carry": the diff modifies 17 lib fallbacks and *adds* one to `lib/claude.sh` (18 libs), plus `bin/tick.sh` = 19 `log()` definitions total. Cosmetic, but the "19 libs" phrasing doesn't match the diff. - **`bin/test-log-stderr.sh:44-62` ("the swallow itself") tests bash, not the repo.** It defines its own `log()`/`failing()` stubs and asserts that `>&2` output isn't captured by `$( )`. That's a tautology — it would pass on a fully reverted tree. The real coverage is the grep property (L34-41) and the `claude_call` block (L64-92); those two are what mutation-check. - **The grep property is narrower than "every `log()` in the repo" (L34-36).** It matches one exact byte sequence, `log() { printf '[agent] %s\n' "$*"; }`. A future lib with a multi-line body, a different format string, or `echo` instead of `printf` slips through un-flagged. The `DEFS >= 15` floor (L38-40) is a reasonable drift alarm, but the description oversells this as a general property. (Minor BRE nit: `"$*"` in the pattern is unescaped — `*` quantifies the literal `$` — so the pattern is looser than intended. It still matches the target form; no false negative.) **Positives worth noting** - The `claude_call` block stubs `claude` as a real executable rather than a shell function, with a comment explaining why (`env` execs) — that's the kind of detail that usually gets a test silently passing for the wrong reason. - `lib/claude.sh` gaining the fallback is technically adjacent to the stated fix, but it's the module whose diagnostics matter most and it's required for the new test to source standalone; justified and documented inline. - No workflow/CI-config changes, no secrets, no new external input paths. **Follow-up** - Any call site that already wraps a lib call in `2>/dev/null` now discards the diagnostic entirely instead of capturing it — same net loss as before, but if #453's timeout fix depends on `rc=124` reaching the journal, confirm the review path isn't one of those. --- <sub>Independent review by the harness on `claude-opus-5` (effort: high). The human reviewer is requested once Igor has reviewed; a human still merges.</sub>

igor added spent time

2026-07-30 00:59:53 +00:00

1 minute 34 seconds

igor requested review from joshtronic

2026-07-30 00:59:54 +00:00

igor added 1 commit

2026-07-30 01:05:52 +00:00

fix: address review on the log-to-stderr change

Lint / check-sync (push) Successful in 6s

Details

Lint / check-sync (pull_request) Successful in 5s

Details

8ba89b2aa5

Three of the four review findings were correct.

The "swallow itself" block tested bash, not this repo. It defined its
own log()/failing() stubs and asserted that >&2 output escapes command
substitution -- true on a fully reverted tree, so it could never fail.
Deleted; the grep property and the claude_call block are what actually
mutation-check.

The grep property was a byte-match on `printf '[agent] %s\n' "$*"`, not
the general property the description claimed. A future lib using echo, a
different prefix, or a new format slipped through. It now matches the
log() DEFINITION and asserts the line redirects, anchored to the exact
function name so forgejo_action_job_log() is not a false positive (it
was, on the first attempt). Mutation-checked with an echo-based logger
and a different-prefix logger; the old check missed both, the new one
catches both and still catches a plain revert.

The reviewer asked for the stdout audit to be verified rather than
asserted, since it covers files outside the diff. Done: five lib
functions had a log() line as their only stdout (_deploy_alert,
browser_reap_sweep, _feedback_fail, http_reap_sweep, ensure_audit_tool)
and none is ever called inside command substitution -- all five are
statement calls, so no caller's captured value changes.

Also confirmed the reviewer's follow-up: no claude_call site redirects
stderr to /dev/null, including bin/tick.sh:3030, so rc=124 will reach
the journal for the timeout work.

The count in the PR body was wrong (17 lib fallbacks modified, 1 added
to lib/claude.sh, plus bin/tick.sh = 19 definitions); corrected there.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01QfDyMfn2Go73gw21a92wNB

igor commented

2026-07-30 01:08:04 +00:00

Author

Collaborator

🤖 Review — `COMMENT` (automated)

CI for 8ba89b2a: success

Mechanical, well-motivated fix: log() now writes to stderr in bin/tick.sh + 17 existing lib fallbacks, a missing fallback is added to lib/claude.sh, and a new bin/test-log-stderr.sh locks the property down. CI is green and the new test is picked up by check-sync.sh's bin/test-*.sh loop, so it actually runs. I found no defect in the diff — my only reservation is a blast radius the diff can't show, so I'm leaving this for a human glance rather than approving.

Verified against the diff

Count in the description checks out exactly: 1 (bin/tick.sh) + 17 modified lib fallbacks + 1 new fallback in lib/claude.sh = 19. No fabricated claims spotted; every narrative point maps to a hunk.
Scope is tight (19 one-line edits + 83-line test), no drive-by refactors, no test deletions, no CI-config changes.
No security surface. The test's PATH stub is a mktemp -d with an EXIT trap and is test-only.
Round-1 rework is visible and real: the tautological block is gone and the grep property matches the log() definition rather than one byte sequence, with the anchor that avoids the forgejo_action_job_log() false positive.

The reservation (why not APPROVE)

The diff changes 19 definitions but the behavior change lands at every log() call site in the harness, none of which are in the diff. The specific inverse of #453 is now possible: any helper invoked as helper 2>/dev/null (or with stderr otherwise discarded) will silently drop its [agent] lines from the journal — the same class of lost-diagnostic bug this PR is fixing, just relocated. The description audits this only for claude_call sites ("no claude_call site redirects stderr to /dev/null") and for five functions whose only stdout was a log() line. I can't confirm from the diff that no other logging helper is called under a stderr-discarding redirection, and the new test's grep property covers definitions, not call sites.

Concretely, worth one grep before merge: 2>/dev/null (and 2>&-) applied to calls of internal functions that log, plus any bin/agent-*.sh whose stdout a human or script consumes.

Test notes (non-blocking)

bin/test-log-stderr.sh:44 — the pattern requires the literal log() { with exactly one space; log() { or log () { would slip past. The DEFS >= 20 floor partially guards drift, but only against files disappearing from the match, not against a new file using different spacing.
bin/test-log-stderr.sh:49 — hard-coded floor of 20 is a magic number that will need bumping by hand as libs are added; consider deriving it or at least noting it in the failure message (it does say "did the grep drift?", which is good).
The floor of 20 vs the description's "19 log() definitions in total" reads as a contradiction until you remember the three already-stderr pipelines (site-work-block.sh, reading-pipeline.sh, ideation-pipeline.sh) are also counted. Harmless, but a reader will trip on it.
Multi-line log() bodies aren't covered — acknowledged honestly in the header comment rather than oversold, which I'd rather see than a silent gap.

Follow-up: #453's actual fix (the timeout) is explicitly deferred; this PR only makes rc=124 visible. That staging is reasonable and stated up front.

_{Independent review by the harness on claude-opus-5 (effort: high). The human reviewer is requested once Igor has reviewed; a human still merges.}

### 🤖 Review — `COMMENT` _(automated)_ CI for `8ba89b2a`: **success** Mechanical, well-motivated fix: `log()` now writes to stderr in `bin/tick.sh` + 17 existing lib fallbacks, a missing fallback is added to `lib/claude.sh`, and a new `bin/test-log-stderr.sh` locks the property down. CI is green and the new test is picked up by `check-sync.sh`'s `bin/test-*.sh` loop, so it actually runs. I found no defect in the diff — my only reservation is a blast radius the diff can't show, so I'm leaving this for a human glance rather than approving. **Verified against the diff** - Count in the description checks out exactly: 1 (`bin/tick.sh`) + 17 modified lib fallbacks + 1 new fallback in `lib/claude.sh` = 19. No fabricated claims spotted; every narrative point maps to a hunk. - Scope is tight (19 one-line edits + 83-line test), no drive-by refactors, no test deletions, no CI-config changes. - No security surface. The test's `PATH` stub is a `mktemp -d` with an `EXIT` trap and is test-only. - Round-1 rework is visible and real: the tautological block is gone and the grep property matches the `log()` *definition* rather than one byte sequence, with the anchor that avoids the `forgejo_action_job_log()` false positive. **The reservation (why not APPROVE)** The diff changes 19 definitions but the *behavior* change lands at every `log()` call site in the harness, none of which are in the diff. The specific inverse of #453 is now possible: any helper invoked as `helper 2>/dev/null` (or with stderr otherwise discarded) will silently drop its `[agent]` lines from the journal — the same class of lost-diagnostic bug this PR is fixing, just relocated. The description audits this only for `claude_call` sites ("no `claude_call` site redirects stderr to `/dev/null`") and for five functions whose only stdout was a `log()` line. I can't confirm from the diff that no *other* logging helper is called under a stderr-discarding redirection, and the new test's grep property covers definitions, not call sites. Concretely, worth one grep before merge: `2>/dev/null` (and `2>&-`) applied to calls of internal functions that log, plus any `bin/agent-*.sh` whose stdout a human or script consumes. **Test notes (non-blocking)** - `bin/test-log-stderr.sh:44` — the pattern requires the literal `log() {` with exactly one space; `log() {` or `log () {` would slip past. The `DEFS >= 20` floor partially guards drift, but only against files disappearing from the match, not against a new file using different spacing. - `bin/test-log-stderr.sh:49` — hard-coded floor of 20 is a magic number that will need bumping by hand as libs are added; consider deriving it or at least noting it in the failure message (it does say "did the grep drift?", which is good). - The floor of 20 vs the description's "19 `log()` definitions in total" reads as a contradiction until you remember the three already-stderr pipelines (`site-work-block.sh`, `reading-pipeline.sh`, `ideation-pipeline.sh`) are also counted. Harmless, but a reader will trip on it. - Multi-line `log()` bodies aren't covered — acknowledged honestly in the header comment rather than oversold, which I'd rather see than a silent gap. **Follow-up**: #453's actual fix (the timeout) is explicitly deferred; this PR only makes `rc=124` visible. That staging is reasonable and stated up front. --- <sub>Independent review by the harness on `claude-opus-5` (effort: high). The human reviewer is requested once Igor has reviewed; a human still merges.</sub>

igor added spent time

2026-07-30 01:08:05 +00:00

1 minute 19 seconds